[velux] New OpenHAB2 binding - feedback welcome!

Add-ons Bindings
,
1113

Here you go Andrew this is all the log for a command sent to a Velux which is already manually opened.

> 2020-11-13 14:40:04.003 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB() initiated by Thread[OH-thingHandler-2,5,main] finished cycle 149990.
> 2020-11-13 14:40:13.680 [TRACE] [.velux.internal.handler.VeluxHandler] - handleCommand(velux:window:7680cbd2:Dennis_Velux:position,37) initiated by Thread[safeCall-10217,5,main].
> 2020-11-13 14:40:13.684 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[safeCall-10217,5,main]): command 37 on channel velux:window:7680cbd2:Dennis_Velux:position will be scheduled.
> 2020-11-13 14:40:13.687 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommand(velux:window:7680cbd2:Dennis_Velux:position,37) called.
> 2020-11-13 14:40:13.690 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand.scheduled(Thread[OH-velux-67,5,main]) Start work with calling handleCommandScheduled().
> 2020-11-13 14:40:13.690 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[safeCall-10217,5,main]) done.
> 2020-11-13 14:40:13.692 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(Thread[OH-velux-67,5,main]): command 37 on channel velux:window:7680cbd2:Dennis_Velux:position.
> 2020-11-13 14:40:13.694 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(velux:window:7680cbd2:Dennis_Velux:position,37) called.
> 2020-11-13 14:40:13.695 [TRACE] [.velux.internal.handler.VeluxHandler] - handleCommand() done.
> 2020-11-13 14:40:13.698 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
> 2020-11-13 14:40:13.700 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
> 2020-11-13 14:40:13.702 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(): working on item velux:window:7680cbd2:Dennis_Velux:position (type velux:window/position) with COMMAND 37.
> 2020-11-13 14:40:13.704 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleCommand(velux:window:7680cbd2:Dennis_Velux:position,position,37,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@4db670) called.
> 2020-11-13 14:40:13.705 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 18.
> 2020-11-13 14:40:13.707 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): there are some existing products.
> 2020-11-13 14:40:13.709 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): found command of type PercentType.
> 2020-11-13 14:40:13.711 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): found command to set level to 37.
> 2020-11-13 14:40:13.713 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(37 as PercentType) created.
> 2020-11-13 14:40:13.715 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleCommand(): sending command with target level 37.
> 2020-11-13 14:40:13.717 [TRACE] [.bridge.VeluxBridgeRunProductCommand] - sendCommand(nodeId=1,value=37) called.
> 2020-11-13 14:40:13.718 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
> 2020-11-13 14:40:13.720 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setNodeAndMainParameter(1) called.
> 2020-11-13 14:40:13.722 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator) called.
> 2020-11-13 14:40:13.724 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
> 2020-11-13 14:40:13.725 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator,authenticated) called.
> 2020-11-13 14:40:13.727 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
> 2020-11-13 14:40:13.728 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Send Command to Actuator,authenticated) called.
> 2020-11-13 14:40:13.730 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(Send Command to Actuator,authenticated) called.
> 2020-11-13 14:40:13.731 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - getRequestCommand() returns 0x300.
> 2020-11-13 14:40:13.733 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): ntfSessionID=1131.
> 2020-11-13 14:40:13.735 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqCommandOriginator=8.
> 2020-11-13 14:40:13.741 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevel=5.
> 2020-11-13 14:40:13.745 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqParameterActive=0.
> 2020-11-13 14:40:13.748 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI1=0.
> 2020-11-13 14:40:13.751 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI2=0.
> 2020-11-13 14:40:13.754 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqMainParameter=18944.
> 2020-11-13 14:40:13.758 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArrayCount=1.
> 2020-11-13 14:40:13.761 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArray01=1.
> 2020-11-13 14:40:13.763 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevelLock=0.
> 2020-11-13 14:40:13.765 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL03=0.
> 2020-11-13 14:40:13.767 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL47=0.
> 2020-11-13 14:40:13.769 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqLockTime=0.
> 2020-11-13 14:40:13.774 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes() data is 04 6B 08 05 00 00 00 4A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
> 2020-11-13 14:40:13.776 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_COMMAND_SEND_REQ,authenticated) initiated by Thread[OH-velux-67,5,main].
> 2020-11-13 14:40:13.777 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_COMMAND_SEND_REQ with 66 bytes of data.
> 2020-11-13 14:40:13.779 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x300 with data size 66 called.
> 2020-11-13 14:40:13.784 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 45 03 00 04 6B 08 05 00 00 00 4A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6E.
> 2020-11-13 14:40:13.788 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): transportEncoding=00 45 03 00 04 6B 08 05 00 00 00 4A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6E.
> 2020-11-13 14:40:13.790 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 71 called.
> 2020-11-13 14:40:13.793 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 45 03 00 04 6B 08 05 00 00 00 4A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6E C0.
> 2020-11-13 14:40:13.795 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): sending 73 bytes.
> 2020-11-13 14:40:13.796 [TRACE] [x.internal.bridge.slip.io.Connection] - io() called.
> 2020-11-13 14:40:13.799 [TRACE] [x.internal.bridge.slip.io.Connection] - io(): sending packet with 73 bytes: C0 00 45 03 00 04 6B 08 05 00 00 00 4A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6E C0
> 2020-11-13 14:40:13.801 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 73 bytes.
> 2020-11-13 14:40:13.805 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 73 bytes: C0 00 45 03 00 04 6B 08 05 00 00 00 4A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6E C0 
> 2020-11-13 14:40:13.806 [TRACE] [x.internal.bridge.slip.io.Connection] - io(): wait time 500 msecs.
> 2020-11-13 14:40:14.308 [TRACE] [x.internal.bridge.slip.io.Connection] - io(): receiving bytes.
> 2020-11-13 14:40:14.310 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
> 2020-11-13 14:40:14.314 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 10 bytes: C0 00 06 03 01 04 6B 01 6A C0 
> 2020-11-13 14:40:14.316 [TRACE] [x.internal.bridge.slip.io.Connection] - io(): received packet with 10 bytes: C0 00 06 03 01 04 6B 01 6A C0
> 2020-11-13 14:40:14.317 [TRACE] [x.internal.bridge.slip.io.Connection] - io() finished.
> 2020-11-13 14:40:14.319 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): received packet C0 00 06 03 01 04 6B 01 6A C0.
> 2020-11-13 14:40:14.321 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 10 called.
> 2020-11-13 14:40:14.323 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 06 03 01 04 6B 01 6A.
> 2020-11-13 14:40:14.325 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 8.
> 2020-11-13 14:40:14.327 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
> 2020-11-13 14:40:14.329 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 04 6B 01.
> 2020-11-13 14:40:14.331 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x301 and data 04 6B 01.
> 2020-11-13 14:40:14.332 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
> 2020-11-13 14:40:14.334 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 04 6B 01.
> 2020-11-13 14:40:14.336 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_COMMAND_SEND_CFM with 3 bytes of data.
> 2020-11-13 14:40:14.337 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): passes back command 0x301 and data 04 6B 01.
> 2020-11-13 14:40:14.339 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(GW_COMMAND_SEND_CFM with 3 bytes of data) called.
> 2020-11-13 14:40:14.341 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): handling response GW_COMMAND_SEND_CFM (0x301).
> 2020-11-13 14:40:14.343 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() called for GW_COMMAND_SEND_CFM (0x301) with 3 bytes of data.
> 2020-11-13 14:40:14.344 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() returns true.
> 2020-11-13 14:40:14.346 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): returned status: OK - Command is accepted.
> 2020-11-13 14:40:14.347 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingSessionID() called for requestNodeID 1131 and responseNodeID 1131.
> 2020-11-13 14:40:14.349 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() called for requestSessionID 1131 and responseSessionID 1131.
> 2020-11-13 14:40:14.351 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() returns true.
> 2020-11-13 14:40:14.352 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): skipping wait for more packets as sequential processing is not enforced.
> 2020-11-13 14:40:14.354 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): finished=true,success=true.
> 2020-11-13 14:40:14.356 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_COMMAND_SEND_REQ) returns success.
> 2020-11-13 14:40:14.358 [DEBUG] [.bridge.VeluxBridgeRunProductCommand] - sendCommand() finished successfully.
> 2020-11-13 14:40:14.359 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): The new shutter level will be send through the home monitoring events.
> 2020-11-13 14:40:14.360 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 18.
> 2020-11-13 14:40:14.362 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): position of actuators are updated.
> 2020-11-13 14:40:14.363 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionAttempt set to Fri Nov 13 14:40:14 CET 2020.
> 2020-11-13 14:40:14.365 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionSuccess set to Fri Nov 13 14:40:14 CET 2020.
> 2020-11-13 14:40:14.366 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(Thread[OH-velux-67,5,main]) done.
> 2020-11-13 14:40:14.367 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand.scheduled(Thread[OH-velux-67,5,main]) done.
> 2020-11-13 14:40:14.368 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB() initiated by Thread[OH-thingHandler-3,5,main] starting cycle 149991.
> 2020-11-13 14:40:14.370 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB(): processing of possible HSM messages.
> 2020-11-13 14:40:14.372 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB(): looping through all (both child things and bridge) linked channels for a need of refresh.
> 2020-11-13 14:40:14.372 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB.scheduled() initiated by Thread[OH-velux-68,5,main] will process HouseStatus.
> 2020-11-13 14:40:14.375 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
> 2020-11-13 14:40:14.375 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:window:7680cbd2:Dennis_Velux:limitMaximum, velux:window:7680cbd2:Landing4_Velux:position, velux:window:7680cbd2:Landing3_Velux:position, velux:window:7680cbd2:Landing2_Velux:position, velux:rollershutter:07cf225a:Tim_Blind:position, velux:rollershutter:7680cbd2:Masterbed1_Blind:position, velux:rollershutter:7680cbd2:Dennis_Blind:position, velux:scene:7680cbd2:Close_all_blinds:action, velux:window:7680cbd2:Bathroom_Velux:position, velux:scene:7680cbd2:Open_Masterbed_Blinds:action, velux:window:7680cbd2:Shower_Velux:position, velux:rollershutter:7680cbd2:Nell_Blind:position, velux:window:7680cbd2:Nell_Velux:limitMinimum, velux:window:7680cbd2:Masterbed1_Velux:position, velux:scene:7680cbd2:Open_all_windows:action, velux:scene:7680cbd2:Close_all_windows:action, velux:window:7680cbd2:Dennis_Velux:limitMinimum, velux:window:7680cbd2:Nell_Velux:limitMaximum, velux:rollershutter:7680cbd2:Masterbed3_Blind:position, velux:rollershutter:7680cbd2:Masterbed2_Blind:position, velux:window:7680cbd2:Masterbed3_Velux:position, velux:window:7680cbd2:Dennis_Velux:position, velux:window:7680cbd2:Masterbed2_Velux:position, velux:scene:7680cbd2:Close_Masterbed_Blinds:action, velux:window:7680cbd2:Landing1_Velux:position, velux:window:7680cbd2:Timmy_Velux:position, velux:scene:7680cbd2:Open_all_blinds:action, velux:window:7680cbd2:Nell_Velux:position].
> 2020-11-13 14:40:14.377 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,limitMaximum) returns enum velux:window/limitMaximum.
> 2020-11-13 14:40:14.379 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
> 2020-11-13 14:40:14.377 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
> 2020-11-13 14:40:14.381 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
> 2020-11-13 14:40:14.381 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
> 2020-11-13 14:40:14.383 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
> 2020-11-13 14:40:14.383 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
> 2020-11-13 14:40:14.385 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
> 2020-11-13 14:40:14.386 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
> 2020-11-13 14:40:14.387 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
> 2020-11-13 14:40:14.390 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status,authenticated) called.
> 2020-11-13 14:40:14.390 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
> 2020-11-13 14:40:14.392 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(Retrieve House Status,authenticated) called.
> 2020-11-13 14:40:14.393 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
> 2020-11-13 14:40:14.394 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
> 2020-11-13 14:40:14.397 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_OPENHAB_RECEIVEONLY,authenticated) initiated by Thread[OH-velux-68,5,main].
> 2020-11-13 14:40:14.396 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
> 2020-11-13 14:40:14.398 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_OPENHAB_RECEIVEONLY with 0 bytes of data.
> 2020-11-13 14:40:14.399 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
> 2020-11-13 14:40:14.401 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): special command: determine whether there is any message waiting.
> 2020-11-13 14:40:14.403 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): check for a waiting message.
> 2020-11-13 14:40:14.403 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
> 2020-11-13 14:40:14.405 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable(): called.
> 2020-11-13 14:40:14.406 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
> 2020-11-13 14:40:14.407 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
> 2020-11-13 14:40:14.409 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 bytes ready to be read (> 0 means true).
> 2020-11-13 14:40:14.409 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
> 2020-11-13 14:40:14.412 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable(): no message waiting.
> 2020-11-13 14:40:14.413 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
> 2020-11-13 14:40:14.414 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): no message waiting, aborting.
> 2020-11-13 14:40:14.416 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_OPENHAB_RECEIVEONLY) returns failure.
> 2020-11-13 14:40:14.416 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
> 2020-11-13 14:40:14.418 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
> 2020-11-13 14:40:14.419 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:scene,action) returns enum velux:scene/action.
> 2020-11-13 14:40:14.421 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB.scheduled() initiated by Thread[OH-velux-68,5,main] has finished.
> 2020-
1114

Im doing more testing and I think the ntfstate = 128 seems to be consistent. The only issue seems to be that it does not update the state unless you send a command to the window and even then it does not seem to be in the log file until a few minutes later when the binding does a sort of round robin of all the actuators.

Is there a way to trap the ntfstate in a rule? I can at least test this.

1115

I am glad you find it consistent but I do still need to see a trace including it (unfortunately your prior post did not do so). I need the byte payload for the GW_GET_NODE_INFORMATION_NTF (124 bytes long) and the GW_NODE_STATE_POSITION_CHANGED_NTF (20 bytes long) notifications. Examples are as follows (although since you are on the older version you will have slightly different texts in the messages).

I need to see position 2 in the GW_NODE_STATE_POSITION_CHANGED_NTF payload and position 85 in the GW_GET_NODE_INFORMATION_NTF payload. In the examples below these are both “05” (done) and I want to see what is in those positions in your traces (possibly “80” …)

2020-11-13 16:22:47.562 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.1.142] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 00 05 9A 00 9A 00 F7 FF F7 FF F7 FF F7 FF 00 00 80 63 00 00
...
2020-11-13 16:26:10.461 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.1.142] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data => 01 00 01 00 42 61 74 68 72 6F 6F 6D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 03 01 00 00 35 56 36 13 5A 11 2A 05 70 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4F 01 81 37 02 D8 02 64 00 D8 03 BA 00 00 00 00 00 00 00 00 00 00 00 00 00
1116

PS @Julian_Divett in your earlier trace you showed the following values when your window was manually opened. And it would be useful to know if either ntfCurrentPosition or ntfTarget bear any relationship whatsoever to its real manual position. Depending on whether you have inverted = true or false, 51200 would be 0% or 100%, and 14336 would be 28% or 72%. Personally I think if the electronics are disengaged, then the actual physical position could be anything, and neither of these numbers would reflect the reality…

ntfState=128.
ntfCurrentPosition=51200.
ntfTarget=14336
1117

@Julian_Divett, @kleiner-irrer, @Chiuaua79 just for info, the latest version of the jar file is HERE, with solutions to all your above-mentioned wishes. Please test and confirm it is Ok.

1118 
2020-11-14 15:48:20.958 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(velux:window:7680cbd2:Dennis_Velux:position,62) called.
2020-11-14 15:48:20.960 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[safeCall-14,5,main]) done.
2020-11-14 15:48:20.961 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:20.962 [TRACE] [.velux.internal.handler.VeluxHandler] - handleCommand() done.
2020-11-14 15:48:20.966 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
2020-11-14 15:48:20.968 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): no existing products with changed parameters.
2020-11-14 15:48:20.971 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(): working on item velux:window:7680cbd2:Dennis_Velux:position (type velux:window/position) with COMMAND 62.
2020-11-14 15:48:20.973 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleCommand(velux:window:7680cbd2:Dennis_Velux:position,position,62,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@817c2) called.
2020-11-14 15:48:20.975 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 18.
2020-11-14 15:48:20.978 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): there are some existing products.
2020-11-14 15:48:20.980 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): found command of type PercentType.
2020-11-14 15:48:20.983 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): found command to set level to 62.
2020-11-14 15:48:20.986 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(62 as PercentType) created.
2020-11-14 15:48:20.988 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleCommand(): sending command with target level 62.
2020-11-14 15:48:20.990 [TRACE] [.bridge.VeluxBridgeRunProductCommand] - sendCommand(nodeId=1,value=62) called.
2020-11-14 15:48:20.993 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2020-11-14 15:48:20.995 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setNodeAndMainParameter(1) called.
2020-11-14 15:48:20.997 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator) called.
2020-11-14 15:48:20.998 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2020-11-14 15:48:20.999 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator,authenticated) called.
2020-11-14 15:48:21.006 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2020-11-14 15:48:21.008 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Send Command to Actuator, authenticated) called.
2020-11-14 15:48:21.010 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Send Command to Actuator', authenticated
2020-11-14 15:48:21.011 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - getRequestCommand() returns 0x300.
2020-11-14 15:48:21.013 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): ntfSessionID=2244.
2020-11-14 15:48:21.014 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqCommandOriginator=8.
2020-11-14 15:48:21.015 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevel=5.
2020-11-14 15:48:21.017 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqParameterActive=0.
2020-11-14 15:48:21.018 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI1=0.
2020-11-14 15:48:21.019 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI2=0.
2020-11-14 15:48:21.020 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqMainParameter=31744.
2020-11-14 15:48:21.022 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArrayCount=1.
2020-11-14 15:48:21.023 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArray01=1.
2020-11-14 15:48:21.024 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevelLock=0.
2020-11-14 15:48:21.025 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL03=0.
2020-11-14 15:48:21.027 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL47=0.
2020-11-14 15:48:21.028 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqLockTime=0.
2020-11-14 15:48:21.030 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes() data is 08 C4 08 05 00 00 00 7C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2020-11-14 15:48:21.032 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_COMMAND_SEND_REQ => started => Thread[pool-43-thread-1,5,main] 
2020-11-14 15:48:21.033 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_COMMAND_SEND_REQ => send mode => preparing command 
2020-11-14 15:48:21.035 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x300 with data size 66 called.
2020-11-14 15:48:21.037 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 45 03 00 08 C4 08 05 00 00 00 7C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 FB.
2020-11-14 15:48:21.038 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 71 called.
2020-11-14 15:48:21.041 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 45 03 00 08 C4 08 05 00 00 00 7C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 FB C0.
2020-11-14 15:48:21.042 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_COMMAND_SEND_REQ => command ready => start sending 
2020-11-14 15:48:21.044 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_REQ => sending data => 08 C4 08 05 00 00 00 7C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2020-11-14 15:48:21.046 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: called.
2020-11-14 15:48:21.048 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: sending packet with 73 bytes: C0 00 45 03 00 08 C4 08 05 00 00 00 7C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 FB C0
2020-11-14 15:48:21.049 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 73 bytes.
2020-11-14 15:48:21.052 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 73 bytes: C0 00 45 03 00 08 C4 08 05 00 00 00 7C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 FB C0 
2020-11-14 15:48:21.053 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: receiving bytes.
2020-11-14 15:48:21.055 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2020-11-14 15:48:21.106 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2020-11-14 15:48:21.107 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 10 bytes: C0 00 06 03 01 08 C4 01 C9 C0 
2020-11-14 15:48:21.109 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: received packet with 10 bytes: C0 00 06 03 01 08 C4 01 C9 C0
2020-11-14 15:48:21.110 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: finished.
2020-11-14 15:48:21.112 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 10 called.
2020-11-14 15:48:21.113 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 06 03 01 08 C4 01 C9.
2020-11-14 15:48:21.115 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 8.
2020-11-14 15:48:21.117 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2020-11-14 15:48:21.119 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 08 C4 01.
2020-11-14 15:48:21.120 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x301 and data 08 C4 01.
2020-11-14 15:48:21.122 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2020-11-14 15:48:21.123 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 08 C4 01.
2020-11-14 15:48:21.125 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => received data => 08 C4 01
2020-11-14 15:48:21.126 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => applying data length => 3
2020-11-14 15:48:21.127 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(GW_COMMAND_SEND_CFM with 3 bytes of data) called.
2020-11-14 15:48:21.129 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): handling response GW_COMMAND_SEND_CFM (0x301).
2020-11-14 15:48:21.130 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() called for GW_COMMAND_SEND_CFM (0x301) with 3 bytes of data.
2020-11-14 15:48:21.131 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() returns true.
2020-11-14 15:48:21.133 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): returned status: OK - Command is accepted.
2020-11-14 15:48:21.134 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingSessionID() called for requestNodeID 2244 and responseNodeID 2244.
2020-11-14 15:48:21.135 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() called for requestSessionID 2244 and responseSessionID 2244.
2020-11-14 15:48:21.136 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() returns true.
2020-11-14 15:48:21.138 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): skipping wait for more packets as sequential processing is not enforced.
2020-11-14 15:48:21.139 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): finished=true,success=true.
2020-11-14 15:48:21.140 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_COMMAND_SEND_REQ => finished => success
2020-11-14 15:48:21.141 [DEBUG] [.bridge.VeluxBridgeRunProductCommand] - sendCommand() finished successfully.
2020-11-14 15:48:21.142 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): The new shutter level will be send through the home monitoring events.
2020-11-14 15:48:21.143 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 18.
2020-11-14 15:48:21.145 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): position of actuators are updated.
2020-11-14 15:48:21.146 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionAttempt set to Sat Nov 14 15:48:21 CET 2020.
2020-11-14 15:48:21.147 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionSuccess set to Sat Nov 14 15:48:21 CET 2020.
2020-11-14 15:48:21.149 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(Thread[pool-43-thread-1,5,main]) done.
2020-11-14 15:48:21.150 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand.scheduled(Thread[pool-43-thread-1,5,main]) done.
2020-11-14 15:48:25.427 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB() initiated by Thread[OH-thingHandler-2,5,main] starting cycle 93.
2020-11-14 15:48:25.439 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB(): processing of possible HSM messages.
2020-11-14 15:48:25.441 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB(): loop through all (child things and bridge) linked channels needing a refresh
2020-11-14 15:48:25.441 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB.scheduled() initiated by Thread[pool-43-thread-1,5,main] will process HouseStatus.
2020-11-14 15:48:25.443 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2020-11-14 15:48:25.444 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2020-11-14 15:48:25.446 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2020-11-14 15:48:25.446 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:window:7680cbd2:Dennis_Velux:limitMaximum, velux:window:7680cbd2:Landing4_Velux:position, velux:window:7680cbd2:Landing3_Velux:position, velux:window:7680cbd2:Landing2_Velux:position, velux:rollershutter:07cf225a:Tim_Blind:position, velux:rollershutter:7680cbd2:Masterbed1_Blind:position, velux:rollershutter:7680cbd2:Dennis_Blind:position, velux:scene:7680cbd2:Close_all_blinds:action, velux:window:7680cbd2:Bathroom_Velux:position, velux:scene:7680cbd2:Open_Masterbed_Blinds:action, velux:window:7680cbd2:Shower_Velux:position, velux:rollershutter:7680cbd2:Nell_Blind:position, velux:window:7680cbd2:Nell_Velux:limitMinimum, velux:window:7680cbd2:Masterbed1_Velux:position, velux:scene:7680cbd2:Open_all_windows:action, velux:scene:7680cbd2:Close_all_windows:action, velux:window:7680cbd2:Dennis_Velux:limitMinimum, velux:window:7680cbd2:Nell_Velux:limitMaximum, velux:rollershutter:7680cbd2:Masterbed3_Blind:position, velux:rollershutter:7680cbd2:Masterbed2_Blind:position, velux:window:7680cbd2:Masterbed3_Velux:position, velux:window:7680cbd2:Dennis_Velux:position, velux:window:7680cbd2:Masterbed2_Velux:position, velux:scene:7680cbd2:Close_Masterbed_Blinds:action, velux:window:7680cbd2:Landing1_Velux:position, velux:window:7680cbd2:Timmy_Velux:position, velux:scene:7680cbd2:Open_all_blinds:action, velux:window:7680cbd2:Nell_Velux:position].
2020-11-14 15:48:25.448 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2020-11-14 15:48:25.448 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,limitMaximum) returns enum velux:window/limitMaximum.
2020-11-14 15:48:25.450 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.450 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2020-11-14 15:48:25.452 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2020-11-14 15:48:25.454 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2020-11-14 15:48:25.452 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.456 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2020-11-14 15:48:25.459 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2020-11-14 15:48:25.461 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => started => Thread[pool-43-thread-1,5,main] 
2020-11-14 15:48:25.463 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2020-11-14 15:48:25.464 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.467 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.467 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.0.21: called.
2020-11-14 15:48:25.469 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.0.21: called.
2020-11-14 15:48:25.469 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.471 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2020-11-14 15:48:25.471 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.473 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 6
2020-11-14 15:48:25.473 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.475 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 6 messages ready to be read (> 0 means true).
2020-11-14 15:48:25.475 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2020-11-14 15:48:25.477 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.0.21: there are messages waiting.
2020-11-14 15:48:25.477 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.479 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => message(s) waiting => start reading 
2020-11-14 15:48:25.479 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2020-11-14 15:48:25.481 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: called.
2020-11-14 15:48:25.481 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.482 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: receiving bytes.
2020-11-14 15:48:25.483 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2020-11-14 15:48:25.485 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.487 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:scene,action) returns enum velux:scene/action.
2020-11-14 15:48:25.485 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2020-11-14 15:48:25.489 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as item is not refreshable.
2020-11-14 15:48:25.490 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2020-11-14 15:48:25.494 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 01 02 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00 47 C0 
2020-11-14 15:48:25.494 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.499 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.498 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: received packet with 27 bytes: C0 00 17 02 11 01 02 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00 47 C0
2020-11-14 15:48:25.501 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: finished.
2020-11-14 15:48:25.501 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:scene,action) returns enum velux:scene/action.
2020-11-14 15:48:25.503 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as item is not refreshable.
2020-11-14 15:48:25.503 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2020-11-14 15:48:25.505 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.507 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.507 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 01 02 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00 47.
2020-11-14 15:48:25.509 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2020-11-14 15:48:25.509 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2020-11-14 15:48:25.511 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.512 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2020-11-14 15:48:25.514 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,limitMinimum) returns enum velux:window/limitMinimum.
2020-11-14 15:48:25.515 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 01 02 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00.
2020-11-14 15:48:25.516 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.518 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.518 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 01 02 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00.
2020-11-14 15:48:25.520 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.521 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2020-11-14 15:48:25.523 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:scene,action) returns enum velux:scene/action.
2020-11-14 15:48:25.524 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 01 02 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00.
2020-11-14 15:48:25.525 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as item is not refreshable.
2020-11-14 15:48:25.527 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:scene,action) returns enum velux:scene/action.
2020-11-14 15:48:25.529 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as item is not refreshable.
2020-11-14 15:48:25.529 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 01 02 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00
2020-11-14 15:48:25.531 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,limitMinimum) returns enum velux:window/limitMinimum.
2020-11-14 15:48:25.531 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2020-11-14 15:48:25.533 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.534 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2020-11-14 15:48:25.535 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,limitMaximum) returns enum velux:window/limitMaximum.
2020-11-14 15:48:25.537 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.537 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2020-11-14 15:48:25.539 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2020-11-14 15:48:25.541 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.540 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2020-11-14 15:48:25.544 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2020-11-14 15:48:25.544 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2020-11-14 15:48:25.546 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.548 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.548 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=1.
2020-11-14 15:48:25.550 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.550 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=2.
2020-11-14 15:48:25.552 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.554 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.554 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=51200.
2020-11-14 15:48:25.556 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=31744.
2020-11-14 15:48:25.558 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.560 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2020-11-14 15:48:25.561 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:scene,action) returns enum velux:scene/action.
2020-11-14 15:48:25.562 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as item is not refreshable.
2020-11-14 15:48:25.562 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=-1687224320.
2020-11-14 15:48:25.565 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.565 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2020-11-14 15:48:25.566 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.567 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=1,productState=2,productPosition=51200,productTarget=31744) called.
2020-11-14 15:48:25.569 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.570 [TRACE] [nternal.things.VeluxExistingProducts] - isRegisteredProductBridgeIndex 1) called.
2020-11-14 15:48:25.572 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.573 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(String 56:18:5E:5A:0A:29:08:09) returns true.
2020-11-14 15:48:25.574 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:scene,action) returns enum velux:scene/action.
2020-11-14 15:48:25.576 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as item is not refreshable.
2020-11-14 15:48:25.576 [TRACE] [nternal.things.VeluxExistingProducts] - get(1) called.
2020-11-14 15:48:25.578 [TRACE] [nternal.things.VeluxExistingProducts] - isRegisteredProductBridgeIndex 1) called.
2020-11-14 15:48:25.581 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:window,position) returns enum velux:window/position.
2020-11-14 15:48:25.581 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(String 56:18:5E:5A:0A:29:08:09) returns true.
2020-11-14 15:48:25.584 [TRACE] [g.velux.internal.things.VeluxProduct] - setState(name=Dennis_Velux,index=1) state 5 replaced by 2.
2020-11-14 15:48:25.584 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.586 [TRACE] [g.velux.internal.things.VeluxProduct] - setCurrentPosition(name=Dennis_Velux,index=1) target 51200 replaced by 31744.
2020-11-14 15:48:25.587 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB(): loop through properties needing a refresh
2020-11-14 15:48:25.587 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex 56:18:5E:5A:0A:29:08:09.
2020-11-14 15:48:25.589 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2020-11-14 15:48:25.590 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/ipAddress, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2020-11-14 15:48:25.591 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2020-11-14 15:48:25.592 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2020-11-14 15:48:25.593 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2020-11-14 15:48:25.594 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.594 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: called.
2020-11-14 15:48:25.595 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,ipAddress) returns enum velux:klf200/ipAddress.
2020-11-14 15:48:25.595 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: receiving bytes.
2020-11-14 15:48:25.596 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.596 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2020-11-14 15:48:25.597 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2020-11-14 15:48:25.597 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2020-11-14 15:48:25.598 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.599 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 20 bytes: C0 00 10 03 02 08 C4 08 01 00 C8 00 02 03 06 02 00 80 99 C0 
2020-11-14 15:48:25.601 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: received packet with 20 bytes: C0 00 10 03 02 08 C4 08 01 00 C8 00 02 03 06 02 00 80 99 C0
2020-11-14 15:48:25.602 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2020-11-14 15:48:25.603 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: finished.
2020-11-14 15:48:25.603 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.604 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2020-11-14 15:48:25.604 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 20 called.
2020-11-14 15:48:25.605 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.606 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 10 03 02 08 C4 08 01 00 C8 00 02 03 06 02 00 80 99.
2020-11-14 15:48:25.607 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2020-11-14 15:48:25.608 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.608 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 18.
2020-11-14 15:48:25.609 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2020-11-14 15:48:25.609 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2020-11-14 15:48:25.611 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.611 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 08 C4 08 01 00 C8 00 02 03 06 02 00 80.
2020-11-14 15:48:25.612 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2020-11-14 15:48:25.614 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.614 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x302 and data 08 C4 08 01 00 C8 00 02 03 06 02 00 80.
2020-11-14 15:48:25.615 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2020-11-14 15:48:25.615 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2020-11-14 15:48:25.616 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.617 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 08 C4 08 01 00 C8 00 02 03 06 02 00 80.
2020-11-14 15:48:25.618 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2020-11-14 15:48:25.619 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2020-11-14 15:48:25.619 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_RUN_STATUS_NTF => received data => 08 C4 08 01 00 C8 00 02 03 06 02 00 80
2020-11-14 15:48:25.620 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshOpenHAB() initiated by Thread[OH-thingHandler-2,5,main] finished cycle 93.
2020-11-14 15:48:25.620 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_RUN_STATUS_NTF => parallelism allowed => continuing
2020-11-14 15:48:25.622 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: called.
2020-11-14 15:48:25.623 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: receiving bytes.
2020-11-14 15:48:25.624 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2020-11-14 15:48:25.626 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2020-11-14 15:48:25.628 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 20 bytes: C0 00 10 03 02 08 C4 08 01 00 C8 00 01 03 0F 02 00 80 93 C0 
2020-11-14 15:48:25.629 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: received packet with 20 bytes: C0 00 10 03 02 08 C4 08 01 00 C8 00 01 03 0F 02 00 80 93 C0
2020-11-14 15:48:25.630 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: finished.
2020-11-14 15:48:25.632 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 20 called.
2020-11-14 15:48:25.633 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 10 03 02 08 C4 08 01 00 C8 00 01 03 0F 02 00 80 93.
2020-11-14 15:48:25.635 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 18.
2020-11-14 15:48:25.636 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2020-11-14 15:48:25.638 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 08 C4 08 01 00 C8 00 01 03 0F 02 00 80.
2020-11-14 15:48:25.639 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x302 and data 08 C4 08 01 00 C8 00 01 03 0F 02 00 80.
2020-11-14 15:48:25.641 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2020-11-14 15:48:25.643 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 08 C4 08 01 00 C8 00 01 03 0F 02 00 80.
2020-11-14 15:48:25.644 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_RUN_STATUS_NTF => received data => 08 C4 08 01 00 C8 00 01 03 0F 02 00 80
2020-11-14 15:48:25.646 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_RUN_STATUS_NTF => parallelism allowed => continuing
2020-11-14 15:48:25.647 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: called.
2020-11-14 15:48:25.648 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: receiving bytes.
2020-11-14 15:48:25.649 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2020-11-14 15:48:25.651 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2020-11-14 15:48:25.652 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 9 bytes: C0 00 05 03 04 08 C4 CE C0 
2020-11-14 15:48:25.654 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: received packet with 9 bytes: C0 00 05 03 04 08 C4 CE C0
2020-11-14 15:48:25.655 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: finished.
2020-11-14 15:48:25.657 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 9 called.
2020-11-14 15:48:25.658 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 05 03 04 08 C4 CE.
2020-11-14 15:48:25.659 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 7.
2020-11-14 15:48:25.661 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x304 .
2020-11-14 15:48:25.663 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 08 C4.
2020-11-14 15:48:25.664 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x304 and data 08 C4.
2020-11-14 15:48:25.665 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x304 .
2020-11-14 15:48:25.667 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 08 C4.
2020-11-14 15:48:25.668 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_SESSION_FINISHED_NTF => received data => 08 C4
2020-11-14 15:48:25.669 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_SESSION_FINISHED_NTF => parallelism allowed => continuing
2020-11-14 15:48:25.671 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: called.
2020-11-14 15:48:25.672 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: receiving bytes.
2020-11-14 15:48:25.673 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2020-11-14 15:48:25.675 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2020-11-14 15:48:25.677 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 01 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00 C5 C0 
2020-11-14 15:48:25.678 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: received packet with 27 bytes: C0 00 17 02 11 01 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00 C5 C0
2020-11-14 15:48:25.679 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.21: finished.
2020-11-14 15:48:25.681 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2020-11-14 15:48:25.683 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 01 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00 C5.
2020-11-14 15:48:25.684 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2020-11-14 15:48:25.685 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2020-11-14 15:48:25.687 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 01 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00.
2020-11-14 15:48:25.689 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 01 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00.
2020-11-14 15:48:25.690 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2020-11-14 15:48:25.692 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 01 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00.
2020-11-14 15:48:25.693 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 01 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00
2020-11-14 15:48:25.695 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2020-11-14 15:48:25.696 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2020-11-14 15:48:25.697 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2020-11-14 15:48:25.699 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2020-11-14 15:48:25.700 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2020-11-14 15:48:25.701 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=1.
2020-11-14 15:48:25.702 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=128.
2020-11-14 15:48:25.704 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=51200.
2020-11-14 15:48:25.705 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=31744.
2020-11-14 15:48:25.706 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2020-11-14 15:48:25.708 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=-1687224320.
2020-11-14 15:48:25.709 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2020-11-14 15:48:25.710 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=1,productState=128,productPosition=51200,productTarget=31744) called.
2020-11-14 15:48:25.712 [TRACE] [nternal.things.VeluxExistingProducts] - isRegisteredProductBridgeIndex 1) called.
2020-11-14 15:48:25.713 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(String 56:18:5E:5A:0A:29:08:09) returns true.
2020-11-14 15:48:25.714 [TRACE] [nternal.things.VeluxExistingProducts] - get(1) called.
2020-11-14 15:48:25.715 [TRACE] [nternal.things.VeluxExistingProducts] - isRegisteredProductBridgeIndex 1) called.
2020-11-14 15:48:25.717 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(String 56:18:5E:5A:0A:29:08:09) returns true.
2020-11-14 15:48:25.718 [TRACE] [g.velux.internal.things.VeluxProduct] - setState(name=Dennis_Velux,index=1) state 2 replaced by 128.
1119

Hi thanks Andrew - I’m back and testing the new binding. In fact the old one was not giving back the
GW_NODE_STATE_POSITION_CHANGED_NTF so not much use. So above it the log file for a Windows that was opened manually. As expected nothing happens in the log file when you manually open so when I try and send a command (open to 62) it then updates the ntfstate to 128. Also the numeric position value becomes UNDEF in Visual Studio.

1120

Just noticed that this appears in the logs a bit later on:

2020-11-14 16:44:12.865 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_NTF with 124 bytes of data) called.
2020-11-14 16:44:12.867 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_NTF (0x210).
2020-11-14 16:44:12.868 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_NTF (0x210) with 124 bytes of data.
2020-11-14 16:44:12.869 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2020-11-14 16:44:12.870 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeID=1.
2020-11-14 16:44:12.871 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfOrder=1.
2020-11-14 16:44:12.872 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPlacement=0.
2020-11-14 16:44:12.873 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfName=Dennis_Velux.
2020-11-14 16:44:12.874 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfVelocity=1.
2020-11-14 16:44:12.875 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeTypeSubType=257 (SLIDER_WINDOW).
2020-11-14 16:44:12.876 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): derived product description=Window opener.
2020-11-14 16:44:12.877 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductGroup=769.
2020-11-14 16:44:12.879 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductType=1.
2020-11-14 16:44:12.880 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeVariation=0.
2020-11-14 16:44:12.881 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPowerMode=0.
2020-11-14 16:44:12.882 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfBuildNumber=2.
2020-11-14 16:44:12.883 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfSerialNumber=[86, 24, 94, 90, 10, 41, 8, 9].
2020-11-14 16:44:12.884 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfState=128.
2020-11-14 16:44:12.885 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfCurrentPosition=51200.
2020-11-14 16:44:12.886 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTarget=51200.
2020-11-14 16:44:12.887 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFP1CurrentPosition=63487.
2020-11-14 16:44:12.888 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFP2CurrentPosition=63487.
2020-11-14 16:44:12.889 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFP3CurrentPosition=63487.
2020-11-14 16:44:12.890 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFP4CurrentPosition=63487.
2020-11-14 16:44:12.891 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfRemainingTime=20232.
2020-11-14 16:44:12.892 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTimeStamp=1325967495.
2020-11-14 16:44:12.893 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNbrOfAlias=1.
2020-11-14 16:44:12.894 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasOne=-670846436.
2020-11-14 16:44:12.895 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasTwo=0.
2020-11-14 16:44:12.896 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasThree=0.
2020-11-14 16:44:12.897 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFour=0.
2020-11-14 16:44:12.899 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFive=0.
2020-11-14 16:44:12.900 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 1 and responseNodeID 1.
2020-11-14 16:44:12.901 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for requestNodeID 1 and responseNodeID 1.
2020-11-14 16:44:12.902 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2020-11-14 16:44:12.903 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2,name=Dennis_Velux) created.
2020-11-14 16:44:12.904 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=true,success=true.
2020-11-14 16:44:12.905 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_GET_NODE_INFORMATION_REQ => finished => success
2020-11-14 16:44:12.906 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getProduct(): returning product Product "Dennis_Velux" / SLIDER_WINDOW (bridgeIndex=1,serial=56:18:5E:5A:0A:29:08:09,position=C800).
2020-11-14 16:44:12.908 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(constructur with 63487 as veluxPosition) called.
2020-11-14 16:44:12.908 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition() gives up.
2020-11-14 16:44:12.909 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): position of actuator is 'UNDEFINED'.
2020-11-14 16:44:12.910 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh() returns UNDEF.
2020-11-14 16:44:12.911 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(): updating channel velux:window:7680cbd2:Dennis_Velux:position to UNDEF.
1121

Many thanks @Julian_Divett for the great help. To summarise, what we know so far…

  • If one sends a command to a window when it is in normal operation mode, one receives several GW_NODE_STATE_POSITION_CHANGED_NTF messages whose second byte value ranges from “02” to “05”.

  • I wanted to confirm that, if one sends a command to the window when it is in manual override mode, the second byte value would be “80”. The one single line that I needed from your logs (see below) does indeed confirm that. Thank you.

2020-11-14 15:48:25.693 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.0.21] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 01 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 9B 6F 00 00

HOWEVER, I still need to confirm if the value of the 85th byte of a GW_GET_NODE_INFORMATION_NTF message from a window when it is in manual override mode is also “80”. The logs that you posted do not include such a line, but it is certainly in the log somewhere. Can you please search through them to find a line like the following from my own system (which in my case has the value “05”).

2020-11-14 16:26:36.028 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.1.142] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data => 01 00 01 00 42 61 74 68 72 6F 6F 6D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 03 01 00 00 35 56 36 13 5A 11 2A 05 70 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4F 02 D2 D1 02 D8 02 64 00 D8 03 BA 00 00 00 00 00 00 00 00 00 00 00 00 00

And…
… this is what you were asking for. Right?

1122

Yes the 85th byte is 80. Regarding the UNDEF I guess we can trap that somehow in a rule. I’m just trying to figure the best way to implement this. I was thinking a regular cron job that sends a command to each of the veluxes which does nothing ie if the window is at 100 (closed in my case) then send a 100 command. We would then pickup which veluxes are showing 128 or position UNDEF. It’s a bit clunky though! Any thoughts??

GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data => 01 00 01 00 44 65 6E 6E 69 73 5F 56 65 6C 75 78 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 01 03 01 00 00 02 56 18 5E 5A 0A 29 08 09 80 C8 00 7C 00 F7 FF F7 FF F7 FF F7 FF 00 00 4F 08 9B D5 01 D8 03 B2 1C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

1123

@Julian_Divett thanks for confirming the “80” at byte 85.

This type of notification is a response to a regular polling request (i.e. every 60 seconds or so). So I imagine that it should come through at some point with 80 without you having to send a new position command. However, I can’t verify that, so you would need to check. i.e send a command when it is NOT in manual mode (to clear the 80) then manually move the window, and see if/when the 80 comes back…

1124

@AndrewFG unfortunately it does not seem to change to 80 until you send a command

Here is the polled string several minutes after a Manual Operation
00 00 00 00 4E 65 6C 6C 5F 56 65 6C 75 78 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 01 03 01 00 00 02 56 18 5E 5A 0A 28 06 14 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4F 09 81 2D 01 D8 03 B2 1C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
And this is after sending a command whilst in Manual
00 00 00 00 4E 65 6C 6C 5F 56 65 6C 75 78 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 01 03 01 00 00 02 56 18 5E 5A 0A 28 06 14 80 C8 00 C0 00 F7 FF F7 FF F7 FF F7 FF 00 00 4F 09 82 9B 01 D8 03 B2 1C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
After Closing Manually (so back in Automatic mode)
00 00 00 00 4E 65 6C 6C 5F 56 65 6C 75 78 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 01 03 01 00 00 02 56 18 5E 5A 0A 28 06 14 80 C8 00 C0 00 F7 FF F7 FF F7 FF F7 FF 00 00 4F 09 85 B6 01 D8 03 B2 1C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
After sending Command whilst in Automatic
00 00 00 00 4E 65 6C 6C 5F 56 65 6C 75 78 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 01 01 03 01 00 00 02 56 18 5E 5A 0A 28 06 14 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4F 09 86 E9 01 D8 03 B2 1C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

1125

@Julian_Divett many thanks for the detective work. So at least it means we know how it functions. Unfortunately that means you will indeed need a rule to “exercise” the actuator regularly and thus trigger the UNDEF position error. Perhaps something like setting newPosition = oldPosition (or newPosition = oldPosition +/- 1) ??

1 Like
1126

@AndrewFG

This seems to work

rule "test window every 10 minutes"
when
Time cron "0 0/10 * * * ?" //every 10 minutes
then 
if (Dennis_Velux.state != UNDEF) {
    Dennis_Velux.sendCommand(Dennis_Velux.state)
    logInfo("Test", "sending current position to Dennis velux")
}
else
{
logInfo("Test", "Velux in Manual mode send pushover alert and try and close window")
sendPushoverMessage(pushoverBuilder("Dennis Window is Manually operated").withPriority(2))	
Dennis_Velux.sendCommand(100) //try and reset
}
end
1 Like
1127

^
PS I will add (something like) this rule to the ReadMe file.

1128

Hi @AndrewFG. Silent mode is now working when defining “silent” i.s.o. “short” in a manual things file.

When adding the scene as a thing via paperUI, the setting keeps returning to “default”.

I am happy how things are working now, however :smiley:

1129

The scene code is definitely broken: @gs4711 Guenther’s original code executes a command set named GW_SET_NODE_VELOCITY_REQ/CFM to set the scene and actuator velocity. But this command is not described in the KLF API specification, and the only mention of it is change note “3.17 GW_SET_NODE_VELOCITY_REQ/CFM command set removed”. So I suppose that these commands may have been supported in earlier versions of the KLF firmware but subsequently deleted.

I will dig into this further to see if it could be fixed. It would be helpful if you could turn on logger tracing and let me know if there are any entries for GW_SET_NODE_VELOCITY_REQ…

1130

I found and fixed several things…

  1. The API does not support setting Scene velocity permanently in the bridge.
  2. But it accepts velocity as a one time argument when it executes a Scene.
  3. If the velocity parameter was changed via PaperUI, the new value was not saved. (Indeed changes to ANY parameter were not saved…)

Based on these findings I built yet another version of the JAR file HERE

Please cancel this request. No longer required! Thank you.

2 Likes
1131

Hi @AndrewFG,

tested around over about one week now: nothing to compain :slight_smile:
Windows and Blinds seem to work ok, restart of bridge connectivity as well.
The binding is seems to be on a good way.

Very good job :slight_smile:

1132

Many thanks Jens, for your support. I am working to solve one final issue, and when that is solved, I will ask for the Pull Request to be released.