Automations Trigger Slowly

Spiftacu1ar · January 23, 2019, 11:26pm

I have recently installed Lutron switches (using smart bridge pro) and setup Home assistant. I am trying to get the Pico remotes to turn on/off specific lights, a bit more complex than what lutron app allows. I have set up some automations which do the right thing, but have a response time of a few seconds.

Things I have found while attempting to debug:

The Pico remotes all show up as sensors as expected
When I push a button, sensor state changes from 0 to expected number instantly in the HA dashboard (e.g. On is 1, dim up is 8, etc), then back to 0 a few seconds later
If I toggle a light from the dashboard, the light toggles instantly.
The automation seems to affect the light when the pico state returns to 0, even though the trigger is set to trigger on to 1 (ON) from 0 or even leaving from field blank.
I also tried installing node-red and using that. Using debug window, I see that when I push a button, the transition from 0 to 1 and then back are instant and reflect the actual button position
Even with node-red, the delay in toggling lights is about the same.

I have since uninstalled node-red to eliminate it as a possible source of issues.

Any ideas what could be the issue?

pnbruckner · January 24, 2019, 3:08am

Look in home-assistant.log, and make sure DEBUG is enabled for everything. All state changes, executions of automations and scripts, even every step that is taken in an automation action or script is logged. All the detail I believe you need is right there waiting for you to look at.

I think you’ll find that automations trigger almost immediately after the events they’re waiting for happen. If there’s a delay, it’s probably in the platform code that interacts with your sensors and other devices, or in external buses, etc.

Spiftacu1ar · January 26, 2019, 4:52am

Ok, so it has taken some time to get around to this, but here are the results.

I set logger default to debug, and then used tail -f on the log file to see what is going on real time.

When I use the toggle button from the browser, I get the following output immediately, and also immediate light change:

2019-01-26 04:43:38 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974483696] Received {'service': 'turn_off', 'type': 'call_service', 'service_data': {'entity_id': 'light.master_bedroom_closet_light'}, 'domain': 'light', 'id': 32}
2019-01-26 04:43:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_off, service_data=entity_id=light.master_bedroom_closet_light, domain=light>
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.light.lutron_caseta_pro] Writing light OUTPUT value: 8 1 0 None
2019-01-26 04:43:38 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974483696] Sending {'result': None, 'type': 'result', 'id': 32, 'success': True}
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Read value for host 192.168.1.11: OUTPUT 8 1 0.000000
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.light.lutron_caseta_pro] Got light OUTPUT value: OUTPUT 8 1 0.000000
2019-01-26 04:43:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state light.master_bedroom_closet_light=on; supported_features=33, area_name=Master Bedroom, friendly_name=Master Bedroom Closet Light, brightness=255, integration_id=8 @ 2019-01-25T20:43:17.749694-08:00>, new_state=<state light.master_bedroom_closet_light=off; supported_features=33, friendly_name=Master Bedroom Closet Light, integration_id=8, area_name=Master Bedroom @ 2019-01-25T20:43:38.252674-08:00>, entity_id=light.master_bedroom_closet_light>
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:43:38 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:43:38 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974483696] Sending {'type': 'event', 'event': {'data': {'old_state': <state light.master_bedroom_closet_light=on; supported_features=33, area_name=Master Bedroom, friendly_name=Master Bedroom Closet Light, brightness=255, integration_id=8 @ 2019-01-25T20:43:17.749694-08:00>, 'new_state': <state light.master_bedroom_closet_light=off; supported_features=33, friendly_name=Master Bedroom Closet Light, integration_id=8, area_name=Master Bedroom @ 2019-01-25T20:43:38.252674-08:00>, 'entity_id': 'light.master_bedroom_closet_light'}, 'context': {'user_id': '98f89f7ea7d94be1a36ecd6d92de583a', 'id': 'ab3873379e2345f098c75e5db08ac351'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 1, 26, 4, 43, 38, 252954, tzinfo=<UTC>), 'event_type': 'state_changed'}, 'id': 2}

Alternatively, if I push a remote button, I get the following output immediately, but wait another 1-2 seconds before the light transitions. There is no additional output just before or after the light transitions:

2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Read value for host 192.168.1.11: DEVICE 6 4 3.000000
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.sensor.lutron_caseta_pro] Got DEVICE value: DEVICE 6 4 3.000000
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.sensor.lutron_caseta_pro] Got Button Press, updating value
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state sensor.master_bedroom_bedside_remote=0; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-25T20:41:54.263824-08:00>, new_state=<state sensor.master_bedroom_bedside_remote=4; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-25T20:42:00.178074-08:00>, entity_id=sensor.master_bedroom_bedside_remote>
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974483696] Sending {'type': 'event', 'event': {'data': {'old_state': <state sensor.master_bedroom_bedside_remote=0; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-25T20:41:54.263824-08:00>, 'new_state': <state sensor.master_bedroom_bedside_remote=4; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-25T20:42:00.178074-08:00>, 'entity_id': 'sensor.master_bedroom_bedside_remote'}, 'context': {'user_id': None, 'id': 'af8f3010e81b4877983e6be1e75710f0'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 1, 26, 4, 42, 0, 178303, tzinfo=<UTC>), 'event_type': 'state_changed'}, 'id': 2}
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: entity_id=automation.bedside_remote_off_press, name=Bedside Remote Off Press>
2019-01-26 04:42:00 INFO (MainThread) [homeassistant.components.automation] Executing Bedside Remote Off Press
2019-01-26 04:42:00 INFO (MainThread) [homeassistant.helpers.script] Script Bedside Remote Off Press: Running script
2019-01-26 04:42:00 INFO (MainThread) [homeassistant.helpers.script] Script Bedside Remote Off Press: Executing step call service
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_off, service_data=entity_id=['light.master_bedroom_closet_light'], transition=1, domain=light>
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.light.lutron_caseta_pro] Writing light OUTPUT value: 8 1 0 1.00
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state automation.bedside_remote_off_press=on; friendly_name=Bedside Remote Off Press, id=bedside_remote_off_press, last_triggered=2019-01-25T20:41:51.821066-08:00 @ 2019-01-25T20:31:20.799238-08:00>, new_state=<state automation.bedside_remote_off_press=on; friendly_name=Bedside Remote Off Press, id=bedside_remote_off_press, last_triggered=2019-01-25T20:42:00.242538-08:00 @ 2019-01-25T20:31:20.799238-08:00>, entity_id=automation.bedside_remote_off_press>
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974483696] Sending {'type': 'event', 'event': {'data': {'old_state': <state automation.bedside_remote_off_press=on; friendly_name=Bedside Remote Off Press, id=bedside_remote_off_press, last_triggered=2019-01-25T20:41:51.821066-08:00 @ 2019-01-25T20:31:20.799238-08:00>, 'new_state': <state automation.bedside_remote_off_press=on; friendly_name=Bedside Remote Off Press, id=bedside_remote_off_press, last_triggered=2019-01-25T20:42:00.242538-08:00 @ 2019-01-25T20:31:20.799238-08:00>, 'entity_id': 'automation.bedside_remote_off_press'}, 'context': {'user_id': None, 'id': 'af8f3010e81b4877983e6be1e75710f0'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 1, 26, 4, 42, 0, 243773, tzinfo=<UTC>), 'event_type': 'state_changed'}, 'id': 2}
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Read value for host 192.168.1.11: OUTPUT 8 1 0.000000
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.light.lutron_caseta_pro] Got light OUTPUT value: OUTPUT 8 1 0.000000
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state light.master_bedroom_closet_light=on; supported_features=33, area_name=Master Bedroom, friendly_name=Master Bedroom Closet Light, brightness=255, integration_id=8 @ 2019-01-25T20:41:54.212864-08:00>, new_state=<state light.master_bedroom_closet_light=off; supported_features=33, friendly_name=Master Bedroom Closet Light, integration_id=8, area_name=Master Bedroom @ 2019-01-25T20:42:00.278128-08:00>, entity_id=light.master_bedroom_closet_light>
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974483696] Sending {'type': 'event', 'event': {'data': {'old_state': <state light.master_bedroom_closet_light=on; supported_features=33, area_name=Master Bedroom, friendly_name=Master Bedroom Closet Light, brightness=255, integration_id=8 @ 2019-01-25T20:41:54.212864-08:00>, 'new_state': <state light.master_bedroom_closet_light=off; supported_features=33, friendly_name=Master Bedroom Closet Light, integration_id=8, area_name=Master Bedroom @ 2019-01-25T20:42:00.278128-08:00>, 'entity_id': 'light.master_bedroom_closet_light'}, 'context': {'user_id': None, 'id': 'af8f3010e81b4877983e6be1e75710f0'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 1, 26, 4, 42, 0, 278362, tzinfo=<UTC>), 'event_type': 'state_changed'}, 'id': 2}
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Read value for host 192.168.1.11: DEVICE 6 4 4.000000
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.sensor.lutron_caseta_pro] Got DEVICE value: DEVICE 6 4 4.000000
2019-01-26 04:42:00 DEBUG (MainThread) [custom_components.sensor.lutron_caseta_pro] Got Button Release, updating value
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state sensor.master_bedroom_bedside_remote=4; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-25T20:42:00.178074-08:00>, new_state=<state sensor.master_bedroom_bedside_remote=0; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-25T20:42:00.405522-08:00>, entity_id=sensor.master_bedroom_bedside_remote>
2019-01-26 04:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974483696] Sending {'type': 'event', 'event': {'data': {'old_state': <state sensor.master_bedroom_bedside_remote=4; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-25T20:42:00.178074-08:00>, 'new_state': <state sensor.master_bedroom_bedside_remote=0; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-25T20:42:00.405522-08:00>, 'entity_id': 'sensor.master_bedroom_bedside_remote'}, 'context': {'user_id': None, 'id': 'ac47d6b212954190bffa99cdc550e1df'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 1, 26, 4, 42, 0, 405685, tzinfo=<UTC>), 'event_type': 'state_changed'}, 'id': 2}

pnbruckner · January 26, 2019, 12:55pm

Well, here’s the difference. In the first instance (manual turn off) the light.turn_off service contained this data:

service_data=entity_id=light.master_bedroom_closet_light

And in the second instance (turn off from automation) the light.turn_off service contained this data:

service_data=entity_id=['light.master_bedroom_closet_light'], transition=1

Notice the transition=1? So you wrote the service call in the automation to make the light turn off more slowly. If you don’t want that, then remove the transition argument.

Spiftacu1ar · January 26, 2019, 7:19pm

The transition occurs after the wait time I describe in this issue. Lutron has a default transition that seems to be slightly longer than 1s, so that actually makes it transition faster.

For the sake of thoroughness, I have removed the transition and brightness specifiers. I still have the additional response delay of 1-2s before the light starts to turn on.

2019-01-26 19:11:50 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Read value for host 192.168.1.11: DEVICE 6 2 3.000000
2019-01-26 19:11:50 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:50 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:50 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:50 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:50 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:50 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.sensor.lutron_caseta_pro] Got DEVICE value: DEVICE 6 2 3.000000
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.sensor.lutron_caseta_pro] Got Button Press, updating value
2019-01-26 19:11:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state sensor.master_bedroom_bedside_remote=0; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-26T11:11:41.102813-08:00>, new_state=<state sensor.master_bedroom_bedside_remote=1; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-26T11:11:51.004994-08:00>, entity_id=sensor.master_bedroom_bedside_remote>
2019-01-26 19:11:51 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974130032] Sending {'type': 'event', 'event': {'data': {'old_state': <state sensor.master_bedroom_bedside_remote=0; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-26T11:11:41.102813-08:00>, 'new_state': <state sensor.master_bedroom_bedside_remote=1; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-26T11:11:51.004994-08:00>, 'entity_id': 'sensor.master_bedroom_bedside_remote'}, 'context': {'user_id': None, 'id': '7d8ac51b4ab8463c8925631fce4fb431'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 1, 26, 19, 11, 51, 5201, tzinfo=<UTC>), 'event_type': 'state_changed'}, 'id': 2}
2019-01-26 19:11:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: entity_id=automation.bedside_remote_on_press, name=Bedside Remote On Press>
2019-01-26 19:11:51 INFO (MainThread) [homeassistant.components.automation] Executing Bedside Remote On Press
2019-01-26 19:11:51 INFO (MainThread) [homeassistant.helpers.script] Script Bedside Remote On Press: Running script
2019-01-26 19:11:51 INFO (MainThread) [homeassistant.helpers.script] Script Bedside Remote On Press: Executing step call service
2019-01-26 19:11:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_on, service_data=entity_id=['light.master_bedroom_closet_light'], domain=light>
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.light.lutron_caseta_pro] Writing light OUTPUT value: 8 1 100 None
2019-01-26 19:11:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state automation.bedside_remote_on_press=on; friendly_name=Bedside Remote On Press, id=bedside_remote_on_press, last_triggered=2019-01-26T11:11:41.019561-08:00 @ 2019-01-26T11:11:36.218002-08:00>, new_state=<state automation.bedside_remote_on_press=on; friendly_name=Bedside Remote On Press, id=bedside_remote_on_press, last_triggered=2019-01-26T11:11:51.076168-08:00 @ 2019-01-26T11:11:36.218002-08:00>, entity_id=automation.bedside_remote_on_press>
2019-01-26 19:11:51 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974130032] Sending {'type': 'event', 'event': {'data': {'old_state': <state automation.bedside_remote_on_press=on; friendly_name=Bedside Remote On Press, id=bedside_remote_on_press, last_triggered=2019-01-26T11:11:41.019561-08:00 @ 2019-01-26T11:11:36.218002-08:00>, 'new_state': <state automation.bedside_remote_on_press=on; friendly_name=Bedside Remote On Press, id=bedside_remote_on_press, last_triggered=2019-01-26T11:11:51.076168-08:00 @ 2019-01-26T11:11:36.218002-08:00>, 'entity_id': 'automation.bedside_remote_on_press'}, 'context': {'user_id': None, 'id': '7d8ac51b4ab8463c8925631fce4fb431'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 1, 26, 19, 11, 51, 77227, tzinfo=<UTC>), 'event_type': 'state_changed'}, 'id': 2}
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Read value for host 192.168.1.11: OUTPUT 8 1 100.000000
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.light.lutron_caseta_pro] Got light OUTPUT value: OUTPUT 8 1 100.000000
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Read value for host 192.168.1.11: DEVICE 6 2 4.000000
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.lutron_caseta_pro] Invoking callback for host 192.168.1.11
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.sensor.lutron_caseta_pro] Got DEVICE value: DEVICE 6 2 4.000000
2019-01-26 19:11:51 DEBUG (MainThread) [custom_components.sensor.lutron_caseta_pro] Got Button Release, updating value
2019-01-26 19:11:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state sensor.master_bedroom_bedside_remote=1; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-26T11:11:51.004994-08:00>, new_state=<state sensor.master_bedroom_bedside_remote=0; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-26T11:11:51.223399-08:00>, entity_id=sensor.master_bedroom_bedside_remote>
2019-01-26 19:11:51 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1974130032] Sending {'type': 'event', 'event': {'data': {'old_state': <state sensor.master_bedroom_bedside_remote=1; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-26T11:11:51.004994-08:00>, 'new_state': <state sensor.master_bedroom_bedside_remote=0; friendly_name=Master Bedroom Bedside Remote, integration_id=6, area_name=Master Bedroom @ 2019-01-26T11:11:51.223399-08:00>, 'entity_id': 'sensor.master_bedroom_bedside_remote'}, 'context': {'user_id': None, 'id': 'eaaa98ae366841f49d43d2adb5b7f346'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2019, 1, 26, 19, 11, 51, 223537, tzinfo=<UTC>), 'event_type': 'state_changed'}, 'id': 2}

pnbruckner, thank you for taking the time to help me diagnose this issue!

pnbruckner · January 26, 2019, 9:37pm

So the button being pressed (that triggers the remote) goes through the lutron component, same as the light, right? Maybe they’re interfering with each other. I mean, maybe the communications concerning the button press and its release are delaying the message getting through that changes the light. Just a guess. Certainly the automation is reacting immediately and calling the light service immediately. Must be in the lutron component.

Spiftacu1ar · January 26, 2019, 10:10pm

I think you are right. I just stopped my HA server, and starting messing with direct telnet commands with the lutron bridge.

#OUTPUT,8,1,100 and #OUTPUT,8,1,0 both instantly turn the light on or off.

If I push a button on the remote right before pushing enter on the telnet command, I get the delay in starting a light. This seems to be an issue with me lutron hub, which is unfortunate. Lots of people say they have really good luck with HA and the smart bridge pro though. It’s curious that no one else seems to reporting really slow response from the lutron side.