MAXLAN aufgehangen...

[tucka]

Hi,

heute Mittag hat sich mein FHEM auf dem RPI aufgehangen, nachdem sich FHEM anscheinend nicht mehr mit dem CUBE verbinden konnte.

Erst nach booten des RPI und Neustart des CUBEs lief alles wieder.

Hat jemand sowas schon mal gehabt?

Anbei das Logfile:

2013.01.04 11:27:49.286 3: Opening MaxLAN device 192.168.2.107:62910
2013.01.04 11:27:49.296 3: MaxLAN device opened
2013.01.04 11:27:51.299 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:27:51.300 1: MAXLAN_ExpectAnswer: Error while waiting for answer H:
2013.01.04 11:27:53.304 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:27:53.304 1: MAXLAN_ExpectAnswer: Error while waiting for answer M:
2013.01.04 11:27:58.551 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:00.555 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:02.559 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:04.563 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:06.567 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:08.571 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:10.575 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:12.579 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:14.583 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.04 11:28:16.587 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
.... und das geht dann alle 2 Sekunden unendlich so weiter...

Danke!
Tucka

[mathias-mm]

Hallo,

genau dieses Problem habe ich auch. Nach dem Neustart der FB7390 und LanCube ging alles wieder. Ist mir jetzt innerhalb von 3 Tagen 2 mal passiert.
Hat jemand ne Idee?

Grüße

[stobor]

Hallo,

ich habe das jetzt gerade das zweite mal heute, dass FHEM heute nicht mehr reagiert. Im Log finde ich nur:

2013.01.15 18:27:21 3: 1
2013.01.15 18:27:28 3: Opening ml device 192.168.1.21:62910
2013.01.15 18:27:28 3: ml device opened
2013.01.15 18:27:30 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 18:27:30 1: MAXLAN_ExpectAnswer: Error while waiting for answer H:
2013.01.15 18:27:32 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 18:27:32 1: MAXLAN_ExpectAnswer: Error while waiting for answer M:
2013.01.15 18:27:34 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 18:27:36 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 18:27:38 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 18:27:40 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 18:27:42 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 18:27:44 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 18:27:46 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
...
2013.01.15 19:39:33 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 19:39:35 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 19:39:37 1: MAXLAN_ReadSingleResponse: timeout while reading from socket

Das hatte ich heute Nachmittag schon mal. Da half nur ein Neustart der FritzBox.

Woran kann das denn liegen? Es sieht ja so aus, als ob MAX! amok läuft. Das legt ja das komplette FHEM lahm.
Kann man das irgendwie verhindern? (außer MAX! nicht zu nutzen ;-) )
Ich habe die Cube mal vom Strom getrennt. Das half nicht. Die MAX!-Komponenten waren über die MAX!-PC-Software problemlos ansprechbar.

Danke für Hilfe.

[Matthias Gehre]

Kam bei mir noch nicht vor. Vielleicht tritt das genau dann auf, wenn ihr die MAX! Software benutzt?
Oder wenn der Cube die Daten in die Cloud pusht? Nutzt ihr das?

[stobor]

Ich nutze sowohl den Pushdienst als auch die PC-Software. Geht das überhaupt ohne (bei Cube-Nutzung)?
Mit der PC-Software konnte ich jederzit problemlos zugreifen. Auch nachdem ich die Software geschlossen habe, war der Zugriff auf FHEM nicht möglich.
Ich werde mal probieren, ob das Phänomen wieder auftritt, wenn ich die PC-Software erneut starte.
Vielleicht kann man den Fehler ja trotzdem abfangen, da es ja insb. bei der Konfiguration neuer Komponenten mal vorkommen kann, dass man die Software nutzen muss.

[Matthias Gehre]

Damit ich den Fehler beheben kann, muss er erst mal 100% reproduzierbar sein. Also brauche ich die Schritte, die ich durchführen muss,
damit es zum Hänger kommt.

[stobor]

Ich habe jetzt mal versucht, parallel die MAX!-Software zu nutzen und parallel das Verhalten von FHEM beobachtet.

1. FHEM geöffnet (keine MAX!-Anwendung aktiv): Log sieht normal aus

2. MAX!-Software am PC gestartet und mit der Cube verbunden. Ab jetzt taucht im Log im 2sec.-Takt Folgendes auf:
   2013.01.16 19:44:52 3: Opening ml device 192.168.1.21:62910
    2013.01.16 19:44:52 3: Can't connect to 192.168.1.21:62910: Connection refused
    2013.01.16 19:44:52 2: MAXLAN_Connect: Could not connect  
   FHEM reagiert noch normal.

3. Über die MAX!-PC-Software eine MAX!-Konfiguration geändert. Im Log taucht weiterhin "nur" die Fehlermeldung auf:
   2013.01.16 19:47:53 3: Opening ml device 192.168.1.21:62910
    2013.01.16 19:47:53 3: Can't connect to 192.168.1.21:62910: Connection refused
    2013.01.16 19:47:53 2: MAXLAN_Connect: Could not connect
   FHEM reagiert noch normal.
   
4. MAX!-App auf iPhone gestartet. Fehlermeldung in App, dass Gateway nicht verbunden ist. FHEM-LOg zeigt weiterhin "nur" den obig genannten Fehler.

5. Dann MAX!-PC-Software beendet. FHEM-Log liefert keine Fehler mehr.

6. MAX!-App auf iPhone: Datenupdate angefordert. iPhone wurde aktualisiert. Im FHEM-Log weiterhin keine Fehler mehr. FHEM arbeitet normal.

Komisch, damit scheint's nix zu tun zu haben.
Ich habe mir auch noch einmal das Log der MAX!-PC-Software angesehen. als die Probleme auftraten, war bei mir die MAX!-Software nicht aktiv.

Hilft das?

[Matthias Gehre]

Wenn dieser Fehler auftritt, stürzt dann FHEM ab? Also existiert der Perl Prozess noch?

Oder hängt es? Und gibt es weiterhin Ausgaben im Log? Oder hören die
"2013.01.15 19:39:37 1: MAXLAN_ReadSingleResponse: timeout while reading from socket"
plötzlich auf?

[stobor]

Wie kann ich denn feststellen, ob der Perl-Prozess noch läuft?
Ich bin kein Telnet/Linux Experte, darum wäre eine kurze Beschreibung toll.
Ich nutze FHEM auf der FritzBox7390.
Die Meldung scheint aber minutenlang zu kommen, solange bis ich die FritzBox neu gestartet habe.


Jetzt ist mir im Log aber gerade NOCH etwas aufgefallen:

2013.01.15 14:29:07 3: Opening ml device 192.168.1.21:62910
2013.01.15 14:29:07 3: ml device opened
2013.01.15 14:29:09 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 14:29:09 1: MAXLAN_ExpectAnswer: Error while waiting for answer H:
2013.01.15 14:29:11 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
2013.01.15 14:29:11 1: MAXLAN_ExpectAnswer: Error while waiting for answer M:
2013.01.15 14:29:14 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
Use of uninitialized value $rmsg in concatenation (.) or string at ./FHEM/00_MAXLAN.pm line 404.
Use of uninitialized value $rmsg in substr at ./FHEM/00_MAXLAN.pm line 405.
Use of uninitialized value $rmsg in substr at ./FHEM/00_MAXLAN.pm line 406.
substr outside of string at ./FHEM/00_MAXLAN.pm line 406.
Use of uninitialized value in split at ./FHEM/00_MAXLAN.pm line 406.
Use of uninitialized value $rmsg in pattern match (m//) at ./FHEM/00_MAXLAN.pm line 159.
2013.01.15 14:29:16 1: MAXLAN_ReadSingleResponse: timeout while reading from socket
Use of uninitialized value $rmsg in concatenation (.) or string at ./FHEM/00_MAXLAN.pm line 404.
Use of uninitialized value $rmsg in substr at ./FHEM/00_MAXLAN.pm line 405.
Use of uninitialized value $rmsg in substr at ./FHEM/00_MAXLAN.pm line 406.
substr outside of string at ./FHEM/00_MAXLAN.pm line 406.
Use of uninitialized value in split at ./FHEM/00_MAXLAN.pm line 406.
Use of uninitialized value $rmsg in pattern match (m//) at ./FHEM/00_MAXLAN.pm line 159.
...

Diese Meldungen hören auch erst nach einem FritzBox Neustart auf.

[Matthias Gehre]

Ich hab eine Änderung hochgeladen. Die kommt morgen mit dem Update.,
Guckt mal, ob der Fehler dann noch auftritt.

[stobor]

Ab wann wäre die Änderung morgen verfügbar?
Ich bekomme nämlich seit heute 08:16Uhr schon wieder:

MAXLAN_ExpectAnswer: Error while waiting for answer H:
MAXLAN_ReadSingleResponse: timeout while reading from socket
MAXLAN_ExpectAnswer: Error while waiting for answer M:
MAXLAN_ReadSingleResponse: timeout while reading from socket
MAXLAN_ReadSingleResponse: timeout while reading from socket
MAXLAN_ReadSingleResponse: timeout while reading from socket
...

und das Log füllt sich fleißig weiter mit
MAXLAN_ReadSingleResponse: timeout while reading from socket
und es ist jetzt 19:43Uhr.

Könnte das mit Deinem Update behoben werden?
Dann muss ich wohl die ganze FritzBox wieder neu starten, damit sich FHEM wieder berappelt, oder?

[Matthias Gehre]

Weiß nicht, wann die Updates verfügbar werden. Ich committe dir nur in Repository und irgendwann morgens werden die dann per fhem update verfügbar.
Die Fehlermeldungen kommen dann trotzdem noch, aber es sollte FHEM nicht mehr abstürzen.

[stobor]

Super, danke.
Ich habe FHEM aktualisiert. Ich werd's jetzt mal beobachten und mich noch einmal melden.

[stobor]

Es gibt noch immer:

2013.01.20 22:24:04 3: Opening ml device 192.168.1.21:62910
2013.01.20 22:24:04 3: ml device opened
2013.01.20 22:24:07 2: Got message for undefined device, and failed to guess type from msg 'WallThermostatConfig' - ignoring
2013.01.20 22:24:07 2: Got message for undefined device, and failed to guess type from msg 'Error' - ignoring

Ist das was Kritisches?
Und gerade war die gesamte FritzBox extrem langsam (inkl. FHEM Weboberfläche). Und nach ein paar Minuten hat sich die Box von allein neu gestartet. Komisch.
Konnte im Log aber nichts sehen.

[stobor]

Diese Meldungen
2013.01.20 22:24:04 3: Opening ml device 192.168.1.21:62910
2013.01.20 22:24:04 3: ml device opened
2013.01.20 22:24:07 2: Got message for undefined device, and failed to guess type from msg 'WallThermostatConfig' - ignoring
2013.01.20 22:24:07 2: Got message for undefined device, and failed to guess type from msg 'Error' - ignoring
tauchen im Minutentakt auf. Das lastet doch sicherlich unnötig aus, oder?

Außerdem gibt es immer mal wieder so etwas:

2013.01.20 13:59:23 1: MAX_01f4f1 is against deletion (HASH(0xedada8)), continuing with rereadcfg anyway
2013.01.20 13:59:23 1: MAX_011246 is against deletion (HASH(0x6f3eb0)), continuing with rereadcfg anyway
2013.01.20 13:59:23 1: MAX_006445 is against deletion (HASH(0x6f34b0)), continuing with rereadcfg anyway
2013.01.20 13:59:23 1: MAX_006d9b is against deletion (HASH(0x11ee7e8)), continuing with rereadcfg anyway
2013.01.20 13:59:23 1: MAX_0063be is against deletion (HASH(0x6f5740)), continuing with rereadcfg anyway

Ist das relevant?
Insgesamt habe ich das Gefühl, dass die MAX-Integration FHEM noch etwas instabil macht.

Es gibt noch immer:

2013.01.20 22:24:04 3: Opening ml device 192.168.1.21:62910
2013.01.20 22:24:04 3: ml device opened
2013.01.20 22:24:07 2: Got message for undefined device, and failed to guess type from msg 'WallThermostatConfig' - ignoring
2013.01.20 22:24:07 2: Got message for undefined device, and failed to guess type from msg 'Error' - ignoring

Ist das was Kritisches?
Und gerade war die gesamte FritzBox extrem langsam (inkl. FHEM Weboberfläche). Und nach ein paar Minuten hat sich die Box von allein neu gestartet. Komisch.
Konnte im Log aber nichts sehen.