Since homebridge 1.4.0 little bug with cache i think

[fennec622]

Analysis

Since 1.4.0 when i switch a light or outlet in on mode or off mode

Expected Behavior

Mqtthing object

I change state and immediatly come back in original state but in reality command is ok, i close home and i restart and the state is the good state

In 1.3.9 all is ok it's Mqtthing object

https://user-images.githubusercontent.com/24509422/150740382-45fbed67-7ee3-4479-b11b-2033df09f2aa.MP4

Steps To Reproduce

Just change state the second change is ok statut

Logs

[24/01/2022, 08:38:02] [Escalier] Publishing MQTT: zigbee2mqtt/boutonentree2/right/set = ON
[24/01/2022, 08:38:04] [Escalier] Received MQTT: zigbee2mqtt/boutonentree2 = {"action":null,"last_seen":"2022-01-24T07:38:04.730Z","linkquality":61,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"OFF"}
[24/01/2022, 08:38:04] [Escalier] apply() function decoded message to [OFF]
[24/01/2022, 08:38:04] [Escalier] Received MQTT: zigbee2mqtt/boutonentree2 = {"action":null,"last_seen":"2022-01-24T07:38:04.730Z","linkquality":61,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"ON"}
[24/01/2022, 08:38:04] [Escalier] apply() function decoded message to [ON]
[24/01/2022, 08:38:04] [Escalier] Received MQTT: zigbee2mqtt/boutonentree2 = {"action":null,"last_seen":"2022-01-24T07:38:04.861Z","linkquality":61,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"ON"}
[24/01/2022, 08:38:04] [Escalier] apply() function decoded message to [ON]

Configuration

{
            "accessory": "mqttthing",
            "type": "lightbulb",
            "name": "Escalier",
            "topics": {
                "getOn": {
                    "topic": "zigbee2mqtt/boutonentree2",
                    "apply": "return JSON.parse(message).state_right"
                },
                "setOn": "zigbee2mqtt/boutonentree2/right/set",
                "getOnline": {
                    "topic": "zigbee2mqtt/boutonentree2/availability",
                    "apply": "return message == 'online' ? 'ON' : 'OFF';"
                }
            },
            "logMqtt": false,
            "integerValue": false,
            "onValue": "ON",
            "offValue": "OFF",
            "turnOffAfterms": "120000",
            "onlineValue": "ON",
            "offlineValue": "OFF"
        },

Environment

• OS: RPY last
• Software: 1.4.0
• Node:16.13.1
• npm:8.1.2 -mqtthing 1.1.38

Process Supervisor

hb-service

Additional Context

No response

[dylexrocks]

I can confirm this problem. I experience the same behavior for my lights and also use homebridge 1.4.0 and mqttthing 1.1.39

[fennec622]

https://github.com/homebridge/homebridge/issues/3073

[arachnetech]

Does this happen with all mqttthing lightbulbs in homebridge 1.4? I've not had time to try to reproduce yet.

[arachnetech]

Just checked and I'm still on 1.3.8... I'll try updating my development instance.

[fennec622]

Does this happen with all mqttthing lightbulbs in homebridge 1.4? I've not had time to try to reproduce yet.

Yes all object

i come back in 1.3.9

Try to update to 1.4 for me bug is imediatly present

[arachnetech]

Finally updated my development instance to 1.4.0, but I'm not seeing this issue - I can turn my test bulbs on and they stay on.

[arachnetech]

Just tried with config:

"accessories": [
        {
            "accessory": "mqttthing",
            "type": "lightbulb",
            "url": "homebridge2",
            "name": "Escalier",
            "topics": {
                "getOn": {
                    "topic": "test/Escalier",
                    "apply": "return JSON.parse(message).state_right"
                },
                "setOn": "test/Escalier/right/set",
                "getOnline": {
                    "topic": "zigbee2mqtt/boutonentree2/availability",
                    "apply": "return message == 'online' ? 'ON' : 'OFF';"
                }
            },
            "logMqtt": true,
            "integerValue": false,
            "onValue": "ON",
            "offValue": "OFF",
            "turnOffAfterms": "120000",
            "onlineValue": "ON",
            "offlineValue": "OFF"
        }
    ]

... and it still worked fine for me. It only turns off when I turn it off:

https://user-images.githubusercontent.com/24389384/155862099-95974350-ada9-4060-bdb5-404be01c9f2f.MOV

[fennec622]

Ok thanks for job I try

[itavero]

Just wondering, @arachnetech, during your test, did you also have status messages being published? (i.e. the getOn part of the config).

Users are reporting similar issues on my Homebridge plugin, so I'm not sure if it's a Homebridge issue or we are just coincidentally doing the same thing "wrong" in our plugins: itavero/homebridge-z2m#383

[fennec622]

Again same bug in 1.4.0 before I delete Home and persist and accessories

But same problem

[arachnetech]

Just wondering, @arachnetech, during your test, did you also have status messages being published? (i.e. the getOn part of the config).

Users are reporting similar issues on my Homebridge plugin, so I'm not sure if it's a Homebridge issue or we are just coincidentally doing the same thing "wrong" in our plugins: itavero/homebridge-z2m#383

No, I was monitoring MQTT setOn messages published by mqtt-thing, but I didn't publish any getOn messages. Interesting... will try to reproduce again with that too when I get a chance...

[arachnetech]

Just had another attempt at reproducing this, this time with a bit of fake test code which responds to a setOn message with a corresponding getOn message, as @itavero suggested this might be relevant.

I haven't managed to reproduce exactly @fennec622, but I do get some strange behaviour when I turn my fake light on then off (or off then on) quickly. I added a delay to my test code - so every setOn is still echoed, but only after a second has elapsed. I also added some additional diagnostic logging to track when I tell homebridge that a characteristic has changed.

Everything works fine unless I switch the light on then off really quickly. In this case, even though I've told homebridge that the state is on then the state is off, the Home app ignores my second notification and leaves the light on. However (not shown in the video below) if I the move away from the Home app and then back to it, it shows the correct off state - so this particular problem appears to be with the Home app rather than Homebridge.

https://www.dropbox.com/s/t30t861gvcuig77/RPReplay_Final1647297515.mov

Note from this video, I only notify Homebridge of a characteristic change if I receive a 'get' message giving a state different to the one I currently believe the accessory to be in. This is why there is no 'updating' etc. when the get message confirms the state I just set: I have to change the state again before the confirmation of the first state change for the state to disagree with what Homebridge has told me (and so for me to bother to notify it). When the updates are fairly spread out, everything works fine - it's only when they're very close together that the Home app appears to fail to repaint.

I don't think any of this helps - this doesn't seem quite like the original problem to me.

[arachnetech]

Actually, looking at the logs originally provided, this might be the same...

[24/01/2022, 08:38:02] [Escalier] Publishing MQTT: zigbee2mqtt/boutonentree2/right/set = ON
[24/01/2022, 08:38:04] [Escalier] Received MQTT: zigbee2mqtt/boutonentree2 = {"action":null,"last_seen":"2022-01-24T07:38:04.730Z","linkquality":61,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"OFF"}
[24/01/2022, 08:38:04] [Escalier] apply() function decoded message to [OFF]
[24/01/2022, 08:38:04] [Escalier] Received MQTT: zigbee2mqtt/boutonentree2 = {"action":null,"last_seen":"2022-01-24T07:38:04.730Z","linkquality":61,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"ON"}
[24/01/2022, 08:38:04] [Escalier] apply() function decoded message to [ON]
[24/01/2022, 08:38:04] [Escalier] Received MQTT: zigbee2mqtt/boutonentree2 = {"action":null,"last_seen":"2022-01-24T07:38:04.861Z","linkquality":61,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"ON"}
[24/01/2022, 08:38:04] [Escalier] apply() function decoded message to [ON]

You switch it ON, and you receive an OFF followed by two ONs. If these are in sufficiently quick succession, Homebridge (or the Home app?) may ignore them.

So, first question: are all these 08:38:04 messages received at (nearly) the same time?

Second question: why does your light say it's turning off immediately after you turn it on, then that it's turning on twice? Can you stop it from doing this?

[fennec622]

@arachnetech

it's true it's strange

I try this morning and same conclusion when I change stat I have always 3 command

Log from zigbee2mqtt

MQTT publish: topic 'zigbee2mqtt/boutonentree2', payload '{"action":null,"last_seen":"2022-03-15T06:48:52.804Z","linkquality":72,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"OFF"}' Info MQTT publish: topic 'zigbee2mqtt/boutonentree2', payload '{"action":null,"last_seen":"2022-03-15T06:48:52.804Z","linkquality":72,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"ON"}' Info MQTT publish: topic 'zigbee2mqtt/boutonentree2', payload '{"action":null,"last_seen":"2022-03-15T06:48:52.934Z","linkquality":72,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"ON"}' Info MQTT publish: topic 'zigbee2mqtt/boutonentree2', payload '{"action":null,"last_seen":"2022-03-15T06:48:56.800Z","linkquality":72,"operation_mode_left":null,"operation_mode_right":null,"state_left":"OFF","state_right":"ON"}'

I don't know why

in real the light is ok just one command on or off

before in 1.3.9 no problem but with 1.4.0 problem

I post this bug in zigbee2mqtt

thanks

[itavero]

A user of my plugin reports that downgrading hap-nodejs back to v0.9.8, resolved the problem for him.

If I have some time, I might investigate what changed in between 0.9.8 and 0.10.0 that might result in this behavior.