Z-Wave FIBEFGWPF-102-5 Unknown Device

Add-ons Bindings
1

Hello,

Problem:

Once I add the Fibaro Wall plug from the Inbox to my things it stays unknown and it is not possible to link any channels.

Solution trail:

  • delete/reinstall Z-Wave Binding
  • switch openHAB2 Version from 2.2.0 to 2.3.0 #1153
  • delete Fibaro Wall plug via B button
  • pair Fibaro plug

Hardware:

  • Raspberry B+
  • Z-Wave ZMEUZB1
  • Fibaro Wall Plug FIBEFGWPF-102-5

Software:

  • raspbian stretch
  • openHAB2 2.3.0 #1153

Logs:

openhab.log:

2017-12-30 02:36:14.559 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-12-30 02:36:19.521 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-12-30 02:36:19.530 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-12-30 02:36:19.533 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-12-30 02:36:19.537 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-12-30 02:36:19.541 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 1
2017-12-30 02:36:19.544 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-12-30 02:36:19.573 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-12-30 02:37:04.594 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:96a7c203:node2’ to inbox.
2017-12-30 10:42:08.295 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

events.log:

2017-12-30 11:33:16.136 [hingStatusInfoChangedEvent] - ‘zwave:device:96a7c203:node2’ changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2017-12-30 11:33:16.176 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:96a7c203:node2’ has been updated.

I also followed this instructions without success:

Could someone help me?

2

I would guess that there’s some sort of communication issue. Maybe the device isn’t properly included, or maybe the controller can’t communicate with it. The fact that the binding says the manufacturer codes are 7fffffff means there’s something fundamentally not working.

I would suggest to exclude the device and add it back - preferably do this via the UI and not by moving the controller to the device (eg if you have a stick with a battery). Make sure the device is close enough to be able to communicate directly with the controller.

3

Hello Chris,

First thank you for your work with the Z-Wave Binding.

After exclude I tried to include the device again. Here are my log results:

2017-12-30 15:43:49.318 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:1ff892ba:node4’ to inbox.
2017-12-30 15:43:49.470 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 4: Is currently marked as failed by the controller!
2017-12-30 15:44:10.059 [ERROR] [st.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:1ff892ba:node4/config’
2017-12-30 15:45:32.109 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 4: setupNetworkKey useSchemeZero=false
2017-12-30 15:46:04.699 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

I hope it has nothing to do with the already reported HTTP PUT request failure. Could it be that the wall plug is defective?

Best Regards,
Rob

4

No - it shouldn’t be related.

It’s possible, but it’s hard to really say what’s happening. I would suggest to enable debug logging to make sure you can really see what’s happening (please, when posting logs, use code fences, or highlight and press the </> button - it makes it a lot easier to read - especially if you post a debug log).

5

Hi Chris,

do I have to grep for something special? Two minutes of including the device with log mode debug contains 17000 lines.

6

No - please don’t use grep. Make sure that debug is only turned on for the zwave binding - not generally - otherwise you will get a LOT of rubbish from the http server. If it’s still 17000 lines (which I don’t think it should be), then find somewhere on the net to drop it and I’ll have a look.

7

Hi Chris,

here it comes.

Add Fibaro Wall Plug:

    2017-12-30 19:10:12.064 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - ZWave product zwave:device has no references!
    2017-12-30 19:10:12.071 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - ZWave product zwave:serial_zstick has no references!
    2017-12-30 19:10:12.323 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
    2017-12-30 19:10:12.327 [DEBUG] [ve.internal.protocol.ZWaveController] - Neither inclusion nor exclusion was active!
    2017-12-30 19:10:12.330 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Starting ZWave inclusion scan for zwave:serial_zstick:a72078f6
    2017-12-30 19:10:12.333 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
    2017-12-30 19:10:12.338 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
    2017-12-30 19:10:12.343 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
    2017-12-30 19:10:12.346 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 01 70 
    2017-12-30 19:10:12.349 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 01 70 
    2017-12-30 19:10:12.351 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 0. Queue={}
    2017-12-30 19:10:12.355 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 01 00 00 B2 
    2017-12-30 19:10:12.360 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
    2017-12-30 19:10:12.364 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 01 00 00 B2 
    2017-12-30 19:10:12.367 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 01 00 00 B2 
    2017-12-30 19:10:12.369 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 00 
    2017-12-30 19:10:12.372 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
    2017-12-30 19:10:12.374 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
    2017-12-30 19:10:12.388 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=C1 01 
    2017-12-30 19:10:12.391 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 00 
    2017-12-30 19:10:12.393 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
    2017-12-30 19:10:12.394 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
    2017-12-30 19:10:12.396 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 46ms/191ms.
    2017-12-30 19:10:27.326 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 02 00 00 B1 
    2017-12-30 19:10:27.337 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
    2017-12-30 19:10:27.340 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 02 00 00 B1 
    2017-12-30 19:10:27.344 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 02 00 00 B1 
    2017-12-30 19:10:27.347 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 02 00 00 
    2017-12-30 19:10:27.349 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
    2017-12-30 19:10:27.352 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=C1 01 
    2017-12-30 19:10:27.356 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 02 00 00 
    2017-12-30 19:10:27.358 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
    2017-12-30 19:10:27.361 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
    2017-12-30 19:10:30.404 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 07 00 00 B4 
    2017-12-30 19:10:30.411 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
    2017-12-30 19:10:30.415 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 07 00 00 B4 
    2017-12-30 19:10:30.418 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 07 00 00 B4 
    2017-12-30 19:10:30.421 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 07 00 00 
    2017-12-30 19:10:30.424 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
    2017-12-30 19:10:30.427 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
    2017-12-30 19:10:30.435 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=C1 01 
    2017-12-30 19:10:30.439 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 07 00 00 
    2017-12-30 19:10:30.441 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
    2017-12-30 19:10:30.443 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
    2017-12-30 19:10:42.332 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
    2017-12-30 19:10:42.336 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
    2017-12-30 19:10:42.339 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
    2017-12-30 19:10:42.339 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
    2017-12-30 19:10:42.342 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller end inclusion
    2017-12-30 19:10:42.343 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 01 B4 
    2017-12-30 19:10:42.346 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 01 B4 
    2017-12-30 19:10:42.502 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 06 00 00 B5 
    2017-12-30 19:10:42.507 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
    2017-12-30 19:10:42.510 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 06 00 00 B5 
    2017-12-30 19:10:42.513 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 06 00 00 B5 
    2017-12-30 19:10:42.516 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 00 00 
    2017-12-30 19:10:42.518 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
    2017-12-30 19:10:42.521 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
    2017-12-30 19:10:42.528 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 01 
    2017-12-30 19:10:42.532 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 00 00 
    2017-12-30 19:10:42.534 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
    2017-12-30 19:10:42.536 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
    2017-12-30 19:10:42.539 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 190ms/191ms.
    2017-12-30 19:10:49.918 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1A 00 49 84 02 14 04 10 01 5E 22 85 59 70 56 5A 7A 72 32 8E 71 73 98 31 25 86 4B 
    2017-12-30 19:10:49.926 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
    2017-12-30 19:10:49.931 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1A 00 49 84 02 14 04 10 01 5E 22 85 59 70 56 5A 7A 72 32 8E 71 73 98 31 25 86 4B 
    2017-12-30 19:10:49.937 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1A 00 49 84 02 14 04 10 01 5E 22 85 59 70 56 5A 7A 72 32 8E 71 73 98 31 25 86 4B 
    2017-12-30 19:10:49.941 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 02 14 04 10 01 5E 22 85 59 70 56 5A 7A 72 32 8E 71 73 98 31 25 86 
    2017-12-30 19:10:49.952 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update request. Node information received.
    2017-12-30 19:10:49.954 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update request. Node not known!
    2017-12-30 19:10:49.957 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
    2017-12-30 19:10:49.980 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovered
    2017-12-30 19:10:50.005 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:a72078f6:node2' to inbox.
    2017-12-30 19:10:50.015 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Newly included node doesn't exist - initialising from start.
    2017-12-30 19:10:50.023 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
    2017-12-30 19:10:50.028 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 01 
    2017-12-30 19:10:50.028 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Init node thread start
    2017-12-30 19:10:50.034 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 02 14 04 10 01 5E 22 85 59 70 56 5A 7A 72 32 8E 71 73 98 31 25 86 
    2017-12-30 19:10:50.040 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=0, expected=AddNodeToNetwork, cancelled=false      MISMATCH
    2017-12-30 19:10:50.172 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 2: Serializing from file /var/lib/openhab2/zwave/node2.xml
    2017-12-30 19:10:50.174 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 2: Error serializing from file: file does not exist.
    2017-12-30 19:10:50.177 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from EMPTYNODE
    2017-12-30 19:10:50.179 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - EMPTYNODE: queue length(0), free to send(true)
    2017-12-30 19:10:50.181 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
    2017-12-30 19:10:50.182 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: Initialisation starting
    2017-12-30 19:10:50.184 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to PROTOINFO
    2017-12-30 19:10:50.186 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
    2017-12-30 19:10:50.187 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
    2017-12-30 19:10:50.189 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: PROTOINFO - send IdentifyNode
    2017-12-30 19:10:50.191 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
    2017-12-30 19:10:50.192 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
    2017-12-30 19:10:50.195 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 02 B8 
    2017-12-30 19:10:50.196 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 02 B8 
    2017-12-30 19:10:50.199 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 0. Queue={}
    2017-12-30 19:10:50.202 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 00 00 00 03 00 00 B5 
    2017-12-30 19:10:50.203 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Init node thread finished
    2017-12-30 19:10:50.216 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
    2017-12-30 19:10:50.221 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 00 00 00 03 00 00 B5 
    2017-12-30 19:10:50.226 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 01 41 00 00 00 03 00 00 B5 
    2017-12-30 19:10:50.231 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=00 00 00 03 00 00 
    2017-12-30 19:10:50.235 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: ProtocolInfo
    2017-12-30 19:10:50.239 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Listening = false
    2017-12-30 19:10:50.242 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Routing = false
    2017-12-30 19:10:50.246 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Beaming = false
    2017-12-30 19:10:50.249 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Version = 1
    2017-12-30 19:10:50.252 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: FLIRS = false
    2017-12-30 19:10:50.255 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Security = false
    2017-12-30 19:10:50.258 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Max Baud = 9600
    2017-12-30 19:10:50.263 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Basic = Slave
    2017-12-30 19:10:50.266 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Generic = Not Known
    2017-12-30 19:10:50.270 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Specific = Not Known
    2017-12-30 19:10:50.274 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=IdentifyNode[0x41], type=Request[0x00], priority=High, dest=255, callback=0, payload=02 
    2017-12-30 19:10:50.278 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=00 00 00 03 00 00 
    2017-12-30 19:10:50.282 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false        transaction complete!
    2017-12-30 19:10:50.285 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
    2017-12-30 19:10:50.288 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
    2017-12-30 19:10:50.292 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.
    2017-12-30 19:10:50.295 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.
    2017-12-30 19:10:50.298 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PROTOINFO: queue length(0), free to send(true)
    2017-12-30 19:10:50.304 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
    2017-12-30 19:10:50.308 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to INIT_NEIGHBORS
    2017-12-30 19:10:50.311 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
    2017-12-30 19:10:50.315 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - INIT_NEIGHBORS try 0: stageAdvanced(true)
    2017-12-30 19:10:50.318 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: INIT_NEIGHBORS - send RoutingInfo
    2017-12-30 19:10:50.322 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 2: Request routing info
    2017-12-30 19:10:50.325 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
    2017-12-30 19:10:50.329 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
    2017-12-30 19:10:50.332 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 134ms/191ms.
    2017-12-30 19:10:50.334 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
    2017-12-30 19:10:50.336 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 02 00 00 03 79 
    2017-12-30 19:10:50.338 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 07 00 80 02 00 00 03 79 
    2017-12-30 19:10:50.348 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 20 01 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5E 
    2017-12-30 19:10:50.354 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
    2017-12-30 19:10:50.359 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 20 01 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5E 
    2017-12-30 19:10:50.366 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 20 01 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5E 
    2017-12-30 19:10:50.373 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=GetRoutingInfo[0x80], type=Response[0x01], priority=High, dest=255, callback=0, payload=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
    2017-12-30 19:10:50.376 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 2: Got NodeRoutingInfo request.
    2017-12-30 19:10:50.380 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 2: No neighbors reported
    2017-12-30 19:10:50.383 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
    2017-12-30 19:10:50.387 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=GetRoutingInfo[0x80], type=Request[0x00], priority=High, dest=255, callback=0, payload=02 00 00 03 
    2017-12-30 19:10:50.392 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=GetRoutingInfo[0x80], type=Response[0x01], priority=High, dest=255, callback=0, payload=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
    2017-12-30 19:10:50.396 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=GetRoutingInfo, callback id=0, expected=GetRoutingInfo, cancelled=false        transaction complete!
    2017-12-30 19:10:50.399 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
    2017-12-30 19:10:50.402 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - INIT_NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
    2017-12-30 19:10:50.403 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.
    2017-12-30 19:10:50.405 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.
    2017-12-30 19:10:50.407 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - INIT_NEIGHBORS: queue length(0), free to send(true)
    2017-12-30 19:10:50.408 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - INIT_NEIGHBORS try 1: stageAdvanced(false)
    2017-12-30 19:10:50.410 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to FAILED_CHECK
    2017-12-30 19:10:50.411 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
    2017-12-30 19:10:50.413 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
    2017-12-30 19:10:50.417 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 2: Requesting IsFailedNode status from controller.
    2017-12-30 19:10:50.419 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
    2017-12-30 19:10:50.421 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
    2017-12-30 19:10:50.423 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 83ms/191ms.
    2017-12-30 19:10:50.425 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
    2017-12-30 19:10:50.427 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 02 9B 
    2017-12-30 19:10:50.430 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 02 9B 
    2017-12-30 19:10:50.435 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99 
    2017-12-30 19:10:50.440 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
    2017-12-30 19:10:50.442 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 62 01 99 
    2017-12-30 19:10:50.444 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 62 01 99 
    2017-12-30 19:10:50.446 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IsFailedNodeID[0x62], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
    2017-12-30 19:10:50.448 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 2: Is currently marked as failed by the controller!
    2017-12-30 19:10:50.450 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Node is DEAD.
    2017-12-30 19:10:50.452 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
    2017-12-30 19:10:50.454 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Status event during initialisation - Node is FAILED
    2017-12-30 19:10:50.456 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is FAILED
    2017-12-30 19:10:50.458 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=IsFailedNodeID[0x62], type=Request[0x00], priority=High, dest=255, callback=0, payload=02 
    2017-12-30 19:10:50.460 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=IsFailedNodeID[0x62], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
    2017-12-30 19:10:50.462 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IsFailedNodeID, callback id=0, expected=IsFailedNodeID, cancelled=false        transaction complete!
    2017-12-30 19:10:50.464 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
    2017-12-30 19:10:50.465 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
    2017-12-30 19:10:50.467 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.
    2017-12-30 19:10:50.468 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.
    2017-12-30 19:10:50.470 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
    2017-12-30 19:10:50.471 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
    2017-12-30 19:10:50.473 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to WAIT
    2017-12-30 19:10:50.475 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
    2017-12-30 19:10:50.477 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - WAIT try 0: stageAdvanced(true)
    2017-12-30 19:10:50.479 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: WAIT - Listening=false, FrequentlyListening=false
    2017-12-30 19:10:50.481 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: WAIT - Still waiting!
    2017-12-30 19:10:50.482 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 50ms/191ms.
    2017-12-30 19:10:56.707 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=367, service.bundleid=238, service.scope=singleton} - org.openhab.binding.zwave
    2017-12-30 19:10:56.743 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
    2017-12-30 19:10:56.752 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: MANUFACTURER not set
    2017-12-30 19:10:56.755 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller status changed to ONLINE.
    2017-12-30 19:10:56.757 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller is ONLINE. Starting device initialisation.
    2017-12-30 19:10:56.786 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating node properties.
    2017-12-30 19:10:56.788 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating node properties. MAN=2147483647
    2017-12-30 19:10:56.791 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Properties synchronised
    2017-12-30 19:10:56.817 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
    2017-12-30 19:10:56.824 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
    2017-12-30 19:11:03.899 [INFO ] [org.quartz.core.QuartzScheduler     ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
8

For what it’s worth, I have the exact same issue with my ‘FGWP101 Metered Wall Plug Switch’ since recently (presumably after updating to OpenHAB 2.2)…

I will try to get the ZWave debug logs - I’ve already completely reset both of my wall plug modules and excluded and re-included them to my zwave controller to no avail. (I use the Z-wave stick from Aeotec)

9

Just for the records. I use the ZMEEUZB1 stick.
Meanwhile I colud test with another new Fibaro Wall Plug,
same issue. Also HABmin does not help.

Could it be that this Fibaro Wall Plug is really not kown by the database because Fibaro changed some Hardware revision?

10

So I‘ve updated my USB stick with the latest Firmware 5.22 hoping to come forward. I used the orginal Z-Way image and even there I couldn’t see this wall plug

One of my peers using the same stick with a Devolo wall plug without any problems.

11

Just tested the another USB Stick. Now it is working perfectly. So my USB Stick was broken, and the plugs are fine.

12

So you use another ZMEEUZB or other Z-Wave stick (such as Aeon one) ?