Koenkk / zigbee2mqtt

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

Can't start new stick #4513

Closed golddragon007 closed 3 years ago

golddragon007 commented 3 years ago

What happened

I've changed my CC2531 controller to a slaesh’s CC2652RB stick one. First I've flashed the CC2652RB, then I replaced the old stick to the new one, I started the zigbee, I saw a pan_id error. I've changed it, by incrementing one (from 6754 to 6755). After restart I've still getting the following:

Zigbee2MQTT:info  2020-10-01 14:50:09: Logging to console and directory: 'data/log/2020-10-01.14-50-09' filename: log.txt
Zigbee2MQTT:info  2020-10-01 14:50:10: Starting Zigbee2MQTT version 1.14.4 (commit #1.14.4)
Zigbee2MQTT:info  2020-10-01 14:50:10: Starting zigbee-herdsman...
Zigbee2MQTT:error 2020-10-01 14:51:26: Error while starting zigbee-herdsman
Zigbee2MQTT:error 2020-10-01 14:51:26: Failed to start zigbee
Zigbee2MQTT:error 2020-10-01 14:51:26: Exiting...
Zigbee2MQTT:error 2020-10-01 14:51:26: Error: Coordinator failed to start, probably the panID is already in use, try a different panID or channel
    at /zigbee2mqtt-1.14.4/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:171:23
    at Generator.throw (<anonymous>)
    at rejected (/zigbee2mqtt-1.14.4/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:25:65)
npm
 ERR! code ELIFECYCLE
npm ERR! errno 1
npm 
ERR! zigbee2mqtt@1.14.4 start: `node index.js`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the zigbee2mqtt@1.14.4 start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2020-10-01T12_51_26_198Z-debug.log
2020-10-01T14:51:28: PM2 log: App [npm:0] exited with code [1] via signal [SIGINT]
2020-10-01T14:51:28: PM2 log: App [npm:0] starting in -fork mode-
2020-10-01T14:51:28: PM2 log: App [npm:0] online
> zigbee2mqtt@1.14.4 start /zigbee2mqtt-1.14.4
> node index.js

What did you expect to happen

Boot up and work.

How to reproduce it (minimal and precise)

Debug info

Zigbee2MQTT version: 1.14.4.2 Adapter hardware: CC2531 and slaesh’s CC2652RB stick Adapter firmware version: CC2652RB_20200805 (https://github.com/Koenkk/Z-Stack-firmware/tree/master/coordinator/Z-Stack_3.x.0/bin)

golddragon007 commented 3 years ago

I've just updated to 1.15 both the stick and the software, incremented the pan_id, but still, it doesn't want to start... (same error)

Zigbee2MQTT:info  2020-10-01 21:41:36: Logging to console and directory: 'data/log/2020-10-01.21-41-36' filename: log.txt
Zigbee2MQTT:info  2020-10-01 21:41:37: Starting Zigbee2MQTT version 1.15.0 (commit #1.15.0)
Zigbee2MQTT:info  2020-10-01 21:41:37: Starting zigbee-herdsman...
Zigbee2MQTT:error 2020-10-01 21:42:53: Error while starting zigbee-herdsman
Zigbee2MQTT:error 2020-10-01 21:42:53: Failed to start zigbee
Zigbee2MQTT:error 2020-10-01 21:42:53: Exiting...
Zigbee2MQTT:error 2020-10-01 21:42:53: Error: Coordinator failed to start, probably the panID is already in use, try a different panID or channel
    at /zigbee2mqtt-1.15.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:171:23
    at Generator.throw (<anonymous>)
    at rejected (/zigbee2mqtt-1.15.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:25:65)
npm

ERR! code ELIFECYCLE
npm ERR! errno 1
npm 
ERR! zigbee2mqtt@1.15.0 start: `node index.js`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the zigbee2mqtt@1.15.0 start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2020-10-01T19_42_53_889Z-debug.log
2020-10-01T21:42:54: PM2 log: App [npm:0] exited with code [1] via signal [SIGINT]
2020-10-01T21:42:54: PM2 log: App [npm:0] starting in -fork mode-
2020-10-01T21:42:54: PM2 log: App [npm:0] online
> zigbee2mqtt@1.15.0 start /zigbee2mqtt-1.15.0
> node index.js

/root/.npm/_logs/2020-10-01T19_42_53_889Z-debug.log:

# cat /root/.npm/_logs/2020-10-01T19_42_53_889Z-debug.log
0 info it worked if it ends with ok
1 verbose cli [
1 verbose cli   '/usr/bin/node',
1 verbose cli   '/usr/lib/node_modules/pm2/lib/ProcessContainerFork.js',
1 verbose cli   'start'
1 verbose cli ]
2 info using npm@6.14.6
3 info using node@v12.18.4
4 verbose run-script [ 'prestart', 'start', 'poststart' ]
5 info lifecycle zigbee2mqtt@1.15.0~prestart: zigbee2mqtt@1.15.0
6 info lifecycle zigbee2mqtt@1.15.0~start: zigbee2mqtt@1.15.0
7 verbose lifecycle zigbee2mqtt@1.15.0~start: unsafe-perm in lifecycle true
8 verbose lifecycle zigbee2mqtt@1.15.0~start: PATH: /usr/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/zigbee2mqtt-1.15.0/node_modules/.bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
9 verbose lifecycle zigbee2mqtt@1.15.0~start: CWD: /zigbee2mqtt-1.15.0
10 silly lifecycle zigbee2mqtt@1.15.0~start: Args: [ '-c', 'node index.js' ]
11 silly lifecycle zigbee2mqtt@1.15.0~start: Returned: code: 1  signal: null
12 info lifecycle zigbee2mqtt@1.15.0~start: Failed to exec start script
13 verbose stack Error: zigbee2mqtt@1.15.0 start: `node index.js`
13 verbose stack Exit status 1
13 verbose stack     at EventEmitter.<anonymous> (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:332:16)
13 verbose stack     at EventEmitter.emit (events.js:315:20)
13 verbose stack     at ChildProcess.<anonymous> (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14)
13 verbose stack     at ChildProcess.emit (events.js:315:20)
13 verbose stack     at maybeClose (internal/child_process.js:1021:16)
13 verbose stack     at Process.ChildProcess._handle.onexit (internal/child_process.js:286:5)
14 verbose pkgid zigbee2mqtt@1.15.0
15 verbose cwd /zigbee2mqtt-1.15.0
16 verbose Linux 5.4.65-v7l+
17 verbose argv "/usr/bin/node" "/usr/lib/node_modules/pm2/lib/ProcessContainerFork.js" "start"
18 verbose node v12.18.4
19 verbose npm  v6.14.6
20 error code ELIFECYCLE
21 error errno 1
22 error zigbee2mqtt@1.15.0 start: `node index.js`
22 error Exit status 1
23 error Failed at the zigbee2mqtt@1.15.0 start script.
23 error This is probably not a problem with npm. There is likely additional logging output above.
24 verbose exit [ 1, true ]
Koenkk commented 3 years ago

Could you provide the herdsman debug logging of this issue?

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

golddragon007 commented 3 years ago

@Koenkk As I said, I don't know where do I need to put the "zigbee_herdsman_debug": true to enable it, it's not mentioned anywhere just configuration. To which? And on which level? advanced? root?

Trauma commented 3 years ago

Some what the same issue with latest docker tag, reverting to 1.14.4 works.

Using '/app/data' as data directory

> zigbee2mqtt@1.14.4 start /app
> node index.js

Zigbee2MQTT:info  2020-10-03 16:59:00: Logging to console only'
Zigbee2MQTT:debug 2020-10-03 16:59:01: Loaded state from file /app/data/state.json
Zigbee2MQTT:info  2020-10-03 16:59:01: Starting Zigbee2MQTT version 1.14.4 (commit #654817a)
Zigbee2MQTT:info  2020-10-03 16:59:01: Starting zigbee-herdsman...
Zigbee2MQTT:debug 2020-10-03 16:59:01: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null},"backupPath":"/app/data/coordinator_backup.json","databaseBackupPath":"/app/data/database.db.backup","databasePath":"/app/data/database.db","network":{"channelList":[20],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6754},"serialPort":{"path":"/dev/ttyACM0"}}'
Zigbee2MQTT:error 2020-10-03 16:59:20: Error while starting zigbee-herdsman
Zigbee2MQTT:error 2020-10-03 16:59:20: Failed to start zigbee
Zigbee2MQTT:error 2020-10-03 16:59:20: Exiting...
Zigbee2MQTT:error 2020-10-03 16:59:20: Error: Failed to connect to the adapter (Error: SRSP - SYS - ping after 6000ms)
    at ZStackAdapter.<anonymous> (/app/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/zStackAdapter.js:90:31)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! zigbee2mqtt@1.14.4 start: `node index.js`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the zigbee2mqtt@1.14.4 start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2020-10-03T14_59_20_839Z-debug.log
golddragon007 commented 3 years ago

Here is the log, with a full revert I was able to reproduce it. mqtt.txt

Koenkk commented 3 years ago

@golddragon007 can you try staring on a different channel? (docs: https://www.zigbee2mqtt.io/information/configuration.html#configuration)

golddragon007 commented 3 years ago

Well, it's kind of late, I've found a way that seems it's work now, but I have still issues. So I did the following:

  1. Create a full backup for HA.
  2. Reflash ZigBee controller with the newest kernel
  3. Remove antenna
  4. Plugin and start z2m
  5. After it's starting up all my ZigBee entities goes away from HA
  6. Full restore of HA & install back the antenna

Now I have a somewhat working controller, the strange stuff that only some of the devices connects to it the others refusing or as I see from the log the controller refusing it... Also, I got some errors and after maybe 12 hours it's breaking down totally with buffer full error. I try to collect this, until then please check the current reason why refusing devices to connect. z2m.log

Also for some reason for me, the UI doesn't work, I see always the "Loading, please wait." message (and technically none of the tabs works on the UI).

TheMClaeys commented 3 years ago

I receive the same error as Trauma a few posts above since a few versions. I have to unplug the stick, plug it back in and then it starts fine. I thought it was an issue with my stick, so I bought a new one, flashed it and it has the same issue. The strange thing is that Home Assistant itself still sees the stick in hardware, so the stick is still connected even though Zigbee2MQTT is apparently unable to "ping it".

golddragon007 commented 3 years ago

And around a day of run here is the error:

2020-10-04T20:18:22.664Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":17}
2020-10-04T20:18:22.664Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
(node:243) 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:243) 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: 4)
2020-10-04T20:18:22.667Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,182,0,0,0,240]

'Full' log file: z2m-buffer-full.log

The problem that the Zigbee network doesn't work, nor before nor after the error, and now I have around 1 month already down my Zigbee network half of my stuff is Zigbee so it's starting to be really bad.

Oh and I don't have problem with the USB, because it should be still connected according dmesg:

pi@raspberrypi:~ $ dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.4.65-v7l+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1341 SMP Tue Sep 15 13:13:32 BST 2020
[    0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.1
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Reserved memory: created CMA memory pool at 0x000000001ec00000, size 256 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] On node 0 totalpages: 1012480
[    0.000000]   DMA zone: 2304 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 196608 pages, LIFO batch:63
[    0.000000]   HighMem zone: 815872 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: 1010176
[    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  smsc95xx.macaddr=DC:A6:32:0D:C1:B0 vc_mem.mem_base=0x3eb00000 vc_mem.mem_size=0x3ff00000  console=ttyS0,115200 console=tty1 root=PARTUUID=73fce24b-02 rootfstype=ext4 elevator=deadline fsck.repair=yes lsm=apparmor 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] software IO TLB: mapped [mem 0x17cc0000-0x1bcc0000] (64MB)
[    0.000000] Memory: 3654580K/4049920K available (10240K kernel code, 738K rwdata, 2808K rodata, 2048K init, 857K bss, 133196K reserved, 262144K cma-reserved, 3263488K highmem)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 31124 entries in 61 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] GIC: Using split EOI/Deactivate mode
[    0.000000] random: get_random_bytes called from start_kernel+0x344/0x520 with crng_init=0
[    0.000008] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns
[    0.000031] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns
[    0.000111] bcm2835: system timer (irq = 17)
[    0.000771] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[    0.000791] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000812] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000828] Switching to timer-based delay loop, resolution 18ns
[    0.001066] Console: colour dummy device 80x30
[    0.001560] printk: console [tty1] enabled
[    0.001621] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
[    0.001662] pid_max: default: 32768 minimum: 301
[    0.001819] LSM: Security Framework initializing
[    0.001941] AppArmor: AppArmor initialized
[    0.002158] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.002200] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.003364] Disabling memory control group subsystem
[    0.003503] CPU: Testing write buffer coherency: ok
[    0.004001] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.004874] Setting up static identity map for 0x200000 - 0x20003c
[    0.005080] rcu: Hierarchical SRCU implementation.
[    0.005725] smp: Bringing up secondary CPUs ...
[    0.006793] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.007981] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.009099] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.009244] smp: Brought up 1 node, 4 CPUs
[    0.009314] SMP: Total of 4 processors activated (432.00 BogoMIPS).
[    0.009339] CPU: All CPU(s) started in HYP mode.
[    0.009362] CPU: Virtualization extensions available.
[    0.010144] devtmpfs: initialized
[    0.023500] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
[    0.023766] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.023816] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.031691] pinctrl core: initialized pinctrl subsystem
[    0.032656] NET: Registered protocol family 16
[    0.036265] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.036855] audit: initializing netlink subsys (disabled)
[    0.037103] audit: type=2000 audit(0.030:1): state=initialized audit_enabled=0 res=1
[    0.038222] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.038258] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.038595] Serial: AMBA PL011 UART driver
[    0.041982] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[    0.060846] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-09-17 12:31, variant start
[    0.070861] raspberrypi-firmware soc:firmware: Firmware hash is 6105bb6ab6db9d62a57ce2bb96c527a2cc46a717
[    0.124667] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1
[    0.129120] vgaarb: loaded
[    0.129589] SCSI subsystem initialized
[    0.129840] usbcore: registered new interface driver usbfs
[    0.129911] usbcore: registered new interface driver hub
[    0.130039] usbcore: registered new device driver usb
[    0.130347] usb_phy_generic phy: phy supply vcc not found, using dummy regulator
[    0.132172] clocksource: Switched to clocksource arch_sys_counter
[    0.899186] VFS: Disk quotas dquot_6.6.0
[    0.899297] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.899467] FS-Cache: Loaded
[    0.899679] CacheFiles: Loaded
[    0.900424] AppArmor: AppArmor Filesystem Enabled
[    0.901222] simple-framebuffer: probe of 0.framebuffer failed with error -12
[    0.910960] thermal_sys: Registered thermal governor 'step_wise'
[    0.911313] NET: Registered protocol family 2
[    0.912078] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[    0.912130] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    0.912411] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.912501] TCP: Hash tables configured (established 8192 bind 8192)
[    0.912664] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.912714] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.912975] NET: Registered protocol family 1
[    0.913686] RPC: Registered named UNIX socket transport module.
[    0.913715] RPC: Registered udp transport module.
[    0.913740] RPC: Registered tcp transport module.
[    0.913764] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.913798] PCI: CLS 0 bytes, default 64
[    0.915590] hw perfevents: enabled with armv7_cortex_a15 PMU driver, 7 counters available
[    0.917729] Initialise system trusted keyrings
[    0.917967] workingset: timestamp_bits=14 max_order=20 bucket_order=6
[    0.928755] FS-Cache: Netfs 'nfs' registered for caching
[    0.929476] NFS: Registering the id_resolver key type
[    0.929523] Key type id_resolver registered
[    0.929548] Key type id_legacy registered
[    0.929583] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.930663] Key type asymmetric registered
[    0.930691] Asymmetric key parser 'x509' registered
[    0.930869] bounce: pool size: 64 pages
[    0.930922] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    0.931161] io scheduler mq-deadline registered
[    0.931188] io scheduler kyber registered
[    0.934997] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[    0.935039] brcm-pcie fd500000.pcie:   No bus range found for /scb/pcie@7d500000, using [bus 00-ff]
[    0.935125] brcm-pcie fd500000.pcie:      MEM 0x0600000000..0x0603ffffff -> 0x00f8000000
[    0.935210] brcm-pcie fd500000.pcie:   IB MEM 0x0000000000..0x00bfffffff -> 0x0000000000
[    0.994311] brcm-pcie fd500000.pcie: link up, 5 GT/s x1 (SSC)
[    0.994645] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[    0.994679] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.994712] pci_bus 0000:00: root bus resource [mem 0x600000000-0x603ffffff] (bus address [0xf8000000-0xfbffffff])
[    0.994788] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[    0.995041] pci 0000:00:00.0: PME# supported from D0 D3hot
[    0.998413] PCI: bus0: Fast back to back transfers disabled
[    0.998649] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[    0.998807] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[    0.999235] pci 0000:01:00.0: PME# supported from D0 D3cold
[    1.002677] PCI: bus1: Fast back to back transfers disabled
[    1.002748] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[    1.002786] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[    1.002884] pci 0000:00:00.0: PCI bridge to [bus 01]
[    1.002920] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
[    1.003225] pcieport 0000:00:00.0: enabling device (0140 -> 0142)
[    1.003467] pcieport 0000:00:00.0: PME: Signaling with IRQ 55
[    1.003868] pcieport 0000:00:00.0: AER: enabled with IRQ 55
[    1.004202] pci 0000:01:00.0: enabling device (0140 -> 0142)
[    1.010770] iproc-rng200 fe104000.rng: hwrng registered
[    1.011097] vc-mem: phys_addr:0x00000000 mem_base=0x3eb00000 mem_size:0x3ff00000(1023 MiB)
[    1.011726] vc-sm: Videocore shared memory driver
[    1.012338] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[    1.024151] brd: module loaded
[    1.036081] loop: module loaded
[    1.037437] Loading iSCSI transport class v2.0-870.
[    1.039366] libphy: Fixed MDIO Bus: probed
[    1.039954] bcmgenet fd580000.ethernet: failed to get enet clock
[    1.039988] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000
[    1.040023] bcmgenet fd580000.ethernet: failed to get enet-wol clock
[    1.040058] bcmgenet fd580000.ethernet: failed to get enet-eee clock
[    1.040098] bcmgenet: Skipping UMAC reset
[    1.052243] libphy: bcmgenet MII bus: probed
[    1.142342] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus
[    1.143447] usbcore: registered new interface driver r8152
[    1.143530] usbcore: registered new interface driver lan78xx
[    1.143604] usbcore: registered new interface driver smsc95xx
[    1.144079] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.144127] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    1.146404] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000001000000890
[    1.147692] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.04
[    1.147730] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.147764] usb usb1: Product: xHCI Host Controller
[    1.147791] usb usb1: Manufacturer: Linux 5.4.65-v7l+ xhci-hcd
[    1.147818] usb usb1: SerialNumber: 0000:01:00.0
[    1.148425] hub 1-0:1.0: USB hub found
[    1.148531] hub 1-0:1.0: 1 port detected
[    1.149081] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.149121] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    1.149163] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    1.149624] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.04
[    1.149660] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.149692] usb usb2: Product: xHCI Host Controller
[    1.149719] usb usb2: Manufacturer: Linux 5.4.65-v7l+ xhci-hcd
[    1.149746] usb usb2: SerialNumber: 0000:01:00.0
[    1.150337] hub 2-0:1.0: USB hub found
[    1.150419] hub 2-0:1.0: 4 ports detected
[    1.151843] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    1.152125] dwc_otg: FIQ enabled
[    1.152136] dwc_otg: NAK holdoff enabled
[    1.152188] dwc_otg: FIQ split-transaction FSM enabled
[    1.152214] Module dwc_common_port init
[    1.152666] usbcore: registered new interface driver uas
[    1.152785] usbcore: registered new interface driver usb-storage
[    1.152986] mousedev: PS/2 mouse device common for all mice
[    1.155028] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    1.158216] sdhci: Secure Digital Host Controller Interface driver
[    1.158246] sdhci: Copyright(c) Pierre Ossman
[    1.158861] mmc-bcm2835 fe300000.mmcnr: could not get clk, deferring probe
[    1.159404] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.163117] ledtrig-cpu: registered to indicate activity on CPUs
[    1.163436] hidraw: raw HID events driver (C) Jiri Kosina
[    1.163639] usbcore: registered new interface driver usbhid
[    1.163665] usbhid: USB HID core driver
[    1.164659] vchiq: vchiq_init_state: slot_zero = (ptrval)
[    1.166543] [vc_sm_connected_init]: start
[    1.175413] [vc_sm_connected_init]: end - returning 0
[    1.177505] Initializing XFRM netlink socket
[    1.177557] NET: Registered protocol family 17
[    1.177700] Key type dns_resolver registered
[    1.178101] Registering SWP/SWPB emulation handler
[    1.178423] registered taskstats version 1
[    1.178455] Loading compiled-in X.509 certificates
[    1.178964] Key type ._fscrypt registered
[    1.178991] Key type .fscrypt registered
[    1.179104] AppArmor: AppArmor sha1 policy hashing enabled
[    1.189116] uart-pl011 fe201000.serial: cts_event_workaround enabled
[    1.189205] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 29, base_baud = 0) is a PL011 rev2
[    1.195192] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    1.196118] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    1.196149] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[    1.246851] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    1.248524] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.250194] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.253199] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    1.254880] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.260946] mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA
[    1.263870] of_cfs_init
[    1.264002] of_cfs_init: OK
[    1.265037] Waiting for root device PARTUUID=73fce24b-02...
[    1.300512] random: fast init done
[    1.324459] mmc1: new high speed SDIO card at address 0001
[    1.512553] usb 2-2: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[    1.543624] usb 2-2: New USB device found, idVendor=152d, idProduct=0562, bcdDevice= 2.08
[    1.543662] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    1.543693] usb 2-2: Product: External
[    1.543719] usb 2-2: Manufacturer: JMicron
[    1.543745] usb 2-2: SerialNumber: DD5641988388D
[    1.564946] scsi host0: uas
[    1.566297] scsi 0:0:0:0: Direct-Access     JMicron  Tech             0208 PQ: 0 ANSI: 6
[    1.567706] sd 0:0:0:0: [sda] Spinning up disk...
[    1.692204] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    1.874062] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[    1.874100] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.874130] usb 1-1: Product: USB2.0 Hub
[    1.875766] hub 1-1:1.0: USB hub found
[    1.876016] hub 1-1:1.0: 4 ports detected
[    2.202201] usb 1-1.3: new full-speed USB device number 3 using xhci_hcd
[    2.337579] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[    2.337616] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.337648] usb 1-1.3: Product: slae.sh cc2652rb stick - slaesh's iot stuff
[    2.337677] usb 1-1.3: Manufacturer: Silicon Labs
[    2.337703] usb 1-1.3: SerialNumber: 00_12_4B_00_21_CC_02_11
[    2.632247] ..ready
[    3.673190] sd 0:0:0:0: [sda] 1000215216 512-byte logical blocks: (512 GB/477 GiB)
[    3.673229] sd 0:0:0:0: [sda] 4096-byte physical blocks
[    3.673422] sd 0:0:0:0: [sda] Write Protect is off
[    3.673454] sd 0:0:0:0: [sda] Mode Sense: 5f 00 00 08
[    3.673780] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    3.674468] sd 0:0:0:0: [sda] Optimal transfer size 33553920 bytes not a multiple of physical block size (4096 bytes)
[    3.677267]  sda: sda1 sda2
[    3.680092] sd 0:0:0:0: [sda] Attached SCSI disk
[    3.707431] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
[    3.707529] VFS: Mounted root (ext4 filesystem) readonly on device 8:2.
[    3.717364] devtmpfs: mounted
[    3.725667] Freeing unused kernel memory: 2048K
[    3.732473] Run /sbin/init as init process
[    4.347960] systemd[1]: System time before build time, advancing clock.
[    4.428183] NET: Registered protocol family 10
[    4.429499] Segment Routing with IPv6
[    4.474304] 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)
[    4.475109] systemd[1]: Detected architecture arm.
[    4.532435] systemd[1]: Set hostname to <raspberrypi>.
[    5.181359] systemd[1]: /lib/systemd/system/lighttpd.service:6: PIDFile= references path below legacy directory /var/run/, updating /var/run/lighttpd.pid → /run/lighttpd.pid; please update the unit file accordingly.
[    5.279136] random: systemd: uninitialized urandom read (16 bytes read)
[    5.288691] random: systemd: uninitialized urandom read (16 bytes read)
[    5.289228] systemd[1]: Listening on udev Kernel Socket.
[    5.290126] random: systemd: uninitialized urandom read (16 bytes read)
[    5.294301] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    5.295660] systemd[1]: Listening on Journal Socket.
[    5.296731] systemd[1]: Condition check resulted in Huge Pages File System being skipped.
[    5.303607] systemd[1]: Starting Restore / save the current clock...
[    5.311471] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[    5.906186] EXT4-fs (sda2): re-mounted. Opts: (null)
[    6.006291] systemd-journald[117]: Received request to flush runtime journal from PID 1
[    6.665888] rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x00010000
[    6.675858] rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00001000
[    6.678803] rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x00010000
[    6.686531] rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x00010000
[    6.720263] mc: Linux media interface: v0.10
[    6.767154] videodev: Linux video capture interface: v2.00
[    6.768613] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    6.791627] bcm2835_audio bcm2835_audio: card created with 8 channels
[    6.800450] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    6.802066] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    6.802699] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    6.802719] [vc_sm_connected_init]: start
[    6.812740] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    6.822551] [vc_sm_connected_init]: installed successfully
[    6.831814] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    6.832402] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    6.839812] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    6.844002] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    6.851756] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[    6.857484] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[    6.859062] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[    6.859535] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[    6.859561] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    6.859582] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    6.859602] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    6.859621] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    6.859805] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[    6.862903] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    6.911698] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    6.911876] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    6.920441] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    6.920510] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    6.931260] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    6.931300] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    6.952777] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    6.979028] [drm] No displays found. Consider forcing hotplug if HDMI is attached
[    6.979153] vc4-drm gpu: bound fe600000.firmwarekms (ops vc4_fkms_ops [vc4])
[    6.979177] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    6.979189] [drm] No driver support for vblank timestamp query.
[    6.979201] [drm] Setting vblank_disable_immediate to false because get_vblank_timestamp == NULL
[    6.979685] [drm] Initialized vc4 0.0.0 20140616 for gpu on minor 0
[    7.080445] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    7.127990] brcmfmac: F1 signature read @0x18000000=0x15264345
[    7.134511] [drm] Initialized v3d 1.0.0 20180419 for fec00000.v3d on minor 1
[    7.139307] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    7.139755] usbcore: registered new interface driver brcmfmac
[    7.150735] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43455-sdio.raspberrypi,4-model-b.txt failed with error -2
[    7.250306] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    7.265068] usbcore: registered new interface driver usbserial_generic
[    7.265138] usbserial: USB Serial support registered for generic
[    7.278236] usbcore: registered new interface driver cp210x
[    7.278312] usbserial: USB Serial support registered for cp210x
[    7.278482] cp210x 1-1.3:1.0: cp210x converter detected
[    7.298058] usb 1-1.3: cp210x converter now attached to ttyUSB0
[    7.380792] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    7.399384] 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.014336] audit: type=1400 audit(1601820689.579:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/man" pid=290 comm="apparmor_parser"
[    9.014412] audit: type=1400 audit(1601820689.579:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_filter" pid=290 comm="apparmor_parser"
[    9.014452] audit: type=1400 audit(1601820689.579:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_groff" pid=290 comm="apparmor_parser"
[    9.019700] audit: type=1400 audit(1601820689.579:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=291 comm="apparmor_parser"
[    9.019771] audit: type=1400 audit(1601820689.579:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=291 comm="apparmor_parser"
[    9.912704] random: crng init done
[    9.912721] random: 7 urandom warning(s) missed due to ratelimiting
[    9.973192] 8021q: 802.1Q VLAN Support v1.8
[   10.086817] uart-pl011 fe201000.serial: no DMA platform data
[   10.163761] audit: type=1400 audit(1601820690.729:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor" pid=450 comm="apparmor_parser"
[   10.163779] audit: type=1400 audit(1601820690.729:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor///usr/bin/gdbus" pid=450 comm="apparmor_parser"
[   10.163794] audit: type=1400 audit(1601820690.729:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor///usr/bin/git" pid=450 comm="apparmor_parser"
[   10.163812] audit: type=1400 audit(1601820690.729:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor///usr/bin/socat" pid=450 comm="apparmor_parser"
[   10.238768] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[   10.342227] Adding 1048572k swap on /var/swap.  Priority:-2 extents:8 across:1425404k SSFS
[   10.455958] bcmgenet: Skipping UMAC reset
[   10.457464] bcmgenet fd580000.ethernet: configuring instance for external RGMII
[   10.457665] bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control off
[   11.265598] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[   11.272216] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   16.749364] Bluetooth: Core ver 2.22
[   16.749414] NET: Registered protocol family 31
[   16.749419] Bluetooth: HCI device and connection manager initialized
[   16.749433] Bluetooth: HCI socket layer initialized
[   16.749441] Bluetooth: L2CAP socket layer initialized
[   16.749456] Bluetooth: SCO socket layer initialized
[   16.756102] Bluetooth: HCI UART driver ver 2.3
[   16.756112] Bluetooth: HCI UART protocol H4 registered
[   16.756152] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   16.756298] Bluetooth: HCI UART protocol Broadcom registered
[   16.918777] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   16.918787] Bluetooth: BNEP filters: protocol multicast
[   16.918802] Bluetooth: BNEP socket layer initialized
[   17.017074] audit: type=1400 audit(1601820697.579:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="docker-default" pid=811 comm="apparmor_parser"
[   18.442411] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[   18.451981] Bridge firewalling registered
[   20.236302] hassio: port 1(vethb81eb5d) entered blocking state
[   20.236311] hassio: port 1(vethb81eb5d) entered disabled state
[   20.236654] device vethb81eb5d entered promiscuous mode
[   20.237491] hassio: port 1(vethb81eb5d) entered blocking state
[   20.237498] hassio: port 1(vethb81eb5d) entered forwarding state
[   20.237667] hassio: port 1(vethb81eb5d) entered disabled state
[   20.315183] IPv6: ADDRCONF(NETDEV_CHANGE): vethb81eb5d: link becomes ready
[   20.315276] hassio: port 1(vethb81eb5d) entered blocking state
[   20.315283] hassio: port 1(vethb81eb5d) entered forwarding state
[   20.315415] IPv6: ADDRCONF(NETDEV_CHANGE): hassio: link becomes ready
[   20.925261] cgroup: cgroup: disabling cgroup2 socket matching due to net_prio or net_cls activation
[   21.704463] hassio: port 1(vethb81eb5d) entered disabled state
[   21.709970] eth0: renamed from vethfde20ee
[   21.753022] hassio: port 1(vethb81eb5d) entered blocking state
[   21.753031] hassio: port 1(vethb81eb5d) entered forwarding state
[   23.058483] docker0: port 1(veth0ea363a) entered blocking state
[   23.058491] docker0: port 1(veth0ea363a) entered disabled state
[   23.058747] device veth0ea363a entered promiscuous mode
[   23.059180] docker0: port 1(veth0ea363a) entered blocking state
[   23.059188] docker0: port 1(veth0ea363a) entered forwarding state
[   23.059362] docker0: port 1(veth0ea363a) entered disabled state
[   23.080462] hassio: port 2(vethd54b819) entered blocking state
[   23.080471] hassio: port 2(vethd54b819) entered disabled state
[   23.080721] device vethd54b819 entered promiscuous mode
[   23.081048] hassio: port 2(vethd54b819) entered blocking state
[   23.081055] hassio: port 2(vethd54b819) entered forwarding state
[   23.209209] IPv6: ADDRCONF(NETDEV_CHANGE): vethd54b819: link becomes ready
[   23.239546] IPv6: ADDRCONF(NETDEV_CHANGE): veth0ea363a: link becomes ready
[   23.239617] docker0: port 1(veth0ea363a) entered blocking state
[   23.239624] docker0: port 1(veth0ea363a) entered forwarding state
[   23.239742] IPv6: ADDRCONF(NETDEV_CHANGE): docker0: link becomes ready
[   23.782832] docker0: port 1(veth0ea363a) entered disabled state
[   23.783636] eth0: renamed from vethc6d4489
[   23.823180] docker0: port 1(veth0ea363a) entered blocking state
[   23.823189] docker0: port 1(veth0ea363a) entered forwarding state
[   24.202708] hassio: port 2(vethd54b819) entered disabled state
[   24.203150] eth1: renamed from veth022af1c
[   24.245432] hassio: port 2(vethd54b819) entered blocking state
[   24.245442] hassio: port 2(vethd54b819) entered forwarding state
[   24.679015] udevd[202]: starting version 3.2.9
[   24.709355] udevd[203]: starting eudev-3.2.9
[   36.552925] audit: type=1400 audit(1601820717.119:12): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor" pid=2067 comm="apparmor_parser"
[   36.552944] audit: type=1400 audit(1601820717.119:13): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor///usr/bin/gdbus" pid=2067 comm="apparmor_parser"
[   36.552961] audit: type=1400 audit(1601820717.119:14): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor///usr/bin/git" pid=2067 comm="apparmor_parser"
[   36.552978] audit: type=1400 audit(1601820717.119:15): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor///usr/bin/socat" pid=2067 comm="apparmor_parser"
[   36.747748] hassio: port 3(veth08b0f38) entered blocking state
[   36.747756] hassio: port 3(veth08b0f38) entered disabled state
[   36.748114] device veth08b0f38 entered promiscuous mode
[   36.878029] IPv6: ADDRCONF(NETDEV_CHANGE): vethdf44269: link becomes ready
[   36.878172] IPv6: ADDRCONF(NETDEV_CHANGE): veth08b0f38: link becomes ready
[   36.878234] hassio: port 3(veth08b0f38) entered blocking state
[   36.878241] hassio: port 3(veth08b0f38) entered forwarding state
[   37.612994] hassio: port 3(veth08b0f38) entered disabled state
[   37.624208] eth0: renamed from vethdf44269
[   37.693091] hassio: port 3(veth08b0f38) entered blocking state
[   37.693099] hassio: port 3(veth08b0f38) entered forwarding state
[   38.054207] hassio: port 4(veth0bde27d) entered blocking state
[   38.054215] hassio: port 4(veth0bde27d) entered disabled state
[   38.054405] device veth0bde27d entered promiscuous mode
[   38.054659] hassio: port 4(veth0bde27d) entered blocking state
[   38.054666] hassio: port 4(veth0bde27d) entered forwarding state
[   38.055839] hassio: port 4(veth0bde27d) entered disabled state
[   38.191501] IPv6: ADDRCONF(NETDEV_CHANGE): veth611ca56: link becomes ready
[   38.191645] IPv6: ADDRCONF(NETDEV_CHANGE): veth0bde27d: link becomes ready
[   38.191704] hassio: port 4(veth0bde27d) entered blocking state
[   38.191711] hassio: port 4(veth0bde27d) entered forwarding state
[   39.012814] hassio: port 4(veth0bde27d) entered disabled state
[   39.013622] eth0: renamed from veth611ca56
[   39.094728] hassio: port 4(veth0bde27d) entered blocking state
[   39.094737] hassio: port 4(veth0bde27d) entered forwarding state
[   39.405387] hassio: port 5(veth8ee8a81) entered blocking state
[   39.405398] hassio: port 5(veth8ee8a81) entered disabled state
[   39.405722] device veth8ee8a81 entered promiscuous mode
[   39.406308] hassio: port 5(veth8ee8a81) entered blocking state
[   39.406319] hassio: port 5(veth8ee8a81) entered forwarding state
[   39.535720] IPv6: ADDRCONF(NETDEV_CHANGE): veth8ee8a81: link becomes ready
[   40.382677] hassio: port 5(veth8ee8a81) entered disabled state
[   40.393774] eth0: renamed from veth49162e4
[   40.444338] hassio: port 5(veth8ee8a81) entered blocking state
[   40.444347] hassio: port 5(veth8ee8a81) entered forwarding state
[   42.123646] udevd[493]: starting version 3.2.9
[   42.143167] udevd[494]: starting eudev-3.2.9
[   42.730179] Bluetooth: RFCOMM TTY layer initialized
[   42.730201] Bluetooth: RFCOMM socket layer initialized
[   42.730217] Bluetooth: RFCOMM ver 1.11
[   43.492102] hassio: port 6(vethb234241) entered blocking state
[   43.492110] hassio: port 6(vethb234241) entered disabled state
[   43.492747] device vethb234241 entered promiscuous mode
[   43.571107] IPv6: ADDRCONF(NETDEV_CHANGE): veth93cbf1f: link becomes ready
[   43.571247] IPv6: ADDRCONF(NETDEV_CHANGE): vethb234241: link becomes ready
[   43.571342] hassio: port 6(vethb234241) entered blocking state
[   43.571348] hassio: port 6(vethb234241) entered forwarding state
[   44.793088] hassio: port 6(vethb234241) entered disabled state
[   44.793546] eth0: renamed from veth93cbf1f
[   44.843950] hassio: port 6(vethb234241) entered blocking state
[   44.844008] hassio: port 6(vethb234241) entered forwarding state
[   45.115095] hassio: port 7(veth0446c0c) entered blocking state
[   45.115106] hassio: port 7(veth0446c0c) entered disabled state
[   45.115351] device veth0446c0c entered promiscuous mode
[   45.115679] hassio: port 7(veth0446c0c) entered blocking state
[   45.115689] hassio: port 7(veth0446c0c) entered forwarding state
[   45.256980] IPv6: ADDRCONF(NETDEV_CHANGE): veth0446c0c: link becomes ready
[   46.082967] hassio: port 7(veth0446c0c) entered disabled state
[   46.087854] eth0: renamed from veth3ca4238
[   46.164661] hassio: port 7(veth0446c0c) entered blocking state
[   46.164671] hassio: port 7(veth0446c0c) entered forwarding state
[   51.518267] hassio: port 8(veth810b493) entered blocking state
[   51.518275] hassio: port 8(veth810b493) entered disabled state
[   51.518781] device veth810b493 entered promiscuous mode
[   51.639760] IPv6: ADDRCONF(NETDEV_CHANGE): vethe9680dd: link becomes ready
[   51.639916] IPv6: ADDRCONF(NETDEV_CHANGE): veth810b493: link becomes ready
[   51.639976] hassio: port 8(veth810b493) entered blocking state
[   51.639982] hassio: port 8(veth810b493) entered forwarding state
[   53.263154] hassio: port 8(veth810b493) entered disabled state
[   53.264670] eth0: renamed from vethe9680dd
[   53.324710] hassio: port 8(veth810b493) entered blocking state
[   53.324720] hassio: port 8(veth810b493) entered forwarding state
[   53.658756] hassio: port 9(vethf42dc57) entered blocking state
[   53.658764] hassio: port 9(vethf42dc57) entered disabled state
[   53.659105] device vethf42dc57 entered promiscuous mode
[   53.659644] hassio: port 9(vethf42dc57) entered blocking state
[   53.659652] hassio: port 9(vethf42dc57) entered forwarding state
[   53.790992] IPv6: ADDRCONF(NETDEV_CHANGE): vethf42dc57: link becomes ready
[   54.753420] eth0: renamed from veth0032039
[   54.812763] hassio: port 9(vethf42dc57) entered disabled state
[   54.815000] hassio: port 9(vethf42dc57) entered blocking state
[   54.815009] hassio: port 9(vethf42dc57) entered forwarding state
[   55.678161] hassio: port 10(vethbbc9559) entered blocking state
[   55.678169] hassio: port 10(vethbbc9559) entered disabled state
[   55.678414] device vethbbc9559 entered promiscuous mode
[   55.678708] hassio: port 10(vethbbc9559) entered blocking state
[   55.678716] hassio: port 10(vethbbc9559) entered forwarding state
[   55.822513] hassio: port 10(vethbbc9559) entered disabled state
[   55.855694] IPv6: ADDRCONF(NETDEV_CHANGE): veth8a7ea8c: link becomes ready
[   55.855886] IPv6: ADDRCONF(NETDEV_CHANGE): vethbbc9559: link becomes ready
[   55.855962] hassio: port 10(vethbbc9559) entered blocking state
[   55.855969] hassio: port 10(vethbbc9559) entered forwarding state
[   57.123170] eth0: renamed from veth8a7ea8c
[   57.167283] hassio: port 10(vethbbc9559) entered disabled state
[   57.169073] hassio: port 10(vethbbc9559) entered blocking state
[   57.169082] hassio: port 10(vethbbc9559) entered forwarding state
[   57.677288] hassio: port 11(vethe51d30f) entered blocking state
[   57.677296] hassio: port 11(vethe51d30f) entered disabled state
[   57.677582] device vethe51d30f entered promiscuous mode
[   57.677942] hassio: port 11(vethe51d30f) entered blocking state
[   57.677952] hassio: port 11(vethe51d30f) entered forwarding state
[   57.845737] IPv6: ADDRCONF(NETDEV_CHANGE): vethe51d30f: link becomes ready
[   59.075303] hassio: port 11(vethe51d30f) entered disabled state
[   59.075899] eth0: renamed from veth51966ad
[   59.164903] hassio: port 11(vethe51d30f) entered blocking state
[   59.164912] hassio: port 11(vethe51d30f) entered forwarding state
[   59.809300] hassio: port 12(veth95ea6e8) entered blocking state
[   59.809309] hassio: port 12(veth95ea6e8) entered disabled state
[   59.811906] device veth95ea6e8 entered promiscuous mode
[   59.814519] hassio: port 12(veth95ea6e8) entered blocking state
[   59.814528] hassio: port 12(veth95ea6e8) entered forwarding state
[   59.992114] IPv6: ADDRCONF(NETDEV_CHANGE): veth95ea6e8: link becomes ready
[   61.404732] hassio: port 12(veth95ea6e8) entered disabled state
[   61.405628] eth0: renamed from vethc8d6195
[   61.454747] hassio: port 12(veth95ea6e8) entered blocking state
[   61.454757] hassio: port 12(veth95ea6e8) entered forwarding state
[   68.640517] udevd[189]: starting version 3.2.9
[   68.661274] udevd[190]: starting eudev-3.2.9
[  175.537157] hassio: port 13(veth5207534) entered blocking state
[  175.537171] hassio: port 13(veth5207534) entered disabled state
[  175.537654] device veth5207534 entered promiscuous mode
[  175.592112] IPv6: ADDRCONF(NETDEV_CHANGE): veth08f8e21: link becomes ready
[  175.592274] IPv6: ADDRCONF(NETDEV_CHANGE): veth5207534: link becomes ready
[  175.592352] hassio: port 13(veth5207534) entered blocking state
[  175.592359] hassio: port 13(veth5207534) entered forwarding state
[  176.793511] hassio: port 13(veth5207534) entered disabled state
[  176.796101] eth0: renamed from veth08f8e21
[  176.843648] hassio: port 13(veth5207534) entered blocking state
[  176.843659] hassio: port 13(veth5207534) entered forwarding state
[  177.534838] hassio: port 14(veth6c1e7c1) entered blocking state
[  177.534846] hassio: port 14(veth6c1e7c1) entered disabled state
[  177.535280] device veth6c1e7c1 entered promiscuous mode
[  177.536018] hassio: port 14(veth6c1e7c1) entered blocking state
[  177.536026] hassio: port 14(veth6c1e7c1) entered forwarding state
[  177.554918] IPv6: ADDRCONF(NETDEV_CHANGE): veth6c1e7c1: link becomes ready
[  179.282562] hassio: port 14(veth6c1e7c1) entered disabled state
[  179.304298] eth0: renamed from veth560290b
[  179.364264] hassio: port 14(veth6c1e7c1) entered blocking state
[  179.364273] hassio: port 14(veth6c1e7c1) entered forwarding state
pi@raspberrypi:~ $ cat /proc/uptime
66804.87 218701.81
Koenkk commented 3 years ago

@golddragon007 is your stick connected through a USB extension cable?

golddragon007 commented 3 years ago

@Koenkk currently not. There was a long time, approx half-year without extension cable with cc2531 when it worked simply well, with few battery devices. Now I have Niko sockets. These are routers as well and also speaks A LOT. That the cc2531 seemed can't handle it too well without too big delays sometimes and also I was not able to connect more device to the network. So I've changed to a more powerful one. I can connect it via extension cable, but it won't work differently I'm 100% sure about that...

There's something even worst happening here I guess, if I shut down and pull out the Zigbee controller the connected devices doesn't even disconnect, they still reporting connected state with their LED... I think I need to try to disconnect everything deletes the addon reinstall and reconnects everything...

Koenkk commented 3 years ago

Before trying anything else, I really recommend connecting it via an extension cable and positioning it 20 cms away from the Pi. Especially Pi 4 generates a lot of interference. I've seen cases where the Pi generated so much interference that it prevented the stick from completely functioning.

golddragon007 commented 3 years ago

It doesn't need too much time to break down, here is the dmesg, you can see when did I add the extension cable:

[  177.554918] IPv6: ADDRCONF(NETDEV_CHANGE): veth6c1e7c1: link becomes ready
[  179.282562] hassio: port 14(veth6c1e7c1) entered disabled state
[  179.304298] eth0: renamed from veth560290b
[  179.364264] hassio: port 14(veth6c1e7c1) entered blocking state
[  179.364273] hassio: port 14(veth6c1e7c1) entered forwarding state
[84951.816675] hassio: port 14(veth6c1e7c1) entered disabled state
[84951.820197] veth560290b: renamed from eth0
[84951.974592] hassio: port 14(veth6c1e7c1) entered disabled state
[84951.996589] device veth6c1e7c1 left promiscuous mode
[84951.996603] hassio: port 14(veth6c1e7c1) entered disabled state
[85016.079577] usb 1-1.3: USB disconnect, device number 3
[85016.080013] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
[85016.080157] cp210x 1-1.3:1.0: device disconnected
[85366.032886] usb 1-1.3: new full-speed USB device number 4 using xhci_hcd
[85366.178216] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[85366.178225] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[85366.178231] usb 1-1.3: Product: slae.sh cc2652rb stick - slaesh's iot stuff
[85366.178237] usb 1-1.3: Manufacturer: Silicon Labs
[85366.178243] usb 1-1.3: SerialNumber: 00_12_4B_00_21_CC_02_11
[85366.185899] cp210x 1-1.3:1.0: cp210x converter detected
[85366.192136] usb 1-1.3: cp210x converter now attached to ttyUSB0
[85391.305299] hassio: port 14(veth55ce20d) entered blocking state
[85391.305308] hassio: port 14(veth55ce20d) entered disabled state
[85391.307149] device veth55ce20d entered promiscuous mode
[85391.343590] IPv6: ADDRCONF(NETDEV_CHANGE): vethd6afa32: link becomes ready
[85391.343788] IPv6: ADDRCONF(NETDEV_CHANGE): veth55ce20d: link becomes ready
[85391.343906] hassio: port 14(veth55ce20d) entered blocking state
[85391.343913] hassio: port 14(veth55ce20d) entered forwarding state
[85392.684417] hassio: port 14(veth55ce20d) entered disabled state
[85392.684975] eth0: renamed from vethd6afa32
[85392.734328] hassio: port 14(veth55ce20d) entered blocking state
[85392.734339] hassio: port 14(veth55ce20d) entered forwarding state
[85634.226191] hassio: port 14(veth55ce20d) entered disabled state
[85634.226497] vethd6afa32: renamed from eth0
[85634.369836] hassio: port 14(veth55ce20d) entered disabled state
[85634.405294] device veth55ce20d left promiscuous mode
[85634.405312] hassio: port 14(veth55ce20d) entered disabled state
[85635.004183] hassio: port 14(veth1a6e467) entered blocking state
[85635.004191] hassio: port 14(veth1a6e467) entered disabled state
[85635.004417] device veth1a6e467 entered promiscuous mode
[85635.004711] hassio: port 14(veth1a6e467) entered blocking state
[85635.004718] hassio: port 14(veth1a6e467) entered forwarding state
[85635.032759] IPv6: ADDRCONF(NETDEV_CHANGE): veth1a6e467: link becomes ready
[85636.376480] hassio: port 14(veth1a6e467) entered disabled state
[85636.380442] eth0: renamed from veth017a48e
[85636.428259] hassio: port 14(veth1a6e467) entered blocking state
[85636.428269] hassio: port 14(veth1a6e467) entered forwarding state
pi@raspberrypi:~ $ cat /proc/uptime
88264.30 289139.89

And the new log: z2m-buffer-full2.log

I really hope that all reconnection will solve this. If you have any other idea that you can find out from the logs, let me know and I will try to try it.

Koenkk commented 3 years ago

Can you try powering off the following device: 0x086bd7fffeee0278 (0x086bd7fffeee0278): 170-33505 - Niko Connected socket outlet (Router) especially this once is causing a lot of trouble.

golddragon007 commented 3 years ago

Ok, I've found it and turned off that circuit with two other Niko router. We will see how it will go now (or won't).

golddragon007 commented 3 years ago

z2m-buffer-full3.log Well, it's still happening and nothing wants to connect to it...

Koenkk commented 3 years ago

Can you try changing: https://github.com/Koenkk/zigbee-herdsman-converters/blob/master/converters/fromZigbee.js#L803 to

electrical_measurement_power: {
        /**
         * When using this converter also add the following to the configure method of the device:
         * await readEletricalMeasurementConverterAttributes(endpoint);
         */
        cluster: 'haElectricalMeasurement',
        type: ['attributeReport', 'readResponse'],
        convert: (model, msg, publish, options, meta) => {
             // ADD THIS
             if (msg.type === 'attributeReport') {
                msg.meta.frameControl.disableDefaultResponse = true;
            }
             // TILL HERE
            const getFactor = (key) => {
                const multiplier = msg.endpoint.getClusterAttributeValue('haElectricalMeasurement', `${key}Multiplier`);
                const divisor = msg.endpoint.getClusterAttributeValue('haElectricalMeasurement', `${key}Divisor`);
                const factor = multiplier && divisor ? multiplier / divisor : 1;
                return factor;
            };

            const lookup = [
                {key: 'activePower', name: 'power', factor: 'acPower'},
                {key: 'activePowerPhB', name: 'power_phase_b', factor: 'acPower'},
                {key: 'activePowerPhC', name: 'power_phase_c', factor: 'acPower'},
                {key: 'rmsCurrent', name: 'current', factor: 'acCurrent'},
                {key: 'rmsCurrentPhB', name: 'current_phase_b', factor: 'acCurrent'},
                {key: 'rmsCurrentPhC', name: 'current_phase_c', factor: 'acCurrent'},
                {key: 'rmsVoltage', name: 'voltage', factor: 'acVoltage'},
                {key: 'rmsVoltagePhB', name: 'voltage_phase_b', factor: 'acVoltage'},
                {key: 'rmsVoltagePhC', name: 'voltage_phase_c', factor: 'acVoltage'},
            ];

            const payload = {};
            for (const entry of lookup) {
                if (msg.data.hasOwnProperty(entry.key)) {
                    const factor = getFactor(entry.factor);
                    const property = postfixWithEndpointName(entry.name, msg, model);
                    payload[property] = precisionRound(msg.data[entry.key] * factor, 2);
                }
            }
            return payload;
        },
    },

See https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html on how to modify fromZigbee.js

golddragon007 commented 3 years ago

I've added, so far it seems it works, at least there are messages and it doesn't stuck/slow down like previously. However, still, the devices don't want to connect to it (the already paired one from the previous system). And I can't pair a new one to it. Is it possible to add a last seen column to the UI device list? Which displays the last received or ack message time?

golddragon007 commented 3 years ago

I've factory reset all my devices, uninstalled z2m deleted the /share/zigbee2mqtt folder and reflashed the ZigBee coordinator. HA restart. Installed back z2m, and surprise! Can't start the controller. Same issue like in the first comment. I've tried to change pan_id (6754 -> 6755) and also the channel (11 -> 12), doesn't matter, it doesn't start the same error. panid-in-use.log

Koenkk commented 3 years ago
golddragon007 commented 3 years ago

@Koenkk It doesn't want to start with ch 15 either. It seems for me that there's no need to debug the Zigbee at all. The problem is in the software on the stick or z2m itself. Or I've got two faulty stick from @slaesh or I missing something that's not described anywhere. I've just reflashed my cc2531, clean z2m and it started without any issue. I was even able to pair a device. I also flashed the debug firmware that shows the LEDs on the board. The red one went slightly dim on the boot even if it failed with the error. Then somehow configure itself, next reboot it went the red off, the blue was continuously on in both cases. But I was not able to pair any device...

Koenkk commented 3 years ago

@golddragon007 if I understand correctly both CC2652RB don't work? I still think sniffing makes sense to do, the CC2531 will not do the check which makes your CC2652RB fail on startup.

golddragon007 commented 3 years ago

@Koenkk Yes, I have two CC2652RB and both failing with the same error (see previous log files). Then I can try to sniff with the CC2531 when the CC2652RB boots up (at least tries).

slaesh commented 3 years ago

I also flashed the debug firmware that shows the LEDs on the board. The red one went slightly dim on the boot even if it failed with the error. Then somehow configure itself, next reboot it went the red off, the blue was continuously on in both cases. But I was not able to pair any device...

Sounds good.

Blue on = CPU is running the Orange one = just toggles on every received byte. On/Off doesn't mean anything. just to show if there is communication at all. ;)

just troughing this two cents right now. Need to read everything else tomorrow.

golddragon007 commented 3 years ago

@Koenkk Here is an export for the Wireshark. The controller failed appr. 3 times under this time. ws.txt Now I think maybe the battery-powered Zigbee devices block the start of this?

Koenkk commented 3 years ago

Can you share the pcapng file and your nework key?

golddragon007 commented 3 years ago

Amm where can I find the pcapng? Amm it seems the program didn't create it, because there was no path... meh. I will redo it today.

golddragon007 commented 3 years ago

Well, I tried now, but it seems that it doesn't really catch too many messages... To be more precise, nothing from the coordinator. It's just failing... I can't see anything now, yesterday I've just reset all the battery-powered devices, now I can't see any message, except if I try to pair a device, you can see it here those requests: try-to-connect.zip The keys are defaults as the docs says.

Koenkk commented 3 years ago

Are you sure that non of the "Beacon requests" is from the slaesh stick?

When I start my slaesh stick (with the following fw: https://github.com/Koenkk/Z-Stack-firmware/blob/master/coordinator/Z-Stack_3.x.0/bin/CC2652RB_20200925.zip), a "Beacon request" is send by the stick (and this is expected behaviour).

image

Btw; also make sure there is no data/coordinator_backup.json file.

golddragon007 commented 3 years ago

Sorry if it wasn't clear. Yesterday I've cleared all the used battery devices. Now when I listened I've didn't catch any message from the slaesh stick. (like it doesn't use the antenna or I don't know. I've found the test python file, that @slaesh using, but that tests only the serial port and doesn't the Zigbee antenna or capability, at least it seems for me. With that it passed) To check somehow if the sniffing working, I've tried two devices pair, that's what you see in the file. I've always stopped z2m and deleted the full shared directory of the z2m. And I need to note that some cases it went into coordinator mode (booted up), but still, it wasn't able to connect any device to it. I can say now only two theory by this.

  1. The Zigbee antenna part doesn't work on both sticks (which is strange and statistically has a low chance, but not impossible)
  2. There's on some kind of programming bug in z2m or the firmware that makes to doesn't work the stick

I've tried to search for a different implementation for this to try it out if another software can make it work, but I didn't find yet. So at least I would be able to close out the hardware problem.

Koenkk commented 3 years ago

@golddragon007 you can try out Home Assistant ZHA, except the CC2652RB firmware, the whole stack is different.

golddragon007 commented 3 years ago

@Koenkk I've tried now to add it to ZHA and I can't even add it. This is the error message: "Unable to connect to ZHA device." Some logs:

2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.zigbee.application] Probing /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0 at 115200 baud
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0 serial port
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0 at 115200 baud
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.api] Sending special byte to skip the bootloader
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xEF'
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.Ping.Rsp(Capabilities=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future pending cb=[ZNP.wait_for_responses.<locals>.<lambda>() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:400, <TaskWakeupMethWrapper object at 0xa44892c8>()]>)
2020-10-10 14:12:26 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xFE\x00\x21\x01\x20'

2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.zigbee.application] Probing /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0 at 115200 baud
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0 serial port
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0 at 115200 baud
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.api] Sending special byte to skip the bootloader
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xEF'
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.Ping.Rsp(Capabilities=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future pending cb=[ZNP.wait_for_responses.<locals>.<lambda>() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:400, <TaskWakeupMethWrapper object at 0xa28c4538>()]>)
2020-10-10 14:13:19 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xFE\x00\x21\x01\x20'

2020-10-10 14:13:24 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.Ping.Rsp(Capabilities=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future cancelled>)
2020-10-10 14:13:24 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x00, subsystem=Subsystem.RPCError, type=CommandType.SRSP)
2020-10-10 14:13:24 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SRSP)
2020-10-10 14:13:24 DEBUG (MainThread) [zigpy_znp.api] There are 0 callbacks and 0 one-shot listeners remaining
2020-10-10 14:13:24 WARNING (MainThread) [zigpy_znp.zigbee.application] Failed to probe ZNP radio with config {'path': '/dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0', 'baudrate': 115200, 'flow_control': None}
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 467, in request
    response = await response_future
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 116, in probe
    await znp.connect()
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 210, in connect
    ping_rsp = await self.request(c.SYS.Ping.Req())
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 467, in request
    response = await response_future
  File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2020-10-10 14:13:24 DEBUG (MainThread) [zigpy_znp.api] We were disconnected from /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0: None
2020-10-10 14:13:24 DEBUG (MainThread) [zigpy_znp.uart] Closing /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_09_E4-if00-port0 serial port

If you see here a different mac, that's because I've tried also with my second stick...

Koenkk commented 3 years ago

@slaesh should the stick work with Home Assistant ZHA?

puddly commented 3 years ago

It should as of 0.116.0, which was released three days ago.

The above log is for an older release that did not toggle the DTR and RTS pins. I don't own the hardware but replicating the pin toggling you used in zigbee-herdsman made it work for another user (https://github.com/zha-ng/zigpy-znp/issues/35, https://github.com/zha-ng/zigpy-znp/pull/36).

golddragon007 commented 3 years ago

Yes, so now I've updated the HA and I was able to add the coordinator, now we look into why I can't pair a device to it.

golddragon007 commented 3 years ago

Same issue with zha like with z2m. It detects the coordinator, but can't start the network.

puddly commented 3 years ago

Solved by using a powered hub with the Raspberry Pi 4 that was also booting off of an m.2 SSD.

Interestingly, @golddragon007 said that a CC2531 was working just fine plugged into the same Pi so could it possibly be a power issue? The stick seems to become unresponsive right when the network is being formed, which is when Z-Stack should be performing a scan to find existing networks on the provided channel and may be momentarily drawing a lot of current.

golddragon007 commented 3 years ago

@Koenkk it seems you were 100% right. For some reason for this stick, it's not enough the power for the CC2652RB that the Pi can provide, but it's enough for the cc2531. My USB meter is on the way, once it will arrive I will do further analysis on this. With a USB hub that powered separately, it works without any issue now. We also tested on a windows machine the sticks before with the following way to see if we can do a scan:

# python 3.7+ requried
# With virtual env
$ pip install virtualenv
$ virtualenv -p python3
$ git clone https://github.com/zha-ng/zigpy-znp/
$ virtualenv -p python3 venv
$ source venv/bin/activate
(venv) $ pip install -e ./zigpy-znp/
(venv) $ python -m zigpy_znp.tools.nvram_reset -vvv -c /dev/serial/by-id/...
(venv) $ python -m zigpy_znp.tools.energy_scan -vvv /dev/serial/by-id/...

# Without virtual env
git clone https://github.com/zha-ng/zigpy-znp/
pip install -e ./zigpy-znp/
# For reset network.
python -m zigpy_znp.tools.nvram_reset -vvv -c /dev/serial/by-id/...
# For scan networks.
python -m zigpy_znp.tools.energy_scan -vvv /dev/serial/by-id/...

The received power is also enough to not drop or restart the CC2652RB, but it's not enough to fully run it... I will post here the readings once I will have any.

Koenkk commented 3 years ago

@golddragon007 great to hear you found the root cause. I've added this info to the FAQ.

golddragon007 commented 3 years ago

I've done the measures. In the end, it seems the cc2531 eats more than the cc2652rb, but also more resistant for the voltage drop. You can find the full here: Usb-measures.zip You need to download from here (https://www.avhzy.com/html/product-detail/ct3) the PC software (Windows only) if you want to check directly the measures, otherwise, there are BMP pictures inside the folder.

Also, I've done some changes, I use now the m.2 drive from the USB hub and I using ZigBee directly from the PI because it's really consumed normally all the power budget of the PI's USB port (and those peaks yuck). It works currently in this way too. But I will see if I need to move to the hub later on if I start stressing something...

Oh and I noticed that this cc2652rb hangs a bit the system, especially when z2m want to start up but the OS did not finish properly the mounting (I guess).

github-actions[bot] commented 3 years ago

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