Delay in light turning on using automation

[Fonta]

Home Assistant release (hass --version):
0.36.0.dev0 (But also in latest stable)

Python release (python3 --version):
Python 3.4.2

Component/platform:
switch/light/rfxtrx
remote and switch are KlikAanKlikUit (ClickOnClickOff) devices.
rfxtrx module is this one: http://www.rfxcom.com/store/Transceivers/14103

Description of problem:
There's a short delay after an automation is triggered to turn on a light which is a few seconds.

When you activate the motion sensor (also could be a signal from a remote control), the corresponding switch and light turn on in the webinterface almost instantly,
but then after that in reality it takes another +/- 2 seconds for the lights to turn on.
If you turn the switch "on" in the webinterface yourself, the light does turn on instantly.
The size of the installation didn't seem to matter, I made a clean install with only 1 light, 1 switch and 1 automation and everything else disabled but was the same.
I also tried different types of triggers and showing the motion sensor as a binary switch, but with no luck.
creating a binary_sensor out of the motionswitch, and attaching the trigger to this didn't help either.

The +/- 2 seconds doesn't seem long, but for me it's enough time to be at least at the half of the hallway.

Expected:
Expectation is that the light turn on immediatly, like pressing a button on the webinterface, after motion is detected.

Problem-relevant configuration.yaml entries and steps to reproduce:

switch:
  - platform: rfxtrx
    automatic_add: False
    devices:
      0b110000014a655a0a000050:
        name: Motion Hallway

light:
  - platform: rfxtrx
    devices:
      0b11000423bc0cfe00010f70:
        name: Hallway

automation:
  alias: Turn on light hallway on movement
  trigger:
    platform: template
    value_template: "{{ is_state('switch.motion_hallway', 'on') }}"
  action:
    service: light.turn_on
    entity_id: light.hallway

1. Motion sensor get activated by motion and sends an "on" signal".
2. The rfxtrx module get this, and passes it to HA
3. Motion sensor turns "on" in webinterface
4. HA executes automation
5. Light turns "on" in webinterface
   -- +/- 2 seconds delay --
6. Light really turns on
   Untill step 5 everything seems to be pretty instant.

Traceback (if applicable):

DEBUG:homeassistant.components.rfxtrx:Receive RFXCOM event from (Device_id: 14a655a10 Class: LightingDevice Sub: 0, Pkt_id: 0b110000014a655a0a010f50)
DEBUG:homeassistant.components.rfxtrx:Device_id: 14a655a10 device_update. Command: On
INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=<state switch.motion_hallway=off; friendly_name=Motion Hallway, assumed_state=True, hidden=True @ 2017-01-11T11:58:35.980616+01:00>, entity_id=switch.motion_hallway, new_state=<state switch.motion_hallway=on; friendly_name=Motion Hallway, assumed_state=True, hidden=True @ 2017-01-11T11:59:24.353260+01:00>>
DEBUG:homeassistant.components.websocket_api:WS 1860221072: Sending {'type': 'event', 'event': {'time_fired': datetime.datetime(2017, 1, 11, 10, 59, 24, 353536, tzinfo=<UTC>), 'origin': 'LOCAL', 'event_type': 'state_changed', 'data': {'old_state': <state switch.motion_hallway=off; friendly_name=Motion Hallway, assumed_state=True, hidden=True @ 2017-01-11T11:58:35.980616+01:00>, 'entity_id': 'switch.motion_hallway', 'new_state': <state switch.motion_hallway=on; friendly_name=Motion Hallway, assumed_state=True, hidden=True @ 2017-01-11T11:59:24.353260+01:00>}}, 'id': 2}
INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=<state binary_sensor.hallway_movement=off; friendly_name=hallway_movement, sensor_class=motion @ 2017-01-11T11:58:34.936308+01:00>, entity_id=binary_sensor.hallway_movement, new_state=<state binary_sensor.hallway_movement=on; friendly_name=hallway_movement, sensor_class=motion @ 2017-01-11T11:59:24.401141+01:00>>
INFO:homeassistant.components.automation:Executing Turn on light hallway on movement
INFO:homeassistant.core:Bus:Handling <Event logbook_entry[L]: domain=automation, message=has been triggered, name=Turn on light hallway on movement, entity_id=automation.turn_on_light_hallway_on_movement>
INFO:homeassistant.helpers.script:Script Turn on light hallway on movement: Running script
INFO:homeassistant.helpers.script:Script Turn on light hallway on movement: Executing step call service
INFO:homeassistant.core:Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_call_id=1977334896-2, service_data=brightness=70, entity_id=['light.hallway']>
DEBUG:homeassistant.components.websocket_api:WS 1860221072: Sending {'type': 'event', 'event': {'time_fired': datetime.datetime(2017, 1, 11, 10, 59, 24, 401378, tzinfo=<UTC>), 'origin': 'LOCAL', 'event_type': 'state_changed', 'data': {'old_state': <state binary_sensor.hallway_movement=off; friendly_name=hallway_movement, sensor_class=motion @ 2017-01-11T11:58:34.936308+01:00>, 'entity_id': 'binary_sensor.hallway_movement', 'new_state': <state binary_sensor.hallway_movement=on; friendly_name=hallway_movement, sensor_class=motion @ 2017-01-11T11:59:24.401141+01:00>}}, 'id': 2}
INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=<state group.automation_motion_sensors=off; friendly_name=Motion Sensors, order=30, entity_id=('binary_sensor.hallway_movement', 'binary_sensor.toilet_movement') @ 2017-01-11T11:58:54.430337+01:00>, entity_id=group.automation_motion_sensors, new_state=<state group.automation_motion_sensors=on; friendly_name=Motion Sensors, order=30, entity_id=('binary_sensor.hallway_movement', 'binary_sensor.toilet_movement') @ 2017-01-11T11:59:24.438459+01:00>>
DEBUG:homeassistant.components.websocket_api:WS 1860221072: Sending {'type': 'event', 'event': {'time_fired': datetime.datetime(2017, 1, 11, 10, 59, 24, 438684, tzinfo=<UTC>), 'origin': 'LOCAL', 'event_type': 'state_changed', 'data': {'old_state': <state group.automation_motion_sensors=off; friendly_name=Motion Sensors, order=30, entity_id=('binary_sensor.hallway_movement', 'binary_sensor.toilet_movement') @ 2017-01-11T11:58:54.430337+01:00>, 'entity_id': 'group.automation_motion_sensors', 'new_state': <state group.automation_motion_sensors=on; friendly_name=Motion Sensors, order=30, entity_id=('binary_sensor.hallway_movement', 'binary_sensor.toilet_movement') @ 2017-01-11T11:59:24.438459+01:00>}}, 'id': 2}
INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=<state light.hallway=off; supported_features=1, friendly_name=Hallway, assumed_state=True @ 2017-01-11T11:58:34.589379+01:00>, entity_id=light.hallway, new_state=<state light.hallway=on; supported_features=1, friendly_name=Hallway, brightness=70, assumed_state=True @ 2017-01-11T11:59:24.461722+01:00>>
DEBUG:homeassistant.components.websocket_api:WS 1860221072: Sending {'type': 'event', 'event': {'time_fired': datetime.datetime(2017, 1, 11, 10, 59, 24, 461928, tzinfo=<UTC>), 'origin': 'LOCAL', 'event_type': 'state_changed', 'data': {'old_state': <state light.hallway=off; supported_features=1, friendly_name=Hallway, assumed_state=True @ 2017-01-11T11:58:34.589379+01:00>, 'entity_id': 'light.hallway', 'new_state': <state light.hallway=on; supported_features=1, friendly_name=Hallway, brightness=70, assumed_state=True @ 2017-01-11T11:59:24.461722+01:00>}}, 'id': 2}
INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=<state group.all_lights=off; auto=True, entity_id=('light.hallway', 'light.big_livingroom', 'light.window', 'light.toilet', 'light.big_bedroom', 'light.door_side', 'light.floor_led', 'light.window_side', 'light.desk', 'light.door'), hidden=True, friendly_name=all lights, order=0, assumed_state=True @ 2017-01-11T11:58:34.594081+01:00>, entity_id=group.all_lights, new_state=<state group.all_lights=on; auto=True, entity_id=('light.hallway', 'light.big_livingroom', 'light.window', 'light.toilet', 'light.big_bedroom', 'light.door_side', 'light.floor_led', 'light.window_side', 'light.desk', 'light.door'), hidden=True, friendly_name=all lights, order=0, assumed_state=True @ 2017-01-11T11:59:24.478558+01:00>>
INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=<state group.hallway_lights=off; friendly_name=Hallway, order=11, entity_id=('light.hallway',), assumed_state=True @ 2017-01-11T11:58:54.370259+01:00>, entity_id=group.hallway_lights, new_state=<state group.hallway_lights=on; friendly_name=Hallway, order=11, entity_id=('light.hallway',), assumed_state=True @ 2017-01-11T11:59:24.483987+01:00>>
DEBUG:homeassistant.components.websocket_api:WS 1860221072: Sending {'type': 'event', 'event': {'time_fired': datetime.datetime(2017, 1, 11, 10, 59, 24, 478706, tzinfo=<UTC>), 'origin': 'LOCAL', 'event_type': 'state_changed', 'data': {'old_state': <state group.all_lights=off; auto=True, entity_id=('light.hallway', 'light.big_livingroom', 'light.window', 'light.toilet', 'light.big_bedroom', 'light.door_side', 'light.floor_led', 'light.window_side', 'light.desk', 'light.door'), hidden=True, friendly_name=all lights, order=0, assumed_state=True @ 2017-01-11T11:58:34.594081+01:00>, 'entity_id': 'group.all_lights', 'new_state': <state group.all_lights=on; auto=True, entity_id=('light.hallway', 'light.big_livingroom', 'light.window', 'light.toilet', 'light.big_bedroom', 'light.door_side', 'light.floor_led', 'light.window_side', 'light.desk', 'light.door'), hidden=True, friendly_name=all lights, order=0, assumed_state=True @ 2017-01-11T11:59:24.478558+01:00>}}, 'id': 2}
DEBUG:homeassistant.components.websocket_api:WS 1860221072: Sending {'type': 'event', 'event': {'time_fired': datetime.datetime(2017, 1, 11, 10, 59, 24, 484122, tzinfo=<UTC>), 'origin': 'LOCAL', 'event_type': 'state_changed', 'data': {'old_state': <state group.hallway_lights=off; friendly_name=Hallway, order=11, entity_id=('light.hallway',), assumed_state=True @ 2017-01-11T11:58:54.370259+01:00>, 'entity_id': 'group.hallway_lights', 'new_state': <state group.hallway_lights=on; friendly_name=Hallway, order=11, entity_id=('light.hallway',), assumed_state=True @ 2017-01-11T11:59:24.483987+01:00>}}, 'id': 2}
INFO:homeassistant.core:Bus:Handling <Event service_executed[L]: service_call_id=1977334896-2>
INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=<state group.lights_view=off; hidden=True, entity_id=('group.living_room_lights', 'group.bedroom_lights', 'group.hallway_lights', 'group.toilet_lights'), icon=mdi:lightbulb, friendly_name=Lights, view=True, order=4, assumed_state=True @ 2017-01-11T11:58:54.481564+01:00>, entity_id=group.lights_view, new_state=<state group.lights_view=on; hidden=True, entity_id=('group.living_room_lights', 'group.bedroom_lights', 'group.hallway_lights', 'group.toilet_lights'), icon=mdi:lightbulb, friendly_name=Lights, view=True, order=4, assumed_state=True @ 2017-01-11T11:59:24.498697+01:00>>
DEBUG:homeassistant.components.websocket_api:WS 1860221072: Sending {'type': 'event', 'event': {'time_fired': datetime.datetime(2017, 1, 11, 10, 59, 24, 498830, tzinfo=<UTC>), 'origin': 'LOCAL', 'event_type': 'state_changed', 'data': {'old_state': <state group.lights_view=off; hidden=True, entity_id=('group.living_room_lights', 'group.bedroom_lights', 'group.hallway_lights', 'group.toilet_lights'), icon=mdi:lightbulb, friendly_name=Lights, view=True, order=4, assumed_state=True @ 2017-01-11T11:58:54.481564+01:00>, 'entity_id': 'group.lights_view', 'new_state': <state group.lights_view=on; hidden=True, entity_id=('group.living_room_lights', 'group.bedroom_lights', 'group.hallway_lights', 'group.toilet_lights'), icon=mdi:lightbulb, friendly_name=Lights, view=True, order=4, assumed_state=True @ 2017-01-11T11:59:24.498697+01:00>}}, 'id': 2}
INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=<state automation.turn_on_light_hallway_on_movement=on; friendly_name=Turn on light hallway on movement, last_triggered=None @ 2017-01-11T11:58:54.784060+01:00>, entity_id=automation.turn_on_light_hallway_on_movement, new_state=<state automation.turn_on_light_hallway_on_movement=on; friendly_name=Turn on light hallway on movement, last_triggered=2017-01-11T11:59:24.508082+01:00 @ 2017-01-11T11:58:54.784060+01:00>>
DEBUG:homeassistant.components.websocket_api:WS 1860221072: Sending {'type': 'event', 'event': {'time_fired': datetime.datetime(2017, 1, 11, 10, 59, 24, 508606, tzinfo=<UTC>), 'origin': 'LOCAL', 'event_type': 'state_changed', 'data': {'old_state': <state automation.turn_on_light_hallway_on_movement=on; friendly_name=Turn on light hallway on movement, last_triggered=None @ 2017-01-11T11:58:54.784060+01:00>, 'entity_id': 'automation.turn_on_light_hallway_on_movement', 'new_state': <state automation.turn_on_light_hallway_on_movement=on; friendly_name=Turn on light hallway on movement, last_triggered=2017-01-11T11:59:24.508082+01:00 @ 2017-01-11T11:58:54.784060+01:00>}}, 'id': 2}

Additional info:
Thread on the forum:
https://community.home-assistant.io/t/slow-to-trigger-motion-via-wired-pir/8775

[Fonta]

Made a little movie where you can see the delay.
As soon as I move my hand accross the motion sensor, it gets received by HA and the ligt_on action is being triggerd, but after that there's a delay.
https://www.youtube.com/watch?v=Ovml40Qh3Vc

[pvizeli]

Work good for my with homematic/hue. Do you have a delay on switch light by UI?

[Fonta]

@pvizeli There's practically no delay when I activate a light in the UI.

In short: no delay turning on a light on the web interface. 2-3 seconds delay in turning on/of by automation.

[balloobbot]

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 👍

[Fonta]

@balloobbot Latest dev still has the same problem.

[niektenhoopen]

I think I have the same issue in HASS 0.45.1. Python 3.4.2. Identical setup, including RFXTRX module.

• motion is detected through motion sensor (I've tested with a Fibaro Z-Wave Motion Sensor and the COCO/KAKU motion sensor)
• gui switch toggles instantly in HASS
• HASS automation runs (gui switch on => light on)
• light in gui switches to 'on' in HASS
• after about 2 seconds the actual light (COCO/KAKU) turns on

If I manually turn on the light in the gui, it turns on instantly.

[pvizeli]

Try a docker image with python 3.6

[Fonta]

@pvizeli I'm really not familiar with docker. Can't I just backup my current sd card in the pi, update python to 3.6 and then try again?

[pvizeli]

Yes, but you need compile it self for python 3.6

[Fonta]

@pvizeli Today I've created a new sd card with hassbian and updated Python to 3.6.1 on that one following the steps in https://community.home-assistant.io/t/python-3-6-upgrade-of-a-virtualenv/.
Unfortunately it didn't fix the delay.

[Fonta]

Also tried with the hass.io image. This has the same issue with the delay.

[svenbrocking]

I Also tried the same thing on my hass.io setup using the latest version. This resulted in the same behavior as above, so a +/- 2 sec delay but only when using an automation.

[OWK2017]

I also have a problem with delayed trigger on Rls 0.54 on a Cubie truck system with Ubuntu OS.

If an automation is triggered manually in the UI, response/action is instantly. Using RFXTRX devices to trigger HA without condition will have an response/action after 3-10 seconds.

I've read some posts on the HA forum (search the forum for 'slow trigger') and there seem more users with this problem. I.e. one that have the problem with Z-wave triggered automatons.

This problem is keeping me from migrating to HA, because it is not reliable...

Best regards,
OWK

[Fonta]

So it might not only be a problem with the rfxtrx module, but maybe it's even a bigger problem.
I don't know how triggers are handled, but @balloob probably does :)

[OWK2017]

Yeah, I sense that this could be bigger that just RFXTRX, but are we the only ones having issues with it?
Maybe there is a way to set debug for triggers and get some info from HA on what's happening

[Fonta]

I can confirm that this is still an issue.
This evening I also tried something new by publishing a msg to mqtt and listening to that same msg.
The same behaviour is seen. It just takes a while until the action in the automation is executed.

Still the same as this: https://www.youtube.com/watch?v=Ovml40Qh3Vc

[Fonta]

I'm now running hassio on a hpe microserver gen10 and the problem persists.

Also I tried appdaemon. I simply created a trigger to turn on a light when motion is detected. This didn't help either.

[pvizeli]

That is a RFXTRX problem. This platform is written very bad and don't try to follow our internal guide lines. I work on a cleanup to fix this problems:
#10501

[Fonta]

Thx @pvizeli! Sounds promising!

[OWK2017]

Hi Pascal You already did a lot of work! Your effort is highly appreciated, because I’m stuck for now and not making progress migrating to HA. Kind regards OWK

[balloobbot]

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 👍

[Fonta]

Issue is unfortunately still present.

[OWK2017]

I'm on HA release 0.65.6 now and it still takes ages for a RFXTRX signal to get processed.
So I agree with f0nt4 and chocobn69, despite effort the original issue is unfortunately still present.

for me this issue is blocking practical use of any 433MHz sensor, switch or remote control. Leaving me no choice to stick to my old domotica system.

Any chance someone knows how tro fix this or should I move away from RFXTRX?

Regards,
OWK

[Fonta]

We're still waiting till someone comes up with a solution. @pvizeli mentioned he's working on something but I guess it simply doesn't have a lot of priority.
In the meanwhile I did find out that if I use something else as the trigger, the automation is fast.
I mean that if I use a pir which sends a signal to the rfxtrx receiver, the signal sent to the switch is delayed, but if I sent a msg over mqtt and let that be the trigger, the automation is fast.
Which makes me think that the rfxtrx receiver shortly blocks when it received a signal.

[chocobn69]

FYI I had this issue with z-wave on a RP3.
I switched few weeks ago to a more powerfull server (i5 recycled desktop server with 8go ram and it's a lot faster than before. Maybe cpu related ?

[Fonta]

I'm running hassio on kind of the same hardware, but the few seconds delay is still there. If I use a different trigger as said before, the automation is fast.

[OWK2017]

My setup is a Cubie Truck with Lubuntu and my delay can be up to 23 seconds, sometimes faster.
Looking at the HA hardware requirments on the aebsite I can’t believe it is CPU related. Raspberry Pi is required.

Having the problem with other components as well could indicate a more general problem. That explains only the fact that it will complete the taks at the end

Regards
OWK

[balloobbot]

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 👍

[Fonta]

Running latest version, the issue still exists 1,5 years later already.

[Mace404]

Also having very slow response (receive) times with 433mhz sensors and RFXTRX.
Sending is instant (433mh switches / klikaanklikuit / somfy) but receiving is delayed.

[Fonta]

In 4 days this issue will be open for 2 years :)
I've moved over to z-wave motion sensors from fibaro last week and that does speed things up.

[alexmannuk]

Is this still an issue you are experiencing? Can you please try upgrading to the latest version of Home Assistant (0.90) and report back if this is still a problem? Thanks!

[Fonta]

After having the issue for 2 years, I got rid of the motion rfxtrx motion sensors and am now using zwave sensors as I said in the previous comment.
Lights turn on a lot faster now, so my guess would be that the motion sensors keep the rfxcom receiver "busy" so the signal to turn on the light has to wait.
Can't do any testing though.

[OWK2017]

I have worked around the delay by using NodeRed and MQTT. Could not think of something else to come over a problem existing for so long... Regards OWK Op 23 mrt. 2019 om 11:14 heeft Fonta <notifications@github.com> het volgende geschreven: After having the issue for 2 years, I got rid of the motion rfxtrx motion sensors and am now using zwave sensors as I said in the previous comment. Lights turn on a lot faster now, so my guess would be that the motion sensors keep the rfxcom receiver "busy" so the signal to turn on the light has to wait. Can't do any testing though. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[stale]

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 now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[Fonta]

As far as I'm aware the issue is not resolved. Can't test however because I moved to different motion detectors.

[Teljemo]

I use 433 MHz components to get a voice notice from my mailbox. (components from Telldus)
door sensor in the mailbox sends signal to a hub (tellstick) witch sends the signal to a dummy smart plug.
I use this dummy setup cause of the delay. I have the dummy on for 100 sec and if im lucky HA takes over in that time. The door sensor signal is so short so HA never got the signal. Its like it needs to be pushed all the way.. Strange?.
In HA I have a automation to google_say on my google home speakers when triggered from the dummy.
Would really appreciate some help on this delay problem.

[stale]

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 now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[OWK2017]

I’m running HA on hassio and an Intel-nuc i-3 for some time now.

After a fresh/new installation, for test I started using RfxTrx again to learn how it responds and it works much better.
Although X10 security (binary sensor on 433 MHz) is not processed on the hassio version of HA, while the RfxTrx receiver is handling the received signals correctly.

It’s hard to conclude a cause of the earlier problems. Is it solved by processing power or is in the mean time something fixed in the software? Could it be that the RfxTrx module in HA differs in main stream and hassio?

So I moved on and will focus on other interesting features of HA. Case can be closed if no one else responds.

Best regards
OWK

[stale]

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 now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[Fonta]

I didn't even took the trouble to respond to the stale's bot msg a week ago. Guess this will never be solved.
Great job in just waiting for the issue to go away.

[OWK2017]

Couldn’t agree more... Met vriendelijke groet Olaf Wansink

Op 12 feb. 2020 om 23:53 heeft Fonta ***@***.***> het volgende geschreven:

 I didn't even took the trouble to respond to the stale's bot msg a week ago. Guess this will never be solved. Great job in just waiting for the issue to go away. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or unsubscribe.