Hacs shows disconnected after (up to) 3 hours, have to constantly "reconfigure"

MithUK1 commented 1 year ago

Hi, this has been an issue fo rme since i styarted using this integration quite some time ago.
I leave this hoping the next version will fix my issue but it never does.

Eseentially at some random time interval after configuring the integration it will stop communicating with alarm.com and will show as needing reconfiguration:

Until that point, my motion sensors and alarm system are seen and function correctly

For note, I can still log in to alarm.com with the same username and password (and authenticator code) as normal.

However in the activity log you can see it does a web login over and again (to scrape the sensor activity is my guess) then at 11:01 it simply stops and the integration displays as recongure.

I'm unsure of what log or where to get it to help troubleshoot this issue further, but if you let me know i'll help from my end however i can. Thanks, M

elahd commented 1 year ago

Can you enable debug logging for the integration and post what shows up in Home Assistant's logs?

Add the following to configuration.yaml, then reboot:

logger:
  default: warn
  logs:
    custom_components.alarmdotcom: debug
    pyalarmdotcomajax: debug

catellie commented 1 year ago

I just installed this today and experience the same problem. After turning on the above, restarting and then re-authenticting I just see this in my log file:

2023-02-12 17:17:10.828 ERROR (MainThread) [pyalarmdotcomajax] Trying to refresh auth tokens by logging in again.
2023-02-12 17:17:15.525 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com.
2023-02-12 17:17:15.526 ERROR (MainThread) [pyalarmdotcomajax] Trying to refresh auth tokens by logging in again.
2023-02-12 17:17:19.342 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com.
2023-02-12 17:17:19.754 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com.
2023-02-12 17:17:19.755 ERROR (MainThread) [pyalarmdotcomajax] Trying to refresh auth tokens by logging in again.
2023-02-12 17:17:25.691 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com.
2023-02-12 17:17:25.692 ERROR (MainThread) [pyalarmdotcomajax] Trying to refresh auth tokens by logging in again.

Home Assistant appears to be happy at this stage though. :shrug: In case it matters, I'm located in Sweden and got this though the Garda reseller - which shows up as expected in the UI. The imported list of devices seems fairly reasonable, except for one device that the was just "unknown".

catellie commented 1 year ago

As I dig around more I also found this in the log:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 414, in async_add_entities
    tasks = [
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 414, in <listcomp>
    tasks = [
  File "/config/custom_components/alarmdotcom/alarm_control_panel.py", line 83, in <genexpr>
    AlarmControlPanel(
  File "/config/custom_components/alarmdotcom/alarm_control_panel.py", line 116, in __init__
    self._attr_supported_features = AlarmControlPanelEntityFeature(
  File "/usr/local/lib/python3.10/enum.py", line 385, in __call__
    return cls.__new__(cls, value)
  File "/usr/local/lib/python3.10/enum.py", line 710, in __new__
    raise ve_exc
ValueError: 7 is not a valid AlarmControlPanelEntityFeature

and later:

2023-02-12 17:19:19.415 ERROR (MainThread) [custom_components.alarmdotcom.alarmhub] Authentication failed while fetching Garda Alarm:REDACTED data: Invalid account credentials.

cmbuckley commented 1 year ago

Just to add to this, I see the following in debug logs:

2023-02-09 14:20:25.241 DEBUG (MainThread) [pyalarmdotcomajax] Logged in to Alarm.com.
2023-02-09 14:20:25.618 DEBUG (MainThread) [pyalarmdotcomajax] {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}
2023-02-09 14:20:25.619 ERROR (MainThread) [custom_components.alarmdotcom.alarmhub] Authentication failed while fetching ADT Smart Services:<redacted> data: Invalid account credentials.

There's no changes to the credentials to cause this. I tried reducing the sync frequency to see if it was a weak attempt at rate limiting, but that made no difference.

Somewhat related, because the underlying library makes opportunistic attempts to re-establish login when unsupported device types are found, this doubles the number of calls to the login endpoint.

elahd commented 1 year ago

Tagging @roooodcastro and @dkedinger from #207.

Can anyone running into this problem help inspect web browser cookies when logged into Alarm.com? To do this in Chrome:

Log in to alarm.com.
Right click anywhere on the page and select "Inspect".
In the inspector window, click on "Application" on top, then "Cookies" ->"https://www.alarm.com" in the left nav.
Send a screenshot of just the column circled in green.

@cmbuckley The add-in attempts to log in so frequently because, in some instances, Alarm.com returns the same response for expired credentials and lack of permissions. There's definitely a more intelligent way to go about this, just haven't gotten around to implementing it.

cmbuckley commented 1 year ago

Here's mine:

I appreciate why there's the repeated log-in, but as you say it'd be nice to have a better way to deal with this, such as being able to restrict the device types that are checked.

roooodcastro commented 1 year ago

Mine are similar:

Screenshot_20230213_185701

However, I must add that this is not just an annoyance. The integration functionality is affected too. I can arm/disarm the alarm just fine, sometimes it takes a couple of minutes, however all sensors, including the arm/disarm state sensor, have stale or simply wrong readings, due to them only updating sporadically.

There's definitely a more intelligent way to go about this, just haven't gotten around to implementing it.

Do you know what a solution for this looks like, or have you not looked into this at all yet? I could have a go at implementing it if you have a plan.

elahd commented 1 year ago

Thanks. The "afg" cookie is the AJAX cookie that the integration is complaining about missing. I thought that some providers may just not use that cookie, but looks like thats not the case since you all have it. I need to do a deeper dive and, also, release code that provides more detailed errors when the cookie goes missing. It's possible that the missing cookie is just a side effect of an upstream error.

@catellie The "7 is not a valid AlarmControlPanelEntityFeature" error should be fixed in the latest release.

@roooodcastro My plan was to have the integration look at the response object from either the system or partition endpoints. These objects contain a list of IDs for all sensors/devices in the system. If any device category has no devices listed, the library would skip over the endpoints for those devices on every subsequent refresh. This check would be done, say, once every 5-10 minutes so that the library could pick up new devices as they're added. This would need to be implemented in pyalarmdotcomajax, not in this Home Assistant integration.

cmbuckley commented 1 year ago

@elahd just to be clear here - the integration configures and works absolutely fine for a few hours, or a couple of days even, and then sporadically gets a bad response from the login endpoint, which causes the reconfigure notification.

As @roooodcastro mentioned, once that happens the sensors no longer perform their regular sync, even though the integration itself continues to work from the perspective of being able to set/unset the alarm.

Your suggestion of remembering empty device responses and skipping them from subsequent requests in the underlying library sounds spot on - but it feels like there's a separate need for an improved retry mechanism around that failed log-in, which is unfortunately coupled to the device detection because of the 403 responses when there's none of that device type.

catellie commented 1 year ago

@elahd : I updated earlier today, and as I got the red warning again now (hours later, but not when I upgraded) I re-authenticated and it appears to not make much of a difference:

This error originated from a custom integration.

Logger: homeassistant
Source: custom_components/alarmdotcom/alarm_control_panel.py:116
Integration: Alarm.com (documentation, issues)
First occurred: 10:23:29 PM (1 occurrences)
Last logged: 10:23:29 PM

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 414, in async_add_entities
    tasks = [
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 414, in <listcomp>
    tasks = [
  File "/config/custom_components/alarmdotcom/alarm_control_panel.py", line 83, in <genexpr>
    AlarmControlPanel(
  File "/config/custom_components/alarmdotcom/alarm_control_panel.py", line 116, in __init__
    self._attr_supported_features = AlarmControlPanelEntityFeature(
  File "/usr/local/lib/python3.10/enum.py", line 385, in __call__
    return cls.__new__(cls, value)
  File "/usr/local/lib/python3.10/enum.py", line 710, in __new__
    raise ve_exc
ValueError: 7 is not a valid AlarmControlPanelEntityFeature

I also got some Unable to extract ajax key from Alarm.com. REDACTED_FOR_POSTING messages. As well as custom_components.alarmdotcom.alarmhub: Error logging in:

Let me know if there is more info I can provide.

elahd commented 1 year ago

Thanks, @catellie. I'll release something later tonight in line with the last part of this comment to help with the multiple login attempts.

catellie commented 1 year ago

@elahd Either you were super fast or my previous update didn't fully "bite", as I found another which gives a different error:

Logger: homeassistant
Source: helpers/selector.py:72
First occurred: 10:45:37 PM (1 occurrences)
Last logged: 10:45:37 PM

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 225, in async_init
    flow, result = await task
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 252, in _async_init
    result = await self._async_handle_step(flow, flow.init_step, data, init_done)
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 367, in _async_handle_step
    result: FlowResult = await getattr(flow, method)(user_input)
  File "/config/custom_components/alarmdotcom/config_flow.py", line 291, in async_step_reauth
    return await self.async_step_reauth_confirm(user_input)
  File "/config/custom_components/alarmdotcom/config_flow.py", line 302, in async_step_reauth_confirm
    return await self.async_step_user()
  File "/config/custom_components/alarmdotcom/config_flow.py", line 127, in async_step_user
    vol.Required(CONF_USERNAME): TextSelector(
  File "/usr/src/homeassistant/homeassistant/helpers/selector.py", line 912, in __init__
    super().__init__(config)
  File "/usr/src/homeassistant/homeassistant/helpers/selector.py", line 72, in __init__
    self.config = self.CONFIG_SCHEMA(config)
  File "/usr/local/lib/python3.10/site-packages/voluptuous/schema_builder.py", line 272, in __call__
    return self._compiled([], data)
  File "/usr/local/lib/python3.10/site-packages/voluptuous/schema_builder.py", line 595, in validate_dict
    return base_validate(path, iteritems(data), out)
  File "/usr/local/lib/python3.10/site-packages/voluptuous/schema_builder.py", line 433, in validate_mapping
    raise er.MultipleInvalid(errors)
voluptuous.error.MultipleInvalid: extra keys not allowed @ data['autocomplete']

I hope that's more helpful? Using autocomplete for a login field seems like a rather bad idea... :facepalm:

elahd commented 1 year ago

@catellie Which version of Home Assistant are you using? Also, autocomplete use is in line with Home Assistant standards: https://developers.home-assistant.io/docs/data_entry_flow_index#enabling-browser-autofill. These autocomplete hints help password managers locate username, password, and OTP fields.

elahd commented 1 year ago

Also, I had a fix for the "reconfigure" issue ready to go but accidentally purged the Codespace before pushing the code 🤦🏻‍♂️. Currently waiting on a GitHub support ticket to recover the data.

catellie commented 1 year ago

@elahd I run Home Assistant 2022.12.0.dev20221114 Frontend 20221114.0.dev - latest in docker on Ubuntu. The actual docker has not been restarted for 5+ weeks so I guess "latest" might not be super accurate.

catellie commented 1 year ago

For the record: I had reason to restart my HA and noticed that I no longer get the complaining message and even though I have not re-authenticated since the above message (5 days ago), I could still toggle a light switch that came with my alarm. So I guess something has mended? How/why is unclear, but thanks anyway!

elahd commented 1 year ago

@catellie Thanks for the update. I think that some of the "extra" errors you were getting were related to your version of Home Assistant, although I'm not able to replicate them on my end in 2022.12.0.

@cmbuckley I implemented a smarter device update scheme that only hits endpoints for device types that are present in a user's account. The integration is also smarter about attempting to log back in -- it'll only log back in after verifying that it has been logged out. Can you re-install from the master branch to verify that everything works? @roooodcastro? Thanks!

elahd commented 1 year ago

Has anyone been able to test?

roooodcastro commented 1 year ago

Hi @elahd, sorry for the delay, I was away from home for a few days. I've re-downloaded it now from master a couple hours ago, and so far it's not prompting me to re-configure the integration anymore.

I do see however some errors that I don't remember seeing before (or I might just not have noticed either):

Error fetching data from Alarm.com. Got 403 status when fetching data for device type DeviceType.SYSTEM. User is already logged in. Giving up on device type.

I get these for a few device types, both from devices types I don't have, and these two SYSTEM, and SENSOR, which looks just generic. I'm getting a lot of these errors starting when I restarted HA after updating to master, and they keep showing up (last logged is 1 minute before I copied the text):

First occurred: 10:45:22 (722 occurrences)
Last logged: 12:02:47

The sensors also don't seem to be updating, I've triggered a motion sensor, some window/door sensors, and armed/disarmed the alarm, and the integration doesn't seem to pick up any of the events.

I'll update tomorrow how's it looking. Using the latest HA 2023.2.5 now too.

cmbuckley commented 1 year ago

I've updated today, but since the errors were sporadic I will give it a couple of days before reporting back with any logs.

elahd commented 1 year ago

Thanks, guys.

@roooodcastro Can you enable debugging for the integration (instructions)? I'd like to see the actual server response for that system data fetch error.

Also, which provider are you using?

catellie commented 1 year ago

Further to my previous feedback: it would appear that although I no longer see any errors, the integration is only half working.

Even though all devices seem to be registered as such and I'm able to toggle the power sockets from the app, very few sensor changes seem to be reported, for example: my kitchen lights automatically turn on at sun down and then off before bed time (this works perfectly fine as such since long before I installed HA), but the HA logs currently claim nothing has happened for 3+ days. Similarly, when I manually turn the alarm on it still shows as disarmed in HA (but it's correct in the Alarm.com app). Hence, I'm not able to automate stuff when I leave the house. :-(

Best / Jonas

Den ons 22 feb. 2023 02:38Elahd Bar-Shai @.***> skrev:

@catellie https://github.com/catellie Thanks for the update. I think that some of the "extra" errors you were getting were related to your version of Home Assistant, although I'm not able to replicate them on my end in 2022.12.0.

@cmbuckley https://github.com/cmbuckley I implemented a smarter device update scheme that only hits endpoints for device types that are present in a user's account. The integration is also smarter about attempting to log back in -- it'll only log back in after verifying that it has been logged out. Can you re-install from the master branch to verify that everything works? @roooodcastro https://github.com/roooodcastro? Thanks!

— Reply to this email directly, view it on GitHub https://github.com/pyalarmdotcom/alarmdotcom/issues/187#issuecomment-1439315698, or unsubscribe https://github.com/notifications/unsubscribe-auth/AADZ47KKC7CHVADD3A5GGJTWYVUZNANCNFSM6AAAAAAS2GTXNE . You are receiving this because you were mentioned.Message ID: @.***>

elahd commented 1 year ago

Thanks, @catellie. With the issues you had before the update, were the sensors updating as you expected them to? Also, can you enable debug mode and share the errors?

It seems like this issue is caused by some sort of intermittent connection issue or provider-specific rate limit. The debug logs should show the details.

catellie commented 1 year ago

Hi again @elahd ,

I'm not 100% sure about the sensors stability before since it wasn't really fully working. I believe I've seen my camera sensors occasionally report motion and the mentioned kitchen lights have at least HAPPENED to show the right state.

Still, I've had the debug mode on since day one (due to this issue) and scanning them I can see a couple of things (some of the them somewhat odd:

The login seems correct (there is a large ajax dump) and my provider is correctly named - presumably my rather long userid is OK and it says 2FA is not required.
An update listener is registered and then an update is requested, from which there is a trouble condition where it mentions that it cant get data from GARAGE_DOOR (status 423) along with messages in my local language - this odd mostly because I don't have any garage door sensor - so perhaps a hardcode?
Then a long list of my devices/sensors seems correctly initialized. (5.5 seconds runtime)
There is an arm config entry with update interval of 30 (seconds?) along with a long list of my devices again
About 30 s later there is an update request which fails (403) with: ``` [pyalarmdotcomajax] _async_get_items_and_subordinates(): Failed to get data for device type DeviceType.CAMERA. Response: [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]. Errors: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}.
That appears to trigger things to start over with login, GARAGE_DOOR complaint etc
After another dump of all my devices there is the pretty bad stacktrace with the extra "autocomplete" I mentioned earlier. (this is on the 22nd of Feb)

And then nothing more in the logs at all related to alarmdotcom (a fair amount about a broken ledstrip I'm aware of, though so logging certainly works in general).

Does this help? The garage door issue can presumably be removed although it appears harmless, but perhaps the autocomplete exception is what causes the updates to fail?

I can see the "garage_door" being imported in cover.py, but I've not decoded exactly where it fails to realize that it shouldn't bother with them...

As a side: the installer of my system named devices/sensors in my local language, which includes some non-ASCII characters, but at a glance that appears to correctly handled.

Best / Jonas

roooodcastro commented 1 year ago

Thanks, guys.

@roooodcastro Can you enable debugging for the integration (instructions)? I'd like to see the actual server response for that system data fetch error.

Also, which provider are you using?

Hi, I'm using Smartzone, which is an Irish provider for Alarm.com.

Since my last reply, nothing has really changed in the system. I'm not getting re-prompted over and over for login anymore, but sensors are not being updated at all.

Here's the full debug log of a single "update cycle":

2023-02-26 01:19:48.073 DEBUG (MainThread) [custom_components.alarmdotcom.alarmhub] custom_components.alarmdotcom.alarmhub: Requesting update from Alarm.com.
2023-02-26 01:19:48.073 DEBUG (MainThread) [pyalarmdotcomajax] Calling update on Alarm.com
2023-02-26 01:19:48.461 DEBUG (MainThread) [pyalarmdotcomajax] Trouble condition response: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}
2023-02-26 01:19:48.462 DEBUG (MainThread) [pyalarmdotcomajax] Refreshing data for device types: [<DeviceType.SYSTEM: 'systems'>, <DeviceType.CAMERA: 'cameras'>, <DeviceType.GARAGE_DOOR: 'garageDoors'>, <DeviceType.GATE: 'gates'>, <DeviceType.IMAGE_SENSOR: 'imageSensors'>, <DeviceType.LIGHT: 'lights'>, <DeviceType.LOCK: 'locks'>, <DeviceType.PARTITION: 'partitions'>, <DeviceType.SENSOR: 'sensors'>, <DeviceType.THERMOSTAT: 'thermostats'>, <DeviceType.WATER_SENSOR: 'waterSensors'>]
2023-02-26 01:19:48.881 DEBUG (MainThread) [pyalarmdotcomajax] _async_build_device_list(): Failed to get data for device type DeviceType.SYSTEM. Response: [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]. Errors: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}.
2023-02-26 01:19:48.881 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com. Got 403 status when fetching data for device type DeviceType.SYSTEM. User is already logged in. Giving up on device type.
2023-02-26 01:19:48.886 DEBUG (MainThread) [pyalarmdotcomajax] Server response: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}
2023-02-26 01:19:49.267 DEBUG (MainThread) [pyalarmdotcomajax] _async_build_device_list(): Failed to get data for device type DeviceType.CAMERA. Response: [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]. Errors: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}.
2023-02-26 01:19:49.267 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com. Got 403 status when fetching data for device type DeviceType.CAMERA. User is already logged in. Giving up on device type.
2023-02-26 01:19:49.272 DEBUG (MainThread) [pyalarmdotcomajax] Server response: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}
2023-02-26 01:19:49.273 DEBUG (MainThread) [pyalarmdotcomajax] Skipping GARAGE_DOOR. Not installed in user environment.
2023-02-26 01:19:49.274 DEBUG (MainThread) [pyalarmdotcomajax] Skipping GATE. Not installed in user environment.
2023-02-26 01:19:49.657 DEBUG (MainThread) [pyalarmdotcomajax] _async_build_device_list(): Failed to get data for device type DeviceType.IMAGE_SENSOR. Response: [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]. Errors: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}.
2023-02-26 01:19:49.657 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com. Got 403 status when fetching data for device type DeviceType.IMAGE_SENSOR. User is already logged in. Giving up on device type.
2023-02-26 01:19:49.662 DEBUG (MainThread) [pyalarmdotcomajax] Server response: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}
2023-02-26 01:19:49.662 DEBUG (MainThread) [pyalarmdotcomajax] Skipping LIGHT. Not installed in user environment.
2023-02-26 01:19:49.663 DEBUG (MainThread) [pyalarmdotcomajax] Skipping LOCK. Not installed in user environment.
2023-02-26 01:19:50.082 DEBUG (MainThread) [pyalarmdotcomajax] _async_build_device_list(): Failed to get data for device type DeviceType.PARTITION. Response: [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]. Errors: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}.
2023-02-26 01:19:50.083 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com. Got 403 status when fetching data for device type DeviceType.PARTITION. User is already logged in. Giving up on device type.
2023-02-26 01:19:50.086 DEBUG (MainThread) [pyalarmdotcomajax] Server response: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}
2023-02-26 01:19:50.492 DEBUG (MainThread) [pyalarmdotcomajax] _async_build_device_list(): Failed to get data for device type DeviceType.SENSOR. Response: [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]. Errors: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}.
2023-02-26 01:19:50.493 ERROR (MainThread) [pyalarmdotcomajax] Error fetching data from Alarm.com. Got 403 status when fetching data for device type DeviceType.SENSOR. User is already logged in. Giving up on device type.
2023-02-26 01:19:50.495 DEBUG (MainThread) [pyalarmdotcomajax] Server response: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}
2023-02-26 01:19:50.496 DEBUG (MainThread) [pyalarmdotcomajax] Skipping THERMOSTAT. Not installed in user environment.
2023-02-26 01:19:50.496 DEBUG (MainThread) [pyalarmdotcomajax] Skipping WATER_SENSOR. Not installed in user environment.
2023-02-26 01:19:50.497 DEBUG (MainThread) [custom_components.alarmdotcom.alarmhub] Finished fetching Smartzone:<MY USERNAME> data in 2.424 seconds (success: True)
2023-02-26 01:19:50.497 DEBUG (MainThread) [custom_components.alarmdotcom.alarm_control_panel] Processing state DeviceState.DISARMED for My Home
2023-02-26 01:19:50.498 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Front Door
2023-02-26 01:19:50.499 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.ACTIVE for Hallway Motion Detector
2023-02-26 01:19:50.499 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Kitchen Back Door
2023-02-26 01:19:50.499 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Living Room Window Left
2023-02-26 01:19:50.500 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Living Room Window Right
2023-02-26 01:19:50.501 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Panel Glass Break
2023-02-26 01:19:50.502 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Panel Motion
2023-02-26 01:19:50.502 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.ACTIVE for Upstairs Motion Detector

While all doors and windows are indeed closed, I know for a fact that at least one of those motion sensors are not detecting any motion, and that my alarm is armed, not disarmed, so I know that this data is not correct.

Thanks

catellie commented 1 year ago

Further to my message above, I also experimented with arming from HA:

When showing the "disarmed" state, pressing "arm home" does indeed work in the end - it just takes a while before it is shown as such. However, in the armed state pressing disarm appears to never complete correctly - but checking the state in their own app indicate that it was actually successful.
Logs from around the same state look generally the same as indicated above, but strangely now also complains (403) about a THERMOSTAT which I indeed don't have either.
Around this time (presumably unrelated) my extra display (aka IQ Remote) stopped communicating with the main panel - various retries later I gave up and just rebooted it and now it is happy again.

So, I guess we are mostly in the same state, where a fair number of active switching through HA is possible, but sensing changes mostly does not work, and there are indications that the calls to the Alarm.com site are not quite in sync with what sensors that actually exist (Garage door/Gate/Thermostat) - possibly also being fragile when it comes to offline sensors (such as my IQ remote).

Best / Jonas

elahd commented 1 year ago

Ok, I think this may be the problem -- from @roooodcastro's logs:

2023-02-26 01:19:48.881 DEBUG (MainThread) [pyalarmdotcomajax] _async_build_device_list(): Failed to get data for device type DeviceType.SYSTEM. Response: [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]. Errors: {'errors': [{'status': '403', 'detail': 'NotAllowed', 'code': 403}]}.

The integration uses DeviceType.SYSTEM as the root element for an alarm system. The hierarchy is DeviceType.SYSTEM -> DeviceType.PARTITION -> All other device types. If the integration can't find a DeviceType.SYSTEM, it fails ungracefully. It also won't be able to build a list of which device types you have, meaning that it will check endpoints for device types that you don't own.

Are you using accounts with limited / custom permissions with the integration or is the integration logged in using an account with "Master Control" / "Full Control" permissions? If you're using a limited account, can you see what happens if you use a Full Control?

@roooodcastro: When a device is showing an incorrect state, can you pull its debug entry from Home Assistant and post here?

catellie commented 1 year ago

I'm most certainly logging in with the "master" user (marked with a 🌟 in the app), but perhaps my local reseller has added some limitations or setup something incorrectly? My only partition is just named "partition1" and I never had any garage door or gate in my system, so neither should be probed for if things are working correctly. Perhaps we need a way to filter out incorrect stuff?

roooodcastro commented 1 year ago

I'm also using the master user, like @catellie said with the star beside the name.

What do you mean by pull its debug entry? It's not one or a few, all my sensors are wrong. I've opened doors/windows today, armed/disarmed the alarm, activated motion sensors multiple times by walking in the house, but none of the sensors/states have changed since.

I can still perform arming/disarming actions, but even these won't update the state of the alarm entity in HA, it just remains in the same state it was at the last HA reboot yesterday.

catellie commented 1 year ago

@roooodcastro yup, sound very much like we're in the same (or exceedingly similar) boat. I see the occasional alarm state update, but I'm pretty sure whatever was supposed to listen to the sensor states died in that stack trace. Plus the garage/gate confusion. My gut feeling is that the initial handshake goes reasonably well, which makes the list of devices (along with states at the time) look ok at a glance, and the recent fix appears to keep the session intact, but since the listener is confused/dead only explicit actions from HA will do anything.

roooodcastro commented 1 year ago

I've noticed that whenever the integration is reloaded (or when it initially starts after a HA restart), I do get a valid response from Alarm.com and it seems to fetch the sensor values correctly this one time, but after that it behaves like I mentioned above.

I tried reloading the integration after (physically) changing the state of one of the sensors, and the sensor state in HA was updated. So whatever is done when starting the integration is working flawlessly, but the periodic update is the one failing.

Here's the full initialization log (I've removed any IDs or identifying info and replaced them with {redacted}):

Btw, my doorbell camera is not currently working properly, so the "trouble condition response" you see for it is valid and correct.

2023-02-25 22:10:39.835 DEBUG (MainThread) [custom_components.alarmdotcom] custom_components.alarmdotcom: Initializing Alarmdotcom from config entry.
2023-02-25 22:10:39.835 DEBUG (MainThread) [pyalarmdotcomajax] Attempting to log in to Alarm.com
2023-02-25 22:10:41.649 DEBUG (MainThread) [pyalarmdotcomajax] Response status from Alarm.com: 200
2023-02-25 22:10:41.846 DEBUG (MainThread) [pyalarmdotcomajax] {'__VIEWSTATE': '{redacted}', '__VIEWSTATEGENERATOR': '{redacted}', '__EVENTVALIDATION': '{redacted}', '__PREVIOUSPAGE': '{redacted}'}
2023-02-25 22:10:43.901 DEBUG (MainThread) [pyalarmdotcomajax] Logged in to Alarm.com.
2023-02-25 22:10:44.760 DEBUG (MainThread) [pyalarmdotcomajax] Got Provider: Smartzone, User ID: {redacted}
2023-02-25 22:10:44.762 DEBUG (MainThread) [custom_components.alarmdotcom.alarmhub] custom_components.alarmdotcom.alarmhub: Registered update listener.
2023-02-25 22:10:44.762 DEBUG (MainThread) [custom_components.alarmdotcom.alarmhub] custom_components.alarmdotcom.alarmhub: Requesting update from Alarm.com.
2023-02-25 22:10:44.762 DEBUG (MainThread) [pyalarmdotcomajax] Calling update on Alarm.com
2023-02-25 22:10:45.159 DEBUG (MainThread) [pyalarmdotcomajax] Trouble condition response: {'data': [{'id': '{redacted}', 'type': 'troubleConditions/trouble-condition', 'attributes': {'description': 'Video Device - Not Responding (Doorbell camera)', 'extraData': {'description': 'Unplug the device for 10 seconds and then reconnect the power cord. If the LED is not solid green, click the "Troubleshoot" button.', 'buttonText': 'Troubleshoot', 'deviceId': 2048, 'isWirelessCamera': True, 'cameraModel': 'ADC-VDB105x'}, 'severity': 2, 'troubleConditionType': 21, 'deviceId': 2048, 'emberDeviceId': '{redacted}', 'canBeMutedOrReset': False, 'sinceUtc': '0001-01-01T00:00:00'}, 'relationships': {'system': {'data': {'id': '{redacted}', 'type': 'systems/system'}}}}], 'included': [], 'meta': {'transformer_version': '1.1'}}
2023-02-25 22:10:45.160 DEBUG (MainThread) [pyalarmdotcomajax] Refreshing data for device types: [<DeviceType.SYSTEM: 'systems'>, <DeviceType.CAMERA: 'cameras'>, <DeviceType.GARAGE_DOOR: 'garageDoors'>, <DeviceType.GATE: 'gates'>, <DeviceType.IMAGE_SENSOR: 'imageSensors'>, <DeviceType.LIGHT: 'lights'>, <DeviceType.LOCK: 'locks'>, <DeviceType.PARTITION: 'partitions'>, <DeviceType.SENSOR: 'sensors'>, <DeviceType.THERMOSTAT: 'thermostats'>, <DeviceType.WATER_SENSOR: 'waterSensors'>]
2023-02-25 22:10:45.606 DEBUG (MainThread) [pyalarmdotcomajax] Installed device types: {<DeviceType.IMAGE_SENSOR: 'imageSensors'>, <DeviceType.SENSOR: 'sensors'>, <DeviceType.PARTITION: 'partitions'>, <DeviceType.SCENE: 'scenes'>, <DeviceType.GEO_DEVICE: 'geoDevices'>, <DeviceType.CAMERA: 'cameras'>}
2023-02-25 22:10:45.607 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized systems/system {redacted}'s system
2023-02-25 22:10:46.001 DEBUG (MainThread) [pyalarmdotcomajax] Installed device types: {<DeviceType.IMAGE_SENSOR: 'imageSensors'>, <DeviceType.SENSOR: 'sensors'>, <DeviceType.PARTITION: 'partitions'>, <DeviceType.SCENE: 'scenes'>, <DeviceType.GEO_DEVICE: 'geoDevices'>, <DeviceType.CAMERA: 'cameras'>}
2023-02-25 22:10:46.001 DEBUG (MainThread) [pyalarmdotcomajax] Skipping GARAGE_DOOR. Not installed in user environment.
2023-02-25 22:10:46.001 DEBUG (MainThread) [pyalarmdotcomajax] Skipping GATE. Not installed in user environment.
2023-02-25 22:10:46.769 DEBUG (MainThread) [pyalarmdotcomajax] Installed device types: {<DeviceType.IMAGE_SENSOR: 'imageSensors'>, <DeviceType.SENSOR: 'sensors'>, <DeviceType.PARTITION: 'partitions'>, <DeviceType.SCENE: 'scenes'>, <DeviceType.GEO_DEVICE: 'geoDevices'>, <DeviceType.CAMERA: 'cameras'>}
2023-02-25 22:10:46.770 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized image-sensor/image-sensor Panel Camera
2023-02-25 22:10:46.770 DEBUG (MainThread) [pyalarmdotcomajax] Skipping LIGHT. Not installed in user environment.
2023-02-25 22:10:46.770 DEBUG (MainThread) [pyalarmdotcomajax] Skipping LOCK. Not installed in user environment.
2023-02-25 22:10:47.187 DEBUG (MainThread) [pyalarmdotcomajax] Installed device types: {<DeviceType.IMAGE_SENSOR: 'imageSensors'>, <DeviceType.SENSOR: 'sensors'>, <DeviceType.PARTITION: 'partitions'>, <DeviceType.SCENE: 'scenes'>, <DeviceType.GEO_DEVICE: 'geoDevices'>, <DeviceType.CAMERA: 'cameras'>}
2023-02-25 22:10:47.187 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/partition My Home
2023-02-25 22:10:47.612 DEBUG (MainThread) [pyalarmdotcomajax] Installed device types: {<DeviceType.IMAGE_SENSOR: 'imageSensors'>, <DeviceType.SENSOR: 'sensors'>, <DeviceType.PARTITION: 'partitions'>, <DeviceType.SCENE: 'scenes'>, <DeviceType.GEO_DEVICE: 'geoDevices'>, <DeviceType.CAMERA: 'cameras'>}
2023-02-25 22:10:47.612 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Front Door
2023-02-25 22:10:47.612 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Hallway Motion Detector
2023-02-25 22:10:47.612 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Kitchen Back Door
2023-02-25 22:10:47.612 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Living Room Window Left
2023-02-25 22:10:47.612 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Living Room Window Right
2023-02-25 22:10:47.612 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Panel Camera
2023-02-25 22:10:47.613 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Panel Glass Break
2023-02-25 22:10:47.613 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Panel Motion
2023-02-25 22:10:47.613 DEBUG (MainThread) [pyalarmdotcomajax.devices] Initialized devices/sensor Upstairs Motion Detector
2023-02-25 22:10:47.613 DEBUG (MainThread) [pyalarmdotcomajax] Skipping THERMOSTAT. Not installed in user environment.
2023-02-25 22:10:47.613 DEBUG (MainThread) [pyalarmdotcomajax] Skipping WATER_SENSOR. Not installed in user environment.
2023-02-25 22:10:47.613 DEBUG (MainThread) [custom_components.alarmdotcom.alarmhub] Finished fetching Smartzone:{my username, redacted} data in 2.851 seconds (success: True)
2023-02-25 22:10:47.613 DEBUG (MainThread) [custom_components.alarmdotcom] Alarmdotcom config options {'arm_code': '', 'arm_home_options': [], 'arm_away_options': ['no_entry_delay'], 'arm_night_options': [], 'update_interval': 30}
2023-02-25 22:10:47.613 DEBUG (MainThread) [custom_components.alarmdotcom] {'{bunch of IDs, redacted}'}
2023-02-25 22:10:47.653 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [partition: My Home ({redacted})].
2023-02-25 22:10:47.654 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [sensor: Front Door ({redacted})].
2023-02-25 22:10:47.679 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [sensor: Hallway Motion Detector ({redacted})].
2023-02-25 22:10:47.679 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [sensor: Kitchen Back Door ({redacted})].
2023-02-25 22:10:47.681 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [sensor: Living Room Window Left ({redacted})].
2023-02-25 22:10:47.682 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [sensor: Living Room Window Right ({redacted})].
2023-02-25 22:10:47.684 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [sensor: Panel Glass Break ({redacted})].
2023-02-25 22:10:47.684 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [sensor: Panel Motion ({redacted})].
2023-02-25 22:10:47.684 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [sensor: Upstairs Motion Detector ({redacted})].
2023-02-25 22:10:47.684 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Front Door ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.685 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Hallway Motion Detector ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.685 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Kitchen Back Door ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.685 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Living Room Window Left ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.685 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Living Room Window Right ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.685 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Panel Glass Break ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.685 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Panel Motion ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.685 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Upstairs Motion Detector ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.686 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Partition: My Home ({redacted})] [Attribute: Battery].
2023-02-25 22:10:47.687 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Front Door ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.687 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Hallway Motion Detector ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.688 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Kitchen Back Door ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.688 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Living Room Window Left ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.688 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Living Room Window Right ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.688 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Panel Glass Break ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.688 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Panel Motion ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.694 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Upstairs Motion Detector ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.695 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Partition: My Home ({redacted})] [Attribute: Malfunction].
2023-02-25 22:10:47.695 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Front Door ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.696 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Hallway Motion Detector ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.696 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Kitchen Back Door ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.696 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Living Room Window Left ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.696 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Living Room Window Right ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.696 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Panel Glass Break ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.696 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Panel Motion ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.696 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Sensor: Upstairs Motion Detector ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.696 DEBUG (MainThread) [custom_components.alarmdotcom.base_device] custom_components.alarmdotcom.base_device: Initializing [Partition: My Home ({redacted})] [Attribute: Debug].
2023-02-25 22:10:47.698 DEBUG (MainThread) [custom_components.alarmdotcom.alarm_control_panel] Processing state DeviceState.DISARMED for My Home
2023-02-25 22:10:47.699 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Front Door
2023-02-25 22:10:47.700 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.ACTIVE for Hallway Motion Detector
2023-02-25 22:10:47.701 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Kitchen Back Door
2023-02-25 22:10:47.702 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Living Room Window Left
2023-02-25 22:10:47.703 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Living Room Window Right
2023-02-25 22:10:47.703 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Panel Glass Break
2023-02-25 22:10:47.704 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.CLOSED for Panel Motion
2023-02-25 22:10:47.705 DEBUG (MainThread) [custom_components.alarmdotcom.binary_sensor] Processing state DeviceState.ACTIVE for Upstairs Motion Detector
2023-02-25 22:10:47.740 DEBUG (MainThread) [custom_components.alarmdotcom] custom_components.alarmdotcom: Finished initializing Alarmdotcom from config entry.

cmbuckley commented 1 year ago

This reflects my findings too - no errors with the integration, but none of the sensor states have changed since updating.

catellie commented 1 year ago

Just double checking @elahd , @cmbuckley and @roooodcastro : did you filter the logs on pyalarmdotcomajax or examine the raw logs? I've noticed that the filter will skip the (IMHO important) stack trace:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 225, in async_init
    flow, result = await task
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 252, in _async_init
    result = await self._async_handle_step(flow, flow.init_step, data, init_done)
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 367, in _async_handle_step
    result: FlowResult = await getattr(flow, method)(user_input)
  File "/config/custom_components/alarmdotcom/config_flow.py", line 291, in async_step_reauth
    return await self.async_step_reauth_confirm(user_input)
  File "/config/custom_components/alarmdotcom/config_flow.py", line 302, in async_step_reauth_confirm
    return await self.async_step_user()
  File "/config/custom_components/alarmdotcom/config_flow.py", line 127, in async_step_user
    vol.Required(CONF_USERNAME): TextSelector(
  File "/usr/src/homeassistant/homeassistant/helpers/selector.py", line 912, in __init__
    super().__init__(config)
  File "/usr/src/homeassistant/homeassistant/helpers/selector.py", line 72, in __init__
    self.config = self.CONFIG_SCHEMA(config)
  File "/usr/local/lib/python3.10/site-packages/voluptuous/schema_builder.py", line 272, in __call__
    return self._compiled([], data)
  File "/usr/local/lib/python3.10/site-packages/voluptuous/schema_builder.py", line 595, in validate_dict
    return base_validate(path, iteritems(data), out)
  File "/usr/local/lib/python3.10/site-packages/voluptuous/schema_builder.py", line 433, in validate_mapping
    raise er.MultipleInvalid(errors)
voluptuous.error.MultipleInvalid: extra keys not allowed @ data['autocomplete']

... which in my mind could very well be the reason why the listener doesn't pick up anything...

elahd commented 1 year ago

@catellie You're getting that error because you're running an old version of Home Assistant. The "autocomplete" feature first appears in 2022.12.0. See home-assistant/core#81060.

Your dev build may have just missed that commit. Can you update to a newer version?

catellie commented 1 year ago

@elahd Color me confused: I've now forcefully pulled, stopped, removed and restarted my docker image and it STILL claims to be the same version in the dialog as before. I initially tried fiddling with my kitchen lights which appeared to work once (on) and then it turned unavailable (along with what I've named "relay"), but I still could reach the furthest away one. As this was visible also on my local panel, I ran a self diagnostic there, which seemed to reboot twice before it was happy. And low and behold: I no longer see the stack trace and although states aren't instant, I now seem to be able to arm + disarm as well as tweak the lights. Clearly I've not yet let it run for the mentioned 3 hours, but it certainly seems a lot better than before! So, tentative theory: my experience was a combination oldish docker image and the control panel needing a reset!

elahd commented 1 year ago

Three questions for you guys:

1️⃣ Looking at node-alarm-dot-com/homebridge-node-alarm-dot-com#23, is the refresh failure resolved if you increase your polling time to 90 seconds? I'm working on WebSocket support for this integration, so you wouldn't be stuck with a high poll time for long. I'm curious to see whether this fixes your issues.

@roooodcastro Based on this comment, your instance is running into 403 errors on all endpoints when it attempts to refresh. It should be wiping out your entity statuses to clearly indicate a failure but is instead just keeping the prior values. I'll work on this. 2️⃣ Can you check your Home Assistant config_entries file to see if a two factor code is stored for Alarm.com? Check /config/.storage/core.config_entries. This file is one large JSON object. Search for "alarmdotcom". Within the alarmdotcom entry, you should see this:

        "data": {
          "username": "<YOUR_USERNAME>",
          "password": "<YOUR_PASSWORD>",
          "2fa_cookie": "<LONG_ALL_CAPS_ALPHANUMERIC_STRING>"
        },

Don't paste it here, but can you tell me whether you see a 2fa_cookie in the alarmdotcom entry and whether the format looks correct?

3️⃣ Last, log into the alarm.com website, then go to Settings > Login Information > Linked Devices. Do you see a bunch of entries with the name "Home Assistant (XXX)"?

catellie commented 1 year ago

Here are my answers: 1) I've adjusted, but will have to come back with results 2) My 2fa line only says: null (also, a few lines down the update interval has been adjusted) 3) I see nothing about "Home Assistant ...", but instead a fair number of "Other" entries all of them with an incorrectly (but consistent) reverse lookup of my location. There is also a handful of correctly identified devices (though still with the same incorrect location). At a glance the number of "Other" entries could very well match the number of warning emails I've had recently about new logins.... ;-) I guess some parts of the request is intentionally altered with a unique ID that the alarm.com site doesn't appreciate much...

Best / Jonas

roooodcastro commented 1 year ago

Here are mine:

Adjusted mine to 90s 1 hour ago, but it seems to still throw the 403 errors
Yes, I do have a 2fa_cookie entry and it does seem to be populated with valid data
I have a bunch of HomeAssistant entries there, including one with a recent login a few minutes before I checked

I also noticed this new error after HA restarted. I've just updated to 2023.3.0, the new version released an hour ago:

2023-03-01 22:52:23.943 ERROR (MainThread) [custom_components.alarmdotcom.alarmhub] Unexpected error fetching Smartzone:{redacted} data:
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/aiohttp/connector.py", line 1152, in _create_direct_connection
hosts = await asyncio.shield(host_resolved)
File "/usr/local/lib/python3.10/site-packages/aiohttp/connector.py", line 874, in _resolve_host
addrs = await self._resolver.resolve(host, port, family=self._family)
File "/usr/local/lib/python3.10/site-packages/aiohttp/resolver.py", line 33, in resolve
infos = await self._loop.getaddrinfo(
File "/usr/local/lib/python3.10/asyncio/base_events.py", line 863, in getaddrinfo
return await self.run_in_executor(
File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/usr/local/lib/python3.10/socket.py", line 955, in getaddrinfo
for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -3] Try again
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/pyalarmdotcomajax/__init__.py", line 871, in _async_get_trouble_conditions
async with self._websession.get(
File "/usr/local/lib/python3.10/site-packages/aiohttp/client.py", line 1141, in __aenter__
self._resp = await self._coro
File "/usr/local/lib/python3.10/site-packages/aiohttp/client.py", line 536, in _request
conn = await self._connector.connect(
File "/usr/local/lib/python3.10/site-packages/aiohttp/connector.py", line 540, in connect
proto = await self._create_connection(req, traces, timeout)
File "/usr/local/lib/python3.10/site-packages/aiohttp/connector.py", line 901, in _create_connection
_, proto = await self._create_direct_connection(req, traces, timeout)
File "/usr/local/lib/python3.10/site-packages/aiohttp/connector.py", line 1166, in _create_direct_connection
raise ClientConnectorError(req.connection_key, exc) from exc
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host www.alarm.com:443 ssl:default [Try again]
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 239, in _async_refresh
self.data = await self._async_update_data()
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 195, in _async_update_data
return await self.update_method()
File "/config/custom_components/alarmdotcom/alarmhub.py", line 227, in async_update
await self.system.async_update()
File "/usr/local/lib/python3.10/site-packages/pyalarmdotcomajax/__init__.py", line 347, in async_update
await self._async_get_trouble_conditions()
File "/usr/local/lib/python3.10/site-packages/pyalarmdotcomajax/__init__.py", line 913, in _async_get_trouble_conditions
raise DataFetchFailed from err
pyalarmdotcomajax.errors.DataFetchFailed

Let me know if this looks to be caused by the update to 2023.3.0, so I can rollback to 2023.2.5.

catellie commented 1 year ago

Further to the above:

As mentioned I set the poll time to 90s last night and when I toggled the alarm on (armed home) from HA and then back off it showed up correctly in the log (somewhat slow as expected). However, I used the panel next to my door to arm away this morning and then auto-armed off (BT sensor in my paired phone) when I later returned and neither of these are shown in the HA history.

(Side note: It is somewhat less than obvious that you need to click the "Disarmed" icon to see the history etc...)

For the record: The whole reason for me to install this feature is to automate turning stuff off/on when the "arm away" event happens, so clearly this not working is something I would very much like to help sorting out if possible.

BTW: I just found another stack trace complaining about "autocomplete" so I guess that's proof somehow still have run the older docker image. :thinking:

catellie commented 1 year ago

Apparently docker had me fooled - there was more than one image and the one I updated was apparently not the one that was actually used. :facepalm: Some fiddling later and I'm actually on 2023.4.0.dev20230302 After a restart I had to update my country for some reason, then alarmdotcom complain about login and after reauth and reload I believe I actually where I though I was earlier. Using HA to arm/disarm seems to work as before. Also as before, when I use the panel to arm/disarm HA does not register things, BUT at least now the logs make a bit more sense: I get the 403 for DeviceType.CAMERA, then a 200 from the login where it complains about the DeviceType.GARAGE_DOOR and GATE as before. A new details is a 403 from DeviceType.IMAGE_SENSOR and then a refresh of the auth tokens ny login which results in 200 BUT the ajax key is not found in that response - it appears to just contain headers? So the log reports "Update failed", "Error fetching ...." and "(success: False)" and then seem happy to "Processing state DeviceState.DISARMED for partition1" Then another login try that returns 423, further complaints around the GARAGE_DOOR and GATE and so on.

I would say that the primary suspect is Unable to extract ajax key from Alarm.com. from the 200 OK call to the login service. :shrug:

elahd commented 1 year ago

@catellie:

Do you use two factor authentication to log in?
About your HA version, can you try updating manually from within the docker container using pip3 install homeassistant==2023.3.0? You can confirm your installed version under Settings > About.

@roooodcastro:

This looks like a different issue than what you were running into before. This isn't the result of a 403, it's the result of a connectivity issue between HA and Alarm.com:

File "/usr/local/lib/python3.10/site-packages/aiohttp/connector.py", line 1166, in _create_direct_connection
raise ClientConnectorError(req.connection_key, exc) from exc
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host www.alarm.com:443 ssl:default [Try again]

Was this a one-time error or are you getting it consistently?

catellie commented 1 year ago

@elahd 1) Nope, just userud + passwd 2) Might try that at some stage, but now the dialog seems correct: 2023.4.0.dev20230302

elahd commented 1 year ago

@catellie Thanks! Would you mind using a prod branch for a bit to help eliminate any potential unrelated errors?

elahd commented 1 year ago

@catellie

I would say that the primary suspect is Unable to extract ajax key from Alarm.com. from the 200 OK call to the login service. 🤷

Yep, that appears to be the case. I just found in the enum at https://www.alarm.com/web/system/assets/@adc/ajax/enums/AjaxResponseHttpCode.ts:

export const InvalidAntiForgeryToken = 403;

The "ajax key" is the anti-forgery token, but I'm not sure of what the issue is. Can you see if the afg field changes at all while you browse Alarm.com?

roooodcastro commented 1 year ago

@elahd Sorry, false alarm, that error seems to only have happened once. It's business as usual here with the 403 errors.

catellie commented 1 year ago

[Sorry, been offline for a while]. @elahd Any preference on the image? I just tried "latest" which gives me Home Assistant 2023.3.0 Frontend-version: 20230301.0 - latest - the "stable" one seems much older. With this image I got a couple of hacs plug updates (including Alarmdotcom) and right now the ajax key problem seems not to manifest. :tada: I still get 403 for SYSTEM and some other things, BUT now CAMERA, GARAGE_DOOR and GATE are skipped with "Not installed in user environment" - this seems like a good step forward! (Although I have a couple of cameras, they are not top priority to get to work with HA in my mind so I don't mind them being ignored)

The logs appears to indicate that sensors are now refreshed regularly at least. I'll keep an eye on that for a while...

Side note: I'm assuming the GARAGE_DOOR is a proper, advanced type of device - technically I have an ordinary door sensor on a door that leads to the garage, but it not named as such, so could hardly be picked up here unless there is severe (and misguided) AI applied.

I do see a couple of stack traces still, but none of them appear to be related to alarmdotcom (I have a broken tapo strip where the spare part should arrive next week).

catellie commented 1 year ago

Well, something is still not quite right with the state refresh. My usual test case is my kitchen window lights (a Zigbee NEXA socket) and although the INITIAL state is correctly shown for this one (as well as the other ones), after I use the Alarm.com app to turn it off, the following (several) updates claim:

2023-03-05 17:26:08.785 DEBUG (MainThread) [custom_components.alarmdotcom.light] Processing state DeviceState.ON for KitchenWindow

Manually refreshing my panel confirms it SHOULD be reported as OFF.

catellie commented 1 year ago

Clarification: if I use HA to turn the kitchen lights off or on, the reported state becomes correct again - it is only when I'm using the official Alarm.com app or their panel to change state that the reported state in HA remains stuck at whichever state it was last changed to from HA (or the initial state).

catellie commented 1 year ago

BTW: I don't really mind, but technically the subject of this ticket is now resolved IMHO, perhaps we should create a separate ticket for "Alarmdotcom device states do not update correctly" or similar?

roooodcastro commented 1 year ago

Agree that this is now a separate issue, but I don't mind to keep tracking it here either.

Got a couple of updates (no good news though):

I've removed the integration and went into Alarm.com and manually removed all HomeAssistant login entries with "Forget this device", then I re-installed the integration and logged in again. This did not change the sensor update issue.
I have an automation to arm the alarm at a certain time, that didn't work today (it fails on some days, but it works like 9 out of 10 days). I then tried to arm the alarm through HA, and noticed that all sensors were correctly updated immediately after.

After successfully manually arming the alarm through HA, I saw these logs:

2023-03-05 22:04:54.435 DEBUG (MainThread) [pyalarmdotcomajax.devices.partition] Calling arm stay.
2023-03-05 22:04:54.435 DEBUG (MainThread) [pyalarmdotcomajax] Sending Command.ARM_STAY to Alarm.com.
2023-03-05 22:04:54.438 DEBUG (MainThread) [pyalarmdotcomajax] Url https://www.alarm.com/web/api/devices/partitions/{redacted}/armStay
2023-03-05 22:04:54.841 DEBUG (MainThread) [pyalarmdotcomajax] Response from Alarm.com 403
2023-03-05 22:04:54.841 WARNING (MainThread) [pyalarmdotcomajax] Error executing armStay, logging in and trying again...
2023-03-05 22:04:54.845 DEBUG (MainThread) [pyalarmdotcomajax] Attempting to log in to Alarm.com
2023-03-05 22:04:55.402 DEBUG (MainThread) [pyalarmdotcomajax] Response status from Alarm.com: 200
2023-03-05 22:04:55.583 DEBUG (MainThread) [pyalarmdotcomajax] {'__VIEWSTATE': '{redacted}', '__VIEWSTATEGENERATOR': '{redacted}', '__EVENTVALIDATION': '{redacted}', '__PREVIOUSPAGE': '{redacted}'}
2023-03-05 22:04:56.780 DEBUG (MainThread) [pyalarmdotcomajax] Logged in to Alarm.com.
2023-03-05 22:04:57.545 DEBUG (MainThread) [pyalarmdotcomajax] Got Provider: Smartzone, User ID: {redacted}
2023-03-05 22:04:57.547 DEBUG (MainThread) [pyalarmdotcomajax] Sending Command.ARM_STAY to Alarm.com.
2023-03-05 22:04:57.547 DEBUG (MainThread) [pyalarmdotcomajax] Url https://www.alarm.com/web/api/devices/partitions/{redacted}/armStay
2023-03-05 22:04:59.941 DEBUG (MainThread) [pyalarmdotcomajax] Response from Alarm.com 200
2023-03-05 22:04:59.941 DEBUG (MainThread) [pyalarmdotcomajax] Calling update on Alarm.com
{From here on, it's a bunch of debug logs for a successful update call, all sensors updated. Omitting the logs as I've already pasted the same kind of logs before}

pyalarmdotcom / alarmdotcom

Hacs shows disconnected after (up to) 3 hours, have to constantly "reconfigure" #187