Unwanted delay when 2 switches turn on in automation

Configuration
1

I have an automation that triggers when a motion detector is tripped and turns on a zwave relay and zwave swall switch. However, I am getting significant delays between the relay and switch turning on, a good 10 seconds.

alias: "Bathroom Motion Sensor On"
trigger:
  platform: state
  entity_id: binary_sensor.bathroom_motion_sensor_32_0
  to: "on"
action:
  - service: switch.turn_on
    entity_id: group.bathroom

I’ve tried using the homeassistant.turn_on service. I also tried turning them on separately using 2 services in the action. The only change in result I got was that the order they turn on changed. The relay used to turn on first, and the switch delayed. Now the switch turns on first and the relay delayed.

I’ve also reduced the zwave polling rate to reduce network traffic even though both of these devices give unsolicited reports and are not polled.

Interesting is that they both turn off simultaneously though.

Any ideas?

2

How big is your home-assistant_v2.db file? I had the same issue with lagging automations until I configured the recorder: to only record automations. In my situation, it probably was the constant db writes from states…

3

Wow, never though to take a look at that.

2447397888 bytes. That’s pretty large. Link to docs to fix it?

4

How much is stored in there is in the “recorder:” component. You can make it so that you only record certain events:

recorder:
  purge_days: 1
  include:
    domains:
      - device tracker
      - automations

For example, that would only record the device tracker and automations, which is what most people are really into. You can shut down HA and either remove and delete the file and add the above to your recorder configuration, and observe the difference.

The recorder component instructions are here: https://home-assistant.io/components/recorder

5

That didn’t fix it. This time, the relay didn’t even turn on.

6

OK, that was strange. When I flipped the input boolean in HASS, the OZW log said “dropping packet presumed dead”. So I flipped the wall switch to manually trigger the relay, and now it’s working fine. Weird.

If I trigger the automation via the dev commands. It works. However, when I walk into the room, it’s still a 10s delay between the lights.

Looking in the logbook, it shows the bathroom sink turned on at 23:26:38, and the bathroom fan at 23:26:48.

7

What model wall switch and what model relay?

8

Aeotec DSC26103 relay on the fan and GE 12727 toggle switch.

9

Does anything in your Zwave log say (queued)? And is either device far away from your Z-Stick?

10

Both are withing 20-30ft of the stick. The relay is installed in the attic as that is where the junction box for the fan is. The wall switch is installed in the wall 20ft away with 2 walls between the stick and it.

I deleted my zwcfg file and restarted the Pi. So right now, the log file is a bit full to look through and the zwave network has been dog slow. I’ll try to get that info for you.

11

No need to look, but queued just means it is not sending it out right away. How many Zwave devices do you have? If you deleted your zwcfg file, does it come back with all of your entity IDs for your automations? Did you rename them at all in OZCP?

12

Some I used OZCP to rename, others I renamed with the new HASS zwave tab. All entity IDs seem to have come back fine. I have approximately 30 zwave devices currently. The network is dog slow to the point of unusable. I assume from deleting the zwcfg? It’s been a long while now.

13

I don’t think deleting the zwcfg would make it slow. When you restart HA or OZCP, however, it has to query all of your devices, their neighbors and the first 10 minutes will be slow, definitely. When that process is finished, however, it should be fine.

You said deleting the home-assistant_v2.db log and editing the recorder did not work. Is the home-assistant_v2.db file still growing fast?

14

No, the size was drastically decreased, but it made this process difficult to troubleshoot. I’ve temporarily removed the recorder configuration except for purge_days while I work through this problem.

15

Did you try tailing the OZW_Log.txt file for that node ID to see how fast the device is being triggered?

tail -f OZW_Log.txt | grep Node022

First change to the /home/homeassistant/.homeassistant directory and then execute that and see how long it takes to send out and receive the message to the Node that you are having problems with…

16

The more I troubleshoot, the more things seem to go wrong. Motion sensors are taking forever to trigger automations now. When flipping devices manually with the HASS interface, they respond but the interface takes a very long time to update. 1 motion sensor isn’t even trigger automations with the status “Sleeping (CacheLoad)”. 1 is very slow with the status “Sleeping (Dynamic)”. The bathroom door sensor isn’t operating with “Sleeping (Associations)”. And the schlage lock responded fine for a bit and is now marked as dead…

And the bathroom sink won’t even update at all in the HASS interface with the following error:

2017-06-01 01:23:45.240 Info, Node014, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - False
2017-06-01 01:23:45.240 Info, Node014, SwitchBinary::Set - Setting node 14 to Off
2017-06-01 01:23:45.240 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Set (Node=14): 0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x25, 0x01, 0x00, 0x25, 0xeb, 0x01
2017-06-01 01:23:45.240 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0xec, 0x07
2017-06-01 01:23:45.296 Info, Node014, Sending (Send) message (Callback ID=0xeb, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=14): 0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x25, 0x01, 0x00, 0x25, 0xeb, 0x01
2017-06-01 01:23:45.305 Detail, Node014,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-06-01 01:23:45.306 Detail, Node014,   ZW_SEND_DATA delivered to Z-Wave stack
2017-06-01 01:23:45.328 Detail, Node014,   Received: 0x01, 0x07, 0x00, 0x13, 0xeb, 0x00, 0x00, 0x03, 0x03
2017-06-01 01:23:45.328 Detail, Node014,   ZW_SEND_DATA Request with callback ID 0xeb received (expected 0xeb)
2017-06-01 01:23:45.329 Info, Node014, Request RTT 32 Average Request RTT 190
2017-06-01 01:23:45.329 Detail, Node014, Removing current message
2017-06-01 01:23:45.329 Info, Node014, Sending (Send) message (Callback ID=0xec, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0xec, 0x07
2017-06-01 01:23:45.338 Detail, Node014,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-06-01 01:23:45.339 Detail, Node014,   ZW_SEND_DATA delivered to Z-Wave stack
2017-06-01 01:23:45.361 Detail, Node014,   Received: 0x01, 0x07, 0x00, 0x13, 0xec, 0x00, 0x00, 0x03, 0x04
2017-06-01 01:23:45.361 Detail, Node014,   ZW_SEND_DATA Request with callback ID 0xec received (expected 0xec)
2017-06-01 01:23:45.362 Info, Node014, Request RTT 31 Average Request RTT 110
2017-06-01 01:23:55.329 Error, Node014, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-06-01 01:23:55.329 Detail, Node014, Removing current message
2017-06-01 01:23:55.330 Detail, Node014, Notification: Notification - TimeOut
17

Are you polling all of your devices? You should only poll devices that are plugged into a wall (not battery powered devices). I am asking so that we can make sure your network does not have more traffic than it should. The log above, even though it is saying queuing, it is sending things out pretty fast, but it seems like your device is not responding. The problem is not always your device.

This is what I have for polling and it seems to work:

zwave:
  usb_path: /dev/ttyACM0
  autoheal: false
  polling_interval: 30000
  device_config_domain:
    light:
      polling_intensity: 1
      refresh_value: true
      delay: 5
    switch:
      polling_intensity: 1
      refresh_value: true
      delay: 5

What does your polling look like?

18 
  polling_interval: 60000
  device_config:
    light.hallway_level_2_0:
      polling_intensity: 1
      refresh_value: true
      delay: 2
    switch.office_switch_16_0:
      polling_intensity: 1
      refresh_value: true
    switch.seth_room_switch_18_0:
      polling_intensity: 1
      refresh_value: true
    switch.laundry_room_switch_22_0:
      polling_intensity: 1
      refresh_value: true
    switch.kitchen_fan_switch_19_0:
      polling_intensity: 1
      refresh_value: true
    switch.entry_switch_20_0:
      polling_intensity: 1
      refresh_value: true
    switch.bedroom_switch_17_0:
      polling_intensity: 1
      refresh_value: true
    switch.basement_switch_21_0:
      polling_intensity: 1
      refresh_value: true
19

Are you running anything else like an mqtt server on the same host, with alot of traffic?

20

Nope. This is maddening. It was running great for the longest time. I upgraded to .45 and lost my schlage lock, which I was able to re-pair. And a few days ago started getting the strange automation problem. Now everything has gone completely awry. I’m approaching panic.