search

Koenkk / zigbee2mqtt

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

UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms #4398

Closed Dustinhoefer closed 3 years ago

Dustinhoefer commented 4 years ago

Hello!

Since a few hours, my console is filled with these messages:

(node:2212) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms at Timeout.waiter.timer.setTimeout [as _onTimeout] (C:\Users\Dustin\Desktop\zigbee2mqtt-master\node_modules\zigbee-herdsman\dist\utils\waitress.js:46:35) at ontimeout (timers.js:436:11) at tryOnTimeout (timers.js:300:5) at listOnTimeout (timers.js:263:5) at Timer.processTimers (timers.js:223:10) (node:2212) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1) (node:2212) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Any Idea? I read in this issue (https://github.com/Koenkk/zigbee2mqtt/issues/2318), that it should be fixed and that restarting the PC without the Zigbee Stick should solve this problem. It solved it a bit, but not completely.

Any Ideas? I have 11 devices set up.

Koenkk commented 4 years ago

There are some known stability issues in 1.14.4, should be fixed in latest dev. (https://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html)

Dustinhoefer commented 4 years ago

@Koenkk Updated to the dev branch, copied the database and configuration over.

Getting this error now:

(node:9200) UnhandledPromiseRejectionWarning: Error: SREQ '--> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":2,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,3,2,11,254,0]}}' failed with status '(0x02: INVALID_PARAM)' (expected '(0x00: SUCCESS)') at Znp. (C:\Users\Dustin\Desktop\zigbee2mqtt-dev\node_modules\zigbee-herdsman\dist\adapter\z-stack\znp\znp.js:291:27) at Generator.next () at fulfilled (C:\Users\Dustin\Desktop\zigbee2mqtt-dev\node_modules\zigbee-herdsman\dist\adapter\z-stack\znp\znp.js:24:58) (node:9200) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1) (node:9200) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Koenkk commented 4 years ago

Can you try reflashing your CC2531?

Dustinhoefer commented 4 years ago

I bought it with firmware Juli 2019 and have never flashed it before. Which version should I flash it with? Do you have a good guide for that? :)

Koenkk commented 4 years ago

Firmware: https://github.com/Koenkk/Z-Stack-firmware/tree/master/coordinator/Z-Stack_Home_1.2/bin/source_routing Guide: https://www.zigbee2mqtt.io/getting_started/flashing_the_cc2531.html

Dustinhoefer commented 4 years ago

Thanks a bunch! Will try that soonish

Right now it is actually working again. I restarted the pc without the stick, then inserted it in a different usb port.

Hope this fixes it, if not, I will flash the new firmware! Will close the issue for now and report back, if it persists with the new version :)

Dustinhoefer commented 4 years ago

And it stopped working again .... Will update the firmware soon and report back ...

Dustinhoefer commented 4 years ago

@Koenkk But can you tell me something please. How can it be that, after 2 month of everything working, it suddenly stops working? Without me updating anything?

I just unzipped my old version from 2 month ago, set it up again and even that is not working anymore. I have neither updated the stick, nor is zigbee2mqtt any different to the version that was wokring 2of 2 month...

Dustinhoefer commented 4 years ago

Now I can not even get a single device to connect to the network. Is network data (e.g. connected devices) stored somewhere outside the zigbee2mqtt folder? I am getting the same error mentioned above with a new zigbee2mqtt installation

Koenkk commented 4 years ago

The CC2531 is not very powerful and can crash if it receives a lot of commands at the same time. The firmware linked improves stability on the CC2531 (but it will still crash with larger networks, +- 30 devices).

Dustinhoefer commented 4 years ago

I only have like 10 devices :/ Also, setting up a new network, I can not even get 1 device to connect, before I get the same error. Is there any data written outside of the downloaded folder that I need to delete, so I can start fresh?

Koenkk commented 4 years ago

Thats strange indeed. To start fresh clean the data directory to only contain https://github.com/Koenkk/zigbee2mqtt/tree/master/data and reflash the stick.

If the problem persist provide the herdsman debug logging.

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

mrucki commented 4 years ago

@Koenkk please find debug logs below:

OS: raspbian buster Zigbee device: CC2531 flashed with CC2531_SOURCE_ROUTING_20190619.zip Zigbee2Mqtt checked with:

and always get Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms

The error occurs after about 2h 40 minutes from starting Zigbee2Mqtt. I have been testing it for last few days: each time after 2h XX minutes !

Tried with dev branch as well - last git pull did yesterday.

The only workaround I figured out is cron job:

0 */2 * * * sudo systemctl restart zigbee2mqtt

I tested it over a night and in the morning worked fine (start stop commands visible in logs of course) but I don't want to have such dirty hack in my Raspberry PI :(

The debug log from today, error after 2h 40 mins:

Sep 29 12:29:01 raspberrypi npm[788]: Zigbee2MQTT:info  2020-09-29 12:29:01: MQTT publish: topic 'zigbee2mqtt/ArtursRoomTempHum', payload '{"battery":37,"humidity":53.85,"linkquality":23,"pressure":1013
Sep 29 12:30:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 12:30:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 12:35:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 12:35:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 12:40:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 12:40:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 12:45:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 12:45:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 12:50:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 12:50:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 12:52:13 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 12:52:13: Received Zigbee message from 'ArtursRoomTempHum', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":2865,"10":0
Sep 29 12:52:13 raspberrypi npm[788]: Zigbee2MQTT:info  2020-09-29 12:52:13: MQTT publish: topic 'zigbee2mqtt/ArtursRoomTempHum', payload '{"battery":37,"humidity":55.62,"linkquality":34,"pressure":1012
Sep 29 12:55:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 12:55:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 13:00:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:00:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 13:04:23 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:04:23: Received Zigbee message from 'KitchenWirelessSwitch', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":3005,"1
Sep 29 13:04:23 raspberrypi npm[788]: Zigbee2MQTT:info  2020-09-29 13:04:23: MQTT publish: topic 'zigbee2mqtt/KitchenWirelessSwitch', payload '{"battery":100,"linkquality":55,"voltage":3005}'
Sep 29 13:05:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:05:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 13:10:11 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:10:11: Received Zigbee message from 'KitchenTempHum', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":2935,"10":0,"1
Sep 29 13:10:11 raspberrypi npm[788]: Zigbee2MQTT:info  2020-09-29 13:10:11: MQTT publish: topic 'zigbee2mqtt/KitchenTempHum', payload '{"battery":62,"humidity":53.03,"linkquality":78,"pressure":1013,"t
Sep 29 13:10:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:10:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 13:10:43 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:10:42: Received Zigbee message from 'ArtursRoomTempHum', type 'attributeReport', cluster 'msTemperatureMeasurement', data '{"measure
Sep 29 13:10:43 raspberrypi npm[788]: Zigbee2MQTT:info  2020-09-29 13:10:43: MQTT publish: topic 'zigbee2mqtt/ArtursRoomTempHum', payload '{"battery":37,"humidity":55.62,"linkquality":42,"pressure":1012
Sep 29 13:10:43 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:10:43: Received Zigbee message from 'ArtursRoomTempHum', type 'attributeReport', cluster 'msRelativeHumidity', data '{"measuredValue
Sep 29 13:10:43 raspberrypi npm[788]: Zigbee2MQTT:info  2020-09-29 13:10:43: MQTT publish: topic 'zigbee2mqtt/ArtursRoomTempHum', payload '{"battery":37,"humidity":56.47,"linkquality":39,"pressure":1012
Sep 29 13:10:43 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:10:43: Received Zigbee message from 'ArtursRoomTempHum', type 'attributeReport', cluster 'msPressureMeasurement', data '{"16":10129,
Sep 29 13:10:43 raspberrypi npm[788]: Zigbee2MQTT:info  2020-09-29 13:10:43: MQTT publish: topic 'zigbee2mqtt/ArtursRoomTempHum', payload '{"battery":37,"humidity":56.47,"linkquality":39,"pressure":1012
Sep 29 13:12:14 raspberrypi npm[788]: (node:801) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms
Sep 29 13:12:14 raspberrypi npm[788]:     at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
Sep 29 13:12:14 raspberrypi npm[788]:     at listOnTimeout (internal/timers.js:549:17)
Sep 29 13:12:14 raspberrypi npm[788]:     at processTimers (internal/timers.js:492:7)
Sep 29 13:12:14 raspberrypi npm[788]: (node:801) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block
Sep 29 13:12:14 raspberrypi npm[788]: (node:801) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node
Sep 29 13:15:25 raspberrypi npm[788]: Zigbee2MQTT:debug 2020-09-29 13:15:25: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 13:15:34 raspberrypi npm[788]: (node:801) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms
Sep 29 13:15:34 raspberrypi npm[788]:     at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
Sep 29 13:15:34 raspberrypi npm[788]:     at listOnTimeout (internal/timers.js:549:17)
Sep 29 13:15:34 raspberrypi npm[788]:     at processTimers (internal/timers.js:492:7)
Sep 29 13:15:34 raspberrypi npm[788]: (node:801) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block
lines 269-318/318 (END)
Koenkk commented 4 years ago

Please provide the herdsman debug logging (normal debug logging isn't enough to debug this issue). See https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging how to obtain this logging

mrucki commented 4 years ago

@Koenkk this time with zigbee-herdsman debug log (after about 1h 50 mins):

Sep 29 15:34:29 raspberrypi npm[31735]: Zigbee2MQTT:debug 2020-09-29 15:34:29: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 15:34:47 raspberrypi npm[31735]: 2020-09-29T13:34:47.349Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,55,68,129,0,0,0,0,145,210,1,1,0,49,0,52,42,172,0,0,35,28,95,17,90,10,1,255,66,26,1,33
Sep 29 15:34:47 raspberrypi npm[31735]: 2020-09-29T13:34:47.349Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,55,68,129,0,0,0,0,145,210,1,1,0,49,0,52,42,172,0,0,35,28,95,17,90,10,1,255,
Sep 29 15:34:47 raspberrypi npm[31735]: 2020-09-29T13:34:47.350Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 55 - 2 - 4 - 129 - [0,0,0,0,145,210,1,1,0,49,0,52,42,172,0,0,35,28,95,17,90,10,1,25
Sep 29 15:34:47 raspberrypi npm[31735]: 2020-09-29T13:34:47.351Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":0,"srcaddr":53905,"srcendpoint":1,"dstendpoint":1
Sep 29 15:34:47 raspberrypi npm[31735]: 2020-09-29T13:34:47.354Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":true,"direct
Sep 29 15:34:47 raspberrypi npm[31735]: Zigbee2MQTT:debug 2020-09-29 15:34:47: Received Zigbee message from 'KitchenWirelessSwitch', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":3005,
Sep 29 15:34:47 raspberrypi npm[31735]: Zigbee2MQTT:info  2020-09-29 15:34:47: MQTT publish: topic 'zigbee2mqtt/KitchenWirelessSwitch', payload '{"battery":100,"linkquality":49,"voltage":3005}'
Sep 29 15:34:47 raspberrypi npm[31735]: 2020-09-29T13:34:47.363Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.702Z zigbee-herdsman:controller:log Permit joining
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.703Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.704Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.717Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.718Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.718Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.718Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.719Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.721Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dst
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.722Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,33,0,30,6,0,25,34,2,11,254,0,232
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.727Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.728Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.728Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.728Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.729Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.735Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.735Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.736Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.736Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.736Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.741Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,0,242,33,20]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.742Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,0,242,33,20]
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.742Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [0,242,33] - 20
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.742Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":242,"transid":33}
Sep 29 15:36:12 raspberrypi npm[31735]: 2020-09-29T13:36:12.743Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Sep 29 15:39:29 raspberrypi npm[31735]: Zigbee2MQTT:debug 2020-09-29 15:39:29: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 15:39:32 raspberrypi npm[31735]: 2020-09-29T13:39:32.706Z zigbee-herdsman:controller:log Permit joining
Sep 29 15:39:32 raspberrypi npm[31735]: 2020-09-29T13:39:32.707Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
Sep 29 15:39:32 raspberrypi npm[31735]: 2020-09-29T13:39:32.708Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
Sep 29 15:39:38 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms
Sep 29 15:39:38 raspberrypi npm[31735]:     at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
Sep 29 15:39:38 raspberrypi npm[31735]:     at listOnTimeout (internal/timers.js:549:17)
Sep 29 15:39:38 raspberrypi npm[31735]:     at processTimers (internal/timers.js:492:7)
Sep 29 15:39:38 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch b
Sep 29 15:39:38 raspberrypi npm[31735]: (node:31748) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the 
Sep 29 15:42:52 raspberrypi npm[31735]: 2020-09-29T13:42:52.709Z zigbee-herdsman:controller:log Permit joining
Sep 29 15:42:52 raspberrypi npm[31735]: 2020-09-29T13:42:52.710Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
Sep 29 15:42:52 raspberrypi npm[31735]: 2020-09-29T13:42:52.711Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
Sep 29 15:42:58 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms
Sep 29 15:42:58 raspberrypi npm[31735]:     at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
Sep 29 15:42:58 raspberrypi npm[31735]:     at listOnTimeout (internal/timers.js:549:17)
Sep 29 15:42:58 raspberrypi npm[31735]:     at processTimers (internal/timers.js:492:7)
Sep 29 15:42:58 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch b
Sep 29 15:44:29 raspberrypi npm[31735]: Zigbee2MQTT:debug 2020-09-29 15:44:29: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 15:46:12 raspberrypi npm[31735]: 2020-09-29T13:46:12.715Z zigbee-herdsman:controller:log Permit joining
Sep 29 15:46:12 raspberrypi npm[31735]: 2020-09-29T13:46:12.716Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
Sep 29 15:46:12 raspberrypi npm[31735]: 2020-09-29T13:46:12.716Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
Sep 29 15:46:18 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms
Sep 29 15:46:18 raspberrypi npm[31735]:     at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
Sep 29 15:46:18 raspberrypi npm[31735]:     at listOnTimeout (internal/timers.js:549:17)
Sep 29 15:46:18 raspberrypi npm[31735]:     at processTimers (internal/timers.js:492:7)
Sep 29 15:46:18 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch b
Sep 29 15:49:29 raspberrypi npm[31735]: Zigbee2MQTT:debug 2020-09-29 15:49:29: Saving state to file /opt/zigbee2mqtt/data/state.json
Sep 29 15:49:32 raspberrypi npm[31735]: 2020-09-29T13:49:32.725Z zigbee-herdsman:controller:log Permit joining
Sep 29 15:49:32 raspberrypi npm[31735]: 2020-09-29T13:49:32.726Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
Sep 29 15:49:32 raspberrypi npm[31735]: 2020-09-29T13:49:32.726Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
Sep 29 15:49:38 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms
Sep 29 15:49:38 raspberrypi npm[31735]:     at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
Sep 29 15:49:38 raspberrypi npm[31735]:     at listOnTimeout (internal/timers.js:549:17)
Sep 29 15:49:38 raspberrypi npm[31735]:     at processTimers (internal/timers.js:492:7)
Sep 29 15:49:38 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch b
Sep 29 15:52:52 raspberrypi npm[31735]: 2020-09-29T13:52:52.730Z zigbee-herdsman:controller:log Permit joining
Sep 29 15:52:52 raspberrypi npm[31735]: 2020-09-29T13:52:52.731Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
Sep 29 15:52:52 raspberrypi npm[31735]: 2020-09-29T13:52:52.732Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
Sep 29 15:52:58 raspberrypi npm[31735]: (node:31748) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms
Sep 29 15:52:58 raspberrypi npm[31735]:     at Timeout._onTimeout (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
Sep 29 15:52:58 raspberrypi npm[31735]:     at listOnTimeout (internal/timers.js:549:17)
Sep 29 15:52:58 raspberrypi npm[31735]:     at processTimers (internal/timers.js:492:7)
Koenkk commented 4 years ago

At the moment it crashes, can you provide the output of dmesg command?

mrucki commented 4 years ago

This time I set permit_join: false in configuration file and it just stopped working. No errors in log file but also no messages from devices, only several messages like this: Saving state to file /opt/zigbee2mqtt/data/state.json

Then dmesg 

pi@raspberrypi:~ $ dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.4.68-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1343 SMP Mon Sep 28 12:38:29 BST 2020
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Reserved memory: created CMA memory pool at 0x37400000, size 64 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] On node 0 totalpages: 242688
[    0.000000]   Normal zone: 2133 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 242688 pages, LIFO batch:63
[    0.000000] percpu: Embedded 20 pages/cpu s49920 r8192 d23808 u81920
[    0.000000] pcpu-alloc: s49920 r8192 d23808 u81920 alloc=20*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=cc2b1ff6-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 880476K/970752K available (9216K kernel code, 697K rwdata, 2604K rodata, 1024K init, 830K bss, 24740K reserved, 65536K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 29216 entries in 58 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] random: get_random_bytes called from start_kernel+0x32c/0x508 with crng_init=0
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000022] Switching to timer-based delay loop, resolution 52ns
[    0.000290] Console: colour dummy device 80x30
[    0.000876] printk: console [tty1] enabled
[    0.000944] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.000992] pid_max: default: 32768 minimum: 301
[    0.001205] LSM: Security Framework initializing
[    0.001449] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.001495] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.002895] Disabling memory control group subsystem
[    0.003040] CPU: Testing write buffer coherency: ok
[    0.003631] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.004599] Setting up static identity map for 0x100000 - 0x10003c
[    0.004820] rcu: Hierarchical SRCU implementation.
[    0.005531] smp: Bringing up secondary CPUs ...
[    0.006726] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.008053] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.009271] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.009424] smp: Brought up 1 node, 4 CPUs
[    0.009513] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.009541] CPU: All CPU(s) started in HYP mode.
[    0.009566] CPU: Virtualization extensions available.
[    0.010671] devtmpfs: initialized
[    0.027163] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.027466] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.027523] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.030728] pinctrl core: initialized pinctrl subsystem
[    0.031864] NET: Registered protocol family 16
[    0.036164] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.041062] audit: initializing netlink subsys (disabled)
[    0.041366] audit: type=2000 audit(0.040:1): state=initialized audit_enabled=0 res=1
[    0.042835] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.042875] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.043111] Serial: AMBA PL011 UART driver
[    0.045108] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.070102] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-09-28 12:54, variant start
[    0.080117] raspberrypi-firmware soc:firmware: Firmware hash is 2c4b5cf8e4a920c2976ebdb62b27bd742b69ea8b
[    0.131622] bcm2835-dma 3f007000.dma: DMA legacy API manager, dmachans=0x1
[    0.133801] SCSI subsystem initialized
[    0.134078] usbcore: registered new interface driver usbfs
[    0.134160] usbcore: registered new interface driver hub
[    0.134306] usbcore: registered new device driver usb
[    0.136309] clocksource: Switched to clocksource arch_sys_counter
[    1.296789] VFS: Disk quotas dquot_6.6.0
[    1.296930] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.297148] FS-Cache: Loaded
[    1.297438] CacheFiles: Loaded
[    1.308850] thermal_sys: Registered thermal governor 'step_wise'
[    1.309233] NET: Registered protocol family 2
[    1.310305] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[    1.310381] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    1.310522] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    1.310733] TCP: Hash tables configured (established 8192 bind 8192)
[    1.310919] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.310992] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.311310] NET: Registered protocol family 1
[    1.312121] RPC: Registered named UNIX socket transport module.
[    1.312153] RPC: Registered udp transport module.
[    1.312180] RPC: Registered tcp transport module.
[    1.312206] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.313990] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    1.317481] Initialise system trusted keyrings
[    1.317786] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    1.329683] FS-Cache: Netfs 'nfs' registered for caching
[    1.330381] NFS: Registering the id_resolver key type
[    1.330439] Key type id_resolver registered
[    1.330466] Key type id_legacy registered
[    1.330502] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.331823] Key type asymmetric registered
[    1.331852] Asymmetric key parser 'x509' registered
[    1.331931] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    1.331969] io scheduler mq-deadline registered
[    1.331996] io scheduler kyber registered
[    1.335451] bcm2708_fb soc:fb: FB found 1 display(s)
[    1.348062] Console: switching to colour frame buffer device 82x26
[    1.354935] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
[    1.364861] bcm2835-rng 3f104000.rng: hwrng registered
[    1.367998] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    1.373797] vc-sm: Videocore shared memory driver
[    1.376868] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    1.394877] brd: module loaded
[    1.410222] loop: module loaded
[    1.414129] Loading iSCSI transport class v2.0-870.
[    1.417659] libphy: Fixed MDIO Bus: probed
[    1.420320] usbcore: registered new interface driver lan78xx
[    1.422948] usbcore: registered new interface driver smsc95xx
[    1.425473] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.156320] Core Release: 2.80a
[    2.158714] Setting default values for core params
[    2.161147] Finished setting default values for core params
[    2.364006] Using Buffer DMA mode
[    2.366474] Periodic Transfer Interrupt Enhancement - disabled
[    2.368970] Multiprocessor Interrupt Enhancement - disabled
[    2.371436] OTG VER PARAM: 0, OTG VER FLAG: 0
[    2.373834] Dedicated Tx FIFOs mode
[    2.376880] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = b7514000 dma = 0xf7514000 len=9024
[    2.381603] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    2.392694] dwc_otg: Microframe scheduler enabled
[    2.392767] WARN::hcd_init_fiq:457: FIQ on core 1
[    2.395009] WARN::hcd_init_fiq:458: FIQ ASM at 8070fc04 length 36
[    2.397259] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
[    2.399477] dwc_otg 3f980000.usb: DWC OTG Controller
[    2.401784] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    2.404150] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
[    2.406487] Init: Port Power? op_state=1
[    2.408731] Init: Power Port (0)
[    2.411261] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.04
[    2.415769] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.418212] usb usb1: Product: DWC OTG Controller
[    2.420582] usb usb1: Manufacturer: Linux 5.4.68-v7+ dwc_otg_hcd
[    2.423005] usb usb1: SerialNumber: 3f980000.usb
[    2.426038] hub 1-0:1.0: USB hub found
[    2.428354] hub 1-0:1.0: 1 port detected
[    2.431293] dwc_otg: FIQ enabled
[    2.431303] dwc_otg: NAK holdoff enabled
[    2.431312] dwc_otg: FIQ split-transaction FSM enabled
[    2.431327] Module dwc_common_port init
[    2.431673] usbcore: registered new interface driver usb-storage
[    2.434180] mousedev: PS/2 mouse device common for all mice
[    2.437706] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    2.443117] sdhci: Secure Digital Host Controller Interface driver
[    2.445542] sdhci: Copyright(c) Pierre Ossman
[    2.448508] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
[    2.451678] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    2.454452] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.458874] ledtrig-cpu: registered to indicate activity on CPUs
[    2.461839] hidraw: raw HID events driver (C) Jiri Kosina
[    2.464592] usbcore: registered new interface driver usbhid
[    2.467212] usbhid: USB HID core driver
[    2.470762] vchiq: vchiq_init_state: slot_zero = (ptrval)
[    2.475100] [vc_sm_connected_init]: start
[    2.483926] [vc_sm_connected_init]: end - returning 0
[    2.488339] Initializing XFRM netlink socket
[    2.490712] NET: Registered protocol family 17
[    2.493171] Key type dns_resolver registered
[    2.496211] Registering SWP/SWPB emulation handler
[    2.498911] registered taskstats version 1
[    2.501270] Loading compiled-in X.509 certificates
[    2.504121] Key type ._fscrypt registered
[    2.506458] Key type .fscrypt registered
[    2.519577] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    2.521975] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    2.528480] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    2.532376] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    2.534760] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[    2.563669] sdhost: log_buf @ (ptrval) (f7513000)
[    2.602130] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    2.606095] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.609999] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.615085] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    2.617207] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    2.621905] of_cfs_init
[    2.624215] of_cfs_init: OK
[    2.627263] Waiting for root device PARTUUID=cc2b1ff6-02...
[    2.646488] Indeed it is in host mode hprt0 = 00021501
[    2.719755] random: fast init done
[    2.769824] mmc0: host does not support reading read-only switch, assuming write-enable
[    2.778185] mmc0: new high speed SDHC card at address aaaa
[    2.781271] mmc1: new high speed SDIO card at address 0001
[    2.784429] mmcblk0: mmc0:aaaa SC32G 29.7 GiB
[    2.792505]  mmcblk0: p1 p2
[    2.821409] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    2.825607] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    2.837876] devtmpfs: mounted
[    2.847008] Freeing unused kernel memory: 1024K
[    2.849606] Run /sbin/init as init process
[    2.856358] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.858894] Indeed it is in host mode hprt0 = 00001101
[    3.096723] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    3.101789] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.105430] hub 1-1:1.0: USB hub found
[    3.108310] hub 1-1:1.0: 4 ports detected
[    3.426386] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.556751] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    3.562062] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.565557] hub 1-1.1:1.0: USB hub found
[    3.568494] hub 1-1.1:1.0: 3 ports detected
[    3.615184] systemd[1]: System time before build time, advancing clock.
[    3.736604] NET: Registered protocol family 10
[    3.740807] Segment Routing with IPv6
[    3.804686] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    3.814508] systemd[1]: Detected architecture arm.
[    3.886367] usb 1-1.1.2: new full-speed USB device number 4 using dwc_otg
[    3.948632] systemd[1]: Set hostname to <raspberrypi>.
[    4.056650] usb 1-1.1.2: New USB device found, idVendor=0451, idProduct=16a8, bcdDevice= 0.09
[    4.062606] usb 1-1.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    4.068943] usb 1-1.1.2: Product: TI CC2531 USB CDC
[    4.072038] usb 1-1.1.2: Manufacturer: Texas Instruments
[    4.074950] usb 1-1.1.2: SerialNumber: __0X00124B001936A05F
[    4.386377] usb 1-1.1.1: new high-speed USB device number 5 using dwc_otg
[    4.516956] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00
[    4.522608] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.793930] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed
[    4.801160] libphy: lan78xx-mdiobus: probed
[    4.820743] systemd[1]: /lib/systemd/system/smbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/smbd.pid → /run/samba/smbd.pid; please update the unit file accordingly.
[    4.837209] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64
[    4.879396] systemd[1]: /lib/systemd/system/nmbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/nmbd.pid → /run/samba/nmbd.pid; please update the unit file accordingly.
[    5.047898] random: systemd: uninitialized urandom read (16 bytes read)
[    5.067389] random: systemd: uninitialized urandom read (16 bytes read)
[    5.073727] systemd[1]: Created slice User and Session Slice.
[    5.081274] random: systemd: uninitialized urandom read (16 bytes read)
[    5.085208] systemd[1]: Listening on fsck to fsckd communication Socket.
[    5.092830] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    5.110095] systemd[1]: Listening on Journal Socket (/dev/log).
[    5.118169] systemd[1]: Listening on udev Control Socket.
[    5.940286] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    6.077809] systemd-journald[105]: Received request to flush runtime journal from PID 1
[    6.808456] mc: Linux media interface: v0.10
[    6.858829] videodev: Linux video capture interface: v2.00
[    6.859759] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    6.864848] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    6.864872] [vc_sm_connected_init]: start
[    6.869701] [vc_sm_connected_init]: installed successfully
[    6.903634] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    6.908150] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    6.919940] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    6.924334] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    6.940790] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    6.954035] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    6.971624] bcm2835_audio bcm2835_audio: card created with 8 channels
[    6.976062] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[    6.981347] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    7.001521] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[    7.002118] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[    7.002603] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[    7.002641] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    7.002663] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    7.002681] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    7.002699] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    7.002945] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[    7.020095] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    7.020148] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    7.028659] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    7.028720] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    7.085013] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    7.085071] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    7.403583] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    7.551307] cdc_acm 1-1.1.2:1.0: ttyACM0: USB ACM device
[    7.553800] usbcore: registered new interface driver cdc_acm
[    7.553814] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
[    7.565311] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    7.641288] brcmfmac: F1 signature read @0x18000000=0x15264345
[    7.656635] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    7.657203] usbcore: registered new interface driver brcmfmac
[    7.696254] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43455-sdio.raspberrypi,3-model-b-plus.txt failed with error -2
[    7.927526] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    7.942504] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Mar 23 2020 02:19:54 version 7.45.206 (r725000 CY) FWID 01-88ee44ea
[    8.919082] random: crng init done
[    8.919097] random: 7 urandom warning(s) missed due to ratelimiting
[    9.835077] uart-pl011 3f201000.serial: no DMA platform data
[    9.855166] 8021q: 802.1Q VLAN Support v1.8
[   10.176517] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[   10.293778] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[   10.566128] 8021q: adding VLAN 0 to HW filter on device eth0
[   15.719881] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   16.775851] Bluetooth: Core ver 2.22
[   16.775945] NET: Registered protocol family 31
[   16.775953] Bluetooth: HCI device and connection manager initialized
[   16.775977] Bluetooth: HCI socket layer initialized
[   16.775991] Bluetooth: L2CAP socket layer initialized
[   16.776015] Bluetooth: SCO socket layer initialized
[   16.792104] Bluetooth: HCI UART driver ver 2.3
[   16.792119] Bluetooth: HCI UART protocol H4 registered
[   16.792203] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   16.792419] Bluetooth: HCI UART protocol Broadcom registered
[   17.065282] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   17.065293] Bluetooth: BNEP filters: protocol multicast
[   17.065315] Bluetooth: BNEP socket layer initialized
[   17.228572] ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.wlan0.retrans_time - use net.ipv6.neigh.wlan0.retrans_time_ms instead
[   36.254117] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[   36.265346] Bridge firewalling registered
Koenkk commented 4 years ago

It looks you are having some USB instability causing the CC2531 to be disconnected. This can also be caused by a bad power supply on the Pi.

mrucki commented 4 years ago

Ah, and one thing I missed in my comments is that my raspberry pi + zigbee2mqtt + openhab has worked fine for last year until few days ago I upgraded my Raspbian from stretch to buster version - perhaps this causes usb instability? Are there any known issues with Raspbian Buster ?

mrucki commented 4 years ago

@Koenkk I found there is a possibility to set an option like max_usb_current=1 in /boot/config.txt but it was missing in my device. So I added it to my config file and after 4 hours (much longer then previously) issue occurred again:

pi@raspberrypi:~ $ dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.4.68-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1343 SMP Mon Sep 28 12:38:29 BST 2020
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Reserved memory: created CMA memory pool at 0x37400000, size 64 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] On node 0 totalpages: 242688
[    0.000000]   Normal zone: 2133 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 242688 pages, LIFO batch:63
[    0.000000] percpu: Embedded 20 pages/cpu s49920 r8192 d23808 u81920
[    0.000000] pcpu-alloc: s49920 r8192 d23808 u81920 alloc=20*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=cc2b1ff6-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 880476K/970752K available (9216K kernel code, 697K rwdata, 2604K rodata, 1024K init, 830K bss, 24740K reserved, 65536K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 29216 entries in 58 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] random: get_random_bytes called from start_kernel+0x32c/0x508 with crng_init=0
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000022] Switching to timer-based delay loop, resolution 52ns
[    0.000290] Console: colour dummy device 80x30
[    0.000877] printk: console [tty1] enabled
[    0.000944] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.000993] pid_max: default: 32768 minimum: 301
[    0.001208] LSM: Security Framework initializing
[    0.001450] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.001496] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.002896] Disabling memory control group subsystem
[    0.003042] CPU: Testing write buffer coherency: ok
[    0.003628] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.004599] Setting up static identity map for 0x100000 - 0x10003c
[    0.004819] rcu: Hierarchical SRCU implementation.
[    0.005528] smp: Bringing up secondary CPUs ...
[    0.006717] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.008040] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.009254] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.009407] smp: Brought up 1 node, 4 CPUs
[    0.009495] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.009523] CPU: All CPU(s) started in HYP mode.
[    0.009548] CPU: Virtualization extensions available.
[    0.010650] devtmpfs: initialized
[    0.027154] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.027459] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.027516] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.030739] pinctrl core: initialized pinctrl subsystem
[    0.031875] NET: Registered protocol family 16
[    0.036180] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.041075] audit: initializing netlink subsys (disabled)
[    0.041379] audit: type=2000 audit(0.040:1): state=initialized audit_enabled=0 res=1
[    0.042847] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.042886] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.043124] Serial: AMBA PL011 UART driver
[    0.045117] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.070103] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-09-28 12:54, variant start
[    0.080117] raspberrypi-firmware soc:firmware: Firmware hash is 2c4b5cf8e4a920c2976ebdb62b27bd742b69ea8b
[    0.131628] bcm2835-dma 3f007000.dma: DMA legacy API manager, dmachans=0x1
[    0.133805] SCSI subsystem initialized
[    0.134080] usbcore: registered new interface driver usbfs
[    0.134162] usbcore: registered new interface driver hub
[    0.134308] usbcore: registered new device driver usb
[    0.136311] clocksource: Switched to clocksource arch_sys_counter
[    1.297349] VFS: Disk quotas dquot_6.6.0
[    1.297490] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.297706] FS-Cache: Loaded
[    1.297998] CacheFiles: Loaded
[    1.309466] thermal_sys: Registered thermal governor 'step_wise'
[    1.309850] NET: Registered protocol family 2
[    1.310915] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[    1.310990] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    1.311132] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    1.311342] TCP: Hash tables configured (established 8192 bind 8192)
[    1.311528] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.311601] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.311920] NET: Registered protocol family 1
[    1.312733] RPC: Registered named UNIX socket transport module.
[    1.312765] RPC: Registered udp transport module.
[    1.312791] RPC: Registered tcp transport module.
[    1.312817] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.314601] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    1.318091] Initialise system trusted keyrings
[    1.318379] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    1.330293] FS-Cache: Netfs 'nfs' registered for caching
[    1.331093] NFS: Registering the id_resolver key type
[    1.331149] Key type id_resolver registered
[    1.331175] Key type id_legacy registered
[    1.331211] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.332536] Key type asymmetric registered
[    1.332566] Asymmetric key parser 'x509' registered
[    1.332646] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    1.332683] io scheduler mq-deadline registered
[    1.332710] io scheduler kyber registered
[    1.336161] bcm2708_fb soc:fb: FB found 1 display(s)
[    1.348728] Console: switching to colour frame buffer device 82x26
[    1.355594] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
[    1.365485] bcm2835-rng 3f104000.rng: hwrng registered
[    1.368627] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    1.374421] vc-sm: Videocore shared memory driver
[    1.377490] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    1.395479] brd: module loaded
[    1.410799] loop: module loaded
[    1.414695] Loading iSCSI transport class v2.0-870.
[    1.418223] libphy: Fixed MDIO Bus: probed
[    1.420878] usbcore: registered new interface driver lan78xx
[    1.423500] usbcore: registered new interface driver smsc95xx
[    1.426025] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.156832] Core Release: 2.80a
[    2.159228] Setting default values for core params
[    2.161662] Finished setting default values for core params
[    2.364499] Using Buffer DMA mode
[    2.366966] Periodic Transfer Interrupt Enhancement - disabled
[    2.369460] Multiprocessor Interrupt Enhancement - disabled
[    2.371924] OTG VER PARAM: 0, OTG VER FLAG: 0
[    2.374320] Dedicated Tx FIFOs mode
[    2.377315] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = b7514000 dma = 0xf7514000 len=9024
[    2.382029] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    2.393107] dwc_otg: Microframe scheduler enabled
[    2.393174] WARN::hcd_init_fiq:457: FIQ on core 1
[    2.395416] WARN::hcd_init_fiq:458: FIQ ASM at 8070fc04 length 36
[    2.397666] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
[    2.399909] dwc_otg 3f980000.usb: DWC OTG Controller
[    2.402213] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    2.404577] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
[    2.406912] Init: Port Power? op_state=1
[    2.409159] Init: Power Port (0)
[    2.411694] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.04
[    2.416208] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.418665] usb usb1: Product: DWC OTG Controller
[    2.421039] usb usb1: Manufacturer: Linux 5.4.68-v7+ dwc_otg_hcd
[    2.423464] usb usb1: SerialNumber: 3f980000.usb
[    2.426523] hub 1-0:1.0: USB hub found
[    2.428831] hub 1-0:1.0: 1 port detected
[    2.431757] dwc_otg: FIQ enabled
[    2.431767] dwc_otg: NAK holdoff enabled
[    2.431777] dwc_otg: FIQ split-transaction FSM enabled
[    2.431791] Module dwc_common_port init
[    2.432148] usbcore: registered new interface driver usb-storage
[    2.434631] mousedev: PS/2 mouse device common for all mice
[    2.438109] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    2.443525] sdhci: Secure Digital Host Controller Interface driver
[    2.445957] sdhci: Copyright(c) Pierre Ossman
[    2.448957] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
[    2.452109] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    2.454895] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.459336] ledtrig-cpu: registered to indicate activity on CPUs
[    2.462285] hidraw: raw HID events driver (C) Jiri Kosina
[    2.465032] usbcore: registered new interface driver usbhid
[    2.467653] usbhid: USB HID core driver
[    2.471204] vchiq: vchiq_init_state: slot_zero = (ptrval)
[    2.475522] [vc_sm_connected_init]: start
[    2.484397] [vc_sm_connected_init]: end - returning 0
[    2.488782] Initializing XFRM netlink socket
[    2.491159] NET: Registered protocol family 17
[    2.493611] Key type dns_resolver registered
[    2.496690] Registering SWP/SWPB emulation handler
[    2.499366] registered taskstats version 1
[    2.501731] Loading compiled-in X.509 certificates
[    2.504558] Key type ._fscrypt registered
[    2.506888] Key type .fscrypt registered
[    2.520033] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    2.522445] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    2.529011] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    2.532876] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    2.535262] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[    2.564169] sdhost: log_buf @ (ptrval) (f7513000)
[    2.602672] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    2.606644] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.610514] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.615601] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    2.617719] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    2.622410] of_cfs_init
[    2.624726] of_cfs_init: OK
[    2.627845] Waiting for root device PARTUUID=cc2b1ff6-02...
[    2.646496] Indeed it is in host mode hprt0 = 00021501
[    2.719872] random: fast init done
[    2.771106] mmc0: host does not support reading read-only switch, assuming write-enable
[    2.779200] mmc1: new high speed SDIO card at address 0001
[    2.782173] mmc0: new high speed SDHC card at address aaaa
[    2.785409] mmcblk0: mmc0:aaaa SC32G 29.7 GiB
[    2.793431]  mmcblk0: p1 p2
[    2.821533] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    2.825708] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    2.838004] devtmpfs: mounted
[    2.847055] Freeing unused kernel memory: 1024K
[    2.849627] Run /sbin/init as init process
[    2.856359] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.858926] Indeed it is in host mode hprt0 = 00001101
[    3.096725] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    3.101834] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.105421] hub 1-1:1.0: USB hub found
[    3.108325] hub 1-1:1.0: 4 ports detected
[    3.426385] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.556788] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    3.562142] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.565701] hub 1-1.1:1.0: USB hub found
[    3.568661] hub 1-1.1:1.0: 3 ports detected
[    3.615104] systemd[1]: System time before build time, advancing clock.
[    3.666375] usb 1-1.3: new full-speed USB device number 4 using dwc_otg
[    3.736241] NET: Registered protocol family 10
[    3.740364] Segment Routing with IPv6
[    3.788561] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    3.811333] systemd[1]: Detected architecture arm.
[    3.816354] usb 1-1.3: New USB device found, idVendor=0451, idProduct=16a8, bcdDevice= 0.09
[    3.822253] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    3.825262] usb 1-1.3: Product: TI CC2531 USB CDC
[    3.828206] usb 1-1.3: Manufacturer: Texas Instruments
[    3.831074] usb 1-1.3: SerialNumber: __0X00124B001936A05F
[    3.942162] systemd[1]: Set hostname to <raspberrypi>.
[    4.336432] usb 1-1.1.1: new high-speed USB device number 5 using dwc_otg
[    4.466888] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00
[    4.472581] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.743293] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed
[    4.750533] libphy: lan78xx-mdiobus: probed
[    4.784795] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64
[    4.864667] systemd[1]: /lib/systemd/system/smbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/smbd.pid → /run/samba/smbd.pid; please update the unit file accordingly.
[    4.922667] systemd[1]: /lib/systemd/system/nmbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/nmbd.pid → /run/samba/nmbd.pid; please update the unit file accordingly.
[    5.087609] random: systemd: uninitialized urandom read (16 bytes read)
[    5.107338] random: systemd: uninitialized urandom read (16 bytes read)
[    5.115468] systemd[1]: Created slice system-getty.slice.
[    5.123118] random: systemd: uninitialized urandom read (16 bytes read)
[    5.126728] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    5.137782] systemd[1]: Listening on fsck to fsckd communication Socket.
[    5.147181] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    5.154989] systemd[1]: Listening on Syslog Socket.
[    5.930532] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    6.037909] systemd-journald[122]: Received request to flush runtime journal from PID 1
[    6.736048] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    6.738900] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    6.738925] [vc_sm_connected_init]: start
[    6.745945] mc: Linux media interface: v0.10
[    6.749575] [vc_sm_connected_init]: installed successfully
[    6.801410] videodev: Linux video capture interface: v2.00
[    6.889185] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    6.889506] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    6.890215] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    6.925318] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    6.927999] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    6.941656] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    6.953104] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    6.973551] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    6.973606] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    6.987102] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    6.987374] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    6.989090] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[    6.989888] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[    6.990308] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[    6.990661] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[    6.990690] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    6.990712] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    6.990731] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    6.990748] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    6.991117] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[    6.994195] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    6.994243] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    7.003207] bcm2835_audio bcm2835_audio: card created with 8 channels
[    7.233723] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    7.401795] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
[    7.404299] usbcore: registered new interface driver cdc_acm
[    7.404323] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
[    7.452086] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    7.590862] brcmfmac: F1 signature read @0x18000000=0x15264345
[    7.630739] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    7.631891] usbcore: registered new interface driver brcmfmac
[    7.670397] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43455-sdio.raspberrypi,3-model-b-plus.txt failed with error -2
[    7.901867] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    7.916297] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Mar 23 2020 02:19:54 version 7.45.206 (r725000 CY) FWID 01-88ee44ea
[    9.534759] uart-pl011 3f201000.serial: no DMA platform data
[    9.690614] 8021q: 802.1Q VLAN Support v1.8
[    9.906986] random: crng init done
[    9.907001] random: 7 urandom warning(s) missed due to ratelimiting
[   10.016999] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[   10.115222] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[   10.383556] 8021q: adding VLAN 0 to HW filter on device eth0
[   15.567679] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   16.575380] Bluetooth: Core ver 2.22
[   16.575469] NET: Registered protocol family 31
[   16.575477] Bluetooth: HCI device and connection manager initialized
[   16.575502] Bluetooth: HCI socket layer initialized
[   16.575531] Bluetooth: L2CAP socket layer initialized
[   16.575555] Bluetooth: SCO socket layer initialized
[   16.599826] Bluetooth: HCI UART driver ver 2.3
[   16.599842] Bluetooth: HCI UART protocol H4 registered
[   16.599911] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   16.600128] Bluetooth: HCI UART protocol Broadcom registered
[   16.790004] ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.wlan0.retrans_time - use net.ipv6.neigh.wlan0.retrans_time_ms instead
[   16.879275] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   16.879288] Bluetooth: BNEP filters: protocol multicast
[   16.879305] Bluetooth: BNEP socket layer initialized
[   36.205041] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[   36.216776] Bridge firewalling registered
Koenkk commented 4 years ago

Try plugging the stick directly in the pi (without extension cable), does it survive longer?

mrucki commented 4 years ago

Ok, will try tonight

One more thing, today I stopped zigbee2mqtt, then cleared dmesg with sudo dmesg -C then sudo iwconfig wlan0 power off then started zigbee2mqtt and when it failed the dmesg showed only:

pi@raspberrypi:~ $ dmesg 
[26123.004286] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled (which is fine as tuned off power management above)

no info about reconnecting usb device

mrucki commented 4 years ago

@Koenkk same issue when plugging the stick directly in the pi (without extension cable).

golddragon007 commented 4 years ago

Hello,

I've changed my cc2531 to slaesh’s CC2652RB stick. After I've forced the ZigBee stick to start with the old pan_id (even if I've changed the pan id it didn't want to start... see: https://github.com/Koenkk/zigbee2mqtt/issues/4513), now I've got both errors in the z2m log (as OP has) in debug log mode, in mixed order:

Zigbee2MQTT:debug 2020-10-02 10:09:48: Saving state to file /share/zigbee2mqtt/state.json
(node:235) UnhandledPromiseRejectionWarning: Error: SREQ '--> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}' failed with status '(0x11: BUFFER_FULL)' (expected '(0x00: SUCCESS)')
    at Znp.<anonymous> (/zigbee2mqtt-1.15.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/znp/znp.js:291:27)
    at Generator.next (<anonymous>)
    at fulfilled (/zigbee2mqtt-1.15.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/znp/znp.js:24:58)
(node:235) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 36)
Zigbee2MQTT:debug 2020-10-02 10:14:48: Saving state to file /share/zigbee2mqtt/state.json
(node:235) UnhandledPromiseRejectionWarning: Error: SREQ '--> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":188,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,189,2,11,254,0]}}' failed with status '(0x11: BUFFER_FULL)' (expected '(0x00: SUCCESS)')
    at Znp.<anonymous> (/zigbee2mqtt-1.15.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/znp/znp.js:291:27)
    at Generator.next (<anonymous>)
    at fulfilled (/zigbee2mqtt-1.15.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/znp/znp.js:24:58)
(node:235) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 37)
Zigbee2MQTT:debug 2020-10-02 10:19:48: Saving state to file /share/zigbee2mqtt/state.json

I don't see where do I need to put the "zigbee_herdsman_debug": true in the config, it's missing from here: https://www.zigbee2mqtt.io/information/configuration.html

Koenkk commented 4 years ago

@mrucki is anything shown in dmesg at the time Zigbee2MQTT crashes?

@golddragon007 zigbee_herdsman_debug: true only applies to the Home Assistant addon. See https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging . Might also be worth looking at dmesg at the time of the crash. Also what system do you use (Pi?), how is the adapter connected, and are any there any other USB devices attached?

mrucki commented 4 years ago

@Koenkk as wrote above:

sudo dmesg -C then sudo iwconfig wlan0 power off then started zigbee2mqtt and when it failed the dmesg showed only pi@raspberrypi:~ $ dmesg [26123.004286] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled (which is fine as tuned off power management above)

so nothing in dmesg

Today I reflashed my RaspberryPi with brand new RaspberryPi OS Buster - started OpenHab, Grafana, Influxdb, Eclipse Mosquitto and Zigbee2Mqtt (latest) using Docker.

Unfortunatelly issue ocuured again - I wonder if someone else tested zigbee2mqtt with raspbian buster?

golddragon007 commented 4 years ago

@Koenkk I using Pi 4 with bash only (no GUI). My boot drive is an m.2 SSD connected via USB 3 and now the slaesh’s CC2652RB stick (directly).

"zigbee_herdsman_debug: true only applies to the Home Assistant addon" Yes, I know, that's why I wanted to use that. I've put it into the root, it didn't cry so I hope it does the job.

Regarding dmesg, I have something but this time looks for me yesterday's midnight (because these are logged before ~20 hour) when I tried to figure out why it doesn't want to boot up and start broadcasting the Zigbee network:

[...]
[ 6027.488915] scsi host0: uas_eh_device_reset_handler start
[ 6027.639647] usb 2-2: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 6027.673081] scsi host0: uas_eh_device_reset_handler success
[ 6030.532417] hassio: port 14(veth8c410e9) entered blocking state
[ 6030.532427] hassio: port 14(veth8c410e9) entered disabled state
[ 6030.532795] device veth8c410e9 entered promiscuous mode
[ 6030.573408] IPv6: ADDRCONF(NETDEV_CHANGE): vethcd6a52d: link becomes ready
[ 6030.573560] IPv6: ADDRCONF(NETDEV_CHANGE): veth8c410e9: link becomes ready
[ 6030.573660] hassio: port 14(veth8c410e9) entered blocking state
[ 6030.573666] hassio: port 14(veth8c410e9) entered forwarding state
[ 6032.193073] hassio: port 14(veth8c410e9) entered disabled state
[ 6032.203987] eth0: renamed from vethcd6a52d
[ 6032.270318] hassio: port 14(veth8c410e9) entered blocking state
[ 6032.270331] hassio: port 14(veth8c410e9) entered forwarding state
[ 6138.872649] hassio: port 14(veth8c410e9) entered disabled state
[ 6138.873340] vethcd6a52d: renamed from eth0
[ 6139.019898] hassio: port 14(veth8c410e9) entered disabled state
[ 6139.037527] device veth8c410e9 left promiscuous mode
[ 6139.037538] hassio: port 14(veth8c410e9) entered disabled state
[ 6176.650967] usb 1-1.3: USB disconnect, device number 6
[ 6176.651545] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
[ 6176.651661] cp210x 1-1.3:1.0: device disconnected
[ 6187.850223] usb 1-1.3: new full-speed USB device number 7 using xhci_hcd
[ 6187.985569] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[ 6187.985583] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 6187.985593] usb 1-1.3: Product: slae.sh cc2652rb stick - slaesh's iot stuff
[ 6187.985603] usb 1-1.3: Manufacturer: Silicon Labs
[ 6187.985613] usb 1-1.3: SerialNumber: 00_12_4B_00_21_CC_09_E4
[ 6187.989631] cp210x 1-1.3:1.0: cp210x converter detected
[ 6187.997921] usb 1-1.3: cp210x converter now attached to ttyUSB0
[ 6218.140701] sd 0:0:0:0: [sda] tag#27 uas_eh_abort_handler 0 uas-tag 6 inflight: CMD
[ 6218.140710] sd 0:0:0:0: [sda] tag#27 CDB: opcode=0x2a 2a 00 00 cd 47 d8 00 00 08 00
[ 6218.140723] sd 0:0:0:0: [sda] tag#26 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD
[ 6218.140729] sd 0:0:0:0: [sda] tag#26 CDB: opcode=0x2a 2a 00 01 cc 9f 70 00 00 08 00
[ 6218.140746] sd 0:0:0:0: [sda] tag#25 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD IN
[ 6218.140751] sd 0:0:0:0: [sda] tag#25 CDB: opcode=0x28 28 00 00 b6 d6 c0 00 00 20 00
[ 6218.141072] sd 0:0:0:0: [sda] tag#11 uas_eh_abort_handler 0 uas-tag 5 inflight: CMD
[ 6218.141077] sd 0:0:0:0: [sda] tag#11 CDB: opcode=0x2a 2a 00 03 4c 70 48 00 00 08 00
[ 6218.141087] sd 0:0:0:0: [sda] tag#10 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD
[ 6218.141092] sd 0:0:0:0: [sda] tag#10 CDB: opcode=0x2a 2a 00 03 4c 32 38 00 00 08 00
[ 6218.141108] sd 0:0:0:0: [sda] tag#7 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD
[ 6218.141113] sd 0:0:0:0: [sda] tag#7 CDB: opcode=0x2a 2a 00 01 54 89 48 00 00 08 00
[ 6219.660740] sd 0:0:0:0: [sda] tag#24 uas_eh_abort_handler 0 uas-tag 7 inflight: CMD
[ 6219.660748] sd 0:0:0:0: [sda] tag#24 CDB: opcode=0x2a 2a 00 01 cc a3 b8 00 00 08 00
[ 6219.990754] sd 0:0:0:0: [sda] tag#4 uas_eh_abort_handler 0 uas-tag 8 inflight: CMD
[ 6219.990762] sd 0:0:0:0: [sda] tag#4 CDB: opcode=0x2a 2a 00 00 e1 32 c8 00 00 08 00
[ 6221.110754] sd 0:0:0:0: [sda] tag#8 uas_eh_abort_handler 0 uas-tag 9 inflight: CMD
[ 6221.110763] sd 0:0:0:0: [sda] tag#8 CDB: opcode=0x2a 2a 00 00 df 82 f0 00 00 08 00
[ 6221.190764] sd 0:0:0:0: [sda] tag#5 uas_eh_abort_handler 0 uas-tag 10 inflight: CMD
[ 6221.190773] sd 0:0:0:0: [sda] tag#5 CDB: opcode=0x35 35 00 00 00 00 00 00 00 00 00
[ 6223.260806] sd 0:0:0:0: [sda] tag#6 uas_eh_abort_handler 0 uas-tag 11 inflight: CMD OUT
[ 6223.260815] sd 0:0:0:0: [sda] tag#6 CDB: opcode=0x2a 2a 00 00 18 6e c8 00 02 00 00
[ 6227.580874] sd 0:0:0:0: [sda] tag#9 uas_eh_abort_handler 0 uas-tag 12 inflight: CMD OUT
[ 6227.580888] sd 0:0:0:0: [sda] tag#9 CDB: opcode=0x2a 2a 00 01 58 71 f8 00 00 08 00
[ 6229.740901] sd 0:0:0:0: [sda] tag#28 uas_eh_abort_handler 0 uas-tag 13 inflight: CMD OUT
[ 6229.740910] sd 0:0:0:0: [sda] tag#28 CDB: opcode=0x2a 2a 00 00 61 24 10 00 00 20 00
[ 6234.781009] sd 0:0:0:0: [sda] tag#23 uas_eh_abort_handler 0 uas-tag 25 inflight: CMD OUT
[ 6234.781017] sd 0:0:0:0: [sda] tag#23 CDB: opcode=0x2a 2a 00 01 82 9c d8 00 00 10 00
[ 6234.781319] sd 0:0:0:0: [sda] tag#22 uas_eh_abort_handler 0 uas-tag 24 inflight: CMD OUT
[ 6234.781326] sd 0:0:0:0: [sda] tag#22 CDB: opcode=0x2a 2a 00 01 82 93 c8 00 00 08 00
[ 6234.781630] sd 0:0:0:0: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 23 inflight: CMD OUT
[ 6234.781636] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x2a 2a 00 01 82 2d 18 00 00 10 00
[ 6234.781714] sd 0:0:0:0: [sda] tag#20 uas_eh_abort_handler 0 uas-tag 22 inflight: CMD OUT
[ 6234.781720] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x2a 2a 00 01 82 25 f8 00 00 08 00
[ 6234.781792] sd 0:0:0:0: [sda] tag#19 uas_eh_abort_handler 0 uas-tag 21 inflight: CMD OUT
[ 6234.781798] sd 0:0:0:0: [sda] tag#19 CDB: opcode=0x2a 2a 00 01 81 9c 98 00 00 08 00
[ 6234.781872] sd 0:0:0:0: [sda] tag#18 uas_eh_abort_handler 0 uas-tag 20 inflight: CMD OUT
[ 6234.781877] sd 0:0:0:0: [sda] tag#18 CDB: opcode=0x2a 2a 00 01 81 97 98 00 00 10 00
[ 6234.781952] sd 0:0:0:0: [sda] tag#17 uas_eh_abort_handler 0 uas-tag 19 inflight: CMD OUT
[ 6234.781957] sd 0:0:0:0: [sda] tag#17 CDB: opcode=0x2a 2a 00 01 81 48 20 00 00 08 00
[ 6234.782032] sd 0:0:0:0: [sda] tag#16 uas_eh_abort_handler 0 uas-tag 18 inflight: CMD OUT
[ 6234.782037] sd 0:0:0:0: [sda] tag#16 CDB: opcode=0x2a 2a 00 01 81 47 40 00 00 08 00
[ 6234.782112] sd 0:0:0:0: [sda] tag#15 uas_eh_abort_handler 0 uas-tag 17 inflight: CMD OUT
[ 6234.782117] sd 0:0:0:0: [sda] tag#15 CDB: opcode=0x2a 2a 00 01 81 40 88 00 00 10 00
[ 6234.782193] sd 0:0:0:0: [sda] tag#14 uas_eh_abort_handler 0 uas-tag 16 inflight: CMD OUT
[ 6234.782198] sd 0:0:0:0: [sda] tag#14 CDB: opcode=0x2a 2a 00 01 81 3f 58 00 00 08 00
[ 6234.782273] sd 0:0:0:0: [sda] tag#13 uas_eh_abort_handler 0 uas-tag 15 inflight: CMD OUT
[ 6234.782278] sd 0:0:0:0: [sda] tag#13 CDB: opcode=0x2a 2a 00 01 81 3e 98 00 00 08 00
[ 6234.782352] sd 0:0:0:0: [sda] tag#12 uas_eh_abort_handler 0 uas-tag 14 inflight: CMD OUT
[ 6234.782358] sd 0:0:0:0: [sda] tag#12 CDB: opcode=0x2a 2a 00 01 80 a0 20 00 00 08 00
[ 6234.782433] sd 0:0:0:0: [sda] tag#3 uas_eh_abort_handler 0 uas-tag 29 inflight: CMD OUT
[ 6234.782439] sd 0:0:0:0: [sda] tag#3 CDB: opcode=0x2a 2a 00 01 7e b3 c0 00 00 10 00
[ 6234.782512] sd 0:0:0:0: [sda] tag#2 uas_eh_abort_handler 0 uas-tag 28 inflight: CMD OUT
[ 6234.782518] sd 0:0:0:0: [sda] tag#2 CDB: opcode=0x2a 2a 00 01 7e b2 c0 00 00 10 00
[ 6234.782601] sd 0:0:0:0: [sda] tag#1 uas_eh_abort_handler 0 uas-tag 27 inflight: CMD OUT
[ 6234.782607] sd 0:0:0:0: [sda] tag#1 CDB: opcode=0x2a 2a 00 01 82 9e d0 00 00 08 00
[ 6234.782896] sd 0:0:0:0: [sda] tag#0 uas_eh_abort_handler 0 uas-tag 26 inflight: CMD OUT
[ 6234.782902] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x2a 2a 00 01 82 9d d8 00 00 08 00
[ 6234.841016] scsi host0: uas_eh_device_reset_handler start
[ 6234.991693] usb 2-2: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 6235.025168] scsi host0: uas_eh_device_reset_handler success
[ 6237.643253] hassio: port 14(vethb8eaced) entered blocking state
[ 6237.643264] hassio: port 14(vethb8eaced) entered disabled state
[ 6237.643546] device vethb8eaced entered promiscuous mode
[ 6237.683540] IPv6: ADDRCONF(NETDEV_CHANGE): vethbfa56ae: link becomes ready
[ 6237.683707] IPv6: ADDRCONF(NETDEV_CHANGE): vethb8eaced: link becomes ready
[ 6237.683812] hassio: port 14(vethb8eaced) entered blocking state
[ 6237.683819] hassio: port 14(vethb8eaced) entered forwarding state
[ 6239.681911] hassio: port 14(vethb8eaced) entered disabled state
[ 6239.691810] eth0: renamed from vethbfa56ae
[ 6239.752612] hassio: port 14(vethb8eaced) entered blocking state
[ 6239.752620] hassio: port 14(vethb8eaced) entered forwarding state
[ 6292.323965] hassio: port 14(vethb8eaced) entered disabled state
[ 6292.324266] vethbfa56ae: renamed from eth0
[ 6292.510624] hassio: port 14(vethb8eaced) entered disabled state
[ 6292.528684] device vethb8eaced left promiscuous mode
[ 6292.528698] hassio: port 14(vethb8eaced) entered disabled state
[ 6293.041041] hassio: port 14(vethda08b39) entered blocking state
[ 6293.041048] hassio: port 14(vethda08b39) entered disabled state
[ 6293.041253] device vethda08b39 entered promiscuous mode
[ 6293.041510] hassio: port 14(vethda08b39) entered blocking state
[ 6293.041517] hassio: port 14(vethda08b39) entered forwarding state
[ 6293.090438] IPv6: ADDRCONF(NETDEV_CHANGE): vethda08b39: link becomes ready
[ 6294.363345] hassio: port 14(vethda08b39) entered disabled state
[ 6294.366027] eth0: renamed from veth82f331b
[ 6294.428371] hassio: port 14(vethda08b39) entered blocking state
[ 6294.428380] hassio: port 14(vethda08b39) entered forwarding state
[ 6703.993420] hassio: port 14(vethda08b39) entered disabled state
[ 6703.994290] veth82f331b: renamed from eth0
[ 6704.127503] hassio: port 14(vethda08b39) entered disabled state
[ 6704.149613] device vethda08b39 left promiscuous mode
[ 6704.149623] hassio: port 14(vethda08b39) entered disabled state
[ 6704.828291] hassio: port 14(vethf86c105) entered blocking state
[ 6704.828299] hassio: port 14(vethf86c105) entered disabled state
[ 6704.828518] device vethf86c105 entered promiscuous mode
[ 6704.828848] hassio: port 14(vethf86c105) entered blocking state
[ 6704.828854] hassio: port 14(vethf86c105) entered forwarding state
[ 6704.858765] IPv6: ADDRCONF(NETDEV_CHANGE): vethf86c105: link becomes ready
[ 6706.268081] hassio: port 14(vethf86c105) entered disabled state
[ 6706.269370] eth0: renamed from veth3626608
[ 6706.338278] hassio: port 14(vethf86c105) entered blocking state
[ 6706.338286] hassio: port 14(vethf86c105) entered forwarding state
[ 6829.046336] hassio: port 14(vethf86c105) entered disabled state
[ 6829.046789] veth3626608: renamed from eth0
[ 6829.191643] IPv6: ADDRCONF(NETDEV_CHANGE): veth3626608: link becomes ready
[ 6829.191812] hassio: port 14(vethf86c105) entered blocking state
[ 6829.191818] hassio: port 14(vethf86c105) entered forwarding state
[ 6829.227806] hassio: port 14(vethf86c105) entered disabled state
[ 6829.246039] device vethf86c105 left promiscuous mode
[ 6829.246050] hassio: port 14(vethf86c105) entered disabled state
[ 6829.863822] hassio: port 14(veth847db35) entered blocking state
[ 6829.863830] hassio: port 14(veth847db35) entered disabled state
[ 6829.864032] device veth847db35 entered promiscuous mode
[ 6829.864292] hassio: port 14(veth847db35) entered blocking state
[ 6829.864299] hassio: port 14(veth847db35) entered forwarding state
[ 6829.928485] IPv6: ADDRCONF(NETDEV_CHANGE): veth847db35: link becomes ready
[ 6831.231236] eth0: renamed from veth7169dd1
[ 6831.279315] hassio: port 14(veth847db35) entered disabled state
[ 6831.280734] hassio: port 14(veth847db35) entered blocking state
[ 6831.280744] hassio: port 14(veth847db35) entered forwarding state
[ 6978.986569] hassio: port 14(veth847db35) entered disabled state
[ 6978.990067] veth7169dd1: renamed from eth0
[ 6979.119293] hassio: port 14(veth847db35) entered disabled state
[ 6979.146127] device veth847db35 left promiscuous mode
[ 6979.146137] hassio: port 14(veth847db35) entered disabled state
[ 7033.185446] usb 1-1.3: USB disconnect, device number 7
[ 7033.185898] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
[ 7033.186008] cp210x 1-1.3:1.0: device disconnected
[ 7048.991089] usb 1-1.3: new full-speed USB device number 8 using xhci_hcd
[ 7049.126519] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[ 7049.126528] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 7049.126535] usb 1-1.3: Product: slae.sh cc2652rb stick - slaesh's iot stuff
[ 7049.126541] usb 1-1.3: Manufacturer: Silicon Labs
[ 7049.126547] usb 1-1.3: SerialNumber: 00_12_4B_00_21_CC_09_E4
[ 7049.132152] cp210x 1-1.3:1.0: cp210x converter detected
[ 7049.136668] usb 1-1.3: cp210x converter now attached to ttyUSB0
[ 7078.951607] sd 0:0:0:0: [sda] tag#27 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD IN
[ 7078.951616] sd 0:0:0:0: [sda] tag#27 CDB: opcode=0x28 28 00 01 1f 7f a0 00 00 20 00
[ 7079.001354] sd 0:0:0:0: [sda] tag#24 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD
[ 7079.001364] sd 0:0:0:0: [sda] tag#24 CDB: opcode=0x2a 2a 00 01 54 98 a8 00 00 08 00
[ 7079.021358] sd 0:0:0:0: [sda] tag#18 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD
[ 7079.021366] sd 0:0:0:0: [sda] tag#18 CDB: opcode=0x2a 2a 00 00 89 45 68 00 00 40 00
[ 7079.151375] sd 0:0:0:0: [sda] tag#25 uas_eh_abort_handler 0 uas-tag 5 inflight: CMD IN
[ 7079.151385] sd 0:0:0:0: [sda] tag#25 CDB: opcode=0x28 28 00 00 cd 47 e0 00 00 08 00
[ 7079.151636] sd 0:0:0:0: [sda] tag#19 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD IN
[ 7079.151642] sd 0:0:0:0: [sda] tag#19 CDB: opcode=0x28 28 00 03 4c 2d 68 00 00 08 00
[ 7079.171415] sd 0:0:0:0: [sda] tag#16 uas_eh_abort_handler 0 uas-tag 6 inflight: CMD
[ 7079.171423] sd 0:0:0:0: [sda] tag#16 CDB: opcode=0x2a 2a 00 01 cc 9f 70 00 00 08 00
[ 7080.391388] sd 0:0:0:0: [sda] tag#17 uas_eh_abort_handler 0 uas-tag 7 inflight: CMD
[ 7080.391398] sd 0:0:0:0: [sda] tag#17 CDB: opcode=0x2a 2a 00 01 5f aa 08 00 00 08 00
[ 7084.071403] sd 0:0:0:0: [sda] tag#20 uas_eh_abort_handler 0 uas-tag 8 inflight: CMD
[ 7084.071412] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x2a 2a 00 00 18 f7 80 00 01 08 00
[ 7085.041431] sd 0:0:0:0: [sda] tag#26 uas_eh_abort_handler 0 uas-tag 9 inflight: CMD
[ 7085.041440] sd 0:0:0:0: [sda] tag#26 CDB: opcode=0x2a 2a 00 01 58 a3 70 00 00 08 00
[ 7087.511495] sd 0:0:0:0: [sda] tag#28 uas_eh_abort_handler 0 uas-tag 10 inflight: CMD
[ 7087.511511] sd 0:0:0:0: [sda] tag#28 CDB: opcode=0x2a 2a 00 01 58 7f b8 00 00 08 00
[ 7087.551468] scsi host0: uas_eh_device_reset_handler start
[ 7087.702283] usb 2-2: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 7087.736538] scsi host0: uas_eh_device_reset_handler success
[ 7090.399672] hassio: port 14(veth640c74b) entered blocking state
[ 7090.399680] hassio: port 14(veth640c74b) entered disabled state
[ 7090.400099] device veth640c74b entered promiscuous mode
[ 7090.504415] IPv6: ADDRCONF(NETDEV_CHANGE): vethb63994d: link becomes ready
[ 7090.504675] IPv6: ADDRCONF(NETDEV_CHANGE): veth640c74b: link becomes ready
[ 7090.504774] hassio: port 14(veth640c74b) entered blocking state
[ 7090.504781] hassio: port 14(veth640c74b) entered forwarding state
[ 7092.013170] hassio: port 14(veth640c74b) entered disabled state
[ 7092.013993] eth0: renamed from vethb63994d
[ 7092.089901] hassio: port 14(veth640c74b) entered blocking state
[ 7092.089916] hassio: port 14(veth640c74b) entered forwarding state
[ 7227.512708] hassio: port 14(veth640c74b) entered disabled state
[ 7227.513103] vethb63994d: renamed from eth0
[ 7227.697452] hassio: port 14(veth640c74b) entered disabled state
[ 7227.715582] device veth640c74b left promiscuous mode
[ 7227.715592] hassio: port 14(veth640c74b) entered disabled state
[ 7228.253032] hassio: port 14(veth01b45b8) entered blocking state
[ 7228.253042] hassio: port 14(veth01b45b8) entered disabled state
[ 7228.253555] device veth01b45b8 entered promiscuous mode
[ 7228.253651] hassio: port 14(veth01b45b8) entered blocking state
[ 7228.253658] hassio: port 14(veth01b45b8) entered forwarding state
[ 7228.280857] IPv6: ADDRCONF(NETDEV_CHANGE): veth01b45b8: link becomes ready
[ 7229.544136] hassio: port 14(veth01b45b8) entered disabled state
[ 7229.544787] eth0: renamed from veth7ec754f
[ 7229.605298] hassio: port 14(veth01b45b8) entered blocking state
[ 7229.605307] hassio: port 14(veth01b45b8) entered forwarding state
[ 7295.678339] hassio: port 14(veth01b45b8) entered disabled state
[ 7295.683172] veth7ec754f: renamed from eth0
[ 7295.822053] hassio: port 14(veth01b45b8) entered disabled state
[ 7295.841388] device veth01b45b8 left promiscuous mode
[ 7295.841400] hassio: port 14(veth01b45b8) entered disabled state
[ 7296.312759] hassio: port 14(veth26fd859) entered blocking state
[ 7296.312768] hassio: port 14(veth26fd859) entered disabled state
[ 7296.312993] device veth26fd859 entered promiscuous mode
[ 7296.313302] hassio: port 14(veth26fd859) entered blocking state
[ 7296.313310] hassio: port 14(veth26fd859) entered forwarding state
[ 7296.347666] IPv6: ADDRCONF(NETDEV_CHANGE): veth26fd859: link becomes ready
[ 7297.604642] hassio: port 14(veth26fd859) entered disabled state
[ 7297.605029] eth0: renamed from vethd991206
[ 7297.674868] hassio: port 14(veth26fd859) entered blocking state
[ 7297.674878] hassio: port 14(veth26fd859) entered forwarding state
[ 7321.371180] hassio: port 14(veth26fd859) entered disabled state
[ 7321.371543] vethd991206: renamed from eth0
[ 7321.519565] hassio: port 14(veth26fd859) entered disabled state
[ 7321.562891] device veth26fd859 left promiscuous mode
[ 7321.562908] hassio: port 14(veth26fd859) entered disabled state
[ 7356.393054] usb 1-1.3: USB disconnect, device number 8
[ 7356.393791] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
[ 7356.394086] cp210x 1-1.3:1.0: device disconnected
[ 7472.595120] usb 1-1.3: new full-speed USB device number 9 using xhci_hcd
[ 7472.730514] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[ 7472.730522] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 7472.730529] usb 1-1.3: Product: slae.sh cc2652rb stick - slaesh's iot stuff
[ 7472.730535] usb 1-1.3: Manufacturer: Silicon Labs
[ 7472.730541] usb 1-1.3: SerialNumber: 00_12_4B_00_21_CC_09_E4
[ 7472.736186] cp210x 1-1.3:1.0: cp210x converter detected
[ 7472.740538] usb 1-1.3: cp210x converter now attached to ttyUSB0
[ 7502.635391] sd 0:0:0:0: [sda] tag#9 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD
[ 7502.635401] sd 0:0:0:0: [sda] tag#9 CDB: opcode=0x2a 2a 00 00 df 87 10 00 00 08 00
[ 7502.775388] sd 0:0:0:0: [sda] tag#20 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD
[ 7502.775397] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x2a 2a 00 00 cd 46 a8 00 00 08 00
[ 7502.775410] sd 0:0:0:0: [sda] tag#11 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD
[ 7502.775416] sd 0:0:0:0: [sda] tag#11 CDB: opcode=0x2a 2a 00 03 4c 2d 68 00 00 08 00
[ 7502.775426] sd 0:0:0:0: [sda] tag#10 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD
[ 7502.775432] sd 0:0:0:0: [sda] tag#10 CDB: opcode=0x2a 2a 00 01 cc 9f 68 00 00 08 00
[ 7502.775442] sd 0:0:0:0: [sda] tag#8 uas_eh_abort_handler 0 uas-tag 5 inflight: CMD
[ 7502.775447] sd 0:0:0:0: [sda] tag#8 CDB: opcode=0x2a 2a 00 03 4c 32 38 00 00 08 00
[ 7502.965416] sd 0:0:0:0: [sda] tag#15 uas_eh_abort_handler 0 uas-tag 7 inflight: CMD
[ 7502.965461] sd 0:0:0:0: [sda] tag#15 CDB: opcode=0x2a 2a 00 00 f3 31 00 00 00 10 00
[ 7502.965497] sd 0:0:0:0: [sda] tag#14 uas_eh_abort_handler 0 uas-tag 6 inflight: CMD
[ 7502.965507] sd 0:0:0:0: [sda] tag#14 CDB: opcode=0x2a 2a 00 01 13 4e b8 00 00 08 00
[ 7502.965530] sd 0:0:0:0: [sda] tag#13 uas_eh_abort_handler 0 uas-tag 9 inflight: CMD
[ 7502.965540] sd 0:0:0:0: [sda] tag#13 CDB: opcode=0x2a 2a 00 00 61 24 10 00 00 20 00
[ 7502.965558] sd 0:0:0:0: [sda] tag#12 uas_eh_abort_handler 0 uas-tag 8 inflight: CMD
[ 7502.965564] sd 0:0:0:0: [sda] tag#12 CDB: opcode=0x2a 2a 00 00 6c 5b f8 00 00 10 00
[ 7503.225386] sd 0:0:0:0: [sda] tag#16 uas_eh_abort_handler 0 uas-tag 10 inflight: CMD
[ 7503.225395] sd 0:0:0:0: [sda] tag#16 CDB: opcode=0x2a 2a 00 01 54 a0 40 00 00 08 00
[ 7505.675439] sd 0:0:0:0: [sda] tag#17 uas_eh_abort_handler 0 uas-tag 11 inflight: CMD
[ 7505.675454] sd 0:0:0:0: [sda] tag#17 CDB: opcode=0x2a 2a 00 01 5c 65 30 00 00 08 00
[ 7507.515415] sd 0:0:0:0: [sda] tag#19 uas_eh_abort_handler 0 uas-tag 13 inflight: CMD
[ 7507.515424] sd 0:0:0:0: [sda] tag#19 CDB: opcode=0x2a 2a 00 00 18 bd 20 00 01 98 00
[ 7507.515437] sd 0:0:0:0: [sda] tag#18 uas_eh_abort_handler 0 uas-tag 12 inflight: CMD
[ 7507.515442] sd 0:0:0:0: [sda] tag#18 CDB: opcode=0x2a 2a 00 01 5f e6 70 00 00 08 00
[ 7507.555535] scsi host0: uas_eh_device_reset_handler start
[ 7507.706130] usb 2-2: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 7507.739593] scsi host0: uas_eh_device_reset_handler success
[ 7509.936851] hassio: port 14(veth59c21ee) entered blocking state
[ 7509.936860] hassio: port 14(veth59c21ee) entered disabled state
[ 7509.937172] device veth59c21ee entered promiscuous mode
[ 7510.006721] IPv6: ADDRCONF(NETDEV_CHANGE): veth00d7117: link becomes ready
[ 7510.006894] IPv6: ADDRCONF(NETDEV_CHANGE): veth59c21ee: link becomes ready
[ 7510.007135] hassio: port 14(veth59c21ee) entered blocking state
[ 7510.007143] hassio: port 14(veth59c21ee) entered forwarding state
[ 7511.567488] hassio: port 14(veth59c21ee) entered disabled state
[ 7511.570193] eth0: renamed from veth00d7117
[ 7511.616563] hassio: port 14(veth59c21ee) entered blocking state
[ 7511.616572] hassio: port 14(veth59c21ee) entered forwarding state
[ 7577.112462] hassio: port 14(veth59c21ee) entered disabled state
[ 7577.113143] veth00d7117: renamed from eth0
[ 7577.221590] IPv6: ADDRCONF(NETDEV_CHANGE): veth00d7117: link becomes ready
[ 7577.221769] hassio: port 14(veth59c21ee) entered blocking state
[ 7577.221775] hassio: port 14(veth59c21ee) entered forwarding state
[ 7577.244972] hassio: port 14(veth59c21ee) entered disabled state
[ 7577.277567] device veth59c21ee left promiscuous mode
[ 7577.277579] hassio: port 14(veth59c21ee) entered disabled state
[ 7577.938823] hassio: port 14(veth03078ec) entered blocking state
[ 7577.938831] hassio: port 14(veth03078ec) entered disabled state
[ 7577.939075] device veth03078ec entered promiscuous mode
[ 7577.939445] hassio: port 14(veth03078ec) entered blocking state
[ 7577.939453] hassio: port 14(veth03078ec) entered forwarding state
[ 7577.989991] IPv6: ADDRCONF(NETDEV_CHANGE): veth03078ec: link becomes ready
[ 7579.396841] hassio: port 14(veth03078ec) entered disabled state
[ 7579.399112] eth0: renamed from veth438ce03
[ 7579.477908] hassio: port 14(veth03078ec) entered blocking state
[ 7579.477952] hassio: port 14(veth03078ec) entered forwarding state
[ 7634.815100] hassio: port 14(veth03078ec) entered disabled state
[ 7634.815489] veth438ce03: renamed from eth0
[ 7634.926351] IPv6: ADDRCONF(NETDEV_CHANGE): veth438ce03: link becomes ready
[ 7634.926629] hassio: port 14(veth03078ec) entered blocking state
[ 7634.926639] hassio: port 14(veth03078ec) entered forwarding state
[ 7634.965536] hassio: port 14(veth03078ec) entered disabled state
[ 7634.995557] device veth03078ec left promiscuous mode
[ 7634.995580] hassio: port 14(veth03078ec) entered disabled state
[ 7635.544158] hassio: port 14(veth55522bb) entered blocking state
[ 7635.544166] hassio: port 14(veth55522bb) entered disabled state
[ 7635.545555] device veth55522bb entered promiscuous mode
[ 7635.546166] hassio: port 14(veth55522bb) entered blocking state
[ 7635.546174] hassio: port 14(veth55522bb) entered forwarding state
[ 7635.600238] IPv6: ADDRCONF(NETDEV_CHANGE): veth55522bb: link becomes ready
[ 7636.787770] hassio: port 14(veth55522bb) entered disabled state
[ 7636.796806] eth0: renamed from veth8e60969
[ 7636.848334] hassio: port 14(veth55522bb) entered blocking state
[ 7636.848343] hassio: port 14(veth55522bb) entered forwarding state
[ 7669.785515] hassio: port 14(veth55522bb) entered disabled state
[ 7669.785818] veth8e60969: renamed from eth0
[ 7669.918713] hassio: port 14(veth55522bb) entered disabled state
[ 7669.951865] device veth55522bb left promiscuous mode
[ 7669.951883] hassio: port 14(veth55522bb) entered disabled state
[ 7686.031591] usb 1-1.3: USB disconnect, device number 9
[ 7686.032272] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
[ 7686.032467] cp210x 1-1.3:1.0: device disconnected
[ 7707.047231] usb 1-1.3: new full-speed USB device number 10 using xhci_hcd
[ 7707.182661] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[ 7707.182671] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 7707.182678] usb 1-1.3: Product: slae.sh cc2652rb stick - slaesh's iot stuff
[ 7707.182684] usb 1-1.3: Manufacturer: Silicon Labs
[ 7707.182690] usb 1-1.3: SerialNumber: 00_12_4B_00_21_CC_09_E4
[ 7707.186323] cp210x 1-1.3:1.0: cp210x converter detected
[ 7707.192531] usb 1-1.3: cp210x converter now attached to ttyUSB0
[ 7736.957479] sd 0:0:0:0: [sda] tag#10 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD
[ 7736.957488] sd 0:0:0:0: [sda] tag#10 CDB: opcode=0x2a 2a 00 01 54 a4 80 00 00 10 00
[ 7737.237527] sd 0:0:0:0: [sda] tag#23 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD
[ 7737.237542] sd 0:0:0:0: [sda] tag#23 CDB: opcode=0x2a 2a 00 01 cc 9f 70 00 00 08 00
[ 7737.237564] sd 0:0:0:0: [sda] tag#13 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD
[ 7737.237575] sd 0:0:0:0: [sda] tag#13 CDB: opcode=0x2a 2a 00 00 cd 47 d8 00 00 08 00
[ 7737.237593] sd 0:0:0:0: [sda] tag#11 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD
[ 7737.237603] sd 0:0:0:0: [sda] tag#11 CDB: opcode=0x2a 2a 00 03 4c 2d 68 00 00 08 00
[ 7737.237622] sd 0:0:0:0: [sda] tag#8 uas_eh_abort_handler 0 uas-tag 5 inflight: CMD
[ 7737.237631] sd 0:0:0:0: [sda] tag#8 CDB: opcode=0x2a 2a 00 03 4c 32 38 00 00 08 00
[ 7737.547504] sd 0:0:0:0: [sda] tag#20 uas_eh_abort_handler 0 uas-tag 6 inflight: CMD
[ 7737.547513] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x2a 2a 00 01 5f ea 20 00 00 30 00
[ 7738.317510] sd 0:0:0:0: [sda] tag#14 uas_eh_abort_handler 0 uas-tag 7 inflight: CMD IN
[ 7738.317519] sd 0:0:0:0: [sda] tag#14 CDB: opcode=0x28 28 00 00 89 23 b0 00 00 08 00
[ 7738.937502] sd 0:0:0:0: [sda] tag#15 uas_eh_abort_handler 0 uas-tag 8 inflight: CMD
[ 7738.937511] sd 0:0:0:0: [sda] tag#15 CDB: opcode=0x2a 2a 00 00 55 7e c0 00 00 08 00
[ 7742.647557] sd 0:0:0:0: [sda] tag#12 uas_eh_abort_handler 0 uas-tag 9 inflight: CMD
[ 7742.647573] sd 0:0:0:0: [sda] tag#12 CDB: opcode=0x2a 2a 00 00 18 dc c8 00 01 98 00
[ 7750.957603] sd 0:0:0:0: [sda] tag#16 uas_eh_abort_handler 0 uas-tag 11 inflight: CMD
[ 7750.957611] sd 0:0:0:0: [sda] tag#16 CDB: opcode=0x2a 2a 00 01 38 db e8 00 00 08 00
[ 7750.957623] sd 0:0:0:0: [sda] tag#9 uas_eh_abort_handler 0 uas-tag 10 inflight: CMD
[ 7750.957629] sd 0:0:0:0: [sda] tag#9 CDB: opcode=0x2a 2a 00 01 bd e7 88 00 00 08 00
[ 7761.197692] sd 0:0:0:0: [sda] tag#28 uas_eh_abort_handler 0 uas-tag 21 inflight: CMD
[ 7761.197701] sd 0:0:0:0: [sda] tag#28 CDB: opcode=0x2a 2a 00 00 48 22 98 00 00 08 00
[ 7761.197714] sd 0:0:0:0: [sda] tag#27 uas_eh_abort_handler 0 uas-tag 20 inflight: CMD
[ 7761.197719] sd 0:0:0:0: [sda] tag#27 CDB: opcode=0x2a 2a 00 00 48 21 00 00 00 08 00
[ 7761.197730] sd 0:0:0:0: [sda] tag#26 uas_eh_abort_handler 0 uas-tag 19 inflight: CMD
[ 7761.197735] sd 0:0:0:0: [sda] tag#26 CDB: opcode=0x2a 2a 00 00 48 20 80 00 00 08 00
[ 7761.197745] sd 0:0:0:0: [sda] tag#25 uas_eh_abort_handler 0 uas-tag 18 inflight: CMD
[ 7761.197750] sd 0:0:0:0: [sda] tag#25 CDB: opcode=0x2a 2a 00 00 48 20 48 00 00 08 00
[ 7761.197760] sd 0:0:0:0: [sda] tag#24 uas_eh_abort_handler 0 uas-tag 17 inflight: CMD
[ 7761.197765] sd 0:0:0:0: [sda] tag#24 CDB: opcode=0x2a 2a 00 00 48 20 28 00 00 10 00
[ 7761.197774] sd 0:0:0:0: [sda] tag#22 uas_eh_abort_handler 0 uas-tag 16 inflight: CMD
[ 7761.197779] sd 0:0:0:0: [sda] tag#22 CDB: opcode=0x2a 2a 00 00 48 20 18 00 00 08 00
[ 7761.197789] sd 0:0:0:0: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 15 inflight: CMD
[ 7761.197794] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x2a 2a 00 00 48 20 00 00 00 08 00
[ 7761.197804] sd 0:0:0:0: [sda] tag#19 uas_eh_abort_handler 0 uas-tag 14 inflight: CMD
[ 7761.197809] sd 0:0:0:0: [sda] tag#19 CDB: opcode=0x2a 2a 00 00 0c 6e 38 00 00 08 00
[ 7761.197818] sd 0:0:0:0: [sda] tag#18 uas_eh_abort_handler 0 uas-tag 13 inflight: CMD
[ 7761.197823] sd 0:0:0:0: [sda] tag#18 CDB: opcode=0x2a 2a 00 00 0c 6d b8 00 00 08 00
[ 7761.197833] sd 0:0:0:0: [sda] tag#17 uas_eh_abort_handler 0 uas-tag 12 inflight: CMD
[ 7761.197838] sd 0:0:0:0: [sda] tag#17 CDB: opcode=0x2a 2a 00 00 08 23 40 00 00 08 00
[ 7761.197847] sd 0:0:0:0: [sda] tag#7 uas_eh_abort_handler 0 uas-tag 29 inflight: CMD
[ 7761.197853] sd 0:0:0:0: [sda] tag#7 CDB: opcode=0x2a 2a 00 00 49 4a 78 00 00 08 00
[ 7761.197862] sd 0:0:0:0: [sda] tag#6 uas_eh_abort_handler 0 uas-tag 28 inflight: CMD
[ 7761.197868] sd 0:0:0:0: [sda] tag#6 CDB: opcode=0x2a 2a 00 00 49 22 28 00 00 08 00
[ 7761.197877] sd 0:0:0:0: [sda] tag#5 uas_eh_abort_handler 0 uas-tag 27 inflight: CMD
[ 7761.197882] sd 0:0:0:0: [sda] tag#5 CDB: opcode=0x2a 2a 00 00 48 2d 68 00 00 08 00
[ 7761.197892] sd 0:0:0:0: [sda] tag#4 uas_eh_abort_handler 0 uas-tag 26 inflight: CMD
[ 7761.197897] sd 0:0:0:0: [sda] tag#4 CDB: opcode=0x2a 2a 00 00 48 2a 88 00 00 08 00
[ 7761.197906] sd 0:0:0:0: [sda] tag#3 uas_eh_abort_handler 0 uas-tag 25 inflight: CMD
[ 7761.197911] sd 0:0:0:0: [sda] tag#3 CDB: opcode=0x2a 2a 00 00 48 29 d8 00 00 08 00
[ 7761.197921] sd 0:0:0:0: [sda] tag#2 uas_eh_abort_handler 0 uas-tag 24 inflight: CMD
[ 7761.197926] sd 0:0:0:0: [sda] tag#2 CDB: opcode=0x2a 2a 00 00 48 29 88 00 00 08 00
[ 7761.197935] sd 0:0:0:0: [sda] tag#1 uas_eh_abort_handler 0 uas-tag 23 inflight: CMD
[ 7761.197940] sd 0:0:0:0: [sda] tag#1 CDB: opcode=0x2a 2a 00 00 48 29 70 00 00 08 00
[ 7761.197950] sd 0:0:0:0: [sda] tag#0 uas_eh_abort_handler 0 uas-tag 22 inflight: CMD
[ 7761.197955] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x2a 2a 00 00 48 24 10 00 00 10 00
[ 7761.287722] scsi host0: uas_eh_device_reset_handler start
[ 7761.448409] usb 2-2: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 7761.481710] scsi host0: uas_eh_device_reset_handler success
[ 7764.777291] hassio: port 14(veth6bcccb7) entered blocking state
[ 7764.777299] hassio: port 14(veth6bcccb7) entered disabled state
[ 7764.777657] device veth6bcccb7 entered promiscuous mode
[ 7764.833220] IPv6: ADDRCONF(NETDEV_CHANGE): veth70b7ffd: link becomes ready
[ 7764.833576] IPv6: ADDRCONF(NETDEV_CHANGE): veth6bcccb7: link becomes ready
[ 7764.833691] hassio: port 14(veth6bcccb7) entered blocking state
[ 7764.833700] hassio: port 14(veth6bcccb7) entered forwarding state
[ 7766.432806] eth0: renamed from veth70b7ffd
[ 7766.468511] hassio: port 14(veth6bcccb7) entered disabled state
[ 7766.482454] hassio: port 14(veth6bcccb7) entered blocking state
[ 7766.482505] hassio: port 14(veth6bcccb7) entered forwarding state
[ 8015.072024] hassio: port 14(veth6bcccb7) entered disabled state
[ 8015.072343] veth70b7ffd: renamed from eth0
[ 8015.258172] hassio: port 14(veth6bcccb7) entered disabled state
[ 8015.277406] device veth6bcccb7 left promiscuous mode
[ 8015.277420] hassio: port 14(veth6bcccb7) entered disabled state
[ 8015.844690] hassio: port 14(veth0a4c4db) entered blocking state
[ 8015.844698] hassio: port 14(veth0a4c4db) entered disabled state
[ 8015.844924] device veth0a4c4db entered promiscuous mode
[ 8015.845207] hassio: port 14(veth0a4c4db) entered blocking state
[ 8015.845214] hassio: port 14(veth0a4c4db) entered forwarding state
[ 8015.880843] IPv6: ADDRCONF(NETDEV_CHANGE): veth0a4c4db: link becomes ready
[ 8017.070566] hassio: port 14(veth0a4c4db) entered disabled state
[ 8017.071975] eth0: renamed from veth17bfca5
[ 8017.142333] hassio: port 14(veth0a4c4db) entered blocking state
[ 8017.142342] hassio: port 14(veth0a4c4db) entered forwarding state
bash-5.0# cat /proc/uptime
79962.78 254697.07

There's no current log message inside the dmesg, however inside the addon log I see a few minutes ago one.

Koenkk commented 4 years ago

@golddragon007 looks that the stick is disconnected:

[ 7356.393791] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
[ 7356.394086] cp210x 1-1.3:1.0: device disconnected
[ 7472.595120] usb 1-1.3: new full-speed USB device number 9 using xhci_hcd
[ 7472.730514] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[ 7472.730522] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 7472.730529] usb 1-1.3: Product: slae.sh cc2652rb stick - slaesh's iot stuff
[ 7472.730535] usb 1-1.3: Manufacturer: Silicon Labs
[ 7472.730541] usb 1-1.3: SerialNumber: 00_12_4B_00_21_CC_09_E4
[ 7472.736186] cp210x 1-1.3:1.0: cp210x converter detected
[ 7472.740538] usb 1-1.3: cp210x converter now attached to ttyUSB0

I think this happens because the SSD draws to much current, leading to some instability on the USB bus. Probably not fixable from Zigbee2MQTT itself. @slaesh maybe you have a solution for this issue?

golddragon007 commented 4 years ago

@golddragon007 looks that the stick is disconnected:

[ 7356.393791] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
[ 7356.394086] cp210x 1-1.3:1.0: device disconnected
[ 7472.595120] usb 1-1.3: new full-speed USB device number 9 using xhci_hcd
[ 7472.730514] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[ 7472.730522] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 7472.730529] usb 1-1.3: Product: slae.sh cc2652rb stick - slaesh's iot stuff
[ 7472.730535] usb 1-1.3: Manufacturer: Silicon Labs
[ 7472.730541] usb 1-1.3: SerialNumber: 00_12_4B_00_21_CC_09_E4
[ 7472.736186] cp210x 1-1.3:1.0: cp210x converter detected
[ 7472.740538] usb 1-1.3: cp210x converter now attached to ttyUSB0

I think this happens because the SSD draws to much current, leading to some instability on the USB bus. Probably not fixable from Zigbee2MQTT itself. @slaesh maybe you have a solution for this issue?

No, that happened when I physically removed the stick. It was 20 hours ago. After that I have no new disconnections logged, and I still get messages in the HA add-on log.

mrucki commented 4 years ago

@Koenkk I run again zigbee2mqtt in docker but now with DEBUG=*

Then I save all logs to file and then removed logs related to mqtt:

less zigbee2mqtt-1.log | grep -v "mmqttjs:client" | grep -v "mqtt-packet" > zigbee2mqtt-no-mqtt.log

Please find zigbee2mqtt-no-mqtt.log attached - it has zigbee-herdsman and serialport lib debug logs zigbee2mqtt-no-mqtt.log

plus dmesg there are some docker stuff as I played with it in meantime

pi@raspberrypi:~ $ dmesg 
[78033.006015] docker0: port 1(veth2a3f56a) entered disabled state
[78033.006293] vethd0de499: renamed from eth0
[78033.166572] docker0: port 1(veth2a3f56a) entered disabled state
[78033.184958] device veth2a3f56a left promiscuous mode
[78033.184970] docker0: port 1(veth2a3f56a) entered disabled state
[78033.354235] docker0: port 1(veth1af357b) entered blocking state
[78033.354251] docker0: port 1(veth1af357b) entered disabled state
[78033.354754] device veth1af357b entered promiscuous mode
[78033.355363] docker0: port 1(veth1af357b) entered blocking state
[78033.355374] docker0: port 1(veth1af357b) entered forwarding state
[78033.473129] IPv6: ADDRCONF(NETDEV_CHANGE): veth1af357b: link becomes ready
[78036.330303] docker0: port 1(veth1af357b) entered disabled state
[78036.332327] eth0: renamed from veth52b7069
[78036.380810] docker0: port 1(veth1af357b) entered blocking state
[78036.380822] docker0: port 1(veth1af357b) entered forwarding state
[86770.162485] docker0: port 1(veth1af357b) entered disabled state
[86770.162904] veth52b7069: renamed from eth0
[86770.288459] docker0: port 1(veth1af357b) entered disabled state
[86770.303779] device veth1af357b left promiscuous mode
[86770.303791] docker0: port 1(veth1af357b) entered disabled state
[86770.502353] docker0: port 1(veth641498f) entered blocking state
[86770.502368] docker0: port 1(veth641498f) entered disabled state
[86770.502653] device veth641498f entered promiscuous mode
[86770.502940] docker0: port 1(veth641498f) entered blocking state
[86770.502948] docker0: port 1(veth641498f) entered forwarding state
[86770.615897] IPv6: ADDRCONF(NETDEV_CHANGE): veth641498f: link becomes ready
[86771.320766] docker0: port 1(veth641498f) entered disabled state
[86771.321415] eth0: renamed from veth68c04df
[86771.371231] docker0: port 1(veth641498f) entered blocking state
[86771.371243] docker0: port 1(veth641498f) entered forwarding state
mrucki commented 4 years ago

@Koenkk please note that this command:

less zigbee2mqtt-1.log | grep -v "mmqttjs:client" | grep -v "mqtt-packet" | grep "serialport/bindings" | grep "read"

shows last log from 19:39 where first zigbee2mqtt timeout occured at 19:42

Looks like there is an issue with reading data from serial port... but restarting zigbee2mqtt fixes it, no need to reconnect hardware

golddragon007 commented 4 years ago

@Koenkk For me, after I've restarted the add-on with herdsman debug, I did not get any more error, but still, nothing wants to connect to the controller and I don't know why, I tried to repair it, but that's also doesn't help. dmesg after restart:

[80512.212110] hassio: port 14(veth0a4c4db) entered disabled state
[80512.212471] veth17bfca5: renamed from eth0
[80512.336085] hassio: port 14(veth0a4c4db) entered disabled state
[80512.352997] device veth0a4c4db left promiscuous mode
[80512.353009] hassio: port 14(veth0a4c4db) entered disabled state
[80512.835365] hassio: port 14(veth274155e) entered blocking state
[80512.835373] hassio: port 14(veth274155e) entered disabled state
[80512.835648] device veth274155e entered promiscuous mode
[80512.836046] hassio: port 14(veth274155e) entered blocking state
[80512.836053] hassio: port 14(veth274155e) entered forwarding state
[80512.881920] IPv6: ADDRCONF(NETDEV_CHANGE): veth274155e: link becomes ready
[80514.105124] hassio: port 14(veth274155e) entered disabled state
[80514.105710] eth0: renamed from veth0d9a584
[80514.185625] hassio: port 14(veth274155e) entered blocking state
[80514.185634] hassio: port 14(veth274155e) entered forwarding state

Docker log:

Zigbee2MQTT:debug 2020-10-03 13:13:05: Saving state to file /share/zigbee2mqtt/state.json
2020-10-03T11:14:36.395Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,28,68,129,0,0,4,11,19,201,1,1,0,66,0,49,51,195,0,0,8,8,14,10,5,5,33,18,9,19,201,29,118]
2020-10-03T11:14:36.395Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,4,11,19,201,1,1,0,66,0,49,51,195,0,0,8,8,14,10,5,5,33,18,9,19,201,29,118]
2020-10-03T11:14:36.395Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,4,11,19,201,1,1,0,66,0,49,51,195,0,0,8,8,14,10,5,5,33,18,9,19,201,29] - 118
2020-10-03T11:14:36.395Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":2820,"srcaddr":51475,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":66,"securityuse":0,"timestamp":12792625,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[8,14,10,5,5,33,18,9]}}
2020-10-03T11:14:36.399Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":14,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":1285,"dataType":33,"attrData":2322}]},"address":51475,"endpoint":1,"linkquality":66,"groupID":0}'
2020-10-03T11:14:36.399Z zigbee-herdsman:controller:log 'zcl' data is from unknown device with address '51475', skipping...
2020-10-03T11:14:36.399Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:14:57.391Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:14:57.391Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:14:57.391Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:14:57.399Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:14:57.399Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:14:57.399Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:14:57.399Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:14:57.399Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:14:57.400Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":78,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,79,2,11,254,0]}}
2020-10-03T11:14:57.401Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,78,0,30,6,0,25,79,2,11,254,0,234]
2020-10-03T11:14:57.401Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:14:57.401Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:14:57.401Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:14:57.402Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:14:57.402Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:14:57.409Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:14:57.409Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:14:57.409Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:14:57.410Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:14:57.410Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:14:57.433Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,78,154]
2020-10-03T11:14:57.433Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,78,154]
2020-10-03T11:14:57.433Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,78] - 154
2020-10-03T11:14:57.436Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":78}
2020-10-03T11:14:57.436Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Zigbee2MQTT:debug 2020-10-03 13:18:05: Saving state to file /share/zigbee2mqtt/state.json
2020-10-03T11:18:17.392Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:18:17.393Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:18:17.393Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:18:17.401Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:18:17.401Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:18:17.401Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:18:17.401Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:18:17.401Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:18:17.403Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":79,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,80,2,11,254,0]}}
2020-10-03T11:18:17.403Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,79,0,30,6,0,25,80,2,11,254,0,244]
2020-10-03T11:18:17.405Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:18:17.405Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:18:17.406Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:18:17.406Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:18:17.406Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:18:17.412Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:18:17.412Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:18:17.412Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:18:17.413Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:18:17.413Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:18:17.444Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,79,155]
2020-10-03T11:18:17.444Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,79,155]
2020-10-03T11:18:17.444Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,79] - 155
2020-10-03T11:18:17.444Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":79}
2020-10-03T11:18:17.445Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:19:50.518Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,13,69,193,91,233,91,233,120,2,238,254,255,215,107,8,142,38]
2020-10-03T11:19:50.518Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,13,69,193,91,233,91,233,120,2,238,254,255,215,107,8,142,38]
2020-10-03T11:19:50.518Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 13 - 2 - 5 - 193 - [91,233,91,233,120,2,238,254,255,215,107,8,142] - 38
2020-10-03T11:19:50.519Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - endDeviceAnnceInd - {"srcaddr":59739,"nwkaddr":59739,"ieeeaddr":"0x086bd7fffeee0278","capabilities":142}
2020-10-03T11:19:50.519Z zigbee-herdsman:controller:log Device announce '0x086bd7fffeee0278'
2020-10-03T11:19:50.519Z zigbee-herdsman:controller:log Device announce is from unknown device '0x086bd7fffeee0278'
2020-10-03T11:19:50.519Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:19:53.602Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,13,69,193,91,233,91,233,120,2,238,254,255,215,107,8,142,38]
2020-10-03T11:19:53.602Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,13,69,193,91,233,91,233,120,2,238,254,255,215,107,8,142,38]
2020-10-03T11:19:53.602Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 13 - 2 - 5 - 193 - [91,233,91,233,120,2,238,254,255,215,107,8,142] - 38
2020-10-03T11:19:53.602Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - endDeviceAnnceInd - {"srcaddr":59739,"nwkaddr":59739,"ieeeaddr":"0x086bd7fffeee0278","capabilities":142}
2020-10-03T11:19:53.602Z zigbee-herdsman:controller:log Device announce '0x086bd7fffeee0278'
2020-10-03T11:19:53.602Z zigbee-herdsman:controller:log Device announce is from unknown device '0x086bd7fffeee0278'
2020-10-03T11:19:53.602Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:20:48.223Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,13,69,193,81,10,81,10,29,3,238,254,255,215,107,8,142,66]
2020-10-03T11:20:48.224Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,13,69,193,81,10,81,10,29,3,238,254,255,215,107,8,142,66]
2020-10-03T11:20:48.224Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 13 - 2 - 5 - 193 - [81,10,81,10,29,3,238,254,255,215,107,8,142] - 66
2020-10-03T11:20:48.224Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - endDeviceAnnceInd - {"srcaddr":2641,"nwkaddr":2641,"ieeeaddr":"0x086bd7fffeee031d","capabilities":142}
2020-10-03T11:20:48.224Z zigbee-herdsman:controller:log Device announce '0x086bd7fffeee031d'
2020-10-03T11:20:48.224Z zigbee-herdsman:controller:log Device announce is from unknown device '0x086bd7fffeee031d'
2020-10-03T11:20:48.224Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:21:37.393Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:21:37.393Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:21:37.394Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:21:37.421Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:21:37.422Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:21:37.422Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:21:37.422Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:21:37.422Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:21:37.424Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":80,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,81,2,11,254,0]}}
2020-10-03T11:21:37.424Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,80,0,30,6,0,25,81,2,11,254,0,234]
2020-10-03T11:21:37.426Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:21:37.426Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:21:37.426Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:21:37.426Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:21:37.426Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:21:37.474Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:21:37.474Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:21:37.474Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:21:37.474Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:21:37.474Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:21:37.475Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,80,132]
2020-10-03T11:21:37.475Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,80,132]
2020-10-03T11:21:37.475Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,80] - 132
2020-10-03T11:21:37.475Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":80}
2020-10-03T11:21:37.475Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:22:16.608Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,13,69,193,62,164,62,164,125,254,237,254,255,215,107,8,142,220]
2020-10-03T11:22:16.608Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,13,69,193,62,164,62,164,125,254,237,254,255,215,107,8,142,220]
2020-10-03T11:22:16.608Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 13 - 2 - 5 - 193 - [62,164,62,164,125,254,237,254,255,215,107,8,142] - 220
2020-10-03T11:22:16.608Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - endDeviceAnnceInd - {"srcaddr":42046,"nwkaddr":42046,"ieeeaddr":"0x086bd7fffeedfe7d","capabilities":142}
2020-10-03T11:22:16.608Z zigbee-herdsman:controller:log Device announce '0x086bd7fffeedfe7d'
2020-10-03T11:22:16.608Z zigbee-herdsman:controller:log Device announce is from unknown device '0x086bd7fffeedfe7d'
2020-10-03T11:22:16.608Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Zigbee2MQTT:debug 2020-10-03 13:23:05: Saving state to file /share/zigbee2mqtt/state.json
2020-10-03T11:24:57.394Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:24:57.394Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:24:57.394Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:24:57.407Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:24:57.407Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:24:57.407Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:24:57.407Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:24:57.407Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:24:57.410Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":81,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,82,2,11,254,0]}}
2020-10-03T11:24:57.410Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,81,0,30,6,0,25,82,2,11,254,0,232]
2020-10-03T11:24:57.411Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:24:57.411Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:24:57.411Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:24:57.411Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:24:57.411Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:24:57.431Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:24:57.431Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:24:57.431Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:24:57.431Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:24:57.432Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:24:57.458Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,81,133]
2020-10-03T11:24:57.459Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,81,133]
2020-10-03T11:24:57.459Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,81] - 133
2020-10-03T11:24:57.459Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":81}
2020-10-03T11:24:57.459Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:26:23.416Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,13,69,193,242,217,242,217,80,246,237,254,255,215,107,8,142,249]
2020-10-03T11:26:23.417Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,13,69,193,242,217,242,217,80,246,237,254,255,215,107,8,142,249]
2020-10-03T11:26:23.417Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 13 - 2 - 5 - 193 - [242,217,242,217,80,246,237,254,255,215,107,8,142] - 249
2020-10-03T11:26:23.417Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - endDeviceAnnceInd - {"srcaddr":55794,"nwkaddr":55794,"ieeeaddr":"0x086bd7fffeedf650","capabilities":142}
2020-10-03T11:26:23.417Z zigbee-herdsman:controller:log Device announce '0x086bd7fffeedf650'
2020-10-03T11:26:23.417Z zigbee-herdsman:controller:log Device announce is from unknown device '0x086bd7fffeedf650'
2020-10-03T11:26:23.418Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:26:26.429Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,13,69,193,242,217,242,217,80,246,237,254,255,215,107,8,142,249]
2020-10-03T11:26:26.429Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,13,69,193,242,217,242,217,80,246,237,254,255,215,107,8,142,249]
2020-10-03T11:26:26.429Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 13 - 2 - 5 - 193 - [242,217,242,217,80,246,237,254,255,215,107,8,142] - 249
2020-10-03T11:26:26.430Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - endDeviceAnnceInd - {"srcaddr":55794,"nwkaddr":55794,"ieeeaddr":"0x086bd7fffeedf650","capabilities":142}
2020-10-03T11:26:26.430Z zigbee-herdsman:controller:log Device announce '0x086bd7fffeedf650'
2020-10-03T11:26:26.430Z zigbee-herdsman:controller:log Device announce is from unknown device '0x086bd7fffeedf650'
2020-10-03T11:26:26.430Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Zigbee2MQTT:debug 2020-10-03 13:28:05: Saving state to file /share/zigbee2mqtt/state.json
2020-10-03T11:28:17.394Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:28:17.395Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:28:17.395Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:28:17.949Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:28:17.950Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:28:17.950Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:28:17.950Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:28:17.950Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:28:17.956Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":82,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,83,2,11,254,0]}}
2020-10-03T11:28:17.956Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,82,0,30,6,0,25,83,2,11,254,0,234]
2020-10-03T11:28:17.957Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:28:17.957Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:28:17.957Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:28:17.958Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:28:17.963Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:28:17.970Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:28:17.970Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:28:17.970Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:28:17.970Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:28:17.970Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:28:17.978Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,82,134]
2020-10-03T11:28:17.978Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,82,134]
2020-10-03T11:28:17.978Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,82] - 134
2020-10-03T11:28:17.980Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":82}
2020-10-03T11:28:17.980Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:31:13.646Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,13,69,193,242,217,242,217,80,246,237,254,255,215,107,8,142,249]
2020-10-03T11:31:13.646Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,13,69,193,242,217,242,217,80,246,237,254,255,215,107,8,142,249]
2020-10-03T11:31:13.646Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 13 - 2 - 5 - 193 - [242,217,242,217,80,246,237,254,255,215,107,8,142] - 249
2020-10-03T11:31:13.646Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - endDeviceAnnceInd - {"srcaddr":55794,"nwkaddr":55794,"ieeeaddr":"0x086bd7fffeedf650","capabilities":142}
2020-10-03T11:31:13.646Z zigbee-herdsman:controller:log Device announce '0x086bd7fffeedf650'
2020-10-03T11:31:13.646Z zigbee-herdsman:controller:log Device announce is from unknown device '0x086bd7fffeedf650'
2020-10-03T11:31:13.646Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:31:37.395Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:31:37.395Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:31:37.395Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:31:37.407Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:31:37.408Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:31:37.408Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:31:37.408Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:31:37.408Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:31:37.409Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":83,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,84,2,11,254,0]}}
2020-10-03T11:31:37.409Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,83,0,30,6,0,25,84,2,11,254,0,236]
2020-10-03T11:31:37.410Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:31:37.410Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:31:37.410Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:31:37.410Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:31:37.411Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:31:37.422Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:31:37.423Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:31:37.423Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:31:37.423Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:31:37.423Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:31:37.653Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,83,135]
2020-10-03T11:31:37.653Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,83,135]
2020-10-03T11:31:37.653Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,83] - 135
2020-10-03T11:31:37.654Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":83}
2020-10-03T11:31:37.654Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Zigbee2MQTT:debug 2020-10-03 13:33:05: Saving state to file /share/zigbee2mqtt/state.json
2020-10-03T11:34:57.396Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:34:57.396Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:34:57.396Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:34:57.455Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:34:57.455Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:34:57.455Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:34:57.455Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:34:57.455Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:34:57.456Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":84,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,85,2,11,254,0]}}
2020-10-03T11:34:57.456Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,84,0,30,6,0,25,85,2,11,254,0,234]
2020-10-03T11:34:57.457Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:34:57.457Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:34:57.457Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:34:57.457Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:34:57.457Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:34:57.470Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:34:57.470Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:34:57.470Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:34:57.470Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:34:57.471Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:34:57.499Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,84,128]
2020-10-03T11:34:57.499Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,84,128]
2020-10-03T11:34:57.499Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,84] - 128
2020-10-03T11:34:57.499Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":84}
2020-10-03T11:34:57.499Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Zigbee2MQTT:debug 2020-10-03 13:38:05: Saving state to file /share/zigbee2mqtt/state.json
2020-10-03T11:38:17.397Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:38:17.398Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:38:17.398Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:38:17.448Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:38:17.448Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:38:17.448Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:38:17.448Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:38:17.449Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:38:17.450Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":85,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,86,2,11,254,0]}}
2020-10-03T11:38:17.450Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,85,0,30,6,0,25,86,2,11,254,0,232]
2020-10-03T11:38:17.451Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:38:17.451Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:38:17.451Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:38:17.451Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:38:17.451Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:38:17.472Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:38:17.472Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:38:17.472Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:38:17.475Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:38:17.475Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:38:17.499Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,85,129]
2020-10-03T11:38:17.499Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,85,129]
2020-10-03T11:38:17.500Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,85] - 129
2020-10-03T11:38:17.500Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":85}
2020-10-03T11:38:17.500Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:41:37.398Z zigbee-herdsman:controller:log Permit joining
2020-10-03T11:41:37.398Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0}
2020-10-03T11:41:37.398Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228]
2020-10-03T11:41:37.419Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82]
2020-10-03T11:41:37.419Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82]
2020-10-03T11:41:37.419Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82
2020-10-03T11:41:37.419Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0}
2020-10-03T11:41:37.419Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:41:37.420Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":86,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,87,2,11,254,0]}}
2020-10-03T11:41:37.420Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,86,0,30,6,0,25,87,2,11,254,0,234]
2020-10-03T11:41:37.421Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]
2020-10-03T11:41:37.421Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240]
2020-10-03T11:41:37.421Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240
2020-10-03T11:41:37.421Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0}
2020-10-03T11:41:37.421Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:41:37.438Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103]
2020-10-03T11:41:37.438Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103]
2020-10-03T11:41:37.438Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103
2020-10-03T11:41:37.438Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0}
2020-10-03T11:41:37.438Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
2020-10-03T11:41:37.457Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,225,242,86,130]
2020-10-03T11:41:37.457Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,225,242,86,130]
2020-10-03T11:41:37.457Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [225,242,86] - 130
2020-10-03T11:41:37.458Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":225,"endpoint":242,"transid":86}
2020-10-03T11:41:37.458Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
mrucki commented 4 years ago

@Koenkk please look what else I noticed:

2020-10-03T13:24:59.601685393Z   serialport/bindings/unixRead Starting read +5ms
2020-10-03T13:24:59.603077207Z   serialport/bindings/unixRead read error [Error: EAGAIN: resource temporarily unavailable, read] {
2020-10-03T13:24:59.603741422Z   serialport/bindings/unixRead waiting for readable because of code: EAGAIN +1ms
2020-10-03T13:24:59.604015118Z   serialport/bindings/poller Polling for "readable" +14ms
2020-10-03T13:28:19.588261306Z   serialport/stream _write 10 bytes of data +3m
2020-10-03T13:28:19.588339899Z   serialport/binding-abstract write 10 bytes +3m
2020-10-03T13:28:19.589390882Z   serialport/bindings/unixWrite Starting write 10 bytes offset 0 bytesToWrite 10 +3m
2020-10-03T13:28:19.590786030Z   serialport/bindings/unixWrite write returned: wrote 10 bytes +1ms
2020-10-03T13:28:19.591875658Z   serialport/bindings/unixWrite Finished writing 10 bytes +1ms
2020-10-03T13:28:19.592046959Z   serialport/stream binding.write write finished +4ms

and finally after 3 minutes:

2020-10-03T13:28:19.601888773Z   serialport/bindings/poller received "readable" +3m

received readable after 3 minutes? Does it mean that if during that time zigbee-herdsman tried to send any data (permitJoin request or dataRequestExt, etc) it would crash due to timeout 6000ms ?

MORD0R commented 4 years ago 
* CC2531 is connected with extension cable

* CC2531 is the only usb device connected

* I'm using zigbee2mqtt as a systemctl service - I rebooted Raspberry Pi, stopped zigbee2mqtt and the log above occured during dmesg

* I'm using power supply with output 5v and 3.1 A so should be enough

Ah, and one thing I missed in my comments is that my raspberry pi + zigbee2mqtt + openhab has worked fine for last year until few days ago I upgraded my Raspbian from stretch to buster version - perhaps this causes usb instability? Are there any known issues with Raspbian Buster ?

I have almost the same software installed and i do also have this error UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms. But the problem started afther i upgraded zigbee2mqtt. Maybe it has something to do with the zram. Openhabian added zram as default. https://community.openhab.org/t/zram-status/80996

mrucki commented 4 years ago

@MORD0R but I checked previous versions of zigbee2mqtt (previous docker tags and same issue) and I don't have Openhabian but Raspbian Buster. Currently OpenHab is running as a docker image and cannot see any zram installed in my OS

Koenkk commented 4 years ago

@mrucki reading https://github.com/serialport/node-serialport/issues/1805, can you check if modemmanager is installed? https://www.zigbee2mqtt.io/information/FAQ.html#modemmanager-is-installed

mrucki commented 4 years ago

@Koenkk nope - I checked and it wasn't installed. Currently I reflashed again my RaspberryPi but this time with Ubuntu Server instead of Raspbian Buster.

ubuntu@ubuntu:~$ sudo apt-get purge modemmanager
Reading package lists... Done
Building dependency tree       
Reading state information... Done
Package 'modemmanager' is not installed, so not removed
0 upgraded, 0 newly installed, 0 to remove and 49 not upgraded.

also here modemmanager is not installed - will keep you posted if there will be any issue in few hours 👍

mrucki commented 4 years ago

As mentioned above tried with Ubuntu Server but still same error:

(node:17) UnhandledPromiseRejectionWarning: Error: SRSP - ZDO - mgmtPermitJoinReq after 6000ms
    at Timeout._onTimeout (/app/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7)
(node:17) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
(node:17) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Everything runs as a docker: openhab, influxdb, grafana, eclipse mosquitto, zigbee2mqtt

mrucki commented 4 years ago 
2020-10-04T13:41:50.068134966Z   serialport/stream _read reading { start: 2755, toRead: 62781 } +17ms
2020-10-04T13:41:50.068441266Z   serialport/binding-abstract read +3m
2020-10-04T13:41:50.068791524Z   serialport/bindings/unixRead Starting read +19ms
2020-10-04T13:41:50.074823101Z   serialport/bindings/unixRead read error [Error: EAGAIN: resource temporarily unavailable, read] {
2020-10-04T13:41:50.074945652Z   errno: -11,
2020-10-04T13:41:50.074974089Z   code: 'EAGAIN',
2020-10-04T13:41:50.075000391Z   syscall: 'read'
2020-10-04T13:41:50.075026329Z } +1ms
2020-10-04T13:41:50.075341796Z   serialport/bindings/unixRead waiting for readable because of code: EAGAIN +1ms
2020-10-04T13:41:50.075416691Z   serialport/bindings/poller Polling for "readable" +22ms
2020-10-04T13:42:23.278849684Z Zigbee2MQTT:debug 2020-10-04 13:42:23: Saving state to file /app/data/state.json
2020-10-04T13:42:23.283361062Z winston:file: written true false
2020-10-04T13:42:23.286823280Z winston:file: logged 22757 debug 2020-10-04 13:42:23: Saving state to file /app/data/state.json
2020-10-04T13:42:23.286980935Z 
2020-10-04T13:47:23.290436292Z Zigbee2MQTT:debug 2020-10-04 13:47:23: Saving state to file /app/data/state.json
2020-10-04T13:47:23.290558166Z winston:file: written true false
2020-10-04T13:47:23.290592593Z winston:file: logged 22826 debug 2020-10-04 13:47:23: Saving state to file /app/data/state.json
2020-10-04T13:47:23.291050715Z 
2020-10-04T13:52:23.292702573Z Zigbee2MQTT:debug 2020-10-04 13:52:23: Saving state to file /app/data/state.json
2020-10-04T13:52:23.294951372Z winston:file: written true false
2020-10-04T13:52:23.297543504Z winston:file: logged 22895 debug 2020-10-04 13:52:23: Saving state to file /app/data/state.json
2020-10-04T13:52:23.297671681Z 
2020-10-04T13:57:23.302938675Z Zigbee2MQTT:debug 2020-10-04 13:57:23: Saving state to file /app/data/state.json
2020-10-04T13:57:23.304658721Z winston:file: written true false
2020-10-04T13:57:23.315475561Z winston:file: logged 22964 debug 2020-10-04 13:57:23: Saving state to file /app/data/state.json
2020-10-04T13:57:23.315606030Z 
2020-10-04T14:02:23.303500629Z Zigbee2MQTT:debug 2020-10-04 14:02:23: Saving state to file /app/data/state.json
2020-10-04T14:02:23.306220097Z winston:file: written true false
2020-10-04T14:02:23.309794300Z winston:file: logged 23033 debug 2020-10-04 14:02:23: Saving state to file /app/data/state.json
2020-10-04T14:02:23.309949977Z

looks like serialport hangs, stops receiving

slaesh commented 4 years ago

Did you tested the debug-fw which will make use of the LEDs? To see in which "state" the stick is.. Maybe any other resource is trying to access the serial-port and this may force the stick into reset-state.

Like this known bug: https://community.openhab.org/t/apparently-the-zwave-binding-blocks-the-dev-ttyusb0-port-in-combination-with-a-cc2652rb-zigbee2mqtt-dongle/103245

mrucki commented 4 years ago

I didn't test it however once I installed fresh new Ubuntu Server on my Raspberry pi I added docker, docker-compose and run:

version: '3.3'
services:
  influxdb:
    image: influxdb:1.8.3
    restart: always
    ports:
      - '8086:8086'
    volumes:
      - /home/ubuntu/iot/influxdb-data:/var/lib/influxdb
      - /home/ubuntu/iot/influxdb-conf:/etc/influxdb
    environment:
      - INFLUXDB_ADMIN_USER=...
      - INFLUXDB_ADMIN_PASSWORD=...
  grafana:
    image: grafana/grafana:7.2.0
    restart: always
    depends_on:
        - influxdb
    ports:
      - '3000:3000'
    user: "1000"
    volumes:
      - /home/ubuntu/iot/grafana-data:/var/lib/grafana
      - /home/ubuntu/iot/grafana-conf:/etc/grafana
  mosquitto:
    image: eclipse-mosquitto:1.6.12
    restart: always
    ports:
      - '1883:1883'
      - '9001:9001'
  openhab:
    image: openhab/openhab:2.5.9
    restart: always
    depends_on:
        - mosquitto
        - influxdb
    ports:
      - '8080:8080'
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - /etc/timezone:/etc/timezone:ro
      - /home/ubuntu/iot/openhab-data/conf:/openhab/conf
      - /home/ubuntu/iot/openhab-data/userdata:/openhab/userdata
      - /home/ubuntu/iot/openhab-data/addons:/openhab/addons
      - /home/ubuntu/iot/openhab-data/backup:/openhab/backup
    environment:
      - USER_ID=1000
      - GROUP_ID=1000
  zigbee2mqtt:
    image: koenkk/zigbee2mqtt
    restart: always
    depends_on:
        - mosquitto
    devices:
      - "/dev/ttyACM0:/dev/ttyACM0"
    volumes:
      - /home/ubuntu/iot/zigbee2mqtt_data:/app/data

There is only one USB device and no EXTRA_JAVA_OPTS in OpenHab (searched with docker exec -it openhab /bin/bash )

@slaesh what do you recommend for debug?

MORD0R commented 4 years ago

Did you tested the debug-fw which will make use of the LEDs? To see in which "state" the stick is.. Maybe any other resource is trying to access the serial-port and this may force the stick into reset-state.

Like this known bug: https://community.openhab.org/t/apparently-the-zwave-binding-blocks-the-dev-ttyusb0-port-in-combination-with-a-cc2652rb-zigbee2mqtt-dongle/103245

Is disabled the z wave binding. And i think this error is gone. But im not sure. I have to wait a few days.

mrucki commented 4 years ago

I setup such cron job:

0 */2 * * * docker-compose restart zigbee2mqtt >> /home/ubuntu/cron-jobs.log 2>&1

ugly hack but all 4 devices have been working for last 2 days

Dustinhoefer commented 4 years ago

Hey everyone, I am the issue reporter. Did @MORD0R find out if that did the trick? @mrucki that is unfortunately not possible for me, since the devices aren't even working when I start the server ...

Any other ideas?

slaesh commented 4 years ago

@mrucki ttyACM0 in your configuration looks weird? oO

you could use this python script to test the stick itself: https://github.com/slaesh/cc2652-stick/tree/master/coordinator-test

golddragon007 commented 4 years ago

@slaesh he has cc2531 as I understood well, that mounts to ttyACM0 by default. And I don't know if it will work the cc2652 test script for that chip. Especially because cc2531 doesn't have any serial chip like yours.

MORD0R commented 4 years ago

Hey everyone, I am the issue reporter. Did @MORD0R find out if that did the trick? @mrucki that is unfortunately not possible for me, since the devices aren't even working when I start the server ...

Any other ideas?

No it doesnt work error is back.

@golddragon007 I have to use /dev/ttyUSB0 and sometimes /dev/ttyACM0 But i think thats because the pi 4 got an USB 3 port and USB2 port.

Use the command:ls /dev/USB

golddragon007 commented 4 years ago

@MORD0R it has nothing to do with the pi 4 USB ports. ttyUSBx means that the connected device communicates with "USB serial port adapter" the ttyACMx means "abstract control model" that is a sub-type of USB communication device (CDC). Also, there is the ttySx will be a serial port ttyAMAx is also serial interface, but ARM devices provide it as far as I know on pi 4 this is for Bluetooth if I'm right. The connection depends on the plugged-in device, and it's implementation, not on the port itself.

timdonovanuk commented 4 years ago

My z2m just failed with this error all over the logs.

golddragon007 commented 3 years ago

@Koenkk I had this error now, with slaesh's stick. Here is my log: network_fail.zip In the beginning, I had 7 Aqara opple switches, 6 mija light sensor and 4 TS0601_thermostat. The system was pretty stable. Then I've added my 22 Niko smart outlets and everything changed as you see. These Niko outlets poop into the air in every appr. 2-3 sec...