Issue of the topic: every morning at 06:25 openhab restarts and i cant figure out why, as you can see in the events log all is normal untill somewhere between 06:25:03 when the last item updated and 06:25:42 when openhab restarts
I only set this opi zero up 5 days ago when my opi pc gave up and i never had any problem like this on the opi pc
if the restarts where random i would think the low ram was causing it but I’m at 80%-+ usage and these restarts are way to precise for that.
i have no rules that happen anywhere near this time, no rules that can restart openhab at all, and all my items get the data over a telnet connection to a esp8266 once per min.
the only extra add-on i have installed are telegram and cloud
Any thoughts on where i should start looking?
is there a new daily restart setting that i have missed?
thanks
Stefan
openhab.log
2019-08-02 00:12:00.158 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule 'last ten min': The argument 'state' must not be null.
2019-08-02 06:25:42.082 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Stockholm'.
2019-08-02 06:25:42.784 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_SE'.
2019-08-02 06:25:48.275 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 49da12ec-5a38-4d79-b994-0399171edb1c, base URL = http://localhost:8080)
2019-08-02 06:26:07.180 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '_default.items'
2019-08-02 06:26:09.312 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2019-08-02 06:26:43.279 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '_default.rules'
2019-08-02 06:26:44.900 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2019-08-02 06:26:46.165 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '_default.sitemap'
events.log
2019-08-02 06:25:03.341 [vent.ItemStateChangedEvent] - hum_inside changed from 40.48 to 40.52
2019-08-02 06:25:03.345 [vent.ItemStateChangedEvent] - ht21d_tmp_wless changed from 25.3 to 25.31
2019-08-02 06:26:53.554 [vent.ItemStateChangedEvent] - pressure changed from NULL to 1011.31
2019-08-02 06:26:53.604 [vent.ItemStateChangedEvent] - snail_mail_counter changed from NULL to 39.0
2019-08-02 06:26:53.643 [vent.ItemStateChangedEvent] - Fan changed from NULL to 1.0
2019-08-02 06:26:53.667 [vent.ItemStateChangedEvent] - co2ppm_z19 changed from NULL to 435.0
2019-08-02 06:26:53.685 [vent.ItemStateChangedEvent] - soil_low changed from NULL to 0.0
2019-08-02 06:26:53.705 [vent.ItemStateChangedEvent] - lightning changed from NULL to 627.0
Don’t rule out entirely external root causes, like a water boiler firing up.
Decades ago there was a mainframe that crashed around 0730 some mornings. Eventually linked to nearby airfield switching on its ground radar, which had a minor fault and gave a wide spectrum radio fart at start up.
If it where a complete reboot of the opi zero something strange like that would have been high on my list too, but only openhab that just makes it more strange, this morning i was staring at it while it happened i even made sure the wifi did not go down or something like that.
I just made sure that i wont get any notifications if openhab starts at 06.25,26 or 27…
I don’t think these restarts will cause any issues its just one of those things that keep annoying you until you can figure it out…
There’s nothing in OH to cause that so it’s most likely your OS causing this.
Ramp up OH debugging to make sure you don’t miss any hint, but I’m pretty sure it’s not OH to directly cause this.
Before this starts i have around 20% free ram and 20% zram
something here appears to fill the last ram and ends up with java and openhab restarting…
now to figure out what all these commands do…
Aug 5 06:07:00 localhost systemd[1]: Starting Daily apt upgrade and clean activities...
Aug 5 06:07:00 localhost systemd[1]: Started Daily apt upgrade and clean activities.
Aug 5 06:15:01 localhost CRON[11607]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Aug 5 06:15:01 localhost CRON[11608]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Aug 5 06:15:02 localhost wpa_supplicant[646]: wlan0: WPA: Group rekeying completed with 30:91:8f:71:fd:a1 [GTK=CCMP]
Aug 5 06:17:01 localhost CRON[11677]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Aug 5 06:25:01 localhost CRON[11927]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Aug 5 06:25:01 localhost CRON[11928]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
Aug 5 06:25:02 localhost wpa_supplicant[646]: wlan0: WPA: Group rekeying completed with 30:91:8f:71:fd:a1 [GTK=CCMP]
Aug 5 06:25:04 localhost kernel: [77705.212830] rsync invoked oom-killer: gfp_mask=0x6200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null), order=0, oom_score_adj=0
Aug 5 06:25:04 localhost kernel: [77705.212837] rsync cpuset=/ mems_allowed=0
Aug 5 06:25:04 localhost kernel: [77705.212857] CPU: 3 PID: 11940 Comm: rsync Not tainted 4.19.63-sunxi64 #5.92
Aug 5 06:25:04 localhost kernel: [77705.212860] Hardware name: OrangePi Zero Plus2 (DT)
Aug 5 06:25:04 localhost kernel: [77705.212864] Call trace:
Aug 5 06:25:04 localhost kernel: [77705.212882] dump_backtrace+0x0/0x1a0
Aug 5 06:25:04 localhost kernel: [77705.212889] show_stack+0x14/0x20
Aug 5 06:25:04 localhost kernel: [77705.212896] dump_stack+0x9c/0xbc
Aug 5 06:25:04 localhost kernel: [77705.212904] dump_header+0x64/0x23c
Aug 5 06:25:04 localhost kernel: [77705.212909] oom_kill_process+0x338/0x380
Aug 5 06:25:04 localhost kernel: [77705.212914] out_of_memory+0x1ac/0x508
Aug 5 06:25:04 localhost kernel: [77705.212922] __alloc_pages_nodemask+0xac4/0xb58
Aug 5 06:25:04 localhost kernel: [77705.212929] alloc_pages_vma+0x88/0x210
Aug 5 06:25:04 localhost kernel: [77705.212937] wp_page_copy+0x94/0x670
Aug 5 06:25:04 localhost kernel: [77705.212943] do_wp_page+0xb0/0x658
Aug 5 06:25:04 localhost kernel: [77705.212949] __handle_mm_fault+0x660/0xdb8
Aug 5 06:25:04 localhost kernel: [77705.212955] handle_mm_fault+0xec/0x1c0
Aug 5 06:25:04 localhost kernel: [77705.212962] do_page_fault+0x1c0/0x480
Aug 5 06:25:04 localhost kernel: [77705.212967] do_mem_abort+0x54/0x100
Aug 5 06:25:04 localhost kernel: [77705.212972] el0_da+0x20/0x24
Aug 5 06:25:04 localhost kernel: [77705.212974] Mem-Info:
Aug 5 06:25:04 localhost kernel: [77705.212990] active_anon:42536 inactive_anon:42565 isolated_anon:0
Aug 5 06:25:04 localhost kernel: [77705.212990] active_file:41 inactive_file:13 isolated_file:0
Aug 5 06:25:04 localhost kernel: [77705.212990] unevictable:0 dirty:0 writeback:0 unstable:0
Aug 5 06:25:04 localhost kernel: [77705.212990] slab_reclaimable:2201 slab_unreclaimable:5506
Aug 5 06:25:04 localhost kernel: [77705.212990] mapped:376 shmem:494 pagetables:873 bounce:0
Aug 5 06:25:04 localhost kernel: [77705.212990] free:585 free_pcp:119 free_cma:81
Aug 5 06:25:04 localhost kernel: [77705.213003] Node 0 active_anon:170144kB inactive_anon:170260kB active_file:164kB inactive_file:52kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:1504kB dirty:0kB writeback:0kB shmem:1976kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Aug 5 06:25:04 localhost kernel: [77705.213006] Node 0 DMA32 free:2340kB min:2372kB low:2964kB high:3556kB active_anon:170144kB inactive_anon:170260kB active_file:188kB inactive_file:0kB unevictable:0kB writepending:0kB present:524288kB managed:492932kB mlocked:0kB kernel_stack:4160kB pagetables:3492kB bounce:0kB free_pcp:476kB local_pcp:160kB free_cma:324kB
Aug 5 06:25:04 localhost kernel: [77705.213022] lowmem_reserve[]: 0 0 0
Aug 5 06:25:04 localhost kernel: [77705.213030] Node 0 DMA32: 69*4kB (UEH) 28*8kB (UEHC) 40*16kB (UEHC) 20*32kB (UEHC) 6*64kB (UH) 2*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2420kB
Aug 5 06:25:04 localhost kernel: [77705.213076] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Aug 5 06:25:04 localhost kernel: [77705.213079] 863 total pagecache pages
Aug 5 06:25:04 localhost kernel: [77705.213084] 271 pages in swap cache
Aug 5 06:25:04 localhost kernel: [77705.213088] Swap cache stats: add 109988, delete 109717, find 43384/90377
Aug 5 06:25:04 localhost kernel: [77705.213090] Free swap = 0kB
Aug 5 06:25:04 localhost kernel: [77705.213093] Total swap = 246464kB
Aug 5 06:25:04 localhost kernel: [77705.213095] 131072 pages RAM
Aug 5 06:25:04 localhost kernel: [77705.213097] 0 pages HighMem/MovableOnly
Aug 5 06:25:04 localhost kernel: [77705.213099] 7839 pages reserved
Aug 5 06:25:04 localhost kernel: [77705.213101] 32768 pages cma reserved
Aug 5 06:25:04 localhost kernel: [77705.213104] Tasks state (memory values in pages):
Aug 5 06:25:04 localhost kernel: [77705.213107] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
Aug 5 06:25:04 localhost kernel: [77705.213143] [ 279] 0 279 7167 531 69632 186 0 systemd-journal
Aug 5 06:25:04 localhost kernel: [77705.213153] [ 313] 0 313 3800 6 53248 288 -1000 systemd-udevd
Aug 5 06:25:04 localhost kernel: [77705.213164] [ 420] 62583 420 20971 14 65536 139 0 systemd-timesyn
Aug 5 06:25:04 localhost kernel: [77705.213172] [ 423] 0 423 1920 0 49152 774 0 haveged
Aug 5 06:25:04 localhost kernel: [77705.213181] [ 426] 101 426 2608 2 61440 152 0 systemd-resolve
Aug 5 06:25:04 localhost kernel: [77705.213189] [ 594] 0 594 1337 31 45056 45 0 cron
Aug 5 06:25:04 localhost kernel: [77705.213198] [ 597] 0 597 2600 56 61440 135 0 systemd-logind
Aug 5 06:25:04 localhost kernel: [77705.213206] [ 603] 103 603 1750 116 53248 78 -900 dbus-daemon
Aug 5 06:25:04 localhost kernel: [77705.213214] [ 646] 0 646 2421 63 57344 140 0 wpa_supplicant
Aug 5 06:25:04 localhost kernel: [77705.213223] [ 649] 102 649 54992 10 73728 203 0 rsyslogd
Aug 5 06:25:04 localhost kernel: [77705.213231] [ 654] 0 654 24645 5 90112 1947 0 networkd-dispat
Aug 5 06:25:04 localhost kernel: [77705.213240] [ 664] 0 664 81542 319 131072 412 0 NetworkManager
Aug 5 06:25:04 localhost kernel: [77705.213249] [ 751] 0 751 25840 0 98304 2005 0 unattended-upgr
Aug 5 06:25:04 localhost kernel: [77705.213257] [ 759] 0 759 2603 8 53248 172 -1000 sshd
Aug 5 06:25:04 localhost kernel: [77705.213266] [ 783] 0 783 57866 5 86016 211 0 polkitd
Aug 5 06:25:04 localhost kernel: [77705.213273] [ 1112] 0 1112 2094 11 65536 304 0 dhclient
Aug 5 06:25:04 localhost kernel: [77705.213282] [ 1160] 108 1160 937987 41897 1568768 51937 0 java
Aug 5 06:25:04 localhost kernel: [77705.213290] [ 1164] 0 1164 8897 214 102400 441 0 nmbd
Aug 5 06:25:04 localhost kernel: [77705.213298] [ 1172] 0 1172 1051 0 40960 36 0 agetty
Aug 5 06:25:04 localhost kernel: [77705.213306] [ 1176] 0 1176 995 0 45056 33 0 agetty
Aug 5 06:25:04 localhost kernel: [77705.213314] [ 1178] 0 1178 995 0 49152 35 0 agetty
Aug 5 06:25:04 localhost kernel: [77705.213322] [ 1341] 0 1341 12730 76 139264 617 0 smbd
Aug 5 06:25:04 localhost kernel: [77705.213330] [ 1374] 0 1374 11773 30 131072 615 0 smbd-notifyd
Aug 5 06:25:04 localhost kernel: [77705.213338] [ 1375] 0 1375 11779 27 131072 614 0 cleanupd
Aug 5 06:25:04 localhost kernel: [77705.213346] [ 1376] 0 1376 12726 59 135168 620 0 lpqd
Aug 5 06:25:04 localhost kernel: [77705.213360] [ 11925] 0 11925 1699 81 49152 27 0 cron
Aug 5 06:25:04 localhost kernel: [77705.213368] [ 11928] 0 11928 478 17 40960 0 0 sh
Aug 5 06:25:04 localhost kernel: [77705.213376] [ 11930] 0 11930 453 15 45056 0 0 run-parts
Aug 5 06:25:04 localhost kernel: [77705.213385] [ 11933] 0 11933 478 17 40960 0 0 armbian-ram-log
Aug 5 06:25:04 localhost kernel: [77705.213393] [ 11934] 0 11934 792 79 45056 0 0 armbian-ramlog
Aug 5 06:25:04 localhost kernel: [77705.213401] [ 11940] 0 11940 23995 22628 233472 0 0 rsync
Aug 5 06:25:04 localhost kernel: [77705.213408] [ 11941] 0 11941 456 15 45056 0 0 tee
Aug 5 06:25:04 localhost kernel: [77705.213416] [ 11943] 0 11943 35945 34902 327680 0 0 rsync
Aug 5 06:25:04 localhost kernel: [77705.213422] Out of memory: Kill process 1160 (java) score 509 or sacrifice child
Aug 5 06:25:04 localhost kernel: [77705.214069] Killed process 1160 (java) total-vm:3751948kB, anon-rss:167572kB, file-rss:0kB, shmem-rss:16kB
Aug 5 06:25:04 localhost kernel: [77705.470193] oom_reaper: reaped process 1160 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:16kB
Aug 5 06:25:04 localhost systemd[1]: openhab2.service: Main process exited, code=killed, status=9/KILL
Aug 5 06:25:04 localhost systemd[1]: openhab2.service: Failed with result 'signal'.
i just looked in /etc/cron.daily, there is a file called: armbian-ram-logging
that does this: #!/bin/sh
/usr/lib/armbian/armbian-ramlog write >/dev/null 2>&1
might be what is causing it or i hope it is so i can solve it…
what i have tried now is to decrease swappiness from 100 to 60 so i have more z-ram free when this happens and i have set log rotation to daily instead of weekly, if i understand it right this should give smaller log files to play with…
As for the disabling/enabling bindings its a good thought and i would have tried it but i don’t have any installed, I’m getting all the sensor data over telnet.
thanks all for the help i feel like I’m getting closer and closer to solve this
now just wait for the next morning and see…
