Hallo zusammen!
Seit einiger Zeit kann ich feststellen, dass mein FHEM nach einer gewissen Zeitdauer ( > mehrere Wochen) undefiniert abstürzt. Leider habe ich keine Ahnung, wo der Fehler liegt oder sehe den Wald vor lauter Bäumen nicht.
Der Server an sich ist erreichbar und kann per SSH auch angesprochen werden. Somit kann ich FHEM zwar neu starten, aber ich würde gerne die Ursache kennen. Angeblich arbeitet der Dienst auch ordnungsgemäß (s.u.), aber der Aufruf über einen Webbrowser scheitert und auch Aktionen werden nicht gestartet.
Es wäre toll, wenn jmd. von euch eine Idee hat, wo ich suchen kann bzw. wie ich den Fehler lokalisieren kann.
Die aus meiner Sicht relevanten Logs und Auszüge füge ich an, kann sie auch gerne ergänzen:
Auszug aus dmesg
[1164227.531918] Out of memory: Kill process 912 (perl) score 465 or sacrifice child
[1164227.531951] Killed process 912 (perl) total-vm:498512kB, anon-rss:428356kB, file-rss:0kB, shmem-rss:0kB
[2545932.485113] fake-hwclock invoked oom-killer: gfp_mask=0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK), nodemask=0, order=1, oom_score_adj=0
[2545932.485123] fake-hwclock cpuset=/ mems_allowed=0
[2545932.485146] CPU: 2 PID: 8165 Comm: fake-hwclock Not tainted 4.9.35-v7+ #1014
[2545932.485150] Hardware name: BCM2835
[2545932.485182] [<8010fb3c>] (unwind_backtrace) from [<8010c058>] (show_stack+0x20/0x24)
[2545932.485199] [<8010c058>] (show_stack) from [<80455880>] (dump_stack+0xd4/0x118)
[2545932.485217] [<80455880>] (dump_stack) from [<8026cd84>] (dump_header+0x9c/0x1f4)
[2545932.485235] [<8026cd84>] (dump_header) from [<802106a0>] (oom_kill_process+0x3e0/0x4e4)
[2545932.485252] [<802106a0>] (oom_kill_process) from [<80210b08>] (out_of_memory+0x124/0x334)
[2545932.485270] [<80210b08>] (out_of_memory) from [<80215c34>] (__alloc_pages_nodemask+0xcf4/0xdd0)
[2545932.485290] [<80215c34>] (__alloc_pages_nodemask) from [<8011ab34>] (copy_process.part.5+0xec/0x17b0)
[2545932.485308] [<8011ab34>] (copy_process.part.5) from [<8011c388>] (_do_fork+0xc8/0x408)
[2545932.485324] [<8011c388>] (_do_fork) from [<8011c7ec>] (SyS_clone+0x34/0x3c)
[2545932.485341] [<8011c7ec>] (SyS_clone) from [<801080c0>] (ret_fast_syscall+0x0/0x1c)
[2545932.485347] Mem-Info:
[2545932.485368] active_anon:110818 inactive_anon:110866 isolated_anon:0
active_file:233 inactive_file:269 isolated_file:0
unevictable:0 dirty:0 writeback:0 unstable:0
slab_reclaimable:1402 slab_unreclaimable:2469
mapped:757 shmem:621 pagetables:704 bounce:0
free:6518 free_pcp:402 free_cma:1420
[2545932.485386] Node 0 active_anon:443272kB inactive_anon:443464kB active_file:932kB inactive_file:1076kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:3028kB dirty:0kB writeback:0kB shmem:2484kB writeback_tmp:0kB unstable:0kB pages_scanned:28452 all_unreclaimable? yes
[2545932.485409] Normal free:26072kB min:16384kB low:20480kB high:24576kB active_anon:443272kB inactive_anon:443464kB active_file:932kB inactive_file:1076kB unevictable:0kB writepending:0kB present:966656kB managed:945512kB mlocked:0kB slab_reclaimable:5608kB slab_unreclaimable:9876kB kernel_stack:1096kB pagetables:2816kB bounce:0kB free_pcp:1608kB local_pcp:180kB free_cma:5680kB
[2545932.485412] lowmem_reserve[]: 0 0
[2545932.485425] Normal: 291*4kB (UMEHC) 158*8kB (UEHC) 82*16kB (UMEHC) 78*32kB (UMEHC) 32*64kB (UMEH) 17*128kB (UMEH) 7*256kB (MEH) 7*512kB (EH) 4*1024kB (UME) 1*2048kB (M) 1*4096kB (C) = 26076kB
[2545932.485507] 3308 total pagecache pages
[2545932.485515] 2142 pages in swap cache
[2545932.485522] Swap cache stats: add 37056, delete 34914, find 423186/424683
[2545932.485525] Free swap = 0kB
[2545932.485529] Total swap = 102396kB
[2545932.485533] 241664 pages RAM
[2545932.485537] 0 pages HighMem/MovableOnly
[2545932.485541] 5286 pages reserved
[2545932.485545] 2048 pages cma reserved
[2545932.485549] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name
[2545932.485587] [ 139] 0 139 2507 669 8 0 33 0 systemd-journal
[2545932.485598] [ 143] 0 143 2868 1 8 0 126 -1000 systemd-udevd
[2545932.485608] [ 338] 105 338 994 57 5 0 39 0 avahi-daemon
[2545932.485619] [ 339] 0 339 1267 27 6 0 23 0 cron
[2545932.485630] [ 341] 0 341 8035 93 11 0 94 0 rsyslogd
[2545932.485641] [ 347] 104 347 1372 34 6 0 51 -900 dbus-daemon
[2545932.485653] [ 363] 105 363 968 3 4 0 54 0 avahi-daemon
[2545932.485664] [ 374] 0 374 848 20 6 0 32 0 systemd-logind
[2545932.485674] [ 533] 0 533 640 21 5 0 42 0 dhcpcd
[2545932.485686] [ 564] 0 564 1964 31 8 0 84 -1000 sshd
[2545932.485697] [ 603] 65534 603 572 4 6 0 27 0 thd
[2545932.485707] [ 655] 0 655 1012 1 7 0 32 0 agetty
[2545932.485718] [ 721] 106 721 1443 41 6 0 69 0 ntpd
[2545932.485728] [ 913] 999 913 244561 217660 482 0 23859 0 perl
[2545932.485741] [ 7285] 0 7285 1492 69 6 0 5 0 cron
[2545932.485751] [ 7323] 0 7323 477 21 5 0 0 0 sh
[2545932.485762] [ 7329] 0 7329 454 22 4 0 0 0 run-parts
[2545932.485773] [ 7984] 0 7984 1492 69 6 0 5 0 cron
[2545932.485784] [ 8021] 0 8021 477 21 5 0 0 0 sh
[2545932.485795] [ 8025] 0 8025 454 22 5 0 0 0 run-parts
[2545932.485805] [ 8029] 0 8029 477 27 6 0 0 0 apt
[2545932.485816] [ 8046] 0 8046 1806 57 7 0 0 0 apt-config
[2545932.485826] [ 8096] 0 8096 1492 69 6 0 5 0 cron
[2545932.485837] [ 8125] 0 8125 1492 69 6 0 5 0 cron
[2545932.485847] [ 8131] 0 8131 477 20 5 0 0 0 logrotate
[2545932.485857] [ 8134] 0 8134 1269 53 7 0 0 0 logrotate
[2545932.485868] [ 8137] 0 8137 477 21 5 0 0 0 sh
[2545932.485878] [ 8140] 0 8140 454 22 5 0 0 0 run-parts
[2545932.485889] [ 8141] 0 8141 477 20 6 0 0 0 fake-hwclock
[2545932.485899] [ 8143] 0 8143 1485 61 6 0 7 0 cron
[2545932.485910] [ 8148] 0 8148 477 21 5 0 0 0 fake-hwclock
[2545932.485921] [ 8157] 0 8157 477 21 4 0 0 0 sh
[2545932.485931] [ 8158] 0 8158 1386 30 7 0 0 0 dpkg
[2545932.485942] [ 8159] 0 8159 454 23 4 0 0 0 run-parts
[2545932.485952] [ 8162] 0 8162 483 20 6 0 0 0 modprobe
[2545932.485962] [ 8163] 0 8163 856 19 6 0 0 0 date
[2545932.485972] [ 8165] 0 8165 477 20 5 0 0 0 fake-hwclock
[2545932.485979] Out of memory: Kill process 913 (perl) score 923 or sacrifice child
[2545932.486007] Killed process 913 (perl) total-vm:978244kB, anon-rss:870640kB, file-rss:0kB, shmem-rss:0kB
Auszug auf FHEM-Log:
tail -20 /opt/fhem/log/fhem-2021-08-30.log
2021.08.30 19:02:09 1: PERL WARNING: "my" variable $dev masks earlier declaration in same scope at (eval 204138) line 1.
2021.08.30 19:02:09 3: eval: {my $ret; my $dev = $name."Kanal02";my $dev}
2021.08.30 19:06:06 3: ZWave get fu_Licht swmStatus
2021.08.30 19:06:11 2: ZWave: No ACK from fu_Licht after 5s for sentget:1312022602257b
2021.08.30 19:06:13 2: ZWAVE1 transmit NO_ACK for CB 7b, target fu_Licht
2021.08.30 19:09:25 1: Cannot fork: Cannot allocate memory
2021.08.30 19:09:25 1: Cannot fork: Cannot allocate memory
2021.08.30 19:09:28 3: [Astro] No altitude attribute set in global device, using 0.0 m above sea level
2021.08.30 19:09:29 1: PROPLANTA WetterStadtProplanta: Start.650 Could not start forked process, old process still running
2021.08.30 20:02:08 1: PERL WARNING: "my" variable $dev masks earlier declaration in same scope at (eval 204164) line 1.
2021.08.30 20:02:08 3: eval: {my $ret; my $dev = $name."Kanal02";my $dev}
2021.08.30 20:02:08 1: PERL WARNING: "my" variable $dev masks earlier declaration in same scope at (eval 204166) line 1.
2021.08.30 20:02:08 3: eval: {my $ret; my $dev = $name."Kanal02";my $dev}
2021.08.30 20:06:06 3: ZWave get fu_Licht swmStatus
2021.08.30 20:06:11 2: ZWave: No ACK from fu_Licht after 5s for sentget:1312022602257c
2021.08.30 20:06:13 2: ZWAVE1 transmit NO_ACK for CB 7c, target fu_Licht
2021.08.30 20:09:25 1: Cannot fork: Cannot allocate memory
2021.08.30 20:09:25 1: Cannot fork: Cannot allocate memory
2021.08.30 20:09:28 3: [Astro] No altitude attribute set in global device, using 0.0 m above sea level
2021.08.30 20:09:29 1: PROPLANTA WetterStadtProplanta: Start.650 Could not start forked process, old process still running
Leider kann ich den fehlenden Speicherplatz nicht erkennen:
df
Filesystem 1K-blocks Used Available Use% Mounted on
/dev/root 15279920 2104976 12528288 15% /
devtmpfs 468148 0 468148 0% /dev
tmpfs 472756 0 472756 0% /dev/shm
tmpfs 472756 12212 460544 3% /run
tmpfs 5120 4 5116 1% /run/lock
tmpfs 472756 0 472756 0% /sys/fs/cgroup
/dev/mmcblk0p1 41322 21418 19905 52% /boot
Der Status des Dienstes sieht gut aus:
sudo systemctl status fhem.service
● fhem.service - LSB: FHEM server
Loaded: loaded (/etc/init.d/fhem)
Drop-In: /etc/systemd/system/fhem.service.d
└─fhem.conf
Active: active (exited) since Thu 2021-08-05 00:46:03 CEST; 1 months 2 days ago
Process: 658 ExecStart=/etc/init.d/fhem start (code=exited, status=0/SUCCESS)
Aug 05 00:45:44 FhemRaspi3 systemd[1]: Starting LSB: FHEM server...
Aug 05 00:46:01 FhemRaspi3 fhem[658]: Starting fhem...
Aug 05 00:46:03 FhemRaspi3 systemd[1]: Started LSB: FHEM server.
Warning: Unit file changed on disk, 'systemctl daemon-reload' recommended.
Viele Grüße
Dein Speicherproblem ist nicht auf der Festplatte, sondern im Arbeitsspeicher.
Exakt: https://forum.fhem.de/index.php/topic,84372.msg766405.html#msg766405
Gruß, Joachim
Danke für den Hinweis. Der gelinkte Post weist auf viele und verschiedene Ursachen hin. Habe ich eine realistische Chance den Fehler zu finden oder besser den Dienst neu starten, wenn Cannot Fork... im Log steht.
Ich habe tatsächlich keine Ahnung warum es passiert, finde es aber lästig und kann, wenn ich es merke, dann leider nichts mehr feststellen.
Wie du schon gemerkt hast: es gibt leider nicht die eine Lösung...
Als ich noch die Probleme hatte, hab ich auch mit dem notify und Neustart "gelebt"...
Aktuell hab ich keine Probleme mehr... :)
Bei mir war es (sehr wahrscheinlich) der Umstieg auf Buster (oder implizit andere Perl-Version)...
Mehrere Wochen ist ja "gut"...
...in meiner schlimmsten Zeit ging das keine Woche...
...und bei anderen (im Thread) sogar nur Stunden...
Gruß, Joachim
Vielen Dank für die schnelle Hilfe.
Dann probiere ich mal den Reboot und im Winter, sofern es nicht viel schlimmer wird, mit den Aussetzern, versuche ich das Problem zu lokalisieren.
Soll ich meinen Beitrag auf "gelöst" setzen? Faktisch ist er das zwar nicht, aber....
Du kannst ihn ja auch auf "erst mal erledigt" setzen... ;)
Gruß, Joachim