Closed endurance1968 closed 3 months ago
No it's not a feature. Did you check the uptime?
the adapter was running 5 days should be inline with the cerbo as I updated to 3.41 last week.
So everything clear or do you still need help?
Are you also sure, that the alarm comes from this driver? Many times users are messing up with notifications from the MultiPlus or the battery aggregator.
My request how to debug why the driver restarted is still open.
was the driver causing the alarm - I would say 99% yes, as the time of driver restart is exactly the same as the alarm one. Is the driver sending the alarm no (generated by MPII). I am not interested in the alarm as such - that is just a visible symptom but why the service restarted.
You checked the docs on how to troubleshoot, right? https://mr-manuel.github.io/venus-os_dbus-serialbattery_docs/troubleshoot/
Everything relevant in in the /var/log/dbus-serialbattery.tty*/*
logs. If the log is to short sheck the other files in the same folder.
yes and in case you are asking for the exact uptimes
root@einstein:~# svstat /service/dbus-serialbattery.tty*
/service/dbus-serialbattery.ttyUSB0: up (pid 24786) 253687 seconds
/service/dbus-serialbattery.ttyUSB1: up (pid 24830) 253686 seconds
/service/dbus-serialbattery.ttyUSB2: up (pid 24875) 253684 seconds
root@einstein:~# uptime
13:22:29 up 10 days, 8:38, load average: 1.06, 1.25, 1.88
which is ~3 days which is equal to the 8.8.2024 visible in the log I pasted. Let me try to rephrase the question. How can I enhance the logging so I can see why the driver has restarted? As you can see above there is no indication in the log visible that there was an error. Simply switching to debug log very likely will not help as the log will be overwritten until I recognize the restart. It does not happen very often so of course priority is not high but I dont like restarts without knowing why.
Since there is nothing in the log as you said, probably the system restarts the service for whatever reason. Most common reasons are high CPU or memory full.
Maybe this logs can help you:
/var/log/dmesg*
/var/log/message*
There is nothing other you could check, that I‘m aware of. You could try to ask in the Victron Community.
OK thanks that I just can keep montoring and hope to spot abnormalities in time.
Just FYI - it restarted again - no errors in the logs also nothing within system logs. root@einstein:~ svstat /service/dbus-serialbattery.tty /service/dbus-serialbattery.ttyUSB0: up (pid 11087) 840 seconds /service/dbus-serialbattery.ttyUSB1: up (pid 11131) 839 seconds /service/dbus-serialbattery.ttyUSB2: up (pid 11175) 838 seconds root@einstein:~ uptime 19:55:55 up 14 days, 15:11, load average: 2.01, 1.83, 2.24
Did you try to check all logs in the log directory? Somewhere has to be something...
I do not see anything - only log that has newer entries then the restart is messages, and I see nothing related. But it might be connected to "load" I opened VRM and RemoteConsole at this time. But could also be a pure coincidence.
Olaf
tail -n100 -f /data/log/dbus-serialbattery.ttyUSB*/current | tai64nlocal .... 2024-08-08 14:54:51.925584500 INFO:SerialBattery:> CHARGE FET: None | DISCHARGE FET: None | BALANCE FET: None 2024-08-08 14:54:51.926326500 INFO:SerialBattery:Serial Number/Unique Identifier: SeplosBMS16cells_280.0Ah 2024-08-15 19:41:55.087418500 INFO:SerialBattery: 2024-08-15 19:41:55.088109500 INFO:SerialBattery:Starting dbus-serialbattery 2024-08-15 19:41:55.090213500 INFO:SerialBattery:Venus OS v3.41 2024-08-15 19:41:55.090869500 INFO:SerialBattery:dbus-serialbattery v1.3.20240705 2024-08-15 19:42:11.110805500 INFO:SerialBattery:-- Testing BMS: 1 of 3 rounds 2024-08-15 19:42:11.110813500 INFO:SerialBattery:Testing Seplos 2024-08-15 19:42:12.261076500 INFO:SerialBattery:Connection established to Seplos 2024-08-15 19:42:20.158854500 INFO:SerialBattery:Found existing battery with DeviceInstance = 3 2024-08-15 19:42:20.605706500 INFO:SerialBattery:DeviceInstance = 3
tail -n 200 -f /data/log/serial-starter/current | tai64nlocal ... 2024-08-08 14:54:21.942664500 INFO: Start service dbus-serialbattery.ttyUSB1 once 2024-08-08 14:54:23.278951500 INFO: Start service dbus-serialbattery.ttyUSB2 once 2024-08-15 19:41:25.471782500 INFO: Start service vedirect-interface.ttyS5 2024-08-15 19:41:26.599900500 INFO: Start service vedirect-interface.ttyS6 2024-08-15 19:41:27.707592500 INFO: Start service vedirect-interface.ttyS7 2024-08-15 19:41:28.944411500 INFO: Start service dbus-cgwacs.ttyUSB0 once 2024-08-15 19:41:30.167358500 INFO: Start service dbus-cgwacs.ttyUSB1 once 2024-08-15 19:41:31.361507500 INFO: Start service dbus-cgwacs.ttyUSB2 once 2024-08-15 19:41:34.585856500 INFO: Start service gps-dbus.ttyUSB0 once 2024-08-15 19:41:35.805906500 INFO: Start service gps-dbus.ttyUSB1 once 2024-08-15 19:41:37.035723500 INFO: Start service gps-dbus.ttyUSB2 once 2024-08-15 19:41:44.343171500 INFO: Start service vedirect-interface.ttyUSB0 once 2024-08-15 19:41:45.574362500 INFO: Start service vedirect-interface.ttyUSB1 once 2024-08-15 19:41:46.788566500 INFO: Start service vedirect-interface.ttyUSB2 once 2024-08-15 19:41:50.065782500 INFO: Start service dbus-serialbattery.ttyUSB0 once 2024-08-15 19:41:51.336263500 INFO: Start service dbus-serialbattery.ttyUSB1 once 2024-08-15 19:41:52.608211500 INFO: Start service dbus-serialbattery.ttyUSB2 once
/var/log/messages Aug 15 12:59:17 einstein user.warn kernel: [1239309.529431] 3fa0: 00000000 00d2b598 00000000 00000008 Aug 15 12:59:17 einstein user.warn kernel: [1239309.537776] 3fc0: 0000000b beaa3478 00e40c30 000000af 00e4cbf0 00e478fc 00000000 00000000 Aug 15 12:59:17 einstein user.warn kernel: [1239309.546120] 3fe0: 00000000 00d2b598 00d2b598 4ee017e8 000f0010 00000002 Aug 16 02:05:01 einstein cron.info CROND[19984]: (root) CMD (/opt/victronenergy/swupdate-scripts/check-updates.sh -auto -delay) Aug 16 02:05:01 einstein cron.info CROND[19983]: (root) CMDOUT ( Checking for updates ) Aug 16 02:05:01 einstein cron.info CROND[19983]: (root) CMDOUT (arguments: -auto -delay)
/var/log drwx------ 2 root root 4096 Aug 15 03:19 dbus-systemcalc-py drwx------ 2 root root 4096 Aug 15 05:05 node-red-venus drwx------ 2 root root 4096 Aug 15 10:10 vrmlogger drwx------ 2 root root 4096 Aug 15 11:07 ssh-tunnel drwx------ 2 root root 4096 Aug 15 11:26 flashmq drwxr-xr-x 2 root root 4096 Aug 16 00:00 BatteryAggregator drwx------ 2 root root 4096 Aug 16 02:00 localsettings -rw-r--r-- 1 root root 31628 Aug 16 02:05 messages -rw-r--r-- 1 root root 292 Aug 16 02:27 lastlog
What i try to do is move node-red from the Cerbo to an extra device this should reduce CPU % load by ~7% also there should be more mem free. It should not be an issue as the cerbo never runs >60% cpu load but maybe it helps.
Eventually you could also try to increase the poll interval
Thanks I will try to reduce poll intervalls if the disabling of large feature does not help. I meanwhile remove node-red which brings ~5-10% less CPU load and some free memory gain. Maybe this helps lets see - if it now runs for some weeks instead of 3-5 days without restart it should be fine.
changed poll to every 10s, nodered is as written moved but still restarted and I do not see any errors or hints why. Next step is to go back to standard image instead of large. No idea if this changes anything but maybe worth a try.
root@einstein:~# uptime
05:28:52 up 3 days, 17:24, load average: 1.40, 2.53, 2.58
root@einstein:~# svstat /service/dbus-serialbattery.tty*
/service/dbus-serialbattery.ttyUSB0: up (pid 5287) 8 seconds
/service/dbus-serialbattery.ttyUSB1: up (pid 5348) 7 seconds
/service/dbus-serialbattery.ttyUSB2: up (pid 5398) 6 seconds
root@einstein:~# tail -n 20 -f /data/log/serial-starter/current | tai64nlocal
2024-08-21 12:06:29.001529500 INFO: Start service dbus-serialbattery.ttyUSB1 once
2024-08-21 12:06:30.848893500 INFO: Start service dbus-cgwacs.ttyUSB2 once
2024-08-21 12:06:36.659477500 INFO: Start service gps-dbus.ttyUSB2 once
2024-08-21 12:06:46.777501500 INFO: Start service vedirect-interface.ttyUSB2 once
2024-08-21 12:06:52.331120500 INFO: Start service dbus-serialbattery.ttyUSB2 once
2024-08-25 05:28:21.080110500 INFO: Start service vedirect-interface.ttyS5
2024-08-25 05:28:22.192458500 INFO: Start service vedirect-interface.ttyS6
2024-08-25 05:28:23.315218500 INFO: Start service vedirect-interface.ttyS7
2024-08-25 05:28:24.664268500 INFO: Start service dbus-cgwacs.ttyUSB0 once
2024-08-25 05:28:25.914097500 INFO: Start service dbus-cgwacs.ttyUSB1 once
2024-08-25 05:28:27.186115500 INFO: Start service dbus-cgwacs.ttyUSB2 once
2024-08-25 05:28:30.405547500 INFO: Start service gps-dbus.ttyUSB0 once
2024-08-25 05:28:31.710135500 INFO: Start service gps-dbus.ttyUSB1 once
2024-08-25 05:28:32.901960500 INFO: Start service gps-dbus.ttyUSB2 once
2024-08-25 05:28:40.307532500 INFO: Start service vedirect-interface.ttyUSB0 once
2024-08-25 05:28:41.566139500 INFO: Start service vedirect-interface.ttyUSB1 once
2024-08-25 05:28:42.767474500 INFO: Start service vedirect-interface.ttyUSB2 once
2024-08-25 05:28:46.019584500 INFO: Start service dbus-serialbattery.ttyUSB0 once
2024-08-25 05:28:47.381898500 INFO: Start service dbus-serialbattery.ttyUSB1 once
2024-08-25 05:28:48.774570500 INFO: Start service dbus-serialbattery.ttyUSB2 once
root@einstein:~# tail -n100 -f /var/log/localsettings/current | tai64nlocal
....
2024-08-25 05:28:02.684136500 INFO:root:Setting /Settings/Devices/serialbattery_SeplosBMS16cells_304_0Ah/SocCalc changed. Old: 37.1, New: 37.0
2024-08-25 05:29:10.600213500 INFO:root:Setting /Settings/Devices/serialbattery_SeplosBMS16cells_304_0Ah/LastSeen changed. Old: 1724241990, New: 1724563750
2024-08-25 05:29:10.905831500 INFO:root:Added new setting /Settings//Devices/serialbattery_SeplosBMS16cells_304_0Ah/LastSeen. default:1724563750, type:i, min:0, max: 0, silent: False
2024-08-25 05:29:15.632996500 INFO:root:Setting /Settings/Devices/serialbattery_SeplosBMS16cells_305_0Ah/LastSeen changed. Old: 1724241991, New: 1724563755
2024-08-25 05:29:15.895508500 INFO:root:Added new setting /Settings//Devices/serialbattery_SeplosBMS16cells_305_0Ah/LastSeen. default:1724563755, type:i, min:0, max: 0, silent: False
2024-08-25 05:29:16.939028500 INFO:root:Setting /Settings/Devices/serialbattery_SeplosBMS16cells_280_0Ah/LastSeen changed. Old: 1724242038, New: 1724563756
2024-08-25 05:29:17.179305500 INFO:root:Added new setting /Settings//Devices/serialbattery_SeplosBMS16cells_280_0Ah/LastSeen. default:1724563756, type:i, min:0, max: 0, silent: False
2024-08-25 05:29:23.345680500 INFO:root:Setting /Settings/Relay/0/InitialState changed. Old: 0, New: 1
tail -n100 -f /data/log/dbus-serialbattery.ttyUSB*/current | tai64nlocal
2024-08-21 12:07:18.533104500 INFO:SerialBattery:> CCCM SOC: False | DCCM SOC: False
2024-08-21 12:07:18.533671500 INFO:SerialBattery:> CHARGE FET: None | DISCHARGE FET: None | BALANCE FET: None
2024-08-21 12:07:18.534356500 INFO:SerialBattery:Serial Number/Unique Identifier: SeplosBMS16cells_280.0Ah
2024-08-25 05:28:51.274421500 INFO:SerialBattery:
2024-08-25 05:28:51.275117500 INFO:SerialBattery:Starting dbus-serialbattery
2024-08-25 05:28:51.277149500 INFO:SerialBattery:Venus OS v3.41
2024-08-25 05:28:51.277799500 INFO:SerialBattery:dbus-serialbattery v1.3.20240705
2024-08-25 05:29:07.294346500 INFO:SerialBattery:-- Testing BMS: 1 of 3 rounds
2024-08-25 05:29:07.295159500 INFO:SerialBattery:Testing Seplos
2024-08-25 05:29:08.445096500 INFO:SerialBattery:Connection established to Seplos
2024-08-25 05:29:16.920034500 INFO:SerialBattery:Found existing battery with DeviceInstance = 3
2024-08-25 05:29:17.283889500 INFO:SerialBattery:DeviceInstance = 3
2024-08-25 05:29:17.285671500 INFO:SerialBattery:PID file created successfully: /var/tmp/dbus-serialbattery_3.pid
2024-08-25 05:29:17.286419500 INFO:SerialBattery:Used DeviceInstances = ['3', '1', '2']
2024-08-25 05:29:17.287303500 INFO:SerialBattery:com.victronenergy.battery.ttyUSB2
2024-08-25 05:29:17.321583500 INFO:SerialBattery:publish config values = False
2024-08-25 05:29:17.323883500 INFO:SerialBattery:Battery Seplos connected to dbus from /dev/ttyUSB2
2024-08-25 05:29:17.325403500 INFO:SerialBattery:========== Settings ==========
2024-08-25 05:29:17.326351500 INFO:SerialBattery:> Connection voltage: 52.38 V | Current: -0.67 A | SoC: 35.7%
2024-08-25 05:29:17.327363500 INFO:SerialBattery:> Cell count: 16 | Cells populated: 16
2024-08-25 05:29:17.328280500 INFO:SerialBattery:> LINEAR LIMITATION ENABLE: True
2024-08-25 05:29:17.329329500 INFO:SerialBattery:> MIN CELL VOLTAGE: 2.900 V | MAX CELL VOLTAGE: 3.450 V| FLOAT CELL VOLTAGE: 3.400 V
2024-08-25 05:29:17.330389500 INFO:SerialBattery:> MAX BATTERY CHARGE CURRENT: 150.0 A | MAX BATTERY DISCHARGE CURRENT: 140.0 A
2024-08-25 05:29:17.332134500 INFO:SerialBattery:> CVCM: True
2024-08-25 05:29:17.333889500 INFO:SerialBattery:> CCCM CV: True | DCCM CV: True
2024-08-25 05:29:17.334616500 INFO:SerialBattery:> CCCM T: True | DCCM T: True
2024-08-25 05:29:17.337165500 INFO:SerialBattery:> CCCM SOC: False | DCCM SOC: False
2024-08-25 05:29:17.338529500 INFO:SerialBattery:> CHARGE FET: None | DISCHARGE FET: None | BALANCE FET: None
2024-08-25 05:29:17.339768500 INFO:SerialBattery:Serial Number/Unique Identifier: SeplosBMS16cells_280.0Ah
root@einstein:/var/log# tail -f messages
Aug 24 02:05:01 einstein cron.info CROND[17331]: (root) CMD (/opt/victronenergy/swupdate-scripts/check-updates.sh -auto -delay)
Aug 24 02:05:01 einstein cron.info CROND[17330]: (root) CMDOUT (*** Checking for updates ***)
Aug 24 02:05:01 einstein cron.info CROND[17330]: (root) CMDOUT (arguments: -auto -delay)
Aug 24 02:05:01 einstein cron.info CROND[17330]: (root) CMDOUT (Auto-update disabled, exit.)
Aug 24 04:48:29 einstein daemon.info connmand[842]: ntp: time slew +1.273279 s
Aug 24 23:00:46 einstein daemon.info connmand[842]: ntp: time slew +1.269580 s
Aug 25 02:05:01 einstein cron.info CROND[7450]: (root) CMD (/opt/victronenergy/swupdate-scripts/check-updates.sh -auto -delay)
Aug 25 02:05:01 einstein cron.info CROND[7449]: (root) CMDOUT (*** Checking for updates ***)
Aug 25 02:05:01 einstein cron.info CROND[7449]: (root) CMDOUT (arguments: -auto -delay)
Aug 25 02:05:01 einstein cron.info CROND[7449]: (root) CMDOUT (Auto-update disabled, exit.)
root@einstein:/var/log# ls -lart
drwxr-xr-x 66 root root 4096 Aug 23 08:33 .
drwx------ 2 root root 4096 Aug 24 04:39 start-gui
-rw-r--r-- 1 root root 26838 Aug 25 02:05 messages
-rw-r--r-- 1 root root 292 Aug 25 05:17 lastlog
drwxr-xr-x 2 root root 4096 Aug 25 05:28 BatteryAggregator
drwx------ 2 root root 4096 Aug 25 05:29 localsettings
From the serialstarter
log you see that multiple serial device services where started again. This indicates that there is a problem in Venus OS and a restart of this services is triggered somehow. Did you ask in the Victron Community?
No not for this issue as so far I never got useful answers from this community forum :( - I think not related to the people but due to "no structure" of the platform. Looking into the below i think the issue seems somehow usb interface related - with that bit more concrete info I will ask the community.
looking into which services were restarted it looks to be USB interface related I just listed all services with similar up/downtime as serial battery: root@einstein:~# svstat /service/* | grep -i "9... seconds" /service/dbus-cgwacs.ttyUSB0: down 9162 seconds /service/dbus-cgwacs.ttyUSB1: down 9161 seconds /service/dbus-cgwacs.ttyUSB2: down 9160 seconds /service/dbus-serialbattery.ttyUSB0: up (pid 5287) 9144 seconds /service/dbus-serialbattery.ttyUSB1: up (pid 5348) 9143 seconds /service/dbus-serialbattery.ttyUSB2: up (pid 5398) 9142 seconds /service/gps-dbus.ttyUSB0: down 9152 seconds /service/gps-dbus.ttyUSB1: down 9151 seconds /service/gps-dbus.ttyUSB2: down 9150 seconds /service/vedirect-interface.ttyS5: up (pid 4531) 9169 seconds, normally down /service/vedirect-interface.ttyS6: up (pid 4581) 9168 seconds, normally down /service/vedirect-interface.ttyS7: up (pid 4616) 9167 seconds, normally down /service/vedirect-interface.ttyUSB0: down 9147 seconds /service/vedirect-interface.ttyUSB1: down 9146 seconds /service/vedirect-interface.ttyUSB2: down 9145 seconds
Maybe you use a USB hub?
Yes I do as there is no other way to connect the devices. I bought one that was recommended by Venus users (included power supply). But I could replace for test purposes.
Have you at least two USB ports? So you could at least figure out, if the device that is connected directly, does not have the same behaviour as the others connected via the USB hub.
I put one USB connector directly on the cerbo two I left on the hub. Lets see if this changes anything. I went back to standard venus (no large) as well. Note: no answer from community
Can you link the community post here?
For testing you could try this:
To log USB device disconnections on a system running Dunfell Linux (Yocto Project version 3.1), you can use the udev
system to trigger logging when a USB device is disconnected. Below is a guide to achieve this:
Create a udev
Rule
udev
rules allow you to run custom scripts or commands in response to hardware events, such as USB device connections or disconnections.
Create a new udev
rule file:
bash
sudo nano /etc/udev/rules.d/99-usb-disconnect.rules
Add the following content to the file:
bash
ACTION=="remove", SUBSYSTEM=="usb", RUN+="/usr/local/bin/usb-disconnect-logger.sh"
ACTION=="remove"
triggers the rule when a USB device is removed.SUBSYSTEM=="usb"
limits the rule to USB devices.RUN+="/usr/local/bin/usb-disconnect-logger.sh"
specifies the script to run when the rule is triggered.Create the Logging Script
Create a script that will handle logging when a USB device is disconnected.
Create the script:
bash
sudo nano /usr/local/bin/usb-disconnect-logger.sh
Add the following content to the script:
bash
#!/bin/bash
echo "$(date): USB device disconnected - Device Info: $DEVNAME" >> /var/log/usb-disconnect.log
This script logs the date and the device name to /var/log/usb-disconnect.log.
Make the script executable:
bash
sudo chmod +x /usr/local/bin/usb-disconnect-logger.sh
Reload udev
Rules
After creating the udev
rule and script, reload the udev
rules to apply the changes:
bash
sudo udevadm control --reload-rules
sudo udevadm trigger
Verify Logging
Test the setup by disconnecting a USB device and checking the log file:
bash
cat /var/log/usb-disconnect.log
You should see entries corresponding to the disconnection events.
This setup ensures that every time a USB device is removed, an entry is logged with the date, time, and device name.
That this way the log grows forever, therefore use it only for troubleshooting.
Meanwhile I think it was USB Hub related. I switched to another modell and so far since 11 days no restarts. I will let it run for a while and then switch back to the previous one to verify.
Describe the problem
Every few days the service seems to restart - is this a feature? Only notifiying it as the MPII throws a low voltage alarm at this moment. I do not see any error in the logs how to nail down the issue?
Driver version of the currently installed driver
v1.3.20240705
Driver version of the last known working driver
No response
Venus OS device type
Cerbo GX
Venus OS version
3.41
BMS type
Seplos
Cell count
16
Battery count
3
Connection type
Serial USB adapter to RS485
Config file
Relevant log output
Any other information that may be helpful
No response