2022-04-22 09:00:24.086 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:24.101 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:00:24.101 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:24.101 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:00:24.101 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:24.101 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:00:24.101 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:24.101 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:00:24.101 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:24.117 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:00:24.117 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:00:24.132 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:00:24.132 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:00:24.132 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:00:24.132 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:24.132 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:00:24.132 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] finished cycle 41.
2022-04-22 09:00:24.148 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:00:24.148 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:00:24.164 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:00:24.164 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 0
2022-04-22 09:00:24.164 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 messages ready to be read (> 0 means true).
2022-04-22 09:00:24.164 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are no messages waiting.
2022-04-22 09:00:24.164 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => no waiting messages => done 
2022-04-22 09:00:24.164 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:00:24.164 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2022-04-22 09:00:24.164 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => no updates
2022-04-22 09:00:24.179 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:00:34.194 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] starting cycle 42.
2022-04-22 09:00:34.194 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): processing of possible HSM messages.
2022-04-22 09:00:34.194 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] will process HouseStatus.
2022-04-22 09:00:34.194 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through all (child things and bridge) linked channels needing a refresh
2022-04-22 09:00:34.194 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2022-04-22 09:00:34.194 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:00:34.194 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:00:34.194 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:00:34.194 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning true, as item is to be refreshed, now.
2022-04-22 09:00:34.210 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): refreshing channel velux:rollershutter:192_168_178_231:Hobbykamer:position.
2022-04-22 09:00:34.225 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-thingHandler-21,5,main]): command REFRESH on channel velux:rollershutter:192_168_178_231:Hobbykamer:position will be scheduled.
2022-04-22 09:00:34.225 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommand(velux:rollershutter:192_168_178_231:Hobbykamer:position,REFRESH) called.
2022-04-22 09:00:34.225 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-thingHandler-21,5,main]) done.
2022-04-22 09:00:34.225 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:00:34.225 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2022-04-22 09:00:34.225 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning true, as item is to be refreshed, now.
2022-04-22 09:00:34.225 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): refreshing channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition.
2022-04-22 09:00:34.225 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-thingHandler-21,5,main]): command REFRESH on channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition will be scheduled.
2022-04-22 09:00:34.241 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommand(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,REFRESH) called.
2022-04-22 09:00:34.257 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-thingHandler-21,5,main]) done.
2022-04-22 09:00:34.257 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through properties needing a refresh
2022-04-22 09:00:34.257 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:34.257 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2022-04-22 09:00:34.257 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/address, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2022-04-22 09:00:34.257 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2022-04-22 09:00:34.272 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.272 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:34.288 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,address) returns enum velux:klf200/address.
2022-04-22 09:00:34.288 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.288 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2022-04-22 09:00:34.288 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.288 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2022-04-22 09:00:34.288 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.288 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2022-04-22 09:00:34.303 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.303 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:00:34.303 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.319 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:00:34.319 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.319 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:00:34.319 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:00:34.319 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:00:34.319 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:00:34.319 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:00:34.335 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:00:34.335 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:00:34.335 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.335 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:00:34.350 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:00:34.350 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.350 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:00:34.350 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:34.350 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] finished cycle 42.
2022-04-22 09:00:34.366 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:00:34.366 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 0
2022-04-22 09:00:34.381 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 messages ready to be read (> 0 means true).
2022-04-22 09:00:34.381 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are no messages waiting.
2022-04-22 09:00:34.381 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => no waiting messages => done 
2022-04-22 09:00:34.381 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:00:34.381 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2022-04-22 09:00:34.381 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => no updates
2022-04-22 09:00:34.381 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:00:34.381 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]): command REFRESH on channel velux:rollershutter:192_168_178_231:Hobbykamer:position.
2022-04-22 09:00:34.413 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:192_168_178_231:Hobbykamer:position,REFRESH) called.
2022-04-22 09:00:34.413 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:00:34.413 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
2022-04-22 09:00:34.413 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): no existing products with changed parameters.
2022-04-22 09:00:34.413 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): work on refresh.
2022-04-22 09:00:34.413 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): refreshing item velux:rollershutter:192_168_178_231:Hobbykamer:position (type velux:rollershutter/position).
2022-04-22 09:00:34.413 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleRefresh(velux:rollershutter:192_168_178_231:Hobbykamer:position,position,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@bfd0) called.
2022-04-22 09:00:34.413 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 7.
2022-04-22 09:00:34.428 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): there are some existing products.
2022-04-22 09:00:34.444 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:00:34.444 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setProductId(6) called.
2022-04-22 09:00:34.444 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Product) called.
2022-04-22 09:00:34.444 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:34.444 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Product,authenticated) called.
2022-04-22 09:00:34.444 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:34.460 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve Product, authenticated) called.
2022-04-22 09:00:34.460 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve Product', authenticated
2022-04-22 09:00:34.475 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - getRequestCommand() returns GW_GET_NODE_INFORMATION_REQ (0x200).
2022-04-22 09:00:34.475 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getRequestDataAsArrayOfBytes() returns data for retrieving node with id 6.
2022-04-22 09:00:34.475 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:00:34.475 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => send mode => preparing command 
2022-04-22 09:00:34.475 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x200 with data size 1 called.
2022-04-22 09:00:34.475 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 04 02 00 06 00.
2022-04-22 09:00:34.475 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 6 called.
2022-04-22 09:00:34.475 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 04 02 00 06 00 C0.
2022-04-22 09:00:34.491 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => command ready => start sending 
2022-04-22 09:00:34.491 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_REQ => sending data => 06
2022-04-22 09:00:34.506 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:00:34.506 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 8 bytes: C0 00 04 02 00 06 00 C0
2022-04-22 09:00:34.506 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 8 bytes.
2022-04-22 09:00:34.506 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 8 bytes: C0 00 04 02 00 06 00 C0 
2022-04-22 09:00:34.522 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:00:34.522 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:00:34.772 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:00:34.772 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 9 bytes: C0 00 05 02 01 00 06 00 C0 
2022-04-22 09:00:34.772 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 9 bytes: C0 00 05 02 01 00 06 00 C0
2022-04-22 09:00:34.772 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:00:34.788 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 9 called.
2022-04-22 09:00:34.788 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 05 02 01 00 06 00.
2022-04-22 09:00:34.788 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 7.
2022-04-22 09:00:34.788 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x201 .
2022-04-22 09:00:34.788 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 00 06.
2022-04-22 09:00:34.788 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x201 and data 00 06.
2022-04-22 09:00:34.788 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x201 .
2022-04-22 09:00:34.804 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 00 06.
2022-04-22 09:00:34.819 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => received data => 00 06
2022-04-22 09:00:34.819 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => applying data length => 2
2022-04-22 09:00:34.819 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_CFM with 2 bytes of data) called.
2022-04-22 09:00:34.819 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_CFM (0x201).
2022-04-22 09:00:34.819 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_CFM (0x201) with 2 bytes of data.
2022-04-22 09:00:34.819 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2022-04-22 09:00:34.835 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): returned status: OK - Request accepted.
2022-04-22 09:00:34.850 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 6 and responseNodeID 6.
2022-04-22 09:00:34.850 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for request NodeID 6 and response NodeID 6.
2022-04-22 09:00:34.850 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2022-04-22 09:00:34.850 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=false,success=false.
2022-04-22 09:00:34.850 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:00:34.850 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:00:34.866 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:00:34.866 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:00:34.882 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 131 bytes: C0 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 26 C0 
2022-04-22 09:00:34.882 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 131 bytes: C0 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 26 C0
2022-04-22 09:00:34.882 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:00:34.882 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 131 called.
2022-04-22 09:00:34.897 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 26.
2022-04-22 09:00:34.913 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 129.
2022-04-22 09:00:34.913 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x210 .
2022-04-22 09:00:34.913 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 124 bytes: 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:00:34.913 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x210 and data 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:00:34.944 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x210 .
2022-04-22 09:00:34.944 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 124 bytes: 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:00:34.944 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data => 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1D 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-04-22 09:00:34.960 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => applying data length => 124
2022-04-22 09:00:34.960 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_NTF with 124 bytes of data) called.
2022-04-22 09:00:34.975 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_NTF (0x210).
2022-04-22 09:00:34.975 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_NTF (0x210) with 124 bytes of data.
2022-04-22 09:00:34.975 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2022-04-22 09:00:34.975 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeID=6.
2022-04-22 09:00:34.975 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfOrder=6.
2022-04-22 09:00:34.975 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPlacement=0.
2022-04-22 09:00:34.991 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfName=Hobbykamer.
2022-04-22 09:00:35.007 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfVelocity=1.
2022-04-22 09:00:35.007 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeTypeSubType=1088 (SLIDER_SHUTTER).
2022-04-22 09:00:35.007 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): derived product description=Exterior Venetian blind.
2022-04-22 09:00:35.007 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductGroup=0.
2022-04-22 09:00:35.007 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductType=0.
2022-04-22 09:00:35.007 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeVariation=0.
2022-04-22 09:00:35.007 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPowerMode=0.
2022-04-22 09:00:35.007 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfBuildNumber=0.
2022-04-22 09:00:35.022 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfSerialNumber=[0, 0, 0, 0, 0, 0, 0, 0].
2022-04-22 09:00:35.022 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfState=5.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTarget=51200.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter1=63487.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter2=63487.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter3=33713.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter4=63487.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfRemainingTime=20224.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTimeStamp=1325419805.
2022-04-22 09:00:35.038 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNbrOfAlias=0.
2022-04-22 09:00:35.054 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasOne=0.
2022-04-22 09:00:35.069 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasTwo=0.
2022-04-22 09:00:35.069 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasThree=0.
2022-04-22 09:00:35.069 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFour=0.
2022-04-22 09:00:35.069 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFive=0.
2022-04-22 09:00:35.069 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 6 and responseNodeID 6.
2022-04-22 09:00:35.069 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for request NodeID 6 and response NodeID 6.
2022-04-22 09:00:35.069 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2022-04-22 09:00:35.069 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): device provided invalid serial number, using name 'Hobbykamer' instead.
2022-04-22 09:00:35.100 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2,name=Hobbykamer) created.
2022-04-22 09:00:35.100 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=true,success=true.
2022-04-22 09:00:35.100 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => finished => success
2022-04-22 09:00:35.100 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getProduct(): returning product Product "Hobbykamer" / SLIDER_SHUTTER (bridgeIndex=6,serial=Hobbykamer,position=C800).
2022-04-22 09:00:35.100 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(constructur with 51200 as veluxPosition) called.
2022-04-22 09:00:35.100 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition() created with percent-type 100.
2022-04-22 09:00:35.100 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): position of actuator is 100%.
2022-04-22 09:00:35.116 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh() returns 100.
2022-04-22 09:00:35.116 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): updating channel velux:rollershutter:192_168_178_231:Hobbykamer:position to 100.
2022-04-22 09:00:35.132 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionAttempt set to Fri Apr 22 09:00:34 CEST 2022.
2022-04-22 09:00:35.132 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionSuccess set to Fri Apr 22 09:00:34 CEST 2022.
2022-04-22 09:00:35.132 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]) done.
2022-04-22 09:00:35.132 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]): command REFRESH on channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition.
2022-04-22 09:00:35.132 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,REFRESH) called.
2022-04-22 09:00:35.132 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:00:35.132 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
2022-04-22 09:00:35.147 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): no existing products with changed parameters.
2022-04-22 09:00:35.163 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): work on refresh.
2022-04-22 09:00:35.163 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): refreshing item velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition (type velux:rollershutter/vanePosition).
2022-04-22 09:00:35.163 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleRefresh(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,vanePosition,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@bfd0) called.
2022-04-22 09:00:35.163 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 7.
2022-04-22 09:00:35.163 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): there are some existing products.
2022-04-22 09:00:35.163 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:00:35.179 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setProductId(6) called.
2022-04-22 09:00:35.179 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Product) called.
2022-04-22 09:00:35.194 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:35.194 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Product,authenticated) called.
2022-04-22 09:00:35.194 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:35.194 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve Product, authenticated) called.
2022-04-22 09:00:35.194 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve Product', authenticated
2022-04-22 09:00:35.194 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - getRequestCommand() returns GW_GET_NODE_INFORMATION_REQ (0x200).
2022-04-22 09:00:35.194 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getRequestDataAsArrayOfBytes() returns data for retrieving node with id 6.
2022-04-22 09:00:35.194 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:00:35.210 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => send mode => preparing command 
2022-04-22 09:00:35.210 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x200 with data size 1 called.
2022-04-22 09:00:35.225 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 04 02 00 06 00.
2022-04-22 09:00:35.225 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 6 called.
2022-04-22 09:00:35.225 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 04 02 00 06 00 C0.
2022-04-22 09:00:35.225 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => command ready => start sending 
2022-04-22 09:00:35.225 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_REQ => sending data => 06
2022-04-22 09:00:35.241 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:00:35.241 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 8 bytes: C0 00 04 02 00 06 00 C0
2022-04-22 09:00:35.257 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 8 bytes.
2022-04-22 09:00:35.257 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 8 bytes: C0 00 04 02 00 06 00 C0 
2022-04-22 09:00:35.257 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:00:35.257 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:00:35.413 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:00:35.413 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 9 bytes: C0 00 05 02 01 00 06 00 C0 
2022-04-22 09:00:35.413 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 9 bytes: C0 00 05 02 01 00 06 00 C0
2022-04-22 09:00:35.413 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:00:35.429 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 9 called.
2022-04-22 09:00:35.429 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 05 02 01 00 06 00.
2022-04-22 09:00:35.429 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 7.
2022-04-22 09:00:35.429 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x201 .
2022-04-22 09:00:35.429 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 00 06.
2022-04-22 09:00:35.429 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x201 and data 00 06.
2022-04-22 09:00:35.429 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x201 .
2022-04-22 09:00:35.429 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 00 06.
2022-04-22 09:00:35.444 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => received data => 00 06
2022-04-22 09:00:35.460 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => applying data length => 2
2022-04-22 09:00:35.460 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_CFM with 2 bytes of data) called.
2022-04-22 09:00:35.460 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_CFM (0x201).
2022-04-22 09:00:35.460 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_CFM (0x201) with 2 bytes of data.
2022-04-22 09:00:35.460 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2022-04-22 09:00:35.475 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): returned status: OK - Request accepted.
2022-04-22 09:00:35.491 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 6 and responseNodeID 6.
2022-04-22 09:00:35.491 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for request NodeID 6 and response NodeID 6.
2022-04-22 09:00:35.491 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2022-04-22 09:00:35.491 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=false,success=false.
2022-04-22 09:00:35.491 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:00:35.491 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:00:35.491 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:00:35.491 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:00:35.507 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 131 bytes: C0 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 25 C0 
2022-04-22 09:00:35.522 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 131 bytes: C0 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 25 C0
2022-04-22 09:00:35.522 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:00:35.522 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 131 called.
2022-04-22 09:00:35.538 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 25.
2022-04-22 09:00:35.554 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 129.
2022-04-22 09:00:35.554 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x210 .
2022-04-22 09:00:35.554 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 124 bytes: 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:00:35.554 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x210 and data 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:00:35.585 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x210 .
2022-04-22 09:00:35.585 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 124 bytes: 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:00:35.585 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data => 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4F 00 4D 1E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-04-22 09:00:35.585 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => applying data length => 124
2022-04-22 09:00:35.616 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_NTF with 124 bytes of data) called.
2022-04-22 09:00:35.616 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_NTF (0x210).
2022-04-22 09:00:35.616 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_NTF (0x210) with 124 bytes of data.
2022-04-22 09:00:35.616 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2022-04-22 09:00:35.616 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeID=6.
2022-04-22 09:00:35.616 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfOrder=6.
2022-04-22 09:00:35.616 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPlacement=0.
2022-04-22 09:00:35.616 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfName=Hobbykamer.
2022-04-22 09:00:35.616 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfVelocity=1.
2022-04-22 09:00:35.632 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeTypeSubType=1088 (SLIDER_SHUTTER).
2022-04-22 09:00:35.632 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): derived product description=Exterior Venetian blind.
2022-04-22 09:00:35.647 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductGroup=0.
2022-04-22 09:00:35.647 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductType=0.
2022-04-22 09:00:35.647 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeVariation=0.
2022-04-22 09:00:35.647 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPowerMode=0.
2022-04-22 09:00:35.647 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfBuildNumber=0.
2022-04-22 09:00:35.647 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfSerialNumber=[0, 0, 0, 0, 0, 0, 0, 0].
2022-04-22 09:00:35.663 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfState=5.
2022-04-22 09:00:35.663 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:00:35.679 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTarget=51200.
2022-04-22 09:00:35.679 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter1=63487.
2022-04-22 09:00:35.679 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter2=63487.
2022-04-22 09:00:35.679 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter3=33713.
2022-04-22 09:00:35.679 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter4=63487.
2022-04-22 09:00:35.679 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfRemainingTime=20224.
2022-04-22 09:00:35.694 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTimeStamp=1325419806.
2022-04-22 09:00:35.710 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNbrOfAlias=0.
2022-04-22 09:00:35.710 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasOne=0.
2022-04-22 09:00:35.710 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasTwo=0.
2022-04-22 09:00:35.710 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasThree=0.
2022-04-22 09:00:35.710 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFour=0.
2022-04-22 09:00:35.710 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFive=0.
2022-04-22 09:00:35.710 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 6 and responseNodeID 6.
2022-04-22 09:00:35.710 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for request NodeID 6 and response NodeID 6.
2022-04-22 09:00:35.725 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2022-04-22 09:00:35.741 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): device provided invalid serial number, using name 'Hobbykamer' instead.
2022-04-22 09:00:35.741 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2,name=Hobbykamer) created.
2022-04-22 09:00:35.741 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=true,success=true.
2022-04-22 09:00:35.741 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => finished => success
2022-04-22 09:00:35.741 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getProduct(): returning product Product "Hobbykamer" / SLIDER_SHUTTER (bridgeIndex=6,serial=Hobbykamer,position=C800).
2022-04-22 09:00:35.741 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(constructur with 33713 as veluxPosition) called.
2022-04-22 09:00:35.741 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition() created with percent-type 66.
2022-04-22 09:00:35.741 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): position of vane is 66%.
2022-04-22 09:00:35.757 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh() returns 66.
2022-04-22 09:00:35.757 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): updating channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition to 66.
2022-04-22 09:00:35.772 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionAttempt set to Fri Apr 22 09:00:35 CEST 2022.
2022-04-22 09:00:35.788 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionSuccess set to Fri Apr 22 09:00:35 CEST 2022.
2022-04-22 09:00:35.804 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]) done.
2022-04-22 09:00:44.366 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] starting cycle 43.
2022-04-22 09:00:44.366 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): processing of possible HSM messages.
2022-04-22 09:00:44.366 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] will process HouseStatus.
2022-04-22 09:00:44.366 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through all (child things and bridge) linked channels needing a refresh
2022-04-22 09:00:44.366 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2022-04-22 09:00:44.366 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:00:44.366 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2022-04-22 09:00:44.366 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:00:44.366 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:00:44.382 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:44.397 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2022-04-22 09:00:44.397 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:44.397 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:00:44.397 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:00:44.397 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:00:44.397 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:00:44.397 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.397 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:00:44.413 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.429 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through properties needing a refresh
2022-04-22 09:00:44.429 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/address, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2022-04-22 09:00:44.429 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2022-04-22 09:00:44.429 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:00:44.429 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:00:44.429 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:00:44.444 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.460 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,address) returns enum velux:klf200/address.
2022-04-22 09:00:44.460 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.460 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2022-04-22 09:00:44.460 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.460 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2022-04-22 09:00:44.460 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.460 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2022-04-22 09:00:44.460 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.475 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:00:44.475 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:00:44.491 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 0
2022-04-22 09:00:44.491 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 messages ready to be read (> 0 means true).
2022-04-22 09:00:44.491 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are no messages waiting.
2022-04-22 09:00:44.491 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => no waiting messages => done 
2022-04-22 09:00:44.491 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:00:44.491 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.491 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2022-04-22 09:00:44.491 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:00:44.507 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.507 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:00:44.522 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => no updates
2022-04-22 09:00:44.522 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:00:44.522 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.522 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:00:44.522 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.522 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:00:44.522 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:44.538 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] finished cycle 43.
2022-04-22 09:00:54.569 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] starting cycle 44.
2022-04-22 09:00:54.569 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): processing of possible HSM messages.
2022-04-22 09:00:54.569 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] will process HouseStatus.
2022-04-22 09:00:54.569 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through all (child things and bridge) linked channels needing a refresh
2022-04-22 09:00:54.569 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2022-04-22 09:00:54.569 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:00:54.569 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2022-04-22 09:00:54.569 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:54.569 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:00:54.585 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:00:54.585 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2022-04-22 09:00:54.600 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.600 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:00:54.600 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:54.600 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:00:54.600 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:00:54.600 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:00:54.600 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:00:54.616 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:00:54.616 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.632 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through properties needing a refresh
2022-04-22 09:00:54.632 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/address, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2022-04-22 09:00:54.632 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2022-04-22 09:00:54.632 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:00:54.632 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:00:54.647 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:00:54.647 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 0
2022-04-22 09:00:54.663 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 messages ready to be read (> 0 means true).
2022-04-22 09:00:54.663 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are no messages waiting.
2022-04-22 09:00:54.663 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => no waiting messages => done 
2022-04-22 09:00:54.663 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:00:54.663 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2022-04-22 09:00:54.663 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => no updates
2022-04-22 09:00:54.663 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:00:54.678 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.694 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,address) returns enum velux:klf200/address.
2022-04-22 09:00:54.694 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.694 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2022-04-22 09:00:54.694 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.694 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2022-04-22 09:00:54.694 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.694 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2022-04-22 09:00:54.694 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.710 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:00:54.710 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.725 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:00:54.725 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.725 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:00:54.725 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.725 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:00:54.725 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.725 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:00:54.725 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:00:54.741 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] finished cycle 44.
2022-04-22 09:00:56.398 [TRACE] [.velux.internal.handler.VeluxHandler] - handleCommand(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,66) initiated by Thread[OH-safeCall-7,5,main].
2022-04-22 09:00:56.398 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-safeCall-7,5,main]): command 66 on channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition will be scheduled.
2022-04-22 09:00:56.398 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommand(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,66) called.
2022-04-22 09:00:56.398 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-safeCall-7,5,main]) done.
2022-04-22 09:00:56.398 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]): command 66 on channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition.
2022-04-22 09:00:56.413 [TRACE] [.velux.internal.handler.VeluxHandler] - handleCommand() done.
2022-04-22 09:00:56.413 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,66) called.
2022-04-22 09:00:56.429 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:00:56.429 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
2022-04-22 09:00:56.429 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): no existing products with changed parameters.
2022-04-22 09:00:56.429 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): working on item velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition (type velux:rollershutter/vanePosition) with COMMAND 66.
2022-04-22 09:00:56.429 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleCommand(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,vanePosition,66,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@bfd0) called.
2022-04-22 09:00:56.429 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 7.
2022-04-22 09:00:56.429 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): there are some existing products.
2022-04-22 09:00:56.429 [TRACE] [nternal.things.VeluxExistingProducts] - get(6) called.
2022-04-22 09:00:56.444 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): found vane position PercentType.66 command
2022-04-22 09:00:56.460 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(constructur with 51200 as veluxPosition) called.
2022-04-22 09:00:56.460 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition() created with percent-type 100.
2022-04-22 09:00:56.460 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(66 as PercentType) created.
2022-04-22 09:00:56.460 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleCommand(): sending command to set vane position to 33792.
2022-04-22 09:00:56.460 [TRACE] [.bridge.VeluxBridgeRunProductCommand] - sendCommand(nodeId=6,value=100) called.
2022-04-22 09:00:56.460 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:00:56.460 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setNodeIdAndParameters(6) called.
2022-04-22 09:00:56.476 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator) called.
2022-04-22 09:00:56.476 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:56.491 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator,authenticated) called.
2022-04-22 09:00:56.491 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:00:56.491 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Send Command to Actuator, authenticated) called.
2022-04-22 09:00:56.491 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Send Command to Actuator', authenticated
2022-04-22 09:00:56.491 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - getRequestCommand() returns 0x300.
2022-04-22 09:00:56.491 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): ntfSessionID=1292.
2022-04-22 09:00:56.491 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqCommandOriginator=8.
2022-04-22 09:00:56.507 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevel=5.
2022-04-22 09:00:56.507 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqParameterActive=0.
2022-04-22 09:00:56.523 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI1=32.
2022-04-22 09:00:56.523 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI2=0.
2022-04-22 09:00:56.523 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqMainParameter=51200.
2022-04-22 09:00:56.523 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFunctionalParameter1=63487.
2022-04-22 09:00:56.523 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFunctionalParameter2=63487.
2022-04-22 09:00:56.523 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFunctionalParameter3=33792.
2022-04-22 09:00:56.538 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFunctionalParameter4=63487.
2022-04-22 09:00:56.538 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArrayCount=1.
2022-04-22 09:00:56.554 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArray01=6.
2022-04-22 09:00:56.554 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevelLock=0.
2022-04-22 09:00:56.554 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL03=0.
2022-04-22 09:00:56.554 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL47=0.
2022-04-22 09:00:56.554 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqLockTime=0.
2022-04-22 09:00:56.569 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes() data is 05 0C 08 05 00 20 00 C8 00 00 00 00 00 84 00 00 00 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 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:00:56.569 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:00:56.585 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => send mode => preparing command 
2022-04-22 09:00:56.585 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x300 with data size 66 called.
2022-04-22 09:00:56.585 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 45 03 00 05 0C 08 05 00 20 00 C8 00 00 00 00 00 84 00 00 00 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 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 29.
2022-04-22 09:00:56.585 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 71 called.
2022-04-22 09:00:56.585 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 45 03 00 05 0C 08 05 00 20 00 C8 00 00 00 00 00 84 00 00 00 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 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 29 C0.
2022-04-22 09:00:56.601 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => command ready => start sending 
2022-04-22 09:00:56.616 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_REQ => sending data => 05 0C 08 05 00 20 00 C8 00 00 00 00 00 84 00 00 00 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 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-04-22 09:00:56.616 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:00:56.616 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 73 bytes: C0 00 45 03 00 05 0C 08 05 00 20 00 C8 00 00 00 00 00 84 00 00 00 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 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 29 C0
2022-04-22 09:00:56.616 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 73 bytes.
2022-04-22 09:00:56.632 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 73 bytes: C0 00 45 03 00 05 0C 08 05 00 20 00 C8 00 00 00 00 00 84 00 00 00 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 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 29 C0 
2022-04-22 09:00:56.648 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:00:56.648 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:00:56.835 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:00:56.835 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 10 bytes: C0 00 06 03 01 05 0C 01 0C C0 
2022-04-22 09:00:56.835 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 10 bytes: C0 00 06 03 01 05 0C 01 0C C0
2022-04-22 09:00:56.835 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:00:56.851 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 10 called.
2022-04-22 09:00:56.851 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 06 03 01 05 0C 01 0C.
2022-04-22 09:00:56.851 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 8.
2022-04-22 09:00:56.851 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2022-04-22 09:00:56.851 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 05 0C 01.
2022-04-22 09:00:56.851 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x301 and data 05 0C 01.
2022-04-22 09:00:56.851 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2022-04-22 09:00:56.851 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 05 0C 01.
2022-04-22 09:00:56.866 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => received data => 05 0C 01
2022-04-22 09:00:56.882 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => applying data length => 3
2022-04-22 09:00:56.882 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(GW_COMMAND_SEND_CFM with 3 bytes of data) called.
2022-04-22 09:00:56.882 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): handling response GW_COMMAND_SEND_CFM (0x301).
2022-04-22 09:00:56.882 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() called for GW_COMMAND_SEND_CFM (0x301) with 3 bytes of data.
2022-04-22 09:00:56.882 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() returns true.
2022-04-22 09:00:56.898 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): returned status: OK - Command is accepted.
2022-04-22 09:00:56.898 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingSessionID() called for requestNodeID 1292 and responseNodeID 1292.
2022-04-22 09:00:56.898 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() called for request SessionID 1292 and response SessionID 1292.
2022-04-22 09:00:56.913 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() returns true.
2022-04-22 09:00:56.913 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): skipping wait for more packets as sequential processing is not enforced.
2022-04-22 09:00:56.913 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): finished=true,success=true.
2022-04-22 09:00:56.913 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => finished => success
2022-04-22 09:00:56.913 [DEBUG] [.bridge.VeluxBridgeRunProductCommand] - sendCommand() finished successfully.
2022-04-22 09:00:56.913 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): store vane position to cache.
2022-04-22 09:00:56.913 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): vane position will be updated via polling.
2022-04-22 09:00:56.913 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 7.
2022-04-22 09:00:56.913 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleCommand(): position of actuators will be updated.
2022-04-22 09:00:56.944 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionAttempt set to Fri Apr 22 09:00:56 CEST 2022.
2022-04-22 09:00:56.944 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionSuccess set to Fri Apr 22 09:00:56 CEST 2022.
2022-04-22 09:00:56.944 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]) done.
2022-04-22 09:01:04.771 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] starting cycle 45.
2022-04-22 09:01:04.771 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): processing of possible HSM messages.
2022-04-22 09:01:04.771 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] will process HouseStatus.
2022-04-22 09:01:04.771 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through all (child things and bridge) linked channels needing a refresh
2022-04-22 09:01:04.771 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2022-04-22 09:01:04.771 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:01:04.771 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:04.771 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2022-04-22 09:01:04.771 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:01:04.787 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.787 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:01:04.803 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.803 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:04.803 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2022-04-22 09:01:04.803 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:04.803 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:01:04.803 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:01:04.803 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through properties needing a refresh
2022-04-22 09:01:04.818 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/address, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2022-04-22 09:01:04.834 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2022-04-22 09:01:04.834 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.834 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,address) returns enum velux:klf200/address.
2022-04-22 09:01:04.834 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:01:04.834 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:01:04.834 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:01:04.849 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:01:04.849 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:01:04.865 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:01:04.865 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 8
2022-04-22 09:01:04.865 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 8 messages ready to be read (> 0 means true).
2022-04-22 09:01:04.865 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are messages waiting.
2022-04-22 09:01:04.865 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => message(s) waiting => start reading 
2022-04-22 09:01:04.865 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:04.865 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:04.865 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.881 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2022-04-22 09:01:04.896 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.896 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2022-04-22 09:01:04.896 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.896 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:04.896 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:04.896 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2022-04-22 09:01:04.896 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.896 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:01:04.912 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 33 00 00 44 C0 
2022-04-22 09:01:04.928 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.928 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:01:04.928 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.928 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:01:04.928 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.928 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 33 00 00 44 C0
2022-04-22 09:01:04.928 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:01:04.943 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:04.943 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:04.943 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 33 00 00 44.
2022-04-22 09:01:04.959 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:04.959 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:04.959 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.959 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 33 00 00.
2022-04-22 09:01:04.959 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:01:04.974 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:04.974 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] finished cycle 45.
2022-04-22 09:01:04.974 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 33 00 00.
2022-04-22 09:01:04.990 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:04.990 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 33 00 00.
2022-04-22 09:01:04.990 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 33 00 00
2022-04-22 09:01:05.006 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:05.021 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:05.021 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:05.021 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:05.021 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:05.021 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=6.
2022-04-22 09:01:05.021 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=2.
2022-04-22 09:01:05.021 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:01:05.021 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=51200.
2022-04-22 09:01:05.021 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:05.037 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:05.053 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=33713.
2022-04-22 09:01:05.053 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:05.053 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:05.053 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1295187968.
2022-04-22 09:01:05.053 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:05.053 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=6,productState=2,productPosition=51200,productTarget=51200) called.
2022-04-22 09:01:05.053 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 6) returns true.
2022-04-22 09:01:05.053 [TRACE] [nternal.things.VeluxExistingProducts] - get(6) called.
2022-04-22 09:01:05.068 [TRACE] [g.velux.internal.things.VeluxProduct] - setState(name=Hobbykamer,index=6) state 5 replaced by 2.
2022-04-22 09:01:05.084 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Hobbykamer.
2022-04-22 09:01:05.084 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:05.084 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:05.084 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:05.084 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:05.084 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:05.099 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:05.099 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:05.115 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 34 00 00 43 C0 
2022-04-22 09:01:05.115 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 34 00 00 43 C0
2022-04-22 09:01:05.115 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:05.115 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:05.115 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 34 00 00 43.
2022-04-22 09:01:05.115 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:05.115 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:05.115 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 34 00 00.
2022-04-22 09:01:05.131 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 34 00 00.
2022-04-22 09:01:05.146 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:05.146 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 34 00 00.
2022-04-22 09:01:05.146 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 06 02 C8 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 4D 34 00 00
2022-04-22 09:01:05.146 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:05.146 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:05.162 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:05.178 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:05.178 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:05.178 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=6.
2022-04-22 09:01:05.178 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=2.
2022-04-22 09:01:05.178 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:01:05.178 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=51200.
2022-04-22 09:01:05.178 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:05.178 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:05.193 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=33713.
2022-04-22 09:01:05.193 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:05.209 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:05.209 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1295253504.
2022-04-22 09:01:05.209 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:05.209 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=6,productState=2,productPosition=51200,productTarget=51200) called.
2022-04-22 09:01:05.209 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 6) returns true.
2022-04-22 09:01:05.209 [TRACE] [nternal.things.VeluxExistingProducts] - get(6) called.
2022-04-22 09:01:05.209 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Hobbykamer.
2022-04-22 09:01:05.224 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:05.224 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:05.240 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:05.240 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:05.240 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:05.240 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:05.240 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:05.240 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 20 bytes: C0 00 10 03 02 05 0C 08 06 00 C8 00 02 01 06 80 04 00 5F C0 
2022-04-22 09:01:05.256 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 20 bytes: C0 00 10 03 02 05 0C 08 06 00 C8 00 02 01 06 80 04 00 5F C0
2022-04-22 09:01:05.256 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:05.271 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 20 called.
2022-04-22 09:01:05.271 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 10 03 02 05 0C 08 06 00 C8 00 02 01 06 80 04 00 5F.
2022-04-22 09:01:05.271 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 18.
2022-04-22 09:01:05.271 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2022-04-22 09:01:05.271 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 05 0C 08 06 00 C8 00 02 01 06 80 04 00.
2022-04-22 09:01:05.271 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x302 and data 05 0C 08 06 00 C8 00 02 01 06 80 04 00.
2022-04-22 09:01:05.271 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2022-04-22 09:01:05.287 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 05 0C 08 06 00 C8 00 02 01 06 80 04 00.
2022-04-22 09:01:05.303 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_RUN_STATUS_NTF => received data => 05 0C 08 06 00 C8 00 02 01 06 80 04 00
2022-04-22 09:01:05.303 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_RUN_STATUS_NTF => parallelism allowed => continuing
2022-04-22 09:01:05.303 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:05.303 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:05.303 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:05.303 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:05.303 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 13 bytes: C0 00 09 03 03 05 0C 06 00 00 00 06 C0 
2022-04-22 09:01:05.318 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 13 bytes: C0 00 09 03 03 05 0C 06 00 00 00 06 C0
2022-04-22 09:01:05.334 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:05.334 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 13 called.
2022-04-22 09:01:05.334 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 09 03 03 05 0C 06 00 00 00 06.
2022-04-22 09:01:05.334 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 11.
2022-04-22 09:01:05.334 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x303 .
2022-04-22 09:01:05.334 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 6 bytes: 05 0C 06 00 00 00.
2022-04-22 09:01:05.334 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x303 and data 05 0C 06 00 00 00.
2022-04-22 09:01:05.349 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x303 .
2022-04-22 09:01:05.349 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 6 bytes: 05 0C 06 00 00 00.
2022-04-22 09:01:05.365 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_REMAINING_TIME_NTF => received data => 05 0C 06 00 00 00
2022-04-22 09:01:05.365 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_REMAINING_TIME_NTF => parallelism allowed => continuing
2022-04-22 09:01:05.365 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:05.365 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:05.365 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:05.365 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:05.365 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 20 bytes: C0 00 10 03 02 05 0C 08 06 00 C8 00 00 01 20 00 05 00 FA C0 
2022-04-22 09:01:05.365 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 20 bytes: C0 00 10 03 02 05 0C 08 06 00 C8 00 00 01 20 00 05 00 FA C0
2022-04-22 09:01:05.381 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:05.396 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 20 called.
2022-04-22 09:01:05.396 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 10 03 02 05 0C 08 06 00 C8 00 00 01 20 00 05 00 FA.
2022-04-22 09:01:05.396 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 18.
2022-04-22 09:01:05.396 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2022-04-22 09:01:05.396 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 05 0C 08 06 00 C8 00 00 01 20 00 05 00.
2022-04-22 09:01:05.396 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x302 and data 05 0C 08 06 00 C8 00 00 01 20 00 05 00.
2022-04-22 09:01:05.412 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2022-04-22 09:01:05.412 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 05 0C 08 06 00 C8 00 00 01 20 00 05 00.
2022-04-22 09:01:05.412 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_RUN_STATUS_NTF => received data => 05 0C 08 06 00 C8 00 00 01 20 00 05 00
2022-04-22 09:01:05.428 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_COMMAND_RUN_STATUS_NTF => parallelism allowed => continuing
2022-04-22 09:01:05.428 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:05.428 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:05.428 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:05.428 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:05.428 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 9 bytes: C0 00 05 03 04 05 0C 0B C0 
2022-04-22 09:01:05.428 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 9 bytes: C0 00 05 03 04 05 0C 0B C0
2022-04-22 09:01:05.428 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:05.443 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 9 called.
2022-04-22 09:01:05.459 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 05 03 04 05 0C 0B.
2022-04-22 09:01:05.459 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 7.
2022-04-22 09:01:05.459 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x304 .
2022-04-22 09:01:05.459 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 05 0C.
2022-04-22 09:01:05.459 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x304 and data 05 0C.
2022-04-22 09:01:05.474 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x304 .
2022-04-22 09:01:05.474 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 05 0C.
2022-04-22 09:01:05.490 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_SESSION_FINISHED_NTF => received data => 05 0C
2022-04-22 09:01:05.490 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_SESSION_FINISHED_NTF => parallelism allowed => continuing
2022-04-22 09:01:05.490 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:05.490 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:05.490 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:05.490 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:05.490 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 35 00 00 14 C0 
2022-04-22 09:01:05.490 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 35 00 00 14 C0
2022-04-22 09:01:05.521 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:05.521 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:05.521 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 35 00 00 14.
2022-04-22 09:01:05.521 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:05.521 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:05.521 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 35 00 00.
2022-04-22 09:01:05.521 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 35 00 00.
2022-04-22 09:01:05.521 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:05.537 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 35 00 00.
2022-04-22 09:01:05.553 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 35 00 00
2022-04-22 09:01:05.553 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:05.553 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:05.553 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:05.553 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:05.568 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:05.568 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=6.
2022-04-22 09:01:05.568 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=5.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=51200.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=10825.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1295319040.
2022-04-22 09:01:05.584 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:05.599 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=6,productState=5,productPosition=51200,productTarget=51200) called.
2022-04-22 09:01:05.615 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 6) returns true.
2022-04-22 09:01:05.615 [TRACE] [nternal.things.VeluxExistingProducts] - get(6) called.
2022-04-22 09:01:05.615 [TRACE] [g.velux.internal.things.VeluxProduct] - setState(name=Hobbykamer,index=6) state 2 replaced by 5.
2022-04-22 09:01:05.615 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Hobbykamer.
2022-04-22 09:01:05.615 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:05.615 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:05.631 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:05.646 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:05.646 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:05.646 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:05.646 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:05.646 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 38 00 00 19 C0 
2022-04-22 09:01:05.646 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 38 00 00 19 C0
2022-04-22 09:01:05.646 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:05.662 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:05.678 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 38 00 00 19.
2022-04-22 09:01:05.678 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:05.678 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:05.678 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 38 00 00.
2022-04-22 09:01:05.678 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 38 00 00.
2022-04-22 09:01:05.678 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:05.678 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 38 00 00.
2022-04-22 09:01:05.678 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 38 00 00
2022-04-22 09:01:05.709 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:05.709 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:05.709 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:05.709 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:05.709 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:05.709 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=6.
2022-04-22 09:01:05.724 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=5.
2022-04-22 09:01:05.724 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:01:05.740 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=51200.
2022-04-22 09:01:05.740 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:05.740 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:05.740 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=10825.
2022-04-22 09:01:05.740 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:05.740 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:05.740 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1295515648.
2022-04-22 09:01:05.740 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:05.756 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=6,productState=5,productPosition=51200,productTarget=51200) called.
2022-04-22 09:01:05.756 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 6) returns true.
2022-04-22 09:01:05.771 [TRACE] [nternal.things.VeluxExistingProducts] - get(6) called.
2022-04-22 09:01:05.771 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Hobbykamer.
2022-04-22 09:01:05.771 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:05.771 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:05.771 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:05.771 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:05.771 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:05.771 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:06.477 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:06.477 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 05 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3D 00 00 74 C0 
2022-04-22 09:01:06.477 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 05 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3D 00 00 74 C0
2022-04-22 09:01:06.477 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:06.492 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:06.492 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 05 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3D 00 00 74.
2022-04-22 09:01:06.492 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:06.492 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:06.492 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 05 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3D 00 00.
2022-04-22 09:01:06.492 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 05 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3D 00 00.
2022-04-22 09:01:06.492 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:06.508 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 05 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3D 00 00.
2022-04-22 09:01:06.523 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 05 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3D 00 00
2022-04-22 09:01:06.523 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:06.523 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:06.523 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:06.523 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:06.539 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:06.539 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=5.
2022-04-22 09:01:06.539 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=5.
2022-04-22 09:01:06.555 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=0.
2022-04-22 09:01:06.555 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=0.
2022-04-22 09:01:06.555 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:06.555 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:06.555 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=63487.
2022-04-22 09:01:06.555 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:06.555 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:06.555 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1295843328.
2022-04-22 09:01:06.570 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:06.570 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=5,productState=5,productPosition=0,productTarget=0) called.
2022-04-22 09:01:06.586 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 5) returns true.
2022-04-22 09:01:06.586 [TRACE] [nternal.things.VeluxExistingProducts] - get(5) called.
2022-04-22 09:01:06.586 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Terrasdeur.
2022-04-22 09:01:06.586 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:06.586 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:06.586 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:06.602 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:06.602 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:06.617 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:07.680 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:07.680 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 3E 00 00 1F C0 
2022-04-22 09:01:07.680 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 3E 00 00 1F C0
2022-04-22 09:01:07.680 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:07.696 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:07.696 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 3E 00 00 1F.
2022-04-22 09:01:07.696 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:07.696 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:07.696 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 3E 00 00.
2022-04-22 09:01:07.696 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 3E 00 00.
2022-04-22 09:01:07.696 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:07.711 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 3E 00 00.
2022-04-22 09:01:07.727 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 06 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4D 3E 00 00
2022-04-22 09:01:07.727 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:07.727 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:07.727 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:07.727 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:07.727 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:07.742 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=6.
2022-04-22 09:01:07.758 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=5.
2022-04-22 09:01:07.758 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:01:07.758 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=51200.
2022-04-22 09:01:07.758 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:07.758 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:07.758 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=10825.
2022-04-22 09:01:07.758 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:07.758 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:07.774 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1295908864.
2022-04-22 09:01:07.774 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:07.789 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=6,productState=5,productPosition=51200,productTarget=51200) called.
2022-04-22 09:01:07.789 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 6) returns true.
2022-04-22 09:01:07.789 [TRACE] [nternal.things.VeluxExistingProducts] - get(6) called.
2022-04-22 09:01:07.789 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Hobbykamer.
2022-04-22 09:01:07.789 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:07.789 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:07.789 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:07.789 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:07.805 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:07.821 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:08.947 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:08.947 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 01 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3F 00 00 72 C0 
2022-04-22 09:01:08.947 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 01 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3F 00 00 72 C0
2022-04-22 09:01:08.963 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:08.963 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:08.963 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 01 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3F 00 00 72.
2022-04-22 09:01:08.963 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:08.963 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:08.963 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 01 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3F 00 00.
2022-04-22 09:01:08.963 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 01 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3F 00 00.
2022-04-22 09:01:08.963 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:08.979 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 01 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3F 00 00.
2022-04-22 09:01:08.994 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 01 05 C8 00 C8 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 3F 00 00
2022-04-22 09:01:08.994 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:08.994 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:08.994 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:09.010 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:09.010 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:09.010 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=1.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=5.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=51200.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=63487.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:09.025 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1295974400.
2022-04-22 09:01:09.041 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:09.057 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=1,productState=5,productPosition=51200,productTarget=51200) called.
2022-04-22 09:01:09.057 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 1) returns true.
2022-04-22 09:01:09.057 [TRACE] [nternal.things.VeluxExistingProducts] - get(1) called.
2022-04-22 09:01:09.057 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Slaapkamer.
2022-04-22 09:01:09.057 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:09.072 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:09.088 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:09.088 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:09.088 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:09.088 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:10.901 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:10.901 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 00 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 41 00 00 0D C0 
2022-04-22 09:01:10.901 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 00 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 41 00 00 0D C0
2022-04-22 09:01:10.901 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:10.916 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:10.916 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 00 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 41 00 00 0D.
2022-04-22 09:01:10.916 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:10.916 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:10.916 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 00 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 41 00 00.
2022-04-22 09:01:10.916 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 00 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 41 00 00.
2022-04-22 09:01:10.916 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:10.932 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 00 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 41 00 00.
2022-04-22 09:01:10.948 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 00 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 41 00 00
2022-04-22 09:01:10.948 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:10.948 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:10.948 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:10.948 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:10.963 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:10.963 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=0.
2022-04-22 09:01:10.979 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=5.
2022-04-22 09:01:10.979 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=0.
2022-04-22 09:01:10.979 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=0.
2022-04-22 09:01:10.979 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:10.979 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:10.979 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=63487.
2022-04-22 09:01:10.995 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:10.995 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:10.995 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1296105472.
2022-04-22 09:01:11.010 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:11.010 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=0,productState=5,productPosition=0,productTarget=0) called.
2022-04-22 09:01:11.010 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 0) returns true.
2022-04-22 09:01:11.010 [TRACE] [nternal.things.VeluxExistingProducts] - get(0) called.
2022-04-22 09:01:11.010 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Terrasraam.
2022-04-22 09:01:11.010 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:11.010 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:11.010 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:11.026 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:11.026 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:11.041 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:11.479 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:11.479 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 03 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 42 00 00 0D C0 
2022-04-22 09:01:11.479 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 03 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 42 00 00 0D C0
2022-04-22 09:01:11.479 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:11.495 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:11.495 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 03 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 42 00 00 0D.
2022-04-22 09:01:11.495 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:11.495 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:11.495 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 03 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 42 00 00.
2022-04-22 09:01:11.495 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 03 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 42 00 00.
2022-04-22 09:01:11.495 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:11.495 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 03 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 42 00 00.
2022-04-22 09:01:11.526 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 03 05 00 00 00 00 F7 FF F7 FF F7 FF F7 FF 00 00 4D 42 00 00
2022-04-22 09:01:11.526 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:11.526 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:11.526 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:11.526 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:11.541 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:11.541 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=3.
2022-04-22 09:01:11.541 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=5.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=0.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=0.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=63487.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1296171008.
2022-04-22 09:01:11.557 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:11.573 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=3,productState=5,productPosition=0,productTarget=0) called.
2022-04-22 09:01:11.588 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 3) returns true.
2022-04-22 09:01:11.588 [TRACE] [nternal.things.VeluxExistingProducts] - get(3) called.
2022-04-22 09:01:11.588 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Werkkamer.
2022-04-22 09:01:11.588 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:11.588 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:11.604 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:11.604 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:11.620 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:11.620 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:12.307 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:12.307 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 04 05 F7 FF F7 FF F7 FF F7 FF F7 FF F7 FF 00 00 4D 43 00 00 0B C0 
2022-04-22 09:01:12.307 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 04 05 F7 FF F7 FF F7 FF F7 FF F7 FF F7 FF 00 00 4D 43 00 00 0B C0
2022-04-22 09:01:12.307 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:12.323 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2022-04-22 09:01:12.323 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 04 05 F7 FF F7 FF F7 FF F7 FF F7 FF F7 FF 00 00 4D 43 00 00 0B.
2022-04-22 09:01:12.323 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2022-04-22 09:01:12.323 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:12.323 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 04 05 F7 FF F7 FF F7 FF F7 FF F7 FF F7 FF 00 00 4D 43 00 00.
2022-04-22 09:01:12.323 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 04 05 F7 FF F7 FF F7 FF F7 FF F7 FF F7 FF 00 00 4D 43 00 00.
2022-04-22 09:01:12.338 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2022-04-22 09:01:12.354 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 04 05 F7 FF F7 FF F7 FF F7 FF F7 FF F7 FF 00 00 4D 43 00 00.
2022-04-22 09:01:12.354 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 04 05 F7 FF F7 FF F7 FF F7 FF F7 FF F7 FF 00 00 4D 43 00 00
2022-04-22 09:01:12.354 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2022-04-22 09:01:12.354 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2022-04-22 09:01:12.354 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2022-04-22 09:01:12.354 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2022-04-22 09:01:12.354 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2022-04-22 09:01:12.370 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=4.
2022-04-22 09:01:12.370 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=5.
2022-04-22 09:01:12.385 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=63487.
2022-04-22 09:01:12.385 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=63487.
2022-04-22 09:01:12.385 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter1=63487.
2022-04-22 09:01:12.385 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter2=63487.
2022-04-22 09:01:12.385 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter3=63487.
2022-04-22 09:01:12.385 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFuntionalParameter4=63487.
2022-04-22 09:01:12.385 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2022-04-22 09:01:12.401 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=1296236544.
2022-04-22 09:01:12.401 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2022-04-22 09:01:12.417 [DEBUG] [nternal.things.VeluxExistingProducts] - update(bridgeProductIndex=4,productState=5,productPosition=63487,productTarget=63487) called.
2022-04-22 09:01:12.417 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 4) returns true.
2022-04-22 09:01:12.417 [TRACE] [nternal.things.VeluxExistingProducts] - get(4) called.
2022-04-22 09:01:12.417 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Keukenraam.
2022-04-22 09:01:12.417 [TRACE] [nternal.things.VeluxExistingProducts] - update() successfully finished (dirty=true).
2022-04-22 09:01:12.417 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => product updated
2022-04-22 09:01:12.417 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2022-04-22 09:01:12.432 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:12.432 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:12.448 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:14.993 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] starting cycle 46.
2022-04-22 09:01:14.993 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): processing of possible HSM messages.
2022-04-22 09:01:14.993 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through all (child things and bridge) linked channels needing a refresh
2022-04-22 09:01:14.993 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:14.993 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:01:14.993 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:14.993 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:01:15.009 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.009 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through properties needing a refresh
2022-04-22 09:01:15.024 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/address, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2022-04-22 09:01:15.024 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2022-04-22 09:01:15.024 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.024 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,address) returns enum velux:klf200/address.
2022-04-22 09:01:15.024 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.024 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2022-04-22 09:01:15.024 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.040 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2022-04-22 09:01:15.056 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.056 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2022-04-22 09:01:15.056 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.056 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:01:15.056 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.056 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:01:15.071 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.087 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:01:15.087 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.087 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:01:15.087 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.087 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:01:15.087 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:15.087 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-21,5,main] finished cycle 46.
2022-04-22 09:01:16.321 [DEBUG] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => no slip message
2022-04-22 09:01:16.321 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 0 bytes: 
2022-04-22 09:01:16.321 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 0 bytes: 
2022-04-22 09:01:16.321 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:16.337 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:01:16.337 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished successfully.
2022-04-22 09:01:16.337 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => updates received => synchronizing
2022-04-22 09:01:16.337 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns true.
2022-04-22 09:01:16.337 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): there are some existing products with changed parameters.
2022-04-22 09:01:16.337 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): actuator Slaapkamer has changed values.
2022-04-22 09:01:16.337 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): bridge index is 1.
2022-04-22 09:01:16.337 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:16.368 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): actuator Keukenraam has changed values.
2022-04-22 09:01:16.368 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): bridge index is 4.
2022-04-22 09:01:16.368 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:16.368 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): actuator Hobbykamer has changed values.
2022-04-22 09:01:16.368 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): bridge index is 6.
2022-04-22 09:01:16.384 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:16.384 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): isInverted is false.
2022-04-22 09:01:16.399 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(constructur with 51200 as veluxPosition) called.
2022-04-22 09:01:16.399 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition() created with percent-type 100.
2022-04-22 09:01:16.399 [DEBUG] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): updating channel velux:rollershutter:192_168_178_231:Hobbykamer:position to position 100%.
2022-04-22 09:01:16.399 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): actuator Terrasraam has changed values.
2022-04-22 09:01:16.399 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): bridge index is 0.
2022-04-22 09:01:16.399 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:16.399 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): actuator Werkkamer has changed values.
2022-04-22 09:01:16.415 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): bridge index is 3.
2022-04-22 09:01:16.431 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:16.431 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): actuator Terrasdeur has changed values.
2022-04-22 09:01:16.431 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): bridge index is 5.
2022-04-22 09:01:16.431 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:16.431 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): resetting dirty flag.
2022-04-22 09:01:16.431 [TRACE] [nternal.things.VeluxExistingProducts] - resetDirtyFlag() called.
2022-04-22 09:01:16.431 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts() done.
2022-04-22 09:01:16.446 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:01:16.462 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] will process HouseStatus.
2022-04-22 09:01:16.462 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2022-04-22 09:01:16.462 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:01:16.462 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2022-04-22 09:01:16.462 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:16.462 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2022-04-22 09:01:16.462 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:16.478 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:01:16.493 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:01:16.493 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:01:16.493 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:01:16.493 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:01:16.493 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:01:16.493 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:01:16.493 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:01:16.493 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 0
2022-04-22 09:01:16.493 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 messages ready to be read (> 0 means true).
2022-04-22 09:01:16.509 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are no messages waiting.
2022-04-22 09:01:16.524 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => no waiting messages => done 
2022-04-22 09:01:16.524 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:01:16.524 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2022-04-22 09:01:16.524 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => no updates
2022-04-22 09:01:16.524 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:01:25.105 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-23,5,main] starting cycle 47.
2022-04-22 09:01:25.105 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): processing of possible HSM messages.
2022-04-22 09:01:25.105 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] will process HouseStatus.
2022-04-22 09:01:25.105 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through all (child things and bridge) linked channels needing a refresh
2022-04-22 09:01:25.105 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2022-04-22 09:01:25.105 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:01:25.105 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2022-04-22 09:01:25.105 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:25.105 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2022-04-22 09:01:25.121 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:25.121 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:01:25.136 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:25.136 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:01:25.136 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.136 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:01:25.136 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.136 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through properties needing a refresh
2022-04-22 09:01:25.136 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/address, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2022-04-22 09:01:25.152 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2022-04-22 09:01:25.168 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.168 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,address) returns enum velux:klf200/address.
2022-04-22 09:01:25.168 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:01:25.168 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:01:25.168 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:01:25.168 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:01:25.183 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:01:25.183 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:01:25.199 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:01:25.199 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.199 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2022-04-22 09:01:25.199 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.199 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 0
2022-04-22 09:01:25.199 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2022-04-22 09:01:25.215 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.215 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2022-04-22 09:01:25.230 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.230 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:01:25.230 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.230 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:01:25.230 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.230 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:01:25.230 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.230 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:01:25.246 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.246 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:01:25.261 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:25.261 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-23,5,main] finished cycle 47.
2022-04-22 09:01:25.261 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 messages ready to be read (> 0 means true).
2022-04-22 09:01:25.261 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are no messages waiting.
2022-04-22 09:01:25.261 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => no waiting messages => done 
2022-04-22 09:01:25.261 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:01:25.261 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2022-04-22 09:01:25.277 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => no updates
2022-04-22 09:01:25.293 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:01:35.269 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-23,5,main] starting cycle 48.
2022-04-22 09:01:35.269 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): processing of possible HSM messages.
2022-04-22 09:01:35.269 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] will process HouseStatus.
2022-04-22 09:01:35.269 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through all (child things and bridge) linked channels needing a refresh
2022-04-22 09:01:35.269 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2022-04-22 09:01:35.269 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:01:35.269 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2022-04-22 09:01:35.269 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:35.285 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2022-04-22 09:01:35.285 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:35.301 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:01:35.301 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:35.301 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:01:35.301 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning true, as item is to be refreshed, now.
2022-04-22 09:01:35.301 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): refreshing channel velux:rollershutter:192_168_178_231:Hobbykamer:position.
2022-04-22 09:01:35.301 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-thingHandler-23,5,main]): command REFRESH on channel velux:rollershutter:192_168_178_231:Hobbykamer:position will be scheduled.
2022-04-22 09:01:35.301 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommand(velux:rollershutter:192_168_178_231:Hobbykamer:position,REFRESH) called.
2022-04-22 09:01:35.301 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-thingHandler-23,5,main]) done.
2022-04-22 09:01:35.316 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:01:35.332 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning true, as item is to be refreshed, now.
2022-04-22 09:01:35.332 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): refreshing channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition.
2022-04-22 09:01:35.332 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-thingHandler-23,5,main]): command REFRESH on channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition will be scheduled.
2022-04-22 09:01:35.332 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommand(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,REFRESH) called.
2022-04-22 09:01:35.332 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommand(Thread[OH-thingHandler-23,5,main]) done.
2022-04-22 09:01:35.332 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through properties needing a refresh
2022-04-22 09:01:35.332 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:01:35.347 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:01:35.347 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/address, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2022-04-22 09:01:35.363 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:01:35.363 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:01:35.363 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:01:35.363 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:01:35.363 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:01:35.363 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 0
2022-04-22 09:01:35.379 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 messages ready to be read (> 0 means true).
2022-04-22 09:01:35.394 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2022-04-22 09:01:35.394 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are no messages waiting.
2022-04-22 09:01:35.394 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.394 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,address) returns enum velux:klf200/address.
2022-04-22 09:01:35.394 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => no waiting messages => done 
2022-04-22 09:01:35.394 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.394 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2022-04-22 09:01:35.394 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:01:35.394 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2022-04-22 09:01:35.410 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.426 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2022-04-22 09:01:35.426 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.426 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => no updates
2022-04-22 09:01:35.426 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2022-04-22 09:01:35.426 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.426 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:01:35.426 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:01:35.426 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.457 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:01:35.457 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.457 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:01:35.457 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.457 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:01:35.457 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.457 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:01:35.472 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:35.488 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-23,5,main] finished cycle 48.
2022-04-22 09:01:35.488 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]): command REFRESH on channel velux:rollershutter:192_168_178_231:Hobbykamer:position.
2022-04-22 09:01:35.488 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:192_168_178_231:Hobbykamer:position,REFRESH) called.
2022-04-22 09:01:35.488 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:01:35.488 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
2022-04-22 09:01:35.488 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): no existing products with changed parameters.
2022-04-22 09:01:35.488 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): work on refresh.
2022-04-22 09:01:35.504 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): refreshing item velux:rollershutter:192_168_178_231:Hobbykamer:position (type velux:rollershutter/position).
2022-04-22 09:01:35.519 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleRefresh(velux:rollershutter:192_168_178_231:Hobbykamer:position,position,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@bfd0) called.
2022-04-22 09:01:35.519 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 7.
2022-04-22 09:01:35.519 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): there are some existing products.
2022-04-22 09:01:35.519 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:01:35.519 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setProductId(6) called.
2022-04-22 09:01:35.519 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Product) called.
2022-04-22 09:01:35.519 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:35.519 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Product,authenticated) called.
2022-04-22 09:01:35.519 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:35.535 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve Product, authenticated) called.
2022-04-22 09:01:35.551 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve Product', authenticated
2022-04-22 09:01:35.551 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - getRequestCommand() returns GW_GET_NODE_INFORMATION_REQ (0x200).
2022-04-22 09:01:35.551 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getRequestDataAsArrayOfBytes() returns data for retrieving node with id 6.
2022-04-22 09:01:35.551 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:01:35.551 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => send mode => preparing command 
2022-04-22 09:01:35.551 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x200 with data size 1 called.
2022-04-22 09:01:35.551 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 04 02 00 06 00.
2022-04-22 09:01:35.551 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 6 called.
2022-04-22 09:01:35.551 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 04 02 00 06 00 C0.
2022-04-22 09:01:35.551 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => command ready => start sending 
2022-04-22 09:01:35.566 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_REQ => sending data => 06
2022-04-22 09:01:35.582 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:35.582 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 8 bytes: C0 00 04 02 00 06 00 C0
2022-04-22 09:01:35.582 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 8 bytes.
2022-04-22 09:01:35.582 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 8 bytes: C0 00 04 02 00 06 00 C0 
2022-04-22 09:01:35.582 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:35.582 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:35.644 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:35.644 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 9 bytes: C0 00 05 02 01 00 06 00 C0 
2022-04-22 09:01:35.644 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 9 bytes: C0 00 05 02 01 00 06 00 C0
2022-04-22 09:01:35.644 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:35.644 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 9 called.
2022-04-22 09:01:35.644 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 05 02 01 00 06 00.
2022-04-22 09:01:35.644 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 7.
2022-04-22 09:01:35.660 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x201 .
2022-04-22 09:01:35.660 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 00 06.
2022-04-22 09:01:35.660 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x201 and data 00 06.
2022-04-22 09:01:35.660 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x201 .
2022-04-22 09:01:35.660 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 00 06.
2022-04-22 09:01:35.660 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => received data => 00 06
2022-04-22 09:01:35.660 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => applying data length => 2
2022-04-22 09:01:35.660 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_CFM with 2 bytes of data) called.
2022-04-22 09:01:35.660 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_CFM (0x201).
2022-04-22 09:01:35.660 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_CFM (0x201) with 2 bytes of data.
2022-04-22 09:01:35.660 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2022-04-22 09:01:35.660 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): returned status: OK - Request accepted.
2022-04-22 09:01:35.676 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 6 and responseNodeID 6.
2022-04-22 09:01:35.691 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for request NodeID 6 and response NodeID 6.
2022-04-22 09:01:35.691 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2022-04-22 09:01:35.691 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=false,success=false.
2022-04-22 09:01:35.691 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:35.691 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:35.691 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:35.691 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:35.691 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 131 bytes: C0 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 30 C0 
2022-04-22 09:01:35.707 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 131 bytes: C0 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 30 C0
2022-04-22 09:01:35.722 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:35.722 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 131 called.
2022-04-22 09:01:35.722 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 30.
2022-04-22 09:01:35.722 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 129.
2022-04-22 09:01:35.722 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x210 .
2022-04-22 09:01:35.722 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 124 bytes: 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:01:35.722 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x210 and data 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:01:35.722 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x210 .
2022-04-22 09:01:35.738 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 124 bytes: 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:01:35.754 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data => 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-04-22 09:01:35.754 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => applying data length => 124
2022-04-22 09:01:35.754 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_NTF with 124 bytes of data) called.
2022-04-22 09:01:35.754 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_NTF (0x210).
2022-04-22 09:01:35.754 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_NTF (0x210) with 124 bytes of data.
2022-04-22 09:01:35.754 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2022-04-22 09:01:35.754 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeID=6.
2022-04-22 09:01:35.754 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfOrder=6.
2022-04-22 09:01:35.754 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPlacement=0.
2022-04-22 09:01:35.769 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfName=Hobbykamer.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfVelocity=1.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeTypeSubType=1088 (SLIDER_SHUTTER).
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): derived product description=Exterior Venetian blind.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductGroup=0.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductType=0.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeVariation=0.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPowerMode=0.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfBuildNumber=0.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfSerialNumber=[0, 0, 0, 0, 0, 0, 0, 0].
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfState=5.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:01:35.785 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTarget=51200.
2022-04-22 09:01:35.801 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter1=63487.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter2=63487.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter3=10825.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter4=63487.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfRemainingTime=20224.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTimeStamp=1325419866.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNbrOfAlias=0.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasOne=0.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasTwo=0.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasThree=0.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFour=0.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFive=0.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 6 and responseNodeID 6.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for request NodeID 6 and response NodeID 6.
2022-04-22 09:01:35.816 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2022-04-22 09:01:35.832 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): device provided invalid serial number, using name 'Hobbykamer' instead.
2022-04-22 09:01:35.847 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2,name=Hobbykamer) created.
2022-04-22 09:01:35.847 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=true,success=true.
2022-04-22 09:01:35.847 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => finished => success
2022-04-22 09:01:35.847 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getProduct(): returning product Product "Hobbykamer" / SLIDER_SHUTTER (bridgeIndex=6,serial=Hobbykamer,position=C800).
2022-04-22 09:01:35.847 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(constructur with 51200 as veluxPosition) called.
2022-04-22 09:01:35.847 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition() created with percent-type 100.
2022-04-22 09:01:35.847 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): position of actuator is 100%.
2022-04-22 09:01:35.847 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh() returns 100.
2022-04-22 09:01:35.847 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): updating channel velux:rollershutter:192_168_178_231:Hobbykamer:position to 100.
2022-04-22 09:01:35.847 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionAttempt set to Fri Apr 22 09:01:35 CEST 2022.
2022-04-22 09:01:35.863 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionSuccess set to Fri Apr 22 09:01:35 CEST 2022.
2022-04-22 09:01:35.863 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]) done.
2022-04-22 09:01:35.879 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]): command REFRESH on channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition.
2022-04-22 09:01:35.879 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,REFRESH) called.
2022-04-22 09:01:35.879 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:01:35.879 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
2022-04-22 09:01:35.879 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): no existing products with changed parameters.
2022-04-22 09:01:35.879 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): work on refresh.
2022-04-22 09:01:35.879 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): refreshing item velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition (type velux:rollershutter/vanePosition).
2022-04-22 09:01:35.879 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleRefresh(velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition,vanePosition,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@bfd0) called.
2022-04-22 09:01:35.879 [TRACE] [nternal.things.VeluxExistingProducts] - getNoMembers() returns 7.
2022-04-22 09:01:35.879 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): there are some existing products.
2022-04-22 09:01:35.879 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:01:35.910 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setProductId(6) called.
2022-04-22 09:01:35.910 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Product) called.
2022-04-22 09:01:35.910 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:35.910 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Product,authenticated) called.
2022-04-22 09:01:35.910 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:35.910 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve Product, authenticated) called.
2022-04-22 09:01:35.910 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve Product', authenticated
2022-04-22 09:01:35.910 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - getRequestCommand() returns GW_GET_NODE_INFORMATION_REQ (0x200).
2022-04-22 09:01:35.910 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getRequestDataAsArrayOfBytes() returns data for retrieving node with id 6.
2022-04-22 09:01:35.910 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:01:35.910 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => send mode => preparing command 
2022-04-22 09:01:35.910 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x200 with data size 1 called.
2022-04-22 09:01:35.910 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 04 02 00 06 00.
2022-04-22 09:01:35.941 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 6 called.
2022-04-22 09:01:35.941 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 04 02 00 06 00 C0.
2022-04-22 09:01:35.941 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => command ready => start sending 
2022-04-22 09:01:35.941 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_REQ => sending data => 06
2022-04-22 09:01:35.941 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:35.941 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 8 bytes: C0 00 04 02 00 06 00 C0
2022-04-22 09:01:35.941 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 8 bytes.
2022-04-22 09:01:35.941 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 8 bytes: C0 00 04 02 00 06 00 C0 
2022-04-22 09:01:35.941 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:35.941 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:36.066 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:36.066 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 9 bytes: C0 00 05 02 01 00 06 00 C0 
2022-04-22 09:01:36.066 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 9 bytes: C0 00 05 02 01 00 06 00 C0
2022-04-22 09:01:36.066 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:36.066 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 9 called.
2022-04-22 09:01:36.066 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 05 02 01 00 06 00.
2022-04-22 09:01:36.082 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 7.
2022-04-22 09:01:36.082 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x201 .
2022-04-22 09:01:36.082 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 00 06.
2022-04-22 09:01:36.082 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x201 and data 00 06.
2022-04-22 09:01:36.082 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x201 .
2022-04-22 09:01:36.082 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 00 06.
2022-04-22 09:01:36.082 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => received data => 00 06
2022-04-22 09:01:36.082 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => applying data length => 2
2022-04-22 09:01:36.082 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_CFM with 2 bytes of data) called.
2022-04-22 09:01:36.082 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_CFM (0x201).
2022-04-22 09:01:36.082 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_CFM (0x201) with 2 bytes of data.
2022-04-22 09:01:36.082 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2022-04-22 09:01:36.082 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): returned status: OK - Request accepted.
2022-04-22 09:01:36.113 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 6 and responseNodeID 6.
2022-04-22 09:01:36.113 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for request NodeID 6 and response NodeID 6.
2022-04-22 09:01:36.113 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2022-04-22 09:01:36.113 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=false,success=false.
2022-04-22 09:01:36.113 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2022-04-22 09:01:36.113 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2022-04-22 09:01:36.113 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2022-04-22 09:01:36.113 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2022-04-22 09:01:36.113 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 131 bytes: C0 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 31 C0 
2022-04-22 09:01:36.129 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 131 bytes: C0 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 31 C0
2022-04-22 09:01:36.144 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2022-04-22 09:01:36.144 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 131 called.
2022-04-22 09:01:36.144 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 7F 02 10 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 31.
2022-04-22 09:01:36.144 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 129.
2022-04-22 09:01:36.144 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x210 .
2022-04-22 09:01:36.144 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 124 bytes: 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:01:36.144 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x210 and data 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:01:36.144 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x210 .
2022-04-22 09:01:36.160 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 124 bytes: 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2022-04-22 09:01:36.176 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data => 06 00 06 00 48 6F 62 62 79 6B 61 6D 65 72 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 04 40 00 00 00 00 00 00 00 00 00 00 00 00 00 05 C8 00 C8 00 F7 FF F7 FF 2A 49 F7 FF 00 00 4F 00 4D 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-04-22 09:01:36.176 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => applying data length => 124
2022-04-22 09:01:36.176 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_NTF with 124 bytes of data) called.
2022-04-22 09:01:36.176 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): handling response GW_GET_NODE_INFORMATION_NTF (0x210).
2022-04-22 09:01:36.176 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() called for GW_GET_NODE_INFORMATION_NTF (0x210) with 124 bytes of data.
2022-04-22 09:01:36.176 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - isLengthValid() returns true.
2022-04-22 09:01:36.176 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeID=6.
2022-04-22 09:01:36.176 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfOrder=6.
2022-04-22 09:01:36.176 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPlacement=0.
2022-04-22 09:01:36.176 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfName=Hobbykamer.
2022-04-22 09:01:36.191 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfVelocity=1.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeTypeSubType=1088 (SLIDER_SHUTTER).
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): derived product description=Exterior Venetian blind.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductGroup=0.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfProductType=0.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNodeVariation=0.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfPowerMode=0.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfBuildNumber=0.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfSerialNumber=[0, 0, 0, 0, 0, 0, 0, 0].
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfState=5.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfCurrentPosition=51200.
2022-04-22 09:01:36.207 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTarget=51200.
2022-04-22 09:01:36.222 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter1=63487.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter2=63487.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter3=10825.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfFunctionalParameter4=63487.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfRemainingTime=20224.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfTimeStamp=1325419867.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfNbrOfAlias=0.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasOne=0.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasTwo=0.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasThree=0.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFour=0.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): ntfAliasFive=0.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingNodeID() called for requestNodeID 6 and responseNodeID 6.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() called for request NodeID 6 and response NodeID 6.
2022-04-22 09:01:36.238 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - check4matchingAnyID() returns true.
2022-04-22 09:01:36.238 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): device provided invalid serial number, using name 'Hobbykamer' instead.
2022-04-22 09:01:36.269 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2,name=Hobbykamer) created.
2022-04-22 09:01:36.269 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): finished=true,success=true.
2022-04-22 09:01:36.269 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_GET_NODE_INFORMATION_REQ => finished => success
2022-04-22 09:01:36.269 [TRACE] [ux.internal.bridge.slip.SCgetProduct] - getProduct(): returning product Product "Hobbykamer" / SLIDER_SHUTTER (bridgeIndex=6,serial=Hobbykamer,position=C800).
2022-04-22 09:01:36.269 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(constructur with 10825 as veluxPosition) called.
2022-04-22 09:01:36.269 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition() created with percent-type 21.
2022-04-22 09:01:36.269 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): position of vane is 21%.
2022-04-22 09:01:36.269 [TRACE] [rnal.handler.ChannelActuatorPosition] - handleRefresh() returns 21.
2022-04-22 09:01:36.269 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): updating channel velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition to 21.
2022-04-22 09:01:36.269 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionAttempt set to Fri Apr 22 09:01:36 CEST 2022.
2022-04-22 09:01:36.301 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionSuccess set to Fri Apr 22 09:01:36 CEST 2022.
2022-04-22 09:01:36.301 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]) done.
2022-04-22 09:01:45.501 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-25,5,main] starting cycle 49.
2022-04-22 09:01:45.501 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): processing of possible HSM messages.
2022-04-22 09:01:45.501 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] will process HouseStatus.
2022-04-22 09:01:45.501 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through all (child things and bridge) linked channels needing a refresh
2022-04-22 09:01:45.501 [TRACE] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() called.
2022-04-22 09:01:45.501 [TRACE] [elux.internal.handler.BridgeChannels] - getAllLinkedChannelUIDs() returns [velux:rollershutter:192_168_178_231:Hobbykamer:position, velux:rollershutter:192_168_178_231:Hobbykamer:vanePosition].
2022-04-22 09:01:45.501 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2022-04-22 09:01:45.501 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,position) returns enum velux:rollershutter/position.
2022-04-22 09:01:45.501 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status) called.
2022-04-22 09:01:45.501 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.501 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:45.501 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:rollershutter,vanePosition) returns enum velux:rollershutter/vanePosition.
2022-04-22 09:01:45.501 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Retrieve House Status,authenticated) called.
2022-04-22 09:01:45.501 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.501 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2022-04-22 09:01:45.501 [TRACE] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob(): loop through properties needing a refresh
2022-04-22 09:01:45.501 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Retrieve House Status, authenticated) called.
2022-04-22 09:01:45.501 [TRACE] [binding.velux.internal.VeluxItemType] - getPropertyEntriesByThing(velux:klf200) returns [velux:klf200/firmware, velux:klf200/address, velux:klf200/subnetMask, velux:klf200/defaultGW, velux:klf200/DHCP, velux:klf200/WLANSSID, velux:klf200/WLANPassword, velux:klf200/products, velux:klf200/scenes, velux:klf200/check].
2022-04-22 09:01:45.501 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Retrieve House Status', authenticated
2022-04-22 09:01:45.501 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,firmware) returns enum velux:klf200/firmware.
2022-04-22 09:01:45.501 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.501 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,address) returns enum velux:klf200/address.
2022-04-22 09:01:45.532 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_178_231-1,5,main] 
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.532 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => receive-only mode => checking messages 
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,subnetMask) returns enum velux:klf200/subnetMask.
2022-04-22 09:01:45.532 [TRACE] [x.internal.bridge.slip.io.Connection] - isAlive() on 192.168.178.231: called.
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.532 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: called.
2022-04-22 09:01:45.532 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available() called.
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,defaultGW) returns enum velux:klf200/defaultGW.
2022-04-22 09:01:45.532 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - available() => slip message count 0
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.532 [TRACE] [nternal.bridge.slip.io.SSLconnection] - available(): found 0 messages ready to be read (> 0 means true).
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,DHCP) returns enum velux:klf200/DHCP.
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.532 [TRACE] [x.internal.bridge.slip.io.Connection] - isMessageAvailable() on 192.168.178.231: there are no messages waiting.
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANSSID) returns enum velux:klf200/WLANSSID.
2022-04-22 09:01:45.532 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => no waiting messages => done 
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.532 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,WLANPassword) returns enum velux:klf200/WLANPassword.
2022-04-22 09:01:45.532 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.532 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => no updates
2022-04-22 09:01:45.532 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,products) returns enum velux:klf200/products.
2022-04-22 09:01:45.563 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2022-04-22 09:01:45.563 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.563 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,scenes) returns enum velux:klf200/scenes.
2022-04-22 09:01:45.563 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.563 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,check) returns enum velux:klf200/check.
2022-04-22 09:01:45.563 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshedNow(): returning false, as refresh cycle has not yet come for this item.
2022-04-22 09:01:45.563 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-25,5,main] finished cycle 49.