fhem hängt nach hmlan disconnected - reappeared

[jhohn]

Moin,

nachdem heute morgen meine Nachtspeicheröfen nicht richtig geladen waren (was den WAF auf ungefähr Aussentemperaturen senkt), bin ich auf die Suche in den Logs gegangen und habe festgestellt das mein fhem sporadisch neu startet. Vorher sind immer disconnected, reappeared Meldungen des HMLAN im Log und die Zeit zwischen letzter reappeared Meldung und Neustart variiert von ein paar Minuten bis mehrere Stunden. Letzte Nacht scheint fhem dann gegen 22:46 ausgestiegen und nicht neu gestartet zu sein. Ich habe heute morgen um 05:51, als ich es gemerkt habe, die Fritzbox neu gestartet.

Code Auswählen Erweitern


2013.01.07 08:53:05 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.07 08:53:23 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.07 08:55:06 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.07 08:55:36 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.07 08:57:17 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.07 08:58:18 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.07 09:00:04 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.07 09:01:03 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.07 09:02:35 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.07 09:03:10 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.07 09:06:26 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.07 09:06:39 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.07 09:11:35 1: Including fhem.cfg
2013.01.07 09:11:36 3: telnetPort: port 7072 opened
2013.01.07 09:11:37 3: WEB: port 8083 opened
2013.01.07 09:11:37 3: WEBphone: port 8084 opened
2013.01.07 09:11:37 3: WEBtablet: port 8085 opened
2013.01.07 09:11:39 3: No I/O device found for ActionDetector
2013.01.07 09:11:39 3: Opening hmlan device 192.168.178.32:1000
2013.01.07 09:11:39 3: hmlan device opened
2013.01.07 09:11:45 1: Including ./log/fhem.save
2013.01.07 09:11:46 1: usb create starting
2013.01.07 09:11:46 1: usb create end
2013.01.07 09:11:46 0: Server started (version Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2436 2013-01-04 19:38:41Z borisneubert $, pid 1527)


2013.01.08 11:00:21 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.08 11:00:30 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.08 11:01:56 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.08 11:02:36 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.08 11:03:19 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.08 11:03:25 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.08 11:09:37 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.08 11:09:51 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.08 11:15:50 1: Including fhem.cfg
2013.01.08 11:15:51 3: telnetPort: port 7072 opened
2013.01.08 11:15:52 3: WEB: port 8083 opened
2013.01.08 11:15:53 3: WEBphone: port 8084 opened
2013.01.08 11:15:53 3: WEBtablet: port 8085 opened
2013.01.08 11:15:54 3: No I/O device found for ActionDetector
2013.01.08 11:15:55 3: Opening hmlan device 192.168.178.32:1000
2013.01.08 11:15:55 3: hmlan device opened
2013.01.08 11:16:00 1: Including ./log/fhem.save
2013.01.08 11:16:01 1: usb create starting
2013.01.08 11:16:02 1: usb create end
2013.01.08 11:16:02 0: Server started (version Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2442 2013-01-06 17:23:43Z rudolfkoenig $, pid 1502)


2013.01.09 20:06:24 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.09 20:07:40 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.09 23:05:20 1: Including fhem.cfg
2013.01.09 23:05:22 3: telnetPort: port 7072 opened
2013.01.09 23:05:23 3: WEB: port 8083 opened
2013.01.09 23:05:23 3: WEBphone: port 8084 opened
2013.01.09 23:05:23 3: WEBtablet: port 8085 opened
2013.01.09 23:05:25 3: No I/O device found for ActionDetector
2013.01.09 23:05:26 3: Opening hmlan device 192.168.178.32:1000
2013.01.09 23:05:26 3: hmlan device opened
2013.01.09 23:05:37 1: Including ./log/fhem.save
2013.01.09 23:05:38 1: usb create starting
2013.01.09 23:05:39 1: usb create end
2013.01.09 23:05:39 0: Server started (version Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2449 2013-01-07 19:52:24Z rudolfkoenig $, pid 1748)


2013.01.10 08:18:23 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.10 08:18:30 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.10 08:21:24 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.10 08:21:38 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.10 08:22:42 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.10 08:22:50 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.10 08:26:13 1: Including fhem.cfg
2013.01.10 08:26:15 3: telnetPort: port 7072 opened
2013.01.10 08:26:15 3: WEB: port 8083 opened
2013.01.10 08:26:16 3: WEBphone: port 8084 opened
2013.01.10 08:26:16 3: WEBtablet: port 8085 opened
2013.01.10 08:26:17 3: No I/O device found for ActionDetector
2013.01.10 08:26:18 3: Opening hmlan device 192.168.178.32:1000
2013.01.10 08:26:18 3: hmlan device opened
2013.01.10 08:26:24 1: Including ./log/fhem.save
2013.01.10 08:26:24 1: usb create starting
2013.01.10 08:26:25 1: usb create end
2013.01.10 08:26:25 0: Server started (version Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2449 2013-01-07 19:52:24Z rudolfkoenig $, pid 1612)


2013.01.10 08:53:04 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.10 08:53:33 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.10 08:56:38 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.10 08:57:15 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.10 08:58:28 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.10 08:58:37 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.10 08:59:09 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.10 08:59:35 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.10 09:34:11 1: Including fhem.cfg
2013.01.10 09:34:12 3: telnetPort: port 7072 opened
2013.01.10 09:34:13 3: WEB: port 8083 opened
2013.01.10 09:34:13 3: WEBphone: port 8084 opened
2013.01.10 09:34:14 3: WEBtablet: port 8085 opened
2013.01.10 09:34:15 3: No I/O device found for ActionDetector
2013.01.10 09:34:16 3: Opening hmlan device 192.168.178.32:1000
2013.01.10 09:34:16 3: hmlan device opened
2013.01.10 09:34:21 1: Including ./log/fhem.save
2013.01.10 09:34:22 1: usb create starting
2013.01.10 09:34:23 1: usb create end
2013.01.10 09:34:23 0: Server started (version Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2449 2013-01-07 19:52:24Z rudolfkoenig $, pid 1649)


2013.01.11 08:11:27 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.11 08:11:44 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.11 08:12:16 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.11 08:12:24 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.11 08:22:14 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.11 08:22:22 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.11 08:27:41 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.11 08:28:13 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.11 10:38:47 1: Including fhem.cfg
2013.01.11 10:38:48 3: telnetPort: port 7072 opened
2013.01.11 10:38:49 3: WEB: port 8083 opened
2013.01.11 10:38:49 3: WEBphone: port 8084 opened
2013.01.11 10:38:49 3: WEBtablet: port 8085 opened
2013.01.11 10:38:50 3: No I/O device found for ActionDetector
2013.01.11 10:38:51 3: Opening hmlan device 192.168.178.32:1000
2013.01.11 10:38:51 3: hmlan device opened
2013.01.11 10:38:57 1: Including ./log/fhem.save
2013.01.11 10:38:58 1: usb create starting
2013.01.11 10:38:58 1: usb create end
2013.01.11 10:38:58 0: Server started (version Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2449 2013-01-07 19:52:24Z rudolfkoenig $, pid 1745)


2013.01.13 22:40:05 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.13 22:40:32 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.13 22:41:57 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.13 22:42:23 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.13 22:46:26 1: 192.168.178.32:1000 disconnected, waiting to reappear
2013.01.13 22:46:49 1: 192.168.178.32:1000 reappeared (hmlan)
2013.01.14 05:51:02 1: Including fhem.cfg
2013.01.14 05:51:03 3: telnetPort: port 7072 opened
2013.01.14 05:51:04 3: WEB: port 8083 opened
2013.01.14 05:51:04 3: WEBphone: port 8084 opened
2013.01.14 05:51:04 3: WEBtablet: port 8085 opened
2013.01.14 05:51:06 3: No I/O device found for ActionDetector
2013.01.14 05:51:08 3: Opening hmlan device 192.168.178.32:1000
2013.01.14 05:51:08 3: hmlan device opened
2013.01.14 05:51:14 1: Including ./log/fhem.save
2013.01.14 05:51:15 1: usb create starting
2013.01.14 05:51:15 1: usb create end
2013.01.14 05:51:15 0: Server started (version Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2459 2013-01-09 09:14:30Z rudolfkoenig $, pid 1697)


[rudolfkoenig]

Disconnected.. reappeared ist vermutlich irgendwelchen Modulen (WOL?) oder anderen Skripten geschuldet, die fhem blockieren (bisher sind mir HTTP-get/ping/sleep bekannt als Verursacher). Den schuldigen sollte man relativ einfach mit einem detaillierten log rausfinden.

Den Absturz zu finden wird schwieriger, da es relativ selten auftritt: vermutlich wird etwas in der Fritzbox-Console ausgegeben, falls man fhem in einem telnet session direkt startet. Die Console ist auf das erste telnet-session umgeleitet. Allerdings muesste dieser Session bis zum Absturz offen sein.

[jhohn]

Vielen Dank für die schnelle Rückmeldung.
An Modulen nutze ich holiday (für Ferien, Feiertage und Müllabfuhr), Twilight, Sunrise unf FB_mail soll mir Batteriewarnungen schicken. Leere Batterien habe ich aber noch nicht gehabt.
Ich habe aber eben gesehen dass ich "attr hmlan hmProtocolEvents 3" wieder in der Konfig habe. Das hatte ich mal zum testen mit einem HM-PB-2-WM55 eingebaut und später wieder rausgeworfen aber allem Anschein nach vergessen zu speichern. Ich gehe jetzt mal davon aus, dass die disconnected davon kommen.
Das mit der telnetsession kann ich dann erst testen wenn ich wieder zu Hause bin.

[Hansi57]

Hatte ein ähnliches Problem:

2013.01.14 19:46:09 1: /dev/ttyACM0 disconnected, waiting to reappear
2013.01.14 19:46:14 3: Setting CUL_0 baudrate to 9600
2013.01.14 19:46:14 1: /dev/ttyACM0 reappeared (CUL_0)
2013.01.14 19:46:16 1: /dev/ttyACM0 disconnected, waiting to reappear
2013.01.14 19:46:22 3: Setting CUL_0 baudrate to 9600
2013.01.14 19:46:22 1: /dev/ttyACM0 reappeared (CUL_0)
2013.01.14 19:47:06 1: /dev/ttyACM0 disconnected, waiting to reappear
2013.01.14 19:47:11 3: Setting CUL_0 baudrate to 9600
2013.01.14 19:47:11 1: /dev/ttyACM0 reappeared (CUL_0)

usw. Das Problem war folgende Zeile:

define CUL1 CUL /dev/ttyACM0@9600 1234

in der fhem.cfg (vorletzte Zeile) Dieser Eintrag wird gar nicht genutzt. Ich hab die Zeile einfach gelöscht und dann war der Effekt weg. Schon seit 1 Stunde.

[jhohn]

Da gestern mein RPi gekommen ist habe ich alles darauf umgezogen. Auf der Fritzbox läuft also derzeit nur ein leeres fhem, in welches demnächst mal ein paar FritzBox Funktionen eingebaut werden. Die Telnetsession läuft und fals sich fhem da mal wieder aufhängen sollte melde ich mich hier wieder.

Beim Umzug und Testen des Systems ist mir aufgefallen dass die disconnected - reappeared Meldungen, auch auf dem RPi, öfter mal kommen wenn ich Seiten mit Monatsplots aufrufe. Fhem scheint dann wohl mit der Generierung des Plots beschäftigt zu sein und verliert dadurch die Verbindung zum HMLAN. Aber das gehört dann nicht mehr hier in die Fritz!Box Abteilung.