search

openhab / org.openhab.binding.zwave

openHAB binding for Z-Wave
Eclipse Public License 2.0
171 stars 202 forks source link

NPE in ZWaveDiscoveryService #1072

Open marcusb opened 5 years ago

marcusb commented 5 years ago

Performing discovery causes the following NPE:

018-11-22 11:26:11.662 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:512
2018-11-22 11:26:13.668 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null                                                               
        at org.openhab.binding.zwave.discovery.ZWaveDiscoveryService$1.run(ZWaveDiscoveryService.java:83) ~[?:?]     
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]                                  
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:?]                                                        
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:?]            
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:?]              
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]                                         
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]                                                                           
        at java.lang.Thread.run(Thread.java:748) [?:?]

The line in question is

                // Add all existing devices
                for (ZWaveNode node : controllerHandler.getNodes()) {

indicating that controllerHandler appears to be null.

This happens when I try to add a new dimmer to the network, a GE dimmer not yet in the device database. I don't know if that's related in any way to the new device though. (I did successfully discover a few other devices just the day before with the same installation.)

marcusb commented 5 years ago

Additional logs during discovery.

I also notice that the binding is losing the serial port configuration for the Zstick every time I perform discovery. The serial port was configured through Paper UI, but after discovery, the property has no value and all devices are offline. I have to reconfigure the serial port every time. Looks like that might be related to this issue.

2018-11-22 11:39:54.491 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2018-11-22 11:39:54.494 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Deactivate zwave:serial_zstick:512
2018-11-22 11:39:54.505 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=424, service.bundleid=231, service.scope=singleton} - org.openhab.binding.zwave
2018-11-22 11:39:54.509 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2018-11-22 11:39:54.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Interrupted taking message from recvQueue
java.lang.InterruptedException: null
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014) ~[?:?]
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2048) ~[?:?]
    at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403) ~[?:?]
    at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:427) [231:org.openhab.binding.zwave:2.4.0.201811050432]
2018-11-22 11:39:54.513 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:512.
2018-11-22 11:39:54.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-22 11:39:54.515 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-22 11:39:54.515 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 15 hours time.
2018-11-22 11:39:54.522 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Controller status changed to OFFLINE.
2018-11-22 11:39:54.522 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller status changed to OFFLINE.
2018-11-22 11:39:54.525 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller status changed to OFFLINE.
2018-11-22 11:39:54.524 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller status changed to OFFLINE.
2018-11-22 11:39:54.531 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller is not online.
2018-11-22 11:39:54.527 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Controller is not online.
2018-11-22 11:39:54.545 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Controller status changed to OFFLINE.
2018-11-22 11:39:54.536 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller is not online.
2018-11-22 11:39:54.522 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller status changed to OFFLINE.
2018-11-22 11:39:54.562 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller is not online.
2018-11-22 11:39:54.562 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller is not online.
2018-11-22 11:39:54.565 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Controller is not online.
2018-11-22 11:39:54.551 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller status changed to OFFLINE.
2018-11-22 11:39:54.570 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Controller status changed to OFFLINE.
2018-11-22 11:39:54.521 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2018-11-22 11:39:54.572 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Controller is not online.
2018-11-22 11:39:54.563 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller status changed to OFFLINE.
2018-11-22 11:39:54.577 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is not online.
2018-11-22 11:39:54.578 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Controller status changed to OFFLINE.
2018-11-22 11:39:54.585 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Controller is not online.
2018-11-22 11:39:54.586 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller status changed to OFFLINE.
2018-11-22 11:39:54.589 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller is not online.
2018-11-22 11:39:54.594 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller is not online.
2018-11-22 11:39:54.598 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Controller status changed to OFFLINE.
2018-11-22 11:39:54.599 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller status changed to OFFLINE.
2018-11-22 11:39:54.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller is not online.
2018-11-22 11:39:54.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Controller is not online.
2018-11-22 11:39:54.606 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller status changed to OFFLINE.
2018-11-22 11:39:54.609 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller is not online.
2018-11-22 11:39:54.613 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Controller status changed to OFFLINE.
2018-11-22 11:39:54.611 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller status changed to OFFLINE.
2018-11-22 11:39:54.619 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller is not online.
2018-11-22 11:39:54.620 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller status changed to OFFLINE.
2018-11-22 11:39:54.622 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller status changed to OFFLINE.
2018-11-22 11:39:54.625 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Controller status changed to OFFLINE.
2018-11-22 11:39:54.613 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:512
2018-11-22 11:39:54.619 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Controller is not online.
2018-11-22 11:39:54.626 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller status changed to OFFLINE.
2018-11-22 11:39:54.632 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller status changed to OFFLINE.
2018-11-22 11:39:54.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller is not online.
2018-11-22 11:39:54.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Controller is not online.
2018-11-22 11:39:54.636 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is not online.
2018-11-22 11:39:54.634 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller is not online.
2018-11-22 11:39:54.637 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Controller status changed to OFFLINE.
2018-11-22 11:39:54.640 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller is not online.
2018-11-22 11:39:54.641 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:512
2018-11-22 11:39:54.645 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Controller is not online.
2018-11-22 11:39:56.254 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 8: TID 179: Timeout at state WAIT_REQUEST. 3 retries remaining.
2018-11-22 11:39:56.256 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2018-11-22 11:39:56.258 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 179: Transaction ABORTED
2018-11-22 11:39:56.260 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2018-11-22 11:39:56.262 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 03 00 16 EA 
2018-11-22 11:39:56.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-22 11:39:56.646 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
    at org.openhab.binding.zwave.discovery.ZWaveDiscoveryService$1.run(ZWaveDiscoveryService.java:83) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
2018-11-22 11:40:08.261 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 8: TID 179: Timeout at state ABORTED. 3 retries remaining.
marcusb commented 5 years ago

Possibly related to https://github.com/openhab/org.openhab.binding.zwave/issues/1059