Fibaro Wall Plug not recognized (FGWP101 Metered Wall Plug Switch)

waitz_sebastian · July 2, 2018, 8:40pm

Hey all,
I was re-adding an unused fibaro wall plug (FGW101) today to my OH2.3-snapshot and got “device unknown” error.
Anyone a suggestion how to make it work? I already tried removing and adding again without success.
Here are some details about the plug (I have several of them working perfectly fine):

Z-Wave Node 31 (010F:0600:1000:25.25)
Unknown Device
zwave:device:91085fff:node31

 <entry>
   <commandClass>VERSION</commandClass>
   <versionCommandClass>
     <version>1</version>
     <instances>1</instances>
     <versionSupported>1</versionSupported>
     <libraryType>LIB_SLAVE_ENHANCED</libraryType>
     <protocolVersion>3.52</protocolVersion>
     <applicationVersion>25.25</applicationVersion>
   </versionCommandClass>
 </entry>

Thanks for your help.

sihui · July 2, 2018, 8:51pm

It has been in the database for a long time so it should even work with an old 2.3 snapshot:

https://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/130

To make sure it is not a missing database entry in the snapshot binding I would upgrade to a recent 2.4 snapshot:
https://openhab.ci.cloudbees.com/job/openHAB2-Bundles/lastSuccessfulBuild/org.openhab.binding$org.openhab.binding.zwave/

waitz_sebastian · July 3, 2018, 8:16am

Thanks for your swift reply and suggestion. Even though other wall plugs do work perfectly fine with the old binding, the new one started working after installing the 2.4-snap you mentioned. At least remotely everything seems to be fine. The switch is properly recognized and I can link items. Will test in more detail this afternoon, but upgrading to latest version seems to have done the trick.
Thanks again.

domofl · December 30, 2018, 4:13pm

Hi all,

I was using domoticz, but had some communication issues (sometimes switch commands timed out), so I decided to try openHAB. Looks like it is working fine (although HABmin does not work on edge, but that’s another story), except for two wall plug swtiches that I have: Fibaro FGWPE/F 102 ZW5. When it comes up in the “INBOX” it comes up as unkown devcice. In HABmin manufacturer is empty, type/id is empty, firmware says version 0.0, the rest of the info is ok I think.
If I look at the device on domoticz it gives 0x0602 0x1001, zwave+ version 1, library version 3, protocol version 4.05, application version 3.05.
Not sure how to try to fix it. Any suggestions?

Thanks,

Ramon

chris · December 30, 2018, 4:30pm

Probably there is something wrong with the communication with the device otherwise the manufacturer information etc would not be 0 or empty.

Check the logs to see what is happening - maybe use debug mode to see what’s going on. There is an online log viewer here that might also help.

domofl · December 30, 2018, 4:41pm

Hi Chris,

Thank you for your reply.
All other devices are working ok (including other devices from fibaro), so its a bit odd.
But forgive my ignorance (im new), where is the log located? Im running openhabian fresh install on a raspberry pi.

It is not related to the application version 3.05 that domotics reports? That’s is above the 2.5 version number and below the 3.2 version number.

Thanks for the help,

RAmon

chris · December 30, 2018, 4:47pm

Sorry, but I don’t know anything about Domotics, let alone version 3.05??

As mentioned above though, if your version is empty, and the manufacturer info, device type, id etc are all empty, then it is not related to database definitions. Until this information is available (ie downloaded from the device) then the binding can not know what the device is. This information must be retrieved from the device before anything else and from what you said, this is not happening. As this is one of the first things that the binding does, I suspect it is not communicating.

domofl · December 30, 2018, 5:23pm

3.05 is the application FW version that domotics reports the wall plug is using.

Anyway this is in the openhab.log:
2018-12-30 18:15:23.880 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 18: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-30 18:15:23.887 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:7358337f:node18’ to inbox.

No errors or anything, just WARN and INFO.

Thanks,

Ramon

domofl · December 30, 2018, 5:36pm

Sorry I was a bit too fast, looking bit further back into the log (not sure if they are related one relates to a different node):

2018-12-29 15:12:50.199 [ERROR] [ersey.server.ServerRuntime$Responder] - Error while committing the output stream.
org.eclipse.jetty.io.EofException: null
        at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:286) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
        at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:429) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
        at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:323) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
        at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
        at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:801) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
        at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[87:org.eclipse.jetty.util:9.4.11.v20180605]
        at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) ~[87:org.eclipse.jetty.util:9.4.11.v20180605]
        at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:538) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
        at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:790) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
        at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:846) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
        at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:240) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
        at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:216) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
        at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:398) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
        at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.flush(ResponseWriter.java:330) ~[?:?]
        at org.glassfish.jersey.message.internal.CommittingOutputStream.flush(CommittingOutputStream.java:292) ~[171:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.message.internal.OutboundMessageContext.commitStream(OutboundMessageContext.java:817) ~[171:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.server.ContainerResponse.commitStream(ContainerResponse.java:394) ~[172:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:752) [172:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:444) [172:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:434) [172:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:329) [172:org.glassfish.jersey.core.jersey-server:2.22.2]
….

goes on a bit with similar lines…

2018-12-29 15:59:19.919 [ERROR] [mmandclass.ZWaveSecurityCommandClass] - NODE 14: Error decapsulating security message
java.security.InvalidKeyException: No installed provider supports this key: (null)
        at javax.crypto.Cipher.chooseProvider(Cipher.java:893) ~[?:?]
        at javax.crypto.Cipher.init(Cipher.java:1249) ~[?:?]
        at javax.crypto.Cipher.init(Cipher.java:1186) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.generateMAC(ZWaveSecurityCommandClass.java:501) ~[206:org.openhab.binding.zwave:2.4.0]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.getSecurityMessageDecapsulation(ZWaveSecurityCommandClass.java:303) [206:org.openhab.binding.z$
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1233) [206:org.openhab.binding.zwave:2.4.0]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:485) [206:org.openhab.binding.zwave:2.4.0]

2018-12-30 16:51:52.387 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 18: Restore from config: Error. Data invalid, ignoring config.
2018-12-30 16:51:52.483 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 19: Restore from config: Error. Data invalid, ignoring config.

chris · December 30, 2018, 5:51pm

Ok, I thought you meant it was the Domotics version. Anyway, openHAB should report the same, and the fact that it reports nothing means there’s no communications.

As confirmed here - no manufacturer information is known.

Please enable debug logging (log:set DEBUG org.openhab.binding.zwave) so we can see what is happening - this doesn’t really show anything.

Also, please format the logs using the </> button, or use code fences as it’s hard to read without this. I’ll see if I can edit your post…

domofl · December 31, 2018, 11:07am

Ok I did that, got the following (after reboot), I took out other stuff not related to node 18. Not sure how to proceed. Looks like it is communicating, sort of, responds to a ping.

Thanks,

Ramon

2018-12-31 11:53:30.558 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Handler disposed. Unregistering listener.
2018-12-31 11:53:30.578 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 18: Serializing to file /var/lib/openhab2/zwave/network_fef20e8f__node_18.xml
2018-12-31 11:54:26.838 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: MANUFACTURER not set
2018-12-31 11:54:30.134 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 18: Node found
2018-12-31 11:54:30.244 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 18: Init node thread start
2018-12-31 11:54:30.812 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 18: Serializing from file /var/lib/openhab2/zwave/network_fef20e8f__node_18.xml
2018-12-31 11:54:31.059 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 18: Restore from config: Error. Data invalid, ignoring config.
2018-12-31 11:54:31.060 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Starting initialisation from EMPTYNODE
2018-12-31 11:54:31.225 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 18: Init node thread finished
2018-12-31 11:54:31.227 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node advancer - advancing to IDENTIFY_NODE
2018-12-31 11:54:31.230 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node advancer: Initialisation starting
018-12-31 11:54:31.802 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: ProtocolInfo
2018-12-31 11:54:31.804 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Listening = true
2018-12-31 11:54:31.806 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Routing   = true
2018-12-31 11:54:31.810 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Beaming   = true
2018-12-31 11:54:31.823 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Version   = 4
2018-12-31 11:54:31.825 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: FLIRS     = false
2018-12-31 11:54:31.828 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Security  = false
2018-12-31 11:54:31.830 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Max Baud  = 40000
2018-12-31 11:54:31.847 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Basic    = BASIC_TYPE_ROUTING_SLAVE
2018-12-31 11:54:31.849 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Generic  = GENERIC_TYPE_SWITCH_BINARY
2018-12-31 11:54:31.852 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 18: Specific = SPECIFIC_TYPE_POWER_SWITCH_BINARY
2018-12-31 11:54:31.855 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2018-12-31 11:54:31.859 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2018-12-31 11:54:31.861 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Version = 1, version set. Enabling extra functionality.
2018-12-31 11:54:31.865 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2018-12-31 11:54:31.867 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_BASIC
2018-12-31 11:54:31.870 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2018-12-31 11:54:31.872 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2018-12-31 11:54:32.097 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1279a46
2018-12-31 11:54:32.101 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node Init transaction completed with response COMPLETE
2018-12-31 11:54:32.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-31 11:54:32.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 9: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:32.106 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node advancer - advancing to PING
2018-12-31 11:54:32.110 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 18: Creating new message for command NO_OPERATION_PING
2018-12-31 11:54:32.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-31 11:54:32.117 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: ZWaveCommandClassTransactionPayload - send to node
2018-12-31 11:54:32.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=93 16 01 02 02 0$
2018-12-31 11:54:32.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 9: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:32.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-31 11:54:32.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 9: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:32.123 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY not supported
2018-12-31 11:54:32.130 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured
2018-12-31 11:54:32.133 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayloa$
2018-12-31 11:54:32.136 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=93 16 01 02 02 0$
2018-12-31 11:54:32.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Adding to device queue
2018-12-31 11:54:32.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Added 15 to queue - size 2
2018-12-31 11:54:32.138 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo
2018-12-31 11:54:32.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-31 11:54:32.703 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 08 00 13 12 01 00 25 01 D3

chris · December 31, 2018, 11:23am

The log is a bit short, but there is currently no communication with the device. Is there anything more in the log (I expect so)?

domofl · December 31, 2018, 4:17pm

The log was growing pretty fast, so I stopped it. I can start it again if that helps, but well if it is not communicating then I guess it will also not show anything else?
I also tried to exclude the node and delete the node from teh controller, but that does not appear to work. Seems along the way I made now few ghost nodes as well, which I also cannot delete.
I can try a hard reset of the controller, see if that helps. The weird thing remains that domoticz is communicating with it.

Thanks,

Ramon

chris · December 31, 2018, 4:32pm

Well, you stopped the log before the binding started to communicate with it, so I can’t confirm that from the log, although it is likely the case from what we’ve seen…

domofl · December 31, 2018, 5:08pm

There was some more actually (see below).
I think it is communicating as it says NODE 18: Node advancer: APP_VERSION - VERSION not supported

Thanks,

Ramon

2018-12-31 11:54:33.081 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2018-12-31 11:54:33.085 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Added 21 to queue - size 5
2018-12-31 11:54:33.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, pa$
2018-12-31 11:54:33.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 20: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-31 11:54:33.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-31 11:54:33.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01
2018-12-31 11:54:33.095 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 20: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.097 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-31 11:54:33.112 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 20: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.116 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01
2018-12-31 11:54:33.118 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2018-12-31 11:54:33.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 20: Advanced to WAIT_DATA
2018-12-31 11:54:33.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 20: Transaction not completed
2018-12-31 11:54:33.122 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-31 11:54:33.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-31 11:54:33.340 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 13 00 49 84 12 0D 04 10 01 5E 22 59 56 7A 32 71 73 98 31 BB
2018-12-31 11:54:33.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=18, callback=132, $
2018-12-31 11:54:33.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=18, callback=132, payload=84 12 0D 04$
2018-12-31 11:54:33.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 20: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-31 11:54:33.360 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 20: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 20: (Callback 0)
2018-12-31 11:54:33.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 20: callback 0
2018-12-31 11:54:33.370 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=18, callback=132, payload=84 12 0D 04$
2018-12-31 11:54:33.372 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update request. Node information received. Transaction TID 20: [WAIT_DATA] priority=Controller$
2018-12-31 11:54:33.374 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_ZWAVEPLUS_INFO
2018-12-31 11:54:33.376 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created
2018-12-31 11:54:33.378 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_ZWAVEPLUS_INFO.
2018-12-31 11:54:33.380 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_ZWAVEPLUS_INFO to the list of supported command classes.
2018-12-31 11:54:33.381 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_APPLICATION_STATUS
2018-12-31 11:54:33.384 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_APPLICATION_STATUS, endpoint 0 created
2018-12-31 11:54:33.386 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_APPLICATION_STATUS.
2018-12-31 11:54:33.387 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_APPLICATION_STATUS to the list of supported command classes.
2018-12-31 11:54:33.389 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_ASSOCIATION_GRP_INFO
2018-12-31 11:54:33.391 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created
2018-12-31 11:54:33.393 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_ASSOCIATION_GRP_INFO.
2018-12-31 11:54:33.395 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_ASSOCIATION_GRP_INFO to the list of supported command classes.
2018-12-31 11:54:33.396 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_CRC_16_ENCAP
2018-12-31 11:54:33.398 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_CRC_16_ENCAP, endpoint 0 created
2018-12-31 11:54:33.400 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_CRC_16_ENCAP.
2018-12-31 11:54:33.401 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_CRC_16_ENCAP to the list of supported command classes.
2018-12-31 11:54:33.402 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_FIRMWARE_UPDATE_MD
2018-12-31 11:54:33.404 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created
2018-12-31 11:54:33.406 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_FIRMWARE_UPDATE_MD.
2018-12-31 11:54:33.407 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_FIRMWARE_UPDATE_MD to the list of supported command classes.
2018-12-31 11:54:33.408 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_METER
2018-12-31 11:54:33.410 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_METER, endpoint 0 created
2018-12-31 11:54:33.412 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_METER.
2018-12-31 11:54:33.413 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_METER to the list of supported command classes.
2018-12-31 11:54:33.415 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_ALARM
2018-12-31 11:54:33.416 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_ALARM, endpoint 0 created
2018-12-31 11:54:33.418 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_ALARM.
2018-12-31 11:54:33.419 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_ALARM to the list of supported command classes.
2018-12-31 11:54:33.421 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_POWERLEVEL
2018-12-31 11:54:33.423 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created
2018-12-31 11:54:33.424 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_POWERLEVEL.
2018-12-31 11:54:33.425 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_POWERLEVEL to the list of supported command classes.
2018-12-31 11:54:33.427 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_SECURITY
2018-12-31 11:54:33.429 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_SECURITY, endpoint 0 created
2018-12-31 11:54:33.430 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_SECURITY.
2018-12-31 11:54:33.432 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_SECURITY to the list of supported command classes.
2018-12-31 11:54:33.433 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Creating new instance of command class COMMAND_CLASS_SENSOR_MULTILEVEL
2018-12-31 11:54:33.435 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0 created
2018-12-31 11:54:33.436 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 18: Application update is adding command class COMMAND_CLASS_SENSOR_MULTILEVEL.
2018-12-31 11:54:33.438 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Adding command class COMMAND_CLASS_SENSOR_MULTILEVEL to the list of supported command classes.
2018-12-31 11:54:33.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 20: Advanced to DONE
2018-12-31 11:54:33.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Response processed after 382ms
2018-12-31 11:54:33.444 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 20: Transaction completed
2018-12-31 11:54:33.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: notifyTransactionResponse TID:20 DONE
2018-12-31 11:54:33.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-31 11:54:33.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 20: Transaction event listener: DONE: DONE ->
2018-12-31 11:54:33.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-31 11:54:33.453 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@e3e161
2018-12-31 11:54:33.454 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 13 88
2018-12-31 11:54:33.455 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node Init transaction completed with response COMPLETE
2018-12-31 11:54:33.455 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 13 88
2018-12-31 11:54:33.457 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node advancer - advancing to SECURITY_REPORT
2018-12-31 11:54:33.467 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 18: Updated networkKey
2018-12-31 11:54:33.459 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-31 11:54:33.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-31 11:54:33.457 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-31 11:54:33.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 21: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-31 11:54:33.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-31 11:54:33.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-31 11:54:33.476 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B
2018-12-31 11:54:33.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-31 11:54:33.477 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 18: setupNetworkKey useSchemeZero=false
2018-12-31 11:54:33.483 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Skipping secure inclusion
2018-12-31 11:54:33.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, pa$
2018-12-31 11:54:33.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01
2018-12-31 11:54:33.486 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.487 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-31 11:54:33.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 21: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-12-31 11:54:33.492 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01
2018-12-31 11:54:33.490 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node advancer - advancing to MANUFACTURER
2018-12-31 11:54:33.495 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node advancer - advancing to APP_VERSION
2018-12-31 11:54:33.497 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node advancer: APP_VERSION - VERSION not supported
2018-12-31 11:54:33.498 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Node advancer - advancing to DISCOVERY_COMPLETE
2018-12-31 11:54:33.500 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 18: Device discovery completed
2018-12-31 11:54:33.505 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.

chris · December 31, 2018, 5:43pm

It’s pretty hard to see what’s happening - this is what the log looks like -:

It doesn’t show a received frame, but it then seems to skip straight to the end of the initialisation with very little being logged.

Maybe there’s an exception being thrown that’s not logged, or maybe it’s related to the crypto exception -:

I’m not sure what would cause this - you could make sure that there is a network key set in the controller. In theory this should be set automatically, but if there was something strange with the binding initialisation, maybe this hasn’t been configured.

Otherwise there’s not a lot to go on from the log

domofl · December 31, 2018, 5:44pm

Ok I tried a hard reset of the controller and that seemed to work.
So I guess the issue is resolved. Now all the work of re-including everything…

Thanks for the help chris.

Sergei · January 6, 2021, 10:57pm

Guys I have the same issue. Device ID is 0602:1003
I read all the discussion above and I understand that I need to manually write the config for the newer device version. But I’m too lame to do that.
Could you please give a step by step instruction? Please.
I run OH 2 on Synology DS214
P.S. Maybe I just need to update my binding? However I tried via paperUI and it didn’t go…

sihui · January 7, 2021, 6:32am

Yes. Hundreds of posts here in the forum, just use the search function or use a script:

Sergei · January 11, 2021, 8:06pm

Thanks. Will try in a few days and report back!