search

Koenkk / zigbee2mqtt

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

Version 1.16.0 overall slow network response #4884

Closed Imaginous closed 3 years ago

Imaginous commented 3 years ago

What happened

When pressing a zigbee button or sending in MQTT command to a lamp takes about 1.5 seconds. When sending 2 commands directly after one another to turn on 2 lights. They will turn on about 1.5 - 2.0 seconds after each other.

This started since version 1.16.0. Copied back my 1.15.0 version and everything runs smoothly again.

What did you expect to happen

Thate the commands would be almost instantanious.

How to reproduce it (minimal and precise)

Upgrade to version 1.16.0 -> zigbee network becomes slow. Restore to version 1.15.0 -> zigbee network is fast again.

No devices have been added or changed between the upgrade.

Debug info

Zigbee2MQTT version: 1.16.0 Adapter hardware: Conbee II Adapter firmware version: 0x26660700 Hardware: Raspberry Pi 3

Rene-Sackers commented 3 years ago

@Koenkk is this available yet? I can't find any relevant commits or pull requests and I see no dev branch. I reinstalled edge by following the instructions, including reloading the add-ons page, I configured the device_delay to several different values, but no effect.

Edit: nvm, I found the dev branch, but I'm still unsure of what exact version I am running the add-on on.

Koenkk commented 3 years ago

@Rene-Sackers can you provide the herdsman debug log of starting Zigbee2MQTT?

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

Rene-Sackers commented 3 years ago

@Rene-Sackers can you provide the herdsman debug log of starting Zigbee2MQTT?

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

I'm running it as an addon on HASS, the link you have says Set "zigbee_herdsman_debug": true in the configuration., but I don't know what the configuration is. This is JSON, but the configuration that I know is the yaml file you get under the addon in the HASS interface. What configuration file am I supposed to change?

Rene-Sackers commented 3 years ago

I managed to enable it by sending the MQTT message, but how do I read the herdsman logs? https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging states Important: this is not logged to the log files and is only available on the STDOUT.. I can attach to the zigbee2mqtt docker container, but that only gives me the same log lines that I do see in the log files. How do I get the STDOUT of herdsman?

DenisBY commented 3 years ago

I managed to enable it by sending the MQTT message, but how do I read the herdsman logs? https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging states Important: this is not logged to the log files and is only available on the STDOUT.. I can attach to the zigbee2mqtt docker container, but that only gives me the same log lines that I do see in the log files. How do I get the STDOUT of herdsman?

Try to use docker logs <container_id>

Rene-Sackers commented 3 years ago

Managed to enable it. So apparently you do just add it to the yaml configuration file in yaml format. Logs:

Zigbee2MQTT:info  2020-12-11 14:26:59: MQTT publish: topic 'zigbee2mqtt/dinner_table_lights_x', payload '{"brightness":13,"color":{"x":0.509709837429556,"y":0.415043632474748},"color_temp":463,"state":"ON"}'
Zigbee2MQTT:info  2020-12-11 14:26:59: MQTT publish: topic 'zigbee2mqtt/dinner_table_right', payload '{"brightness":13,"color":{"x":0.509709837429556,"y":0.415043632474748},"color_temp":463,"linkquality":188,"state":"ON"}'
2020-12-11T14:26:59.853Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10101110
2020-12-11T14:26:59.853Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T14:26:59.875Z zigbee-herdsman:deconz:driver delay sending of APS Request
2020-12-11T14:26:59.875Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 52
2020-12-11T14:26:59.876Z zigbee-herdsman:deconz:driver query aps data confirm
2020-12-11T14:26:59.878Z zigbee-herdsman:deconz:frameParser DATA_INDICATION RESPONSE - seqNr. 52 srcAddr: 0xabd9 destAddr: 0x0 profile id: 0x104 cluster id: 0x6
2020-12-11T14:26:59.878Z zigbee-herdsman:deconz:frameParser response payload: 8,11,11,1,0
2020-12-11T14:26:59.878Z zigbee-herdsman:deconz:adapter resolve data request with transSeq Nr.: 11
2020-12-11T14:26:59.878Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":11,"manufacturerCode":null,"commandIdentifier":11},"Payload":{"cmdId":1,"statusCode":0}},"address":43993,"endpoint":1,"linkquality":188,"groupID":null}'
2020-12-11T14:26:59.878Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T14:26:59.878Z zigbee-herdsman:deconz:adapter response received
Zigbee2MQTT:info  2020-12-11 14:26:59: MQTT publish: topic 'zigbee2mqtt/dinner_table_center', payload '{"brightness":13,"color":{"x":0.509709837429556,"y":0.415043632474748},"color_temp":463,"linkquality":188,"state":"ON"}'
2020-12-11T14:26:59.975Z zigbee-herdsman:deconz:driver delay sending of APS Request
2020-12-11T14:26:59.975Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 53
2020-12-11T14:26:59.977Z zigbee-herdsman:deconz:driver query aps data confirm
2020-12-11T14:26:59.977Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0xabd9 request id: 11 confirm status: 0
2020-12-11T14:26:59.977Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T14:26:59.978Z zigbee-herdsman:deconz:adapter sendZclFrameToEndpoint - message send with transSeq Nr.: 11
2020-12-11T14:27:00.075Z zigbee-herdsman:deconz:driver DATA_REQUEST - destAddr: 0xbe63 EP:1 SeqNr. 49 request id: 12
2020-12-11T14:27:00.076Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 54
2020-12-11T14:27:00.078Z zigbee-herdsman:deconz:frameParser DATA_REQUEST RESPONSE - request id: 12 status: 0
2020-12-11T14:27:00.078Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T14:27:00.078Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - seqNr.: 54 status: 5
2020-12-11T14:27:00.086Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10100110
2020-12-11T14:27:00.086Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T14:27:00.155Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10101110
2020-12-11T14:27:00.155Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T14:27:00.177Z zigbee-herdsman:deconz:driver query aps data confirm
2020-12-11T14:27:00.277Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 55
2020-12-11T14:27:00.277Z zigbee-herdsman:deconz:driver query aps data indication
2020-12-11T14:27:00.279Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0xbe63 request id: 12 confirm status: 0
2020-12-11T14:27:00.279Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T14:27:00.279Z zigbee-herdsman:deconz:adapter sendZclFrameToEndpoint - message send with transSeq Nr.: 12
2020-12-11T14:27:00.279Z zigbee-herdsman:deconz:driver query aps data indication
2020-12-11T14:27:00.377Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 56
2020-12-11T14:27:00.379Z zigbee-herdsman:deconz:frameParser DATA_INDICATION RESPONSE - seqNr. 56 srcAddr: 0xbe63 destAddr: 0x0 profile id: 0x104 cluster id: 0x6
2020-12-11T14:27:00.379Z zigbee-herdsman:deconz:frameParser response payload: 8,12,11,1,0
2020-12-11T14:27:00.379Z zigbee-herdsman:deconz:adapter resolve data request with transSeq Nr.: 12
2020-12-11T14:27:00.379Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":12,"manufacturerCode":null,"commandIdentifier":11},"Payload":{"cmdId":1,"statusCode":0}},"address":48739,"endpoint":1,"linkquality":188,"groupID":null}'
2020-12-11T14:27:00.379Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T14:27:00.379Z zigbee-herdsman:deconz:adapter response received
Zigbee2MQTT:info  2020-12-11 14:27:00: MQTT publish: topic 'zigbee2mqtt/dinner_table_left', payload '{"brightness":13,"color":{"x":0.509709837429556,"y":0.415043632474748},"color_temp":463,"linkquality":188,"state":"ON"}'
2020-12-11T14:27:00.478Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 57
2020-12-11T14:27:00.480Z zigbee-herdsman:deconz:frameParser DATA_INDICATION RESPONSE - seqNr.: 57 status: 5
2020-12-11T14:27:05.193Z zigbee-herdsman:deconz:driver send read device state from queue. seqNr: 58
2020-12-11T14:27:05.196Z zigbee-herdsman:deconz:frameParser device state: 10100010
2020-12-11T14:27:05.198Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1

I have dinnertable(left/right/center) hooked up to a single group. They turn on one after another with about a 0.5s delay between each.

Koenkk commented 3 years ago

@Rene-Sackers now provide the same lgo when starting zigbee2mqtt

Rene-Sackers commented 3 years ago

@Rene-Sackers now provide the same lgo when starting zigbee2mqtt

Not sure exactly what part you are looking for, but here's all of the herdsman related logs from the start of the addon:

Zigbee2MQTT:info  2020-12-11 18:24:38: Zigbee: disabling joining new devices.
2020-12-11T18:24:38.510Z zigbee-herdsman:controller:log Disable joining
2020-12-11T18:24:38.512Z zigbee-herdsman:deconz:adapter zclFrame to all - zclFrame.payload:
2020-12-11T18:24:38.514Z zigbee-herdsman:deconz:adapter { options: 11, commisioningWindow: 0 }
2020-12-11T18:24:38.514Z zigbee-herdsman:deconz:adapter sendZclFrameToAll - message send
Zigbee2MQTT:info  2020-12-11 18:24:38: Started frontend on port 0.0.0.0:8099
2020-12-11T18:24:38.600Z zigbee-herdsman:deconz:driver DATA_REQUEST - destAddr: 0xfffd EP:242 SeqNr. 8 request id: 1
2020-12-11T18:24:38.602Z zigbee-herdsman:deconz:frameParser DATA_REQUEST RESPONSE - request id: 1 status: 0
2020-12-11T18:24:38.603Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T18:24:38.674Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10100110
2020-12-11T18:24:38.674Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T18:24:38.700Z zigbee-herdsman:deconz:driver query aps data confirm
2020-12-11T18:24:38.800Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 9
2020-12-11T18:24:38.803Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0xfffd request id: 1 confirm status: 0
2020-12-11T18:24:38.803Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T18:24:38.901Z zigbee-herdsman:deconz:driver DATA_REQUEST - destAddr: 0xfffc EP:0 SeqNr. 10 request id: 2
2020-12-11T18:24:38.903Z zigbee-herdsman:deconz:frameParser DATA_REQUEST RESPONSE - request id: 2 status: 0
2020-12-11T18:24:38.903Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T18:24:38.975Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10100110
2020-12-11T18:24:38.975Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T18:24:39.002Z zigbee-herdsman:deconz:driver query aps data confirm
2020-12-11T18:24:39.102Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 11
2020-12-11T18:24:39.104Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0xfffc request id: 2 confirm status: 0
2020-12-11T18:24:39.104Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2020-12-11T18:24:39.105Z zigbee-herdsman:deconz:adapter PERMIT_JOIN - 0 seconds
Zigbee2MQTT:info  2020-12-11 18:24:39: Connecting to MQTT server at mqtt://core-mosquitto:1883
2020-12-11T18:24:39.203Z zigbee-herdsman:deconz:driver send write parameter request from queue. seqNr: 12 paramId: 33 param: 0
2020-12-11T18:24:39.206Z zigbee-herdsman:deconz:frameParser write parameter response - parameter id: 33 - status: 0

...

Zigbee2MQTT:info  2020-12-11 18:24:39: MQTT publish: topic 'zigbee2mqtt/hallway_motion', payload '{"battery":100,"battery_low":false,"occupancy":false,"tamper":false}'
2020-12-11T18:24:39.408Z zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 13 paramId: 5
2020-12-11T18:24:39.429Z zigbee-herdsman:deconz:frameParser PANID: 1a62
2020-12-11T18:24:39.507Z zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 14 paramId: 11
2020-12-11T18:24:39.509Z zigbee-herdsman:deconz:frameParser APS_EXT_PANID: 0xdddddddddddddddd
2020-12-11T18:24:39.608Z zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 15 paramId: 28
2020-12-11T18:24:39.610Z zigbee-herdsman:deconz:frameParser CHANNEL: 11
2020-12-11T18:24:39.709Z zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 16 paramId: 24
2020-12-11T18:24:39.711Z zigbee-herdsman:deconz:frameParser NETWORK_KEY: hidden
Zigbee2MQTT:info  2020-12-11 18:24:39: MQTT publish: topic 'zigbee2mqtt/bridge/info', payload '{"commit":"d0132a4","config":{"advanced":{"adapter_concurrent":null,"adapter_delay":null,"availability_blacklist":[],"availability_blocklist":[],"availability_passlist":[],"availability_timeout":0,"availability_whitelist":[],"cache_state":true,"cache_state_persistent":true,"cache_state_send_on_startup":true,"channel":11,"elapsed":false,"ext_pan_id":[221,221,221,221,221,221,221,221],"homeassistant_discovery_topic":"homeassistant","homeassistant_legacy_triggers":true,"homeassistant_status_topic":"hass/status","last_seen":"disable","legacy_api":true,"log_directory":"/share/zigbee2mqtt-edge/log/%TIMESTAMP%","log_file":"log.txt","log_level":"info","log_output":["console","file"],"log_rotation":true,"log_syslog":{},"pan_id":6754,"report":false,"soft_reset_timeout":0,"timestamp_format":"YYYY-MM-DD HH:mm:ss"},"ban":[],"blocklist":[],"device_options":{},"devices":{"0x588e81fffee74843":{"friendly_name":"dinner_table_center"},"0x588e81fffeedf006":{"friendly_name":"hallway"},"0x588e81fffeedf149":{"friendly_name":"kitchen"},"0x588e81fffef35f19":{"friendly_name":"extended_kitchen"},"0x588e81fffefca545":{"friendly_name":"dinner_table_left"},"0x588e81fffefca563":{"friendly_name":"dinner_table_right"},"0x60a423fffee67d5a":{"friendly_name":"ikea_on_off_remote_1"},"0xbc33acfffe460d76":{"friendly_name":"living_room_lamp"},"0xbc33acfffe661d30":{"friendly_name":"kitchen_motion"},"0xbc33acfffea77b44":{"friendly_name":"ikea_dimmer_remote_1"},"0xec1bbdfffea80880":{"friendly_name":"hallway_motion"},"0xec1bbdfffeab9f94":{"friendly_name":"lidl_dimmer_remote_1"}},"experimental":{"new_api":true,"output":"json"},"external_converters":[],"frontend":{"port":8099},"groups":{"1":{"devices":["0x588e81fffee74843/1","0x588e81fffefca545/1","0x588e81fffefca563/1"],"friendly_name":"dinner_table_lights_x"}},"homeassistant":true,"map_options":{"graphviz":{"colors":{"fill":{"coordinator":"#e04e5d","enddevice":"#fff8ce","router":"#4ea3e0"},"font":{"coordinator":"#ffffff","enddevice":"#000000","router":"#ffffff"},"line":{"active":"#009900","inactive":"#994444"}}}},"mqtt":{"base_topic":"zigbee2mqtt","force_disable_retain":false,"include_device_information":false,"server":"mqtt://core-mosquitto:1883","user":"mqtt"},"passlist":[],"permit_join":false,"queue":{},"serial":{"adapter":"deconz","disable_led":false,"port":"/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2252724-if00"},"whitelist":[],"zigbee_herdsman_debug":true},"coordinator":{"meta":{"maintrel":0,"majorrel":38,"minorrel":88,"product":0,"revision":"0x26580700","transportrev":0},"type":"ConBee2/RaspBee2"},"log_level":"info","network":{"channel":11,"extended_pan_id":"0xdddddddddddddddd","pan_id":6754},"permit_join":false,"version":"1.16.2-dev"}'

...

Zigbee2MQTT:info  2020-12-11 18:24:39: MQTT publish: topic 'zigbee2mqtt/bridge/groups', payload '[{"friendly_name":"dinner_table_lights_x","id":1,"members":[{"endpoint":1,"ieee_address":"0x588e81fffee74843"},{"endpoint":1,"ieee_address":"0x588e81fffefca545"},{"endpoint":1,"ieee_address":"0x588e81fffefca563"}]},{"friendly_name":"default_bind_group","id":901,"members":[]}]'
2020-12-11T18:24:39.810Z zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 17 paramId: 5
2020-12-11T18:24:39.812Z zigbee-herdsman:deconz:frameParser PANID: 1a62
2020-12-11T18:24:39.910Z zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 18 paramId: 11
2020-12-11T18:24:39.911Z zigbee-herdsman:deconz:frameParser APS_EXT_PANID: 0xdddddddddddddddd
2020-12-11T18:24:40.010Z zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 19 paramId: 28
2020-12-11T18:24:40.012Z zigbee-herdsman:deconz:frameParser CHANNEL: 11
2020-12-11T18:24:40.111Z zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 20 paramId: 24
2020-12-11T18:24:40.112Z zigbee-herdsman:deconz:frameParser NETWORK_KEY: hidden
Zigbee2MQTT:info  2020-12-11 18:24:40: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"commit":"d0132a4","coordinator":{"meta":{"maintrel":0,"majorrel":38,"minorrel":88,"product":0,"revision":"0x26580700","transportrev":0},"type":"ConBee2/RaspBee2"},"log_level":"info","network":{"channel":11,"extendedPanID":"0xdddddddddddddddd","panID":6754},"permit_join":false,"version":"1.16.2-dev"}'

P.S. it looks like this part:

Zigbee2MQTT:info  2020-12-11 18:28:44: MQTT publish: topic 'zigbee2mqtt/bridge/info', payload '{"commit":"d0132a4","config":{"advanced":{"adapter_concurrent":null,"adapter_delay":null

Always says adapter_delay: null, even though I've tried specifying different values in the configuration.

In the logging above, the following value was specified:

advanced:
  log_level: info
  pan_id: 6754
  ...
  adapter_delay: 0

But it's also null in the log if I specify 100, 200, or whatever other value.

Koenkk commented 3 years ago

@Rene-Sackers where do you specify this? It should be specified in the configuration shown on the addon page.

Rene-Sackers commented 3 years ago

@Rene-Sackers where do you specify this? It should be specified in the configuration shown on the addon page.

Yeah, that's where I did it. image

Edit: For reference, here's a video of the delay: https://www.youtube.com/watch?v=8OT3KOkrPso

Imaginous commented 3 years ago

I tested this morning with the latest dev version. There is still a delay with adapter_delay: 0

Also my button action is now failing regularly, I see the following in the log files:

Zigbee2MQTT:info 2020-12-13 10:34:36: MQTT publish: topic 'zigbee2mqtt/Slaapkamer1_Verlichting', payload '{"brightness":0,"brightness_l1":254,"brightness_l2":254,"linkquality":121,"state":"OFF","state_l1":"ON","state_l2":"OFF"}' (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 8) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 10) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 12) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 14) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 16) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 18) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 20) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 22) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 24) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 26) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 28) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 30) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 32) Zigbee2MQTT:info 2020-12-13 10:34:45: MQTT publish: topic 'zigbee2mqtt/Slaapkamer1_Verlichting', payload '{"brightness":0,"brightness_l1":254,"brightness_l2":254,"linkquality":121,"state":"OFF","state_l1":"ON","state_l2":"OFF"}' Zigbee2MQTT:info 2020-12-13 10:34:45: MQTT publish: topic 'zigbee2mqtt/Alarm_Knop_IKEA', payload '{"action":"off","battery":87,"click":"off","linkquality":121,"update":{"state":"idle"},"update_available":false}' Zigbee2MQTT:info 2020-12-13 10:34:46: MQTT publish: topic 'zigbee2mqtt/Slaapkamer1_Verlichting', payload '{"brightness":0,"brightness_l1":254,"brightness_l2":254,"linkquality":121,"state":"OFF","state_l1":"ON","state_l2":"OFF"}' Zigbee2MQTT:info 2020-12-13 10:34:46: MQTT publish: topic 'zigbee2mqtt/Alarm_Knop_IKEA', payload '{"action":"off","battery":87,"click":"off","linkquality":121,"update":{"state":"idle"},"update_available":false}' Zigbee2MQTT:info 2020-12-13 10:34:46: MQTT publish: topic 'zigbee2mqtt/Slaapkamer1_Verlichting', payload '{"brightness":0,"brightness_l1":254,"brightness_l2":254,"linkquality":121,"state":"OFF","state_l1":"OFF","state_l2":"OFF"}' Zigbee2MQTT:info 2020-12-13 10:34:46: MQTT publish: topic 'zigbee2mqtt/Slaapkamer1_Verlichting', payload '{"brightness":0,"brightness_l1":254,"brightness_l2":254,"linkquality":121,"state":"OFF","state_l1":"OFF","state_l2":"OFF"}' Zigbee2MQTT:info 2020-12-13 10:34:47: MQTT publish: topic 'zigbee2mqtt/Slaapkamer1_Verlichting', payload '{"brightness":0,"brightness_l1":254,"brightness_l2":254,"linkquality":121,"state":"OFF","state_l1":"OFF","state_l2":"OFF"}' Zigbee2MQTT:info 2020-12-13 10:34:47: MQTT publish: topic 'zigbee2mqtt/Slaapkamer1_Verlichting', payload '{"brightness":0,"brightness_l1":254,"brightness_l2":254,"linkquality":121,"state":"OFF","state_l1":"OFF","state_l2":"OFF"}' (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 34) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 36) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 38) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 40) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 42) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 44) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 46) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 48) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 50) (node:21898) UnhandledPromiseRejectionWarning: undefined (node:21898) 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: 52) Zigbee2MQTT:error 2020-12-13 10:35:34: Publish 'set' 'brightness' to 'Slaapkamer1_Verlichting' failed: 'Error: Command 0xbc33acfffe6563a7/2 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":0}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) failed (no response received)'

Koenkk commented 3 years ago

Not sure why this doesn't work. @ChrisHae maybe it's better to turn things around here. By default don't do a delay and when a user experiences problems he can set a delay.

ChrisHae commented 3 years ago

Not sure why this doesn't work. @ChrisHae maybe it's better to turn things around here. By default don't do a delay and when a user experiences problems he can set a delay.

@Koenkk Yes I can and will probably do that. But it does not explain why @Rene-Sackers can't set that parameter

Zigbee2MQTT:info 2020-12-11 18:28:44: MQTT publish: topic 'zigbee2mqtt/bridge/info', payload '{"commit":"d0132a4","config":{"advanced":{"adapter_concurrent":null,"adapter_delay":null

it seems the value is not passed to zigbee-herdsman.

In my zigbee-herdsman version there is a debug output that tells the actual value of the parameter passed down to the driver:

Zigbee2MQTT:info 2020-12-15 09:02:23: Starting zigbee-herdsman... Zigbee2MQTT:debug 2020-12-15 09:02:23: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":0},"backupPath":"/opt/zigbee2mqtt/data/coordinator_backup.json","databaseBackupPath":"/opt/zigbee2mqtt/data/database.db.backup","databasePath":"/opt/zigbee2mqtt/data/database.db","network":{"channelList":[15],"extendedPanID":[0,0,0,0,0,0,0,0],"networkKey":"HIDDEN","panID":6754},"serialPort":{"adapter":"deconz","path":null}}' zigbee-herdsman:adapter No path provided, auto detecting path +0ms zigbee-herdsman:adapter Auto detected path '/dev/ttyACM0' from adapter 'DeconzAdapter' +201ms zigbee-herdsman:deconz:driver Set delay to 0 +0ms

I don't know how you can fix this. Perhaps try to reinstall mqtt? The error happens in z2mqtt and not in zigbee-herdsman I think.

The oher question is why @Imaginous has so many UnhandledPromiseRejectionWarnings. I don't changed much other code. And when I'm testing I can use mqtt explorer the toggle my lights with no visible delay and there are no error messages.

So @Imaginous I would realy need zigbee-herdsman debug logs like Rene-Sackers posted it. https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging

Koenkk commented 3 years ago

@ChrisHae It seems this doesn't work because every option needs to be added manually to the addon (https://github.com/danielwelch/hassio-zigbee2mqtt/issues/493). @Rene-Sackers please create an issue there.

Imaginous commented 3 years ago

@ChrisHae you can download the herdsman log here: Herdsman log

I clicked the Alarm_Knop_IKEA (10:31:56 which is 1 hour ahead of other log entries, wrong time notation) to turn on two lights in device Slaapkamer1_Verlichting (10:32:11) it is on.

There is happening a lot ;) I can't completely understand what is going on.

ChrisHae commented 3 years ago

From 10:31:56 to 10:32:11 is 15 seconds. But it is not the actual perceived delay? I can see in the logs the time difference from sending the first command to receiving the confirmation of the second command is 400ms. Around 300ms between confirmation of the first to confirmation of the second command. After that there is much traffic going on...

How long is the delay you perceive with your eyes?

Perhaps the long actual delay is because of repeated bind requests.

Imaginous commented 3 years ago

@ChrisHae The percieved delay is less then a second. It's just the fact that it isn't there with version 1.15.0.

I don't understand what the traffic could be after turning it on/off. I don't see it with the older version.

ndfred commented 3 years ago

I am also chasing this here, if you want zero delay (which is working really well for me so far) there is a little hack you can just edit node_modules/zigbee-herdsman/dist/adapter/deconz/driver/driver.js manually: https://github.com/Koenkk/zigbee-herdsman/issues/273

Testing of that configuration is welcome, please comment over there if you are trying this out!

juslex commented 3 years ago

I will leave my feedback. I'm using version 1.16.2-dev commit: 2468d61. I put delay 0 in the settings and noticed that the speed returned to what it was before in version 1.15.0. Because I also have a zzh !, I decided to replace the conbee II with him due to this issue here: https://github.com/Koenkk/zigbee2mqtt/issues/4461 In zzh it is clear that there is less latency in the responses of the devices. The xiaomi and sonoff PIR sensors and the respective automations connecting the lights on the zemismart switches are faster on the zzh than on the conbee II.

ndfred commented 3 years ago

I've been digging a little deeper into it, and it turns out only READY_TO_SEND_TIMEOUT is ever updated when you set your delay value in the config file, and there will still be a potential 100ms delay to process responses and another 100ms before sending status requests (which Z2M does to check what button was pressed on a remote for instance).

See my comment here for more details and a temporary fix before I get a PR out: https://github.com/Koenkk/zigbee-herdsman/issues/273#issuecomment-750343636

Imaginous commented 3 years ago

Today I have tested version 1.17.0, with the adapter_delay: 0 setting. It is still slow.

@ndfred, can you post the exact steps to do the driver hack... and @ChrisHae is it possible to implement this hack when a value of 0 is applied for the adapter delay?

Imaginous commented 3 years ago

I did some testing @ndfred and @ChrisHae. I found out that the following values gave a satisfying result without an extremely high CPU load: setDelay(delay) { this.DELAY = delay; if (delay === 0) { this.HANDLE_DEVICE_STATUS_DELAY = 10; // device status will be handelt immediately in handler function this.PROCESS_APS_QUEUES_DELAY = 1; this.READY_TO_SEND_TIMEOUT = 1; } else if (delay <= 50) { this.READY_TO_SEND_TIMEOUT = 50; this.PROCESS_APS_QUEUES_DELAY = 50; this.HANDLE_DEVICE_STATUS_DELAY = 10; } else if (delay > 1200) { this.READY_TO_SEND_TIMEOUT = 1200; } else { this.READY_TO_SEND_TIMEOUT = delay; } }

So I changed the values to: HANDLE_DEVICE_STATUS_DELAY = 10 PROCESS_APS_QUEUES_DELAY = 1 READY_TO_SEND_TIMEOUT = 1

Setting the values to 0 would increase the CPU load dramatically.

@ChrisHae, I think it would be a good idea if you adopt these values for an adaptor_delay: 0 setting. Like the code above.

Imaginous commented 3 years ago

I have been busy tweaking the delays. I found that a delay of 5 gives superb performance and low CPU load.

I have altered the driver.js file. It can be downloaded from my server, I think it should be implemented in the next release. In the meantime it can be downloaded: driver.js

Place the "driver.js" file in the following path: /opt/_zigbee2mqtt/node_modules/zigbee-herdsman/dist/adapter/deconz

If it generates too much traffic I might have to remove the link again.

ChrisHae commented 3 years ago

hi, I was absent for a couple of days. Thanks for testing and tweaking. I will look at the changes and implement them soon.

ChrisHae commented 3 years ago

I have uploaded the new delay settings PROCESS_APS_QUEUES_DELAY = 5 READY_TO_SEND_TIMEOUT = 1 The are active when you set adapter_delay = 0 in the configuration.yaml HANDLE_DEVICE_STATUS_DELAY is not needed to be altered because it is an dummy value when adapter_delay is set to 0. The device status is handled immediatly without an delay when a new message is received.

juslex commented 3 years ago

Hello, guys.

I'm thinking about going back to conbee 2. Did this fix have an effect on decreasing latency?

Imaginous commented 3 years ago

Hello, guys.

I'm thinking about going back to conbee 2. Did this fix have an effect on decreasing latency?

If you download my fix it has very low latency. I don't know when @Koenkk will implement it in regular releases.

juslex commented 3 years ago

Hello, guys. I'm thinking about going back to conbee 2. Did this fix have an effect on decreasing latency?

If you download my fix it has very low latency. I don't know when @Koenkk will implement it in regular releases.

thank you very much for the feedback. I have conbee2 and zzh, however each has a different problem than the routers on my network (zemismart 3 and 2 gangs wall switch). Unfortunately the problem involving zzh cannot be solved, since the problem in conbee has a hope of being solved. I have 50 devices and in the last few months there have been 5 or 6 total repairs changing the coordinator. In these comings and goings, even using conbee in version 1.15, I noticed that his latency is higher than zzh. Are they both at the same speed now?

Imaginous commented 3 years ago

I can't comment if they are on the same speed now... I only can tell that with my patch it is faster then it was in 1.15.

Koenkk commented 3 years ago

Fix wil be in next z2m version (release on 1 February)

juslex commented 3 years ago

Fix wil be in next z2m version (release on 1 February)

The @Imaginous fix is alive now in dev branch?

Koenkk commented 3 years ago

No, only fixes from @ChrisHae

juslex commented 3 years ago

@Imaginous did you test the @ChrisHae fix?

Imaginous commented 3 years ago

I did not test the latest @ChrisHae fix. I trust him, as he said to have my changes incorporated.

Will test again with the next official build of February 1st.

juslex commented 3 years ago

I did not test the latest @ChrisHae fix. I trust him, as he said to have my changes incorporated.

Will test again with the next official build of February 1st.

Very good job @Koenkk @ChrisHae @Imaginous Conbee 2 is now faster than zzh.

There's just one more thing to Conbee become my official Coordinator, the fix mentioned here (https://github.com/Koenkk/zigbee2mqtt/issues/4461#) and it's done !

Thank you so much

Imaginous commented 3 years ago

For some reason I still have speed problems with update V1.17.1

I have replaced the driver.js file with my modified one and it is blazing fast again.

The only difference I see is in my code:

    this.DELAY = 0;
    this.READY_TO_SEND_TIMEOUT = 1;
    this.HANDLE_DEVICE_STATUS_DELAY = 5;
    this.PROCESS_APS_QUEUES_DELAY = 5;
    const that = this;
    setInterval(() => { that.processQueue(); }, 5); // fire non aps requests
    setInterval(() => { that.processBusyQueue(); }, 5); // check timeouts for non aps requests
    setInterval(() => { that.processApsQueue(); }, this.PROCESS_APS_QUEUES_DELAY); // fire aps request
    setInterval(() => { that.processApsBusyQueue(); }, 5); // check timeouts for all open aps requests

Versus this in Chris' code:

    this.DELAY = 100;
    this.READY_TO_SEND_TIMEOUT = 300;
    this.HANDLE_DEVICE_STATUS_DELAY = 100;
    this.PROCESS_APS_QUEUES_DELAY = 100;
    const that = this;
    setInterval(() => { that.processQueue(); }, 100); // fire non aps requests
    setInterval(() => { that.processBusyQueue(); }, 1000); // check timeouts for non aps requests
    setInterval(() => { that.processApsQueue(); }, this.PROCESS_APS_QUEUES_DELAY); // fire aps request
    setInterval(() => { that.processApsBusyQueue(); }, 1000); // check timeouts for all open aps requests

For some reason the code of @ChrisHae is fast or the first 2 times pressing my light button but becomes slower after pressing it multiple times. Then eventually it will freeze for about 10 seconds and will start processing the "missed" button presses.

With my timings it stays fast and I don't experience any negative side effects.

Maybe the above timings can also be altered with the 0 delay option... or just implement them like I did.

ChrisHae commented 3 years ago

@juslex which value do you here (line94)?

setInterval(() => { that.deviceStateRequest()
                            .then(result => {})
                            .catch(error => {}); }, 10000);
Imaginous commented 3 years ago

@juslex which value do you here (line94)?

setInterval(() => { that.deviceStateRequest()
                            .then(result => {})
                            .catch(error => {}); }, 10000);

@ChrisHae, I have the same value in my altered driver.js

juslex commented 3 years ago

@juslex which value do you here (line94)?

setInterval(() => { that.deviceStateRequest()
                            .then(result => {})
                            .catch(error => {}); }, 10000);

@ChrisHae same value here too 560BACF8-DAD4-4D9C-ACCA-9A60E4D6BAE6

ChrisHae commented 3 years ago

@Imaginous So I would like to understand the reason for your 10 seconds freeze. Because I have the same values as you suggested that have an impact on the speed. The other values that you changed does not affect the sending and receiving of commands. And none of the values would explain a 10 seconds freeze. Also my tests did not show this behaviour.

So my question would be: does the freeze happens always when you pressing the switch multiple times or is it a rare event? And could you please provide a zigbee-herdsman debug log? https://www.zigbee2mqtt.io/information/debug.html I need the output of zigbee-herdsman:deconz:driver from the logs.

@juslex did you also experience this behaviour?

Imaginous commented 3 years ago

@ChrisHae The 10 second delay does not always happen. But it seems if multiple events are triggered in a short time span the delay slowly gets longer till a certain point. Then is takes for about 10 seconds and seems that all backlogged packages are processed.

With my settings I can't recreate this. I can click my button as many times as I like and the lights keep responding.

srnoth commented 3 years ago

Can confirm the same behavior @Imaginous is describing. First button press is instant but you then press more buttons within a few seconds they are either delayed by a couple seconds or missed altogether.

(On version 1.17.1 with adapter_delay: 0 set)

juslex commented 3 years ago

Can confirm the same behavior @Imaginous is describing. First button press is instant but you then press more buttons within a few seconds they are either delayed by a couple seconds or missed altogether.

(On version 1.17.1 with adapter_delay: 0 set)

same thing here

ChrisHae commented 3 years ago

Ok, I have adapted all values and set the default adapter_delay to 0. Lets wait for new release.

Koenkk commented 3 years ago

@ChrisHae in latest dev now. (https://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html)

snippem commented 3 years ago

Hi wanted to test the adjustments in the adapterdelay settings and updated the dev coming from a build yesterday. Now my setup does not start anymore. see the log:

Zigbee2MQTT:info 2021-02-09 09:34:27: MQTT publish: topic 'homeassistant/sensor/0x842e14fffe3daeed/energy/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"device":{"identifiers":["zigbee2mqtt_0x842e14fffe3daeed"],"manufacturer":"TuYa","model":"10A UK or 16A EU smart plug (TS0121_plug)","name":"eettafel apparaten","sw_version":"Zigbee2MQTT 1.17.1-dev"},"device_class":"energy","json_attributes_topic":"zigbee2mqtt/eettafel apparaten","name":"eettafel apparaten energy","state_topic":"zigbee2mqtt/eettafel apparaten","unique_id":"0x842e14fffe3daeed_energy_zigbee2mqtt","unit_of_measurement":"kWh","value_template":"{{ value_json.energy }}"}' Zigbee2MQTT:info 2021-02-09 09:34:27: MQTT publish: topic 'homeassistant/sensor/0x842e14fffe3daeed/power_outage_memory/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"device":{"identifiers":["zigbee2mqtt_0x842e14fffe3daeed"],"manufacturer":"TuYa","model":"10A UK or 16A EU smart plug (TS0121_plug)","name":"eettafel apparaten","sw_version":"Zigbee2MQTT 1.17.1-dev"},"json_attributes_topic":"zigbee2mqtt/eettafel apparaten","name":"eettafel apparaten power outage memory","state_topic":"zigbee2mqtt/eettafel apparaten","unique_id":"0x842e14fffe3daeed_power_outage_memory_zigbee2mqtt","value_template":"{{ value_json.power_outage_memory }}"}' Zigbee2MQTT:info 2021-02-09 09:34:27: MQTT publish: topic 'homeassistant/sensor/0x842e14fffe3daeed/linkquality/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"device":{"identifiers":["zigbee2mqtt_0x842e14fffe3daeed"],"manufacturer":"TuYa","model":"10A UK or 16A EU smart plug (TS0121_plug)","name":"eettafel apparaten","sw_version":"Zigbee2MQTT 1.17.1-dev"},"icon":"mdi:signal","json_attributes_topic":"zigbee2mqtt/eettafel apparaten","name":"eettafel apparaten linkquality","state_topic":"zigbee2mqtt/eettafel apparaten","unique_id":"0x842e14fffe3daeed_linkquality_zigbee2mqtt","unit_of_measurement":"lqi","value_template":"{{ value_json.linkquality }}"}' Zigbee2MQTT:error 2021-02-09 09:35:21: Failed to disable reporting for '0x00158d0004147a7e' - Error: Unbind 0x00158d0004147a7e/1 genOnOff from '0x00212effff05221b/1' failed (waiting for response TIMEOUT) at DeconzAdapter. (/app/node_modules/zigbee-herdsman/dist/adapter/deconz/adapter/deconzAdapter.js:755:23) at Generator.throw () at rejected (/app/node_modules/zigbee-herdsman/dist/adapter/deconz/adapter/deconzAdapter.js:25:65) at runMicrotasks () at runNextTicks (internal/process/task_queues.js:58:5) at processTimers (internal/timers.js:494:9) Zigbee2MQTT:error 2021-02-09 09:35:39: Publish 'set' 'brightness' to 'keuken werkblad' failed: 'Error: Command 0x90fd9ffffe17ea2a/1 genLevelCtrl.moveToLevelWithOnOff({"level":26,"transtime":20}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (no response received)' Zigbee2MQTT:info 2021-02-09 09:35:39: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"Publish 'set' 'brightness' to 'keuken werkblad' failed: 'Error: Command 0x90fd9ffffe17ea2a/1 genLevelCtrl.moveToLevelWithOnOff({\"level\":26,\"transtime\":20}, {\"timeout\":10000,\"disableResponse\":false,\"disableRecovery\":false,\"disableDefaultResponse\":false,\"direction\":0,\"srcEndpoint\":null,\"reservedBits\":0,\"manufacturerCode\":null,\"transactionSequenceNumber\":null,\"writeUndiv\":false}) failed (no response received)'","meta":{"friendly_name":"keuken werkblad"},"type":"zigbee_publish_error"}' Zigbee2MQTT:error 2021-02-09 09:36:22: Failed to disable reporting for '0x00158d00041477d9' - Error: Unbind 0x00158d00041477d9/1 genOnOff from '0x00212effff05221b/1' failed (waiting for response TIMEOUT) at DeconzAdapter. (/app/node_modules/zigbee-herdsman/dist/adapter/deconz/adapter/deconzAdapter.js:755:23) at Generator.throw () at rejected (/app/node_modules/zigbee-herdsman/dist/adapter/deconz/adapter/deconzAdapter.js:25:65) at runMicrotasks () at runNextTicks (internal/process/task_queues.js:58:5) at processTimers (internal/timers.js:494:9)

Could this be related to the changes made which has been made related with the adapter delay settings?

(running the non dev build now btw and that works)

sjuxax commented 3 years ago

fwiw, I've found that adapter_delay: 30 keeps things working pretty well. This is with the commits from earlier today. When I try with adapter_delay: 0, I get many timeouts and z2m struggles to do anything, and eventually stops responding almost entirely. adapter_delay: 30 seems to keep the adapter happy enough and the lag doesn't really seem noticeable, but even if it was, it's better than not being usable at all, which is what I was experiencing with adapter_delay: 0.

ChrisHae commented 3 years ago

@snippem yes sorry, a bug slipped through while commiting my code yesterday. I have uploaded a fix now. a workaround for now is to use adapter_delay: 1 or any other number in configuration.yaml

Koenkk commented 3 years ago

Fix will be in dev in 1 hour from now.

srnoth commented 3 years ago

Current dev version is still unstable. Even with adapter_delay set to 30 it gets bogged down (especially when adjusting light groups) and eventually crashes. Required physical reboot of the conbee stick.

Going back to version 15 is 99.9% stable. It seems as if the changes made in v16 were solving for a very rare problem and have ended up breaking usability for a much larger group of users. Maybe best to go back to v15 and review what changes are actually needed or not.