Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

New Edge not starting anymore with ezsp 7.4.0 #20827

Closed
wastez opened this issue Jan 15, 2024 · 56 comments
Closed

New Edge not starting anymore with ezsp 7.4.0 #20827

wastez opened this issue Jan 15, 2024 · 56 comments
Labels
problem Something isn't working stale Stale issues

Comments

@wastez
Copy link

wastez commented Jan 15, 2024

What happened?

It doesn’t start anymore.
no error message, just writing „starting“ in the logs.
the gui doesn’t get available.

What did you expect to happen?

No response

How to reproduce it (minimal and precise)

No response

Zigbee2MQTT version

latest edge

Adapter firmware version

7.4.0

Adapter

EZSP Sonoff Dongle E

Setup

Proxmox

Debug log

No response

@wastez wastez added the problem Something isn't working label Jan 15, 2024
@Koenkk
Copy link
Owner

Koenkk commented Jan 15, 2024

  • What zigbee herdsman version shows up under frontend -> settings -> about
  • Can you provide the herdsman debug log of this?

See this on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

CC: @Nerivec

@wastez
Copy link
Author

wastez commented Jan 15, 2024

[21:09:25] INFO: Socat not enabled
[21:09:25] INFO: Zigbee Herdsman debug logging enabled
[21:09:25] INFO: Starting Zigbee2MQTT...
2024-01-15T20:09:27.572Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2024-01-15T20:09:27.573Z zigbee-herdsman:adapter:ezsp:debg Adapter concurrent: 8
2024-01-15T20:09:27.574Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[25]},"serialPort":{"path":"/dev/ttyACM0","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-15T20:09:27.575Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:27.580Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2024-01-15T20:09:27.580Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2024-01-15T20:09:27.580Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2024-01-15T20:09:27.581Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2024-01-15T20:09:27.582Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset
2024-01-15T20:09:28.683Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2024-01-15T20:09:28.683Z zigbee-herdsman:adapter:ezsp:uart --> parsed c1020b0a527e
2024-01-15T20:09:28.683Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK c1020b0a527e
2024-01-15T20:09:28.683Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2024-01-15T20:09:28.684Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success
2024-01-15T20:09:28.685Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":4}
2024-01-15T20:09:28.685Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":4}
2024-01-15T20:09:28.686Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 00000004
2024-01-15T20:09:28.686Z zigbee-herdsman:adapter:ezsp:uart --> [004221a850ed2c7e]
2024-01-15T20:09:28.686Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2024-01-15T20:09:28.691Z zigbee-herdsman:adapter:ezsp:uart <-- [0142a1a8592815c6ab047e]
2024-01-15T20:09:28.691Z zigbee-herdsman:adapter:ezsp:uart --> parsed 0142a1a8592815c6ab047e
2024-01-15T20:09:28.691Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,1,0): 0142a1a8592815c6ab047e
2024-01-15T20:09:28.691Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2024-01-15T20:09:28.691Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2024-01-15T20:09:28.708Z zigbee-herdsman:adapter:ezsp:uart Error while parsing to ZpiObject 'TypeError: debug.log is not a function
    at SerialDriver.handleACK (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:232:15)
    at SerialDriver.handleDATA (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:212:30)
    at SerialDriver.onParsed (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:173:22)
    at Parser.emit (node:events:517:28)
    at Parser.parseNext (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:52:34)
    at Parser._transform (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:33:14)
    at Parser.Transform._write (node:internal/streams/transform:175:8)
    at writeOrBuffer (node:internal/streams/writable:392:12)
    at _write (node:internal/streams/writable:333:10)
    at Parser.Writable.write (node:internal/streams/writable:337:10)'
2024-01-15T20:09:30.688Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":1} after 2000ms
2024-01-15T20:09:30.688Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (1)
2024-01-15T20:09:30.688Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (0,0,0): 00000004
2024-01-15T20:09:31.190Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (0,0,1): 00000004
2024-01-15T20:09:31.190Z zigbee-herdsman:adapter:ezsp:uart --> [084221a850ef017e]
2024-01-15T20:09:31.190Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (1)
2024-01-15T20:09:31.193Z zigbee-herdsman:adapter:ezsp:uart <-- [a1443b7e]
2024-01-15T20:09:31.193Z zigbee-herdsman:adapter:ezsp:uart --> parsed a1443b7e
2024-01-15T20:09:31.195Z zigbee-herdsman:adapter:ezsp:uart Error while parsing to ZpiObject 'TypeError: debug.log is not a function
    at SerialDriver.handleNAK (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:247:15)
    at SerialDriver.onParsed (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:179:22)
    at Parser.emit (node:events:517:28)
    at Parser.parseNext (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:52:34)
    at Parser._transform (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:33:14)
    at Parser.Transform._write (node:internal/streams/transform:175:8)
    at writeOrBuffer (node:internal/streams/writable:392:12)
    at _write (node:internal/streams/writable:333:10)
    at Parser.Writable.write (node:internal/streams/writable:337:10)
    at SerialPort.ondata (node:internal/streams/readable:777:22)'
2024-01-15T20:09:33.192Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":1} after 2000ms
2024-01-15T20:09:33.193Z zigbee-herdsman:adapter:ezsp:uart -!- break rewaiting (1)
2024-01-15T20:09:33.193Z zigbee-herdsman:adapter:ezsp:uart Can't resend DATA frame (0,0,1): 00000004
2024-01-15T20:09:33.193Z zigbee-herdsman:adapter:ezsp:driv Reset connection. Try 0
2024-01-15T20:09:33.193Z zigbee-herdsman:adapter:ezsp:driv Stop driver
2024-01-15T20:09:33.193Z zigbee-herdsman:adapter:ezsp:ezsp Stop ezsp
2024-01-15T20:09:33.193Z zigbee-herdsman:adapter:ezsp:uart closing
2024-01-15T20:09:33.194Z zigbee-herdsman:adapter:ezsp:driv Reset connection. Try 0
2024-01-15T20:09:33.194Z zigbee-herdsman:adapter:ezsp:driv Stop driver
2024-01-15T20:09:33.194Z zigbee-herdsman:adapter:ezsp:ezsp Stop ezsp
2024-01-15T20:09:33.194Z zigbee-herdsman:adapter:ezsp:uart closing
2024-01-15T20:09:33.194Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-15T20:09:33.194Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-15T20:09:33.197Z zigbee-herdsman:adapter:ezsp:uart Port closed
2024-01-15T20:09:33.197Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-15T20:09:33.197Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-15T20:09:33.197Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-15T20:09:33.197Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-15T20:09:34.195Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:34.197Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2024-01-15T20:09:34.197Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2024-01-15T20:09:34.197Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2024-01-15T20:09:34.197Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2024-01-15T20:09:34.197Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset
2024-01-15T20:09:34.197Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:34.200Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 1 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:09:35.288Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2024-01-15T20:09:35.288Z zigbee-herdsman:adapter:ezsp:uart --> parsed c1020b0a527e
2024-01-15T20:09:35.288Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK c1020b0a527e
2024-01-15T20:09:35.288Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2024-01-15T20:09:35.288Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success
2024-01-15T20:09:35.288Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":4}
2024-01-15T20:09:35.319Z zigbee-herdsman:adapter:ezsp:erro Reset error Error: Connection not initialized
    at Ezsp.execCommand (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:592:19)
    at Ezsp.version (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:376:35)
    at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:152:25)
    at Driver.reset (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:116:24)
    at EZSPAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:174:20)
    at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:132:29)
    at Zigbee.start (/app/lib/zigbee.ts:60:27)
    at Controller.start (/app/lib/controller.ts:98:27)
    at start (/app/index.js:107:5)
2024-01-15T20:09:35.320Z zigbee-herdsman:adapter:ezsp:driv Pause 10sec before try 1
2024-01-15T20:09:39.204Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 2
2024-01-15T20:09:39.204Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:39.206Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 2 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:09:44.208Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 3
2024-01-15T20:09:44.208Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:44.210Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 3 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:09:45.288Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-15T20:09:45.289Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-15T20:09:45.289Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-15T20:09:45.289Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 000005
2024-01-15T20:09:45.289Z zigbee-herdsman:adapter:ezsp:uart --> [004221ada69d7e]
2024-01-15T20:09:45.289Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2024-01-15T20:09:45.293Z zigbee-herdsman:adapter:ezsp:uart <-- [0142a1ad0c2a5cfc0f7e]
2024-01-15T20:09:45.293Z zigbee-herdsman:adapter:ezsp:uart --> parsed 0142a1ad0c2a5cfc0f7e
2024-01-15T20:09:45.294Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,1,0): 0142a1ad0c2a5cfc0f7e
2024-01-15T20:09:45.294Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2024-01-15T20:09:45.294Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2024-01-15T20:09:45.294Z zigbee-herdsman:adapter:ezsp:uart Error while parsing to ZpiObject 'TypeError: debug.log is not a function
    at SerialDriver.handleACK (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:232:15)
    at SerialDriver.handleDATA (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:212:30)
    at SerialDriver.onParsed (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:173:22)
    at Parser.emit (node:events:517:28)
    at Parser.parseNext (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:52:34)
    at Parser._transform (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:33:14)
    at Parser.Transform._write (node:internal/streams/transform:175:8)
    at writeOrBuffer (node:internal/streams/writable:392:12)
    at _write (node:internal/streams/writable:333:10)
    at Parser.Writable.write (node:internal/streams/writable:337:10)'
2024-01-15T20:09:45.321Z zigbee-herdsman:adapter:ezsp:driv Reset connection. Try 1
2024-01-15T20:09:45.321Z zigbee-herdsman:adapter:ezsp:driv Stop driver
2024-01-15T20:09:45.321Z zigbee-herdsman:adapter:ezsp:ezsp Stop ezsp
2024-01-15T20:09:45.321Z zigbee-herdsman:adapter:ezsp:uart closing
2024-01-15T20:09:45.321Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-15T20:09:45.321Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-15T20:09:46.323Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:46.324Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 1 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:09:47.291Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":1} after 2000ms
2024-01-15T20:09:47.291Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (1)
2024-01-15T20:09:47.291Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (0,0,0): 000005
2024-01-15T20:09:47.792Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (0,0,1): 000005
2024-01-15T20:09:47.792Z zigbee-herdsman:adapter:ezsp:uart --> [084221ad235e7e]
2024-01-15T20:09:47.792Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (1)
2024-01-15T20:09:47.795Z zigbee-herdsman:adapter:ezsp:uart <-- [a1443b7e]
2024-01-15T20:09:47.795Z zigbee-herdsman:adapter:ezsp:uart --> parsed a1443b7e
2024-01-15T20:09:47.795Z zigbee-herdsman:adapter:ezsp:uart Error while parsing to ZpiObject 'TypeError: debug.log is not a function
    at SerialDriver.handleNAK (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:247:15)
    at SerialDriver.onParsed (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:179:22)
    at Parser.emit (node:events:517:28)
    at Parser.parseNext (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:52:34)
    at Parser._transform (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:33:14)
    at Parser.Transform._write (node:internal/streams/transform:175:8)
    at writeOrBuffer (node:internal/streams/writable:392:12)
    at _write (node:internal/streams/writable:333:10)
    at Parser.Writable.write (node:internal/streams/writable:337:10)
    at SerialPort.ondata (node:internal/streams/readable:777:22)'
2024-01-15T20:09:49.213Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 4
2024-01-15T20:09:49.213Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:49.214Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 4 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:09:49.214Z zigbee-herdsman:adapter:ezsp:erro EZSP could not connect: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
2024-01-15T20:09:49.214Z zigbee-herdsman:adapter:ezsp:erro Reset error Error: Failure to connect
    at Ezsp.connect (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:293:19)
    at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:143:13)
    at Driver.reset (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:116:24)
    at Driver.onReset (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:132:9)
2024-01-15T20:09:49.214Z zigbee-herdsman:adapter:ezsp:driv Pause 10sec before try 1
2024-01-15T20:09:49.793Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":1} after 2000ms
2024-01-15T20:09:49.793Z zigbee-herdsman:adapter:ezsp:uart -!- break rewaiting (1)
2024-01-15T20:09:49.794Z zigbee-herdsman:adapter:ezsp:uart Can't resend DATA frame (0,0,1): 000005
2024-01-15T20:09:49.795Z zigbee-herdsman:adapter:ezsp:erro Watchdog heartbeat timeout Error: Failure send nop:{"type":"Buffer","data":[0,0,5]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:608:23
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Ezsp.watchdogHandler (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:712:13)
2024-01-15T20:09:51.325Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 2
2024-01-15T20:09:51.325Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:51.327Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 2 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:09:55.294Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 1
2024-01-15T20:09:55.294Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-15T20:09:55.294Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-15T20:09:55.294Z zigbee-herdsman:adapter:ezsp:uart --> DATA (1,1,0): 010005
2024-01-15T20:09:55.294Z zigbee-herdsman:adapter:ezsp:uart --> [7d314321adfcbe7e]
2024-01-15T20:09:55.295Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (2)
2024-01-15T20:09:55.298Z zigbee-herdsman:adapter:ezsp:uart <-- [1243a1ad0c2a5c56567e]
2024-01-15T20:09:55.299Z zigbee-herdsman:adapter:ezsp:uart --> parsed 1243a1ad0c2a5c56567e
2024-01-15T20:09:55.299Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (1,2,0): 1243a1ad0c2a5c56567e
2024-01-15T20:09:55.299Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (2)
2024-01-15T20:09:55.299Z zigbee-herdsman:adapter:ezsp:uart --> [82503a7e]
2024-01-15T20:09:55.300Z zigbee-herdsman:adapter:ezsp:uart Error while parsing to ZpiObject 'TypeError: debug.log is not a function
    at SerialDriver.handleACK (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:232:15)
    at SerialDriver.handleDATA (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:212:30)
    at SerialDriver.onParsed (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:173:22)
    at Parser.emit (node:events:517:28)
    at Parser.parseNext (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:52:34)
    at Parser._transform (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:33:14)
    at Parser.Transform._write (node:internal/streams/transform:175:8)
    at writeOrBuffer (node:internal/streams/writable:392:12)
    at _write (node:internal/streams/writable:333:10)
    at Parser.Writable.write (node:internal/streams/writable:337:10)'
2024-01-15T20:09:56.329Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 3
2024-01-15T20:09:56.329Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:09:56.330Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 3 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:09:57.297Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":2} after 2000ms
2024-01-15T20:09:57.297Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (2)
2024-01-15T20:09:57.297Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (1,1,0): 010005
2024-01-15T20:09:57.798Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (1,1,1): 010005
2024-01-15T20:09:57.798Z zigbee-herdsman:adapter:ezsp:uart --> [194321ad797d5d7e]
2024-01-15T20:09:57.798Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (2)
2024-01-15T20:09:57.801Z zigbee-herdsman:adapter:ezsp:uart <-- [a274587e]
2024-01-15T20:09:57.801Z zigbee-herdsman:adapter:ezsp:uart --> parsed a274587e
2024-01-15T20:09:57.802Z zigbee-herdsman:adapter:ezsp:uart Error while parsing to ZpiObject 'TypeError: debug.log is not a function
    at SerialDriver.handleNAK (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:247:15)
    at SerialDriver.onParsed (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:179:22)
    at Parser.emit (node:events:517:28)
    at Parser.parseNext (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:52:34)
    at Parser._transform (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:33:14)
    at Parser.Transform._write (node:internal/streams/transform:175:8)
    at writeOrBuffer (node:internal/streams/writable:392:12)
    at _write (node:internal/streams/writable:333:10)
    at Parser.Writable.write (node:internal/streams/writable:337:10)
    at SerialPort.ondata (node:internal/streams/readable:777:22)'
2024-01-15T20:09:59.217Z zigbee-herdsman:adapter:ezsp:driv Reset connection. Try 1
2024-01-15T20:09:59.217Z zigbee-herdsman:adapter:ezsp:driv Stop driver
2024-01-15T20:09:59.217Z zigbee-herdsman:adapter:ezsp:ezsp Stop ezsp
2024-01-15T20:09:59.217Z zigbee-herdsman:adapter:ezsp:uart closing
2024-01-15T20:09:59.217Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-15T20:09:59.217Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-15T20:09:59.799Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":2} after 2000ms
2024-01-15T20:09:59.799Z zigbee-herdsman:adapter:ezsp:uart -!- break rewaiting (2)
2024-01-15T20:09:59.799Z zigbee-herdsman:adapter:ezsp:uart Can't resend DATA frame (1,1,1): 010005
2024-01-15T20:09:59.800Z zigbee-herdsman:adapter:ezsp:erro Watchdog heartbeat timeout Error: Failure send nop:{"type":"Buffer","data":[1,0,5]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:608:23
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Ezsp.watchdogHandler (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:712:13)
2024-01-15T20:10:00.218Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:10:00.219Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 1 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:10:01.332Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 4
2024-01-15T20:10:01.332Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true}
2024-01-15T20:10:01.334Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 4 error: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/serialPort.ts:28:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-15T20:10:01.334Z zigbee-herdsman:adapter:ezsp:erro EZSP could not connect: Error: Error while opening serialport 'Error: Error Resource temporarily unavailable Cannot lock port'
2024-01-15T20:10:01.334Z zigbee-herdsman:adapter:ezsp:erro Reset error Error: Failure to connect
    at Ezsp.connect (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:293:19)
    at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:143:13)
    at Driver.reset (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:116:24)
    at EZSPAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:174:20)
    at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:132:29)
    at Zigbee.start (/app/lib/zigbee.ts:60:27)
    at Controller.start (/app/lib/controller.ts:98:27)
    at start (/app/index.js:107:5)
2024-01-15T20:10:01.334Z zigbee-herdsman:adapter:ezsp:driv Pause 30sec before try 2

@wastez
Copy link
Author

wastez commented Jan 15, 2024

The version from 13.1 is working without problems.
The version from today isn't working anymore.
So it seem to be related to the last changes in the zigbee-herdsmann source.

Nerivec added a commit to Nerivec/zigbee-herdsman that referenced this issue Jan 15, 2024
@Nerivec
Copy link
Collaborator

Nerivec commented Jan 15, 2024

I unfortunately don't have test equipment at the moment...
@wastez, following the fix, assuming everything works, I'd appreciate it if you could report your observations in a couple of days (here will be fine, even if it's closed by then, unless you encounter a new issue of course). 😉

@wastez
Copy link
Author

wastez commented Jan 15, 2024

@Nerivec
Of course i will tell you how it will work.

@Koenkk
Would it possible to migrate it into the dev channel?
Would be really great.

@wastez
Copy link
Author

wastez commented Jan 15, 2024

@Nerivec
Do you have a idea if I could migrate this manual to the container?

otherwise i will restore the backup from yesterday because right now z2m isn’t usable for me and with the edge version I can’t back. (Need the edge version because auf the 7.4.0 firmware)

@mamrai1
Copy link

mamrai1 commented Jan 16, 2024

If you haven't deleted the old latest-dev image:
1)Stop z2m container and delete the latest-dev image
2) docker tag sha256:0d024c7064d81f74864b6327d35144716c33f936e0b74cc23660db224e088d31 koenkk/zigbee2mqtt:latest-dev
3) start the container

Koenkk pushed a commit to Koenkk/zigbee-herdsman that referenced this issue Jan 16, 2024
@Koenkk
Copy link
Owner

Koenkk commented Jan 16, 2024

Should be fixed now!

Changes will be available in the dev branch in a few hours from now.

@wastez
Copy link
Author

wastez commented Jan 16, 2024

@mamrai1
Yeah that was the problem deleted it and made no backup of it in Hass.
So I thought to implement the changes directly. But this was not so easy.
So i had to restore my backup from the last day on my proxmox server.

@Koenkk
Thank you will test it.

@wastez
Copy link
Author

wastez commented Jan 16, 2024

Ok updated it and now it seem to work.
So far so good, will keep you up to date.

@wastez
Copy link
Author

wastez commented Jan 19, 2024

@Nerivec
Just to inform you, so it seems to work but there are some waitress problems.

For example:

Zigbee2MQTT:error 2024-01-16 22:31:25: Failed to configure 'Vorhaus - Bewegungsmelder', attempt 2 (Error: Read 0x54ef441000777cc6/1 aqaraOpple([338], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 33566 - 1 - 173 - 64704 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:471:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1766:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))

@Koenkk
Copy link
Owner

Koenkk commented Jan 20, 2024

@wastez thats not because of the EZSP adapter, seems the device just doesn't respond.

@wastez
Copy link
Author

wastez commented Jan 20, 2024

Yes but since this changes I have it with every device.

@Koenkk
Copy link
Owner

Koenkk commented Jan 21, 2024

@wastez looks like an issue in the EZSP firmware, did you already try downgrading it?

@wastez
Copy link
Author

wastez commented Jan 21, 2024

Yes could be and of course I could downgrade.
But it wasn't before this changes I think, even with this firmware. Are you sure the changes could not cause this problem?

@wastez
Copy link
Author

wastez commented Jan 21, 2024

Here much more about it:


[18:03:27] INFO: Preparing to start...
[18:03:27] INFO: Socat not enabled
[18:03:28] INFO: Starting Zigbee2MQTT...
Assertion failed: Command (setConfigurationValue(1, 255)) returned unexpected state: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":55}
Assertion failed: exportKey returned unexpected status: 45
Zigbee2MQTT:warn  2024-01-20 18:03:43: Failed to ping 'Bad - Deckenbeleuchtung' (attempt 1/1, Read 0x84b4dbfffe2171c7/1 genBasic(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 15786 - 1 - 8 - 0 - 1 after 10000ms))
Zigbee2MQTT:warn  2024-01-20 18:04:55: OTA: Images currently unavailable for device 'TS0601', hardwareVersion '1', manufacturerName _TZE200_hue3yfsn, {"fieldControl":0,"manufacturerCode":4098,"imageType":5634,"fileVersion":69}'
Zigbee2MQTT:error 2024-01-20 18:12:56: Failed to configure 'Vorhaus - Bewegungsmelder', attempt 1 (Error: Read 0x54ef441000777cc6/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 33566 - 1 - 42 - 1 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1764:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:error 2024-01-20 18:12:59: Failed to configure 'Hobbyzimmer - Bewegungsmelder', attempt 1 (Error: Read 0x54ef44100053d18c/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 50564 - 1 - 43 - 1 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1764:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:error 2024-01-20 18:13:38: Failed to configure 'Hobbyzimmer - Bewegungsmelder', attempt 2 (Error: Read 0x54ef44100053d18c/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 50564 - 1 - 44 - 1 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1764:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:error 2024-01-20 18:13:47: Failed to configure 'Vorhaus - Bewegungsmelder', attempt 2 (Error: Read 0x54ef441000777cc6/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 33566 - 1 - 49 - 1 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1764:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:error 2024-01-20 18:17:46: Failed to configure 'Vorhaus - Bewegungsmelder', attempt 3 (Error: Read 0x54ef441000777cc6/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 33566 - 1 - 61 - 1 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1764:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:error 2024-01-20 18:17:49: Failed to configure 'Hobbyzimmer - Bewegungsmelder', attempt 3 (Error: Read 0x54ef44100053d18c/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 50564 - 1 - 64 - 1 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1764:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:error 2024-01-20 18:52:30: Failed to configure 'Bad - Bewegungsmelder', attempt 1 (Error: Read 0x54ef44100053ce97/1 aqaraOpple([338], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 20912 - 1 - 54 - 64704 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1767:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:error 2024-01-20 19:06:24: Failed to configure 'Bad - Bewegungsmelder', attempt 2 (Error: Read 0x54ef44100053ce97/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 20912 - 1 - 115 - 1 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1764:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:error 2024-01-20 19:44:42: Failed to configure 'Bad - Bewegungsmelder', attempt 3 (Error: Read 0x54ef44100053ce97/1 aqaraOpple([338], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 20912 - 1 - 218 - 64704 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1767:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:warn  2024-01-21 05:23:10: Failed to ping 'Bad - Lueftersteuerung' (attempt 1/2, Read 0x00124b0024c336a3/1 genBasic(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 37115 - 1 - 96 - 0 - 1 after 10000ms))
Zigbee2MQTT:warn  2024-01-21 05:23:33: Failed to ping 'Bad - Lueftersteuerung' (attempt 2/2, Read 0x00124b0024c336a3/1 genBasic(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 37115 - 1 - 97 - 0 - 1 after 10000ms))

@wastez
Copy link
Author

wastez commented Jan 21, 2024

But looks it only happens after a fresh start of z2m

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 21, 2024

Can you capture one with herdsman debug ON?

@wastez
Copy link
Author

wastez commented Jan 22, 2024

Ok here it is:


Zigbee2MQTT:error 2024-01-22 00:54:43: Failed to configure 'Hobbyzimmer - Bewegung
smelder', attempt 1 (Error: Read 0x54ef44100053d18c/1 aqaraOpple([338], {"timeout"
:10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":tr
ue,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"tran
sactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 50564 - 1 - 34 
- 64704 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23
)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsm
an/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/requ
est.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpo
int.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.
ts:1767:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts
:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))
Zigbee2MQTT:debug 2024-01-22 00:54:46: Saving state to file /config/zigbee2mqtt/st
ate.json
Zigbee2MQTT:debug 2024-01-22 00:54:50: Received Zigbee message from 'Kueche - Lamp
enschirm', type 'readResponse', cluster 'genBasic', data '{"zclVersion":3}' from e
ndpoint 1 with groupID 0
Zigbee2MQTT:info  2024-01-22 00:54:50: MQTT publish: topic 'zigbee2mqtt/Kueche - L
ampenschirm', payload '{"brightness":254,"color_mode":"color_temp","color_options"
:

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 22, 2024

Can you include the stuff before Zigbee2MQTT:error ? That's the part I want.
Everything from INFO: Preparing to start... to the first error would be great in fact.

@wastez
Copy link
Author

wastez commented Jan 22, 2024

Do you search for that:


Zigbee2MQTT:info  2024-01-22 00:54:20: Configuring 'Hobbyzimmer - Bewegungsmelder'
Zigbee2MQTT:debug 2024-01-22 00:54:20: Received Zigbee message from 'Hobbyzimmer - Bewegungsmelder', type 'attributeReport', cluster 'aqaraOpple', data '{"247":{"data":[1,33,196,11,3,40,24,4,33,0,0,5,33,2,0,8,33,10,1,10,33,57,97,12,32,1,19,32,0,20,32,0,100,16,0,101,33,21,0,105,32,30,106,32,3,107,32,0],"type":"Buffer"}}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: Processed buffer into data {"1":3012,"3":24,"4":0,"5":2,"8":266,"10":24889,"12":1,"19":0,"20":0,"100":0,"101":21,"105":30,"106":3,"107":0}
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: unknown key 19 with value 0
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: unknown key 20 with value 0
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: Processed data into payload {"voltage":3012,"battery":100,"device_temperature":24,"power_outage_count":1,"illuminance":21,"detection_interval":30,"motion_sensitivity":"high","trigger_indicator":false}
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: Processed data into payload {"voltage":3012,"battery":100,"device_temperature":24,"power_outage_count":1,"illuminance":21,"detection_interval":30,"motion_sensitivity":"high","trigger_indicator":false}
Zigbee2MQTT:info  2024-01-22 00:54:20: MQTT publish: topic 'zigbee2mqtt/Hobbyzimmer - Bewegungsmelder', payload '{"battery":100,"detection_interval":30,"device_temperature":24,"illuminance":21,"last_seen":"2024-01-22T00:54:20+01:00","linkquality":224,"motion_sensitivity":"high","occupancy":false,"power_outage_count":1,"trigger_indicator":false,"update":{"installed_version":10,"latest_version":10,"state":"idle"},"update_available":null,"voltage":3012}'
Zigbee2MQTT:debug 2024-01-22 00:54:21: Received Zigbee message from 'Hobbyzimmer - Bewegungsmelder', type 'readResponse', cluster 'genPowerCfg', data '{"batteryVoltage":29}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2024-01-22 00:54:21: MQTT publish: topic 'zigbee2mqtt/Hobbyzimmer - Bewegungsmelder', payload '{"battery":33,"detection_interval":30,"device_temperature":24,"illuminance":21,"last_seen":"2024-01-22T00:54:21+01:00","linkquality":224,"motion_sensitivity":"high","occupancy":false,"power_outage_count":1,"trigger_indicator":false,"update":{"installed_version":10,"latest_version":10,"state":"idle"},"update_available":null,"voltage":2900}'
Zigbee2MQTT:debug 2024-01-22 00:54:22: Received Zigbee message from 'Hobbyzimmer - Bewegungsmelder', type 'readResponse', cluster 'aqaraOpple', data '{"258":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2024-01-22 00:54:22: RTCGQ14LM: Processed data into payload {"detection_interval":30}

Zigbee2MQTT:info  2024-01-22 00:54:22: MQTT publish: topic 'zigbee2mqtt/Hobbyzimmer - Bewegungsmelder', payload '{"battery":33,"detection_interval":30,"device_temperature":24,"illuminance":21,"last_seen":"2024-01-22T00:54:22+01:00","linkquality":220,"motion_sensitivity":"high","occupancy":false,"power_outage_count":1,"trigger_indicator":false,"update":{"installed_version":10,"latest_version":10,"state":"idle"},"update_available":null,"voltage":2900}'
Zigbee2MQTT:debug 2024-01-22 00:54:23: Received Zigbee message from 'Hobbyzimmer - Bewegungsmelder', type 'readResponse', cluster 'aqaraOpple', data '{"268":3}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2024-01-22 00:54:23: RTCGQ14LM: Processed data into payload {"motion_sensitivity":"high"}
Zigbee2MQTT:info  2024-01-22 00:54:23: MQTT publish: topic 'zigbee2mqtt/Hobbyzimmer - Bewegungsmelder', payload '{"battery":33,"detection_interval":30,"device_temperature":24,"illuminance":21,"last_seen":"2024-01-22T00:54:23+01:00","linkquality":224,"motion_sensitivity":"high","occupancy":false,"power_outage_count":1,"trigger_indicator":false,"update":{"installed_version":10,"latest_version":10,"state":"idle"},"update_available":null,"voltage":2900}'
Zigbee2MQTT:error 2024-01-22 00:54:43: Failed to configure 'Hobbyzimmer - Bewegungsmelder', attempt 1 (Error: Read 0x54ef44100053d18c/1 aqaraOpple([338], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 50564 - 1 - 34 - 64704 - 1 after 10000ms)

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 22, 2024

I'm looking for the lines like you had in your first log, zigbee-herdsman:adapter:ezsp:ezsp, zigbee-herdsman:adapter:ezsp:uart that kind. Seems you don't have herdsman debug ON here.

@wastez
Copy link
Author

wastez commented Jan 22, 2024

Sorry less cuted it:


2024-01-21T23:54:03.733Z zigbee-herdsman:adapter:ezsp:driv handleRouteRecord: nwk=28854, ieee=0�����, lqi=208, rssi=-48, relays=�
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:uart <-- [719ab1a97d312a15b259914a25aa5592499c16f77b5bbe9874fe896389f8ee547e]
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:uart --> parsed 719ab1a9112a15b259914a25aa5592499c16f77b5bbe9874fe896389f8ee547e
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (7,1,0): 719ab1a9112a15b259914a25aa5592499c16f77b5bbe9874fe896389f8ee547e
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (0)
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:uart --> [8070787e]
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 719ab1a9112a15b259914a25aa5592499c16f77b5bbe9874fe896389f8ee547e
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: d890014500000000050000000000000058d0d0b670ffff034f000004
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x45: {"_cls_":"incomingMessageHandler","_id_":69,"_isRequest_":false,"type":0,"apsFrame":{"profileId":0,"sequence":88,"clusterId":5,"sourceEndpoint":0,"destinationEndpoint":0,"groupId":0,"options":0},"lastHopLqi":208,"lastHopRssi":-48,"sender":28854,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[79,0,0]}}
2024-01-21T23:54:03.780Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":0,"sequence":88,"clusterId":5,"sourceEndpoint":0,"destinationEndpoint":0,"groupId":0,"options":0},"lqi":208,"rssi":-48,"sender":28854,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[79,0,0]}}
2024-01-21T23:54:08.294Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-21T23:54:08.294Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-21T23:54:08.294Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-21T23:54:08.294Z zigbee-herdsman:adapter:ezsp:uart --> DATA (1,0,0): d900010500
2024-01-21T23:54:08.294Z zigbee-herdsman:adapter:ezsp:uart --> [109b21a9512a04b07e]
2024-01-21T23:54:08.295Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (2)
2024-01-21T23:54:08.298Z zigbee-herdsman:adapter:ezsp:uart <-- [029ba1a9512a484c7e]
2024-01-21T23:54:08.298Z zigbee-herdsman:adapter:ezsp:uart --> parsed 029ba1a9512a484c7e
2024-01-21T23:54:08.298Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,2,0): 029ba1a9512a484c7e
2024-01-21T23:54:08.298Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2024-01-21T23:54:08.298Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2024-01-21T23:54:08.298Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (2): 029ba1a9512a484c7e
2024-01-21T23:54:08.298Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: d980010500
2024-01-21T23:54:08.299Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x5: {"_cls_":"nop","_id_":5,"_isRequest_":false}
2024-01-21T23:54:08.299Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (2) success
2024-01-21T23:54:18.302Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-21T23:54:18.302Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-21T23:54:18.303Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-21T23:54:18.303Z zigbee-herdsman:adapter:ezsp:uart --> DATA (2,1,0): da00010500
2024-01-21T23:54:18.303Z zigbee-herdsman:adapter:ezsp:uart --> [219821a9512a804e7e]
2024-01-21T23:54:18.303Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (3)
2024-01-21T23:54:18.307Z zigbee-herdsman:adapter:ezsp:uart <-- [7d3398a1a9512af9ba7e]
2024-01-21T23:54:18.307Z zigbee-herdsman:adapter:ezsp:uart --> parsed 1398a1a9512af9ba7e
2024-01-21T23:54:18.307Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (1,3,0): 1398a1a9512af9ba7e
2024-01-21T23:54:18.307Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (2)
2024-01-21T23:54:18.307Z zigbee-herdsman:adapter:ezsp:uart --> [82503a7e]
2024-01-21T23:54:18.307Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (3): 1398a1a9512af9ba7e
2024-01-21T23:54:18.307Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: da80010500
2024-01-21T23:54:18.307Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x5: {"_cls_":"nop","_id_":5,"_isRequest_":false}
2024-01-21T23:54:18.308Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (3) success
2024-01-21T23:54:20.312Z zigbee-herdsman:adapter:ezsp:uart <-- [2398b1a90d2a9177d5451925ba7d317d5d1d7c9a26928ce87d5d7e]
2024-01-21T23:54:20.312Z zigbee-herdsman:adapter:ezsp:uart --> parsed 2398b1a90d2a9177d5451925ba117d1d7c9a26928ce87d7e
2024-01-21T23:54:20.312Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (2,3,0): 2398b1a90d2a9177d5451925ba117d1d7c9a26928ce87d7e
2024-01-21T23:54:20.312Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (3)
2024-01-21T23:54:20.312Z zigbee-herdsman:adapter:ezsp:uart --> [83401b7e]
2024-01-21T23:54:20.312Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (3): 2398b1a90d2a9177d5451925ba117d1d7c9a26928ce87d7e
2024-01-21T23:54:20.313Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: da9001590084c58cd153001044ef54e0d4013961
2024-01-21T23:54:20.313Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x59: {"_cls_":"incomingRouteRecordHandler","_id_":89,"_isRequest_":false,"source":50564,"longId":{"type":"Buffer","data":[84,239,68,16,0,83,209,140]},"lastHopLqi":224,"lastHopRssi":-44,"relay":{"type":"Buffer","data":[57]}}
2024-01-21T23:54:20.313Z zigbee-herdsman:adapter:ezsp:driv handleRouteRecord: nwk=50564, ieee=T�DSь, lqi=224, rssi=-44, relays=9
2024-01-21T23:54:20.370Z zigbee-herdsman:adapter:ezsp:uart <-- [3398b1a97d312a15b65854b624ab5593499c22c77f690b9874c4da3c987374c8a7aafddf4e4bf4c4f3cdd6488c462688ee763384e0748860a12d2a33b0f35038082e07dff5ca00ab509a24be51f5d7c0b2f46a3102d27e]
2024-01-21T23:54:20.370Z zigbee-herdsman:adapter:ezsp:uart --> parsed 3398b1a9112a15b65854b624ab5593499c22c77f690b9874c4da3c987374c8a7aafddf4e4bf4c4f3cdd6488c462688ee763384e0748860a12d2a33b0f35038082e07dff5ca00ab509a24be51f5d7c0b2f46a3102d27e
2024-01-21T23:54:20.370Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (3,3,0): 3398b1a9112a15b65854b624ab5593499c22c77f690b9874c4da3c987374c8a7aafddf4e4bf4c4f3cdd6488c462688ee763384e0748860a12d2a33b0f35038082e07dff5ca00ab509a24be51f5d7c0b2f46a3102d27e
2024-01-21T23:54:20.370Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (4)
2024-01-21T23:54:20.370Z zigbee-herdsman:adapter:ezsp:uart --> [8430fc7e]
2024-01-21T23:54:20.370Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (3): 3398b1a9112a15b65854b624ab5593499c22c77f690b9874c4da3c987374c8a7aafddf4e4bf4c4f3cdd6488c462688ee763384e0748860a12d2a33b0f35038082e07dff5ca00ab509a24be51f5d7c0b2f46a3102d27e
2024-01-21T23:54:20.371Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: da90014500000401c0fc0101000100006ce0d484c5ffff391c5f118f0af70041300121c40b032818042100000521020008210a010a2139610c20011320001420006410006521150069201e6a20036b200004
2024-01-21T23:54:20.371Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x45: {"_cls_":"incomingMessageHandler","_id_":69,"_isRequest_":false,"type":0,"apsFrame":{"profileId":260,"sequence":108,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"lastHopLqi":224,"lastHopRssi":-44,"sender":50564,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[28,95,17,143,10,247,0,65,48,1,33,196,11,3,40,24,4,33,0,0,5,33,2,0,8,33,10,1,10,33,57,97,12,32,1,19,32,0,20,32,0,100,16,0,101,33,21,0,105,32,30,106,32,3,107,32,0]}}
2024-01-21T23:54:20.371Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":260,"sequence":108,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"lqi":224,"rssi":-44,"sender":50564,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[28,95,17,143,10,247,0,65,48,1,33,196,11,3,40,24,4,33,0,0,5,33,2,0,8,33,10,1,10,33,57,97,12,32,1,19,32,0,20,32,0,100,16,0,101,33,21,0,105,32,30,106,32,3,107,32,0]}}
2024-01-21T23:54:20.371Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":true,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":143,"manufacturerCode":4447,"commandIdentifier":10},"Payload":[{"attrId":247,"dataType":65,"attrData":{"type":"Buffer","data":[1,33,196,11,3,40,24,4,33,0,0,5,33,2,0,8,33,10,1,10,33,57,97,12,32,1,19,32,0,20,32,0,100,16,0,101,33,21,0,105,32,30,106,32,3,107,32,0]}}],"Command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}},"address":50564,"endpoint":1,"linkquality":224,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}'
Zigbee2MQTT:info  2024-01-22 00:54:20: Configuring 'Hobbyzimmer - Bewegungsmelder'
2024-01-21T23:54:20.372Z zigbee-herdsman:controller:endpoint Read 0x54ef44100053d18c/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false})
2024-01-21T23:54:20.372Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0x54ef44100053d18c:50564/1 (0,0,1), timeout=10000
Zigbee2MQTT:debug 2024-01-22 00:54:20: Received Zigbee message from 'Hobbyzimmer - Bewegungsmelder', type 'attributeReport', cluster 'aqaraOpple', data '{"247":{"data":[1,33,196,11,3,40,24,4,33,0,0,5,33,2,0,8,33,10,1,10,33,57,97,12,32,1,19,32,0,20,32,0,100,16,0,101,33,21,0,105,32,30,106,32,3,107,32,0],"type":"Buffer"}}' from endpoint 1 with groupID 0
2024-01-21T23:54:20.373Z zigbee-herdsman:adapter:ezsp:ezsp ==> sendUnicast: {"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":82,"clusterId":1,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":83,"message":{"type":"Buffer","data":[16,31,0,32,0]}}
2024-01-21T23:54:20.374Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"sendUnicast","_id_":52,"_isRequest_":true,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":82,"clusterId":1,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":83,"message":{"type":"Buffer","data":[16,31,0,32,0]}}
2024-01-21T23:54:20.374Z zigbee-herdsman:adapter:ezsp:uart --> DATA (3,4,0): db000134000084c504010100010100010000525305101f002000
2024-01-21T23:54:20.374Z zigbee-herdsman:adapter:ezsp:uart --> [349921a9602a15369c904b24aa5493499d4e27f9becb7794fde66367527e]
2024-01-21T23:54:20.374Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (4)
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: Processed buffer into data {"1":3012,"3":24,"4":0,"5":2,"8":266,"10":24889,"12":1,"19":0,"20":0,"100":0,"101":21,"105":30,"106":3,"107":0}
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: unknown key 19 with value 0
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: unknown key 20 with value 0
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: Processed data into payload {"voltage":3012,"battery":100,"device_temperature":24,"power_outage_count":1,"illuminance":21,"detection_interval":30,"motion_sensitivity":"high","trigger_indicator":false}
Zigbee2MQTT:debug 2024-01-22 00:54:20: RTCGQ14LM: Processed data into payload {"voltage":3012,"battery":100,"device_temperature":24,"power_outage_count":1,"illuminance":21,"detection_interval":30,"motion_sensitivity":"high","trigger_indicator":false}
Zigbee2MQTT:info  2024-01-22 00:54:20: MQTT publish: topic 'zigbee2mqtt/Hobbyzimmer - Bewegungsmelder', payload '{"battery":100,"detection_interval":30,"device_temperature":24,"illuminance":21,"last_seen":"2024-01-22T00:54:20+01:00","linkquality":224,"motion_sensitivity":"high","occupancy":false,"power_outage_count":1,"trigger_indicator":false,"update":{"installed_version":10,"latest_version":10,"state":"idle"},"update_available":null,"voltage":3012}'
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:uart <-- [4499a1a9602a15e510857e]
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:uart --> parsed 4499a1a9602a15e510857e
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (4,4,0): 4499a1a9602a15e510857e
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (5)
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:uart --> [8520dd7e]
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (4): 4499a1a9602a15e510857e
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: db800134000057
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x34: {"_cls_":"sendUnicast","_id_":52,"_isRequest_":false,"status":0,"sequence":87}
2024-01-21T23:54:20.384Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (4) success
2024-01-21T23:54:20.392Z zigbee-herdsman:adapter:ezsp:uart <-- [5499b1a96b2a15369c904b24aa5493499d4e27fcbece67ad537e]
2024-01-21T23:54:20.392Z zigbee-herdsman:adapter:ezsp:uart --> parsed 5499b1a96b2a15369c904b24aa5493499d4e27fcbece67ad537e
2024-01-21T23:54:20.393Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (5,4,0): 5499b1a96b2a15369c904b24aa5493499d4e27fcbece67ad537e
2024-01-21T23:54:20.393Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (6)
2024-01-21T23:54:20.393Z zigbee-herdsman:adapter:ezsp:uart --> [8610be7e]
2024-01-21T23:54:20.393Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (4): 5499b1a96b2a15369c904b24aa5493499d4e27fcbece67ad537e
2024-01-21T23:54:20.393Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: db90013f000084c50401010001010001000057530000
2024-01-21T23:54:20.393Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x3f: {"_cls_":"messageSentHandler","_id_":63,"_isRequest_":false,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":87,"clusterId":1,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":83,"status":0,"message":{"type":"Buffer","data":[]}}
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:uart <-- [6499b1a97d312a15b658954a24ab5593499c23c77f690b9874f5de7c88dc7d5e3f87f6c9307d337e]
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:uart --> parsed 6499b1a9112a15b658954a24ab5593499c23c77f690b9874f5de7c88dc7e3f87f6c930137e
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (6,4,0): 6499b1a9112a15b658954a24ab5593499c23c77f690b9874f5de7c88dc7e3f87f6c930137e
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (7)
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:uart --> [87009f7e]
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (4): 6499b1a9112a15b658954a24ab5593499c23c77f690b9874f5de7c88dc7e3f87f6c930137e
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: db9001450000040101000101000100006de0d484c5ffff08181f01200000201d04
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x45: {"_cls_":"incomingMessageHandler","_id_":69,"_isRequest_":false,"type":0,"apsFrame":{"profileId":260,"sequence":109,"clusterId":1,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"lastHopLqi":224,"lastHopRssi":-44,"sender":50564,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[24,31,1,32,0,0,32,29]}}
2024-01-21T23:54:21.330Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":260,"sequence":109,"clusterId":1,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"lqi":224,"rssi":-44,"sender":50564,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[24,31,1,32,0,0,32,29]}}
2024-01-21T23:54:21.331Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":31,"manufacturerCode":null,"commandIdentifier":1},"Payload":[{"attrId":32,"status":0,"dataType":32,"attrData":29}],"Command":{"ID":1,"name":"readRsp","parameters":[{"name":"attrId","type":33},{"name":"status","type":32},{"name":"dataType","type":32,"conditions":[{"type":"statusEquals","value":0}]},{"name":"attrData","type":1000,"conditions":[{"type":"statusEquals","value":0}]}]}},"address":50564,"endpoint":1,"linkquality":224,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}'
Zigbee2MQTT:debug 2024-01-22 00:54:21: Received Zigbee message from 'Hobbyzimmer - Bewegungsmelder', type 'readResponse', cluster 'genPowerCfg', data '{"batteryVoltage":29}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2024-01-22 00:54:21: MQTT publish: topic 'zigbee2mqtt/Hobbyzimmer - Bewegungsmelder', payload '{"battery":33,"detection_interval":30,"device_temperature":24,"illuminance":21,"last_seen":"2024-01-22T00:54:21+01:00","linkquality":224,"motion_sensitivity":"high","occupancy":false,"power_outage_count":1,"trigger_indicator":false,"update":{"installed_version":10,"latest_version":10,"state":"idle"},"update_available":null,"voltage":2900}'
2024-01-21T23:54:21.333Z zigbee-herdsman:controller:endpoint Read 0x54ef44100053d18c/1 aqaraOpple([258], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false})
2024-01-21T23:54:21.334Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0x54ef44100053d18c:50564/1 (0,0,1), timeout=10000
2024-01-21T23:54:21.334Z zigbee-herdsman:adapter:ezsp:ezsp ==> sendUnicast: {"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":83,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":84,"message":{"type":"Buffer","data":[20,95,17,32,0,2,1]}}
2024-01-21T23:54:21.334Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"sendUnicast","_id_":52,"_isRequest_":true,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":83,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":84,"message":{"type":"Buffer","data":[20,95,17,32,0,2,1]}}
2024-01-21T23:54:21.334Z zigbee-herdsman:adapter:ezsp:uart --> DATA (4,7,0): dc000134000084c50401c0fc010100010000535407145f1120000201
2024-01-21T23:54:21.334Z zigbee-herdsman:adapter:ezsp:uart --> [479e21a9602a15369c904be5565493499d4e27f8b9c973d4ece6638bfde7617e]
2024-01-21T23:54:21.334Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (5)
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:uart <-- [759ea1a9602a15eaf9217e]
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:uart --> parsed 759ea1a9602a15eaf9217e
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (7,5,0): 759ea1a9602a15eaf9217e
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (0)
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:uart --> [8070787e]
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (5): 759ea1a9602a15eaf9217e
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: dc800134000058
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x34: {"_cls_":"sendUnicast","_id_":52,"_isRequest_":false,"status":0,"sequence":88}
2024-01-21T23:54:21.342Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (5) success
2024-01-21T23:54:21.352Z zigbee-herdsman:adapter:ezsp:uart <-- [059eb1a96b2a15369c904be5565493499d4e27f3b9ce67ccc47e]
2024-01-21T23:54:21.352Z zigbee-herdsman:adapter:ezsp:uart --> parsed 059eb1a96b2a15369c904be5565493499d4e27f3b9ce67ccc47e
2024-01-21T23:54:21.352Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,5,0): 059eb1a96b2a15369c904be5565493499d4e27f3b9ce67ccc47e
2024-01-21T23:54:21.352Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2024-01-21T23:54:21.352Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2024-01-21T23:54:21.353Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (5): 059eb1a96b2a15369c904be5565493499d4e27f3b9ce67ccc47e
2024-01-21T23:54:21.353Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: dc90013f000084c50401c0fc01010001000058540000
2024-01-21T23:54:21.353Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x3f: {"_cls_":"messageSentHandler","_id_":63,"_isRequest_":false,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":88,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":84,"status":0,"message":{"type":"Buffer","data":[]}}
2024-01-21T23:54:22.343Z zigbee-herdsman:adapter:ezsp:uart <-- [159eb1a97d312a15b65854b624ab5593499c20fb78690b9874f7da3c98dc7f3da6ebedc06bc6f27e]
2024-01-21T23:54:22.343Z zigbee-herdsman:adapter:ezsp:uart --> parsed 159eb1a9112a15b65854b624ab5593499c20fb78690b9874f7da3c98dc7f3da6ebedc06bc6f27e
2024-01-21T23:54:22.344Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (1,5,0): 159eb1a9112a15b65854b624ab5593499c20fb78690b9874f7da3c98dc7f3da6ebedc06bc6f27e
2024-01-21T23:54:22.344Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (2)
2024-01-21T23:54:22.344Z zigbee-herdsman:adapter:ezsp:uart --> [82503a7e]
2024-01-21T23:54:22.344Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (5): 159eb1a9112a15b65854b624ab5593499c20fb78690b9874f7da3c98dc7f3da6ebedc06bc6f27e
2024-01-21T23:54:22.344Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: dc90014500000401c0fc0101000100006edcd384c5ffff0a1c5f112001020100201e04
2024-01-21T23:54:22.344Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x45: {"_cls_":"incomingMessageHandler","_id_":69,"_isRequest_":false,"type":0,"apsFrame":{"profileId":260,"sequence":110,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"lastHopLqi":220,"lastHopRssi":-45,"sender":50564,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[28,95,17,32,1,2,1,0,32,30]}}
2024-01-21T23:54:22.344Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":260,"sequence":110,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"lqi":220,"rssi":-45,"sender":50564,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[28,95,17,32,1,2,1,0,32,30]}}
2024-01-21T23:54:22.344Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":true,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":32,"manufacturerCode":4447,"commandIdentifier":1},"Payload":[{"attrId":258,"status":0,"dataType":32,"attrData":30}],"Command":{"ID":1,"name":"readRsp","parameters":[{"name":"attrId","type":33},{"name":"status","type":32},{"name":"dataType","type":32,"conditions":[{"type":"statusEquals","value":0}]},{"name":"attrData","type":1000,"conditions":[{"type":"statusEquals","value":0}]}]}},"address":50564,"endpoint":1,"linkquality":220,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}'
Zigbee2MQTT:debug 2024-01-22 00:54:22: Received Zigbee message from 'Hobbyzimmer - Bewegungsmelder', type 'readResponse', cluster 'aqaraOpple', data '{"258":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2024-01-22 00:54:22: RTCGQ14LM: Processed data into payload {"detection_interval":30}
Zigbee2MQTT:info  2024-01-22 00:54:22: MQTT publish: topic 'zigbee2mqtt/Hobbyzimmer - Bewegungsmelder', payload '{"battery":33,"detection_interval":30,"device_temperature":24,"illuminance":21,"last_seen":"2024-01-22T00:54:22+01:00","linkquality":220,"motion_sensitivity":"high","occupancy":false,"power_outage_count":1,"trigger_indicator":false,"update":{"installed_version":10,"latest_version":10,"state":"idle"},"update_available":null,"voltage":2900}'
2024-01-21T23:54:22.346Z zigbee-herdsman:controller:endpoint Read 0x54ef44100053d18c/1 aqaraOpple([268], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false})
2024-01-21T23:54:22.347Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0x54ef44100053d18c:50564/1 (0,0,1), timeout=10000
2024-01-21T23:54:22.347Z zigbee-herdsman:adapter:ezsp:ezsp ==> sendUnicast: {"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":84,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":85,"message":{"type":"Buffer","data":[20,95,17,33,0,12,1]}}
2024-01-21T23:54:22.347Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"sendUnicast","_id_":52,"_isRequest_":true,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":84,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":85,"message":{"type":"Buffer","data":[20,95,17,33,0,12,1]}}
2024-01-21T23:54:22.347Z zigbee-herdsman:adapter:ezsp:uart --> DATA (5,2,0): dd000134000084c50401c0fc010100010000545507145f1121000c01
2024-01-21T23:54:22.347Z zigbee-herdsman:adapter:ezsp:uart --> [529f21a9602a15369c904be5565493499d4e27ffb8c973d4ece76385fd9d057e]
2024-01-21T23:54:22.347Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (6)
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:uart <-- [269fa1a9602a15eb52707e]
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:uart --> parsed 269fa1a9602a15eb52707e
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (2,6,0): 269fa1a9602a15eb52707e
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (3)
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:uart --> [83401b7e]
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (6): 269fa1a9602a15eb52707e
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: dd800134000059
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x34: {"_cls_":"sendUnicast","_id_":52,"_isRequest_":false,"status":0,"sequence":89}
2024-01-21T23:54:22.355Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (6) success
2024-01-21T23:54:22.363Z zigbee-herdsman:adapter:ezsp:uart <-- [369fb1a96b2a15369c904be5565493499d4e27f2b8ce671f1f7e]
2024-01-21T23:54:22.363Z zigbee-herdsman:adapter:ezsp:uart --> parsed 369fb1a96b2a15369c904be5565493499d4e27f2b8ce671f1f7e
2024-01-21T23:54:22.363Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (3,6,0): 369fb1a96b2a15369c904be5565493499d4e27f2b8ce671f1f7e
2024-01-21T23:54:22.363Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (4)
2024-01-21T23:54:22.363Z zigbee-herdsman:adapter:ezsp:uart --> [8430fc7e]
2024-01-21T23:54:22.363Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (6): 369fb1a96b2a15369c904be5565493499d4e27f2b8ce671f1f7e
2024-01-21T23:54:22.363Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: dd90013f000084c50401c0fc01010001000059550000
2024-01-21T23:54:22.363Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x3f: {"_cls_":"messageSentHandler","_id_":63,"_isRequest_":false,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":89,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":85,"status":0,"message":{"type":"Buffer","data":[]}}
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:uart <-- [469fb1a97d312a15b65854b624ab5593499c21c77f690b9874f7da3c98dd7f33a6ebeddd6b875a7e]
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:uart --> parsed 469fb1a9112a15b65854b624ab5593499c21c77f690b9874f7da3c98dd7f33a6ebeddd6b875a7e
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (4,6,0): 469fb1a9112a15b65854b624ab5593499c21c77f690b9874f7da3c98dd7f33a6ebeddd6b875a7e
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (5)
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:uart --> [8520dd7e]
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (6): 469fb1a9112a15b65854b624ab5593499c21c77f690b9874f7da3c98dd7f33a6ebeddd6b875a7e
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: dd90014500000401c0fc0101000100006fe0d484c5ffff0a1c5f1121010c0100200304
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x45: {"_cls_":"incomingMessageHandler","_id_":69,"_isRequest_":false,"type":0,"apsFrame":{"profileId":260,"sequence":111,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"lastHopLqi":224,"lastHopRssi":-44,"sender":50564,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[28,95,17,33,1,12,1,0,32,3]}}
2024-01-21T23:54:23.356Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":260,"sequence":111,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"lqi":224,"rssi":-44,"sender":50564,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[28,95,17,33,1,12,1,0,32,3]}}
2024-01-21T23:54:23.356Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":true,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":33,"manufacturerCode":4447,"commandIdentifier":1},"Payload":[{"attrId":268,"status":0,"dataType":32,"attrData":3}],"Command":{"ID":1,"name":"readRsp","parameters":[{"name":"attrId","type":33},{"name":"status","type":32},{"name":"dataType","type":32,"conditions":[{"type":"statusEquals","value":0}]},{"name":"attrData","type":1000,"conditions":[{"type":"statusEquals","value":0}]}]}},"address":50564,"endpoint":1,"linkquality":224,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}'
Zigbee2MQTT:debug 2024-01-22 00:54:23: Received Zigbee message from 'Hobbyzimmer - Bewegungsmelder', type 'readResponse', cluster 'aqaraOpple', data '{"268":3}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2024-01-22 00:54:23: RTCGQ14LM: Processed data into payload {"motion_sensitivity":"high"}
Zigbee2MQTT:info  2024-01-22 00:54:23: MQTT publish: topic 'zigbee2mqtt/Hobbyzimmer - Bewegungsmelder', payload '{"battery":33,"detection_interval":30,"device_temperature":24,"illuminance":21,"last_seen":"2024-01-22T00:54:23+01:00","linkquality":224,"motion_sensitivity":"high","occupancy":false,"power_outage_count":1,"trigger_indicator":false,"update":{"installed_version":10,"latest_version":10,"state":"idle"},"update_available":null,"voltage":2900}'
2024-01-21T23:54:23.359Z zigbee-herdsman:controller:endpoint Read 0x54ef44100053d18c/1 aqaraOpple([338], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false})
2024-01-21T23:54:23.359Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0x54ef44100053d18c:50564/1 (0,0,1), timeout=10000
2024-01-21T23:54:23.359Z zigbee-herdsman:adapter:ezsp:ezsp ==> sendUnicast: {"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":85,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":86,"message":{"type":"Buffer","data":[20,95,17,34,0,82,1]}}
2024-01-21T23:54:23.359Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"sendUnicast","_id_":52,"_isRequest_":true,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":85,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":86,"message":{"type":"Buffer","data":[20,95,17,34,0,82,1]}}
2024-01-21T23:54:23.359Z zigbee-herdsman:adapter:ezsp:uart --> DATA (6,5,0): de000134000084c50401c0fc010100010000555607145f1122005201
2024-01-21T23:54:23.359Z zigbee-herdsman:adapter:ezsp:uart --> [659c21a9602a15369c904be5565493499d4e27febbc973d4ece463dbfde6947e]
2024-01-21T23:54:23.359Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (7)
2024-01-21T23:54:23.367Z zigbee-herdsman:adapter:ezsp:uart <-- [579ca1a9602a15e84d4e7e]
2024-01-21T23:54:23.367Z zigbee-herdsman:adapter:ezsp:uart --> parsed 579ca1a9602a15e84d4e7e
2024-01-21T23:54:23.367Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (5,7,0): 579ca1a9602a15e84d4e7e
2024-01-21T23:54:23.367Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (6)
2024-01-21T23:54:23.367Z zigbee-herdsman:adapter:ezsp:uart --> [8610be7e]
2024-01-21T23:54:23.367Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (7): 579ca1a9602a15e84d4e7e
2024-01-21T23:54:23.367Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: de80013400005a
2024-01-21T23:54:23.368Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x34: {"_cls_":"sendUnicast","_id_":52,"_isRequest_":false,"status":0,"sequence":90}
2024-01-21T23:54:23.368Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (7) success
2024-01-21T23:54:23.375Z zigbee-herdsman:adapter:ezsp:uart <-- [679cb1a96b2a15369c904be5565493499d4e27f1bbce67ff5e7e]
2024-01-21T23:54:23.375Z zigbee-herdsman:adapter:ezsp:uart --> parsed 679cb1a96b2a15369c904be5565493499d4e27f1bbce67ff5e7e
2024-01-21T23:54:23.375Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (6,7,0): 679cb1a96b2a15369c904be5565493499d4e27f1bbce67ff5e7e
2024-01-21T23:54:23.375Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (7)
2024-01-21T23:54:23.376Z zigbee-herdsman:adapter:ezsp:uart --> [87009f7e]
2024-01-21T23:54:23.376Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (7): 679cb1a96b2a15369c904be5565493499d4e27f1bbce67ff5e7e
2024-01-21T23:54:23.376Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: de90013f000084c50401c0fc0101000100005a560000
2024-01-21T23:54:23.376Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x3f: {"_cls_":"messageSentHandler","_id_":63,"_isRequest_":false,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":90,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":86,"status":0,"message":{"type":"Buffer","data":[]}}
2024-01-21T23:54:28.306Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-21T23:54:28.306Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-21T23:54:28.306Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-21T23:54:28.306Z zigbee-herdsman:adapter:ezsp:uart --> DATA (7,7,0): df00010500
2024-01-21T23:54:28.306Z zigbee-herdsman:adapter:ezsp:uart --> [779d21a9512a5e6c7e]
2024-01-21T23:54:28.307Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (0)
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:uart <-- [709da1a9512a4b157e]
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:uart --> parsed 709da1a9512a4b157e
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (7,0,0): 709da1a9512a4b157e
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (0)
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:uart --> [8070787e]
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (0): 709da1a9512a4b157e
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: df80010500
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x5: {"_cls_":"nop","_id_":5,"_isRequest_":false}
2024-01-21T23:54:28.311Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (0) success
2024-01-21T23:54:31.092Z zigbee-herdsman:adapter:ezsp:uart <-- [009db5a9902a7d33369c22607e]
2024-01-21T23:54:31.092Z zigbee-herdsman:adapter:ezsp:uart --> parsed 009db5a9902a13369c22607e
2024-01-21T23:54:31.092Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,0,0): 009db5a9902a13369c22607e
2024-01-21T23:54:31.092Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2024-01-21T23:54:31.092Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2024-01-21T23:54:31.092Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (0): 009db5a9902a13369c22607e
2024-01-21T23:54:31.092Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: df9401c4000684c5
2024-01-21T23:54:31.093Z zigbee-herdsman:adapter:ezsp:ezsp <== 0xc4: {"_cls_":"incomingNetworkStatusHandler","_id_":196,"_isRequest_":false,"errorCode":6,"target":50564}
2024-01-21T23:54:31.093Z zigbee-herdsman:adapter:ezsp:driv Unhandled frame incomingNetworkStatusHandler
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:uart <-- [109db1a9d42a57369ce95b7e]
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:uart --> parsed 109db1a9d42a57369ce95b7e
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (1,0,0): 109db1a9d42a57369ce95b7e
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (2)
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:uart --> [82503a7e]
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (0): 109db1a9d42a57369ce95b7e
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: df900180004284c5
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x80: {"_cls_":"incomingRouteErrorHandler","_id_":128,"_isRequest_":false,"status":66,"target":50564}
2024-01-21T23:54:31.094Z zigbee-herdsman:adapter:ezsp:driv handleRouteError: nwk=50564, status=66
2024-01-21T23:54:33.370Z zigbee-herdsman:adapter:ezsp:debg Response timeout (0x54ef44100053d18c:50564,0)
2024-01-21T23:54:33.370Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0x54ef44100053d18c:50564/1 (1,0,1), timeout=10000
2024-01-21T23:54:33.371Z zigbee-herdsman:adapter:ezsp:ezsp ==> sendUnicast: {"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":86,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":87,"message":{"type":"Buffer","data":[20,95,17,34,0,82,1]}}
2024-01-21T23:54:33.371Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"sendUnicast","_id_":52,"_isRequest_":true,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":86,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":87,"message":{"type":"Buffer","data":[20,95,17,34,0,82,1]}}
2024-01-21T23:54:33.371Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,2,0): e0000134000084c50401c0fc010100010000565707145f1122005201
2024-01-21T23:54:33.371Z zigbee-herdsman:adapter:ezsp:uart --> [02a221a9602a15369c904be5565493499d4e27fdbac973d4ece463dbfd3b177e]
2024-01-21T23:54:33.371Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:uart <-- [21a2a1a9602a15e906ad7e]
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:uart --> parsed 21a2a1a9602a15e906ad7e
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (2,1,0): 21a2a1a9602a15e906ad7e
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (3)
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:uart --> [83401b7e]
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 21a2a1a9602a15e906ad7e
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: e080013400005b
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x34: {"_cls_":"sendUnicast","_id_":52,"_isRequest_":false,"status":0,"sequence":91}
2024-01-21T23:54:33.379Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success
2024-01-21T23:54:33.389Z zigbee-herdsman:adapter:ezsp:uart <-- [31a2b1a96b2a15369c904be5565493499d4e27f0bace67f4d67e]
2024-01-21T23:54:33.389Z zigbee-herdsman:adapter:ezsp:uart --> parsed 31a2b1a96b2a15369c904be5565493499d4e27f0bace67f4d67e
2024-01-21T23:54:33.389Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (3,1,0): 31a2b1a96b2a15369c904be5565493499d4e27f0bace67f4d67e
2024-01-21T23:54:33.389Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (4)
2024-01-21T23:54:33.389Z zigbee-herdsman:adapter:ezsp:uart --> [8430fc7e]
2024-01-21T23:54:33.389Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 31a2b1a96b2a15369c904be5565493499d4e27f0bace67f4d67e
2024-01-21T23:54:33.389Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: e090013f000084c50401c0fc0101000100005b570000
2024-01-21T23:54:33.389Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x3f: {"_cls_":"messageSentHandler","_id_":63,"_isRequest_":false,"type":0,"indexOrDestination":50564,"apsFrame":{"profileId":260,"sequence":91,"clusterId":64704,"sourceEndpoint":1,"destinationEndpoint":1,"groupId":0,"options":256},"messageTag":87,"status":0,"message":{"type":"Buffer","data":[]}}
2024-01-21T23:54:38.309Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-21T23:54:38.309Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-21T23:54:38.309Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-21T23:54:38.310Z zigbee-herdsman:adapter:ezsp:uart --> DATA (1,4,0): e100010500
2024-01-21T23:54:38.310Z zigbee-herdsman:adapter:ezsp:uart --> [14a321a9512a0cd27e]
2024-01-21T23:54:38.310Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (2)
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:uart <-- [42a3a1a9512a2c9f7e]
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:uart --> parsed 42a3a1a9512a2c9f7e
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (4,2,0): 42a3a1a9512a2c9f7e
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (5)
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:uart --> [8520dd7e]
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (2): 42a3a1a9512a2c9f7e
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: e180010500
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x5: {"_cls_":"nop","_id_":5,"_isRequest_":false}
2024-01-21T23:54:38.314Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (2) success
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:uart <-- [52a3b5a9902a7d33369c30ed7e]
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:uart --> parsed 52a3b5a9902a13369c30ed7e
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (5,2,0): 52a3b5a9902a13369c30ed7e
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (6)
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:uart --> [8610be7e]
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (2): 52a3b5a9902a13369c30ed7e
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: e19401c4000684c5
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:ezsp <== 0xc4: {"_cls_":"incomingNetworkStatusHandler","_id_":196,"_isRequest_":false,"errorCode":6,"target":50564}
2024-01-21T23:54:41.107Z zigbee-herdsman:adapter:ezsp:driv Unhandled frame incomingNetworkStatusHandler
2024-01-21T23:54:41.108Z zigbee-herdsman:adapter:ezsp:uart <-- [62a3b1a9d42a57369c5c2a7e]
2024-01-21T23:54:41.108Z zigbee-herdsman:adapter:ezsp:uart --> parsed 62a3b1a9d42a57369c5c2a7e
2024-01-21T23:54:41.108Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (6,2,0): 62a3b1a9d42a57369c5c2a7e
2024-01-21T23:54:41.108Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (7)
2024-01-21T23:54:41.108Z zigbee-herdsman:adapter:ezsp:uart --> [87009f7e]
2024-01-21T23:54:41.108Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (2): 62a3b1a9d42a57369c5c2a7e
2024-01-21T23:54:41.108Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: e1900180004284c5
2024-01-21T23:54:41.109Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x80: {"_cls_":"incomingRouteErrorHandler","_id_":128,"_isRequest_":false,"status":66,"target":50564}
2024-01-21T23:54:41.109Z zigbee-herdsman:adapter:ezsp:driv handleRouteError: nwk=50564, status=66
2024-01-21T23:54:43.381Z zigbee-herdsman:adapter:ezsp:debg Response timeout (0x54ef44100053d18c:50564,1)
2024-01-21T23:54:43.382Z zigbee-herdsman:controller:endpoint Read 0x54ef44100053d18c/1 aqaraOpple([338], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 50564 - 1 - 34 - 64704 - 1 after 10000ms)
Zigbee2MQTT:error 2024-01-22 00:54:43: Failed to configure 'Hobbyzimmer - Bewegungsmelder', attempt 1 (Error: Read 0x54ef44100053d18c/1 aqaraOpple([338], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":4447,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 50564 - 1 - 34 - 64704 - 1 after 10000ms)
    at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23)
    at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:478:47)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20)
    at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20)
    at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:478:28)
    at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/xiaomi.ts:1767:13)
    at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:140:25)
    at Configure.configure (/app/lib/extension/configure.ts:120:13)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17))

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 22, 2024

@kirovilya Could this be a side-effect of the removal of setExtendedTimeout? Koenkk/zigbee-herdsman#871

<== 0x80: {"_cls_":"incomingRouteErrorHandler","_id_":128,"_isRequest_":false,"status":66,"target":50564}
handleRouteError: nwk=50564, status=66

https://docs.silabs.com/d/zigbee-stack-api/7.4.0/message#ember-incoming-route-error-handler

A status of EMBER_MAC_INDIRECT_TIMEOUT indicates that a message sent to the target end device could not be delivered by the parent because the indirect transaction timer expired. Upon receipt of the route error, the stack sets the extended timeout for the target node in the address table, if present. It then calls this handler to indicate receipt of the error.

If I understand this correctly, the default timeout starts at 3sec, and can increase up to 30s, so after having failed a few times, the timeout has increased internally on its own, and it stops failing, which would explain the reported behavior (on start)...

@kirovilya
Copy link
Contributor

@Nerivec I'm not sure if this is the reason, but anything is possible.
I removed the extended timeout because I saw how in bellows send it only to end devices; for ordinary routers such a command is not executed.

if these commands are sent to a sleeping sensor, then of course they will not reach - you need to wake up the sensor

@wastez
Copy link
Author

wastez commented Jan 22, 2024

@kirovilya
This make sense it happens on end devices.....

@wastez
Copy link
Author

wastez commented Jan 22, 2024

@kirovilya
If you tell me this is no problem then it's ok to me.
Just wanted to report problems which I don't saw before.

@kirovilya
Copy link
Contributor

@wastez "Failed to configure" - means that the device has not yet been configured (perhaps it was not configured when the device was added) - which means it needs to be woken up for configuration.
Configuration is done at the start of z2m for all unconfigured devices.

@wastez
Copy link
Author

wastez commented Jan 22, 2024

@kirovilya
This is strange, I'm using the devices for a long time and they are configured and they are working.

@kirovilya
Copy link
Contributor

@wastez One of the possible reasons is that previously this device did not have a “configure” code, but now it does, and therefore it needs to be executed.

@wastez
Copy link
Author

wastez commented Jan 22, 2024

@kirovilya
It's ok for me.
And this make sense that this happen to all my aqara motion sensors? (At least)

@kirovilya
Copy link
Contributor

@wastez I don’t know why this happened... try waking up one of the sensors and performing configuration (you can force the button at the bottom of the sensor page) - the error for this sensor should disappear.

@wastez
Copy link
Author

wastez commented Jan 22, 2024

@kirovilya
Ok will test it and will report.

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 22, 2024

@wastez Just a side note from what I read over time since you mentioned them:
Aqara has always been plagued with issues regarding their Zigbee protocol, it was supposed to get better with the T1 versions, but considering the number of reports I have seen, even recently, I still suspect they didn't follow the Zigbee standard properly.
This manifests with devices being extremely annoying in how they pick routers. Some will drop from the network rather than connect to a router "they don't like". I guess if you are lucky enough to have routers they like, then you wouldn't see any issue... There were quite a few threads about these (several on the Hubitat forums if memory serves) if you want more details.

@wastez
Copy link
Author

wastez commented Jan 22, 2024

Hmmmmmm....
Ok for now I can see that some things where not refreshed since some time. (battery)
Looks like reconfiguration makes a difference.
Will keep you up to date.

@RichardPar
Copy link

RichardPar commented Jan 23, 2024

I have the same issue... does not start on boot... using a RESTART and it then works.. I am using EDGE (23/11/2024) on HA and the latest ezsp multiprotocol. This is a new install with No sensors attached yet.

Assertion failed: Command (setConfigurationValue(1, 255)) returned unexpected state: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":55}

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 23, 2024

@RichardPar do you have any more logs (try starting with herdsman debug ON)? This config ID assertion is not an issue per say, it's just not supported anymore, the code needs cleanup; anyway, it does not prevent startup.

@RichardPar
Copy link

RichardPar commented Jan 23, 2024

@RichardPar do you have any more logs (try starting with herdsman debug ON)? This config ID assertion is not an issue per say, it's just not supported anymore, the code needs cleanup; anyway, it does not prevent startup.

It hangs after a boot at this point.. it however starts when I do a RESTART. I will add Herdsmen debug this evening (when I get home in an hour)

''[16:26:15] INFO: Preparing to start...
[16:26:16] INFO: Socat not enabled
[16:26:20] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:info 2024-01-23 16:26:26: Logging to console and directory: '/config/zigbee2mqtt/log/2024-01-23.16-26-26' filename: log.txt
Zigbee2MQTT:info 2024-01-23 16:26:26: Starting Zigbee2MQTT version 1.35.1-dev (commit #de7bc7c)
Zigbee2MQTT:info 2024-01-23 16:26:26: Starting zigbee-herdsman (0.32.7)
Assertion failed: Command (setConfigurationValue(1, 255)) returned unexpected state: {"cls":"setConfigurationValue","id":83,"isRequest":false,"status":55}
Assertion failed: Command (setValue) returned unexpected state: {"cls":"setValue","id":171,"isRequest":false,"status":55}
Assertion failed: exportKey returned unexpected status: 45
``

@kirovilya
Copy link
Contributor

"Assertion failed" - not a critical situation for ezsp adapter. I can hide them or put them in debug logs.

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 23, 2024

It's good to have them as console.assert I think. It will help figure out values supported for each adapter, in case it becomes needed to init based on detected adapter in the future (it's less "hidden" than debug).

@RichardPar
Copy link

It hangs on Boot :D There has to be a race condition with something else.. but to clarify - it does not start at all on first boot..

image


As to how to enable debug, where would herdsman be set? I added under the Socat stanza - didnt seem to do anything

image

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 23, 2024

Check the Show unused optional configuration options, and it will pop up as a toggle.

@wastez
Copy link
Author

wastez commented Jan 23, 2024

You have to change to yaml edit in the right upper corner. (And not enter it in the socat section)

@RichardPar
Copy link

Its looping

2024-01-23T21:20:33.598Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-23T21:20:33.599Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-23T21:20:33.599Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-23T21:20:33.599Z zigbee-herdsman:adapter:ezsp:uart --> DATA (6,6,0): 160005
2024-01-23T21:20:33.599Z zigbee-herdsman:adapter:ezsp:uart --> [665421ad29157e]
2024-01-23T21:20:33.600Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (7)
2024-01-23T21:20:33.601Z zigbee-herdsman:adapter:ezsp:uart <-- [6754a1ad]
2024-01-23T21:20:33.602Z zigbee-herdsman:adapter:ezsp:uart <-- [0c2a5c79557e]
2024-01-23T21:20:33.602Z zigbee-herdsman:adapter:ezsp:uart --> parsed 6754a1ad0c2a5c79557e
2024-01-23T21:20:33.602Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (6,7,0): 6754a1ad0c2a5c79557e
2024-01-23T21:20:33.602Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (7)
2024-01-23T21:20:33.603Z zigbee-herdsman:adapter:ezsp:uart --> [87009f7e]
2024-01-23T21:20:33.603Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (7): 6754a1ad0c2a5c79557e
2024-01-23T21:20:33.603Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 168005580049
2024-01-23T21:20:33.604Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x5: {"_cls_":"nop","_id_":5,"_isRequest_":false}
2024-01-23T21:20:33.604Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (7) success
2024-01-23T21:20:37.486Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 3
2024-01-23T21:20:37.486Z zigbee-herdsman:adapter:ezsp:uart Opening TCP socket with core-silabs-multiprotocol:9999
2024-01-23T21:20:37.490Z zigbee-herdsman:adapter:ezsp:uart Socket error
2024-01-23T21:20:37.491Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 3 error: Error: Error while opening socket
    at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:150: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-23T21:20:37.492Z zigbee-herdsman:adapter:ezsp:uart Port closed
2024-01-23T21:20:37.492Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-23T21:20:37.492Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-23T21:20:42.495Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 4
2024-01-23T21:20:42.496Z zigbee-herdsman:adapter:ezsp:uart Opening TCP socket with core-silabs-multiprotocol:9999
2024-01-23T21:20:42.501Z zigbee-herdsman:adapter:ezsp:uart Socket error
2024-01-23T21:20:42.507Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 4 error: Error: Error while opening socket
    at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:150: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-23T21:20:42.507Z zigbee-herdsman:adapter:ezsp:erro EZSP could not connect: Error: Error while opening socket
2024-01-23T21:20:42.509Z zigbee-herdsman:adapter:ezsp:erro Reset error Error: Failure to connect
2024-01-23T21:20:42.501Z zigbee-herdsman:adapter:ezsp:uart Socket error
2024-01-23T21:20:42.507Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 4 error: Error: Error while opening socket
    at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:150: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-23T21:20:42.507Z zigbee-herdsman:adapter:ezsp:erro EZSP could not connect: Error: Error while opening socket
2024-01-23T21:20:42.509Z zigbee-herdsman:adapter:ezsp:erro Reset error Error: Failure to connect
    at Ezsp.connect (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:293:19)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:143:13)
    at Driver.reset (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:116:24)
    at Driver.onReset (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:132:9)
2024-01-23T21:20:42.509Z zigbee-herdsman:adapter:ezsp:driv Pause 60sec before try 5
2024-01-23T21:20:42.509Z zigbee-herdsman:adapter:ezsp:uart Port closed
2024-01-23T21:20:42.509Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-23T21:20:42.510Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-23T21:20:43.599Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-23T21:20:43.599Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-23T21:20:43.600Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-23T21:20:43.600Z zigbee-herdsman:adapter:ezsp:uart --> DATA (7,7,0): 170005
2024-01-23T21:20:43.600Z zigbee-herdsman:adapter:ezsp:uart --> [775521ad73367e]
2024-01-23T21:20:43.601Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (0)
2024-01-23T21:20:43.602Z zigbee-herdsman:adapter:ezsp:uart <-- [7055]
2024-01-23T21:20:43.602Z zigbee-herdsman:adapter:ezsp:uart <-- [a1ad0c2a5c12ca7e]
2024-01-23T21:20:43.603Z zigbee-herdsman:adapter:ezsp:uart --> parsed 7055a1ad0c2a5c12ca7e
2024-01-23T21:20:43.603Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (7,0,0): 7055a1ad0c2a5c12ca7e
2024-01-23T21:20:43.603Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (0)
2024-01-23T21:20:43.603Z zigbee-herdsman:adapter:ezsp:uart --> [8070787e]
2024-01-23T21:20:43.604Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (0): 7055a1ad0c2a5c12ca7e
2024-01-23T21:20:43.604Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 178005580049
2024-01-23T21:20:43.604Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x5: {"_cls_":"nop","_id_":5,"_isRequest_":false}
2024-01-23T21:20:43.605Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (0) success
2024-01-23T21:20:53.607Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-23T21:20:53.607Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-23T21:20:53.608Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-23T21:20:53.608Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 180005
2024-01-23T21:20:53.608Z zigbee-herdsman:adapter:ezsp:uart --> [005a21ad4c5f7e]
2024-01-23T21:20:53.608Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)

@wastez
Copy link
Author

wastez commented Jan 23, 2024

Looks like it can't connect to the port of the multiprotocol addon.

Can you access it via telnet? To see if the port is reachable.

@RichardPar
Copy link

Looks like it can't connect to the port of the multiprotocol addon.

Can you access it via telnet? To see if the port is reachable.

If I click restart on the Z2MQTT plugin, it immidiately connects. Its there and running (as my THREAD devices are online)

@wastez
Copy link
Author

wastez commented Jan 23, 2024

Maybee z2m try's connect to early while the multiprotocol addon isn't already up and ready for connections.

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 23, 2024

Can you check the logs of the silabs addon? You might find some more information there...
Something seems to make the socket drop in some weird fashion.

@RichardPar
Copy link

RichardPar commented Jan 23, 2024

Can you check the logs of the silabs addon? You might find some more information there... Something seems to make the socket drop in some weird fashion.

I'll dig for some more debug.. Silabs is listening

Z2MQTT looks like its connecting to something.. (below is the same small logs from Silabs Multiprotocol)

[21:16:06] INFO: Socat enabled
[21:16:07] INFO: Starting socat
Socat startup parameters:
Options:     -d -d
Master:      pty,raw,echo=0,link=/tmp/ttyZ2M,mode=777
Slave:       tcp-listen:8485,keepalive,nodelay,reuseaddr,keepidle=1,keepintvl=1,keepcnt=5
[21:16:07] INFO: Starting socat process ...
2024/01/23 21:16:07 socat[47] N PTY is /dev/pts/0
2024/01/23 21:16:07 socat[47] N listening on AF=2 0.0.0.0:8485
[21:16:08] INFO: Zigbee Herdsman debug logging enabled
[21:16:11] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:debug 2024-01-23 21:16:23: Loaded state from file /config/zigbee2mqtt/state.json
Zigbee2MQTT:info  2024-01-23 21:16:23: Logging to console and directory: '/config/zigbee2mqtt/log/2024-01-23.21-16-22' filename: log.txt
Zigbee2MQTT:debug 2024-01-23 21:16:23: Removing old log directory '/config/zigbee2mqtt/log/2024-01-23.17-45-09'
Zigbee2MQTT:info  2024-01-23 21:16:23: Starting Zigbee2MQTT version 1.35.1-dev (commit #de7bc7c)
Zigbee2MQTT:info  2024-01-23 21:16:23: Starting zigbee-herdsman (0.32.7)
Zigbee2MQTT:debug 2024-01-23 21:16:23: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/config/zigbee2mqtt/coordinator_backup.json","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","databasePath":"/config/zigbee2mqtt/database.db","network":{"channelList":[11],"extendedPanID":[79,21,20,244,142,185,35,167],"networkKey":"HIDDEN","panID":57138},"serialPort":{"adapter":"ezsp","path":"tcp://core-silabs-multiprotocol:9999","rtscts":false}}'
2024-01-23T21:16:23.529Z zigbee-herdsman:adapter:ezsp:debg Adapter concurrent: 8
2024-01-23T21:16:23.531Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[189,75,78,133,143,84,44,153,64,153,244,26,19,43,146,35],"panID":57138,"extendedPanID":[79,21,20,244,142,185,35,167],"channelList":[11]},"serialPort":{"rtscts":false,"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-23T21:16:23.534Z zigbee-herdsman:adapter:ezsp:uart Opening TCP socket with core-silabs-multiprotocol:9999
2024-01-23T21:16:23.554Z zigbee-herdsman:adapter:ezsp:uart Socket connected
2024-01-23T21:16:23.555Z zigbee-herdsman:adapter:ezsp:uart Socket ready
2024-01-23T21:16:23.556Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2024-01-23T21:16:23.558Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2024-01-23T21:16:23.560Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2024-01-23T21:16:23.561Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset
2024-01-23T21:16:23.566Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2024-01-23T21:16:23.568Z zigbee-herdsman:adapter:ezsp:uart --> parsed c1020b0a527e
2024-01-23T21:16:23.569Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK c1020b0a527e
2024-01-23T21:16:23.570Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2024-01-23T21:16:23.572Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success
2024-01-23T21:16:23.573Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":4}
2024-01-23T21:16:23.574Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":4}
2024-01-23T21:16:23.577Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 00000004
2024-01-23T21:16:23.578Z zigbee-herdsman:adapter:ezsp:uart --> [004221a850ed2c7e]
2024-01-23T21:16:23.579Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2024-01-23T21:16:25.582Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":1} after 2000ms
2024-01-23T21:16:25.582Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (1)
2024-01-23T21:16:25.582Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (0,0,0): 00000004
2024-01-23T21:16:26.084Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (0,0,1): 00000004
2024-01-23T21:16:26.084Z zigbee-herdsman:adapter:ezsp:uart --> [084221a850ef017e]
2024-01-23T21:16:26.085Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (1)
2024-01-23T21:16:27.649Z zigbee-herdsman:adapter:ezsp:uart <-- [c102]
2024-01-23T21:16:27.650Z zigbee-herdsman:adapter:ezsp:uart <-- [0b0a527e0142a1a8592815c6ab047e]
2024-01-23T21:16:27.650Z zigbee-herdsman:adapter:ezsp:uart --> parsed c1020b0a527e
2024-01-23T21:16:27.652Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK c1020b0a527e
2024-01-23T21:16:27.652Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2024-01-23T21:16:27.652Z zigbee-herdsman:adapter:ezsp:uart --> parsed 0142a1a8592815c6ab047e
2024-01-23T21:16:27.653Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,1,0): 0142a1a8592815c6ab047e
2024-01-23T21:16:27.653Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2024-01-23T21:16:27.654Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2024-01-23T21:16:27.655Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 0142a1a8592815c6ab047e
2024-01-23T21:16:27.656Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 0080000d020074
2024-01-23T21:16:27.657Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x0: {"_cls_":"version","_id_":0,"_isRequest_":false,"protocolVersion":13,"stackType":2,"stackVersion":29696}
2024-01-23T21:16:27.659Z zigbee-herdsman:adapter:ezsp:uart -+- rewaiting (1) success
2024-01-23T21:16:27.659Z zigbee-herdsman:adapter:ezsp:ezsp Switching to eszp version 13
2024-01-23T21:16:27.660Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":13}
2024-01-23T21:16:27.660Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":13}
2024-01-23T21:16:27.661Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,1,0): 01000100000d
2024-01-23T21:16:27.662Z zigbee-herdsman:adapter:ezsp:uart --> [014321a9542a7d38aea17e]
2024-01-23T21:16:27.662Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2024-01-23T21:16:27.664Z zigbee-herdsman:adapter:ezsp:uart <-- [8160597e]
2024-01-23T21:16:27.664Z zigbee-herdsman:adapter:ezsp:uart --> parsed 8160597e
2024-01-23T21:16:27.664Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 8160597e
2024-01-23T21:16:27.665Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success
2024-01-23T21:16:28.650Z zigbee-herdsman:adapter:ezsp:uart <-- [a144]
2024-01-23T21:16:28.651Z zigbee-herdsman:adapter:ezsp:uart <-- [3b7e]
2024-01-23T21:16:28.651Z zigbee-herdsman:adapter:ezsp:uart --> parsed a1443b7e
2024-01-23T21:16:28.652Z zigbee-herdsman:adapter:ezsp:uart <-- NAK (1): a1443b7e
2024-01-23T21:16:28.652Z zigbee-herdsman:adapter:ezsp:uart NAK Unexpected packet sequence 1
2024-01-23T21:16:33.573Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-23T21:16:33.573Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null

SiLabs Multiprotocol

[2024-01-23T21:15:44.334445Z] Info : Secondary APP vUNDEFINED
[2024-01-23T21:15:44.334677Z] Info : Daemon startup was successful. Waiting for client connections
[2024-01-23T21:15:45.825920Z] Info : New client connection using library v4.4.0.0
[2024-01-23T21:15:45.828668Z] Info : Opened connection socket for ep#12
[2024-01-23T21:15:45.831555Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Listening on port 9999 for connection...

Accepting connection.

Accepted connection 8.

Restarting
[2024-01-23T21:16:23.562458Z] Info : Endpoint socket #12: Client disconnected. 0 connections
[2024-01-23T21:16:23.562661Z] Info : Client disconnected
[2024-01-23T21:16:24.565571Z] Info : New client connection using library v4.4.0.0
[2024-01-23T21:16:24.568432Z] Info : Opened connection socket for ep#12
[2024-01-23T21:16:24.571146Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Reusing socket from previous instance.

Socket connection has been closed, restarting...

Listening on port 9999 for connection...

Accepting connection.

Accepted connection 9.

Restarting
[2024-01-23T21:16:38.687566Z] Info : Endpoint socket #12: Client disconnected. 0 connections
[2024-01-23T21:16:38.687730Z] Info : Client disconnected
[2024-01-23T21:16:39.690400Z] Info : New client connection using library v4.4.0.0
[2024-01-23T21:16:39.693238Z] Info : Opened connection socket for ep#12
[2024-01-23T21:16:39.696036Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Reusing socket from previous instance.

Socket connection has been closed, restarting...

Listening on port 9999 for connection...

Accepting connection.

Accepted connection 10.

Restarting
[2024-01-23T21:25:40.057648Z] Info : Endpoint socket #12: Client disconnected. 0 connections
[2024-01-23T21:25:40.057851Z] Info : Client disconnected
[2024-01-23T21:25:41.061237Z] Info : New client connection using library v4.4.0.0
[2024-01-23T21:25:41.064223Z] Info : Opened connection socket for ep#12
[2024-01-23T21:25:41.067195Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Reusing socket from previo

@wastez
Copy link
Author

wastez commented Jan 23, 2024

Something bring the multiprotocol to crash and restart the port.
I don't use it so I don't know all about it it.
It has to have a debug mode too, this logs are to less to get the reasons why this happens.

@RichardPar
Copy link

RichardPar commented Jan 23, 2024

Something bring the multiprotocol to crash and restart the port. I don't use it so I don't know all about it it. It has to have a debug mode too, this logs are to less to get the reasons why this happens.

Why when I restart Z2MQTT it all works fine? (Multiprotocol is not restarted) I have reproduced on 3 differenent installs too.
I can restatart Multiprotocol Addon and z2mqtt wont connect back first load... I dont know which side it is, but whichever it has made Z2MQTT sadly very unstable.

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 24, 2024

@RichardPar Can you try again once 0.33.2 is available to update and let me know if the behavior is better? If it's an underlaying issue with socket or silabs, of course, that won't fix the problem, but at least Z2M should handle the fail properly now. Well, hopefully anyway...

@RichardPar
Copy link

@RichardPar Can you try again once 0.33.2 is available to update and let me know if the behavior is better? If it's an underlaying issue with socket or silabs, of course, that won't fix the problem, but at least Z2M should handle the fail properly now. Well, hopefully anyway...

Installed and ran+connectesd first time ... I will put it through more paces and see how it purrs.

Copy link
Contributor

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

@github-actions github-actions bot added the stale Stale issues label Jul 24, 2024
@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Aug 24, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
problem Something isn't working stale Stale issues
Projects
None yet
Development

No branches or pull requests

6 participants