search

openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.7k forks source link

zwave exception constantly #1957

Closed snizzleorg closed 9 years ago

snizzleorg commented 9 years ago 
2015-01-10 14:49:35.336 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing
2015-01-10 14:49:40.376 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing
2015-01-10 14:49:45.426 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing
2015-01-10 14:49:45.447 [ERROR] [b.z.i.p.s.SendDataMessageClass] - Sent Data was not placed on stack due to error 0.
2015-01-10 14:49:49.434 [ERROR] [eController$ZWaveReceiveThread] - Got an exception during receiving. exiting thread.
java.lang.ArrayIndexOutOfBoundsException: 7
    at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:301) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleMultiChannelEncapResponse(ZWaveMultiInstanceCommandClass.java:399) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleApplicationCommandRequest(ZWaveMultiInstanceCommandClass.java:143) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:80) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:188) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:168) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$12(ZWaveController.java:162) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.processIncomingMessage(ZWaveController.java:1181) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.run(ZWaveController.java:1238) ~[na:na]
2015-01-10 14:49:50.466 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing
2015-01-10 14:49:55.207 [WARN ] [veController$WatchDogTimerTask] - Threads not alive, respawning
2015-01-10 14:49:55.224 [INFO ] [b.z.i.protocol.ZWaveController] - Disconnected from serial port
2015-01-10 14:49:55.227 [INFO ] [b.z.i.protocol.ZWaveController] - Connecting to serial port /dev/ttyAMA0
2015-01-10 14:49:55.239 [INFO ] [b.z.i.protocol.ZWaveController] - Serial port is initialized
2015-01-10 14:49:55.249 [WARN ] [b.z.i.p.s.SendDataMessageClass] - Already processed another send data request for this callback Id, ignoring.
2015-01-10 14:49:55.268 [WARN ] [b.z.i.p.s.SendDataMessageClass] - Already processed another send data request for this callback Id, ignoring.
2015-01-10 14:49:55.270 [ERROR] [eController$ZWaveReceiveThread] - Message cancelled by controller (CAN), resending
2015-01-10 14:50:00.420 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing

keeps happening constantly. I'm using the 1.6.1 openhab build and 1.6.1 zwave binding from cloudbees (downloaded today)

Any idea why this keep occurring?

snizzleorg commented 9 years ago

even after a fresh start:

2015-01-10 17:58:06.305 [INFO ] [.z.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyAMA0
2015-01-10 17:58:06.336 [INFO ] [.service.AbstractActiveService] - ZWave Refresh Service has been started
2015-01-10 17:58:06.934 [INFO ] [b.z.i.protocol.ZWaveController] - Starting Z-Wave controller
2015-01-10 17:58:06.963 [INFO ] [b.z.i.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms.
2015-01-10 17:58:06.966 [INFO ] [b.z.i.protocol.ZWaveController] - Connecting to serial port /dev/ttyAMA0
2015-01-10 17:58:07.585 [INFO ] [.service.AbstractActiveService] - HTTP Refresh Service has been started
2015-01-10 17:58:07.671 [INFO ] [b.z.i.protocol.ZWaveController] - Serial port is initialized
2015-01-10 17:58:11.370 [INFO ] [rialApiGetInitDataMessageClass] - NODE 1: Node found
2015-01-10 17:58:11.384 [INFO ] [rialApiGetInitDataMessageClass] - NODE 2: Node found
2015-01-10 17:58:11.397 [INFO ] [rialApiGetInitDataMessageClass] - NODE 3: Node found
2015-01-10 17:58:11.409 [INFO ] [rialApiGetInitDataMessageClass] - NODE 4: Node found
2015-01-10 17:58:11.431 [INFO ] [rialApiGetInitDataMessageClass] - NODE 6: Node found
2015-01-10 17:58:11.442 [INFO ] [rialApiGetInitDataMessageClass] - NODE 8: Node found
2015-01-10 17:58:11.456 [INFO ] [rialApiGetInitDataMessageClass] - NODE 9: Node found
2015-01-10 17:58:11.468 [INFO ] [rialApiGetInitDataMessageClass] - NODE 12: Node found
2015-01-10 17:58:11.481 [INFO ] [rialApiGetInitDataMessageClass] - NODE 23: Node found
2015-01-10 17:58:11.495 [INFO ] [rialApiGetInitDataMessageClass] - NODE 24: Node found
2015-01-10 17:58:11.506 [INFO ] [rialApiGetInitDataMessageClass] - NODE 25: Node found
2015-01-10 17:58:11.523 [INFO ] [rialApiGetInitDataMessageClass] - NODE 26: Node found
2015-01-10 17:58:11.536 [INFO ] [rialApiGetInitDataMessageClass] - NODE 33: Node found
2015-01-10 17:58:11.547 [INFO ] [rialApiGetInitDataMessageClass] - NODE 35: Node found
2015-01-10 17:58:11.564 [INFO ] [rialApiGetInitDataMessageClass] - NODE 37: Node found
2015-01-10 17:58:11.584 [INFO ] [rialApiGetInitDataMessageClass] - NODE 38: Node found
2015-01-10 17:58:11.598 [INFO ] [rialApiGetInitDataMessageClass] - NODE 39: Node found
2015-01-10 17:58:11.616 [INFO ] [rialApiGetInitDataMessageClass] - NODE 40: Node found
2015-01-10 17:58:11.637 [INFO ] [rialApiGetInitDataMessageClass] - NODE 41: Node found
2015-01-10 17:58:11.653 [INFO ] [rialApiGetInitDataMessageClass] - NODE 42: Node found
2015-01-10 17:58:11.664 [INFO ] [rialApiGetInitDataMessageClass] - NODE 44: Node found
2015-01-10 17:58:11.677 [INFO ] [rialApiGetInitDataMessageClass] - NODE 45: Node found
2015-01-10 17:58:11.690 [INFO ] [rialApiGetInitDataMessageClass] - NODE 46: Node found
2015-01-10 17:58:11.703 [INFO ] [rialApiGetInitDataMessageClass] - NODE 47: Node found
2015-01-10 17:58:11.718 [INFO ] [rialApiGetInitDataMessageClass] - NODE 48: Node found
2015-01-10 17:58:11.729 [INFO ] [rialApiGetInitDataMessageClass] - NODE 50: Node found
2015-01-10 17:58:11.743 [INFO ] [rialApiGetInitDataMessageClass] - NODE 51: Node found
2015-01-10 17:58:11.761 [INFO ] [rialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2015-01-10 17:58:11.777 [INFO ] [rialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2015-01-10 17:58:11.795 [INFO ] [rialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2015-01-10 17:58:11.830 [INFO ] [rialApiGetInitDataMessageClass] - # Nodes = 27
2015-01-10 17:58:11.857 [INFO ] [rialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2015-01-10 17:58:16.903 [ERROR] [WaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing
2015-01-10 17:58:21.938 [ERROR] [WaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing
2015-01-10 17:58:26.997 [ERROR] [WaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing
2015-01-10 17:58:28.991 [INFO ] [.service.AbstractActiveService] - Hue Refresh Service has been started
2015-01-10 17:58:30.470 [WARN ] [b.z.i.protocol.ZWaveController] - NODE 6: Config file data is invalid, ignoring config.
2015-01-10 17:58:32.027 [WARN ] [WaveController$ZWaveSendThread] - NODE 255: Discarding message: Message: class = GetControllerCapabilities (0x05), type = Request (0x00), payload = 
2015-01-10 17:58:33.346 [WARN ] [b.z.i.protocol.ZWaveController] - NODE 23: Config file data is invalid, ignoring config.
2015-01-10 17:58:33.969 [WARN ] [b.z.i.protocol.ZWaveController] - NODE 24: Config file data is invalid, ignoring config.
2015-01-10 17:58:36.641 [WARN ] [b.z.i.protocol.ZWaveController] - NODE 37: Config file data is invalid, ignoring config.
2015-01-10 17:58:37.066 [ERROR] [WaveController$ZWaveSendThread] - NODE 1: Timeout while sending message. Requeueing
2015-01-10 17:58:42.106 [ERROR] [WaveController$ZWaveSendThread] - NODE 1: Timeout while sending message. Requeueing
2015-01-10 17:58:43.864 [ERROR] [eController$ZWaveReceiveThread] - Message cancelled by controller (CAN), resending
2015-01-10 17:58:44.052 [ERROR] [eController$ZWaveReceiveThread] - Message cancelled by controller (CAN), resending
2015-01-10 17:58:44.405 [ERROR] [i.p.s.IdentifyNodeMessageClass] - NODE 4: Basic device class 0x60 not found
2015-01-10 17:58:44.433 [ERROR] [eController$ZWaveReceiveThread] - Message cancelled by controller (CAN), resending
2015-01-10 17:58:44.724 [ERROR] [eController$ZWaveReceiveThread] - Message cancelled by controller (CAN), resending
2015-01-10 17:58:45.338 [ERROR] [eController$ZWaveReceiveThread] - Got an exception during receiving. exiting thread.
java.lang.ArrayIndexOutOfBoundsException: 7
    at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:301) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleMultiChannelEncapResponse(ZWaveMultiInstanceCommandClass.java:399) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleApplicationCommandRequest(ZWaveMultiInstanceCommandClass.java:143) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:80) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:188) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:168) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$12(ZWaveController.java:162) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.processIncomingMessage(ZWaveController.java:1181) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.run(ZWaveController.java:1238) ~[na:na]
2015-01-10 17:58:47.698 [WARN ] [veController$WatchDogTimerTask] - Threads not alive, respawning
2015-01-10 17:58:47.737 [INFO ] [b.z.i.protocol.ZWaveController] - Disconnected from serial port
2015-01-10 17:58:47.757 [INFO ] [b.z.i.protocol.ZWaveController] - Connecting to serial port /dev/ttyAMA0
2015-01-10 17:58:47.797 [INFO ] [b.z.i.protocol.ZWaveController] - Serial port is initialized
2015-01-10 17:58:48.434 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - Unsupported command class SWITCH_ALL (0x27)
2015-01-10 17:58:48.835 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - Unsupported command class SWITCH_ALL (0x27)
2015-01-10 17:58:48.942 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - Unsupported command class SWITCH_ALL (0x27)
2015-01-10 17:58:49.330 [WARN ] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 38: Already in or beyond node stage, ignoring. current = Frequently Changed Information, requested = Ping Node
2015-01-10 17:58:49.671 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - Unsupported command class SWITCH_ALL (0x27)
2015-01-10 17:58:54.926 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing
2015-01-10 17:58:54.933 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2015-01-10 17:58:59.986 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing
2015-01-10 17:58:59.993 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2015-01-10 17:59:05.046 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing
2015-01-10 17:59:05.050 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2015-01-10 17:59:07.269 [ERROR] [eController$ZWaveReceiveThread] - Message cancelled by controller (CAN), resending
2015-01-10 17:59:07.551 [ERROR] [eController$ZWaveReceiveThread] - Got an exception during receiving. exiting thread.
java.lang.ArrayIndexOutOfBoundsException: 7
    at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:301) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleMultiChannelEncapResponse(ZWaveMultiInstanceCommandClass.java:399) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleApplicationCommandRequest(ZWaveMultiInstanceCommandClass.java:143) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:80) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:188) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:168) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$12(ZWaveController.java:162) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.processIncomingMessage(ZWaveController.java:1181) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.run(ZWaveController.java:1238) ~[na:na]
2015-01-10 17:59:07.699 [WARN ] [veController$WatchDogTimerTask] - Threads not alive, respawning
2015-01-10 17:59:07.725 [INFO ] [b.z.i.protocol.ZWaveController] - Disconnected from serial port
2015-01-10 17:59:07.728 [INFO ] [b.z.i.protocol.ZWaveController] - Connecting to serial port /dev/ttyAMA0
2015-01-10 17:59:07.770 [INFO ] [b.z.i.protocol.ZWaveController] - Serial port is initialized
2015-01-10 17:59:08.437 [WARN ] [.z.internal.ZWaveActiveBinding] - No item bound for event from nodeId = 3, endpoint = 0, command class = SWITCH_BINARY, value = 0, ignoring.
2015-01-10 17:59:13.526 [ERROR] [WaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing
2015-01-10 17:59:13.529 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.
2015-01-10 17:59:18.606 [ERROR] [WaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing
2015-01-10 17:59:18.609 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.

Is this perhaps specific to the razberry module or do other people have the same issue with USB Z-Wave adaptors?

cdjackson commented 9 years ago

I would recommend upgrading to the latest version on the HABmin site. This fixes a problem that I think will help here. The CAN messages in the log are indicative of problems communicating with the z-stick and I’ve today fixed a major issue with the binding that will help this considerably.

Also, please enable debug logging if problems persist as the current log is not useful to work out what’s wrong.=

cdjackson commented 9 years ago

Does this issue still exist with the test binding on HABmin site?

snizzleorg commented 9 years ago

I haven't had the chance yet. Downloaded it just now and will give it a spin.

https://github.com/cdjackson/HABmin/blob/6a2b375d40341f439226e94814d4e01b807f3e3c/addons/org.openhab.binding.zwave-1.7.0-SNAPSHOT.jar

Hope that this is the correct version.

snizzleorg commented 9 years ago

It seems to not throw exceptions any more.

snizzleorg commented 9 years ago

well.. too early. although it doesn't happen often anymore. but I still get the exceptions:

2015-02-01 13:41:18.578 [DEBUG] [ApplicationCommandMessageClass:37  ]- NODE 38: Application Command Request (Stage Node Complete)
2015-02-01 13:41:18.587 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 38: Incoming command class MULTI_INSTANCE (0x60)
2015-02-01 13:41:18.592 [DEBUG] [ZWaveMultiInstanceCommandClass:120 ]- NODE 38: Received Multi-instance/Multi-channel Request
2015-02-01 13:41:18.658 [ERROR] [eController$ZWaveReceiveThread:1271]- Got an exception during receiving. exiting thread.
java.lang.ArrayIndexOutOfBoundsException: 7
    at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:301) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleMultiChannelEncapResponse(ZWaveMultiInstanceCommandClass.java:399) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleApplicationCommandRequest(ZWaveMultiInstanceCommandClass.java:143) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:80) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:188) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:168) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$12(ZWaveController.java:162) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.processIncomingMessage(ZWaveController.java:1181) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.run(ZWaveController.java:1238) ~[na:na]
2015-02-01 13:41:18.666 [DEBUG] [eController$ZWaveReceiveThread:1273]- Stopped Z-Wave receive thread
2015-02-01 13:41:22.335 [WARN ] [veController$WatchDogTimerTask:1307]- Threads not alive, respawning
2015-02-01 13:41:22.338 [DEBUG] [WaveController$ZWaveSendThread:1133]- Stopped Z-Wave send thread
2015-02-01 13:41:22.353 [INFO ] [b.z.i.protocol.ZWaveController:458 ]- Disconnected from serial port
2015-02-01 13:41:22.356 [INFO ] [b.z.i.protocol.ZWaveController:376 ]- Connecting to serial port /dev/ttyAMA0
2015-02-01 13:41:22.367 [DEBUG] [eController$ZWaveReceiveThread:1189]- Starting Z-Wave receive thread
2015-02-01 13:41:22.371 [INFO ] [b.z.i.protocol.ZWaveController:389 ]- Serial port is initialized
2015-02-01 13:41:22.374 [DEBUG] [WaveController$ZWaveSendThread:1042]- Starting Z-Wave send thread
2015-02-01 13:41:22.381 [DEBUG] [eController$ZWaveReceiveThread:1237]- Receive Message = 01 09 00 04 00 33 03 30 03 FF 0E 
2015-02-01 13:41:22.387 [DEBUG] [b.z.i.protocol.ZWaveController:164 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 33 03 30 03 FF
cdjackson commented 9 years ago

Thanks - can you post the few lines before this? I want to see the “Receive Message = “ from just before this point.

snizzleorg commented 9 years ago 
2015-02-01 13:10:29.414 [DEBUG] [.z.internal.ZWaveActiveBinding:398 ]- ZwaveIncomingEvent
2015-02-01 13:10:29.421 [DEBUG] [eController$ZWaveReceiveThread:1237]- Receive Message = 01 09 00 04 00 26 03 20 01 FF 09
2015-02-01 13:10:29.429 [DEBUG] [b.z.i.protocol.ZWaveController:164 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payl$
2015-02-01 13:10:29.432 [DEBUG] [ApplicationCommandMessageClass:37  ]- NODE 38: Application Command Request (Stage Frequently Changed Information)
2015-02-01 13:10:29.435 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 38: Incoming command class BASIC (0x20)
2015-02-01 13:10:29.439 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:70  ]- Received Basic Request for Node ID = 38
2015-02-01 13:10:29.441 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:75  ]- Basic Set sent to the controller will be processed as Basic Report
2015-02-01 13:10:29.444 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:104 ]- Basic report from nodeId = 38, value = 0xFF
2015-02-01 13:10:29.447 [DEBUG] [b.z.i.protocol.ZWaveController:482 ]- Notifying event listeners
2015-02-01 13:10:29.450 [DEBUG] [.z.internal.ZWaveActiveBinding:398 ]- ZwaveIncomingEvent
2015-02-01 13:10:29.454 [DEBUG] [.z.internal.ZWaveActiveBinding:419 ]- Got a value event from Z-Wave network for nodeId = 38, endpoint = 0, command c$
2015-02-01 13:10:29.465 [DEBUG] [b.z.i.protocol.ZWaveController:482 ]- Notifying event listeners
2015-02-01 13:10:29.467 [DEBUG] [.z.internal.ZWaveActiveBinding:398 ]- ZwaveIncomingEvent
2015-02-01 13:10:29.483 [DEBUG] [eController$ZWaveReceiveThread:1237]- Receive Message = 01 09 00 04 00 26 03 60 0D 01 BB
2015-02-01 13:10:29.490 [DEBUG] [b.z.i.protocol.ZWaveController:164 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payl$
2015-02-01 13:10:29.499 [DEBUG] [ApplicationCommandMessageClass:37  ]- NODE 38: Application Command Request (Stage Frequently Changed Information)
2015-02-01 13:10:29.502 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 38: Incoming command class MULTI_INSTANCE (0x60)
2015-02-01 13:10:29.509 [DEBUG] [ZWaveMultiInstanceCommandClass:120 ]- NODE 38: Received Multi-instance/Multi-channel Request
2015-02-01 13:10:29.571 [ERROR] [eController$ZWaveReceiveThread:1271]- Got an exception during receiving. exiting thread.
java.lang.ArrayIndexOutOfBoundsException: 7
        at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:301) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleMultiChannelEncapResponse(ZWaveMultiInstance$
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleApplicationCommandRequest(ZWaveMultiInstance$
        at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java$
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:188) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:168) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$12(ZWaveController.java:162) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.processIncomingMessage(ZWaveController.java:1181) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.run(ZWaveController.java:1238) ~[na:na]
2015-02-01 13:10:29.580 [DEBUG] [eController$ZWaveReceiveThread:1273]- Stopped Z-Wave receive thread
2015-02-01 13:10:32.293 [WARN ] [veController$WatchDogTimerTask:1307]- Threads not alive, respawning
2015-02-01 13:10:32.296 [DEBUG] [WaveController$ZWaveSendThread:1133]- Stopped Z-Wave send thread
2015-02-01 13:10:32.309 [INFO ] [b.z.i.protocol.ZWaveController:458 ]- Disconnected from serial port
2015-02-01 13:10:32.312 [INFO ] [b.z.i.protocol.ZWaveController:376 ]- Connecting to serial port /dev/ttyAMA0
2015-02-01 13:10:32.338 [DEBUG] [eController$ZWaveReceiveThread:1189]- Starting Z-Wave receive thread
2015-02-01 13:10:32.342 [INFO ] [b.z.i.protocol.ZWaveController:389 ]- Serial port is initialized
2015-02-01 13:10:32.345 [DEBUG] [WaveController$ZWaveSendThread:1042]- Starting Z-Wave send thread
2015-02-01 13:10:34.363 [DEBUG] [eController$ZWaveReceiveThread:1237]- Receive Message = 01 16 00 49 84 2A 10 04 08 04 80 46 81 72 8F 75 43 86 84 EF $
2015-02-01 13:10:34.373 [DEBUG] [b.z.i.protocol.ZWaveController:164 ]- Message: class = ApplicationUpdate (0x49), type = Request (0x00), payload = 84$
2015-02-01 13:10:34.377 [DEBUG] [.ApplicationUpdateMessageClass:46  ]- NODE 42: Application update request, node information received.
2015-02-01 13:10:34.380 [DEBUG] [b.z.i.protocol.ZWaveController:482 ]- Notifying event listeners
2015-02-01 13:10:34.382 [DEBUG] [.z.internal.ZWaveActiveBinding:398 ]- ZwaveIncomingEvent
2015-02-01 13:10:34.386 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:403 ]- NODE 42: Is awake with 2 messages in the wake-up queue.
2015-02-01 13:10:34.389 [DEBUG] [b.z.i.protocol.ZWaveController:830 ]- Callback ID = 187
2015-02-01 13:11:42.047 [DEBUG] [.z.internal.ZWaveActiveBinding:419 ]- Got a value event from Z-Wave network for nodeId = 38, endpoint = 0, command c$
2015-02-01 13:11:42.061 [DEBUG] [eController$ZWaveReceiveThread:1237]- Receive Message = 01 09 00 04 00 26 03 60 0D 01 BB
2015-02-01 13:11:42.155 [DEBUG] [b.z.i.protocol.ZWaveController:164 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payl$
2015-02-01 13:11:42.164 [DEBUG] [ApplicationCommandMessageClass:37  ]- NODE 38: Application Command Request (Stage Frequently Changed Information)
2015-02-01 13:11:42.171 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 38: Incoming command class MULTI_INSTANCE (0x60)
2015-02-01 13:11:42.178 [DEBUG] [ZWaveMultiInstanceCommandClass:120 ]- NODE 38: Received Multi-instance/Multi-channel Request
2015-02-01 13:11:42.239 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 255: Creating empty message of class = SendDataAbort (0x16), type = Reque$
2015-02-01 13:11:42.243 [DEBUG] [o.b.z.i.protocol.SerialMessage:226 ]- Assembled message buffer = 01 03 00 16 EA
2015-02-01 13:11:42.254 [DEBUG] [WaveController$ZWaveSendThread:1096]- Sending Message = 01 03 00 16 EA
2015-02-01 13:11:42.255 [ERROR] [eController$ZWaveReceiveThread:1271]- Got an exception during receiving. exiting thread.
java.lang.ArrayIndexOutOfBoundsException: 7
        at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:301) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleMultiChannelEncapResponse(ZWaveMultiInstance$
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleApplicationCommandRequest(ZWaveMultiInstance$
        at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java$
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:188) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:168) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$12(ZWaveController.java:162) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.processIncomingMessage(ZWaveController.java:1181) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.run(ZWaveController.java:1238) ~[na:na]
2015-02-01 13:11:42.268 [DEBUG] [eController$ZWaveReceiveThread:1273]- Stopped Z-Wave receive thread
2015-02-01 13:11:42.278 [ERROR] [WaveController$ZWaveSendThread:1109]- NODE 8: Timeout while sending message. Requeueing
2015-02-01 13:11:42.282 [DEBUG] [.z.internal.protocol.ZWaveNode:419 ]- NODE 8: Retry count exceeded. Node is DEAD.
2015-02-01 13:11:42.286 [DEBUG] [b.z.i.protocol.ZWaveController:482 ]- Notifying event listeners
2015-02-01 13:11:42.294 [WARN ] [veController$WatchDogTimerTask:1307]- Threads not alive, respawning
2015-02-01 13:11:42.297 [DEBUG] [.z.internal.ZWaveActiveBinding:398 ]- ZwaveIncomingEvent
2015-02-01 13:19:26.858 [DEBUG] [.z.internal.ZWaveActiveBinding:398 ]- ZwaveIncomingEvent
2015-02-01 13:19:26.862 [DEBUG] [.z.internal.ZWaveActiveBinding:419 ]- Got a value event from Z-Wave network for nodeId = 38, endpoint = 0, command c$
2015-02-01 13:19:26.905 [DEBUG] [eController$ZWaveReceiveThread:1237]- Receive Message = 01 09 00 04 00 26 03 60 0D 01 BB
2015-02-01 13:19:26.923 [DEBUG] [b.z.i.protocol.ZWaveController:164 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payl$
2015-02-01 13:19:26.926 [DEBUG] [ApplicationCommandMessageClass:37  ]- NODE 38: Application Command Request (Stage Node Complete)
2015-02-01 13:19:26.929 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 38: Incoming command class MULTI_INSTANCE (0x60)
2015-02-01 13:19:26.938 [DEBUG] [ZWaveMultiInstanceCommandClass:120 ]- NODE 38: Received Multi-instance/Multi-channel Request
2015-02-01 13:19:26.994 [ERROR] [eController$ZWaveReceiveThread:1271]- Got an exception during receiving. exiting thread.
java.lang.ArrayIndexOutOfBoundsException: 7
        at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:301) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleMultiChannelEncapResponse(ZWaveMultiInstance$
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleApplicationCommandRequest(ZWaveMultiInstance$
        at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java$
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:188) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:168) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$12(ZWaveController.java:162) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.processIncomingMessage(ZWaveController.java:1181) ~[na:na]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.run(ZWaveController.java:1238) ~[na:na]
2015-02-01 13:19:27.003 [DEBUG] [eController$ZWaveReceiveThread:1273]- Stopped Z-Wave receive thread
2015-02-01 13:19:29.239 [DEBUG] [.b.z.i.c.ZWaveBatteryConverter:60  ]- Generating poll message for BATTERY for node 38 endpoint 0
2015-02-01 13:19:29.242 [DEBUG] [i.p.c.ZWaveBatteryCommandClass:104 ]- Node 38: Creating new message for application command BATTERY_GET
2015-02-01 13:19:29.249 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 38: Creating empty message of class = SendData (0x13), type = Request (0x$
2015-02-01 13:19:29.252 [DEBUG] [b.z.i.protocol.ZWaveController:830 ]- Callback ID = 11
2015-02-01 13:19:29.260 [DEBUG] [WaveController$ZWaveSendThread:1048]- Took message from queue for sending. Queue length = 0
2015-02-01 13:19:29.264 [DEBUG] [o.b.z.i.protocol.SerialMessage:226 ]- Assembled message buffer = 01 09 00 13 26 02 80 02 25 0B 6D
2015-02-01 13:19:29.267 [DEBUG] [b.z.i.protocol.ZWaveController:467 ]- Enqueueing message. Queue length = 0
2015-02-01 13:19:29.283 [DEBUG] [WaveController$ZWaveSendThread:1077]- Sending Message = 01 09 00 13 26 02 80 02 25 0B 6D
2015-02-01 13:19:32.304 [WARN ] [veController$WatchDogTimerTask:1307]- Threads not alive, respawning
2015-02-01 13:19:32.307 [DEBUG] [WaveController$ZWaveSendThread:1133]- Stopped Z-Wave send thread
2015-02-01 13:19:32.324 [INFO ] [b.z.i.protocol.ZWaveController:458 ]- Disconnected from serial port
2015-02-01 13:19:32.327 [INFO ] [b.z.i.protocol.ZWaveController:376 ]- Connecting to serial port /dev/ttyAMA0
2015-02-01 13:19:32.352 [DEBUG] [eController$ZWaveReceiveThread:1189]- Starting Z-Wave receive thread
2015-02-01 13:19:32.356 [DEBUG] [WaveController$ZWaveSendThread:1042]- Starting Z-Wave send thread
snizzleorg commented 9 years ago

Its actually still happening approx. every 5 min

and the receive message is the same:

Receive Message = 01 09 00 04 00 26 03 60 0D 01 BB

so it seems that this particular message causes the exception

snizzleorg commented 9 years ago

the related sensor is a FGMS01 (Fibaro Motion Sensor) - so I guess its not some much the time but me moving about and triggering it...

cdjackson commented 9 years ago

What is device 38? It’s sending completely invalid data. It’s sending a multi_instance_encapsulation message with no data… I’ll add a check to stop this, but this seems ‘broken’ to me.

snizzleorg commented 9 years ago

screen shot 2015-02-01 at 14 08 38

cdjackson commented 9 years ago

I have one of these - I’ll double check it’s not doing the same thing…

It’s sending out 2 messages. The first is the basic class (FF means triggered). It’s fine. 01 09 00 04 00 26 03 20 01 FF 09

Then almost instantly it’s ending the following -: 01 09 00 04 00 26 03 60 0D 01 BB This is broken Ignoring the beginning few bytes -: 26 = 38 decimal and is the node number 03 is the length of the data 60 is multi instance message 0d is encapsulation 01 is endpoint ID BB is the checksum

So, the data isn’t in error (as such) - it’s just effectively an empty frame… I’ll add a check to catch this...=

snizzleorg commented 9 years ago

Well actually I have a couple of these. Only one seems to cause the problem... maybe its a configuration issue?

snizzleorg commented 9 years ago

although they are all configured identically

screen shot 2015-02-01 at 14 14 40

cdjackson commented 9 years ago

What about associations - are they the same?

snizzleorg commented 9 years ago

no. apparently not. Node 38 has group 3 (Controller Updates) associated with the raspberry pi running openhab. The others don't. They only have group 1 (device status) associated with openhab.

snizzleorg commented 9 years ago

actually only one other hasn't. Of the ones that have only Node38 is causing problems.

cdjackson commented 9 years ago

I use group 3 for all Fibaro devices - normally no other groups. I’ve just added a check to stop this so will test shortly.=

cdjackson commented 9 years ago

Mine only seems to be sending the BINARY report - not the multi_instance

cdjackson commented 9 years ago

I’ve just loaded a new version to the HABmin git - let me know if it helps...=

snizzleorg commented 9 years ago

Ok. I downloaded it but same exception remains:

2015-02-01 16:10:41.228 [DEBUG] [eController$ZWaveReceiveThread:1237]- Receive Message = 01 09 00 04 00 26 03 60 0D 01 BB 
2015-02-01 16:10:41.313 [DEBUG] [b.z.i.protocol.ZWaveController:164 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 26 03 60 0D 01 
2015-02-01 16:10:41.347 [DEBUG] [ApplicationCommandMessageClass:37  ]- NODE 38: Application Command Request (Stage Frequently Changed Information)
2015-02-01 16:10:41.365 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 38: Incoming command class MULTI_INSTANCE (0x60)
2015-02-01 16:10:41.393 [DEBUG] [ZWaveMultiInstanceCommandClass:120 ]- NODE 38: Received Multi-instance/Multi-channel Request
2015-02-01 16:10:41.675 [ERROR] [eController$ZWaveReceiveThread:1271]- Got an exception during receiving. exiting thread.
java.lang.ArrayIndexOutOfBoundsException: 7
    at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:301) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleMultiChannelEncapResponse(ZWaveMultiInstanceCommandClass.java:399) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.handleApplicationCommandRequest(ZWaveMultiInstanceCommandClass.java:143) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:80) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:188) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:168) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$12(ZWaveController.java:162) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.processIncomingMessage(ZWaveController.java:1181) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveReceiveThread.run(ZWaveController.java:1238) ~[na:na]
2015-02-01 16:10:41.715 [DEBUG] [eController$ZWaveReceiveThread:1273]- Stopped Z-Wave receive thread
2015-02-01 16:10:42.234 [WARN ] [veController$WatchDogTimerTask:1307]- Threads not alive, respawning
2015-02-01 16:10:42.237 [DEBUG] [WaveController$ZWaveSendThread:1133]- Stopped Z-Wave send thread
2015-02-01 16:10:42.242 [INFO ] [b.z.i.protocol.ZWaveController:458 ]- Disconnected from serial port
2015-02-01 16:10:42.278 [INFO ] [b.z.i.protocol.ZWaveController:376 ]- Connecting to serial port /dev/ttyAMA0
2015-02-01 16:10:42.327 [DEBUG] [eController$ZWaveReceiveThread:1189]- Starting Z-Wave receive thread
2015-02-01 16:10:42.334 [DEBUG] [WaveController$ZWaveSendThread:1042]- Starting Z-Wave send thread
2015-02-01 16:10:42.333 [INFO ] [b.z.i.protocol.ZWaveController:389 ]- Serial port is initialized
snizzleorg commented 9 years ago

AHH stop. It was still using the old binding. will test now. Sorry for that

cdjackson commented 9 years ago

:) I was just about to say the debug messages didn’t line up…=

snizzleorg commented 9 years ago

hm. i deleted the old binding and now I have those:

root@snizzlesync:~# ls -l /usr/share/openhab/addons/
total 3496
-rw-r--r-- 1 openhab root     126 Nov 30 23:18 README
-rw-r--r-- 1 openhab root   12099 Nov 30 23:13 org.openhab.action.pushover-1.6.1.jar
-rw-r--r-- 1 openhab root   80586 Nov 30 23:15 org.openhab.binding.astro-1.6.1.jar
-rw-r--r-- 1 openhab root   19403 Nov 30 23:14 org.openhab.binding.http-1.6.1.jar
-rw-r--r-- 1 openhab root   27455 Nov 30 23:14 org.openhab.binding.hue-1.6.1.jar
-rw-r--r-- 1 openhab root   10071 Nov 30 23:14 org.openhab.binding.networkhealth-1.6.1.jar
-rw-r--r-- 1 openhab root 1581267 Jan 25 16:17 org.openhab.binding.plex-1.7.0-SNAPSHOT.jar
-rw-r--r-- 1 openhab root    8269 Nov 30 23:14 org.openhab.binding.wol-1.6.1.jar
-rw-r--r-- 1 openhab root   31525 Feb  1 15:49 org.openhab.binding.zwave-1.7.0-SNAPSHOT.jar
-rw-r--r-- 1 openhab root 1123714 Jun 20  2014 org.openhab.io.habmin-1.5.0-SNAPSHOT.jar
-rw-r--r-- 1 openhab root   32547 Jan 10 11:50 org.openhab.io.habmin-1.7.0-SNAPSHOT.jar
-rw-r--r-- 1 openhab root    7378 Nov 30 23:16 org.openhab.persistence.logging-1.6.1.jar
-rw-r--r-- 1 openhab root  618722 Nov 30 23:16 org.openhab.persistence.rrd4j-1.6.1.jar

zwave however doesn't seem to get loaded at all....

porbably for the same reason the habmin interface isn't working either. also the binding seems rather small... is the size correct?

snizzleorg commented 9 years ago

ah - again my fault. something went wrong while downloading. the supposedly jar file just contains a 404 error html page...

snizzleorg commented 9 years ago

now with the actual binding I get this:

2015-02-01 16:44:53.799 [INFO ] [.service.AbstractActiveService] - ZWave Refresh Service has been started
2015-02-01 16:44:54.109 [ERROR] [.service.AbstractActiveService] - Error while executing background thread ZWave Refresh Service
java.lang.NullPointerException: null
    at org.openhab.binding.zwave.internal.ZWaveActiveBinding.execute(ZWaveActiveBinding.java:99) ~[na:na]
    at org.openhab.core.binding.AbstractActiveBinding$BindingActiveService.execute(AbstractActiveBinding.java:156) ~[na:na]
    at org.openhab.core.service.AbstractActiveService$RefreshThread.run(AbstractActiveService.java:173) ~[na:na]
2015-02-01 16:44:59.305 [INFO ] [.b.a.internal.bus.AstroBinding] - AstroConfig[latitude=52.52437,longitude=13.41053,interval=600,systemTimezone=Europe/Berlin (CET +0100),daylightSavings=false]

in openhab.log

but it seems to work and I don't get any exceptions in the wave.log anymore. At least not for now.

I'll wait a few hours to see if I get any exceptions.

cdjackson commented 9 years ago

Thanks. I’ll take a look at this error…

Can you take a look in the log for the following string “Process Multi-channel Encapsulation”. It should also be accompanied by an error message…

snizzleorg commented 9 years ago

it isn't:

2015-02-01 16:46:44.949 [DEBUG] [eController$ZWaveReceiveThread:1552]- Receive Message = 01 05 00 13 14 00 FD
2015-02-01 16:46:44.957 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 3: Sent Data successfully placed on stack.
2015-02-01 16:46:44.963 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 13 14 00 00 00 FF
2015-02-01 16:46:44.974 [DEBUG] [b.z.i.protocol.ZWaveController:1246]- Process Message = 01 07 00 13 14 00 00 00 FF
2015-02-01 16:46:44.967 [DEBUG] [eController$ZWaveReceiveThread:1552]- Receive Message = 01 0D 00 04 00 03 07 60 0D 01 01 25 03 00 B9
2015-02-01 16:46:44.983 [DEBUG] [b.z.i.protocol.ZWaveController:174 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 14 00
2015-02-01 16:46:44.989 [DEBUG] [b.z.i.p.s.SendDataMessageClass:75  ]- NODE 3: SendData Request. CallBack ID = 20, Status = Transmission complete and$
2015-02-01 16:46:44.993 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload $
2015-02-01 16:46:45.003 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload $
2015-02-01 16:46:45.007 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SendData, expected=ApplicationCommandHand$
2015-02-01 16:46:45.016 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0D 00 04 00 03 07 60 0D 01 01 25 03 00 B9
2015-02-01 16:46:45.025 [DEBUG] [b.z.i.protocol.ZWaveController:1246]- Process Message = 01 0D 00 04 00 03 07 60 0D 01 01 25 03 00 B9
2015-02-01 16:46:45.034 [DEBUG] [b.z.i.protocol.ZWaveController:174 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payl$
2015-02-01 16:46:45.042 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 3: Application Command Request (ALIVE:DYNAMIC_VALUES)
2015-02-01 16:46:45.050 [DEBUG] [ApplicationCommandMessageClass:57  ]- NODE 3: Incoming command class MULTI_INSTANCE (0x60)
2015-02-01 16:46:45.055 [DEBUG] [ZWaveMultiInstanceCommandClass:144 ]- NODE 3: Received Multi-instance/Multi-channel Request
2015-02-01 16:46:45.063 [DEBUG] [ZWaveMultiInstanceCommandClass:407 ]- NODE 3: Process Multi-channel Encapsulation 10 : 5
2015-02-01 16:46:45.071 [DEBUG] [ZWaveMultiInstanceCommandClass:425 ]- NODE 3: Requested Command Class = SWITCH_BINARY (0x25)
2015-02-01 16:46:45.077 [DEBUG] [ZWaveMultiInstanceCommandClass:445 ]- NODE 3: Endpoint = 1, calling handleApplicationCommandRequest.
2015-02-01 16:46:45.083 [DEBUG] [.ZWaveBinarySwitchCommandClass:79  ]- Received Switch Binary Request for Node ID = 3
2015-02-01 16:46:45.089 [DEBUG] [.ZWaveBinarySwitchCommandClass:115 ]- NODE 3: Switch Binary report, value = 0x00
2015-02-01 16:46:45.095 [DEBUG] [b.z.i.protocol.ZWaveController:656 ]- Notifying event listeners
2015-02-01 16:46:45.101 [DEBUG] [.z.internal.ZWaveActiveBinding:430 ]- ZwaveIncomingEvent
2015-02-01 16:46:45.107 [DEBUG] [.z.internal.ZWaveActiveBinding:447 ]- NODE 3: Got a value event from Z-Wave network, endpoint = 1, command class = S$
2015-02-01 16:46:45.141 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload $
2015-02-01 16:46:45.154 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = ApplicationCommandHandler (0x04), type = Request$
2015-02-01 16:46:45.165 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=ApplicationCommandHandler, expected=Appli$
2015-02-01 16:46:45.173 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-02-01 16:46:45.179 [DEBUG] [b.z.i.protocol.ZWaveController:656 ]- Notifying event listeners
2015-02-01 16:46:45.187 [DEBUG] [.z.internal.ZWaveActiveBinding:430 ]- ZwaveIncomingEvent

or here:

2015-02-01 16:47:00.498 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 4: Sent Data successfully placed on stack.
2015-02-01 16:47:00.563 [DEBUG] [eController$ZWaveReceiveThread:1552]- Receive Message = 01 05 00 13 21 00 C8
2015-02-01 16:47:00.585 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 13 21 00 00 00 CA
2015-02-01 16:47:00.590 [DEBUG] [b.z.i.protocol.ZWaveController:1246]- Process Message = 01 07 00 13 21 00 00 00 CA
2015-02-01 16:47:00.598 [DEBUG] [b.z.i.protocol.ZWaveController:174 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 21 00
2015-02-01 16:47:00.602 [DEBUG] [b.z.i.p.s.SendDataMessageClass:75  ]- NODE 4: SendData Request. CallBack ID = 33, Status = Transmission complete and$
2015-02-01 16:47:00.629 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload $
2015-02-01 16:47:00.638 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload $
2015-02-01 16:47:00.650 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SendData, expected=ApplicationCommandHand$
2015-02-01 16:47:00.686 [DEBUG] [eController$ZWaveReceiveThread:1552]- Receive Message = 01 0D 00 04 00 04 07 60 0D 01 01 25 03 00 BE
2015-02-01 16:47:00.712 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0D 00 04 00 04 07 60 0D 01 01 25 03 00 BE
2015-02-01 16:47:00.725 [DEBUG] [b.z.i.protocol.ZWaveController:1246]- Process Message = 01 0D 00 04 00 04 07 60 0D 01 01 25 03 00 BE
2015-02-01 16:47:00.741 [DEBUG] [b.z.i.protocol.ZWaveController:174 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payl$
2015-02-01 16:47:00.753 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 4: Application Command Request (ALIVE:DYNAMIC_VALUES)
2015-02-01 16:47:00.780 [DEBUG] [ApplicationCommandMessageClass:57  ]- NODE 4: Incoming command class MULTI_INSTANCE (0x60)
2015-02-01 16:47:00.789 [DEBUG] [ZWaveMultiInstanceCommandClass:144 ]- NODE 4: Received Multi-instance/Multi-channel Request
2015-02-01 16:47:00.805 [DEBUG] [ZWaveMultiInstanceCommandClass:407 ]- NODE 4: Process Multi-channel Encapsulation 10 : 5
2015-02-01 16:47:00.817 [DEBUG] [ZWaveMultiInstanceCommandClass:425 ]- NODE 4: Requested Command Class = SWITCH_BINARY (0x25)
2015-02-01 16:47:00.832 [DEBUG] [ZWaveMultiInstanceCommandClass:445 ]- NODE 4: Endpoint = 1, calling handleApplicationCommandRequest.
2015-02-01 16:47:00.847 [DEBUG] [.ZWaveBinarySwitchCommandClass:79  ]- Received Switch Binary Request for Node ID = 4
2015-02-01 16:47:00.862 [DEBUG] [.ZWaveBinarySwitchCommandClass:115 ]- NODE 4: Switch Binary report, value = 0x00
2015-02-01 16:47:00.872 [DEBUG] [b.z.i.protocol.ZWaveController:656 ]- Notifying event listeners
2015-02-01 16:47:00.885 [DEBUG] [.z.internal.ZWaveActiveBinding:430 ]- ZwaveIncomingEvent
2015-02-01 16:47:00.895 [DEBUG] [.z.internal.ZWaveActiveBinding:447 ]- NODE 4: Got a value event from Z-Wave network, endpoint = 1, command class = S$
2015-02-01 16:47:00.923 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload $
2015-02-01 16:47:00.953 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = ApplicationCommandHandler (0x04), type = Request$
2015-02-01 16:47:00.963 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=ApplicationCommandHandler, expected=Appli$
2015-02-01 16:47:00.979 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-02-01 16:47:00.988 [DEBUG] [b.z.i.protocol.ZWaveController:656 ]- Notifying event listeners
2015-02-01 16:47:01.001 [DEBUG] [.z.internal.ZWaveActiveBinding:430 ]- ZwaveIncomingEvent
2015-02-01 16:47:01.016 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:878 ]- NODE 4: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request$
2015-02-01 16:47:01.039 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:187 ]- NODE 4: Node advancer - checking initialisation queue.
2015-02-01 16:47:01.049 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:192 ]- NODE 4: Node advancer - message removed from queue. Queue size now 1.
2015-02-01 16:47:01.065 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:252 ]- NODE 4: Node advancer - DYNAMIC_VALUES: queue length(1), free to send(true)
2015-02-01 16:47:01.081 [DEBUG] [b.z.i.protocol.ZWaveController:1020]- Callback ID = 34
2015-02-01 16:47:01.096 [DEBUG] [b.z.i.protocol.ZWaveController:641 ]- Enqueueing message. Queue length = 8
snizzleorg commented 9 years ago

with the node 38 it is however accompanied by an error:

2015-02-01 16:47:08.573 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 38: Application Command Request (FAILED:WAIT)
2015-02-01 16:47:08.579 [DEBUG] [.z.internal.protocol.ZWaveNode:223 ]- NODE 38: Node has risen from the DEAD. Init stage is WAIT:{}.
2015-02-01 16:47:08.584 [DEBUG] [.z.internal.protocol.ZWaveNode:244 ]- NODE 38: Initialisation incomplete, not signalling state change.
2015-02-01 16:47:08.591 [DEBUG] [ApplicationCommandMessageClass:57  ]- NODE 38: Incoming command class BASIC (0x20)
2015-02-01 16:47:08.600 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:75  ]- Received Basic Request for Node ID = 38
2015-02-01 16:47:08.608 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:80  ]- Basic Set sent to the controller will be processed as Basic Report
2015-02-01 16:47:08.613 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:109 ]- Basic report from nodeId = 38, value = 0xFF
2015-02-01 16:47:08.619 [DEBUG] [b.z.i.protocol.ZWaveController:656 ]- Notifying event listeners
2015-02-01 16:47:08.625 [DEBUG] [.z.internal.ZWaveActiveBinding:430 ]- ZwaveIncomingEvent
2015-02-01 16:47:08.630 [DEBUG] [.z.internal.ZWaveActiveBinding:447 ]- NODE 38: Got a value event from Z-Wave network, endpoint = 0, command class = $
2015-02-01 16:47:08.650 [DEBUG] [ApplicationCommandMessageClass:86  ]- Transaction not completed: node address inconsistent.
2015-02-01 16:47:08.658 [DEBUG] [WaveController$ZWaveSendThread:1293]- Took message from queue for sending. Queue length = 7
2015-02-01 16:47:08.664 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0A 00 13 04 03 85 02 02 25 25 64
2015-02-01 16:47:08.667 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 04 00 26 03 60 0D 01 BB
2015-02-01 16:47:08.681 [DEBUG] [WaveController$ZWaveSendThread:1350]- NODE 4: Sending REQUEST Message = 01 0A 00 13 04 03 85 02 02 25 25 64
2015-02-01 16:47:08.685 [DEBUG] [b.z.i.protocol.ZWaveController:1246]- Process Message = 01 09 00 04 00 26 03 60 0D 01 BB
2015-02-01 16:47:08.696 [DEBUG] [eController$ZWaveReceiveThread:1552]- Receive Message = 01 04 01 13 01 E8
2015-02-01 16:47:08.706 [DEBUG] [b.z.i.protocol.ZWaveController:174 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payl$
2015-02-01 16:47:08.714 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 38: Application Command Request (ALIVE:WAIT)
2015-02-01 16:47:08.724 [DEBUG] [ApplicationCommandMessageClass:57  ]- NODE 38: Incoming command class MULTI_INSTANCE (0x60)
2015-02-01 16:47:08.734 [DEBUG] [ApplicationCommandMessageClass:63  ]- NODE 38: Command class MULTI_INSTANCE (0x60) not found, trying to add it.
2015-02-01 16:47:08.758 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:220 ]- NODE 38: Creating new instance of command class MULTI_INSTANCE
2015-02-01 16:47:08.762 [DEBUG] [ApplicationCommandMessageClass:69  ]- NODE 38: Adding command class MULTI_INSTANCE (0x60)
2015-02-01 16:47:08.767 [DEBUG] [.z.internal.protocol.ZWaveNode:499 ]- NODE 38: Adding command class MULTI_INSTANCE to the list of supported command $
2015-02-01 16:47:08.787 [DEBUG] [ZWaveMultiInstanceCommandClass:144 ]- NODE 38: Received Multi-instance/Multi-channel Request
2015-02-01 16:47:08.789 [DEBUG] [ZWaveMultiInstanceCommandClass:407 ]- NODE 38: Process Multi-channel Encapsulation 6 : 5
2015-02-01 16:47:08.792 [ERROR] [ZWaveMultiInstanceCommandClass:410 ]- NODE 38: Invalid data length
2015-02-01 16:47:08.795 [DEBUG] [ApplicationCommandMessageClass:86  ]- Transaction not completed: node address inconsistent.
2015-02-01 16:47:08.808 [DEBUG] [eController$ZWaveReceiveThread:1552]- Receive Message = 01 05 00 13 25 00 CC
2015-02-01 16:47:08.812 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8
2015-02-01 16:47:08.822 [DEBUG] [b.z.i.protocol.ZWaveController:1246]- Process Message = 01 04 01 13 01 E8
2015-02-01 16:47:08.825 [DEBUG] [b.z.i.protocol.ZWaveController:174 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01
2015-02-01 16:47:08.849 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 4: Sent Data successfully placed on stack.
2015-02-01 16:47:08.856 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 13 25 00 00 00 CE
2015-02-01 16:47:08.860 [DEBUG] [eController$ZWaveReceiveThread:1552]- Receive Message = 01 10 00 04 00 04 0A 85 03 02 05 00 01 04 81 FF 13 0C
2015-02-01 16:47:08.864 [DEBUG] [b.z.i.protocol.ZWaveController:1246]- Process Message = 01 07 00 13 25 00 00 00 CE
cdjackson commented 9 years ago

That’s great - thanks. It looks like this is fixed (as far as the binding goes anyway - there’s still the question of why the device is sending invalid data)….=

snizzleorg commented 9 years ago

hm... thanks for helping me. maybe I'll reset the offending motion detector if I get the time to climb up the ladder... It's still working and signalling movement - so I'm not urged...

cdjackson commented 9 years ago

Just to note that I also fixed the other NPE you reported earlier... Thanks.

I'll close this - any more hassles though, feel free to open another issue...

NCO3 commented 8 years ago

Interesting thread :-) I have the org.openhab.binding.zwave-1.7.1.jar in my addons and get timeouts very often (node is dead). The openhab package I use is the apt-get. Can I replace the 1.7.1 zwave binding addon with this one without the risk of incompatibilities? org.openhab.binding.zwave-1.8.0-SNAPSHOT.jar ?? Thanks.

cdjackson commented 8 years ago

Yes you can update the versions - no problem.

Sent from my iPhone

On 13 Nov 2015, at 13:28, NCO3 notifications@github.com wrote:

Interesting thread :-) I have the org.openhab.binding.zwave-1.7.1.jar in my addons and get timeouts very often (node is dead). The openhab package I use is the apt-get. Can I replace the 1.7.1 zwave binding addon with this one without the risk of incompatibilities? org.openhab.binding.zwave-1.8.0-SNAPSHOT.jar ?? Thanks.

— Reply to this email directly or view it on GitHub.

EleanorRagone commented 8 years ago

I'm not entirely sure if it's directly related, but I'm getting pretty much all of these identical errors. (I've googled a handful of errors I'm getting and this thread comes up every time). I am running 1.8.1.

I'm also having issues with a handful of my 6 nodes being marked dead randomly. I can't seem to figure out why it's happening. It seems to have started after I decided to reorganize my items into separate files, which seems to have upset habmin. Any thoughts?

EleanorRagone commented 8 years ago

Restoring all my items to a single file and restarting a few times seemed to fix the problem.... for now, at least.