First try - lots of errors

[rdehuyss]

Bug Report

What happened

Ikea Tradfri bulbs only sometimes respond

What did you expect to happen

Ikea Tradfri bulbs respond to commands via HomeAssistant

How to reproduce it (minimal and precise)

• using latest via docker-compose
• using a cc2531 flashed by Hans (h4nc) with revision 20190608
• pair 2 ikea GU10 bulbs as described, a repeater and a sensor
• try to control them

  Debug Info

  info  2019-12-31 00:20:09: Logging to console and directory: '/app/data/log/2019-12-31.00-20-09'
  debug 2019-12-31 00:20:09: Loaded state from file /app/data/state.json
  info  2019-12-31 00:20:09: Starting zigbee2mqtt version 1.8.0 (commit #da4d26a)
  info  2019-12-31 00:20:09: Starting zigbee-herdsman...
  debug 2019-12-31 00:20:09: Using zigbee-herdsman with settings: '{"network":{"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":"HIDDEN"},"databasePath":"/app/data/database.db","databaseBackupPath":"/app/data/database.db.backup","backupPath":"/app/data/coordinator_backup.json","serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM1"}}'
  info  2019-12-31 00:20:11: zigbee-herdsman started
  info  2019-12-31 00:20:11: Coordinator firmware version: '{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190608}}'
  debug 2019-12-31 00:20:11: Zigbee network parameters: {"panID":6754,"extendedPanID":"0xdddddddddddddddd","channel":11}
  info  2019-12-31 00:20:11: Currently 4 devices are joined:
  info  2019-12-31 00:20:11: Zigbee Versterker (0x000d6ffffe903bbf): E1746 - IKEA TRADFRI signal repeater (Router)
  info  2019-12-31 00:20:11: Gang PIR (0xccccccfffec78f65): E1525 - IKEA TRADFRI motion sensor (EndDevice)
  info  2019-12-31 00:20:11: 0x000b57fffea82c85 (0x000b57fffea82c85): LED1650R5 - IKEA TRADFRI LED bulb GU10 400 lumen, dimmable (Router)
  info  2019-12-31 00:20:11: 0x000b57fffeb961c0 (0x000b57fffeb961c0): LED1650R5 - IKEA TRADFRI LED bulb GU10 400 lumen, dimmable (Router)
  warn  2019-12-31 00:20:11: `permit_join` set to  `true` in configuration.yaml.
  warn  2019-12-31 00:20:11: Allowing new devices to join.
  warn  2019-12-31 00:20:11: Set `permit_join` to `false` once you joined all devices.
  info  2019-12-31 00:20:11: Zigbee: allowing new devices to join.
  info  2019-12-31 00:20:11: Connecting to MQTT server at mqtt://192.168.1.250
  info  2019-12-31 00:20:11: Connected to MQTT server
  info  2019-12-31 00:20:11: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
  info  2019-12-31 00:20:11: MQTT publish: topic 'zigbee2mqtt/Zigbee Versterker', payload '{"linkquality":21}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'zigbee2mqtt/Gang PIR', payload '{"occupancy":true,"linkquality":49,"battery":100}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'zigbee2mqtt/0x000b57fffea82c85', payload '{"state":"OFF","brightness":61}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'zigbee2mqtt/group_1', payload '{"state":"ON","brightness":61}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'zigbee2mqtt/0x000b57fffeb961c0', payload '{"state":"ON"}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"version":"1.8.0","commit":"da4d26a","coordinator":{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190608}},"log_level":"debug","permit_join":false}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'homeassistant/sensor/0x000d6ffffe903bbf/linkquality/config', payload '{"unit_of_measurement":"-","value_template":"{{ value_json.linkquality }}","state_topic":"zigbee2mqtt/Zigbee Versterker","json_attributes_topic":"zigbee2mqtt/Zigbee Versterker","name":"Zigbee Versterker_linkquality","unique_id":"0x000d6ffffe903bbf_linkquality_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000d6ffffe903bbf"],"name":"Zigbee Versterker","sw_version":"Zigbee2mqtt 1.8.0","model":"TRADFRI signal repeater (E1746)","manufacturer":"IKEA"},"availability_topic":"zigbee2mqtt/bridge/state"}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'homeassistant/binary_sensor/0xccccccfffec78f65/occupancy/config', payload '{"payload_on":true,"payload_off":false,"value_template":"{{ value_json.occupancy }}","device_class":"motion","state_topic":"zigbee2mqtt/Gang PIR","json_attributes_topic":"zigbee2mqtt/Gang PIR","name":"Gang PIR_occupancy","unique_id":"0xccccccfffec78f65_occupancy_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0xccccccfffec78f65"],"name":"Gang PIR","sw_version":"Zigbee2mqtt 1.8.0","model":"TRADFRI motion sensor (E1525)","manufacturer":"IKEA"},"availability_topic":"zigbee2mqtt/bridge/state"}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'homeassistant/sensor/0xccccccfffec78f65/battery/config', payload '{"unit_of_measurement":"%","device_class":"battery","value_template":"{{ value_json.battery }}","state_topic":"zigbee2mqtt/Gang PIR","json_attributes_topic":"zigbee2mqtt/Gang PIR","name":"Gang PIR_battery","unique_id":"0xccccccfffec78f65_battery_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0xccccccfffec78f65"],"name":"Gang PIR","sw_version":"Zigbee2mqtt 1.8.0","model":"TRADFRI motion sensor (E1525)","manufacturer":"IKEA"},"availability_topic":"zigbee2mqtt/bridge/state"}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'homeassistant/sensor/0xccccccfffec78f65/linkquality/config', payload '{"unit_of_measurement":"-","value_template":"{{ value_json.linkquality }}","state_topic":"zigbee2mqtt/Gang PIR","json_attributes_topic":"zigbee2mqtt/Gang PIR","name":"Gang PIR_linkquality","unique_id":"0xccccccfffec78f65_linkquality_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0xccccccfffec78f65"],"name":"Gang PIR","sw_version":"Zigbee2mqtt 1.8.0","model":"TRADFRI motion sensor (E1525)","manufacturer":"IKEA"},"availability_topic":"zigbee2mqtt/bridge/state"}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'homeassistant/light/0x000b57fffea82c85/light/config', payload '{"brightness":true,"schema":"json","command_topic":"zigbee2mqtt/0x000b57fffea82c85/set","state_topic":"zigbee2mqtt/0x000b57fffea82c85","json_attributes_topic":"zigbee2mqtt/0x000b57fffea82c85","name":"0x000b57fffea82c85_light","unique_id":"0x000b57fffea82c85_light_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000b57fffea82c85"],"name":"0x000b57fffea82c85","sw_version":"Zigbee2mqtt 1.8.0","model":"TRADFRI LED bulb GU10 400 lumen, dimmable (LED1650R5)","manufacturer":"IKEA"},"availability_topic":"zigbee2mqtt/bridge/state"}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'homeassistant/sensor/0x000b57fffea82c85/linkquality/config', payload '{"unit_of_measurement":"-","value_template":"{{ value_json.linkquality }}","state_topic":"zigbee2mqtt/0x000b57fffea82c85","json_attributes_topic":"zigbee2mqtt/0x000b57fffea82c85","name":"0x000b57fffea82c85_linkquality","unique_id":"0x000b57fffea82c85_linkquality_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000b57fffea82c85"],"name":"0x000b57fffea82c85","sw_version":"Zigbee2mqtt 1.8.0","model":"TRADFRI LED bulb GU10 400 lumen, dimmable (LED1650R5)","manufacturer":"IKEA"},"availability_topic":"zigbee2mqtt/bridge/state"}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'homeassistant/light/0x000b57fffeb961c0/light/config', payload '{"brightness":true,"schema":"json","command_topic":"zigbee2mqtt/0x000b57fffeb961c0/set","state_topic":"zigbee2mqtt/0x000b57fffeb961c0","json_attributes_topic":"zigbee2mqtt/0x000b57fffeb961c0","name":"0x000b57fffeb961c0_light","unique_id":"0x000b57fffeb961c0_light_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000b57fffeb961c0"],"name":"0x000b57fffeb961c0","sw_version":"Zigbee2mqtt 1.8.0","model":"TRADFRI LED bulb GU10 400 lumen, dimmable (LED1650R5)","manufacturer":"IKEA"},"availability_topic":"zigbee2mqtt/bridge/state"}'
  info  2019-12-31 00:20:11: MQTT publish: topic 'homeassistant/sensor/0x000b57fffeb961c0/linkquality/config', payload '{"unit_of_measurement":"-","value_template":"{{ value_json.linkquality }}","state_topic":"zigbee2mqtt/0x000b57fffeb961c0","json_attributes_topic":"zigbee2mqtt/0x000b57fffeb961c0","name":"0x000b57fffeb961c0_linkquality","unique_id":"0x000b57fffeb961c0_linkquality_zigbee2mqtt","device":{"identifiers":["zigbee2mqtt_0x000b57fffeb961c0"],"name":"0x000b57fffeb961c0","sw_version":"Zigbee2mqtt 1.8.0","model":"TRADFRI LED bulb GU10 400 lumen, dimmable (LED1650R5)","manufacturer":"IKEA"},"availability_topic":"zigbee2mqtt/bridge/state"}'
  debug 2019-12-31 00:21:51: Received MQTT message on 'zigbee2mqtt/0x000b57fffeb961c0/set' with data '{"state": "OFF"}'
  debug 2019-12-31 00:21:51: Publishing 'set' 'state' to '0x000b57fffeb961c0'
  debug 2019-12-31 00:21:56: Received MQTT message on 'zigbee2mqtt/0x000b57fffea82c85/set' with data '{"state": "ON"}'
  debug 2019-12-31 00:21:56: Publishing 'set' 'state' to '0x000b57fffea82c85'
  error 2019-12-31 00:21:57: Publish 'set' 'state' to '0x000b57fffeb961c0' failed: 'Error: SRSP - AF - dataRequest after 6000ms'
  debug 2019-12-31 00:21:57: Error: SRSP - AF - dataRequest after 6000ms
  at Timeout.object.timer.setTimeout [as _onTimeout] (/app/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
  at ontimeout (timers.js:436:11)
  at tryOnTimeout (timers.js:300:5)
  at listOnTimeout (timers.js:263:5)
  at Timer.processTimers (timers.js:223:10)
  info  2019-12-31 00:21:57: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x000b57fffeb961c0' failed: 'Error: SRSP - AF - dataRequest after 6000ms'","meta":{"friendly_name":"0x000b57fffeb961c0"}}'
  debug 2019-12-31 00:21:59: Received MQTT message on 'zigbee2mqtt/0x000b57fffeb961c0/set' with data '{"state": "OFF"}'
  debug 2019-12-31 00:21:59: Publishing 'set' 'state' to '0x000b57fffeb961c0'
  debug 2019-12-31 00:22:00: Received MQTT message on 'zigbee2mqtt/0x000b57fffeb961c0/set' with data '{"state": "ON"}'
  debug 2019-12-31 00:22:00: Publishing 'set' 'state' to '0x000b57fffeb961c0'
  debug 2019-12-31 00:22:01: Received MQTT message on 'zigbee2mqtt/0x000b57fffea82c85/set' with data '{"state": "ON"}'
  debug 2019-12-31 00:22:01: Publishing 'set' 'state' to '0x000b57fffea82c85'
  debug 2019-12-31 00:22:01: Received MQTT message on 'zigbee2mqtt/0x000b57fffea82c85/set' with data '{"state": "OFF"}'
  debug 2019-12-31 00:22:01: Publishing 'set' 'state' to '0x000b57fffea82c85'
  error 2019-12-31 00:22:03: Publish 'set' 'state' to '0x000b57fffea82c85' failed: 'Error: SRSP - AF - dataRequest after 6000ms'
  debug 2019-12-31 00:22:03: Error: SRSP - AF - dataRequest after 6000ms
  at Timeout.object.timer.setTimeout [as _onTimeout] (/app/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
  at ontimeout (timers.js:436:11)
  at tryOnTimeout (timers.js:300:5)
  at listOnTimeout (timers.js:263:5)
  at Timer.processTimers (timers.js:223:10)
  info  2019-12-31 00:22:03: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x000b57fffea82c85' failed: 'Error: SRSP - AF - dataRequest after 6000ms'","meta":{"friendly_name":"0x000b57fffea82c85"}}'
  info  2019-12-31 00:22:03: MQTT publish: topic 'zigbee2mqtt/group_1', payload '{"state":"ON","brightness":61}'
  info  2019-12-31 00:22:03: MQTT publish: topic 'zigbee2mqtt/0x000b57fffea82c85', payload '{"state":"ON","brightness":61}'
  info  2019-12-31 00:22:03: MQTT publish: topic 'zigbee2mqtt/0x000b57fffea82c85', payload '{"state":"OFF","brightness":61}'
  info  2019-12-31 00:22:07: MQTT publish: topic 'zigbee2mqtt/group_1', payload '{"state":"OFF","brightness":61}'
  info  2019-12-31 00:22:07: MQTT publish: topic 'zigbee2mqtt/0x000b57fffeb961c0', payload '{"state":"OFF"}'
  info  2019-12-31 00:22:07: MQTT publish: topic 'zigbee2mqtt/group_1', payload '{"state":"ON","brightness":61}'
  info  2019-12-31 00:22:07: MQTT publish: topic 'zigbee2mqtt/0x000b57fffeb961c0', payload '{"state":"ON"}'
  debug 2019-12-31 00:22:59: Received MQTT message on 'zigbee2mqtt/bridge/networkmap' with data 'graphviz'
  info  2019-12-31 00:22:59: Starting network scan (includeRoutes 'false')
  error 2019-12-31 00:23:09: Failed to execute LQI for 'Coordinator'
  error 2019-12-31 00:23:19: Failed to execute LQI for 'Zigbee Versterker'
  error 2019-12-31 00:23:29: Failed to execute LQI for '0x000b57fffea82c85'
  debug 2019-12-31 00:23:29: LQI succeeded for '0x000b57fffeb961c0'
  info  2019-12-31 00:23:29: Network scan finished
  info  2019-12-31 00:23:29: MQTT publish: topic 'zigbee2mqtt/bridge/networkmap/graphviz', payload 'digraph G {
  node[shape=record];
  "0x00124b0018e2491f" [style="bold, filled", fillcolor="#e04e5d", fontcolor="#ffffff", label="{Coordinator|0x00124b0018e2491f (0)failed: lqi|2019-12-31T00:23:29+01:00}"];
  "0x00124b0018e2491f" -> "0x000b57fffeb961c0" [penwidth=0.5, weight=0, color="#994444", label="97"]
  "0x000d6ffffe903bbf" [style="rounded, filled", fillcolor="#4ea3e0", fontcolor="#ffffff", label="{Zigbee Versterker|0x000d6ffffe903bbf (34684)failed: lqi|IKEA TRADFRI signal repeater (E1746)|unknown}"];
  "0x000d6ffffe903bbf" -> "0x000b57fffeb961c0" [penwidth=0.5, weight=0, color="#994444", label="140"]
  "0xccccccfffec78f65" [style="rounded, dashed, filled", fillcolor="#fff8ce", fontcolor="#000000", label="{Gang PIR|0xccccccfffec78f65 (9023)|IKEA TRADFRI motion sensor (E1525)|unknown}"];
  "0x000b57fffea82c85" [style="rounded, filled", fillcolor="#4ea3e0", fontcolor="#ffffff", label="{0x000b57fffea82c85|0x000b57fffea82c85 (28427)failed: lqi|IKEA TRADFRI LED bulb GU10 400 lumen, dimmable (LED1650R5)|2019-12-31T00:22:03+01:00}"];
  "0x000b57fffea82c85" -> "0x000b57fffeb961c0" [penwidth=0.5, weight=0, color="#994444", label="120"]
  "0x000b57fffeb961c0" [style="rounded, filled", fillcolor="#4ea3e0", fontcolor="#ffffff", label="{0x000b57fffeb961c0|0x000b57fffeb961c0 (32192)|IKEA TRADFRI LED bulb GU10 400 lumen, dimmable (LED1650R5)|2019-12-31T00:22:07+01:00}"];
  }'

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.