ufodone / envisalink_new

A modernized version of the Home Assistant envisalink integration available through HACS.
MIT License
60 stars 6 forks source link

Partition Arming Away when Trying to Arm Stay #37

Closed PablaV closed 1 year ago

PablaV commented 1 year ago

As of ~v6.3 on occasion my partition will arm 'Away' instead of arming 'Home'/'Stay' which is what I had initially set the partition to. Not really much info I got aside from some logs I have attached. I armed the partition stay at 10:31:59pm then at 10:33:59pm it armed away, at that time I set the partition to arm to stay and that went through successfully. This happens randomly and happens if I arm using HA or even manually on my panel. I am currently on v6.6 with bypass zone switches enabled.

2023-06-07 22:31:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: 500 with data: 000
2023-06-07 22:31:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] DSC ack recieved.
2023-06-07 22:31:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:31:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:31:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:31:47.973 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:31:47.973 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:31:52.973 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:31:57.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:31:58.417 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Queueing command '031' data: '1' ; calling_task=Task-196642
2023-06-07 22:31:58.418 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:31:58.418 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:31:58.418 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] TX > b'0311C5'
2023-06-07 22:31:58.419 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:31:58.421 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:31:58.421 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 50003129

2023-06-07 22:31:58.421 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: 500 with data: 031
2023-06-07 22:31:58.421 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] DSC ack recieved.
2023-06-07 22:31:58.421 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:31:58.421 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:31:58.422 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:31:58.422 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:31:58.422 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:31:59.300 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:31:59.300 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 5108B10

2023-06-07 22:31:59.300 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_keypad_led_state_update for code: 510 with data: 8B
2023-06-07 22:31:59.301 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] Keypad LED state update: 0x8b ready=1 armed=1 memory=0 bypass=1 trouble=0 program=0 fire=0 backlight=1
2023-06-07 22:31:59.301 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:31:59.301 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:31:59.301 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:31:59.302 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Queueing command '071' data: '1*1#' ; calling_task=dump_zone_bypass_status
2023-06-07 22:31:59.302 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:31:59.303 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:31:59.303 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] TX > b'0711*1#47'
2023-06-07 22:31:59.304 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:31:59.307 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:31:59.307 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 5000712D

2023-06-07 22:31:59.307 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: 500 with data: 071
2023-06-07 22:31:59.308 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] DSC ack recieved.
2023-06-07 22:31:59.308 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:31:59.308 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:31:59.308 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:31:59.308 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:31:59.309 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:31:59.380 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:31:59.380 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 6561D2

2023-06-07 22:31:59.380 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 656 with data: 1
2023-06-07 22:31:59.381 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] (partition 1) state has updated: {"exit_delay": true, "alpha": "Exit Delay In Progress"}
2023-06-07 22:31:59.381 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:31:59.381 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Triggering state change callback for partition: [1]
2023-06-07 22:31:59.381 DEBUG (MainThread) [custom_components.envisalink_new] The envisalink 'Home Partition' sent a partition update event: [1]
2023-06-07 22:31:59.381 DEBUG (MainThread) [custom_components.envisalink_new] state_updated for 'Home Partition Keypad'
2023-06-07 22:31:59.383 DEBUG (MainThread) [custom_components.envisalink_new] state_updated for 'Home Partition'
2023-06-07 22:31:59.384 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:31:59.384 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:31:59.767 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:31:59.767 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 51080FE

2023-06-07 22:31:59.767 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_keypad_led_state_update for code: 510 with data: 80
2023-06-07 22:31:59.767 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] Keypad LED state update: 0x80 ready=0 armed=0 memory=0 bypass=0 trouble=0 program=0 fire=0 backlight=1
2023-06-07 22:31:59.767 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:31:59.767 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:31:59.767 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:00.262 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:32:00.262 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 5108301

2023-06-07 22:32:00.263 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_keypad_led_state_update for code: 510 with data: 83
2023-06-07 22:32:00.263 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] Keypad LED state update: 0x83 ready=1 armed=1 memory=0 bypass=0 trouble=0 program=0 fire=0 backlight=1
2023-06-07 22:32:00.263 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:32:00.263 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:32:00.263 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:02.174 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:32:02.174 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 6561D2

2023-06-07 22:32:02.174 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 656 with data: 1
2023-06-07 22:32:02.174 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] (partition 1) state has updated: {"exit_delay": true, "alpha": "Exit Delay In Progress"}
2023-06-07 22:32:02.174 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:32:02.174 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Triggering state change callback for partition: [1]
2023-06-07 22:32:02.174 DEBUG (MainThread) [custom_components.envisalink_new] The envisalink 'Home Partition' sent a partition update event: [1]
2023-06-07 22:32:02.174 DEBUG (MainThread) [custom_components.envisalink_new] state_updated for 'Home Partition Keypad'
2023-06-07 22:32:02.175 DEBUG (MainThread) [custom_components.envisalink_new] state_updated for 'Home Partition'
2023-06-07 22:32:02.175 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:32:02.175 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:06.597 WARNING (MainThread) [async_upnp_client.profiles.dlna] Only InstanceID 0 is supported
2023-06-07 22:32:07.176 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:12.177 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:17.178 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:22.179 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:27.180 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:32.180 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:37.181 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:42.182 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:47.183 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:47.971 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Queueing command '000' data: '' ; calling_task=keep_alive
2023-06-07 22:32:47.971 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:32:47.971 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:32:47.971 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] TX > b'00090'
2023-06-07 22:32:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 50000025

2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: 500 with data: 000
2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] DSC ack recieved.
2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:32:47.974 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:32:52.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:32:57.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:02.976 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:07.976 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:12.977 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:17.978 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:22.979 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:27.979 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:32.980 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:37.980 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:42.981 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:47.971 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Queueing command '000' data: '' ; calling_task=keep_alive
2023-06-07 22:33:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:33:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:33:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] TX > b'00090'
2023-06-07 22:33:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 50000025

2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: 500 with data: 000
2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] DSC ack recieved.
2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:33:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:33:52.976 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:57.977 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:58.790 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:33:58.791 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 5108200

2023-06-07 22:33:58.791 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_keypad_led_state_update for code: 510 with data: 82
2023-06-07 22:33:58.791 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] Keypad LED state update: 0x82 ready=0 armed=1 memory=0 bypass=0 trouble=0 program=0 fire=0 backlight=1
2023-06-07 22:33:58.791 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:33:58.791 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:33:58.791 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:59.676 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:33:59.676 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 7011C9

2023-06-07 22:33:59.677 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] No handler defined in config for 701, skipping...
2023-06-07 22:33:59.677 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] No handler configured for evl command.
2023-06-07 22:33:59.677 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] KeyError: 'handler'
2023-06-07 22:33:59.677 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:33:59.677 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:33:59.677 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:33:59.678 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:33:59.678 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 65210FE

2023-06-07 22:33:59.678 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 652 with data: 10
2023-06-07 22:33:59.678 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] (partition 1) state has updated: {"armed_away": true, "armed_stay": false, "armed_zero_entry_delay": false, "alpha": "Arm Away", "exit_delay": false, "entry_delay": false}
2023-06-07 22:33:59.678 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:33:59.678 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Triggering state change callback for partition: [1]
2023-06-07 22:33:59.678 DEBUG (MainThread) [custom_components.envisalink_new] The envisalink 'Home Partition' sent a partition update event: [1]
2023-06-07 22:33:59.678 DEBUG (MainThread) [custom_components.envisalink_new] state_updated for 'Home Partition Keypad'
2023-06-07 22:33:59.679 DEBUG (MainThread) [custom_components.envisalink_new] state_updated for 'Home Partition'
2023-06-07 22:33:59.679 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:33:59.679 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:04.680 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:09.681 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:14.683 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:19.683 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:21.808 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Queueing command '031' data: '1' ; calling_task=Task-197415
2023-06-07 22:34:21.808 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:34:21.808 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:34:21.809 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] TX > b'0311C5'
2023-06-07 22:34:21.809 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:34:21.811 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:34:21.811 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 50003129

2023-06-07 22:34:21.811 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: 500 with data: 031
2023-06-07 22:34:21.811 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] DSC ack recieved.
2023-06-07 22:34:21.811 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:34:21.811 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:34:21.811 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:21.812 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:34:21.812 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:34:22.286 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:34:22.286 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 5108B10

2023-06-07 22:34:22.286 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_keypad_led_state_update for code: 510 with data: 8B
2023-06-07 22:34:22.286 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] Keypad LED state update: 0x8b ready=1 armed=1 memory=0 bypass=1 trouble=0 program=0 fire=0 backlight=1
2023-06-07 22:34:22.286 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:34:22.286 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:34:22.286 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:22.367 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:34:22.367 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 6561D2

2023-06-07 22:34:22.367 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 656 with data: 1
2023-06-07 22:34:22.367 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] (partition 1) state has updated: {"exit_delay": true, "alpha": "Exit Delay In Progress"}
2023-06-07 22:34:22.367 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:34:22.367 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Triggering state change callback for partition: [1]
2023-06-07 22:34:22.367 DEBUG (MainThread) [custom_components.envisalink_new] The envisalink 'Home Partition' sent a partition update event: [1]
2023-06-07 22:34:22.367 DEBUG (MainThread) [custom_components.envisalink_new] state_updated for 'Home Partition Keypad'
2023-06-07 22:34:22.368 DEBUG (MainThread) [custom_components.envisalink_new] state_updated for 'Home Partition'
2023-06-07 22:34:22.368 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:34:22.368 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:27.370 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:32.371 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:37.372 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:42.373 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:43.706 ERROR (MainThread) [homeassistant.components.zwave_js] Unable to set value 57-98-0-targetMode: Z-Wave error 204: Failed to send the command after 1 attempts (Status NoAck) (ZW0204)
2023-06-07 22:34:43.710 ERROR (MainThread) [homeassistant.core] Error executing service: <ServiceCall lock.lock (c:01H2CQYYZWKSJASEWYFS379TEN): entity_id=['lock.east_side_door']>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zwave_js/entity.py", line 316, in _async_set_value
    return await self.info.node.async_set_value(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zwave_js_server/model/node/__init__.py", line 490, in async_set_value
    result = await self.async_send_command(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zwave_js_server/model/node/__init__.py", line 447, in async_send_command
    result = await self.client.async_send_command(message, **kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zwave_js_server/client.py", line 116, in async_send_command
    return await future
           ^^^^^^^^^^^^
zwave_js_server.exceptions.FailedZWaveCommand: Z-Wave error 204: Failed to send the command after 1 attempts (Status NoAck) (ZW0204)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1928, in catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1950, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 226, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 811, in entity_service_call
    future.result()  # pop exception if have
    ^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1034, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 851, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/lock/__init__.py", line 99, in _async_lock
    await entity.async_lock(**remove_entity_service_fields(service_call))
  File "/usr/src/homeassistant/homeassistant/components/zwave_js/lock.py", line 129, in async_lock
    await self._set_lock_state(STATE_LOCKED)
  File "/usr/src/homeassistant/homeassistant/components/zwave_js/lock.py", line 122, in _set_lock_state
    await self._async_set_value(
  File "/usr/src/homeassistant/homeassistant/components/zwave_js/entity.py", line 321, in _async_set_value
    raise HomeAssistantError from err
homeassistant.exceptions.HomeAssistantError
2023-06-07 22:34:47.374 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:47.972 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Queueing command '000' data: '' ; calling_task=keep_alive
2023-06-07 22:34:47.973 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:34:47.973 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:34:47.973 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] TX > b'00090'
2023-06-07 22:34:47.973 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:34:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] {---------------------------------------
2023-06-07 22:34:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] RX < 50000025

2023-06-07 22:34:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: 500 with data: 000
2023-06-07 22:34:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.dsc_client] DSC ack recieved.
2023-06-07 22:34:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Invoking state change callbacks
2023-06-07 22:34:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] }---------------------------------------
2023-06-07 22:34:47.975 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:47.976 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Command processor woke up.
2023-06-07 22:34:47.976 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Checking command queue: len=1
2023-06-07 22:34:52.976 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:34:57.977 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:35:02.979 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:35:07.979 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:35:12.980 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
2023-06-07 22:35:17.982 DEBUG (MainThread) [custom_components.envisalink_new.pyenvisalink.envisalink_base_client] Waiting for data from EVL
ufodone commented 1 year ago

I think this is likely related to #15.

The logs you provided show what I think may be a bug in my attempt to fix the issue. My suspicious is that this may incorrectly show away instead of home only on the first time you arm the system after HA has been restarted. Are you able to confirm that? If so, I think I fix should be fairly straightforward.

PablaV commented 1 year ago

I initially thought it was that issue, but my panel actually is armed away. I learnt this the hard way when the alarm went off because of motion indoors lol. I will check and see if this issues occurs the first time after a restart to see if I can find a pattern.

ufodone commented 1 year ago

The logs you provided show the integration sending the arm command to the EVL in stay mode, with the EVL then sending a few exit delay status updates followed eventually by an indication that is is armed in away mode. After the arm command is sent, the integration also (erroneously) sends a request for the zone bypass status. My speculation is that this command is somehow confusing the EVL into doing the wrong thing with respect to arming.

The logs from #15 show the same behaviour - although after I think it was about 2 minutes of being armed, the EVL eventually sent another update indicating it was in the correct arm mode. I think it's still the same root cause though.

The more recent version releases have included my attempts to fix this issue but your logs reveal a bug. I can look at making a fix but would appreciate if you could confirm the behaviour as I've had difficulty reproducing this issue myself.

PablaV commented 1 year ago

Gave arming a try after restarting HA and it incorrectly armed away instead of stay. I checked the panel to make sure and it shows as armed away.

ufodone commented 1 year ago

I've committed a change which I hope will fix this issue for you but haven't published a new release yet as I'm going to be away from the computer for a few days.

Would you be able to try installing the "main" version to see if that fixes your issue? You should be able to select it from the "Redownload" option for the integration in HACS.

PablaV commented 1 year ago

So I have been testing the "main" version for the past few days and haven't encountered any time where my panel arms away instead of stay! Safe to say the issue has been fixed, thanks! :)

ufodone commented 1 year ago

Great, thanks for the confirmation. I've pushed a new release which contains the fix.