search

Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
12.13k stars 1.68k forks source link

Xiaomi Wall Switch (QBKG12LM) clicks skipped #3592

Closed ArkadiuszNiemiec closed 4 years ago

ArkadiuszNiemiec commented 4 years ago

What happened

I have tried tu use Conbee II as coordinator and had to repair few devices. After this one of my wall switches (QBKG12LM - working as a router) did not report clicks (they are working in decoupled mode). Here are logs after clicking left button twice, right button twice and both buttons once:

zigbee2mqtt:debug 2020-05-22 17:49:28: Received Zigbee message from 'bedroom_wall_switch', type 'attributeReport', cluster 'genMultistateInput', data '{"presentValue":1}' from endpoint 5 with groupID null
zigbee2mqtt:debug 2020-05-22 17:49:28: Skipping re-transmitted Xiaomi message
zigbee2mqtt:debug 2020-05-22 17:49:29: Received Zigbee message from 'bedroom_wall_switch', type 'attributeReport', cluster 'genMultistateInput', data '{"presentValue":1}' from endpoint 5 with groupID null
zigbee2mqtt:debug 2020-05-22 17:49:29: Skipping re-transmitted Xiaomi message
zigbee2mqtt:debug 2020-05-22 17:49:30: Received Zigbee message from 'bedroom_wall_switch', type 'attributeReport', cluster 'genMultistateInput', data '{"presentValue":1}' from endpoint 6 with groupID null
zigbee2mqtt:debug 2020-05-22 17:49:30: Skipping re-transmitted Xiaomi message
zigbee2mqtt:debug 2020-05-22 17:49:31: Received Zigbee message from 'bedroom_wall_switch', type 'attributeReport', cluster 'genMultistateInput', data '{"presentValue":1}' from endpoint 6 with groupID null
zigbee2mqtt:debug 2020-05-22 17:49:31: Skipping re-transmitted Xiaomi message
zigbee2mqtt:debug 2020-05-22 17:49:31: Received Zigbee message from 'bedroom_wall_switch', type 'attributeReport', cluster 'genMultistateInput', data '{"presentValue":1}' from endpoint 7 with groupID null
zigbee2mqtt:debug 2020-05-22 17:49:31: Skipping re-transmitted Xiaomi message

What did you expect to happen

To get MQTT messages about clicks.

How to reproduce it (minimal and precise)

Click "broken" switch and watch logs.

Debug Info

Zigbee2mqtt version: 1.13.1 Adapter hardware: ConBee II (is it related?) Adapter firmware version: ---

Koenkk commented 4 years ago

Could you provide the herdsman debug log of this?

To enable herdsman debug logging, see https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging

ArkadiuszNiemiec commented 4 years ago

Single click, I hope copied everything:

2020-05-22T16:07:26.121Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10101010
2020-05-22T16:07:26.167Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 37
2020-05-22T16:07:26.177Z zigbee-herdsman:deconz:frameParser DATA_INDICATION Response - seqNr. 37 srcAddr: 0xf6b6 destAddr: 0x0 profile id: 0x104 cluster id: 0x12 new state: 00100010
2020-05-22T16:07:26.179Z zigbee-herdsman:deconz:frameParser payload: 24,48,10,85,0,33,1,0
2020-05-22T16:07:26.188Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true},"transactionSequenceNumber":48,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":85,"dataType":33,"attrData":1}]},"address":63158,"endpoint":6,"linkquality":140,"groupID":null}'
zigbee2mqtt:debug 2020-05-22 18:07:26: Received Zigbee message from 'bedroom_wall_switch', type 'attributeReport', cluster 'genMultistateInput', data '{"presentValue":1}' from endpoint 6 with groupID null
zigbee2mqtt:debug 2020-05-22 18:07:26: Skipping re-transmitted Xiaomi message

Here is the other switch I have and its working correctly. It is also working as a router but probably not for any other wall switch:

2020-05-22T16:09:34.059Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10101010
2020-05-22T16:09:34.078Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 125
2020-05-22T16:09:34.081Z zigbee-herdsman:deconz:frameParser DATA_INDICATION Response - seqNr. 125 srcAddr: 0x4710 destAddr: 0x0 profile id: 0x104 cluster id: 0x12 new state: 00100010
2020-05-22T16:09:34.081Z zigbee-herdsman:deconz:frameParser payload: 24,1,10,85,0,33,1,0
2020-05-22T16:09:34.083Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true},"transactionSequenceNumber":1,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":85,"dataType":33,"attrData":1}]},"address":18192,"endpoint":5,"linkquality":140,"groupID":null}'
zigbee2mqtt:debug 2020-05-22 18:09:34: Received Zigbee message from 'office_wall_switch', type 'attributeReport', cluster 'genMultistateInput', data '{"presentValue":1}' from endpoint 5 with groupID null
zigbee2mqtt:info  2020-05-22 18:09:34: MQTT publish: topic 'zigbee2mqtt/office_wall_switch', payload '{"power":3.95,"consumption":0.36,"temperature":30,"linkquality":140,"state_left":"OFF","state_right":"ON","state_undefined":"OFF","click":"left_single"}'
zigbee2mqtt:info  2020-05-22 18:09:34: MQTT publish: topic 'zigbee2mqtt/office_wall_switch', payload '{"power":3.95,"consumption":0.36,"temperature":30,"linkquality":140,"state_left":"OFF","state_right":"ON","state_undefined":"OFF","click":""}'
zigbee2mqtt:info  2020-05-22 18:09:34: MQTT publish: topic 'homeassistant/device_automation/0x00158d0004267a2d/click_left_single/config', payload '{"automation_type":"trigger","type":"click","subtype":"left_single","payload":"left_single","topic":"zigbee2mqtt/office_wall_switch/click","device":{"identifiers":["zigbee2mqtt_0x00158d0004267a2d"],"name":"office_wall_switch","sw_version":"Zigbee2mqtt 1.13.1","model":"Aqara double key wired wall switch (QBKG12LM)","manufacturer":"Xiaomi"}}'
zigbee2mqtt:info  2020-05-22 18:09:34: MQTT publish: topic 'zigbee2mqtt/office_wall_switch/click', payload 'left_single'

The map is not complete but it might help. The bedroom_wall_switch is being ignored, the office_wall_switch is working correctly. Other wall switches, routed through bedroom_wall_switch are also working OK:

Capture

Koenkk commented 4 years ago

Thanks for the good logging. Issues should be fixed in latest dev branch.

ArkadiuszNiemiec commented 4 years ago

Cheers! Thank you :)

XavierTolza commented 4 years ago

Hi! I'm still having exactly the same problem. Everything works fine for a few days, but at one point (I think after a raspi restart) all my Xiaomi devices get unresponsive. I could not get any response from any of my devices.

Details of my setup: Coordinator: CC2531 USB stick Computer: Raspberry Pi 4 Setup: Docker running on koenkk/zigbee2mqtt:latest-dev (digest 9a25ea759a2ef3b789fb0192e214df0408d7935381a8fd1dd8c71a55ddbe2f45) Version of Zigbee2Mqtt: 1.14.1-dev Coordinator version: 20190608

Here is my full debug log

zmqtt_1                 | 2020-07-12T06:15:04.049Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,33,68,129,162,189,6,0,194,98,2,1,0,86,0,163,33,110,0,0,13,28,95,17,126,10,0,0,16,1,0,0,16,0,194,98,29,115]
zmqtt_1                 | 2020-07-12T06:15:04.051Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,33,68,129,162,189,6,0,194,98,2,1,0,86,0,163,33,110,0,0,13,28,95,17,126,10,0,0,16,1,0,0,16,0,194,98,29,115]
zmqtt_1                 | 2020-07-12T06:15:04.051Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 33 - 2 - 4 - 129 - [162,189,6,0,194,98,2,1,0,86,0,163,33,110,0,0,13,28,95,17,126,10,0,0,16,1,0,0,16,0,194,98,29] - 115
zmqtt_1                 | 2020-07-12T06:15:04.052Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":48546,"clusterid":6,"srcaddr":25282,"srcendpoint":2,"dstendpoint":1,"wasbroadcast":0,"linkquality":86,"securityuse":0,"timestamp":7217571,"transseqnumber":0,"len":13,"data":{"type":"Buffer","data":[28,95,17,126,10,0,0,16,1,0,0,16,0]}}
zmqtt_1                 | 2020-07-12T06:15:04.054Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":true,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":126,"manufacturerCode":4447,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":16,"attrData":1},{"attrId":0,"dataType":16,"attrData":0}]},"address":25282,"endpoint":2,"linkquality":86,"groupID":48546}'
zmqtt_1                 | zigbee2mqtt:debug 2020-07-12 08:15:04: Received Zigbee message from 'Prise 1', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 2 with groupID 48546
zmqtt_1                 | 2020-07-12T06:15:04.060Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | zigbee2mqtt:debug 2020-07-12 08:15:04: Skipping re-transmitted Xiaomi message

And the wireshark sniffing (You can download the complete capture file here) image

Koenkk commented 4 years ago

@XavierTolza is controlling them from zigbee2mqtt still possible? (e.g. turning on/off?).

XavierTolza commented 4 years ago

I forgot to mention I am using home assistant as interface. Controlling from home assistant does not work. I tried to control my wall plug named "Prise 1". I pushed ON in zigbee2mqtt/Prise 1/set/state, it did not work. Here is the full log:

zmqtt_1                 | zigbee2mqtt:debug 2020-07-12 18:44:49: Received MQTT message on 'zigbee2mqtt/Prise 1/set/state' with data 'ON'
zmqtt_1                 | zigbee2mqtt:debug 2020-07-12 18:44:49: Publishing 'set' 'state' to 'Prise 1'
zmqtt_1                 | 2020-07-12T16:44:49.800Z zigbee-herdsman:controller:endpoint Command 0x00158d0001233ef6/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null})
zmqtt_1                 | 2020-07-12T16:44:49.801Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":25282,"destendpoint":1,"srcendpoint":1,"clusterid":6,"transid":10,"options":0,"radius":30,"len":3,"data":{"type":"Buffer","data":[1,6,1]}}
zmqtt_1                 | 2020-07-12T16:44:49.802Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,13,36,1,194,98,1,1,6,0,10,0,30,3,1,6,1,159]
zmqtt_1                 | 2020-07-12T16:44:49.816Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:49.816Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:49.817Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 1 - [0] - 100
zmqtt_1                 | 2020-07-12T16:44:49.817Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0}
zmqtt_1                 | 2020-07-12T16:44:49.817Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:50.301Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,1,10,45]
zmqtt_1                 | 2020-07-12T16:44:50.301Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,1,10,45]
zmqtt_1                 | 2020-07-12T16:44:50.302Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,1,10] - 45
zmqtt_1                 | 2020-07-12T16:44:50.302Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":1,"transid":10}
zmqtt_1                 | 2020-07-12T16:44:50.302Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:52.303Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":25282,"destendpoint":1,"srcendpoint":1,"clusterid":6,"transid":11,"options":0,"radius":30,"len":3,"data":{"type":"Buffer","data":[1,6,1]}}
zmqtt_1                 | 2020-07-12T16:44:52.304Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,13,36,1,194,98,1,1,6,0,11,0,30,3,1,6,1,158]
zmqtt_1                 | 2020-07-12T16:44:52.311Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:52.311Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:52.312Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 1 - [0] - 100
zmqtt_1                 | 2020-07-12T16:44:52.312Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0}
zmqtt_1                 | 2020-07-12T16:44:52.312Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:52.700Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,1,11,44]
zmqtt_1                 | 2020-07-12T16:44:52.701Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,1,11,44]
zmqtt_1                 | 2020-07-12T16:44:52.702Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,1,11] - 44
zmqtt_1                 | 2020-07-12T16:44:52.703Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":1,"transid":11}
zmqtt_1                 | 2020-07-12T16:44:52.704Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:54.708Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":25282,"destendpoint":1,"srcendpoint":1,"clusterid":6,"transid":12,"options":0,"radius":30,"len":3,"data":{"type":"Buffer","data":[1,6,1]}}
zmqtt_1                 | 2020-07-12T16:44:54.709Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,13,36,1,194,98,1,1,6,0,12,0,30,3,1,6,1,153]
zmqtt_1                 | 2020-07-12T16:44:54.720Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:54.720Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:54.721Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 1 - [0] - 100
zmqtt_1                 | 2020-07-12T16:44:54.721Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0}
zmqtt_1                 | 2020-07-12T16:44:54.722Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:55.000Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,1,12,43]
zmqtt_1                 | 2020-07-12T16:44:55.001Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,1,12,43]
zmqtt_1                 | 2020-07-12T16:44:55.001Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,1,12] - 43
zmqtt_1                 | 2020-07-12T16:44:55.003Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":1,"transid":12}
zmqtt_1                 | 2020-07-12T16:44:55.003Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:57.006Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":25282,"destendpoint":1,"srcendpoint":1,"clusterid":6,"transid":13,"options":0,"radius":30,"len":3,"data":{"type":"Buffer","data":[1,6,1]}}
zmqtt_1                 | 2020-07-12T16:44:57.006Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,13,36,1,194,98,1,1,6,0,13,0,30,3,1,6,1,152]
zmqtt_1                 | 2020-07-12T16:44:57.013Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:57.014Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:57.014Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 1 - [0] - 100
zmqtt_1                 | 2020-07-12T16:44:57.014Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0}
zmqtt_1                 | 2020-07-12T16:44:57.014Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:57.450Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,1,13,42]
zmqtt_1                 | 2020-07-12T16:44:57.450Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,1,13,42]
zmqtt_1                 | 2020-07-12T16:44:57.451Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,1,13] - 42
zmqtt_1                 | 2020-07-12T16:44:57.451Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":1,"transid":13}
zmqtt_1                 | 2020-07-12T16:44:57.452Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:59.453Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":25282,"destendpoint":1,"srcendpoint":1,"clusterid":6,"transid":14,"options":0,"radius":30,"len":3,"data":{"type":"Buffer","data":[1,6,1]}}
zmqtt_1                 | 2020-07-12T16:44:59.454Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,13,36,1,194,98,1,1,6,0,14,0,30,3,1,6,1,155]
zmqtt_1                 | 2020-07-12T16:44:59.468Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:59.468Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:44:59.469Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 1 - [0] - 100
zmqtt_1                 | 2020-07-12T16:44:59.469Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0}
zmqtt_1                 | 2020-07-12T16:44:59.470Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:44:59.840Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,1,14,41]
zmqtt_1                 | 2020-07-12T16:44:59.840Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,1,14,41]
zmqtt_1                 | 2020-07-12T16:44:59.840Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,1,14] - 41
zmqtt_1                 | 2020-07-12T16:44:59.841Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":1,"transid":14}
zmqtt_1                 | 2020-07-12T16:44:59.841Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:45:01.844Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":25282,"destendpoint":1,"srcendpoint":1,"clusterid":6,"transid":15,"options":0,"radius":30,"len":3,"data":{"type":"Buffer","data":[1,6,1]}}
zmqtt_1                 | 2020-07-12T16:45:01.845Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,13,36,1,194,98,1,1,6,0,15,0,30,3,1,6,1,154]
zmqtt_1                 | 2020-07-12T16:45:01.851Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:45:01.851Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,1,0,100]
zmqtt_1                 | 2020-07-12T16:45:01.852Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 1 - [0] - 100
zmqtt_1                 | 2020-07-12T16:45:01.852Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0}
zmqtt_1                 | 2020-07-12T16:45:01.852Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:45:02.165Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,1,15,40]
zmqtt_1                 | 2020-07-12T16:45:02.165Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,1,15,40]
zmqtt_1                 | 2020-07-12T16:45:02.165Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,1,15] - 40
zmqtt_1                 | 2020-07-12T16:45:02.166Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":1,"transid":15}
zmqtt_1                 | 2020-07-12T16:45:02.166Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
zmqtt_1                 | 2020-07-12T16:45:02.167Z zigbee-herdsman:controller:endpoint Command 0x00158d0001233ef6/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) failed (Data request failed with error: 'MAC channel access failure' (225))
zmqtt_1                 | zigbee2mqtt:error 2020-07-12 18:45:02: Publish 'set' 'state' to 'Prise 1' failed: 'Error: Command 0x00158d0001233ef6/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) failed (Data request failed with error: 'MAC channel access failure' (225))'
zmqtt_1                 | zigbee2mqtt:debug 2020-07-12 18:45:02: Error: Command 0x00158d0001233ef6/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) failed (Data request failed with error: 'MAC channel access failure' (225))
zmqtt_1                 |     at ZStackAdapter.<anonymous> (/app/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/zStackAdapter.js:644:27)
zmqtt_1                 |     at Generator.next (<anonymous>)
zmqtt_1                 |     at fulfilled (/app/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/zStackAdapter.js:5:58)
zmqtt_1                 | zigbee2mqtt:info  2020-07-12 18:45:02: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to 'Prise 1' failed: 'Error: Command 0x00158d0001233ef6/1 genOnOff.on({}, {\"timeout\":10000,\"disableResponse\":false,\"disableDefaultResponse\":false,\"direction\":0,\"srcEndpoint\":null,\"reservedBits\":0,\"manufacturerCode\":null,\"transactionSequenceNumber\":null}) failed (Data request failed with error: 'MAC channel access failure' (225))'","meta":{"friendly_name":"Prise 1"}}'

The wireshark screenshot: image And the full capture file

It took about 10sec before the last error message, during which zigbee-herdsman was sending/receiving packets several times. Looks like a problem with address resolution? But it used to work in the past, I tried with two other wall sockets, I had the same result.

XavierTolza commented 4 years ago

In case it might help, here is my configuration from zigbee2mqtt/bridge/config/devices/get

[
  {
    "ieeeAddr": "0x00124b001938a033",
    "type": "Coordinator",
    "networkAddress": 0,
    "friendly_name": "Coordinator",
    "softwareBuildID": "zStack12",
    "dateCode": "20190608",
    "lastSeen": 1594572814540
  },
  {
    "ieeeAddr": "0x00158d00015e86a1",
    "type": "EndDevice",
    "networkAddress": 18084,
    "model": "RTCGQ01LM",
    "vendor": "Xiaomi",
    "description": "MiJia human body movement sensor",
    "friendly_name": "Capteur mouvement",
    "manufacturerID": 4151,
    "manufacturerName": "LUMI",
    "powerSource": "Battery",
    "modelID": "lumi.sensor_motion",
    "lastSeen": 1593971569593
  },
  {
    "ieeeAddr": "0x00158d0001233ef6",
    "type": "Router",
    "networkAddress": 25282,
    "model": "ZNCZ02LM",
    "vendor": "Xiaomi",
    "description": "Mi power plug ZigBee",
    "friendly_name": "Prise 1",
    "manufacturerID": 4447,
    "manufacturerName": "LUMI",
    "powerSource": "Mains (single phase)",
    "modelID": "lumi.plug",
    "hardwareVersion": 18,
    "dateCode": "04-20-2018",
    "lastSeen": 1594536652931
  },
  {
    "ieeeAddr": "0x00158d00013e7f7d",
    "type": "Router",
    "networkAddress": 49277,
    "model": "ZNCZ02LM",
    "vendor": "Xiaomi",
    "description": "Mi power plug ZigBee",
    "friendly_name": "Prise 2",
    "manufacturerID": 4447,
    "manufacturerName": "LUMI",
    "powerSource": "Mains (single phase)",
    "modelID": "lumi.plug",
    "hardwareVersion": 18,
    "dateCode": "04-20-2018",
    "lastSeen": 1593533632038
  },
  {
    "ieeeAddr": "0x00158d00021333c2",
    "type": "EndDevice",
    "networkAddress": 48546,
    "model": "WXKG02LM",
    "vendor": "Xiaomi",
    "description": "Aqara double key wireless wall switch",
    "friendly_name": "Interrupteur 1",
    "manufacturerID": 4151,
    "manufacturerName": "LUMI",
    "powerSource": "Battery",
    "modelID": "lumi.sensor_86sw2",
    "lastSeen": 1593801364207
  },
  {
    "ieeeAddr": "0x00158d00023a86a2",
    "type": "EndDevice",
    "networkAddress": 8081,
    "model": "WXKG02LM",
    "vendor": "Xiaomi",
    "description": "Aqara double key wireless wall switch",
    "friendly_name": "Interrupteur 2",
    "manufacturerID": 4151,
    "manufacturerName": "LUMI",
    "powerSource": "Battery",
    "modelID": "lumi.sensor_86sw2",
    "hardwareVersion": 20,
    "softwareBuildID": "3000-0001",
    "dateCode": "20170411",
    "lastSeen": 1593533310941
  },
  {
    "ieeeAddr": "0x00158d00013e4c4d",
    "type": "Router",
    "networkAddress": 4896,
    "model": "ZNCZ02LM",
    "vendor": "Xiaomi",
    "description": "Mi power plug ZigBee",
    "friendly_name": "Prise noire",
    "manufacturerID": 4447,
    "manufacturerName": "LUMI",
    "powerSource": "Mains (single phase)",
    "modelID": "lumi.plug",
    "hardwareVersion": 18,
    "softwareBuildID": "3000-0001",
    "dateCode": "04-20-2018",
    "lastSeen": 1594501926264
  },
  {
    "ieeeAddr": "0x00158d0001a5e1f0",
    "type": "EndDevice",
    "networkAddress": 35600,
    "model": "MCCGQ01LM",
    "vendor": "Xiaomi",
    "description": "MiJia door & window contact sensor",
    "friendly_name": "Capteur porte 1",
    "manufacturerID": 4151,
    "manufacturerName": "LUMI",
    "powerSource": "Battery",
    "modelID": "lumi.sensor_magnet",
    "lastSeen": 1593461072712
  },
  {
    "ieeeAddr": "0x00158d00014d6072",
    "type": "EndDevice",
    "networkAddress": 19303,
    "model": "MCCGQ01LM",
    "vendor": "Xiaomi",
    "description": "MiJia door & window contact sensor",
    "friendly_name": "Capteur porte 2",
    "manufacturerID": 4151,
    "manufacturerName": "LUMI",
    "powerSource": "Battery",
    "modelID": "lumi.sensor_magnet",
    "lastSeen": 1594134401881
  }
]
Koenkk commented 4 years ago

MAC channel access failure' (225)) is usually occurred because there is too much interference, is your CC2531 connected through a USB extension cable?

XavierTolza commented 4 years ago

Yes! I saw some issues about that and I tried it with a 30cm cable (see setup picture behind). Should I try a longer cable? IMG_20200714_203129

Koenkk commented 4 years ago

That should be enough, does it work when having the device close to the coordinator?

XavierTolza commented 4 years ago

Unfortunately not. I tried with the button 1m await, still the same error. I don't think it's an RF issue since it worked perfectly for a few days and went off after a reboot.

XavierTolza commented 4 years ago

I finally had some time to spend on it and I think I understood the problem! The Skipping re-transmitted Xiaomi message is caused by this piece of code :

        /**
         * Don't handle re-transmitted Xiaomi messages.
         * https://github.com/Koenkk/zigbee2mqtt/issues/1238
         *
         * Some Xiaomi router devices re-transmit messages from Xiaomi end devices.
         * The source address of these message is set to the one of the Xiaomi router.
         * Therefore it looks like if the message came from the Xiaomi router, while in
         * fact it came from the end device.
         * Handling these message would result in false state updates.
         * The group ID attribute of these message defines the source address of the end device.
         * As the same message is also received directly from the end device, it makes no sense
         * to handle these messages.
         */
        const hasGroupID = data.hasOwnProperty('groupID') && !!data.groupID;
        if (utils.isXiaomiDevice(data.device) && utils.isRouter(data.device) && hasGroupID) {
            logger.debug('Skipping re-transmitted Xiaomi message');
            return false;
        }

Which was created during this issue. It looks like Xiaomi routers do not have a standard behaviour when forwarding messages, which leads to z2m receiving twice the message, once from the end device, and from the router with the end device id in the groupid. Thus, you disabled messages forwarded from the router. I guess it's fine when both messages are received, but in my case I think the end device is not directly received as it is further away from the coordinator. I started z2m on another computer with another CC2531, closer to both the end device and the router and it worked fine.

Shouldn't xiaomi routing process be fullly implemented to support their routers? There might be a way to de-duplicate messages as the Xiaomi Aqara gateway does not suffer from duplicated messages.

Koenkk commented 4 years ago

The question is how to de-duplicate, they way they forward this is really hack and not zigbee compliant in any way. We could do something with a timeout but it's a solution I do not prefer.

XavierTolza commented 4 years ago

I saw some comment in the code about "debouncing". Isn't that appropriate? Otherwise, what about some kind of XiaomiDeboucer class, keeping in memory the last message from each sensor and the reception time. It could be called in shouldProcess function, and if the packet if different than the last packet (the question is how do you define "different") returns the packet, modified with the end device id at the right place so the packet can follow normal processing afterward.

Koenkk commented 4 years ago

I'm wondering if the Xiaomi bridge does the filtering based on wether it already received that transactionID. Can you provide the log when changing the code you mentioned in https://github.com/Koenkk/zigbee2mqtt/issues/3592#issuecomment-669745722 to

        if (utils.isXiaomiDevice(data.device)) {
            console.log(`XIAOMI MESSAGE, RECEIVED FROM: '${resolvedEntity.name}' (${data.device.type}), GROUPID: '${data.groupID}', transaction: '${data.meta.zclTransactionSequenceNumber}'`);
        }
        const hasGroupID = data.hasOwnProperty('groupID') && !!data.groupID;
        if (utils.isXiaomiDevice(data.device) && data.device.type === 'Router' && hasGroupID) {
            logger.debug('Skipping re-transmitted Xiaomi message');
            return false;
        }
XavierTolza commented 4 years ago

I had some trouble doing so because I added some devices and everything suddenly worked again. After a while, the bug is back. Here's the log :

zigbee2mqtt:debug 2020-08-12 08:15:32: Received Zigbee message from 'Prise rouge', type 'read', cluster 'genTime', data '["time"]' from endpoint 1 with groupID 42013
XIAOMI MESSAGE, RECEIVED FROM: 'Prise rouge' (Router), GROUPID: '42013', transaction: '75'
zigbee2mqtt:debug 2020-08-12 08:15:32: Skipping re-transmitted Xiaomi message
zigbee2mqtt:debug 2020-08-12 08:16:34: Received Zigbee message from 'Prise rouge', type 'read', cluster 'genTime', data '["time"]' from endpoint 1 with groupID 42013
XIAOMI MESSAGE, RECEIVED FROM: 'Prise rouge' (Router), GROUPID: '42013', transaction: '76'
zigbee2mqtt:debug 2020-08-12 08:16:34: Skipping re-transmitted Xiaomi message
zigbee2mqtt:debug 2020-08-12 08:17:09: Received Zigbee message from 'Prise rouge', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":3300,"3":25,"5":22,"8":13850,"10":38387,"100":0,"101":0,"110":0,"111":255,"153":0,"155":0}}' from endpoint 1 with groupID 42013
XIAOMI MESSAGE, RECEIVED FROM: 'Prise rouge' (Router), GROUPID: '42013', transaction: '77'
zigbee2mqtt:debug 2020-08-12 08:17:09: Skipping re-transmitted Xiaomi message

42013 is a wall switch (end device). It looks like the transaction is indeed a good marker. If it is of any help, I also dumped a full data object from an end device, when the transmission was direct and the same device when the transmission was relayed by a xiaomi router

Koenkk commented 4 years ago

@XavierTolza can you try replacing the entire content of receive.js with https://raw.githubusercontent.com/Koenkk/zigbee2mqtt/issue_3592/lib/extension/receive.js and see if that fixes the issue?

XavierTolza commented 4 years ago

Seems better! :) It looks like I can receive updates from the end devices. Here is a log where I turned on and off a wall switch (Interrupteur mural 1 with address 42013):

zigbee2mqtt:debug 2020-08-12 15:32:35: Received Zigbee message from 'Prise rouge', type 'attributeReport', cluster 'genOnOff', data '{"61440":61086987,"onOff":1}' from endpoint 2 with groupID 42013
zigbee2mqtt:debug 2020-08-12 15:32:35: Handling re-transmitted Xiaomi message
zigbee2mqtt:info  2020-08-12 15:32:35: MQTT publish: topic 'zigbee2mqtt/Interrupteur mural 1', payload '{"state":"ON","linkquality":55,"elapsed":219924,"last_seen":1597238752398}'
zigbee2mqtt:debug 2020-08-12 15:32:38: Received Zigbee message from 'Prise rouge', type 'attributeReport', cluster 'genOnOff', data '{"61440":61086987,"onOff":0}' from endpoint 2 with groupID 42013
zigbee2mqtt:debug 2020-08-12 15:32:38: Handling re-transmitted Xiaomi message
zigbee2mqtt:info  2020-08-12 15:32:38: MQTT publish: topic 'zigbee2mqtt/Interrupteur mural 1', payload '{"state":"OFF","linkquality":57,"elapsed":2966,"last_seen":1597238752398}'

But when I try to switch it from home assistant, I get an error:

zigbee2mqtt:debug 2020-08-12 15:42:52: Received MQTT message on 'zigbee2mqtt/Interrupteur mural 1/set' with data 'ON'
zigbee2mqtt:debug 2020-08-12 15:42:52: Publishing 'set' 'state' to 'Interrupteur mural 1'
zigbee2mqtt:error 2020-08-12 15:42:56: Publish 'set' 'state' to 'Interrupteur mural 1' failed: 'Error: Command 0x00158d00047d338c/2 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) failed (Data request failed with error: 'No network route' (205))'
zigbee2mqtt:debug 2020-08-12 15:42:56: Error: Command 0x00158d00047d338c/2 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) failed (Data request failed with error: 'No network route' (205))
    at ZStackAdapter.<anonymous> (/home/xavier/PycharmProjects/zigbee2mqtt/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/zStackAdapter.js:657:27)
    at Generator.next (<anonymous>)
    at fulfilled (/home/xavier/PycharmProjects/zigbee2mqtt/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/zStackAdapter.js:24:58)
zigbee2mqtt:info  2020-08-12 15:42:56: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to 'Interrupteur mural 1' failed: 'Error: Command 0x00158d00047d338c/2 genOnOff.on({}, {\"timeout\":10000,\"disableResponse\":false,\"disableDefaultResponse\":false,\"direction\":0,\"srcEndpoint\":null,\"reservedBits\":0,\"manufacturerCode\":null,\"transactionSequenceNumber\":null}) failed (Data request failed with error: 'No network route' (205))'","meta":{"friendly_name":"Interrupteur mural 1"}}'
Koenkk commented 4 years ago

@XavierTolza

XavierTolza commented 4 years ago

After a week of testing, it looks like everything is working fine! So it looks like the bug is solved :)

Koenkk commented 4 years ago

@XavierTolza great, implemented the fix.

Changes will be available in the latest dev branch in a few hours (https://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html)

to4ko commented 4 years ago

@Koenkk

i foind that we are still missing messages from xiaomi ends (in this case from contact_seat_t and rocker_hood_k) thru xiaomi routers - aqara sockets. can this fix be implemented to them as well(QBCZ11LM)?

Also there was kind of test done and looks like this two guys (QBKG11LM QBKG12LM) acting same way and Aqara relay too. So kind of general xiomi repeaters issue.

image

Koenkk commented 4 years ago

@to4ko the fix I implemented is not device specific and should work for all.

Can you provide the debug logging of your problem?

to4ko commented 4 years ago

@Koenkk

this is what i get - Mi motion sensor connected via Aqara Socket. There was a movement (i entered the storage my storage room)

debug 2020-09-26 19:56:39: Received Zigbee message from 'Socket_PC_MB', type 'attributeReport', cluster 'genAnalogInput', data '{"presentValue":39.91999816894531}' from endpoint 2 with groupID 0
info  2020-09-26 19:56:39: MQTT publish: topic 'zigbee2mqtt/Socket_PC_MB', payload '{"consumption":768.61,"device":{"applicationVersion":31,"dateCode":"10-13-2017","friendlyName":"Socket_PC_MB","hardwareVersion":18,"ieeeAddr":"0x00158d0002467773","manufacturerID":4447,"manufacturerName":"LUMI","model":"QBCZ11LM","networkAddress":52543,"powerSource":"Mains (single phase)","stackVersion":2,"type":"Router","zclVersion":1},"elapsed":33284,"last_seen":1601139399686,"linkquality":57,"power":39.92,"power_outage_memory":true,"state":"ON","temperature":29,"voltage":null}'
debug 2020-09-26 19:56:41: Received Zigbee message from 'Socket_PC_MB', type 'attributeReport', cluster 'genAnalogInput', data '{"presentValue":43.25}' from endpoint 2 with groupID 0
info  2020-09-26 19:56:41: MQTT publish: topic 'zigbee2mqtt/Socket_PC_MB', payload '{"consumption":768.61,"device":{"applicationVersion":31,"dateCode":"10-13-2017","friendlyName":"Socket_PC_MB","hardwareVersion":18,"ieeeAddr":"0x00158d0002467773","manufacturerID":4447,"manufacturerName":"LUMI","model":"QBCZ11LM","networkAddress":52543,"powerSource":"Mains (single phase)","stackVersion":2,"type":"Router","zclVersion":1},"elapsed":1485,"last_seen":1601139401171,"linkquality":55,"power":43.25,"power_outage_memory":true,"state":"ON","temperature":29,"voltage":null}'
debug 2020-09-26 19:56:44: Received Zigbee message from 'Motion_St', type 'attributeReport', cluster 'genBasic', data '{"65282":[{"elmType":16,"elmVal":1},{"elmType":33,"elmVal":3035},{"elmType":33,"elmVal":12712},{"elmType":36,"elmVal":[0,1]},{"elmType":33,"elmVal":14},{"elmType":32,"elmVal":98}]}' from endpoint 1 with groupID 0
info  2020-09-26 19:56:44: MQTT publish: topic 'zigbee2mqtt/Motion_St', payload '{"battery":100,"device":{"applicationVersion":11,"friendlyName":"Motion_St","ieeeAddr":"0x00158d0001aea602","manufacturerID":4151,"manufacturerName":"LUMI","model":"RTCGQ01LM","networkAddress":36684,"powerSource":"Battery","type":"EndDevice"},"elapsed":1247605,"last_seen":1601139404062,"linkquality":55,"occupancy":false,"voltage":3035}'
debug 2020-09-26 19:56:44: Received Zigbee message from 'Motion_St', type 'attributeReport', cluster 'genBasic', data '{"modelId":"lumi.sensor_motion"}' from endpoint 1 with groupID 0
Koenkk commented 4 years ago

@to4ko looks to be the same as https://github.com/Koenkk/zigbee2mqtt/issues/4459 , we need to figure out what in the genBasic messages means occupancy. Please provide the same as https://github.com/Koenkk/zigbee2mqtt/issues/4459#issuecomment-699076267