Ugh, this happened again this morning with the master bedroom light! This has to be a bug in HA somewhere but tracking this down would be pretty impossible considering how infrequence it happens. I’ve had my logs on debug since the last instance months ago so I was able to trace through it but besides the normal zwave status updates I see the only reference to the light turning on is this:
2019-12-08 05:32:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=zwave.bedroom_light, old_state=<state zwave.bedroom_light=ready; node_id=5, node_name=Bedroom Light, manufacturer_name=Cooper, product_name=RF9534DS Wall Dimmer Module, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=False, capabilities={'routing', 'listening'}, neighbors={1, 2, 3, 4, 7, 10, 11, 12, 14, 15, 19, 20, 22, 23, 24, 26, 27, 28, 29, 30}, sentCnt=8436, sentFailed=96, retries=25, receivedCnt=8697, receivedDups=240, receivedUnsolicited=39, sentTS=2019-12-08 05:32:06:122 , receivedTS=2019-12-08 05:32:06:213 , lastRequestRTT=83, averageRequestRTT=50, lastResponseRTT=90, averageResponseRTT=57, application_version=1.12, friendly_name=Bedroom Light @ 2019-12-07T06:54:00.379671-05:00>, new_state=<state zwave.bedroom_light=ready; node_id=5, node_name=Bedroom Light, manufacturer_name=Cooper, product_name=RF9534DS Wall Dimmer Module, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=False, capabilities={'routing', 'listening'}, neighbors={1, 2, 3, 4, 7, 10, 11, 12, 14, 15, 19, 20, 22, 23, 24, 26, 27, 28, 29, 30}, sentCnt=8437, sentFailed=96, retries=25, receivedCnt=8698, receivedDups=240, receivedUnsolicited=39, sentTS=2019-12-08 05:32:08:220 , receivedTS=2019-12-08 05:32:08:246 , lastRequestRTT=18, averageRequestRTT=34, lastResponseRTT=25, averageResponseRTT=41, application_version=1.12, friendly_name=Bedroom Light @ 2019-12-07T06:54:00.379671-05:00>>
2019-12-08 05:32:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.bedroom_light_level, old_state=<state light.bedroom_light_level=off; node_id=5, value_index=0, value_instance=1, value_id=72057594126630913, friendly_name=Bedroom Light, supported_features=33 @ 2019-12-07T17:30:42.528597-05:00>, new_state=<state light.bedroom_light_level=on; brightness=240, node_id=5, value_index=0, value_instance=1, value_id=72057594126630913, friendly_name=Bedroom Light, supported_features=33 @ 2019-12-08T05:32:08.366538-05:00>>
2019-12-08 05:32:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139813407445968] Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'zwave.bedroom_light', 'old_state': <state zwave.bedroom_light=ready; node_id=5, node_name=Bedroom Light, manufacturer_name=Cooper, product_name=RF9534DS Wall Dimmer Module, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=False, capabilities={'routing', 'listening'}, neighbors={1, 2, 3, 4, 7, 10, 11, 12, 14, 15, 19, 20, 22, 23, 24, 26, 27, 28, 29, 30}, sentCnt=8436, sentFailed=96, retries=25, receivedCnt=8697, receivedDups=240, receivedUnsolicited=39, sentTS=2019-12-08 05:32:06:122 , receivedTS=2019-12-08 05:32:06:213 , lastRequestRTT=83, averageRequestRTT=50, lastResponseRTT=90, averageResponseRTT=57, application_version=1.12, friendly_name=Bedroom Light @ 2019-12-07T06:54:00.379671-05:00>, 'new_state': <state zwave.bedroom_light=ready; node_id=5, node_name=Bedroom Light, manufacturer_name=Cooper, product_name=RF9534DS Wall Dimmer Module, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=False, capabilities={'routing', 'listening'}, neighbors={1, 2, 3, 4, 7, 10, 11, 12, 14, 15, 19, 20, 22, 23, 24, 26, 27, 28, 29, 30}, sentCnt=8437, sentFailed=96, retries=25, receivedCnt=8698, receivedDups=240, receivedUnsolicited=39, sentTS=2019-12-08 05:32:08:220 , receivedTS=2019-12-08 05:32:08:246 , lastRequestRTT=18, averageRequestRTT=34, lastResponseRTT=25, averageResponseRTT=41, application_version=1.12, friendly_name=Bedroom Light @ 2019-12-07T06:54:00.379671-05:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 12, 8, 10, 32, 8, 363032, tzinfo=<UTC>), 'context': {'id': 'e85bae8c3dff4d8ebf6c0e262c38602c', 'parent_id': None, 'user_id': None}}}
It just appears to happen. For context, at 5:30 every day I have a set of lights turn on, the bedroom light is not one of them. Everyday, for months (years) this has worked fine but randomly another light will turn on (or one of the ones that should turn on, don’t) and it can cause problems. It’s not a linked light or part of an automation as it would happen more frequently, this is clearly some kind of race condition/bug in the system when the stars are aligning. This morning, in addition to our bedroom light two other lights came on too that are not part of the animation, one of which is the pantry light that only turns on if the door sensor is triggered which it was not but the light was on.
2019-12-08 05:32:01 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.pantry, old_state=<state light.pantry=off; friendly_name=Pantry Light, supported_features=41 @ 2019-12-07T16:52:37.703943-05:00>, new_state=<state light.pantry=on; brightness=254, friendly_name=Pantry Light, supported_features=41 @ 2019-12-08T05:32:01.252449-05:00>>
Any thoughts?