Changes to device states not reflected in Home Assistant

[patrickabernathy]

I've been testing version 3.0.1 and the new version 3.0.2 but both versions seem to do an initial poll but after a few minutes just stops. In the debug logs I see the initial poll request then nothing else. I've been arming and disarming my system in an attempt to get it to trigger but no response from my integrations. I've switched back to v2.2.2 and everything seems to work normally with the 30 second poll timer.

[lbreggi]

Same here - is there something I can do to help to identify the issue? Thanks!

[ghds514]

Greatly appreciate everything being done for this plugin.

Also experiencing this. When moving from 2.2.2 to 3.0.1, polling it seemed like everything was working correctly once I added 2FA authentication to my account. When I moved to 3.0.2, HA reported a need to reconfigure the plugin, although it appeared to continue to function correctly. Once I re-authenticated for 3.0.2, the Arming status stopped updating.

Let me know if there is anything I can do to help.

[elahd]

v3.0.3 fixes the alarm status issue. Can you try that?

[lbreggi]

I believe the arm / disarm is now working again with the 3.0.3 but the feedback about locks still not working

[TheWebMachine]

Arm/Disarm status still not updating properly for me in 3.0.3. If I manipulate from HA, it updates status. If it is armed/disarmed elsewhere, the status never updates and my automations in HA never run. Reverting back to 2.2.2 for now.

[ghds514]

I believe everything is working correctly for me in 3.0.3. It does seem that a change in arming status takes loner to be reflected in HA than before, but I do see that there is a setting in the configuration that may allow for modification of this.

[TheWebMachine]

Ugh...forgot 2.2.2 was funky, too. I'm rolling back to 2.2.1 until v3.x is resolved. Between 3.0.3, 3.0.2, and 2.2.2, I've had 3 false alarms incidents on my system because of these status polling issues...I basically can't rely on HA at all for this at the moment or else I risk losing my alarm permit from all the false alarms. 🤦🏻‍♂️

3.0.3 polls correctly for no more than 20 minutes after the integration is loaded/reloaded and if you manipulate via HA, polling works again for a while. The moment anything outside of HA happens to the system (scheduled arming, manual arming, etc), the polling completely stops until I perform an action against alarm.com via HA or reload the integration. 🤷🏻‍♂️

[elahd]

Test out v3.0.4-beta.1. WebSockets work more reliably now (on my account, at least). If you're still running into trouble, go into the integration's settings page and set a low poll time.

[elahd]

Use v3.0.4-beta.2. There's a bug in beta.1 that ignores user-entered polling intervals.

[TheWebMachine]

Use v3.0.4-beta.2. There's a bug in beta.1 that ignores user-entered polling intervals.

So far, so good. A little over an hour into updating. I have my polling set to 30 seconds (have since the option became available in v2.x) and when I externally manipulate the panel, it takes no more than 30 seconds to show up in HA, which is actually about as long as it takes ADC to send me the SMS alert, so that is what I expect.

I'll keep testing throughout the day and with different intervals and report back. I'll be able to leave the house idle for a few hours while I go run some errands, which will give time for polling to start failing again if it's going to, as that's usually when I notice it stop working...and how I've accidentally set my system off a few times before forgetting we were pecking at a bug. hahaha

[lbreggi]

I'm also trying the beta and so far seems to be working fine! I'm still with the feeling that the 2.x version was reflecting changes faster in the dashboard, but the way it is in the beta is totally fine. I will keep testing. Thanks!

[elahd]

@jprasm / @sspaul1976: Can you post details about the delays you posted about in #289? There are delays that are inherent to Alarm.com's infrastructure, so I want to confirm whether the delays that you're experiencing are expected or unexpected.

Expected behavior is below. See the release notes for v3.0.3 for details regarding why this is the case.

1. Actions initiated through Home Assistant may take up to 60 seconds to complete. This includes commands for your alarm, locks, garage doors, etc.
2. Changes to Door/Window/Motion sensors and actions taken outside of Home Assistant may take up to 3 minutes to register via push notification and may not register at all. If you have a low poll time, you should expect to see the same refresh times that you saw in the v2.x version of this integration.

Also, can you confirm the refresh interval that is set for the integration?

[jprasm]

Hi elahd,

I only use this integration to arm and disarm my alarm system - I know that there is a delay with the various window and door sensors, and I know that's normal behaviour (the delay on door/window sensors is so long that I don't use them for any automations unfortunately).

With 2.2.1 the arm/disarm of my system is nearly instantaneous! Love it. However, when I upgrade to the latest, there is a significant delay in arm/disarm (15-30 seconds at least). Not good!

I have the update interval set at 15 seconds.

[TheWebMachine]

Are you on the latest 3.0.4-beta2? Arm/Disarm from within HA is under 5s for me in the latest beta, regardless of polling interval.

[catellie]

@elahd [continuing from other thead] I thought I was using the actual release (3.0.4), but as I checked my logs it looks like the restart somehow didn't work out so I expect it might be in a state of flux (downloaded, but not yet successfully restarted).

A closer examination of the logs indicates that I may have jumped the gun a bit: It did indeed get into the correct state just minutes later - roughly 10 minutes after I armed away. I can see this event just before the door event:

023-06-09 07:18:51.315 DEBUG (MainThread) [pyalarmdotcomajax.websockets.client]
====================[ WEBSOCKET MESSAGE: BEGIN ]====================
{
    "EventDateUtc": "2023-06-09T05:18:51.068Z",
    "UnitId": REDACTED,
    "DeviceId": 127,
    "EventType": 10,
    "EventValue": 0.0,
    "CorrelatedId": null,
    "QstringForExtraData": "ew=&ew_contact_user_type=-1",
    "DeviceType": -1
}
2023-06-09 07:18:51.315 DEBUG (MainThread) [pyalarmdotcomajax.websockets.messages] WebSocket Message Type: Event
2023-06-09 07:18:51.315 INFO (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Got async update for partition1 (REDACTED) from WebSocket message with new {'state': 3, 'desiredState': 3}.
2023-06-09 07:18:51.316 DEBUG (MainThread) [pyalarmdotcomajax.devices] Desired: [3] | Current: [3]
2023-06-09 07:18:51.316 DEBUG (MainThread) [pyalarmdotcomajax.websockets.client]
====================[ WEBSOCKET MESSAGE: END ]====================

Although I'm not really sure what the state numbers mean, I'm pretty sure that partition1 is their name for my house. So me arming away appears to have caused this event to show up in the integration - but for some reason it still didn't show up as the new state until 10 minutes later when "getting all devices" occurred. (There were several Sending keep alive signal. entries in that time.)

So basically, it works in the end, but the websocket listener seems to have ignored the partition1 becoming armed message for some reason.

BTW: I still have a fair amount of noise from the energy meter currently being blocked by my provider plus some Tapo device issue, so reading the logs is pretty messy for me.

[elahd]

@catellie

• The debug logs are verbose. It's a pain to look through. Sorry about that!
• State 3 is arm away.
• You are missing one key message between WEBSOCKET MESSAGE: BEGIN and WEBSOCKET MESSAGE: END. Below is what you should expect to see in the logs when arming/disarming:

Arm away flow initiated:

2023-06-09 20:55:52.128 DEBUG (MainThread) [pyalarmdotcomajax.devices.partition] Calling arm away.

Integration changes partition status in pyalarmdotcomajax's device registry to "armed away":

2023-06-09 20:55:52.128 INFO (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Got async update for Alarm (999999999-127) from WebSocket message with new {'desiredState': 3}.

Integration receives state change update from pyalarmdotcomajax and changes state in HA to "arming". (Updates to a device trigger updates for all sub-entities.)

2023-06-09 20:55:52.131 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Alarm Control Panel Alarm (999999999-127): arming
2023-06-09 20:55:52.131 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Malfunction (999999999-127): off
2023-06-09 20:55:52.131 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Battery (999999999-127): off
2023-06-09 20:55:52.132 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Debug (999999999-127): None

Pyalarmdotcomajax sends arm away command to Alarm.com and waits for a synchronous response from the server:

2023-06-09 20:55:52.132 INFO (MainThread) [pyalarmdotcomajax] Sending Command.ARM_AWAY to Alarm.com.
2023-06-09 20:55:52.133 DEBUG (MainThread) [pyalarmdotcomajax] Url https://www.alarm.com/web/api/devices/partitions/999999999-127/armAway

While waiting for a synchronous response, pyalarmdotcomajax gets an asynchronous WebSocket message indicating that the alarm has been armed. (EventType 10 = armed away):

2023-06-09 20:55:53.211 DEBUG (MainThread) [pyalarmdotcomajax.websockets.client] 
====================[ WEBSOCKET MESSAGE: BEGIN ]====================
{
    "EventDateUtc": "2023-06-09T20:55:52.989Z",
    "UnitId": 999999999,
    "DeviceId": 127,
    "EventType": 10,
    "EventValue": -234234234.0,
    "CorrelatedId": null,
    "QstringForExtraData": "lid=77777777&ew=&ew_contact_user_type=0",
    "DeviceType": -1
}
2023-06-09 20:55:53.212 DEBUG (MainThread) [pyalarmdotcomajax.websockets.messages] WebSocket Message Type: Event

The below is the same pattern at the earlier arming change, except that we're changing the state to armed away. Your post is missing the "Updated Device..." logs, indicating that the integration never got a notice from the library.

2023-06-09 20:55:53.212 INFO (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Got async update for Alarm (999999999-127) from WebSocket message with new {'state': 3, 'desiredState': 3}.
2023-06-09 20:55:53.215 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Alarm Control Panel Alarm (999999999-127): armed_away
2023-06-09 20:55:53.216 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Malfunction (999999999-127): off
2023-06-09 20:55:53.216 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Battery (999999999-127): off
2023-06-09 20:55:53.217 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Debug (999999999-127): None
2023-06-09 20:55:53.217 DEBUG (MainThread) [pyalarmdotcomajax.websockets.client] 
====================[ WEBSOCKET MESSAGE: END ]====================

Pyalarmdotcomajax gets a (synchronous) response from the arm away request. Ignore the "async" in the "Got async update" message -- it's a synchronous update.

2023-06-09 20:55:54.184 DEBUG (MainThread) [pyalarmdotcomajax] Response from Alarm.com 200
2023-06-09 20:55:54.185 DEBUG (MainThread) [pyalarmdotcomajax] 
==============================
Server Response:
{"data": {"id": "999999999-127", "type": "devices/partition", "attributes": {"partitionId": 1, "state": 3, "desiredState": 3, "extendedArmingOptions": {"Disarmed": [], "ArmedStay": [2, 1, 0, 4], "ArmedAway": [2, 1, 0, 4], "ArmedNight": []}, "invalidExtendedArmingOptions": {"Disarmed": [], "ArmedStay": [], "ArmedAway": [], "ArmedNight": []}, "needsClearIssuesPrompt": false, "canEnableAlexa": false, "isAlexaEnabled": false, "canAccessPanelWifi": true, "canBypassSensorWhenArmed": false, "dealerEnforcesForceBypass": false, "hasSensorInTroubleCondition": false, "hasOpenBypassableSensors": false, "hideForceBypass": false, "sensorNamingFormat": 3, "managedDeviceType": 11, "canBeRenamed": true, "canAccessWebSettings": true, "canAccessAppSettings": true, "webSettings": 1002, "hasState": true, "canBeDeleted": false, "canAccessTroubleshootingWizard": false, "troubleshootingWizard": null, "addDeviceResource": 0, "canBeAssociatedToVideoDevice": false, "associatedCameraDeviceIds": {}, "macAddress": "", "manufacturer": "", "isAssignedToCareReceiver": false, "isOAuth": false, "isZWave": false, "supportsCommandClassBasic": false, "isMalfunctioning": false, "canBeSaved": true, "canChangeDescription": true, "description": "Alarm", "deviceModelId": 9609, "canConfirmStateChange": true, "canReceiveCommands": true, "remoteCommandsEnabled": true, "hasPermissionToChangeState": true, "deviceIcon": {"icon": 186}, "batteryLevelNull": null, "lowBattery": false, "criticalBattery": false}, "relationships": {"sensors": {"data": [{"id": "999999999-14", "type": "devices/sensor"}, {"id": "999999999-26", "type": "devices/sensor"}, {"id": "999999999-23", "type": "devices/sensor"}, {"id": "999999999-22", "type": "devices/sensor"}, {"id": "999999999-5288", "type": "devices/sensor"}, {"id": "999999999-5258", "type": "devices/sensor"}, {"id": "999999999-7", "type": "devices/sensor"}, {"id": "999999999-28", "type": "devices/sensor"}, {"id": "999999999-11", "type": "devices/sensor"}, {"id": "999999999-10", "type": "devices/sensor"}, {"id": "999999999-17", "type": "devices/sensor"}, {"id": "999999999-16", "type": "devices/sensor"}, {"id": "999999999-5285", "type": "devices/sensor"}, {"id": "999999999-31", "type": "devices/sensor"}, {"id": "999999999-30", "type": "devices/sensor"}, {"id": "999999999-4", "type": "devices/sensor"}, {"id": "999999999-3", "type": "devices/sensor"}, {"id": "999999999-5", "type": "devices/sensor"}, {"id": "999999999-6", "type": "devices/sensor"}, {"id": "999999999-24", "type": "devices/sensor"}, {"id": "999999999-9", "type": "devices/sensor"}, {"id": "999999999-8", "type": "devices/sensor"}, {"id": "999999999-25", "type": "devices/sensor"}, {"id": "999999999-33", "type": "devices/sensor"}, {"id": "999999999-229", "type": "devices/sensor"}, {"id": "999999999-1", "type": "devices/sensor"}, {"id": "999999999-12", "type": "devices/sensor"}, {"id": "999999999-13", "type": "devices/sensor"}, {"id": "999999999-27", "type": "devices/sensor"}, {"id": "999999999-15", "type": "devices/sensor"}, {"id": "999999999-18", "type": "devices/sensor"}, {"id": "999999999-21", "type": "devices/sensor"}, {"id": "999999999-19", "type": "devices/sensor"}, {"id": "999999999-20", "type": "devices/sensor"}, {"id": "999999999-5290", "type": "devices/sensor"}], "meta": {"count": "35"}}, "system": {"data": {"id": "88888888", "type": "systems/system"}}, "stateInfo": {"data": {"id": "999999999-127-6", "type": "devices/state-info"}}}}, "included": [], "meta": {"transformer_version": "1.1"}}
==============================
2023-06-09 20:55:54.185 INFO (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Got async update for Alarm (999999999-127) from user action response with new {'partitionId': 1, 'state': 3, 'desiredState': 3, 'extendedArmingOptions': {'Disarmed': [], 'ArmedStay': [2, 1, 0, 4], 'ArmedAway': [2, 1, 0, 4], 'ArmedNight': []}, 'invalidExtendedArmingOptions': {'Disarmed': [], 'ArmedStay': [], 'ArmedAway': [], 'ArmedNight': []}, 'needsClearIssuesPrompt': False, 'canEnableAlexa': False, 'isAlexaEnabled': False, 'canAccessPanelWifi': True, 'canBypassSensorWhenArmed': False, 'dealerEnforcesForceBypass': False, 'hasSensorInTroubleCondition': False, 'hasOpenBypassableSensors': False, 'hideForceBypass': False, 'sensorNamingFormat': 3, 'managedDeviceType': 11, 'canBeRenamed': True, 'canAccessWebSettings': True, 'canAccessAppSettings': True, 'webSettings': 1002, 'hasState': True, 'canBeDeleted': False, 'canAccessTroubleshootingWizard': False, 'troubleshootingWizard': None, 'addDeviceResource': 0, 'canBeAssociatedToVideoDevice': False, 'associatedCameraDeviceIds': {}, 'macAddress': '', 'manufacturer': '', 'isAssignedToCareReceiver': False, 'isOAuth': False, 'isZWave': False, 'supportsCommandClassBasic': False, 'isMalfunctioning': False, 'canBeSaved': True, 'canChangeDescription': True, 'description': 'Alarm', 'deviceModelId': 9609, 'canConfirmStateChange': True, 'canReceiveCommands': True, 'remoteCommandsEnabled': True, 'hasPermissionToChangeState': True, 'deviceIcon': {'icon': 186}, 'batteryLevelNull': None, 'lowBattery': False, 'criticalBattery': False}.

Integration updates HA entity states:

2023-06-09 20:55:54.185 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Alarm Control Panel Alarm (999999999-127): armed_away
2023-06-09 20:55:54.186 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Malfunction (999999999-127): off
2023-06-09 20:55:54.186 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Battery (999999999-127): off
2023-06-09 20:55:54.186 INFO (MainThread) [custom_components.alarmdotcom.base_device] Updated Device Alarm Debug (999999999-127): None

The relevant parts of the code that handle this process are (in order):

1. Partition WebSocket message handler, here, which calls...
2. async_handle_external_dual_state_change() for the device's representation in pyalarmdotcomajax. This calls async_handle_external_attribute_change() a few lines below, which, here, calls...
3. All external update callback functions registered with the device. Each entity in Home Assistant registers a callback function with pyalarmdotcomajax to be run when the library receives a state update. That function is _update_device_data(). This is the function that appears to have been skipped in your case.

I'lll add extra tracing code to a dev release for you to test. That should highlight what the problem is. I'll follow up here when it's ready.

[elahd]

@catellie

I added trace logging to the master branch. If you install master via HACS, you'll see additional logs. Included are:

1. Logs when the integration registers an update listener with pyalarmdotcomajax:

2023-06-10 01:13:32.288 DEBUG (MainThread) [pyalarmdotcomajax.devices] Registering external update callback for Front Porch (103238342-1200) with Front Porch Light (103238342-1200)

2. Logs when the integration is notified of a state change:

2023-06-10 01:13:38.901 DEBUG (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Calling external update callback for listener Front Porch Malfunction (103238342-1200) by Front Porch Light (103238342-1200)

3. A count of how many external update callbacks are registered with every device in pyalarmdotcomajax. This is shown when pyalarmdotcomajax gets an update:

2023-06-10 01:13:38.907 DEBUG (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Front Porch Light (103238342-1200) has 4 external update callbacks.)

I also added version numbers for the integration and library to the message that you see when Home Assistant starts:

===================================================================
ALARMDOTCOM v3.0.5-alpha.1

This is a custom component
If you have any issues with this you need to open an issue here:
https://github.com/pyalarmdotcom/alarmdotcom/issues

pyalarmdotcomajax v0.5.4-alpha.1
===================================================================

[catellie]

@elahd the newest I can see to download, even with beta turned on its 3.0.4, so now I'm on master 5162e35 🤞

[catellie]

@elahd I've now let it run for a while and comparing logs with what I do and what I see in Home Assistant UI Logbook.

• One basic thing: It appears that may door sensor information do not show up in the UI Logbook while the motion sensors (and partions) do. Both kinds show up on the websockets logfile trace so presumably this is intentional?
• Also, I've not quite figured out the timestamps in the trace file compared to the UI Logbook - typically what I see in the UI is some 10-20 seconds later than the traces - this makes comparison a bit harder, but typically no big deal.
• With the above in mind, the stuff I've compared have mostly made fair sense so far, with one excaption:

====================[ WEBSOCKET MESSAGE: BEGIN ]====================
{
    "EventDateUtc": "2023-06-10T09:14:30.889Z",
    "UnitId": REDACTED,
    "DeviceId": 127,
    "EventType": 8,
    "EventValue": 1.0,
    "CorrelatedId": 0,
    "QstringForExtraData": "ew=REDACTED&ew_contact_user_type=0&ew_group_id=0&ew_contact_id=REDACTED",
    "DeviceType": -1
}
2023-06-10 11:14:31.098 DEBUG (MainThread) [pyalarmdotcomajax.websockets.messages] WebSocket Message Type: Event
2023-06-10 11:14:31.098 INFO (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Got update for partition1 (100787381-127) from WebSocket message with new {'state': 1, 'desiredState': 1}.
2023-06-10 11:14:31.098 DEBUG (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices partition1 (REDACTED) has 0 external update callbacks.)
2023-06-10 11:14:31.099 DEBUG (MainThread) [pyalarmdotcomajax.websockets.client]
====================[ WEBSOCKET MESSAGE: END ]====================

(and a very similar one with state 2 just before) I think this one is from when I did a short "ARM HOME" / "DISARM" on my entrance panel, but it never showed up in the HA UI.

Related to your extra logs points above:

1. I see these base ones in my list, but there are also many variants that are labeled with Malfunction/Battery/Debug. Intentional or not?

2023-06-10 07:58:56.471 Hemlarm Garda REDACTED with partition1 REDACTED
2023-06-10 07:58:56.478 Altandörr REDACTED with Altandörr REDACTED
2023-06-10 07:58:56.480 Entredörr REDACTED with Entredörr REDACTED
2023-06-10 07:58:56.481 Källardörr REDACTED with Källardörr REDACTED
2023-06-10 07:58:56.482 Övervåning REDACTED with Övervåning REDACTED
2023-06-10 07:58:56.483 Panel Glass Break REDACTED with Panel Glass Break REDACTED
2023-06-10 07:58:56.483 Vardagsrum REDACTED with Vardagsrum REDACTED
2023-06-10 07:58:56.491 Switch REDACTED with Switch REDACTED
2023-06-10 07:58:56.491 Köksfönster REDACTED with Köksfönster REDACTED
2023-06-10 07:58:56.492 Dimmer-relay REDACTED with Dimmer-relay REDACTED

2. I see no logs with Calling external update callback from pyalarmdotcomajax.devices - only registering and initializing

3. Here are the external backs extracter from my logs (trimmed down for readability):

2023-06-10 09:30:58.376 pyalarmdotcomajax.devices Övervåning REDACTED has 0 external update callbacks.)
2023-06-10 10:10:50.954 pyalarmdotcomajax.devices Övervåning REDACTED has 0 external update callbacks.)
2023-06-10 10:26:49.655 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 10:56:51.058 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 11:08:49.068 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 11:09:12.354 pyalarmdotcomajax.devices Övervåning REDACTED has 0 external update callbacks.)
2023-06-10 11:14:24.405 pyalarmdotcomajax.devices partition1 REDACTED has 0 external update callbacks.)
2023-06-10 11:14:31.098 pyalarmdotcomajax.devices partition1 REDACTED has 0 external update callbacks.)
2023-06-10 11:44:02.754 pyalarmdotcomajax.devices Övervåning REDACTED has 0 external update callbacks.)
2023-06-10 12:20:18.950 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 12:28:55.509 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 12:58:59.349 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 13:26:45.028 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 13:27:54.291 pyalarmdotcomajax.devices partition1 REDACTED has 0 external update callbacks.)
2023-06-10 13:28:00.985 pyalarmdotcomajax.devices Entredörr REDACTED has 0 external update callbacks.)
2023-06-10 13:28:00.985 pyalarmdotcomajax.devices Entredörr REDACTED has 0 external update callbacks.)
2023-06-10 13:47:46.853 pyalarmdotcomajax.devices partition1 REDACTED has 0 external update callbacks.)
2023-06-10 13:56:50.954 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 13:58:56.784 pyalarmdotcomajax.devices Entredörr REDACTED has 0 external update callbacks.)
2023-06-10 13:58:56.784 pyalarmdotcomajax.devices Entredörr REDACTED has 0 external update callbacks.)
2023-06-10 13:58:57.758 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)
2023-06-10 15:02:03.004 pyalarmdotcomajax.devices Vardagsrum REDACTED has 0 external update callbacks.)

The timings here make fair sense to when things HAVE happened: For example the partition1 arm home/disarm at 11:14 and later 13:27 just before Entredörr (Front door) opens/closes (but leave no trace in the Logbook) and then disarm again at 13:47 (this one was automatic, so it makes snse that the door was opened later at 13:58).

Also, here is the blurb:

ALARMDOTCOM v3.0.5-alpha.1

This is a custom component
If you have any issues with this you need to open an issue here:
https://github.com/pyalarmdotcom/alarmdotcom/issues

pyalarmdotcomajax v0.5.4-alpha.1

As always, let me know if you need more details / Jonas

[elahd]

Thanks, that's really helpful. Now I need to figure out why external update callbacks wouldn't register. Registration happens when the device is added to hass, either after integration config or on boot.

Can you tell me again which operating system, Python version, and Home Assistant version you have installed? You can check your Python version in the command line using python --version (if that doesn't work, python3 --version).

[catellie]

I'm out and about for the evening, but basically I'm running the latest (ish) 32bit (don't ask) docker image:

Home Assistant 2023.6.1 Frontend 20230608.0 - latest

I can give more details tomorrow.

Best / Jonas

Den lör 10 juni 2023 17:41Elahd Bar-Shai @.***> skrev:

Thanks, that's really helpful. Now I need to figure out why external update callbacks wouldn't register. Registration happens when the device is added to hass https://developers.home-assistant.io/docs/core/entity/#async_added_to_hass, either after integration config or on boot.

Can you tell me again which operating system, Python version, and Home Assistant version you have installed? You can check your Python version in the command line using python --version (if that doesn't work, python3 --version).

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

[catellie]

BTW: If it wasn't obvious from my last message, I'm on Python 3.11.3 The container I run is: 6cdc9d02defe ghcr.io/home-assistant/home-assistant:latest "/init" 2 days ago Up 2 days homeassistant Which apparently is based on Alpine Linux 3.18 and run this kernel: Linux version 4.15.0-208-generic (buildd@lcy02-amd64-061) (gcc version 7.5.0 (Ubuntu 7.5.0-3ubuntu1~18.04)) #220-Ubuntu SMP Mon Mar 20 14:26:46 UTC 2023

It should hardly matter, but for the record the host is running 32 bit Ubuntu 18.04.

[catellie]

Oh, and just to be clear: my block under point 1 above was the list of Registering external update callback that where triggered on HASS boot, but I had trimmed out variants to make it readable, for example my front door had these:

Registering external update callback for Entredörr Battery REDACTED with Entredörr REDACTED
Registering external update callback for Entredörr Debug REDACTED with Entredörr REDACTED
Registering external update callback for Entredörr Malfunction REDACTED with Entredörr REDACTED
Registering external update callback for Entredörr REDACTED with Entredörr REDACTED

I guess the battery/debug/malfunction variants CAN be useful, but the the primary one (here at the bottom) is presumably the one that really needs the listener for instant feedback - I expect the others to be good enough reporting at the occasional full scan?

As far as I can tell, all my devices have all four of these whether I like it or not and the registration log indicates that first all the primary ones are registered, then all the Malfunction, then all the Battery and finally all the Debug - but the devices in each group seem semi-jumbled - in this specific case, partition1 starting each group but my Z-wave devices coming in significantly later in the lists. :shrug: Could this cause some kind of clash that makes it fail?

[catellie]

Side note: I've noticed some HA devices now have "Attributes" showing at the bottom of the info dialog. It would be pretty neat if you were able to expose the battery level that way - currently my front door just shows "DisplayStateText Closed". Also, somewhat strangely, it currently has two Logbook entry that say "Turned off" and "Became unavailable" about an hour after I came home last night - this seems to be the same for all (or at least most) of my alarm.com sensors so I suspect those entries should be ignored.

[catellie]

Further digging: On the positive side, the presence sensors (Vardagsrum and Övervåning in my list above) seem to report "Turned on/off" perfectly still while neither the of the doors (Entredörr and Altandörr) make any sense. Obviously they are different kind of sensors (the doors have what I believe are magnets) so that might affect the details in how they are reported? For kicks, I opened and close the back door and saw this in the logs:

====================[ WEBSOCKET MESSAGE: BEGIN ]====================
{
    "EventDateUtc": "2023-06-11T11:03:39.963Z",
    "UnitId": REDACTED,
    "DeviceId": 4,
    "EventType": 100,
    "EventValue": 0.0,
    "CorrelatedId": null,
    "QstringForExtraData": null,
    "DeviceType": 1
}
2023-06-11 13:03:40.142 DEBUG (MainThread) [pyalarmdotcomajax.websockets.messages] WebSocket Message Type: Event
2023-06-11 13:03:40.143 INFO (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Got update for Altandörr (REDACTED) from WebSocket message with new {'state': 2, 'desiredState': 2}.
2023-06-11 13:03:40.143 DEBUG (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Altandörr (REDACTED) has 0 external update callbacks.)
2023-06-11 13:03:40.143 INFO (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Got update for Altandörr (REDACTED) from WebSocket message with new {'state': 1, 'desiredState': 1}.
2023-06-11 13:03:40.143 DEBUG (MainThread) [pyalarmdotcomajax.devices] pyalarmdotcomajax.devices Altandörr (REDACTED) has 0 external update callbacks.)
2023-06-11 13:03:40.143 DEBUG (MainThread) [pyalarmdotcomajax.websockets.client]
====================[ WEBSOCKET MESSAGE: END ]====================

... but still nothing in the Logbook. Just to be on the safe side: I assume you don't care too much about the name? In the json dump the ö character in the name shows up as Altand\u00f6rr which seems to be the correct unicode representation, but there is clearly potential for a mismatch depending on the parser...

[Edit: as far as I can tell, the doors and then presence sensor both toggle between the 1 and 2 state, so for now the only oddity I can detect is the ö characted :shrug: ]

Best / Jonas

[elahd]

@catellie Thanks, this is fantastic detail. I'm pretty sure that we're running into a race condition in which the integration attempts to register update listeners with the pyalarmdotcomajax devices before the devices are fully initialized. I made a few changes to how events are reported from the library to the integration. Instead of pyalarmdotcomajax devices reporting directly to their Home Assistant counterparts, a controller in pyalarmdotcomajax now reports directly to a controller in the integration. The controllers are initialized before any devices and are more reliably present. Can you install the latest master branch and see if you have better results?

[catellie]

@elahd Installed. Have plans for the evening, but will try to check the logs...

[catellie]

@elahd Well, I can already say one thing is better: my front door was correctly registered as opening and closing when I left today! (The two time stamps have the exact same second which is somewhat unlikely, but less important.)

[mbhforum]

I upgraded to 3.0.4 from 3.0.3 Beta. I noticed when we left the house today, my routine didn't arm my Alarm. I went back into the system and had to configure the entity state in the scene back to Away.

[catellie]

@mbhforum That's fairly common for the nonworking listener - sometimes it fixes itself at the next full sync, though. If you feel adventurous using master seems a lot better...