Verisure integration slow after update to 2020.1 from 0.118

krissen commented 3 years ago

The problem

The Verisure integration has never been impressively snappy; usually a change within the Verisure system (armed, open/closed door etc.) would take 20-30 seconds or so to show up in HA. However, having recently upgraded from 0.118.* to 2020.1.0 (and then to 2020.1.1), it is considerably more slow. Changes are reflected in HA before late, but it always takes over a minute.

Environment

System Health

version	2021.1.1
installation_type	Home Assistant Container
dev	false
hassio	false
docker	true
virtualenv	false
python_version	3.8.7
os_name	Linux
os_version	5.10.5-arch1-1
arch	x86_64
timezone	Europe/Stockholm

Home Assistant Community Store

Home Assistant Cloud

Lovelace

Spotify

api_endpoint_reachable | ok -- | --

Home Assistant Core release with the issue: 2020.1.*
Last working Home Assistant Core release (if known): 0.118.*
Operating environment (OS/Container/Supervised/Core): Docker running on Arch
Integration causing this issue: Verisure
Link to integration documentation on our website: https://www.home-assistant.io/integrations/verisure/

Problem-relevant `configuration.yaml`

verisure:
  username: !secret verisurename
  password: !secret verisurepass
  hygrometers: 1
  door_window: 1
  alarm: 1
  thermometers: 1

Traceback/Error logs

Nothing yet. Just restarted with debug; will update if something shows up.

Additional information

Previously, when arming Verisure from within HA, everything was instantaneous: HA showed alarm_control_panel.furustigen_alarm as being armed immediately and it was indeed armed from Verisure's end as well. However, having upgraded, when arming from within HA Verisure immediately arms as before but it takes a minute or two before HA catches up.

So, the integration is not broken, but merely more sluggish than before.

probot-home-assistant[bot] commented 3 years ago

Hey there @frenck, mind taking a look at this issue as its been labeled with an integration (verisure) you are listed as a codeowner for? Thanks! _{^{(message by CodeOwnersMention)}}

Depechie commented 3 years ago

Wanted to report similar issue. Not that it takes minutes in my case, but arming and disarming takes longer than older HA versions.

Kane610 commented 3 years ago

IIRC the polling has always been every few minutes due to Verisure blocking clients polling too often, so I think you are just remembering it wrong :)

Depechie commented 3 years ago

Yeah time is relative and difficult to ‘feel’ for sure :)

krissen commented 3 years ago

No, something has changed, for sure.

I concede that the issue of delay with regards to HA seeing changes in Verisure might be as it always has been. Could simply be the matter that it depends on how close to the next poll alarm status was changed, and that I simply had bad luck the first five times I changed Verisure status after upgrading.

However, when arming Verisure from HA, HA has previously set the status to "armed" straight away. No delay at all. (Whereas there has always been a delay if I'd arm the device from Verisure.) Now, it seemingly does not set the status immediately but instead waits for the status change at the Verisure end. This leads to a delay.

On the other hand, the current way might be more correct. (HA doesn't set status to, for instance, 'armed' before it actually sees that the Verisure status is armed (as opposed to setting it to armed when it's telling Verisure to arm).) But I preferred how it was earlier.

frenck commented 3 years ago

The integration has not changed in that period. There has been some cleanup, but zero/0/nada logic changes.

To be honest, I'm not experiencing this issue myself either...

krissen commented 3 years ago

The integration has not changed in that period. There has been some cleanup, but zero/0/nada logic changes.

I would rather suggest that something has changed in HA core that affects the integration.

To be honest, I'm not experiencing this issue myself either...

Does that include arming and disarming Verisure from within HA?

frenck commented 3 years ago

Does that include arming and disarming Verisure from within HA? yes

krissen commented 3 years ago

yes

So -- just curious -- has that never been instantaneous for you, or is it still?

To be clear, when I arm it from HA, Verisure does react immediately, but it now takes the 30-180 seconds or some such before HA acknowledges the fact. Whereas previously, HA reflected the state change directly (but probably not through a poll to Verisure).

Depechie commented 3 years ago

I can concur with @krissen that this is indeed the change we see. The Verisure notification pops up right away ( from the Verisure app ) when triggering an arm alarm through HA, but status change in HA will linger.

Previous HA did it instantaneous.

Kane610 commented 3 years ago

I disagree. It could take minutes for state changes to get notified through hass. I get notifications on alarm and disarm through homekit and I'm usually a fair distance from home when I get notified

krissen commented 3 years ago

I disagree. It could take minutes for state changes to get notified through hass. I get notifications on alarm and disarm through homekit and I'm usually a fair distance from home when I get notified

I am guessing we are talking about somewhat different things. What you describe is how it has always been, yes, when the alarm has been armed through Verisure. However, it used to be the case, that if the alarm was armed through HA, HA, HomeKit and Verisure would all reflect the state change immediately. Now, there is the delay you describe regardless of how it is armed -- delay for HA and HomeKit, that is; no delay with regards to Verisure itself.

krissen commented 3 years ago

The error showed at the bottom of this screenshot is something I never saw in HA <= 0.118. Now, I can reproduce it at will.

It is issued when I have armed the alarm from within HA, and try to arm it (again). It has, in fact, been armed already, but HA doesn't know it. I never saw it before, because it did not ever used to be the case, that HA wouldn't know it was armed --- if, that is, the alarm would have been armed from HA.

EDIT: I'll update with logs for the error later today.

krissen commented 3 years ago

So this doesn't give any more information as to why there's a delay, it is just the log for when Verisure has been armed from HA, but HA doesn't know it yet, and there is a second (and third) attempt to arm through HA. The latter two attempts fail with an error message that VS has, indeed, already been armed.

2021-01-16 00:12:58 INFO (SyncWorker_22) [homeassistant.components.verisure] verisure set arm state ARMED_HOME
2021-01-16 00:13:07 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140648999605152] Invalid response, status code: 400 - Data: {"errorGroup":"BAD_REQUEST","errorCode":"VAL_00818","errorMessage":"The requested arm state is not possible to apply due to armstate already set"}
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 135, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1445, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1480, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 593, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 664, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 630, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/alarm_control_panel/__init__.py", line 136, in async_alarm_arm_home
    await self.hass.async_add_executor_job(self.alarm_arm_home, code)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/verisure/alarm_control_panel.py", line 103, in alarm_arm_home
    set_arm_state("ARMED_HOME", code)
  File "/usr/src/homeassistant/homeassistant/components/verisure/alarm_control_panel.py", line 30, in set_arm_state
    transaction_id = hub.session.set_arm_state(code, state)[
  File "/usr/local/lib/python3.8/site-packages/verisure/session.py", line 215, in set_arm_state
    _validate_response(response)
  File "/usr/local/lib/python3.8/site-packages/verisure/session.py", line 16, in _validate_response
    raise ResponseError(response.status_code, response.text)
verisure.session.ResponseError: Invalid response, status code: 400 - Data: {"errorGroup":"BAD_REQUEST","errorCode":"VAL_00818","errorMessage":"The requested arm state is not possible to apply due to armstate already set"}
2021-01-16 00:13:14 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140648999605152] Invalid response, status code: 400 - Data: {"errorGroup":"BAD_REQUEST","errorCode":"VAL_00008","errorMessage":"Invalid or non-existing value for code"}
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 135, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1445, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1480, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 593, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 664, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 630, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/alarm_control_panel/__init__.py", line 136, in async_alarm_arm_home
    await self.hass.async_add_executor_job(self.alarm_arm_home, code)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/verisure/alarm_control_panel.py", line 103, in alarm_arm_home
    set_arm_state("ARMED_HOME", code)
  File "/usr/src/homeassistant/homeassistant/components/verisure/alarm_control_panel.py", line 30, in set_arm_state
    transaction_id = hub.session.set_arm_state(code, state)[
  File "/usr/local/lib/python3.8/site-packages/verisure/session.py", line 215, in set_arm_state
    _validate_response(response)
  File "/usr/local/lib/python3.8/site-packages/verisure/session.py", line 16, in _validate_response
    raise ResponseError(response.status_code, response.text)
verisure.session.ResponseError: Invalid response, status code: 400 - Data: {"errorGroup":"BAD_REQUEST","errorCode":"VAL_00008","errorMessage":"Invalid or non-existing value for code"}

This time it worked / was reflected instantaneously at both Verisure and HA:

2021-01-16 06:44:56 INFO (SyncWorker_27) [homeassistant.components.verisure] verisure set arm state DISARMED

Tried it out just now a couple more times.

First try at arming from HA: was reflected in VS and HA immediately. When disarming, it was disarmed at VS immediately and took roughly a minute for HA to catch up.

Second try five minutes later: arming from HA was reflected immediately at VS but took 69 seconds for HA. Disarming from HA was reflected immediately at VS but took 80 seconds for HA to notice.

So, this particular post includes reports of six individual alarm actions; three "arm home" and three disarm. All six were taken from within HA. Two (one "arm home" and one disarm) were reflected immediately at both VS and HA. Four was recognized immediately by VS but had delays of about a minute before HA reflected the state change.

In other words, it is not immediate all the time, but nor is there a delay (when arming from HA) at all times. But, restating just to be clear, there never used to be a delay when arming or disarming through HA (@ HA <= 0.118.*). However, there always was, and still is, when arming or disarming from the Verisure end.

... I should add that this is not a big deal, nor am I clamouring for it to be recognized as such. I merely noticed a change that I thought warranted reporting. If it would be a simple fix, I preferred when arming through HA led to HA knowing VS was armed straight away. But it, obviously, is not a big deal to wait 30-120 seconds or so.

frenck commented 3 years ago

That is a great report!

I just came by to tell you I experienced the same thing for the first time this morning, so definitely something is of...

hwoffinden commented 3 years ago

Thank you for reporting this. I too experience this behaviour.

thomasgermain commented 3 years ago

I have the same issue.

First occurred: 18:00:48 (65 occurrences)
Last logged: 23:09:49
...
verisure.session.RequestError: HTTPSConnectionPool(host='e-api02.verisure.com', port=443): Max retries exceeded with url: /xbn/2/installation/[REDACTED]/overview (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f959ac160>: Failed to establish a new connection: [Errno 110] Operation timed out'))

The log sounds really strange to me since my pages from verisure seems to work correctly and even https://e-api02.verisure.com/ is also responding correctly (as well as e-api01).

When I arm (or disarm) through HA (dedicated verisure user for HA), I receive a notification from verisure. The notification come instantly while it takes long time to HA to know status has changed (before 2021-1-x, it was also instantly). ->Exact same behavior as @krissen

KTHconsult commented 3 years ago

I get in line supporting this slow behaviour. Door binary censor is 1+ minute to report changes to HA in my case.

frenck commented 3 years ago

Door binary censor is 1+ minute to report changes to HA in my case.

That is correct behavior, as this is a polling integration.

frenck commented 3 years ago

So I've been using the new (rewritten) integration, that shipped with Home Assistant 2021.4 for a couple of weeks now and I haven't noticed any slowness with it as of now.

Can someone confirm the same?

krissen commented 3 years ago

So I've been using the new (rewritten) integration, that shipped with Home Assistant 2021.4 for a couple of weeks now and I haven't noticed any slowness with it as of now.

Can someone confirm the same?

I usually wait at least a couple of days after a .0 release, but I'll make an exception for this! :-) Will update and test.

Depechie commented 3 years ago

hey @frenck I updated to the new version, but it made it worse for me. The HomeKit integration is no longer working... status updates are not going through in any direction ( so doing actions in homekit have no effect and doing actions in home assistant do not reflect in homekit ). Also when performing an arm or disarm action in Home Assistant I now always get the popup stating: Unable to call service 'VerisureSmartcam' object has no attribute 'is_streaming'

Depechie commented 3 years ago

Details of the exception when trying anything in homekit

Logger: homeassistant.core
Source: components/verisure/alarm_control_panel.py:83
First occurred: 12:30:09 AM (1 occurrences)
Last logged: 12:30:09 AM

Error executing service: <ServiceCall alarm_control_panel.alarm_disarm (c:aecf01b98fda6496dfc53a06ce1b0d4d): entity_id=['alarm_control_panel.verisure_alarm']>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1496, in catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1515, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 206, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 649, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 692, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 686, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/verisure/alarm_control_panel.py", line 99, in async_alarm_disarm
    await self._async_set_arm_state("DISARMED", code)
  File "/usr/src/homeassistant/homeassistant/components/verisure/alarm_control_panel.py", line 83, in _async_set_arm_state
    arm_state = await self.hass.async_add_executor_job(
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/verisure/session.py", line 195, in set_arm_state
    _validate_response(response)
  File "/usr/local/lib/python3.8/site-packages/verisure/session.py", line 16, in _validate_response
    raise ResponseError(response.status_code, response.text)
verisure.session.ResponseError: Invalid response, status code: 400 - Data: {"errorGroup":"BAD_REQUEST","errorCode":"VAL_00008","errorMessage":"Invalid or non-existing value for code"}

krissen commented 3 years ago

I'm afraid I'm experiencing the same as @Depechie. There are now no state changes in the HA alarm panel. Not while HA is running in any case.

I can arm the alarm from within HA. Verisure acknowledged the action and actually arms, but HA is not aware of it; shows the system to be unarmed. A subsequent arming action results in an error, as reported above.

The status of the alarm panel is set correctly on server restart, however.

Status of binary sensors (doors, windows), are working better, I think; will have to do some more testing.

krissen commented 3 years ago

Just to add, also like @Depechie, I'm seeing the odd VerisureSmartcam error popup when disarming through HA. The action is carried out on Verisure. The alarm is actually disarmed. But HA does not reflect the fact. A second attempt to disarm in HA (although actually already disarmed if you'd ask Verisure) results in the previously reported error, as expected.

Despite waiting hours, the status does not change in HA. (As opposed to changing in minutes, in <2021.4.)

Restarting HA gets it up to speed again, with regards to the actual alarm status.

Happy to install a custom integration or some such to troubleshoot faster than testing changes through HA core updates would allow, @frenck! But would want to avoid HA core beta if possible.

krissen commented 3 years ago

Restarting the integration also updates HA's alarm panel to reflect the actual status.

My most recent attempt to arm through HA led to the curious result that (1) VS was armed; (2) HA reflected the fact but (3) HA also issued the previously mentioned camera error popup. Perhaps because of (3), the automations I've got set up surrounding the status of the alarm were not triggered. 🤷‍♂️ Despite the state change of the HA-entity.

frenck commented 3 years ago

But would want to avoid HA core beta if possible.

That is what beta's are for.... If no-one tests the beta than .0 will become a beta. Simple as that. We have around 300 beta testers, un fortunately, some bugs where not detected.

Nevertheless, 2 bugs, including the Smartcam error have been solved in 2021.4.1

thomasgermain commented 3 years ago

I just tested the 2020.4.1 (new clean docker image), no smartcam error and the status of the alarm seems to update without delay.

I'll update my "production" HA this week end and let you know

krissen commented 3 years ago

That is what beta's are for.... If no-one tests the beta than .0 will become a beta. Simple as that. We have around 300 beta testers, un fortunately, some bugs where not detected.

I hear you. But willingness to test parts is different from wanting to test HA beta core as a whole. It is one thing to have some, particular unstable parts; another to have all the parts unstable. But I digress.

Nevertheless, 2 bugs, including the Smartcam error have been solved in 2021.4.1

Excellent! Will upgrade, test and report.

krissen commented 3 years ago

Can confirm, works well now!

Still possible to get the BAD_REQUEST error. I'm guessing it happens when you larm/disarm quickly enough from HA that HA hasn't confirmed what's happening on VS' end. Worked if I waited a short while and tried again.

From my point of view, the issue can be closed. Not pulling the trigger in case you want to wait for further confirmations from additional users.

Thank you! 🙏

robinostlund commented 3 years ago

State updates for plugs is very slow for me, if i swtich to on it will turn on the light directly but the state takes around 20 seconds to be updated. Anyone else that have these issues?

frenck commented 3 years ago

@robinostlund That is expected, as this is a cloud polling integration. It take be even longer.

That is not a bug.

robinostlund commented 3 years ago

Yeah get that but it started in version 2021.4.0 and before that it was instant changing state after triggering switch.turn_on 🧐

frenck commented 3 years ago

Hmm... right assuming the changed state until an update arrives. I think the code for that is still there, will check that 👍

robinostlund commented 3 years ago

@frenck awesome thanks 😊

thomasgermain commented 3 years ago

Just tested it. It's working fine. This is really great to have the status update "instantly" after arming/disarming. Just one annoying thing, the integration is creating plenty of areas, I have 24 devices and it creates almost 1 area per device

frenck commented 3 years ago

The switch/wallplug states have been fixed and is part of Home Assistant 2021.5.0 (beta 2 and newer).

home-assistant / core