Deconz-rest-plugin: Transition (fading in/out of lights) stopped working in .76 in home assistant

[tubalainen]

Hello!

The transition feature is being ignored in .76. Works great in .75

Example from an automation in Home Assistant - it fades out over a time of 30 seconds (in .75) but just turns off in .76:

action:
  - data:
      entity_id:
        - light.lampa_taket_kontoret
        - light.lampa_ikea_rgb
        - light.ledstrip_skrivbordet
        - light.lampa_kontoret_bakom_monitorn
        - light.takpanel_kontor
        - light.lampa_kistan
        - light.led_panel_jormlien
      transition: 30
    service: light.turn_off

[tubalainen]

I use the latest Home Assistant version, 0.110.1 and I run the marthoc docker dist.

[tubalainen]

More details on the issue.

Here is the API exchange between Home Assistant and Deconz.

On/Off works like expected - but with "transition" declared in my automation it does not compute fully with .76 - it just turns off with the default transitiontime (1-2 seconds ish).

I use this automation in Home Assistant (dim from 100% down to 0 (off) in 30 seconds):

- id: 'kontoret_master_off'
  alias: Kontoret master fjärr off
  initial_state: 'on'
  trigger:
  - event_data:
      id: remote_master_kontor
      event: 2002
    platform: event
    event_type: deconz_event
  condition: []
  action:
#  - data:
#      entity_id: switch.circadian_lighting_lampor_kontoret_fargtemp_circadian
#    service: switch.turn_off
#  - delay: 00:00:02
  - data:
      entity_id:
        - light.lampa_taket_kontoret
        - light.lampa_ikea_rgb
        - light.ledstrip_skrivbordet
        - light.lampa_kontoret_bakom_monitorn
        - light.takpanel_kontor
        - light.lampa_kistan
        - light.led_panel_jormlien
      transition: 30
    service: light.turn_off

The following outcome in the debug log from Home Assistant with version .76 (when the button is being pushed) - the lights turns off (with a default transition of 1-2 sec ish?):

2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"24","r":"sensors","state":{"buttonevent":2002,"lastupdated":"2020-05-23T13:50:40.110"},"t":"event","uniqueid":"00:0d:6f:ff:fe:b1:e0:65-01-1000"}
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/21/state"
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/21/state/bri': 0}},
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/14/state"
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"21","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":440,"on":false,"reachable":true},"t":"event","uniqueid":"00:0d:6f:ff:fe:55:7e:77-01"}
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/14/state/bri': 0}},
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"14","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":370,"on":false,"reachable":true},"t":"event","uniqueid":"90:fd:9f:ff:fe:89:75:a9-01"}
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/5/state"
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/5/state/bri': 0}},
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"5","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":366,"on":true,"reachable":true},"t":"event","uniqueid":"00:17:88:01:02:04:b8:08-0b"}
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/20/state"
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/20/state/bri': 0}},
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"20","r":"lights","state":{"alert":null,"bri":0,"colormode":"xy","hue":0,"on":false,"reachable":true,"sat":0,"xy":[0.41,0.342]},"t":"event","uniqueid":"00:0d:6f:ff:fe:1f:1c:15-01"}
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/18/state"
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/18/state/bri': 0}},
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"18","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":454,"on":false,"reachable":true},"t":"event","uniqueid":"90:fd:9f:ff:fe:1f:c0:16-01"}
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/16/state"
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/16/state/bri': 0}},
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"16","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":370,"on":false,"reachable":true},"t":"event","uniqueid":"00:0b:57:ff:fe:dd:3d:4c-01"}
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"14","r":"lights","state":{"alert":null,"bri":251,"colormode":"ct","ct":370,"on":false,"reachable":true},"t":"event","uniqueid":"90:fd:9f:ff:fe:89:75:a9-01"}
2020-05-23 15:50:40 DEBUG (MainThread) [pydeconz.websocket] {"config":{"alert":"none","battery":87,"delay":60,"duration":60,"group":"41217","on":true,"reachable":true},"e":"changed","id":"30","r":"sensors","t":"event","uniqueid":"90:fd:9f:ff:fe:8c:81:53-01-0006"}

And here is the exact same log from Home Assistant using .75 - the lights dim/transitions to off state 30 seconds later:

2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"24","r":"sensors","state":{"buttonevent":2002,"lastupdated":"2020-05-23T13:56:36"},"t":"event","uniqueid":"00:0d:6f:ff:fe:b1:e0:65-01-1000"}
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/16/state"
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/16/state/on': False}},
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/20/state"
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"16","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":370,"on":false,"reachable":true},"t":"event","uniqueid":"00:0b:57:ff:fe:dd:3d:4c-01"}
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/20/state/on': False}},
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"20","r":"lights","state":{"alert":null,"bri":0,"colormode":"xy","hue":0,"on":false,"reachable":true,"sat":0,"xy":[0.41,0.342]},"t":"event","uniqueid":"00:0d:6f:ff:fe:1f:1c:15-01"}
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/5/state"
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/5/state/on': False}},
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"5","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":366,"on":false,"reachable":true},"t":"event","uniqueid":"00:17:88:01:02:04:b8:08-0b"}
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/14/state"
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/14/state/on': False}},
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"14","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":370,"on":false,"reachable":true},"t":"event","uniqueid":"90:fd:9f:ff:fe:89:75:a9-01"}
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/18/state"
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/18/state/on': False}},
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"18","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":454,"on":false,"reachable":true},"t":"event","uniqueid":"90:fd:9f:ff:fe:1f:c0:16-01"}
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] Sending "put" "{'on': False, 'bri': 0, 'transitiontime': 300}" to "172.17.0.2 /lights/21/state"
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.gateway] HTTP request response: [{'success': {'/lights/21/state/on': False}},
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"21","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":440,"on":false,"reachable":true},"t":"event","uniqueid":"00:0d:6f:ff:fe:55:7e:77-01"}
2020-05-23 15:56:36 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"20","r":"lights","state":{"alert":null,"bri":254,"colormode":"xy","hue":0,"on":false,"reachable":true,"sat":0,"xy":[0.41,0.342]},"t":"event","uniqueid":"00:0d:6f:ff:fe:1f:1c:15-01"}
2020-05-23 15:56:38 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"21","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":440,"on":true,"reachable":true},"t":"event","uniqueid":"00:0d:6f:ff:fe:55:7e:77-01"}
2020-05-23 15:56:38 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"21","r":"lights","state":{"alert":null,"bri":254,"colormode":"ct","ct":440,"on":true,"reachable":true},"t":"event","uniqueid":"00:0d:6f:ff:fe:55:7e:77-01"}
2020-05-23 15:56:39 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"56002","r":"groups","state":{"all_on":false,"any_on":false},"t":"event"}
2020-05-23 15:56:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"18","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":454,"on":true,"reachable":true},"t":"event","uniqueid":"90:fd:9f:ff:fe:1f:c0:16-01"}
2020-05-23 15:56:40 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"18","r":"lights","state":{"alert":null,"bri":254,"colormode":"ct","ct":454,"on":true,"reachable":true},"t":"event","uniqueid":"90:fd:9f:ff:fe:1f:c0:16-01"}
2020-05-23 15:56:48 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"5","r":"lights","state":{"alert":null,"bri":0,"colormode":"ct","ct":366,"on":true,"reachable":true},"t":"event","uniqueid":"00:17:88:01:02:04:b8:08-0b"}
2020-05-23 15:56:48 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"5","r":"lights","state":{"alert":null,"bri":155,"colormode":"ct","ct":366,"on":true,"reachable":true},"t":"event","uniqueid":"00:17:88:01:02:04:b8:08-0b"}
2020-05-23 15:57:02 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"5","r":"lights","state":{"alert":null,"bri":39,"colormode":"ct","ct":366,"on":true,"reachable":true},"t":"event","uniqueid":"00:17:88:01:02:04:b8:08-0b"}
2020-05-23 15:57:06 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"16","r":"lights","state":{"alert":null,"bri":1,"colormode":"ct","ct":370,"on":false,"reachable":true},"t":"event","uniqueid":"00:0b:57:ff:fe:dd:3d:4c-01"}
2020-05-23 15:57:07 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"14","r":"lights","state":{"alert":null,"bri":1,"colormode":"ct","ct":370,"on":false,"reachable":true},"t":"event","uniqueid":"90:fd:9f:ff:fe:89:75:a9-01"}
2020-05-23 15:57:07 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"21","r":"lights","state":{"alert":null,"bri":254,"colormode":"ct","ct":440,"on":false,"reachable":true},"t":"event","uniqueid":"00:0d:6f:ff:fe:55:7e:77-01"}
2020-05-23 15:57:07 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"21","r":"lights","state":{"alert":null,"bri":1,"colormode":"ct","ct":440,"on":false,"reachable":true},"t":"event","uniqueid":"00:0d:6f:ff:fe:55:7e:77-01"}
2020-05-23 15:57:07 DEBUG (MainThread) [pydeconz.websocket] {"e":"changed","id":"20","r":"lights","state":{"alert":null,"bri":1,"colormode":"xy","hue":0,"on":false,"reachable":true,"sat":0,"xy":[0.41,0.342]},"t":"event","uniqueid":"00:0d:6f:ff:fe:1f:1c:15-01"}

[ebaauw]

A PUT to a light state with a body of {"on": false, "bri": 0, "transitiontime": 300} now results in a _Move to Level_ (0, 300), followed by an _Off with Effect_ (0, 0), effectively cancelling the transition. I think it used to result in a _Move to Level (with On/Off)_ (0, 300).

The change was intentional, see https://github.com/dresden-elektronik/deconz-rest-plugin/issues/1111#issuecomment-456464872:

[...] except when turning the light off with a transitiontime. The light comes back on at bri 1 instead of at the previous or specified bri. It might be better to ignore the transitiontime when bri is not specified (similar to setting the light on) and to send _Move to Level_ (b, t), followed by an _Off with Effect_ (0, 1) when it is.

I don't recall exactly what I was thinking back in January. Not all lights will actually turn off on _Move to Level (with On/Off)_, so maybe that was my reasoning no longer to send _Move to Level (with On/Off)_. But indeed, now it's no longer possible to turn a light off slowly with one REST API call. I still think it's a good idea to have changed the logic for {"on": false, "transitiontime": 300} to _Off with Effect_ (0, 0), but {"on": false, "bri": 0, "transitiontime": 300} should still result in a _Move to Level (with On/Off)_ (0, 300).

[ebaauw]

Ok, with https://github.com/ebaauw/deconz-rest-plugin/commit/56b3624200bf0b0ac334e363786b5709a84914a7, the behaviour should be:

Body | Command(s)
-- | --
{"on": false} | _Off with Effect_ (0, 0)
{"on": false, "transitiontime":_t_}
(Note that _t_ is ignored) | _Off with Effect_ (0, 0)
{"on": false, "bri":_b_} | _Move to Level_ (_b_, 4)
_Off with Effect_ (0, 0)
{"on": false, "bri":_b_, "transitiontime":_t_}
Note that _b_ is ignored) | _Move to Level (with On/Off)_ (0, _t_)

This is the same as the Hue bridge, except for {"on": false, "transitiontime":_t_}, as per my remark above.

Note that _Off with Effect_ is sent only to Hue lights; _Off_ is sent to other lights.

[tubalainen]

Mr. Ninja! Thanks! <3

[manup]

Thanks @ebaauw :+1: there will be a v2.05.77 small bug fix release later today which includes the fix.
v2.05.77 will also be available in stable channel.

[axlthorell]

Hi, I'm running 2.05.77 and I have issues with the light turn on/off together with transition.
I can only make the turn off with transition work if the light is already on, otherwise I get an error.
I have tried with both using

light.turn_on
brightness: 0
transition: 10

and

light.turn_off
transition: 10

Both with the same error if the light is already off.

File "/usr/local/lib/python3.7/site-packages/pydeconz/errors.py", line 58, in raise_error
    raise cls("{} {}".format(error["address"], error["description"]))
pydeconz.errors.pydeconzException: /lights/27/state parameter, bri, is not modifiable. Device is set to off.

This is a big issue when using scripts for turning off lights, the script won't work at all.

[ebaauw]

@axlthorell What lights do you have? What API calls does your script make?

[axlthorell]

@ebaauw I have IKEA Trådfri lights. As far as I know this issue started either when upgrading my deconz plugin from 5.3.2 (deCONZ 2.05.75) or from upgrading HA to 110.3, done at the same time.
How do I check the API call?
I get the same error if I use the services under developer tools i HA.

[axlthorell]

This is how it looks for me when calling the service when the light is already off.

[ebaauw]

Sorry, I don't know HA. I need to see what API requests HA sends to deCONZ.
deCONZ will log them if you run it with --dbg-http=1:

May 28 20:31:49 pi1 deCONZ[1442]: 20:31:49:106 HTTP API PUT /api/xxxxxxxxxxxx/lights/7/state - 192.x.x.40
May 28 20:31:49 pi1 deCONZ[1442]: 20:31:49:106 Text Data:   {"on":true}
May 28 20:31:49 pi1 deCONZ[1442]: 20:31:49:106 ApiMode: 0

[axlthorell]

@ebaauw Not quite sure how I activate debug, do I need to run deCONZ from command line?
I've tried adding dbg_http: 1 and dbg_info: 2 in the config for the plug in but I'm not seeing any API requests in any log.

[axlthorell]

@ebaauw is this it?
21:35:13:839 Websocket 172.30.32.1:38728 send message: {"e":"changed","id":"23","r":"lights","state":{"alert":null,"bri":1,"colormode":"ct","ct":317,"on":false,"reachable":true},"t":"event","uniqueid":"68:0a:e2:ff:fe:38:c3:6b-01"} (ret = 175)

[ebaauw]

No, that's the API reporting the changed light state back to HA.

[axlthorell]

Downgraded deCONZ to 2.05.75 and it works again.

[tubalainen]

This bug has been resolved in .77