Switch turned on by switch.turn_off and vice versa

kevinkk525 commented 4 years ago

The problem

I now noticed on several occasions that my automations that trigger all switches to turn on actually turn off some switches and vice versa. This was confirmed by another user on the forum using ESPHome, while I use my own mqtt framework. I use an automation that triggers multiple switches to turn on/off at the same time. grafik grafik grafik

Expected behaviour: service switch.turn_off should be unable to turn something on. switch.turn_on should be unable to turn something off.

Environment

Home Assistant Core release with the issue: 0.117
Last working Home Assistant Core release (if known):
Operating environment (OS/Container/Supervised/Core): Container
Integration causing this issue: Switch or Mqtt Switch
Link to integration documentation on our website: https://www.home-assistant.io/integrations/switch.mqtt/

Problem-relevant `configuration.yaml`

Additional information

Mqtt switches autodiscovered using configuration:

{
  "~" : "home/3eabaa00/GPIO/5",
  "name" : "Relais1",
  "stat_t" : "~",
  "uniq_id" : "3eabaa00_GPIO_5",
  "avty_t" : "home/3eabaa00/available",
  "cmd_t" : "~/set",
  "dev" : {
    "ids" : "3eabaa00",
    "sw" : "pysmartnode 602",
    "mf" : "espressif",
    "mdl" : "esp8266",
    "name" : "3eabaa00",
    "connections" : [ [ "mac", "2c:f4:32:aa:ab:3e" ] ]
  }
}

probot-home-assistant[bot] commented 4 years ago

Hey there @home-assistant/core, @emontnemery, mind taking a look at this issue as its been labeled with an integration (mqtt) you are listed as a codeowner for? Thanks! _{^{(message by CodeOwnersMention)}}

emontnemery commented 4 years ago

Please share the automation also and enable debug logging as suggested below, then share a log where the problem is reproduced.

Log settings:

logger:
  default: info
  logs:
    homeassistant.core: debug
    homeassistant.components.mqtt: debug

kevinkk525 commented 4 years ago

I couldn't yet reproduce it myself but the forum member tmaults provided his automation and the log during the incident (and there is not even mqtt involved):

I was able to recreate the issue by adding the automation shown below and after verifying that the “switch.power_controller_switch” was turned off, trigger the automation by changing the state of “input_boolean.helper_test” the “switch.power_controller_switch” was turned on as shown in the log snippet below.

    id: ‘1604578529672’
    alias: Test service.turn_on/turn_off
    description: ‘’
    trigger:
        platform: state
        entity_id: input_boolean.helper_test
        condition: []
    action:
        service: switch.turn_off
        data: {}
        entity_id: switch.power_controller_switch
        mode: single


2020-11-05 07:16:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=input_boolean, service=turn_on, service_data=entity_id=input_boolean.helper_test>
2020-11-05 07:16:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=input_boolean.helper_test, old_state=<state input_boolean.helper_test=off; editable=True, friendly_name=helper_test @ 2020-11-05T07:15:48.565933-07:00>, new_state=<state input_boolean.helper_test=on; editable=True, friendly_name=helper_test @ 2020-11-05T07:16:38.348087-07:00>>
2020-11-05 07:16:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=Test service.turn_on/turn_off, entity_id=automation.test_service_turn_on_turn_off, source=state of input_boolean.helper_test>
2020-11-05 07:16:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.test_service_turn_on_turn_off, old_state=<state automation.test_service_turn_on_turn_off=on; last_triggered=2020-11-05T07:15:48.567523-07:00, mode=single, current=0, id=1604578529672, friendly_name=Test service.turn_on/turn_off @ 2020-11-05T07:12:56.710931-07:00>, new_state=<state automation.test_service_turn_on_turn_off=on; last_triggered=2020-11-05T07:16:38.349349-07:00, mode=single, current=1, id=1604578529672, friendly_name=Test service.turn_on/turn_off @ 2020-11-05T07:12:56.710931-07:00>>
2020-11-05 07:16:38 INFO (MainThread) [homeassistant.components.automation.test_service_turn_on_turn_off] Test service.turn_on/turn_off: Running automation actions
2020-11-05 07:16:38 INFO (MainThread) [homeassistant.components.automation.test_service_turn_on_turn_off] Test service.turn_on/turn_off: Executing step call service
2020-11-05 07:16:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=turn_off, service_data=entity_id=[‘switch.power_controller_switch’]>
2020-11-05 07:16:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.test_service_turn_on_turn_off, old_state=<state automation.test_service_turn_on_turn_off=on; last_triggered=2020-11-05T07:16:38.349349-07:00, mode=single, current=1, id=1604578529672, friendly_name=Test service.turn_on/turn_off @ 2020-11-05T07:12:56.710931-07:00>, new_state=<state automation.test_service_turn_on_turn_off=on; last_triggered=2020-11-05T07:16:38.349349-07:00, mode=single, current=0, id=1604578529672, friendly_name=Test service.turn_on/turn_off @ 2020-11-05T07:12:56.710931-07:00>>
2020-11-05 07:16:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.power_controller_switch, old_state=<state switch.power_controller_switch=off; friendly_name=Pool switch, icon= @ 2020-11-05T07:15:48.640535-07:00>, new_state=<state switch.power_controller_switch=on; friendly_name=Pool switch, icon= @ 2020-11-05T07:16:38.494662-07:00>>```

emontnemery commented 4 years ago

That is weird. What integration does the forum member's switch belong to?

tmaults commented 4 years ago

The integration is ESPHome.

emontnemery commented 4 years ago

@tmaults could you try to reproduce the bug with these log settings:

logger:
  default: info
  logs:
    aioesphomeapi: debug
    homeassistant.core: debug
    homeassistant.components.esphome: debug

Ideally, also patch your installation with some additional logs (added as warnings for visibility):

diff --git a/homeassistant/components/esphome/__init__.py b/homeassistant/components/esphome/__init__.py
index c9d07a22ec..eb63852928 100644
--- a/homeassistant/components/esphome/__init__.py
+++ b/homeassistant/components/esphome/__init__.py
@@ -538,6 +538,7 @@ class EsphomeEntity(Entity):

     async def _on_state_update(self) -> None:
         """Update the entity state when state or static info changed."""
+        _LOGGER.warning("EsphomeEntity._on_state_update %s: %s", self.entity_id, self._state)
         self.async_write_ha_state()

     async def _on_device_update(self) -> None:
diff --git a/homeassistant/components/esphome/switch.py b/homeassistant/components/esphome/switch.py
index 3f8ca90d6c..5f4a5e32bc 100644
--- a/homeassistant/components/esphome/switch.py
+++ b/homeassistant/components/esphome/switch.py
@@ -1,4 +1,5 @@
 """Support for ESPHome switches."""
+import logging
 from typing import Optional

 from aioesphomeapi import SwitchInfo, SwitchState
@@ -9,6 +10,7 @@ from homeassistant.helpers.typing import HomeAssistantType

 from . import EsphomeEntity, esphome_state_property, platform_async_setup_entry

+_LOGGER = logging.getLogger(__name__)

 async def async_setup_entry(
     hass: HomeAssistantType, entry: ConfigEntry, async_add_entities
@@ -55,8 +57,10 @@ class EsphomeSwitch(EsphomeEntity, SwitchEntity):

     async def async_turn_on(self, **kwargs) -> None:
         """Turn the entity on."""
+        _LOGGER.warning("EsphomeSwitch.async_turn_on %s", self.entity_id)
         await self._client.switch_command(self._static_info.key, True)

     async def async_turn_off(self, **kwargs) -> None:
         """Turn the entity off."""
+        _LOGGER.warning("EsphomeSwitch.async_turn_off %s", self.entity_id)
         await self._client.switch_command(self._static_info.key, False)

tmaults commented 4 years ago

@emontnemery

I am running Home Assistant as a docker and I am not familiar with patching. I will apply the logger settings and provide feedback.

tmaults commented 4 years ago

Log attached. log capture.txt

emontnemery commented 4 years ago

The new log is missing the corresponding line showing the state update in HA:

2020-11-05 07:16:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.power_controller_switch ...

There is a message from the switch though, which I assume means it was turned on:

2020-11-06 07:29:40 DEBUG (MainThread) [aioesphomeapi.connection] 192.168.254.205: Got message of type <class 'api_pb2.SwitchStateResponse'>: key: 436442702
state: true

Unfortunately, the logs from esphome only show that a command is sent to the switch, but not which command (on or off) it is.

Would it be possible to reconfigure the ESPHome switch to use MQTT instead of the native protocol and try to reproduce it again?

emontnemery commented 4 years ago

@kevinkk525 are your misbehaving switches also flashed with ESPHome?

kevinkk525 commented 4 years ago

@emontnemery no, I'm using my own mqtt framework https://github.com/kevinkk525/pysmartnode

tmaults commented 4 years ago

@emontnemery

I was able to enlist the help of my son that knows much more than I do and he was able to patch the docker instance with the additional logging you requested. it is attached. log capture.txt

emontnemery commented 4 years ago

Thanks a lot @tmaults!

This very much looks like a bug in ESPHome. Since @kevinkk525 has a similar problem, it's likely in ESPHome firmware, but I'm not the expert.

- Automation triggered:
020-11-06 08:51:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=input_boolean, service=turn_on, service_data=entity_id=input_boolean.helper_test>
2020-11-06 08:51:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=input_boolean.helper_test, old_state=<state input_boolean.helper_test=off; editable=True, friendly_name=helper_test @ 2020-11-06T08:51:04.709452-07:00>, new_state=<state input_boolean.helper_test=on; editable=True, friendly_name=helper_test @ 2020-11-06T08:51:30.983357-07:00>>
2020-11-06 08:51:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=Test service.turn_on/turn_off, entity_id=automation.test_service_turn_on_turn_off, source=state of input_boolean.helper_test>
2020-11-06 08:51:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.test_service_turn_on_turn_off, old_state=<state automation.test_service_turn_on_turn_off=on; last_triggered=2020-11-06T07:29:40.762240-07:00, mode=single, current=0, id=1604578529672, friendly_name=Test service.turn_on/turn_off @ 2020-11-06T08:51:04.941342-07:00>, new_state=<state automation.test_service_turn_on_turn_off=on; last_triggered=2020-11-06T08:51:30.984817-07:00, mode=single, current=1, id=1604578529672, friendly_name=Test service.turn_on/turn_off @ 2020-11-06T08:51:04.941342-07:00>>
2020-11-06 08:51:30 INFO (MainThread) [homeassistant.components.automation.test_service_turn_on_turn_off] Test service.turn_on/turn_off: Running automation actions
2020-11-06 08:51:30 INFO (MainThread) [homeassistant.components.automation.test_service_turn_on_turn_off] Test service.turn_on/turn_off: Executing step call service
2020-11-06 08:51:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=turn_off, service_data=entity_id=['switch.power_controller_switch']>
- EsphomeSwitch.async_turn_off called - This means there is not a bug in Home Assistant's automation component
2020-11-06 08:51:30 WARNING (MainThread) [homeassistant.components.esphome.switch] EsphomeSwitch.async_turn_off switch.power_controller_switch
- aioesphomeapi sends request to switch
2020-11-06 08:51:30 DEBUG (MainThread) [aioesphomeapi.connection] 192.168.254.205: Sending <class 'api_pb2.SwitchCommandRequest'>: key: 436442702
2020-11-06 08:51:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.test_service_turn_on_turn_off, old_state=<state automation.test_service_turn_on_turn_off=on; last_triggered=2020-11-06T08:51:30.984817-07:00, mode=single, current=1, id=1604578529672, friendly_name=Test service.turn_on/turn_off @ 2020-11-06T08:51:04.941342-07:00>, new_state=<state automation.test_service_turn_on_turn_off=on; last_triggered=2020-11-06T08:51:30.984817-07:00, mode=single, current=0, id=1604578529672, friendly_name=Test service.turn_on/turn_off @ 2020-11-06T08:51:04.941342-07:00>>
- State update from the switch: Turned on
2020-11-06 08:51:31 DEBUG (MainThread) [aioesphomeapi.connection] 192.168.254.205: Got message of type <class 'api_pb2.SwitchStateResponse'>: key: 436442702 state: true
2020-11-06 08:51:31 WARNING (MainThread) [homeassistant.components.esphome] EsphomeEntity._on_state_update switch.power_controller_switch: SwitchState(key=436442702, state=True)
- HA state machine registers the state update
2020-11-06 08:51:31 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.power_controller_switch, old_state=<state switch.power_controller_switch=off; friendly_name=Pool switch, icon= @ 2020-11-06T08:51:05.600647-07:00>, new_state=<state switch.power_controller_switch=on; friendly_name=Pool switch, icon= @ 2020-11-06T08:51:31.127681-07:00>>

probot-home-assistant[bot] commented 4 years ago

esphome documentation esphome source _{^{(message by IssueLinks)}}

emontnemery commented 4 years ago

Tagging this as an ESPHome issue. Since the bug doesn't seem to be in HomeAssistant but in the firmware, maybe an issue should be opened here instead: https://github.com/esphome/issues

kevinkk525 commented 4 years ago

Hmm that was dismissed as an esphome bug too quickly. I specifically said I don't use esphome but an mqtt framework. So I doubt it is (only?) an esphome issue, otherwise I wouldn't have it. But I can't reproduce it that easily. I had maybe 5 incidents in the last 2 months, so it might take a while until I can back with a detailed log.

emontnemery commented 4 years ago

Sorry @kevinkk525 I misunderstood your message, retagged as MQTT.

tmaults commented 4 years ago

I investigated further on the ESPHome logging and found that it was a misconfiguration on a relay that was toggling state rather than setting state. I retested my automation and it is correctly leaving the switch off when triggered.

emontnemery commented 4 years ago

@tmaults great! I'll mark the conversation about ESPHome as solved.

kevinkk525 commented 3 years ago

ok it happened again and I had a look at the logs (which are gone by now as I didn't save them correctly) but I saw the problem: HA sends request ON to device, device send OFF back (no idea why but that's my issue to solve..). HA then just logs it as "Turned off by service switch.turn_on". So the behaviour of my devices is causing the problem. However, wouldn't it be better if HA just ignored this case? Because the device did not turn off because of the request, it might misbehave or (in case of an actual switch) be manually turned off just in that moment. So the logs should just say "Turned off" (by itself).

emontnemery commented 3 years ago

@kevinkk525 Alright, could it just be a timing thing; someone or something else turned the switch off just as the automation fired?

Since the MQTT protocol is 100% asynchronous without any request ID or anything like that it's impossible to know what state update is a result of which command.

At the same time it's a little bit weird that HA interprets the state update as a result of the automation.

kevinkk525 commented 3 years ago

It is possible that in some instances someone else could have turned off the switch but in the last instance there were no other activations in the debug log so for some reason it was really returning the wrong value. However, in any of those situations HA should only interpret a state change as originating from service.turn_on if the new state is indeed ON and not OFF. But I might be trying to achieve "perfection" in a very rare case.

emontnemery commented 3 years ago

I had some discussion with @bdraco about this: it is assumed that a state update is the result of a service call or automations if the state update happens within 5s of the service call. We should consider adjusting the language in the frontend, or - perhaps better - do some additional filtering of the state changes to verify that the state update matches the service call.

github-actions[bot] commented 3 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

deviantintegral commented 3 years ago

I can confirm this isn't firmware or mqtt specific, as I am seeing this issue with a ZigBee power switch via deconz.

The automation:

alias: Turn off Espresso
description: ''
trigger:
  - platform: time
    at: '19:00'
condition: []
action:
  - type: turn_off
    device_id: eae958ae221061bdad462c4894855a40
    entity_id: switch.espresso_outlet
    domain: switch
mode: single

This isn't consistent, and looks like it's only happened 2 or 3 times over the past week. I didn't have debug logging enabled, so nothing to add there.

I may modify the automation to run every minute or two to see if I can reproduce this more reliably.

deviantintegral commented 3 years ago

Ah!

it will be assumed that a state update is the result of a service call or automations if the state update happens within 5s

I misread this as "we'll change this in the future". Is this how the code currently works? If so, I think that the "turned on" line may actually have been triggered by a misconfiguration in my flux setup. That would also explain why this is only happening occasionally - it would only trigger if my kitchen lights were on and able to be updated by flux.

emontnemery commented 3 years ago

@deviantintegral yes, the comment describes the implementation as it is today, not as it may be in the future. Sorry about the confusion, I've updated my comment.

davey400 commented 3 years ago

on-off I am having a similar issue with a Zigbee device. Device is a Sonoff on/off switch.

If I turn it on in the GUI, it immediately switches of again, most of the times.

Not uing MQTT, device is paired to a Conbee, using the Phoscon web-interface to pair it and the auto-recognize by HA.

emontnemery commented 3 years ago

@davey400 that sounds completely unrelated, can you please open a new issue about that?

davey400 commented 3 years ago

How is this unrelated? The behaviour is exactly the same as the topic start; the service that is supposed to turn it on immediately turns it of again, just like the example in the TS. Only difference is that my screenshot is from a manual action, to keep things simple.

Same thing happens if an automation is used, but to eliminate factors I now only use the build-in function.

emontnemery commented 3 years ago

@davey400 The root cause of this issue is explained here: https://github.com/home-assistant/core/issues/42798#issuecomment-741007677

In short: In OP's case a turn_on service call was issued, and an unrelated state change to OFF was attributed to that service call which makes the logbook entry highly confusing. This is a general issue/weakness with how we try to pair state changes with service calls.

davey400 commented 3 years ago

"In OP's case a turn_on service call was issued, and an unrelated state change to OFF was attributed to that service call which makes the logbook entry highly confusing". That is exactly the same behaviour as what I have.

emontnemery commented 3 years ago

Then I misunderstood you, I thought your problem was that the device was being turned off immediately after you try to turn it on?

github-actions[bot] commented 3 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

home-assistant / core