openHAB ignores refresh_interval

bruxi · December 10, 2015, 7:40am

Hi,

I try to get Greenwave PowerNode NS310-F running with openHAB. Basically they work but they don’t send status updates to the controller by themselves as mentioned in the manual. So I try to refresh them by refresh_interval=10 e.g.
But this is fully ignored by openHAB, they don’t refresh at all as I can see in the event log.
Here’s my item setting:
Switch HomeEntertainmentReceiverSwitch “Power” (gEntertainment) { zwave=“24:command=BASIC,refresh_interval=60” }

I also tried with command=BINARY-SWITCH, same results.

Another question is: has anybody successfully used the power meter function of that sort of devices? This doesn’t work either. The following setting leads to no result (another switch but same Powernode device):

Switch WashingmachineSwitch “Waschmaschinenschalter” (gKitchen, gSwitches) { zwave=“25:command=BASIC,refresh_interval=10” }
Number WashingmachinePowerConsumption “Stromverbrauch total [%.2f KWh]” (gPowerControl) { zwave=“25:command=METER,meter_scale=E_KWh,refresh_interval=300” }

Thanks and best regards,
Jens

Spaceman_Spiff · December 11, 2015, 1:14pm

Unfortunately I don’t have the PowerNode, but I have had no issues with the refresh-intervall.
It has been working well for me. Maybe this is a PowerNode issue?

bruxi · December 12, 2015, 3:00pm

I don’t think that this is only an issue with the Powernodes. I have this behaviour also with other devices which report their state change to the controller when being switched. Here are all devices or items which should refresh by refresh_interval:

cat $OHCONFIG/items/zwave.items | grep refresh
Switch GlobeLamp “Globus” (gLR) { zwave=“10:command=SWITCH_BINARY,refresh_interval=5” }
Switch BeamerSwitch “Beamerschalter” (gHomeEntertainment, gSwitches) { zwave=“11:command=SWITCH_BINARY,refresh_interval=10” }
// Number BeamerPowerConsumption “Stromverbrauch total [%.2f KWh]” (gPowerControl) { zwave=“11:command=METER,meter_scale=E_KWh,refresh_interval=300” }
Switch HomeEntertainmentReceiverSwitch “Power” (gEntertainment) { zwave=“24:command=BASIC,refresh_interval=60” }
Number HomeEntertainmentPowerConsumption “Home-Entertainment Stromverbrauch total [%.2f KWh]” (gPowerControl) { zwave=“24:command=METER,meter_scale=E_KWh,refresh_interval=300” }
Switch KitchenTableLamp “Küchentischlampe” (gKitchen,gKitchenLamps) { zwave=“22:0:command=SWITCH_BINARY,refresh_interval=10” }
Switch KitchenSmallLamp “Schnippeleckenlampe” (gKitchen,gKitchenLamps) { zwave=“5:0:command=SWITCH_BINARY,refresh_interval=10” }
Switch WashingmachineSwitch “Waschmaschinenschalter” (gKitchen, gSwitches) { zwave=“25:command=BASIC,refresh_interval=10” }
Number WashingmachinePowerConsumption “Stromverbrauch total [%.2f KWh]” (gPowerControl) { zwave=“25:command=METER,meter_scale=E_KWh,refresh_interval=300” }
Number WashingmachineWattsConsumption “Stromaufnahme z.Zt. [%.2f Watt]” <power_watts> (gPowerControl) { zwave=“25:command=METER,meter_scale=E_W,refresh_interval=30” }
Switch BedroomLamp “Schlafzimmerlampe” (gBedroom) { zwave=“20:command=SWITCH_BINARY,refresh_interval=10” }

Having a look at the event log, some items refresh, some don’t:
cat $OHEVENTS | grep -e Kitchen -e Washing -e BedroomLamp | tail -100
2015-12-12 15:42:52 - KitchenSmallLamp state updated to OFF
2015-12-12 15:43:12 - KitchenSmallLamp state updated to OFF
2015-12-12 15:43:27 - KitchenSmallLamp state updated to OFF
2015-12-12 15:43:42 - KitchenSmallLamp state updated to OFF
2015-12-12 15:43:57 - KitchenSmallLamp state updated to OFF
2015-12-12 15:44:12 - KitchenSmallLamp state updated to OFF
2015-12-12 15:44:27 - KitchenSmallLamp state updated to OFF
2015-12-12 15:44:47 - KitchenSmallLamp state updated to OFF
2015-12-12 15:44:54 - KitchenTempChart state updated to 19.3
2015-12-12 15:44:54 - KitchenTemp state updated to 19.3
2015-12-12 15:44:55 - KitchenHumidityChart state updated to 52
2015-12-12 15:44:55 - KitchenHumidity state updated to 52
2015-12-12 15:44:56 - KitchenBattery state updated to 100
2015-12-12 15:44:56 - KitchenLumi state updated to 0
2015-12-12 15:45:02 - KitchenSmallLamp state updated to OFF
2015-12-12 15:45:17 - KitchenSmallLamp state updated to OFF
2015-12-12 15:45:32 - KitchenSmallLamp state updated to OFF
2015-12-12 15:45:47 - KitchenSmallLamp state updated to OFF
2015-12-12 15:46:02 - KitchenSmallLamp state updated to OFF
2015-12-12 15:46:22 - KitchenSmallLamp state updated to OFF
2015-12-12 15:46:37 - KitchenSmallLamp state updated to OFF
2015-12-12 15:46:52 - KitchenSmallLamp state updated to OFF
2015-12-12 15:47:07 - KitchenSmallLamp state updated to OFF
2015-12-12 15:47:22 - KitchenSmallLamp state updated to OFF
2015-12-12 15:47:42 - KitchenSmallLamp state updated to OFF
2015-12-12 15:47:57 - KitchenSmallLamp state updated to OFF
2015-12-12 15:48:12 - KitchenSmallLamp state updated to OFF
2015-12-12 15:48:27 - KitchenSmallLamp state updated to OFF
2015-12-12 15:48:43 - KitchenSmallLamp state updated to OFF
2015-12-12 15:48:43 - KitchenSmallLamp state updated to OFF
2015-12-12 15:48:57 - KitchenSmallLamp state updated to OFF
2015-12-12 15:49:17 - KitchenSmallLamp state updated to OFF
2015-12-12 15:49:32 - KitchenSmallLamp state updated to OFF
2015-12-12 15:49:48 - KitchenSmallLamp state updated to OFF
2015-12-12 15:49:54 - KitchenTempChart state updated to 19.3
2015-12-12 15:49:54 - KitchenTemp state updated to 19.3
2015-12-12 15:49:55 - KitchenHumidityChart state updated to 53
2015-12-12 15:49:55 - KitchenHumidity state updated to 53
2015-12-12 15:49:56 - KitchenHumidityChart state updated to 53
2015-12-12 15:49:56 - KitchenHumidity state updated to 53
2015-12-12 15:49:56 - KitchenBattery state updated to 100
2015-12-12 15:49:56 - KitchenLumi state updated to 0
2015-12-12 15:50:03 - KitchenSmallLamp state updated to OFF
2015-12-12 15:50:17 - KitchenSmallLamp state updated to OFF
2015-12-12 15:50:32 - KitchenSmallLamp state updated to OFF
2015-12-12 15:50:53 - KitchenSmallLamp state updated to OFF
2015-12-12 15:51:07 - KitchenSmallLamp state updated to OFF
2015-12-12 15:51:23 - KitchenSmallLamp state updated to OFF
2015-12-12 15:51:37 - KitchenSmallLamp state updated to OFF
2015-12-12 15:51:52 - KitchenSmallLamp state updated to OFF
2015-12-12 15:52:13 - KitchenSmallLamp state updated to OFF
2015-12-12 15:52:24 - KitchenMotion state updated to OPEN
2015-12-12 15:52:28 - KitchenSmallLamp state updated to OFF
2015-12-12 15:52:28 - KitchenTableLamp state updated to ON
2015-12-12 15:52:43 - KitchenSmallLamp state updated to OFF
2015-12-12 15:52:58 - KitchenSmallLamp state updated to OFF
2015-12-12 15:53:13 - KitchenSmallLamp state updated to OFF
2015-12-12 15:53:28 - KitchenSmallLamp state updated to OFF
2015-12-12 15:53:47 - KitchenMotion state updated to CLOSED
2015-12-12 15:53:48 - KitchenSmallLamp state updated to OFF
2015-12-12 15:54:03 - KitchenSmallLamp state updated to OFF
2015-12-12 15:54:18 - KitchenSmallLamp state updated to OFF
2015-12-12 15:54:33 - KitchenSmallLamp state updated to OFF
2015-12-12 15:54:48 - KitchenSmallLamp state updated to OFF
2015-12-12 15:54:54 - KitchenTempChart state updated to 19.4
2015-12-12 15:54:55 - KitchenTemp state updated to 19.4
2015-12-12 15:54:55 - KitchenHumidityChart state updated to 53
2015-12-12 15:54:55 - KitchenHumidity state updated to 53
2015-12-12 15:54:56 - KitchenBattery state updated to 100
2015-12-12 15:54:56 - KitchenLumi state updated to 1
2015-12-12 15:55:03 - KitchenSmallLamp state updated to OFF
2015-12-12 15:55:03 - KitchenSmallLamp state updated to OFF
2015-12-12 15:55:23 - KitchenSmallLamp state updated to OFF
2015-12-12 15:55:38 - KitchenSmallLamp state updated to OFF
2015-12-12 15:55:53 - KitchenSmallLamp state updated to OFF
2015-12-12 15:56:08 - KitchenSmallLamp state updated to OFF
2015-12-12 15:56:08 - KitchenSmallLamp state updated to OFF
2015-12-12 15:56:08 - KitchenSmallLamp state updated to OFF
2015-12-12 15:56:23 - KitchenSmallLamp state updated to OFF
2015-12-12 15:56:38 - KitchenSmallLamp state updated to OFF
2015-12-12 15:56:53 - KitchenSmallLamp state updated to OFF
2015-12-12 15:57:08 - KitchenSmallLamp state updated to OFF
2015-12-12 15:57:23 - KitchenSmallLamp state updated to OFF
2015-12-12 15:57:33 - KitchenSmallLamp state updated to OFF
2015-12-12 15:57:48 - KitchenSmallLamp state updated to OFF
2015-12-12 15:58:03 - KitchenSmallLamp state updated to OFF
2015-12-12 15:58:10 - KitchenMotion state updated to OPEN
2015-12-12 15:58:23 - KitchenSmallLamp state updated to OFF
2015-12-12 15:58:23 - KitchenSmallLamp state updated to OFF
2015-12-12 15:58:39 - KitchenSmallLamp state updated to ON
2015-12-12 15:58:39 - KitchenSmallLamp state updated to ON
2015-12-12 15:58:39 - KitchenSmallLamp state updated to ON
2015-12-12 15:58:39 - KitchenSmallLamp state updated to ON
2015-12-12 15:58:40 - KitchenSmallLamp state updated to ON
2015-12-12 15:58:40 - KitchenSmallLamp state updated to ON
2015-12-12 15:58:40 - KitchenSmallLamp state updated to ON
2015-12-12 15:58:53 - KitchenSmallLamp state updated to ON
2015-12-12 15:59:08 - KitchenSmallLamp state updated to ON
2015-12-12 15:59:23 - KitchenSmallLamp state updated to ON
2015-12-12 15:59:43 - KitchenSmallLamp state updated to ON

chris · December 12, 2015, 4:33pm

ZWave devices report updates through the association mechanism - have you configured the associations for the devices (assuming they support associations)? If not, they won’t automatically report updates.

You should also note that using refresh_interval will not mean the devices are updated at the rate you set - this will set the minimum time only, and it won’t be faster than 10 seconds (from memory). The binding will reduce polling to avoid putting too many requests into the queue at once which could slow down commands (ie turning your lights on).

You will be much better off getting the automatic association reports working and turning polling off.

bruxi · December 13, 2015, 10:34am

Hi Chris,

thank you for the hint that the refresh_interval can’t be less than 10s. I would like to prefer automatic reporting by the devices but I know that the mentioned Greenwave Powerndodes won’t report device state update when being switched manually. The vendor tells in the manual to use frequent polling by the controller.
But in my case the polling via the refresh_interval is completely ignored and is never being refreshed for those devices.
Interestingly I can’t configure association groups via habmin but the manual says the device supports 4 association groups. Here’s a screenshot from habmin.

chris · December 13, 2015, 10:38am

Strange that the greenwave devices don’t support association reporting - for a new device, this is a bit poor really… However, it does appear that this is the case…

Polling shouldn’t be ignored - please can you provide a log and I’ll take a look.

bruxi · December 13, 2015, 10:53am

Hi chris,

here’s a part of the log:

2015-12-13 11:50:24.875 [INFO ] [.z.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyAMA0
2015-12-13 11:50:24.877 [INFO ] [.z.internal.ZWaveActiveBinding] - Update config, healtime = 2
2015-12-13 11:50:24.878 [INFO ] [.z.internal.ZWaveActiveBinding] - Update config, masterController = true
2015-12-13 11:50:24.980 [INFO ] [b.z.i.protocol.ZWaveController] - Disconnected from serial port
2015-12-13 11:50:24.981 [INFO ] [b.z.i.protocol.ZWaveController] - Stopped Z-Wave controller
2015-12-13 11:50:24.982 [INFO ] [b.z.i.protocol.ZWaveController] - Starting Z-Wave controller
2015-12-13 11:50:24.983 [INFO ] [b.z.i.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
2015-12-13 11:50:24.984 [INFO ] [b.z.i.protocol.ZWaveController] - Connecting to serial port /dev/ttyAMA0
2015-12-13 11:50:25.003 [INFO ] [b.z.i.protocol.ZWaveController] - Serial port is initialized
2015-12-13 11:50:25.035 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'openelec.items'
2015-12-13 11:50:25.285 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'denon.items'
2015-12-13 11:50:25.554 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'zwave.items'
2015-12-13 11:50:25.913 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'voice.items'
2015-12-13 11:50:26.046 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'rrd4j.persist'
2015-12-13 11:50:26.060 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'mysql.persist'
2015-12-13 11:50:26.116 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'entertainment.rules'
2015-12-13 11:50:26.423 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'motion.rules'
2015-12-13 11:50:26.638 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:26.639 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:26.641 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Could not store item 'DenonInput' in database with statement 'INSERT INTO Item21 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;': No operations allowed after connection closed.
2015-12-13 11:50:26.663 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'lamps.rules'
2015-12-13 11:50:26.737 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'voice.rules'
2015-12-13 11:50:26.799 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'rgb.rules'
2015-12-13 11:50:26.838 [WARN ] [ApplicationCommandMessageClass] - NODE 15: Not initialized yet, ignoring message.
2015-12-13 11:50:26.855 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'default.sitemap'
2015-12-13 11:50:26.922 [INFO ] [.o.a.t.i.TelegramActionService] - Bot bot1 loaded from config file
2015-12-13 11:50:27.319 [WARN ] [ApplicationCommandMessageClass] - NODE 15: Not initialized yet, ignoring message.
2015-12-13 11:50:28.302 [INFO ] [rialApiGetInitDataMessageClass] - NODE 1: Node found
2015-12-13 11:50:28.303 [INFO ] [rialApiGetInitDataMessageClass] - NODE 4: Node found
2015-12-13 11:50:28.304 [INFO ] [rialApiGetInitDataMessageClass] - NODE 5: Node found
2015-12-13 11:50:28.305 [INFO ] [rialApiGetInitDataMessageClass] - NODE 7: Node found
2015-12-13 11:50:28.306 [INFO ] [rialApiGetInitDataMessageClass] - NODE 10: Node found
2015-12-13 11:50:28.307 [INFO ] [rialApiGetInitDataMessageClass] - NODE 11: Node found
2015-12-13 11:50:28.308 [INFO ] [rialApiGetInitDataMessageClass] - NODE 12: Node found
2015-12-13 11:50:28.309 [INFO ] [rialApiGetInitDataMessageClass] - NODE 13: Node found
2015-12-13 11:50:28.310 [INFO ] [rialApiGetInitDataMessageClass] - NODE 14: Node found
2015-12-13 11:50:28.311 [INFO ] [rialApiGetInitDataMessageClass] - NODE 15: Node found
2015-12-13 11:50:28.311 [INFO ] [rialApiGetInitDataMessageClass] - NODE 16: Node found
2015-12-13 11:50:28.312 [INFO ] [rialApiGetInitDataMessageClass] - NODE 20: Node found
2015-12-13 11:50:28.313 [INFO ] [rialApiGetInitDataMessageClass] - NODE 21: Node found
2015-12-13 11:50:28.313 [INFO ] [rialApiGetInitDataMessageClass] - NODE 22: Node found
2015-12-13 11:50:28.314 [INFO ] [rialApiGetInitDataMessageClass] - NODE 23: Node found
2015-12-13 11:50:28.315 [INFO ] [rialApiGetInitDataMessageClass] - NODE 24: Node found
2015-12-13 11:50:28.316 [INFO ] [rialApiGetInitDataMessageClass] - NODE 25: Node found
2015-12-13 11:50:28.318 [INFO ] [rialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2015-12-13 11:50:28.318 [INFO ] [rialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2015-12-13 11:50:28.319 [INFO ] [rialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2015-12-13 11:50:28.320 [INFO ] [rialApiGetInitDataMessageClass] - # Nodes = 17
2015-12-13 11:50:28.321 [INFO ] [rialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2015-12-13 11:50:30.928 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:30.930 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:30.931 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Could not store item 'DenonVolume' in database with statement 'INSERT INTO Item20 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;': No operations allowed after connection closed.
2015-12-13 11:50:31.465 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:31.466 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:31.467 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Could not store item 'GlobeLamp' in database with statement 'INSERT INTO Item1 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;': No operations allowed after connection closed.
2015-12-13 11:50:31.510 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Unsupported command class MULTI_INSTANCE_ASSOCIATION
2015-12-13 11:50:31.512 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Unsupported command class FIRMWARE_UPDATE_MD
2015-12-13 11:50:31.513 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Unsupported command class POWERLEVEL
2015-12-13 11:50:31.659 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Unsupported command class MULTI_INSTANCE_ASSOCIATION
2015-12-13 11:50:31.661 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Unsupported command class FIRMWARE_UPDATE_MD
2015-12-13 11:50:31.662 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Unsupported command class POWERLEVEL
2015-12-13 11:50:34.431 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:34.641 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 25: Unsupported command class PROTECTION
2015-12-13 11:50:34.810 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 25: Unsupported command class PROTECTION
2015-12-13 11:50:37.182 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:37.630 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 24: Unsupported command class PROTECTION
2015-12-13 11:50:37.990 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 24: Unsupported command class PROTECTION
2015-12-13 11:50:40.790 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:44.205 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:44.747 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:44.929 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 20: Unsupported command class PROTECTION
2015-12-13 11:50:45.079 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 20: Unsupported command class PROTECTION
2015-12-13 11:50:45.461 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 20: Unsupported command class PROTECTION
2015-12-13 11:50:50.115 [ERROR] [WaveController$ZWaveSendThread] - NODE 20: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-13 11:50:50.117 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 20: Got an error while sending data. Resending message.
2015-12-13 11:50:50.543 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:50.544 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:50.545 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Could not store item 'CorridorMotion' in database with statement 'INSERT INTO Item12 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;': No operations allowed after connection closed.
2015-12-13 11:50:50.954 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:50.955 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:50.957 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Could not store item 'CorridorBattery' in database with statement 'INSERT INTO Item15 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;': No operations allowed after connection closed.
2015-12-13 11:50:52.146 [ERROR] [eController$ZWaveReceiveThread] - Protocol error (CAN), resending
2015-12-13 11:50:53.162 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:53.317 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:53.486 [ERROR] [eController$ZWaveReceiveThread] - Protocol error (CAN), resending
2015-12-13 11:50:53.626 [ERROR] [eController$ZWaveReceiveThread] - Protocol error (CAN), resending
2015-12-13 11:50:53.766 [ERROR] [eController$ZWaveReceiveThread] - Protocol error (CAN), resending
2015-12-13 11:50:53.906 [ERROR] [eController$ZWaveReceiveThread] - Protocol error (CAN), resending
2015-12-13 11:50:54.046 [ERROR] [eController$ZWaveReceiveThread] - Protocol error (CAN), resending
2015-12-13 11:50:55.261 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:56.179 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:57.077 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:57.078 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:57.079 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Could not store item 'StandardLamp' in database with statement 'INSERT INTO Item8 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;': No operations allowed after connection closed.
2015-12-13 11:50:57.261 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:57.262 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2015-12-13 11:50:57.263 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Could not store item 'KitchenMotion' in database with statement 'INSERT INTO Item36 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;': No operations allowed after connection closed.
2015-12-13 11:51:02.426 [ERROR] [WaveController$ZWaveSendThread] - NODE 5: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-13 11:51:02.427 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 5: Got an error while sending data. Resending message.
2015-12-13 11:51:06.942 [INFO ] [.o.m.c.i.folder.FolderObserver] - File 'mysql.persist' has been deleted
2015-12-13 11:51:07.468 [ERROR] [WaveController$ZWaveSendThread] - NODE 5: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-13 11:51:07.470 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 5: Got an error while sending data. Resending message.
2015-12-13 11:51:08.696 [ERROR] [eController$ZWaveReceiveThread] - Protocol error (CAN), resending
2015-12-13 11:51:09.061 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:51:09.427 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:51:09.658 [WARN ] [.z.internal.ZWaveActiveBinding] - NODE 11: No item bound for event, endpoint = 1, command class = SWITCH_BINARY, value = 0, ignoring.
2015-12-13 11:51:09.738 [WARN ] [.z.internal.ZWaveActiveBinding] - NODE 11: No item bound for event, endpoint = 2, command class = SWITCH_BINARY, value = 0, ignoring.
2015-12-13 11:51:09.918 [WARN ] [.z.internal.ZWaveActiveBinding] - NODE 23: No item bound for event, endpoint = 0, command class = SENSOR_BINARY, value = 0, ignoring.
2015-12-13 11:51:15.866 [ERROR] [WaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-13 11:51:15.867 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 13: Got an error while sending data. Resending message.
2015-12-13 11:51:20.886 [ERROR] [WaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-13 11:51:20.887 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 13: Got an error while sending data. Resending message.
2015-12-13 11:51:25.906 [ERROR] [WaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-13 11:51:25.907 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 13: Got an error while sending data. Resending message.
2015-12-13 11:51:30.926 [WARN ] [WaveController$ZWaveSendThread] - NODE 13: Too many retries. Discarding message: Message: class = SendData (0x13), type = Request (0x00), payload = 0D 03 32 01 08
2015-12-13 11:51:33.677 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:51:33.846 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:51:33.959 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:51:34.068 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:51:39.626 [ERROR] [WaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-13 11:51:39.627 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
2015-12-13 11:51:44.726 [ERROR] [WaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-13 11:51:44.727 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
2015-12-13 11:51:49.746 [ERROR] [WaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-13 11:51:49.747 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
2015-12-13 11:51:55.046 [ERROR] [WaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-13 11:51:55.047 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
2015-12-13 11:52:00.146 [ERROR] [WaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-13 11:52:00.147 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
2015-12-13 11:52:01.141 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:52:15.628 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:52:15.848 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:52:16.078 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES

chris · December 13, 2015, 10:57am

Sorry - I need the debug level logging…

bruxi · December 13, 2015, 11:08am

From only the zwave binding or from something else, too? Here’s the zwave-debug:

2015-12-13 12:06:17.377 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 0F 03 20 01 FF 20
2015-12-13 12:06:17.378 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 04 00 0F 03 20 01 FF 20
2015-12-13 12:06:17.378 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0F 03 20 01 FF
2015-12-13 12:06:17.379 [DEBUG] [ApplicationCommandMessageClass] - NODE 15: Application Command Request (ALIVE:DONE)
2015-12-13 12:06:17.379 [DEBUG] [ApplicationCommandMessageClass] - NODE 15: Incoming command class BASIC
2015-12-13 12:06:17.379 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass] - NODE 15: Received Basic Request
2015-12-13 12:06:17.380 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass] - NODE 15: Basic Set sent to the controller will be processed as Basic Report
2015-12-13 12:06:17.380 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass] - NODE 15: Basic report, value = 0xFF
2015-12-13 12:06:17.380 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2015-12-13 12:06:17.381 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:17.381 [DEBUG] [.z.internal.ZWaveActiveBinding] - NODE 15: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
2015-12-13 12:06:17.382 [DEBUG] [ApplicationCommandMessageClass] - Transaction not completed: node address inconsistent.
2015-12-13 12:06:17.835 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 0F 0A 71 05 00 00 00 FF 07 08 00 00 6A
2015-12-13 12:06:17.856 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:17.856 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:17.857 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 0F 0A 71 05 00 00 00 FF 07 08 00 00 6A
2015-12-13 12:06:17.858 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 10 00 04 00 0F 0A 71 05 00 00 00 FF 07 08 00 00 6A
2015-12-13 12:06:17.860 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0F 0A 71 05 00 00 00 FF 07 08 00 00
2015-12-13 12:06:17.860 [DEBUG] [ApplicationCommandMessageClass] - NODE 15: Application Command Request (ALIVE:DONE)
2015-12-13 12:06:17.861 [DEBUG] [ApplicationCommandMessageClass] - NODE 15: Incoming command class ALARM
2015-12-13 12:06:17.861 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass] - NODE 15: Received Alarm Request
2015-12-13 12:06:17.861 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass] - NODE 15: Alarm report - Value = 0
2015-12-13 12:06:17.861 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass] - NODE 15: Alarm Type = General (0)
2015-12-13 12:06:17.862 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveAlarmValueEvent
2015-12-13 12:06:17.862 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:17.862 [DEBUG] [.z.internal.ZWaveActiveBinding] - NODE 15: Got a value event from Z-Wave network, endpoint = 0, command class = ALARM, value = 0
2015-12-13 12:06:17.863 [DEBUG] [ApplicationCommandMessageClass] - Transaction not completed: node address inconsistent.
2015-12-13 12:06:21.384 [DEBUG] [i.c.ZWaveBinarySwitchConverter] - NODE 10: Generating poll message for SWITCH_BINARY, endpoint 0
2015-12-13 12:06:21.384 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 10: Creating new message for application command SWITCH_BINARY_GET
2015-12-13 12:06:21.385 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 10: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-12-13 12:06:21.385 [DEBUG] [b.z.i.protocol.ZWaveController] - Callback ID = 234
2015-12-13 12:06:21.386 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-12-13 12:06:21.387 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-12-13 12:06:21.388 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0A 02 25 02 25 EA 05
2015-12-13 12:06:21.388 [DEBUG] [WaveController$ZWaveSendThread] - NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 25 02 25 EA 05
2015-12-13 12:06:21.395 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2015-12-13 12:06:21.426 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:21.426 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:21.427 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2015-12-13 12:06:21.427 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2015-12-13 12:06:21.428 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
2015-12-13 12:06:21.428 [DEBUG] [b.z.i.p.s.SendDataMessageClass] - NODE 10: Sent Data successfully placed on stack.
2015-12-13 12:06:21.429 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 07 00 13 EA 00 00 02 03
2015-12-13 12:06:21.445 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:21.447 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:21.448 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 EA 00 00 02 00 00 0D
2015-12-13 12:06:21.448 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 13 EA 00 00 02 00 00 0D
2015-12-13 12:06:21.449 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = SendData (0x13), type = Request (0x00), payload = EA 00 00 02
2015-12-13 12:06:21.450 [DEBUG] [b.z.i.p.s.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 234, Status = Transmission complete and ACK received(0)
2015-12-13 12:06:21.451 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0A 02 25 02
2015-12-13 12:06:21.451 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = EA 00 00 02
2015-12-13 12:06:21.451 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:21.453 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:21.465 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:21.466 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:21.467 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:21.468 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:21.469 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0A 03 25 03 00
2015-12-13 12:06:21.469 [DEBUG] [ApplicationCommandMessageClass] - NODE 10: Application Command Request (ALIVE:DONE)
2015-12-13 12:06:21.470 [DEBUG] [ApplicationCommandMessageClass] - NODE 10: Incoming command class SWITCH_BINARY
2015-12-13 12:06:21.470 [DEBUG] [.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 10
2015-12-13 12:06:21.471 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 10: Switch Binary report, value = 0x00
2015-12-13 12:06:21.471 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2015-12-13 12:06:21.471 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:21.471 [DEBUG] [.z.internal.ZWaveActiveBinding] - NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
2015-12-13 12:06:21.473 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0A 02 25 02
2015-12-13 12:06:21.473 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0A 03 25 03 00
2015-12-13 12:06:21.474 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:21.474 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 12:06:21.474 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 12:06:21.475 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:21.475 [DEBUG] [WaveController$ZWaveSendThread] - NODE 10: Response processed after 86ms/3707ms.
2015-12-13 12:06:26.388 [DEBUG] [i.c.ZWaveBinarySwitchConverter] - NODE 5: Generating poll message for SWITCH_BINARY, endpoint 0
2015-12-13 12:06:26.388 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 5: Creating new message for application command SWITCH_BINARY_GET
2015-12-13 12:06:26.389 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 5: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-12-13 12:06:26.389 [DEBUG] [b.z.i.protocol.ZWaveController] - Callback ID = 235
2015-12-13 12:06:26.389 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-12-13 12:06:26.390 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-12-13 12:06:26.391 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 25 02 25 EB 0B
2015-12-13 12:06:26.392 [DEBUG] [WaveController$ZWaveSendThread] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 25 02 25 EB 0B
2015-12-13 12:06:26.399 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2015-12-13 12:06:26.426 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:26.426 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:26.427 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2015-12-13 12:06:26.427 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2015-12-13 12:06:26.428 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
2015-12-13 12:06:26.428 [DEBUG] [b.z.i.p.s.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
2015-12-13 12:06:26.429 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 07 00 13 EB 00 00 02 02
2015-12-13 12:06:26.450 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:26.450 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:26.453 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 EB 00 00 02 00 00 0C
2015-12-13 12:06:26.454 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 13 EB 00 00 02 00 00 0C
2015-12-13 12:06:26.454 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = SendData (0x13), type = Request (0x00), payload = EB 00 00 02
2015-12-13 12:06:26.455 [DEBUG] [b.z.i.p.s.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 235, Status = Transmission complete and ACK received(0)
2015-12-13 12:06:26.456 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 05 02 25 02
2015-12-13 12:06:26.457 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = EB 00 00 02
2015-12-13 12:06:26.457 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:26.460 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 25 03 00 D2
2015-12-13 12:06:26.476 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:26.476 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:26.477 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 05 03 25 03 00 D2
2015-12-13 12:06:26.478 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 04 00 05 03 25 03 00 D2
2015-12-13 12:06:26.478 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 05 03 25 03 00
2015-12-13 12:06:26.479 [DEBUG] [ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
2015-12-13 12:06:26.479 [DEBUG] [ApplicationCommandMessageClass] - NODE 5: Incoming command class SWITCH_BINARY
2015-12-13 12:06:26.480 [DEBUG] [.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 5
2015-12-13 12:06:26.480 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 5: Switch Binary report, value = 0x00
2015-12-13 12:06:26.480 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2015-12-13 12:06:26.481 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:26.481 [DEBUG] [.z.internal.ZWaveActiveBinding] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
2015-12-13 12:06:26.482 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 05 02 25 02
2015-12-13 12:06:26.483 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 05 03 25 03 00
2015-12-13 12:06:26.484 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:26.484 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 12:06:26.484 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 12:06:26.492 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:26.493 [DEBUG] [WaveController$ZWaveSendThread] - NODE 5: Response processed after 101ms/3707ms.
2015-12-13 12:06:31.391 [DEBUG] [i.c.ZWaveBinarySwitchConverter] - NODE 11: Generating poll message for SWITCH_BINARY, endpoint 0
2015-12-13 12:06:31.391 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 11: Creating new message for application command SWITCH_BINARY_GET
2015-12-13 12:06:31.392 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 11: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-12-13 12:06:31.392 [DEBUG] [b.z.i.protocol.ZWaveController] - Callback ID = 236
2015-12-13 12:06:31.393 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-12-13 12:06:31.393 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-12-13 12:06:31.394 [DEBUG] [i.c.ZWaveBinarySwitchConverter] - NODE 10: Generating poll message for SWITCH_BINARY, endpoint 0
2015-12-13 12:06:31.395 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 10: Creating new message for application command SWITCH_BINARY_GET
2015-12-13 12:06:31.397 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0B 02 25 02 25 EC 02
2015-12-13 12:06:31.398 [DEBUG] [WaveController$ZWaveSendThread] - NODE 11: Sending REQUEST Message = 01 09 00 13 0B 02 25 02 25 EC 02
2015-12-13 12:06:31.399 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 10: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-12-13 12:06:31.399 [DEBUG] [b.z.i.protocol.ZWaveController] - Callback ID = 237
2015-12-13 12:06:31.400 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-12-13 12:06:31.405 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2015-12-13 12:06:31.436 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:31.436 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:31.437 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2015-12-13 12:06:31.438 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2015-12-13 12:06:31.438 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
2015-12-13 12:06:31.438 [DEBUG] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
2015-12-13 12:06:31.440 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 07 00 13 EC 00 00 02 05
2015-12-13 12:06:31.456 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:31.461 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:31.463 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 EC 00 00 02 00 00 0B
2015-12-13 12:06:31.464 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 13 EC 00 00 02 00 00 0B
2015-12-13 12:06:31.465 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = SendData (0x13), type = Request (0x00), payload = EC 00 00 02
2015-12-13 12:06:31.466 [DEBUG] [b.z.i.p.s.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 236, Status = Transmission complete and ACK received(0)
2015-12-13 12:06:31.467 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 25 02
2015-12-13 12:06:31.468 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = EC 00 00 02
2015-12-13 12:06:31.468 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:31.470 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0B 03 25 03 00 DC
2015-12-13 12:06:31.486 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:31.494 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:31.495 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 0B 03 25 03 00 DC
2015-12-13 12:06:31.497 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 04 00 0B 03 25 03 00 DC
2015-12-13 12:06:31.498 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0B 03 25 03 00
2015-12-13 12:06:31.498 [DEBUG] [ApplicationCommandMessageClass] - NODE 11: Application Command Request (ALIVE:DONE)
2015-12-13 12:06:31.499 [DEBUG] [ApplicationCommandMessageClass] - NODE 11: Incoming command class SWITCH_BINARY
2015-12-13 12:06:31.499 [DEBUG] [.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 11
2015-12-13 12:06:31.500 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 11: Switch Binary report, value = 0x00
2015-12-13 12:06:31.500 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2015-12-13 12:06:31.500 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:31.501 [DEBUG] [.z.internal.ZWaveActiveBinding] - NODE 11: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
2015-12-13 12:06:31.502 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 25 02
2015-12-13 12:06:31.503 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0B 03 25 03 00
2015-12-13 12:06:31.504 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:31.504 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 12:06:31.505 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 12:06:31.505 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:31.509 [DEBUG] [WaveController$ZWaveSendThread] - NODE 11: Response processed after 111ms/3707ms.
2015-12-13 12:06:31.510 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-12-13 12:06:31.511 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0A 02 25 02 25 ED 02
2015-12-13 12:06:31.512 [DEBUG] [WaveController$ZWaveSendThread] - NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 25 02 25 ED 02
2015-12-13 12:06:31.519 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2015-12-13 12:06:31.546 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:31.545 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:31.547 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2015-12-13 12:06:31.547 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2015-12-13 12:06:31.548 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
2015-12-13 12:06:31.548 [DEBUG] [b.z.i.p.s.SendDataMessageClass] - NODE 10: Sent Data successfully placed on stack.
2015-12-13 12:06:31.549 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 07 00 13 ED 00 00 02 04
2015-12-13 12:06:31.566 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:31.565 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:31.567 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 ED 00 00 02 00 00 0A
2015-12-13 12:06:31.568 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 13 ED 00 00 02 00 00 0A
2015-12-13 12:06:31.568 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = SendData (0x13), type = Request (0x00), payload = ED 00 00 02
2015-12-13 12:06:31.569 [DEBUG] [b.z.i.p.s.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 237, Status = Transmission complete and ACK received(0)
2015-12-13 12:06:31.570 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0A 02 25 02
2015-12-13 12:06:31.570 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = ED 00 00 02
2015-12-13 12:06:31.571 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:31.572 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:31.586 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:31.585 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:31.587 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:31.588 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:31.589 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0A 03 25 03 00
2015-12-13 12:06:31.589 [DEBUG] [ApplicationCommandMessageClass] - NODE 10: Application Command Request (ALIVE:DONE)
2015-12-13 12:06:31.590 [DEBUG] [ApplicationCommandMessageClass] - NODE 10: Incoming command class SWITCH_BINARY
2015-12-13 12:06:31.590 [DEBUG] [.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 10
2015-12-13 12:06:31.590 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 10: Switch Binary report, value = 0x00
2015-12-13 12:06:31.591 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2015-12-13 12:06:31.591 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:31.591 [DEBUG] [.z.internal.ZWaveActiveBinding] - NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
2015-12-13 12:06:31.592 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0A 02 25 02
2015-12-13 12:06:31.593 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0A 03 25 03 00
2015-12-13 12:06:31.594 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:31.594 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 12:06:31.594 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 12:06:31.595 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:31.595 [DEBUG] [WaveController$ZWaveSendThread] - NODE 10: Response processed after 83ms/3707ms.
2015-12-13 12:06:31.597 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:31.615 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 12:06:31.616 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 12:06:31.617 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:31.618 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 00 04 00 0A 03 25 03 00 DD
2015-12-13 12:06:31.619 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0A 03 25 03 00
2015-12-13 12:06:31.619 [DEBUG] [ApplicationCommandMessageClass] - NODE 10: Application Command Request (ALIVE:DONE)
2015-12-13 12:06:31.620 [DEBUG] [ApplicationCommandMessageClass] - NODE 10: Incoming command class SWITCH_BINARY
2015-12-13 12:06:31.620 [DEBUG] [.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 10
2015-12-13 12:06:31.620 [DEBUG] [.ZWaveBinarySwitchCommandClass] - NODE 10: Switch Binary report, value = 0x00
2015-12-13 12:06:31.621 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2015-12-13 12:06:31.621 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 12:06:31.621 [DEBUG] [.z.internal.ZWaveActiveBinding] - NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
2015-12-13 12:06:31.622 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0A 02 25 02
2015-12-13 12:06:31.626 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0A 03 25 03 00
2015-12-13 12:06:31.626 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, expected=ApplicationCommandHandler, cancelled=false
2015-12-13 12:06:31.627 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 12:06:31.627 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 12:06:31.627 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent

bruxi · December 13, 2015, 11:11am

for Node 24, which is a Powernode and should be polled every 60s, the only thing that happens is an error in the log:

2015-12-13 11:50:44.205 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:50:53.162 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:51:09.427 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:51:34.068 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:52:16.078 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:53:49.776 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 11:56:31.675 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES
2015-12-13 12:01:53.560 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Retries exceeded at STATIC_VALUES

Here’s the item description:

Switch HomeEntertainmentReceiverSwitch “Power” (gEntertainment) { zwave=“24:command=BASIC,refresh_interval=60” }

I also tried command=SWITCH_BINARY without success.

chris · December 13, 2015, 11:14am

I suspect that the node isn’t finishing initialisation - it doesn’t get polled until it is complete. I’d need to see the log during initialisation…

Also, when you post logs, please format them appropriately (using the </> button).

bruxi · December 13, 2015, 12:29pm

Just restarted openhab so that you can see all devices from the initialization phase. The character limit makes it not easy to post much debug output.

2015-12-13 13:10:48.945 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 24: Init node thread start
2015-12-13 13:10:48.938 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 22: Init node thread start
2015-12-13 13:10:48.923 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 15: Init node thread start
2015-12-13 13:10:48.946 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 25: Init node thread start
2015-12-13 13:10:48.946 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-12-13 13:10:48.963 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9
2015-12-13 13:10:48.965 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9
2015-12-13 13:10:48.969 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 04 01 05 08 F7
2015-12-13 13:10:48.986 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 13:10:48.986 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 13:10:48.989 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 01 05 08 F7
2015-12-13 13:10:48.991 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 04 01 05 08 F7
2015-12-13 13:10:48.992 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 08
2015-12-13 13:10:48.994 [DEBUG] [rollerCapabilitiesMessageClass] - Controller is secondary = false
2015-12-13 13:10:48.995 [DEBUG] [rollerCapabilitiesMessageClass] - Controller is on other network = false
2015-12-13 13:10:48.996 [DEBUG] [rollerCapabilitiesMessageClass] - Node ID Server is present = false
2015-12-13 13:10:48.997 [DEBUG] [rollerCapabilitiesMessageClass] - Controller is real primary = true
2015-12-13 13:10:48.998 [DEBUG] [rollerCapabilitiesMessageClass] - Controller is SUC = false
2015-12-13 13:10:49.011 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = GetControllerCapabilities (0x05), type = Request (0x00), payload =
2015-12-13 13:10:49.013 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 08
2015-12-13 13:10:49.015 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=GetControllerCapabilities, expected=GetControllerCapabilities, cancelled=false
2015-12-13 13:10:49.025 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 13:10:49.026 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 13:10:49.027 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 13:10:49.028 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Response processed after 62ms/803ms.
2015-12-13 13:10:50.869 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 22: Serializing from file /var/lib/openhab/zwave/node22.xml
2015-12-13 13:10:50.871 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 15: Serializing from file /var/lib/openhab/zwave/node15.xml
2015-12-13 13:10:50.871 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 22: Error serializing from file: file does not exist.
2015-12-13 13:10:50.876 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 12: Serializing from file /var/lib/openhab/zwave/node12.xml
2015-12-13 13:10:50.878 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 25: Serializing from file /var/lib/openhab/zwave/node25.xml
2015-12-13 13:10:50.879 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 21: Serializing from file /var/lib/openhab/zwave/node21.xml
2015-12-13 13:10:50.880 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 25: Error serializing from file: file does not exist.
2015-12-13 13:10:50.878 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 11: Serializing from file /var/lib/openhab/zwave/node11.xml
2015-12-13 13:10:50.882 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 4: Serializing from file /var/lib/openhab/zwave/node4.xml
2015-12-13 13:10:50.884 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 13: Serializing from file /var/lib/openhab/zwave/node13.xml
2015-12-13 13:10:50.884 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 24: Serializing from file /var/lib/openhab/zwave/node24.xml
2015-12-13 13:10:50.884 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 14: Serializing from file /var/lib/openhab/zwave/node14.xml
2015-12-13 13:10:50.885 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 24: Error serializing from file: file does not exist.
2015-12-13 13:10:50.886 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 5: Serializing from file /var/lib/openhab/zwave/node5.xml
2015-12-13 13:10:50.884 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 20: Serializing from file /var/lib/openhab/zwave/node20.xml
2015-12-13 13:10:50.884 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 10: Serializing from file /var/lib/openhab/zwave/node10.xml
2015-12-13 13:10:50.889 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 20: Error serializing from file: file does not exist.
2015-12-13 13:10:50.893 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 1: Serializing from file /var/lib/openhab/zwave/node1.xml
2015-12-13 13:10:50.894 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 7: Serializing from file /var/lib/openhab/zwave/node7.xml
2015-12-13 13:10:50.897 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 23: Serializing from file /var/lib/openhab/zwave/node23.xml
2015-12-13 13:10:50.898 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 16: Serializing from file /var/lib/openhab/zwave/node16.xml
2015-12-13 13:10:50.973 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2015-12-13 13:10:50.975 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2015-12-13 13:10:50.976 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: Initialisation starting
2015-12-13 13:10:50.978 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - advancing to PROTOINFO
2015-12-13 13:10:50.979 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2015-12-13 13:10:50.980 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: PROTOINFO - send IdentifyNode
2015-12-13 13:10:51.007 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2015-12-13 13:10:51.009 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-12-13 13:10:51.011 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - queued packet. Queue length is 1
2015-12-13 13:10:51.012 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 25: Init node thread finished
2015-12-13 13:10:51.010 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-12-13 13:10:51.024 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2015-12-13 13:10:51.026 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2015-12-13 13:10:51.026 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 19 A3
2015-12-13 13:10:51.027 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: Initialisation starting
2015-12-13 13:10:51.028 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 04 00 41 19 A3
2015-12-13 13:10:51.023 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2015-12-13 13:10:51.023 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2015-12-13 13:10:51.048 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2015-12-13 13:10:51.028 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - advancing to PROTOINFO
2015-12-13 13:10:51.049 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: Initialisation starting
2015-12-13 13:10:51.052 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 9C 01 04 10 01 ED
2015-12-13 13:10:51.048 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2015-12-13 13:10:51.055 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2015-12-13 13:10:51.056 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: PROTOINFO - send IdentifyNode
2015-12-13 13:10:51.057 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2015-12-13 13:10:51.059 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-12-13 13:10:51.059 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - queued packet. Queue length is 1
2015-12-13 13:10:51.060 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 22: Init node thread finished
2015-12-13 13:10:51.061 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer: Initialisation starting
2015-12-13 13:10:51.063 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer - advancing to PROTOINFO
2015-12-13 13:10:51.063 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - advancing to PROTOINFO
2015-12-13 13:10:51.063 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2015-12-13 13:10:51.064 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2015-12-13 13:10:51.065 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: PROTOINFO - send IdentifyNode
2015-12-13 13:10:51.064 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer: PROTOINFO - send IdentifyNode
2015-12-13 13:10:51.068 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2015-12-13 13:10:51.070 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 2
2015-12-13 13:10:51.073 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2015-12-13 13:10:51.073 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - queued packet. Queue length is 1
2015-12-13 13:10:51.074 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 24: Init node thread finished
2015-12-13 13:10:51.116 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 13:10:51.118 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 D3 9C 01 04 10 01 ED
2015-12-13 13:10:51.121 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 01 41 D3 9C 01 04 10 01 ED
2015-12-13 13:10:51.123 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = IdentifyNode (0x41), type = Response (0x01), payload = D3 9C 01 04 10 01
2015-12-13 13:10:51.125 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 25: ProtocolInfo
2015-12-13 13:10:51.125 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=0
2015-12-13 13:10:51.074 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 3
2015-12-13 13:10:51.142 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 25: Listening = true
2015-12-13 13:10:51.142 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 20: Node advancer - queued packet. Queue length is 1
2015-12-13 13:10:51.143 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 20: Init node thread finished
2015-12-13 13:10:51.144 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 25: Routing = true
2015-12-13 13:10:51.165 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 25: Version = 4
2015-12-13 13:10:51.167 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 25: FLIRS = false
2015-12-13 13:10:51.168 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 25: Basic = Routing Slave
2015-12-13 13:10:51.169 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 25: Generic = Binary Switch
2015-12-13 13:10:51.171 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 25: Specific = Binary Power Switch
2015-12-13 13:10:51.173 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 25: Creating new instance of command class NO_OPERATION
2015-12-13 13:10:51.179 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 25: Adding command class NO_OPERATION to the list of supported command classes.
2015-12-13 13:10:51.180 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 25: Creating new instance of command class BASIC
2015-12-13 13:10:51.234 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 25: Adding command class BASIC to the list of supported command classes.
2015-12-13 13:10:51.235 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 25: Creating new instance of command class SWITCH_BINARY
2015-12-13 13:10:51.237 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 25: Adding command class SWITCH_BINARY to the list of supported command classes.
2015-12-13 13:10:51.239 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 25: Creating new instance of command class SWITCH_ALL
2015-12-13 13:10:51.240 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 25: Adding command class SWITCH_ALL to the list of supported command classes.
2015-12-13 13:10:51.242 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 19
2015-12-13 13:10:51.244 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = D3 9C 01 04 10 01
2015-12-13 13:10:51.245 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, expected=IdentifyNode, cancelled=false
2015-12-13 13:10:51.296 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 13:10:51.297 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 13:10:51.298 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 13:10:51.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2015-12-13 13:10:51.301 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2015-12-13 13:10:51.302 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - message removed from queue. Queue size 0.
2015-12-13 13:10:51.303 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - PROTOINFO: queue length(0), free to send(true)
2015-12-13 13:10:51.335 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Initialisation retry timer started 5000
2015-12-13 13:10:51.336 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2015-12-13 13:10:51.337 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - advancing to NEIGHBORS
2015-12-13 13:10:51.338 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2015-12-13 13:10:51.338 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer: NEIGHBORS - send RoutingInfo
2015-12-13 13:10:51.340 [DEBUG] [p.s.GetRoutingInfoMessageClass] - NODE 25: Request routing info
2015-12-13 13:10:51.342 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00)
2015-12-13 13:10:51.343 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 4
2015-12-13 13:10:51.344 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 25: Node advancer - queued packet. Queue length is 1
2015-12-13 13:10:51.345 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Response processed after 298ms/803ms.
2015-12-13 13:10:51.346 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2015-12-13 13:10:51.348 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 16 AC
2015-12-13 13:10:51.349 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 04 00 41 16 AC
2015-12-13 13:10:51.355 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 9C 00 04 10 01 EC
2015-12-13 13:10:51.366 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 13:10:51.382 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 13:10:51.384 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 D3 9C 00 04 10 01 EC
2015-12-13 13:10:51.387 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 01 41 D3 9C 00 04 10 01 EC
2015-12-13 13:10:51.389 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = IdentifyNode (0x41), type = Response (0x01), payload = D3 9C 00 04 10 01
2015-12-13 13:10:51.390 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 22: ProtocolInfo
2015-12-13 13:10:51.391 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 22: Listening = true
2015-12-13 13:10:51.391 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 22: Routing = true
2015-12-13 13:10:51.397 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 22: Version = 4
2015-12-13 13:10:51.399 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 22: FLIRS = false
2015-12-13 13:10:51.400 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 22: Basic = Routing Slave
2015-12-13 13:10:51.402 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 22: Generic = Binary Switch
2015-12-13 13:10:51.406 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 22: Specific = Binary Power Switch
2015-12-13 13:10:51.409 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Creating new instance of command class NO_OPERATION
2015-12-13 13:10:51.411 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 22: Adding command class NO_OPERATION to the list of supported command classes.
2015-12-13 13:10:51.413 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Creating new instance of command class BASIC
2015-12-13 13:10:51.417 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 22: Adding command class BASIC to the list of supported command classes.
2015-12-13 13:10:51.419 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Creating new instance of command class SWITCH_BINARY
2015-12-13 13:10:51.422 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 22: Adding command class SWITCH_BINARY to the list of supported command classes.
2015-12-13 13:10:51.424 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 22: Creating new instance of command class SWITCH_ALL
2015-12-13 13:10:51.428 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 22: Adding command class SWITCH_ALL to the list of supported command classes.
2015-12-13 13:10:51.431 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 16
2015-12-13 13:10:51.436 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = D3 9C 00 04 10 01
2015-12-13 13:10:51.438 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, expected=IdentifyNode, cancelled=false
2015-12-13 13:10:51.440 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 13:10:51.442 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 13:10:51.445 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 13:10:51.447 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2015-12-13 13:10:51.449 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - checking initialisation queue. Queue size 1.
2015-12-13 13:10:51.452 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - message removed from queue. Queue size 0.
2015-12-13 13:10:51.454 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - PROTOINFO: queue length(0), free to send(true)
2015-12-13 13:10:51.524 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 1: Restore from config: Ok.
2015-12-13 13:10:51.534 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Initialisation retry timer started 5000
2015-12-13 13:10:51.535 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2015-12-13 13:10:51.536 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - advancing to NEIGHBORS
2015-12-13 13:10:51.537 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2015-12-13 13:10:51.538 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer: NEIGHBORS - send RoutingInfo
2015-12-13 13:10:51.539 [DEBUG] [p.s.GetRoutingInfoMessageClass] - NODE 22: Request routing info
2015-12-13 13:10:51.540 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00)
2015-12-13 13:10:51.541 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 4
2015-12-13 13:10:51.541 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 22: Node advancer - queued packet. Queue length is 1
2015-12-13 13:10:51.542 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Response processed after 192ms/803ms.
2015-12-13 13:10:51.543 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2015-12-13 13:10:51.545 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 18 A2
2015-12-13 13:10:51.547 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 04 00 41 18 A2
2015-12-13 13:10:51.568 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 9C 01 04 10 01 ED
2015-12-13 13:10:51.582 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-12-13 13:10:51.582 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2015-12-13 13:10:51.585 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 D3 9C 01 04 10 01 ED
2015-12-13 13:10:51.587 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 09 01 41 D3 9C 01 04 10 01 ED
2015-12-13 13:10:51.589 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = IdentifyNode (0x41), type = Response (0x01), payload = D3 9C 01 04 10 01
2015-12-13 13:10:51.591 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 24: ProtocolInfo
2015-12-13 13:10:51.591 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 24: Listening = true
2015-12-13 13:10:51.592 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 24: Routing = true
2015-12-13 13:10:51.593 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 24: Version = 4
2015-12-13 13:10:51.594 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 24: FLIRS = false
2015-12-13 13:10:51.595 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 24: Basic = Routing Slave
2015-12-13 13:10:51.601 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2015-12-13 13:10:51.633 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 24: Generic = Binary Switch
2015-12-13 13:10:51.634 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 1: Initialisation retry timer started 5000
2015-12-13 13:10:51.646 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2015-12-13 13:10:51.647 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: Initialisation starting
2015-12-13 13:10:51.648 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - advancing to PROTOINFO
2015-12-13 13:10:51.649 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2015-12-13 13:10:51.649 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: PROTOINFO - send IdentifyNode
2015-12-13 13:10:51.650 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2015-12-13 13:10:51.651 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 4
2015-12-13 13:10:51.652 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - queued packet. Queue length is 1
2015-12-13 13:10:51.653 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 1: Init node thread finished
2015-12-13 13:10:51.634 [DEBUG] [i.p.s.IdentifyNodeMessageClass] - NODE 24: Specific = Binary Power Switch
2015-12-13 13:10:51.703 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 24: Creating new instance of command class NO_OPERATION
2015-12-13 13:10:51.708 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 24: Adding command class NO_OPERATION to the list of supported command classes.
2015-12-13 13:10:51.713 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 24: Creating new instance of command class BASIC
2015-12-13 13:10:51.721 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 24: Adding command class BASIC to the list of supported command classes.
2015-12-13 13:10:51.726 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 24: Creating new instance of command class SWITCH_BINARY
2015-12-13 13:10:51.731 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 24: Adding command class SWITCH_BINARY to the list of supported command classes.
2015-12-13 13:10:51.740 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 24: Creating new instance of command class SWITCH_ALL
2015-12-13 13:10:51.745 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 24: Adding command class SWITCH_ALL to the list of supported command classes.
2015-12-13 13:10:51.755 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 18
2015-12-13 13:10:51.756 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 10: Restore from config: Ok.
2015-12-13 13:10:51.765 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = D3 9C 01 04 10 01
2015-12-13 13:10:51.768 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, expected=IdentifyNode, cancelled=false
2015-12-13 13:10:51.773 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-12-13 13:10:51.777 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-12-13 13:10:51.785 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-12-13 13:10:51.780 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 10: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2015-12-13 13:10:51.789 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 10: Initialisation retry timer started 5000
2015-12-13 13:10:51.790 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 10: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2015-12-13 13:10:51.791 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 10: Node advancer: Initialisation starting
2015-12-13 13:10:51.792 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 10: Node advancer - advancing to PROTOINFO
2015-12-13 13:10:51.789 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2015-12-13 13:10:51.793 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 10: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2015-12-13 13:10:51.796 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 10: Node advancer: PROTOINFO - send IdentifyNode
2015-12-13 13:10:51.797 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2015-12-13 13:10:51.799 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 5
2015-12-13 13:10:51.799 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 10: Node advancer - queued packet. Queue length is 1
2015-12-13 13:10:51.800 [DEBUG] [b.z.i.protocol.ZWaveController] - NODE 10: Init node thread finished
2015-12-13 13:10:51.794 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - checking initialisation queue. Queue size 1.
2015-12-13 13:10:51.856 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - message removed from queue. Queue size 0.
2015-12-13 13:10:51.857 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - PROTOINFO: queue length(0), free to send(true)
2015-12-13 13:10:51.926 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Initialisation retry timer started 5000
2015-12-13 13:10:51.927 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2015-12-13 13:10:51.928 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - advancing to NEIGHBORS
2015-12-13 13:10:51.929 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2015-12-13 13:10:51.929 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer: NEIGHBORS - send RoutingInfo
2015-12-13 13:10:51.930 [DEBUG] [p.s.GetRoutingInfoMessageClass] - NODE 24: Request routing info
2015-12-13 13:10:51.951 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00)
2015-12-13 13:10:51.952 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 6
2015-12-13 13:10:51.953 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 24: Node advancer - queued packet. Queue length is 1

chris · December 13, 2015, 12:33pm

Agreed - you can email me at chris -at- cd-jackson.com.

Also, when you post logs into the forum, please format them appropriately (using the </> button) - it makes it a lot easier to read, and stops the post being extremely long (I’ve been editing your posts to fix this…).

bruxi · December 13, 2015, 12:36pm

Just reformmated the log in my post, sorry. I will send you the complete log via email.

chris · December 13, 2015, 12:38pm

Hmmm - I’m not quite sure what you’ve done, but it’s not right now… I’d already changed it as per your previous posts - now it’s scrolling down the page again…

chris · December 13, 2015, 12:39pm

I’ve reformatted it again

l_grave · December 16, 2015, 10:51am

I had something similar yesterday, also with the Greenwave devices.
I was trying to get all zwave devices to reinitialize, but I had a 1.8.0 snapshot build of the Zwave binding, before the SWITCH_ALL initialization was fixed.
This resulted in all devices with SWITCH_ALL not being able to finish initialization.

The fix was to grab the latest build from cloudbees and replace the zwave binding jar file.

dominicdesu · December 28, 2015, 10:18am

@bruxi @chris
The NS310 actually has association groups. It was just not available in the zwave device file, which seems to be for an older version of the device, the NS210.
I have created a PR to add the device file for the NS310: https://github.com/openhab/openhab/pull/3603/

The device is working quite nicely. It will not automatically report when the On/Off button is pressed, but it almost immediately reports when the power consumption has changed. It is even possible to configure the default power-on state after a power loss, and more.

sercasyr · January 10, 2016, 9:55am

Hi,

I have exactly the same problem.
I set refresh_interval to 30 seconds, and the polling is done ALWAYS at a 5 second rate.

And I don’t a have a Greenwave PowerNode device.
I am using Fibaro and Aeon Labs devices.
The problem seems to be in a dfferent place.

So I don’t agree with you, Chris.
OpenHAB is indeed ignoring the refresh interval, because I set a minimum interval of 30 seconds, and the polling is done each 5 seconds.

Sometimes you can’t use the association mechanism because the device does not send the message if you don’t query it. I have to do this for the “dead” node info. I can’t get this info in a different way…

Switch swSensorComedorMuerto {zwave=“18:command=info,item=dead,refresh_interval=30”}

Even if you might be better off not performing a polling, you may want to perform a regular polling if the device is battery powered. But you can’t, at least with the command “info”, unless you want a 5-second polling…

It is a big problem because the overload this produces is making the system run very slow…

chris · January 10, 2016, 10:07am

I see this written a lot - it’s often not the same problem…

Info is a different story - it has a fixed rate - it doesn’t poll anything though, it’s just updating OH from internal states.

I believe that polling is working ok - and by polling, I’m talking about polling a zwave device. I use 90 seconds here on a few devices, and it is working for me. The example you give is for the info ‘command class’ which as I said above, doesn’t poll, and is using a fixed rate.

What is actually running slow? What hardware are you using? Again, this is only updating internal variables, not doing anything that would slow down the network.