this comes up in my log quite often…
I dont see any direct issues with it
however it might be good to know for @chris ?
2:23:44.593 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:358)[190:org.openhab.binding.zwave:2.0.0.201609202159]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_101]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_101]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
12:23:47.092 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling...
12:23:47.094 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:358)[190:org.openhab.binding.zwave:2.0.0.201609202159]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_101]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_101]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
12:24:10.621 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling...
12:24:10.628 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:358)[190:org.openhab.binding.zwave:2.0.0.201609202159]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_101]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_101]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
Are you running the latest version? The line numbers in the errors don’t quite tie up, but I think you normally run a reasonably new version right?
I think the route cause is that nodeId seems to be 0, which is never a good thing. In theory, there is protection in the binding to stop a device attempting to initialise when the ID is unknown so I’m not sure how this got through. The other option is if this starts after a binding is updated or restarted for some reason since nodeId is set to 0 when the thing is destroyed (and I’m wondering if a thread continues to run…)
Same issue here with Snapshot installation from yesterday:
2016-09-30 13:24:52.446 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:360)[190:org.openhab.binding.zwave:2.0.0.201609281514]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_65]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_65]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_65]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
And: I have no idea, which device shall have Node ID 0.
I’m seeing the same issue since one or two builds, currently on openHAB2 Snapshot #603, zwave binding 2.0.0.201611222318
2016-11-23 14:41:30.220 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:360)[215:org.openhab.binding.zwave:2.0.0.201611222318]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_111]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_111]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_111]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_111]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_111]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_111]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
I saw that issue a couple of times… I thinks its related to update the zwave binding while OH2 is running.
It only started to happen after binding uninstall/reinstall to me with a low chance that it happens at all…
I’m getting the same thing and I’ve restarted and rebooted numerous times (pi). Various zwave things are not reliably coming online. I’m running OH2 with about a week old snapshot. I tried to removed nodes 9 and 16 from the controller using habmin, unsucessfully as you can see from the log.
I am not getting these exceptions after uninstalling a nightly and reinstalling the latest stable 2.2.0. Rebooting doesn’t help. I also have some devices that aren’t being discovered correctly. Not sure if that’s related.
Hi.
I am new to OH - consider stupidities as potential root causes of my contributions
I did a fresh install of the latest OH version, and also notice this nullpointer exception on node0.
2018-05-04 11:16:51.162 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException: null
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:365) [205:org.openhab.binding.zwave:2.2.0]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
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 first question to answer is why there’s a node 0 - this shouldn’t be possible, so it would be good to get some context to see how this actually happened.
Give me a hint @chris, is this the kind of info that can clarify?
I don’t exactly remember if my first change (as that might have triggered “node 0”) to OH was adding the ntp binding, or adding the z-stick.
Yesterday I had troubles adding a RFXCOM USB Transceiver. I had to play with tty and usb configs, and as I was not sure about the discovery behaviour, I also removed and re-added my z-stick (Z-Wave USB Stick with Serial Interface). Don’t know if that can cause?
Yesterday I also added 4 z-wave plugs, and I added a Z-Wave Node 9: ZW100 MultiSensor 6. (today I removed & added it again).
In the logs, this kind events appears every now & then:
2018-05-04 11:32:10.153 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1503 to 1504
2018-05-04 11:32:10.164 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_ack changed from 530 to 531
2018-05-04 11:32:10.176 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1504 to 1505
2018-05-04 11:32:10.187 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1505 to 1506
2018-05-04 11:32:10.198 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1506 to 1507
2018-05-04 11:32:10.312 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_ack changed from 531 to 532
2018-05-04 11:32:10.327 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1507 to 1508
2018-05-04 11:32:10.345 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1508 to 1509
2018-05-04 11:32:10.360 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1509 to 1510
2018-05-04 11:32:10.773 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_ack changed from 532 to 533
2018-05-04 11:32:10.792 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1510 to 1511
2018-05-04 11:32:10.805 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1511 to 1512
2018-05-04 11:32:10.817 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1512 to 1513
2018-05-04 11:32:10.830 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_ack changed from 533 to 534
2018-05-04 11:32:10.842 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1513 to 1514
2018-05-04 11:32:10.869 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1514 to 1515
2018-05-04 11:32:10.893 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1515 to 1516
2018-05-04 11:32:10.918 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_ack changed from 534 to 535
2018-05-04 11:32:10.946 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1516 to 1517
2018-05-04 11:32:10.959 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1517 to 1518
2018-05-04 11:32:10.970 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1518 to 1519
2018-05-04 11:32:10.983 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_ack changed from 535 to 536
2018-05-04 11:32:10.997 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1519 to 1520
2018-05-04 11:32:11.009 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1520 to 1521
2018-05-04 11:32:11.019 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1521 to 1522
2018-05-04 11:43:31.966 [vent.ItemStateChangedEvent] - zwave_serial_zstick_78e94ad2_serial_sof changed from 1522 to 1523
My Z-Wave ZW100 MultiSensor 6 is on node 9, so normally this is not related, but you never know… I would expect that the binary sensor i a motion sensor, and that it should switch on triggered by motion. I seems not to happen. Other sensors (temperature, humidity, …) do update. I have to find out what it is meant to, and how to see it updated.
another context info: the exceptions were there again. That is exactly 30 mins after the last exception trigger.
2018-05-04 11:16:51.162
2018-05-04 11:46:24.923
2018-05-04 12:16:51.162
…
Also remarkable: the nullpointer exception each time happens twice.
The last log event before (ntp is also triggered each 30 mins) is:
2018-05-04 11:46:24.923 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 04/05/2018 11:45:24 CEST to 04/05/2018 11:46:24 CEST
The new log:
2018-05-04 11:46:51.162 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException: null
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:365) [205:org.openhab.binding.zwave:2.2.0]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
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-05-04 11:46:51.162 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException: null
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:365) [205:org.openhab.binding.zwave:2.2.0]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
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) [?:?]
Firstly, we need to see the debug logs during the initialisation - there is a check at that point to ensure the value is valid (ie between 1 and 232). After than, it gets set to 0 only once the thing handler is closed (ie in the dispose method) - so probably this is what is happening. The question is why the handler is being disposed and yet still running.
Somehow we need to capture a log of this if we can. The dispose method logs the following text -:
… but after a reboot yesterday that error disappeared and has not shown again.