Published state always shows initial values for "hue" and "sat" instead of current values

[jonemo]

I am using version 0.4.0 with config setting topic_prefix = "livingroom", have a Hue Bridge configured and working, and two color light strips configured in the bridge. I can change the hue, saturation, on/off status of both light strips as expected by sending payloads like {"on": "true"} and {"hue": 43210, "sat": 50}, and so on.

However, I noticed that the state information published back by hue2mqtt never reflects the current state of the lights. Instead the messages always just show the initial values from when hue2mqtt was last started.

Here is an example log from subscribing to livingroom/light/#:

# two initial messages sent at hue2mqtt start:

livingroom/light/00:17:88:01:03:ce:55:5f-0b:
b'{"id": 2, "name": "reading", "uniqueid": "00:17:88:01:03:ce:55:5f-0b", "state": {"on": true, "alert": "select", "bri": 50, "ct": 153, "effect": "none", "hue": 30000, "sat": 100, "xy": [0, 0], "transitiontime": null, "reachable": true, "color_mode": null, "mode": "homeautomation"}, "manufacturername": "Signify Netherlands B.V.", "modelid": "LST002", "productname": "Hue lightstrip plus", "type": "Extended color light", "swversion": "1.101.2"}'

livingroom/light/00:17:88:01:01:1b:85:b9-0b:
b'{"id": 3, "name": "table", "uniqueid": "00:17:88:01:01:1b:85:b9-0b", "state": {"on": true, "alert": "select", "bri": 10, "ct": 310, "effect": "none", "hue": 10000, "sat": 100, "xy": [0, 0], "transitiontime": null, "reachable": true, "color_mode": null, "mode": "homeautomation"}, "manufacturername": "Signify Netherlands B.V.", "modelid": "LST002", "productname": "Hue lightstrip plus", "type": "Extended color light", "swversion": "67.101.2"}'

# my first command message:

livingroom/light/00:17:88:01:01:1b:85:b9-0b/set:
b'{"hue": 20000}'

livingroom/light/00:17:88:01:01:1b:85:b9-0b:
b'{"id": 3, "name": "table", "uniqueid": "00:17:88:01:01:1b:85:b9-0b", "state": {"on": true, "alert": "select", "bri": 10, "ct": null, "effect": "none", "hue": 10000, "sat": 100, "xy": [0, 0], "transitiontime": null, "reachable": true, "color_mode": null, "mode": "homeautomation"}, "manufacturername": "Signify Netherlands B.V.", "modelid": "LST002", "productname": "Hue lightstrip plus", "type": "Extended color light", "swversion": "67.101.2"}'

livingroom/light/00:17:88:01:01:1b:85:b9-0b/set:
b'{"sat": 50}'

livingroom/light/00:17:88:01:01:1b:85:b9-0b:
b'{"id": 3, "name": "table", "uniqueid": "00:17:88:01:01:1b:85:b9-0b", "state": {"on": true, "alert": "select", "bri": 10, "ct": null, "effect": "none", "hue": 10000, "sat": 100, "xy": [0, 0], "transitiontime": null, "reachable": true, "color_mode": null, "mode": "homeautomation"}, "manufacturername": "Signify Netherlands B.V.", "modelid": "LST002", "productname": "Hue lightstrip plus", "type": "Extended color light", "swversion": "67.101.2"}'

livingroom/light/00:17:88:01:01:1b:85:b9-0b/set:
b'{"hue": 20000}'

livingroom/light/00:17:88:01:01:1b:85:b9-0b:
b'{"id": 3, "name": "table", "uniqueid": "00:17:88:01:01:1b:85:b9-0b", "state": {"on": true, "alert": "select", "bri": 10, "ct": null, "effect": "none", "hue": 10000, "sat": 100, "xy": [0, 0], "transitiontime": null, "reachable": true, "color_mode": null, "mode": "homeautomation"}, "manufacturername": "Signify Netherlands B.V.", "modelid": "LST002", "productname": "Hue lightstrip plus", "type": "Extended color light", "swversion": "67.101.2"}'

Note how the reported state always has "hue": 10000, "sat": 100, instead of the new values. The lights do change to the new values.

Here is the verbose output from hue2mqtt from the same session that produced the MQTT messages above:

hue2mqtt -v
2023-04-09 16:12:39 hue2mqtt hue2mqtt.hue2mqtt INFO Hue2MQTT v0.4.0 - Hue to MQTT Bridge.
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.protocol INFO [CONNECTION MADE]
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x20] b'\x00\x00'
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler DEBUG [CONNACK] flags: 0x0, result: 0x0
2023-04-09 16:12:39 hue2mqtt hue2mqtt.mqtt.wrapper DEBUG Subscribing to livingroom/light/+/set
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 1
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.package INFO [SEND SUB] 1 [b'livingroom/light/+/set']
2023-04-09 16:12:39 hue2mqtt hue2mqtt.mqtt.wrapper DEBUG Subscribing to livingroom/group/+/set
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 2
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.package INFO [SEND SUB] 2 [b'livingroom/group/+/set']
2023-04-09 16:12:39 hue2mqtt gmqtt.client DEBUG [QoS query IS EMPTY]
2023-04-09 16:12:39 hue2mqtt hue2mqtt.hue2mqtt INFO Connected to MQTT Broker
2023-04-09 16:12:39 hue2mqtt hue2mqtt.hue2mqtt INFO Connecting to Hue Bridge at 192.168.3.2
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x90] b'\x00\x01\x00'
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler INFO [SUBACK] 1 (0,)
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 1
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x90] b'\x00\x02\x00'
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler INFO [SUBACK] 2 (0,)
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 2
2023-04-09 16:12:39 hue2mqtt aiohue.bridge.192.168.3.2 DEBUG Unused result: {'schedules': {}, 'rules': {}, 'resourcelinks': {}}
2023-04-09 16:12:39 hue2mqtt hue2mqtt.hue2mqtt INFO Bridge Name: PhilipsHue Pycon
2023-04-09 16:12:39 hue2mqtt hue2mqtt.hue2mqtt INFO Bridge MAC: ec:b5:fa:a5:c4:61
2023-04-09 16:12:39 hue2mqtt hue2mqtt.hue2mqtt INFO API Version: 1.57.0
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.package DEBUG Sending PUBLISH (q1), 'b'livingroom/status'', ... (117 bytes)
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 3
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.package DEBUG Sending PUBLISH (q1), 'b'livingroom/light/00:17:88:01:03:ce:55:5f-0b'', ... (444 bytes)
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 4
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.package DEBUG Sending PUBLISH (q1), 'b'livingroom/light/00:17:88:01:01:1b:85:b9-0b'', ... (443 bytes)
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 5
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.package DEBUG Sending PUBLISH (q1), 'b'livingroom/group/1'', ... (348 bytes)
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 6
2023-04-09 16:12:39 hue2mqtt hue2mqtt.hue2mqtt DEBUG Ignoring virtual sensor: Daylight
2023-04-09 16:12:39 hue2mqtt aiohue.bridge.192.168.3.2 DEBUG Subscribing to events
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x40] b'\x00\x03'
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler INFO [RECEIVED PUBACK FOR] 3
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 3
2023-04-09 16:12:39 hue2mqtt gmqtt.client DEBUG [REMOVE MESSAGE] 3
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x40] b'\x00\x04'
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler INFO [RECEIVED PUBACK FOR] 4
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 4
2023-04-09 16:12:39 hue2mqtt gmqtt.client DEBUG [REMOVE MESSAGE] 4
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x40] b'\x00\x05'
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler INFO [RECEIVED PUBACK FOR] 5
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 5
2023-04-09 16:12:39 hue2mqtt gmqtt.client DEBUG [REMOVE MESSAGE] 5
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x40] b'\x00\x06'
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.handler INFO [RECEIVED PUBACK FOR] 6
2023-04-09 16:12:39 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 6
2023-04-09 16:12:39 hue2mqtt gmqtt.client DEBUG [REMOVE MESSAGE] 6
2023-04-09 16:12:44 hue2mqtt gmqtt.client DEBUG [QoS query IS EMPTY]
2023-04-09 16:12:48 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x30] b'\x00/livingroom/light/00:17:88:01:01:1b:85:b9-0b/set{"hue": 20000}'
2023-04-09 16:12:48 hue2mqtt gmqtt.mqtt.handler DEBUG [RECV livingroom/light/00:17:88:01:01:1b:85:b9-0b/set with QoS: 0] b'{"hue": 20000}'
2023-04-09 16:12:48 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: None
2023-04-09 16:12:48 hue2mqtt hue2mqtt.mqtt.wrapper DEBUG Message received on livingroom/light/00:17:88:01:01:1b:85:b9-0b/set with payload: b'{"hue": 20000}'
2023-04-09 16:12:48 hue2mqtt hue2mqtt.mqtt.wrapper DEBUG Calling handle_set_light to handle livingroom/light/00:17:88:01:01:1b:85:b9-0b/set
2023-04-09 16:12:48 hue2mqtt hue2mqtt.hue2mqtt INFO Updating table
2023-04-09 16:12:48 hue2mqtt aiohue.bridge.192.168.3.2 DEBUG Received event: {'creationtime': '2023-04-11T18:12:48Z', 'data': [{'color': {'xy': {'x': 0.3425, 'y': 0.4703}}, 'color_temperature': {'mirek': None, 'mirek_valid': False}, 'id': '80056023-81c0-433d-97ee-0f7d74886046', 'id_v1': '/lights/3', 'owner': {'rid': '058913a2-925e-4c70-a464-a73297dc139a', 'rtype': 'device'}, 'type': 'light'}], 'id': 'ca6f5504-3745-4252-98bf-5fdc7ba75b34', 'type': 'update'}
2023-04-09 16:12:48 hue2mqtt gmqtt.mqtt.package DEBUG Sending PUBLISH (q1), 'b'livingroom/light/00:17:88:01:01:1b:85:b9-0b'', ... (444 bytes)
2023-04-09 16:12:48 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 7
2023-04-09 16:12:48 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x40] b'\x00\x07'
2023-04-09 16:12:48 hue2mqtt gmqtt.mqtt.handler INFO [RECEIVED PUBACK FOR] 7
2023-04-09 16:12:48 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 7
2023-04-09 16:12:48 hue2mqtt gmqtt.client DEBUG [REMOVE MESSAGE] 7
2023-04-09 16:12:49 hue2mqtt gmqtt.client DEBUG [QoS query IS EMPTY]
2023-04-09 16:12:54 hue2mqtt gmqtt.client DEBUG [QoS query IS EMPTY]
2023-04-09 16:12:56 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x30] b'\x00/livingroom/light/00:17:88:01:01:1b:85:b9-0b/set{"sat": 50}'
2023-04-09 16:12:56 hue2mqtt gmqtt.mqtt.handler DEBUG [RECV livingroom/light/00:17:88:01:01:1b:85:b9-0b/set with QoS: 0] b'{"sat": 50}'
2023-04-09 16:12:56 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: None
2023-04-09 16:12:56 hue2mqtt hue2mqtt.mqtt.wrapper DEBUG Message received on livingroom/light/00:17:88:01:01:1b:85:b9-0b/set with payload: b'{"sat": 50}'
2023-04-09 16:12:56 hue2mqtt hue2mqtt.mqtt.wrapper DEBUG Calling handle_set_light to handle livingroom/light/00:17:88:01:01:1b:85:b9-0b/set
2023-04-09 16:12:56 hue2mqtt hue2mqtt.hue2mqtt INFO Updating table
2023-04-09 16:12:56 hue2mqtt aiohue.bridge.192.168.3.2 DEBUG Received event: {'creationtime': '2023-04-11T18:12:56Z', 'data': [{'color': {'xy': {'x': 0.3614, 'y': 0.4235}}, 'color_temperature': {'mirek': None, 'mirek_valid': False}, 'id': '80056023-81c0-433d-97ee-0f7d74886046', 'id_v1': '/lights/3', 'owner': {'rid': '058913a2-925e-4c70-a464-a73297dc139a', 'rtype': 'device'}, 'type': 'light'}], 'id': '3890581c-2a03-4790-b06e-7b7495e4d959', 'type': 'update'}
2023-04-09 16:12:56 hue2mqtt gmqtt.mqtt.package DEBUG Sending PUBLISH (q1), 'b'livingroom/light/00:17:88:01:01:1b:85:b9-0b'', ... (444 bytes)
2023-04-09 16:12:56 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 8
2023-04-09 16:12:56 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x40] b'\x00\x08'
2023-04-09 16:12:56 hue2mqtt gmqtt.mqtt.handler INFO [RECEIVED PUBACK FOR] 8
2023-04-09 16:12:56 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 8
2023-04-09 16:12:56 hue2mqtt gmqtt.client DEBUG [REMOVE MESSAGE] 8
2023-04-09 16:12:59 hue2mqtt gmqtt.client DEBUG [QoS query IS EMPTY]
2023-04-09 16:13:04 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x30] b'\x00/livingroom/light/00:17:88:01:01:1b:85:b9-0b/set{"hue": 20000}'
2023-04-09 16:13:04 hue2mqtt gmqtt.mqtt.handler DEBUG [RECV livingroom/light/00:17:88:01:01:1b:85:b9-0b/set with QoS: 0] b'{"hue": 20000}'
2023-04-09 16:13:04 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: None
2023-04-09 16:13:04 hue2mqtt hue2mqtt.mqtt.wrapper DEBUG Message received on livingroom/light/00:17:88:01:01:1b:85:b9-0b/set with payload: b'{"hue": 20000}'
2023-04-09 16:13:04 hue2mqtt hue2mqtt.mqtt.wrapper DEBUG Calling handle_set_light to handle livingroom/light/00:17:88:01:01:1b:85:b9-0b/set
2023-04-09 16:13:04 hue2mqtt hue2mqtt.hue2mqtt INFO Updating table
2023-04-09 16:13:04 hue2mqtt aiohue.bridge.192.168.3.2 DEBUG Received event: {'creationtime': '2023-04-11T18:13:04Z', 'data': [{'color': {'xy': {'x': 0.3614, 'y': 0.4235}}, 'color_temperature': {'mirek': None, 'mirek_valid': False}, 'id': '80056023-81c0-433d-97ee-0f7d74886046', 'id_v1': '/lights/3', 'owner': {'rid': '058913a2-925e-4c70-a464-a73297dc139a', 'rtype': 'device'}, 'type': 'light'}], 'id': 'fff11be2-27bb-4649-bb06-d44f26d254d5', 'type': 'update'}
2023-04-09 16:13:04 hue2mqtt gmqtt.mqtt.package DEBUG Sending PUBLISH (q1), 'b'livingroom/light/00:17:88:01:01:1b:85:b9-0b'', ... (444 bytes)
2023-04-09 16:13:04 hue2mqtt gmqtt.mqtt.utils DEBUG NEW ID: 9
2023-04-09 16:13:04 hue2mqtt gmqtt.mqtt.handler DEBUG [CMD 0x40] b'\x00\t'
2023-04-09 16:13:04 hue2mqtt gmqtt.mqtt.handler INFO [RECEIVED PUBACK FOR] 9
2023-04-09 16:13:04 hue2mqtt gmqtt.mqtt.utils DEBUG FREE MID: 9
2023-04-09 16:13:04 hue2mqtt gmqtt.client DEBUG [REMOVE MESSAGE] 9
2023-04-09 16:13:04 hue2mqtt gmqtt.client DEBUG [QoS query IS EMPTY]

The same happens with the other light strip. The same also happens when I remove the topic_prefix config setting. Please let me know if there is anything else I could try to debug this behavior.

[kuplakoralli]

I have similar issue with published group messages. When light is turned on/off the state field of the group message is not updated (all_on or any_on) and remains the same (when the hue2mqtt was started). To me it seems that the light messages has the correct state. I have version 0.4.1.