HUE Dimmer Switch schaltet/wiederholt manchmal letzten Befehl

Begonnen von popy, 04 Januar 2019, 20:42:40

Vorheriges Thema - Nächstes Thema

popy

@justme1968:
Ich habe den sporadischen Fehler ;)
Siehe Log:


2019.01.11 23:06:58 4: parse status message for DIM_VR_Master_Dimmer
2019.01.11 23:06:58 5: $VAR1 = {
          'type' => 'ZLLSwitch',
          'config' => {
                        'reachable' => bless( do{\(my $o = 1)}, 'JSON::PP::Boolean' ),
                        'on' => $VAR1->{'config'}{'reachable'},
                        'pending' => [],
                        'battery' => 100
                      },
          'swversion' => '5.45.1.17846',
          'state' => {
                       'lastupdated' => '2019-01-07T20:09:46',
                       'buttonevent' => 4002
                     },
          'manufacturername' => 'Philips',
          'uniqueid' => '00:17:88:01:04:ef:29:44-02-fc00',
          'name' => 'Schalter Eingang',
          'modelid' => 'RWL021'
        };

2019.01.11 23:06:58 4: DIM_VR_Master_Dimmer: offsetUTC: 3600
2019.01.11 23:06:58 4: using HttpUtils_NonblockingGet: GET sensors/5
2019.01.11 23:06:58 4: using HttpUtils_NonblockingGet: GET sensors/8
2019.01.11 23:06:58 4: using HttpUtils_NonblockingGet: GET sensors/11
2019.01.11 23:06:58 4: using HttpUtils_NonblockingGet: GET sensors/14
2019.01.11 23:06:58 4: using HttpUtils_NonblockingGet: GET sensors/17
2019.01.11 23:06:58 4: using HttpUtils_NonblockingGet: GET sensors/20
2019.01.11 23:06:58 4: using HttpUtils_NonblockingGet: GET
2019.01.11 23:06:59 4: using HttpUtils_NonblockingGet: GET sensors/22
2019.01.11 23:06:59 4: using HttpUtils_NonblockingGet: GET sensors/5
2019.01.11 23:06:59 4: using HttpUtils_NonblockingGet: GET sensors/8
2019.01.11 23:06:59 4: using HttpUtils_NonblockingGet: GET sensors/11
2019.01.11 23:06:59 4: using HttpUtils_NonblockingGet: GET sensors/14
2019.01.11 23:06:59 4: using HttpUtils_NonblockingGet: GET sensors/17
2019.01.11 23:06:59 4: using HttpUtils_NonblockingGet: GET sensors/20
2019.01.11 23:06:59 2: hueBridge1: http request failed: http://192.168.0.2/api/MIMTbOjbs1GqHvrK68SHhIQoeKtCVIwrMx7JOlB7/sensors/20: empty answer received
2019.01.11 23:06:59 4: parse status message for hueBridge1
2019.01.11 23:06:59 4: hueBridge1: message for unknow sensor received: hueBridge1-S1
2019.01.11 23:06:59 4: hueBridge1: message for unknow sensor received: hueBridge1-S13
2019.01.11 23:07:00 4: parse status message for DIM_VR_Master_Dimmer
2019.01.11 23:07:00 5: $VAR1 = {
          'state' => {
                       'buttonevent' => 4002,
                       'lastupdated' => '2019-01-07T20:09:46'
                     },
          'manufacturername' => 'Philips',
          'uniqueid' => '00:17:88:01:04:ef:29:44-02-fc00',
          'type' => 'ZLLSwitch',
          'config' => {
                        'reachable' => bless( do{\(my $o = 1)}, 'JSON::PP::Boolean' ),
                        'on' => $VAR1->{'config'}{'reachable'},
                        'pending' => [],
                        'battery' => 100
                      },
          'swversion' => '5.45.1.17846',
          'name' => 'Schalter Eingang',
          'modelid' => 'RWL021'
        };

2019.01.11 23:07:00 4: DIM_VR_Master_Dimmer: offsetUTC: 3601
2019.01.11 23:07:00 4: DIM_VR_Master_Dimmer: lastupdated: 2019-01-07 21:09:47, hash->{lastupdated}:  2019-01-07 21:09:46
2019.01.11 23:07:00 5: DIM_VR_Master_Dimmer: $VAR1 = {
          'state' => {
                       'buttonevent' => 4002,
                       'lastupdated' => '2019-01-07T20:09:46'
                     },
          'manufacturername' => 'Philips',
          'uniqueid' => '00:17:88:01:04:ef:29:44-02-fc00',
          'type' => 'ZLLSwitch',
          'config' => {
                        'reachable' => bless( do{\(my $o = 1)}, 'JSON::PP::Boolean' ),
                        'on' => $VAR1->{'config'}{'reachable'},
                        'pending' => [],
                        'battery' => 100
                      },
          'swversion' => '5.45.1.17846',
          'name' => 'Schalter Eingang',
          'modelid' => 'RWL021'
        };

2019.01.11 23:07:00 1: act_on_Master: EVENT TO DEBUG: 4002 !!!!!!!!!!!!!!!!!!!!! HIER SCHAUEN!!!!!!!!


Das offsetUTC des Helpers ändert sich um eine Sekunde!

Vorher: 2019.01.11 23:06:58 4: DIM_VR_Master_Dimmer: offsetUTC: 3600
Problem: 2019.01.11 23:07:00 4: DIM_VR_Master_Dimmer: offsetUTC: 3601

Somit wäre das Problem auch gelöst wenn das Modul nicht mit der lokalzeit in lastupdated arbeiten würde sondern mit der UTC.
Was sagst du dazu?

pOpY

justme1968

sorry. fürs nicht melden.

ich möchte erst noch die alexa geschichte fertig machen. dann schaue ich mir dein problem in ruhe an.
hue, tradfri, alexa-fhem, homebridge-fhem, LightScene, readingsGroup, ...

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

popy

Zitat von: justme1968 am 12 Januar 2019, 11:41:05
sorry. fürs nicht melden.

ich möchte erst noch die alexa geschichte fertig machen. dann schaue ich mir dein problem in ruhe an.

Kein Thema.
Habe mich mal selbst an die Arbeit gemacht und folgendes realisiert:

  • readings werden nur übernommen wenn internal lastupdated sich ändert -> Somit ist das Problem beim starten weg und auch wenn sich offsetUTC um eine Sekunden ändert (sporadischer Fall)
  • Damit die angezeigten Zeiten die Lokalzeiten sind, habe ich folgendes gemacht

    • ist noch kein offsetUTC von der bridge vorhanden wird der lokale verwendet -> egal wenn es anders wäre als bei der bridge da es nur um die Anzeige geht
    • ist ein offsetUTC von der bridge vorhanden wird dies verwendet -> egal wenn sich dieses nun um 1 Sekunde ändert da es nur um die Anzeige geht
    • das ganze wird als internal/reading lastupdated_local verwaltet/gespeichert

Kannst du Bitte mal über den Code/Patch schauen, da ich in perl nicht so bewandert bin.
Meine ersten Tests schauen vielversprechend aus, nach dem Neustart wird nixhts ausgelöst, Sporadischer Langzeittest läuft....

Angehängt die Files.
Ausgegangen bin ich von der aktuellen Version (heute ein Update gemacht).

Zitat von: inoma am 11 Januar 2019, 22:22:14
Ich habe das gleich bei mir auch beobachtet, nach dem neustart von FHEM wird immer zumindest bei einem Hue Dimmer einmal ein Event ausgelöst. Nachdem ich den Thread gelesen habe, ist die Ursache anscheinend gefunden. Also popy ist nicht der Einzige wo das auftritt. Beste Grüsse und schönes Wochenende!

Kannst du diese Version mal testen, also einfach die gepatchte 31_HUEDevice.pm einspielen nach /opt/fhem/FHEM und dann noch "chown fhem:dialout 31_HUEDevice.pm"

pOpY

popy

@justme1968:

Kleines Update, seit ~3,5 Tagen keine einzige Fehlauslösung mit meiner Änderung.
Ich lasse jetzt noch bis Samstag laufen, dann ist es eine Woche ohne Fehlauslösung  ;)

Hattest du schon Zeit dir den Patch anzusehen?
Wo kann ich den einchecken/einreichen?

Danke
pOpY

Jamo

Ich habe gerade eben (heute Abend) deinen Patch eingespielt, und 2 mal shutdown-restart gemacht, ich kann bestätigen das mit dem Patch das event beim restart nicht mehr auftritt. Hier nochmal der Auszug aus dem Logfile von heute morgen, wo der Fehler noch auftritt:
2019.01.15 07:48:36 3: CUL_HM set Alarm_Smoke_SZ statusRequest
2019.01.15 07:48:36 3: HueDimmerKüche1 Event: 4002
2019.01.15 07:48:37 3: CUL_HM set Schalter_HausTuer statusRequest


Allerdings ist das event noch ein einziges mal vor dem ersten Shutdown-restart aufgetreten, und zwar nachdem ich deinen Patch mit 'reload 31_HUEDevice.pm' geladen hatte:
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_Initialize redefined at ./FHEM/31_HUEDevice.pm line 160.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_devStateIcon redefined at ./FHEM/31_HUEDevice.pm line 192.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_summaryFn redefined at ./FHEM/31_HUEDevice.pm line 250.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_Define redefined at ./FHEM/31_HUEDevice.pm line 259.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_Undefine redefined at ./FHEM/31_HUEDevice.pm line 383.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_SetParam redefined at ./FHEM/31_HUEDevice.pm line 398.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_Set redefined at ./FHEM/31_HUEDevice.pm line 613.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine cttorgb redefined at ./FHEM/31_HUEDevice.pm line 850.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine xyYtorgb redefined at ./FHEM/31_HUEDevice.pm line 887.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_Get redefined at ./FHEM/31_HUEDevice.pm line 934.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_ReadFromServer redefined at ./FHEM/31_HUEDevice.pm line 1019.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_GetUpdate redefined at ./FHEM/31_HUEDevice.pm line 1036.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDeviceSetIcon redefined at ./FHEM/31_HUEDevice.pm line 1080.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_Parse redefined at ./FHEM/31_HUEDevice.pm line 1106.
2019.01.15 23:19:00 1: PERL WARNING: Subroutine HUEDevice_Attr redefined at ./FHEM/31_HUEDevice.pm line 1505.
2019.01.15 23:19:01 3: HueDimmerKüche1 Event: 4002
2019.01.15 23:19:04 0: Server shutdown
2019.01.15 23:19:04 1: HMCCURPCPROC: [d_rpcBidCos_RF] Stopping RPC server
Bullseye auf iNUC, Homematic + HMIP(UART/HMUSB), Debmatic, HUEBridge, Zigbee/ConbeeII, FB, Alexa (fhem-lazy), Livetracking, LaCrosse JeeLink, LoRaWan / TTN / Chirpstack

popy

Danke für deine Tests.
Dass es nach dem einspielen und reload einmal aufgetreten ist kann ich erklären  ;)
Die neue Version arbeitet mit lastupdated timestamps auf UTC Basis, also nicht mit der Lokalzeit wie vorher.
Da dein fhem bei allen Geräten als letzten lastupdated Timestamp auf Basis der Lokalzeit gespeichert hatte (alte Version) wurden diese aktualisiert auf den UTC timestamp und das Event je Gerät einmal getriggert.

Jeder weitete Neustart und auch zufälliges Auslösen während der Laufzeit (so wie bei mir) sollte jetzt der Vergangenheit angehören  ;)

Ich werde ich paar Tage testen und mich wieder melden.

Danke
pOpY

Jamo

Heute morgen auch kein Fehler bei 2-maligem restart. Scheint wirklich gut zu funktionieren.
Bullseye auf iNUC, Homematic + HMIP(UART/HMUSB), Debmatic, HUEBridge, Zigbee/ConbeeII, FB, Alexa (fhem-lazy), Livetracking, LaCrosse JeeLink, LoRaWan / TTN / Chirpstack

popy

Zitat von: inoma am 16 Januar 2019, 08:54:21
Heute morgen auch kein Fehler bei 2-maligem restart. Scheint wirklich gut zu funktionieren.

Danke für Deine positive Rückmeldung.
Warten wir mal auf @justme1968 bis er Zeit hat  ;)

lg
pOpY

Jamo

Bisher ist der Fehler nicht wieder augetreten, ich denke mal dein Patch funktioniert, und könnte übernommen werden.
Bullseye auf iNUC, Homematic + HMIP(UART/HMUSB), Debmatic, HUEBridge, Zigbee/ConbeeII, FB, Alexa (fhem-lazy), Livetracking, LaCrosse JeeLink, LoRaWan / TTN / Chirpstack

popy

Zitat von: inoma am 18 Januar 2019, 11:35:29
Bisher ist der Fehler nicht wieder augetreten, ich denke mal dein Patch funktioniert, und könnte übernommen werden.

Danke für die Info.
Auch bei mir bis jetzt kein Problem mehr  ;)
Bin mit @justme1968 per PM in Kontakt und er wird sich das Thema nächste Woche ansehen.

pOpY

justme1968

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

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

popy

Zitat von: justme1968 am 22 Januar 2019, 11:53:20
ich habe den patch eingebaut.

danke
  andre

Sprich ein update 31_HUEDevice und ich habe das offiziellen update?

justme1968

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

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

popy


popy

Eingespielt, Änderungen sind drinnen und funktionieren.

Danke