Endless zwave error messages in OH2 log

semperor · January 4, 2017, 10:07pm

I’m playing with OH2 since a few weeks. I always get the following error messages. I tried many things, including to set up the whole raspberry pi. Any ideas? Maybe @chris ?

22:24:40.064 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 2 attempts left!
22:24:40.066 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
22:24:45.071 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 1 attempts left!
22:24:45.072 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
22:24:50.076 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 0 attempts left!
22:24:50.078 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
22:24:55.084 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=7, callback=177, payload=07 03 71 04 00
22:26:37.445 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:4c44233f:node3' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
22:26:39.750 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
22:26:39.752 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
22:26:44.756 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 1 attempts left!
22:26:44.758 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
22:26:49.762 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
22:26:49.764 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
22:26:54.769 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=194, payload=02 05 71 04 00 00 00
22:26:56.219 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:4c44233f:node3' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
22:27:07.316 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:4c44233f:node12' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
22:27:08.537 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
22:27:08.538 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.
22:27:13.543 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 1 attempts left!
22:27:13.545 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.
22:27:18.549 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 0 attempts left!
22:27:18.551 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.
22:27:23.557 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=3, callback=204, payload=03 05 71 04 00 00 00
22:27:25.006 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:4c44233f:node12' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
22:27:34.676 [INFO ] [marthome.event.ItemStateChangedEvent] - Node_5_Schlafzimmer_RelativeHumidity changed from 42 to 43
22:29:52.886 [INFO ] [marthome.event.ItemStateChangedEvent] - Node_4_Kueche_RelativeHumidity changed from 40 to 42
22:30:04.515 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 2 attempts left!
22:30:04.517 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message.
22:30:09.520 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 1 attempts left!
22:30:09.524 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message.
22:30:14.529 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 0 attempts left!
22:30:14.533 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message.
22:30:19.537 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=4, callback=221, payload=04 05 71 04 00 07 00
22:31:00.117 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 6: Timeout while sending message. Requeueing - 2 attempts left!
22:31:00.119 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 6: Got an error while sending data. Resending message.
22:31:05.122 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 6: Timeout while sending message. Requeueing - 1 attempts left!
22:31:05.124 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 6: Got an error while sending data. Resending message.
22:31:10.128 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 6: Timeout while sending message. Requeueing - 0 attempts left!
22:31:10.130 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 6: Got an error while sending data. Resending message.
22:31:15.134 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 6: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=6, callback=230, payload=06 05 71 04 00 07 00

Thanks in advance.

chris · January 5, 2017, 7:24am

It’s hard to say without a debug logfile. If the errors are regular and random, then it probably just indicates that there are communication problems in the network. If it’s systematic, then we’d need to look further, but without a longer debug log, it’s not possible to say much unfortunately.

semperor · January 6, 2017, 4:33pm

Thank you @chris. You will find the log at my gdrive. Would be great if you could find the reason and a solution. The log is really messy with these messageses.

semperor · January 8, 2017, 9:11pm

@chris do you had time to have a look at my logiles?

chris · January 9, 2017, 1:00pm

Sorry - I’ve had limited time as I’m on holiday abroad. I’ll try and take a look tonight if I can.

chris · January 9, 2017, 1:11pm

What are the devices that are giving the errors - are they all the same type? What version of the binding are you using? I’d suggest to update to the very latest snapshot from yesterday to see if that helps as I changed the way the ALARM_GET command works.

semperor · January 10, 2017, 8:25pm

Thank you very much @chris. I updated right now. Still the same behaviour.

I have three different kinds of Zwave things. I created a zip file with the XML files: https://drive.google.com/open?id=0B8ujMGuKIQQfc1Z6eVRyTzF5Tnc

Thank you 1000 times for your support!

chris · January 11, 2017, 1:43pm

Thanks. Can you provide me the links to the database for the devices you have (just the 3 giving trouble - node 2, 3 and 7 I think)? Sorry, but I’m travelling and generally have only poor access to internet.

semperor · January 13, 2017, 4:45pm

No problem @chris. Thank you for your help!!!

I looked in the log file and found the problems at nodes 2, 3, 4, 6, 7, 12. Only nodes 5 and 13 seem to be working. But 5 is the same as 2, 3, 4 and 12…

Nodes 2, 3, 4 and 12 are ZW100 (I assume the parameter ‘zwave_version’ shows me the firmware version, cause there are 3 diffrent versions in your database). Node 6 is a ZW074 and Node 7 a MT02646.

Additionally I found some other error messages:

2017-01-12 00:27:26.135 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Size error 4<>1 from config_255_4_wo
2017-01-12 00:27:26.183 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Size error 2<>1 from config_44_2
2017-01-12 00:27:26.666 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 4<>1 from config_255_4_wo
2017-01-12 00:27:27.323 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Size error 4<>1 from config_255_4_wo
2017-01-12 00:27:27.358 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Size error 4<>1 from config_255_4_wo
2017-01-12 00:27:27.534 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Size error 4<>1 from config_255_4_wo

spy0r · January 13, 2017, 6:54pm

i do have the same messages as well:

2017-01-10 21:37:20.195 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.
2017-01-10 21:37:21.099 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 2<>1 from config_42_2
2017-01-10 21:37:21.175 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 2<>1 from config_44_2
2017-01-10 21:37:31.482 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 2<>1 from config_42_2
2017-01-10 21:37:31.483 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 2<>1 from config_44_2
2017-01-10 21:37:31.483 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 4<>1 from config_255_4_wo
2017-01-10 21:37:31.488 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node...
2017-01-10 21:37:31.498 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 2<>1 from config_42_2
2017-01-10 21:37:31.499 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 2<>1 from config_44_2
2017-01-10 21:37:31.499 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Size error 4<>1 from config_255_4_wo
2017-01-10 21:37:31.499 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node...

as well as

2017-01-10 21:43:04.288 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 19: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-10 21:43:04.288 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 19: Got an error while sending data. Resending message.
2017-01-10 21:43:09.289 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 19: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-10 21:43:09.290 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 19: Got an error while sending data. Resending message.
2017-01-10 21:43:14.291 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 19: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-10 21:43:14.291 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 19: Got an error while sending data. Resending message.
2017-01-10 21:43:19.292 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 19: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=19, callback=164, payload=13 04 59 03 00 01 

2017-01-11 00:37:43.805 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-11 00:37:43.805 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.
2017-01-11 00:37:48.806 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-11 00:37:48.806 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.
2017-01-11 00:37:53.807 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-11 00:37:53.807 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Got an error while sending data. Resending message.
2017-01-11 00:37:58.808 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=3, callback=26, payload=03 05 71 04 00 00 00

in my case these errors are from different devices as ZW100 (Node3) or Sensative Strips (Node 19) but at the first view only from them regulary and not from other devices (there is another ZW100 in the same network)

How can i help?

Mike_Bagdanoff · January 13, 2017, 9:25pm

I’m hoping in the long run these will be lessened, most of mine have to do with not being able to talk to the ZCOMBO smoke detectors, which don’t seem to wake up when they are supposed to though the do work correctly regardless.

semperor · January 28, 2017, 12:17pm

@chris are you back from your trip? Would be great if you can find the reason and maybe a general solution. Because I’m not the only one:

and

chris · January 28, 2017, 4:13pm

Yep (unfortunately ;)).

I’m not really sure what you mean here. I’ve reduced the logging in general so most problems are now only logged in debug mode but that won’t mean the timeouts don’t exist. So, when you reference a link with someone saying that their ZWave network is “broken” - reducing the logging won’t really help that. Normally there’s many reasons for timeouts often it’s not a problem with the binding, and for sure there’s no single solution to everyones issues (unfortunately ;))…

Please can you ensure that you’re using the latest SNAPSHOT version of the binding and then provide the logs again if the problems still exist. Most of your timeouts are caused by ALARM_GET messages, and this has changed a bit on the past few weeks.

tschaban · May 11, 2017, 9:51pm

Hi @semperor, did you fix your problem with that? I’m experiencing same. Reboot helps for 20 hrs but later entire zWave network is dead.

many thx in advance