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

Failed to interview the Yale lock YDM4109+ #3290

Closed
dinhchinh82 opened this issue Apr 4, 2020 · 54 comments
Closed

Failed to interview the Yale lock YDM4109+ #3290

dinhchinh82 opened this issue Apr 4, 2020 · 54 comments

Comments

@dinhchinh82
Copy link
Contributor

dinhchinh82 commented Apr 4, 2020

Bug Report

I tried to add the Yale Zigbee lock which is using Zigbee module to Zigbee2mqtt 1.12.0 but got some errors.
I reuse the configuration of YFM40 as below:

{
zigbeeModel: ['iZBModule01', 'c700050000'],
model: 'YMF40',
vendor: 'Yale',
description: 'Real living lock',
supports: 'lock/unlock, battery',
fromZigbee: [fz.lock_operation_event, fz.battery],
toZigbee: [tz.generic_lock],
meta: {configureKey: 2},
configure: async (device, coordinatorEndpoint) => {
const endpoint = device.getEndpoint(1);
await bind(endpoint, coordinatorEndpoint, ['closuresDoorLock', 'genPowerCfg']);
await configureReporting.lockState(endpoint);
await configureReporting.batteryPercentageRemaining(endpoint);
},
},

What happened

The lock is recognized even got the failed to interview in the log but it still shows on HASS. Sometimes could not interviewed.

The lock/unlock still work but not stable. Sometime, when click the lock/unlock, the response is quite slow (5-10 seconds) even the lock is very near to the Coordinator. Please check the log below.

The report status works well and it is very fast (when lock/unlock using finger print or code).
Here is the log:

zigbee2mqtt:info 2020-04-04 23:10:40: Switching log level to 'debug'
zigbee2mqtt:info 2020-04-04 23:10:40: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"version":"1.12.0","commit":"unknown","coordinator":{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190619}},"log_level":"debug","permit_join":true}'
zigbee2mqtt:debug 2020-04-04 23:11:15: Saving state to file /share/zigbee2mqtt/state.json
zigbee2mqtt:info 2020-04-04 23:11:22: Starting interview of '0x000d6f0012bc896e'
zigbee2mqtt:info 2020-04-04 23:11:22: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"interview_started","meta":{"friendly_name":"0x000d6f0012bc896e"}}'
zigbee2mqtt:debug 2020-04-04 23:11:22: Device '0x000d6f0012bc896e' announced itself
zigbee2mqtt:info 2020-04-04 23:11:22: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"device_announced","message":"announce","meta":{"friendly_name":"0x000d6f0012bc896e"}}'
zigbee2mqtt:debug 2020-04-04 23:11:42: Received Zigbee message from '0x000d6f0012bc896e', type 'readResponse', cluster 'genBasic', data '{"modelId":"c700050000","manufacturerName":"ASSA ABLOY iRevo"}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-04 23:11:42: No converter available for 'YMF40' with cluster 'genBasic' and type 'readResponse' and data '{"modelId":"c700050000","manufacturerName":"ASSA ABLOY iRevo"}'
zigbee2mqtt:info 2020-04-04 23:11:42: MQTT publish: topic 'homeassistant/lock/0x000d6f0012bc896e/lock/config', payload '{"command_topic":"zigbee2mqtt/0x000d6f0012bc896e/set","value_template":"{{ value_json.state }}","state_locked":"LOCK","state_unlocked":"UNLOCK","state_topic":"zigbee2mqtt/0x000d6f0012bc896e","json_attributes_topic":"zigbee2mqtt/0x000d6f0012bc896e","name":"0x000d6f0012bc896e_lock","unique_id":"0x000d6f0012bc896e_lock_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000d6f0012bc896e"],"name":"0x000d6f0012bc896e","sw_version":"Zigbee2mqtt 1.12.0","model":"Real living lock (YMF40)","manufacturer":"Yale"},"availability_topic":"zigbee2mqtt/bridge/state"}'
zigbee2mqtt:info 2020-04-04 23:11:42: MQTT publish: topic 'homeassistant/sensor/0x000d6f0012bc896e/battery/config', payload '{"unit_of_measurement":"%","device_class":"battery","value_template":"{{ value_json.battery }}","state_topic":"zigbee2mqtt/0x000d6f0012bc896e","json_attributes_topic":"zigbee2mqtt/0x000d6f0012bc896e","name":"0x000d6f0012bc896e_battery","unique_id":"0x000d6f0012bc896e_battery_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000d6f0012bc896e"],"name":"0x000d6f0012bc896e","sw_version":"Zigbee2mqtt 1.12.0","model":"Real living lock (YMF40)","manufacturer":"Yale"},"availability_topic":"zigbee2mqtt/bridge/state"}'
zigbee2mqtt:info 2020-04-04 23:11:42: MQTT publish: topic 'homeassistant/sensor/0x000d6f0012bc896e/linkquality/config', payload '{"icon":"mdi:signal","unit_of_measurement":"lqi","value_template":"{{ value_json.linkquality }}","state_topic":"zigbee2mqtt/0x000d6f0012bc896e","json_attributes_topic":"zigbee2mqtt/0x000d6f0012bc896e","name":"0x000d6f0012bc896e_linkquality","unique_id":"0x000d6f0012bc896e_linkquality_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000d6f0012bc896e"],"name":"0x000d6f0012bc896e","sw_version":"Zigbee2mqtt 1.12.0","model":"Real living lock (YMF40)","manufacturer":"Yale"},"availability_topic":"zigbee2mqtt/bridge/state"}'
zigbee2mqtt:error 2020-04-04 23:11:47: Failed to interview '0x000d6f0012bc896e', device has not successfully been paired
zigbee2mqtt:info 2020-04-04 23:11:47: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"interview_failed","meta":{"friendly_name":"0x000d6f0012bc896e"}}'
zigbee2mqtt:info 2020-04-04 23:11:47: Configuring '0x000d6f0012bc896e'
zigbee2mqtt:error 2020-04-04 23:12:02: Failed to configure '0x000d6f0012bc896e', attempt 1 (Error: Bind 0x000d6f0012bc896e/1 genPowerCfg from '0x00124b001f2b1406/1' failed (Error: AREQ - ZDO - bindRsp after 10000ms)
at Endpoint. (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:235:23)
at Generator.throw ()
at rejected (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:6:65))
zigbee2mqtt:debug 2020-04-04 23:12:17: Received Zigbee message from '0x000d6f0012bc896e', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":0,"opereventcode":2,"userid":1,"pin":0,"zigbeelocaltime":291218,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info 2020-04-04 23:12:17: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"UNLOCK","user":1,"source":0,"linkquality":70}'
zigbee2mqtt:info 2020-04-04 23:12:17: Configuring '0x000d6f0012bc896e'
zigbee2mqtt:debug 2020-04-04 23:12:22: Received Zigbee message from '0x000d6f0012bc896e', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":2,"opereventcode":1,"userid":0,"pin":0,"zigbeelocaltime":291228,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info 2020-04-04 23:12:22: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"LOCK","user":0,"source":2,"linkquality":59}'
zigbee2mqtt:error 2020-04-04 23:12:27: Failed to configure '0x000d6f0012bc896e', attempt 2 (Error: Bind 0x000d6f0012bc896e/1 closuresDoorLock from '0x00124b001f2b1406/1' failed (Error: AREQ - ZDO - bindRsp after 10000ms)
at Endpoint. (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:235:23)
at Generator.throw ()
at rejected (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:6:65))
zigbee2mqtt:debug 2020-04-04 23:13:38: Received Zigbee message from '0x000d6f0012bc896e', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":0,"opereventcode":2,"userid":1,"pin":0,"zigbeelocaltime":291304,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info 2020-04-04 23:13:38: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"UNLOCK","user":1,"source":0,"linkquality":57}'
zigbee2mqtt:info 2020-04-04 23:13:38: Configuring '0x000d6f0012bc896e'
zigbee2mqtt:error 2020-04-04 23:13:48: Failed to configure '0x000d6f0012bc896e', attempt 3 (Error: Bind 0x000d6f0012bc896e/1 closuresDoorLock from '0x00124b001f2b1406/1' failed (Error: AREQ - ZDO - bindRsp after 10000ms)
at Endpoint. (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:235:23)
at Generator.throw ()
at rejected (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:6:65))
zigbee2mqtt:debug 2020-04-04 23:16:04: Received MQTT message on 'zigbee2mqtt/bridge/config/permit_join' with data 'false'
zigbee2mqtt:info 2020-04-04 23:16:04: Zigbee: disabling joining new devices.
zigbee2mqtt:debug 2020-04-04 23:16:04: Received MQTT message on 'zigbee2mqtt/bridge/config/permit_join' with data 'false'
zigbee2mqtt:info 2020-04-04 23:16:04: Zigbee: disabling joining new devices.
zigbee2mqtt:info 2020-04-04 23:16:04: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"version":"1.12.0","commit":"unknown","coordinator":{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190619}},"log_level":"debug","permit_join":false}'
zigbee2mqtt:info 2020-04-04 23:16:04: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"version":"1.12.0","commit":"unknown","coordinator":{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190619}},"log_level":"debug","permit_join":false}'
zigbee2mqtt:debug 2020-04-04 23:16:15: Saving state to file /share/zigbee2mqtt/state.json
zigbee2mqtt:debug 2020-04-04 23:19:39: Received MQTT message on 'zigbee2mqtt/0x000d6f0012bc896e/set' with data 'LOCK'
zigbee2mqtt:debug 2020-04-04 23:19:39: Publishing 'set' 'state' to '0x000d6f0012bc896e'
zigbee2mqtt:debug 2020-04-04 23:19:47: Received Zigbee message from '0x000d6f0012bc896e', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":1,"opereventcode":1,"userid":0,"pin":0,"zigbeelocaltime":291669,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info 2020-04-04 23:19:47: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"LOCK","user":0,"source":1,"linkquality":65}'
zigbee2mqtt:debug 2020-04-04 23:19:49: Received MQTT message on 'zigbee2mqtt/0x000d6f0012bc896e/set' with data 'UNLOCK'
zigbee2mqtt:debug 2020-04-04 23:19:49: Publishing 'set' 'state' to '0x000d6f0012bc896e'
zigbee2mqtt:error 2020-04-04 23:19:53: Publish 'set' 'state' to '0x000d6f0012bc896e' failed: 'Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.lockDoor({"pincodevalue":""}, {"timeout":6000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: AREQ - AF - dataConfirm after 5000ms)'
zigbee2mqtt:debug 2020-04-04 23:19:53: Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.lockDoor({"pincodevalue":""}, {"timeout":6000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: AREQ - AF - dataConfirm after 5000ms)
at Endpoint. (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:339:23)
at Generator.throw ()
at rejected (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:6:65)
zigbee2mqtt:info 2020-04-04 23:19:53: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x000d6f0012bc896e' failed: 'Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.lockDoor({"pincodevalue":""}, {"timeout":6000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: AREQ - AF - dataConfirm after 5000ms)'","meta":{"friendly_name":"0x000d6f0012bc896e"}}'
(node:234) UnhandledPromiseRejectionWarning: Error: Timeout - 24303 - 1 - 6 - 257 - 1 after 6000ms
at Timeout._onTimeout (/zigbee2mqtt-1.12.0/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
at listOnTimeout (internal/timers.js:531:17)
at processTimers (internal/timers.js:475:7)
(node:234) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:234) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

What did you expect to happen

The lock/unlock function works stability without error.

How to reproduce it (minimal and precise)

click lock/unlock on the HASS interface.

Debug Info

zigbee2mqtt version: 1.12.0.
CC253X firmware version: CC2530 (Gban) Source routing. Revision:20190619

@Koenkk
Copy link
Owner

Koenkk commented Apr 4, 2020

Could you sniff the traffic when controlling lock/unlock? https://www.zigbee2mqtt.io/how_tos/how_to_sniff_zigbee_traffic.html

@dinhchinh82
Copy link
Contributor Author

@Koenkk please check the traffic as below
https://pastebin.com/fsKu4Br7

As I checked more detail, each time controlling unlock, the error in Zigbee2mqtt as below:

zigbee2mqtt:error 2020-04-05 10:26:07: Publish 'set' 'state' to '0x000d6f0012bc896e' failed: 'Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.unlockDoor({"pincodevalue":""}, {"timeout":6000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: AREQ - AF - dataConfirm after 5000ms)'
zigbee2mqtt:info 2020-04-05 10:26:07: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x000d6f0012bc896e' failed: 'Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.unlockDoor({"pincodevalue":""}, {"timeout":6000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: AREQ - AF - dataConfirm after 5000ms)'","meta":{"friendly_name":"0x000d6f0012bc896e"}}'

@Koenkk
Copy link
Owner

Koenkk commented Apr 5, 2020

Could you send the pcapng file?

@dinhchinh82
Copy link
Contributor Author

@Koenkk
Copy link
Owner

Koenkk commented Apr 6, 2020

I need you network key to decrypt the file.

@dinhchinh82
Copy link
Contributor Author

@Koenkk please use the decrypt key below:
0c1634495d0b0d0f02162a3e080a0c0d

@dinhchinh82
Copy link
Contributor Author

@Koenkk please let me know if you need any further information.

@Koenkk
Copy link
Owner

Koenkk commented Apr 9, 2020

It looks that there are 2 Zigbee networks operating on this channel (both Texas Instruments coordinator). Can you confirm this? If yes, I would recommend to move one of your networks to a different channel.

@dinhchinh82
Copy link
Contributor Author

@Koenkk Yes last time I have 2 Zigbee coordinators but I already set different channels.

By the way, I just turn off all the Zigbe coordinator and set up new one from scratch.
I can make sure there is only 1 ZC in this new test. And the error is still same as before.
Please check the new capture file (I set the channel to 20) as below:
https://www.dropbox.com/s/y5gh1dln9v0kysg/Yale%20YDM4109%20sniff%20log_2010.04.10.pcapng?dl=0

The new decrypt key:
0b1f34495d0b0d0f1616293d510a0c0d

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 10, 2020

Here is the log from Zigbee2mqtt, I already tested with latest version 1.12.2. This time, same error and the battery of the log is even unable to read as before.
https://pastebin.com/ZnaQ8hBA

Koenkk added a commit to Koenkk/zigbee-herdsman that referenced this issue Apr 11, 2020
@Koenkk
Copy link
Owner

Koenkk commented Apr 11, 2020

Lock/unlock timeout should be fixed in latest dev branch.

Regarding configure fail, can you provide the herdsman debug logging of this.

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

@dinhchinh82
Copy link
Contributor Author

@Koenkk the lock/unlock functions work well in dev branch now.
By the way, the status of the lock is not updated when lock/unlock using passcode, fingerprint etc. The battery status is also unavailable.
Screenshot:
https://prnt.sc/rxdrd0

Debug log of lock/unlock from Home Assistant:
https://pastebin.com/YvrmkPfa

@Koenkk
Copy link
Owner

Koenkk commented Apr 11, 2020

@dinhchinh82 thats because the configure fails.

Regarding configure fail, can you provide the herdsman debug logging of this.

(from above comment)

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 11, 2020

@Koenkk I have not seen the configure failed anymore with dev branch. Here is the debug logging:
https://pastebin.com/YvrmkPfa

@Koenkk
Copy link
Owner

Koenkk commented Apr 12, 2020

Can you try to trigger it manually and see if it errors: https://www.zigbee2mqtt.io/information/mqtt_topics_and_message_structure.html#zigbee2mqttbridgeconfigure

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 15, 2020

@Koenkk I've tried to setup everything from scratch to test again. Then I still found the error.
My environment:

  • Zigbee2mqtt 1.12.2-dev (commit #62254bb)
  • ZC channel: 20 (no any other same zigbee on this channel).
  • Home Assistant 0.108.3

Here are the test result:

  • The lock/unlock function from Home assistant is not stable.
  • Only can lock but quite slowly.
  • The unlock function worked or failed randomly
  • Reporting & battery: not available
  • Still a lot of exception/warning in the debug log

The debugging log (from starting zigbee service to the time lock/unlock from Home Assistant)
https://pastebin.com/KMpQNLhJ

Please let me know if you need any other information for investigation.

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 15, 2020

I also have tried to trigger the configuration manually and got error:

zigbee2mqtt:info 2020-04-15 05:50:39: Configuring '0x000d6f0012bc896e'
zigbee2mqtt:error 2020-04-15 05:50:51: Failed to configure '0x000d6f0012bc896e', attempt 2 (Error: Bind 0x000d6f0012bc896e/1 genPowerCfg from '0x00124b001b7d8cf4/1' failed (Error: AREQ - ZDO - bindRsp after 10000ms)
at Endpoint. (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:244:23)
at Generator.throw ()
at rejected (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:6:65))
zigbee2mqtt:debug 2020-04-15 05:51:51: Received Zigbee message from '0x000d6f0012bc896e', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":11}' from endpoint 1 with groupID 0
zigbee2mqtt:info 2020-04-15 05:51:51: Configuring '0x000d6f0012bc896e'
zigbee2mqtt:debug 2020-04-15 05:51:56: Received Zigbee message from '0x000d6f0012bc896e', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":11}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-15 05:52:01: Received Zigbee message from '0x000d6f0012bc896e', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":11}' from endpoint 1 with groupID 0
zigbee2mqtt:error 2020-04-15 05:52:01: Failed to configure '0x000d6f0012bc896e', attempt 3 (Error: Bind 0x000d6f0012bc896e/1 closuresDoorLock from '0x00124b001b7d8cf4/1' failed (Error: AREQ - ZDO - bindRsp after 10000ms)
at Endpoint. (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:244:23)
at Generator.throw ()
at rejected (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:6:65))
zigbee2mqtt:debug 2020-04-15 05:52:05: Received Zigbee message from '0x000d6f0012bc896e', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":11}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-15 05:52:10: Received Zigbee message from '0x000d6f0012bc896e', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":11}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-15 05:52:15: Received Zigbee message from '0x000d6f0012bc896e', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":11}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-15 05:53:11: Saving state to file /opt/zigbee2mqtt/data/state.json

@Koenkk
Copy link
Owner

Koenkk commented Apr 15, 2020

Could you sniff the traffic of this again?

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 21, 2020

@Koenkk please check the updated sniff & debug log:

decrypt key: 01:03:05:07:09:0B:0D:0F:00:02:04:06:08:0A:0C:0D (default)

Test environment:

  • HA 0.108.6
  • Zigbee2mqtt 1.12.2-dev
  • CC2531 default firmware 20190608
  • Device: Yale lock YDM4109+

Today Test result:

  • Lock from HA: works but not stability (around 10-15 seconds).
  • Unlock from HA: works but not stability (around 10-15 seconds). Some error in the debug log.
  • Update status of real lock from unlocked to locked: works and fast
  • Update status of real lock from locked to unlocked: works partially & slow

@Koenkk
Copy link
Owner

Koenkk commented Apr 21, 2020

Please point me a bit more to the problematic parts (provide the No. where e.g. commands fails). Regarding the delay, I indeed see that the lock takes 5 seconds to response, but I don't think we can solve that from Zigbee2mqtt itself. The device only requests for data every 5 seconds.

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 22, 2020

@Koenkk it's quite strange that after about 8 hours from setting lock, it seems to work more reliable.
Please check the full test result as below:
1. Control from Home Assistant (HA): 8 times

  • Lock: 20 seconds, 12 seconds, 12 seconds, 13 seconds, 2 seconds, 7 seconds, 1 seconds, 2 seconds
    for the case that lock takes about 10 seconds or more, there is error message in debug log as below:

zigbee2mqtt:debug 2020-04-22 09:58:27: Publishing 'set' 'state' to '0x000d6f0012bc896e'
zigbee2mqtt:debug 2020-04-22 09:58:27: Received Zigbee message from '0x000d6f0012bc896e', type 'attributeReport', cluster 'closuresDoorLock', data '{"lockState":2}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-22 09:58:27: No converter available for 'YMF40' with cluster 'closuresDoorLock' and type 'attributeReport' and data '{"lockState":2}'
zigbee2mqtt:debug 2020-04-22 09:58:32: Received Zigbee message from '0x000d6f0012bc896e', type 'attributeReport', cluster 'closuresDoorLock', data '{"lockState":2}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-22 09:58:32: No converter available for 'YMF40' with cluster 'closuresDoorLock' and type 'attributeReport' and data '{"lockState":2}'
(node:226) UnhandledPromiseRejectionWarning: Error: Timeout - 37335 - 1 - 160 - 257 - 0 after 10000ms
at Timeout._onTimeout (/app/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
at listOnTimeout (internal/timers.js:531:17)
at processTimers (internal/timers.js:475:7)
(node:226) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 27)
(node:226) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 27)
zigbee2mqtt:info 2020-04-22 09:58:44: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"LOCK","user":0,"source":1,"linkquality":131,"battery":127.5}'

  • Unlock: 5 seconds, 30 seconds, 1 seconds, 6 seconds, 8 seconds, 9 seconds, 3 seconds, 4 seconds
    For the case that unlock takes around 10 seconds or more, ther is error message in debug log as below:

zigbee2mqtt:error 2020-04-22 10:04:01: Publish 'set' 'state' to '0x000d6f0012bc896e' failed: 'Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.unlockDoor({"pincodevalue":""}, {"timeout":10000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: Timeout - 37335 - 1 - 170 - 257 - 1 after 10000ms)'
zigbee2mqtt:debug 2020-04-22 10:04:01: Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.unlockDoor({"pincodevalue":""}, {"timeout":10000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: Timeout - 37335 - 1 - 170 - 257 - 1 after 10000ms)
at Endpoint. (/app/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:349:23)
at Generator.throw ()
at rejected (/app/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:6:65)
zigbee2mqtt:info 2020-04-22 10:04:01: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x000d6f0012bc896e' failed: 'Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.unlockDoor({"pincodevalue":""}, {"timeout":10000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: Timeout - 37335 - 1 - 170 - 257 - 1 after 10000ms)'","meta":{"friendly_name":"0x000d6f0012bc896e"}}'
zigbee2mqtt:debug 2020-04-22 10:04:03: Received Zigbee message from '0x000d6f0012bc896e', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":1,"opereventcode":1,"userid":0,"pin":0,"zigbeelocaltime":1799118,"data":0}' from endpoint 1 with groupID 0

2. Report status from Real lock to Home Assistant:

  • Lock: under 1 second (very fast)
    The debug log is as below:

zigbee2mqtt:debug 2020-04-22 10:15:08: Received Zigbee message from '0x000d6f0012bc896e', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":2,"opereventcode":1,"userid":0,"pin":0,"zigbeelocaltime":1799809,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info 2020-04-22 10:15:08: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"LOCK","user":0,"source":2,"linkquality":113,"battery":127.5}'
zigbee2mqtt:debug 2020-04-22 10:15:08: Received Zigbee message from '0x000d6f0012bc896e', type 'attributeReport', cluster 'closuresDoorLock', data '{"lockState":1}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-22 10:15:08: No converter available for 'YMF40' with cluster 'closuresDoorLock' and type 'attributeReport' and data '{"lockState":1}'

  • Unlock by finger print: not updated to Home Assistant
    The debug log is as below:

zigbee2mqtt:debug 2020-04-22 10:12:27: Received Zigbee message from '0x000d6f0012bc896e', type 'attributeReport', cluster 'closuresDoorLock', data '{"lockState":2}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-22 10:12:27: No converter available for 'YMF40' with cluster 'closuresDoorLock' and type 'attributeReport' and data '{"lockState":2}'

  • Unlock by pin code: under 1 second (very fast)
    The debug log is as below:

zigbee2mqtt:debug 2020-04-22 10:14:38: Received Zigbee message from '0x000d6f0012bc896e', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":0,"opereventcode":2,"userid":1,"pin":0,"zigbeelocaltime":1799778,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info 2020-04-22 10:14:38: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"UNLOCK","user":1,"source":0,"linkquality":115,"battery":127.5}'
zigbee2mqtt:debug 2020-04-22 10:14:38: Received Zigbee message from '0x000d6f0012bc896e', type 'attributeReport', cluster 'closuresDoorLock', data '{"lockState":2}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-22 10:14:38: No converter available for 'YMF40' with cluster 'closuresDoorLock' and type 'attributeReport' and data '{"lockState":2}'

Other points:

  • Battery: work
  • Link quality: work

Remaining points to fix:

  • Lock/Unlock from HA more stabilty, no error message in the log
  • Update the status from lock to HA by fingerprint

Full debug log:
https://pastebin.com/BFjNkRTk

@Koenkk
Copy link
Owner

Koenkk commented Apr 22, 2020

I've added support for it in the latest dev branch. Both points should be fixed.

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 22, 2020

@Koenkk I've just tested with the latest dev branch.

Remaining points to fix:

  • Lock/Unlock from HA more stable, no error message in the log
    => It seems to be more stable but still sometimes (a few) got error in the log as below. the percentage of error is about 10%. In this case the operation is also slow.

zigbee2mqtt:info 2020-04-22 18:41:59: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"UNLOCK","user":0,"source":1,"linkquality":89,"battery":39.5}'
zigbee2mqtt:error 2020-04-22 18:42:11: Publish 'set' 'state' to '0x000d6f0012bc896e' failed: 'Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.unlockDoor({"pincodevalue":""}, {"timeout":10000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: Timeout - 37335 - 1 - 13 - 257 - 1 after 10000ms)'
zigbee2mqtt:info 2020-04-22 18:42:12: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x000d6f0012bc896e' failed: 'Error: Command 0x000d6f0012bc896e/1 closuresDoorLock.unlockDoor({"pincodevalue":""}, {"timeout":10000,"manufacturerCode":null,"disableDefaultResponse":true}) failed (Error: Timeout - 37335 - 1 - 13 - 257 - 1 after 10000ms)'","meta":{"friendly_name":"0x000d6f0012bc896e"}}'
zigbee2mqtt:info 2020-04-22 18:42:14: MQTT publish: topic 'zigbee2mqtt/0x000d6f0012bc896e', payload '{"state":"UNLOCK","user":0,"source":1,"linkquality":89,"battery":39.5}'

  • Update the status from lock to HA by fingerprint
    => Still not fixed yet (unlock by finger print and the log status is not updated to Home Assistant yet). Here is the herdsman debugging log.

zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,1,1,215,145,1,1,0,84,0,44,226,42,0,0,7,24,30,10,0,0,48,2,215,145,29,74] +13s
zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,1,1,215,145,1,1,0,84,0,44,226,42,0,0,7,24,30,10,0,0,48,2,215,145,29,74] +1ms
zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,1,1,215,145,1,1,0,84,0,44,226,42,0,0,7,24,30,10,0,0,48,2,215,145,29] - 74 +1ms
zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":257,"srcaddr":37335,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":84,"securityuse":0,"timestamp":2810412,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,30,10,0,0,48,2]}} +13s
zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true},"transactionSequenceNumber":30,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":48,"attrData":2}]},"address":37335,"endpoint":1,"linkquality":84,"groupID":0}' +13s
zigbee2mqtt:debug 2020-04-22 18:46:00: Received Zigbee message from '0x000d6f0012bc896e', type 'attributeReport', cluster 'closuresDoorLock', data '{"lockState":2}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-22 18:46:00: No converter available for 'YMF40' with cluster 'closuresDoorLock' and type 'attributeReport' and data '{"lockState":2}'
zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +20ms

@Koenkk
Copy link
Owner

Koenkk commented Apr 22, 2020

This does not look like the latest code.

  • Make sure that you dind't modify zigbee-herdsman-converters locally (overide devices.js e.g.)
  • For hassio it takes a few hours before it's updated.

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 22, 2020

@Koenkk I did not use the hassio addon for this test. I've install dev branch manually as your guide.

zigbee2mqtt:info 2020-04-22 18:40:06: Logging to console and directory: '/opt/zigbee2mqtt/data/log/2020-04-22.18-40-06' filename: log.txt
zigbee2mqtt:info 2020-04-22 18:40:06: Starting zigbee2mqtt version 1.12.2-dev (commit #d073a7f)
zigbee2mqtt:info 2020-04-22 18:40:06: Starting zigbee-herdsman...
zigbee2mqtt:info 2020-04-22 18:40:08: zigbee-herdsman started
zigbee2mqtt:info 2020-04-22 18:40:08: Coordinator firmware version: '{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190608}}'

Make sure that you dind't modify zigbee-herdsman-converters locally (overide devices.js e.g.)

Yes. I just used the default converter, not changed the devices.js

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 23, 2020

@Koenkk I'm sorry that I had used the modified device.js so the test result is not correct.
I just rebuilt the testing process as below:

  • reinstall zigbee2mqtt manually from scratch again, not using docker from HASSIO
  • Use the original devices.js, don't touch anything.

Result:

  • after pairing the lock, it's quite strange that it is recognized as "iZBModule01" lock (YMF40), not "c700050000" (YDM4109+).
    And the YDM4109+ is also recognized as YFM40 since zigbee2mqtt 1.12.2, no information related to "c700050000" in the log as before.

So in order to test the new configuration, I've removed the config part of YMF40 and change the configuration as below:

{
zigbeeModel: ['iZBModule01'],
model: 'YDM4109+',
vendor: 'Yale',
description: 'Intelligent biometric digital lock',
supports: 'lock/unlock, battery',
fromZigbee: [fz.lock_operation_event, fz.battery, fz.lock],
toZigbee: [tz.generic_lock],
// Increased timeout needed: #3290
meta: {configureKey: 2, timeout: 20000},
configure: async (device, coordinatorEndpoint) => {
const endpoint = device.getEndpoint(1);
await bind(endpoint, coordinatorEndpoint, ['closuresDoorLock', 'genPowerCfg']);
await configureReporting.lockState(endpoint);
await configureReporting.batteryPercentageRemaining(endpoint);
},
},

By this way, the YDM4109+ is recognized correctly. It's paired successfully and fast.

But if take a look more detail in the debugging log, there is still error during configuring step as below:

(node:32476) UnhandledPromiseRejectionWarning: Error: Timeout - 62898 - 1 - 13 - 0 - 1 after 10000ms
at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
at listOnTimeout (internal/timers.js:549:17)
at processTimers (internal/timers.js:492:7)
(node:32476) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag --unhandled-rejections=strict (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 6)
zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,0,1,32,230] +4s

Summary:

  • Link quality: work
  • Lock/unlock from HA: work (3~23 seconds)
  • Update the status from lock to HA by passcode: work (fast)
  • Update the status from lock to HA by fingerprint: work (fast)

Remaining points to fix:

  • The lock is now recognized as YMF40. need to change manually as above.
  • Battery: did not work (may be after several hours it will be available).

Full debugging log using DEBUG=zigbee-herdsman* npm start
https://pastebin.com/SzJbuyRy

Koenkk added a commit to Koenkk/zigbee-herdsman-converters that referenced this issue Apr 23, 2020
@Koenkk
Copy link
Owner

Koenkk commented Apr 23, 2020

The lock is now recognized as YMF40. need to change manually as above.

Should be fixed in latest dev (please wait a few hours before trying)

Regarding configure error, please provide a bit longer logging (yours stop some moments before I expect the error).

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 24, 2020

@Koenkk I confirm the latest commit in dev branch now recognized the lock exactly.
The battery works after several hours.

For the configure error, please check full debugging log again as below:
https://pastebin.com/Ni8WTmbm

@Koenkk
Copy link
Owner

Koenkk commented Apr 24, 2020

Could you sniff the traffic while the configure is happening?

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 25, 2020

@Koenkk I've just test the latest branch again. Please check the result and related data.

Test result by 2020.04.25:

  • Link quality: work
  • Battery: work
  • Lock/unlock from HA: work (3~23 seconds)
  • Identity lock: recognized correctly
  • Update the status from lock to HA by passcode: work (fast)
  • Update the status from lock to HA by fingerprint: NOT WORK AGAIN !! (quite strange!!!)

Debugging lock:
https://pastebin.com/FCyXUrzQ

Sniff zigbee data:
https://www.dropbox.com/s/l254t2lck6z9s44/Yale%20YDM4109%20sniff%20log%202020.04.25.pcapng?dl=0

2nd test:
https://pastebin.com/UfNVtx72
https://www.dropbox.com/s/rijnrz44icrhbw9/Yale%20YDM4109%20sniff%20log%202020.04.25%20part%202.pcapng?dl=0

decrypt key: 01:03:05:07:09:0B:0D:0F:00:02:04:06:08:0A:0C:0D (default)

Test environment:

  • HA 0.108.6
  • Zigbee adapter: CC2531 ver 20190608
  • Zigbee2mqtt: 1.12-dev (commit #d8ec59b)

@Koenkk
Copy link
Owner

Koenkk commented Apr 28, 2020

Please add some annotation to the log where you unlock it by fingerprint (otherwise I have no clue were to look at).

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented Apr 28, 2020

@Koenkk I check the debugging log and found out the following points:

  1. There is still error during interviewing:

zigbee2mqtt:debug 2020-04-28 13:31:36: Received Zigbee message from '0x000d6f0012bc896e', type 'readResponse', cluster 'genBasic', data '{"hwVersion":0}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-28 13:31:36: No converter available for 'YMF40/YDM4109+' with cluster 'genBasic' and type 'readResponse' and data '{"hwVersion":0}'

zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms
(node:4355) UnhandledPromiseRejectionWarning: Error: Timeout - 53915 - 1 - 11 - 0 - 1 after 10000ms
at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
at listOnTimeout (internal/timers.js:549:17)
at processTimers (internal/timers.js:492:7)
(node:4355) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag --unhandled-rejections=strict (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
(node:4355) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
full debug log:
https://www.dropbox.com/s/tn3t63857ylpskn/Yale%20YDM4109%20debugging%20log%20interview%202020.04.28.log?dl=0

  1. Unlock by fingerprint, there is no additional log anymore today.

By the way, I feel it's quite strange because I already catched the log when opening by fingerprint by the test on Apr 22 as below (from previous comment):

Unlock by finger print: not updated to Home Assistant
The debug log is as below:
zigbee2mqtt:debug 2020-04-22 10:12:27: Received Zigbee message from '0x000d6f0012bc896e', type 'attributeReport', cluster 'closuresDoorLock', data '{"lockState":2}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-04-22 10:12:27: No converter available for 'YMF40' with cluster 'closuresDoorLock' and type 'attributeReport' and data '{"lockState":2}'

I also confirmed the test on Apr 23, if opening by fingerprint, the status is updated immediately to the Home Assistant.

@Koenkk
Copy link
Owner

Koenkk commented Apr 29, 2020

  1. What is your node version? (node --version)
  2. Strange, can you try repairing?

@dinhchinh82
Copy link
Contributor Author

  1. My node version: node --version
    v12.16.2
  2. I just repaired again . Here is error in the log:

zigbee-herdsman:controller:endpoint Bind 0x000d6f0012bc896e/1 genPowerCfg from '0x00124b0018e2f59a/1' failed (Error: AREQ - ZDO - bindRsp after 10000ms) +0ms
zigbee2mqtt:error 2020-04-30 02:15:01: Failed to configure '0x000d6f0012bc896e', attempt 1 (Error: Bind 0x000d6f0012bc896e/1 genPowerCfg from '0x00124b0018e2f59a/1' failed (Error: AREQ - ZDO - bindRsp after 10000ms)
at Endpoint. (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:244:23)
at Generator.throw ()
at rejected (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/endpoint.js:6:65))

@Koenkk
Copy link
Owner

Koenkk commented May 2, 2020

Can you try again with latest dev branch? (pushed a possible fix)

@dinhchinh82
Copy link
Contributor Author

dinhchinh82 commented May 4, 2020

@Koenkk I have tested with the latest dev branch ( 1.13.0-dev (commit #772f6c0))

Here are the result:

  • Configure: success (but a little bit slow, may be several minutes to see the successfully message in the debugging log)
  • Link quality: work
  • Battery: not work immediately after pairing but work after several hours.
  • Lock/unlock from HA: work (3~23 seconds)
  • Identity lock: recognized correctly
  • Update the status from lock to HA by passcode: work (fast)
  • Update the status from lock to HA by fingerprint: STILL NOT WORK !!
    here is the debugging log once unlocking by fingerprint:

zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,1,1,232,153,1,1,0,110,0,46,203,114,0,0,7,24,94,10,0,0,48,2,232,153,29,67] +2m
zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,1,1,232,153,1,1,0,110,0,46,203,114,0,0,7,24,94,10,0,0,48,2,232,153,29,67] +1ms
zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,1,1,232,153,1,1,0,110,0,46,203,114,0,0,7,24,94,10,0,0,48,2,232,153,29] - 67 +0ms
zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":257,"srcaddr":39400,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":110,"securityuse":0,"timestamp":7523118,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,94,10,0,0,48,2]}} +2m
zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true},"transactionSequenceNumber":94,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":48,"attrData":2}]},"address":39400,"endpoint":1,"linkquality":110,"groupID":0}' +2m
zigbee2mqtt:debug 2020-05-04 17:50:05: Received Zigbee message from '0x000d6f0012bc896e', type 'attributeReport', cluster 'closuresDoorLock', data '{"lockState":2}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-05-04 17:50:05: No converter available for 'YMF40/YDM4109+' with cluster 'closuresDoorLock' and type 'attributeReport' and data '{"lockState":2}'
zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +16ms

Koenkk added a commit to Koenkk/zigbee-herdsman-converters that referenced this issue May 5, 2020
@Koenkk
Copy link
Owner

Koenkk commented May 5, 2020

Update the status from lock to HA by fingerprint: STILL NOT WORK !!

Should be fixed in latest dev branch.

@dinhchinh82
Copy link
Contributor Author

@Koenkk I confirm the lock status is updated correctly to HA once unlock by fingerprint.
This issue can be resolved for now.
Thank you very much for your support.

@Koenkk
Copy link
Owner

Koenkk commented May 6, 2020

Cool! thanks

@Koenkk Koenkk closed this as completed May 6, 2020
@gagandeep90
Copy link

@Koenkk I confirm the lock status is updated correctly to HA once unlock by fingerprint.
This issue can be resolved for now.
Thank you very much for your support.

Hi, Could you please post a link or a picture of the Zigbee Module that you used for the YDM4109+

@matisaul
Copy link

Hi @Koenkk ,

I update this module to last version, from 1.7, and now My Yale YMF40 is publishing this to mosquitto:

zigbee2mqtt:debug 2020-06-23 20:26:59: Received Zigbee message from 'Cerradura Principal', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":2,"opereventcode":10,"userid":0,"pin":0,"zigbeelocaltime":1770453224,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2020-06-23 20:26:59: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal', payload '{"linkquality":76,"action":"auto_lock","action_user":0,"action_source":2}'
zigbee2mqtt:info  2020-06-23 20:26:59: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal', payload '{"linkquality":76,"action":""}'
zigbee2mqtt:info  2020-06-23 20:26:59: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal/action', payload 'auto_lock'

So, is sending the correct message to MQTT broker, but inmediatly change this:

{"linkquality":76,"action":"auto_lock","action_user":0,"action_source":2}

To this:
'{"linkquality":76,"action":""}'

So, previous data is deleted by the last one.... Do you know why this is happened?

I tried to erase and repair the lock, but It happened anyway.

@Koenkk
Copy link
Owner

Koenkk commented Jun 24, 2020

This is expected behaviour, this is an action and only applies to this specific message. The next time a message is received from the lock this does not apply anymore so it is not cached

@matisaul
Copy link

matisaul commented Jun 24, 2020

In my case, every time I unlock/lock the door, this message is being send. Now, my lock doesn't update anymore in Home Assistant. I remove the lock, and restart HA. Autodiscovery tool find the lock again, but always shows as Unlock.

@matisaul
Copy link

matisaul commented Jun 24, 2020

I opened the door 3 minutes ago, this is what I get:

zigbee2mqtt:debug 2020-06-24 17:45:32: Received Zigbee message from 'Cerradura Principal', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":2,"opereventcode":2,"userid":0,"pin":0,"zigbeelocaltime":1770453239,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2020-06-24 17:45:32: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal', payload '{"linkquality":26,"action":"unlock","action_user":0,"action_source":2}'
zigbee2mqtt:info  2020-06-24 17:45:32: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal', payload '{"linkquality":26,"action":""}'
zigbee2mqtt:info  2020-06-24 17:45:32: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal/action', payload 'unlock'
zigbee2mqtt:debug 2020-06-24 17:45:47: Received Zigbee message from 'Cerradura Principal', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":2,"opereventcode":10,"userid":0,"pin":0,"zigbeelocaltime":1770453239,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2020-06-24 17:45:47: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal', payload '{"linkquality":15,"action":"auto_lock","action_user":0,"action_source":2}'
zigbee2mqtt:info  2020-06-24 17:45:47: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal', payload '{"linkquality":15,"action":""}'
zigbee2mqtt:info  2020-06-24 17:45:47: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal/action', payload 'auto_lock'

This is what I get in HA:

image

@ddahya
Copy link

ddahya commented Jun 25, 2020

@dinhchinh82 are you able to provide details on the Zigbee Module that you used for the YDM4109+

@Koenkk
Copy link
Owner

Koenkk commented Jun 27, 2020

@matisaul I would expect the lock to confirm the lockState with and attributeReport. The problem of using commandOperationEventNotification is that it can give an incorrect state. (see #3582).

Can you try to reconfigure your lock via https://www.zigbee2mqtt.io/information/mqtt_topics_and_message_structure.html#zigbee2mqttbridgeconfigure and see if it works after that? Make sure to wake the lock up before executing this command.

@matisaul
Copy link

matisaul commented Jul 1, 2020

@Koenkk After reconfigure the lock, I get correctly the status (lock/unlock) but fails with action_user and action_source. It seems that the addon is publishing twice the info, the first one with all the data, and the second one without action information (in HA don't get action_source and action_user):

zigbee2mqtt:debug 2020-07-01 10:00:17: Received MQTT message on 'zigbee2mqtt/bridge/configure' with data 'Cerradura Principal'
zigbee2mqtt:info  2020-07-01 10:00:17: Configuring 'Cerradura Principal'
zigbee2mqtt:info  2020-07-01 10:00:58: Successfully configured 'Cerradura Principal'
zigbee2mqtt:debug 2020-07-01 09:39:40: Received Zigbee message from 'Cerradura Principal', type 'commandOperationEventNotification', cluster 'closuresDoorLock', data '{"opereventsrc":2,"opereventcode":10,"userid":0,"pin":0,"zigbeelocaltime":1770453363,"data":0}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2020-07-01 09:39:40: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal', payload '{"linkquality":44,"state":"UNLOCK","lock_state":"unlocked","action":"auto_lock","action_user":0,"action_source":2}'
zigbee2mqtt:info  2020-07-01 09:39:40: MQTT publish: topic 'zigbee2mqtt/Cerradura Principal', payload '{"linkquality":44,"state":"UNLOCK","lock_state":"unlocked","action":""}'

Maybe It is a problem with the auto_lock feature...

@matisaul
Copy link

matisaul commented Jul 1, 2020

Now I'm getting a lot of this messages:

zigbee2mqtt:debug 2020-07-01 11:43:06: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-07-01 11:43:11: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-07-01 11:43:15: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-07-01 11:43:20: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-07-01 11:43:25: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-07-01 11:43:30: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-07-01 11:43:35: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-07-01 11:43:40: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0
zigbee2mqtt:debug 2020-07-01 11:43:49: Received Zigbee message from 'Cerradura Principal', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"manufacturerCode":4491,"imageType":0,"fileVersion":9}' from endpoint 1 with groupID 0

@Koenkk
Copy link
Owner

Koenkk commented Jul 1, 2020

@matisaul the empty action after the auto_lock action is expected, otherwise you cannot create automations based on this value in Home Assistant. (more details can be found here: #959 (comment))

@matisaul
Copy link

matisaul commented Jul 1, 2020

But I think that show the"auto-lock" feature when you are "unlocking" the door doesn't any sense... I need to use action_user and action_source on my automations, but I can't because this attributes disappears after less than 1 second after unlock the door.

@Koenkk
Copy link
Owner

Koenkk commented Jul 3, 2020

@matisaul it depends how you use it, in my opinion it's shouldn't be persistent as it only applies at the moment the lock is done, after e.g. 10 minutes it doesn't make sense anymore. You should be able to do all kinds of stuff with this value in an automation. In case you want to persist it set it into a input_text inside an automation.

@matisaul
Copy link

matisaul commented Jul 6, 2020

@Koenkk Sadly, I can't do that, because action_user and action_source attributes disappears after less than once second (not just the value, but whole attributes). HA is not able to trigger any automation in that short time.
Once again, I think that attributes need to be always on the entity, and should not be erased, Is there anything I can do to make it work again? I feel my lock is dumb right now (I can't know who is opening the door, just if is open or closed).

@Koenkk
Copy link
Owner

Koenkk commented Jul 7, 2020

@matisaul AFAIK Home Assistant should handle all messages, even when appearing for a short time.

I've created a small example automation (not tested), first create the input_text.lock_last_user_action and use this:

automation:
  - alias: Persist last lock last action user
    trigger:
      platform: mqtt
      topic: 'zigbee2mqtt/<FRIENDLY_NAME>'
    condition:
      condition: template
      value_template: '{{ trigger.payload_json.action_user is defined }}'
    action:
      - service: input_text.set_value
        data_template:
          entity_id: input_text.lock_last_user_action
          value: "{{ trigger.payload_json.action_user }}"

@matisaul
Copy link

matisaul commented Jul 7, 2020

Wow! Thanks @Koenkk . That did the trick!

Thanks for all your patience!

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

5 participants