Unwanted delay in Automations

[f00dagi]

Hi!

update: for troubleshooting purposes I also made a clean install of latest hassio image and latest build of ha-plejd on different hardware (rpi4) and a new memory card. Same Plejd setup in my house. On top of that I installed only samba and ssh and created a light group to minimize the risk of interference from other plugins/code. Unfortunately the same behavior with only one of several lamps in that group turns on. If turning on lamps one by one it works just fine.

Thanks for a great development project, very useful for us Plejd users.

I want to turn on multiple lights at the same time but with Plejd-Hassio I have been rather unsuccessful.

For example when I run an automation what happens is that the automation turn on the first light immediately but there is an (exact?) delay of 10 seconds between each following light turning on.

If I trigger two lights manually they both turn on immediately.

I have also tried the plugin group lights and starting several entities under one button but that results in only the first light turning on.

I can not be sure but to me it seems like your Plejd-Hassio integration has some kind of flaw?

Thanks again for your work!

[klali]

Do you get anything in your logs?

Can you turn on debugging for the plejd component and report back?

[f00dagi]

Thanks for your reply.

update: to improve readability of code turn_on_lights_by_automation: http://bit.ly/2NqWq1S turn_on_lights_by_light group: http://bit.ly/2K1DAMO

Thanks for your time. I am really eager to get this working properly. If you want more debugging data just let me know.

[klali]

Very interesting. This is probably the same/related to #10

So the 10 seconds seem to be the SERVICE_CALL_LIMIT from core.py where it has a timeout of 10 seconds on all service calls. The actual call doesn't take this amount of time, but maybe we're not returning correctly or marking that we're done correctly.

I'll try to poke a bit at this and see if I can reproduce and if so fix it.

If you want to debug this a bit on your own, you can add debug logs on exit of the turn_on() and turn_off() functions and see what the time is when those are called.

[f00dagi]

Interesting, then there is a lead to the root cause, sounds promising.

I tried to google on how to add debug logs as you request but I cannot find any examples. Could you point me in the right direction or modify my code below to include debugging. Thanks.

- id: '1570825239747'
  alias: Time
  trigger:
  - at: '14:08'
    platform: time
  condition: []
  action:
  - data:
      brightness: '1'
      entity_id: light.allrum_tak
    service: light.turn_on
  - data:
      brightness: '1'
      entity_id: light.allrum_vagg
    service: light.turn_on
  - data:
      brightness: '1'
      entity_id: light.trappa_vagg
    service: light.turn_on

[klali]

No, in light.py at the end of the turn_on() and turn_off() functions, not the config. There are some other debug calls in those functions.

But I don't know how much that would help at all, I've spent a little time looking at this but need to try at a more modern home assistant installation than what I had immediately available.

[mudape]

Hi, Made a light.group with two different DIM-02 controllers. Don't behave as expected, only one light turns off.

I've added 'Exiting turn_xxx' as debug info

2019-11-07 23:38:49 DEBUG (SyncWorker_2) [custom_components.plejd.light] all plejd setup completed  
2019-11-07 23:38:49 WARNING (Thread-30) [custom_components.plejd.light] Encountered bluepy internal error: 'Unexpected response (rd)'  
2019-11-07 23:38:49 DEBUG (SyncWorker_2) [custom_components.plejd.light] kitchen_ceiling(15) turned False with brightness 70c0  
2019-11-07 23:38:54 DEBUG (Thread-30) [custom_components.plejd.light] hobby_ceiling(10) turned False with brightness 1616  
2019-11-07 23:39:36 DEBUG (SyncWorker_2) [custom_components.plejd.light] no match for command 'b'001b'' (b'010110001b3eabc45d01')  
2019-11-07 23:40:01 DEBUG (SyncWorker_2) [custom_components.plejd.light] no match for command 'b'001b'' (b'010110001b56abc45d01')  
2019-11-07 23:40:06 DEBUG (SyncWorker_0) [custom_components.plejd.light] turning on diningroom_window_downlight(0f) with brigtness 00  
2019-11-07 23:40:06 DEBUG (SyncWorker_4) [custom_components.plejd.light] turning on livingroom_window_downlight(0b) with brigtness 00  
2019-11-07 23:40:06 WARNING (SyncWorker_2) [custom_components.plejd.light] read/write failed in ping: 'Unexpected response (wr)'  
2019-11-07 23:40:06 DEBUG (SyncWorker_4) [custom_components.plejd.light] Exiting turn_on livingroom_window_downlight(0b) with brigtness 00  
2019-11-07 23:40:06 DEBUG (SyncWorker_2) [custom_components.plejd.light] Starting plejd connection  
2019-11-07 23:40:06 DEBUG (SyncWorker_2) [custom_components.plejd.light] stopping notification thread  
2019-11-07 23:40:06 ERROR (MainThread) [homeassistant.core] Error doing job: Future exception was never retrieved  
Traceback (most recent call last):  
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run  
    result = self.fn(*self.args, **self.kwargs)  
  File "/config/custom_components/plejd/light.py", line 325, in _start_plejd  
    _ping(dt_util.utcnow())  
  File "/config/custom_components/plejd/light.py", line 320, in _ping  
    connect(pi)  
  File "/config/custom_components/plejd/light.py", line 137, in connect  
    disconnect(pi)  
  File "/config/custom_components/plejd/light.py", line 252, in disconnect  
    plejdinfo["device"].disconnect()  
  File "/usr/local/lib/python3.7/site-packages/bluepy/btle.py", line 454, in disconnect  
    self._getResp('stat')  
  File "/usr/local/lib/python3.7/site-packages/bluepy/btle.py", line 407, in _getResp  
    resp = self._waitResp(wantType + ['ntfy', 'ind'], timeout)  
  File "/usr/local/lib/python3.7/site-packages/bluepy/btle.py", line 338, in _waitResp  
    if self._helper.poll() is not None:  
AttributeError: 'NoneType' object has no attribute 'poll'  
2019-11-07 23:40:06 WARNING (SyncWorker_0) [custom_components.plejd.light] Write failed: 'Device disconnected'  
2019-11-07 23:40:06 DEBUG (SyncWorker_0) [custom_components.plejd.light] Starting plejd connection  
2019-11-07 23:40:07 DEBUG (Thread-30) [custom_components.plejd.light] exiting notification thread  
2019-11-07 23:40:09 DEBUG (SyncWorker_0) [custom_components.plejd.light] Connected to Plejd device 'd8:47:97:50:a9:5d'  
2019-11-07 23:40:12 DEBUG (SyncWorker_0) [custom_components.plejd.light] setting up notification thread  
2019-11-07 23:40:12 DEBUG (Thread-31) [custom_components.plejd.light] starting notification thread  
2019-11-07 23:40:12 DEBUG (SyncWorker_0) [custom_components.plejd.light] all plejd setup completed  
2019-11-07 23:40:12 DEBUG (SyncWorker_0) [custom_components.plejd.light] Exiting turn_on diningroom_window_downlight(0f) with brigtness 00  
2019-11-07 23:40:57 DEBUG (SyncWorker_7) [custom_components.plejd.light] turning on diningroom_window_downlight(0f) with brigtness 00  
2019-11-07 23:40:57 DEBUG (SyncWorker_19) [custom_components.plejd.light] turning on livingroom_window_downlight(0b) with brigtness 00  
2019-11-07 23:40:57 WARNING (Thread-31) [custom_components.plejd.light] Encountered bluepy internal error: 'Unexpected response (wr)'  
2019-11-07 23:40:57 DEBUG (SyncWorker_19) [custom_components.plejd.light] Exiting turn_on livingroom_window_downlight(0b) with brigtness 00  
2019-11-07 23:41:12 DEBUG (SyncWorker_7) [custom_components.plejd.light] diningroom_ceiling(13) turned True with brightness 8469  
2019-11-07 23:41:17 DEBUG (SyncWorker_15) [custom_components.plejd.light] turning on diningroom_window_downlight(0f) with brigtness 00  
2019-11-07 23:41:17 DEBUG (SyncWorker_14) [custom_components.plejd.light] turning on livingroom_window_downlight(0b) with brigtness 00  
2019-11-07 23:41:17 WARNING (Thread-31) [custom_components.plejd.light] Encountered bluepy internal error: 'Unexpected response (wr)'  
2019-11-07 23:41:17 DEBUG (SyncWorker_7) [custom_components.plejd.light] Exiting turn_on diningroom_window_downlight(0f) with brigtness 00  
2019-11-07 23:41:19 DEBUG (SyncWorker_15) [custom_components.plejd.light] diningroom_window_downlight(0f) turned True with brightness 3838  
2019-11-07 23:41:19 DEBUG (SyncWorker_11) [custom_components.plejd.light] turning off diningroom_window_downlight(0f)  
2019-11-07 23:41:19 DEBUG (SyncWorker_14) [custom_components.plejd.light] Exiting turn_on livingroom_window_downlight(0b) with brigtness 00  
2019-11-07 23:41:20 DEBUG (Thread-31) [custom_components.plejd.light] diningroom_window_downlight(0f) turned False with brightness 3838  
2019-11-07 23:42:18 DEBUG (SyncWorker_15) [custom_components.plejd.light] no match for command 'b'001b'' (b'010110001bdfabc45d01')  
2019-11-07 23:42:50 DEBUG (SyncWorker_11) [custom_components.plejd.light] no match for command 'b'001b'' (b'010110001bffabc45d01')  
2019-11-07 23:43:00 DEBUG (Thread-31) [custom_components.plejd.light] livingroom_window_outlet(0c) turned True with brightness 6910

Running hass.io 0.103.2 on a Raspberry Pi 3b

[f00dagi]

Hi Klas, any progress on this issue? I am really eager to get it working. I realize you are busy but I hope you can find some time. Thanks.

_{Sent with GitHawk}

[klali]

I didn't manage to reproduce your specific errors, but I'm seeing other bad behaviour. I would mostly lay this at bluepy, sometimes the functions to read/write bluetooth seem to hang.

I think the sanest thing here would be to replace the bluetooth layer, I started looking at using d-bus directly because I don't like any of the python libraries abstracting it. I don't have enough problems with my installation to make this a priority but it's a plan to start poking at.

[f00dagi]

Hi Klas, I found the plugin hassio-plejd that has sorted out these issues. Thanks for developing this plugin though, it really got me started in home automation.

_{Sent with GitHawk}

[klali]

I just pushed a new branch of this, using the bluez dbus directly: https://github.com/klali/ha-plejd/tree/dbus

for me this seems to solve these issues of using a group, if you're still using this and want to help me see if that seems better than bluepy, give it a spin.

[klali]

The dbus branch is now merged, this should now be fixed.

[f00dagi]

Unfortunately I made a clean install of hass.io and used https://github.com/icanos/hassio-plejd instead for Plejd. There is therefore no easy way for me to test your update. Thanks for the effort though and I might return to this add-on later.