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

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

Vorheriges Thema - Nächstes Thema

P.A.Trick

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:


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?
Cubietruck,RPI,QNAP Ts-419p+, FS20, FRITZ!DECT200, 7 MAX! Thermostate, 3 MAX! Fensterkontakte, Kodi, CUL V3.3, EM1000S, LW12, LD382, HUE, HM-CFG-USB-2, 1x HM-LC-SW1-FM, 2x HM-LC-SW2-FM, 2x HM-LC-Sw1PBU-FM, 3xHM-LC-Bl1PBU-FM,HM-SEC-RHS, 2xHM-SEC-SD,HM-WDS30-T-O, 3x HM-LC-Dim1TPBU-FM, RPI+AddOn

justme1968

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?
hue, tradfri, alexa-fhem, homebridge-fhem, LightScene, readingsGroup, ...

https://github.com/sponsors/justme-1968

P.A.Trick

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

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
Cubietruck,RPI,QNAP Ts-419p+, FS20, FRITZ!DECT200, 7 MAX! Thermostate, 3 MAX! Fensterkontakte, Kodi, CUL V3.3, EM1000S, LW12, LD382, HUE, HM-CFG-USB-2, 1x HM-LC-SW1-FM, 2x HM-LC-SW2-FM, 2x HM-LC-Sw1PBU-FM, 3xHM-LC-Bl1PBU-FM,HM-SEC-RHS, 2xHM-SEC-SD,HM-WDS30-T-O, 3x HM-LC-Dim1TPBU-FM, RPI+AddOn

netbus

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

P.A.Trick

Cubietruck,RPI,QNAP Ts-419p+, FS20, FRITZ!DECT200, 7 MAX! Thermostate, 3 MAX! Fensterkontakte, Kodi, CUL V3.3, EM1000S, LW12, LD382, HUE, HM-CFG-USB-2, 1x HM-LC-SW1-FM, 2x HM-LC-SW2-FM, 2x HM-LC-Sw1PBU-FM, 3xHM-LC-Bl1PBU-FM,HM-SEC-RHS, 2xHM-SEC-SD,HM-WDS30-T-O, 3x HM-LC-Dim1TPBU-FM, RPI+AddOn

Loctotex

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

P.A.Trick

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 :-/
Cubietruck,RPI,QNAP Ts-419p+, FS20, FRITZ!DECT200, 7 MAX! Thermostate, 3 MAX! Fensterkontakte, Kodi, CUL V3.3, EM1000S, LW12, LD382, HUE, HM-CFG-USB-2, 1x HM-LC-SW1-FM, 2x HM-LC-SW2-FM, 2x HM-LC-Sw1PBU-FM, 3xHM-LC-Bl1PBU-FM,HM-SEC-RHS, 2xHM-SEC-SD,HM-WDS30-T-O, 3x HM-LC-Dim1TPBU-FM, RPI+AddOn

Loctotex

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.

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.

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



justme1968

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

stacktraceAsString(1) oder stacktrace() sollten helfen.
hue, tradfri, alexa-fhem, homebridge-fhem, LightScene, readingsGroup, ...

https://github.com/sponsors/justme-1968

Loctotex

#9
na klar,
stacktraceAsString(1) liefert mir:
HUEBridge_HTTP_Call2:1707 HUEBridge_Call:1250 HUEBridge_GetUpdate:3342 HandleTimeout:677

Das kommt von hier:
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?

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

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 ?

hue, tradfri, alexa-fhem, homebridge-fhem, LightScene, readingsGroup, ...

https://github.com/sponsors/justme-1968

Loctotex

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


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.
hue, tradfri, alexa-fhem, homebridge-fhem, LightScene, readingsGroup, ...

https://github.com/sponsors/justme-1968

Loctotex

#13
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?
if( defined($config->{websocketport}) && !defined($hash->{CD}) ) {
    $hash->{websocketport} = $config->{websocketport};
    HUEBridge_openWebsocket($hash);
  }

justme1968

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.
hue, tradfri, alexa-fhem, homebridge-fhem, LightScene, readingsGroup, ...

https://github.com/sponsors/justme-1968