Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

OH3 zwave continous initialization errors, queue full messages, going offline, and no (user) data going out the radio #1501

Closed
TheKorn2 opened this issue Jan 7, 2021 · 3 comments
Closed

OH3 zwave continous initialization errors, queue full messages, going offline, and no (user) data going out the radio #1501

TheKorn2 opened this issue Jan 7, 2021 · 3 comments

Comments

@TheKorn2
Copy link

TheKorn2 commented Jan 7, 2021

OH 3.1.0-SNAPSHOT (#2115) , though similar behavior seen with 3.0 on this hardware. (That's why I tried the snapshot!)

In short, no joy in mudville. The binding keeps warning about queue full messages, then the binding crashes during initialization (on different devices), and after 30 minutes of this repeating song and dance still no user data can get out the radio.

Controller is an aeon z-stick 5.

I have a parallel installation of openhab 1.8 (not running at the same time, obviously!) that works very well with all this hardware. I shut down OH1.8, start up OH3.1, and then the fit hits the shan.

Full debug log file from startup, along with a full zwave radio sniff available here: www dot thekorn dot net/temp/zwave_2021-01-06_log_and_sniff.zip

Here are some highlights from the log file...

2021-01-06 11:20:14.851 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread.
java.lang.IllegalStateException: Queue full
        at java.util.AbstractQueue.add(AbstractQueue.java:98) ~[?:?]
        at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:326) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:447) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1078) ~[bundleFile:?]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:445) ~[bundleFile:?]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:363) [bundleFile:?]
2021-01-06 11:20:14.880 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
(snip)
2021-01-06 11:20:14.908 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Stopping ZWave network
2021-01-06 11:20:14.909 [DEBUG] [ve.internal.protocol.ZWaveController] - Shutting down ZWave controller
2021-01-06 11:20:14.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Shutting down transaction manager
2021-01-06 11:20:15.481 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 214: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@57ed715b[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1Tran
sactionWaiter@3ff9f5b7] rejected from java.util.concurrent.ThreadPoolExecutor@e0cccb5[Shutting down, pool size = 137, active threads = 137, queued tasks = 0, completed tasks = 52]
        at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1355) ~[?:?]
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:291) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:378) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
2021-01-06 11:20:19.913 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWave Transaction manager failed to terminate properly, forcing shutdown
2021-01-06 11:20:20.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction manager shutdown
2021-01-06 11:20:19.922 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction exception
java.util.concurrent.ExecutionException: java.lang.InterruptedException
        at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
        at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) [bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:291) [bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) [bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:378) [bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
Caused by: java.lang.InterruptedException

(snip)

2021-01-06 11:21:59.870 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread.
java.lang.IllegalStateException: Queue full
        at java.util.AbstractQueue.add(AbstractQueue.java:98) ~[?:?]
        at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:326) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:447) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1078) ~[bundleFile:?]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:445) ~[bundleFile:?]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:427) [bundleFile:?]
2021-01-06 11:21:59.872 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
2021-01-06 11:21:59.877 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller status changed to OFFLINE.
2021-01-06 11:21:59.880 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Stopping ZWave network
2021-01-06 11:21:59.880 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 196: Controller status changed to OFFLINE.
2021-01-06 11:21:59.880 [DEBUG] [ve.internal.protocol.ZWaveController] - Shutting down ZWave controller
2021-01-06 11:21:59.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Shutting down transaction manager
2021-01-06 11:21:59.883 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 196: Controller is not online.
2021-01-06 11:21:59.885 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 91: Controller status changed to OFFLINE.
2021-01-06 11:21:59.887 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 91: Controller is not online.
2021-01-06 11:21:59.888 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 103: Controller status changed to OFFLINE.
2021-01-06 11:21:59.889 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller is not online.
2021-01-06 11:21:59.889 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 103: Controller is not online.
2021-01-06 11:22:00.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@47f73904
2021-01-06 11:22:00.229 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 190: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@76ccf2ad[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1Tran
sactionWaiter@80dc5b1] rejected from java.util.concurrent.ThreadPoolExecutor@39cf2f61[Shutting down, pool size = 137, active threads = 137, queued tasks = 0, completed tasks = 43]
        at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1355) ~[?:?]
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:291) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:378) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
2021-01-06 11:22:04.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWave Transaction manager failed to terminate properly, forcing shutdown
2021-01-06 11:22:04.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction exception
java.util.concurrent.ExecutionException: java.lang.InterruptedException
        at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
        at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) [bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:291) [bundleFile:?]

And it keeps going forever and ever.

If you need anything else to help debug, I'm more than happy to provide it!
@5iver
Copy link

5iver commented Jan 14, 2021

See #1178. Try disabling the daily heal and restarting OH. This is a workaround until the binding is refactored.

@TheKorn2
Copy link
Author

Thanks for the suggestion! I disabled healing entirely, shut down OH3, and restarted it. Unfortunately it appears that my issue is unrelated, as there was no change in behavior. For fun I (case insensitive) grepped the zwave log against "heal", and no mentions of it come up. (Besides it's dying right away, within a minute of startup, so kind of doubt there'd even be time to heal since initialization never completes.)

Don't know what's causing it, but it looks like a queue overflow to be the primary trigger. Now the obvious question is begged, "Why is the queue overflowing?" (I know I know, it's easy to ask the questions, difficult to answer them!)

2021-01-15 04:11:43.873 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 B8 0E 32 02 21 44 00 00 0B 14 00 00 00 00 00 00 13 2021-01-15 04:11:43.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 125<>3 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=184, callback =0, payload=00 B8 0E 32 02 21 44 00 00 0B 14 00 00 00 00 00 00 2021-01-15 04:11:44.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@2efaa35d 2021-01-15 04:11:44.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 179 to queue - size 137 2021-01-15 04:11:44.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2021-01-15 04:11:45.109 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 42: Timeout at state WAIT_RESPONSE. 3 retries remaining. 2021-01-15 04:11:45.109 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 42: Transaction is current transaction, so clearing!!!!! 2021-01-15 04:11:45.109 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 42: Transaction CANCELLED 2021-01-15 04:11:45.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:42 CANCELLED 2021-01-15 04:11:45.111 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2021-01-15 04:11:45.111 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 42: Transaction event listener: DONE: CANCELLED -> 2021-01-15 04:11:45.112 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 7A C0 2021-01-15 04:11:45.115 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 7A C0 2021-01-15 04:11:45.115 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 38: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7cc34d32 2021-01-15 04:11:45.117 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2021-01-15 04:11:45.118 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2021-01-15 04:11:45.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 43: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2021-01-15 04:11:45.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 126<>2 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2021-01-15 04:11:45.120 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 01 04 07 01 7A 2021-01-15 04:11:45.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 127<>1 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload =53 9C 01 04 07 01 2021-01-15 04:11:46.181 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@763b2642 2021-01-15 04:11:46.182 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 180 to queue - size 137 2021-01-15 04:11:46.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2021-01-15 04:11:46.262 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 08 6F 08 31 05 04 64 00 02 A4 54 3C 2021-01-15 04:11:46.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 128<>0 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=111, callback =8, payload=08 6F 08 31 05 04 64 00 02 A4 54 2021-01-15 04:11:46.264 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. java.lang.IllegalStateException: Queue full at java.util.AbstractQueue.add(AbstractQueue.java:98) ~[?:?] at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:326) ~[?:?] at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:447) ~[bundleFile:?] at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1078) ~[bundleFile:?] at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:445) ~[bundleFile:?] at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:427) [bundleFile:?] 2021-01-15 04:11:46.283 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive 2021-01-15 04:11:46.292 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 159: Controller status changed to OFFLINE. 2021-01-15 04:11:46.292 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 70: Controller status changed to OFFLINE. 2021-01-15 04:11:46.293 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 159: Controller is not online. 2021-01-15 04:11:46.293 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 116: Controller status changed to OFFLINE. 2021-01-15 04:11:46.294 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 113: Controller status changed to OFFLINE. 2021-01-15 04:11:46.295 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 113: Controller is not online.

@TheKorn2
Copy link
Author

System was nuked and transitioned to zwave-js instead. It at least works!

@TheKorn2 TheKorn2 closed this as not planned Won't fix, can't repro, duplicate, stale Jan 29, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@TheKorn2 @5iver