State on HASS is not updated after arming (but physical panel is updated)

[pedropaislopes]

Hi! Here is a bug that exists for me at least for six months.

Alarm state is disarmed, on HASS and Securitas panel. After pressing "Arm night" on HASS alarm control panel, physical alarm changes it states for "armed night". But HASS alarm state continues as "disarmed".

I've raised log level to debug to try to understand what is happening. Here is arming log:

2023-10-22 18:22:08.941 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:22:09.599 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:22:09.599 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSArmPanel":{"res":"OK","msg":"O seu pedido foi enviado","referenceId":"OWA_______________hassmurgui20231022232209441________________"}}}
2023-10-22 18:22:10.601 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:22:10.839 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:22:10.839 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSArmStatus":{"res":"WAIT","msg":"Pedido em processamento","status":null,"protomResponse":null,"protomResponseDate":null,"numinst":null,"requestId":"_pollingStatus_1746058","error":null}}}
2023-10-22 18:22:11.845 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:22:12.096 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:22:12.097 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSArmStatus":{"res":"WAIT","msg":"Pedido em processamento","status":null,"protomResponse":null,"protomResponseDate":null,"numinst":null,"requestId":"_pollingStatus_2050240","error":null}}}
2023-10-22 18:22:13.101 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:22:13.351 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:22:13.351 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSArmStatus":{"res":"OK","msg":"O seu alarme foi ligado modo parcial noite","status":"Q","protomResponse":"Q","protomResponseDate":"2023-10-22 23:22:09.506","numinst":"1786560","requestId":"_pollingStatus_1372149","error":null}}}
2023-10-22 18:22:13.352 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:22:13.690 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:22:13.690 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarm":{"res":"OK","msg":"O seu pedido foi enviado","referenceId":"OWA_______________hassmurgui20231022232213494________________"}}}
2023-10-22 18:22:14.691 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:22:15.304 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:22:15.304 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarmStatus":{"res":"WAIT","msg":"Pedido em processamento","status":null,"numinst":null,"protomResponse":null,"protomResponseDate":null}}}
2023-10-22 18:22:16.308 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:22:16.552 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:22:16.553 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarmStatus":{"res":"OK","msg":"O seu alarme está desligado","status":"0","numinst":"1786560","protomResponse":"D","protomResponseDate":"2023-10-22 23:22:13.576"}}}

But I can confirm, on Securitas physical panel, that the alarm state is "armed night".

After a while, on the next periodic alarm state refresh:

2023-10-22 18:23:48.391 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:23:48.738 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:23:48.738 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarm":{"res":"OK","msg":"O seu pedido foi enviado","referenceId":"OWA_______________hassmurgui20231022232348554________________"}}}
2023-10-22 18:23:49.741 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:23:49.985 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:23:49.985 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarmStatus":{"res":"WAIT","msg":"Pedido em processamento","status":null,"numinst":null,"protomResponse":null,"protomResponseDate":null}}}
2023-10-22 18:23:50.987 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:23:51.231 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:23:51.231 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarmStatus":{"res":"WAIT","msg":"Pedido em processamento","status":null,"numinst":null,"protomResponse":null,"protomResponseDate":null}}}
2023-10-22 18:23:52.234 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:23:52.494 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:23:52.494 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarmStatus":{"res":"WAIT","msg":"Pedido em processamento","status":null,"numinst":null,"protomResponse":null,"protomResponseDate":null}}}
2023-10-22 18:23:53.506 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:23:54.112 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:23:54.113 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarmStatus":{"res":"WAIT","msg":"Pedido em processamento","status":null,"numinst":null,"protomResponse":null,"protomResponseDate":null}}}
2023-10-22 18:23:55.116 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] Making request with device_id 4baed023e8aa45ae, uuid 4baed023e8aa45ae and idDeviceIndigitall 
2023-10-22 18:23:55.352 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] --------------Response--------------
2023-10-22 18:23:55.352 DEBUG (MainThread) [custom_components.securitas.securitas_direct_new_api.apimanager] {"data":{"xSCheckAlarmStatus":{"res":"OK","msg":"O seu alarme foi ligado modo parcial noite","status":"Q","numinst":"1786560","protomResponse":"Q","protomResponseDate":"2023-10-22 23:23:48.646"}}}

And HASS alarm changes its state to "armed night".

The same behavior occurs on other states - armed away and disarmed.

This no synchronization behavior occurs, let's say, in 50% of state changes. So it is (very) annoying.

I've managed to circumvent this issue changing sleep times to 10 (ten) seconds on set_arm_state function.

But maybe rewriting the check alarm logic can resolve this issue, for example, to wait for a real alarm state change. If Securitas server response is the same of old alarm state, ask for Securitas state again until the state changes on their servers (with some timeout to prevent endless loop).

Cheers!

[guerrerotook]

Obrigado per a sua resposta.

The issue is that sometimes, when your arm your alarm at the end the process go back to disarmed.

As you can see in your logs, O seu alarme está desligado this is the last status after trying to wait for the server to reply with the right status. That sometimes happens to me also in my alarm, but after the next update the alarm suddenly go to arm status.

In here there is nothing I can do, because I'm calling the Securitas Direct API and I don't control it, so if after trying to arm the alarm, reply back with you alarm is disarmed, that is.

Also what you mention in your comments about changing the logic, the operation is, you request a change in alarm, that return you an object that looking at how the android app is doing, is checking every second if the operation succeed. Once the operation is completed that object cannot be used again, why? because the status of the object is not wait anymore, as the source code show here.

https://github.com/guerrerotook/securitas-direct-new-api/blob/6244745fce497489281695a53e135ad770a314c7/custom_components/securitas/alarm_control_panel.py#L209

So again, there is nothing I can do from my side.

[pedropaislopes]

Muito obrigado pela rápida resposta!

My fix, that I've done since four versions behind, is to change (https://github.com/guerrerotook/securitas-direct-new-api/blob/6244745fce497489281695a53e135ad770a314c7/custom_components/securitas/alarm_control_panel.py#L152) and line 196 to await asyncio.sleep(10). Arming and disarming works absolutely great and rock solid with physical alarm and HASS panel always synchronized. No need to way for the next update.

I've tried with 3, 5 and 7 seconds, but 10 seems to be the most reliable waiting time.

Thanks a lot!

Cheers!

[KoolLSL]

For info, I have also, long time ago, added a delay before re-checking the alarm state after arming or disarming, because a few times it was not reliable. Currently 4 seconds delay, and confirming the state via notify. 10 seconds is even safer.

[guerrerotook]

Well, if you think that I should do the intervals longer, 4 seconds is more that enough.

[pedropaislopes]

Let me test now with 4 seconds!

[pedropaislopes]

Unfortunately 4 seconds is not enough.

To work reliably on my installation, lines 152 and 196 on set_arm_state should be 10 seconds. Lines 165 and 211 is OK with 1 second.

I think that, this way, even the number of queries to Securitas servers is reduced.

Cheers!

[KoolLSL]

@guerrerotook Maybe this delay could be set in the user configuration ? As it seems to depends of installations, regions, or other factors.

[guerrerotook]

I'm working to add optional configuration to the integration so you can setup those variables to whatever you like! Stay tuned.

[ToroNander]

Hi!

I followed your topic here but regarding the new release and related options, there are now

A) Scan intervall to query the last status in the Server (in pic value "36" of the new release)

&

B) Delay in second to check the arming and disarming operation (in pic value "2" of the new release).

The value of 10sec which u discovered as proper value is to set in B), is that right?

Which value is recommended for A)? And which value is set in Version 2.3.0.0 for that?

BR Toro