Yeah⊠Iâd give it some time to settle. If it still doesnât work in an hour or so, youâll need to get some logs. My 125 devices take at least an hour before things start to settle and be controllable.
Just saw some debug related to Node 5, also in the same boat: I do see âTransaction Not completedâ - there must be a bug in this zwave binding. Iâm on 2.5.0 SNAPSHOT Build #1465
I have attached a trace log, nodes 5 and node 6 are the ones that im trying to get working (others may not work also)
zwave.log (678.8 KB)
I also see this in the log
No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:c5b08a5b
13:55:43.805 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling...
13:55:43.806 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:c5b08a5b:node5:meter_kwh
13:55:43.807 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for COMMAND_CLASS_METER, endpoint 0
13:55:43.808 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for COMMAND_CLASS_METER, endpoint 0
13:55:43.808 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 5: Creating new message for application command METER_GET
13:55:43.809 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_METER
13:55:43.810 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: Command Class COMMAND_CLASS_METER is NOT required to be secured
13:55:43.810 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:c5b08a5b:node5:meter_watts
13:55:43.811 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for COMMAND_CLASS_METER, endpoint 0
13:55:43.812 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for COMMAND_CLASS_METER, endpoint 0
13:55:43.813 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 5: Creating new message for application command METER_GET
13:55:43.813 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_METER
13:55:43.814 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: Command Class COMMAND_CLASS_METER is NOT required to be secured
13:55:43.815 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling zwave:device:c5b08a5b:node5:meter_reset
13:55:43.815 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 5: Generating poll message for COMMAND_CLASS_METER, endpoint 0
13:55:43.816 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
13:55:43.817 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Added 244 to queue - size 3
13:55:43.817 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:55:43.818 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 32 01 00 25 15 E3
13:55:43.819 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 32 01 00 25 15 E3
13:55:43.820 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:55:43.820 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 244: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 21
13:55:43.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
13:55:43.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Added 245 to queue - size 3
13:55:43.822 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:55:43.823 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:55:43.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:55:43.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:55:43.825 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 244: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 21
13:55:43.826 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:55:43.827 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:55:43.827 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:55:43.830 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:55:43.831 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:55:43.832 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:55:43.832 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 244: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 21
13:55:43.833 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:55:43.834 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 244: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 21
13:55:43.834 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:55:43.835 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 5: sentData successfully placed on stack.
13:55:43.836 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 244: Advanced to WAIT_REQUEST
13:55:43.836 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: TID 244: Transaction not completed
13:55:43.837 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:55:43.838 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:55:43.859 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 15 00 00 03 FD
13:55:43.860 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=21, payload=15 00 00 03
13:55:43.861 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=21, payload=15 00 00 03
13:55:43.862 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 244: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 21
13:55:43.863 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:55:43.864 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 244: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 21
13:55:43.864 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 244: (Callback 21)
13:55:43.865 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:55:43.866 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 244: callback 21
13:55:43.866 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=21, payload=15 00 00 03
13:55:43.867 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 21, Status = Transmission complete and ACK received(0)
13:55:43.868 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
13:55:43.868 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 244: Advanced to WAIT_DATA
13:55:43.869 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: TID 244: Transaction not completed
13:55:43.869 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 05 0A 32 02 21 44 00 00 00 87 00 00 36
13:55:43.870 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:55:43.871 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 32 02 21 44 00 00 00 87 00 00
13:55:43.871 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:55:43.872 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 32 02 21 44 00 00 00 87 00 00
13:55:43.873 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:55:43.873 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
13:55:43.874 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
13:55:43.875 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_METER, endpoint 0
13:55:43.875 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_METER
13:55:43.876 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_METER V3 METER_REPORT
13:55:43.877 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 5: Meter: Type=Electric(1), Scale=kWh(0), Value=1.35
13:55:43.877 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveMeterValueEvent
13:55:43.878 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 1.35
13:55:43.879 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:c5b08a5b:node5:meter_kwh to 1.35 [DecimalType]
13:55:43.880 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
13:55:43.881 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@11989d8e.
13:55:43.882 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenNum2 changed from 6.61 to 1.35
13:55:43.882 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@11989d8e.
13:55:43.885 [INFO ] [home.event.GroupItemStateChangedEvent] - gPowerUsage changed from 208.635 to 203.375 through KitchenNum2
13:55:43.885 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:244 DONE
13:55:43.887 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:55:43.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
13:55:43.889 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:55:43.890 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:55:43.891 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:55:43.892 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 32 01 10 25 16 F0
13:55:43.893 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 32 01 10 25 16 F0
13:55:43.894 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:55:43.894 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 245: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 22
13:55:43.912 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:55:43.913 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:55:43.914 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:55:43.914 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 245: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 22
13:55:43.915 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:55:43.916 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:55:43.917 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:55:43.920 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:55:43.921 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:55:43.922 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:55:43.923 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 245: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 22
13:55:43.923 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:55:43.924 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 245: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 22
13:55:43.925 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:55:43.926 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 5: sentData successfully placed on stack.
13:55:43.926 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 245: Advanced to WAIT_REQUEST
13:55:43.927 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: TID 245: Transaction not completed
13:55:43.927 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:55:43.928 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:55:43.949 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 16 00 00 03 FE
13:55:43.950 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=22, payload=16 00 00 03
13:55:43.951 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=22, payload=16 00 00 03
13:55:43.952 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 245: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 22
13:55:43.952 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:55:43.953 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 245: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 22
13:55:43.954 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 245: (Callback 22)
13:55:43.954 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:55:43.959 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 05 08 32 02 21 32 00 00 00 00 DB
13:55:43.972 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 245: callback 22
13:55:43.972 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 08 32 02 21 32 00 00 00 00
13:55:43.972 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=22, payload=16 00 00 03
13:55:43.974 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 22, Status = Transmission complete and ACK received(0)
13:55:43.974 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
13:55:43.975 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 245: Advanced to WAIT_DATA
13:55:43.975 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: TID 245: Transaction not completed
13:55:43.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 08 32 02 21 32 00 00 00 00
13:55:43.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:55:43.977 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
13:55:43.977 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
13:55:43.978 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_METER, endpoint 0
13:55:43.978 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_METER
13:55:43.979 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_METER V3 METER_REPORT
13:55:43.980 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 5: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
13:55:43.980 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveMeterValueEvent
13:55:43.981 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0E+1
13:55:43.981 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:c5b08a5b:node5:meter_watts to 0 [DecimalType]
13:55:43.983 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
13:55:43.984 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@493ae914.
13:55:43.984 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@493ae914.
13:55:43.985 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:245 DONE
13:55:43.986 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
A config update to the effected device:
14:41:12.692 [WARN ] [org.eclipse.jetty.server.HttpChannel ] - /rest/config-descriptions/thing:zwave:device:c5b08a5b:node6
javax.servlet.ServletException: javax.servlet.ServletException: A MultiException has 1 exceptions. They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_17,18,1434504190) has been shut down
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:88) ~[?:?]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
at org.eclipse.jetty.server.Server.handle(Server.java:531) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352) [84:org.eclipse.jetty.server:9.4.11.v20180605]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) [84:org.eclipse.jetty.server:9.4.11.v20180605]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281) [75:org.eclipse.jetty.io:9.4.11.v20180605]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) [75:org.eclipse.jetty.io:9.4.11.v20180605]
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [75:org.eclipse.jetty.io:9.4.11.v20180605]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: javax.servlet.ServletException: A MultiException has 1 exceptions. They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_17,18,1434504190) has been shut down
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:489) ~[?:?]
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) ~[?:?]
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) ~[?:?]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) ~[?:?]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) ~[?:?]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) ~[?:?]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) ~[?:?]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) ~[?:?]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) ~[?:?]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) ~[?:?]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) ~[?:?]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) ~[?:?]
... 15 more
Caused by: org.glassfish.hk2.api.MultiException: A MultiException has 1 exceptions. They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_17,18,1434504190) has been shut down
at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:106) ~[?:?]
at org.jvnet.hk2.internal.FactoryCreator.dispose(FactoryCreator.java:173) ~[?:?]
at org.jvnet.hk2.internal.SystemDescriptor.dispose(SystemDescriptor.java:526) ~[?:?]
at org.glassfish.jersey.process.internal.RequestScope$Instance.remove(RequestScope.java:532) ~[?:?]
at org.glassfish.jersey.process.internal.RequestScope$Instance.release(RequestScope.java:549) ~[?:?]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319) ~[?:?]
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) ~[?:?]
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) ~[?:?]
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) ~[?:?]
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) ~[?:?]
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) ~[?:?]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) ~[?:?]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) ~[?:?]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) ~[?:?]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) ~[?:?]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) ~[?:?]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) ~[?:?]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) ~[?:?]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) ~[?:?]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) ~[?:?]
... 15 more
Caused by: java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_17,18,1434504190) has been shut down
at org.jvnet.hk2.internal.ServiceLocatorImpl.checkState(ServiceLocatorImpl.java:2288) ~[?:?]
at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandleImpl(ServiceLocatorImpl.java:629) ~[?:?]
at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:622) ~[?:?]
at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:640) ~[?:?]
at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:103) ~[?:?]
at org.jvnet.hk2.internal.FactoryCreator.dispose(FactoryCreator.java:173) ~[?:?]
at org.jvnet.hk2.internal.SystemDescriptor.dispose(SystemDescriptor.java:526) ~[?:?]
at org.glassfish.jersey.process.internal.RequestScope$Instance.remove(RequestScope.java:532) ~[?:?]
at org.glassfish.jersey.process.internal.RequestScope$Instance.release(RequestScope.java:549) ~[?:?]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319) ~[?:?]
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) ~[?:?]
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) ~[?:?]
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) ~[?:?]
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) ~[?:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) ~[?:?]
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) ~[?:?]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) ~[?:?]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) ~[?:?]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) ~[?:?]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) ~[?:?]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) ~[?:?]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) ~[?:?]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) ~[?:?]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) ~[?:?]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219) ~[?:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) ~[?:?]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) ~[?:?]
... 15 more
Further, it appears the Active Channels after that update is now 0. It was previously 3 (Meter, Switch, Dimmer)
Definitely not âsettlingâ there is a bug I suspect. I only have about 12 devices, should take no more than 5minutes. Logs now attached.
Youâre right⊠12 devices should go very quickly. Have you tried restarting OH after the upgrade?
How about trying a delete and rediscover of the Things?
Fixed it!!
This post 
, the darn channel names had changed!!!
Readd your device thing and adopted the new channels you may see that behaviour.
The channel for switch and dimmer itemtype is now switch_dimmer1 and is instantly updated through the binding and through the pyhsical switch.
Actually it is working 100% correct for the first time since I have this device 
Switch FibFGD212_1_Sw { channel="zwave:device:uzb:node37:switch_dimmer1" }
Dimmer FibFGD212_1_Dim { channel="zwave:device:uzb:node37:switch_dimmer1" }
1 Like
Can anyone suggest what I should look for it my Zwave device pairs fine with the controller, is visible (at least for a little while in OH2) but then subsuquently is offline constantly? despite being powered by mains? Its a problematic Aeotec Dimmer Nano, which I wonder is faulty?
This message is not an error - itâs a debug message just indicating the state. It does not indicate a problem at all.
I see a lot of timeouts from node 11 so there is something wrong with that device! You can try a reset/reinclude to see if it resolves it, but the problem is the low level communication, and not the binding.
Other devices in the log appear ok.
I donât think the issues you have with the âpredictedâ state is related to ZWave. It sounds like a new feature of the system. I was not personally aware of the link to the thing being offline - the offline state of things works basically the same as in OH1, but it seems that the framework is now trying to be a lot smarter, and this may be causing problems.
I assume you mean is there a way to get logs only from a certain device? If so, then just get the logs, and use the log viewer to view them. The viewer provides a means to filter logs on certain nodes.
1 Like
Hopefully this question hasnât been asked all too often. I think I remember that there is or used to be a problem setting up things via config files, and it has or had to be done via Paper UI. Is this problem gone with the latest version of the binding?
When upgrading from OH2.3 to 2.4, can I delete all Zwave things via Paper UI and after the OH update and binding installation add the exact definition via config files?
You can, but be aware that configuration parameters cannot be set/changed once you do this. Here is a post with detail, in a topic all about unmanaged zwave Things.
1 Like
Ok, guess Iâll have to keep using PaperUI then 
Hi All,
Hope I donât ask something that has been covered already - if so please forgive me.
With the release of 2.4 I was thinking of setting up a new Raspberry from scratch with OpenHABian and restore a V2.3 backup made accordingly to this approach.
Is this something that would work or would I again have to delete all Z-Wave things?
Would it make a difference if I would plug the controller in and install the Z-Wave binding before restoring the backup?
Having to delete all Z-Wave things (and probably Items as done via PaperUI) is something that really scares meâŠ
Thanks a lot!
Chris
Nope, you still need to delete them as they were created on pre-2.4 OH.
But you can do that in the new system so you neednât be afraid of breaking anything.
where can i download the actual snapshot version 2.4.0 of z-wave binding?
or does it still make sense to load the snapshot after refactoring? should the binding be loaded via Paper UI?
currently i donât have any new z-wave devices and all existing devices ran with the development version
my openhab version: 2.4.0 (released version)
Because 2.4 is now the stable release, there are no more 2.4 snaphots.
That one was merged into 2.4 a while ago. So you should be good to go with the 2.4 zwave stable binding installed through PaperUI. Donât forget to delete any zwave bindings in your addons folder.
thanks ⊠is it necessary to re-integrate all devices when switching from development version 2.4.0 to stable version 2.4.0?
Nope. Only if your devices need to pick up changes from the database.
Hi,
Iâve managed to get the Danalock v3 working with the 2.4 addon - thanks! A minor issue though is that when the lock is activated from zwave I see this in the event.log:
2018-12-26 13:53:42.435 [ome.event.ItemCommandEvent] - Item 'DoorLock' received command ON
2018-12-26 13:53:42.444 [vent.ItemStateChangedEvent] - DoorLock changed from OFF to ON
2018-12-26 13:53:44.192 [vent.ItemStateChangedEvent] - DoorLock changed from ON to OFF
2018-12-26 13:53:44.595 [vent.ItemStateChangedEvent] - DoorLock changed from OFF to ON
That is fairly annoying as I obviously have different rules for the lock turning on and off. I have attached the zwave.log (87.1 KB)
. @chris, perhaps you can see what is wrong?
Try increasing the Command Poll Delay from 1500ms to (say) 2500 or 3500ms. The issue looks like with the delay in the security, the GET request is coming in before the lock has locked. Given that the lock also sends a notification, you could probably set this to 0 to disable it.
1 Like