Exceptions in persistence layer after migration to openHAB 3

I did a clean reinstall of openHAB 3 via openhabian. After that I installed all bindings, services etc. I had previously and imported my previous configuration and scripts. Now I’m trying to get everything to operate again like before.

There’s one problem related to persistence which I’m having trouble with:

All items which I want to persist I’ve included in a group Gpersist. I’ve a rule

rule "Item update arrived, store timestamp"
when
    Member of Gpersist received update
then
    logDebug("persistor", "persisting " + (triggeringItem as GenericItem).name)
    (triggeringItem as GenericItem).persist()
    (triggeringItem as GenericItem).persist("influxdb")
end

and another one persisting items which are in the group GwarningsSensorsBatteryLevelsMin

rule "Battery level update arrived, store timestamp"
when
    Member of GwarningsSensorsBatteryLevelsMin received update
then
    logDebug("batterylevels", "initializing timestamp for " + (triggeringItem as GenericItem).name)
    (triggeringItem as GenericItem).persist()
    (triggeringItem as GenericItem).persist("influxdb")
end

MapDB is my default persistence service, but I need to also store the items in an InfluxDB.

For some time, I see this debug logging stating that the items I’m interested in, are persisted. But this suddenly stops. I’ve checked for errors in my openhab.log and found these:

2021-12-16 04:03:16.233 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'persistor-1' failed: java.nio.channels.ClosedByInterruptException in persistor
2021-12-16 04:03:30.416 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'persistor-1' failed: java.nio.channels.ClosedChannelException in persistor
2021-12-16 16:19:29.771 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'batterywarnings-4' failed: java.nio.channels.ClosedChannelException in batterywarnings
2021-12-16 17:11:07.969 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'batterywarnings-4' failed: java.nio.channels.ClosedChannelException in batterywarnings
2021-12-16 17:22:03.401 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'persistor-1' failed: java.io.EOFException in persistor

From 17:22 on I do not see the above mentioned debug log messages any more. I’m guessing that the persistence service errored to often and then stops its work.

There are items which are in both groups, so it could be some kind of race condition, but it’s only a wild guess. Could someone please support me finding out the reason for these exceptions?

  • Platform information:
    • Hardware: Raspberry Pi 4 Model B
    • OS: Raspbian GNU/Linux 11 (bullseye)
    • Java Runtime Environment: OpenJDK Runtime Environment Zulu11.52+13-CA (build 11.0.13+8-LTS)
    • openHAB version: 3.1.0

I kept getting these exceptions, but I could not make out a reason for it. I already deleted my MapDB storage since I found some hints that I helped a few people. Today I saw this in my logs:

17224:147220-2021-12-18 11:50:04.642 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
17225-147221-java.io.IOError: java.nio.channels.ClosedChannelException
17226-147222-   at org.mapdb.Volume$FileChannelVol.getLong(Volume.java:977) ~[?:?]
17227-147223-   at org.mapdb.StoreWAL.update(StoreWAL.java:382) ~[?:?]
17228-147224-   at org.mapdb.Caches$HashTable.update(Caches.java:270) ~[?:?]
17229-147225-   at org.mapdb.EngineWrapper.update(EngineWrapper.java:63) ~[?:?]
17230-147226-   at org.mapdb.BTreeMap.put2(BTreeMap.java:707) ~[?:?]
17231-147227-   at org.mapdb.BTreeMap.put(BTreeMap.java:643) ~[?:?]
17232-147228-   at org.openhab.persistence.mapdb.internal.MapDbPersistenceService.store(MapDbPersistenceService.java:186) ~[?:?]
17233-147229-   at org.openhab.core.persistence.internal.PersistItemsJob.run(PersistItemsJob.java:58) ~[?:?]

So, even though I deleted my MapDB data, I have exceptions in the persistence layer.

I had some strange things happening when flashing OH 3.1 onto my SD card:

  • flashing failed on the first try
  • flashing was slow – about max 10 MB/s on a Sandisk Extreme Pro card
  • flashing speed varied from 2-11 MB/s

Thus I ordered a new Sandisk Extreme Pro card and flashed it today. I’ll keep you posted, if it helps.

I’m quite confident that it will, because I had other issues with openHAB, too: a Group containing several lights did not update properly when some states of contained lights changed, which occurred also after a reboot – but with the new SD card this issue is gone.

A sidenote to the maintainers, if someone reads this: it would be a good feature to monitor file system integrity or at least I/O operation errors since most users will probably have openHAB run on SD cards. In such cases, errors should be propagated.

Unfortunately, the problems re-appeared :frowning: I also got some persistence exceptions again:

1816:42212:2021-12-18 16:27:35.996 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'persistor-1' failed: java.nio.channels.ClosedByInterruptException in persistor
1817:42213:2021-12-18 16:27:43.946 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'batterywarnings-4' failed: java.nio.channels.ClosedChannelException in batterywarnings
1818:42214:2021-12-18 16:27:43.950 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'batterywarnings-4' failed: java.nio.channels.ClosedChannelException in batterywarnings
1819:42215:2021-12-18 16:27:43.953 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'batterywarnings-4' failed: java.nio.channels.ClosedChannelException in batterywarnings

I tried checking the file system, but maybe I did something wrong, here are the startup logs:

Dec 18 16:35:26 openhabian systemd-fsck[127]: Please pass 'fsck.mode=force' on the kernel command line rather than creating /forcefsck on the root file system.
Dec 18 16:35:26 openhabian systemd-fsck[147]: e2fsck 1.46.2 (28-Feb-2021)
Dec 18 16:35:26 openhabian systemd-fsck[147]: Pass 1: Checking inodes, blocks, and sizes
Dec 18 16:35:26 openhabian systemd-fsck[147]: Pass 2: Checking directory structure
Dec 18 16:35:26 openhabian systemd-fsck[147]: Pass 3: Checking directory connectivity
Dec 18 16:35:26 openhabian systemd-fsck[147]: Pass 4: Checking reference counts
Dec 18 16:35:26 openhabian systemd-fsck[147]: Pass 5: Checking group summary information
Dec 18 16:35:26 openhabian systemd-fsck[147]: rootfs: 69913/1865344 files (0.2% non-contiguous), 1524304/7725184 blocks
Dec 18 16:35:26 openhabian systemd-fsck[218]: Please pass 'fsck.mode=force' on the kernel command line rather than creating /forcefsck on the root file system.
Dec 18 16:35:26 openhabian systemd-fsck[247]: fsck.fat 4.2 (2021-01-31)
Dec 18 16:35:26 openhabian systemd-fsck[247]: /dev/mmcblk0p1: 293 files, 98584/516190 clusters
Dec 18 16:35:26 openhabian kernel: [    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=0 bcm2708_fb.fbheight=0 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:D5:43:05 vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000  console=ttyS0,115200 console=tty1 root=PARTUUID=bc45598e-02 rootfstype=ext4 fsck.repair=yes rootwait
Dec 18 16:36:11 openhabian systemd[1]: systemd-fsckd.service: Succeeded.
Dec 18 16:36:11 openhabian systemd[1]: systemd-fsckd.service: Consumed 1.376s CPU time.

Is my file system ok? Do I have to check it differently?`