keymaster icon indicating copy to clipboard operation
keymaster copied to clipboard
verified publisher icon FutureTense

ISSUE: Notifications are not firing, or opposites

Open lordratner opened this issue 9 months ago • 2 comments

Describe the bug I'm not sure if it is related, but in the beta branch, I'm seeing two issues:

  1. When the lock is operated via Home Assistant, I get the opposite notification of what actually happened. Clicking the Lock badge unlocks the lock, but I get a "RF Lock" Notification. Click it again to close the lock and I get "RF Unlock." This behavior happens with the autolock as well. Whenever it closes the lock I get an unlock notification. As a side note, the notification message also doesn't seems to have logic for autolock. If the lock was manually opened, the autolock triggers after the set time and the notification says "Manual" and if the lock was opened with HA, the notification sent from autolock says "RF." However this is made even more confusing by the Unlock instead of lock message, since they are flipped.

Now, operating the lock manually triggers the correct notification.

  1. The only way I can get notifications is by turning on the global notifications toggle. The toggles in the individual code slots have no effect. It's all or nothing using the global toggle.

Environment (please complete the following information):

  • OS: HAOS
  • Type of system that HA is running on: Proxmox VM
  • Home Assistant version: 25.7.2
  • Hassio/Docker/Core: HAOS v 16.0
  • Component version: beta branch v0.0.0 (according to the integration page
  • Z-Wave integration name: zwave_js ui
  • Lock make and model: Kwikset HomeConnect 620

Logs Here's the logs from a simple unlock using the lovelace badge.

You can see the "event_label" for the lock_unlocked event is "RF Lock" when the lock was just unlocked. Is this just a coding error having them flipped?

But the event label for the handle_zwave_js_lock_event is "RF unlock operation" which is correct

2025-07-21 12:04:18.686 DEBUG (MainThread) [custom_components.keymaster.coordinator] [handle_lock_state_change] Mud Room Door: event: <Event state_changed[L]: entity_id=lock.mud_room_door_lock, old_state=<state lock.mud_room_door_lock=locked; friendly_name=Mud Room Door Lock , supported_features=0 @ 2025-07-21T11:53:23.476071-05:00>, new_state=<state lock.mud_room_door_lock=unlocked; friendly_name=Mud Room Door Lock , supported_features=0 @ 2025-07-21T12:04:18.685827-05:00>>
2025-07-21 12:04:18.687 DEBUG (MainThread) [custom_components.keymaster.coordinator] [handle_lock_state_change] Mud Room Door: action_type: alarm_type, alarm_level_value: 1, alarm_type_value: 24
2025-07-21 12:04:18.687 DEBUG (MainThread) [custom_components.keymaster.coordinator] [handle_lock_state_change] Mud Room Door: old_state: locked, new_state: unlocked
2025-07-21 12:04:18.687 DEBUG (MainThread) [custom_components.keymaster.coordinator] [lock_unlocked] Mud Room Door: Running. code_slot_num: 0, source: entity_state, event_label: RF Lock, action_code: 24
2025-07-21 12:04:18.688 DEBUG (MainThread) [custom_components.keymaster.helpers] [KeymasterTimer] Starting auto-lock timer for 60 seconds. Ending 2025-07-21 12:05:18.688071-05:00
2025-07-21 12:04:18.688 DEBUG (MainThread) [custom_components.keymaster.helpers] [send_manual_notification] script: script.keymaster_notification, title: Mud Room Door, message: RF Lock
2025-07-21 12:04:18.688 DEBUG (MainThread) [custom_components.keymaster.helpers] [call_hass_service] service: script.keymaster_notification, target: None, service_data: {'title': 'Mud Room Door', 'message': 'RF Lock'}
2025-07-21 12:04:18.688 INFO (MainThread) [homeassistant.components.script.keymaster_notification] Keymaster Notification: Running script sequence
2025-07-21 12:04:18.688 INFO (MainThread) [homeassistant.components.script.keymaster_notification] Keymaster Notification: Executing step call service
2025-07-21 12:04:18.988 INFO (MainThread) [homeassistant.components.mobile_app.notify] mobile_app push notification rate limits for Seth's Pixel 9 Pro: 21 sent, 500 allowed, 0 errors, resets in 6:55:41
2025-07-21 12:04:20.573 DEBUG (MainThread) [custom_components.keymaster.coordinator] [handle_zwave_js_lock_event] Mud Room Door: event: <Event zwave_js_notification[L]: domain=zwave_js, node_id=24, home_id=4160347363, endpoint=0, device_id=5183ab889185ee11dd85e862d7086167, command_class=113, command_class_name=Notification, label=Access Control, type=6, event=4, event_label=RF unlock operation, parameters=>, new_state: unlocked, params: {}, code_slot_num: 0
2025-07-21 12:04:20.573 DEBUG (MainThread) [custom_components.keymaster.coordinator] [lock_unlocked] Mud Room Door: Throttled. source: event

Here's the log for the autolock one minute later:

2025-07-21 12:05:18.689 DEBUG (MainThread) [custom_components.keymaster.coordinator] [timer_triggered] Mud Room Door
2025-07-21 12:05:18.689 DEBUG (MainThread) [custom_components.keymaster.coordinator] [lock_lock] Mud Room Door: Locking
2025-07-21 12:05:18.689 DEBUG (MainThread) [custom_components.keymaster.helpers] [call_hass_service] service: lock.lock, target: {'entity_id': 'lock.mud_room_door_lock'}, service_data: None
2025-07-21 12:05:18.689 DEBUG (MainThread) [custom_components.keymaster.helpers] [KeymasterTimer] Timer elapsed
2025-07-21 12:05:20.244 DEBUG (MainThread) [custom_components.keymaster.coordinator] [handle_lock_state_change] Mud Room Door: event: <Event state_changed[L]: entity_id=lock.mud_room_door_lock, old_state=<state lock.mud_room_door_lock=unlocked; friendly_name=Mud Room Door Lock , supported_features=0 @ 2025-07-21T12:04:18.685827-05:00>, new_state=<state lock.mud_room_door_lock=locked; friendly_name=Mud Room Door Lock , supported_features=0 @ 2025-07-21T12:05:20.244295-05:00>>
2025-07-21 12:05:20.244 DEBUG (MainThread) [custom_components.keymaster.coordinator] [handle_lock_state_change] Mud Room Door: action_type: alarm_type, alarm_level_value: 1, alarm_type_value: 25
2025-07-21 12:05:20.244 DEBUG (MainThread) [custom_components.keymaster.coordinator] [handle_lock_state_change] Mud Room Door: old_state: unlocked, new_state: locked
2025-07-21 12:05:20.244 DEBUG (MainThread) [custom_components.keymaster.coordinator] [lock_locked] Mud Room Door: Running. source: entity_state, event_label: RF Unlock, action_code: 25
2025-07-21 12:05:20.244 DEBUG (MainThread) [custom_components.keymaster.helpers] [KeymasterTimer] Cancelling auto-lock timer
2025-07-21 12:05:20.244 DEBUG (MainThread) [custom_components.keymaster.helpers] [send_manual_notification] script: script.keymaster_notification, title: Mud Room Door, message: RF Unlock
2025-07-21 12:05:20.244 DEBUG (MainThread) [custom_components.keymaster.helpers] [call_hass_service] service: script.keymaster_notification, target: None, service_data: {'title': 'Mud Room Door', 'message': 'RF Unlock'}
2025-07-21 12:05:22.179 DEBUG (MainThread) [custom_components.keymaster.coordinator] [handle_zwave_js_lock_event] Mud Room Door: event: <Event zwave_js_notification[L]: domain=zwave_js, node_id=24, home_id=4160347363, endpoint=0, device_id=5183ab889185ee11dd85e862d7086167, command_class=113, command_class_name=Notification, label=Access Control, type=6, event=3, event_label=RF lock operation, parameters=>, new_state: locked, params: {}, code_slot_num: 0
2025-07-21 12:05:22.179 DEBUG (MainThread) [custom_components.keymaster.coordinator] [lock_locked] Mud Room Door: Throttled. source: event
2025-07-21 12:05:22.594 DEBUG (MainThread) [custom_components.hacs] Nothing in the queue

Same thing here. The "lock_locked" event has an event_label of "RF Unlock", which is incorrect, but the handle_zwave_js_lock_event has an event_lable of "RF lock operation" which is correct.

lordratner avatar Jul 21 '25 17:07 lordratner

So, I could be wrong, but here's what I think is happening.

event_type: zwave_js_notification
data:
  domain: zwave_js
  node_id: 24
  home_id: 4160347363
  endpoint: 0
  device_id: 5183ab889185ee11dd85e862d7086167
  command_class: 113
  command_class_name: Notification
  label: Access Control
  type: 6
  event: 3
  event_label: RF lock operation
  parameters: {}
origin: LOCAL
time_fired: "2025-07-21T17:38:06.306948+00:00"
context:
  id: 01K0Q10WB27NASJ3N64XTF91HA
  parent_id: null
  user_id: null

This is the zwave_js_notification that is fired by the lock when you lock it. It has no alarm_type in it, but one of the Zwave notification values is 24-113-0-alarmType which changes with whatever is happening to the lock.

If you look at the logs, [handle_lock_state_change] runs before [handle_zwave_js_lock_event], however the latter is when the alarm_type is updated to reflect the lock change. I don't know how or why the state change is recognized before the zwave event, but I think the integration is grabbing the alarm_type from the 24-113-0-alarmType value before it has actually changed to represent the correct value. Then it references the alarm_type map to get the notification message.

This also explains why manually operating the lock isn't having the same problem. In this case the integration waits until the zwave event is detected (with the correct alarm_type) then builds the notification.

So I think the solution here is to change the handling so the integration is not looking at the Home Assistant lock entity for state changes, since those will change immediately even if the lock never gets the command, and instead look at the zwave events to act on state changes.

Thoughts?

lordratner avatar Jul 21 '25 17:07 lordratner

I did a pull request to fix the code-slot notifications.

Not sure on a fix for the opposite-status notifications, but that's not an issue if you aren't using global notifications anyways.

lordratner avatar Jul 22 '25 15:07 lordratner