Log function regularly broken down

Duke_Jones · December 10, 2021, 5:18pm

Platform information:
- Hardware: _Raspberry 4, 4G
- OS: _Openhabian
- Java Runtime Environment: _openjdk 11.0.10 2021-01-19 LTS
  OpenJDK Runtime Environment Zulu11.45+27-CA (build 11.0.10+9-LTS)
  OpenJDK Client VM Zulu11.45+27-CA (build 11.0.10+9-LTS, mixed mode)
- openHAB version: 3.1.0 Release

Hi everybody,

for some time now I have had the problem that the log function keeps collapsing. I would be happy if someone could give me a hand so that I can solve the problem.
At the moment, I have to restart the Raspi at least once a day to get the log to work again. The end of the log looks like this:

openhab.log :

2021-12-10 16:20:22.138 [INFO ] [nhab.core.model.script.Waschmaschine] - 1
2021-12-10 16:20:48.138 [INFO ] [nhab.core.model.script.Waschmaschine] - Switch_WallpluInit - onCheckedCount_WaMa=0, offCheckedCount_WaMa=3, Leistung=2180.153
2021-12-10 16:20:48.142 [INFO ] [nhab.core.model.script.Waschmaschine] - 1
2021-12-10 16:21:00.134 [INFO ] [nhab.core.model.script.Waschmaschine] - Switch_WallpluInit - onCheckedCount_WaMa=0, offCheckedCount_WaMa=3, Leistung=2054.853
2021-12-10 16:21:00.137 [INFO ] [nhab.core.model.script.Waschmaschine] - 1
2021-12-10 16:21:10.140 [INFO ] [nhab.core.model.script.Waschmaschine] - Switch_WallpluInit - onCheckedCount_WaMa=0, offCheckedCount_WaMa=3, Leistung=2188.494
2021-12-10 16:21:10.145 [INFO ] [nhab.core.model.script.Waschmaschine] - 1
2021-12-10 16:21:25.134 [INFO ] [nhab.core.model.script.Waschmaschine] - Switch_WallpluInit - onCheckedCount_WaMa=0, offCheckedCount_WaMa=3, Leistung=1980.439
2021-12-10 16:21:25.138 [INFO ] [nhab.core.model.script.Waschmaschine] - 1
2021-12-10 16:21:36.314 [INFO ] [nhab.core.model.script.Waschmaschine] - Switch_WallpluInit - onCheckedCount_WaMa=0, offCheckedCount_WaMa=3, Leistung=2099.839
2021-12-10 16:21:36.317 [INFO ] [nhab.core.model.script.Waschmaschine] - 1
2021-12-10 16:21:49.133 [INFO ] [nhab.core.model.script.Waschmaschine] - Switch_WallpluInit - onCheckedCount_WaMa=0, offCheckedCount_WaMa=3, Leistung=1965.03
2021-12-1

there it stops

events.log :

2021-12-10 16:22:13.146 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'offCheckedCount_WaMa' changed from 3 to 0
2021-12-10 16:22:22.130 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBLW_Watts' changed from 4.472 to 17.546
2021-12-10 16:22:23.130 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBLW_Watts' changed from 17.546 to 213.045
2021-12-10 16:22:24.129 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBLW_Watts' changed from 213.045 to 238.144
2021-12-10 16:22:25.129 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBLW_Watts' changed from 238.144 to 196.561
2021-12-10 16:22:26.131 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBLW_Watts' changed from 196.561 to 220.812
2021-12-10 16:22:30.129 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBLW_Watts' changed from 220.812 to 238.72
2021-12

there it stops

Does anybody have an idea ?

anon71759204 · December 10, 2021, 9:49pm

Wolfgang_S · December 11, 2021, 8:55am

is that always about the same file size when it stops to log into the file ?
there is still ( enough ) free diskspace on the partition logging is being done ?

Duke_Jones · December 11, 2021, 12:14pm

@anon71759204
Thank you for the answer. However, the cause described there seems to be different. In my case, the log runs in principle, but stops after a while.

The “org.ops4j.pax.logging.cfg” also exists and has the content,
I expect. If you think it makes sense, I can post the content.

@Wolfgang_S

is that always about the same file size when it stops to log into the file ?

Hm, it doesn’t seem so. But I will observe this.

there is still ( enough ) free diskspace on the partition logging is being done ?

Yes, definitely. 5.2GB are still free.

I find it noticeable that the writing seems to stop in the middle of a new row. You can see incomplete date entries at the last row.

Duke_Jones · December 11, 2021, 1:28pm

It happend again:

2021-12-11 12:02:06.482 [INFO ] [odel.script.AutoOffTimer_Kellerlicht] - Kellerlicht automatisch ausgeschaltet
2021-12-11 12:07:46.282 [INFO ] [openhab.core.model.script.LSteuerung] - EE-Warnlevel 2, CO²=1416.9ppm
2021-12-11 12:08:24.587 [INFO ] [odel.script.AutoOffTimer_Kellerlicht] - Kellerlicht zeitgesteuert eingeschaltet
2021-12-11 12:10:24.590 [INFO ] [odel.script.AutoOffTimer_Kellerlicht] - Kellerlicht automatisch ausgeschaltet
2021-12-11 12:27:00.325 [INFO ] [odel.script.AutoOffTimer_Kellerlicht] - Kellerlicht zeitgesteuert eingeschaltet
2021-12-11 12:29:00.328 [INFO ] [odel.script.AutoOffTimer_Kellerlicht] - Kellerlicht automatisch ausgeschaltet
2021-12-11 12:50:35.183 [WARN ] [ab.binding.mqtt.generic.ChannelState] - Incoming payload '11.0~~~~~~~~~~~~~~~~~~~~~~~~~' not supported by type 'NumberValue'
2021-12-11 13:05:48.325 [INFO ] [openhab.core.model.script.LSteuerung] - startup received
2021-12-11 13:05:48.331 [INFO ] [openhab.core.model.script.LSteuerung] - LF-Warnlevel aus, Temperatur=17.0°C, Taupunkt(+1.0°C)=9.4°C
2021-12-11 13:05:48.338 [INFO ] [openhab.core.model.script.LSteuerung] - EE-Warnlevel 2, CO²=1468.4ppm
2021-12-11 13:05:48.353 [INFO ] [openhab.core.model.script.LSteuerung] - startup received
2021-12-11 13:05:48.360 [INFO ] [openhab.core.model.script.LSteuerung] - LF-Warnlevel aus, Temperatur=17.0°C, Taupunkt(+1.0°C)=9.4°C
2021-12-11 13:05:48.370 [INFO ] [openhab.core.model.script.LSteuerung] - EE-Warnlevel 2, CO²=1468.4ppm
2021-12-11 13:56:48.506 [INFO ] [rnal.service.RemoteControllerService] - Using WebSocket interface
2021-12-11 13:56:48.552 [INFO ] [rnal.service.RemoteControllerService] - Using WebSocket interface
2021-12-11 13:56:48.884 [WARN ] [l.protocol.Remot

and

2021-12-11 13:05:25.957 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBTV_Dewpoint' changed from 8.2 to 8.4
2021-12-11 13:05:48.306 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBTV_Humidity' changed from 39.2 to 39.4
2021-12-11 13:05:48.309 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBTV_Temperature' changed from 22.8 to 22.9
2021-12-11 13:05:48.311 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBTV_Pressure_EE' changed from 1006.2 to 1007.5
2021-12-11 13:05:48.314 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBTV_CO2_EE' changed from 1475.6 to 1468.4
2021-12-11 13:05:48.315 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'IBTV_Startup' changed from OFF to ON
2021-12-11 13:05:48.321 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_Startup' received command OFF
2021-12-11 13:05:48.328 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED1_On' received command ON
2021-12-11 13:05:48.335 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED2_On' received command ON
2021-12-11 13:05:48.342 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED3_On' received command ON
2021-12-11 13:05:48.353 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'IBTV_Startup' predicted to become OFF
2021-12-11 13:05:48.360 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED1_Blink' received command OFF
2021-12-11 13:05:48.367 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED2_Blink' received command OFF
2021-12-11 13:05:48.372 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED3_Blink' received command OFF
2021-12-11 13:05:48.378 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED1_Color' received command 000000
2021-12-11 13:05:48.385 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED2_Color' received command 000000
2021-12-11 13:05:48.390 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED3_Color' received command 000000
2021-12-11 13:05:48.396 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'IBTV_LED3_Blink' received command OFF
2021-12-11 13:05:4

Size of events.log is 512000, openhab.log is 151552.
The other files :

total 27444
-rw-r--r-- 1 openhab openhab   512000 Dec 11 14:25 events.log
-rw-r--r-- 1 openhab openhab   151552 Dec 11 14:23 openhab.log
-rw-r--r-- 1 openhab openhab   155478 Dec  5 11:11 events.log.7
-rw-r--r-- 1 openhab openhab   246748 Dec  5 11:11 openhab.log.7
-rw-r--r-- 1 openhab openhab    56578 Dec  5 10:22 events.log.6
-rw-r--r-- 1 openhab openhab    92435 Dec  5 10:22 openhab.log.6
-rw-r--r-- 1 openhab openhab    64901 Dec  3 20:37 events.log.5
-rw-r--r-- 1 openhab openhab    76235 Dec  3 20:37 openhab.log.5
-rw-r--r-- 1 openhab openhab    72408 Dec  3 19:37 openhab.log.4
-rw-r--r-- 1 openhab openhab    62188 Dec  1 22:35 events.log.4
-rw-r--r-- 1 openhab openhab    73882 Dec  1 22:35 openhab.log.3
-rw-r--r-- 1 openhab openhab    71709 Dec  1 20:41 openhab.log.2
-rw-r--r-- 1 openhab openhab 11883488 Nov 16 16:11 events.log.3
-rw-r--r-- 1 openhab openhab  6530734 Nov 16 16:11 openhab.log.1
-rw-r--r-- 1 openhab openhab   532093 Nov  4 20:36 events.log.2
-rw-r--r-- 1 openhab openhab  7406297 Oct 10 20:26 events.log.1
-rwxr-xr-x 1 openhab openhab        0 Jun 27 22:57 Readme.txt
-rw-rw-r-- 1 openhab openhab        0 Feb  2  2021 audit.log

After rebooting it looks like this:

total 26920
-rw-r--r-- 1 openhab openhab    87559 Dec 11 14:32 events.log
-rw-r--r-- 1 openhab openhab    43407 Dec 11 14:32 openhab.log
-rw-r--r-- 1 openhab openhab   155478 Dec  5 11:11 events.log.7
-rw-r--r-- 1 openhab openhab   246748 Dec  5 11:11 openhab.log.7
-rw-r--r-- 1 openhab openhab    56578 Dec  5 10:22 events.log.6
-rw-r--r-- 1 openhab openhab    92435 Dec  5 10:22 openhab.log.6
-rw-r--r-- 1 openhab openhab    64901 Dec  3 20:37 events.log.5
-rw-r--r-- 1 openhab openhab    76235 Dec  3 20:37 openhab.log.5
-rw-r--r-- 1 openhab openhab    72408 Dec  3 19:37 openhab.log.4
-rw-r--r-- 1 openhab openhab    62188 Dec  1 22:35 events.log.4
-rw-r--r-- 1 openhab openhab    73882 Dec  1 22:35 openhab.log.3
-rw-r--r-- 1 openhab openhab    71709 Dec  1 20:41 openhab.log.2
-rw-r--r-- 1 openhab openhab 11883488 Nov 16 16:11 events.log.3
-rw-r--r-- 1 openhab openhab  6530734 Nov 16 16:11 openhab.log.1
-rw-r--r-- 1 openhab openhab   532093 Nov  4 20:36 events.log.2
-rw-r--r-- 1 openhab openhab  7406297 Oct 10 20:26 events.log.1
-rwxr-xr-x 1 openhab openhab        0 Jun 27 22:57 Readme.txt
-rw-rw-r-- 1 openhab openhab        0 Feb  2  2021 audit.log

Edit:
Now I deleted all log files in the directory and did a reboot.
Let’s see if it made a difference. But that will become clear tomorrow at the earliest

Edit 2
–removed–

Duke_Jones · December 15, 2021, 6:53pm

It still happens (about once a day).
Does anyone have an idea what can I do get the reason ?

Duke_Jones · December 19, 2021, 8:19pm

The problem still exists but I found out something:

Today the log of events.log stopped at 17:48:28.
The log of openhab.log stopped later at 19:59:52.

I also looked into the karaf console and saw that the logging still goes on
even if the two logfiles are not written anymore.

Any ideas ?

anon71759204 · December 20, 2021, 1:19am

Some additional ideas (in no specific order):

Check journal: OH2.2 suddenly logging stopped this morning - #12 by Milmi12
Check that the owner of the files is openhab, see Oh2 stopped logging - what went wrong? (old post, OH 2 …).
Check zram: sudo zramctl
Disable zram (not recommended; see Logs stop ZRAM issue? - #3 by liketofly)
Check SD card for defects (out of reserved spare blocks?).
Replace SD card.
Stop OH and power cycle.
Reduce the amount of logging (openHab log and events stopped working / java.lang.NullPointerException - #13 by Markus2020).

Duke_Jones · December 20, 2021, 8:05pm

Thank you. I will try these tips and will report…