Mapdb: no restore at startup for item status

Tags: #<Tag:0x00007f616f196748>

The actual status of selected items will not be stored to mapdb and/or will not be restored at startup?!
Cause after reboot, I will not find the status of the contacts in my sitemap.
And did not find any hint for this bihaviour in the community.

I am using the following setup:
Hardware: RPI 4 with SSD (including boot from SSD)
openHAB version: 2.5.7-1 (Release Build)
ZRAM: not in use

facts:

  • mapdb is selected via Paper UI for persistence
  • entries for persistence neither in addons.cfg nor in mapdb.cfg

mapdb.persist:

Strategies {
default = everyChange 
}

Items {
gContact,gBattery,gTemperatur,gWallplug : strategy = everyChange, restoreOnStartup
gContact*,gBattery*,gTemperatur*,gWallplug*: strategy = everyChange, restoreOnStartup
}

The contacts are ZWave battery Door/Window contacts.
What I am doing wrong here? Every support is appreciated, thanks in advance.

BR
Thomas

Do you see in logs anything similar to
bundle org.openhab.persistence.mapdb The activate method has thrown an exception

I had this the other day, sudo openhab-cli reset-ownership solved it.

Related -

Some areas to look at and report on there

Thank you very much for both very fast replies @sasha_jpr @rossko57 . I will analyze the proposals and compare it to what I am doing wrong or what is running wrong. So I will come back with the results here.

Update 29th July:
1. I checked the owner topic, proposed by @sasha_jpr
–> everything looked pretty fine (in my opinion):

Version: 2.5.7 (Build)

User: openhab (Active Process 729)
User Groups: openhab tty dialout audio bluetooth gpio

Directories: Folder Name | Path | User:Group
----------- | ---- | ----------
OPENHAB_HOME | /usr/share/openhab2 | openhab:openhab
OPENHAB_RUNTIME | /usr/share/openhab2/runtime | openhab:openhab
OPENHAB_USERDATA | /var/lib/openhab2 | openhab:openhab
OPENHAB_CONF | /etc/openhab2 | openhab:openhab
OPENHAB_LOGDIR | /var/log/openhab2 | openhab:openhab
OPENHAB_BACKUPS | /var/lib/openhab2/backups | openhab:openhab

URLs: http://192.168.178.42:8080
https://192.168.178.42:8443

2. topic regarding REST API, proposed by @rossko57
I used Rest API for the first time, it seems to be a very interesting tool, thanks that bite of knowledge.
It worked, but not in the assumed manor. All contact-items had a defined status visible in the sitemap and iOS app (open or closed) before the reboot. After reboot I found the status of the contact items as same as before or opposite or NULL, but not following any restore rules after reboot.

logs before reboot:
Event-Log: change of status for every item was shown, as anticipated,
openHAB-log: nothing appeared regarding any storage to any database after change of status
REST API: status was shown like in sitemap and iOS app

logs after reboot
Event-Log: could not see any systematic, some items changed from Null to the correct status, some changed it to the opposite status
openHAB-log: nothing appeared regarding any re-storage from any database
REST API: according that what I found out in the Event-log.

Failure: looks like no storage to mapDB will be done!
But mapDB is active in the karaf-console, but in the version 1.14 also after update to openHAB 2.5.7-1 (Release Build)

274 │ Active │ 80 │ 1.14.0 │ openHAB MapDB Persistence Bundle

Possible route causes for failure:

  1. Group def. for my contact items correct?

Group:Contact:OR(OPEN, CLOSED) gContact “Kontakte [(%d)]” (gHaus)

  1. Use of mapDB 1.14.0 correct?
    Earlier request for this topic please find here post#1

If you look down the interactive list, you will find Persistence tools.
You can use that to see if anything is stored in mapdb for one of your Items. No records, nothing to restore. We only expect one record per Item in mapdb, but it has a datestamp of interest.

Use this to find out if records are stored as Items get valid updates.

Use this to find out if non-restored items have any valid mapdb record, after boot but before normal update.

Just to point out, you can never restore the state of Group Items, guessing that is what those are. Group Item states will be calculated from member states.

Members in the following line should be restored. That assumes any of those groups have members.

I got some news, after testing and learning from REST API. I am still searching for the documentation of REST API?!

I updated my mapdb.persist file according to your proposal:

Strategies {
// everyHour : “0 0 * * * ?”
// everyDay : “0 0 0 * * ?”
default = everyChange
}
Items {
* : strategy = everyChange,restoreOnStartup
}

That means every change of every items should be stored to mapdb. Due to using the new SSD for RPI4 , there should be no problem regarding the quantity of writings/readings to storage (like for SD cards).

Using the Persistence topic from REST API, I found out, that for the relevant items (= battery driven Fibaro ZWave contacts for doors/windows) the found state in the persistence curl is equivalent to reality before reboot. There was no physical change of any item before and after reboot. MapDB should run, if not I should not be able to read the persistence curls in REST API! Correct?

But after reboot I found some states correct with 1 datapoint (state the same before and after reboot), some in the opposite state before and after reboot with 1 datapoint, and at least some with 1 datapoint & correct state before reboot, but after reboot with 0 datapoint and “no” state!

Hmm…! I get a litte bit mad by this behaviour. That means for me, that either there is no concrete storage of states to mapdb, or there is a “bug” in mapdb for no restorage after reboot.

But I am wondering as well about the version 1.14.0 of mapdb, which will be installed via paperUI although there are versions 1.15.0 and 2.5.0 available on jfrog!

You’re using it. The interactive utility is the “docs”.

Leave that alone, it works fine in this usage.

Let’s see that, please.

Are you really sure about that?

I am experiencing the same issue with my installation.

Furthermore, I do not see MapDb in the list of Default Persistence Service anymore.


I tried the following without success

  • Reinstall of mapDp
  • sudo openhab-cli reset-ownership
  • Cache deletion and restart
  • restart of openhab service
  • changing the default Persistence in the /etc/openhab2/services/runtime.cfg

This is my mapdb.persist file content:

Strategies {
    default = everyUpdate
}

Items {
        * : strategy = everyChange,restoreOnStartup
}

Any help would be appreciated!

Best regards,
Morten

i’m moving over from here:

started with openhabian-pi-raspios32-202008040929-git5b513cb-crcd22e9bfb.img.xz
installed mapdb persistence binding with
* : strategy = everyChange,restoreOnStartup
created 7 test items

ztamctl before and after every reboot gave this output:

NAME       ALGORITHM DISKSIZE  DATA COMPR TOTAL STREAMS MOUNTPOINT
/dev/zram2 lzo           500M 24.8M 69.5K  332K       4 /opt/zram/zram2
/dev/zram1 lzo           500M 16.5M   17K  176K       4 /opt/zram/zram1
/dev/zram0 lzo           600M    4K   89B   12K       4 [SWAP]

after first reboot(1) the test items were restored correctly. i switched some of these items and made another reboot(2)… well, the items are restored with the same state from the first reboot(1) > not correctly.

[10:31:33] root@openhab:/home/openhabian# systemctl status zram-config
● zram-config.service - zram-config
   Loaded: loaded (/etc/systemd/system/zram-config.service; enabled; vendor preset: enabled)
   Active: active (exited) since Fri 2020-08-07 10:29:13 BST; 2min 34s ago
  Process: 345 ExecStartPre=/bin/rm -f /usr/local/share/zram-config/zram-device-list /usr/local/share/zram-config/zram-d
  Process: 363 ExecStart=/usr/local/bin/zram-config start (code=exited, status=0/SUCCESS)
 Main PID: 363 (code=exited, status=0/SUCCESS)

Aug 07 10:29:13 openhab zram-config[363]: + chmod 755 /opt/zram/zram2/upper /opt/zram/zram2/workdir /var/log
Aug 07 10:29:13 openhab zram-config[363]: + echo 'log                /zram2                /var/log                /log.
Aug 07 10:29:13 openhab zram-config[363]: + invoke-rc.d rsyslog start
Aug 07 10:29:13 openhab zram-config[363]: + invoke-rc.d nginx start
Aug 07 10:29:13 openhab zram-config[363]: + journalctl --flush
Aug 07 10:29:13 openhab zram-config[363]: + '[' '!' -z '' ']'
Aug 07 10:29:13 openhab zram-config[363]: + echo 'createZlog no oldlog dir in ztab'
Aug 07 10:29:13 openhab zram-config[363]: + read -r line
Aug 07 10:29:13 openhab zram-config[363]: + '[' false = true ']'
Aug 07 10:29:13 openhab systemd[1]: Started zram-config.

changed the items to the same value as on reboot(2), made another reboot(3), and suddenly items were restored with value from reboot(2)=reboot(3).

another test:
different values, reboot(4) > restored values from reboot(1)
another reboot(5) without changing items > still restored reboot(1) values

seems i “lost” zram during these reboots:

[10:53:21] root@openhab:/home/openhabian# zramctl
[10:53:27] root@openhab:/home/openhabian# systemctl status zram-config
● zram-config.service - zram-config
   Loaded: loaded (/etc/systemd/system/zram-config.service; enabled; vendor preset: enabled)
   Active: inactive (dead)

after another reboot it’s there again:

[10:59:51] root@openhab:/home/openhabian# zramctl
NAME       ALGORITHM DISKSIZE  DATA COMPR TOTAL STREAMS MOUNTPOINT
/dev/zram2 lzo           500M 24.8M 74.3K  408K       4 /opt/zram/zram2
/dev/zram1 lzo           500M 16.5M   17K  184K       4 /opt/zram/zram1
/dev/zram0 lzo           600M    4K   89B   12K       4 [SWAP]
[10:59:54] root@openhab:/home/openhabian# systemctl status zram-config
● zram-config.service - zram-config
   Loaded: loaded (/etc/systemd/system/zram-config.service; enabled; vendor preset: enabled)
   Active: active (exited) since Fri 2020-08-07 10:56:03 BST; 4min 0s ago
  Process: 245 ExecStartPre=/bin/rm -f /usr/local/share/zram-config/zram-device-list /usr/local/share/zram-config/zram-d
  Process: 271 ExecStart=/usr/local/bin/zram-config start (code=exited, status=0/SUCCESS)
 Main PID: 271 (code=exited, status=0/SUCCESS)

Aug 07 10:56:03 openhab zram-config[271]: + chmod 755 /opt/zram/zram2/upper /opt/zram/zram2/workdir /var/log
Aug 07 10:56:03 openhab zram-config[271]: + echo 'log                /zram2                /var/log                /log.
Aug 07 10:56:03 openhab zram-config[271]: + invoke-rc.d rsyslog start
Aug 07 10:56:03 openhab zram-config[271]: + invoke-rc.d nginx start
Aug 07 10:56:03 openhab zram-config[271]: + journalctl --flush
Aug 07 10:56:03 openhab zram-config[271]: + '[' '!' -z '' ']'
Aug 07 10:56:03 openhab zram-config[271]: + echo 'createZlog no oldlog dir in ztab'
Aug 07 10:56:03 openhab zram-config[271]: + read -r line
Aug 07 10:56:03 openhab zram-config[271]: + '[' false = true ']'
Aug 07 10:56:03 openhab systemd[1]: Started zram-config.

was still active on the next 2 reboots,
but items are still restored with wrong values.

with ~10 reboots values were twice restored with correct values and 8 times with wrong values.

i swear i didn’t do anything else except:

  1. install mapdb binding
  2. create test.items
  3. create mapdb.persist and * : strategy = everyChange,restoreOnStartup

mutliple times 4-6:
4. change item values via habpanel
5. reboot
6. check restored value

did you a) validate values were written to disk (Karaf logging?) and b) wait a reasonably long time between 4 and 5 (10-15 minutes maybe) to avoid caching effects and also between 5 and 6 (did you validate that “restoreOnStartup” was executed ? are you sure the test items cannot be changed by devices or rules ?)
When you do more tests, create a “date” file in the persistence dir right before reboot, and check after reboot. Also use a DateTime item and store the time of its last modification in there.

no.
what does “Karaf logging” mean? if i understand this page correctly log:tail will give me the same results as shown in frontail, won’t it?
i could set log to debug and verify if values are “stored” properly. but i’m not sure if written to disk = Stored 'test1' with state 'ON' in mapdb database ?

i definitely did not wait for 10 minutes.
i did not validate if restoreOnStartup was executed - i really don’t know how.
all i did was watching the log, after reboot testitems changed from NULL to OFF/ON
i don’t know if these changes are triggered by restoreOnStartup - but as on this system there are no rules or whatsoever i can’t imagine anything else triggering these changes.

i probably should make more “structured” reboots instead of just spamming reboot to my poor testsystem…

edit:

ok, before reboot:

[11:50:19] openhabian@openhab:~$ cat /var/lib/openhab2/persistence/date
Fri  7 Aug 11:50:02 BST 2020

after reboot:

[11:54:15] openhabian@openhab:~$ cat /var/lib/openhab2/persistence/date
cat: /var/lib/openhab2/persistence/date: No such file or directory

another try:

[11:54:26] openhabian@openhab:~$ date > /var/lib/openhab2/persistence/date
[11:55:21] openhabian@openhab:~$ cat /var/lib/openhab2/persistence/date
Fri  7 Aug 11:55:21 BST 2020
[11:55:24] openhabian@openhab:~$ zramctl
NAME       ALGORITHM DISKSIZE  DATA COMPR TOTAL STREAMS MOUNTPOINT
/dev/zram2 lzo           500M 24.9M 91.3K  472K       4 /opt/zram/zram2
/dev/zram1 lzo           500M 16.5M   18K  200K       4 /opt/zram/zram1
/dev/zram0 lzo           600M    4K   89B   12K       4 [SWAP]

reboot

[11:59:35] openhabian@openhab:~$ cat /var/lib/openhab2/persistence/date
cat: /var/lib/openhab2/persistence/date: No such file or directory
[11:59:38] openhabian@openhab:~$ zramctl
NAME       ALGORITHM DISKSIZE  DATA COMPR TOTAL STREAMS MOUNTPOINT
/dev/zram2 lzo           500M 24.8M 83.9K  484K       4 /opt/zram/zram2
/dev/zram1 lzo           500M 16.5M   17K  176K       4 /opt/zram/zram1
/dev/zram0 lzo           600M    4K   89B   12K       4 [SWAP]

uh, how do i store the last modification date? :no_mouth:

Normally - restoreonstartup acts early in the process, and I am convinced that it acts "silently’ anyway, generating no events to log. I may have this wrong, but as I recall it is a deliberate design choice so that rules are not triggered by restore.

So I would view a successful restore as finding my Item to have a value “ON” or whatever, rather than NULL, after a boot, with no update logged for it.

Finding an update NULL->blah log implies to me that restore did not work at all.
Perhaps it’s delayed, perhaps it found no record to restore, perhaps a binding beat restore to it with an update. That’s legitimate by the way - if you get "real’ data it should override restore.

Are your test Items linked to any bindings?

i haven’t installed any bindings except mapdb persistence.
items:

Group gTest
Switch Test1         "Montag [%s]"                     (gTest)
Switch Test2         "Dienstag [%s]"                   (gTest)
Switch Test3         "Mittwoch [%s]"                   (gTest)
Switch Test4         "Donnerstag [%s]"                 (gTest)
Switch Test5         "Freitag [%s]"                    (gTest)
Switch Test6         "Samstag [%s]"                    (gTest)
Switch Test7         "Sonntag [%s]"                    (gTest)

Okay, can we see that in context please?
I never see any events.log evidence of restore, it’s invisible magic, though of course system timings vary.

I’m trying to differentiate “restore doesn’t restore” from “restore gives surprise values”

That probably is more of a question what Karaf logging you enabled, isn’t it ?
Least thing to see persistence related actions would be log:set DEBUG org.openhab.persistence.mapdb but I haven’t figured out if that logs anything on restore.

Remember that is the Karaf logging, to appear in openhab.log. That’s different/unrelated to events.log which you and @narf27 refer to.

try item.postUpdate(now) from a rule
(I didn’t validate that, eventually you need to assign the now value to a variable first)

There’s not a lot of context…

here i change a value:

2020-08-07 12:16:54.286 [ome.event.ItemCommandEvent] - Item 'Test2' received command ON
2020-08-07 12:16:54.312 [vent.ItemStateChangedEvent] - Test2 changed from OFF to ON

reboot, whooop. even this rows from above from events.log are lost, the last entry before reboot now is from 11:37… :

2020-08-07 11:37:15.172 [vent.ItemStateChangedEvent] - Test1 changed from OFF to ON
2020-08-07 12:19:12.243 [vent.ItemStateChangedEvent] - Test2 changed from NULL to OFF
2020-08-07 12:19:12.264 [vent.ItemStateChangedEvent] - Test1 changed from NULL to ON
2020-08-07 12:19:12.285 [vent.ItemStateChangedEvent] - Test7 changed from NULL to OFF
2020-08-07 12:19:12.296 [vent.ItemStateChangedEvent] - Test6 changed from NULL to OFF
2020-08-07 12:19:12.308 [vent.ItemStateChangedEvent] - Test5 changed from NULL to OFF
2020-08-07 12:19:12.321 [vent.ItemStateChangedEvent] - Test4 changed from NULL to ON
2020-08-07 12:19:12.333 [vent.ItemStateChangedEvent] - Test3 changed from NULL to OFF

well… that should explain why:

[12:20:17] openhabian@openhab:~$ zramctl
[12:22:54] openhabian@openhab:~$

i just noticed: on reboot i don’t any messages from opehab.log via frontend… (that’s not normal, is it?)

ok, zram was not running:

[12:22:54] openhabian@openhab:~$

triggered rule:

2020-08-07 12:32:47.753 [vent.ItemStateChangedEvent] - TestDateTime changed from NULL to 2020-08-07T12:32:47.725+0100

followed by reboot, zram runs this time:

[12:39:44] openhabian@openhab:~$ zramctl
NAME       ALGORITHM DISKSIZE  DATA  COMPR TOTAL STREAMS MOUNTPOINT
/dev/zram2 lzo           500M 24.8M 103.5K  432K       4 /opt/zram/zram2
/dev/zram1 lzo           500M 16.5M    17K  200K       4 /opt/zram/zram1
/dev/zram0 lzo           600M    4K    89B   12K       4 [SWAP]

this is what i presume is restoreonstartup:
2020-08-07 12:35:37.665 [vent.ItemStateChangedEvent] - TestDateTime changed from NULL to 2020-08-07T12:32:47.000+0100

update for DateTime Item:
2020-08-07 12:42:55.559 [vent.ItemStateChangedEvent] - TestDateTime changed from 2020-08-07T12:32:47.000+0100 to 2020-08-07T12:42:55.547+0100

time for another reboot >>>
zram still ON

[12:46:57] openhabian@openhab:~$ zramctl
NAME       ALGORITHM DISKSIZE  DATA  COMPR TOTAL STREAMS MOUNTPOINT
/dev/zram2 lzo           500M 24.9M 100.7K  484K       4 /opt/zram/zram2
/dev/zram1 lzo           500M 16.5M  17.1K  180K       4 /opt/zram/zram1
/dev/zram0 lzo           600M    4K    89B   12K       4 [SWAP]

but DateTime Item is not up to date:

2020-08-07 12:44:55.208 [vent.ItemStateChangedEvent] - TestDateTime changed from NULL to 2020-08-07T12:32:47.000+0100

Note that 12:32:47.000 is not the same as 12:32:47.725
That’s a curiosity, but probably just a limitation of mapdb and giant integers.

The point about events.log “changed from NULL” is that I don’t expect to see that at all from restore. If I’m right there, it’s a whopping clue.

can i do anything to help/verify etc.?