AN157 problem with OH2

HI,

Upgraded to OH2 final (previously Beta 4) and I have problems with AN157 plugs not responding.
Any tip on how to solve it?

You’ll need to provide more information I’m afraid. What does the debug log show for starters?

Hi Chris,

When searching for new devices:

21:54:29.262 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 6: Checking zwave:everspring_an157_00_000
21:54:29.340 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 6: Device discovery resolved to thingType zwave:everspring_an157_00_000
21:54:29.343 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1b7d2486:node6' to inbox.
21:54:29.343 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 7: Device discovery completed
21:54:29.344 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 7: Checking zwave:act_45602_00_000
21:54:29.344 [INFO ] [smarthome.event.InboxAddedEvent     ] - Discovery Result with UID 'zwave:device:1b7d2486:node6' has been added.
21:54:29.344 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 7: Checking zwave:act_zdm230_00_000

Then adding node 6:

21:56:35.535 [INFO ] [smarthome.event.InboxRemovedEvent   ] - Discovery Result with UID 'zwave:device:1b7d2486:node6' has been removed.
21:56:35.539 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'zwave:device:1b7d2486:node6' has been added.
21:56:35.558 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=315, service.bundle                             id=187, service.scope=singleton} - org.openhab.binding.zwave
21:56:35.574 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1b7d2486:node6' changed from UNINITIALIZED to INITIALIZING
21:56:35.577 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
21:56:35.586 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1b7d2486:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
21:56:35.593 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=315, service.bun                             dleid=187, service.scope=singleton} - org.openhab.binding.zwave
21:56:35.597 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
21:56:35.601 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1b7d2486:node6' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to UNINITIALIZED (HANDLER_MISS                             ING_ERROR)
21:56:35.656 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=316, service.bundle                             id=187, service.scope=singleton} - org.openhab.binding.zwave
21:56:35.675 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1b7d2486:node6' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
21:56:35.682 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
21:56:35.687 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:1b7d2486:node6' has been updated.
21:56:35.688 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Controller status changed to ONLINE.
21:56:35.688 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Controller is ONLINE. Starting device initialisation.
21:56:35.694 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Command received zwave:device:1b7d2486:node6:switch_binary --> REFRESH
21:56:35.695 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling intialised at 1800 seconds - start in 50 milliseconds.
21:56:35.697 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1b7d2486:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
21:56:35.700 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating node properties.
21:56:35.701 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating node properties. MAN=96
21:56:35.704 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating node properties. MAN=96. SET. Was 96
21:56:35.705 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1b7d2486:node6' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
21:56:35.711 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while initializing handler of thing 'zwave:device:1b7d2486:node6': java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
    at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_65]
    at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_65]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:188)   [101:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:81)[101:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:65)[101:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$9.run(ThingManager.java:710)[108:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_65]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_65]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[: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]
Caused by: java.lang.NullPointerException
    at org.openhab.binding.zwave.handler.ZWaveThingHandler.updateNodeProperties(ZWaveThingHandler.java:1353)[187:org.openhab.binding.zwave:2.0.0]
    at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:457)[187:org.openhab.binding.zwave:2.0.0]
    at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:150)[187:org.openhab.binding.zwave:2.0.0]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$9$1.call(ThingManager.java:713)[108:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$9$1.call(ThingManager.java:1)[108:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:179)[101:org.eclipse.smarthome.core:0.9.0.b4]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
    ... 3 more
21:56:35.723 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1b7d2486:node6' changed from ONLINE to UNINITIALIZED (HANDLER_INITIALIZING_ERROR)
21:56:35.745 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling...
21:56:35.745 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling deferred until initialisation complete
21:56:37.762 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 0A 0E 32 02 21 34 00 00 02 28 00 00 00 00 00 00 E4
21:56:37.770 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
21:56:37.775 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 14 00 04 00 0A 0E 32 02 21 34 00 00 02 28 00 00 00 00 00 00 E4
21:56:37.779 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 14 00 04 00 0A 0E 32 02 21 34 00 00 02 28 00 00 00 00 00 00 E4
21:56:37.783 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0A 0E                              32 02 21 34 00 00 02 28 00 00 00 00 00 00
21:56:37.785 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 10: Application Command Request (ALIVE:DONE)
21:56:37.787 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Starting initialisation from DONE
21:56:37.789 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@113db35 already regi                             stered
21:56:37.791 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 10: Incoming command class METER
21:56:37.793 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 10: Received METER command V3
21:56:37.796 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 10: Meter: Type=Electric(1), Scale=W(2), Value=55.2
21:56:37.798 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
21:56:37.800 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveMeterValueEvent
21:56:37.801 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 55.2
21:56:37.804 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_Power_Factor <> E_W
21:56:37.805 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_A <> E_W
21:56:37.807 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_W
21:56:37.809 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_W
21:56:37.811 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating channel state zwave:device:1b7d2486:node10:meter_watts to 55.2 [DecimalType]
21:56:37.813 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent.  lastSent=255, incoming=255

Hi @chris,

Any snapshot/beta I can test ?