Exception while calling fromZigbee converter

diaz66 commented 6 months ago

Description of the issue

After switching to version 1.35.1-1 I started to encounter the error in question.
From this moment on, zigbee2mqtt no longer sends anything to home assistant (Mosquitto broker) -The device generating the error is a PJ-MGW1203
The system block occurs 2/3 times a day randomly

Addon version

v1.35.1-1

Platform

Core 2024.1.2 Supervisor 2023.12.0 Operating System 11.4

my configuration

homeassistant: true
mqtt:
  server: mqtt://core-mosquitto
  user: *****
  password: *****
serial:
  port: /dev/ttyACM0
  adapter: ezsp
frontend:
  port: 8099
advanced:
  homeassistant_legacy_entity_attributes: false
  legacy_api: false
  legacy_availability_payload: false
  log_syslog:
    app_name: Zigbee2MQTT
    eol: /n
    host: localhost
    localhost: localhost
    path: /dev/log
    pid: process.pid
    port: 123
    protocol: tcp4
    type: '5424'
  channel: 25
  log_level: info
device_options:
  legacy: false
devices:
  '0xe0798dfffea826ff':
    friendly_name: Router ZBDongle-E
  '0x003c84fffef0ecca':
    friendly_name: ZigBee Termosifone Camera Mat
  '0xa4c1380483ecb1b5':
    friendly_name: ZigBee Termometro Sala
  '0xa4c13878a044e674':
    friendly_name: ZigBee Termometro Soggiorno
  '0xa4c138fa78091d52':
    friendly_name: ZigBee Presa Frigorifero
  '0xa4c138bab31104b2':
    friendly_name: ZigBee Luce Terrazzo Camera Matrimoniale
  '0xa4c13831eaf7dbba':
    friendly_name: ZigBee Tapparella1 Sala
  '0xa4c138c3b27cee34':
    friendly_name: ZigBee Lampada Luna
  '0xa4c138bcec51d379':
    friendly_name: ZigBee Luce Sala
  '0xa4c1383aad8d029e':
    friendly_name: ZigBee Presa Sala TV
  '0xa4c138e52b567c58':
    friendly_name: ZigBee Presa Camera Grande Play
  '0xa4c138fe60c0d996':
    friendly_name: ZigBee Presa Camera Grande PC
  '0xa4c138ddd7cffecf':
    friendly_name: ZigBee Presa Soggiorno TV
  '0xa4c1388b23a3bf79':
    friendly_name: ZigBee Porta Frigo
  '0xa4c1382e0495eafe':
    friendly_name: ZigBee Porta Congelatore
  '0xa4c138a06155b4d5':
    friendly_name: ZigBee Luce Camera Grande
    power_precision: 1
    power_calibration: 3000
    current_calibration: 100
    energy_precision: 1
    voltage_precision: 1
    current_precision: 1
    state_action: true
  '0x70ac08fffe366ce1':
    friendly_name: Zigbee Power Meter Casa
    energy_precision: 2
    energy_calibration: 1
    current_precision: 2
    power_precision: 2
    voltage_precision: 2
    current_calibration: 1
    power_calibration: 1
    voltage_calibration: 1
  '0xa4c13851ad8d6f9b':
    friendly_name: ZigBee Termometro Esterno
    temperature_precision: 1
  '0xa4c1383a8254d9ae':
    friendly_name: ZigBee Termometro Camera Grande
  '0xa4c1382c28303539':
    friendly_name: ZigBee Termometro Camera Piccola
  '0xa4c13818fe6c6cd3':
    friendly_name: ZigBee Porta Ingresso Interna
  '0xa4c13800b40af798':
    friendly_name: ZigBee Porta Ingresso Esterna
  '0xa4c1380aa558d939':
    friendly_name: ZigBee Presa Camera Piccola
  '0xa4c138af878589ac':
    friendly_name: ZigBee Presa Camera Mat
  '0xa4c138351db79811':
    friendly_name: ZigBee Sensore Acqua Esterno
  '0x4c5bb3fffe2eeaf7':
    friendly_name: Zigbee Power Meter Cucina
    description: Cappa Cucina + le due prese
    current_calibration: 1
    current_precision: 2
    power_precision: 2
    voltage_precision: 2
    energy_precision: 2
    power_calibration: 1
    voltage_calibration: 1
    energy_calibration: 1
  '0x00124b00291ffbe0':
    friendly_name: ZigBee Termometro Camera Mat
blocklist: []
availability: false

Logs of the issue (if applicable)

log.txt **`error 2024-01-12 16:11:45: Exception while calling fromZigbee converter: Command 0x4c5bb3fffe2eeaf7/1 manuSpecificTuya.mcuGatewayConnectionStatus({"payloadSize":1,"payload":1}, {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error)}

`**

BenSki2023 commented 5 months ago

@diaz66 do u have solved the problem?

diaz66 commented 5 months ago

@diaz66 do u have solved the problem?

unfortunately not

nberardi commented 5 months ago

I am facing the same problem.

Koenkk commented 5 months ago

Can you check with the latest dev branch?

nberardi commented 5 months ago

The edge branch, as I am consuming it in HA, is exhibiting the same issue. Let me pull my debug logs.

Silicon Labs Multiprotocol

otbr-agent[300]: 01:11:31.890 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:61e0, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:11:31.890 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:11:31.891 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:13:13.696 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:13:13.851 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:ceef, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:13:13.851 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:13:13.852 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:13:36.639 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:13:36.653 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:14:55.852 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:5475, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:14:55.852 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:14:55.852 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:14:56.846 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:bbb7, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:14:56.846 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:14:56.846 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:14:57.695 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:14:57.853 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:23e2, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:14:57.854 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:14:57.854 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:16:47.556 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:19:22.017 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:19:22.028 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:19:22.034 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:19:22.223 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:107, chksum:b93d, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:19:22.224 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:19:22.224 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:20:17.484 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:96, chksum:5b25, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:20:17.485 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:20:17.485 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:20:18.469 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:96, chksum:5a67, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:20:18.469 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:20:18.469 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:20:19.650 [W] Platform------: Handle transmit done failed: ChannelAccessFailure
otbr-agent[300]: 01:20:19.650 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:107, chksum:db76, ecn:no, to:f2088b724ecfcb71, sec:no, error:ChannelAccessFailure, prio:net
otbr-agent[300]: 01:20:19.650 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:20:19.651 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:22:10.505 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:22:10.511 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:22:33.464 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:96, chksum:79d0, ecn:no, to:5a22296bc9e2413d, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:22:33.464 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:22:33.464 [N] MeshForwarder-:     dst:[fe80:0:0:0:5822:296b:c9e2:413d]:19788
otbr-agent[300]: 01:23:41.893 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:9498, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:23:41.894 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:23:41.894 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:23:42.904 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:88db, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:23:42.904 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:23:42.904 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:23:51.505 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:26:20.894 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:1fb1, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:26:20.895 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:26:20.895 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:26:21.696 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:26:21.913 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:6438, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:26:21.913 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:26:21.914 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:26:22.715 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:26:22.860 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:a5fd, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:26:22.861 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:26:22.861 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:45:06.449 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:46:40.810 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:46:40.957 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:3ef5, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:46:40.958 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:46:40.958 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:48:22.944 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:b8d5, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:48:22.944 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:48:22.944 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:48:23.936 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:65cf, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:48:23.937 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:48:23.937 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:48:24.946 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:c28d, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:48:24.947 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:48:24.947 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:51:12.812 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:51:12.818 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:51:12.964 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:05d5, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:51:12.965 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:51:12.965 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:51:13.994 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:e910, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:51:13.995 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:51:13.995 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
otbr-agent[300]: 01:51:14.806 [W] Mle-----------: Failed to process UDP: Duplicated
otbr-agent[300]: 01:51:14.970 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:122, chksum:91f9, ecn:no, to:f2088b724ecfcb71, sec:no, error:NoAck, prio:net
otbr-agent[300]: 01:51:14.971 [N] MeshForwarder-:     src:[fe80:0:0:0:dc4d:959b:10de:72]:19788
otbr-agent[300]: 01:51:14.971 [N] MeshForwarder-:     dst:[fe80:0:0:0:f008:8b72:4ecf:cb71]:19788
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::3069:3eff:fe75:bd1b/veth43c539f/113
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::3069:3eff:fe75:bd1b/veth43c539f/113
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::3069:3eff:fe75:bd1b/veth43c539f/113
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::3069:3eff:fe75:bd1b/veth43c539f/113
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::3069:3eff:fe75:bd1b/veth43c539f/113
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::3069:3eff:fe75:bd1b/veth43c539f/113
Accepted connection 8.
By using this software, you are agreeing to the Silicon Labs MSLA found at https://www.silabs.com/about-us/legal/master-software-license-agreement.
[19:54:14:046315] Info : Client disconnected
[19:54:14] INFO: zigbeed ended with exit code 5 (signal 0)...
[19:54:16] INFO: Starting zigbeed...
[19:54:17:262946] Info : New client connection using library v4.3.1.0
[19:54:17:267998] Info : Endpoint socket #12: Client connected. 2 connections
Listening on port 9999 for connection...
Accepting connection.

Zigbee2MQTT

2024-01-28T22:55:13.625Z zigbee-herdsman:adapter:ezsp:erro Request error Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[1,0,1,126,0,62,240,147,254,255,251,92,56,1]}: Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[1,0,1,126,0,62,240,147,254,255,251,92,56,1]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
2024-01-28T22:55:13.626Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0xb0ce1814036559a7:5910/1 (0,0,14)
2024-01-28T22:55:13.627Z zigbee-herdsman:adapter:ezsp:ezsp ==> setExtendedTimeout: {"remoteEui64":{"_value":{"type":"Buffer","data":[176,206,24,20,3,101,89,167]}},"extendedTimeout":true}
2024-01-28T22:55:13.628Z zigbee-herdsman:controller:endpoint CommandResponse 0x385cfbfffe93f03e/1 genOta.imageNotify({"payloadType":0,"queryJitter":100}, {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error)
Zigbee2MQTT:error 2024-01-28 17:55:13: Failed to check if update available for 'upstairs_hallway_sensor' (OTA: Device didn't respond to OTA request)
2024-01-28T22:55:13.636Z zigbee-herdsman:adapter:ezsp:uart <-- [1240a1a90c2a25bdf97e]
2024-01-28T22:55:13.637Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (1,2,0): 1240a1a90c2a25bdf97e
2024-01-28T22:55:13.637Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (2)
2024-01-28T22:55:13.637Z zigbee-herdsman:adapter:ezsp:uart --> [82503a7e]
2024-01-28T22:55:13.638Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 028001580030
2024-01-28T22:55:13.639Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x58: {"_cls_":"invalidCommand","_id_":88,"_isRequest_":false,"reason":48}
2024-01-28T22:55:13.639Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (2) success
2024-01-28T22:55:19.504Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-28T22:55:19.504Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-28T22:55:23.641Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"setExtendedTimeout","_id_":126,"_isRequest_":true,"remoteEui64":{"_value":{"type":"Buffer","data":[236,27,189,255,254,142,200,189]}},"extendedTimeout":true}
2024-01-28T22:55:23.642Z zigbee-herdsman:adapter:ezsp:uart --> DATA (2,2,0): 0300017e00bdc88efeffbd1bec01
2024-01-28T22:55:23.642Z zigbee-herdsman:adapter:ezsp:uart --> [224121a92a2aa87ad76ab598b1b9937d5ec87e]
2024-01-28T22:55:23.645Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (3)
2024-01-28T22:55:23.647Z zigbee-herdsman:adapter:ezsp:erro Request error Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[2,0,1,126,0,115,109,163,254,255,251,92,56,1]}: Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[2,0,1,126,0,115,109,163,254,255,251,92,56,1]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
2024-01-28T22:55:23.647Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0xec1bbdfffe48d3a2:52913/1 (0,0,13)
2024-01-28T22:55:23.648Z zigbee-herdsman:adapter:ezsp:ezsp ==> setExtendedTimeout: {"remoteEui64":{"_value":{"type":"Buffer","data":[236,27,189,255,254,72,211,162]}},"extendedTimeout":true}
2024-01-28T22:55:23.649Z zigbee-herdsman:controller:endpoint CommandResponse 0x385cfbfffea36d73/1 genOta.imageNotify({"payloadType":0,"queryJitter":100}, {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error)
Zigbee2MQTT:error 2024-01-28 17:55:23: Failed to check if update available for 'basement_sensor' (OTA: Device didn't respond to OTA request)
2024-01-28T22:55:23.657Z zigbee-herdsman:adapter:ezsp:uart <-- [2341a1a90c2a2519b57e]
2024-01-28T22:55:23.657Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (2,3,0): 2341a1a90c2a2519b57e
2024-01-28T22:55:23.658Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (3)
2024-01-28T22:55:23.658Z zigbee-herdsman:adapter:ezsp:uart --> [83401b7e]
2024-01-28T22:55:23.659Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 038001580030
2024-01-28T22:55:23.659Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x58: {"_cls_":"invalidCommand","_id_":88,"_isRequest_":false,"reason":48}
2024-01-28T22:55:23.660Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (3) success
2024-01-28T22:55:29.507Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-28T22:55:29.507Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-28T22:55:33.665Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"setExtendedTimeout","_id_":126,"_isRequest_":true,"remoteEui64":{"_value":{"type":"Buffer","data":[236,27,189,255,254,142,205,143]}},"extendedTimeout":true}
2024-01-28T22:55:33.665Z zigbee-herdsman:adapter:ezsp:uart --> DATA (3,3,0): 0400017e008fcd8efeffbd1bec01
2024-01-28T22:55:33.665Z zigbee-herdsman:adapter:ezsp:uart --> [334621a92a2a9a7fd76ab598b1b99394637e]
2024-01-28T22:55:33.666Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (4)
2024-01-28T22:55:33.667Z zigbee-herdsman:adapter:ezsp:erro Request error Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[3,0,1,126,0,189,200,142,254,255,189,27,236,1]}: Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[3,0,1,126,0,189,200,142,254,255,189,27,236,1]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
2024-01-28T22:55:33.668Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0x680ae2fffe11df36:58901/1 (0,0,12)
2024-01-28T22:55:33.668Z zigbee-herdsman:adapter:ezsp:ezsp ==> setExtendedTimeout: {"remoteEui64":{"_value":{"type":"Buffer","data":[104,10,226,255,254,17,223,54]}},"extendedTimeout":true}
2024-01-28T22:55:33.669Z zigbee-herdsman:controller:endpoint CommandResponse 0xec1bbdfffe8ec8bd/1 genOta.imageNotify({"payloadType":0,"queryJitter":100}, {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error)
Zigbee2MQTT:error 2024-01-28 17:55:33: Failed to check if update available for 'back_deck_speaker_remote' (OTA: Device didn't respond to OTA request)
2024-01-28T22:55:33.677Z zigbee-herdsman:adapter:ezsp:uart <-- [3446a1a90c2a25ffcb7e]
2024-01-28T22:55:33.679Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (3,4,0): 3446a1a90c2a25ffcb7e
2024-01-28T22:55:33.679Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (4)
2024-01-28T22:55:33.680Z zigbee-herdsman:adapter:ezsp:uart --> [8430fc7e]
2024-01-28T22:55:33.681Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 048001580030
2024-01-28T22:55:33.681Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x58: {"_cls_":"invalidCommand","_id_":88,"_isRequest_":false,"reason":48}
2024-01-28T22:55:33.682Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (4) success
2024-01-28T22:55:39.508Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-28T22:55:39.515Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-28T22:55:43.685Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"setExtendedTimeout","_id_":126,"_isRequest_":true,"remoteEui64":{"_value":{"type":"Buffer","data":[236,27,189,255,254,2,78,209]}},"extendedTimeout":true}
2024-01-28T22:55:43.686Z zigbee-herdsman:adapter:ezsp:uart --> DATA (4,4,0): 0500017e00d14e02feffbd1bec01
2024-01-28T22:55:43.686Z zigbee-herdsman:adapter:ezsp:uart --> [444721a92a2ac4fc5b6ab598b1b993dd347e]
2024-01-28T22:55:43.687Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (5)
2024-01-28T22:55:43.689Z zigbee-herdsman:adapter:ezsp:erro Request error Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[4,0,1,126,0,143,205,142,254,255,189,27,236,1]}: Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[4,0,1,126,0,143,205,142,254,255,189,27,236,1]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
2024-01-28T22:55:43.690Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0x90fd9ffffeedfc2e:31999/1 (0,0,11)
2024-01-28T22:55:43.690Z zigbee-herdsman:adapter:ezsp:ezsp ==> setExtendedTimeout: {"remoteEui64":{"_value":{"type":"Buffer","data":[144,253,159,255,254,237,252,46]}},"extendedTimeout":true}
2024-01-28T22:55:43.691Z zigbee-herdsman:controller:endpoint CommandResponse 0xec1bbdfffe8ecd8f/1 genOta.imageNotify({"payloadType":0,"queryJitter":100}, {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error)
Zigbee2MQTT:error 2024-01-28 17:55:43: Failed to check if update available for 'kitchen_speaker_remote' (OTA: Device didn't respond to OTA request)
2024-01-28T22:55:43.696Z zigbee-herdsman:adapter:ezsp:uart <-- [4547a1a90c2a25866b7e]
2024-01-28T22:55:43.697Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (4,5,0): 4547a1a90c2a25866b7e
2024-01-28T22:55:43.697Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (5)
2024-01-28T22:55:43.697Z zigbee-herdsman:adapter:ezsp:uart --> [8520dd7e]
2024-01-28T22:55:43.697Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 058001580030
2024-01-28T22:55:43.698Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x58: {"_cls_":"invalidCommand","_id_":88,"_isRequest_":false,"reason":48}
2024-01-28T22:55:43.698Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (5) success
2024-01-28T22:55:49.512Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-28T22:55:49.512Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-28T22:55:53.701Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"setExtendedTimeout","_id_":126,"_isRequest_":true,"remoteEui64":{"_value":{"type":"Buffer","data":[104,10,226,255,254,47,55,85]}},"extendedTimeout":true}
2024-01-28T22:55:53.702Z zigbee-herdsman:adapter:ezsp:uart --> DATA (5,5,0): 0600017e0055372ffeffe20a6801
2024-01-28T22:55:53.702Z zigbee-herdsman:adapter:ezsp:uart --> [554421a92a2a4085766ab5c7a03d93fc9f7e]
2024-01-28T22:55:53.703Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (6)
2024-01-28T22:55:53.705Z zigbee-herdsman:adapter:ezsp:erro Request error Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[5,0,1,126,0,209,78,2,254,255,189,27,236,1]}: Error: Failure send setExtendedTimeout:{"type":"Buffer","data":[5,0,1,126,0,209,78,2,254,255,189,27,236,1]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
2024-01-28T22:55:53.705Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0x90fd9ffffe0eaee4:51312/1 (0,0,10)
2024-01-28T22:55:53.706Z zigbee-herdsman:adapter:ezsp:ezsp ==> setExtendedTimeout: {"remoteEui64":{"_value":{"type":"Buffer","data":[144,253,159,255,254,14,174,228]}},"extendedTimeout":true}
2024-01-28T22:55:53.707Z zigbee-herdsman:controller:endpoint CommandResponse 0xec1bbdfffe024ed1/1 genOta.imageNotify({"payloadType":0,"queryJitter":100}, {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error)
Zigbee2MQTT:error 2024-01-28 17:55:53: Failed to check if update available for 'study_speaker_remote' (OTA: Device didn't respond to OTA request)
2024-01-28T22:55:53.712Z zigbee-herdsman:adapter:ezsp:uart <-- [5644a1a90c2a25a7727e]
2024-01-28T22:55:53.713Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (5,6,0): 5644a1a90c2a25a7727e
2024-01-28T22:55:53.713Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (6)
2024-01-28T22:55:53.713Z zigbee-herdsman:adapter:ezsp:uart --> [8610be7e]
2024-01-28T22:55:53.714Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 068001580030
2024-01-28T22:55:53.714Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x58: {"_cls_":"invalidCommand","_id_":88,"_isRequest_":false,"reason":48}
2024-01-28T22:55:53.715Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (6) success
2024-01-28T22:55:59.512Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-28T22:55:59.512Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
Error: Timeout - 49458 - 1 - null - 25 - 1 after 60000ms
    at Timeout._onTimeout (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:64:35)
    at listOnTimeout (node:internal/timers:569:17)
    at processTimers (node:internal/timers:512:7)

Zigbee2MQTT Restartup

[19:54:02] INFO: Preparing to start...
[19:54:03] INFO: Socat not enabled
[19:54:03] INFO: Zigbee Herdsman debug logging enabled
[19:54:05] INFO: Starting Zigbee2MQTT...
2024-01-29T00:54:14.009Z zigbee-herdsman:adapter:ezsp:debg Adapter concurrent: 8
2024-01-29T00:54:14.013Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[82,218,6,79,205,107,117,96,180,170,204,231,64,230,204,82],"panID":20542,"extendedPanID":[231,142,61,137,128,96,100,23],"channelList":[25]},"serialPort":{"baudRate":115200,"path":"tcp://core-silabs-multiprotocol:9999","adapter":"ezsp"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2024-01-29T00:54:14.017Z zigbee-herdsman:adapter:ezsp:uart Opening TCP socket with core-silabs-multiprotocol:9999
2024-01-29T00:54:14.037Z zigbee-herdsman:adapter:ezsp:uart Socket connected
2024-01-29T00:54:14.038Z zigbee-herdsman:adapter:ezsp:uart Socket ready
2024-01-29T00:54:14.039Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2024-01-29T00:54:14.041Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2024-01-29T00:54:14.044Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2024-01-29T00:54:14.045Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset
2024-01-29T00:54:14.056Z zigbee-herdsman:adapter:ezsp:uart Socket error
2024-01-29T00:54:14.112Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 1 error: Error: Error while opening socket
    at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:147:24)
    at Socket.emit (node:events:529:35)
    at emitErrorNT (node:internal/streams/destroy:151:8)
    at emitErrorCloseNT (node:internal/streams/destroy:116:3)
    at processTicksAndRejections (node:internal/process/task_queues:82:21)
2024-01-29T00:54:14.114Z zigbee-herdsman:adapter:ezsp:uart Port closed
2024-01-29T00:54:14.114Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-29T00:54:14.115Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-29T00:54:19.122Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 2
2024-01-29T00:54:19.123Z zigbee-herdsman:adapter:ezsp:uart Opening TCP socket with core-silabs-multiprotocol:9999
2024-01-29T00:54:19.134Z zigbee-herdsman:adapter:ezsp:uart Socket error
2024-01-29T00:54:19.137Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 2 error: Error: Error while opening socket
    at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:147:24)
    at Socket.emit (node:events:529:35)
    at emitErrorNT (node:internal/streams/destroy:151:8)
    at emitErrorCloseNT (node:internal/streams/destroy:116:3)
    at processTicksAndRejections (node:internal/process/task_queues:82:21)
2024-01-29T00:54:19.139Z zigbee-herdsman:adapter:ezsp:uart Port closed
2024-01-29T00:54:19.139Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-29T00:54:19.139Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-29T00:54:24.045Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":-1} after 10000ms
2024-01-29T00:54:24.046Z zigbee-herdsman:adapter:ezsp:driv Reset connection. Try 0
2024-01-29T00:54:24.047Z zigbee-herdsman:adapter:ezsp:driv Stop driver
2024-01-29T00:54:24.047Z zigbee-herdsman:adapter:ezsp:ezsp Stop ezsp
2024-01-29T00:54:24.048Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-29T00:54:24.048Z zigbee-herdsman:adapter:ezsp:driv Close driver
Error: Reset error: Error: {"sequence":-1} after 10000ms
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:299:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)

github-actions[bot] commented 4 months ago

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days

zigbee2mqtt / hassio-zigbee2mqtt