Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Warnings with Aqara occupancy sensor #1238

Closed
milakov opened this issue Mar 11, 2019 · 36 comments
Closed

Warnings with Aqara occupancy sensor #1238

milakov opened this issue Mar 11, 2019 · 36 comments
Milestone

Comments

@milakov
Copy link

milakov commented Mar 11, 2019

Hi, I am seeing warnings for ZNCZ02LM occasionally with recent dev:

  zigbee2mqtt:debug 3/11/2019, 6:15:25 PM Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.plug' (0x00158d0002561266)
  zigbee2mqtt:warn 3/11/2019, 6:15:25 PM No converter available for 'ZNCZ02LM' with cid 'msOccupancySensing', type 'attReport' and data '{"cid":"msOccupancySensing","data":{"occupancy":1}}'
  zigbee2mqtt:warn 3/11/2019, 6:15:25 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
  zigbee2mqtt:debug 3/11/2019, 6:15:25 PM Received zigbee message of type 'attReport' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":93}}' of device 'lumi.plug' (0x00158d0002561266)
  zigbee2mqtt:warn 3/11/2019, 6:15:25 PM No converter available for 'ZNCZ02LM' with cid 'msIlluminanceMeasurement', type 'attReport' and data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":93}}'
  zigbee2mqtt:warn 3/11/2019, 6:15:25 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
  zigbee2mqtt:debug 3/11/2019, 6:15:34 PM Received zigbee message of type 'attReport' with data '{"cid":"genAnalogInput","data":{"presentValue":0}}' of device 'lumi.plug' (0x00158d00024f2e59)
@Fabiancrg
Copy link

Hello
Did you upgrade recently zigbee2mqtt ? If yes, which version are you running ? With which coordinator firmware ?

@Fabiancrg
Copy link

I am asking this because I had the same kind of message with Aqara LED bulb ZNLDP12LM, they are routers like the Xiaomi plugs ZNCZ02LM.
I had the follwing errors:
3/11/2019, 8:20:07 PM - harn: No converter available for 'ZNLDP12LM' with cid 'msOccupancySensing', type 'attReport' and data '{"cid":"msOccupancySensing","data":{"occupancy":1}}'

I had the same message with pressure, humidity or temperature:
warn: No converter available for 'ZNLDP12LM' with cid 'msTemperatureMeasurement', type 'devChange' and data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2028}}'
warn: No converter available for 'ZNLDP12LM' with cid 'msRelativeHumidity', type 'devChange' and data '{"cid":"msRelativeHumidity","data":{"measuredValue":4562}}'
warn: No converter available for 'ZNLDP12LM' with cid 'msPressureMeasurement', type 'devChange' and data '{"cid":"msPressureMeasurement","data":{"16":10094,"20":-1,"measuredValue":1009}}'

These warning disappeared after deleting each ZNLDP12LM and re-paring them.
But apparently I still have other with occupency like you since I upgraded to zigbee2mqtt 1.2.1 and firmware 20190223.

@Fabiancrg
Copy link

After a few hours, I can see that all errors are back, I got plenty of these too now:

3/12/2019, 4:59:27 AM - warn: No converter available for 'ZNLDP12LM' with cid 'msRelativeHumidity', type 'attReport' and data '{"cid":"msRelativeHumidity","data":{"measuredValue":5583}}'
3/12/2019, 4:59:27 AM - warn: No converter available for 'ZNLDP12LM' with cid 'msPressureMeasurement', type 'attReport' and data '{"cid":"msPressureMeasurement","data":{"16":10090,"20":-1,"measuredValue":1009}}'
3/12/2019, 5:08:22 AM - warn: No converter available for 'ZNLDP12LM' with cid 'msTemperatureMeasurement', type 'attReport' and data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":1765}}'

@milakov
Copy link
Author

milakov commented Mar 12, 2019

@Fabiancrg I am using recent dev version, firmware 20190223

But I think I have figured out why do we see those messages. z2m thinks the source of those packets (originally coming from switches, occupancy sensors, temperature/humidity sensors) is Xiaomi smart plug! Obviously, ZNCZ02LM doesn't support those attributes. Those messages come from correct devices as well. I feel like the same message comes to coordinator two ways (directly and through the smart plug, which is a router). When when it comes via the router z2m thinks the source is the router, which is false.

3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2815}}' of device 'lumi.weather' (0x00158d0002775e09)
3/12/2019, 1:57:28 AM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d0002775e09', payload '{"temperature":28.2,"linkquality":86,"last_seen":"2019-03-12T01:57:28+03:00","humidity":33,"pressure":978.3,"battery":100,"voltage":3025}'
3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'devChange' with data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2815}}' of device 'lumi.weather' (0x00158d0002775e09)
3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2815}}' of device 'lumi.plug' (0x00158d0002561266)
3/12/2019, 1:57:28 AM - warn: No converter available for 'ZNCZ02LM' with cid 'msTemperatureMeasurement', type 'attReport' and data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2815}}'
3/12/2019, 1:57:28 AM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msRelativeHumidity","data":{"measuredValue":3286}}' of device 'lumi.plug' (0x00158d0002561266)
3/12/2019, 1:57:28 AM - warn: No converter available for 'ZNCZ02LM' with cid 'msRelativeHumidity', type 'attReport' and data '{"cid":"msRelativeHumidity","data":{"measuredValue":3286}}'
3/12/2019, 1:57:28 AM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msPressureMeasurement","data":{"16":9785,"20":-1,"measuredValue":978}}' of device 'lumi.plug' (0x00158d0002561266)
3/12/2019, 1:57:28 AM - warn: No converter available for 'ZNCZ02LM' with cid 'msPressureMeasurement', type 'attReport' and data '{"cid":"msPressureMeasurement","data":{"16":9785,"20":-1,"measuredValue":978}}'
3/12/2019, 1:57:28 AM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msRelativeHumidity","data":{"measuredValue":3286}}' of device 'lumi.weather' (0x00158d0002775e09)
3/12/2019, 1:57:28 AM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d0002775e09', payload '{"temperature":28.2,"linkquality":84,"last_seen":"2019-03-12T01:57:28+03:00","humidity":32.9,"pressure":978.3,"battery":100,"voltage":3025}'
3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msPressureMeasurement","data":{"16":9785,"20":-1,"measuredValue":978}}' of device 'lumi.weather' (0x00158d0002775e09)
3/12/2019, 1:57:28 AM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d0002775e09', payload '{"temperature":28.2,"linkquality":84,"last_seen":"2019-03-12T01:57:28+03:00","humidity":32.9,"pressure":978,"battery":100,"voltage":3025}'
3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'devChange' with data '{"cid":"msRelativeHumidity","data":{"measuredValue":3286}}' of device 'lumi.weather' (0x00158d0002775e09)
3/12/2019, 1:57:28 AM - debug: Received zigbee message of type 'devChange' with data '{"cid":"msPressureMeasurement","data":{"16":9785}}' of device 'lumi.weather' (0x00158d0002775e09)

and

3/12/2019, 11:46:31 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":36}}' of device 'lumi.plug' (0x00158d0002561266)
3/12/2019, 11:46:31 AM - warn: No converter available for 'ZNCZ02LM' with cid 'msIlluminanceMeasurement', type 'attReport' and data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":36}}'
3/12/2019, 11:46:31 AM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/12/2019, 11:46:31 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.plug' (0x00158d0002561266)
3/12/2019, 11:46:31 AM - warn: No converter available for 'ZNCZ02LM' with cid 'msOccupancySensing', type 'attReport' and data '{"cid":"msOccupancySensing","data":{"occupancy":1}}'
3/12/2019, 11:46:31 AM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/12/2019, 11:46:31 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":36}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c070e)
3/12/2019, 11:46:31 AM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d00029c070e', payload '{"illuminance":36,"linkquality":39,"last_seen":"2019-03-12T11:46:31+03:00","occupancy":false,"battery":100,"voltage":3065}'
3/12/2019, 11:46:31 AM - debug: Received zigbee message of type 'devChange' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":36}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c070e)
3/12/2019, 11:46:31 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c070e)
3/12/2019, 11:46:31 AM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d00029c070e', payload '{"illuminance":36,"linkquality":39,"last_seen":"2019-03-12T11:46:31+03:00","occupancy":true,"battery":100,"voltage":3065}'

@milakov
Copy link
Author

milakov commented Mar 12, 2019

I managed to sniff it.

First, here is the log:

  zigbee2mqtt:debug 3/12/2019, 6:00:49 PM Received zigbee message of type 'attReport' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":93}}' of device 'lumi.plug' (0x00158d0002561266)
  zigbee2mqtt:warn 3/12/2019, 6:00:49 PM No converter available for 'ZNCZ02LM' with cid 'msIlluminanceMeasurement', type 'attReport' and data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":93}}'
  zigbee2mqtt:warn 3/12/2019, 6:00:49 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
  zigbee2mqtt:debug 3/12/2019, 6:00:49 PM Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c0149)
  zigbee2mqtt:info 3/12/2019, 6:00:49 PM MQTT publish: topic 'zigbee2mqtt/0x00158d00029c0149', payload '{"illuminance":93,"linkquality":68,"last_seen":"2019-03-12T18:00:49+03:00","occupancy":true,"battery":100,"voltage":3035}'
  zigbee2mqtt:debug 3/12/2019, 6:00:49 PM Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.plug' (0x00158d0002561266)
  zigbee2mqtt:warn 3/12/2019, 6:00:49 PM No converter available for 'ZNCZ02LM' with cid 'msOccupancySensing', type 'attReport' and data '{"cid":"msOccupancySensing","data":{"occupancy":1}}'
  zigbee2mqtt:warn 3/12/2019, 6:00:49 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.

You can see that occupancy sensor sends illuminance and occupancy update, but the same update is received from smart plug as well. Here is the sniffer screenshot:
Снимок
You can see packets from occupancy sensor (0x4cb2) to the coordinator via smart plug (0xa6f8) (red color).
You can also see smart plug broadcasting attribute report with group ID set to the ID of the occupancy sensor (blue color), and other routers broadcast as well. Group is always set to 0x4cb2 (occupancy sensor) in those broadcasts. Honestly, I don't know yet if it is a valid behaviour.

@Koenkk
Copy link
Owner

Koenkk commented Mar 12, 2019

It would be interesting to see if this is always the case (group id 0x4cb2), if that's indeed the case when can add some logic to ignore these messages.

@milakov
Copy link
Author

milakov commented Mar 12, 2019

I will try tomorrow with some other sensor to see if the smart plug broadcasts its message the same way.

@milakov
Copy link
Author

milakov commented Mar 13, 2019

Got it for the temperature/humidity/pressure sensor now (0x06a1):

Снимок

I observe correlation between availability_timeout and these messages. I had availability_timeout disabled for almost a day and no such warnings in the log. I switched it on (set to 60 seconds), and I got the warning in 10 minutes.

@Fabiancrg
Copy link

@milakov On my side, I had to reboot Z2M several times today as I am trying to add a unsupported device. Last time I restarted it was 3 hours ago and since no message anymore (except the ones I am expecting from my new device).
I don't think I have this availability_timeout set, don't know if it is enabled or disabled by default.

@Koenkk
Copy link
Owner

Koenkk commented Mar 13, 2019

As there doesn't seem to be a consistent way to ignore these, I've added ignore converters.

These messages shouldn't appear anymore in the latest dev.

@milakov
Copy link
Author

milakov commented Mar 13, 2019

@Koenkk Do you have an idea if those messages from the smart plug are valid ones? Is it Ok for the router to broadcast end-device attribute report with the only way to specify that end device through group id?

@milakov
Copy link
Author

milakov commented Mar 13, 2019

My concern here is that it coud broadcast some other device attributes this way and if the code doesn't check for the group then it could update this smart plug attributes, wrongly.

@Koenkk
Copy link
Owner

Koenkk commented Mar 14, 2019

@milakov this looks to be a hacky way of using zigbee of Xiaomi, I will check if we can add the group so we can check this.

Koenkk added a commit that referenced this issue Mar 15, 2019
@Koenkk
Copy link
Owner

Koenkk commented Mar 15, 2019

Can you update to the latest zigbee2mqtt dev and provide the debug logging of these messages?

@Koenkk Koenkk added this to the 1.3 milestone Mar 15, 2019
@Fabiancrg
Copy link

@Koenkk As I have just sent you some logs for my Heiman remote and also get the same messages in the log as milakov, here is the debug message using the dev branch:

serialport/bindings/poller received "readable" +8s serialport/binding-abstract read +8s serialport/bindings/unixRead Starting read +8s serialport/bindings/unixRead Finished read 12 bytes +0ms serialport/stream binding.read finished +8s cc-znp { sof: 254, cc-znp len: 7, cc-znp type: 'AREQ', cc-znp subsys: 'ZDO', cc-znp cmd: 'srcRtgInd', cc-znp payload: cc-znp { dstaddr: 25589, cc-znp relaycount: 2, cc-znp relaylist: <Buffer 69 38 0e fc> }, cc-znp fcs: 177, cc-znp csum: 177 } +8s serialport/stream _read reading +3ms serialport/binding-abstract read +3ms serialport/bindings/unixRead Starting read +3ms cc-znp:AREQ <-- ZDO:srcRtgInd, { dstaddr: 25589, relaycount: 2, relaylist: <Buffer 69 38 0e fc> } +8s zigbee-shepherd:msgHdlr IND <-- ZDO:srcRtgInd +8s serialport/bindings/unixRead waiting for readable because of code: EAGAIN +0ms serialport/bindings/poller Polling for "readable" +4ms serialport/bindings/poller received "readable" +3ms serialport/binding-abstract read +4ms serialport/bindings/unixRead Starting read +4ms serialport/bindings/unixRead Finished read 32 bytes +1ms serialport/stream binding.read finished +5ms cc-znp { sof: 254, cc-znp len: 27, cc-znp type: 'AREQ', cc-znp subsys: 'AF', cc-znp cmd: 'incomingMsg', cc-znp payload: cc-znp { groupid: 0, cc-znp clusterid: 1, cc-znp srcaddr: 25589, cc-znp srcendpoint: 1, cc-znp dstendpoint: 1, cc-znp wasbroadcast: 0, cc-znp linkquality: 34, cc-znp securityuse: 0, cc-znp timestamp: 3444123, cc-znp transseqnumber: 0, cc-znp len: 7, cc-znp data: <Buffer 18 00 0a 21 00 20 b9> }, cc-znp fcs: 13, cc-znp csum: 13 } +8ms serialport/stream _read reading +3ms serialport/binding-abstract read +4ms serialport/bindings/unixRead Starting read +3ms cc-znp:AREQ <-- AF:incomingMsg, { groupid: 0, clusterid: 1, srcaddr: 25589, srcendpoint: 1, dstendpoint: 1, wasbroadcast: 0, linkquality: 34, securityuse: 0, timestamp: 3444123, transseqnumber: 0, len: 7, data: <Buffer 18 00 0a 21 00 20 b9> } +8ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: {"groupid":0,"clusterid":1,"srcaddr":25589,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":34,"securityuse":0,"timestamp":3444123,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,0,10,33,0,32,185]}} +13s zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +10ms serialport/bindings/unixRead waiting for readable because of code: EAGAIN +2ms serialport/bindings/poller Polling for "readable" +6ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: {"groupid":0,"clusterid":1,"srcaddr":25589,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":34,"securityuse":0,"timestamp":3444123,"transseqnumber":0,"len":7,"data":{"0":24,"1":0,"2":10,"3":33,"4":0,"5":32,"6":185},"zclMsg":{"frameCntl":{"frameType":0,"manufSpec":0,"direction":1,"disDefaultRsp":1},"manufCode":0,"seqNum":0,"cmdId":"report","payload":[{"attrId":33,"dataType":32,"attrData":185}]}} +2ms zigbee2mqtt:debug 3/15/2019, 7:54:00 PM Received zigbee message of type 'attReport' with data '{"cid":"genPowerCfg","data":{"batteryPercentageRemaining":185}}' of device 'RC_V14' (0x005043c953287154) zigbee2mqtt:warn 3/15/2019, 7:54:00 PM Device with modelID 'RC_V14' is not supported. zigbee2mqtt:warn 3/15/2019, 7:54:00 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html zigbee2mqtt:debug 3/15/2019, 7:54:00 PM Received zigbee message of type 'devChange' with data '{"cid":"genPowerCfg","data":{"batteryPercentageRemaining":185}}' of device 'RC_V14' (0x005043c953287154) zigbee2mqtt:warn 3/15/2019, 7:54:00 PM Device with modelID 'RC_V14' is not supported. zigbee2mqtt:warn 3/15/2019, 7:54:00 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html serialport/bindings/poller received "readable" +28ms serialport/binding-abstract read +30ms serialport/bindings/unixRead Starting read +28ms serialport/bindings/unixRead Finished read 31 bytes +0ms serialport/stream binding.read finished +30ms cc-znp { sof: 254, cc-znp len: 26, cc-znp type: 'AREQ', cc-znp subsys: 'AF', cc-znp cmd: 'incomingMsg', cc-znp payload: cc-znp { groupid: 0, cc-znp clusterid: 1281, cc-znp srcaddr: 25589, cc-znp srcendpoint: 1, cc-znp dstendpoint: 1, cc-znp wasbroadcast: 0, cc-znp linkquality: 34, cc-znp securityuse: 0, cc-znp timestamp: 3444162, cc-znp transseqnumber: 0, cc-znp len: 6, cc-znp data: <Buffer 11 00 00 01 00 ff> }, cc-znp fcs: 20, cc-znp csum: 20 } +32ms serialport/stream _read reading +1ms serialport/binding-abstract read +2ms serialport/bindings/unixRead Starting read +2ms cc-znp:AREQ <-- AF:incomingMsg, { groupid: 0, clusterid: 1281, srcaddr: 25589, srcendpoint: 1, dstendpoint: 1, wasbroadcast: 0, linkquality: 34, securityuse: 0, timestamp: 3444162, transseqnumber: 0, len: 6, data: <Buffer 11 00 00 01 00 ff> } +32ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: {"groupid":0,"clusterid":1281,"srcaddr":25589,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":34,"securityuse":0,"timestamp":3444162,"transseqnumber":0,"len":6,"data":{"type":"Buffer","data":[17,0,0,1,0,255]}} +30ms zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +33ms serialport/bindings/unixRead waiting for readable because of code: EAGAIN +4ms serialport/bindings/poller Polling for "readable" +6ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: {"groupid":0,"clusterid":1281,"srcaddr":25589,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":34,"securityuse":0,"timestamp":3444162,"transseqnumber":0,"len":6,"data":{"0":17,"1":0,"2":0,"3":1,"4":0,"5":255},"zclMsg":{"frameCntl":{"frameType":1,"manufSpec":0,"direction":0,"disDefaultRsp":1},"manufCode":0,"seqNum":0,"cmdId":"arm","payload":{"armmode":1}}} +4ms zigbee2mqtt:debug 3/15/2019, 7:54:00 PM Received zigbee message of type 'cmdArm' with data '{"cid":"ssIasAce","data":{"armmode":1}}' of device 'RC_V14' (0x005043c953287154) zigbee2mqtt:warn 3/15/2019, 7:54:00 PM Device with modelID 'RC_V14' is not supported. zigbee2mqtt:warn 3/15/2019, 7:54:00 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html serialport/bindings/poller received "readable" +2ms serialport/binding-abstract read +6ms serialport/bindings/unixRead Starting read +2ms serialport/bindings/unixRead Finished read 34 bytes +0ms serialport/stream binding.read finished +7ms cc-znp { sof: 254, cc-znp len: 29, cc-znp type: 'AREQ', cc-znp subsys: 'AF', cc-znp cmd: 'incomingMsg', cc-znp payload: cc-znp { groupid: 25589, cc-znp clusterid: 1, cc-znp srcaddr: 14441, cc-znp srcendpoint: 1, cc-znp dstendpoint: 1, cc-znp wasbroadcast: 0, cc-znp linkquality: 7, cc-znp securityuse: 0, cc-znp timestamp: 3444177, cc-znp transseqnumber: 0, cc-znp len: 9, cc-znp data: <Buffer 1c 5f 11 00 0a 21 00 20 b9> }, cc-znp fcs: 240, cc-znp csum: 240 } +9ms serialport/stream _read reading +2ms serialport/binding-abstract read +3ms serialport/bindings/unixRead Starting read +3ms cc-znp:AREQ <-- AF:incomingMsg, { groupid: 25589, clusterid: 1, srcaddr: 14441, srcendpoint: 1, dstendpoint: 1, wasbroadcast: 0, linkquality: 7, securityuse: 0, timestamp: 3444177, transseqnumber: 0, len: 9, data: <Buffer 1c 5f 11 00 0a 21 00 20 b9> } +9ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: {"groupid":25589,"clusterid":1,"srcaddr":14441,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":7,"securityuse":0,"timestamp":3444177,"transseqnumber":0,"len":9,"data":{"type":"Buffer","data":[28,95,17,0,10,33,0,32,185]}} +5ms zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +8ms serialport/bindings/unixRead waiting for readable because of code: EAGAIN +2ms serialport/bindings/poller Polling for "readable" +5ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: {"groupid":25589,"clusterid":1,"srcaddr":14441,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":7,"securityuse":0,"timestamp":3444177,"transseqnumber":0,"len":9,"data":{"0":28,"1":95,"2":17,"3":0,"4":10,"5":33,"6":0,"7":32,"8":185},"zclMsg":{"frameCntl":{"frameType":0,"manufSpec":1,"direction":1,"disDefaultRsp":1},"manufCode":4447,"seqNum":0,"cmdId":"report","payload":[{"attrId":33,"dataType":32,"attrData":185}]}} +2ms zigbee2mqtt:debug 3/15/2019, 7:54:00 PM Received zigbee message of type 'attReport' with data '{"cid":"genPowerCfg","data":{"batteryPercentageRemaining":185}}' of device 'lumi.light.aqcn02' (0x00158d0002b88cdd) zigbee2mqtt:warn 3/15/2019, 7:54:00 PM No converter available for 'ZNLDP12LM' with cid 'genPowerCfg', type 'attReport' and data '{"cid":"genPowerCfg","data":{"batteryPercentageRemaining":185}}' zigbee2mqtt:warn 3/15/2019, 7:54:00 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html. zigbee2mqtt:debug 3/15/2019, 7:54:00 PM Received zigbee message of type 'devChange' with data '{"cid":"genPowerCfg","data":{"batteryPercentageRemaining":185}}' of device 'lumi.light.aqcn02' (0x00158d0002b88cdd) zigbee2mqtt:warn 3/15/2019, 7:54:00 PM No converter available for 'ZNLDP12LM' with cid 'genPowerCfg', type 'devChange' and data '{"cid":"genPowerCfg","data":{"batteryPercentageRemaining":185}}' zigbee2mqtt:warn 3/15/2019, 7:54:00 PM Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.

@milakov
Copy link
Author

milakov commented Mar 15, 2019

I don't know how to switch this level of debugging with hass.io, here is waht I have:

3/15/2019, 10:01:01 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":55}}' of device 'lumi.plug' (0x00158d0002561266)
3/15/2019, 10:01:01 PM - warn: No converter available for 'ZNCZ02LM' with cid 'msIlluminanceMeasurement', type 'attReport' and data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":55}}'
3/15/2019, 10:01:01 PM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/15/2019, 10:01:01 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":55}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c070e)
3/15/2019, 10:01:01 PM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d00029c070e', payload '{"illuminance":55,"linkquality":73,"last_seen":"2019-03-15T22:01:01+03:00","occupancy":false,"battery":100,"voltage":3065}'
3/15/2019, 10:01:01 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c070e)
3/15/2019, 10:01:01 PM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d00029c070e', payload '{"illuminance":55,"linkquality":73,"last_seen":"2019-03-15T22:01:01+03:00","occupancy":true,"battery":100,"voltage":3065}'
3/15/2019, 10:01:01 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.plug' (0x00158d0002561266)
3/15/2019, 10:01:01 PM - warn: No converter available for 'ZNCZ02LM' with cid 'msOccupancySensing', type 'attReport' and data '{"cid":"msOccupancySensing","data":{"occupancy":1}}'
3/15/2019, 10:01:01 PM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/15/2019, 10:01:01 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":55}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c070e)

@Koenkk
Copy link
Owner

Koenkk commented Mar 15, 2019

@milakov is this with the latest edge?

@milakov
Copy link
Author

milakov commented Mar 15, 2019

Yes, I think it is (using through hass.io). But, to be absolutely sure, I reinstalled z2m one more time, now waiting for those warnings.

@Koenkk
Copy link
Owner

Koenkk commented Mar 15, 2019

The warnings won't appear any more, as they are ignored, the messages should still be logged.

@Fabiancrg
Copy link

I don't know if this is related or not but I might see side effect of this.
I have two door sensors (Xiaomi MCCGQ01LM), door 1 is, according to networkmap, going throught LED bulb 1 (Aqara ZNLDP12LM) and another door 2 is going through LED bulb 2.
When I open door 1, I see two messages published, one for door 1 with "contact":false and one for LED 1 with "state":"ON".
Same thing for door 2 that change state of LED 2.
Apparently this happens only when contact is open and not when it is closed.
Here is the debug log for this:
serialport/bindings/unixRead waiting for readable because of code: EAGAIN +1ms serialport/bindings/poller Polling for "readable" +2ms serialport/bindings/poller received "readable" +5s serialport/binding-abstract read +5s serialport/bindings/unixRead Starting read +5s serialport/bindings/unixRead Finished read 12 bytes +1ms serialport/stream binding.read finished +5s cc-znp { sof: 254, cc-znp len: 7, cc-znp type: 'AREQ', cc-znp subsys: 'ZDO', cc-znp cmd: 'srcRtgInd', cc-znp payload: cc-znp { dstaddr: 59672, cc-znp relaycount: 2, cc-znp relaylist: <Buffer 93 e7 0e fc> }, cc-znp fcs: 243, cc-znp csum: 243 } +5s serialport/stream _read reading +3ms serialport/binding-abstract read +4ms serialport/bindings/unixRead Starting read +3ms cc-znp:AREQ <-- ZDO:srcRtgInd, { dstaddr: 59672, relaycount: 2, relaylist: <Buffer 93 e7 0e fc> } +5s zigbee-shepherd:msgHdlr IND <-- ZDO:srcRtgInd +5s serialport/bindings/unixRead waiting for readable because of code: EAGAIN +1ms serialport/bindings/poller Polling for "readable" +5ms serialport/bindings/poller received "readable" +21ms serialport/binding-abstract read +22ms serialport/bindings/unixRead Starting read +22ms serialport/bindings/unixRead Finished read 32 bytes +0ms serialport/stream binding.read finished +23ms cc-znp { sof: 254, cc-znp len: 27, cc-znp type: 'AREQ', cc-znp subsys: 'AF', cc-znp cmd: 'incomingMsg', cc-znp payload: cc-znp { groupid: 0, cc-znp clusterid: 6, cc-znp srcaddr: 59672, cc-znp srcendpoint: 1, cc-znp dstendpoint: 1, cc-znp wasbroadcast: 0, cc-znp linkquality: 36, cc-znp securityuse: 0, cc-znp timestamp: 5202897, cc-znp transseqnumber: 0, cc-znp len: 7, cc-znp data: <Buffer 18 99 0a 00 00 10 01> }, cc-znp fcs: 132, cc-znp csum: 132 } +25ms serialport/stream _read reading +2ms serialport/binding-abstract read +3ms serialport/bindings/unixRead Starting read +3ms cc-znp:AREQ <-- AF:incomingMsg, { groupid: 0, clusterid: 6, srcaddr: 59672, srcendpoint: 1, dstendpoint: 1, wasbroadcast: 0, linkquality: 36, securityuse: 0, timestamp: 5202897, transseqnumber: 0, len: 7, data: <Buffer 18 99 0a 00 00 10 01> } +26ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: {"groupid":0,"clusterid":6,"srcaddr":59672,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":36,"securityuse":0,"timestamp":5202897,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,153,10,0,0,16,1]}} +11s zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +30ms serialport/bindings/unixRead waiting for readable because of code: EAGAIN +4ms serialport/bindings/poller Polling for "readable" +8ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: {"groupid":0,"clusterid":6,"srcaddr":59672,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":36,"securityuse":0,"timestamp":5202897,"transseqnumber":0,"len":7,"data":{"0":24,"1":153,"2":10,"3":0,"4":0,"5":16,"6":1},"zclMsg":{"frameCntl":{"frameType":0,"manufSpec":0,"direction":1,"disDefaultRsp":1},"manufCode":0,"seqNum":153,"cmdId":"report","payload":[{"attrId":0,"dataType":16,"attrData":1}]}} +5ms zigbee2mqtt:debug 3/16/2019, 12:30:45 AM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'lumi.sensor_magnet' (0x00158d0001ad7150) zigbee2mqtt:info 3/16/2019, 12:30:45 AM MQTT publish: topic 'zigbee2mqtt/LivingRoom_Door', payload '{"contact":false,"linkquality":36,"battery":86,"voltage":2975}' zigbee2mqtt:debug 3/16/2019, 12:30:45 AM Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'lumi.sensor_magnet' (0x00158d0001ad7150) serialport/bindings/poller received "readable" +5ms serialport/binding-abstract read +10ms serialport/bindings/unixRead Starting read +5ms serialport/bindings/unixRead Finished read 34 bytes +0ms serialport/stream binding.read finished +10ms cc-znp { sof: 254, cc-znp len: 29, cc-znp type: 'AREQ', cc-znp subsys: 'AF', cc-znp cmd: 'incomingMsg', cc-znp payload: cc-znp { groupid: 59672, cc-znp clusterid: 6, cc-znp srcaddr: 59283, cc-znp srcendpoint: 1, cc-znp dstendpoint: 1, cc-znp wasbroadcast: 0, cc-znp linkquality: 0, cc-znp securityuse: 0, cc-znp timestamp: 5202915, cc-znp transseqnumber: 0, cc-znp len: 9, cc-znp data: <Buffer 1c 5f 11 99 0a 00 00 10 01> }, cc-znp fcs: 36, cc-znp csum: 36 } +12ms serialport/stream _read reading +2ms serialport/binding-abstract read +2ms serialport/bindings/unixRead Starting read +2ms cc-znp:AREQ <-- AF:incomingMsg, { groupid: 59672, clusterid: 6, srcaddr: 59283, srcendpoint: 1, dstendpoint: 1, wasbroadcast: 0, linkquality: 0, securityuse: 0, timestamp: 5202915, transseqnumber: 0, len: 9, data: <Buffer 1c 5f 11 99 0a 00 00 10 01> } +11ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: {"groupid":59672,"clusterid":6,"srcaddr":59283,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":0,"securityuse":0,"timestamp":5202915,"transseqnumber":0,"len":9,"data":{"type":"Buffer","data":[28,95,17,153,10,0,0,16,1]}} +7ms zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +9ms serialport/bindings/unixRead waiting for readable because of code: EAGAIN +3ms serialport/bindings/poller Polling for "readable" +5ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: {"groupid":59672,"clusterid":6,"srcaddr":59283,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":0,"securityuse":0,"timestamp":5202915,"transseqnumber":0,"len":9,"data":{"0":28,"1":95,"2":17,"3":153,"4":10,"5":0,"6":0,"7":16,"8":1},"zclMsg":{"frameCntl":{"frameType":0,"manufSpec":1,"direction":1,"disDefaultRsp":1},"manufCode":4447,"seqNum":153,"cmdId":"report","payload":[{"attrId":0,"dataType":16,"attrData":1}]}} +2ms zigbee2mqtt:debug 3/16/2019, 12:30:45 AM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'lumi.light.aqcn02' (0x00158d0002c65cf3) zigbee2mqtt:info 3/16/2019, 12:30:45 AM MQTT publish: topic 'zigbee2mqtt/LivingRoom_Light_1', payload '{"state":"ON","linkquality":0,"color":{"x":0.42,"y":0.4},"brightness":200,"color_temp":300}' serialport/bindings/poller received "readable" +2s serialport/binding-abstract read +2s serialport/bindings/unixRead Starting read +2s serialport/bindings/unixRead Finished read 32 bytes +1ms serialport/stream binding.read finished +2s cc-znp { sof: 254, cc-znp len: 27, cc-znp type: 'AREQ', cc-znp subsys: 'AF', cc-znp cmd: 'incomingMsg', cc-znp payload: cc-znp { groupid: 0, cc-znp clusterid: 6, cc-znp srcaddr: 59672, cc-znp srcendpoint: 1, cc-znp dstendpoint: 1, cc-znp wasbroadcast: 0, cc-znp linkquality: 36, cc-znp securityuse: 0, cc-znp timestamp: 5209219, cc-znp transseqnumber: 0, cc-znp len: 7, cc-znp data: <Buffer 18 9a 0a 00 00 10 00> }, cc-znp fcs: 203, cc-znp csum: 203 } +2s serialport/stream _read reading +3ms serialport/binding-abstract read +4ms serialport/bindings/unixRead Starting read +3ms cc-znp:AREQ <-- AF:incomingMsg, { groupid: 0, clusterid: 6, srcaddr: 59672, srcendpoint: 1, dstendpoint: 1, wasbroadcast: 0, linkquality: 36, securityuse: 0, timestamp: 5209219, transseqnumber: 0, len: 7, data: <Buffer 18 9a 0a 00 00 10 00> } +2s zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: {"groupid":0,"clusterid":6,"srcaddr":59672,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":36,"securityuse":0,"timestamp":5209219,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,154,10,0,0,16,0]}} +2s zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +2s serialport/bindings/unixRead waiting for readable because of code: EAGAIN +3ms serialport/bindings/poller Polling for "readable" +7ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: {"groupid":0,"clusterid":6,"srcaddr":59672,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":36,"securityuse":0,"timestamp":5209219,"transseqnumber":0,"len":7,"data":{"0":24,"1":154,"2":10,"3":0,"4":0,"5":16,"6":0},"zclMsg":{"frameCntl":{"frameType":0,"manufSpec":0,"direction":1,"disDefaultRsp":1},"manufCode":0,"seqNum":154,"cmdId":"report","payload":[{"attrId":0,"dataType":16,"attrData":0}]}} +4ms zigbee2mqtt:debug 3/16/2019, 12:30:47 AM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'lumi.sensor_magnet' (0x00158d0001ad7150) zigbee2mqtt:info 3/16/2019, 12:30:47 AM MQTT publish: topic 'zigbee2mqtt/LivingRoom_Door', payload '{"contact":true,"linkquality":36,"battery":86,"voltage":2975}' zigbee2mqtt:debug 3/16/2019, 12:30:47 AM Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'lumi.sensor_magnet' (0x00158d0001ad7150) serialport/bindings/poller received "readable" +6s serialport/binding-abstract read +6s serialport/bindings/unixRead Starting read +6s serialport/bindings/unixRead Finished read 10 bytes +0ms serialport/stream binding.read finished +6s cc-znp { sof: 254, cc-znp len: 5, cc-znp type: 'AREQ', cc-znp subsys: 'ZDO', cc-znp cmd: 'srcRtgInd', cc-znp payload: { dstaddr: 24576, relaycount: 1, relaylist: <Buffer 0e fc> }, cc-znp fcs: 23, cc-znp csum: 23 } +6s serialport/stream _read reading +2ms serialport/binding-abstract read +3ms serialport/bindings/unixRead Starting read +3ms cc-znp:AREQ <-- ZDO:srcRtgInd, { dstaddr: 24576, relaycount: 1, relaylist: <Buffer 0e fc> } +6s zigbee-shepherd:msgHdlr IND <-- ZDO:srcRtgInd +6s serialport/bindings/unixRead waiting for readable because of code: EAGAIN +1ms serialport/bindings/poller Polling for "readable" +4ms serialport/bindings/poller received "readable" +54ms serialport/binding-abstract read +56ms serialport/bindings/unixRead Starting read +55ms serialport/bindings/unixRead Finished read 69 bytes +0ms serialport/stream binding.read finished +56ms cc-znp { sof: 254, cc-znp len: 64, cc-znp type: 'AREQ', cc-znp subsys: 'AF', cc-znp cmd: 'incomingMsg', cc-znp payload: cc-znp { groupid: 0, cc-znp clusterid: 0, cc-znp srcaddr: 24576, cc-znp srcendpoint: 1, cc-znp dstendpoint: 1, cc-znp wasbroadcast: 0, cc-znp linkquality: 36, cc-znp securityuse: 0, cc-znp timestamp: 5228833, cc-znp transseqnumber: 0, cc-znp len: 44, cc-znp data: cc-znp <Buffer 18 63 0a 01 ff 42 25 01 21 9f 0b 04 21 a8 43 05 21 12 00 06 24 01 00 00 00 00 64 29 9f 07 65 21 51 17 66 2b c3 85 01 00 0a 21 0e fc> }, cc-znp fcs: 39, cc-znp csum: 39 } +59ms serialport/stream _read reading +3ms serialport/binding-abstract read +3ms serialport/bindings/unixRead Starting read +3ms cc-znp:AREQ <-- AF:incomingMsg, { groupid: 0, clusterid: 0, srcaddr: 24576, srcendpoint: 1, dstendpoint: 1, wasbroadcast: 0, linkquality: 36, securityuse: 0, timestamp: 5228833, transseqnumber: 0, len: 44, data: <Buffer 18 63 0a 01 ff 42 25 01 21 9f 0b 04 21 a8 43 05 21 12 00 06 24 01 00 00 00 00 64 29 9f 07 65 21 51 17 66 2b c3 85 01 00 0a 21 0e fc> } +59ms zigbee-shepherd:af dispatchIncomingMsg(): type: incomingMsg, msg: {"groupid":0,"clusterid":0,"srcaddr":24576,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":36,"securityuse":0,"timestamp":5228833,"transseqnumber":0,"len":44,"data":{"type":"Buffer","data":[24,99,10,1,255,66,37,1,33,159,11,4,33,168,67,5,33,18,0,6,36,1,0,0,0,0,100,41,159,7,101,33,81,23,102,43,195,133,1,0,10,33,14,252]}} +6s zigbee-shepherd:msgHdlr IND <-- AF:incomingMsg, transId: 0 +64ms serialport/bindings/unixRead waiting for readable because of code: EAGAIN +6ms serialport/bindings/poller Polling for "readable" +10ms zigbee-shepherd:af dispatchIncomingMsg(): type: zclIncomingMsg, msg: {"groupid":0,"clusterid":0,"srcaddr":24576,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":36,"securityuse":0,"timestamp":5228833,"transseqnumber":0,"len":44,"data":{"0":24,"1":99,"2":10,"3":1,"4":255,"5":66,"6":37,"7":1,"8":33,"9":159,"10":11,"11":4,"12":33,"13":168,"14":67,"15":5,"16":33,"17":18,"18":0,"19":6,"20":36,"21":1,"22":0,"23":0,"24":0,"25":0,"26":100,"27":41,"28":159,"29":7,"30":101,"31":33,"32":81,"33":23,"34":102,"35":43,"36":195,"37":133,"38":1,"39":0,"40":10,"41":33,"42":14,"43":252},"zclMsg":{"frameCntl":{"frameType":0,"manufSpec":0,"direction":1,"disDefaultRsp":1},"manufCode":0,"seqNum":99,"cmdId":"report","payload":[{"attrId":65281,"dataType":66,"attrData":{"1":2975,"4":17320,"5":18,"6":[0,1],"10":64526,"100":1951,"101":5969,"102":99779}}]}} +6ms zigbee2mqtt:debug 3/16/2019, 12:30:53 AM Received zigbee message of type 'attReport' with data '{"cid":"genBasic","data":{"65281":{"1":2975,"4":17320,"5":18,"6":[0,1],"10":64526,"100":1951,"101":5969,"102":99779}}}' of device 'lumi.weather' (0x00158d0001f52be8) zigbee2mqtt:info 3/16/2019, 12:30:53 AM MQTT publish: topic 'zigbee2mqtt/Bathroom_1_THP', payload '{"temperature":19.51,"linkquality":36,"humidity":59.69,"pressure":997.8,"battery":86,"voltage":2975}' zigbee2mqtt:debug 3/16/2019, 12:30:53 AM Received zigbee message of type 'devChange' with data '{"cid":"genBasic","data":{"65281":[null,2975,null,null,17320,18,[0,1],null,null,null,64526,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,1951,5969,99779]}}' of device 'lumi.weather' (0x00158d0001f52be8) ^C zigbee2mqtt:debug 3/16/2019, 12:31:06 AM Saving state to file /opt/zigbee2mqtt/data/state.json zigbee2mqtt:info 3/16/2019, 12:31:06 AM MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'offline' zigbee2mqtt:info 3/16/2019, 12:31:06 AM Disconnecting from MQTT server zigbee-shepherd zigbee-shepherd is stopping. +1m serialport/stream #flush +13s serialport/binding-abstract flush +13s zigbee-shepherd:request REQ --> ZDO:mgmtPermitJoinReq +26s cc-znp:SREQ --> ZDO:mgmtPermitJoinReq, { addrmode: 15, dstaddr: 65532, duration: 0, tcsignificance: 0 } +26s serialport/stream _write 10 bytes of data +1ms serialport/binding-abstract write 10 bytes +1ms serialport/bindings/unixWrite Starting write 10 bytes offset 0 bytesToWrite 10 +26s serialport/stream binding.flush finished +2ms serialport/stream #close +0ms serialport/binding-abstract close +3ms serialport/bindings/poller Stopping poller +13s serialport/bindings/poller Destroying poller +0ms serialport/stream binding.read error { Error: Canceled at Poller.emitCanceled (/opt/zigbee2mqtt/node_modules/@serialport/bindings/lib/poller.js:101:17) at Poller.stop (/opt/zigbee2mqtt/node_modules/@serialport/bindings/lib/poller.js:91:10) at close.then (/opt/zigbee2mqtt/node_modules/@serialport/bindings/lib/linux.js:48:19) canceled: true } +2ms serialport/stream _read queueing _read for after open +0ms serialport/bindings/unixWrite write returned null 10 +4ms serialport/bindings/unixWrite wrote 10 bytes +1ms serialport/bindings/unixWrite Finished writing 10 bytes +0ms serialport/stream binding.write write finished +1ms serialport/stream binding.close finished +4ms cc-znp The serialport /dev/ttyACM0 is closed. +13s zigbee-shepherd zigbee-shepherd is stopped. +13ms zigbee2mqtt:info 3/16/2019, 12:31:06 AM zigbee-shepherd stopped

@Fabiancrg
Copy link

In the log, LED1 is "LivingRoom_Light_1" and contact door 1 is "LivingRoom_Door"

@milakov
Copy link
Author

milakov commented Mar 16, 2019

@Koenkk I am still getting the warnings:

3/16/2019, 12:06:25 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":96}}' of device 'lumi.plug' (0x00158d0002561266)
3/16/2019, 12:06:25 AM - warn: No converter available for 'ZNCZ02LM' with cid 'msIlluminanceMeasurement', type 'attReport' and data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":96}}'
3/16/2019, 12:06:25 AM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/16/2019, 12:06:25 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":96}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c0149)
3/16/2019, 12:06:25 AM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d00029c0149', payload '{"illuminance":96,"linkquality":34,"last_seen":"2019-03-16T00:06:25+03:00","occupancy":false,"battery":100,"voltage":3035}'
3/16/2019, 12:06:25 AM - debug: Received zigbee message of type 'devChange' with data '{"cid":"msIlluminanceMeasurement","data":{"measuredValue":96}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c0149)
3/16/2019, 12:06:25 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.plug' (0x00158d0002561266)
3/16/2019, 12:06:25 AM - warn: No converter available for 'ZNCZ02LM' with cid 'msOccupancySensing', type 'attReport' and data '{"cid":"msOccupancySensing","data":{"occupancy":1}}'
3/16/2019, 12:06:25 AM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/16/2019, 12:06:25 AM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c0149)
3/16/2019, 12:06:25 AM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d00029c0149', payload '{"illuminance":96,"linkquality":36,"last_seen":"2019-03-16T00:06:25+03:00","occupancy":true,"battery":100,"voltage":3035}'

@Koenkk
Copy link
Owner

Koenkk commented Mar 16, 2019

@Fabiancrg please provide without DEBUG=* (but with log_level: debug) and post it on pastebin, in this way it's unreadable for me.

@milakov are you sure you are on the latest dev branch and did a rm -rf node_modules && npm install after swithcing? (http://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html).

@Fabiancrg
Copy link

@Koenkk Sorry for previous output, here is the Pastebin link with debug log:
https://pastebin.com/SFg6sfg5

@Koenkk
Copy link
Owner

Koenkk commented Mar 16, 2019

@Fabiancrg you are experiencing the problem @milakov was concerned about, can you update to the latest dev branch and provide the logging again?

@Fabiancrg
Copy link

@Koenkk Here is the debug log after the update --> https://pastebin.com/fPbc4TGE

@milakov
Copy link
Author

milakov commented Mar 16, 2019

@Koenkk I am sure I uninstalled zigbee2mqtt-edge and installed it again in hass.io. I have been using dev branch for quite some time already this way. Unfortunately log doesn't have commit number:

3/16/2019, 10:14:44 AM - info: Starting zigbee2mqtt version 1.2.1 (commit #unknown)

@Koenkk
Copy link
Owner

Koenkk commented Mar 16, 2019

@Fabiancrg can you provide the output on the latest dev branch when running with DEBUG=* npm start

@milakov thinking about this again, ignore converters isn't a durable solution, let's check what comes out of the logs of @Fabiancrg

@Fabiancrg
Copy link

@Koenkk I have just upgraded and open/close the door, here is the new log:

https://pastebin.com/kR83WLFf

@Fabiancrg
Copy link

@Koenkk Please disregard the previous debug log, it does not contains the message about the LIght ON when I open the door, apparently the message was not routed to the light.
I did a new test now and we can see the LivinRoom_Light_2 with ON state when I open the door, here is the log:

https://pastebin.com/78vtvXTY

Note that there is no OFF when door is closed so it seems that only the 'contact = false' is triggering an ON message off the light router.

@Koenkk
Copy link
Owner

Koenkk commented Mar 18, 2019

@milakov @Fabiancrg can you check with the latest dev branch, these messages should be ignored now.

@milakov
Copy link
Author

milakov commented Mar 18, 2019

@Koenkk I am still getting those warnings:

3/18/2019, 8:20:40 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2649}}' of device 'lumi.weather' (0x00158d0002775e09)
3/18/2019, 8:20:40 PM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d0002775e09', payload '{"temperature":26.5,"linkquality":68,"last_seen":"2019-03-18T20:20:40+03:00","humidity":31.7,"pressure":999,"battery":100,"voltage":3025}'
3/18/2019, 8:20:40 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2649}}' of device 'lumi.weather' (0x00158d0002775e09)
3/18/2019, 8:20:40 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msRelativeHumidity","data":{"measuredValue":3195}}' of device 'lumi.plug' (0x00158d0002561266)
3/18/2019, 8:20:40 PM - warn: No converter available for 'ZNCZ02LM' with cid 'msRelativeHumidity', type 'attReport' and data '{"cid":"msRelativeHumidity","data":{"measuredValue":3195}}'
3/18/2019, 8:20:40 PM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/18/2019, 8:20:40 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msRelativeHumidity","data":{"measuredValue":3195}}' of device 'lumi.weather' (0x00158d0002775e09)
3/18/2019, 8:20:40 PM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d0002775e09', payload '{"temperature":26.5,"linkquality":68,"last_seen":"2019-03-18T20:20:40+03:00","humidity":32,"pressure":999,"battery":100,"voltage":3025}'
3/18/2019, 8:20:40 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"msRelativeHumidity","data":{"measuredValue":3195}}' of device 'lumi.weather' (0x00158d0002775e09)
3/18/2019, 8:20:40 PM - debug: Received MQTT message on 'zigbee2mqtt/0x00158d00024f2e59/set' with data 'OFF'
3/18/2019, 8:20:40 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msPressureMeasurement","data":{"16":9994,"20":-1,"measuredValue":999}}' of device 'lumi.weather' (0x00158d0002775e09)
3/18/2019, 8:20:40 PM - info: MQTT publish: topic 'zigbee2mqtt/0x00158d0002775e09', payload '{"temperature":26.5,"linkquality":68,"last_seen":"2019-03-18T20:20:40+03:00","humidity":32,"pressure":999,"battery":100,"voltage":3025}'
3/18/2019, 8:20:40 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2649}}' of device 'lumi.plug' (0x00158d0002561266)
3/18/2019, 8:20:40 PM - warn: No converter available for 'ZNCZ02LM' with cid 'msTemperatureMeasurement', type 'attReport' and data '{"cid":"msTemperatureMeasurement","data":{"measuredValue":2649}}'
3/18/2019, 8:20:40 PM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
3/18/2019, 8:20:40 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msPressureMeasurement","data":{"16":9994,"20":-1,"measuredValue":999}}' of device 'lumi.plug' (0x00158d0002561266)
3/18/2019, 8:20:40 PM - warn: No converter available for 'ZNCZ02LM' with cid 'msPressureMeasurement', type 'attReport' and data '{"cid":"msPressureMeasurement","data":{"16":9994,"20":-1,"measuredValue":999}}'
3/18/2019, 8:20:40 PM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.

And this is start up log:

3/18/2019, 7:50:32 PM - info: Logging to directory: '/share/zigbee2mqtt/log/2019-03-18.19-50-32'
3/18/2019, 7:50:32 PM - debug: Removing old log directory '/share/zigbee2mqtt/log/2019-03-08.20-41-32'
3/18/2019, 7:50:33 PM - debug: Using zigbee-shepherd with settings: '{"net":{"panId":6754,"extPanId":[221,221,221,221,221,221,221,221],"channelList":[20],"precfgkey":"HIDDEN"},"dbPath":"/share/zigbee2mqtt/database.db","sp":{"baudRate":115200,"rtscts":true}}'
3/18/2019, 7:50:33 PM - debug: Loaded state from file /share/zigbee2mqtt/state.json
3/18/2019, 7:50:33 PM - info: Starting zigbee2mqtt version 1.2.1 (commit #unknown)
3/18/2019, 7:50:33 PM - info: Starting zigbee-shepherd
3/18/2019, 7:50:35 PM - info: zigbee-shepherd started
3/18/2019, 7:50:35 PM - info: Coordinator firmware version: '20190223'
3/18/2019, 7:50:35 PM - debug: zigbee-shepherd info: {"enabled":true,"net":{"state":"Coordinator","channel":20,"panId":"0x1a62","extPanId":"0xdddddddddddddddd","ieeeAddr":"0x00124b0019368448","nwkAddr":0},"firmware":{"transportrev":2,"product":0,"version":"2.6.3","revision":20190223},"startTime":1552927835,"joinTimeLeft":0}
3/18/2019, 7:50:35 PM - info: Currently 24 devices are joined:

@Fabiancrg
Copy link

@Koenkk It looks good for me now, I have a message saying "Skipping re-transmitted Xiaomi message", I suppose that's what replaced the message that was sending a ON message from the light.

Mär 18 20:53:15 NUC npm[2942]:   zigbee2mqtt:debug 3/18/2019, 8:53:15 PM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'lumi.sensor_magnet' (0x00158d0001ad6d7d)
Mär 18 20:53:15 NUC npm[2942]:   zigbee2mqtt:info 3/18/2019, 8:53:15 PM MQTT publish: topic 'zigbee2mqtt/Kitchen_Door', payload '{"contact":false,"linkquality":55,"battery":86,"voltage":2975}'
Mär 18 20:53:15 NUC npm[2942]:   zigbee2mqtt:debug 3/18/2019, 8:53:15 PM Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'lumi.sensor_magnet' (0x00158d0001ad6d7d)
Mär 18 20:53:15 NUC npm[2942]:   zigbee2mqtt:debug 3/18/2019, 8:53:15 PM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'lumi.light.aqcn02' (0x00158d0002b88cdd) with groupID undefined
Mär 18 20:53:15 NUC npm[2942]:   zigbee2mqtt:debug 3/18/2019, 8:53:15 PM Skipping re-transmitted Xiaomi message
Mär 18 20:53:19 NUC npm[2942]:   zigbee2mqtt:debug 3/18/2019, 8:53:19 PM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'lumi.sensor_magnet' (0x00158d0001ad6d7d)
Mär 18 20:53:19 NUC npm[2942]:   zigbee2mqtt:info 3/18/2019, 8:53:19 PM MQTT publish: topic 'zigbee2mqtt/Kitchen_Door', payload '{"contact":true,"linkquality":57,"battery":86,"voltage":2975}'
Mär 18 20:53:19 NUC npm[2942]:   zigbee2mqtt:debug 3/18/2019, 8:53:19 PM Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'lumi.sensor_magnet' (0x00158d0001ad6d7d)
Mär 18 20:53:20 NUC npm[2942]:   zigbee2mqtt:debug 3/18/2019, 8:53:20 PM Received zigbee message of type 'attReport' with data '{"cid":"genBasic","data":{"65282":[{"elmType":16,"elmVal":0},{"elmType":33,"elmVal":2975},{"elmType":33,"elmVal":13224},{"elmType":36,"elmVal":[0,3]},{"elmType":33,"elmVal":66},{"elmType":32,"elmVal":96}]}}' of device 'lumi.sensor_magnet' (0x00158d0001ad6d7d)
Mär 18 20:53:20 NUC npm[2942]:   zigbee2mqtt:info 3/18/2019, 8:53:20 PM MQTT publish: topic 'zigbee2mqtt/Kitchen_Door', payload '{"contact":true,"linkquality":57,"battery":86,"voltage":2975}'
Mär 18 20:53:20 NUC npm[2942]:   zigbee2mqtt:debug 3/18/2019, 8:53:20 PM Received zigbee message of type 'devChange' with data '{"cid":"genBasic","data":{"65282":[null,null,null,{"elmVal":[null,3]}]}}' of device 'lumi.sensor_magnet' (0x00158d0001ad6d7d)

@Koenkk
Copy link
Owner

Koenkk commented Mar 19, 2019

@Fabiancrg great, than this issue has been solved.

@milakov it looks that you are on an older version

@milakov
Copy link
Author

milakov commented Mar 19, 2019

@Koenkk Are you positive that the docker image was rebuilt with the new dev version? I am using hass.io.

@milakov
Copy link
Author

milakov commented Mar 22, 2019

I see now "skipping" messages as well!

3/21/2019, 11:02:50 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.plug' (0x00158d0002561266) with groupID undefined
3/21/2019, 11:02:50 PM - debug: Skipping re-transmitted Xiaomi message
3/21/2019, 11:02:50 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"msOccupancySensing","data":{"occupancy":1}}' of device 'lumi.sensor_motion.aq2' (0x00158d00029c070e)

Thanks!

@milakov milakov closed this as completed Mar 22, 2019
wilmardo pushed a commit to wilmardo/zigbee2mqtt that referenced this issue Sep 26, 2019
wilmardo pushed a commit to wilmardo/zigbee2mqtt that referenced this issue Sep 26, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants