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.

[FunkOdyssey]

Und "attr global dnsServer <IP>" duerfte fuer noch weniger Probleme sorgen, da es sich bei der Namensaufloesung nicht blockiert.

Könntest du vielleicht irgendwann einen Hinweis auf das neue Attribut in der CommandRef aufnehmen? Vielen Dank.

[rudolfkoenig]

Erledigt:

dnsServer
Contains the IP address of the DNS Server. If some of the modules or user code calls the HttpUtils_NonblockingGet function, and this attribute is set, then FHEM specific nonblocking code will be used to resolve the given address. If this attribute is not set, the blocking OS implementation (inet_aton and gethostbyname) will be used.

dnsServer
Enthält die IP Adresse des DNS Servers. Die von bestimmten Modulen (oder eigenen Code) aufgerufene HttpUtils_NonblockingGet wird auch bei der DNS Auflösung nicht mehr blockieren, falls dieses Attribut gesetzt ist, da es in diesem Fall FHEM eigene Routinen aufgerufen werden. Sonst werden die OS-eigenen, blockierenden Routinen inet_aton bzw gethostbyname aufgerufen.

[Nemo0815]

Hallo,

ich habe genau das gleiche Problem, seit heute nach FHEM update (war 2 Wochen im Urlaub) ist FHEM nicht mehr über HTTP erreichbar,

Im log steht auch  folgendes:
Bad arg length for Socket::pack_sockaddr_in, length is 0, should be 4 at /usr/lib/arm-linux-gnueabihf/perl5/5.20/Socket.pm line 833.

Gibts dafür schon eine Lösung?

[rudolfkoenig]

Versuch mal:
- 'attr global stacktrace' in fhem.cfg einzufuegen, FHEM neu starten, und Log hier anhaengen.
- HttpUtils.pm aus diesem Thread ausprobieren
- 'attr global dnsServer ....' zu setzen
- restore für HttpUtils.pm durchzuführen

[Nemo0815]

Versuch mal:
- 'attr global stacktrace' in fhem.cfg einzufuegen, FHEM neu starten, und Log hier anhaengen.
- HttpUtils.pm aus diesem Thread ausprobieren
- 'attr global dnsServer ....' zu setzen
- restore für HttpUtils.pm durchzuführen

Stacktrace hab ich im anderen Thread bereits angehängt (https://forum.fhem.de/index.php/topic,57546.0.html), dnsServer hat nichts gebracht, versuche jetzt mal einen Restore

[Nemo0815]

Die HttpUtils.pm aus diesem Thread hat leider auch nichts gebracht, scheint wohl eines der anderen Module der schuldige zu sein die seit dem letzten Update hochgezogen wurden... 

Hier nochmal der Stacktrace mit dem HttpUtils.pm aus dem Thread:

Code Auswählen Erweitern

2016.09.11 15:15:45 1: PERL WARNING: Bareword found where operator expected at ./FHEM/99_perfmon.pm line 4, near ""stylesheet" type"
2016.09.11 15:15:45 1: PERL WARNING: (Missing operator before type?)
2016.09.11 15:15:45 1: PERL WARNING: Bareword found where operator expected at ./FHEM/99_perfmon.pm line 4, near ""text/css" href"
2016.09.11 15:15:45 1: PERL WARNING: (Missing operator before href?)
2016.09.11 15:15:45 1: reload: Error:Modul 99_perfmon deactivated:
Unterminated <> operator at ./FHEM/99_perfmon.pm line 9.

2016.09.11 15:15:45 1: Including fhem.cfg
2016.09.11 15:15:45 1: PERL WARNING: Bareword found where operator expected at ./FHEM/99_perfmon.pm line 4, near ""stylesheet" type"
2016.09.11 15:15:45 3: stacktrace:
2016.09.11 15:15:45 3:     main::__ANON__                      called by ./FHEM/99_perfmon.pm (4)
2016.09.11 15:15:45 3:     (eval)                              called by fhem.pl (2258)
2016.09.11 15:15:45 3:     (eval)                              called by fhem.pl (2257)
2016.09.11 15:15:45 3:     main::CommandReload                 called by fhem.pl (2438)
2016.09.11 15:15:45 3:     main::GlobalAttr                    called by fhem.pl (3213)
2016.09.11 15:15:45 3:     main::CallFn                        called by fhem.pl (2573)
2016.09.11 15:15:45 3:     main::CommandAttr                   called by fhem.pl (1082)
2016.09.11 15:15:45 3:     main::AnalyzeCommand                called by fhem.pl (952)
2016.09.11 15:15:45 3:     main::AnalyzeCommandChain           called by fhem.pl (1215)
2016.09.11 15:15:45 3:     main::CommandInclude                called by fhem.pl (516)
2016.09.11 15:15:45 1: PERL WARNING: (Missing operator before type?)
2016.09.11 15:15:45 3: stacktrace:
2016.09.11 15:15:45 3:     main::__ANON__                      called by ./FHEM/99_perfmon.pm (4)
2016.09.11 15:15:45 3:     (eval)                              called by fhem.pl (2258)
2016.09.11 15:15:45 3:     (eval)                              called by fhem.pl (2257)
2016.09.11 15:15:45 3:     main::CommandReload                 called by fhem.pl (2438)
2016.09.11 15:15:45 3:     main::GlobalAttr                    called by fhem.pl (3213)
2016.09.11 15:15:45 3:     main::CallFn                        called by fhem.pl (2573)
2016.09.11 15:15:45 3:     main::CommandAttr                   called by fhem.pl (1082)
2016.09.11 15:15:45 3:     main::AnalyzeCommand                called by fhem.pl (952)
2016.09.11 15:15:45 3:     main::AnalyzeCommandChain           called by fhem.pl (1215)
2016.09.11 15:15:45 3:     main::CommandInclude                called by fhem.pl (516)
2016.09.11 15:15:45 1: PERL WARNING: Bareword found where operator expected at ./FHEM/99_perfmon.pm line 4, near ""text/css" href"
2016.09.11 15:15:45 3: stacktrace:
2016.09.11 15:15:45 3:     main::__ANON__                      called by ./FHEM/99_perfmon.pm (4)
2016.09.11 15:15:45 3:     (eval)                              called by fhem.pl (2258)
2016.09.11 15:15:45 3:     (eval)                              called by fhem.pl (2257)
2016.09.11 15:15:45 3:     main::CommandReload                 called by fhem.pl (2438)
2016.09.11 15:15:45 3:     main::GlobalAttr                    called by fhem.pl (3213)
2016.09.11 15:15:45 3:     main::CallFn                        called by fhem.pl (2573)
2016.09.11 15:15:45 3:     main::CommandAttr                   called by fhem.pl (1082)
2016.09.11 15:15:45 3:     main::AnalyzeCommand                called by fhem.pl (952)
2016.09.11 15:15:45 3:     main::AnalyzeCommandChain           called by fhem.pl (1215)
2016.09.11 15:15:45 3:     main::CommandInclude                called by fhem.pl (516)
2016.09.11 15:15:45 1: PERL WARNING: (Missing operator before href?)
2016.09.11 15:15:45 3: stacktrace:
2016.09.11 15:15:45 3:     main::__ANON__                      called by ./FHEM/99_perfmon.pm (4)
2016.09.11 15:15:45 3:     (eval)                              called by fhem.pl (2258)
2016.09.11 15:15:45 3:     (eval)                              called by fhem.pl (2257)
2016.09.11 15:15:45 3:     main::CommandReload                 called by fhem.pl (2438)
2016.09.11 15:15:45 3:     main::GlobalAttr                    called by fhem.pl (3213)
2016.09.11 15:15:45 3:     main::CallFn                        called by fhem.pl (2573)
2016.09.11 15:15:45 3:     main::CommandAttr                   called by fhem.pl (1082)
2016.09.11 15:15:45 3:     main::AnalyzeCommand                called by fhem.pl (952)
2016.09.11 15:15:45 3:     main::AnalyzeCommandChain           called by fhem.pl (1215)
2016.09.11 15:15:45 3:     main::CommandInclude                called by fhem.pl (516)
2016.09.11 15:15:45 1: reload: Error:Modul 99_perfmon deactivated:
Unterminated <> operator at ./FHEM/99_perfmon.pm line 9, <$fh> line 10.

2016.09.11 15:15:46 3: Connecting to database SQLite:dbname=/opt/fhem/fhem.db with user
2016.09.11 15:15:46 3: telnetPort: port 7072 opened
2016.09.11 15:15:46 3: WEB: port 8082 opened
2016.09.11 15:15:46 3: WEB_Local: port 8084 opened
2016.09.11 15:15:46 2: eventTypes: loaded 2653 events from ./log/eventTypes.txt
2016.09.11 15:15:46 3: Opening nanoCUL device /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A98ZJ51H-if00-port0
2016.09.11 15:15:46 3: Setting nanoCUL serial parameters to 38400,8,N,1
2016.09.11 15:15:50 3: nanoCUL: Possible commands: BCFiAZEkGMKUYRTVWXefltx
2016.09.11 15:15:50 3: nanoCUL device opened
2016.09.11 15:15:51 3: Opening fbaha device fritz.box:2002
2016.09.11 15:15:51 1: FBAHA fbaha registered with handle: 00000029
2016.09.11 15:15:51 3: fbaha device opened
2016.09.11 15:15:51 3: VCONTROL: Define open DATEI 'V200WO1B.cfg'
2016.09.11 15:15:51 3: VCONTROL: open DATEI 'V200WO1B.cfg'
2016.09.11 15:15:51 3: VCONTROL: DATEI 'V200WO1B.cfg' refreshed
2016.09.11 15:15:51 3: VCONTROL opening VCONTROL device /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_0001-if00-port0
2016.09.11 15:15:51 3: VCONTROL opened VCONTROL device /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_0001-if00-port0
2016.09.11 15:15:51 3: VCONTROL: Initialization
2016.09.11 15:15:52 3: Opening HausstromZaehler device /dev/ttyAMA0
2016.09.11 15:15:52 3: Setting HausstromZaehler serial parameters to 9600,8,N,1
2016.09.11 15:15:52 3: HausstromZaehler device opened
2016.09.11 15:15:52 3: TABLETUI: new ext defined infix:ftui/: dir:./www/tablet:
2016.09.11 15:15:52 3: Registering HTTPSRV TABLETUI for URL /ftui   and assigned link ftui/ ...
2016.09.11 15:15:52 1: PERL WARNING: keys on reference is experimental at ./FHEM/98_THINKINGCLEANER.pm line 433, <$fh> line 984.
2016.09.11 15:15:52 3: stacktrace:
2016.09.11 15:15:52 3:     main::__ANON__                      called by ./FHEM/98_THINKINGCLEANER.pm (433)
2016.09.11 15:15:52 3:     (eval)                              called by fhem.pl (2258)
2016.09.11 15:15:52 3:     (eval)                              called by fhem.pl (2257)
2016.09.11 15:15:52 3:     main::CommandReload                 called by fhem.pl (1698)
2016.09.11 15:15:52 3:     main::LoadModule                    called by fhem.pl (1760)
2016.09.11 15:15:52 3:     main::CommandDefine                 called by fhem.pl (1082)
2016.09.11 15:15:52 3:     main::AnalyzeCommand                called by fhem.pl (952)
2016.09.11 15:15:52 3:     main::AnalyzeCommandChain           called by fhem.pl (1215)
2016.09.11 15:15:52 3:     main::CommandInclude                called by fhem.pl (516)
2016.09.11 15:15:52 1: PERL WARNING: keys on reference is experimental at ./FHEM/98_THINKINGCLEANER.pm line 436, <$fh> line 984.
2016.09.11 15:15:52 3: stacktrace:
2016.09.11 15:15:52 3:     main::__ANON__                      called by ./FHEM/98_THINKINGCLEANER.pm (436)
2016.09.11 15:15:52 3:     (eval)                              called by fhem.pl (2258)
2016.09.11 15:15:52 3:     (eval)                              called by fhem.pl (2257)
2016.09.11 15:15:52 3:     main::CommandReload                 called by fhem.pl (1698)
2016.09.11 15:15:52 3:     main::LoadModule                    called by fhem.pl (1760)
2016.09.11 15:15:52 3:     main::CommandDefine                 called by fhem.pl (1082)
2016.09.11 15:15:52 3:     main::AnalyzeCommand                called by fhem.pl (952)
2016.09.11 15:15:52 3:     main::AnalyzeCommandChain           called by fhem.pl (1215)
2016.09.11 15:15:52 3:     main::CommandInclude                called by fhem.pl (516)
2016.09.11 15:15:52 1: Registering THINKINGCLEANER WebHook myRoomba
2016.09.11 15:15:52 3: myRoomba: Defined with URL http://192.168.178.48 and interval 60
2016.09.11 15:15:52 3: define LEDLeiste: can't reach (IO::Socket::INET: Bad hostname 'WifiLightLED2')
2016.09.11 15:15:52 3: SISPM using "/usr/bin/sispmctl" as parameter to open(); trying ...
2016.09.11 15:15:52 3: SISPM_GetCurrentConfig: Using "/usr/bin/sispmctl" as parameter to open(); trying ...
2016.09.11 15:15:52 3: SISPM_GetCurrentConfig: Found SISPM device number 0 (sispmctl v3)
2016.09.11 15:15:52 3: SISPM_GetCurrentConfig: SISPM device number 0 is USB device 026 (sispmctl v3)
2016.09.11 15:15:52 3: SISPM_GetCurrentConfig: Device number 0 has serial 01:00:48:94:a7 (sispmctl v3)
2016.09.11 15:15:52 3: SISPM_GetCurrentConfig: Initial read done
2016.09.11 15:15:52 3: SISPM GetCurrentConfing done
2016.09.11 15:15:52 3: SISPM setting callback timer
2016.09.11 15:15:52 3: SISPM initialized
2016.09.11 15:15:53 1: Including ./log/fhem.save
2016.09.11 15:15:53 3: WARNING: unsupported character in reading Zählerstand-Bezug-Total (not A-Za-z/\d_\.-), notify the SMLUSB module maintainer.
2016.09.11 15:15:53 3: WARNING: unsupported character in reading Zählerstand-Lieferung-Total (not A-Za-z/\d_\.-), notify the SMLUSB module maintainer.
2016.09.11 15:15:53 3: WARNING: unsupported character in reading Zählerstand-Tarif-1-Bezug (not A-Za-z/\d_\.-), notify the SMLUSB module maintainer.
2016.09.11 15:15:53 3: WARNING: unsupported character in reading Zählerstand-Tarif-1-Lieferung (not A-Za-z/\d_\.-), notify the SMLUSB module maintainer.
2016.09.11 15:15:53 3: WARNING: unsupported character in reading Zählerstand-Tarif-2-Bezug (not A-Za-z/\d_\.-), notify the SMLUSB module maintainer.
2016.09.11 15:15:53 3: WARNING: unsupported character in reading Zählerstand-Tarif-2-Lieferung (not A-Za-z/\d_\.-), notify the SMLUSB module maintainer.
2016.09.11 15:15:53 3: WARNING: unsupported character in reading Einschaltungen_Primärquelle (not A-Za-z/\d_\.-), notify the VCONTROL module maintainer.
2016.09.11 15:15:53 3: WARNING: unsupported character in reading Einschaltungen_Sekundärquelle (not A-Za-z/\d_\.-), notify the VCONTROL module maintainer.
Bad arg length for Socket::pack_sockaddr_in, length is 0, should be 4 at /usr/lib/arm-linux-gnueabihf/perl5/5.20/Socket.pm line 833.

[betateilchen]

Da sind ja ein ganzer Haufen Fehler mit genauso vielen unterschiedlichen Ursachen

• 99_perfmon.pm kann nicht geladen werden
• 98_THINKINGCLEANER.pm benutzt exprimentelle Funktionen
• SMLUSB erzeugt reading mit nicht zulässigen Zeichen (vermutlich die Umlaute)
• Socket.pm versucht, ein Socket zu einer Adresse aufzubauen, die gar nicht vorhanden (weil nicht angegeben) ist

Du solltest Stück für Stück versuchen, die betroffenen Dinge zu klären, indem Du die betroffenen Module deaktivierst und nach und nach wieder so einbaust, dass keine Fehlermeldungen mehr auftreten.

An einen Fehler in der HttpUtils.pm glaube ich in diesem Fall übrigens nicht wirklich.

[Nemo0815]

OMG

Ich habe den Fehler gefunden, Schuld war das WifiLight.pm Modul!

Die LED Leiste im Schlafzimmer war im Urlaub ausgeschaltet und damit nicht erreichbar. Scheinbar blockiert WifiLight das komplette System wenn ein Gerät nicht  gefunden wird beim start von FHEM! (daher auch die Fehlermeldung im Log,
2016.09.11 16:19:07 3: define LEDLeiste: can't reach (IO::Socket::INET: Bad hostname 'WifiLightLED2')

[herrmannj]

Mach mal einen Post dazu im wifilight threat.  Hab das schon mal gehört könnte aber nicht nachstellen. 

Vg
Joerg

[Skram]

Moin zusammen,

ich rolle das Thema mal wieder auf, da es bei mir seit ca. 30.03.2017 wieder relevant ist: FHEM startet nicht.
Ich habe meine lokale "perl/5.20/Socket.pm" mit einem "eval" gepatched, damit ich den Fehler überhaupt lokalisieren kann.

Code Auswählen Erweitern


2017.04.30 21:19:22 0: Featurelevel: 5.8
2017.04.30 21:19:22 0: Server started with 280 defined entities (fhem.pl:14097/2017-04-24 perl:5.020002 os:linux user:root pid:25041)
2017.04.30 21:19:22 1: PERL WARNING: LOKALER EVAL-PATCH! at /usr/lib/x86_64-linux-gnu/perl/5.20/Socket.pm line 157.
2017.04.30 21:19:22 1: stacktrace:
2017.04.30 21:19:22 1:     main::__ANON__                      called by /usr/lib/x86_64-linux-gnu/perl/5.20/Socket.pm (157)
2017.04.30 21:19:22 1:     (eval)                              called by /usr/lib/x86_64-linux-gnu/perl/5.20/Socket.pm (156)
2017.04.30 21:19:22 1:     Socket::sockaddr_in                 called by FHEM/HttpUtils.pm (268)
2017.04.30 21:19:22 1:     main::__ANON__                      called by FHEM/HttpUtils.pm (197)
2017.04.30 21:19:22 1:     main::__ANON__                      called by fhem.pl (682)


Mit meinem behelfsmäßigen Abfangen des Fehlers startet FHEM zwar, viele Module funktionieren aber nicht, so z.B. das o.a. WifiLight, aber auch PUSHOVER, WITHINGS oder FB_CALLMONITOR.

Habt ihr Ideen, wie ich den Fehler weiter eingrenzen kann?

[rudolfkoenig]

2017.04.30 21:19:22 1:     main::__ANON__                      called by /usr/lib/x86_64-linux-gnu/perl/5.20/Socket.pm (157)

Bei mir startet ein ActivePerl 5.20 ohne Probleme, natuerlich mit HttpUtils. Nennenswerter Code ist erst ab Zeile 700 zu sehen, da vorher Doku ist. Die Zeile 157 (wie die Fehlermeldung das suggeriert), ist Doku.

Hast du "attr global dnsServer" gesetzt? Kannst du bitte

Log 1, "SI:".unpack("H*", $iaddr);

vor dem sockaddr_in Aufruf in HttpUtils.pm (Zeile 268) einfuegen, dann "attr global verbose 5" setzen, und das Problem provozieren?

[Skram]

Gesetzt ist

Code Auswählen Erweitern

attr global dnsServer 192.168.0.1

Eine der vielen Logausgaben sieht nun so aus:

Code Auswählen Erweitern


2017.05.02 20:27:33 4: HttpUtils url=http://192.168.0.1:1012/
2017.05.02 20:27:33 1: SI:c0a80001
2017.05.02 20:27:33 1: PERL WARNING: LOKALER EVAL-PATCH! at /usr/lib/x86_64-linux-gnu/perl/5.20/Socket.pm line 157.
2017.05.02 20:27:33 1: stacktrace:
2017.05.02 20:27:33 1:     main::__ANON__                      called by /usr/lib/x86_64-linux-gnu/perl/5.20/Socket.pm (157)
2017.05.02 20:27:33 1:     (eval)                              called by /usr/lib/x86_64-linux-gnu/perl/5.20/Socket.pm (156)
2017.05.02 20:27:33 1:     Socket::sockaddr_in                 called by FHEM/HttpUtils.pm (269)
2017.05.02 20:27:33 1:     main::__ANON__                      called by FHEM/HttpUtils.pm (153)
2017.05.02 20:27:33 1:     main::HttpUtils_gethostbyname       called by FHEM/HttpUtils.pm (306)
2017.05.02 20:27:33 1:     main::HttpUtils_Connect             called by FHEM/DevIo.pm (352)
2017.05.02 20:27:33 1:     main::DevIo_OpenDev                 called by ./FHEM/72_FB_CALLMONITOR.pm (491)
2017.05.02 20:27:33 1:     main::FB_CALLMONITOR_Ready          called by fhem.pl (3396)
2017.05.02 20:27:33 1:     main::CallFn                        called by fhem.pl (744)
2017.05.02 20:27:33 4: FB_CALLMONITOR (FB_Monitor) - unable to connect to Fritz!Box: connect to http://192.168.0.1:1012: Das Argument ist ungültig



Mein "Socket.pm" hat aber definitiv aktiven Code in Zeile 157:

Code Auswählen Erweitern


root@fhem:/opt/fhem# head -n 160 /usr/lib/x86_64-linux-gnu/perl/5.20/Socket.pm | tail -n 10
    } elsif (wantarray) {
        croak "usage:   (port,iaddr) = sockaddr_in(sin_sv)" unless @_ == 1;
        unpack_sockaddr_in(@_);
    } else {
        croak "usage:   sin_sv = sockaddr_in(port,iaddr))" unless @_ == 2;
        eval {
           warn "LOKALER EVAL-PATCH!";
            pack_sockaddr_in(@_);
        } ; warn $@ if $@;
    }



Ratlos....

[rudolfkoenig]

Und ich verwirrt: dein "LOKALER EVAL-PATCH" zeigt nur, dass pack_sockaddr_in aufgerufen wird, und bedeutet noch lange kein Problem. Die nach SI: gezeigte Adresse schaut fuer mich auch richtig aus.

Uebrigens die erwaehnte Codestelle ist bei mir um Zeile 820, d.h. deine Version von Socket.pm hat keine Doku am Anfang, evtl. kann man perl auch ohne Doku konfigurieren, damit es etwas kleiner und schneller ist.

[Skram]

Du hast natürlich recht! Das zweite "warn" kam nicht zum Tragen, da es (jetzt) keinen Fehler gab.
Augenscheinlich tritt das Problem nur sporadisch auf, denn vor ein paar Tagen war das Patchen meiner "Socket.pm" die einzige Möglichkeit, FHEM überhaupt zum Starten zu bewegen.
Ich beobachte weiter und danke Dir soweit!

[Skram]

Ist bei mir auch WIFILIGHT. Wenn der DNS die IP nicht auflösen kann, kommt es zu diesem schrägen Verhalten. 
Sobald ich in der /etc/hosts irgendeine IP-Adresse für das WIFILIGHT Gerät hinterlege, startet FHEM wenigstens wieder.

[rudolfkoenig]

Ist bei mir auch WIFILIGHT.

Wifilight verwendet (soweit ich es sehe) weder HttpUtils noch DevIo, damit bin ich raus. Da dieses Problem auch nicht zu Betreff: passt, sollte man einen neuen Beitrag im passenden Forumsbereich (Beleuchtung) oeffnen.

[herrmannj]

ich werde das asap fixen.

[mifh]

Hallo,

ich bin eben über das selbe Problem gelaufen und bei mir war es auch WifiLight.
Kann es sein, das der Bug noch offen ist?
Kann ich zur Vorbeugung etwas anderes machen, als die Geräte aus FHEM rauszuwerfen?
Ist schon ganz schön störend, wenn einem die ganze FHEM Instanz um die Ohren fliegt, weil ein Gerät offline ist. 
Gruß
Michael