Upgradeded to current build / zwave questions

shorty707 · September 3, 2016, 6:50am

Hi
I updated to the latest build and zwave version.

I have 2 questions now… :-/

whats that new stuff in logging about transaction timers?Transaction 25 completed
STOP transaction timer
Received msg Message[36693]: class=SendData[0x13], type=Request[0x00], dest=1, callback=25, payload=19 01 00 2A
lastTransaction = null
Message is SendData
Checking outstanding transactions: 0
Last transaction: null
Not correlated with transaction

My Power Switches that worked before all stopped working. Logs say:

08:35:47.977 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘zwave_device_15348538564_node2_switch_binary’ received command OFF
08:35:47.981 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:15348538564:node2:switch_binary --> OFF
08:35:48.002 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_SET
08:35:48.004 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Node doesn’t support get requests
08:35:48.006 [WARN ] [converter.ZWaveBinarySwitchConverter] - NODE 2: Generating message failed for command class = SWITCH_BINARY, endpoint = 0
08:35:48.007 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: No messages returned from converter
08:35:48.029 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_15348538564_node2_switch_binary changed from ON to OFF

chris · September 3, 2016, 7:00am

This is a new transaction handler. It improves the handling of transactions in a more systematic way.

It’s not included in the current version yet so I guess you are using a snapshot from cloudbees rather than the official nightly build. If you find any issues, then please let me know.

Please can you advise exactly what version of the code you are using. It seems from your comment above that you are using a test version and I need to know what this is.

thanks.

shorty707 · September 3, 2016, 7:12am

hi
I upgraded to the cloudbees build of sept 1st (upgraded everything …oh2 and all bindings)

upgrading now to the version from yesterday to see if that helps

chris · September 3, 2016, 7:14am

But how have you upgraded? Have you downloaded the zwave binding only through HABmin or PaperUI, or some other way?

chris · September 3, 2016, 7:19am

Another point, I don’t think that the fact that your switch isn’t working is anything to do with what you show in the log. The log shows that the command is being created ok - without more log info we don’t know if it got sent, but it otherwise looks ok.

What is the switch?

Cheers
Chris

shorty707 · September 3, 2016, 7:20am

I basically use @xsnrg Jims script. This upgrades OH2 to the latest nightly and wipes all bindgins etc.
On next startup all these are pulled aswell as current nightly

github.com

xsnrg/OpenHAB2-tools/blob/master/makeHAB

#!/bin/bash
#
# This script will update your OpenHAB 2 installation.
# The script assumes that the OpenHAB 2 is already installed.  Please shut it down and then run the script
# If OpenHAB 2 is not already installed, create the directories ahead of time, and it will install OpenHAB 2
#
# This script will also update or install Smarthome Designer if desired.  Please make sure your work is saved
#  before updating.
#
# v2.3 updated for OpenHAB version number changes
# v2.2 updated for OpenHAB version number changes
# v2.1 some files in userdata/etc need to be removed to support updates to karaf
# v2 Greatly simplified for the new OpenHAB2 Karaf online distribution
# v1.1 Jim Howard
#

#The SNAPSHOT version to pull from cloudbees
vHAB=2.4.0
# The location for archive downloads
DOWN="/opt/DOWN"

This file has been truncated. show original

chris · September 3, 2016, 7:23am

Hmm - strange. It seems something is pulling in snapshots from PR builds, and not just the nightly snapshot, which is a bit of a pain. I suspect it’s not the script, but probably cloudbees is publishing the PR builds - I’ll have a look at the cloudbees configuration to see if I can stop this.

shorty707 · September 3, 2016, 7:26am

mhh ok
did the update again now to get the latest “whatever” build the switches work again now

chris · September 3, 2016, 7:28am

@kai it seems that CI is deploying the PR snapshots which is a bit of a pain. In the cloudbees config there only seems to be an option to build PRs - I’d assumed it wouldn’t deploy anything that wasn’t from master as otherwise any PR request would be deployed as soon as the request is made, but it seems from this conversation that this might not be the case.

Do you know any way to disable this?

chris · September 3, 2016, 7:30am

What type of switches are they? Also, do you still see the same message in the log about not creating the GET message (GET messages not supported)? I guess so, so I don’t think anything changed.

shorty707 · September 3, 2016, 7:35am

http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/1
and
http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/177

Devolo and Philio PAN11 …

as always the Devolo fully works the PAN11 can be switched on / off again but the metering does not work. But thats now like this for as long as I can remember:

debug log now (working switch):

09:32:21.919 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'zwave_device_15348538564_node5_switch_binary' received command ON
09:32:21.945 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:15348538564:node5:switch_binary --> ON
09:32:21.950 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Creating new message for application command SWITCH_BINARY_SET
09:32:21.953 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
09:32:21.953 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
09:32:21.964 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 25 01 FF 25 15 0B 
09:32:21.967 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 25 01 FF 25 15 0B 
09:32:21.978 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
09:32:21.982 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
09:32:21.987 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
09:32:21.989 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
09:32:21.992 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
09:32:22.004 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
09:32:21.987 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_15348538564_node5_switch_binary changed from OFF to ON
09:32:22.013 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 15 00 00 02 FC 
09:32:22.020 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
09:32:22.023 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 15 00 00 02 00 00 F2 
09:32:22.026 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 15 00 00 02 00 00 F2 
09:32:22.029 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=15 00 00 02 
09:32:22.031 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 21, Status = Transmission complete and ACK received(0)
09:32:22.034 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
09:32:22.036 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@274956 already registered
09:32:22.038 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=5, callback=21, payload=05 03 25 01 FF 
09:32:22.042 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=15 00 00 02 
09:32:22.044 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=21, expected=SendData, cancelled=false        transaction complete!
09:32:22.046 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
09:32:22.047 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
09:32:22.049 [DEBUG] [curityCommandClassWithInitialization] - NODE 5: updating lastSentMessageTimestamp
09:32:22.051 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 83ms/4327ms.
09:32:23.601 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 25 03 FF 2D 
09:32:23.605 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
09:32:23.607 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 05 03 25 03 FF 2D 
09:32:23.609 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 05 03 25 03 FF 2D 
09:32:23.612 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 05 03 25 03 FF 
09:32:23.613 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
09:32:23.614 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
09:32:23.616 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@274956 already registered
09:32:23.617 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class SWITCH_BINARY
09:32:23.619 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 5
09:32:23.620 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Switch Binary report, value = 255
09:32:23.622 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
09:32:23.623 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
09:32:23.624 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255
09:32:23.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:15348538564:node5:switch_binary to ON [OnOffType]
09:32:23.634 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=5, callback=21, payload=05 03 25 01 FF 
09:32:23.637 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 05 03 25 03 FF 
09:32:23.638 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=21, expected=SendData, cancelled=false      MISMATCH
09:32:27.926 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 14 06 31 05 01 22 00 EB 19 
09:32:27.933 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
09:32:27.937 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 04 00 14 06 31 05 01 22 00 EB 19 
09:32:27.941 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0C 00 04 00 14 06 31 05 01 22 00 EB 19 
09:32:27.945 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 14 06 31 05 01 22 00 EB

chris · September 3, 2016, 7:43am

Both of these switches are configured for NOGET, so this debug message was fine and doesn’t impact the SET command.