FHEM Startet nicht: HttpUtils - Bad arg length for Socket::pack_sockaddr_in

[Strida]

Nachdem ich heute (gerade eben) ein Update durchgeführt habe, startet FHEM nicht mehr:

Code Auswählen Erweitern

2016.05.15 15:40:58 5: Starting notify loop for ActionDetector, first event alive:23 dead:0 unkn:5 off:0
2016.05.15 15:40:58 5: HMLAN_Send:  HMLAN1 I:+35B49D,00,00,00
2016.05.15 15:40:58 5: Triggering vCCU (1 changes)
2016.05.15 15:40:58 5: Starting notify loop for vCCU, first event HMLAN1:UAS,
2016.05.15 15:40:58 5: Triggering Notify.Fhem.Reload
2016.05.15 15:40:58 4: Notify.Fhem.Reload exec set teleBot message Fhem (re)started - Now!
2016.05.15 15:40:58 5: Cmd: >set teleBot message Fhem (re)started - Now!<
2016.05.15 15:40:58 4: TelegramBot_Set teleBot: called
2016.05.15 15:40:58 4: TelegramBot_Set teleBot: Processing TelegramBot_Set( message )
2016.05.15 15:40:58 5: TelegramBot_Set teleBot: start send for cmd :message: and sendType :0:
2016.05.15 15:40:58 5: TelegramBot_SendIt teleBot: called
2016.05.15 15:40:58 5: TelegramBot_SendIt teleBot: try to send message to :xxxxxxxxx: -:Fhem (re)started - Now!: - :<undef>:
2016.05.15 15:40:58 4: TelegramBot_GetFullnameForContact # Contacts is <undef>
2016.05.15 15:40:58 4: HttpUtils url=<hidden>
Bad arg length for Socket::pack_sockaddr_in, length is 0, should be 4 at /usr/lib/perl/5.18/Socket.pm line 154.


Wenn ich die Definition von Telegram deaktiviert läuft alles andere wie gehabt.

Nachdem ich gestern ebenfalls ein Update installiert habe, scheint das mit Änderungen in dem Modul HttpUtils.pm passiert zu sein, da ich an meiner Konfiguration nichts verändert habe.

Falls der Fehler auf meiner Seite liegt: kann mir bitte jemand helfen FHEM mit Telegram wieder zum laufen zu bringen?

[rudolfkoenig]

Kannst du bitte:
- testen, ob es mit dem alten HttpUtils.pm funktioniert (siehe restore FHEM-Befehl)
- OS und Perl-Version hier mitteilen (steht im Log beim starten)
- uns sagen, ob du "attr global dnsServer" gesetzt hast

[Strida]

Nach dem restore startet fhem wieder, auch mit TelegramBot aktiv:

Code Auswählen Erweitern

fhem> restore 2016-05-15
restore ./FHEM/00_ZWDongle.pm
restore ./FHEM/10_CUL_HM.pm
restore ./FHEM/10_ZWave.pm
restore ./FHEM/31_HUEDevice.pm
restore ./FHEM/50_HP1000.pm
restore ./FHEM/98_backup.pm
restore ./FHEM/HttpUtils.pm
restore ./FHEM/controls_fhem.txt
restore ./fhem.pl


"attr global dnsServer" ist in meiner fhem.cfg nicht zu finden.

Code Auswählen Erweitern

2016.05.15 17:59:18 0: Server started with 273 defined entities (fhem.pl:11425/2016-05-10 perl:5.018002 os:linux ...

Code Auswählen Erweitern

Linux XXXX 3.16.0-30-generic #40~14.04.1-Ubuntu SMP Thu Jan 15 17:43:14 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

Ich hoffe das hilft.

[rudolfkoenig]

Ich kann das Problem bei mir nicht reproduizieren. Kannst Du es bitte mit dem angehaengten HttpUtils.pm nochmal probieren, und die Zeilen mit DNS: aus dem Log hier posten?

[Strida]

Mit dieser Version funktioniert fhem ebenfalls.

Die Zeilen mit DNS:

Code Auswählen Erweitern

log$ grep "DNS: " fhem-2016-05.log
2016.05.15 22:05:04 1: DNS: api.telegram.org:149.154.167.200
2016.05.15 22:05:33 1: DNS: api.telegram.org:149.154.167.199
2016.05.15 22:05:38 1: DNS: api.telegram.org:149.154.167.197
2016.05.15 22:05:43 1: DNS: api.telegram.org:149.154.167.198
2016.05.15 22:05:48 1: DNS: api.telegram.org:149.154.167.200
2016.05.15 22:05:53 1: DNS: api.telegram.org:149.154.167.199
2016.05.15 22:05:58 1: DNS: api.telegram.org:149.154.167.197
2016.05.15 22:06:04 1: DNS: api.telegram.org:149.154.167.198
2016.05.15 22:06:09 1: DNS: api.telegram.org:149.154.167.200
2016.05.15 22:06:14 1: DNS: api.telegram.org:149.154.167.199
2016.05.15 22:06:20 1: DNS: api.telegram.org:149.154.167.198
2016.05.15 22:06:49 1: DNS: api.telegram.org:149.154.167.199
2016.05.15 22:06:54 1: DNS: api.telegram.org:149.154.167.197
2016.05.15 22:06:59 1: DNS: api.telegram.org:149.154.167.199


[rudolfkoenig]

Danke, etwas ueberraschend. Wenn ich es richtig verstehe, liefert inet_aton ein Ergebnis zurueck, und gethostbyname nicht. Da ich das nicht so recht glauben kann, bitte ich dich mit der hier angehaengten Version das nochmal zu verifizieren, und die DNS: Zeilen wieder anzuhaengen.

[Strida]

Die HttpUtils von Deinem letzten Post konnte ich noch nicht testen. Dafür ist aber mit der davor gepostetn Version mein FHEM Server heute am späten Nachmittag völlig unmotiviert wieder zum Stillstand gekommen:

Code Auswählen Erweitern


2016.05.19 17:38:12 1: DNS: api.telegram.org:149.154.167.198
2016.05.19 17:38:37 1: DNS: api.telegram.org:149.154.167.197
2016.05.19 17:39:02 1: DNS: api.telegram.org:149.154.167.199
2016.05.19 17:39:26 1: DNS: api.telegram.org:149.154.167.200
2016.05.19 17:39:50 1: DNS: api.telegram.org:149.154.167.198
2016.05.19 17:40:24 1: DNS: gethostbyname
2016.05.19 17:40:28 1: PERL WARNING: Use of uninitialized value in unpack at FHEM/HttpUtils.pm line 105.
2016.05.19 17:40:28 1: PERL WARNING: Missing argument in sprintf at FHEM/HttpUtils.pm line 105.
2016.05.19 17:40:28 1: DNS: api.telegram.org:0.0.0.0
Bad arg length for Socket::pack_sockaddr_in, length is 0, should be 4 at /usr/lib/perl/5.18/Socket.pm line 154.


Nachdem mir das zwei Stunden später erst aufgefallen ist, als ich heim gekommen bin, hat sich FHEM wieder anstandslos starten lassen. Ich vermute mal, dass das eventuell irgendein Verbindungsproblem ist? In der Zeit lief auch ein Upload für ein Backup, der meine Internetverbindung sicher sehr ausgelastet hat. Ansonsten war in den Logs nichts zu finden, da auch niemand zu Hause war.

[Strida]

Die zweite (hier gepostete) Version der HttpUtils liefert die gleichen log-Einträge:

Code Auswählen Erweitern

2016.05.21 15:31:57 1: DNS: api.telegram.org:149.154.167.199
2016.05.21 15:32:03 1: DNS: api.telegram.org:149.154.167.198
2016.05.21 15:32:08 1: DNS: api.telegram.org:149.154.167.200
2016.05.21 15:32:13 1: DNS: api.telegram.org:149.154.167.197
2016.05.21 15:32:18 1: DNS: api.telegram.org:149.154.167.199
2016.05.21 15:32:23 1: DNS: api.telegram.org:149.154.167.198
2016.05.21 15:32:28 1: DNS: api.telegram.org:149.154.167.200
2016.05.21 15:32:33 1: DNS: api.telegram.org:149.154.167.197
2016.05.21 15:32:39 1: DNS: api.telegram.org:149.154.167.199
2016.05.21 15:32:44 1: DNS: api.telegram.org:149.154.167.198
2016.05.21 15:32:49 1: DNS: api.telegram.org:149.154.167.200
2016.05.21 15:32:54 1: DNS: api.telegram.org:149.154.167.197
2016.05.21 15:32:59 1: DNS: api.telegram.org:149.154.167.199
2016.05.21 15:33:04 1: DNS: api.telegram.org:149.154.167.198
2016.05.21 15:33:09 1: DNS: api.telegram.org:149.154.167.200
2016.05.21 15:33:15 1: DNS: api.telegram.org:149.154.167.197
2016.05.21 15:33:20 1: DNS: api.telegram.org:149.154.167.199
2016.05.21 15:33:25 1: DNS: api.telegram.org:149.154.167.198


[rudolfkoenig]

Sorry, das war nicht die zweite Version. Bei der zweiten Version steht sowas wie

DNS: $host ia:OK , ghbn:N/A

im Log.

[Strida]

Ja, ich hatte versehentlich die falsche (alte) Datei kopiert :/

Nach dem Neustart kommt jetzt:

Code Auswählen Erweitern

2016.05.21 16:15:52 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:15:57 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:02 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:07 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:12 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:17 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:22 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:28 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:33 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:38 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:43 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:48 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:53 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:16:58 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:17:03 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.21 16:17:09 1: DNS: api.telegram.org ia:OK, ghbn:OK


[rudolfkoenig]

Laut diese Ausgabe waren die am Anfang gemeldeten Probleme nur temporaer :/

[Strida]

Heute wieder das gleiche Problem: Die Internet-Verbindung war vom Kabelprovider für einige Minuten ausgefallen und hat FHEM damit zum Absturz gebracht:

Code Auswählen Erweitern

2016.05.25 11:12:46 3: CUL_HM set Dimmer.WohnZi.Regal on
Bad arg length for Socket::pack_sockaddr_in, length is 0, should be 4 at /usr/lib/perl/5.18/Socket.pm line 154.


Code Auswählen Erweitern

/opt/fhem/log$ ls -lah fhem-2016-05.log
-rw-r--r-- 1 fhem dialout 9,3M Mai 25 11:48 fhem-2016-05.log


FHEM ist ganz aktuell:

Code Auswählen Erweitern

fhem> version
Latest Revision: 11507


[rudolfkoenig]

2016.05.25 11:12:46 3: CUL_HM set Dimmer.WohnZi.Regal on
Bad arg length for Socket::pack_sockaddr_in, length is 0, should be 4 at /usr/lib/perl/5.18/Socket.pm line 154.

JETZT waere die Ausgabe der oben angehaengten HttpUtils.pm interessant gewesen.

Ich habe laenger ueber den Code gebruetet, und meine (mit 90%-er Wahrscheinlichkeit, s.u.), dass "dein" gethostbyname sich in so einem Fall "ungewoehnlich" (falsch?) verhaelt, da kein undef zurueckliefert, sondern eine hostent Struktur, allerdings ohne Adresse.
Ich habe die Abfrage nach dem Fehler in HttpUtils.pm geaendert, und hoffe, dass sie besser trifft. Diesen Fix liefert update morgen ab 8.
Alternativ kannst du auch den etwa zwei Wochen alten, selbstgeschriebenen nichtblockierenden gethostbyname-Code verwenden, indem du "attr global dnsServer IP" setzt, wobei IP mit der IP des DNS-Servers (FritzBox?) ersetzt werden muss.
Mein 10% Rest-Irrtum kommt daher, da ich nicht sicher bin, dass Telegram in diesem Fall HttpUtils_NonblockingGet aufgerufen hat.

ls -lah fhem-2016-05.log

Weiss nicht, was mir das sagen soll.

fhem> version
Latest Revision: 11507

Mein version Befehl gibt sowas nicht aus :/

[Strida]

JETZT waere die Ausgabe der oben angehaengten HttpUtils.pm interessant gewesen.

Ich hab die nochmal eingespielt und das WAN interface deaktiviert, dabei kommt:

Code Auswählen Erweitern

2016.05.26 00:58:24 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.26 00:58:29 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.26 00:58:34 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.26 00:58:49 1: DNS: api.telegram.org ia:N/A, ghbn:N/A
2016.05.26 00:58:53 1: DNS: api.telegram.org ia:N/A, ghbn:N/A
2016.05.26 00:58:58 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.26 00:59:19 1: DNS: api.telegram.org ia:OK, ghbn:OK
2016.05.26 00:59:41 1: DNS: api.telegram.org ia:OK, ghbn:OK


Wobei das "N/A" nur kommt, wenn das WLAN interface abgeschaltet wird. Wenn es abgeschaltet ist, kommt interessanterweise wieder das "OK".

Der Router ist ein ASUS RT-N66U. FHEM läuft auf einem Intel Nuc mit Ubuntu 14.04 LTS mit aktuellen updates.

[rudolfkoenig]

Ich hab die nochmal eingespielt und das WAN interface deaktiviert, dabei kommt:

Offensichtlich ist das ungleich ausgefallene Internet-Verbindung, sonst waere FHEM dabei abgestuerzt. Ich vermute, dass in so einem Fall "NS: api.telegram.org ia:N/A, ghbn:OK" gekommen waere, gefolgt von dem Absturz. Die aktuelle HttpUtils.pm Version sollte aber nicht mehr das Problem haben. Und "attr global dnsServer <IP>" duerfte fuer noch weniger Probleme sorgen, da es sich bei der Namensaufloesung nicht blockiert.