Venus OS v3.70 release version - After reboot "low battery voltage" alarm

Q&A and troubleshooting
1

As I have described in a previous post with 3.70 beta unfortunately a battery communication issue got introduced. Unfortunately it had been not solved between 3.70~60 and final release.

Issue:
After any reboot a “low battery warning” is generated (CAN communication with BYD LVL 15,4).
Battery was in that moment at a 52,3V level, so far before a low voltage. After 1 to 2 minutes the alarm gets cleared again.
In previous stable versions this was never an issue (also confirmed by @dmsims).

CAN communication seems to be without errors:

grafik
grafik1246×726 52.2 KB

Therefore I would assume an initialisation issue.

I would highly appreciate, if route cause could be identfied and fixed.

2

It seems I have the same issues, but with a Lynx Smart BMS.

I updated my cerbo from 3.51 to 3.70 this week-end and since then a reboot of the cerbogx generate a “low battery” and a “BMS lost” alarm and my multiplus II AC out shut down.

3

Can you check if this also happens when Signal K and Node-RED are disabled?

4

The problem happens even without SignalK and Node-RED.

I also tested without the nmea connection in case it was messing with the CAN communication with the same result.

One of the two MPPT also complained about losing the BMS :

image
image3272×976 185 KB

5

Can you enable remote support on that site?

6

Remote support is now enabled on installation 256071.

I’ve made a reinstall to remove my modifications and work on a clean system (and yes the problem is still here :wink: )

7

@jeroen On my side I don’t use Signal K. Related to NodeRed, yes the issue disappeared after deactivation. After having re-activated NodeRed again I was even more surprised that on my side the Low Battery error does not occur anymore. What magic can that process incur ?!?

@dmsims COuld you please also describe your scenario?

8

Can you check what happens if you remove the USB pen drive?

9

When restarting without the usb drive I did not have the alarms.

Adding it back and the problem reappears.

Both tests where made without SignalK and Node-RED.

The USB drive is only present to store data when at sea without internet connection. I did not check but it should be empty.

10

If you switch to the Classic UI and plug the pen drive in, how long does if take for a popup to show? (The New UI doesn’t have that popup). During boot it takes several minutes, stalling everything. From the looks of it seems wise to get yourself a new pen drive.

11

When plugin the usb drive the popup appear in about 8 seconds, but there is the warning about the udev worker being slow after 1 minute.

Mar  4 17:37:33 einstein kern.info kernel: [30426.272292] usb 1-1: new high-speed USB device number 3 using ehci-platform
Mar  4 17:37:34 einstein kern.info kernel: [30426.454728] usb 1-1: New USB device found, idVendor=0781, idProduct=5583, bcdDevice= 1.00
Mar  4 17:37:34 einstein kern.info kernel: [30426.463496] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Mar  4 17:37:34 einstein kern.info kernel: [30426.470769] usb 1-1: Product:  SanDisk 3.2Gen1
Mar  4 17:37:34 einstein kern.info kernel: [30426.475717] usb 1-1: Manufacturer:  USB
Mar  4 17:37:34 einstein kern.info kernel: [30426.479922] usb 1-1: SerialNumber: 0101ca484e9ef595f0c859012114f3402aa50a14e90b2739318446f0541d465e3cca000000000000000000007eda03daff89460083558107ca2b000f
Mar  4 17:37:34 einstein kern.info kernel: [30426.573504] usb-storage 1-1:1.0: USB Mass Storage device detected
Mar  4 17:37:34 einstein kern.info kernel: [30426.626065] scsi host0: usb-storage 1-1:1.0
Mar  4 17:37:35 einstein kern.notice kernel: [30427.671395] scsi 0:0:0:0: Direct-Access      USB      SanDisk 3.2Gen1 1.00 PQ: 0 ANSI: 6
Mar  4 17:37:35 einstein kern.notice kernel: [30427.725403] sd 0:0:0:0: [sda] 240353280 512-byte logical blocks: (123 GB/115 GiB)
Mar  4 17:37:35 einstein kern.notice kernel: [30427.747605] sd 0:0:0:0: [sda] Write Protect is off
Mar  4 17:37:35 einstein kern.debug kernel: [30427.752571] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
Mar  4 17:37:35 einstein kern.notice kernel: [30427.757136] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Mar  4 17:37:35 einstein kern.info kernel: [30427.846221]  sda: sda1
Mar  4 17:37:35 einstein kern.notice kernel: [30427.849889] sd 0:0:0:0: [sda] Attached SCSI removable disk
Mar  4 17:37:36 einstein kern.err kernel: [30428.361864] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 17:37:36 einstein kern.err kernel: [30428.369981] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 17:37:36 einstein kern.err kernel: [30428.379161] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 17:37:36 einstein kern.err kernel: [30428.391987] FAT-fs (sda): bogus number of reserved sectors
Mar  4 17:37:36 einstein kern.info kernel: [30428.397752] FAT-fs (sda): Can't find a valid FAT filesystem
Mar  4 17:37:37 einstein kern.warn kernel: [30429.861337] FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
Mar  4 17:37:37 einstein user.notice root: mount.sh/automount Auto-mount of [/media/sda1] successful
Mar  4 17:38:38 einstein daemon.warn kernel: [30490.508284] udevd[114]: worker [31983] /devices/platform/soc/1c14000.usb/usb1/1-1/1-1:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1 is taking a long time

There was also a complain about the volume not properly unmounted, so I reformated the whole partition in ext4 and rebooted to test with the same result :

Mar  4 18:11:24 einstein kern.notice kernel: [    8.636209] scsi 0:0:0:0: Direct-Access      USB      SanDisk 3.2Gen1 1.00 PQ: 0 ANSI: 6
Mar  4 18:11:24 einstein kern.notice kernel: [    8.921904] sd 0:0:0:0: [sda] 240353280 512-byte logical blocks: (123 GB/115 GiB)
Mar  4 18:11:24 einstein kern.notice kernel: [    8.931284] sd 0:0:0:0: [sda] Write Protect is off
Mar  4 18:11:24 einstein kern.debug kernel: [    8.931316] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
Mar  4 18:11:24 einstein kern.notice kernel: [    8.932365] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Mar  4 18:11:24 einstein kern.info kernel: [    8.977615]  sda: sda1
Mar  4 18:11:24 einstein kern.notice kernel: [    8.980866] sd 0:0:0:0: [sda] Attached SCSI removable disk
[...]
Mar  4 18:11:24 einstein kern.err kernel: [   10.176615] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 18:11:24 einstein kern.err kernel: [   10.183990] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 18:11:24 einstein kern.err kernel: [   10.191100] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 18:11:24 einstein kern.err kernel: [   10.198481] FAT-fs (sda): bogus number of reserved sectors
Mar  4 18:11:24 einstein kern.info kernel: [   10.204060] FAT-fs (sda): Can't find a valid FAT filesystem
Mar  4 18:11:24 einstein kern.info kernel: [   10.916245] EXT4-fs (sda1): recovery complete
Mar  4 18:11:24 einstein kern.info kernel: [   10.924334] EXT4-fs (sda1): mounted filesystem cd225cf2-b93a-481d-9610-ce5879a1b88c r/w with ordered data mode. Quota mode: disabled.
[...]
Mar  4 18:11:24 einstein daemon.warn kernel: [   73.012456] udevd[115]: worker [132] /devices/platform/soc/1c14000.usb/usb1/1-1/1-1:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1 is taking a long time

I’ve the disabled the rule executing “/etc/init.d/update-data.sh -r” for devices “sd?[0-9]” and restarted : the problem does not occurs and the udev warning is not present.

Mar  4 18:32:51 einstein kern.notice kernel: [    8.246587] scsi 0:0:0:0: Direct-Access      USB      SanDisk 3.2Gen1 1.00 PQ: 0 ANSI: 6
Mar  4 18:32:51 einstein kern.notice kernel: [    9.539987] sd 0:0:0:0: [sda] 240353280 512-byte logical blocks: (123 GB/115 GiB)
Mar  4 18:32:51 einstein kern.notice kernel: [    9.569045] sd 0:0:0:0: [sda] Write Protect is off
Mar  4 18:32:51 einstein kern.debug kernel: [    9.574905] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
Mar  4 18:32:51 einstein kern.notice kernel: [    9.597238] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Mar  4 18:32:51 einstein kern.info kernel: [    9.707990]  sda: sda1
Mar  4 18:32:51 einstein kern.notice kernel: [    9.708623] sd 0:0:0:0: [sda] Attached SCSI removable disk
Mar  4 18:32:51 einstein kern.err kernel: [    9.988927] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 18:32:51 einstein kern.err kernel: [   10.002990] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 18:32:51 einstein kern.err kernel: [   10.027045] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 18:32:51 einstein kern.err kernel: [   10.039776] FAT-fs (sda): bogus number of reserved sectors
Mar  4 18:32:51 einstein kern.info kernel: [   10.045508] FAT-fs (sda): Can't find a valid FAT filesystem
Mar  4 18:32:51 einstein kern.info kernel: [   10.716532] EXT4-fs (sda1): mounted filesystem cd225cf2-b93a-481d-9610-ce5879a1b88c r/w with ordered data mode. Quota mode: disabled.

re-enabling the udev rule, I also change the log level of udev to debug and tried plugin another usb stick. The popup in the gui-v1 take about 5 seconds, but the logs looks the same :

Mar  4 20:13:49 einstein kern.info kernel: [  943.086366] usb 1-1: new high-speed USB device number 4 using ehci-platform
Mar  4 20:13:49 einstein kern.info kernel: [  943.298698] usb 1-1: New USB device found, idVendor=0951, idProduct=1625, bcdDevice= 1.00
Mar  4 20:13:49 einstein kern.info kernel: [  943.307353] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Mar  4 20:13:49 einstein kern.info kernel: [  943.314917] usb 1-1: Product: DT101 II
Mar  4 20:13:49 einstein kern.info kernel: [  943.318971] usb 1-1: Manufacturer: Kingston
Mar  4 20:13:49 einstein kern.info kernel: [  943.323421] usb 1-1: SerialNumber: 001CC0EC32BCF010C7DF125C
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.334440] udevd[111]: Validate module index
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.334817] udevd[111]: seq 1742 queued, 'add' 'usb'
Mar  4 20:13:49 einstein kern.info kernel: [  943.335987] usb-storage 1-1:1.0: USB Mass Storage device detected
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.343537] udevd[111]: seq 1742 forked new worker [16208]
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.346864] udevd[111]: seq 1743 queued, 'add' 'usb'
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.349411] udevd[16208]: seq 1742 running
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.353180] udevd[111]: seq 1744 queued, 'add' 'workqueue'
Mar  4 20:13:49 einstein kern.info kernel: [  943.354702] scsi host0: usb-storage 1-1:1.0
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.360448] udevd[16208]: no db file to read /run/udev/data/c189:3: No such file or directory
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.360700] udevd[16208]: IMPORT builtin 'usb_id' /lib/udev/rules.d/50-udev-default.rules:13
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.361789] udevd[16208]: IMPORT builtin 'hwdb' /lib/udev/rules.d/50-udev-default.rules:13
Mar  4 20:13:49 einstein daemon.debug kernel: [  943.361852] udevd[16208]: IMPORT builtin 'hwdb' returned non-zero
Mar  4 20:13:50 einstein kern.notice kernel: [  944.405653] scsi 0:0:0:0: Direct-Access     Kingston DT101 II         1.00 PQ: 0 ANSI: 2
Mar  4 20:13:50 einstein kern.notice kernel: [  944.423855] sd 0:0:0:0: [sda] 7818184 512-byte logical blocks: (4.00 GB/3.73 GiB)
Mar  4 20:13:50 einstein kern.notice kernel: [  944.434111] sd 0:0:0:0: [sda] Write Protect is off
Mar  4 20:13:50 einstein kern.debug kernel: [  944.439516] sd 0:0:0:0: [sda] Mode Sense: 03 00 00 00
Mar  4 20:13:50 einstein kern.warn kernel: [  944.441265] sd 0:0:0:0: [sda] No Caching mode page found
Mar  4 20:13:50 einstein kern.warn kernel: [  944.446896] sd 0:0:0:0: [sda] Assuming drive cache: write through
Mar  4 20:13:50 einstein kern.info kernel: [  944.498948]  sda: sda1
Mar  4 20:13:50 einstein kern.notice kernel: [  944.502117] sd 0:0:0:0: [sda] Attached SCSI removable disk
Mar  4 20:13:51 einstein kern.err kernel: [  944.906783] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 20:13:51 einstein kern.err kernel: [  944.924612] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 20:13:51 einstein kern.err kernel: [  944.940701] EXT4-fs (sda): VFS: Can't find ext4 filesystem
Mar  4 20:13:51 einstein kern.err kernel: [  944.967377] FAT-fs (sda): invalid media value (0xd8)

Mar  4 20:13:51 einstein kern.info kernel: [  944.972647] FAT-fs (sda): Can't find a valid FAT filesystem
Mar  4 20:13:52 einstein user.notice root: mount.sh/automount Auto-mount of [/media/sda1] successful
Mar  4 20:13:55 einstein daemon.debug kernel: [  948.789421] udevd[111]: Validate module index
Mar  4 20:13:58 einstein daemon.debug kernel: [  951.793012] udevd[111]: Validate module index
Mar  4 20:14:01 einstein daemon.debug kernel: [  954.796550] udevd[111]: Validate module index
Mar  4 20:14:04 einstein daemon.debug kernel: [  957.797335] udevd[111]: Validate module index
Mar  4 20:14:07 einstein daemon.debug kernel: [  960.800831] udevd[111]: Validate module index
Mar  4 20:14:10 einstein daemon.debug kernel: [  963.802443] udevd[111]: Validate module index
Mar  4 20:14:13 einstein daemon.debug kernel: [  966.805784] udevd[111]: Validate module index
Mar  4 20:14:16 einstein daemon.debug kernel: [  969.819474] udevd[111]: Validate module index
Mar  4 20:14:19 einstein daemon.debug kernel: [  972.820341] udevd[111]: Validate module index
Mar  4 20:14:22 einstein daemon.debug kernel: [  975.823893] udevd[111]: Validate module index
Mar  4 20:14:25 einstein daemon.debug kernel: [  978.825899] udevd[111]: Validate module index
Mar  4 20:14:28 einstein daemon.debug kernel: [  981.829408] udevd[111]: Validate module index
Mar  4 20:14:31 einstein daemon.debug kernel: [  984.833099] udevd[111]: Validate module index
Mar  4 20:14:34 einstein daemon.debug kernel: [  987.835770] udevd[111]: Validate module index
Mar  4 20:14:37 einstein daemon.debug kernel: [  990.839285] udevd[111]: Validate module index
Mar  4 20:14:40 einstein daemon.debug kernel: [  993.842754] udevd[111]: Validate module index
Mar  4 20:14:43 einstein daemon.debug kernel: [  996.844566] udevd[111]: Validate module index
Mar  4 20:14:46 einstein daemon.debug kernel: [  999.848038] udevd[111]: Validate module index
Mar  4 20:14:49 einstein daemon.debug kernel: [ 1002.849242] udevd[111]: Validate module index
Mar  4 20:14:52 einstein daemon.warn kernel: [ 1005.852586] udevd[111]: worker [16208] /devices/platform/soc/1c14000.usb/usb1/1-1/1-1:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1 is taking a long time
Mar  4 20:14:52 einstein daemon.debug kernel: [ 1005.866712] udevd[111]: Validate module index
Mar  4 20:14:55 einstein daemon.debug kernel: [ 1008.874527] udevd[111]: Validate module index
Mar  4 20:14:58 einstein daemon.debug kernel: [ 1011.878102] udevd[111]: Validate module index
Mar  4 20:15:01 einstein daemon.debug kernel: [ 1014.881797] udevd[111]: Validate module index
Mar  4 20:15:04 einstein daemon.debug kernel: [ 1017.884559] udevd[111]: Validate module index
Mar  4 20:15:07 einstein daemon.debug kernel: [ 1020.886750] udevd[111]: Validate module index
Mar  4 20:15:10 einstein daemon.debug kernel: [ 1023.888531] udevd[111]: Validate module index
Mar  4 20:15:13 einstein daemon.debug kernel: [ 1026.894895] udevd[111]: Validate module index
Mar  4 20:15:16 einstein daemon.debug kernel: [ 1029.898415] udevd[111]: Validate module index
Mar  4 20:15:19 einstein daemon.debug kernel: [ 1032.902226] udevd[111]: Validate module index
Mar  4 20:15:22 einstein daemon.debug kernel: [ 1035.905995] udevd[111]: Validate module index
Mar  4 20:15:25 einstein daemon.debug kernel: [ 1038.909482] udevd[111]: Validate module index
Mar  4 20:15:28 einstein daemon.debug kernel: [ 1041.913081] udevd[111]: Validate module index
Mar  4 20:15:31 einstein daemon.debug kernel: [ 1044.914636] udevd[111]: Validate module index
Mar  4 20:15:34 einstein daemon.debug kernel: [ 1047.918122] udevd[111]: Validate module index
Mar  4 20:15:37 einstein daemon.debug kernel: [ 1050.920035] udevd[111]: Validate module index
Mar  4 20:15:40 einstein daemon.debug kernel: [ 1053.927058] udevd[111]: Validate module index
Mar  4 20:15:43 einstein daemon.debug kernel: [ 1056.929568] udevd[111]: Validate module index
Mar  4 20:15:46 einstein daemon.debug kernel: [ 1059.944583] udevd[111]: Validate module index
Mar  4 20:15:49 einstein daemon.debug kernel: [ 1062.947444] udevd[111]: Validate module index
Mar  4 20:15:52 einstein daemon.debug kernel: [ 1065.951025] udevd[111]: Validate module index
Mar  4 20:15:55 einstein daemon.debug kernel: [ 1068.952379] udevd[111]: Validate module index
Mar  4 20:15:58 einstein daemon.debug kernel: [ 1071.955437] udevd[111]: Validate module index
Mar  4 20:16:01 einstein daemon.debug kernel: [ 1074.958582] udevd[111]: Validate module index
Mar  4 20:16:04 einstein daemon.debug kernel: [ 1077.962169] udevd[111]: Validate module index
Mar  4 20:16:07 einstein daemon.debug kernel: [ 1080.964554] udevd[111]: Validate module index
Mar  4 20:16:10 einstein daemon.debug kernel: [ 1083.967188] udevd[111]: Validate module index
Mar  4 20:16:13 einstein daemon.debug kernel: [ 1086.969212] udevd[111]: Validate module index
Mar  4 20:16:16 einstein daemon.debug kernel: [ 1089.972761] udevd[111]: Validate module index
Mar  4 20:16:19 einstein daemon.debug kernel: [ 1092.976232] udevd[111]: Validate module index
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1095.980044] udevd[111]: Validate module index
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1096.182654] udevd[16208]: '/etc/init.d/update-data.sh -r' [16276] exit with return code 0
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1096.182809] udevd[16208]: adding watch on '/dev/sda1'
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1096.183554] udevd[16208]: created db file '/run/udev/data/b8:1' for '/devices/platform/soc/1c14000.usb/usb1/1-1/1-1:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1'
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1096.184977] udevd[16208]: passed 1345 byte device to netlink monitor 0x3a0860
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1096.185035] udevd[16208]: seq 1755 processed
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1096.186502] udevd[111]: passed 242 byte device to netlink monitor 0x39f3c0
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1096.187257] udevd[16208]: seq 1756 running
Mar  4 20:16:22 einstein daemon.debug kernel: [ 1096.188522] udevd[16208]: no db file to read /run/udev/data/+scsi:0:0:0:0: No such file or directory
Mar  4 20:16:25 einstein daemon.debug kernel: [ 1099.192552] udevd[111]: cleanup idle workers
Mar  4 20:16:25 einstein daemon.debug kernel: [ 1099.192856] udevd[111]: Validate module index
Mar  4 20:16:25 einstein daemon.debug kernel: [ 1099.192936] udevd[16231]: Unload module index
Mar  4 20:16:25 einstein daemon.debug kernel: [ 1099.193620] udevd[16208]: Unload module index
Mar  4 20:16:25 einstein daemon.debug kernel: [ 1099.195376] udevd[16212]: Unload module index
Mar  4 20:16:25 einstein daemon.debug kernel: [ 1099.197501] udevd[111]: worker [16208] exited
Mar  4 20:16:25 einstein daemon.debug kernel: [ 1099.197740] udevd[111]: worker [16212] exited
Mar  4 20:16:25 einstein daemon.debug kernel: [ 1099.198254] udevd[111]: worker [16231] exited

It seems the “udevadm settle” in /etc/init.d/update-data.sh stay stuck for some reason for 150s

I tried to add a –timeout=10 and it seems to help, but I dont know what cause this behaviour.

12

I don’t know either what exactly is going on. I tried to reproduce it, but managed to do so only once. Anyway, it doesn’t really matter. The update-data.sh -r is called from udev. Such a program is not allowed to create child process and there is no reason to do that either, since it gets called after the filesystem has been mounted. I changed it to not do that if “-r” is passed. Thanks!

13

I can have a look, but then I need to know the site-id and Remote Support must be enabled.

14

I can confirm that the change in v3.80~3 works for me.

Thanks !

1 Like