FHEM-Start-Loop nach Update von HttpUtils.pm

[Beko136]

Hallo FHEM-Community,

seit Anfang Februar plagt mich das Problem, dass FHEM nach einem UPDATE nicht mehr richtig startet, sondern zumindest gemäß FHEM-Log im Abstand von ca. 2 Minuten einen Neustart hinlegt - immer wieder, quasi endlos. Dazwischen war die Weboberfläche von FHEM nie aufrufbar und es half schließlich immer nur ein Rückstieg auf den Stand von vor dem Update.

Nach Stunden der Suche, der Problemeingrenzung, Log-Analyse mit höherem Verbose-Level usw. habe ich durch ein manuelles Installieren aller angebotenen Updates herausgefunden, dass nach UPD FHEM/HttpUtils.pm das geschildete Problem wieder auftritt. Ich habe also einen erneuen Rückstieg gemacht,

Code Auswählen Erweitern

attr global exclude_from_update FHEM/HttpUtils.pm in fhem.cfg eingetragen und ein erneutes UPDATE durchgeführt. Dieses ließ sich ohne Probleme durchführen und FHEM funktioniert auch noch nach einem Restart ordnungsgemäß.

Es liegt somit nahe, dass zumindest bei mir ein Problem mit diesem Modul zu bestehen scheint. Die einzige auffällige Meldung im FHEM-Log, welche nach einem Update von HttpUtils.pm aufscheint, ansonsten nicht - auch nicht nach dem Update mit Exclude, ist folgende:

Code Auswählen Erweitern

SSL_verify_mode must be a number and not a string at /usr/share/perl5/IO/Socket/SSL.pm line 2386.

Kennt jemand dieses Phänomen/Problem und weiß jemand Rat? Gerne liefere ich weitere Info, sofern diese benötigt werden, lasst es mich einfach wissen.

Danke und schöne Grüße

[rudolfkoenig]

gemäß FHEM-Log im Abstand von ca. 2 Minuten einen Neustart hinlegt

Gibt es eine Fehlemeldung im Log?
Wenn nicht, bitte FHEM in der Console mit "perl fhem.pl -d fhem.cfg" starten, und die letzen Zeilen aus dem Log hier zeigen.

nach UPD FHEM/HttpUtils.pm das geschildete Problem wieder auftritt. Ich habe also einen erneuen Rückstieg gemacht,

Welche Version hat die alte HttpUtils.pm?

SSL_verify_mode must be a number and not a string at /usr/share/perl5/IO/Socket/SSL.pm line 2386.

HttpUtils setzt SSL_verify_mode auf 0, oder uebernimmt den Wert vom Aufrufer.
Von den 18 Modulen, die SSL_verify_mode explizit setzen, erlauben nur Calendar und BOTVAC einen Wert ausser 0 zu setzen.

[Beko136]

Hallo,

nachfolgend habe ich die Meldungen von einer "SSL_verify_mode"-Meldung zur anderen aus dem Log herauskopiert, so wie es endlos dahingehen würde. Dieses stammt nicht von einem manuellen Start über Ihren bereitgestellten Command, sondern von einem regulären Start. Wenn hilfreich/nötig, kann ich das Log von einem manuellen Start auch nachliefern.

Code Auswählen Erweitern

2022.03.03 21:04:21.232 1: Including fhem.cfg
2022.03.03 21:04:21.594 2: eventTypes: loaded 1732 lines from ./log/eventTypes.txt
2022.03.03 21:04:21.615 1: Including ./FHEM/XXXXX_00_config.cfg
2022.03.03 21:04:21.618 1: Including ./FHEM/XXXXX_000_Floorplan_FP.cfg
2022.03.03 21:04:21.644 1: Including ./FHEM/XXXXX_000_Fhem_FH.cfg
2022.03.03 21:04:23.396 1: Including ./FHEM/XXXXX_000_Funktionen_FU.cfg
2022.03.03 21:04:23.734 1: Including ./FHEM/XXXXX_000_Haus_HA.cfg
2022.03.03 21:04:23.871 1: Including ./FHEM/XXXXX_000_Geraete_GE.cfg
2022.03.03 21:04:24.515 1: Including ./FHEM/XXXXX_000_Versorgung_VS.cfg
2022.03.03 21:04:24.532 0: HourCounter Gasverbrauch Define.228 parameters: Gasverbrauch HourCounter KNXGaszaehler:on KNXGaszaehler:off
2022.03.03 21:04:24.698 1: Including ./FHEM/XXXXX_000_Wetter.cfg
2022.03.03 21:04:24.891 1: Including ./FHEM/XXXXX_0OG_Keller_KE.cfg
2022.03.03 21:04:25.015 1: Including ./FHEM/XXXXX_0OG_Garage_GR.cfg
2022.03.03 21:04:25.072 1: Including ./FHEM/XXXXX_0OG_Garten_GT.cfg
2022.03.03 21:04:25.101 1: Including ./FHEM/XXXXX_2OG_Aussen_2A.cfg
2022.03.03 21:04:25.147 1: Including ./FHEM/XXXXX_2OG_Bad_BA.cfg
2022.03.03 21:04:25.188 1: Including ./FHEM/XXXXX_2OG_Gang_GA.cfg
2022.03.03 21:04:25.242 1: Including ./FHEM/XXXXX_2OG_Kinderzimmer_KI.cfg
2022.03.03 21:04:25.284 1: Including ./FHEM/XXXXX_2OG_Kueche_KU.cfg
2022.03.03 21:04:25.374 1: Including ./FHEM/XXXXX_2OG_Schlafzimmer_SZ.cfg
2022.03.03 21:04:25.475 1: Including ./FHEM/XXXXX_2OG_Steuerung.cfg
2022.03.03 21:04:25.626 1: Including ./FHEM/XXXXX_2OG_WC.cfg
2022.03.03 21:04:25.653 1: Including ./FHEM/XXXXX_2OG_Wohnzimmer_WO.cfg
2022.03.03 21:04:25.866 1: Including ./log/fhem.save
2022.03.03 21:04:27.426 2: NETATMO_Wetterstation_XXXXX: missing app refresh token!
2022.03.03 21:04:28.429 1: PERL WARNING: Subroutine SetExtensionsCancel redefined at ./FHEM/SetExtensions.pm line 14.
2022.03.03 21:04:28.430 1: PERL WARNING: Subroutine SE_DoSet redefined at ./FHEM/SetExtensions.pm line 36.
2022.03.03 21:04:28.430 1: PERL WARNING: Subroutine getCmd redefined at ./FHEM/SetExtensions.pm line 65.
2022.03.03 21:04:28.431 1: PERL WARNING: Subroutine getReplCmd redefined at ./FHEM/SetExtensions.pm line 75.
2022.03.03 21:04:28.433 1: PERL WARNING: Subroutine SetExtensions redefined at ./FHEM/SetExtensions.pm line 46.
2022.03.03 21:04:28.433 1: PERL WARNING: Subroutine SetExtensionsFn redefined at ./FHEM/SetExtensions.pm line 224.
2022.03.03 21:04:28.467 0: Featurelevel: 6.1
2022.03.03 21:04:28.468 0: Server started with 374 defined entities (fhem.pl:25715/2022-02-20 perl:5.032001 os:linux user:fhem pid:10760)
SSL_verify_mode must be a number and not a string at /usr/share/perl5/IO/Socket/SSL.pm line 2386.

Die jetzige (alte) HttpUtils.pm hat im Header folgende Zeile stehen:

Code Auswählen Erweitern

$Id: HttpUtils.pm 25487 2022-01-17 20:59:02Z rudolfkoenig $

Mir ist nicht wissentlich, dass ich die beiden Module Calendar oder BOTVAC verwende.

Schöne Grüße

[rudolfkoenig]

Wenn hilfreich/nötig, kann ich das Log von einem manuellen Start auch nachliefern.

BItte.

[Beko136]

Hallo,

ich habe nun, wie angefordert, den manuellen Start über xxx durchgeführt.

Code Auswählen Erweitern

2022.03.07 22:58:11.713 5: HttpUtils url=http://192.168.xxx.180/INCLUDE/api.cgi?jsonnode=2&jsonparam=I&_=1646690291.71323 NonBlocking via http
2022.03.07 22:58:11.713 4: IP: 192.168.xxx.180 -> 192.168.xxx.180
2022.03.07 22:58:11.718 5: Triggering n_FhemNeustart
2022.03.07 22:58:11.718 4: n_FhemNeustart exec {
#TelegramMsg('Neustart');;
SignalMsg('Neustart');;
}
2022.03.07 22:58:11.718 5: Cmd: >{
#TelegramMsg('Neustart');
SignalMsg('Neustart');
}<
2022.03.07 22:58:11.719 5: Cmd: >set SignalMessenger msg FHEM Neustart<
2022.03.07 22:58:11.722 3: set SignalMessenger msg FHEM Neustart : Please define SignalMessenger first
2022.03.07 22:58:11.723 3: SignalMsg Neustart
2022.03.07 22:58:11.743 5: End notify loop for global
2022.03.07 22:58:11.743 0: Featurelevel: 6.1
2022.03.07 22:58:11.743 0: Server started with 372 defined entities (fhem.pl:25777/2022-03-05 perl:5.032001 os:linux user:pi pid:2403)
2022.03.07 22:58:11.772 5: Starting notify loop for rand_0OG_GA_LI_Deckenlicht, 1 event(s), first is active: 0
2022.03.07 22:58:11.772 5: createNotifyHash
2022.03.07 22:58:11.778 5: End notify loop for rand_0OG_GA_LI_Deckenlicht
2022.03.07 22:58:11.779 5: Starting notify loop for rand_0OG_GA_LI_Deckenlicht, 2 event(s), first is StartTime: 2022-03-07 20:00:00
2022.03.07 22:58:11.780 5: End notify loop for rand_0OG_GA_LI_Deckenlicht
2022.03.07 22:58:11.780 5: Starting notify loop for rand_0OG_GA_LI_Deckenlicht, 1 event(s), first is off
2022.03.07 22:58:11.781 5: End notify loop for rand_0OG_GA_LI_Deckenlicht
2022.03.07 22:58:11.782 5: Starting notify loop for rand_2OG_GA_LI_Vorraum, 1 event(s), first is active: 0
2022.03.07 22:58:11.782 5: End notify loop for rand_2OG_GA_LI_Vorraum
2022.03.07 22:58:11.783 5: Starting notify loop for rand_2OG_GA_LI_Vorraum, 2 event(s), first is StartTime: 2022-03-07 19:30:00
2022.03.07 22:58:11.783 5: End notify loop for rand_2OG_GA_LI_Vorraum
2022.03.07 22:58:11.784 5: Starting notify loop for rand_2OG_GA_LI_Vorraum, 1 event(s), first is off
2022.03.07 22:58:11.784 5: End notify loop for rand_2OG_GA_LI_Vorraum
2022.03.07 22:58:11.787 5: HttpUtils url=https://192.168.xxx.210/general/status.html NonBlocking via https
2022.03.07 22:58:11.787 4: IP: 192.168.xxx.210 -> 192.168.xxx.210
2022.03.07 22:58:11.788 3: DbLog logdb - Creating Push-Handle to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2022.03.07 22:58:11.791 3: DbLog logdb - Push-Handle to db mysql:database=fhem;host=localhost;port=3306 created
2022.03.07 22:58:11.791 3: DbLog logdb - UTF8 support enabled
2022.03.07 22:58:11.792 5: Starting notify loop for logdb, 1 event(s), first is connected
2022.03.07 22:58:11.792 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.792 4: DbLog logdb -> ###              start of new Logcycle                       ###
2022.03.07 22:58:11.792 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.792 4: DbLog logdb -> number of events received: 1 of device: logdb
2022.03.07 22:58:11.792 4: DbLog logdb -> check Device: logdb , Event: state: connected
2022.03.07 22:58:11.793 5: DbLog logdb -> parsed Event: logdb , Event: state: connected
2022.03.07 22:58:11.793 5: DbLog logdb -> DbLogInclude of "logdb": CacheUsage,NextSync,state
2022.03.07 22:58:11.793 4: DbLog logdb -> added event - Timestamp: 2022-03-07 22:58:11, Device: logdb, Type: DBLOG, Event: state: connected, Reading: state, Value: connected, Unit:
2022.03.07 22:58:11.794 5: End notify loop for logdb
2022.03.07 22:58:11.794 5: Starting notify loop for rand_0OG_GA_LI_Deckenlicht, 1 event(s), first is off
2022.03.07 22:58:11.795 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.795 4: DbLog logdb -> ###              start of new Logcycle                       ###
2022.03.07 22:58:11.795 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.795 4: DbLog logdb -> number of events received: 1 of device: rand_0OG_GA_LI_Deckenlicht
2022.03.07 22:58:11.795 4: DbLog logdb -> check Device: rand_0OG_GA_LI_Deckenlicht , Event: state: off
2022.03.07 22:58:11.795 5: DbLog logdb -> parsed Event: rand_0OG_GA_LI_Deckenlicht , Event: state: off
2022.03.07 22:58:11.795 5: DbLog logdb -> DbLogExclude of "rand_0OG_GA_LI_Deckenlicht": .*
2022.03.07 22:58:11.795 5: End notify loop for rand_0OG_GA_LI_Deckenlicht
2022.03.07 22:58:11.796 5: Starting notify loop for rand_0OG_GA_LI_Deckenlicht, 1 event(s), first is active: 0
2022.03.07 22:58:11.796 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.796 4: DbLog logdb -> ###              start of new Logcycle                       ###
2022.03.07 22:58:11.797 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.797 4: DbLog logdb -> number of events received: 1 of device: rand_0OG_GA_LI_Deckenlicht
2022.03.07 22:58:11.797 4: DbLog logdb -> check Device: rand_0OG_GA_LI_Deckenlicht , Event: active: 0
2022.03.07 22:58:11.797 5: DbLog logdb -> parsed Event: rand_0OG_GA_LI_Deckenlicht , Event: active: 0
2022.03.07 22:58:11.797 5: DbLog logdb -> DbLogExclude of "rand_0OG_GA_LI_Deckenlicht": .*
2022.03.07 22:58:11.797 5: End notify loop for rand_0OG_GA_LI_Deckenlicht
2022.03.07 22:58:11.798 5: Starting notify loop for rand_2OG_GA_LI_Vorraum, 1 event(s), first is active: 1
2022.03.07 22:58:11.798 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.798 4: DbLog logdb -> ###              start of new Logcycle                       ###
2022.03.07 22:58:11.798 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.799 4: DbLog logdb -> number of events received: 1 of device: rand_2OG_GA_LI_Vorraum
2022.03.07 22:58:11.799 4: DbLog logdb -> check Device: rand_2OG_GA_LI_Vorraum , Event: active: 1
2022.03.07 22:58:11.799 5: DbLog logdb -> parsed Event: rand_2OG_GA_LI_Vorraum , Event: active: 1
2022.03.07 22:58:11.799 5: DbLog logdb -> DbLogExclude of "rand_2OG_GA_LI_Vorraum": .*
2022.03.07 22:58:11.799 5: End notify loop for rand_2OG_GA_LI_Vorraum
2022.03.07 22:58:11.800 5: Starting notify loop for rand_2OG_GA_LI_Vorraum, 1 event(s), first is on
2022.03.07 22:58:11.800 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.800 4: DbLog logdb -> ###              start of new Logcycle                       ###
2022.03.07 22:58:11.800 4: DbLog logdb -> ################################################################
2022.03.07 22:58:11.800 4: DbLog logdb -> number of events received: 1 of device: rand_2OG_GA_LI_Vorraum
2022.03.07 22:58:11.800 4: DbLog logdb -> check Device: rand_2OG_GA_LI_Vorraum , Event: state: on
2022.03.07 22:58:11.800 5: DbLog logdb -> parsed Event: rand_2OG_GA_LI_Vorraum , Event: state: on
2022.03.07 22:58:11.801 5: DbLog logdb -> DbLogExclude of "rand_2OG_GA_LI_Vorraum": .*
2022.03.07 22:58:11.801 5: End notify loop for rand_2OG_GA_LI_Vorraum
2022.03.07 22:58:11.805 3: telnetForBlockingFn_1646690291: port 39761 opened
2022.03.07 22:58:12.262 5: Starting notify loop for APCUPS1500G, 1 event(s), first is OL
2022.03.07 22:58:12.262 5: createNotifyHash
2022.03.07 22:58:12.274 4: DbLog logdb -> ################################################################
2022.03.07 22:58:12.274 4: DbLog logdb -> ###              start of new Logcycle                       ###
2022.03.07 22:58:12.274 4: DbLog logdb -> ################################################################
2022.03.07 22:58:12.274 4: DbLog logdb -> number of events received: 1 of device: APCUPS1500G
2022.03.07 22:58:12.275 4: DbLog logdb -> check Device: APCUPS1500G , Event: state: OL
2022.03.07 22:58:12.275 5: DbLog logdb -> parsed Event: APCUPS1500G , Event: state: OL
2022.03.07 22:58:12.275 5: DbLog logdb -> DbLogInclude of "APCUPS1500G": state,battery.charge,ups.load
2022.03.07 22:58:12.275 4: DbLog logdb -> added event - Timestamp: 2022-03-07 22:58:12, Device: APCUPS1500G, Type: NUT, Event: state: OL, Reading: state, Value: OL, Unit:
2022.03.07 22:58:12.276 5: End notify loop for APCUPS1500G
2022.03.07 22:58:12.279 5: Starting notify loop for APCUPS1500G, 1 event(s), first is ups.load: 12
2022.03.07 22:58:12.280 4: DbLog logdb -> ################################################################
2022.03.07 22:58:12.280 4: DbLog logdb -> ###              start of new Logcycle                       ###
2022.03.07 22:58:12.280 4: DbLog logdb -> ################################################################
2022.03.07 22:58:12.280 4: DbLog logdb -> number of events received: 1 of device: APCUPS1500G
2022.03.07 22:58:12.280 4: DbLog logdb -> check Device: APCUPS1500G , Event: ups.load: 12
2022.03.07 22:58:12.280 5: DbLog logdb -> parsed Event: APCUPS1500G , Event: ups.load: 12
2022.03.07 22:58:12.281 5: DbLog logdb -> DbLogInclude of "APCUPS1500G": state,battery.charge,ups.load
2022.03.07 22:58:12.281 4: DbLog logdb -> added event - Timestamp: 2022-03-07 22:58:12, Device: APCUPS1500G, Type: NUT, Event: ups.load: 12, Reading: ups.load, Value: 12, Unit:
2022.03.07 22:58:12.281 5: End notify loop for APCUPS1500G
2022.03.07 22:58:12.282 4: Connection accepted from telnetForBlockingFn_1646690291_127.0.0.1_33660
SSL_verify_mode must be a number and not a string at /usr/share/perl5/IO/Socket/SSL.pm line 2386.

Dabei ist mir aufgefallen, dass HttpUtils möglicherweise auch in 72_TA_CMI_JSON verwendet wird. Mit diesem Modul hatte ich Anfang Februar Probleme, nämlich dass die Werte nicht mehr ausgelesen werden haben können. Es hat dann einige Tage später ein Update gegeben, seit welchem die Datenerfassung wieder funktioniert. Mit dem damaligen generischen UPDATE für FHEM sind die Symptome des nicht mehr nutzbaren FHEM (Start-Loop) erstmalig aufgetreten. Vielleicht besteht hiermit ein Zusammenhang ...

Schöne Grüße

[rudolfkoenig]

ich habe nun, wie angefordert, den manuellen Start über xxx durchgeführt.

Danke. Ich hoffe, dass der abgeschnittene Anfang des Logs keine fuer das Problem wesentlich Informationen enthaelt.
Nach dem vorliegenden Daten erzeugt der "https://192.168.xxx.210/general/status.html" Aufruf das Problem.
In der neueren HttpUtils.pm Version wird der HTTPS Verbindungsaufbau nicht mehr blockierend durchgefuehrt, und scheinbar schafft irgendwer die Verbinungsparameter (hier SSL_verify_mode) in der Zwischenzeit kaputtzumachen.

Ich habe eine Weile ueber das Problem nachgedacht, SSL.pm angeschaut, etliche Tests durchgefuehrt, leider ohne Ergebnis.
Ich hoffe, dass ein Test mit dem angehaengten HttpUtils.pm zu Aufklaerung des Problems beitragen kann.

[Beko136]

Hallo,

der Log-Output und Ihr Verdacht bzw. das hervorgehobene Gerät waren goldrichtig - ein wahrer Volltreffer. Das Device war vor einigen Jahren einmal ein Test, das Webinterface meines Multifunktionsdruckers auszulesen und die Daten zu erfassen. Dieses Test-Device war unglücklicherweise immer noch aktiv und das in einem FHEM-Raum, welchen ich nicht oft in der GUI aufrufe. Nach Auskommentieren dieses Devices ließ sich das anstehende und reguläre Update für HttpUtils.pm installieren und FHEM funktioniert nachher ebenso wieder ganz normal. Ich würde Ihnen daher den Test mit dem modifizierten Modul ersparen, außer Sie möchten es dennoch versuchen, dann mache ich gerne mit.
Entschuldigen Sie bitte die entstandene "Unruhe", das ursächliche Problem saß, wie in der EDV des Öfteren der Fall, wieder einmal zwischen Bildschirm und Sessellehne.
Ich bedanke mich für den tollen Support und wünsche Ihnen alles Gute!

Schöne Grüße

[rudolfkoenig]

Entschuldigen Sie bitte die entstandene "Unruhe", das ursächliche Problem saß, wie in der EDV des Öfteren der Fall, wieder einmal zwischen Bildschirm und Sessellehne.

Ich sehe das im Moment anders, ein FHEM-Update soll nicht zum Absturz fuehren.

Ueber das Log eines Tests mit dem vorhin angehaengten Modul wuerde ich mich freuen, auch wenn ich nicht sicher bin, dass das Problem damit lokalisiert werden kann. Aber womoeglich beruhigt sie mich, dass es sich hier um einen Ausnahmefall handelt.

[Beko136]

Hallo,

alles klar, wir können gerne einen weiteren Versuch machen. Kann ich Ihnen den Log zur Verfügung stellen, ohne diesen hier posten zu müssen?

Schöne Grüße

[rudolfkoenig]

Danke fuer die Daten.

Das Problem ist die Anweisung

Code Auswählen Erweitern

attr <HTTPMOD_Instanz> sslArgs SSL_verify_mode,SSL_VERIFY_NONE
weil weder HTTPMOD, noch HTTPUtils eine Ersetzung des Symbols SSL_VERIFY_NONE durchfuehrt.

Richtig waere stattdessen

Code Auswählen Erweitern

attr <HTTPMOD_Instanz> sslArgs SSL_verify_mode,0
was aber auch die Voreinstellung ist, insofern ueberfluessig.

Warum das mit der alten HttpUtils.pm funktioniert hat, bleibt ein Raetsel.

Nachtrag: ich sehe gerade, dass die erste Version mit SSL_VERIFY_NONE explizit so in der HTTPMOD Doku erwaehnt wird.
Das sollte mAn angepasst werden, da falsch: erstens fuehrt diese Variante zu Fehler, zweitens suggeriert man damit, dass per Voreinstellung Zertifikate geprueft werden.

Von einem Benutzerfehler koennen wir damit definitiv nicht reden.

[Beko136]

Hallo,

das klingt nachvollziehbar und ich freue mich, dass Sie einen Benutzerfehler ausschließen. Ich möchte nochmals Danke sagen für den tollen Support und wünsche Ihnen alles Gute.

Schöne Grüße