FHEM hängt sich in unregelmäßigen Abständen auf

error500 · 21 Oktober 2015, 21:23:38

Hallo zusammen,

seit einiger Zeit (ca. 4 Wochen) hängt sich FHEM irgendwie auf. An manchen Tagen passiert nichts, an anderen ein oder mehrere male.

Der Raspberry selbst lässt nicht noch via ssh erreichen und z.b. neu starten. In FHEM eingebundene Geräte werden nicht mehr entsprechend der eingestellten Zeitbefehle angesprochen und das Webinterface ist nicht erreichbar.

Ich habe daraufhin das Loglevel auf 5 gestellt und gehofft im Logfile was zu finden. Mir selbst ist daran nichts aufgefallen, was aber nichts heißen soll.

Da ich keine Ahnung habe, woran es liegen kann und hier ungerne das "gesamte System" posten möchte, sagt mir bitte, was ihr an Infos benötigt.

Das Raspberry-System, sowie FHEM selbst habe ich über die entsprechenden Funktionen aktuell gehalten.

Grüße und vielen Dank schon mal,
Mark

rudolfkoenig · 21 Oktober 2015, 21:39:34

Vermutlich wartet irgendein Modul vergeblich auf Daten, oder dreht eine Endlosschleife.
Ich wuerde folgendes probieren:
- per ssh auf dem RPi anmelden, und mit "top" pruefen, ob FHEM Endlosschleife dreht.
- wenn nicht, dann FHEM-PID aus top oder ps merken, und mit "strace -p PID" pruefen, warum FHEM blockiert ist. Vermutlich sieht man im strace-output nur eine Zeile mit read(X, ...). Was hinter X steht, kriegt man mit "ls -l /proc/<PID>/fd/<X>" raus.
- das Ende der Logfile (die letzten 10-20 Zeilen) hier posten

error500 · 22 Oktober 2015, 07:00:23

Hallo,

folgendes hat die Ausgabe von top in Bezug auf FHEM ergeben:

Code Auswählen

2180 fhem 20 0 30916 28m 3768 S 0.0 6.7 97:02.44 perl fhem.pl fhem.cfg

Anschließend mit strace:

Code Auswählen

pi@fhemberry ~ $ sudo strace -p 2180
Process 2180 attached - interrupt to quit
recvfrom(27,

Mit dem ls-Befehl komme ich dann auf folgendes:

Code Auswählen

pi@fhemberry ~ $ sudo ls -l /proc/2180/fd/27
lrwx------ 1 root root 64 Oct 22 06:58 /proc/2180/fd/27 -> socket:[31853]

Hier noch die letzten Zeilen auf dem fhem-log (loglevel 5):

Code Auswählen

2015.10.22 05:00:48 5: JeeLink/RAW: /OK 9 8
2015.10.22 05:00:48 5: JeeLink/RAW: OK 9 8/ 1 4 160 65

2015.10.22 05:00:48 5: JeeLink_0 dispatch OK 9 8 1 4 160 65
2015.10.22 05:00:49 5: JeeLink/RAW: /OK 
2015.10.22 05:00:49 5: JeeLink/RAW: OK /9 54 1 4 155 106

2015.10.22 05:00:49 5: JeeLink_0 dispatch OK 9 54 1 4 155 106
2015.10.22 05:00:51 5: exec at command Temperatur_anzeigen
2015.10.22 05:00:51 5: redefine at command Temperatur_anzeigen as +*00:00:25 { squeezebox_forecast() }
2015.10.22 05:00:52 5: JeeLink/RAW: /OK 9 22 
2015.10.22 05:00:52 5: JeeLink/RAW: OK 9 22 /1 4 157 70

2015.10.22 05:00:52 5: JeeLink_0 dispatch OK 9 22 1 4 157 70
2015.10.22 05:00:58 5: JeeLink/RAW: /OK 9 
2015.10.22 05:00:58 5: JeeLink/RAW: OK 9 /8 1 4 160 65

2015.10.22 05:00:58 5: JeeLink_0 dispatch OK 9 8 1 4 160 65
2015.10.22 05:00:59 5: JeeLink/RAW: /OK 9 54
2015.10.22 05:00:59 5: JeeLink/RAW: OK 9 54/ 1 4 155 106

2015.10.22 05:00:59 5: JeeLink_0 dispatch OK 9 54 1 4 155 106
2015.10.22 05:01:01 5: JeeLink/RAW: /OK 9 9 1
2015.10.22 05:01:01 5: JeeLink/RAW: OK 9 9 1/ 4 84 82

2015.10.22 05:01:01 5: JeeLink_0 dispatch OK 9 9 1 4 84 82
2015.10.22 05:01:02 5: JeeLink/RAW: /OK 9
2015.10.22 05:01:02 5: JeeLink/RAW: OK 9/ 22 1 4 157 70

2015.10.22 05:01:02 5: JeeLink_0 dispatch OK 9 22 1 4 157 70

Wobei mir aufgefallen ist, dass der Temperatur_anzeigen-at zu der Uhrzeit eigentlich inaktiv ist. Wir i.d.R. zwischen 6 und 8 Uhr aktiviert.

Viele Grüße
Mark

rudolfkoenig · 22 Oktober 2015, 13:19:40

Danke, und jetzt noch ein "lsof -p <FHEM-PID>", am besten zeitnahm mit einem erneuten "strace -p <FHEM-PID>".

recvfrom heisst, ein FHEM-Modul wartet auf Netzwerk-Daten, und das ist falsch, weil sowas nur nach "Genehmgung" (d.h. wenn das globale select meldet, dass Daten zu empfangen sind) gemacht werden darf. Ich hoffe, mit lsof die Adresse der Gegenseite rauszukriegen, und dadurch auf das problematisch Modul schliessen kann.

rudolfkoenig · 22 Oktober 2015, 13:27:11

Die Meldung vom at kam auch falls disable aktiv ist.
Habs geaendert und eingecheckt.

error500 · 23 Oktober 2015, 07:09:33

Hallo,

hier die nächsten Ausgaben:

Code Auswählen

pi@fhemberry ~ $ sudo lsof -p 2150
COMMAND  PID USER   FD   TYPE DEVICE  SIZE/OFF   NODE NAME
perl    2150 fhem  cwd    DIR  179,2      4096 262371 /opt/fhem
perl    2150 fhem  rtd    DIR  179,2      4096      2 /
perl    2150 fhem  txt    REG  179,2      9800   8794 /usr/bin/perl
perl    2150 fhem  mem    REG  179,2     87792   5186 /lib/arm-linux-gnueabihf/libz.so.1.2.7
perl    2150 fhem  mem    REG  179,2     75620 135978 /usr/lib/perl/5.14.2/auto/Compress/Raw/Zlib/Zlib.so
perl    2150 fhem  mem    REG  179,2     18040   8763 /usr/lib/perl/5.14.2/auto/File/Glob/Glob.so
perl    2150 fhem  mem    REG  179,2     30496 136039 /usr/lib/perl/5.14.2/auto/Encode/Encode.so
perl    2150 fhem  mem    REG  179,2     71528   3962 /lib/arm-linux-gnueabihf/libresolv-2.13.so
perl    2150 fhem  mem    REG  179,2     18040   1880 /lib/arm-linux-gnueabihf/libnss_dns-2.13.so
perl    2150 fhem  mem    REG  179,2     17932 136024 /usr/lib/perl/5.14.2/auto/Digest/MD5/MD5.so
perl    2150 fhem  mem    REG  179,2      8624 262334 /usr/lib/perl5/auto/Device/SerialPort/SerialPort.so
perl    2150 fhem  mem    REG  179,2     30384 136006 /usr/lib/perl/5.14.2/auto/Data/Dumper/Dumper.so
perl    2150 fhem  mem    REG  179,2     42692   3949 /lib/arm-linux-gnueabihf/libnss_files-2.13.so
perl    2150 fhem  mem    REG  179,2     38608   3946 /lib/arm-linux-gnueabihf/libnss_nis-2.13.so
perl    2150 fhem  mem    REG  179,2     71624   3954 /lib/arm-linux-gnueabihf/libnsl-2.13.so
perl    2150 fhem  mem    REG  179,2     26484   3963 /lib/arm-linux-gnueabihf/libnss_compat-2.13.so
perl    2150 fhem  mem    REG  179,2     13784 136035 /usr/lib/perl/5.14.2/auto/MIME/Base64/Base64.so
perl    2150 fhem  mem    REG  179,2     84480   8756 /usr/lib/perl/5.14.2/auto/POSIX/POSIX.so
perl    2150 fhem  mem    REG  179,2     13840   8761 /usr/lib/perl/5.14.2/auto/Fcntl/Fcntl.so
perl    2150 fhem  mem    REG  179,2     26632   3952 /lib/arm-linux-gnueabihf/librt-2.13.so
perl    2150 fhem  mem    REG  179,2     22128   8760 /usr/lib/perl/5.14.2/auto/List/Util/Util.so
perl    2150 fhem  mem    REG  179,2     22080 136071 /usr/lib/perl/5.14.2/auto/Time/HiRes/HiRes.so
perl    2150 fhem  mem    REG  179,2     30312 261948 /usr/lib/perl5/auto/Socket/Socket.so
perl    2150 fhem  mem    REG  179,2    130448  16120 /lib/arm-linux-gnueabihf/libgcc_s.so.1
perl    2150 fhem  mem    REG  179,2     30276   3964 /lib/arm-linux-gnueabihf/libcrypt-2.13.so
perl    2150 fhem  mem    REG  179,2   1200240   3951 /lib/arm-linux-gnueabihf/libc-2.13.so
perl    2150 fhem  mem    REG  179,2    116462   3948 /lib/arm-linux-gnueabihf/libpthread-2.13.so
perl    2150 fhem  mem    REG  179,2    427628   1888 /lib/arm-linux-gnueabihf/libm-2.13.so
perl    2150 fhem  mem    REG  179,2      9812   3953 /lib/arm-linux-gnueabihf/libdl-2.13.so
perl    2150 fhem  mem    REG  179,2   1347628   8793 /usr/lib/libperl.so.5.14.2
perl    2150 fhem  mem    REG  179,2     13880   8757 /usr/lib/perl/5.14.2/auto/IO/IO.so
perl    2150 fhem  mem    REG  179,2     10170  27297 /usr/lib/arm-linux-gnueabihf/libcofi_rpi.so
perl    2150 fhem  mem    REG  179,2    126236   3945 /lib/arm-linux-gnueabihf/ld-2.13.so
perl    2150 fhem  mem    REG  179,2       733  15051 /etc/group
perl    2150 fhem    0r   CHR    1,3       0t0   3541 /dev/null
perl    2150 fhem    1w   REG  179,2 117142710 268441 /opt/fhem/log/fhem-2015-42.log
perl    2150 fhem    2w   REG  179,2 117142710 268441 /opt/fhem/log/fhem-2015-42.log
perl    2150 fhem    3r   REG  179,2       733  15051 /etc/group
perl    2150 fhem    4w   REG  179,2 117142710 268441 /opt/fhem/log/fhem-2015-42.log
perl    2150 fhem    5u  IPv4   6724       0t0    TCP fhemberry.fritz.box:59973->Datenkiste.fritz.box:9090 (ESTABLISHED)
perl    2150 fhem    6u  IPv4   6463       0t0    TCP *:7072 (LISTEN)
perl    2150 fhem    7u  IPv4   6539       0t0    TCP *:8083 (LISTEN)
perl    2150 fhem    8u  IPv4   6541       0t0    TCP *:8084 (LISTEN)
perl    2150 fhem    9u  IPv4   6544       0t0    TCP *:8085 (LISTEN)
perl    2150 fhem   10w   REG  179,2         0 268439 /opt/fhem/log/fhem-2015-10.log
perl    2150 fhem   11u  IPv4  51036       0t0    TCP fhemberry.fritz.box:35444->LED-AQ.fritz.box:5577 (CLOSE_WAIT)
perl    2150 fhem   12u   CHR  166,0       0t0   4328 /dev/ttyACM0
perl    2150 fhem   13u   CHR  188,0       0t0   4541 /dev/ttyUSB0
perl    2150 fhem   14w   REG  179,2   1791933 268435 /opt/fhem/log/LaCrosse_16-2015-10.log
perl    2150 fhem   15w   REG  179,2   1747688 268440 /opt/fhem/log/sysmon-2015-42.log
perl    2150 fhem   16w   REG  179,2   3552156 268431 /opt/fhem/log/wetter-2015-10.log
perl    2150 fhem   17w   REG  179,2   1342496 268432 /opt/fhem/log/LaCrosse_09-2015-10.log
perl    2150 fhem   18w   REG  179,2    858262 268433 /opt/fhem/log/LaCrosse_36-2015-10.log
perl    2150 fhem   19u  IPv4  52905       0t0    TCP fhemberry.fritz.box:36493->LED-SZ.fritz.box:5577 (CLOSE_WAIT)
perl    2150 fhem   20u  IPv4  52791       0t0    TCP fhemberry.fritz.box:44785->LED-SC.fritz.box:5577 (CLOSE_WAIT)
perl    2150 fhem   21w   REG  179,2   1853255 268434 /opt/fhem/log/LaCrosse_08-2015-10.log
perl    2150 fhem   22u  IPv4   6716       0t0    TCP *:http-alt (LISTEN)
perl    2150 fhem   23u  IPv4   6717       0t0    TCP fhemberry.fritz.box:43498->LED-DT.fritz.box:5577 (CLOSE_WAIT)
perl    2150 fhem   24w   REG  179,2      2846 268383 /opt/fhem/log/SB_PLAYER_0004202bc999-2015-10.log
perl    2150 fhem   25w   REG  179,2      4323 268436 /opt/fhem/log/SB_PLAYER_0004202960da-2015-10.log
perl    2150 fhem   26u  IPv4   6718       0t0    TCP fhemberry.fritz.box:46971->fritz.box:1012 (ESTABLISHED)
perl    2150 fhem   27u  IPv4  59150       0t0    TCP fhemberry.fritz.box:50128->LED-DT.fritz.box:5577 (ESTABLISHED)

und

Code Auswählen

pi@fhemberry ~ $ sudo strace -p 2150
Process 2150 attached - interrupt to quit
recvfrom(27, ^C <unfinished ...>
Process 2150 detached
pi@fhemberry ~ $ sudo ls -l /proc/2150/fd/27
lrwx------ 1 root root 64 Oct 22 13:54 /proc/2150/fd/27 -> socket:[59150]

Vielen Dank für die Hilfe.

Gruß Mark

rudolfkoenig · 23 Oktober 2015, 08:40:51

strace sagt, dass man wg FD-Nr 27 blockiert ist, und lsof sagt, 27 entspricht der Netzwerk-Verbindung LED-DT.fritz.box:5577
Als naechstes muss man im fhem.cfg pruefen, welches Modul sich an LED-DT.fritz.box:5577 wendet, und im passenden Forum (siehe MAINTAINER.txt) dem Modulautor das Problem schildern.

error500 · 23 Oktober 2015, 09:12:09

Super, jetzt weiß ich wo ich ansetzen muss

Danke für die Hilfe und für den schönen Leitfaden, wie man rausfindet, was fhem blockiert.