Seite drucken - FHEM startet nicht mit aktueller Blocking.pm

Titel: FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: djatebbi am 08 November 2017, 09:51:09

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


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


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


2017.11.07 12:56:31 4: [NB_Garage] result executing ping: 
Ping wird ausgefhrt fr 192.168.100.54 mit 32 Bytes Daten:
Zeitberschreitung der Anforderung.
Zeitberschreitung der Anforderung.
Zeitberschreitung der Anforderung.
Zeitberschreitung der Anforderung.
Ping-Statistik fr 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ß

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: rudolfkoenig am 08 November 2017, 15:58:00

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?

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: CoolTux am 08 November 2017, 17:46:46

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 :)

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: rudolfkoenig am 08 November 2017, 18:28:34

Zitatcreated child (-3044),

-> Negative pids gibts nur unter Windows.

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: CoolTux am 08 November 2017, 18:29:55

Vielen Dank Rudi.

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: djatebbi am 09 November 2017, 06:03:25

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

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: CoolTux am 09 November 2017, 06:10:13

Zitat von: djatebbi am 09 November 2017, 06:03:25
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. :)

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: djatebbi am 09 November 2017, 06:31:25

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

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


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

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: CoolTux am 09 November 2017, 06:33:12

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

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: djatebbi am 09 November 2017, 06:42:17

Ich habe mir die Datei

Code Auswählen

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

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: CoolTux am 09 November 2017, 06:52:15

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

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: rudolfkoenig am 09 November 2017, 10:06:32

Kannst du bitte die hier angehaengte Version probieren?

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: djatebbi am 09 November 2017, 10:35:35

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

Code Auswählen


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

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: rudolfkoenig am 09 November 2017, 15:41:23

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.

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: herrmannj am 09 November 2017, 15:49:58

Code Auswählen

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..)

Titel: Antw:FHEM startet nicht mit aktueller Blocking.pm
Beitrag von: djatebbi am 10 November 2017, 09:49:51

Zitat
Code Auswählen Erweitern
Perfmon: possible freeze starting at 10:29:56, delay is 42.483
Kommen die aus dem main oder fork ?

Wie kann ich dies herausfinden?

Ich habe heute das update vom neuen Modul eingespielt und ausgiebig getestet.
Leider habe ich noch immer folgende zusätzliche Einträge in dem Log:

Code Auswählen


Start FHEM
2017.11.10 09:29:04 2: Perfmon: ready to watch out for delays greater than one second
...
(2017.11.10 09:29:10 3: telnetForBlockingFn_1510302550: port 56224 opened)
2017.11.10 09:29:21 1: FRITZBOX 1750E: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:29:33 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:29:45 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:29:45 1: Perfmon: possible freeze starting at 09:29:11, delay is 34.887
2017.11.10 09:29:47 2: PRESENCE (NB_Garage_presence) - device could not be checked (retrying in 10 seconds): Process died prematurely
2017.11.10 09:29:52 3: BlockingCall for NB_Garage was aborted
2017.11.10 09:29:54 1: FRITZBOX 1750E: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:29:57 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:30:00 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:30:00 1: Perfmon: possible freeze starting at 09:29:46, delay is 14.689
2017.11.10 09:30:03 2: PRESENCE (NB_Garage_presence) - device could not be checked after 1 retry (retrying in 10 seconds): Process died prematurely
2017.11.10 09:30:06 1: FRITZBOX 1750E: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:30:06 1: Perfmon: possible freeze starting at 09:30:01, delay is 5.439
2017.11.10 09:30:09 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:30:12 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:30:12 1: Perfmon: possible freeze starting at 09:30:07, delay is 5.131
2017.11.10 09:30:13 1: FRITZBOX 1750E: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:30:13 2: PRESENCE (NB_Garage_presence) - check returned a valid result after 2 unsuccesful retries
2017.11.10 09:30:18 1: FRITZBOX 7390: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:30:18 1: Perfmon: possible freeze starting at 09:30:17, delay is 1.849
2017.11.10 09:30:20 1: FRITZBOX 7490: Readout_Aborted.1865 Error: Timeout when reading Fritz!Box data.
2017.11.10 09:30:20 1: Perfmon: possible freeze starting at 09:30:19, delay is 1.717

Letzte Meldung nach 20 min.
2017.11.10 09:35:19 2: HMCCU: Received no events from CCU since 300 seconds

Diese Meldungen werden in diversen anderen Threads behandelt.
Überall scheint es auf das Blocking.pm Modul seit dem 02.10.2017 zurück zu führen.
Dies soll seit der Version vom 05.10. gefixt worden zu sein, aber bei mir tauchen diese Meldungen trotz dessen auf.
Gibt es hierzu noch eine Idee?

FHEM Forum

FHEM => Automatisierung => Thema gestartet von: djatebbi am 08 November 2017, 09:51:09