search

openhab / org.openhab.binding.zwave

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

pooling exception with latest build #1087

Closed stas-dovgodko closed 5 years ago

stas-dovgodko commented 5 years ago

openhab log exceptions for every pooling, looks like after latest update to 2.4 Build #1458 from prev 2.4 build.

My controller *things

Bridge zwave:serial_zstick:controller "ZWave Controller" [ port="/dev/ttyUSB-ZWAVE", controller_softreset="false", controller_master="true", heal_enable="true", security_networkkey="63 2E 36 E7 B7 34 DE EC 49 F7 B1 1E 55 51 33 06" ]
{

}
==> /var/log/openhab2/openhab.log <==
2018-12-12 01:29:16.953 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling aborted due to exception
java.lang.NullPointerException: null
    at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:368) [231:org.openhab.binding.zwave:2.4.0.201812100737]
    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) [?:?]
cdjackson commented 5 years ago

Please provide a debug log so I can see what is happening.

On 11 Dec 2018, at 23:33, Stas Dovgodko notifications@github.com wrote:

openhab log exceptions for every pooling, looks like after latest update to 2.4 Build #1458 from prev 2.4 build.

My controller *things

Bridge zwave:serial_zstick:controller "ZWave Controller" [ port="/dev/ttyUSB-ZWAVE", controller_softreset="false", controller_master="true", heal_enable="true", security_networkkey="63 2E 36 E7 B7 34 DE EC 49 F7 B1 1E 55 51 33 06" ] {

} ==> /var/log/openhab2/openhab.log <== 2018-12-12 01:29:16.953 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling aborted due to exception java.lang.NullPointerException: null at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:368) [231:org.openhab.binding.zwave:2.4.0.201812100737] 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) [?:?]

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zwave/issues/1087, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_kQ68Y2ywxyOAbG8OQx-u1GPekSEexks5u4EDIgaJpZM4ZOcb8.

stas-dovgodko commented 5 years ago 

18:49:03.398 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:49:03.401 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
18:49:08.284 [INFO ] [smarthome.event.ItemStateChangedEvent] - Music_gOffice_Player_ResponseTime changed from 1.0 to 2.0
18:49:13.152 [INFO ] [smarthome.event.ItemStateChangedEvent] - Azimuth changed from 264.7947229632487 to 264.9806667991166
18:49:13.161 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sun_Azimuth changed from 264.7947229632487 to 264.9806667991166
18:49:13.165 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sun_Elevation changed from -26.168113593287448 to -26.32634378616043
18:49:13.169 [INFO ] [smarthome.event.ItemStateChangedEvent] - Elevation changed from -26.168113593287448 to -26.32634378616043
18:49:13.299 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 02 0A 60 0D 01 01 31 05 04 22 00 06 9A 
18:49:13.311 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0A 60 0D 01 01 31 05 04 22 00 06 
18:49:13.315 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0A 60 0D 01 01 31 05 04 22 00 06 
18:49:13.318 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:49:13.321 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
18:49:13.324 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
18:49:13.326 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
18:49:13.327 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 1
18:49:13.328 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL
18:49:13.329 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT
18:49:13.330 [DEBUG] [ass.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Type = Power(4), Scale = 0
18:49:13.332 [DEBUG] [ass.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Value = 0.6
18:49:13.334 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
18:49:13.335 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@70af4f0c.
18:49:13.336 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
18:49:13.338 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
18:49:13.338 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:49:13.339 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
18:49:14.287 [INFO ] [smarthome.event.ItemStateChangedEvent] - Music_gOffice_Player_ResponseTime changed from 2.0 to 1.0
18:49:16.953 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
18:49:16.957 [WARN ] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling aborted due to exception
java.lang.NullPointerException: null
    at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:368) [231:org.openhab.binding.zwave:2.4.0.201812100737]
    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) [?:?]
18:49:23.277 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 02 0A 60 0D 01 01 31 05 04 22 00 06 9A 
18:49:23.288 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0A 60 0D 01 01 31 05 04 22 00 06 
18:49:23.290 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0A 60 0D 01 01 31 05 04 22 00 06 
18:49:23.294 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
cdjackson commented 5 years ago

Unfortunately that doesn't really help...

What is node 2 and what items/channels are configured?

Also, are there any error showing when the binding starts? Maybe something is misconfigured?

stas-dovgodko commented 5 years ago

Fibaro Dimmer 2 FGD-212.

Configured almost all channels to separate items with paperui. Both controller (aeotec Z-Stick Gen5) and dimmer with online status and after restart working well but after few days dimmer stop reacts to openhab commands, just nothing happend in log too, but working well from own button and has online status in paperui

stas-dovgodko commented 5 years ago

After "reinitialise the device" the same exception. And this happened after every change dimmer in paperui but device actually fade the light (working)

cdjackson commented 5 years ago

I'm not sure what is causing this - the error is in a strange place, and it looks like something might be misconfigured, or has a problem during initialisation.

As asked previously - are there any errors showing when the binding starts?

stas-dovgodko commented 5 years ago

no other errors

cdjackson commented 5 years ago

Ok, thanks. Please let me know if you find anything else that might help - at the moment I don’t think there’s much I can do - sorry.

On 12 Dec 2018, at 19:08, Stas Dovgodko notifications@github.com wrote:

no other errors

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zwave/issues/1087#issuecomment-446706362, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_kQ-dexqCuZqsdBTZFHJc9wnivsaxEks5u4VQegaJpZM4ZOcb8.

stas-dovgodko commented 5 years ago

Removing thing from ui and rediscover looks like resolve the issue )

cdjackson commented 5 years ago

Ok, thanks. I can only think that something has got misconfigured, or the configuration screwed up a bit.

Thanks.