ZWave binding updates

zwave
Tags: #<Tag:0x00007f0148762618>

(Kris K) #298

Hi Scott

I upgraded 30mins ago. It doesnt turn on at all.

All the devices are online. One of my items related to the kitchen island, on the same controller is working just fine. It appears MOST but not all have this issue. The island that works is a Aeotec Dimmer, the non working units are Fibaro FGD212 Dimmer 2 units.


(Scott Rushworth) #299

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.


(Kris K) #300

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

@chris

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)


(Kris K) #301

Definitely not ‘settling’ there is a bug I suspect. I only have about 12 devices, should take no more than 5minutes. Logs now attached.


(Scott Rushworth) #302

You’re right… 12 devices should go very quickly. Have you tried restarting OH after the upgrade?


(Scott Rushworth) #304

How about trying a delete and rediscover of the Things?


(Kris K) #306

Fixed it!!

This post :smiley:, 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 :grinning:

Switch FibFGD212_1_Sw  { channel="zwave:device:uzb:node37:switch_dimmer1" }
Dimmer FibFGD212_1_Dim  { channel="zwave:device:uzb:node37:switch_dimmer1" }

(Kris K) #307

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?


(Chris Jackson) #308

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.


(Chris Jackson) #309

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.


(Mario Preis) #310

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?


(Scott Rushworth) #311

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.


(Mario Preis) #312

Ok, guess I’ll have to keep using PaperUI then :slight_smile:


(Christian) #313

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


(Markus Storm) #314

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.


(Marcel) #315

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)


(SiHui) #316

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.


(Marcel) #317

thanks … is it necessary to re-integrate all devices when switching from development version 2.4.0 to stable version 2.4.0?


(SiHui) #318

Nope. Only if your devices need to pick up changes from the database.


(Dennis P) #319

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?