(gelöst) deCONZ <-> HUE Bridge : Abbruch der Websocket Verbindung

P.A.Trick · 05 Februar 2020, 17:13:00

Im FHEM Log finde ich einen ganzen Haufen voll der folgenden Meldung:

2020.02.05 17:02:08.778 3: deCONZ: websocket: Switching Protocols ok
2020.02.05 17:02:08.707 3: deCONZ: websocket opened to 192.168.1.119:8443
2020.02.05 17:01:08.768 3: deCONZ: websocket: Switching Protocols ok
2020.02.05 17:01:08.705 3: deCONZ: websocket opened to 192.168.1.119:8443
2020.02.05 17:00:08.776 3: deCONZ: websocket: Switching Protocols ok
2020.02.05 17:00:08.703 3: deCONZ: websocket opened to 192.168.1.119:8443
2020.02.05 16:59:08.795 3: deCONZ: websocket: Switching Protocols ok
2020.02.05 16:59:08.729 3: deCONZ: websocket opened to 192.168.1.119:8443

Nach kurzem Studium des Codes bin ich zum Schluss gekommen, dass mir das zu "hoch" ist.
Auf der deCONZ Seite wird nur die Meldung ausgegeben:

Code Auswählen


15:06:07:399 Remove websocket 192.168.1.101:33080 after error Unknown error

Im Forum konnte ich nichts brauchbares finden, außer das man den verbose Level nutzen soll um
die Events zu verstecken. Das finde ich aber eher suboptimal, da dadruch u.U. andere Meldungen verloren gehen.

Deshalb meine Frage: kann ich bei der Fehleranalyse helfen?

justme1968 · 05 Februar 2020, 17:33:18

wenn die verbindung jede minute neu aufgebaut wird stimmt etwas nicht.

wenn die verbindung von fhem aus zu gemacht wird sollte mehr im log stehen. siehst du mit verbose 5 mehr?

kann man auf deCONZ seite mehr rausfinden?

P.A.Trick · 05 Februar 2020, 17:38:33

Im Log sehe ich nicht wirklich mehr. Das die Lampen nicht erreichbar sind ist mMn kein Problem, es tritt immer auf.

Code Auswählen

020.02.05 17:27:09.125 3: deCONZ: websocket: Switching Protocols ok
2020.02.05 17:27:09.069 4: deCONZ: message for unknown sensor received: deCONZ-S10
2020.02.05 17:27:09.061 3: deCONZ: websocket opened to 192.168.1.119:8443
2020.02.05 17:27:09.058 4: parse status message for deCONZ
2020.02.05 17:27:09.018 4: using HttpUtils_NonblockingGet: GET 

        };
                     }
                       'alert' => undef
                       'reachable' => $VAR1->{'state'}{'on'},
                       'ct' => 153,
                       'colormode' => 'xy',
                       'on' => bless( do{\(my $o = 1)}, 'JSON::XS::Boolean' ),
                       'hue' => 0,
                       'bri' => 254,
                       'sat' => 254,
                               ],
                                 '0.3083'
                                 '0.6915',
                       'xy' => [
          'state' => {
          'r' => 'lights',
          'uniqueid' => '00:17:88:01:04:2f:9a:f0-0b',
          'id' => '5',
          't' => 'event',
          'e' => 'changed',
2020.02.05 17:26:37.213 5: deCONZ: websocket data: $VAR1 = {
2020.02.05 17:26:37.211 1: >>>{"e":"changed","id":"5","r":"lights","state":{"alert":null,"bri":254,"colormode":"xy","ct":153,"hue":0,"on":true,"reachable":true,"sat":254,"xy":[0.6915,0.3083]},"t":"event","uniqueid":"00:17:88:01:04:2f:9a:f0-0b"}<<<
2020.02.05 17:26:37.203 3: resource, /lights/3, not available
2020.02.05 17:26:37.202 3: resource, /lights/3, not available
2020.02.05 17:26:37.001 4: using HttpUtils_NonblockingGet: PUT lights/5/state
2020.02.05 17:26:36.997 4: using HttpUtils_NonblockingGet: PUT lights/3/state
2020.02.05 17:26:24.091 4: using HttpUtils_NonblockingGet: GET groups/11

Auf der deCONZ sehe ich auch nichts. Ich vermute aber, dass es ein deCONZ Problem ist. Siehe dazu:

https://github.com/dresden-elektronik/deconz-rest-plugin/issues/2422

netbus · 02 Mai 2020, 09:42:58

Hi,
Ich habe das selbe Problem. Hast du schon eine Lösung?

P.A.Trick · 02 Mai 2020, 10:09:24

Zitat von: netbus am 02 Mai 2020, 09:42:58
Hi,
Ich habe das selbe Problem. Hast du schon eine Lösung?

Nein der Request immer noch unbearbeitet!

https://github.com/dresden-elektronik/deconz-rest-plugin/issues/2422

Loctotex · 10 Dezember 2020, 18:24:13

Hi, ich habe das auch alle 10 Minuten. Habt ihr das lösen können?

P.A.Trick · 11 Dezember 2020, 11:01:13

Zitat von: Loctotex am 10 Dezember 2020, 18:24:13
Hi, ich habe das auch alle 10 Minuten. Habt ihr das lösen können?

Nein leider nicht. Ich habe das verbose auf 2 gesetzt :-/

Loctotex · 12 Dezember 2020, 14:43:08

In der 30_HUEBridge.pm kommt es in der sub HUEBridge_HTTP_Call2($$$$;$) vor, dass der path fehlt. Das scheint nicht beabsichtigt zu sein. Direkt danach ist die Verbindung weg.

Code Auswählen

2020.12.12 13:30:28 4: using HttpUtils_NonblockingGet: GET lights
2020.12.12 13:30:38 4: using HttpUtils_NonblockingGet: GET 
2020.12.12 13:30:38 4: parse status message for deCONZ
2020.12.12 13:30:38 3: deCONZ: websocket opened to 192.168.0.51:443
2020.12.12 13:30:38 4: deCONZ: message for unknown sensor received: deCONZ-S2
2020.12.12 13:30:38 4: deCONZ: message for unknown sensor received: deCONZ-S1
2020.12.12 13:30:38 3: deCONZ: websocket: Switching Protocols ok
2020.12.12 13:30:48 4: using HttpUtils_NonblockingGet: GET lights
2020.12.12 13:30:58 4: using HttpUtils_NonblockingGet: GET lights

Wenn ich das in Zeile 1804 so Abfange läuft es ohne Abbrüche.

Code Auswählen

 if(!defined($path) || $path eq ''){
	   Log3 $name, 4, "HUEBridge_HTTP_Call2: Warning, path is empty.";
	   return undef;
  }

justme1968 · 12 Dezember 2020, 16:51:50

kannst du bitte mal versuchen rauszufinden wo der problematische aufruf her kommt?

stacktraceAsString(1) oder stacktrace() sollten helfen.

Loctotex · 13 Dezember 2020, 11:40:30

na klar,
stacktraceAsString(1) liefert mir:

Code Auswählen

HUEBridge_HTTP_Call2:1707 HUEBridge_Call:1250 HUEBridge_GetUpdate:3342 HandleTimeout:677

Das kommt von hier:

Code Auswählen

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

  if(!$hash->{LOCAL}) {
    RemoveInternalTimer($hash);
    InternalTimer(gettimeofday()+$hash->{INTERVAL}, "HUEBridge_GetUpdate", $hash, 0);
  }

  if( $hash->{websocketport} && !$hash->{PORT} ) {
    HUEBridge_openWebsocket($hash);
  }

  my $type;
  my $result;
  my $poll_devices = AttrVal($name, "pollDevices", 1);
  if( $poll_devices ) {
    my ($now) = gettimeofday();
    if( $poll_devices > 1 || $hash->{LOCAL} || $now - $hash->{helper}{last_config_timestamp} > 300 ) {
      $result = HUEBridge_Call($hash, $hash, undef, undef);

$now - $hash->{helper}{last_config_timestamp} ist in dem Fall größer 300. Meist 310
Ich habe mir mal die Werte ausgeben lassen: muss das mit dem Timestamp so?

Code Auswählen

2020.12.13 11:46:07 4: pollDevices: 1 hashLocal:  now-Timestamp: 290
2020.12.13 11:46:07 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:46:17 4: pollDevices: 1 hashLocal:  now-Timestamp: 300
2020.12.13 11:46:17 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:46:27 4: pollDevices: 1 hashLocal:  now-Timestamp: 310
2020.12.13 11:46:27 4: HUEBridge_HTTP_Call2: Warning, path is empty.
2020.12.13 11:46:27 4:  HUEBridge_HTTP_Call2:1710 HUEBridge_Call:1253 HUEBridge_GetUpdate:3342 HandleTimeout:677
2020.12.13 11:46:37 4: pollDevices: 1 hashLocal:  now-Timestamp: 10
2020.12.13 11:46:37 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:46:47 4: pollDevices: 1 hashLocal:  now-Timestamp: 20
2020.12.13 11:46:47 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:46:57 4: pollDevices: 1 hashLocal:  now-Timestamp: 30
2020.12.13 11:46:57 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:47:07 4: pollDevices: 1 hashLocal:  now-Timestamp: 40
2020.12.13 11:47:07 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:47:17 4: pollDevices: 1 hashLocal:  now-Timestamp: 50
2020.12.13 11:47:17 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:47:27 4: pollDevices: 1 hashLocal:  now-Timestamp: 60
2020.12.13 11:47:27 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:47:37 4: pollDevices: 1 hashLocal:  now-Timestamp: 70
2020.12.13 11:47:37 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:47:47 4: pollDevices: 1 hashLocal:  now-Timestamp: 80
2020.12.13 11:47:47 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:47:57 4: pollDevices: 1 hashLocal:  now-Timestamp: 90
2020.12.13 11:47:57 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:48:07 4: pollDevices: 1 hashLocal:  now-Timestamp: 100
2020.12.13 11:48:07 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:48:17 4: pollDevices: 1 hashLocal:  now-Timestamp: 110
2020.12.13 11:48:17 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:48:27 4: pollDevices: 1 hashLocal:  now-Timestamp: 120
2020.12.13 11:48:27 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:48:37 4: pollDevices: 1 hashLocal:  now-Timestamp: 130
2020.12.13 11:48:37 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:48:47 4: pollDevices: 1 hashLocal:  now-Timestamp: 140
2020.12.13 11:48:47 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:48:57 4: pollDevices: 1 hashLocal:  now-Timestamp: 150
2020.12.13 11:48:57 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:49:07 4: pollDevices: 1 hashLocal:  now-Timestamp: 160
2020.12.13 11:49:07 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:49:17 4: pollDevices: 1 hashLocal:  now-Timestamp: 170
2020.12.13 11:49:17 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:49:27 4: pollDevices: 1 hashLocal:  now-Timestamp: 180
2020.12.13 11:49:27 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:49:37 4: pollDevices: 1 hashLocal:  now-Timestamp: 190
2020.12.13 11:49:37 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:49:47 4: pollDevices: 1 hashLocal:  now-Timestamp: 200
2020.12.13 11:49:47 4: using HttpUtils_NonblockingGet: GET lights
2020.12.13 11:49:57 4: pollDevices: 1 hashLocal:  now-Timestamp: 210
2020.12.13 11:49:57 4: using HttpUtils_NonblockingGet: GET lights

Das Interval beim define hatte ich testweise auf 10 gesetzt.

justme1968 · 13 Dezember 2020, 18:14:49

das modul holt im intervall abstand den status aller lampen ab. und zusätzlich alle 5 minuten den status der bridge selber. den bekommt man eigentlich in dem man direkt auf oberster ebene abfragt. d.h. ohne path.

wie es scheint mag deconz letzteres nicht (mehr ?).

was sagt deconz wenn du mit dem browser auf https://<ip>/api/<key>/ gehst? macht es einen unterschied wenn du den letzten / weg lässt. siehst du eventuell bei einem oder beidem den abbruch im deconz log ?

Loctotex · 13 Dezember 2020, 19:30:26

Deconz kann so weit ich weiß kein https. Bei mir funktioniert auch nur http.

http://<ip>/api/<key>/ funktioniert genauso wie http://<ip>/api/<key> im Browser und liefert mit den Staus der Bridge. Logfile von Deconz muss ich erst aktivieren, lifere ich morgen nach.

justme1968 · 14 Dezember 2020, 14:12:11

also wenn die abfrage per browser geht und per modul nicht habe ich auf die schnelle keine idee ausser das du bitte noch mal schaust ob es tatsächlich die gleiche abfrage ist.

Loctotex · 14 Dezember 2020, 17:19:48

Status der Bridge holen funktioniert.
HttpUtils_NonblockingGet ruft als Callback HUEBridge_dispatch auf.

Von dort wird HUEBridge_Parse aufgerufen. Von da gehts nach HUEBridge_fillBridgeInfo.

HUEBridge_fillBridgeInfo ruft HUEBridge_openWebsocket wenn $config->{websocketport} gesetzt ist.

Hier müsste doch eigentlich geschaut werden ob es schon eine Verbindung gibt oder nicht?
Sowas in etwa?

Code Auswählen

 if( defined($config->{websocketport}) && !defined($hash->{CD}) ) {
    $hash->{websocketport} = $config->{websocketport};
    HUEBridge_openWebsocket($hash);
  }

justme1968 · 14 Dezember 2020, 17:33:56

HUEBridge_openWebsocket schlisst vorher die alte verbindung mit HUEBridge_closeWebsocket. das ist aber ein normaler verbindungsabbau der keine probleme machen sollte. da in HUEBridge_closeWebsocket auch alles gelöscht wird was mit dem websocket zu tun hat kann danach garnicht mehr die read routine aufgerufen geschweige denn daraus gelesen werden.

die bisherigen log eintrage und auch der code der auf deconz dazugehört deutet darauf h in das die verbindung von deconz seite zugemacht wird. ich weiss nur nicht warum.

irgendein puzzle stück fehlt noch und wir haben noch nicht diese ursache gefunden.