ZWave binding updates

vespaman · December 15, 2019, 2:23pm

Well, first log is from openHAB startup, so I suppose a binding restart would be seen in that log?
Is there any other log that I could enable to give more information?

I have no clue what to look for, but now I think that there’s some kind of watchdog restarting just about every bundle - I tried stop a couple of bundles related to serial, but they are restarted once a minute.
So then I stopped a lot of other bindings, and they are also restarted once a minute, just that they are more silent about it. Or is this intentional nowadays (this auto starting)

Maybe I better put this into 2.5.0.RC1 issues thread!?

chris · December 15, 2019, 2:40pm

I’ll take another look.

I don’t know, but if you are saying that working bindings are restarting, then something strange is happening and I’d be surprised if that is a standard OH feature.

I think that thread is horrible as it’s a real mess of information, but up to you - I don’t follow it though. Also 2.5 is currently about to be released (I think the build has already started).

One point though - as far as I know, you are the only one with this issue?

chris · December 15, 2019, 2:47pm

I don’t see anything in the log that indicates why the handlers are closing, but they are. You see this for all devices a couple of minutes after startup - there’s no indication as to why this is happening that I can see. The binding never calls this dispose method - only the framework does.

2019-12-15 10:48:06.074 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 59: Handler disposed. Unregistering listener.

How are you configuring your system? I wonder if there’s something strange with files being touched that causes the system to think that config files are being updated or something (might explain why bindings restart every minute).

vespaman · December 15, 2019, 3:06pm

Good Idea! But I can’t think of any problems with time/touched files etc. I looked at all files under conf, and could not find anything very recent.

Maybe I am alone with this, and if 2.5.0 is already on its way, it is anyway too late for a fix for that.
I think next step is to do a clean install. But that is getting too late for today, so I think I’ll go back to M4, and deal with this after Christmas.
Thanks for trying to help!

vespaman · December 15, 2019, 4:33pm

OK, after doing a lot of tests (thanks @chris for ruling things out, and getting me on the right path!), I now know what is the issue in my system. Between M4 and RC1, there must have been a change how OH treats binding startup failures: I had “http” in the bindings line in my services/addons.cfg that did not work. I guess it should be “http1” nowadays(?). Anyway, in M4, this just gave an error in the log file, but in RC1 (and M5 I guess), this makes OH reset/restart all(?)/most bindings once every minute, including Z-wave binding, which in my case is very large/easily spotted.

After removing “http” from my binding line, I have run without any issues. When I put it back, back comes the issues.

This might be useful to know, and maybe also this explains other peoples issues.

mhilbush · December 15, 2019, 4:55pm

The feature installer runs every minute to look for bindings that need to be loaded. If there’s an invalid binding in addons.cfg (or possibly in userdata/config/org/openhab/addons.config), the feature installer will try to install it over and over every minute. As an aside, in this scenario there also happens to be a memory leak somewhere in the feature installer that will eventually cause openHAB to run out of memory.

Edit: This behavior has been there for a very long time (coming up on 2 years). I’ll reference the issue in a minute.

Here’s the issue.

vespaman · December 15, 2019, 5:06pm

OK, good to know! But the change between M4 and RC1 is that other bindings (for sure zwave in my case) are reloaded/reset/?/, or parts of it. I only know that this exact thing is what made my zwave binding go bananas every minute. So it should not be directly related to the memory leak. (unless the leak is huuuge of course).

mhilbush · December 15, 2019, 5:34pm

Correct. The leak is VERY slow, to the point where it can take days or weeks for the system to fail, depending on how much memory you have.

jwiseman · December 15, 2019, 7:26pm

Thank you Mark for bringing this up! It takes around 3 - 4 days then it happens to me with OH 2.4 with a bunch of 2.5 bindings.

Best, Jay

mhilbush · December 15, 2019, 7:30pm

In order for it to occur, you need to have an invalid binding in addons.cfg. Is that true in your situation?

jwiseman · December 15, 2019, 7:33pm

Timing issue on Zwave binding on startup?

I seem to have a timing issue on when the zWave and Serial are loaded during startup. Is there a way to change the order of a PID for the zWave binding?

When OH fully starts up; I have to stop and start the zWave binding to get it to put all the devices online.

Binding version:

209 │ Active   │  80 │ 2.5.0.201910162319     │ org.openhab.binding.zwave

Logs:

2019-12-13 08:43:52.628 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2019-12-13 08:43:52.761 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2019-12-13 08:55:28.518 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2019-12-13 08:56:04.747 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2019-12-13 08:56:04.873 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2019-12-13 08:56:04.977 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2019-12-13 08:56:05.062 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2019-12-13 08:56:05.062 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

Best, Jay

jwiseman · December 15, 2019, 7:36pm

I’m not sure; these are the ONLY entries for the bindings below; the rest are dropped in addon’s.

ui = basic,paper
binding = network,exec,nest,onkyo,lgwebos,ecobee1
misc = market,hueemulation

Best, Jay

mhilbush · December 15, 2019, 7:41pm

An invalid binding in addons.cfg should cause an error to be logged every minute when the feature installer tries to install the bogus binding.

Bruce_Osborne · December 15, 2019, 8:06pm

2.4 with a 2.5 binding? Possibly.
The 2.5 binding was not designed to work with 2.4. It just happens to work. Amazingly, it was designed to work with the 2.5 version. There have been a multitude of changes between 2.4 and 2.5. That is why it is being released 6 months later than originally planned.

jwiseman · December 15, 2019, 9:03pm

Been running in this conf (2.4 on 2.5 zWave binding) for close to a year now with many updates to the zWave 2.5 version. My issue is a one off based on many /cache & /tmp clear outs. Just wondering if it’s possible to change the PID order in general based on changing a cache file since it’s the same PID every time you startup OH?

Best, Jay

davorf · December 15, 2019, 10:51pm

Hello!

This was the issue with my OH installation. It wasn’t addons.cfg, but addons.config file (in OpenHAB\userdata\config\org\openhab folder) that had plex and plex1 in bindings section (even though there’s only OH1 binding for Plex). After removing it and updating OH to the latest nightly, Z-Wave controller works as expected.

Thank you all for suggestions and help.

Best regards,
Davor

Andrew_Rowe · December 16, 2019, 12:38am

Micael absolutely great job diagnosing your issue!!!
davorf has now confirmed this was also his issue

Chura · December 17, 2019, 9:15am

Thank you and @chris it was my issue as well, after upgrading to 2.5GA last night, Zwave and Powermax flapping. I went into addon.config and found action.pushbullet and misc.restdocs. probably old addons that was removed, however still appeared in my config (installed from paper, not manually)

EDIT: so, my fault, its registered under “Things to do before upgrade”

Bruce_Osborne · December 17, 2019, 11:26am

If you want restdocs it got moved to user interfaces.

feens · December 18, 2019, 1:41am

@chris Updated to 2.5 yesterday, and now I seem to be having intermittent issues where things seem to be come unresponsive for a period of time. It seems to happen to various devices. Things will work fine for a bit, and then I’ll go to control an item and it just does nothing until a number of minutes later.

I pulled some logs from when it was a happening…look for Node 33 in this case.

2019-12-17 20:37:14.812 [nt.ItemStatePredictedEvent] - zwave_device_node33_switch_dimmer predicted to become OFF
2019-12-17 20:37:14.835 [vent.ItemStateChangedEvent] - zwave_device_node33_switch_dimmer changed from 100 to 0
2019-12-17 20:37:14.838 [GroupItemStateChangedEvent] - Dimmers changed from 75.00000000 to 62.50000000 through zwave_device_node33_switch_dimmer
==> /var/log/openhab2/openhab.log <==
2019-12-17 20:37:14.839 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Command received zwave:device:168118d907c:node33:switch_dimmer --> OFF [OnOffType]
2019-12-17 20:37:14.844 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 33: Creating new message for command SWITCH_MULTILEVEL_SET
2019-12-17 20:37:14.847 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: SECURITY not supported
2019-12-17 20:37:14.851 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-12-17 20:37:14.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Adding to device queue
2019-12-17 20:37:14.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Added 1945 to queue - size 14
2019-12-17 20:37:14.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:37:14.865 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling initialised at 86400 seconds - start in 3000 milliseconds.
2019-12-17 20:37:17.865 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling...
2019-12-17 20:37:17.867 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling zwave:device:168118d907c:node33:switch_dimmer
2019-12-17 20:37:17.869 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 33: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-12-17 20:37:17.870 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 33: Creating new message for command SWITCH_MULTILEVEL_GET
2019-12-17 20:37:17.873 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: SECURITY not supported
2019-12-17 20:37:17.874 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-12-17 20:37:17.876 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling skipped for zwave:device:168118d907c:node33:switch_dimmer on COMMAND_CLASS_BASIC
2019-12-17 20:37:17.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Adding to device queue
2019-12-17 20:37:17.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Added 1946 to queue - size 15
2019-12-17 20:37:17.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:37:24.156 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 45: TID 1932: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:37:24.157 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1932: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:37:24.159 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1932: Transaction CANCELLED
2019-12-17 20:37:24.161 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:37:24.162 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 45: notifyTransactionResponse TID:1932 CANCELLED
2019-12-17 20:37:24.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:37:24.169 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0C 03 25 01 00 25 95 7D 
2019-12-17 20:37:24.172 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 25 01 00 25 95 7D 
2019-12-17 20:37:24.174 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:37:24.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1933: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 149
2019-12-17 20:37:26.178 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 12: TID 1933: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:37:26.179 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:37:26.181 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1933: Transaction ABORTED
2019-12-17 20:37:26.183 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:37:26.186 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-12-17 20:37:26.188 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:37:26.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:37:38.182 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 12: TID 1933: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:37:38.184 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1933: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:37:38.185 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1933: Transaction CANCELLED
2019-12-17 20:37:38.187 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:37:38.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:1933 CANCELLED
2019-12-17 20:37:38.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:37:38.194 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0D 03 25 01 00 25 96 7F 
2019-12-17 20:37:38.197 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 0A 00 13 0D 03 25 01 00 25 96 7F 
2019-12-17 20:38:31.989 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:31.991 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-12-17 20:38:31.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:31.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-12-17 20:38:32.001 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-12-17 20:38:32.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-12-17 20:38:32.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-12-17 20:38:32.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-12-17 20:38:32.008 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-12-17 20:38:32.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-12-17 20:38:32.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-12-17 20:38:32.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-12-17 20:38:32.017 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-12-17 20:38:32.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.023 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-12-17 20:38:32.030 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.037 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-12-17 20:38:32.038 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 3<>125 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.040 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: sentData successfully placed on stack.
2019-12-17 20:38:32.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1934: Advanced to WAIT_REQUEST
2019-12-17 20:38:32.045 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 1934: Transaction not completed
2019-12-17 20:38:32.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 4<>124 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (3): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.051 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1934: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 4<>124 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2019-12-17 20:38:32.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1934: Resetting transaction
2019-12-17 20:38:32.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: notifyTransactionResponse TID:1934 WAIT_REQUEST
2019-12-17 20:38:32.064 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Adding to device queue
2019-12-17 20:38:32.067 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Added 1934 to queue - size 14
2019-12-17 20:38:32.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-12-17 20:38:32.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (4): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.077 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (3): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.082 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.087 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-12-17 20:38:32.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-12-17 20:38:32.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:38:32.310 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0D 03 25 01 00 25 96 7F 
2019-12-17 20:38:32.312 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 0A 00 13 0D 03 25 01 00 25 96 7F 
2019-12-17 20:38:32.314 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:32.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:34.318 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 13: TID 1934: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:38:34.320 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:38:34.321 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1934: Transaction ABORTED
2019-12-17 20:38:34.322 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:38:34.325 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-12-17 20:38:34.330 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:34.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:38:46.322 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 13: TID 1934: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:38:46.325 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1934: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:38:46.326 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1934: Transaction CANCELLED
2019-12-17 20:38:46.328 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:38:46.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: notifyTransactionResponse TID:1934 CANCELLED
2019-12-17 20:38:46.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:38:46.335 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 2C 03 25 01 00 25 97 5F 
2019-12-17 20:38:46.338 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 44: Sending REQUEST Message = 01 0A 00 13 2C 03 25 01 00 25 97 5F 
2019-12-17 20:38:46.340 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:46.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1935: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 151
2019-12-17 20:38:48.344 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 44: TID 1935: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:38:48.345 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:38:48.347 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1935: Transaction ABORTED
2019-12-17 20:38:48.349 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:38:48.351 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-12-17 20:38:48.353 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:48.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:39:00.349 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 44: TID 1935: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:39:00.350 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1935: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:39:00.352 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1935: Transaction CANCELLED
2019-12-17 20:39:00.354 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 44: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:39:00.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 44: notifyTransactionResponse TID:1935 CANCELLED
2019-12-17 20:39:00.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:39:00.370 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 2D 03 25 01 FF 25 98 AE 
2019-12-17 20:39:00.373 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 45: Sending REQUEST Message = 01 0A 00 13 2D 03 25 01 FF 25 98 AE 
2019-12-17 20:39:00.375 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:39:00.377 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1942: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 152
2019-12-17 20:39:02.380 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 45: TID 1942: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:39:02.381 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:39:02.383 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1942: Transaction ABORTED
2019-12-17 20:39:02.386 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:39:02.389 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-12-17 20:39:02.391 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:39:02.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:39:14.385 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 45: TID 1942: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:39:14.387 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1942: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:39:14.389 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1942: Transaction CANCELLED
2019-12-17 20:39:14.391 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:39:14.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 45: notifyTransactionResponse TID:1942 CANCELLED
2019-12-17 20:39:14.395 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:39:14.399 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 21 03 26 01 00 25 99 5F 
2019-12-17 20:39:14.402 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 33: Sending REQUEST Message = 01 0A 00 13 21 03 26 01 00 25 99 5F 
2019-12-17 20:39:14.404 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:39:14.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1945: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 153
2019-12-17 20:39:16.409 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 33: TID 1945: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:39:16.410 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:39:16.412 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1945: Transaction ABORTED
2019-12-17 20:39:16.415 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:39:16.417 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA ```