I have issue with my Zigbee network setup (ZHA, raspbee2).
Some of my Osram light bulbs are blinking when powered or randomly. The startup blinking seems to be quite regular, as it blinks at around 5th and 10th second after being powered.
I’m not sure how should I investigate it. There is no single zha_event triggered during this.
Will be grateful for any kind of help.
Here is how the log looks like. I powered the device precisely at 45:00, and ~5s after the it blinked
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [35, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, 0, 0, 19, b'\x00\x0f\x07/\xf0\xb0\x00\xaa>\xb0|\x8e', 0, 175, 255, 221, 58, 2, 0, -57]
2021-03-19 16:45:00 INFO (MainThread) [zigpy_deconz.zigbee.application] New device joined: 0x070f, 7c:b0:3e:aa:00:b0:f0:2f
2021-03-19 16:45:00 INFO (MainThread) [zigpy.application] Device 0x070f (7c:b0:3e:aa:00:b0:f0:2f) joined the network
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy.application] Skip initialization for existing device 7c:b0:3e:aa:00:b0:f0:2f
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy.zdo] [0x070f:zdo] ZDO request ZDOCmd.Device_annce: [0x070F, 7c:b0:3e:aa:00:b0:f0:2f, 142]
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 129 under 130 request id, data: b'01810200'
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, ep: 0, profile: 0x0000, cluster_id: 0x0013, data: b'000f072ff0b000aa3eb07c8e'
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (19, 130, 0, <DeconzAddressEndpoint address_mode=2 address=0x070F endpoint=3>, 260, 4, 1, b'\x01\x81\x02\x00', 2, 0)
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 130]
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 130: 00
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x82 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x070f endpoint=3>, status: 0x00
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [30, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, 3, 260, 4, b'\x19\x81\x02\x07\x01\x02\x00', 0, 175, 255, 176, 58, 2, 0, -57]
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy.zcl] [0x070f:3:0x0004] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=129 command_id=2>
2021-03-19 16:45:00 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, ep: 3, profile: 0x0104, cluster_id: 0x0004, data: b'19810207010200'
2021-03-19 16:45:05 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2021-03-19 16:45:05 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-03-19 16:45:05 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [30, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, 3, 260, 6, b'\x18\x00\n\x00\x00\x10\x01', 0, 175, 255, 224, 58, 2, 0, -57]
2021-03-19 16:45:05 DEBUG (MainThread) [zigpy.zcl] [0x070f:3:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=0 command_id=Command.Report_Attributes>
2021-03-19 16:45:05 DEBUG (MainThread) [zigpy.zcl] [0x070f:3:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2021-03-19 16:45:05 DEBUG (MainThread) [zigpy.zcl] [0x070f:3:0x0006] Attribute report received: on_off=1
2021-03-19 16:45:05 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, ep: 3, profile: 0x0104, cluster_id: 0x0006, data: b'18000a00001001'
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [30, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, 3, 260, 8, b'\x18\x01\n\x00\x00 \xfe', 0, 175, 255, 224, 58, 2, 0, -56]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy.zcl] [0x070f:3:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=1 command_id=Command.Report_Attributes>
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy.zcl] [0x070f:3:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=254>)]]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy.zcl] [0x070f:3:0x0008] Attribute report received: current_level=254
2021-03-19 16:45:06 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x070F:3:0x0008]: received attribute: 0 update with value: 254
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, ep: 3, profile: 0x0104, cluster_id: 0x0008, data: b'18010a000020fe'
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [32, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, 0, 0, 6, b'\x01\xfd\xff\x04\x01\x01\x19\x00\x00', 0, 175, 255, 224, 58, 2, 0, -56]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy.zdo] [0x070f:zdo] ZDO request ZDOCmd.Match_Desc_req: [0xFFFD, 260, [25], []]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 1 under 131 request id, data: b'010000000101'
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, ep: 0, profile: 0x0000, cluster_id: 0x0006, data: b'01fdff040101190000'
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (21, 131, 0, <DeconzAddressEndpoint address_mode=2 address=0x070F endpoint=0>, 0, <ZDOCmd.Match_Desc_rsp: 0x8006>, 0, b'\x01\x00\x00\x00\x01\x01', 2, 0)
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 131]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|APSDE_DATA_CONFIRM|2: 174>, 0]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [28, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 38>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, 0, 0, 1, b'\x02\x00\x00\x00\x00', 0, 175, 255, 176, 58, 2, 0, -56]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy.zdo] [0x070f:zdo] ZDO request ZDOCmd.IEEE_addr_req: [0x0000, 0, 0]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 2 under 132 request id, data: b'0200e52106ffff2e210000000000'
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, ep: 0, profile: 0x0000, cluster_id: 0x0001, data: b'0200000000'
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|APSDE_DATA_CONFIRM|2: 174>, 0]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 131: 00
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x83 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x070f endpoint=0>, status: 0x00
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 132, 0, <DeconzAddressEndpoint address_mode=2 address=0x070F endpoint=0>, 0, <ZDOCmd.IEEE_addr_rsp: 0x8001>, 0, b'\x02\x00\xe5!\x06\xff\xff.!\x00\x00\x00\x00\x00', 2, 0)
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 42>, 132]
2021-03-19 16:45:06 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [28, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, 0, 0, 1, b'\x03\x00\x00\x00\x00', 0, 175, 255, 227, 58, 2, 0, -56]
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy.zdo] [0x070f:zdo] ZDO request ZDOCmd.IEEE_addr_req: [0x0000, 0, 0]
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 3 under 133 request id, data: b'0300e52106ffff2e210000000000'
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x070f>, ep: 0, profile: 0x0000, cluster_id: 0x0001, data: b'0300000000'
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 133, 0, <DeconzAddressEndpoint address_mode=2 address=0x070F endpoint=0>, 0, <ZDOCmd.IEEE_addr_rsp: 0x8001>, 0, b'\x03\x00\xe5!\x06\xff\xff.!\x00\x00\x00\x00\x00', 2, 0)
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 38>, 133]
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 132: e9
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x84 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x070f endpoint=0>, status: 0xe9
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 132 req id frame: TXStatus.MAC_NO_ACK
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy.device] [0x070f] Delivery error for seq # 0x02, on endpoint id 0 cluster 0x8001: message send failure
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 133: e9
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x85 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x070f endpoint=0>, status: 0xe9
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 133 req id frame: TXStatus.MAC_NO_ACK
2021-03-19 16:45:07 DEBUG (MainThread) [zigpy.device] [0x070f] Delivery error for seq # 0x03, on endpoint id 0 cluster 0x8001: message send failure
So, is this related somehow?
I also had the issue multiple times where a light would reconfigure itself and then blink.
it is directly related. https://github.com/home-assistant/core/pull/32456/files#diff-6244af3e0cdc944523cb131851c86bbeadeebccec859efaa54d23edbe274354f Line #347
Thx, I’ll report a bug then.
I’m not sure now, I can’t see stored in registry in the log. It rather should be there if next line also got invoked.
Interesting fact: after random blink during the night, device goes to it default state. Also quickly changed brightness it is back to full after post start blink.