Z-Wave Script/Automation crashes HA

patrickjane commented 6 years ago

Home Assistant release (hass --version): 0.64.3

Python release (python3 --version): Python 3.5.3

Component/platform: script / Z-wave

Description of problem:

I have set up the below mentioned automation to have HA refresh the state of my fibaro Z-wave thermostats. Otherwise it would not refresh the operation mode; it would get stuck on whatever state it was (Heat or Off).

However, when the automation is enabled, it will crash HA constantly after executing the script for the second time (thus crashing every 30 mins with an automation which runs every 15mins).

The crash can be reproduced by calling the script twice manually.

Expected:

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

    - alias: zwave_refresher
      trigger:
        - platform: time
          minutes: "/15"
          seconds: 00
      action:
        - service: script.rescan_zwave

Script:

rescan_zwave:
  alias: refresh_zwave
  sequence:
  - alias: refresh zwave 5
    service: zwave.refresh_node
    data:
      node_id: 5
  - alias: refresh zwave 6
    service: zwave.refresh_node
    data:
      node_id: 6
  - alias: refresh zwave 7
    service: zwave.refresh_node
    data:
      node_id: 7
  - alias: refresh zwave 8
    service: zwave.refresh_node
    data:
      node_id: 8

Activate the automation
wait
HA crashes

OR

Manually execute the script once
wait a while for everything to finish
execute it a second time
HA crashes

Heres two backtraces I captured with attached gdb:

https://gist.github.com/patrickjane/08e4e67ec6bbf931367acce49d799bb1

https://gist.github.com/patrickjane/3832e44ca33b23f74bf6bcbc17b588a8

Mar  9 06:45:06 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 07:15:07 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 07:45:05 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 08:15:05 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 08:45:06 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 09:15:05 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 09:45:07 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 10:15:07 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 10:45:05 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV

Relevant log from /var/log/syslog:

Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.components.automation:Executing zwave_refresher
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event logbook_entry[L]: entity_id=automation.zwave_refresher, domain=automation, message=has been triggered, name=zwave_refresher>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.helpers.script:Script zwave_refresher: Running script
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.helpers.script:Script zwave_refresher: Executing step call service
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event call_service[L]: service_call_id=1972328944-13, service=rescan_zwave, service_data=, domain=script>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.helpers.script:Script refresh_zwave: Running script
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.helpers.script:Script refresh_zwave: Executing step refresh zwave 5
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event call_service[L]: service_call_id=1972328944-14, service=refresh_node, service_data=node_id=5, domain=zwave>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event service_executed[L]: service_call_id=1972328944-14>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.helpers.script:Script refresh_zwave: Executing step refresh zwave 6
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event call_service[L]: service_call_id=1972328944-15, service=refresh_node, service_data=node_id=6, domain=zwave>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event service_executed[L]: service_call_id=1972328944-15>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.helpers.script:Script refresh_zwave: Executing step refresh zwave 7
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event call_service[L]: service_call_id=1972328944-16, service=refresh_node, service_data=node_id=7, domain=zwave>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event service_executed[L]: service_call_id=1972328944-16>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.helpers.script:Script refresh_zwave: Executing step refresh zwave 8
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event call_service[L]: service_call_id=1972328944-17, service=refresh_node, service_data=node_id=8, domain=zwave>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event service_executed[L]: service_call_id=1972328944-17>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event service_executed[L]: service_call_id=1972328944-13>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=script.rescan_zwave, old_state=<state script.rescan_zwave=off; friendly_name=refresh_zwave, last_triggered=2018-03-09T10:30:00.675454+01:00 @ 2018-03-09T10:19:38.330146+01:0
0>, new_state=<state script.rescan_zwave=off; friendly_name=refresh_zwave, last_triggered=2018-03-09T10:45:00.664331+01:00 @ 2018-03-09T10:19:38.330146+01:00>>
Mar  9 10:45:00 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=automation.zwave_refresher, old_state=<state automation.zwave_refresher=on; friendly_name=zwave_refresher, last_triggered=2018-03-09T10:30:00.885381+01:00 @ 2018-03-09T10:19
:47.523429+01:00>, new_state=<state automation.zwave_refresher=on; friendly_name=zwave_refresher, last_triggered=2018-03-09T10:45:00.823652+01:00 @ 2018-03-09T10:19:47.523429+01:00>>
Mar  9 10:45:02 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=zwave.fibaro_system_fgt001_heat_controller, old_state=<state zwave.fibaro_system_fgt001_heat_controller=ready; sentTS=2018-03-09 10:30:14:374 , max_baud_rate=40000, old_enti
ty_id=zwave.fibaro_system_fgt001_heat_controller_5, receivedDups=0, capabilities={'beaming', 'frequent', 'routing'}, lastRequestRTT=32, new_entity_id=zwave.fibaro_system_fgt001_heat_controller, is_awake=True, is_ready=True, node_name=FIBARO System FGT001 Heat Controller, neighbor
s={1, 3, 6, 7, 8, 10}, manufacturer_name=FIBARO System, sentFailed=0, retries=0, battery_level=100, lastResponseRTT=294, is_zwave_plus=True, averageResponseRTT=241, receivedUnsolicited=0, receivedCnt=26, is_failed=False, query_stage=Complete, friendly_name=Thermostat Flur, averag
eRequestRTT=31, receivedTS=2018-03-09 10:30:14:669 , product_name=FGT001 Heat Controller, sentCnt=32, node_id=5, is_info_received=True @ 2018-03-09T10:30:25.852266+01:00>, new_state=<state zwave.fibaro_system_fgt001_heat_controller=initializing; sentTS=2018-03-09 10:45:00:685 , m
ax_baud_rate=40000, old_entity_id=zwave.fibaro_system_fgt001_heat_controller_5, receivedDups=0, capabilities={'beaming', 'frequent', 'routing'}, lastRequestRTT=1289, new_entity_id=zwave.fibaro_system_fgt001_heat_controller, is_awake=True, is_ready=True, node_name=FIBARO System FG
T001 Heat Controller, manufacturer_name=FIBARO System, sentFailed=0, retries=0, battery_level=100, lastResponseRTT=294, is_zwave_plus=True, averageResponseRTT=241, receivedUnsolicited=0, receivedCnt=26, is_failed=False, query_stage=Probe, friendly_name=Thermostat Flur, averageReq
uestRTT=660, receivedTS=2018-03-09 10:30:14:669 , product_name=FGT001 Heat Controller, sentCnt=33, node_id=5, is_info_received=True @ 2018-03-09T10:45:02.084014+01:00>>
Mar  9 10:45:03 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=zwave.fibaro_system_fgt001_heat_controller_2, old_state=<state zwave.fibaro_system_fgt001_heat_controller_2=ready; sentTS=2018-03-09 10:30:18:113 , max_baud_rate=40000, old_
entity_id=zwave.fibaro_system_fgt001_heat_controller_6, receivedDups=0, capabilities={'beaming', 'frequent', 'routing'}, lastRequestRTT=31, new_entity_id=zwave.fibaro_system_fgt001_heat_controller, is_awake=True, is_ready=True, node_name=FIBARO System FGT001 Heat Controller, neig
hbors={1, 3, 5, 7, 8, 10}, manufacturer_name=FIBARO System, sentFailed=0, retries=0, battery_level=100, lastResponseRTT=295, is_zwave_plus=True, averageResponseRTT=243, receivedUnsolicited=0, receivedCnt=26, is_failed=False, query_stage=Complete, friendly_name=Thermostat Wohnzimm
er, averageRequestRTT=33, receivedTS=2018-03-09 10:30:18:408 , product_name=FGT001 Heat Controller, sentCnt=32, node_id=6, is_info_received=True @ 2018-03-09T10:30:25.858760+01:00>, new_state=<state zwave.fibaro_system_fgt001_heat_controller_2=initializing; sentTS=2018-03-09 10:4
5:01:982 , max_baud_rate=40000, old_entity_id=zwave.fibaro_system_fgt001_heat_controller_6, receivedDups=0, capabilities={'beaming', 'frequent', 'routing'}, lastRequestRTT=1230, new_entity_id=zwave.fibaro_system_fgt001_heat_controller, is_awake=True, is_ready=True, node_name=FIBA
RO System FGT001 Heat Controller, manufacturer_name=FIBARO System, sentFailed=0, retries=0, battery_level=100, lastResponseRTT=295, is_zwave_plus=True, averageResponseRTT=243, receivedUnsolicited=0, receivedCnt=26, is_failed=False, query_stage=Probe, friendly_name=Thermostat Wohn
zimmer, averageRequestRTT=631, receivedTS=2018-03-09 10:30:18:408 , product_name=FGT001 Heat Controller, sentCnt=33, node_id=6, is_info_received=True @ 2018-03-09T10:45:03.321162+01:00>>
Mar  9 10:45:04 pi3HA hass[10055]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=zwave.fibaro_system_fgt001_heat_controller_3, old_state=<state zwave.fibaro_system_fgt001_heat_controller_3=ready; sentTS=2018-03-09 10:30:21:728 , max_baud_rate=40000, old_
entity_id=zwave.fibaro_system_fgt001_heat_controller_7, receivedDups=0, capabilities={'beaming', 'frequent', 'routing'}, lastRequestRTT=32, new_entity_id=zwave.fibaro_system_fgt001_heat_controller, is_awake=True, is_ready=True, node_name=FIBARO System FGT001 Heat Controller, neig
hbors={1, 3, 5, 6, 8, 10}, manufacturer_name=FIBARO System, sentFailed=0, retries=0, battery_level=100, lastResponseRTT=295, is_zwave_plus=True, averageResponseRTT=243, receivedUnsolicited=0, receivedCnt=26, is_failed=False, query_stage=Complete, friendly_name=Thermostat Arbeitsz
immer, averageRequestRTT=33, receivedTS=2018-03-09 10:30:22:023 , product_name=FGT001 Heat Controller, sentCnt=32, node_id=7, is_info_received=True @ 2018-03-09T10:30:25.902172+01:00>, new_state=<state zwave.fibaro_system_fgt001_heat_controller_3=initializing; sentTS=2018-03-09 1
0:45:03:219 , max_baud_rate=40000, old_entity_id=zwave.fibaro_system_fgt001_heat_controller_7, receivedDups=0, capabilities={'beaming', 'frequent', 'routing'}, lastRequestRTT=1304, new_entity_id=zwave.fibaro_system_fgt001_heat_controller, is_awake=True, is_ready=True, node_name=F
IBARO System FGT001 Heat Controller, manufacturer_name=FIBARO System, sentFailed=0, retries=0, battery_level=100, lastResponseRTT=295, is_zwave_plus=True, averageResponseRTT=243, receivedUnsolicited=0, receivedCnt=26, is_failed=False, query_stage=Probe, friendly_name=Thermostat A
rbeitszimmer, averageRequestRTT=668, receivedTS=2018-03-09 10:30:22:023 , product_name=FGT001 Heat Controller, sentCnt=33, node_id=7, is_info_received=True @ 2018-03-09T10:45:04.634151+01:00>>
Mar  9 10:45:05 pi3HA systemd[1]: hass.service: Main process exited, code=killed, status=11/SEGV
Mar  9 10:45:05 pi3HA systemd[1]: hass.service: Unit entered failed state.
Mar  9 10:45:05 pi3HA systemd[1]: hass.service: Failed with result 'signal'.

Additional info:

Running on raspberry pi 3 with raspbian stretch. HA was installed using the manual installation method (https://home-assistant.io/docs/installation/raspberry-pi/).

Z-wave config:

zwave:
   usb_path: /dev/ttyACM0

climate:
  platform: zwave

I am using the Z-Wave.Me ZME_UZB1 USB Stick as z-wave controller.

dshokouhi commented 6 years ago

Just out of curiosity did you try to poll your device instead of refreshing every 15 minutes? That seems a bit extreme.

chriskacerguis commented 6 years ago

FWIW - I have about 100 zwave devices, I do not see this issue (using the Aeotec Zwave USB stick)

patrickjane commented 6 years ago

Just out of curiosity did you try to poll your device instead of refreshing every 15 minutes? That seems a bit extreme.

I am new to HA. Could you explain what you mean by this?

kmwoley commented 6 years ago

@patrickjane - I think @dshokouhi was suggesting that you use the zwave: device_config: feature that should trigger polling of the state instead of using the zwave.refresh_node service call.

e.g.

zwave:
  usb_path: /dev/ttyACM0
  network_key: !secret ZWAVE_KEY
  polling_interval: 30000
  device_config:
    light.tv_room_light:
      polling_intensity: 1
      refresh_value: true

@dshokouhi - I believe this using an automation to periodically trigger zwave.refresh_node is a common work around for the built-in zwave polling not functioning correctly. For some reason, it doesn't appear to work for everyone.

See: https://community.home-assistant.io/t/z-wave-polling-questions-answered/2394/28 https://community.home-assistant.io/t/issue-reading-states-of-z-wave-switches/20497/15

Filed: https://github.com/home-assistant/home-assistant/issues/13801

patrickjane commented 6 years ago

I didn't know of the polling feature, I'll give it a shot. The 'workaround' doesn't work for me anyway. Thanks for the info.

patrickjane commented 6 years ago

Nope, does not work for me. The status of the heaters remains wrong/outdated.

balloobbot commented 6 years ago

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 :+1:

CedrickFlocon commented 6 years ago

I got the same issue. If I refresh twice the node (even manually with Z-Wave Network Management) Home assistant seem to crash. I try to refresh my node because my heaters remains outdated.

Home Assistant : 0.79.3

CedrickFlocon commented 6 years ago

@patrickjane I found a trick. Instead of refreshing the whole node (which leads to a HA crash) I refresh only one entity. E.g :

- id: Refresh-FGT-001
  alias: Z Wave refresher
  hide_entity: true
  trigger:
  - platform: time
    minutes: "/15"
    seconds: 00
  action:
    - service: zwave.refresh_entity
      data:
        entity_id: sensor.thermometer
    - service: zwave.refresh_entity
      data:
        entity_id: climate.heater

dison4linux commented 5 years ago

I just came across this as a potential workaround as well. Unfortunately states are not updating out of the box, and polling doesn't seem to work either. Calling zwave.refresh_node does seem to work for now, hopefully I won't run into the issues mentioned above where it will crash HA. Is the issue that leads to needing this workaround in the first place being investigated also? I'm happy to help by providing my findings/logs/etc.

patrickjane commented 5 years ago

@dison4linux You might want to check https://github.com/OpenZWave/open-zwave/issues/1638 and https://community.home-assistant.io/t/fibaro-heat-controller-temperature-battery-not-displaying-correctly/70842/13 then. This is where I reported issues with the fibaro heaters. I don't think that anyone is working on them, however.

balloobbot commented 5 years ago

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 :+1:

iamelk commented 5 years ago

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!

HAjerry commented 3 years ago

I run Home Assistant 0.116.4 with Aeotec ZW090 Z-Stick Gen5. I have the same problem, i.e., Home Assistant crashes on calling zwave.refresh_node.

home-assistant / core

Z-Wave Script/Automation crashes HA #13002