WebSocket via DevIO?

KölnSolar · 19 Juni 2020, 09:32:18

Hi Rudi,
ich kämpfe immer noch mit den websockets by DevIo.

Seit Tagen versuche ich zu verstehen, was ich beim Open falsch machen könnte. Da ich es auch noch an verschiedenen Stellen des Moduls ausführe, war es nicht leicht bei einem geht/geht_nicht Verhalten dem Ganzen auf die Spur zu kommen. Nun habe ich aber endlich herausgefunden, dass ein "seltsamer" ReadFn-Aufruf zum disconnect führt. Warum auch immer wird die ReadFn aufgerufen. Das DevIoSimpleRead führt dann zum disconnect, weil gar keine Daten bereitstehen. Mit ein paar Zusatzloggings das Verhalten, welches im 2. Logauszug dadurch vermieden wird, dass ich einfach den ersten Aufruf der ReadFn OHNE DevIoSimpleRead ausführe.

Fehlverhalten:

Code Auswählen

2020.06.19 08:57:17 4: [EE2] sol  Attempting to open websocket by DevIo
2020.06.19 08:57:17 3: Opening sol device ws:wsServer:wsPort
2020.06.19 08:57:17 5: HttpUtils url=http://wsServer:wsPort/
2020.06.19 08:57:17 4: IP: wsServer -> IPwsServer
2020.06.19 08:57:17 5: HttpUtils request header:
GET / HTTP/1.1
Host: wsServer:wsPort
User-Agent: fhem
Accept-Encoding: gzip,deflate
Connection: Upgrade
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: /u+SyWye/hh3qEBt8GNb8A==
Upgrade: websocket

2020.06.19 08:57:17 4: http://wsServer:wsPort/: HTTP response code 101
2020.06.19 08:57:17 5: HttpUtils http://wsServer:wsPort/: Got data, length: 0
2020.06.19 08:57:17 5: HttpUtils response header:
HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Accept: Mx0apO9tUi3QpxSZXUgeBL6RNBM=
Date: Fri, 19 Jun 2020 06:57:17 GMT
Server: Python/3.5 websockets/7.0
2020.06.19 08:57:17 4: [EE2] sol wsInitFn called by DevIo. Try to login 
2020.06.19 08:57:17 3: sol device opened
2020.06.19 08:57:17 5: [EE2] sol - wsCallbackFn called without error by DevIo
2020.06.19 08:57:17 4: [EE2] sol ReadFn called; maybe too early ? First Read Flag: 1
2020.06.19 08:57:17 1: [DevIo] sol: empty read buffer after first read ? SimpleReadWithTimeout called
2020.06.19 08:57:17 1: [DevIo] sol: disconnected because of empty read buffer
2020.06.19 08:57:17 1: ws:wsServer:wsPort disconnected, waiting to reappear (sol)
2020.06.19 08:57:17 4: [EE2] sol connection seems to be closed. OpenDev for DeviceName: ws:wsServer:wsPort
2020.06.19 08:57:17 5: [EE2] sol - wsCallbackFn called without error by DevIo

Ignoriere ich den 1. Aufruf der ReadFn funktioniert es bestens. Die erste Aktion ist dann nach 20s ein Ping des Servers

Code Auswählen

2020.06.19 09:01:03 4: [EE2] sol  Attempting to open websocket by DevIo
2020.06.19 09:01:03 3: Opening sol device ws:wsServer:wsPort
2020.06.19 09:01:03 5: HttpUtils url=http://wsServer:wsPort/
2020.06.19 09:01:03 4: IP: wsServer:wsPort -> IPwsServer
2020.06.19 09:01:03 5: HttpUtils request header:
GET / HTTP/1.1
Host: wsServer:wsPort
User-Agent: fhem
Accept-Encoding: gzip,deflate
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: zdZLA7J4sTs+aOsOmj7COQ==
Connection: Upgrade
Upgrade: websocket

2020.06.19 09:01:03 4: http://wsServer:wsPort/: HTTP response code 101
2020.06.19 09:01:03 5: HttpUtils http://wsServer:wsPort/: Got data, length: 0
2020.06.19 09:01:03 5: HttpUtils response header:
HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Accept: IILT5oOQKLm8DyRhsDStpMgP+wo=
Date: Fri, 19 Jun 2020 07:01:03 GMT
Server: Python/3.5 websockets/7.0
2020.06.19 09:01:03 4: [EE2] sol wsInitFn called by DevIo. Try to login 
2020.06.19 09:01:03 3: sol device opened
2020.06.19 09:01:03 5: [EE2] sol - wsCallbackFn called without error by DevIo
2020.06.19 09:01:03 4: [EE2] sol ReadFn called; maybe too early ? First Read Flag: 1
2020.06.19 09:01:23 4: [EE2] sol ReadFn called; maybe too early ? First Read Flag: 0
2020.06.19 09:01:23 5: Websocket msg: OP:9 LEN:4 MASK:0 FIN:1
2020.06.19 09:01:23 5: Websocket ping: »;8X
2020.06.19 09:01:23 4: [EE2] sol received websocket data: ><

Läuft da noch was schief, dass die ReadFn "fälschlicherweise" aufgerufen wird ? Und wie gesagt, manchmal klappt der Verbindungsaufbau auch. Allerdings konnte ich das mit dem aktuellen Modulstand nicht reproduzieren.

Danke&Grüße
Markus

rudolfkoenig · 19 Juni 2020, 09:42:51

Ich fuerchte ich kann (trotz deinen fantasiereichen Debug-Texte) nichts dazu sagen, ohne es selbst testen zu koennen.

KölnSolar · 19 Juni 2020, 10:33:01

Das ist die, die Du auch damals schon getestet hattest. Da ich ja gar keine Daten gesendet hatte, liegt das Problem entweder im websocket-Aufbau oder einem möglicherweise sofort vom Server folgenden Ping.

Code Auswählen

Mit TLS kannst Du es auf sol.eet.energy:9124 testen.

Danke vorab
Markus

rudolfkoenig · 19 Juni 2020, 18:19:59

ZitatMit TLS kannst Du es auf sol.eet.energy:9124 testen.

Ich wuesste nicht wie. Wenn ich was sende, kriege ich eine Fehlermeldung (dass es kein JSON ist, oder dass ich per JSON Unsinn schicke), und wenn ich nichts sende, kriege ich alle 20 Sekunden ein ping request (was FHEM brav bantwortet), und meine Pings werden von sol.eet beantwortet. Sonst passiert: nix.

KölnSolar · 19 Juni 2020, 18:49:38

Genau so.

Ich hab ja das Problem, dass nach dem erfolgreichen Verbindungsaufbau die ReadFn aufgerufen wird. Das dortige SimpleRead führt dann zum disconnect, weil keine Daten gelesen werden. Zu einem SimpleWrite für einen Login..... komme ich ja schon gar nicht.

Die InitFn u. CallbackFn, die ich dem Open-Call mitgebe machen außer logging nichts.

Hast Du innerhalb einer FHEM-Instanz mit select/ready getestet ?

Ich probiere es nochmal. Nicht, dass das gerade wieder ohne überlesen des ersten ReadFn-Aufrufs funktioniert. Wenn nicht stell ich mal ein reduziertes Modul ein, dass die Symptome liefert.

rudolfkoenig · 19 Juni 2020, 20:09:04

Ich habe mit folgendem 98_wstest.pm getestet:

Code Auswählen

use strict;
use strict;
use warnings;
use DevIo;
sub wstest_ping($);
sub wstest_connect($);

sub
wstest_Initialize($)
{
  my ($hash) = @_;
  $hash->{DefFn}     = "wstest_Define";
  $hash->{ReadFn}    = "wstest_ReadFn";
  $hash->{ReadyFn}   = "wstest_connect";
}

sub
wstest_Define($$)
{
  my ($hash, $def) = @_;
  my @a = split(" ", $def);
  $hash->{DeviceName} = $a[2];
  wstest_connect($hash);
}

sub
wstest_ping($)
{
  my ($hash) = @_;
  return if(!$hash->{WEBSOCKET});
  DevIo_Ping($hash, "Hello");
  InternalTimer(time()+10, \&wstest_ping, $hash);
}

sub
wstest_ReadFn($)
{
  my ($hash) = @_;
  my $buf = DevIo_SimpleRead($hash);
  return if(!defined($buf)); # Disconnected, dont close, wait for reconnect
  Log 1, "GOT via websocket: >$buf<";
}

sub
wstest_connect($)
{
  my ($hash) = @_;
  my $disco = (ReadingsVal($hash->{NAME}, "state", "") eq "disconnected");
  DevIo_OpenDev($hash, $disco, undef, sub(){ 
    return if(!$hash->{WEBSOCKET});
    DevIo_SimpleWrite($hash, 'list', 2);
    wstest_ping($hash);
  });
}

1;

Aufgerufen habe ich es mit

Code Auswählen

define ws wstest wss:sol.eet.energy:9124
attr ws verbose 5

KölnSolar · 19 Juni 2020, 20:09:54

So hier der Minimalcode

Code Auswählen

##############################################################################
#
# 70_EE3.pm
#
# a module to request data from a EET-solmate-device
#
# written 2020 by KoelnSolar
#
# Version = 0.1
#
##############################################################################

package main;
use strict;
use warnings;

sub EE3_Initialize($)
{
  my ($hash) = @_;
  $hash->{DefFn}    = "EE3_Define";
  $hash->{UndefFn}  = "EE3_Undefine";
  $hash->{ReadFn}   = "EE3_Read";  
  $hash->{ReadyFn}  = "EE3_Ready";
}

sub EE3_Define($$)
{
  my ($hash, $def) = @_;
  my @args = split("[ \t]+", $def);

  if (int(@args) != 4)
  {
    return "[EE3] Define: faulty number of arguments. Usage:\n" .
         "define <name> EE3 <host> <port>";
  }

  $hash->{Host} = $args[2];
  $hash->{Port} = $args[3];

  if ( $hash->{Port} ne "9124" ){
	  return "[EE3] Port is not supported";
  }

  DevIo_CloseDev( $hash) if (defined($hash->{FD}));

 EE3_Init($hash);

  return undef;
}

sub EE3_Undefine($$) 
{
  my ($hash,$arg) = @_;
  DevIo_CloseDev( $hash) ;
  return undef;
}

sub EE3_Init($) 
{
    my ($hash) = @_;

    return if ( DevIo_IsOpen($hash) );

    $hash->{DeviceName} = "wss:".$hash->{Host} . ":" . $hash->{Port}; 

   DevIo_OpenDev( $hash, 0, "wsInit", "wsCb" ); 

}

sub EE3_Ready($)
{
  my ($hash) = @_;

  DevIo_OpenDev( $hash, $hash->{helper}{wsconnect}, "wsInit", "wsCb" );

  return;
}

sub EE3_Read($)
{
  my ($hash) = @_;
  my $name = $hash->{NAME};

#if ($hash->{First_Read} == 1) {
#$hash->{First_Read} = 0;
#return;
#}
  my $buf = DevIo_SimpleRead($hash);
  return "" if ( !defined($buf) );

    Log3 $name, 4, "[EE3] $name received websocket data: >$buf<";
  return;
}

sub wsInit ($){
    my ($hash)     = @_;

	$hash->{First_Read} = 1;

    return undef;

}

sub wsCb ($){
    my ($hash, $error)  = @_;

    return;
}

			
1;

=pod
=item summary device to communicate with an Samsung Television
=begin html

<a name="EE3"></a>

<h3>EE3</h3>
<ul><p>
This module supports EET solmate devices .<br>

</p>
 <b>Define</b><br>
  <code>define &lt;name&gt; EE3 &lt;host&gt; &lt;port&gt;</code><br>
  <p>
 use port 9124<br>                          


  Example:<br>
  define Television EE3 192.168.178.20 9124 <br>

  </p>
 <b>Set</b><br>
  - no set commands supported -

   <b>Get</b><br>
   <ul>N/A</ul><br>
  <br>
   <b>Attributes</b><br>
   		<ul>
			<li>SSL:  	set to 1 supports secure connections</li>
  <br>
		</ul>
  </ul>


</ul>
   
=end html
=cut

ohne überlesen des 1. Read

Code Auswählen

2020.06.19 19:57:38 3: Opening test device wss:sol.eet.energy:9124
2020.06.19 19:57:39 3: test device opened
2020.06.19 19:57:39 1: wss:sol.eet.energy:9124 disconnected, waiting to reappear (test)

kommentiert(also 1. ReadFn-Aufruf ignorieren):

Code Auswählen

2020.06.19 20:05:29 3: Opening test device wss:sol.eet.energy:9124
2020.06.19 20:05:29 3: test device opened
2020.06.19 20:05:49 5: Websocket msg: OP:9 LEN:4 MASK:0 FIN:1
2020.06.19 20:05:49 5: Websocket ping: \¦ÑN
2020.06.19 20:05:49 4: [EE3] test received websocket data: ><
.
.

Siehst Du etwas unsinniges als Ursache in dem Code ?

Edit: da haben wir gerade gleichzeitig gepostet. Ich vergleiche Deinen Code.....

rudolfkoenig · 19 Juni 2020, 20:31:46

Mit deinem Code sehe ich:

Code Auswählen

2020.06.19 20:28:53 3: ee3 device opened
2020.06.19 20:29:13 5: Websocket msg: OP:9 LEN:4 MASK:0 FIN:1
2020.06.19 20:29:13 5: Websocket ping: ©¼^}
2020.06.19 20:29:13 4: [EE3] ee3 received websocket data: ><
2020.06.19 20:29:33 5: Websocket msg: OP:9 LEN:4 MASK:0 FIN:1
2020.06.19 20:29:33 5: Websocket ping: jë
2020.06.19 20:29:33 4: [EE3] ee3 received websocket data: ><

was normal ist.
Leere Strings musst man ignorieren, da DevIo bei Kontrolpaketen wie Ping die Daten komplett verdaut.

Falls DevIo_SimpleRead undefined zurueckliefert, dann ist Zeit die Verbindung zu schliessen, das muesste man in deinem Modul aendern.

KölnSolar · 19 Juni 2020, 21:12:52

Oh Rudi....
Du hast mir die Augen geöffnet. Anfängerfehler. Dieses Perl killt mich noch.

Am Ablauf des Codes muss ich nichts ändern(denke ich), das passt schon. Hab meinen Fehler gerade korrigiert und funktioniert. Es waren die Benennungen der subs für die InitFn u. CallbackFn. Ich vermute, dass Du als Profi das vermeidest, indem Du gerne die Subs im "laufenden" coding definierst. Ich find das nur immer wieder, weil auch anders gewohnt, fürchterlich zum lesen.

Vielen, vielen lieben Dank.

KölnSolar · 20 Juni 2020, 21:50:30

Hi Rudi,
erst einmal nur zur Info: das war es doch nicht.

Wie ich schon sagte: geht/geht_nicht

Es muss irgendwie mit etwas gepuffertem zusammenhängen, denn wenn ich das initiale open beim define oder nach einem enable_device(also nach vorherigem disable) mache, klappt es. Da aber die Verbindung immer mal nach ein paar Stunden abbricht(ohne, dass FHEM es merkt

), habe ich ein reopen eingebaut. Nix besonderes, ein DevIo_Close und dann ein open hinterher, aber da tritt das Symptom dann auf.

Ich such mal weiter.....

Grüße Markus

rudolfkoenig · 20 Juni 2020, 22:31:56

Der Client kann (wie in meinem Beispiel) auch ein regelmaessiges Ping absenden, damit muesste ein Verbindungsabbruch auffallen. Wenn das nicht reicht, koennten wir die Antwort per Timer ueberwachen.

KölnSolar · 20 Juni 2020, 23:13:39

ZitatDer Client kann (wie in meinem Beispiel) auch ein regelmaessiges Ping absenden

Ich schreibe(get data) bereits mit einem 60s-timer. Nur bekomme ich irgendwann keine Antwort mehr.

ZitatWenn das nicht reicht, koennten wir die Antwort per Timer ueberwachen.

Genau das mache ich(bzw. ähnlich).

Das reopen-Flag dürfte keine Rolle spielen, oder ? $:-\$ Ich mache ja einen close der abgebrochenen Verbindung und das (re-)open dann mit reopenflag=0. Und dass ich eine InitFn(im Gegensatz zu Deinem Bsp.) im open übergebe, doch sicherlich auch nicht.

KölnSolar · 22 Juni 2020, 17:49:59

Hi Rudi,
ich glaube(mal wieder

) ich bin dem Fehler näher auf die Spur gekommen. Ich habe mir mal %readyfnlist zur Brust genommen. Und da sah ich zufällig ZWEI Einträge mit unterschiedlichen keys

Code Auswählen

2020.06.22 16:09:05 3: [EE2] - readyFn-entry - devicename: sol, DeviceName: ws:localDomain.de:9124, Key: sol.localDomain.de:9124
2020.06.22 16:09:05 3: [EE2] - readyFn-entry - devicename: sol, DeviceName: ws:localDomain.de:9124, Key: sol.ws:localDomain.de:9124

Ich spekuliere mal, dass das hier in DevIo_Open falsch läuft:

ZitatDevIo_OpenDev
.
.
} elsif($dev =~ m,^(ws:|wss:)?([^/:]+)[0-9]+)(.*?)$,) {# TCP or websocket
my ($proto, $host, $port, $path) = ($1 ? $1 : "", $2, $3, $4);
$dev = "$host:$port";
if($proto eq "wss:") {
$hash->{SSL} = 1;
$proto = "ws:";
}
if($proto eq "ws:") {
require MIME::Base64;
return &$doCb('websocket is only supported with callback') if(!$callback);
}
$path = "/" if(!defined($path) || $path eq "");

# This part is called every time the timeout (5sec) is expired _OR_
# somebody is communicating over another TCP connection. As the connect
# for non-existent devices has a delay of 3 sec, we are sitting all the
# time in this connect. NEXT_OPEN tries to avoid this problem.
if($hash->{NEXT_OPEN} && time() < $hash->{NEXT_OPEN}) {
return &$doCb(undef); # Forum 53309
}

delete($readyfnlist{"$name.$dev"});

my $timeout = $hash->{TIMEOUT} ? $hash->{TIMEOUT} : 3;

# Do common TCP/IP "afterwork":
# if connected: set keepalive, fill selectlist, FD, TCPDev.
# if not: report the error and schedule reconnect
my $doTcpTail = sub($) {
my ($conn) = @_;
if($conn) {
delete($hash->{NEXT_OPEN});
$conn->setsockopt(SOL_SOCKET, SO_KEEPALIVE, 1) if(defined($conn));

} else {
Log3 $name, 1, "$name: Can't connect to $dev: $!" if(!$reopen && $!);
$readyfnlist{"$name.$dev"} = $hash;
DevIo_setStates($hash, "disconnected");
DoTrigger($name, "DISCONNECTED") if(!$reopen);
$hash->{NEXT_OPEN} = time() + $nextOpenDelay;
return 0;
}

$hash->{WEBSOCKET} = 1 if($proto eq "ws:");
$hash->{TCPDev} = $conn;
$hash->{FD} = $conn->fileno();
$hash->{CD} = $conn;
$selectlist{"$name.$dev"} = $hash;
return 1;
};

in DevIo_Close u. DevIo_Disconnected wird mit $hash->{DeviceName} auf die readyfnlist zugegriffen.

Grüße Markus

Edit: Die Zeile für die selectlist hab ich noch ergänzt. Bei mir läuft eine Version, in der ich $dev durch $hash->{DeviceName} ersetzt habe. Bei EE2 warte ich auf den nächsten disconnect(spätestens um 3 Uhr, wenn meine IP neu zugewiesen wird). Das SamsungAV wirkt auf den ersten Blick "gefälliger".

rudolfkoenig · 23 Juni 2020, 10:34:19

Danke fuer den Hinweis, $dev bei wss zu "fixen" war in der Tat ein Fehler.

Ich habe DevIo.pm geaendert und eingecheckt. Ich habe mein wstest.pm im alten Posting auch aktualisiert, und damit und mit dem geaenderten DevIo.pm das reconnect erfolgreich getestet, gegen eine zweite FHEM-Instanz.

KölnSolar · 24 Juni 2020, 07:15:05

Hi Rudi,
da bin ich ja jetzt froh, dass mein Gesülze der letzten Tage dann doch einen Fehlerhintergrund hatte.

Heute Nacht hatte ich disconnects u. die wurden auch brav durch reopen gelöst. Da ich den logelevel niedrig hatte, konnte ich nicht sehen, ob "das System" den Verbindungsabbruch bemerkt hat oder meine eigene Funktion(zyklische Prüfung, ob der Server noch pingt). Das checke ich noch. Das SamsungAV macht noch Probleme, aber vermutlich hab ich da noch einen Bug drin.

Danke&Grüße Markus

btw., was passiert eigentlich technisch genau beim nonblocking-get ? Wird da auch ein Child-Prozess wie beim Blocking-Call eröffnet ?