[SOLVED] MQTT2_CLIENT set connect blockiert FHEM

[knorxi]

Ich habe einen Saugroboter von Roomba den ich über dem MQTT2_CLIENT anspreche.
Bei einem "set RoombiClient connect" braucht er ziemliche lange (ca. 4s) um eine SSL-Verbindung aufzubauen.
Deshalb habe ich den TIMEOUT auf 6s gestellt.
Während des Verbidnungaufbaus wird FHEM blockiert.
Das verstehe ich nicht, da der MQTT2_CLIENT in der Funktion MQTT2_CLIENT_connect doch non-blocking DevIo_OpenDev in DevIo.pm aufruft.
DevIo_OpenDev ruft dann auch non-blocking HttpUtils_Connect in HttpUtils.pm auf.
Hier mal ein list vom MQTT2_CLIENT RoombiClient:

Code Auswählen Erweitern


Internals:
   BUF       
   Clients    :MQTT2_DEVICE:MQTT_GENERIC_BRIDGE:
   ClientsKeepOrder 1
   DEF        192.168.178.43:8883
   DeviceName 192.168.178.43:8883
   FD         64
   FUUID      600996a7-f33f-8d65-624c-1562fe6d5b5a71bc
   NAME       RoombiClient
   NR         432
   PARTIAL   
   SSL        1
   STATE      opened
   TIMEOUT    6
   TYPE       MQTT2_CLIENT
   WBCallback
   clientId   ...
   lastMsgTime 1643791806.38411
   nextOpenDelay 5
   MatchList:
     1:MQTT2_DEVICE ^.
     2:MQTT_GENERIC_BRIDGE ^.
   READINGS:
     2022-02-02 08:51:43   state           opened
   sslargs:
     SSL_version TLSv1_2
Attributes:
   SSL        1
   autocreate no
   clientId   ...
   connectTimeout 6
   mqttVersion 3.1.1
   room       Gästezimmer
   sslargs    SSL_version:TLSv1_2
   username   ...


Wenn ich folgendes in FHEM eingebe:

Code Auswählen Erweitern


{main::Log 1, 'set RoombiClient connect'};
set RoombiClient connect;
{main::Log 1, 'sleep 0s'};
sleep 1;
{main::Log 1, 'sleep 1s'};

Dann steht im Log das:

Code Auswählen Erweitern


2022.02.02 10:19:15 1: set RoombiClient connect
2022.02.02 10:19:15 5: HttpUtils url=https://192.168.178.43:8883/ NonBlocking via https
2022.02.02 10:19:15 4: IP: 192.168.178.43 -> 192.168.178.43
2022.02.02 10:19:15 1: sleep 0s
2022.02.02 10:19:20 5: RoombiClient: sending CONNECT (16)N(0)(4)MQTT(4)...
2022.02.02 10:19:20 5: DevIo_SimpleWrite RoombiClient: 10..
2022.02.02 10:19:20 1: 192.168.178.43:8883 reappeared (RoombiClient)
2022.02.02 10:19:20 1: Callback fired
2022.02.02 10:19:20 1: [Freezemon] Freezemon: possible freeze starting at 10:19:16, delay is 4.476 possibly caused by: no bad guy found :-(
2022.02.02 10:19:20 1: sleep 1s
2022.02.02 10:19:20 5: RoombiClient: received CONNACK (0)(0)

Zwischen "set RoombiClient connect" und "sleep 1s" sollte nur 1s vergehen. Es sind aber 5s.
Habe ich hier einen Denkfehler?
Weiß jemand, wie das Blockieren verhindert werden kann?

[rudolfkoenig]

HttpUtils_Connect ist nicht ganz blockierungsfrei: das Aushandeln der SSL-Verbindungsparameter passiert in der Bibliothek, und ist blockierend.

Ob in diesem Fall das Blockieren daran liegt, kann man vmtl. mit weiteren Debug-Zeilen in HttpUtils.pm, rund um den start_SSL Aufruf rausfinden. Wenn das stimmt, und jemand eine Idee hat, wie man das blockierungsfrei gestalten kann, bitte melden. Die Bibliothek neu zu implementieren ist aber keine Option

[knorxi]

Danke für die Aufklärung! Das macht dann Sinn.
Habe um SSL->start_SSL folgende Debug-Zeilen eingetragen:

Code Auswählen Erweitern


      Log3 $hash, 1, "before calling IO::Socket::SSL->start_SSL";
      eval {
        IO::Socket::SSL->start_SSL($hash->{conn}, \%par) || undef $hash->{conn};
      };
      Log3 $hash, 1, "after call of IO::Socket::SSL->start_SSL";

Im Log steht dann das:

Code Auswählen Erweitern


2022.02.02 15:45:19 1: before calling IO::Socket::SSL->start_SSL
2022.02.02 15:45:24 1: after call of IO::Socket::SSL->start_SSL

Daran scheint es also zu liegen.
Es wäre natürlich toll, wenn jemand eine Idee hätte 
Ich sehe ein, dass das Ändern der Bibliothek keine Option ist 

[knorxi]

Ich habe mal rumgesucht und das hier gefunden:
https://docplayer.org/573367-Io-socket-ssl-ssl-leicht-gemacht-so-gut-es-geht.html
Auf Seite 40 gibt es die Folie: "Fortgeschrittene Nutzung:- non-blocking connect (Client)"
Habe den Code mal so um das start_SSL eingebaut:

Code Auswählen Erweitern


      Log3 $hash, 1, "before calling IO::Socket::SSL->start_SSL";
#      eval {
#        IO::Socket::SSL->start_SSL($hash->{conn}, \%par) || undef $hash->{conn};
#      };

      # nonblocking connect
      # erst non-blocking INET-Connect machen
      # dann non-blocking SSL-Upgrade
      # Upgrade
      $hash->{conn}->blocking(0);
      $par{SSL_startHandshake} = 0;
      IO::Socket::SSL->start_SSL($hash->{conn}, \%par);
      while (1) {
        Time::HiRes::sleep(1); # 1 second
        Log3 $hash, 1, "Wait for SSL->connect";
        $hash->{conn}->connect_SSL && last;        # connect fertig
        die "$!,$SSL_ERROR" if ! $!{EAGAIN}; # Fehler
        if ( $SSL_ERROR == SSL_WANT_READ ) {
          #... warten auf socket readable (select loop...)
        } elsif ( $SSL_ERROR == SSL_WANT_WRITE ) {
          #... warten auf Socket writable
        }
      }


Leider weiß ich nicht genau bzw. überhaupt nicht was ich tue  .
Das Freeze bleibt zwar, aber das connect scheint jetzt non-blocking zu sein.
Zumindest wird ins Log im Sekundentakt geschrieben.
Vielleicht könnt ihr damit etwas anfangen, um es wirklich non-blocking zu machen....

Code Auswählen Erweitern


2022.02.02 16:56:11 1: before calling IO::Socket::SSL->start_SSL
2022.02.02 16:56:12 1: Wait for SSL->connect
2022.02.02 16:56:13 1: Wait for SSL->connect
2022.02.02 16:56:14 1: Wait for SSL->connect
2022.02.02 16:56:15 1: Wait for SSL->connect
2022.02.02 16:56:16 1: Wait for SSL->connect
2022.02.02 16:56:17 1: Wait for SSL->connect
2022.02.02 16:56:18 1: Wait for SSL->connect
2022.02.02 16:56:18 1: after call of IO::Socket::SSL->start_SSL
2022.02.02 16:56:18 1: 192.168.178.43:8883 reappeared (RoombiClient)
2022.02.02 16:56:18 2: [Freezemon] Freezemon: possible freeze starting at 16:56:12, delay is 6.648 possibly caused by: no bad guy found :-(


Edit: Merke gerade, dass ich etwas vom Roombi empfangen kann, aber ein "update checktime" nicht mehr funktioniert:

Code Auswählen Erweitern


"Downloading https://fhem.de/fhemupdate/controls_fhem.txt

fhem
https://fhem.de/fhemupdate/controls_fhem.txt: empty file received


[rudolfkoenig]

Danke fuer deine Recherche, ich habe das eingebaut, etwas getestet, und eingecheckt.
start_SSL sollte ab sofort HttpUtils_NonblockingGet nicht mehr blockieren.
Die anderen Zweige (http:// und BlockingGet) sollten nicht beruehrt sein.

[knorxi]

Suuuper! Vielen Dank!
Erste Tests sehen sehr gut aus.
Kein Freeze beim Connect.
Topp! Ich hoffe das hilft auch anderen, die eine Verbindung mit https aufbauen.

[Bualicher]

Hallo zusammen,
ich habe vorhin ein Update gemacht.
Danach kann ich nicht mehr auf FHEM zugreifen.
Im log vom Neustart steht Folgendes als letzter Eintrag:

Code Auswählen Erweitern

Can't locate object method "connect_SSL" via package "IO::Socket::INET" at FHEM/HttpUtils.pm line 510.

Nachdem ich wieder die Vorgängerversion von HttpUtils.pm (25487) draufgemacht habe, läuft FHEM nach einem Neustart normal.

System läuft auf einem Pi (Buster).

[Timmäää]

Genau das gleiche Problem habe ich auch und habe es im HMCCU-Thread gemeldet, da die Fehlermeldung zwischen vielen HMCCU-Events kam.
HMCCU scheint IO::Socket::INET zu nutzen, das ist aus der letzten Version von httpUtils aber hinausgeflogen in Zeile 6: " use IO::Socket::INET;"
Ggf. ist die Annahme aber auch falsch und es hat nichts mit HMCCU zu tun.

Ich habe mit auch zunächst geholfen, indem ich die alte httpUtils nutze.

[rudolfkoenig]

Can't locate object method "connect_SSL" via package "IO::Socket::INET" at FHEM/HttpUtils.pm line 510.

Ich gehe davon aus, dass eine alte Version von IO::Socket:SSL installiert ist.
Leider habe ich nicht rausgefunden, ab welcher Version connect_SSL unterstuetzt wird.
Ich habe jetzt eine Abfrage eingebaut: das nichtblockierende start_SSL wird nur dann gestartet, wenn connect_SSL vorhanden ist.
Waere nett, wenn ich dazu Feedback kriegen wuerde, da ich den Problemfall nicht getestet habe (s.o.).

HMCCU scheint IO::Socket::INET zu nutzen, das ist aus der letzten Version von httpUtils aber hinausgeflogen in Zeile 6: " use IO::Socket::INET;"

Verstehe die Aussage nicht.
IO::Socket::INET ist aus HttpUtils.pm seit eine Weile "rausgeflogen", weil das bereits in fhem.pl per use eingebunden wird.
Gibt es einen Grund, daran was zu aendern?

[Timmäää]

Verstehe die Aussage nicht.
IO::Socket::INET ist aus HttpUtils.pm seit eine Weile "rausgeflogen", weil das bereits in fhem.pl per use eingebunden wird.
Gibt es einen Grund, daran was zu aendern?

Nein gibt es nicht, ich bin auch nicht derart versiert. Ich hatte nur gesehen, dass die Einbindung in httpUtils herausgenommen wurde und in der Fehlermeldung etwas zu diesem package steht. Vermutlich habe ich auch das SVN dafür falsch bedient, ich hatte die Zeile als rot gesehen und war vermeintlich bei jüngeren Änderungen.
Also bitte alles vergessen.

Danke fürs Fixen, ich benutzte das debian stretch Paket für libio-socket-ssl-perl, das muss dann alt sein.

[Bualicher]

...
Ich habe jetzt eine Abfrage eingebaut: das nichtblockierende start_SSL wird nur dann gestartet, wenn connect_SSL vorhanden ist.
Waere nett, wenn ich dazu Feedback kriegen wuerde, da ich den Problemfall nicht getestet habe (s.o.).
...

Habe deine Version 25622 aus dem Trunk versucht. Fehler bleibt leider bestehen.

Code Auswählen Erweitern

Can't locate object method "connect_SSL" via package "IO::Socket::INET" at FHEM/HttpUtils.pm line 510.

[JoWiemann]

Hallo,

leider kommt 48_BlinkCamera.pm, auch mit den Änderungen von heute morgen, nicht klar.

Code Auswählen Erweitern


2022.02.03 11:03:36 5: BlinkCamera_PollInfo BlinkSys: called
2022.02.03 11:03:36 4: BlinkCamera_DoCmd BlinkSys: called  for cmd :homescreen  par2:POLLING::
2022.02.03 11:03:36 4: BlinkCamera_DoCmd BlinkSys: try to send cmd homescreen  par2:POLLING:
2022.02.03 11:03:36 4: BlinkCamera_DoCmd BlinkSys: call url :https://rest-e004.immedia-semi.com/api/v3/accounts/163957/homescreen:
2022.02.03 11:03:36 4: BlinkCamera_PollInfo BlinkSys: initiate next polling homescreen 60s
2022.02.03 11:03:36 4: BlinkCamera_Callback BlinkSys: called from Polling
2022.02.03 11:03:36 4: BlinkCamera_Callback BlinkSys: status err ::  data <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd">
<HTML><HEAD><META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=iso-8859-1">
<TITLE>ERROR: The request could not be satisfied</TITLE>
</HEAD><BODY>
<H1>400 ERROR</H1>
<H2>The request could not be satisfied.</H2>
<HR noshade size="1px">
Bad request.
We can't connect to the server for this app or website at this time. There might be too much traffic or a configuration error. Try again later, or contact the app or website owner.
<BR clear="all">
If you provide content to customers through CloudFront, you can find steps to troubleshoot and help prevent this error by reviewing the CloudFront documentation.
<BR clear="all">
<HR noshade size="1px">
<PRE>
Generated by cloudfront (CloudFront)
Request ID: --- geschwärzt ---
</PRE>
<ADDRESS>
</ADDRESS>
</BODY></HTML>
2022.02.03 11:03:36 5: BlinkCamera_Callback BlinkSys: data returned :<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd">
<HTML><HEAD><META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=iso-8859-1">
<TITLE>ERROR: The request could not be satisfied</TITLE>
</HEAD><BODY>
<H1>400 ERROR</H1>
<H2>The request could not be satisfied.</H2>
<HR noshade size="1px">
Bad request.
We can't connect to the server for this app or website at this time. There might be too much traffic or a configuration error. Try again later, or contact the app or website owner.
<BR clear="all">
If you provide content to customers through CloudFront, you can find steps to troubleshoot and help prevent this error by reviewing the CloudFront documentation.
<BR clear="all">
<HR noshade size="1px">
<PRE>
Generated by cloudfront (CloudFront)
Request ID: - geschwärzt ---
</PRE>
<ADDRESS>
</ADDRESS>
</BODY></HTML>:
2022.02.03 11:03:36 4: BlinkCamera_Callback BlinkSys: after decoding status ret:Callback returned no valid JSON: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "<!DOCTYPE HTML PUBLI...") at /opt/fhem/FHEM/48_BlinkCamera.pm line 1599.
:
2022.02.03 11:03:36 2: BlinkCamera_Callback BlinkSys: for cmd :homescreen:  retry :1  resulted in :Callback returned no valid JSON: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "<!DOCTYPE HTML PUBLI...") at /opt/fhem/FHEM/48_BlinkCamera.pm line 1599.
:  cmdId :-- from Polling


Mehr debugging kann ich aus Zeitgründen heute nicht mehr machen.

Grüße Jörg

[rudolfkoenig]

Habe deine Version 25622 aus dem Trunk versucht. Fehler bleibt leider bestehen.

Meine Theorie (IO::Socket::SSL ist alt) ist aus zwei Gruenden falsch: die Fehlermeldung redet von IO::Socket::INET, und die Meldung stammt aus der Zeile 510, der Aufruf in Zeile 498 ging ohne Probleme durch.
D.h. irgendwer aendert die Klasse von $hash->{conn} zwischen den beiden connect_SSL aufrufen.

Nach etwas experimentieren: das passiert, wenn der angesprochene Server kein HTTPS unterstuetzt.

Ich habe den Code erneut angepasst, und bitte um Feedback.

[JoWiemann]

Hallo Rudi,

anbei ein verbose 5 für 48_BlinkCamera.pm.

Code Auswählen Erweitern


2022.02.03 12:16:36 5: DNS ANSWER 108:70728180000100040000000009726573742d653030340c696d6d656469612d73656d6903636f6d0000010001c00c000100010000003c00046c9d0404c00c000100010000003c00046c9d045dc00c000100010000003c00046c9d0455c00c000100010000003c00046c9d0433
2022.02.03 12:16:36 4: DNS result for rest-e004.immedia-semi.com: 108.157.4.4, ttl:60
2022.02.03 12:16:36 4: IP: rest-e004.immedia-semi.com -> 108.157.4.4
2022.02.03 12:16:36 5: HttpUtils request header:
GET /api/v3/accounts/163957/homescreen HTTP/1.0
Accept-Encoding: gzip,deflate
agent: TelegramBot/1.0
User-Agent: TelegramBot/1.0
Host: rest-e004.immedia-semi.com
token-auth: aScAZwjxhy1muOkosle0WA

2022.02.03 12:16:36 4: <hidden>: HTTP response code 400
2022.02.03 12:16:36 5: HttpUtils <hidden>: Got data, length: 915
2022.02.03 12:16:36 5: HttpUtils response header:
HTTP/1.1 400 Bad Request
Server: CloudFront
Date: Thu, 03 Feb 2022 11:16:36 GMT
Content-Type: text/html
Content-Length: 915
Connection: close
X-Cache: Error from cloudfront
Via: 1.1 c9ca35e5541827c5873bfdb59f015b20.cloudfront.net (CloudFront)
X-Amz-Cf-Pop: DUS51-P2
X-Amz-Cf-Id: gURqRK7hVuPina-s5F-Sc1bsUujiFkdsDalHMxEjV7HxAXvhHAAGIQ==
2022.02.03 12:16:36 4: BlinkCamera_Callback BlinkSys: called from DoCmd
2022.02.03 12:16:36 4: BlinkCamera_Callback BlinkSys: status err ::  data <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd">
<HTML><HEAD><META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=iso-8859-1">
<TITLE>ERROR: The request could not be satisfied</TITLE>
</HEAD><BODY>
<H1>400 ERROR</H1>
<H2>The request could not be satisfied.</H2>
<HR noshade size="1px">
Bad request.
We can't connect to the server for this app or website at this time. There might be too much traffic or a configuration error. Try again later, or contact the app or website owner.
<BR clear="all">
If you provide content to customers through CloudFront, you can find steps to troubleshoot and help prevent this error by reviewing the CloudFront documentation.
<BR clear="all">
<HR noshade size="1px">
<PRE>
Generated by cloudfront (CloudFront)
Request ID: --- geschwärzt ---
</PRE>
<ADDRESS>
</ADDRESS>
</BODY></HTML>
2022.02.03 12:16:36 5: BlinkCamera_Callback BlinkSys: data returned :<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd">
<HTML><HEAD><META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=iso-8859-1">
<TITLE>ERROR: The request could not be satisfied</TITLE>
</HEAD><BODY>
<H1>400 ERROR</H1>
<H2>The request could not be satisfied.</H2>
<HR noshade size="1px">
Bad request.
We can't connect to the server for this app or website at this time. There might be too much traffic or a configuration error. Try again later, or contact the app or website owner.
<BR clear="all">
If you provide content to customers through CloudFront, you can find steps to troubleshoot and help prevent this error by reviewing the CloudFront documentation.
<BR clear="all">
<HR noshade size="1px">
<PRE>
Generated by cloudfront (CloudFront)
Request ID: --- geschwärzt ---
</PRE>
<ADDRESS>
</ADDRESS>
</BODY></HTML>:
2022.02.03 12:16:36 4: BlinkCamera_Callback BlinkSys: after decoding status ret:Callback returned no valid JSON: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "<!DOCTYPE HTML PUBLI...") at /opt/fhem/FHEM/48_BlinkCamera.pm line 1599.
:
2022.02.03 12:16:36 5: BlinkCamera_Callback BlinkSys: for cmd :homescreen:  retry :1  resulted in :Callback returned no valid JSON: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "<!DOCTYPE HTML PUBLI...") at /opt/fhem/FHEM/48_BlinkCamera.pm line 1599.
:  cmdId :-- from DoCmd
2022.02.03 12:16:36 3: BlinkCamera_Callback BlinkSys: Reached max retries (ret: Callback returned no valid JSON: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "<!DOCTYPE HTML PUBLI...") at /opt/fhem/FHEM/48_BlinkCamera.pm line 1599.
) for cmd homescreen
2022.02.03 12:16:36 5: Starting notify loop for BlinkSys, 5 event(s), first is cmdResult: Callback returned no valid JSON: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "<!DOCTYPE HTML PUBLI...") at /opt/fhem/FHEM/48_BlinkCamera.pm line 1599.\n
2022.02.03 12:16:36 5: Batterie: not on any display, ignoring notify
2022.02.03 12:16:36 5: End notify loop for BlinkSys


[Bualicher]

...
Ich habe den Code erneut angepasst, und bitte um Feedback.

Super. Vielen Dank.
Funktioniert bei mir wieder mit Deiner Version 25623