search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.64k stars 30.4k forks source link

ZHA indicating open, close, open signal when opening opening lumi.sensor_magnet.aq2 sensors #91986

Closed vlape closed 1 year ago

vlape commented 1 year ago

The problem

Recently installed several Aqara lumi.sensor_magnet.aq2 sensors. Automations to detect open and close state to start timers were not activating correctly. Opening contact would start both open and closed timers however in trace, it did not indicate both were executed. Opening the contact, logs indicated open, close, open events. Closing the contact indicates one close event. I have tested with seven of these sensors, same results when opening contact. This is a fresh install, no other autoamtions have been configured.

This is the sensor that should be seen in the debug log IEEE: 00:15:8d:00:09:49:ea:8a Nwk: 0x273f Device Type: EndDevice LQI: 96 RSSI: -76 Last Seen: 2023-04-24T21:11:19 Power Source: Battery or Unknown Quirk: zhaquirks.xiaomi.aqara.magnet_aq2.MagnetAQ2

Home Assistant Yellow Home Assistant 2023.4.6 Supervisor 2023.04.1 Operating System 10.0 Frontend 20230411.1 - latest

What version of Home Assistant Core has the issue?

2023.4.6

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Zigbee Home Automation (ZHA)

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zha

Diagnostics information

config_entry-zha-de5761abbba567abfcd192b06be7492f.json.txt

Example YAML snippet

alias: win_test
description: ""
trigger:
  - platform: state
    entity_id:
      - binary_sensor.dining_area_window_4
    id: DA4-Open
    from: "off"
    to: "on"
    alias: Trigger - Dining Area Window 4 Open
  - platform: state
    entity_id:
      - binary_sensor.dining_area_window_4
    from: "on"
    to: "off"
    id: DA4-Closed
    alias: Trigger - Dining Area Window 4 Closed
condition: []
action:
  - choose:
      - conditions:
          - condition: trigger
            id: DA4-Open
            alias: On Open Trigger
        sequence:
          - service: timer.start
            data: {}
            target:
              entity_id: timer.windows_state_open
            alias: Start Window Open Timer
      - conditions:
          - condition: trigger
            id: DA4-Closed
            alias: On Closed Trigger
        sequence:
          - service: timer.start
            data: {}
            target:
              entity_id: timer.windows_state_closed
            alias: Start Window Closed Timer
mode: single

Anything in the logs that might be useful for us?

2023-04-24 20:20:59.773 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4428b1a90d2a2a95d37e032caad88749e8f726158799457e'
2023-04-24 20:20:59.774 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2023-04-24 20:20:59.777 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x273f, 00:15:8d:00:09:49:ea:8a, 116, -71, [0x6abe]]
2023-04-24 20:20:59.778 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x273f, 00:15:8d:00:09:49:ea:8a, 116, -71, [0x6abe]]
2023-04-24 20:20:59.778 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x273f, 00:15:8d:00:09:49:ea:8a, 116, -71, [0x6abe])
2023-04-24 20:20:59.782 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'})
2023-04-24 20:20:59.786 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'}) completed
2023-04-24 20:20:59.788 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:20:59.789 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:20:59.817 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5428b1a9112a15b658924a24ab5593499c395f11d2e99874fade4383fc7e2fa6efa67c7e'
2023-04-24 20:20:59.818 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2023-04-24 20:20:59.823 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=119), 120, -70, 0x273f, 255, 255, b'\x18 \n\x00\x00\x10\x01']
2023-04-24 20:20:59.824 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=119), 120, -70, 0x273f, 255, 255, b'\x18 \n\x00\x00\x10\x01']
2023-04-24 20:20:59.824 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x273F), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=119, profile_id=260, cluster_id=6, data=Serialized[b'\x18 \n\x00\x00\x10\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70)
2023-04-24 20:20:59.825 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Received ZCL frame: b'\x18 \n\x00\x00\x10\x01'
2023-04-24 20:20:59.826 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=32, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-04-24 20:20:59.828 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-04-24 20:20:59.829 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Received command 0x0A (TSN 32): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-04-24 20:20:59.830 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Attribute report received: on_off=<Bool.true: 1>
2023-04-24 20:20:59.834 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385659.82552, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0})
2023-04-24 20:20:59.836 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385659.82552, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0}) completed
2023-04-24 20:20:59.838 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:20:59.841 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:20:59.841 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6428b1a90d2a2a95d37e032caad88749e4f426158784097e'
2023-04-24 20:20:59.841 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2023-04-24 20:20:59.843 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x273f, 00:15:8d:00:09:49:ea:8a, 120, -70, [0x6abe]]
2023-04-24 20:20:59.843 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x273f, 00:15:8d:00:09:49:ea:8a, 120, -70, [0x6abe]]
2023-04-24 20:20:59.843 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x273f, 00:15:8d:00:09:49:ea:8a, 120, -70, [0x6abe])
2023-04-24 20:20:59.844 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'})
2023-04-24 20:20:59.846 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'}) completed
2023-04-24 20:20:59.847 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7428b1a90d2a2a95d37e032caad88749e0f5261587f5767e'
2023-04-24 20:20:59.848 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2023-04-24 20:20:59.849 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:20:59.850 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:20:59.851 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x273f, 00:15:8d:00:09:49:ea:8a, 124, -69, [0x6abe]]
2023-04-24 20:20:59.851 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x273f, 00:15:8d:00:09:49:ea:8a, 124, -69, [0x6abe]]
2023-04-24 20:20:59.852 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x273f, 00:15:8d:00:09:49:ea:8a, 124, -69, [0x6abe])
2023-04-24 20:20:59.856 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'})
2023-04-24 20:20:59.856 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'}) completed
2023-04-24 20:20:59.857 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:20:59.858 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:20:59.899 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0428b1a9112a15b658924a24ab5593499c365f11d2e99874fade4283fc7e2fa7ef6bff7e'
2023-04-24 20:20:59.899 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2023-04-24 20:20:59.903 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=120), 120, -70, 0x273f, 255, 255, b'\x18!\n\x00\x00\x10\x00']
2023-04-24 20:20:59.904 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=120), 120, -70, 0x273f, 255, 255, b'\x18!\n\x00\x00\x10\x00']
2023-04-24 20:20:59.904 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x273F), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=120, profile_id=260, cluster_id=6, data=Serialized[b'\x18!\n\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70)
2023-04-24 20:20:59.905 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Received ZCL frame: b'\x18!\n\x00\x00\x10\x00'
2023-04-24 20:20:59.907 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=33, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-04-24 20:20:59.910 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2023-04-24 20:20:59.911 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Received command 0x0A (TSN 33): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2023-04-24 20:20:59.912 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Attribute report received: on_off=<Bool.false: 0>
2023-04-24 20:20:59.916 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1428b1a9112a15b658944a24ab5593499c375f11d2e99874ecda3c98de743e58a9c4da4e27eccdfa6bb86d2bb87e'
2023-04-24 20:20:59.916 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2023-04-24 20:20:59.916 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385659.905499, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0})
2023-04-24 20:20:59.917 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385659.905499, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0}) completed
2023-04-24 20:20:59.919 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=121), 120, -70, 0x273f, 255, 255, b'\x1c_\x11"\n\x01\xffB\t\x04!\xa8\x13\n!\xbej']
2023-04-24 20:20:59.920 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=121), 120, -70, 0x273f, 255, 255, b'\x1c_\x11"\n\x01\xffB\t\x04!\xa8\x13\n!\xbej']
2023-04-24 20:20:59.920 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x273F), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=121, profile_id=260, cluster_id=0, data=Serialized[b'\x1c_\x11"\n\x01\xffB\t\x04!\xa8\x13\n!\xbej'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70)
2023-04-24 20:20:59.922 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0000] Received ZCL frame: b'\x1c_\x11"\n\x01\xffA\x08\x04!\xa8\x13\n!\xbej'
2023-04-24 20:20:59.922 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0000] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=True, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), manufacturer=4447, tsn=34, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-04-24 20:20:59.925 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0000] Decoded ZCL frame: BasicCluster:Report_Attributes(attribute_reports=[Attribute(attrid=0xFF01, value=TypeValue(type=LVBytes, value=b'\x04!\xa8\x13\n!\xbej'))])
2023-04-24 20:20:59.926 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0000] Received command 0x0A (TSN 34): Report_Attributes(attribute_reports=[Attribute(attrid=0xFF01, value=TypeValue(type=LVBytes, value=b'\x04!\xa8\x13\n!\xbej'))])
2023-04-24 20:20:59.926 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0000] Attribute report received: 0xFF01=b'\x04!\xa8\x13\n!\xbej'
2023-04-24 20:20:59.927 DEBUG (MainThread) [zhaquirks.xiaomi] 00:15:8d:00:09:49:ea:8a - Attribute report. attribute_id: [65281] value: [{'X-attrib-4': 5032, 'path': 27326}]
2023-04-24 20:20:59.932 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:20:59.935 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:20:59.942 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385659.920948, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0})
2023-04-24 20:20:59.945 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385659.920948, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0}) completed
2023-04-24 20:20:59.949 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:20:59.950 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:20:59.951 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO attributes_cache_v11 VALUES (?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO UPDATE SET\n                        value=excluded.value WHERE value != excluded.value', (00:15:8d:00:09:49:ea:8a, 1, 0, 65281, b'\x04!\xa8\x13\n!\xbej'))
2023-04-24 20:20:59.952 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2428b1a90d2a2a95d37e032caad88749e4f42615879f7f7e'
2023-04-24 20:20:59.952 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2023-04-24 20:20:59.953 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO attributes_cache_v11 VALUES (?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO UPDATE SET\n                        value=excluded.value WHERE value != excluded.value', (00:15:8d:00:09:49:ea:8a, 1, 0, 65281, b'\x04!\xa8\x13\n!\xbej')) completed
2023-04-24 20:20:59.954 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x273f, 00:15:8d:00:09:49:ea:8a, 120, -70, [0x6abe]]
2023-04-24 20:20:59.954 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x273f, 00:15:8d:00:09:49:ea:8a, 120, -70, [0x6abe]]
2023-04-24 20:20:59.954 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x273f, 00:15:8d:00:09:49:ea:8a, 120, -70, [0x6abe])
2023-04-24 20:20:59.956 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:20:59.957 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:20:59.958 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'})
2023-04-24 20:20:59.958 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'}) completed
2023-04-24 20:20:59.960 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:20:59.961 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:21:00.002 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3428b1a9112a15b658924a24ab5593499c345312d2e99874fade4083fc7e2fa6efac487e'
2023-04-24 20:21:00.002 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2023-04-24 20:21:00.003 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=122), 116, -71, 0x273f, 255, 255, b'\x18#\n\x00\x00\x10\x01']
2023-04-24 20:21:00.004 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=122), 116, -71, 0x273f, 255, 255, b'\x18#\n\x00\x00\x10\x01']
2023-04-24 20:21:00.004 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x273F), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=122, profile_id=260, cluster_id=6, data=Serialized[b'\x18#\n\x00\x00\x10\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=116, rssi=-71)
2023-04-24 20:21:00.005 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Received ZCL frame: b'\x18#\n\x00\x00\x10\x01'
2023-04-24 20:21:00.006 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=35, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-04-24 20:21:00.007 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-04-24 20:21:00.008 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Received command 0x0A (TSN 35): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-04-24 20:21:00.010 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Attribute report received: on_off=<Bool.true: 1>
2023-04-24 20:21:00.013 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385660.005336, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0})
2023-04-24 20:21:00.015 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385660.005336, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0}) completed
2023-04-24 20:21:00.021 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:21:00.022 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:21:01.977 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x99D7](E1C-NB7): Device seen - marking the device available and resetting counter
2023-04-24 20:21:01.978 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x99D7](E1C-NB7): Update device availability -  device available: True - new availability: True - changed: False
2023-04-24 20:21:02.962 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4428b1a9112a15b658964d24ab1593499cafe7673a579874f4ce4f83fc7a154de3cd16157e'
2023-04-24 20:21:02.963 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2023-04-24 20:21:02.967 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=225), 192, -52, 0x99d7, 255, 255, b'\x08,\n\x00\x04*\xea\x08\x00']
2023-04-24 20:21:02.968 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=225), 192, -52, 0x99d7, 255, 255, b'\x08,\n\x00\x04*\xea\x08\x00']
2023-04-24 20:21:02.970 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x99D7), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=225, profile_id=260, cluster_id=1794, data=Serialized[b'\x08,\n\x00\x04*\xea\x08\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=192, rssi=-52)
2023-04-24 20:21:02.971 DEBUG (MainThread) [zigpy.zcl] [0x99D7:1:0x0702] Received ZCL frame: b'\x08,\n\x00\x04*\xea\x08\x00'
2023-04-24 20:21:02.973 DEBUG (MainThread) [zigpy.zcl] [0x99D7:1:0x0702] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=44, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-04-24 20:21:02.974 DEBUG (MainThread) [zigpy.zcl] [0x99D7:1:0x0702] Decoded ZCL frame: Metering:Report_Attributes(attribute_reports=[Attribute(attrid=0x0400, value=TypeValue(type=int24s, value=2282))])
2023-04-24 20:21:02.975 DEBUG (MainThread) [zigpy.zcl] [0x99D7:1:0x0702] Received command 0x0A (TSN 44): Report_Attributes(attribute_reports=[Attribute(attrid=0x0400, value=TypeValue(type=int24s, value=2282))])
2023-04-24 20:21:02.975 DEBUG (MainThread) [zigpy.zcl] [0x99D7:1:0x0702] Attribute report received: instantaneous_demand=2282
2023-04-24 20:21:02.978 DEBUG (MainThread) [zigpy.zcl] [0x99D7:1:0x0702] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=44, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 1>)
2023-04-24 20:21:02.978 DEBUG (MainThread) [zigpy.zcl] [0x99D7:1:0x0702] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
2023-04-24 20:21:02.979 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x99D7), dst_ep=1, source_route=None, extended_timeout=False, tsn=44, profile_id=260, cluster_id=1794, data=Serialized[b'\x18,\x0b\n\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-04-24 20:21:02.980 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x99d7, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=44), 48, b'\x18,\x0b\n\x00')
2023-04-24 20:21:02.981 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385662.971353, 'ieee': b0:ce:18:14:03:6c:42:ca, 'min_last_seen_delta': 30.0})
2023-04-24 20:21:02.983 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'452921a9602a1565c0904b27ad5493099d4e2787ddcb7fa7f6cc6317b77e'
2023-04-24 20:21:02.983 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385662.971353, 'ieee': b0:ce:18:14:03:6c:42:ca, 'min_last_seen_delta': 30.0}) completed
2023-04-24 20:21:02.987 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:21:02.988 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:21:02.990 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO attributes_cache_v11 VALUES (?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO UPDATE SET\n                        value=excluded.value WHERE value != excluded.value', (b0:ce:18:14:03:6c:42:ca, 1, 1794, 1024, 2282))
2023-04-24 20:21:02.992 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO attributes_cache_v11 VALUES (?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO UPDATE SET\n                        value=excluded.value WHERE value != excluded.value', (b0:ce:18:14:03:6c:42:ca, 1, 1794, 1024, 2282)) completed
2023-04-24 20:21:02.994 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5529a1a9602a15ed199e7e'
2023-04-24 20:21:02.994 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2023-04-24 20:21:02.996 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 95]
2023-04-24 20:21:02.997 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:21:02.997 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:21:03.013 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6529b1a96b2a1565c0904b27ad5493099d4e27f4ddce67f7ad7e'
2023-04-24 20:21:03.013 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2023-04-24 20:21:03.015 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 39383, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=95), 48, <EmberStatus.SUCCESS: 0>, b'']
2023-04-24 20:21:03.016 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 39383, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=95), 48, <EmberStatus.SUCCESS: 0>, b'']
2023-04-24 20:21:04.036 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7529b1a90d2a2a95d37e032caad88749ecf626158705c47e'
2023-04-24 20:21:04.036 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2023-04-24 20:21:04.040 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x273f, 00:15:8d:00:09:49:ea:8a, 112, -72, [0x6abe]]
2023-04-24 20:21:04.040 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x273f, 00:15:8d:00:09:49:ea:8a, 112, -72, [0x6abe]]
2023-04-24 20:21:04.041 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x273f, 00:15:8d:00:09:49:ea:8a, 112, -72, [0x6abe])
2023-04-24 20:21:04.048 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'})
2023-04-24 20:21:04.049 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'INSERT INTO relays_v11 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:8d:00:09:49:ea:8a, 'relays': b'\x01\xbej'}) completed
2023-04-24 20:21:04.052 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:21:04.052 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:21:04.090 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0529b1a9112a15b658924a24ab5593499c355713d2e99874fade4783fc7e2fa7efff087e'
2023-04-24 20:21:04.091 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2023-04-24 20:21:04.094 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=123), 112, -72, 0x273f, 255, 255, b'\x18$\n\x00\x00\x10\x00']
2023-04-24 20:21:04.095 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=123), 112, -72, 0x273f, 255, 255, b'\x18$\n\x00\x00\x10\x00']
2023-04-24 20:21:04.096 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x273F), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=123, profile_id=260, cluster_id=6, data=Serialized[b'\x18$\n\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=112, rssi=-72)
2023-04-24 20:21:04.096 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Received ZCL frame: b'\x18$\n\x00\x00\x10\x00'
2023-04-24 20:21:04.097 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=36, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-04-24 20:21:04.099 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2023-04-24 20:21:04.100 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Received command 0x0A (TSN 36): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2023-04-24 20:21:04.101 DEBUG (MainThread) [zigpy.zcl] [0x273F:1:0x0006] Attribute report received: on_off=<Bool.false: 0>
2023-04-24 20:21:04.106 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385664.096717, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0})
2023-04-24 20:21:04.110 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f94a00c40>, 'UPDATE devices_v11\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_last_seen_delta', {'ts': 1682385664.096717, 'ieee': 00:15:8d:00:09:49:ea:8a, 'min_last_seen_delta': 30.0}) completed
2023-04-24 20:21:04.111 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2023-04-24 20:21:04.112 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'512e21a9a52af96c7e'
2023-04-24 20:21:04.114 DEBUG (Thread-6) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>)
2023-04-24 20:21:04.115 DEBUG (Thread-6) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f94a00c40>) completed
2023-04-24 20:21:04.129 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'162ea1a9a52a8eb330941c27995796499c4e25abefce4e8aeac76889f97e39a7eecdde6f8fffc7dbd5d2698c4623a9ec763ba5ea758241984c2613b1e070381c0e07bbe5ca658a459a4d9e4f9ff7c3d9d46a35a251904824793f7e'
2023-04-24 20:21:04.130 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2023-04-24 20:21:04.130 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received readCounters: [[411, 105, 598, 563, 4, 0, 2, 2, 297, 279, 11, 5, 6, 5, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]]
2023-04-24 20:21:04.132 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2023-04-24 20:21:04.137 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'622f21a9fe2a160a517e'
2023-04-24 20:21:04.149 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'272fa1a9fe2a15b3c2cdf37e'
2023-04-24 20:21:04.150 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2023-04-24 20:21:04.150 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received getValue: [<EzspStatus.SUCCESS: 0>, b'\x9b']
2023-04-24 20:21:04.152 DEBUG (MainThread) [bellows.zigbee.application] Free buffers status EzspStatus.SUCCESS, value: 155
2023-04-24 20:21:04.153 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 411, MAC_TX_BROADCAST = 105, MAC_RX_UNICAST = 598, MAC_TX_UNICAST_SUCCESS = 563, MAC_TX_UNICAST_RETRY = 4, MAC_TX_UNICAST_FAILED = 0, APS_DATA_RX_BROADCAST = 2, APS_DATA_TX_BROADCAST = 2, APS_DATA_RX_UNICAST = 297, APS_DATA_TX_UNICAST_SUCCESS = 279, APS_DATA_TX_UNICAST_RETRY = 11, APS_DATA_TX_UNICAST_FAILED = 5, ROUTE_DISCOVERY_INITIATED = 6, NEIGHBOR_ADDED = 5, NEIGHBOR_REMOVED = 0, NEIGHBOR_STALE = 0, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 0, APS_DECRYPTION_FAILURE = 0, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 0, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 155]

Additional information

Automation Open Trace

{
  "trace": {
    "last_step": "action/0/choose/0/sequence/0",
    "run_id": "e32222fdc8acf93653aaee5cd6147804",
    "state": "stopped",
    "script_execution": "finished",
    "timestamp": {
      "start": "2023-04-23T23:13:53.927249+00:00",
      "finish": "2023-04-23T23:13:53.948218+00:00"
    },
    "domain": "automation",
    "item_id": "1682280204952",
    "trigger": "state of binary_sensor.dining_area_window_4",
    "trace": {
      "trigger/0": [
        {
          "path": "trigger/0",
          "timestamp": "2023-04-23T23:13:53.927435+00:00",
          "changed_variables": {
            "this": {
              "entity_id": "automation.win_test",
              "state": "on",
              "attributes": {
                "last_triggered": "2023-04-23T23:13:53.823333+00:00",
                "mode": "single",
                "current": 0,
                "id": "1682280204952",
                "friendly_name": "win_test"
              },
              "last_changed": "2023-04-23T21:21:10.733132+00:00",
              "last_updated": "2023-04-23T23:13:53.853579+00:00",
              "context": {
                "id": "01GYR6ABMYXSTR3C500ESVJ12G",
                "parent_id": "01GYR6ABMQRP3NJZ2ZRXJYSPCQ",
                "user_id": null
              }
            },
            "trigger": {
              "id": "DA4-Open",
              "idx": "0",
              "alias": "Trigger - Dining Area Window 4 Open",
              "platform": "state",
              "entity_id": "binary_sensor.dining_area_window_4",
              "from_state": {
                "entity_id": "binary_sensor.dining_area_window_4",
                "state": "off",
                "attributes": {
                  "device_class": "window",
                  "friendly_name": "Dining Area Window 4",
                  "icon": "fapro:brands/windows"
                },
                "last_changed": "2023-04-23T23:13:53.815404+00:00",
                "last_updated": "2023-04-23T23:13:53.815404+00:00",
                "context": {
                  "id": "01GYR6ABMQRP3NJZ2ZRXJYSPCQ",
                  "parent_id": null,
                  "user_id": null
                }
              },
              "to_state": {
                "entity_id": "binary_sensor.dining_area_window_4",
                "state": "on",
                "attributes": {
                  "device_class": "window",
                  "friendly_name": "Dining Area Window 4",
                  "icon": "fapro:brands/windows"
                },
                "last_changed": "2023-04-23T23:13:53.920026+00:00",
                "last_updated": "2023-04-23T23:13:53.920026+00:00",
                "context": {
                  "id": "01GYR6ABR06RDD97A67JNCJTJB",
                  "parent_id": null,
                  "user_id": null
                }
              },
              "for": null,
              "attribute": null,
              "description": "state of binary_sensor.dining_area_window_4"
            }
          }
        }
      ],
      "action/0": [
        {
          "path": "action/0",
          "timestamp": "2023-04-23T23:13:53.932644+00:00",
          "changed_variables": {
            "context": {
              "id": "01GYR6ABR7HVNDQCNTB8E3BS5F",
              "parent_id": "01GYR6ABR06RDD97A67JNCJTJB",
              "user_id": null
            }
          },
          "result": {
            "choice": 0
          }
        }
      ],
      "action/0/choose/0": [
        {
          "path": "action/0/choose/0",
          "timestamp": "2023-04-23T23:13:53.932853+00:00",
          "result": {
            "result": true
          }
        }
      ],
      "action/0/choose/0/conditions/0": [
        {
          "path": "action/0/choose/0/conditions/0",
          "timestamp": "2023-04-23T23:13:53.932941+00:00",
          "result": {
            "result": true
          }
        }
      ],
      "action/0/choose/0/sequence/0": [
        {
          "path": "action/0/choose/0/sequence/0",
          "timestamp": "2023-04-23T23:13:53.935796+00:00",
          "result": {
            "params": {
              "domain": "timer",
              "service": "start",
              "service_data": {},
              "target": {
                "entity_id": [
                  "timer.windows_state_open"
                ]
              }
            },
            "running_script": false,
            "limit": 10
          }
        }
      ]
    },
    "config": {
      "id": "1682280204952",
      "alias": "win_test",
      "description": "",
      "trigger": [
        {
          "platform": "state",
          "entity_id": [
            "binary_sensor.dining_area_window_4"
          ],
          "id": "DA4-Open",
          "from": "off",
          "to": "on",
          "alias": "Trigger - Dining Area Window 4 Open"
        },
        {
          "platform": "state",
          "entity_id": [
            "binary_sensor.dining_area_window_4"
          ],
          "from": "on",
          "to": "off",
          "id": "DA4-Closed",
          "alias": "Trigger - Dining Area Window 4 Closed"
        }
      ],
      "condition": [],
      "action": [
        {
          "choose": [
            {
              "conditions": [
                {
                  "condition": "trigger",
                  "id": "DA4-Open",
                  "alias": "On Open Trigger"
                }
              ],
              "sequence": [
                {
                  "service": "timer.start",
                  "data": {},
                  "target": {
                    "entity_id": "timer.windows_state_open"
                  },
                  "alias": "Start Window Open Timer"
                }
              ]
            },
            {
              "conditions": [
                {
                  "condition": "trigger",
                  "id": "DA4-Closed",
                  "alias": "On Closed Trigger"
                }
              ],
              "sequence": [
                {
                  "service": "timer.start",
                  "data": {},
                  "target": {
                    "entity_id": "timer.windows_state_closed"
                  },
                  "alias": "Start Window Closed Timer"
                }
              ]
            }
          ]
        }
      ],
      "mode": "single"
    },
    "blueprint_inputs": null,
    "context": {
      "id": "01GYR6ABR7HVNDQCNTB8E3BS5F",
      "parent_id": "01GYR6ABR06RDD97A67JNCJTJB",
      "user_id": null
    }
  },
  "logbookEntries": [
    {
      "name": "win_test",
      "message": "triggered by state of binary_sensor.dining_area_window_4",
      "source": "state of binary_sensor.dining_area_window_4",
      "entity_id": "automation.win_test",
      "context_id": "01GYR6ABR7HVNDQCNTB8E3BS5F",
      "when": 1682291633.927693,
      "domain": "automation"
    }
  ]
}

Automation Close Trace

{
  "trace": {
    "last_step": "action/0/choose/1/sequence/0",
    "run_id": "4cd801c4f86fbe39bff5e4f36cc6870d",
    "state": "stopped",
    "script_execution": "finished",
    "timestamp": {
      "start": "2023-04-23T23:13:58.762550+00:00",
      "finish": "2023-04-23T23:13:58.783400+00:00"
    },
    "domain": "automation",
    "item_id": "1682280204952",
    "trigger": "state of binary_sensor.dining_area_window_4",
    "trace": {
      "trigger/1": [
        {
          "path": "trigger/1",
          "timestamp": "2023-04-23T23:13:58.762751+00:00",
          "changed_variables": {
            "this": {
              "entity_id": "automation.win_test",
              "state": "on",
              "attributes": {
                "last_triggered": "2023-04-23T23:13:53.927760+00:00",
                "mode": "single",
                "current": 0,
                "id": "1682280204952",
                "friendly_name": "win_test"
              },
              "last_changed": "2023-04-23T21:21:10.733132+00:00",
              "last_updated": "2023-04-23T23:13:53.946320+00:00",
              "context": {
                "id": "01GYR6ABR7HVNDQCNTB8E3BS5F",
                "parent_id": "01GYR6ABR06RDD97A67JNCJTJB",
                "user_id": null
              }
            },
            "trigger": {
              "id": "DA4-Closed",
              "idx": "1",
              "alias": "Trigger - Dining Area Window 4 Closed",
              "platform": "state",
              "entity_id": "binary_sensor.dining_area_window_4",
              "from_state": {
                "entity_id": "binary_sensor.dining_area_window_4",
                "state": "on",
                "attributes": {
                  "device_class": "window",
                  "friendly_name": "Dining Area Window 4",
                  "icon": "fapro:brands/windows"
                },
                "last_changed": "2023-04-23T23:13:53.920026+00:00",
                "last_updated": "2023-04-23T23:13:53.920026+00:00",
                "context": {
                  "id": "01GYR6ABR06RDD97A67JNCJTJB",
                  "parent_id": null,
                  "user_id": null
                }
              },
              "to_state": {
                "entity_id": "binary_sensor.dining_area_window_4",
                "state": "off",
                "attributes": {
                  "device_class": "window",
                  "friendly_name": "Dining Area Window 4",
                  "icon": "fapro:brands/windows"
                },
                "last_changed": "2023-04-23T23:13:58.754533+00:00",
                "last_updated": "2023-04-23T23:13:58.754533+00:00",
                "context": {
                  "id": "01GYR6AGF216WNKJJZAHEQH707",
                  "parent_id": null,
                  "user_id": null
                }
              },
              "for": null,
              "attribute": null,
              "description": "state of binary_sensor.dining_area_window_4"
            }
          }
        }
      ],
      "action/0": [
        {
          "path": "action/0",
          "timestamp": "2023-04-23T23:13:58.766888+00:00",
          "changed_variables": {
            "context": {
              "id": "01GYR6AGFAW8D1B4TTD77MBJ9F",
              "parent_id": "01GYR6AGF216WNKJJZAHEQH707",
              "user_id": null
            }
          },
          "result": {
            "choice": 1
          }
        }
      ],
      "action/0/choose/0": [
        {
          "path": "action/0/choose/0",
          "timestamp": "2023-04-23T23:13:58.767112+00:00",
          "result": {
            "result": false
          }
        }
      ],
      "action/0/choose/0/conditions/0": [
        {
          "path": "action/0/choose/0/conditions/0",
          "timestamp": "2023-04-23T23:13:58.767208+00:00",
          "result": {
            "result": false
          }
        }
      ],
      "action/0/choose/1": [
        {
          "path": "action/0/choose/1",
          "timestamp": "2023-04-23T23:13:58.767372+00:00",
          "result": {
            "result": true
          }
        }
      ],
      "action/0/choose/1/conditions/0": [
        {
          "path": "action/0/choose/1/conditions/0",
          "timestamp": "2023-04-23T23:13:58.767449+00:00",
          "result": {
            "result": true
          }
        }
      ],
      "action/0/choose/1/sequence/0": [
        {
          "path": "action/0/choose/1/sequence/0",
          "timestamp": "2023-04-23T23:13:58.768805+00:00",
          "result": {
            "params": {
              "domain": "timer",
              "service": "start",
              "service_data": {},
              "target": {
                "entity_id": [
                  "timer.windows_state_closed"
                ]
              }
            },
            "running_script": false,
            "limit": 10
          }
        }
      ]
    },
    "config": {
      "id": "1682280204952",
      "alias": "win_test",
      "description": "",
      "trigger": [
        {
          "platform": "state",
          "entity_id": [
            "binary_sensor.dining_area_window_4"
          ],
          "id": "DA4-Open",
          "from": "off",
          "to": "on",
          "alias": "Trigger - Dining Area Window 4 Open"
        },
        {
          "platform": "state",
          "entity_id": [
            "binary_sensor.dining_area_window_4"
          ],
          "from": "on",
          "to": "off",
          "id": "DA4-Closed",
          "alias": "Trigger - Dining Area Window 4 Closed"
        }
      ],
      "condition": [],
      "action": [
        {
          "choose": [
            {
              "conditions": [
                {
                  "condition": "trigger",
                  "id": "DA4-Open",
                  "alias": "On Open Trigger"
                }
              ],
              "sequence": [
                {
                  "service": "timer.start",
                  "data": {},
                  "target": {
                    "entity_id": "timer.windows_state_open"
                  },
                  "alias": "Start Window Open Timer"
                }
              ]
            },
            {
              "conditions": [
                {
                  "condition": "trigger",
                  "id": "DA4-Closed",
                  "alias": "On Closed Trigger"
                }
              ],
              "sequence": [
                {
                  "service": "timer.start",
                  "data": {},
                  "target": {
                    "entity_id": "timer.windows_state_closed"
                  },
                  "alias": "Start Window Closed Timer"
                }
              ]
            }
          ]
        }
      ],
      "mode": "single"
    },
    "blueprint_inputs": null,
    "context": {
      "id": "01GYR6AGFAW8D1B4TTD77MBJ9F",
      "parent_id": "01GYR6AGF216WNKJJZAHEQH707",
      "user_id": null
    }
  },
  "logbookEntries": [
    {
      "name": "win_test",
      "message": "triggered by state of binary_sensor.dining_area_window_4",
      "source": "state of binary_sensor.dining_area_window_4",
      "entity_id": "automation.win_test",
      "context_id": "01GYR6AGFAW8D1B4TTD77MBJ9F",
      "when": 1682291638.763028,
      "domain": "automation"
    }
  ]
}

zigbee_log_screenshot binary_sensor dining_area_window_4_log_screenshot window_state_close_log_screenshot window_state_open_log_screenshot

home-assistant[bot] commented 1 year ago

Hey there @dmulcahey, @adminiuga, @puddly, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `zha` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign zha` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)

zha documentation zha source (message by IssueLinks)

MattWestb commented 1 year ago

I was doing one fast test and the closing DA was working OK but not the opening one. Little testing and found that ZHA was putting in Device offline instead of LUMI lumi.sensor_magnet.aq2 Opening opened that was making the automation not working OK. And the close is getting open as trigger !!

Deleting all automatons for the device and making new ones and forcing the right triggers then doing them and both open and closing is working OK.

Can you looking how your automatons is looking in yaml ?

My fixed automatons made from device card looks like this:

alias: LMO
description: ""
trigger:
  - type: opened
    platform: device
    device_id: 689023bb85a9fb6320aef0483a01f2cb
    entity_id: binary_sensor.lumi_lumi_sensor_magnet_aq2_opening
    domain: binary_sensor
condition: []
action:
  - event: zha_event
    event_data:
      Data: Open
mode: single

And 

alias: LMC
description: ""
trigger:
  - type: not_opened
    platform: device
    device_id: 689023bb85a9fb6320aef0483a01f2cb
    entity_id: binary_sensor.lumi_lumi_sensor_magnet_aq2_opening
    domain: binary_sensor
condition: []
action:
  - event: zha_event
    event_data:
      Data: Closed
mode: single

So its looks like on bug in ZHA / HA automation logic here.

MattWestb commented 1 year ago

@TheJulianJES Do you having this device ?? Perhaps its can being repeated with other devices so i shall trying doing the same with LIDL magnet and reporting back.

I think perhaps our @puddly have doing somthing that making the linking from the DA to the automation GUI not working OK or it have never working OK so perhaps hi was not to blaming :-)))

MattWestb commented 1 year ago

Was trying adding DA made automatons to LIDL magnet and its using IAS Zone and not OnOff cluster but i is getting the same then adding them.

ZHA DA => HA Automation editor GUI DA Opened => Device offline DA Closed => LIDL Magnet TY0203 Iaszone opened

So somthing spooky is going on here !!

Both devices is working normal and reporting opened and closed OK as events in the log and also on the device card status only the DA mapping looks being broke.

TheJulianJES commented 1 year ago

To confirm: the automations editor in the frontend creates a wrong YAML automation which has incorrect triggers?

MattWestb commented 1 year ago

Yep and if correcting the trigger or doing one new from automation editor its working as it shall do.

MattWestb commented 1 year ago

Was looking but IKEA motion sensor with quirk is working OK (we was fixing the DA also for the last 24.5 firmware) but the 2 different types LIDL motion sensors without quirk and is using IAS Zone is also wrong:

  "manufacturer": "_TZ1800_fcdjzz3s",
  "model": "TY0202",
  "class": "zigpy.device.Device"

LIDL Motion 1 TY0202 Iaszone started detecting motion => Device offline

LIDL Motion 1 TY0202 Iaszone stopped detecting motion => LIDL Motion 1 TY0202 Iaszone started detecting motion

And the same with:

  "manufacturer": "_TZ1800_fcdjzz3s",
  "model": "TY0202",
  "class": "zigpy.device.Device"

Edit: Interesting thing is that the different LIDL models is still using the same device ID from tuya but is completely different devices.

MattWestb commented 1 year ago

Was testing HUE Motion sensor SML001 and:

Wohnzimmer BM Rechts illuminance illuminance changes =>  Device offline
Wohnzimmer BM Rechts temperature temperature changes => Wohnzimmer BM Rechts illuminance illuminance changes
Wohnzimmer BM Rechts occupancy became occupied => Wohnzimmer BM Rechts temperature temperature changes
Wohnzimmer BM Rechts occupancy became not occupied => Wohnzimmer BM Rechts occupancy became occupied
Wohnzimmer BM Rechts on_off started detecting motion => Wohnzimmer BM Rechts occupancy became not occupied
Wohnzimmer BM Rechts on_off stopped detecting motion => Wohnzimmer BM Rechts on_off started detecting motion

The rest DAs is doing the right trigger in the HA automation GUI but its looks somewhere is the list hoping to wrong post in the list of functions.

If i remember right is some devs having this devices so shall being easy pointing out what is going wrong in the code.

TheJulianJES commented 1 year ago

2023.5.0b0 includes a new frontend release. Could you check if it works with that?

MattWestb commented 1 year ago

Normally no problems but all my working test systems (3) is running RCP with OTBR and i dont like distorting them then its on the way in the production system and my Windows 10 have stopping running WSL so cant running docker on it for fast tests that i normally was doing. If i remember right is our Puddly also having one SML001.

vlape commented 1 year ago

I am not sure if it matters, updated Home Assistant Operating System to 10.1 this morning. Same results. Here are zha_event from a different lumi.sensor_magnet.aq2 sensor. Same behavior. Opened window. Closed window.

Let me know if there is anything else useful I can provide.

event_type: zha_event
data:
  device_ieee: 00:15:8d:00:09:46:57:83
  unique_id: 00:15:8d:00:09:46:57:83:1:0x0006
  device_id: cd7b738bc4bdef360f32c1e9086c5073
  endpoint_id: 1
  cluster_id: 6
  command: attribute_updated
  args:
    attribute_id: 0
    attribute_name: on_off
    value: 1
  params: {}
origin: LOCAL
time_fired: "2023-04-27T18:15:57.532550+00:00"
context:
  id: 01GZ1YVPAW2BJAPQEZE4HXCWGJ
  parent_id: null
  user_id: null
event_type: zha_event
data:
  device_ieee: 00:15:8d:00:09:46:57:83
  unique_id: 00:15:8d:00:09:46:57:83:1:0x0006
  device_id: cd7b738bc4bdef360f32c1e9086c5073
  endpoint_id: 1
  cluster_id: 6
  command: attribute_updated
  args:
    attribute_id: 0
    attribute_name: on_off
    value: 0
  params: {}
origin: LOCAL
time_fired: "2023-04-27T18:15:57.560614+00:00"
context:
  id: 01GZ1YVPBRX0RTT06VEMK67A2F
  parent_id: null
  user_id: null
event_type: zha_event
data:
  device_ieee: 00:15:8d:00:09:46:57:83
  unique_id: 00:15:8d:00:09:46:57:83:1:0x0006
  device_id: cd7b738bc4bdef360f32c1e9086c5073
  endpoint_id: 1
  cluster_id: 6
  command: attribute_updated
  args:
    attribute_id: 0
    attribute_name: on_off
    value: 1
  params: {}
origin: LOCAL
time_fired: "2023-04-27T18:15:57.659037+00:00"
context:
  id: 01GZ1YVPEVTSHJD1483871Z1JE
  parent_id: null
  user_id: null
event_type: zha_event
data:
  device_ieee: 00:15:8d:00:09:46:57:83
  unique_id: 00:15:8d:00:09:46:57:83:1:0x0006
  device_id: cd7b738bc4bdef360f32c1e9086c5073
  endpoint_id: 1
  cluster_id: 6
  command: attribute_updated
  args:
    attribute_id: 0
    attribute_name: on_off
    value: 0
  params: {}
origin: LOCAL
time_fired: "2023-04-27T18:16:02.381616+00:00"
context:
  id: 01GZ1YVV2DEEYQDZN84AA645W2
  parent_id: null
  user_id: null
event_type: zha_event
data:
  device_ieee: 00:15:8d:00:09:46:57:83
  unique_id: 00:15:8d:00:09:46:57:83:1:0x0006
  device_id: cd7b738bc4bdef360f32c1e9086c5073
  endpoint_id: 1
  cluster_id: 6
  command: attribute_updated
  args:
    attribute_id: 0
    attribute_name: on_off
    value: 1
  params: {}
origin: LOCAL
time_fired: "2023-04-27T18:16:02.433468+00:00"
context:
  id: 01GZ1YVV41BRTBNEVNHAQXRKXA
  parent_id: null
  user_id: null
event_type: zha_event
data:
  device_ieee: 00:15:8d:00:09:46:57:83
  unique_id: 00:15:8d:00:09:46:57:83:1:0x0006
  device_id: cd7b738bc4bdef360f32c1e9086c5073
  endpoint_id: 1
  cluster_id: 6
  command: attribute_updated
  args:
    attribute_id: 0
    attribute_name: on_off
    value: 0
  params: {}
origin: LOCAL
time_fired: "2023-04-27T18:16:02.449030+00:00"
context:
  id: 01GZ1YVV4HJR0E5413NHG7JAFQ
  parent_id: null
  user_id: null
TheJulianJES commented 1 year ago

So the "Example YAML snippet" initially posted is working correctly with a lumi.sensor_magnet.aq2 on 2023.4.6 for me. That automation does not use device automation triggers at all, as it uses a state trigger.

Thezha_events sent when opening/closing the window indicate that the attribute (cache) was correctly updated too.

@MattWestb You mentioned that you get wrong device automation triggers when creating the automation from the frontend? Can you post a screenshot how you're exactly creating the automation (and from what browser) and what YAML is produced by creating that automation with device automation triggers?

I also created an automation using the lumi.sensor_magnet.aq2 and device automation triggers for opened and closed (instead of directly using state triggers) and they also worked just fine.

MattWestb commented 1 year ago

From the device card: Aqaramk2a clicking opened and getting: Aqaramk2b And if clocking closed i getting: Aqaramk2c The yaml is also wrong so its the linking in ZHA that is getting problem.

Opened:

description: ""
mode: single
trigger:
  - device_id: 689023bb85a9fb6320aef0483a01f2cb
    domain: zha
    platform: device
    type: device_offline
    subtype: device_offline
condition: []
action: []

Closed:

description: ""
mode: single
trigger:
  - type: opened
    platform: device
    device_id: 689023bb85a9fb6320aef0483a01f2cb
    entity_id: binary_sensor.lumi_lumi_sensor_magnet_aq2_opening
    domain: binary_sensor
condition: []
action: []

Google Chrome Chrome is up to date Version 112.0.5615.138 (Official Build) (64-bit)

Edit: The zha_events is very OK also the logbook on the device card and the HA long is OK and the icon on the device card is working OK. Its problems with the linking from the device card to the automation editor that is getting wrong. I war refreshing the browser between clicking on make on automation but the same resolute.

If correcting the trigger in the editor all is working OK but its still one bug here.

Also one PM that i think (not 1110% sure) that is not 100% hitting the bug than i have seen some times its was OK but very rear. I also have seen that later versions of HA is not doing all steps in time trigger that putting light on and off have running but have not all steps but i was thinking it was interference that was doing the Zigbee to delivering the command but its not any error in the log and in the log book HA have not doing all steps and its happening 2-3 times in the week so can being one python bug that is doing strange things in the automatons.

MattWestb commented 1 year ago

The tests was done on one RCP 4.2.2.0. = EZSP 7.2.2.0 and also tested devices that is in production system and they is doing the same.

Lumi Magnet2: Diag Test system zha-90202c43129e6a74f5081ca4b796a4b4-LUMI lumi.sensor_magnet.aq2-689023bb85a9fb6320aef0483a01f2cb.json.txt

Lumi Magnet2 inside one smoke detector. Diag production system zha-998bc857058111eb90e2ad6d9c6e46a8-LUMI lumi.sensor_magnet.aq2-62550608096e11eba461ed53132982ef.json.txt

TheJulianJES commented 1 year ago

From the device card

Oh, I've never created a device automation trigger by going from the device page. Using "Device" as a trigger and then selecting any device automation trigger does not cause the issue: image

I can reproduce the issue when going through the device page though. Pretty sure that's a frontend issue. Your best bet is to open an issue in the frontend repo, include those screenshots, mention with what device it's happening, and that it seems to be off by one.

From what I can tell, the initial issue is a different one that's possibly caused by bad sensor placement. The provided YAML in the OP is correct and works well for me.

MattWestb commented 1 year ago

Transfer the issue to the fronted and we dont need redoing all postings.

TheJulianJES commented 1 year ago

The initial issue is a different one that's possibly caused by bad sensor placement. The provided YAML in the OP is correct and works well for me.

MattWestb commented 1 year ago

OK so we is having 2 different bugs here then i reading the initial post.

vlape commented 1 year ago

The initial issue is a different one that's possibly caused by bad sensor placement. The provided YAML in the OP is correct and works well for me.

I am not sure placement is the issue sinve multiple sensors via multiple routes from the same vendor are producing the same result. Each sensor is no more than 15 feet from a router. I have only put 9 of these sensors on the network. The zigbee network was built as follows: Home Assistant Yellow as coordinator. Three TRADFRI outlets and two Sengled E1C-NB7 outlets were joined to a new network. I waited a week before adding the Aqora sensors Each Aqora aensor was added via the nearest hub. ZHA map indicates the sensors are connected to hubs. There is little physical obstruction between sensors and hub. Do any of these dataponits help?

zha-de5761abbba567abfcd192b06be7492f-LUMI lumi.sensor_magnet.aq2-16745100a7a295eeba80355d027f8533.json.txt fw1_wrp fr1_diag_page

TheJulianJES commented 1 year ago

Screenshot from your initial post:

You're seeing the state bounce. So you see a open/close/open in the same second (even though you're likely just opening it). The sensor sends multiple updates. So either your sensor/magnet is placed badly or it's defective.

vlape commented 1 year ago

You think all nine of them are defective or have badly placed magnets? The reference lines for the sensors and magnets are +/- 2mm. Distance between sensor and magnet is approximately 5mm, well below the maximum of 22mm as indicated in specifications.

MattWestb commented 1 year ago

In the opening posted log all commands is OK send with unique TSN so its not made of the network, every one is being sent from the device that have detected status change.

The magnet sensor can being defect but normally sending closed then its open only false open then being closed. Thais barbecue its one hall element that is in one glass tube with vacuum or gas and if the vacuum or gas is leaked and getting oxygen in it the contacts is not getting good contact and its working more like one vibration sensor. To diagnostic knocking with one back of one screwdriver on the sensor then the magnet is in range and if its sending status changes its defect (I have only 30 years experience of this things from alarm systems).

I think its not very likely all your magnet sensors is defect and if not mounted very badly they shall working OK. You also can here a very silent clicking then the elements is changing status but is not easy hearing if mush sound around.

I was testing one more time in my test system and i cant getting my device sending false closings then opening it in "normal" working conditions in the working range of the magnet.

The code tracing i leaving to other doing that have more knowledge of that.

Edit: I was reference measuring the the distance on flat surface and with the reference markings in the right position and opening is 22 mm and closing 20 mm (its having some hysterics build in for not getting multiple detentions then doing one clear open or closing) and the arrangements up / down is not so critical then the magnetic fled is prity large around the magnet and the sensor is tolerant for it.

vlape commented 1 year ago

@MattWestb I do hear a single click on open and close. Tapping lightly on the sensor with the window open, nothing happens. A firm tap will indicate closed. Will not show open egain until it passes the magnet. I assume this is due to a shock and would be acceptable. With the window closed, there is no change in status

MattWestb commented 1 year ago

All sounds OK but if knocking hard then its open it can getting fast close and then closed it jumping away and need being re triggered with the magnet for working agen.

The working principle of the detector is one Reed switch and is the how its working is described well here: https://en.wikipedia.org/wiki/Reed_switch its pure mechanical but normally working well.

dmulcahey commented 1 year ago

Can you post a picture of the device installation please?

MattWestb commented 1 year ago

The most important is mounting the magnet in the right direction or you can getting strange behavior like double triggering or reverse function of the element.

vlape commented 1 year ago

@dmulcahey Attached @MattWestb the reference lines on the magnet and sensor are facing each other. IMG_0777(1)

issue-triage-workflows[bot] commented 1 year ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.