I am trying to create an automation that will trigger when I press a key on a Fibaro 601 keyfob and turn on a reading light switch.
When I use the keyfob I see entries in the log for the “zwave.scene_activated” event (suffix is [L]) but the automation does not execute. If I enter the event into the developer tools events page, then I see the log entry for “zwave.scene_activated” event (suffix is [R]), and in that case the automation executes.
The logs are as follows, first when pressing the keyfob button:
2018-08-30 11:47:55 DEBUG (Dummy-3) [libopenzwave] notif_callback : new notification
2018-08-30 11:47:55 DEBUG (Dummy-3) [libopenzwave] notif_callback : Notification type : 2, nodeId : 4
2018-08-30 11:47:55 DEBUG (Dummy-3) [libopenzwave] addValueId : ValueID : 72057594110722067
2018-08-30 11:47:55 DEBUG (Dummy-3) [libopenzwave] addValueId : GetCommandClassId : 91, GetType : 3
2018-08-30 11:47:55 DEBUG (Dummy-3) [libopenzwave] addValueId : Notification : {'notificationType': 'ValueChanged', 'homeId': 3445027483, 'nodeId': 4, 'valueId': {'homeId': 3445027483, 'nodeId': 4, 'commandClass': 'COMMAND_CLASS_CENTRAL_SCENE', 'instance': 1, 'index': 1, 'id': 72057594110722067, 'genre': 'User', 'type': 'Int', 'value': 7680, 'label': 'Square', 'units': '', 'readOnly': False}}
2018-08-30 11:47:55 DEBUG (Dummy-3) [libopenzwave] notif_callback : call callback context
2018-08-30 11:47:55 DEBUG (Dummy-3) [openzwave] zwcallback args=[{'notificationType': 'ValueChanged', 'homeId': 3445027483, 'nodeId': 4, 'valueId': {'homeId': 3445027483, 'nodeId': 4, 'commandClass': 'COMMAND_CLASS_CENTRAL_SCENE', 'instance': 1, 'index': 1, 'id': 72057594110722067, 'genre': 'User', 'type': 'Int', 'value': 7680, 'label': 'Square', 'units': '', 'readOnly': False}}]
2018-08-30 11:47:55 DEBUG (Dummy-3) [openzwave] Z-Wave Notification ValueChanged : {'notificationType': 'ValueChanged', 'homeId': 3445027483, 'nodeId': 4, 'valueId': {'homeId': 3445027483, 'nodeId': 4, 'commandClass': 'COMMAND_CLASS_CENTRAL_SCENE', 'instance': 1, 'index': 1, 'id': 72057594110722067, 'genre': 'User', 'type': 'Int', 'value': 7680, 'label': 'Square', 'units': '', 'readOnly': False}}
2018-08-30 11:47:55 DEBUG (Dummy-3) [libopenzwave] notif_callback : end
2018-08-30 11:47:55 INFO (MainThread) [homeassistant.core] Bus:Handling <Event zwave.scene_activated[L]: entity_id=zwave.fibaro_system_fgkf601_keyfob, node_id=4, scene_id=1, scene_data=7680>
2018-08-30 11:47:55 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=zwave.fibaro_system_fgkf601_keyfob, old_state=<state zwave.fibaro_system_fgkf601_keyfob=initializing; node_id=4, node_name=FIBARO System FGKF601 Keyfob, manufacturer_name=FIBARO System, product_name=FGKF601 Keyfob, query_stage=CacheLoad, is_awake=False, is_ready=False, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'zwave_plus', 'beaming', 'routing'}, sentCnt=1, sentFailed=1, retries=0, receivedCnt=0, receivedDups=0, receivedUnsolicited=0, sentTS=2018-08-30 11:47:04:321 , receivedTS=2018-08-30 11:47:04:043 , lastRequestRTT=0, averageRequestRTT=0, lastResponseRTT=0, averageResponseRTT=0, battery_level=37, wake_up_interval=0, friendly_name=FIBARO System FGKF601 Keyfob @ 2018-08-30T10:47:04.250003+00:00>, new_state=<state zwave.fibaro_system_fgkf601_keyfob=initializing; node_id=4, node_name=FIBARO System FGKF601 Keyfob, manufacturer_name=FIBARO System, product_name=FGKF601 Keyfob, query_stage=CacheLoad, is_awake=False, is_ready=False, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'zwave_plus', 'beaming', 'routing'}, sentCnt=1, sentFailed=1, retries=0, receivedCnt=1, receivedDups=0, receivedUnsolicited=1, sentTS=2018-08-30 11:47:04:321 , receivedTS=2018-08-30 11:47:55:761 , lastRequestRTT=0, averageRequestRTT=0, lastResponseRTT=0, averageResponseRTT=0, battery_level=37, wake_up_interval=0, friendly_name=FIBARO System FGKF601 Keyfob @ 2018-08-30T10:47:04.250003+00:00>>
2018-08-30 11:47:55 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140692596228280: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'zwave.fibaro_system_fgkf601_keyfob', 'old_state': <state zwave.fibaro_system_fgkf601_keyfob=initializing; node_id=4, node_name=FIBARO System FGKF601 Keyfob, manufacturer_name=FIBARO System, product_name=FGKF601 Keyfob, query_stage=CacheLoad, is_awake=False, is_ready=False, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'zwave_plus', 'beaming', 'routing'}, sentCnt=1, sentFailed=1, retries=0, receivedCnt=0, receivedDups=0, receivedUnsolicited=0, sentTS=2018-08-30 11:47:04:321 , receivedTS=2018-08-30 11:47:04:043 , lastRequestRTT=0, averageRequestRTT=0, lastResponseRTT=0, averageResponseRTT=0, battery_level=37, wake_up_interval=0, friendly_name=FIBARO System FGKF601 Keyfob @ 2018-08-30T10:47:04.250003+00:00>, 'new_state': <state zwave.fibaro_system_fgkf601_keyfob=initializing; node_id=4, node_name=FIBARO System FGKF601 Keyfob, manufacturer_name=FIBARO System, product_name=FGKF601 Keyfob, query_stage=CacheLoad, is_awake=False, is_ready=False, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'zwave_plus', 'beaming', 'routing'}, sentCnt=1, sentFailed=1, retries=0, receivedCnt=1, receivedDups=0, receivedUnsolicited=1, sentTS=2018-08-30 11:47:04:321 , receivedTS=2018-08-30 11:47:55:761 , lastRequestRTT=0, averageRequestRTT=0, lastResponseRTT=0, averageResponseRTT=0, battery_level=37, wake_up_interval=0, friendly_name=FIBARO System FGKF601 Keyfob @ 2018-08-30T10:47:04.250003+00:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 8, 30, 10, 47, 55, 867554, tzinfo=<UTC>), 'context': {'id': 'c6c6af7eb4a84247a9d85cdbb6429f99', 'user_id': None}}}
and now when synthethising the event in the Events tool:
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.core] Bus:Handling <Event zwave.scene_activated[R]: entity_id=zwave.fibaro_system_fgkf601_keyfob, scene_id=1, scene_data=7680>
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.components.automation] Executing Office Light
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.core] Bus:Handling <Event logbook_entry[L]: name=Office Light, message=has been triggered, domain=automation, entity_id=automation.office_light>
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.helpers.script] Script Office Light: Running script
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.helpers.script] Script Office Light: Executing step call service
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=turn_on, service_data=entity_id=switch.reading_lamp>
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=mqtt, service=publish, service_data=topic=smartthings/outlet (reading light)/switch, qos=0, retain=True, payload=on>
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]>
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]>
2018-08-30 11:49:48 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.office_light, old_state=<state automation.office_light=on; last_triggered=None, id=1535621037915, friendly_name=Office Light @ 2018-08-30T10:49:26.113554+00:00>, new_state=<state automation.office_light=on; last_triggered=2018-08-30T10:49:48.512825+00:00, id=1535621037915, friendly_name=Office Light @ 2018-08-30T10:49:26.113554+00:00>>
2018-08-30 11:49:48 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on smartthings/outlet (reading light)/switch: b'on'
I have run out of ideas as to what to look at next to investigate why the keyfob event doesnt trigger the automation. The only obvious difference is the suffix on the event in the logs [L] versus [R], but I have no idea if that is significant or really what it means.
Any ideas on how to fix this would be appreciated.
–philip