FHEM startet nicht mit aktueller Blocking.pm

[djatebbi]

Hallo zusammen,
seit dem Update von der Blocking.pm am 05.10.2017 bleibt mein FHEM beim Starten hängen bzw. friert ein.
Nur mit dem deaktivieren der Fritzbox, Presence und WOL Module läuft mein FHEM wieder,
bzw. wenn ich die Blocking.pm Version vom 24.09.2017 oder 02.10.2017 (mit den Bekannten Fehlermeldungen) nehme.
Dies scheint bei mir alle Module zu betreffen, die offiziell das Blocking Call verwendet.
Das FHEM und alle anderen Module sind bei mir auf aktuellen Stand.

Mit dem Fritzbox Modul bleibt es hier stehen:

Code Auswählen Erweitern


2017.11.07 12:32:04 4: BlockingCall (FRITZBOX_API_Check_Run): created child (-3044), uses telnetForBlockingFn_1510054324 to connect back
2017.11.07 12:32:04 4: FRITZBOX 1750E: Readout_Start.673 Fork process FRITZBOX_API_Check_Run

Mit dem Presence Modul bleibt es hier stehen:

Code Auswählen Erweitern


2017.11.07 12:28:16 5: PRESENCE (NB_Garage_presence) - stopping timer
2017.11.07 12:28:16 5: PRESENCE (NB_Garage_presence) - starting blocking call for mode lan-ping

Und mit dem WOL Modul ist hier Schluss:

Code Auswählen Erweitern


2017.11.07 12:56:31 4: [NB_Garage] result executing ping:
Ping wird ausgefhrt fr 192.168.100.54 mit 32 Bytes Daten:
Zeitberschreitung der Anforderung.
Zeitberschreitung der Anforderung.
Zeitberschreitung der Anforderung.
Zeitberschreitung der Anforderung.
Ping-Statistik fr 192.168.100.54:
    Pakete: Gesendet = 4, Empfangen = 0, Verloren = 4
    (100% Verlust),
2017.11.07 12:56:31 5: Cmd: >{BlockingStart('1')}<


Da ich mit meinem Latein am Ende bin, bitte ich um Hilfe.
Gruß

[rudolfkoenig]

Du hast eine "Kleinigkeit" vergessen zu erwaehnen: Dein FHEM laeuft unter Windows. Dieses Problem betrifft nur Windows, wenn mehr als ein BlockingCall ausstehend ist, und jeweils AbortFn verwendet wird.

Ich habe jetzt 'ne weile rumexperimentiert, und ich meine es gefixt zu haben (update ab morgen oder ab sofort per SVN). Verstehe aber nicht, wieso das frueher harmlose "wait" (was notfalls -1 zuruecklieferte) jetzt ploetzlich FHEM blockiert. { wait } in der FHEM-Konsole liefert weiterhin -1 zurueck, und verklemmt nicht. Gibt es hier Windows-Experten, die mir das erklaeren koennen?

[CoolTux]

Jetzt erzähl mir bitte Mal einer wie man an den gegeben Informationen sehen kann das das Teil auf Windows läuft. Ich erkenne da gar nichts. Rudi bitte sei so nett und Gib mir eine Brille 

[rudolfkoenig]

created child (-3044),

-> Negative pids gibts nur unter Windows.

[CoolTux]

Vielen Dank Rudi.

[djatebbi]

Sorry, ja läuft auf Windows 10 Pro 1703 mit ActivePerl 5.24.2.2403.

[CoolTux]

Sorry, ja läuft auf Windows 10 Pro 1703 mit ActivePerl 5.24.2.2403.

Bitte sei so nett und schreibe das in Deine Signatur. Windows ist hier eine Ausnahme. 

[djatebbi]

Habe ich gerade gemacht, Bild müsste dies jetzt auch entsprechen, ich bin gerne extravagant  .

Ich habe jetzt die neue Blocking.pm bei mir eingespielt, leider immer noch das selbe Problem, und es hängt auch an der selben Stelle.
Hier nochmal die letzten Zeilen aus meiner frischen Log-Datei.

Code Auswählen Erweitern


2017.11.09 06:19:04 4: HttpUtils url=http://192.168.100.1/webservices/homeautoswitch.lua?sid=6d22bc47c3296047&switchcmd=getdevicelistinfos
2017.11.09 06:19:04 5: IP: 192.168.100.1 -> 192.168.100.1
2017.11.09 06:19:04 1: Perfmon: possible freeze starting at 06:18:57, delay is 7.659
2017.11.09 06:19:04 5: Loading ./FHEM/98_telnet.pm
2017.11.09 06:19:04 3: telnetForBlockingFn_1510204744: port 54776 opened
2017.11.09 06:19:04 5: Starting notify loop for global, 1 event(s), first is DEFINED telnetForBlockingFn_1510204744
2017.11.09 06:19:04 5: createNotifyHash
2017.11.09 06:19:04 5: End notify loop for global
2017.11.09 06:19:04 4: BlockingCall (FRITZBOX_API_Check_Run): created child (-5512), uses telnetForBlockingFn_1510204744 to connect back
2017.11.09 06:19:04 4: FRITZBOX 1750E: Readout_Start.673 Fork process FRITZBOX_API_Check_Run


[CoolTux]

Ich muss da nach fragen. Wie hast Du sie eingespielt??

[djatebbi]

Ich habe mir die Datei

Code Auswählen Erweitern

# $Id: Blocking.pm 15409 2017-11-08 14:51:20Z rudolfkoenig $
von SVN Seite geladen, FHEM ausgeschaltet, Datei ausgetauscht und wieder gestartet.

[CoolTux]

Ok, dann solltest du zu mindest die richtige Datei haben.

[rudolfkoenig]

Kannst du bitte die hier angehaengte Version probieren?

[djatebbi]

Also FHEM startet damit schon mal, aber folgende Meldungen tauchen jetzt bei verbose 3 auf.
95% davon hatte ich vorher nicht.

Code Auswählen Erweitern


2017.11.09 10:29:19 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 134.
2017.11.09 10:29:19 1: *** wait for -6284 /
2017.11.09 10:29:31 1: *** wait done
2017.11.09 10:29:31 1: FRITZBOX 1750E: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:29:31 1: *** wait for -8584 /
2017.11.09 10:29:43 1: *** wait done
2017.11.09 10:29:43 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:29:43 3: Opening MAX device 192.168.100.40:62910
2017.11.09 10:29:43 3: MAX device opened
2017.11.09 10:29:44 1: *** wait for -7748 /
2017.11.09 10:29:55 1: *** wait done
2017.11.09 10:29:55 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:29:55 1: Perfmon: possible freeze starting at 10:29:20, delay is 35.64
2017.11.09 10:29:55 1: *** wait for -1220 /
2017.11.09 10:29:57 1: *** wait done
2017.11.09 10:29:57 2: PRESENCE (NB_Garage_presence) - device could not be checked (retrying in 10 seconds): Process died prematurely
2017.11.09 10:29:57 1: *** wait for -5692 /
2017.11.09 10:30:02 1: *** wait done
2017.11.09 10:30:02 3: BlockingCall for NB_Garage was aborted
2017.11.09 10:30:02 1: *** wait for -5800 /
2017.11.09 10:30:13 1: *** wait done
2017.11.09 10:30:13 1: FRITZBOX 1750E: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:30:14 2: HMCCU: Create child process with timeouts 0.01 and 0.25
2017.11.09 10:30:14 0: HMCCU: Child process for server CB2001 started with PID -7460
2017.11.09 10:30:14 0: CCURPC: CB2001 Creating file queue ./tmp/ccuqueue_2001_1
2017.11.09 10:30:14 0: RPC server(s) starting
2017.11.09 10:30:14 1: *** wait for -5056 /
2017.11.09 10:30:14 0: CCURPC: Initializing RPC server CB2001
2017.11.09 10:30:14 0: CCURPC: Callback server created listening on port 7411
2017.11.09 10:30:14 1: CCURPC: CB2001 Adding callback for events
2017.11.09 10:30:14 1: CCURPC: CB2001 Adding callback for new devices
2017.11.09 10:30:14 1: CCURPC: CB2001 Adding callback for deleted devices
2017.11.09 10:30:14 1: CCURPC: CB2001 Adding callback for modified devices
2017.11.09 10:30:14 1: CCURPC: CB2001 Adding callback for replaced devices
2017.11.09 10:30:14 1: CCURPC: CB2001 Adding callback for readded devices
2017.11.09 10:30:14 1: CCURPC: CB2001 Adding callback for list devices
2017.11.09 10:30:14 0: CCURPC: CB2001 Entering server loop
2017.11.09 10:30:25 1: *** wait done
2017.11.09 10:30:25 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:30:26 1: *** wait for -4688 /
2017.11.09 10:30:37 1: *** wait done
2017.11.09 10:30:37 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:30:38 1: Calendar Kalenderwoche: retrieval failed with error message <hidden>: Can't connect(2) to https://calendar.google.com:443:  SSL connect attempt failed
2017.11.09 10:30:38 1: Calendar Kalenderwoche: retrieved no or empty data
2017.11.09 10:30:38 1: PERL WARNING: Use of uninitialized value $t in numeric lt (<) at ./FHEM/57_Calendar.pm line 1924.
2017.11.09 10:30:38 1: Perfmon: possible freeze starting at 10:29:56, delay is 42.483
2017.11.09 10:30:38 1: *** wait for -8356 /
2017.11.09 10:30:42 1: *** wait done
2017.11.09 10:30:42 2: PRESENCE (NB_Garage_presence) - device could not be checked after 1 retry (retrying in 10 seconds): Process died prematurely
2017.11.09 10:30:42 1: *** wait for -3032 /
2017.11.09 10:30:54 1: *** wait done
2017.11.09 10:30:54 1: FRITZBOX 1750E: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:30:54 0: HMCCU: Received SL event. RPC server CB2001 enters server loop
2017.11.09 10:30:54 1: *** wait for -8340 /
2017.11.09 10:31:06 1: *** wait done
2017.11.09 10:31:06 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:31:06 1: *** wait for -3828 /
2017.11.09 10:31:17 1: *** wait done
2017.11.09 10:31:17 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:31:17 1: Perfmon: possible freeze starting at 10:30:39, delay is 38.934
2017.11.09 10:31:18 1: *** wait for -9812 /
2017.11.09 10:31:19 1: *** wait done
2017.11.09 10:31:19 1: FRITZBOX 1750E: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:31:19 1: *** wait for -2952 /
2017.11.09 10:31:23 1: BlockingInformParent (BlockingStart): Can't connect to localhost:52246: IO::Socket::INET: connect: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2017.11.09 10:31:24 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:52246: IO::Socket::INET: connect: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2017.11.09 10:31:24 1: *** wait done
2017.11.09 10:31:24 2: PRESENCE (NB_Garage_presence) - device could not be checked after 2 retries (retrying in 10 seconds): Process died prematurely
2017.11.09 10:31:24 1: HMCCU: Registering callback http://192.168.100.5:7411/fh2001 with ID CB2001 at http://192.168.100.15:2001/
2017.11.09 10:31:24 1: CCURPC: CB2001 ListDevices. Sending init to HMCCU
2017.11.09 10:31:24 1: HMCCU: RPC callback with URL http://192.168.100.5:7411/fh2001 initialized
2017.11.09 10:31:24 1: *** wait for -4896 /
2017.11.09 10:31:25 2: CCURPC: CB2001 NewDevice received 55 device specifications
2017.11.09 10:31:28 1: BlockingInformParent (BlockingStart): Can't connect to localhost:52246: IO::Socket::INET: connect: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2017.11.09 10:31:29 1: BlockingInformParent (FRITZBOX_Readout_Done): Can't connect to localhost:52246: IO::Socket::INET: connect: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2017.11.09 10:31:29 1: *** wait done
2017.11.09 10:31:29 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:31:29 1: *** wait for -6228 /
2017.11.09 10:31:33 1: BlockingInformParent (BlockingStart): Can't connect to localhost:52246: IO::Socket::INET: connect: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2017.11.09 10:31:34 1: BlockingInformParent (FRITZBOX_Readout_Done): Can't connect to localhost:52246: IO::Socket::INET: connect: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2017.11.09 10:31:34 1: *** wait done
2017.11.09 10:31:34 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:31:34 1: Perfmon: possible freeze starting at 10:31:18, delay is 16.226
2017.11.09 10:31:34 0: HMCCU: Received IN event. RPC server CB2001 initialized.
2017.11.09 10:31:34 2: HMCCU: Updated devices. Success=1 Failed=0
2017.11.09 10:31:34 1: HMCCU: All RPC servers running
2017.11.09 10:31:34 1: *** wait for -3284 /
2017.11.09 10:31:37 1: BlockingInformParent (BlockingStart): Can't connect to localhost:52246: IO::Socket::INET: connect: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2017.11.09 10:31:38 1: BlockingInformParent (FRITZBOX_Readout_Done): Can't connect to localhost:52246: IO::Socket::INET: connect: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte.
2017.11.09 10:31:38 1: *** wait done
2017.11.09 10:31:38 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:31:38 2: PRESENCE (NB_Garage_presence) - check returned a valid result after 3 unsuccesful retries
2017.11.09 10:31:38 1: Perfmon: possible freeze starting at 10:31:35, delay is 3.814
2017.11.09 10:31:38 1: *** wait for -9688 /
2017.11.09 10:31:40 1: *** wait done
2017.11.09 10:31:40 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.09 10:31:40 1: Perfmon: possible freeze starting at 10:31:39, delay is 1.74


[rudolfkoenig]

Die Zeilen mit *** und WARNING sind Debug-Ausgaben der angehaengten Version
Die Ursache der Timout Meldungen sollte man  in den entsprechenden Modulen suchen.

Ich habe die obige Version (aber ohne Debug) eingecheckt.
Weiterhin wird jetzt beim spezifizierten Timeout das Thread auch unter Windows beendet, bisher was das Unix/OSX vorbehalten. Da ich die perl fork Emulation unter Windows nicht in Detail kenne, werden evtl. dadurch irgendwelche Ressourcen nicht mehr freigegeben, aber die Timeout-Funktion nicht aufzurufen ist keine Loesung.

[herrmannj]

Code Auswählen Erweitern

Perfmon: possible freeze starting at 10:29:56, delay is 42.483
Kommen die aus dem main oder fork ?

Wenn 'main' müsstest Du deutliche "Hänger" wahrnehmen. Sprich: fhem würde zwischendurch Sekundenlang mal auf nichts reagieren.

Aus dem fork dürften die aber eigentlich auch nicht kommen (wobei ich mir da nicht komplett sicher bin..)