Frequent timeouts while sending message

[OMR (Ole Morten Rønning)]

Hello.

I have had my zwave network up for a week now, and an noticing quite a lot of Timeout while sending message errors.
In most cases, retransmissions don’t succeed either.

My .items file contains:

Group kitchen

Group livingRoom

Group switches

Group lights

Group sensors

Group remotes

Group div

Group phones

Dimmer WallplugStuaCornerLamp     "Lampe (sofa)"            <dimmablelight>  (livingRoom, lights)        { channel = "zwave:device:3f5c8071:node13:switch_dimmer" } 

Dimmer WallplugStuaShelfLamp      "Lampett (hylle)"         <dimmablelight>  (livingRoom, lights)        { channel = "zwave:device:3f5c8071:node10:switch_dimmer" }

Dimmer WallplugStuaWooferLamp     "Lampett (woofer)"        <dimmablelight>  (livingRoom, lights)        { channel = "zwave:device:3f5c8071:node8:switch_dimmer" }

Dimmer WallplugStuaPianoLamp      "Pianolampe"              <dimmablelight>  (livingRoom, lights)        { channel = "zwave:device:3f5c8071:node9:switch_dimmer" }

Dimmer BuildInStuaWindowLamps     "Karnapp"                 <dimmablelight>  (livingRoom, lights)        { channel = "zwave:device:3f5c8071:node19:switch_dimmer" }

Dimmer BuildInKjDiningTableLamp   "Pendel (spisebord)"      <dimmablelight>  (livingRoom, lights)        { channel = "zwave:device:3f5c8071:node18:switch_dimmer" }

Dimmer WallplugKjCornerLamp       "Lampe (spisestue)"       <dimmablelight>  (livingRoom, lights)        { channel = "zwave:device:3f5c8071:node14:switch_dimmer" }

Dimmer BuildInKjRoofBenchLamp     "Tak (kjøkkenbenk)"      <dimmablelight>  (kitchen, lights)           { channel = "zwave:device:3f5c8071:node16:switch_dimmer" }

Dimmer BuildInKjRoofIslandLamp    "Tak (kjøkkenøy)"        <dimmablelight>  (kitchen, lights)           { channel = "zwave:device:3f5c8071:node17:switch_dimmer" }

Switch WallplugKjokkenPCBenchLamp "Benk (PCer)"            <light>          (kitchen, lights)           { channel = "zwave:device:3f5c8071:node3:switch_binary" }

Switch BuildInKjokkenBench        "Benk (overskap)"        <light>          (kitchen, lights)           { channel = "zwave:device:3f5c8071:node15:switch_binary" }

Number LivingRoomTemperature      "Temperatur (stue)"      <temperature>    (div, sensors)              { channel = "zwave:device:3f5c8071:node7:sensor_temperature" }

Switch WallplugHeaterLexus        "Motorvarmer Lexus"      <poweroutlet>    (div, switches)             { channel = "zwave:device:3f5c8071:node12:switch_binary" }

Switch WallplugReceiver           "Receiver (loft)"        <receiver>       (div, switches)             { channel = "zwave:device:3f5c8071:node11:switch_binary" }

Switch WallplugTV                 "TV" 	 	      		   <television>     (div, switches)             { channel = "zwave:device:3f5c8071:node4:switch_binary" }

Number WallSwitchStua             "Bryter (stua)"          <wallswitch>     (div, remotes)              { channel = "zwave:device:3f5c8071:node22:scene_number" }

Number WallSwitchKjokken          "Bryter (kjøkken)"       <wallswitch>     (div, remotes)              { channel = "zwave:device:3f5c8071:node6:scene_number" }

Alle dimmers and switches are Nexa zwave, except for node12 which is a Fibaro Wall Plug.

Snippet of last hour log grep:

2017-03-05 14:01:07.585 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:01:12.588 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:01:17.591 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:01:27.857 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:01:32.861 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:01:37.864 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:01:48.045 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 10: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:01:53.048 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 10: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:01:58.051 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 10: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:02:08.661 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:02:13.725 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:02:18.729 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:02:23.732 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:02:40.073 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:02:45.076 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:02:50.079 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:06:49.411 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 12: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:06:54.414 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 12: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:06:59.417 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 12: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:31:07.586 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:31:12.590 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:31:17.594 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:31:27.864 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:31:32.867 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:31:37.871 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:31:48.230 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:31:53.234 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:31:58.237 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:32:08.635 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 9: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:32:13.639 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 9: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:32:18.644 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 9: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:32:28.708 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:32:33.711 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:32:38.715 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:32:49.147 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:32:54.151 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:32:59.154 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:33:09.282 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 8: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:33:14.285 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 8: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:33:19.288 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 8: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-05 14:36:49.421 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 12: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-05 14:36:54.424 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 12: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-05 14:36:59.428 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 12: Timeout while sending message. Requeueing - 0 attempts left!

Here are all my logs for easy grep’ing: MyLogs

The only practical implication of this, is that my wall-switch remote sometimes takes 5s to react.

Appreciate if any with more OH2 knowhow than me could give logs a look.
I’m on OH2 Stable 2.0.0

Cheers

[chris (Chris Jackson)]

What are the devices? Let’s start at least with node 11 - the timeout is caused by sending an alarm request -:

[OMR (Ole Morten Rønning)]

Dimmer Wallplug* = Nexa AD147 nodes: 8,9,10,13 & 14

Switch Wallplug* = Nexa AN180 nodes: 3,4, & 11

Switch WallplugHeaterLexus = Fibaro FGWP104 node: 12

Dimmer BuildIn* = Nexa AD146 nodes 16,17,18 & 19

Switch BuildIn* = Nexa AN179 node: 15

Rest are battery powered:

Remote NodOn node: 6 & 22

Sensor: Aeon node: 7

All nodes, except 12 are within a 5m radius of each other.

[chris (Chris Jackson)]

Which version of openhab are you using? Is it a new snapshot or an older version?

I suspect that the problem is you have an old version of OH (possibly the release version). This is polling the alarm channels that don’t actually allow polling - this is fixed in a more recent version.

[OMR (Ole Morten Rønning)]

@OMR

I’m on OH2 Stable 2.0.0

OK, so which version do you suggest I try?

Thanks for looking into this.

[chris (Chris Jackson)]

@OMR

OK, so which version do you suggest I try?

I’d suggest to use the nightly snapshot.

[OMR (Ole Morten Rønning)]

Will do.
Do you know what the road map for a new stable is?

[chris (Chris Jackson)]

I believe the plan is to have one approximately every 3 months, but it’s not been discussed recently.

[OMR (Ole Morten Rønning)]

Just upgraded to snapshot 2.1.0~20170304125936-1 - and all errors in the log went away! Nice

2 side effects of upgrade:

1. Paper UI, all Locations in Control is gone. No things or items listed. Control tab is completely blank
2. HABmin does not show thing Fibaro Wall Plug properly (effect meter items), but ON/OFF works
3. HABmin zwave network viewer does not show topology as I would expect in latest version

Cheers