ZWAVE strange messages in log

Tags: #<Tag:0x00007f6173f34158> #<Tag:0x00007f6173f34018> #<Tag:0x00007f6173f3bc50>

i’ve got strange messages in zwave log.
2015-08-12 18:39:17.711 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:39:19.432 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:41:17.272 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:42:14.042 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:43:11.902 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:44:32.322 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:45:12.482 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:45:54.162 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:46:37.192 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-12 18:47:19.412 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length

What is it? NODE3 is fgms-001 multisensor now i try to catch this in debug mode… Here is error in debug:
2015-08-13 10:52:57.565 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ]- NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_BINARY, value = 255
2015-08-13 10:52:57.569 [DEBUG] [ApplicationCommandMessageClass:85 ]- Transaction not completed: node address inconsistent.
2015-08-13 10:52:57.571 [DEBUG] [eController$ZWaveReceiveThread:1441]- Receive Message = 01 09 00 04 00 03 03 60 0D 01 9E
2015-08-13 10:52:57.590 [DEBUG] [eController$ZWaveReceiveThread:1365]- Receive queue ADD: Length=1
2015-08-13 10:52:57.590 [DEBUG] [b.z.i.protocol.ZWaveController:1123]- Receive queue TAKE: Length=0
2015-08-13 10:52:57.592 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 04 00 03 03 60 0D 01 9E
2015-08-13 10:52:57.593 [DEBUG] [b.z.i.protocol.ZWaveController:1124]- Process Message = 01 09 00 04 00 03 03 60 0D 01 9E
2015-08-13 10:52:57.595 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 03 03 60 0D 01
2015-08-13 10:52:57.596 [DEBUG] [ApplicationCommandMessageClass:38 ]- NODE 3: Application Command Request (ALIVE:DONE)
2015-08-13 10:52:57.597 [DEBUG] [ApplicationCommandMessageClass:56 ]- NODE 3: Incoming command class MULTI_INSTANCE
2015-08-13 10:52:57.598 [DEBUG] [ZWaveMultiInstanceCommandClass:145 ]- NODE 3: Received Multi-instance/Multi-channel Request
2015-08-13 10:52:57.605 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-13 10:52:57.606 [DEBUG] [ApplicationCommandMessageClass:85 ]- Transaction not completed: node address inconsistent.

It does appear as though this frame is corrupt - there is no data in it. The 60 0D part says that this is a multi_instance message, but there’s then no encapsulated command class. I will update this debug message to add a little more information - maybe I can interpret the error differently which might allow the error to be removed, but the result will still be the same - this message has no data for some reason…

Do you know what triggers it?

Chris

I’ve updated the binding to change this log message - please try tomorrow with the latest snapshot and provide an updated log… Also, if you can indicate what happens when you get this error (eg is it when you get motion) that would be good, and possibly also posting the XML file for this node would be interesting…

Cheers
Chris

Today i’ll test it… Now i’m not at home and now there is no error…i think it PIR sensor. At evening i’ll make another test and send message here.

got it! Problem message appear when move detected.

2015-08-17 19:55:00.953 [DEBUG] [ApplicationCommandMessageClass:38 ]- NODE 3: Application Command Request (ALIVE:DONE)
2015-08-17 19:55:00.954 [DEBUG] [ApplicationCommandMessageClass:56 ]- NODE 3: Incoming command class CRC_16_ENCAP
2015-08-17 19:55:00.954 [DEBUG] [CRC16EncapsulationCommandClass:63 ]- NODE 3: Received CRC 16 Encapsulation Request
2015-08-17 19:55:00.955 [DEBUG] [CRC16EncapsulationCommandClass:129 ]- NODE 3: Calling handleApplicationCommandRequest.
2015-08-17 19:55:00.955 [DEBUG] [.ZWaveBinarySensorCommandClass:82 ]- NODE 3: Received Sensor Binary Request (v1)
2015-08-17 19:55:00.956 [DEBUG] [.ZWaveBinarySensorCommandClass:102 ]- NODE 3: Sensor Binary report, type=Unknown, value=255
2015-08-17 19:55:00.956 [DEBUG] [b.z.i.protocol.ZWaveController:595 ]- Notifying event listeners: ZWaveBinarySensorValueEvent
2015-08-17 19:55:00.956 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-08-17 19:55:00.957 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ]- NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_BINARY, value = 255
2015-08-17 19:55:00.958 [DEBUG] [eController$ZWaveReceiveThread:1365]- Receive queue ADD: Length=0
2015-08-17 19:55:00.970 [DEBUG] [ApplicationCommandMessageClass:85 ]- Transaction not completed: node address inconsistent.
2015-08-17 19:55:00.972 [DEBUG] [eController$ZWaveReceiveThread:1441]- Receive Message = 01 09 00 04 00 03 03 60 0D 01 9E
2015-08-17 19:55:00.989 [DEBUG] [eController$ZWaveReceiveThread:1365]- Receive queue ADD: Length=1
2015-08-17 19:55:00.990 [DEBUG] [b.z.i.protocol.ZWaveController:1123]- Receive queue TAKE: Length=0
2015-08-17 19:55:00.991 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 04 00 03 03 60 0D 01 9E
2015-08-17 19:55:00.992 [DEBUG] [b.z.i.protocol.ZWaveController:1124]- Process Message = 01 09 00 04 00 03 03 60 0D 01 9E
2015-08-17 19:55:00.993 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 03 03 60 0D 01
2015-08-17 19:55:00.994 [DEBUG] [ApplicationCommandMessageClass:38 ]- NODE 3: Application Command Request (ALIVE:DONE)
2015-08-17 19:55:00.995 [DEBUG] [ApplicationCommandMessageClass:56 ]- NODE 3: Incoming command class MULTI_INSTANCE
2015-08-17 19:55:00.996 [DEBUG] [ZWaveMultiInstanceCommandClass:145 ]- NODE 3: Received Multi-instance/Multi-channel Request
2015-08-17 19:55:00.996 [ERROR] [ZWaveMultiInstanceCommandClass:436 ]- NODE 3: Invalid data length
2015-08-17 19:55:01.000 [DEBUG] [ApplicationCommandMessageClass:85 ]- Transaction not completed: node address inconsistent.
2015-08-17 19:55:04.528 [DEBUG] [veMultiLevelSwitchCommandClass:163 ]- NODE 2: Creating new message for command SWITCH_MULTILEVEL_SET
2015-08-17 19:55:04.531 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 2: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-08-17 19:55:04.532 [DEBUG] [b.z.i.protocol.ZWaveController:898 ]- Callback ID = 144
2015-08-17 19:55:04.534 [DEBUG] [b.z.i.protocol.ZWaveController:580 ]- Enqueueing message. Queue length = 1
2015-08-17 19:55:04.534 [DEBUG] [WaveController$ZWaveSendThread:1171]- Took message from queue for sending. Queue length = 0
2015-08-17 19:55:04.537 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0A 00 13 02 03 26 01 00 25 90 75
2015-08-17 19:55:04.538 [DEBUG] [WaveController$ZWaveSendThread:1228]- NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 26 01 00 25 90 75
2015-08-17 19:55:04.546 [DEBUG] [eController$ZWaveReceiveThread:1441]- Receive Message = 01 04 01 13 01 E8
2015-08-17 19:55:04.579 [DEBUG] [eController$ZWaveReceiveThread:1365]- Receive queue ADD: Length=1
2015-08-17 19:55:04.580 [DEBUG] [b.z.i.protocol.ZWaveController:1123]- Receive queue TAKE: Length=0
2015-08-17 19:55:04.581 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8
2015-08-17 19:55:04.583 [DEBUG] [b.z.i.protocol.ZWaveController:1124]- Process Message = 01 04 01 13 01 E8
2015-08-17 19:55:04.583 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01
2015-08-17 19:55:04.584 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38 ]- NODE 2: Sent Data successfully placed on stack.

Here is config: Rename jpeg to xml)))))))

Thanks - it doesn’t show anything unfortunately… It basically looks ok except the frame has no information…

As a matter of interest, can you post the few lines before this log - I’d like to see the received data of the CRC_16 message…

Also, the XML didn’t come through - can you just paste it into the message - just encapsulate it within the <pre> tag to ensure it gets formatted correctly…

Cheers
Chris

Files are here


Скачать means Download
If you got problem with downloading you can tell your mail.

You have exactly the same device as I have - same version it seems. I don’t see the MULTI_INSTANCE command class in my XML files, but you have it in yours. This might be simply to do with the fact that you’re receiving commands from this class so the binding adds it to the class list - I suspect it’s not notified during initialisation as the version is 0 (which shouldn’t be possible during initialisation).

I have a suspicion that this might be caused by the MULTI_CHANNEL_ASSOCIATION - have you set this device up using different software, or only through OpenHAB? Currently the MULTI_CHANNEL_ASSOCIATION class is not supported in OH1, but I will add it for OH2. (I could also be wrong about this, but it’s my best guess at the moment :smile: ).

It might be interesting to completely reset the device to see if this changes.

Chris

I meant to add - I had no problem downloading - I even had a button called “Download” :smile:

your point! )) i paired devices with z-way-server not in OH.
Ahrhrh…so many clever words…i can understand 50% of your message. ))

I just wondered if you had configured this through other software (as you have), it might have used a command class that wasn’t supported by OH… I’m not sure of course - it’s a guess…

Even if this is the case, it still seems strange as this command doesn’t look correct, but maybe this is just my understanding of how it is used…

I would try to reset the device, and add it back in to the network.

(sorry - I hope you understand ok).

Cheers
Chris

Yes. i’ll try to reset,exclude,and add it with OH. Right?

Yes - let me know how you get on…

Ok. Give me 2-3 day

No problem - just whenever you get a chance is fine :smile:

Hi Chris!! There is no more problems in log. I reinclude FGMS-001 with habmin.
By the way what do you think about this messages? this messages are not WARNING. It’s normal message as i understand. m?
2015-08-21 23:01:44.501 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221 ]- NODE 4: Unsupported command class SWITCH_ALL
2015-08-21 23:01:44.690 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221 ]- NODE 2: Unsupported command class SWITCH_ALL

May be it’s good idea to mark this as INFO

Great - I suspect the issue is the MULTI_CHANNEL_ASSOCIATION class which I will implement in OH2 (it’s mostly implemented, but for it to be used, it needs some extra functionality to be included in the ESH core)…

Yes - you’re probably right. These messages simply say that a command class isn’t (yet!) supported by the binding, but in most (not all) cases, this isn’t an issue as many of the classes aren’t really important…

I’ll look at ‘downgrading’ these to INFO.

Cheers
Chris