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
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
Hallo,
folgendes hat die Ausgabe von top in Bezug auf FHEM ergeben:
2180 fhem 20 0 30916 28m 3768 S 0.0 6.7 97:02.44 perl fhem.pl fhem.cfg
Anschließend mit strace:
pi@fhemberry ~ $ sudo strace -p 2180
Process 2180 attached - interrupt to quit
recvfrom(27,
Mit dem ls-Befehl komme ich dann auf folgendes:
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):
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
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.
Die Meldung vom at kam auch falls disable aktiv ist.
Habs geaendert und eingecheckt.
Hallo,
hier die nächsten Ausgaben:
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
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
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 (http://fhem.de/MAINTAINER.txt)) dem Modulautor das Problem schildern.
Super, jetzt weiß ich wo ich ansetzen muss ;D
Danke für die Hilfe und für den schönen Leitfaden, wie man rausfindet, was fhem blockiert.