HUE Dimmer Switch schaltet/wiederholt manchmal letzten Befehl

[popy]

Hallo Zusammen.

Habe mir mal zum testen einen HUE Dimmer Switch in fhem angelegt und will ihn als Master OFF Schalter der Wohnung nutzen.
Lt. Wiki (https://wiki.fhem.de/wiki/HUE_Dimmer_Switch) angelegt:

Code Auswählen Erweitern


defmod DIM_VR_Master_Dimmer HUEDevice sensor 22 1 IODev=hueBridge1
attr DIM_VR_Master_Dimmer userattr initialized
attr DIM_VR_Master_Dimmer IODev hueBridge1
attr DIM_VR_Master_Dimmer alias Master Aus Schalter
attr DIM_VR_Master_Dimmer group Vorraum
attr DIM_VR_Master_Dimmer icon taster_ch
attr DIM_VR_Master_Dimmer room System


und auch das notify:

Code Auswählen Erweitern


DIM_VR_Master_Dimmer:.00.* {

  #ignore first state change?
  if(AttrVal($NAME,"initialized","0") eq "1")
  {
fhem("deleteattr ".$NAME." initialized");
#Log 1, "act_on_Master: Ignore first state change to: ".$EVENT;  
return;
  }

  #Welche Taste wurde gedrückt
  if(substr($EVENT, 0, 1) eq "1")
  {
#Ein wurde gedrückt
Log 1, "act_on_Master: Ein gedrückt -> Schalte Vorraum ein!";
fhem("set VR_Decke on ;");
  }
  if(substr($EVENT, 0, 1) eq "2")
  {
#Dim-Up wurde gedrückt
Log 1, "act_on_Master: Dim-UP gedrückt -> Schalte Vorraum ein!";
fhem("set VR_Decke on ;");
  }
  if(substr($EVENT, 0, 1) eq "3")
  {
#Dim-Down wurde gedrückt
Log 1, "act_on_Master: Dim-DOWN gedrückt -> Schalte Vorraum aus!";
fhem("set VR_Decke off ;");
  }
  if(substr($EVENT, 0, 1) eq "4")
  {
#Aus wurde gedrückt
Log 1, "act_on_Master: Aus gedrückt -> Alles Aus!";
fhem("set A_Szenen scene Aus ;");
  }
}


Intervall ist auf 1 und die Reaktionszeit ok und es funktioniert alles.

Leider kommt es vor dass der Schalter auf einmal den letzten Befehl wiederholt sendet.
Das ist natürlich beim 400.* = Master aus für die Wohnung nicht so toll, da die komplette Wohnung abgeschaltet wird.
Das ganze ist z.B.: Heute wieder 2x passiert, es hat sicher keiner gedrückt bzw. es war keiner in der Nähe des Schalters.

Verwendet die Dimmer von euch jemand?
Hat jemand das gleiche Problem bzw. vll. eine Lösung?

PS.: Wollte nicht den alten Thread (https://forum.fhem.de/index.php/topic,50991.0.html) rauskramen.
Vll. hat @Kai-Uwe eine Idee?

Danke
pOpY

[popy]

Heute schon wieder passiert, keiner eine Idee?

[popy]

Es passiert auch wenn fhem neugestartet wird (shutdown restart).
Hier noch so ein Problem: https://forum.fhem.de/index.php/topic,71043.0.html

pOpY

[justme1968]

häng mal ein log mit verbose 5 an wenn das problem auftritt

[popy]

häng mal ein log mit verbose 5 an wenn das problem auftritt

Hallo.

Nur von dem HUEDevice oder vom IODev?
Tritt immer beim Neustart auf bzw. sonst so alle paar Tage.

Update: Habe das HUEDevice auf verbose 5 -> das wird die SD Card aber nicht lange machen bei 1 Sec poll Zeit

pOpY

[popy]

@justme1968:

Wie läuft das eigentlich im Modul? Wird der Timestamp des zuletzt empfangen Events gespeichert und nur wenn sich dieser ändert gibt es ein fhem event?

Gesendet von meinem ONEPLUS A6013 mit Tapatalk

[justme1968]

vom hue device und vom iodevice.

du kannst ja schon mal zeigen wie es beim neustart ausschaut.


der sensor sendet einen zeitstempel, ein event wird nur erzeugt wenn der zeitstempel vom neuen event ungleich dem alten ist.

[popy]

vom hue device und vom iodevice.

du kannst ja schon mal zeigen wie es beim neustart ausschaut.


der sensor sendet einen zeitstempel, ein event wird nur erzeugt wenn der zeitstempel vom neuen event ungleich dem alten ist.

ok danke für die Info habe ein Log gemacht vom startvorgang, da wird 2x der Button press erkannt, obwohl dieser schon gestern war.
Am besten nach "HIER SCHAUEN" suchen, das ist das notify welches dann die Aktionen triggert.
Hier das Log: https://paste.ubuntu.com/p/VtSRN5ck2V/

Habe es mit Beyond Compare analysiert und das Log bei den beiden notifys verglichen.
Auffällig ist folgendes:

Erster Eintrag:

Code Auswählen Erweitern


2019.01.08 20:18:32 4: DIM_VR_Master_Dimmer: lastupdated: 2019-01-07 20:09:46, hash->{lastupdated}:  [b]2019-01-07 21:09:46[/b]
...
          'state' => {
                       'lastupdated' => '2019-01-07T20:09:46',
                       'buttonevent' => 4002
                     },


Zweiter Eintrag:

Code Auswählen Erweitern


2019.01.08 20:19:22 4: DIM_VR_Master_Dimmer: lastupdated: 2019-01-07 21:09:46, hash->{lastupdated}:  [b]2019-01-07 20:09:46[/b]
...
          'state' => {
                       'lastupdated' => '2019-01-07T20:09:46'
                       'buttonevent' => 4002,
                     }


Es schaut schwer nach localtime & UTC Umrechnungs Problem aus, oder?

2019-01-07 21:09:46 <> 2019-01-07 20:09:46

Obwohl die Daten bei "state" gleich sind (Siehe Log).

Was sagst du dazu?

Das mit dem verbose 5 log bei beiden devices und laufen lassen ist eher schlecht -> jetzt schon über 100MB log in nicht mal einem Tag.

Danke
pOpY

[justme1968]

hast du die zeitzohne auf der bridge gesetzt ?

zeig mal bitte ein list vom bridge device.

[popy]

hast du die zeitzohne auf der bridge gesetzt ?

zeig mal bitte ein list vom bridge device.

Habe die bridge ganz normal mit der hue app laufen.
Wie stellt man da die Zeitzone ein?
Ich glaube aber auch nicht dass es an der Bridge liegt, diese liefert ja in beiden fällen nach dem Neustart den gleichen timestamp im state.
Nur die debug Meldung des huedevices darüber hat einmal die falsche Zeit!?

Hier das list:

Code Auswählen Erweitern




Internals:
   DEF        192.168.0.2 60
   INTERVAL   60
   NAME       hueBridge1
   NOTIFYDEV  global
   NR         59
   NTFY_ORDER 50-hueBridge1
   STATE      connected
   TYPE       HUEBridge
   apiversion 1.16.0
   host       192.168.0.2
   mac        00:17:88:16:8f:30
   manufacturer Royal Philips Electronics
   modelName  Philips hue bridge 2012
   modelid    BSB001
   name       Philips hue
   swversion  01041302
   updatestate 2 [1,2,3]
   zigbeechannel 15
   READINGS:
     2018-12-02 11:04:42   lastError       resource, /groups/7, not available
     2019-01-09 13:38:02   state           connected
     2018-12-17 18:53:55   swupdate        ZGB_100B_0104 - 5.127.1.26420
   helper:
     apiversion 69632
     count      0
     last_config_timestamp 1547037482
     offsetUTC  3600
     updatestate 2
Attributes:
   alias      HUE Bridge
   devStateIcon connected:rc_GREEN:on disconnected:rc_RED:off Initialized:message_socket_disabled
   group      Geräte
   httpUtils  1
   icon       hue_filled_bridge_v1
   key        *******
   noshutdown 1
   pollDevices 2
   room       System
   verbose    1


[justme1968]

laut list hat deine bridge die richtige zeitzone.

ich verstehe nicht ganz was schief geht.

mach mal bitte ein list <device> .lastupdated. den punkt nicht vergessen. wenn es geht direkt nach dem neustart.

ich weiss auch nicht ob das problem beim neustart und zwischendurch wirklich die gleichen sind.

[popy]

laut list hat deine bridge die richtige zeitzone.

ich verstehe nicht ganz was schief geht.

mach mal bitte ein list <device> .lastupdated. den punkt nicht vergessen. wenn es geht direkt nach dem neustart.

ich weiss auch nicht ob das problem beim neustart und zwischendurch wirklich die gleichen sind.

Hier die Ausgaben:

Code Auswählen Erweitern


Vor dem Neustart:                       DIM_VR_Master_Dimmer 2019-01-07 21:09:46    2019-01-07 21:09:46
Direkt nach dem Neustart:               DIM_VR_Master_Dimmer 2019-01-07 20:09:46    2019-01-07 20:09:46
Nachdem die Notifys ausgelöst wurden:   DIM_VR_Master_Dimmer 2019-01-07 21:09:46    2019-01-07 21:09:46


Da stimmt irgendwas mit der Zeitzone nicht beim laden des lastupdated Werts , aber ich glaube eher im Code.
Bei mir ist dass immer, zu 100% nachvollziehbar beim starten vom fhem.
Und nach ca. 1-2 Tage wird der letzte Event erneut ausgeführt, was die Taster unbrauchbar macht.

Bin Gerne für weitere Tests bereit.
Hast du Dimmer im Einsatz/Zuhause?

vll. kann @Hans-Ulrich Tag auch diese Tests machen? Er hatte hier das gleiche Problem: https://forum.fhem.de/index.php?action=post;quote=883406;topic=71043.0

pOpY

[popy]

Kann es sein dass im Code in der 31_HUEDevice.pm an der Stelle vom my lastupdated:

Code Auswählen Erweitern


    my $lastupdated;
    if( my $state = $result->{state} ) {
      $lastupdated = $state->{lastupdated};

      return undef if( !$lastupdated );
      return undef if( $lastupdated eq 'none' );

      substr( $lastupdated, 10, 1, ' ' ) if($lastupdated);

      my $offset = 0;
      if( my $iohash = $hash->{IODev} ) {
        substr( $lastupdated, 10, 1, '_' );
        my $sec = SVG_time_to_sec($lastupdated);

        if( my $offset = $iohash->{helper}{offsetUTC} ) {
          $sec += $offset;
          Log3 $name, 4, "$name: offsetUTC: $offset";
        }

        $lastupdated = FmtDateTime($sec);
      }

      $hash->{lastupdated} = ReadingsVal( $name, '.lastupdated', undef ) if( !$hash->{lastupdated} );
      return undef if( $hash->{lastupdated} && $hash->{lastupdated} eq $lastupdated );
     

    if( my $state = $result->{state} ) {
      $lastupdated = $state->{lastupdated};

      return undef if( !$lastupdated );
      return undef if( $lastupdated eq 'none' );

      substr( $lastupdated, 10, 1, ' ' ) if($lastupdated);

      my $offset = 0;
      if( my $iohash = $hash->{IODev} ) {
        substr( $lastupdated, 10, 1, '_' );
        my $sec = SVG_time_to_sec($lastupdated);

        if( my $offset = $iohash->{helper}{offsetUTC} ) {
          $sec += $offset;
          Log3 $name, 4, "$name: offsetUTC: $offset";
        }

        $lastupdated = FmtDateTime($sec);
      }

      $hash->{lastupdated} = ReadingsVal( $name, '.lastupdated', undef ) if( !$hash->{lastupdated} );
      return undef if( $hash->{lastupdated} && $hash->{lastupdated} eq $lastupdated );

      Log3 $name, 4, "$name: lastupdated: $lastupdated, hash->{lastupdated}:  $hash->{lastupdated}";
      Log3 $name, 5, "$name: ". Dumper $result if($HUEDevice_hasDataDumper);

      $hash->{lastupdated} = $lastupdated;     


Beim Starten von fhem bei der huebridge das offsetUTC noch nicht gelesen wurde und somit 0 ist?
Diese Stelle:

Code Auswählen Erweitern


      my $offset = 0;
      if( my $iohash = $hash->{IODev} ) {
        substr( $lastupdated, 10, 1, '_' );
        my $sec = SVG_time_to_sec($lastupdated);

        if( my $offset = $iohash->{helper}{offsetUTC} ) {
          $sec += $offset;
          Log3 $name, 4, "$name: offsetUTC: $offset";
        }


Das würde das Verhalten erklären und auch die Ausgaben/Logs was ich gesammelt habe.
Danach wird nähmlich der Hash->lastupdated auf lastupdated gesetzt und dadurch 2x das Event ausgelöst.

pOpY

[justme1968]

ja. das kann sein...

siehst du die offsetUTC meldung im log? nach dem device update oder davor?

aber eigentlich sollte die bridge vorher aktualisiert werden.

und es erklärt noch nicht das problem beim betrieb.

[popy]

Hab mir in der 32_HUEDevice.pm das my lastupdated angesehen bzw. das Problem versucht zu debuggen.
Das Problem ist wirklich das beim starten die HUEBridge das offsetUTC erst nach einiger Zeit abfragt und bekommt.

Habe 2x debug Meldungen hinzugefügt:

Code Auswählen Erweitern


      my $offset = 0;
      if( my $iohash = $hash->{IODev} ) {
        substr( $lastupdated, 10, 1, '_' );
        my $sec = SVG_time_to_sec($lastupdated);

        if( my $offset = $iohash->{helper}{offsetUTC} ) {
          $sec += $offset;
          Log3 $name, 4, "$name: offsetUTC: $offset";
        }else{
          Log 1, "no offset!";
        }

        $lastupdated = FmtDateTime($sec);
      }else{
          Log 1, "no iohash!";
      }


Es kommt nun immer "no offset!" bis zum 2ten notify nach dem neustart wo die bridge dann offsetUTC bekommen hat.
Habe es dann mit "list hueBridge1" kontrolliert gleich nach dem Neustart:

Es fehlt offsetUTC!!!

Code Auswählen Erweitern


Internals:
   DEF        192.168.0.2 60
   INTERVAL   60
   NAME       hueBridge1
   NOTIFYDEV  global
   NR         59
   NTFY_ORDER 50-hueBridge1
   STATE      connected
   TYPE       HUEBridge
   host       192.168.0.2
   mac        00:17:88:16:8f:30
   manufacturer Royal Philips Electronics
   modelName  Philips hue bridge 2012
   READINGS:
     2018-12-02 11:04:42   lastError       resource, /groups/7, not available
     2019-01-10 11:47:48   state           connected
     2018-12-17 18:53:55   swupdate        ZGB_100B_0104 - 5.127.1.26420
   helper:
     count      0
     last_config_timestamp 1547117268
Attributes:
   alias      HUE Bridge
   devStateIcon connected:rc_GREEN:on disconnected:rc_RED:off Initialized:message_socket_disabled
   group      Geräte
   httpUtils  1
   icon       hue_filled_bridge_v1
   key        ****
   noshutdown 1
   pollDevices 2
   room       System
   verbose    1


Und nach ein paar Minuten Laufzeit, offsetUTC ist vorhanden:

Code Auswählen Erweitern


Internals:
   DEF        192.168.0.2 60
   INTERVAL   60
   NAME       hueBridge1
   NOTIFYDEV  global
   NR         59
   NTFY_ORDER 50-hueBridge1
   STATE      connected
   TYPE       HUEBridge
   apiversion 1.16.0
   host       192.168.0.2
   mac        00:17:88:16:8f:30
   manufacturer Royal Philips Electronics
   modelName  Philips hue bridge 2012
   modelid    BSB001
   name       Philips hue
   swversion  01041302
   updatestate 2 [1,2,3]
   zigbeechannel 15
   READINGS:
     2018-12-02 11:04:42   lastError       resource, /groups/7, not available
     2019-01-10 11:48:49   state           connected
     2018-12-17 18:53:55   swupdate        ZGB_100B_0104 - 5.127.1.26420
   helper:
     apiversion 69632
     count      0
     last_config_timestamp 1547117328
     offsetUTC  3600
     updatestate 2
Attributes:
   alias      HUE Bridge
   devStateIcon connected:rc_GREEN:on disconnected:rc_RED:off Initialized:message_socket_disabled
   group      Geräte
   httpUtils  1
   icon       hue_filled_bridge_v1
   key        ****
   noshutdown 1
   pollDevices 2
   room       System
   verbose    1


Das erklärt nun warum sich fhem so verhält.

ja. das kann sein...

siehst du die offsetUTC meldung im log? nach dem device update oder davor?

aber eigentlich sollte die bridge vorher aktualisiert werden.

und es erklärt noch nicht das problem beim betrieb.

Wie kann es sein das das bei mir (und anderen) nicht der Fall ist (offsetUTC wird erst später abgefragt/gesetzt)?