core: Message send failure with YRD226 TSDB as a child of a router

The problem

When my Yale YRD226 TSDB connect thru a router (Philips Hue or IKEA Tradfri bulbs) instead of the coordinator directly, some lock / unlock commands fails. This issue does not happen when the door lock is directly connected to the coordinator.

The issue has been replicated with both IKEA Tradfri White Spectrum and Philips Hue White ambiance bulbs (tried the Philips Hue in the hope it would solve the problem)

The problem is intermitent. It works for a while and other times it get stucked for a short while.

Thank you in advance for your great work and help!

Environment

  • Home Assistant Core release with the issue: 2021.1.0
  • Last working Home Assistant Core release (if known): none
  • Operating environment (OS/Container/Supervised/Core): Container
  • Integration causing this issue: ZHA
  • ZigBee radio : HUSBZB-1
  • Link to integration documentation on our website: https://www.home-assistant.io/integrations/zha/

Problem-relevant device signature

{
  "node_descriptor": "NodeDescriptor(byte1=2, byte2=64, mac_capability_flags=128, manufacturer_code=4125, maximum_buffer_size=82, maximum_incoming_transfer_size=255, server_mask=0, maximum_outgoing_transfer_size=255, descriptor_capability_field=0)",
  "endpoints": {
    "1": {
      "profile_id": 260,
      "device_type": "0x000a",
      "in_clusters": [
        "0x0000",
        "0x0001",
        "0x0003",
        "0x0009",
        "0x000a",
        "0x0020",
        "0x0101",
        "0x0b05"
      ],
      "out_clusters": [
        "0x000a",
        "0x0019"
      ]
    }
  },
  "manufacturer": "Yale",
  "model": "YRD226 TSDB",
  "class": "zigpy.device.Device"
}

{
  "node_descriptor": "NodeDescriptor(byte1=1, byte2=64, mac_capability_flags=142, manufacturer_code=4107, maximum_buffer_size=82, maximum_incoming_transfer_size=128, server_mask=11264, maximum_outgoing_transfer_size=128, descriptor_capability_field=0)",
  "endpoints": {
    "11": {
      "profile_id": 260,
      "device_type": "0x010c",
      "in_clusters": [
        "0x0000",
        "0x0003",
        "0x0004",
        "0x0005",
        "0x0006",
        "0x0008",
        "0x0300",
        "0x1000",
        "0xfc02"
      ],
      "out_clusters": [
        "0x0019"
      ]
    },
    "242": {
      "profile_id": 41440,
      "device_type": "0x0061",
      "in_clusters": [],
      "out_clusters": [
        "0x0021"
      ]
    }
  },
  "manufacturer": "Philips",
  "model": "LTA003",
  "class": "zigpy.device.Device"
}

image

Problem-relevant configuration.yaml

# Configuration pannel
config:
# Logger
logger:
  default: info
  logs:
    homeassistant.core: debug
    homeassistant.components.zha: debug
    bellows.zigbee.application: debug
    bellows.ezsp: debug
    zigpy: debug
    zigpy_cc: debug
    zigpy_deconz.zigbee.application: debug
    zigpy_deconz.api: debug
    zigpy_xbee.zigbee.application: debug
    zigpy_xbee.api: debug
    zigpy_zigate: debug
    zigpy_znp: debug
    zhaquirks: debug
# Frontend
frontend:
  themes: !include_dir_merge_named themes
# History
history:
  use_include_order: true
  include:
    entities:
      - lock.porte_appartement
      - binary_sensor.porte_appartement
      - binary_sensor.porte_patio
      - binary_sensor.mouvement_salle_a_manger
      - binary_sensor.mouvement_entree
    domains:
      - climate
# Input Boolean
input_boolean:
# Input Datetime
input_datetime:
# Input Number
input_number:
# Input Select
input_select:
# Input Text
input_text:
# Logbook
logbook:
  include:
    entities:
      - lock.porte_appartement
      - binary_sensor.porte_appartement
      - binary_sensor.porte_patio
    domains:
      - climate
# Map
map:
# Mobile App
mobile_app:
# Person
person:
# Simple Service Discovery Protocol (SSDP)
ssdp:
# Sun
sun:
# System Health
system_health:
# Zero-configuration networking (zeroconf) 
zeroconf:
# Zone
zone:
# Text to speech
tts:
  - platform: google_translate
    language: 'fr'
# Configuration files
group: !include groups.yaml
automation: !include automations.yaml
script: !include scripts.yaml
scene: !include scenes.yaml
sensor: !include sensors.yaml
homeassistant:
  customize: !include customize.yaml
  packages: !include_dir_named packages
# Home Assistant SSL
http:
  ssl_certificate: ---
  ssl_key: ---
# Environment Canada weather
weather:
  - platform: environment_canada
    station: QC/s0000635
# Locks
lock:
  # Lock template building
  - platform: template
    name: Porte Édifice
    value_template: "{{ is_state('switch.verrou_porte_edifice', 'off') }}"
    lock:
      service: switch.turn_off
      data:
        entity_id: switch.verrou_porte_edifice
    unlock:
      service: switch.turn_on
      data:
        entity_id: switch.verrou_porte_edifice
# Plant configuration file
plant: !include plant.yaml
# Nest integration
nest:
  client_id: ---
  client_secret: ---
# WOL integration
wake_on_lan:
switch:
  # Flux integration
  # Bedroom lights Flux
  - platform: flux
    name: Autopilote lumières chambre
    lights:
      - light.lampe_chevet
      - light.lampe_plancher
    mode: mired
    start_time: '7:00'
    stop_time: '22:00'
    start_colortemp: 4000
    sunset_colortemp: 3600
    stop_colortemp: 2200
    disable_brightness_adjust: true
  # Secret room light Flux
  - platform: flux
    name: Autopilote lumière pièce secrète
    lights:
      - light.lampe_secrete
    mode: mired
    start_time: '7:00'
    stop_time: '22:00'
    start_colortemp: 2700
    sunset_colortemp: 2600
    stop_colortemp: 2200
    disable_brightness_adjust: true
  # Salon light Flux
  - platform: flux
    name: Autopilote lumières salon
    lights:
      - light.lampe_rouge
      - light.lampe_jaune
    mode: mired
    start_time: '7:00'
    stop_time: '22:00'
    start_colortemp: 4000
    sunset_colortemp: 3600
    stop_colortemp: 2200
    disable_brightness_adjust: true
  # Salle à manger light Flux
  - platform: flux
    name: Autopilote lumières salle à manger
    lights:
      - light.luminaire_salle_a_manger
    mode: mired
    start_time: '7:00'
    stop_time: '22:00'
    start_colortemp: 4000
    sunset_colortemp: 3000
    stop_colortemp: 2200
    disable_brightness_adjust: true
# Light groups
light:
  - platform: group
    name: Luminaire salle à manger
    entities:
      - light.luminaire_salle_manger_1
      - light.luminaire_salle_manger_2
      - light.luminaire_salle_manger_3
# Climate
climate:
  # Office thermostat
  - platform: generic_thermostat
    name: Climatiseur bureau
    heater: switch.climatiseur_bureau
    target_sensor: sensor.xiaomi_cgg1_temperature
    ac_mode: true
  # Living room thermostat
  - platform: generic_thermostat
    name: Climatiseur salon
    heater: switch.climatiseur_salon
    target_sensor: sensor.temperature_xiaomi_cgg1_corridor
    ac_mode: true
# ZHA
#zha:
#  zigpy_config:
#    ota:
#      ikea_provider: true
# Alarm
alarm_control_panel:
  - platform: manual
    name: Alarme --- Rue ------
    arming_time: 30
    delay_time: 0
    trigger_time: 60
    disarmed:
      trigger_time: 0
    armed_home:
      arming_time: 0
      delay_time: 0
    armed_night:
      arming_time: 0
      delay_time: 0
# APCUPSD
apcupsd:
# Alerts
alert:
  lave_vaiselle:
    name: Humidité lave-vaiselle
    message: De l’humidité à été détectée sous le lave-vaiselle.
    done_message: L’humidité sous le lave-vaiselle s’est dissipée.
    entity_id: binary_sensor.humidite_lave_vaiselle
    state: 'on'
    repeat:
      - 5
      - 15
      - 15
      - 15
      - 30
    notifiers:
      - notify
    data:
      push:
        sound:
          critical: 1
          name: default
          volume: 1
    title: Dégât d’eau
  laveuse_a_linge:
    name: Humidité machine à laver
    message: De l’humidité à été détectée sous la machine à laver.
    done_message: L’humidité sous la machine à laver s’est dissipée.
    entity_id: binary_sensor.humidite_machine_a_laver
    state: 'on'
    repeat:
      - 5
      - 15
      - 15
      - 15
      - 30
    notifiers:
      - notify
    data:
      push:
        sound:
          critical: 1
          name: default
          volume: 1
    title: Dégât d’eau
# Media players
media_player:
  # BOSE
  - platform: soundtouch
    host: ---
    port: 8090
    name: Soundtouch bureau

Traceback/Error logs

Full log : HALog.zip

2021-01-07 18:15:07 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=logger, service=set_default_level>
2021-01-07 18:15:07 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=logger, service=set_level>
2021-01-07 18:15:07 INFO (MainThread) [homeassistant.setup] Setup of domain logger took 0.0 seconds
2021-01-07 18:15:08 INFO (MainThread) [homeassistant.setup] Setting up recorder
2021-01-07 18:15:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=recorder, service=purge>
2021-01-07 18:15:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=logger>
2021-01-07 18:15:08 INFO (MainThread) [homeassistant.setup] Setting up http
2021-01-07 18:15:08 INFO (MainThread) [homeassistant.setup] Setup of domain http took 0.0 seconds
2021-01-07 18:15:08 INFO (MainThread) [homeassistant.setup] Setup of domain recorder took 0.2 seconds
2021-01-07 18:15:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=http>
2021-01-07 18:15:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=recorder>
2021-01-07 18:15:08 INFO (MainThread) [homeassistant.setup] Setting up system_log
2021-01-07 18:15:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=system_log, service=clear>

<---------------------------Trunkated, see full log here : https://github.com/home-assistant/core/files/5784962/HALog.zip--------------------------->

2021-01-07 20:33:34 DEBUG (MainThread) [zigpy.zcl] [0xb9bb:11:0x0008] Attribute report received: current_level=153
2021-01-07 20:33:34 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xB9BB:11:0x0008]: received attribute: 0 update with value: 153
2021-01-07 20:33:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 89 (incomingRouteRecordHandler) received: b'9bdd8f97520901881700ffc700'
2021-01-07 20:33:34 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0xdd9b, 00:17:88:01:09:52:97:8f, 255, -57, []]
2021-01-07 20:33:34 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0xdd9b, 00:17:88:01:09:52:97:8f, 255, -57, [])
2021-01-07 20:33:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00040108000b010001000075ffc79bddffff0718f10a0000209902'
2021-01-07 20:33:34 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=117), 255, -57, 0xdd9b, 255, 255, b'\x18\xf1\n\x00\x00 \x99']
2021-01-07 20:33:34 DEBUG (MainThread) [zigpy.zcl] [0xdd9b:11:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=241 command_id=Command.Report_Attributes>
2021-01-07 20:33:34 DEBUG (MainThread) [zigpy.zcl] [0xdd9b:11:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=153>)]]
2021-01-07 20:33:34 DEBUG (MainThread) [zigpy.zcl] [0xdd9b:11:0x0008] Attribute report received: current_level=153
2021-01-07 20:33:34 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xDD9B:11:0x0008]: received attribute: 0 update with value: 153
2021-01-07 20:33:34 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2021-01-07 20:33:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2021-01-07 20:33:37 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumiere_phoenix_roebelenii, old_state=<state sensor.lumiere_phoenix_roebelenii=882; unit_of_measurement=lx, friendly_name=Lumière Phoenix roebelenii, icon=mdi:brightness-5 @ 2021-01-07T20:33:04.149597-05:00>, new_state=<state sensor.lumiere_phoenix_roebelenii=886; unit_of_measurement=lx, friendly_name=Lumière Phoenix roebelenii, icon=mdi:brightness-5 @ 2021-01-07T20:33:37.138999-05:00>>
2021-01-07 20:33:37 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=plant.phoenix_roebelenii, old_state=<state plant.phoenix_roebelenii=problem; problem=moisture low, conductivity low, sensors=moisture=sensor.humidite_phoenix_roebelenii, temperature=sensor.temperature_phoenix_roebelenii, conductivity=sensor.conductivite_phoenix_roebelenii, brightness=sensor.lumiere_phoenix_roebelenii, unit_of_measurement_dict=temperature=°C, moisture=%, brightness=lx, conductivity=µS/cm, moisture=0, temperature=21.3, conductivity=0, brightness=882, max_brightness=935, friendly_name=Phoenix roebelenii @ 2021-01-07T18:15:31.816012-05:00>, new_state=<state plant.phoenix_roebelenii=problem; problem=moisture low, conductivity low, sensors=moisture=sensor.humidite_phoenix_roebelenii, temperature=sensor.temperature_phoenix_roebelenii, conductivity=sensor.conductivite_phoenix_roebelenii, brightness=sensor.lumiere_phoenix_roebelenii, unit_of_measurement_dict=temperature=°C, moisture=%, brightness=lx, conductivity=µS/cm, moisture=0, temperature=21.3, conductivity=0, brightness=886, max_brightness=935, friendly_name=Phoenix roebelenii @ 2021-01-07T18:15:31.816012-05:00>>
2021-01-07 20:33:44 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2021-01-07 20:33:44 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''

Additional information

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 16 (10 by maintainers)

Most upvoted comments

@Adminiuga I was able to recreate a message send failure as well to conclude my findings but here’s the catch : I see [0xbb33] Extending timeout for 0x57 request in the Home Assistant logs but when looking at the frames , it took a little more time than usual but still only 6 seconds before the coordinator got a confirmation from the lock that it has received the command (The bulb was waiting for a data request from the lock and I guess the lock was waiting for the channel to be free.) The network was able to deliver every frame correctly and the lock got unlocked just fine.

I can see the coordinator sent 3 unlock commands initially (in less than 3 seconds) and got all passed to the bulb correctly meaning the two other commands were really unnecessary here. Why is the coordinator doing this? And why does it tell ZigPy that a failure happened (most of the time, even if it says there was a network failure, everything is fine).

In resume

  • The network look healthy.
  • The lock always receive the unlock commands.
  • When the lock gets two unlock commands back to back, it replies to all of them ACK on the MAC link and ZCL Door Lock: Lock Door Response = success on the application level but fails to physically do anything.
    • Definitely a bug from the manufacturer as only 1 unlock command or 3 make the lock unlock.
    • Seems to explain why directly attached to the coordinator, it always works : the coordinator simply wait for a data request from the lock to send anything. And does not spit many commands at once thereafter since it has direct feedback.
  • The message send failure’s I get from time to time doesn’t look rights as the lock still does unlock (outside the bug it has) and there is no miscommunication on the network.

It is clear to me the lock has a software issue. Considering this, I will reach Yale about it. Meanwhile including the previous questions, can we somehow mitigate the number of commands the coordinator spits on the network and why does the coordinator report a message send failure when the frames look all good? Does it mean it was not capable to place the frame on the network?

Thank you for your time and help, it is really appreciated.

+1
mguaylam on Jan 26, 2021

@dmulcahey I also have seen the same issue, although only when routing through various repeaters. When the lock connects directly to the coordinator (NORTEK stick), it works perfectly, but when going through a repeater (in my case, SmartThings smart plugs and/or Ikea signal repeaters), the message fails getting to the lock.

+1
code-in-progress on Jan 16, 2021
Read more comments on GitHub
← core: Meross Matter smart wifi plug fails to pair when added to home assistant directly, but works when credentials are shared from google home
core: Meteoalarm sensor is not loaded on HA version 2021.10.0 →