It says “Error:Bridge”
I was using 3.2.0.M4
FYI - The last message I see from Zwave (after 30 minutes) is:
[DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
But nothing happens after that.
I’m going to try to revert to the previous release to see how that goes.
Strange - so to be clear, the error on the bridge is Error:Bridge? Or is this the error on the node things?
Yes, this was my point above - it starts to initialise the serial port, but then doesn’t log anything more. I’m assuming that this fails, in which case it should set an error message on the thing. However Error:Bridge would be strange.
So there will be no code changes then between the versions and the problem you’re having is unlikely to be related to the binding and is more likely a configuration issue. ie something else changed in the upgrade.
This is the Error when viewing the Things … Z-wave Serial Controller … in fact also ALL of the nodes show the same status.
Do you mean logging from another module … I only have Zwave DEBUG enabled.
The logging is done by the system when the state of the thing changes, and is also available in the UI.
I’m afraid I’ve no idea what’s wrong. As already said above, we see that it tries to open the port, but doesn’t appear to complete this. This seems largely impossible unless it’s throwing an exception, which would result in a communications error - but you have the error as Bridge. From what I can tell this is only set on startup, and so this presumably means something is stopping somewhere that “is not possible” - but is still happening.
Sorry - I’m not really sure how to proceed. I don’t think this is directly a binding issue as this code has not changed for a couple of years (the last code change in the serial handler was September 2020).
Thanks Chris …I think it might be some sort of conflict on the USB Port that zwave is attempting to access … it sometimes works fine (used to always work fine) … since it has nothing to do with the Zwave Binding (i.e. nothing has been changed there) … I’ll look at other configuration changes that I’ve done. Since its intermittent it could have gone unnoticed at first.
Thanks for your input!
Well this is very strange behavior. I can reboot the system multiple times and sometimes the Zwave Serial Controller Thing stays in “Error: Bridge” state … I wait for 60 minutes … nothing … other times it comes up normally. No other differences. What is causing this and open to suggestions to debug it. I have turned on DEBUG for Zwave and Chris has looked at it. The cases where it doesnt work seem to be when the zwave controller states:
[DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:0d28f614c7
Also last ZWave message seems to always be:
[DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
Any ideas on how to debug this? I have seen other posts describing similar but not identical problems.
Thanks Cplant … I tried deleting the lock file as you did but didn’t make any difference … but, I do think think it is somehow related.
In a normal case where the Zwave comes up (less than 50/50 now) … the debug log shows:
2022-08-01 17:32:35.298 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2022-08-01 17:32:35.321 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2022-08-01 17:32:35.331 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2022-08-01 17:32:35.331 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2022-08-01 17:32:35.333 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2022-08-01 17:32:35.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-08-01 17:32:35.394 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2022-08-01 17:32:35.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-08-01 17:32:35.396 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
However, in the failed case (just now) it shows only:
2022-08-02 15:58:41.420 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
And no other messages … so clearly it is not receiving any data from the Zwave device.
Are there any experts in this area that can comment? I have seen other threads talking about a recent issue with Serial Manager on OH3, but I have no idea if its related.
I have not tried the ser2net workaround … my problem is intermittent (sometimes works) … so not sure if it is the same isssue.
The only thing I thought of when I saw your post was check the output of dmesg on the Pi. Because it is dual Zigbee/Zwave I have no experience. For me if z-wave stick is not /dev/ttyACM0 it is a problem, but it sounds like it is normally /dev/ttyUSB0 for you.
Thanks Bob … not really sure what I’m looking for but it appears that the USB0 (and USB1) registered.
here’s the log:
openhabian@openhabian:~ $ dmesg
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 5.15.32-v7l+ (dom@buildbot) (arm-linux-gnueabihf-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1538 SMP Thu Mar 31 19:39:41 BST 2022
[ 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] random: fast init done
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] Reserved memory: created CMA memory pool at 0x000000002ac00000, size 64 MiB
[ 0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[ 0.000000] Zone ranges:
[ 0.000000] DMA [mem 0x0000000000000000-0x000000002fffffff]
[ 0.000000] Normal empty
[ 0.000000] HighMem [mem 0x0000000030000000-0x00000000fbffffff]
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000000000-0x000000003e5fffff]
[ 0.000000] node 0: [mem 0x0000000040000000-0x00000000fbffffff]
[ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff]
[ 0.000000] On node 0, zone HighMem: 512 pages in unavailable ranges
[ 0.000000] percpu: Embedded 16 pages/cpu s35788 r8192 d21556 u65536
[ 0.000000] pcpu-alloc: s35788 r8192 d21556 u65536 alloc=16*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1023808
[ 0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=0 bcm2708_fb.fbheight=0 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:46:06:EB vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000 console=ttyS0,115200 console=tty1 root=PARTUUID=51a6517f-02 rootfstype=ext4 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] software IO TLB: mapped [mem 0x0000000024890000-0x0000000028890000] (64MB)
[ 0.000000] Memory: 3914716K/4102144K available (10240K kernel code, 1390K rwdata, 3292K rodata, 2048K init, 590K bss, 121892K reserved, 65536K cma-reserved, 3315712K highmem)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] ftrace: allocating 35355 entries in 104 pages
[ 0.000000] ftrace: allocated 104 pages with 3 groups
[ 0.000000] trace event string verifier disabled
[ 0.000000] rcu: Hierarchical RCU implementation.
[ 0.000000] Rude variant of Tasks RCU enabled.
[ 0.000000] Tracing variant of Tasks RCU enabled.
[ 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+0x574/0x758 with crng_init=1
[ 0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[ 0.000001] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[ 0.000022] Switching to timer-based delay loop, resolution 18ns
[ 0.000309] Console: colour dummy device 80x30
[ 0.001032] printk: console [tty1] enabled
[ 0.001109] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
[ 0.001162] pid_max: default: 32768 minimum: 301
[ 0.001315] LSM: Security Framework initializing
[ 0.001468] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.001515] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.003077] cgroup: Disabling memory control group subsystem
[ 0.003330] CPU: Testing write buffer coherency: ok
[ 0.003407] CPU0: Spectre BHB: using loop workaround
[ 0.003853] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.005080] Setting up static identity map for 0x200000 - 0x20003c
[ 0.005303] rcu: Hierarchical SRCU implementation.
[ 0.006243] smp: Bringing up secondary CPUs ...
[ 0.007419] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.007436] CPU1: Spectre BHB: using loop workaround
[ 0.008756] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.008774] CPU2: Spectre BHB: using loop workaround
[ 0.010105] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.010122] CPU3: Spectre BHB: using loop workaround
[ 0.010307] smp: Brought up 1 node, 4 CPUs
[ 0.010343] SMP: Total of 4 processors activated (432.00 BogoMIPS).
[ 0.010377] CPU: All CPU(s) started in HYP mode.
[ 0.010403] CPU: Virtualization extensions available.
[ 0.011195] devtmpfs: initialized
[ 0.026305] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
[ 0.026542] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.026598] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[ 0.028546] pinctrl core: initialized pinctrl subsystem
[ 0.029843] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[ 0.034241] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.035025] audit: initializing netlink subsys (disabled)
[ 0.035294] audit: type=2000 audit(0.030:1): state=initialized audit_enabled=0 res=1
[ 0.035891] thermal_sys: Registered thermal governor 'step_wise'
[ 0.036623] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.036681] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.037079] Serial: AMBA PL011 UART driver
[ 0.047563] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[ 0.070028] raspberrypi-firmware soc:firmware: Attached to firmware from 2022-03-24T13:19:43, variant start_cd
[ 0.080039] raspberrypi-firmware soc:firmware: Firmware hash is e5a963efa66a1974127860b42e913d2374139ff5
[ 0.137589] Kprobes globally optimized
[ 0.143117] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1
[ 0.147502] vgaarb: loaded
[ 0.147965] SCSI subsystem initialized
[ 0.148206] usbcore: registered new interface driver usbfs
[ 0.148284] usbcore: registered new interface driver hub
[ 0.148372] usbcore: registered new device driver usb
[ 0.148722] usb_phy_generic phy: supply vcc not found, using dummy regulator
[ 0.149233] pps_core: LinuxPPS API ver. 1 registered
[ 0.149264] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[ 0.149314] PTP clock support registered
[ 0.151428] clocksource: Switched to clocksource arch_sys_counter
[ 0.232141] VFS: Disk quotas dquot_6.6.0
[ 0.232268] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.232466] FS-Cache: Loaded
[ 0.232662] CacheFiles: Loaded
[ 0.241809] NET: Registered PF_INET protocol family
[ 0.242072] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
[ 0.243678] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[ 0.243736] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[ 0.243824] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[ 0.243914] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.244089] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 0.244146] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 0.244420] NET: Registered PF_UNIX/PF_LOCAL protocol family
[ 0.245457] RPC: Registered named UNIX socket transport module.
[ 0.245493] RPC: Registered udp transport module.
[ 0.245521] RPC: Registered tcp transport module.
[ 0.245548] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.245584] PCI: CLS 0 bytes, default 64
[ 1.103260] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[ 1.105613] Initialise system trusted keyrings
[ 1.105880] workingset: timestamp_bits=14 max_order=20 bucket_order=6
[ 1.114868] zbud: loaded
[ 1.116828] FS-Cache: Netfs 'nfs' registered for caching
[ 1.117726] NFS: Registering the id_resolver key type
[ 1.117784] Key type id_resolver registered
[ 1.117813] Key type id_legacy registered
[ 1.117971] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[ 1.118003] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[ 1.119101] Key type asymmetric registered
[ 1.119134] Asymmetric key parser 'x509' registered
[ 1.119378] bounce: pool size: 64 pages
[ 1.119454] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[ 1.119709] io scheduler mq-deadline registered
[ 1.119742] io scheduler kyber registered
[ 1.128254] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[ 1.128317] brcm-pcie fd500000.pcie: No bus range found for /scb/pcie@7d500000, using [bus 00-ff]
[ 1.128432] brcm-pcie fd500000.pcie: MEM 0x0600000000..0x063fffffff -> 0x00c0000000
[ 1.128545] brcm-pcie fd500000.pcie: IB MEM 0x0000000000..0x00bfffffff -> 0x0400000000
[ 1.183534] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC)
[ 1.183937] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[ 1.183974] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 1.184010] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff])
[ 1.184122] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[ 1.184384] pci 0000:00:00.0: PME# supported from D0 D3hot
[ 1.188100] PCI: bus0: Fast back to back transfers disabled
[ 1.188453] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[ 1.188598] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[ 1.189049] pci 0000:01:00.0: PME# supported from D0 D3cold
[ 1.192794] PCI: bus1: Fast back to back transfers disabled
[ 1.192869] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[ 1.192911] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[ 1.193016] pci 0000:00:00.0: PCI bridge to [bus 01]
[ 1.193055] pci 0000:00:00.0: bridge window [mem 0x600000000-0x6000fffff]
[ 1.193491] pcieport 0000:00:00.0: enabling device (0140 -> 0142)
[ 1.193729] pcieport 0000:00:00.0: PME: Signaling with IRQ 57
[ 1.195174] bcm2708_fb soc:fb: Unable to determine number of FBs. Disabling driver.
[ 1.195215] bcm2708_fb: probe of soc:fb failed with error -2
[ 1.203340] iproc-rng200 fe104000.rng: hwrng registered
[ 1.203673] vc-mem: phys_addr:0x00000000 mem_base=0x3f000000 mem_size:0x3f600000(1014 MiB)
[ 1.205074] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[ 1.218135] brd: module loaded
[ 1.228604] loop: module loaded
[ 1.229310] Loading iSCSI transport class v2.0-870.
[ 1.234400] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000
[ 1.341593] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus
[ 1.342825] usbcore: registered new interface driver r8152
[ 1.342912] usbcore: registered new interface driver lan78xx
[ 1.342990] usbcore: registered new interface driver smsc95xx
[ 1.344608] xhci_hcd 0000:01:00.0: enabling device (0140 -> 0142)
[ 1.344792] xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 1.344843] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[ 1.350577] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x00003c0000000890
[ 1.351993] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.15
[ 1.352041] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.352080] usb usb1: Product: xHCI Host Controller
[ 1.352110] usb usb1: Manufacturer: Linux 5.15.32-v7l+ xhci-hcd
[ 1.352141] usb usb1: SerialNumber: 0000:01:00.0
[ 1.352928] hub 1-0:1.0: USB hub found
[ 1.353042] hub 1-0:1.0: 1 port detected
[ 1.353737] xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 1.353781] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[ 1.353826] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[ 1.354331] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.15
[ 1.354375] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.354413] usb usb2: Product: xHCI Host Controller
[ 1.354442] usb usb2: Manufacturer: Linux 5.15.32-v7l+ xhci-hcd
[ 1.354473] usb usb2: SerialNumber: 0000:01:00.0
[ 1.355221] hub 2-0:1.0: USB hub found
[ 1.355332] hub 2-0:1.0: 4 ports detected
[ 1.357052] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 1.357364] dwc_otg: FIQ enabled
[ 1.357378] dwc_otg: NAK holdoff enabled
[ 1.357391] dwc_otg: FIQ split-transaction FSM enabled
[ 1.357409] Module dwc_common_port init
[ 1.357855] usbcore: registered new interface driver uas
[ 1.357980] usbcore: registered new interface driver usb-storage
[ 1.358239] mousedev: PS/2 mouse device common for all mice
[ 1.362896] sdhci: Secure Digital Host Controller Interface driver
[ 1.362933] sdhci: Copyright(c) Pierre Ossman
[ 1.363541] sdhci-pltfm: SDHCI platform and OF driver helper
[ 1.367156] ledtrig-cpu: registered to indicate activity on CPUs
[ 1.367626] hid: raw HID events driver (C) Jiri Kosina
[ 1.367813] usbcore: registered new interface driver usbhid
[ 1.367845] usbhid: USB HID core driver
[ 1.373863] Initializing XFRM netlink socket
[ 1.373943] NET: Registered PF_PACKET protocol family
[ 1.374074] Key type dns_resolver registered
[ 1.374497] Registering SWP/SWPB emulation handler
[ 1.375313] registered taskstats version 1
[ 1.375357] Loading compiled-in X.509 certificates
[ 1.376185] Key type ._fscrypt registered
[ 1.376217] Key type .fscrypt registered
[ 1.376244] Key type fscrypt-provisioning registered
[ 1.387960] uart-pl011 fe201000.serial: there is not valid maps for state default
[ 1.388295] uart-pl011 fe201000.serial: cts_event_workaround enabled
[ 1.388437] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 32, base_baud = 0) is a PL011 rev2
[ 1.397767] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[ 1.398303] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[ 1.399620] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[ 1.399659] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[ 1.430842] of_cfs_init
[ 1.431141] of_cfs_init: OK
[ 1.466659] mmc0: SDHCI controller on fe340000.mmc [fe340000.mmc] using ADMA
[ 1.467078] Waiting for root device PARTUUID=51a6517f-02...
[ 1.518514] mmc1: new high speed SDIO card at address 0001
[ 1.566054] mmc0: new ultra high speed DDR50 SDHC card at address 0001
[ 1.567032] mmcblk0: mmc0:0001 GB1QT 29.8 GiB
[ 1.570203] mmcblk0: p1 p2
[ 1.570776] mmcblk0: mmc0:0001 GB1QT 29.8 GiB
[ 1.591362] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none.
[ 1.591552] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 1.596862] devtmpfs: mounted
[ 1.608173] Freeing unused kernel image (initmem) memory: 2048K
[ 1.621763] Run /sbin/init as init process
[ 1.621795] with arguments:
[ 1.621808] /sbin/init
[ 1.621821] with environment:
[ 1.621833] HOME=/
[ 1.621846] TERM=linux
[ 1.641474] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[ 1.824417] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[ 1.824477] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 1.824515] usb 1-1: Product: USB2.0 Hub
[ 1.827243] hub 1-1:1.0: USB hub found
[ 1.827602] hub 1-1:1.0: 4 ports detected
[ 1.971546] systemd[1]: System time before build time, advancing clock.
[ 2.080220] NET: Registered PF_INET6 protocol family
[ 2.081881] Segment Routing with IPv6
[ 2.081942] In-situ OAM (IOAM) with IPv6
[ 2.139972] systemd[1]: systemd 247.3-7+rpi1 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)
[ 2.140926] systemd[1]: Detected architecture arm.
[ 2.149320] systemd[1]: Set hostname to <openhabian>.
[ 2.171491] usb 1-1.4: new full-speed USB device number 3 using xhci_hcd
[ 2.308942] usb 1-1.4: New USB device found, idVendor=10c4, idProduct=8a2a, bcdDevice= 1.00
[ 2.309014] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=5
[ 2.309055] usb 1-1.4: Product: HubZ Smart Home Controller
[ 2.309089] usb 1-1.4: Manufacturer: Silicon Labs
[ 2.309119] usb 1-1.4: SerialNumber: C130049D
[ 3.074960] systemd[1]: Queued start job for default target Multi-User System.
[ 3.076705] random: systemd: uninitialized urandom read (16 bytes read)
[ 3.080889] systemd[1]: Created slice system-modprobe.slice.
[ 3.081758] random: systemd: uninitialized urandom read (16 bytes read)
[ 3.082861] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[ 3.083348] random: systemd: uninitialized urandom read (16 bytes read)
[ 3.084178] systemd[1]: Created slice User and Session Slice.
[ 3.085010] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[ 3.085782] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 3.087255] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 3.087898] systemd[1]: Reached target Local Encrypted Volumes.
[ 3.088596] systemd[1]: Reached target Network (Pre).
[ 3.089077] systemd[1]: Reached target Paths.
[ 3.089652] systemd[1]: Reached target Slices.
[ 3.090196] systemd[1]: Reached target Swap.
[ 3.091947] systemd[1]: Listening on Syslog Socket.
[ 3.093048] systemd[1]: Listening on fsck to fsckd communication Socket.
[ 3.093797] systemd[1]: Listening on initctl Compatibility Named Pipe.
[ 3.095228] systemd[1]: Listening on Journal Audit Socket.
[ 3.096330] systemd[1]: Listening on Journal Socket (/dev/log).
[ 3.097607] systemd[1]: Listening on Journal Socket.
[ 3.099054] systemd[1]: Listening on udev Control Socket.
[ 3.100201] systemd[1]: Listening on udev Kernel Socket.
[ 3.101365] systemd[1]: Condition check resulted in Huge Pages File System being skipped.
[ 3.106885] systemd[1]: Mounting POSIX Message Queue File System...
[ 3.113367] systemd[1]: Mounting RPC Pipe File System...
[ 3.121219] systemd[1]: Mounting Kernel Debug File System...
[ 3.129057] systemd[1]: Mounting Kernel Trace File System...
[ 3.130212] systemd[1]: Condition check resulted in Kernel Module supporting RPCSEC_GSS being skipped.
[ 3.140317] systemd[1]: Starting Restore / save the current clock...
[ 3.149965] systemd[1]: Starting Set the console keyboard layout...
[ 3.158238] systemd[1]: Starting Create list of static device nodes for the current kernel...
[ 3.167342] systemd[1]: Starting Load Kernel Module configfs...
[ 3.176051] systemd[1]: Starting Load Kernel Module drm...
[ 3.195804] systemd[1]: Starting Load Kernel Module fuse...
[ 3.202789] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[ 3.209792] systemd[1]: Starting File System Check on Root Device...
[ 3.223442] systemd[1]: Starting Journal Service...
[ 3.249041] systemd[1]: Starting Load Kernel Modules...
[ 3.257813] systemd[1]: Starting Coldplug All udev Devices...
[ 3.259838] fuse: init (API version 7.34)
[ 3.289700] systemd[1]: Mounted POSIX Message Queue File System.
[ 3.290714] systemd[1]: Mounted RPC Pipe File System.
[ 3.295049] systemd[1]: Mounted Kernel Debug File System.
[ 3.297580] systemd[1]: Mounted Kernel Trace File System.
[ 3.307078] systemd[1]: Finished Restore / save the current clock.
[ 3.320189] systemd[1]: Finished Create list of static device nodes for the current kernel.
[ 3.325062] systemd[1]: modprobe@configfs.service: Succeeded.
[ 3.326801] systemd[1]: Finished Load Kernel Module configfs.
[ 3.329216] systemd[1]: modprobe@drm.service: Succeeded.
[ 3.330687] systemd[1]: Finished Load Kernel Module drm.
[ 3.332973] systemd[1]: modprobe@fuse.service: Succeeded.
[ 3.336485] systemd[1]: Finished Load Kernel Module fuse.
[ 3.341465] systemd[1]: Finished Load Kernel Modules.
[ 3.352696] systemd[1]: Mounting FUSE Control File System...
[ 3.363637] systemd[1]: Mounting Kernel Configuration File System...
[ 3.371159] systemd[1]: Started File System Check Daemon to report status.
[ 3.387782] systemd[1]: Starting Apply Kernel Variables...
[ 3.405532] systemd[1]: Mounted FUSE Control File System.
[ 3.406586] systemd[1]: Mounted Kernel Configuration File System.
[ 3.469007] systemd[1]: Finished Apply Kernel Variables.
[ 3.498516] systemd[1]: Finished File System Check on Root Device.
[ 3.504605] systemd[1]: Starting Remount Root and Kernel File Systems...
[ 3.620339] systemd[1]: Started Journal Service.
[ 3.702756] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null). Quota mode: none.
[ 3.771539] systemd-journald[136]: Received client request to flush runtime journal.
[ 3.786997] systemd-journald[136]: File /var/log/journal/25070aeb79f44c94a7f7bcc85e4ba968/system.journal corrupted or uncleanly shut down, renaming and replacing.
[ 4.602278] rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x00010000
[ 4.621900] rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00001000
[ 4.633656] rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x00010000
[ 4.677459] rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x00010000
[ 4.769321] mc: Linux media interface: v0.10
[ 4.803783] videodev: Linux video capture interface: v2.00
[ 4.821329] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.830296] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.830327] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[ 4.830353] [vc_sm_connected_init]: start
[ 4.846616] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.847468] vc_sm_cma_vchi_init: failed to open VCHI service (-1)
[ 4.847489] [vc_sm_connected_init]: failed to initialize shared memory service
[ 4.855780] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.855781] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.862715] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.864335] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.875764] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
[ 4.886807] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
[ 4.886998] : Unregister from media controller
[ 4.887017] (efault): Unregistering node (null)[0] device node /dev/video0
[ 4.887036] (efault): Unregistering node (null)[0] device node /dev/video0
[ 4.887053] (efault): Unregistering node (null)[0] device node /dev/video0
[ 4.887070] (efault): Unregistering node (null)[0] device node /dev/video0
[ 4.925664] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.934042] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[ 4.940263] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
[ 4.959750] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[ 4.972804] bcm2835_audio bcm2835_audio: card created with 8 channels
[ 4.979947] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[ 4.992636] cfg80211: loaded regulatory.db is malformed or signature is missing/invalid
[ 5.080891] brcmfmac: F1 signature read @0x18000000=0x15264345
[ 5.148710] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[ 5.150112] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43455-sdio.raspberrypi,4-model-b.bin failed with error -2
[ 5.152954] usbcore: registered new interface driver brcmfmac
[ 5.442741] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[ 5.442930] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[ 5.457632] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241 (1a2f2fa CY) FWID 01-703fd60
[ 5.467320] usbcore: registered new interface driver usbserial_generic
[ 5.467406] usbserial: USB Serial support registered for generic
[ 5.474344] usbcore: registered new interface driver cp210x
[ 5.474645] usbserial: USB Serial support registered for cp210x
[ 5.474831] cp210x 1-1.4:1.0: cp210x converter detected
[ 5.482096] usb 1-1.4: cp210x converter now attached to ttyUSB0
[ 5.482337] cp210x 1-1.4:1.1: cp210x converter detected
[ 5.495682] usb 1-1.4: cp210x converter now attached to ttyUSB1
[ 6.770889] 8021q: 802.1Q VLAN Support v1.8
[ 6.771519] random: crng init done
[ 6.771539] random: 7 urandom warning(s) missed due to ratelimiting
[ 7.006040] uart-pl011 fe201000.serial: no DMA platform data
[ 7.179894] Adding 2097148k swap on /var/swap. Priority:-2 extents:9 across:2777084k SSFS
[ 7.351563] zram: Added device: zram0
[ 7.359748] zram0: detected capacity change from 0 to 2097152
[ 7.467905] Adding 1048572k swap on /dev/zram0. Priority:75 extents:1 across:1048572k SSFS
[ 7.499292] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 7.850166] bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay)
[ 7.852292] bcmgenet fd580000.ethernet eth0: Link is Down
[ 8.464891] systemd-journald[136]: Received client request to flush runtime journal.
[ 8.710182] systemd-journald[136]: Received SIGTERM from PID 1 (systemd).
[ 8.710749] systemd[1]: Stopping Journal Service...
[ 8.809865] systemd[1]: systemd-journald.service: Succeeded.
[ 8.811502] systemd[1]: Stopped Journal Service.
[ 8.842289] systemd[1]: systemd-journald-audit.socket: Succeeded.
[ 8.843759] systemd[1]: Closed Journal Audit Socket.
[ 8.845783] systemd[1]: systemd-journald-dev-log.socket: Succeeded.
[ 8.847116] systemd[1]: Closed Journal Socket (/dev/log).
[ 8.849341] systemd[1]: systemd-journald.socket: Succeeded.
[ 8.850936] systemd[1]: Closed Journal Socket.
[ 8.875566] zram: Added device: zram1
[ 8.937374] zram1: detected capacity change from 0 to 1536000
[ 9.043094] EXT4-fs (zram1): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none.
[ 9.076107] systemd[615]: tailscaled.service: Failed to connect stdout to the journal socket, ignoring: Connection refused
[ 9.255627] tun: Universal TUN/TAP device driver, 1.6
[ 9.456253] systemd[1]: Started Tailscale node agent.
[ 9.894777] zram: Added device: zram2
[ 9.919361] zram2: detected capacity change from 0 to 2097152
[ 10.035586] EXT4-fs (zram2): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none.
[ 10.124781] systemd[1]: Listening on Journal Socket.
[ 10.131922] systemd[1]: Listening on Journal Audit Socket.
[ 10.139070] systemd[1]: Listening on Journal Socket (/dev/log).
[ 10.178772] systemd[1]: Listening on Syslog Socket.
[ 11.312329] systemd[1]: systemd-rfkill.service: Succeeded.
[ 11.991767] bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx
[ 11.991829] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 12.008173] systemd[1]: Starting Journal Service...
[ 12.380909] systemd[1]: Started Journal Service.
[ 13.479292] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 13.794463] Bluetooth: Core ver 2.22
[ 13.794578] NET: Registered PF_BLUETOOTH protocol family
[ 13.794594] Bluetooth: HCI device and connection manager initialized
[ 13.794623] Bluetooth: HCI socket layer initialized
[ 13.794645] Bluetooth: L2CAP socket layer initialized
[ 13.794679] Bluetooth: SCO socket layer initialized
[ 13.804576] Bluetooth: HCI UART driver ver 2.3
[ 13.804603] Bluetooth: HCI UART protocol H4 registered
[ 13.804709] Bluetooth: HCI UART protocol Three-wire (H5) registered
[ 13.805017] Bluetooth: HCI UART protocol Broadcom registered
[ 14.331979] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[ 14.332005] Bluetooth: BNEP filters: protocol multicast
[ 14.332033] Bluetooth: BNEP socket layer initialized
[ 14.359524] NET: Registered PF_ALG protocol family
[ 14.404776] cryptd: max_cpu_qlen set to 1000
[ 31.834961] cam-dummy-reg: disabling
Looks okay to me too.
Tends to imply it is OH related somewhere. Sorry I could not be of more help.
Thanks Andrew -
I updated the system using the openhabian-config tool to the latest SNAPSHOT … I ended up with openHAB 3.4.0 Build #3029. The above link says build 3.3.0 but is that a typo?
Anyway, after updating and restarting, I got a slew of Zigbee errors (see below) … will reboot to see if it repeats. Rebooted … system is slowly coming up … it takes about 30 minutes for the Zigbee devices to all come ONLINE (I have ~50 devices), then the ZWave devices follow … so far so good. Ok, all the zigbee devices came up but the Zwave devices are all in Error:Bridge … same as before 
I had high hopes! Zwave DEBUG was not on so I dont know if its the same (seems likely)
I’ll take another stab at it tomorrow with DEBUG enabled.
==> /var/log/openhab/openhab.log <==
2022-08-02 20:28:38.836 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterMeteringSummationDelivered.initializeDevice(ZigBeeConverterMeteringSummationDelivered.java:76) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:260) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.854 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - null: Exception creating channels
java.lang.NullPointerException: null
at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNetworkManager.getNode(ZigBeeNetworkManager.java:1646) ~[bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.getNode(ZigBeeCoordinatorHandler.java:992) ~[bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.createZigBeeChannelConverter(ZigBeeThingHandler.java:525) ~[bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:385) [bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) [bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [bundleFile:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.833 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - null: Exception getting binding table
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:445) [bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) [bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [bundleFile:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.lang.NullPointerException
at com.zsmartsystems.zigbee.ZigBeeNode$1.call(ZigBeeNode.java:465) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNode$1.call(ZigBeeNode.java:454) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
... 1 more
2022-08-02 20:28:38.818 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - null: Exception getting binding table
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:445) [bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) [bundleFile:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [bundleFile:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.lang.NullPointerException
at com.zsmartsystems.zigbee.ZigBeeNode$1.call(ZigBeeNode.java:465) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNode$1.call(ZigBeeNode.java:454) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
... 1 more
2022-08-02 20:28:38.836 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff.initializeDevice(ZigBeeConverterSwitchOnoff.java:105) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:260) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.828 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.836 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at com.zsmartsystems.zigbee.zcl.ZclCluster.readSync(ZclCluster.java:1727) ~[?:?]
at com.zsmartsystems.zigbee.zcl.clusters.ZclBasicCluster.getStackVersion(ZclBasicCluster.java:393) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:204) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.934 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.825 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at com.zsmartsystems.zigbee.zcl.ZclCluster.readSync(ZclCluster.java:1727) ~[?:?]
at com.zsmartsystems.zigbee.zcl.clusters.ZclBasicCluster.getDateCode(ZclBasicCluster.java:673) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:222) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.900 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNetworkManager.getNode(ZigBeeNetworkManager.java:1646) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.getNode(ZigBeeCoordinatorHandler.java:992) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:238) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.909 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNetworkManager.getNode(ZigBeeNetworkManager.java:1646) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.getNode(ZigBeeCoordinatorHandler.java:992) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:238) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.794 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNetworkManager.getNode(ZigBeeNetworkManager.java:1646) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.getNodeEndpoints(ZigBeeCoordinatorHandler.java:885) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:266) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.949 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.951 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-08-02 20:28:38.958 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Done.
Well, I restarted the system with Zwave DEBUG enabled … and it shows the exact same symptom: Zwave hung up after connecting to the serial port:
2022-08-03 06:35:20.753 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Controller handler not found. Cannot handle command without ZWave controller.
2022-08-03 06:35:56.158 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:0d28f614c7:node10:thermostat_setpoint_heating --> 58 °F [QuantityType]
2022-08-03 06:35:56.159 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller handler not found. Cannot handle command without ZWave controller.
2022-08-03 07:02:21.029 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2022-08-03 07:10:58.868 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:0d28f614c7:node8:lock_door --> ON [OnOffType]
2022-08-03 07:10:58.870 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller handler not found. Cannot handle command without ZWave controller.
So, looking for other suggestions that might be causing this intermittent but very repeatable problem.
No solution, but what looks odd is the timing for this
There are three INFO level Zwave binding messages on startup
> 2021-07-28 10:57:17.006 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
> 2021-07-28 10:57:22.260 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
> 2021-07-28 10:57:22.264 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
and the Connecting to serial port ‘/dev/ttyxxxx’ normally occurs between the first and the second INFO or about 5 seconds. I do not see the first INFO in your posted log, but the Connection appears 27 minutes later??.
I found a debug startup from someone else I had on my machine. Note timing of Connection… and the three INFO logs:
> 2021-12-05 19:57:13.106 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
> 2021-12-05 19:57:13.483 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
> 2021-12-05 19:57:13.487 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:c0f0908e.
> 2021-12-05 19:57:13.707 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node24.
> 2021-12-05 19:57:13.718 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node13.
> 2021-12-05 19:57:13.739 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node40.
> 2021-12-05 19:57:13.744 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node23.
> 2021-12-05 19:57:13.764 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node11.
> 2021-12-05 19:57:13.802 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node14.
> 2021-12-05 19:57:13.816 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node37.
> 2021-12-05 19:57:13.833 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node16.
> 2021-12-05 19:57:13.849 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node27.
> 2021-12-05 19:57:13.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node33.
> 2021-12-05 19:57:13.880 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node6.
> 2021-12-05 19:57:13.894 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node7.
> 2021-12-05 19:57:18.507 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
> 2021-12-05 19:57:18.523 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
> 2021-12-05 19:57:18.535 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
> 2021-12-05 19:57:18.535 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
> 2021-12-05 19:57:18.538 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
> 2021-12-05 19:57:18.627 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
> 2021-12-05 19:57:18.627 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
> 2021-12-05 19:57:18.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
> 2021-12-05 19:57:18.630 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
Edit: Found another example (edited just for the controller items)
> 2022-08-02 11:34:08.239 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:71512f5b78 with scan time of 60
> 2022-08-02 11:34:08.260 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:71512f5b78
> 2022-08-02 11:34:08.264 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
> 2022-08-02 11:34:08.659 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
> 2022-08-02 11:34:08.662 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:71512f5b78.
> 2022-08-02 11:34:13.724 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
> 2022-08-02 11:34:13.766 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
> 2022-08-02 11:34:13.779 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
> 2022-08-02 11:34:13.782 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
> 2022-08-02 11:34:13.784 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
> 2022-08-02 11:34:13.866 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
> 2022-08-02 11:34:13.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
> 2022-08-02 11:34:13.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
> 2022-08-02 11:34:13.868 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
Again about 5 seconds
Yes the whole process of Zigbee and then Zwave takes 30-45 minutes to complete … something that is unacceptable but I have not found a solution for. I my case it seems that the Zwave doesn’t attempt to open the serial port until near the end of the 50 Zigbee devices coming ONLINE. I have no idea why.
FYI - I found in the Github issue the exact scenario I am having. It was purported to be fixed, but clearly it has not (perhaps there are multiple instantiations of the serial driver issue) … anyway, I’ve logged my issue on Github with the relevant log parts.
See: Serial ports getting blocked after some re-connecting · Issue #1842 · openhab/openhab-core · GitHub
I can only wish for this 
Do some people have separate Zwave and Zigbee sticks? Is there an inference issue with doing that or will that cause more problems than you have already 
?
I’ve considered that … but this is a fairly popular stick … I could disable the Zwave to see if affects zigbee (sort of doubt it would have that dramatic effect, but you never know)