Randomly reset of items / configuration, mostly in night

[Termineo (Rainer)]

Hi all,

since a longer time I have the problem, that all few days (about 2-5 days) my openHAB2 seems to reset / reboot at night. In my perception without any static cycle.

At the next morning I realize it because every items without persitence have default values.

In the attached logfile you can see, that the system seems to be frozen for about 40 minutes. Do you have any ideas because of what reason it freezes?

I’m using a RPi3 with openHABian clean installation.

Thanky you in advance!

Rainer

[yfre (eugen)]

Hi Rainer,

try different java. i had similar issue with Zulu java. after i have switched to OpenJDK the problem is gone.
it could be also that PI3 has not sufficient memory for your openHAB setup. once it cannot allocate more memory it restarts JVM/Java. pay attention to free memory.

Eugen

[rossko57]

@Termineo

In the attached logfile you can see,

It might be helpful to see more of what leads up to this. There is install activity going on at 03:45

That is about yahoo weather binding, which has been removed I think (service discontinued)
You might start by cleaning up your addons.cfg

[mstormi (Markus Storm)]

@yfre

try different java

It certainly is NOT caused by Java as a root cause so don’t arbitrarily replace that.
Sure it might help as a side effect (e.g. if new Java uses less memory), but you will not know what that changed so you can run into it anytime again.

I’d take a guess at mem usage, too. You might be having a mem leak.
Enable ZRAM if you have not yet done so but start watching RAM and eventually start removing bindings that might be a reason for the leak.

[scoobydrvr (Keith Wheaton)]

Just wanted to jump in and add that I’m experiencing this as well. I have a rule that runs at startup to initialize states and it appears to be running approximately every 24 hours at 2am.

$ cat openhab.log | egrep "Startup Actions"
2020-05-06 20:17:01.717 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-07 02:43:48.548 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-07 19:35:01.616 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-07 19:35:25.594 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-07 19:35:41.759 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-07 19:35:51.352 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-08 02:43:43.225 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-08 08:00:46.364 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-09 02:41:19.947 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-10 02:38:43.988 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-11 02:38:55.136 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-12 02:38:54.795 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-13 02:37:51.766 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-14 02:35:46.049 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-15 02:36:27.963 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-15 16:04:40.963 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-16 02:15:07.550 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-17 02:14:12.152 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-18 02:14:33.657 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-19 02:14:14.633 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-20 02:14:31.179 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-21 02:15:28.839 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-22 02:35:07.349 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-23 02:14:44.607 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-24 02:14:05.639 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-25 02:11:41.117 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-26 02:08:19.524 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-27 02:08:14.261 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-28 02:08:23.251 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-29 02:08:14.156 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-30 02:08:43.604 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-05-31 02:08:04.833 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-06-01 02:08:10.284 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-06-02 02:08:19.107 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions
2020-06-03 02:09:46.496 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions

Checking around these timestamps doesn’t yield much:

$ cat openhab.log | egrep "2020-05-21 02:15"
2020-05-21 02:15:28.839 [INFO ] [smarthome.model.script.restart.rules] - Performing Startup Actions

$ cat events.log.5  | egrep "2020-05-21 02:15:28"
2020-05-21 02:15:28.042 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 51595 to 51596
2020-05-21 02:15:28.046 [vent.ItemStateChangedEvent] - ZWaveSerialController_FramesAcknowledged changed from 6005 to 6006
2020-05-21 02:15:28.051 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 51596 to 51597
2020-05-21 02:15:28.136 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 51597 to 51598
2020-05-21 02:15:28.140 [vent.ItemStateChangedEvent] - ZWaveSerialController_FramesAcknowledged changed from 6006 to 6007
2020-05-21 02:15:28.151 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 51598 to 51599
2020-05-21 02:15:28.793 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 51599 to 51600
2020-05-21 02:15:28.797 [vent.ItemStateChangedEvent] - ZWaveSerialController_FramesAcknowledged changed from 6007 to 6008
2020-05-21 02:15:28.808 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 51600 to 51601
2020-05-21 02:15:28.842 [ome.event.ItemCommandEvent] - Item 'DenOverride' received command OFF
2020-05-21 02:15:28.844 [ome.event.ItemCommandEvent] - Item 'LivingRoomOverride' received command OFF
2020-05-21 02:15:28.845 [ome.event.ItemCommandEvent] - Item 'MovieMode' received command OFF
2020-05-21 02:15:28.848 [ome.event.ItemCommandEvent] - Item 'DaylightHours' received command OFF
2020-05-21 02:15:28.850 [ome.event.ItemCommandEvent] - Item 'AwayMode' received command OFF
2020-05-21 02:15:28.852 [ome.event.ItemCommandEvent] - Item 'MaxBrightness' received command 100
2020-05-21 02:15:28.854 [ome.event.ItemCommandEvent] - Item 'sliderVolume' received command 69
2020-05-21 02:15:28.869 [ome.event.ItemCommandEvent] - Item 'ThermostatSetpoint' received command 70
2020-05-21 02:15:28.871 [ome.event.ItemCommandEvent] - Item 'AutoRefresh' received command ON
2020-05-21 02:15:28.874 [ome.event.ItemCommandEvent] - Item 'BlowerSwitch' received command OFF
2020-05-21 02:15:28.887 [vent.ItemStateChangedEvent] - DenOverride changed from ON to OFF
2020-05-21 02:15:28.889 [nt.ItemStatePredictedEvent] - BlowerSwitch predicted to become OFF
2020-05-21 02:15:28.911 [vent.ItemStateChangedEvent] - BlowerSwitch changed from NULL to OFF

Note: activity at 2020-05-21 02:15:28.842 are my variables initializing in the system startup rule.

System is running on Odroid C2 with 2Gb of RAM and their version of Ubuntu 18.04.

[rossko57]

I think you’ll have tolook back a little earlier than 1 second in your events.log for a clue.
I’ll take a side bet there is a zwave Thing update a few seconds earlier.

[scoobydrvr (Keith Wheaton)]

Looking over the span of a minute at 02:15 there are nothing but 3 types of messages:

• Z-Wave StartFrames changing
• Z-Wave FramesAcknowledged changing
• Z-Wave nodes updating

Admittedly, it’s a lot of chatter and, now that I’m thinking about it, 2am is my network heal time. Any reason why that would cause OH to run the startup script though and might I expect some sort of error message if something was overflowing or crashing?

[5iver (Scott Rushworth)]

@scoobydrvr

I have a rule that runs at startup to initialize states and it appears to be running approximately every 24 hours at 2am.

What you are experiencing may be different. When Items or Things are added/removed/updated, several bindings and the old rule engine will restart, which will cause your startup rule to be triggered. This is a known issue…

Some addons restart after uninstalling an unrelated addon

I suspect that the heal is updating some Things which restarts your rules and possibly the entire zwave binding. I suggest disabling your daily zwave network heal and run it manually when you add or move devices.

[rossko57]

Search events log for ThingUpdatedEvent to see if you are hitting the snag described by Scott.

EDIT -

@scoobydrvr

might I expect some sort of error message if something was overflowing or crashing?

Yes, but an unexpected / unwanted System started event is not necessarily any kind of error or “crash”. You can trigger one yourself by editing files, for example.

[Andrew_Rowe]

@scoobydrvr

Just wanted to jump in and add that I’m experiencing this as well.

I would be willing to bet (and I’m not a gambling man) that this is not the same exact issue as the original post, it has been a really long time since you’ve posted (welcome back) but I’d like to encourage you to start a new thread about your issue Keith, it will help us solve your issue easier

[scoobydrvr (Keith Wheaton)]

Thank you all for the replies. It seems as though there is something else, unrelated to OPs issue.

@5iver

I suggest disabling your daily zwave network heal and run it manually when you add or move devices

I’ll implement this and see if the behavior changes.

@rossko57

Search events log for ThingUpdatedEvent to see if you are hitting the snag described by Scott

There are tons of these around the timestamp of the startup rule executing from my Yamaha stereo and Z-Wave things. To your point, I think if this was the cause, I’d be seeing this rule run every time one of these events occurred.

@Andrew_Rowe

I would be willing to bet (and I’m not a gambling man) that this is not the same exact issue as the original post, it has been a really long time since you’ve posted (welcome back) but I’d like to encourage you to start a new thread about your issue Keith, it will help us solve your issue easier

Upon a closer reading, I believe you are correct. I didn’t realize the consistent frequency of my issue until I started digging into logs for replies. Thanks for the welcome, I’ll go start a new thread.

[rossko57]

@scoobydrvr

I think if this was the cause, I’d be seeing this rule run every time one of these events occurred.

Not every ThingUpdatedEvent causes any kind of consequence. It depends on the Thing involved, and what changed. zwave Things seem to be culprits sometimes, but you only need one for the effect you’ve seen.

@scoobydrvr

There are tons of these around the timestamp of the startup rule executing

By way of further explanation, these ThingUpdatedEvent are about the properties of the Thing. Not the status like online/offline, which are different events.
So something fundamental changes - I don’t know what, but say a zwave device reports different channels available to what you have configured.

In order for those changes to take effect, some services will need a kick in the pants of some kind. Like when you edit a Thing, and a binding might need to reinitialise it.
At OH 2.5 there seems to be more re-init activity around this than there used to be.
Seeing “tons” of these might be about symptoms, not original trigger.

A recent thread highlighted that a change in zwave binding taken together with a Thing defined under an earlier version could be linked to this kind of problem.

[Termineo (Rainer)]

After two month and many time of analyzing / waiting until the error appears again / analyzing again I just wanted to give a short feedback: I identified and solved the problem.

Additionally to openHAB I had one other software installed on the Pi to control my access point. Also every few days I ran an automatical backup on the OH installation.
After analyzing the memory usage I found out: The access point software search for updates every Wednesday and Saturday night. Sometimes (every few weeks) I now had the situation, that the OH backup was still running when the AP software started updating. Because of an memory overflow openHAB froze / restarted.

Thanks to all for the great support!!!