[velux] New OpenHAB2 binding - feedback welcome!

I have it working now. The item is with the same definition as shown previously, but I was not able to create the Thing via the things file. Instead, I created the thing with custom name ThKLF200Info via the UI, and it was then auto connected to the channel defined via the items file.

1 Like

I had to replace my KLF200 and managed to get everything working again. However, I think after a restart of openhab I get the following set of error messages for each item and the item is not reacting:
All things are online.

2023-08-06 16:37:16.832 [WARN ] [al.handler.utils.Thing2VeluxActuator] - mapThing2Velux(): actuator with uniqueIndex=00:00:00:00:00:00:00:01 is not registered
2023-08-06 16:37:16.834 [WARN ] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): unknown actuator.
2023-08-06 16:37:16.835 [WARN ] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:192_168_178_66:1:position,REFRESH): updating of item velux:rollershutter:192_168_178_66:1:position (type velux:rollershutter/position) failed.
  1. Disable the hub thing in OH
  2. Power cycle the KLF
  3. Enable the hub thing in OH

I did that and I still have the same problem.
Right after enabling the hub thing I got the following error message per item:

2023-08-06 17:45:45.817 [WARN ] [al.handler.utils.Thing2VeluxActuator] - mapThing2Velux(): actuator with uniqueIndex=00:00:00:00:00:00:00:01 is not registered

However, one out of six things are working.now.
Any other idea?

Other question: Does the binding require or interact with californium (coap transport) bundles?

The uniqueIndex value seems to be an unlikely low number => perhaps check your configuration again.

1 Like

Thanks Andrew for taking the time.
After I have added the roller shutter things, the serial value was already prefilled with value “1”. As I got an error message that this field requires a value of pattern xx:xx:xx:xx:xx:xx:xx:xx I simply added zeros.
Do you mean that I can use any number here and it does not need to reflect the number of the KLF200 roller shutter?

EDIT:
ok. Problem solved. Your comment on the serial number made me re-read the docs more carefully regarding serial number and realized now for the first time, it has to be 00:00:00:00:00:00:00:00 for ALL Somfy devices. I do not know why it has worked before with the old KLF200.

Thanks again Andrew

Is anybody using this binding with OH4? Does the migration work without problems?

Updated a week ago and had no problems with the VELUX Binding.

1 Like

Problem ‘moveMainAndVane’ not executed reliable.
(I hope I am allowed to put this problem in this existing thread)

I am using OH4 openHAB 4.0.0 Release Build with teh Velux Binding.
I have connected 7 Velux shades with moving Vanes connected.
I notice the following behaviour: when sending commands using moveMainAndVane, to the KLF200, some commands do not get executed bij the KLF. When the sun rises in the morning at some time OH commands 4 shades to got down and position the vanes at an certain angle. Many times one of the four do not react on the command. WHich one differs from day to day.
Today I managed to get a trace-log of the Velux binding where I see it happening. In the attached log you can see the first command:

moveMainAndVane(thingName:'velux:rollershutter:192_168_178_231:Hobbykamer', mainPercent:100, vanePercent:67) action called

This command is not executed. The following:

moveMainAndVane(thingName:'velux:rollershutter:192_168_178_231:Keukenraam
moveMainAndVane(thingName:'velux:rollershutter:192_168_178_231:Terrasdeur
moveMainAndVane(thingName:'velux:rollershutter:192_168_178_231:Terrasraam

got executed fine. In this case the first command is ‘forgotten’. But this changes from day to day.
The lines with ‘[org.openhab.core.model.script.SUN ]’ are my own debuglines from OH.
The routine I use to command the shades is as the following:

val veluxActions = getActions("velux", "velux:klf200:192_168_178_231")
if (veluxActions !== null) {
	val succeeded = veluxActions.moveMainAndVane("velux:rollershutter:192_168_178_231:"+JaloezieName, 100, slatpos)
	if (succeeded==true){
		logInfo("SUN","OK >" + JaloezieName + space + " veluxActions=" + veluxActions + " Set moveMainAndVane OK")
	}
	else {
		logInfo("SUN","ERR>" + JaloezieName + space + " veluxActions=" + veluxActions + " Unable to set moveMainAndVane")
	}
	Thread::sleep(250)  //probeersel 7-8-2023 om te testen of gelijktijdig naar beneden gaan nu betrouwbaarder werkt.
}
else{
	logInfo("SUN","ERR>" + JaloezieName + space + " Unable to get veluxActions")
}

This issue of not executing a command is not when using the normal Down or Up commands, only the command using the ‘getActions’ method.
I added the ‘Thread::sleep(250)’ to seperate the commands. This did not solve the issue.

Andrew, can you have a look at it? When you need additional info; please ask.
(I had to cut the log. When you need all off it I better send it bij mail.)
Regards, Geert

Log:

===Start calling to move 4 Velux shades down

2023-08-08 09:11:34.530 [INFO ] [org.openhab.core.model.script.SUN   ] -    >Hobbykamer  DOWN: gaat omlaag en set lamellen [SlatPos was:0 nu 67] en geblokkeerd gedurende 60 seconden
2023-08-08 09:11:34.542 [TRACE] [g.velux.internal.action.VeluxActions] - moveMainAndVane(thingName:'velux:rollershutter:192_168_178_231:Hobbykamer', mainPercent:100, vanePercent:67) action called
2023-08-08 09:11:34.547 [TRACE] [.internal.handler.VeluxBridgeHandler] - moveMainAndVane() called on velux:klf200:192_168_178_231
2023-08-08 09:11:34.549 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2023-08-08 09:11:34.550 [TRACE] [nternal.things.VeluxExistingProducts] - get(6) called.
2023-08-08 09:11:34.552 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=Hobbykamer) created.
2023-08-08 09:11:34.555 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(67 as PercentType) created.
2023-08-08 09:11:34.557 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(100 as PercentType) created.
2023-08-08 09:11:34.559 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setNodeIdAndParameters(6) called.
2023-08-08 09:11:34.561 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:34.565 [INFO ] [org.openhab.core.model.script.SUN   ] - OK >Hobbykamer  veluxActions=org.openhab.binding.velux.internal.action.VeluxActions@3ba238cd Set moveMainAndVane OK


2023-08-08 09:11:35.219 [INFO ] [org.openhab.core.model.script.SUN   ] -    >Keukenraam  DOWN: gaat omlaag en set lamellen [SlatPos was:0 nu 67] en geblokkeerd gedurende 60 seconden
2023-08-08 09:11:35.230 [TRACE] [g.velux.internal.action.VeluxActions] - moveMainAndVane(thingName:'velux:rollershutter:192_168_178_231:Keukenraam', mainPercent:100, vanePercent:67) action called
2023-08-08 09:11:35.232 [TRACE] [.internal.handler.VeluxBridgeHandler] - moveMainAndVane() called on velux:klf200:192_168_178_231
2023-08-08 09:11:35.234 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2023-08-08 09:11:35.235 [TRACE] [nternal.things.VeluxExistingProducts] - get(4) called.
2023-08-08 09:11:35.237 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=Keukenraam) created.
2023-08-08 09:11:35.239 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(67 as PercentType) created.
2023-08-08 09:11:35.241 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(100 as PercentType) created.
2023-08-08 09:11:35.243 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setNodeIdAndParameters(4) called.
2023-08-08 09:11:35.246 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:35.249 [INFO ] [org.openhab.core.model.script.SUN   ] - OK >Keukenraam  veluxActions=org.openhab.binding.velux.internal.action.VeluxActions@3ba238cd Set moveMainAndVane OK
2023-08-08 09:11:35.419 [DEBUG] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => no slip message
2023-08-08 09:11:35.421 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 0 bytes: 
2023-08-08 09:11:35.422 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 0 bytes: 
2023-08-08 09:11:35.424 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:35.426 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_OPENHAB_RECEIVEONLY => finished => success
2023-08-08 09:11:35.427 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished successfully.
2023-08-08 09:11:35.429 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob(): => GetHouseStatus() => updates received => synchronizing
2023-08-08 09:11:35.431 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
2023-08-08 09:11:35.432 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): no existing products with changed parameters.
2023-08-08 09:11:35.434 [TRACE] [.internal.handler.VeluxBridgeHandler] - getHouseStatusCommsJob() initiated by Thread[OH-velux:klf200:192_168_178_231-1,5,main] has finished.
2023-08-08 09:11:35.435 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]): command REFRESH on channel velux:klf200:192_168_178_231:downtime.
2023-08-08 09:11:35.437 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:klf200:192_168_178_231:downtime,REFRESH) called.
2023-08-08 09:11:35.439 [TRACE] [binding.velux.internal.VeluxItemType] - getByThingAndChannel(velux:klf200,downtime) returns enum velux:klf200/downtime.
2023-08-08 09:11:35.441 [TRACE] [nternal.things.VeluxExistingProducts] - isDirty() returns false.
2023-08-08 09:11:35.442 [TRACE] [.internal.handler.VeluxBridgeHandler] - syncChannelsWithProducts(): no existing products with changed parameters.
2023-08-08 09:11:35.444 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): work on refresh.
2023-08-08 09:11:35.445 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): refreshing item velux:klf200:192_168_178_231:downtime (type velux:klf200/downtime).
2023-08-08 09:11:35.447 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): updating channel velux:klf200:192_168_178_231:downtime to 0.
2023-08-08 09:11:35.449 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionAttempt set to 2023-08-08T07:11:35.424Z.
2023-08-08 09:11:35.451 [TRACE] [internal.handler.utils.ThingProperty] - setValue() connectionSuccess set to 2023-08-08T07:11:35.424Z.
2023-08-08 09:11:35.452 [TRACE] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(Thread[OH-velux:klf200:192_168_178_231-1,5,main]) done.
2023-08-08 09:11:35.454 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator) called.
2023-08-08 09:11:35.456 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2023-08-08 09:11:35.457 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator,authenticated) called.
2023-08-08 09:11:35.458 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2023-08-08 09:11:35.460 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Send Command to Actuator, authenticated) called.
2023-08-08 09:11:35.461 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Send Command to Actuator', authenticated
2023-08-08 09:11:35.462 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - getRequestCommand() returns 0x300.
2023-08-08 09:11:35.464 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): ntfSessionID=e6c.
2023-08-08 09:11:35.466 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqCommandOriginator=8.
2023-08-08 09:11:35.468 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevel=5.
2023-08-08 09:11:35.469 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqParameterActive=0.
2023-08-08 09:11:35.471 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI1=100000.
2023-08-08 09:11:35.473 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI2=0.
2023-08-08 09:11:35.474 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqMainParameter=c800.
2023-08-08 09:11:35.476 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFunctionalParameters={0xF7FF, 0xF7FF, 0x8600, 0xF7FF}.
2023-08-08 09:11:35.478 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArrayCount=1.
2023-08-08 09:11:35.479 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArray01=4 (reqNodeId=4).
2023-08-08 09:11:35.483 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevelLock=0.
2023-08-08 09:11:35.485 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL03=0.
2023-08-08 09:11:35.486 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL47=0.
2023-08-08 09:11:35.488 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqLockTime=0.
2023-08-08 09:11:35.490 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes() data is 0E 6C 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2023-08-08 09:11:35.492 [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] 
2023-08-08 09:11:35.493 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => send mode => preparing command 
2023-08-08 09:11:35.495 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x300 with data size 66 called.
2023-08-08 09:11:35.497 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 45 03 00 0E 6C 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42.
2023-08-08 09:11:35.499 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 71 called.
2023-08-08 09:11:35.501 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 45 03 00 0E 6C 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 C0.
2023-08-08 09:11:35.502 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => command ready => start sending 
2023-08-08 09:11:35.504 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - sending command GW_COMMAND_SEND_REQ
2023-08-08 09:11:35.506 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_REQ => sending data => 0E 6C 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2023-08-08 09:11:35.507 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:35.509 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 73 bytes: C0 00 45 03 00 0E 6C 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 C0
2023-08-08 09:11:35.511 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 73 bytes.
2023-08-08 09:11:35.514 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 73 bytes: C0 00 45 03 00 0E 6C 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 C0 
2023-08-08 09:11:35.516 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:35.517 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.

2023-08-08 09:11:35.697 [INFO ] [org.openhab.core.model.script.SUN   ] -    >Terrasdeur  DOWN: gaat omlaag en set lamellen [SlatPos was:0 nu 67] en geblokkeerd gedurende 60 seconden
2023-08-08 09:11:35.709 [TRACE] [g.velux.internal.action.VeluxActions] - moveMainAndVane(thingName:'velux:rollershutter:192_168_178_231:Terrasdeur', mainPercent:100, vanePercent:67) action called
2023-08-08 09:11:35.711 [TRACE] [.internal.handler.VeluxBridgeHandler] - moveMainAndVane() called on velux:klf200:192_168_178_231
2023-08-08 09:11:35.713 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2023-08-08 09:11:35.715 [TRACE] [nternal.things.VeluxExistingProducts] - get(5) called.
2023-08-08 09:11:35.717 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=Terrasdeur) created.
2023-08-08 09:11:35.718 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(67 as PercentType) created.
2023-08-08 09:11:35.720 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(100 as PercentType) created.
2023-08-08 09:11:35.722 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:35.722 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setNodeIdAndParameters(5) called.
2023-08-08 09:11:35.723 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 10 bytes: C0 00 06 03 01 0E 6C 01 67 C0 
2023-08-08 09:11:35.724 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:35.726 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 10 bytes: C0 00 06 03 01 0E 6C 01 67 C0
2023-08-08 09:11:35.727 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:35.728 [INFO ] [org.openhab.core.model.script.SUN   ] - OK >Terrasdeur  veluxActions=org.openhab.binding.velux.internal.action.VeluxActions@3ba238cd Set moveMainAndVane OK
2023-08-08 09:11:35.729 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 10 called.
2023-08-08 09:11:35.730 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 06 03 01 0E 6C 01 67.
2023-08-08 09:11:35.732 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 8.
2023-08-08 09:11:35.733 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2023-08-08 09:11:35.735 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 0E 6C 01.
2023-08-08 09:11:35.736 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x301 and data 0E 6C 01.
2023-08-08 09:11:35.738 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2023-08-08 09:11:35.739 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 0E 6C 01.
2023-08-08 09:11:35.741 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => received data => 0E 6C 01
2023-08-08 09:11:35.742 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_SEND_CFM => 0E 6C 01
2023-08-08 09:11:35.743 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => applying data length => 3
2023-08-08 09:11:35.745 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(GW_COMMAND_SEND_CFM with 3 bytes of data) called.
2023-08-08 09:11:35.748 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): handling response GW_COMMAND_SEND_CFM (0x301).
2023-08-08 09:11:35.750 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() called for GW_COMMAND_SEND_CFM (0x301) with 3 bytes of data.
2023-08-08 09:11:35.752 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() returns true.
2023-08-08 09:11:35.754 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): returned status: OK - Command is accepted.
2023-08-08 09:11:35.755 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingSessionID() called for request SessionID 3692 and response SessionID 3692.
2023-08-08 09:11:35.757 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() called for request SessionID 3692 and response SessionID 3692.
2023-08-08 09:11:35.758 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() returns true.
2023-08-08 09:11:35.760 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): skipping wait for more packets as sequential processing is not enforced.
2023-08-08 09:11:35.761 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): finished=true,success=true.
2023-08-08 09:11:35.763 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => finished => success
2023-08-08 09:11:35.764 [TRACE] [.internal.handler.VeluxBridgeHandler] - moveMainAndVane() command successfully sent to velux:klf200:192_168_178_231
2023-08-08 09:11:35.766 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator) called.
2023-08-08 09:11:35.768 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2023-08-08 09:11:35.769 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator,authenticated) called.
2023-08-08 09:11:35.771 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2023-08-08 09:11:35.772 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Send Command to Actuator, authenticated) called.
2023-08-08 09:11:35.774 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Send Command to Actuator', authenticated
2023-08-08 09:11:35.775 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - getRequestCommand() returns 0x300.
2023-08-08 09:11:35.777 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): ntfSessionID=e6d.
2023-08-08 09:11:35.779 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqCommandOriginator=8.
2023-08-08 09:11:35.780 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevel=5.
2023-08-08 09:11:35.782 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqParameterActive=0.
2023-08-08 09:11:35.784 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI1=100000.
2023-08-08 09:11:35.786 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI2=0.
2023-08-08 09:11:35.787 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqMainParameter=c800.
2023-08-08 09:11:35.789 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFunctionalParameters={0xF7FF, 0xF7FF, 0x8600, 0xF7FF}.
2023-08-08 09:11:35.790 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArrayCount=1.
2023-08-08 09:11:35.792 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArray01=5 (reqNodeId=5).
2023-08-08 09:11:35.793 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevelLock=0.
2023-08-08 09:11:35.795 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL03=0.
2023-08-08 09:11:35.797 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL47=0.
2023-08-08 09:11:35.798 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqLockTime=0.
2023-08-08 09:11:35.801 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes() data is 0E 6D 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2023-08-08 09:11:35.803 [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] 
2023-08-08 09:11:35.804 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => send mode => preparing command 
2023-08-08 09:11:35.806 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x300 with data size 66 called.
2023-08-08 09:11:35.808 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 45 03 00 0E 6D 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42.
2023-08-08 09:11:35.809 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 71 called.
2023-08-08 09:11:35.811 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 45 03 00 0E 6D 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 C0.
2023-08-08 09:11:35.813 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => command ready => start sending 
2023-08-08 09:11:35.814 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - sending command GW_COMMAND_SEND_REQ
2023-08-08 09:11:35.816 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_REQ => sending data => 0E 6D 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2023-08-08 09:11:35.818 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:35.819 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 73 bytes: C0 00 45 03 00 0E 6D 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 C0
2023-08-08 09:11:35.821 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 73 bytes.
2023-08-08 09:11:35.824 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 73 bytes: C0 00 45 03 00 0E 6D 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 C0 
2023-08-08 09:11:35.826 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:35.827 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:35.829 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:35.831 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 04 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 56 C0 
2023-08-08 09:11:35.832 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 04 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 56 C0
2023-08-08 09:11:35.834 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:35.835 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2023-08-08 09:11:35.837 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 04 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 56.
2023-08-08 09:11:35.839 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2023-08-08 09:11:35.841 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:35.843 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 04 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:35.844 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 04 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:35.846 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:35.848 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 04 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:35.850 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 04 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00
2023-08-08 09:11:35.851 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_NODE_STATE_POSITION_CHANGED_NTF => 04 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00
2023-08-08 09:11:35.853 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2023-08-08 09:11:35.855 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2023-08-08 09:11:35.857 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2023-08-08 09:11:35.858 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2023-08-08 09:11:35.860 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2023-08-08 09:11:35.861 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=4.
2023-08-08 09:11:35.863 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=2.
2023-08-08 09:11:35.865 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=0x0000.
2023-08-08 09:11:35.866 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=0xC800.
2023-08-08 09:11:35.868 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFunctionalParameters={0xF7FF, 0xF7FF, 0x83B1, 0xF7FF} (returns null).
2023-08-08 09:11:35.869 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2023-08-08 09:11:35.871 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=680394752.
2023-08-08 09:11:35.873 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:35.875 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2023-08-08 09:11:35.876 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - getProduct(): returning VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:4, state:2, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null).
2023-08-08 09:11:35.878 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 4) returns true.
2023-08-08 09:11:35.880 [TRACE] [nternal.things.VeluxExistingProducts] - get(4) called.
2023-08-08 09:11:35.881 [DEBUG] [nternal.things.VeluxExistingProducts] - update() newProduct:VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:4, state:2, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null) (identical)
2023-08-08 09:11:35.883 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Keukenraam, typeId:SLIDER_SHUTTER, bridgeIndex:4, state:45, serial:Keukenraam, position:0000, target:0000, functionalParameters:{0xF7FF, 0xF7FF, 0x0000, 0xF7FF}) (unchanged)
2023-08-08 09:11:35.885 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => update submitted
2023-08-08 09:11:35.887 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2023-08-08 09:11:35.888 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:35.890 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:35.891 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:35.893 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:35.894 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 20 bytes: C0 00 10 03 02 0E 6C 08 04 00 00 00 02 01 06 80 04 00 FE C0 
2023-08-08 09:11:35.896 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 20 bytes: C0 00 10 03 02 0E 6C 08 04 00 00 00 02 01 06 80 04 00 FE C0
2023-08-08 09:11:35.897 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:35.900 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 20 called.
2023-08-08 09:11:35.902 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 10 03 02 0E 6C 08 04 00 00 00 02 01 06 80 04 00 FE.
2023-08-08 09:11:35.905 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 18.
2023-08-08 09:11:35.907 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2023-08-08 09:11:35.908 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 0E 6C 08 04 00 00 00 02 01 06 80 04 00.
2023-08-08 09:11:35.910 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x302 and data 0E 6C 08 04 00 00 00 02 01 06 80 04 00.
2023-08-08 09:11:35.911 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2023-08-08 09:11:35.913 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 0E 6C 08 04 00 00 00 02 01 06 80 04 00.
2023-08-08 09:11:35.915 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_RUN_STATUS_NTF => received data => 0E 6C 08 04 00 00 00 02 01 06 80 04 00
2023-08-08 09:11:35.916 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_RUN_STATUS_NTF => 0E 6C 08 04 00 00 00 02 01 06 80 04 00
2023-08-08 09:11:35.918 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_RUN_STATUS_NTF => parallelism allowed => continuing
2023-08-08 09:11:35.919 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:35.921 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:35.922 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:35.923 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:35.925 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 13 bytes: C0 00 09 03 03 0E 6C 04 00 00 26 49 C0 
2023-08-08 09:11:35.926 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 13 bytes: C0 00 09 03 03 0E 6C 04 00 00 26 49 C0
2023-08-08 09:11:35.927 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:35.929 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 13 called.
2023-08-08 09:11:35.931 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 09 03 03 0E 6C 04 00 00 26 49.
2023-08-08 09:11:35.932 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 11.
2023-08-08 09:11:35.934 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x303 .
2023-08-08 09:11:35.935 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 6 bytes: 0E 6C 04 00 00 26.
2023-08-08 09:11:35.936 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x303 and data 0E 6C 04 00 00 26.
2023-08-08 09:11:35.938 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x303 .
2023-08-08 09:11:35.939 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 6 bytes: 0E 6C 04 00 00 26.
2023-08-08 09:11:35.941 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_REMAINING_TIME_NTF => received data => 0E 6C 04 00 00 26
2023-08-08 09:11:35.943 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_REMAINING_TIME_NTF => 0E 6C 04 00 00 26
2023-08-08 09:11:35.944 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_REMAINING_TIME_NTF => parallelism allowed => continuing
2023-08-08 09:11:35.946 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:35.948 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:35.949 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:35.951 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:35.952 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 04 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 26 28 8E 00 00 76 C0 
2023-08-08 09:11:35.954 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 04 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 26 28 8E 00 00 76 C0
2023-08-08 09:11:35.956 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:35.957 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2023-08-08 09:11:35.959 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 04 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 26 28 8E 00 00 76.
2023-08-08 09:11:35.961 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2023-08-08 09:11:35.962 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:35.964 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 04 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 26 28 8E 00 00.
2023-08-08 09:11:35.965 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 04 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 26 28 8E 00 00.
2023-08-08 09:11:35.967 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:35.969 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 04 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 26 28 8E 00 00.
2023-08-08 09:11:35.970 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 04 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 26 28 8E 00 00
2023-08-08 09:11:35.972 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_NODE_STATE_POSITION_CHANGED_NTF => 04 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 26 28 8E 00 00
2023-08-08 09:11:35.974 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2023-08-08 09:11:35.975 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2023-08-08 09:11:35.977 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2023-08-08 09:11:35.979 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2023-08-08 09:11:35.980 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2023-08-08 09:11:35.982 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=4.
2023-08-08 09:11:35.984 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=4.
2023-08-08 09:11:35.985 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=0x0000.
2023-08-08 09:11:35.987 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=0xC800.
2023-08-08 09:11:35.988 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFunctionalParameters={0xF7FF, 0xF7FF, 0x83B1, 0xF7FF} (returns null).
2023-08-08 09:11:35.990 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=38.
2023-08-08 09:11:35.992 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=680394752.
2023-08-08 09:11:35.994 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:35.995 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2023-08-08 09:11:35.997 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - getProduct(): returning VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:4, state:4, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null).
2023-08-08 09:11:35.999 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 4) returns true.
2023-08-08 09:11:36.000 [TRACE] [nternal.things.VeluxExistingProducts] - get(4) called.
2023-08-08 09:11:36.002 [TRACE] [g.velux.internal.things.VeluxProduct] - setState(name=Keukenraam,index=4) state 45 replaced by 4.
2023-08-08 09:11:36.004 [TRACE] [g.velux.internal.things.VeluxProduct] - setTarget(name=Keukenraam,index=4) target 0 replaced by 51200.
2023-08-08 09:11:36.006 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Keukenraam.
2023-08-08 09:11:36.007 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Keukenraam, typeId:SLIDER_SHUTTER, bridgeIndex:4, state:45, serial:Keukenraam, position:0000, target:0000, functionalParameters:{0xF7FF, 0xF7FF, 0x0000, 0xF7FF}) (previous)
2023-08-08 09:11:36.009 [DEBUG] [nternal.things.VeluxExistingProducts] - update() newProduct:VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:4, state:4, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null) (modifier)
2023-08-08 09:11:36.011 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Keukenraam, typeId:SLIDER_SHUTTER, bridgeIndex:4, state:4, serial:Keukenraam, position:0000, target:C800, functionalParameters:{0xF7FF, 0xF7FF, 0x0000, 0xF7FF}) (modified)
2023-08-08 09:11:36.013 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => update submitted
2023-08-08 09:11:36.014 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2023-08-08 09:11:36.016 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.017 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.019 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.072 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.073 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 10 bytes: C0 00 06 03 01 0E 6D 01 66 C0 
2023-08-08 09:11:36.075 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 10 bytes: C0 00 06 03 01 0E 6D 01 66 C0
2023-08-08 09:11:36.076 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.078 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 10 called.
2023-08-08 09:11:36.080 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 06 03 01 0E 6D 01 66.
2023-08-08 09:11:36.081 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 8.
2023-08-08 09:11:36.082 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2023-08-08 09:11:36.084 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 0E 6D 01.
2023-08-08 09:11:36.085 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x301 and data 0E 6D 01.
2023-08-08 09:11:36.087 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2023-08-08 09:11:36.089 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 0E 6D 01.
2023-08-08 09:11:36.090 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => received data => 0E 6D 01
2023-08-08 09:11:36.092 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_SEND_CFM => 0E 6D 01
2023-08-08 09:11:36.093 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => applying data length => 3
2023-08-08 09:11:36.095 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(GW_COMMAND_SEND_CFM with 3 bytes of data) called.
2023-08-08 09:11:36.096 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): handling response GW_COMMAND_SEND_CFM (0x301).
2023-08-08 09:11:36.098 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() called for GW_COMMAND_SEND_CFM (0x301) with 3 bytes of data.
2023-08-08 09:11:36.100 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() returns true.
2023-08-08 09:11:36.101 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): returned status: OK - Command is accepted.
2023-08-08 09:11:36.103 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingSessionID() called for request SessionID 3693 and response SessionID 3693.
2023-08-08 09:11:36.105 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() called for request SessionID 3693 and response SessionID 3693.
2023-08-08 09:11:36.106 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() returns true.
2023-08-08 09:11:36.107 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): skipping wait for more packets as sequential processing is not enforced.
2023-08-08 09:11:36.109 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): finished=true,success=true.
2023-08-08 09:11:36.110 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => finished => success
2023-08-08 09:11:36.112 [TRACE] [.internal.handler.VeluxBridgeHandler] - moveMainAndVane() command successfully sent to velux:klf200:192_168_178_231
2023-08-08 09:11:36.114 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator) called.
2023-08-08 09:11:36.115 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2023-08-08 09:11:36.117 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator,authenticated) called.
2023-08-08 09:11:36.118 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2023-08-08 09:11:36.120 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Send Command to Actuator, authenticated) called.
2023-08-08 09:11:36.121 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Send Command to Actuator', authenticated
2023-08-08 09:11:36.122 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - getRequestCommand() returns 0x300.
2023-08-08 09:11:36.124 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): ntfSessionID=e6e.
2023-08-08 09:11:36.125 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqCommandOriginator=8.
2023-08-08 09:11:36.127 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevel=5.
2023-08-08 09:11:36.128 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqParameterActive=0.
2023-08-08 09:11:36.130 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI1=100000.
2023-08-08 09:11:36.132 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI2=0.
2023-08-08 09:11:36.133 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqMainParameter=c800.
2023-08-08 09:11:36.134 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFunctionalParameters={0xF7FF, 0xF7FF, 0x8600, 0xF7FF}.
2023-08-08 09:11:36.136 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArrayCount=1.
2023-08-08 09:11:36.137 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArray01=5 (reqNodeId=5).
2023-08-08 09:11:36.139 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevelLock=0.
2023-08-08 09:11:36.140 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL03=0.
2023-08-08 09:11:36.142 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL47=0.
2023-08-08 09:11:36.144 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqLockTime=0.
2023-08-08 09:11:36.146 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes() data is 0E 6E 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2023-08-08 09:11:36.149 [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] 
2023-08-08 09:11:36.150 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => send mode => preparing command 
2023-08-08 09:11:36.152 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x300 with data size 66 called.
2023-08-08 09:11:36.157 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 45 03 00 0E 6E 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 41.
2023-08-08 09:11:36.159 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 71 called.
2023-08-08 09:11:36.161 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 45 03 00 0E 6E 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 41 C0.
2023-08-08 09:11:36.162 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => command ready => start sending 
2023-08-08 09:11:36.164 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - sending command GW_COMMAND_SEND_REQ
2023-08-08 09:11:36.166 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_REQ => sending data => 0E 6E 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2023-08-08 09:11:36.167 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.169 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 73 bytes: C0 00 45 03 00 0E 6E 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 41 C0
2023-08-08 09:11:36.170 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 73 bytes.
2023-08-08 09:11:36.172 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 73 bytes: C0 00 45 03 00 0E 6E 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 41 C0 
2023-08-08 09:11:36.173 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.175 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.177 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.178 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 57 C0 
2023-08-08 09:11:36.180 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 57 C0
2023-08-08 09:11:36.181 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.182 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2023-08-08 09:11:36.184 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 57.
2023-08-08 09:11:36.185 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2023-08-08 09:11:36.187 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:36.189 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:36.190 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:36.192 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:36.193 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:36.195 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00
2023-08-08 09:11:36.197 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_NODE_STATE_POSITION_CHANGED_NTF => 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00
2023-08-08 09:11:36.198 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2023-08-08 09:11:36.200 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2023-08-08 09:11:36.201 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2023-08-08 09:11:36.203 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2023-08-08 09:11:36.205 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2023-08-08 09:11:36.206 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=5.

2023-08-08 09:11:36.207 [INFO ] [org.openhab.core.model.script.SUN   ] -    >Terrasraam  DOWN: gaat omlaag en set lamellen [SlatPos was:0 nu 67] en geblokkeerd gedurende 60 seconden
2023-08-08 09:11:36.207 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=2.
2023-08-08 09:11:36.209 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=0x0000.
2023-08-08 09:11:36.210 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=0xC800.
2023-08-08 09:11:36.212 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFunctionalParameters={0xF7FF, 0xF7FF, 0x83B1, 0xF7FF} (returns null).
2023-08-08 09:11:36.213 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2023-08-08 09:11:36.215 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=680394752.
2023-08-08 09:11:36.217 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:36.218 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2023-08-08 09:11:36.219 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - getProduct(): returning VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:5, state:2, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null).
2023-08-08 09:11:36.221 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 5) returns true.
2023-08-08 09:11:36.222 [TRACE] [g.velux.internal.action.VeluxActions] - moveMainAndVane(thingName:'velux:rollershutter:192_168_178_231:Terrasraam', mainPercent:100, vanePercent:67) action called
2023-08-08 09:11:36.223 [TRACE] [nternal.things.VeluxExistingProducts] - get(5) called.
2023-08-08 09:11:36.224 [TRACE] [.internal.handler.VeluxBridgeHandler] - moveMainAndVane() called on velux:klf200:192_168_178_231
2023-08-08 09:11:36.225 [DEBUG] [nternal.things.VeluxExistingProducts] - update() newProduct:VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:5, state:2, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null) (identical)
2023-08-08 09:11:36.225 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2023-08-08 09:11:36.226 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Terrasdeur, typeId:SLIDER_SHUTTER, bridgeIndex:5, state:45, serial:Terrasdeur, position:0000, target:0000, functionalParameters:{0xF7FF, 0xF7FF, 0x0000, 0xF7FF}) (unchanged)
2023-08-08 09:11:36.227 [TRACE] [nternal.things.VeluxExistingProducts] - get(0) called.
2023-08-08 09:11:36.228 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => update submitted
2023-08-08 09:11:36.229 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=Terrasraam) created.
2023-08-08 09:11:36.229 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2023-08-08 09:11:36.231 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(67 as PercentType) created.
2023-08-08 09:11:36.231 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.233 [TRACE] [internal.things.VeluxProductPosition] - VeluxProductPosition(100 as PercentType) created.
2023-08-08 09:11:36.233 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.236 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setNodeIdAndParameters(0) called.
2023-08-08 09:11:36.236 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.238 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:36.238 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.240 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 20 bytes: C0 00 10 03 02 0E 6D 08 05 00 00 00 02 01 06 80 04 00 FE C0 
2023-08-08 09:11:36.241 [INFO ] [org.openhab.core.model.script.SUN   ] - OK >Terrasraam  veluxActions=org.openhab.binding.velux.internal.action.VeluxActions@3ba238cd Set moveMainAndVane OK
2023-08-08 09:11:36.241 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 20 bytes: C0 00 10 03 02 0E 6D 08 05 00 00 00 02 01 06 80 04 00 FE C0
2023-08-08 09:11:36.243 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.244 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 20 called.
2023-08-08 09:11:36.246 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 10 03 02 0E 6D 08 05 00 00 00 02 01 06 80 04 00 FE.
2023-08-08 09:11:36.247 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 18.
2023-08-08 09:11:36.249 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2023-08-08 09:11:36.250 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 0E 6D 08 05 00 00 00 02 01 06 80 04 00.
2023-08-08 09:11:36.252 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x302 and data 0E 6D 08 05 00 00 00 02 01 06 80 04 00.
2023-08-08 09:11:36.253 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2023-08-08 09:11:36.254 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 0E 6D 08 05 00 00 00 02 01 06 80 04 00.
2023-08-08 09:11:36.256 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_RUN_STATUS_NTF => received data => 0E 6D 08 05 00 00 00 02 01 06 80 04 00
2023-08-08 09:11:36.257 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_RUN_STATUS_NTF => 0E 6D 08 05 00 00 00 02 01 06 80 04 00
2023-08-08 09:11:36.259 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_RUN_STATUS_NTF => parallelism allowed => continuing
2023-08-08 09:11:36.260 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.261 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.263 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.264 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.266 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 13 bytes: C0 00 09 03 03 0E 6D 05 00 00 33 5C C0 
2023-08-08 09:11:36.267 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 13 bytes: C0 00 09 03 03 0E 6D 05 00 00 33 5C C0
2023-08-08 09:11:36.269 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.270 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 13 called.
2023-08-08 09:11:36.272 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 09 03 03 0E 6D 05 00 00 33 5C.
2023-08-08 09:11:36.273 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 11.
2023-08-08 09:11:36.274 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x303 .
2023-08-08 09:11:36.276 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 6 bytes: 0E 6D 05 00 00 33.
2023-08-08 09:11:36.277 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x303 and data 0E 6D 05 00 00 33.
2023-08-08 09:11:36.278 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x303 .
2023-08-08 09:11:36.280 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 6 bytes: 0E 6D 05 00 00 33.
2023-08-08 09:11:36.281 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_REMAINING_TIME_NTF => received data => 0E 6D 05 00 00 33
2023-08-08 09:11:36.284 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_REMAINING_TIME_NTF => 0E 6D 05 00 00 33
2023-08-08 09:11:36.284 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_REMAINING_TIME_NTF => parallelism allowed => continuing
2023-08-08 09:11:36.286 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.288 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.289 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.290 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.292 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8E 00 00 62 C0 
2023-08-08 09:11:36.293 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8E 00 00 62 C0
2023-08-08 09:11:36.295 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.296 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2023-08-08 09:11:36.298 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8E 00 00 62.
2023-08-08 09:11:36.300 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2023-08-08 09:11:36.301 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:36.303 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8E 00 00.
2023-08-08 09:11:36.304 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8E 00 00.
2023-08-08 09:11:36.305 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:36.307 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8E 00 00.
2023-08-08 09:11:36.308 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8E 00 00
2023-08-08 09:11:36.310 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_NODE_STATE_POSITION_CHANGED_NTF => 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8E 00 00
2023-08-08 09:11:36.311 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2023-08-08 09:11:36.313 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2023-08-08 09:11:36.314 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2023-08-08 09:11:36.316 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2023-08-08 09:11:36.317 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2023-08-08 09:11:36.318 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=5.
2023-08-08 09:11:36.320 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=4.
2023-08-08 09:11:36.321 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=0x0000.
2023-08-08 09:11:36.322 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=0xC800.
2023-08-08 09:11:36.323 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFunctionalParameters={0xF7FF, 0xF7FF, 0x83B1, 0xF7FF} (returns null).
2023-08-08 09:11:36.325 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=51.
2023-08-08 09:11:36.327 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=680394752.
2023-08-08 09:11:36.328 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:36.329 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2023-08-08 09:11:36.331 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - getProduct(): returning VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:5, state:4, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null).
2023-08-08 09:11:36.332 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 5) returns true.
2023-08-08 09:11:36.333 [TRACE] [nternal.things.VeluxExistingProducts] - get(5) called.
2023-08-08 09:11:36.335 [TRACE] [g.velux.internal.things.VeluxProduct] - setState(name=Terrasdeur,index=5) state 45 replaced by 4.
2023-08-08 09:11:36.336 [TRACE] [g.velux.internal.things.VeluxProduct] - setTarget(name=Terrasdeur,index=5) target 0 replaced by 51200.
2023-08-08 09:11:36.338 [TRACE] [nternal.things.VeluxExistingProducts] - update(): updating by UniqueIndex Terrasdeur.
2023-08-08 09:11:36.339 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Terrasdeur, typeId:SLIDER_SHUTTER, bridgeIndex:5, state:45, serial:Terrasdeur, position:0000, target:0000, functionalParameters:{0xF7FF, 0xF7FF, 0x0000, 0xF7FF}) (previous)
2023-08-08 09:11:36.341 [DEBUG] [nternal.things.VeluxExistingProducts] - update() newProduct:VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:5, state:4, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null) (modifier)
2023-08-08 09:11:36.342 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Terrasdeur, typeId:SLIDER_SHUTTER, bridgeIndex:5, state:4, serial:Terrasdeur, position:0000, target:C800, functionalParameters:{0xF7FF, 0xF7FF, 0x0000, 0xF7FF}) (modified)
2023-08-08 09:11:36.344 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => update submitted
2023-08-08 09:11:36.345 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2023-08-08 09:11:36.346 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.348 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.349 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.402 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.405 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 10 bytes: C0 00 06 03 01 0E 6E 01 65 C0 
2023-08-08 09:11:36.409 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 10 bytes: C0 00 06 03 01 0E 6E 01 65 C0
2023-08-08 09:11:36.412 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.415 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 10 called.
2023-08-08 09:11:36.418 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 06 03 01 0E 6E 01 65.
2023-08-08 09:11:36.421 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 8.
2023-08-08 09:11:36.424 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2023-08-08 09:11:36.428 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 0E 6E 01.
2023-08-08 09:11:36.432 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x301 and data 0E 6E 01.
2023-08-08 09:11:36.436 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x301 .
2023-08-08 09:11:36.439 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 3 bytes: 0E 6E 01.
2023-08-08 09:11:36.442 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => received data => 0E 6E 01
2023-08-08 09:11:36.445 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_SEND_CFM => 0E 6E 01
2023-08-08 09:11:36.447 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_CFM => applying data length => 3
2023-08-08 09:11:36.449 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(GW_COMMAND_SEND_CFM with 3 bytes of data) called.
2023-08-08 09:11:36.451 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): handling response GW_COMMAND_SEND_CFM (0x301).
2023-08-08 09:11:36.453 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() called for GW_COMMAND_SEND_CFM (0x301) with 3 bytes of data.
2023-08-08 09:11:36.456 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - isLengthValid() returns true.
2023-08-08 09:11:36.458 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): returned status: OK - Command is accepted.
2023-08-08 09:11:36.460 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingSessionID() called for request SessionID 3694 and response SessionID 3694.
2023-08-08 09:11:36.462 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() called for request SessionID 3694 and response SessionID 3694.
2023-08-08 09:11:36.465 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - check4matchingAnyID() returns true.
2023-08-08 09:11:36.466 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): skipping wait for more packets as sequential processing is not enforced.
2023-08-08 09:11:36.469 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - setResponse(): finished=true,success=true.
2023-08-08 09:11:36.471 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => finished => success
2023-08-08 09:11:36.473 [TRACE] [.internal.handler.VeluxBridgeHandler] - moveMainAndVane() command successfully sent to velux:klf200:192_168_178_231
2023-08-08 09:11:36.475 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator) called.
2023-08-08 09:11:36.476 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2023-08-08 09:11:36.478 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - bridgeCommunicate(Send Command to Actuator,authenticated) called.
2023-08-08 09:11:36.479 [TRACE] [ng.velux.internal.bridge.VeluxBridge] - isAuthenticated() returns true.
2023-08-08 09:11:36.480 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(BCP: Send Command to Actuator, authenticated) called.
2023-08-08 09:11:36.482 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() 'Send Command to Actuator', authenticated
2023-08-08 09:11:36.483 [DEBUG] [rnal.bridge.slip.SCrunProductCommand] - getRequestCommand() returns 0x300.
2023-08-08 09:11:36.484 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): ntfSessionID=e6f.
2023-08-08 09:11:36.485 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqCommandOriginator=8.
2023-08-08 09:11:36.486 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevel=5.
2023-08-08 09:11:36.488 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqParameterActive=0.
2023-08-08 09:11:36.490 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI1=100000.
2023-08-08 09:11:36.491 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFPI2=0.
2023-08-08 09:11:36.492 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqMainParameter=c800.
2023-08-08 09:11:36.494 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqFunctionalParameters={0xF7FF, 0xF7FF, 0x8600, 0xF7FF}.
2023-08-08 09:11:36.495 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArrayCount=1.
2023-08-08 09:11:36.497 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqIndexArray01=0 (reqNodeId=0).
2023-08-08 09:11:36.498 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPriorityLevelLock=0.
2023-08-08 09:11:36.499 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL03=0.
2023-08-08 09:11:36.501 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqPL47=0.
2023-08-08 09:11:36.502 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes(): reqLockTime=0.
2023-08-08 09:11:36.505 [TRACE] [rnal.bridge.slip.SCrunProductCommand] - getRequestDataAsArrayOfBytes() data is 0E 6F 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2023-08-08 09:11:36.507 [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] 
2023-08-08 09:11:36.508 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => send mode => preparing command 
2023-08-08 09:11:36.510 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) for command 0x300 with data size 66 called.
2023-08-08 09:11:36.511 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 45 03 00 0E 6F 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 45.
2023-08-08 09:11:36.513 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() for data size 71 called.
2023-08-08 09:11:36.514 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - encode() provides transfer encoding: C0 00 45 03 00 0E 6F 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 45 C0.
2023-08-08 09:11:36.516 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => command ready => start sending 
2023-08-08 09:11:36.518 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - sending command GW_COMMAND_SEND_REQ
2023-08-08 09:11:36.520 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_SEND_REQ => sending data => 0E 6F 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2023-08-08 09:11:36.522 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.523 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: sending packet with 73 bytes: C0 00 45 03 00 0E 6F 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 45 C0
2023-08-08 09:11:36.525 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() called, writing 73 bytes.
2023-08-08 09:11:36.527 [TRACE] [nternal.bridge.slip.io.SSLconnection] - send() finished after having send 73 bytes: C0 00 45 03 00 0E 6F 08 05 00 20 00 C8 00 00 00 00 00 86 00 00 00 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 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 45 C0 
2023-08-08 09:11:36.528 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.530 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.532 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.533 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 20 bytes: C0 00 10 03 02 0E 6D 08 05 00 FF FF 00 1D 10 00 04 00 76 C0 
2023-08-08 09:11:36.535 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 20 bytes: C0 00 10 03 02 0E 6D 08 05 00 FF FF 00 1D 10 00 04 00 76 C0
2023-08-08 09:11:36.536 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.538 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 20 called.
2023-08-08 09:11:36.539 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 10 03 02 0E 6D 08 05 00 FF FF 00 1D 10 00 04 00 76.
2023-08-08 09:11:36.541 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 18.
2023-08-08 09:11:36.542 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2023-08-08 09:11:36.544 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 0E 6D 08 05 00 FF FF 00 1D 10 00 04 00.
2023-08-08 09:11:36.546 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x302 and data 0E 6D 08 05 00 FF FF 00 1D 10 00 04 00.
2023-08-08 09:11:36.547 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2023-08-08 09:11:36.549 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 0E 6D 08 05 00 FF FF 00 1D 10 00 04 00.
2023-08-08 09:11:36.550 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_RUN_STATUS_NTF => received data => 0E 6D 08 05 00 FF FF 00 1D 10 00 04 00
2023-08-08 09:11:36.552 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_RUN_STATUS_NTF => 0E 6D 08 05 00 FF FF 00 1D 10 00 04 00
2023-08-08 09:11:36.553 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_RUN_STATUS_NTF => parallelism allowed => continuing
2023-08-08 09:11:36.556 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.559 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.560 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.562 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.564 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 9 bytes: C0 00 05 03 04 0E 6D 61 C0 
2023-08-08 09:11:36.566 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 9 bytes: C0 00 05 03 04 0E 6D 61 C0
2023-08-08 09:11:36.568 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.569 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 9 called.
2023-08-08 09:11:36.571 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 05 03 04 0E 6D 61.
2023-08-08 09:11:36.572 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 7.
2023-08-08 09:11:36.574 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x304 .
2023-08-08 09:11:36.576 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 0E 6D.
2023-08-08 09:11:36.578 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x304 and data 0E 6D.
2023-08-08 09:11:36.580 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x304 .
2023-08-08 09:11:36.582 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 2 bytes: 0E 6D.
2023-08-08 09:11:36.584 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_SESSION_FINISHED_NTF => received data => 0E 6D
2023-08-08 09:11:36.586 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_SESSION_FINISHED_NTF => 0E 6D
2023-08-08 09:11:36.587 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_SESSION_FINISHED_NTF => parallelism allowed => continuing
2023-08-08 09:11:36.588 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.590 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.592 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.593 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.596 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 57 C0 
2023-08-08 09:11:36.598 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 27 bytes: C0 00 17 02 11 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 57 C0
2023-08-08 09:11:36.600 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.601 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 27 called.
2023-08-08 09:11:36.603 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 17 02 11 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00 57.
2023-08-08 09:11:36.605 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 25.
2023-08-08 09:11:36.606 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:36.608 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:36.610 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x211 and data 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:36.612 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x211 .
2023-08-08 09:11:36.614 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 20 bytes: 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00.
2023-08-08 09:11:36.616 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => received data => 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00
2023-08-08 09:11:36.618 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_NODE_STATE_POSITION_CHANGED_NTF => 05 02 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 00 28 8E 00 00
2023-08-08 09:11:36.620 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => starting
2023-08-08 09:11:36.622 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(GW_NODE_STATE_POSITION_CHANGED_NTF with 20 bytes of data) called.
2023-08-08 09:11:36.624 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): handling response GW_NODE_STATE_POSITION_CHANGED_NTF (0x211).
2023-08-08 09:11:36.625 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() called for GW_NODE_STATE_POSITION_CHANGED_NTF (0x211) with 20 bytes of data.
2023-08-08 09:11:36.627 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - isLengthValid() returns true.
2023-08-08 09:11:36.629 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfNodeID=5.
2023-08-08 09:11:36.631 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfState=2.
2023-08-08 09:11:36.632 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfCurrentPosition=0x0000.
2023-08-08 09:11:36.634 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTarget=0xC800.
2023-08-08 09:11:36.636 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfFunctionalParameters={0xF7FF, 0xF7FF, 0x83B1, 0xF7FF} (returns null).
2023-08-08 09:11:36.637 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfRemainingTime=0.
2023-08-08 09:11:36.639 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): ntfTimeStamp=680394752.
2023-08-08 09:11:36.640 [TRACE] [g.velux.internal.things.VeluxProduct] - VeluxProduct(v2, name=unknown) [notification product] created.
2023-08-08 09:11:36.642 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - setResponse(): finished=true,success=true.
2023-08-08 09:11:36.643 [TRACE] [nternal.bridge.slip.SCgetHouseStatus] - getProduct(): returning VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:5, state:2, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null).
2023-08-08 09:11:36.645 [TRACE] [nternal.things.VeluxExistingProducts] - isRegistered(ProductBridgeIndex 5) returns true.
2023-08-08 09:11:36.647 [TRACE] [nternal.things.VeluxExistingProducts] - get(5) called.
2023-08-08 09:11:36.649 [DEBUG] [nternal.things.VeluxExistingProducts] - update() newProduct:VeluxProduct(v2, creator:GW_COMMAND_SEND_REQ, dataSource:GATEWAY, name:unknown, typeId:UNDEFTYPE, bridgeIndex:5, state:2, serial:00:00:00:00:00:00:00:00, position:0000, target:C800, functionalParameters:null) (identical)
2023-08-08 09:11:36.651 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Terrasdeur, typeId:SLIDER_SHUTTER, bridgeIndex:5, state:4, serial:Terrasdeur, position:0000, target:C800, functionalParameters:{0xF7FF, 0xF7FF, 0x0000, 0xF7FF}) (unchanged)
2023-08-08 09:11:36.653 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => update submitted
2023-08-08 09:11:36.654 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_NODE_STATE_POSITION_CHANGED_NTF => special command => continuing
2023-08-08 09:11:36.656 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.658 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.660 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.662 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.663 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 20 bytes: C0 00 10 03 02 0E 6E 08 05 00 00 00 02 01 06 00 04 00 7D C0 
2023-08-08 09:11:36.665 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 20 bytes: C0 00 10 03 02 0E 6E 08 05 00 00 00 02 01 06 00 04 00 7D C0
2023-08-08 09:11:36.666 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.668 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 20 called.
2023-08-08 09:11:36.670 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 10 03 02 0E 6E 08 05 00 00 00 02 01 06 00 04 00 7D.
2023-08-08 09:11:36.671 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 18.
2023-08-08 09:11:36.673 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2023-08-08 09:11:36.675 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 0E 6E 08 05 00 00 00 02 01 06 00 04 00.
2023-08-08 09:11:36.677 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x302 and data 0E 6E 08 05 00 00 00 02 01 06 00 04 00.
2023-08-08 09:11:36.678 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x302 .
2023-08-08 09:11:36.680 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 13 bytes: 0E 6E 08 05 00 00 00 02 01 06 00 04 00.
2023-08-08 09:11:36.682 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_RUN_STATUS_NTF => received data => 0E 6E 08 05 00 00 00 02 01 06 00 04 00
2023-08-08 09:11:36.685 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_RUN_STATUS_NTF => 0E 6E 08 05 00 00 00 02 01 06 00 04 00
2023-08-08 09:11:36.687 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_RUN_STATUS_NTF => parallelism allowed => continuing
2023-08-08 09:11:36.689 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.690 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.692 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.694 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.696 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 13 bytes: C0 00 09 03 03 0E 6E 05 00 00 33 5F C0 
2023-08-08 09:11:36.697 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: received packet with 13 bytes: C0 00 09 03 03 0E 6E 05 00 00 33 5F C0
2023-08-08 09:11:36.699 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: finished.
2023-08-08 09:11:36.701 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() for packet size 13 called.
2023-08-08 09:11:36.702 [TRACE] [ternal.bridge.slip.utils.SlipRFC1055] - decode() provides payload: 00 09 03 03 0E 6E 05 00 00 33 5F.
2023-08-08 09:11:36.704 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 11.
2023-08-08 09:11:36.706 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x303 .
2023-08-08 09:11:36.708 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 6 bytes: 0E 6E 05 00 00 33.
2023-08-08 09:11:36.710 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x303 and data 0E 6E 05 00 00 33.
2023-08-08 09:11:36.712 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getCommand() returns 0x303 .
2023-08-08 09:11:36.713 [TRACE] [ernal.bridge.slip.utils.SlipEncoding] - getData() returns 6 bytes: 0E 6E 05 00 00 33.
2023-08-08 09:11:36.715 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_REMAINING_TIME_NTF => received data => 0E 6E 05 00 00 33
2023-08-08 09:11:36.716 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - received message GW_COMMAND_REMAINING_TIME_NTF => 0E 6E 05 00 00 33
2023-08-08 09:11:36.717 [TRACE] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.178.231] GW_COMMAND_SEND_REQ => GW_COMMAND_REMAINING_TIME_NTF => parallelism allowed => continuing
2023-08-08 09:11:36.719 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: called.
2023-08-08 09:11:36.721 [TRACE] [x.internal.bridge.slip.io.Connection] - io() on 192.168.178.231: receiving bytes.
2023-08-08 09:11:36.722 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() called.
2023-08-08 09:11:36.724 [TRACE] [e.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => return slip message
2023-08-08 09:11:36.726 [TRACE] [nternal.bridge.slip.io.SSLconnection] - receive() finished after having read 27 bytes: C0 00 17 02 11 05 04 00 00 C8 00 F7 FF F7 FF 83 B1 F7 FF 00 33 28 8F 00 00 63 C0 

^
How are you calling your rules code above for the four actuators? Is it in a loop? Can you please show the full code?

Sure, here it is:

It is a loop indeed. The actual loop starts at line 128. The Lambda is for calculation based on sun and position to decide to move the shades, Up, DOWN or DOWN+Vaneposition.
I wonder however if the calling method is the problem because in the TRACE-logs you can see the movemainandvane command is received but not exectued (if I see it right).

Line 210 has the ‘moveMainAndVane’ command where teh problem arises.

//Lambda function  
import java.net.URLEncoder  //voor Prowl URL 
import org.eclipse.xtext.xbase.lib.Functions

val org.eclipse.xtext.xbase.lib.Functions$Function1<Number, String> calc_slatpos = [winpos |
            
            //Regeling: standaard op basis van lichtsterkte weerstation
            var sunrad=Sunpower_Corrected.state as Number 	//Zonnestraling (gecorrigeerd naar zonhoogte)
            var sunradAvD=(Sunpower_Corrected_Average_Down.state as Number).intValue
            var sunradAvU=(Sunpower_Corrected_Average_Up.state as Number).intValue
            
            // Regeling: ON is op basis van opbrengst zonnepanelen; 
            if (ControlledBySolarpanels.state==ON) {
                sunrad=(YouLess_Solar_Current.state as Number)
                sunradAvD=(Solarpower_Corrected_Average_Down.state as Number).intValue
                sunradAvU=(Solarpower_Corrected_Average_Up.state as Number).intValue
            }

            val sunpos=(LocalSunPositionAzimuth.state as QuantityType<Number>).doubleValue 	//Zonpositie
            val sunhgt=(LocalSunPositionElevation.state as QuantityType<Number>).intValue 	//Zonhoogte

            var sunthrU=(Jaloezie_Sunpower_Threshold_Up.state as Number).intValue    //onder deze waarde gaat jaloezie open of omhoog
            var sunthrD=(Jaloezie_Sunpower_Threshold_Down.state as Number).intValue  //boven deze waarde gaat jaloezie omlaag
            val sunmof=(Jaloezie_Sunpower_MaxOffset.state as Number).intValue        //maximum hoek van zoninval op raam waarbij jaloezie nog gestuurd wordt

            var String result=""

            //bepaal offset (verschil raampositie met zonpositie)
            var sunoffs=(Math::abs(sunpos - winpos)).intValue 	//Zon Offset
            //als offset > 180 graden, dan kortere afstand via andere kant berekenen
            if (sunoffs>180) {
                sunoffs= (360 - sunoffs)
                //logInfo("SUN", "    SUNOFFSET(>180): "+  sunoffs + " winpos=" + winpos )
            }
            else{
                //logInfo("SUN", "    SUNOFFSET(<180): "+  sunoffs + " winpos=" + winpos  )
            }

            //compensatie op/neer-drempels, afhankelijk van hoek zon op raam. Schuiner=meer zon toegestaan=drempel hoger.
            if (sunoffs<sunmof) {  
                sunthrD  = sunthrD+sunoffs
                sunthrU  = sunthrU+sunoffs
            }

            //zonkracht laag genoeg om omhoog te gaan of zon schijnt niet meer op raam 
            if ( (sunradAvU < sunthrU && sunrad < sunthrU ) || (sunoffs >= sunmof)  ) {
                //if (sunradAvU < sunthrU) { logInfo("SUN", "    Zonkracht gemiddeld laag genoeg om omhoog te mogen (sunradAvU:"+  sunradAvU + " < sunthrU:" + sunthrU + ")" ) }
                //if (sunrad < sunthrU)   { logInfo("SUN", "    Huidige zonkracht laag genoeg om omhoog te mogen (sunrad:"+  sunrad + " < sunthrU:" + sunthrU + ")" ) }
                //if (sunoffs >= sunmof)  { logInfo("SUN", "    Zon schijnt niet op raam; mag omhoog (sunoffs:"+  sunoffs + " >= sunmof:" + sunmof + ")" ) }
                result=transform("SCALE", "slatpos.scale", "99")+":UP"  //jaloezie mag omhoog OF gebruik meest dichte stand (=default) volgens slatpos.scale bestand
            } 

            //zon helder genoeg om omlaag te gaan en zon schijnt op raam
            else if (sunradAvD>sunthrD && sunrad>sunthrD && sunoffs<sunmof )  {
                //if (sunradAvD>sunthrD) { logInfo("SUN","    Zonkracht gemiddeld is hoog genoeg om omlaag te gaan (sunradAvD:"+  sunradAvD + " > sunthrD:" + sunthrD ) }
                //if (sunrad > sunthrD) { logInfo("SUN","    Huidige zonkracht is hoog genoeg om omlaag te gaan (sunrad:"+  sunrad + " > sunthrD:" + sunthrD + ")" ) }
                //if (sunoffs<sunmof)   { logInfo("SUN","    Zon schijnt op raam  (sunoffs:"+  sunoffs + " < sunmof:" + sunmof + ")" ) }
                result=transform("SCALE", "slatpos.scale", sunhgt.toString) + ":DOWN" //bereken lamelstand max. (horizontaal) = 45, min (bijna dicht) = 80; jaloezie mag sluiten
            }

            //zon tussen omhoog en omlaag in
            else {
                    //logInfo("SUN","    Zonkracht tussen omhoog en omlaag (sunradAvU:"+ sunradAvU + " > sunthrU:" + sunthrU + " & sunradAvD:" + sunradAvD + " < sunthrD:" + sunthrD +")" )}
                    result=transform("SCALE", "slatpos.scale", sunhgt.toString) + ":SET"  //alleen lamelstand berekenen
            }

            //logInfo("SUN", "     sunoffs:" + sunoffs + ", sunmof:" + sunmof + String::format(", sunpos:%1$.1f", sunpos.floatValue()) + ", winpos:" + winpos +  ", sunrad:"+  sunrad + ", sunthrD:" + sunthrD + ", sunthrU:" + sunthrU + ", sunradAvD:" + sunradAvD + ", sunradAvU:" + sunradAvU + ", sunhgt:" + sunhgt + " Result:"+result)

            return result
]


val org.eclipse.xtext.xbase.lib.Functions$Function4<String, String, String, Number, Boolean> pushMessage = [event,description,url,priority |	
    logInfo("PROWL","Prowl command: event=" + event + " description=" + description + " url=" + url + " priority=" + priority) 
    var String prowlString = sendHttpGetRequest("https://api.prowlapp.com/publicapi/add?apikey=c9c65f5234eaac61f40df64d27254f8633eca350&application=HomeControl&event="+URLEncoder::encode(event,'UTF-8') + "&description="+URLEncoder::encode(description,'UTF-8') + "&priority="+priority + "&url="+url )
    logInfo("PROWL","Prowl responsecode: "+transform("XPATH", "number(//prowl/success/@code)",prowlString)+" remaining: "+ transform("XPATH", "number(//prowl/success/@remaining)",prowlString)) 
    true
]

val  WindowPosition=newArrayList(0,113,293,113,113,113,203,293)
val JaloezieNames=newArrayList("","Hobbykamer","Werkkamer","Keukenraam","Terrasdeur","Terrasraam","Zuidraam","Slaapkamer")
var boolean debug 
var String jPrefix

rule "1 Zonafhankelijke jaloezie besturing"
when
	//Item Sunpower_Corrected_Average_Down changed //tijdelijk ingesteld om frequentie checks te verlagen
    Item PWS_solarradiation changed //als regeling op basis van lichtsterkte weerstation is
    or
    Item YouLess_Solar_Current changed //als regeling op basis van zonnepanelen is
    or
    Item Jaloezie_Global_SunControl changed  //received command ON
    or 
    Item JaloezieSunControl_ForceOn  received command ON  
then
    if (StableAfterSystemStarted.state !=ON) return;
    //logInfo( "SUN","triggeringItem: "+ triggeringItemName + "  =  " + newState)
    //exit rules voor als getriggered wordt door event die niet de besturing heeft (Zonnepanelen of Lichtsensor)
    if (ControlledBySolarpanels.state==ON && triggeringItemName =="Sunpower_Corrected")  return;
    if (ControlledBySolarpanels.state==OFF && triggeringItemName =="YouLess_Solar_Current") return;
    
    //logInfo( "SUN","triggeringItem: "+ triggeringItemName + "  =  " + newState)
    //Jaloezienamen voor gebruik in loop; andere namen voor Items afhankelijk van KLF200 of SOMFY/Connexoon
    if (ControlledByConnexoon.state==ON) { 
        jPrefix="SOMFY"
        //if (debug) {logInfo("SUN","Jaloezieën bestuurd door SOMFY Connexoon")}
    }
	else{
        jPrefix="VELUX"
        //if (debug) {logInfo("SUN","Jaloezieën bestuurd door VELUX Bridge")}
	}
    
    //only calculate average values if necessary
    if (ControlledBySolarpanels.state==ON) {
        Solarpower_Corrected_Average_Down.sendCommand(YouLess_Solar_Current.averageSince(now.minusMinutes((Jaloezie_Sunpower_Time_Mean_Down.state as DecimalType).intValue),"influxdb") as Number ) 
        Solarpower_Corrected_Average_Up.sendCommand(YouLess_Solar_Current.averageSince(now.minusMinutes((Jaloezie_Sunpower_Time_Mean_Up.state as DecimalType).intValue),"influxdb") as Number )
    }
    if (ControlledBySolarpanels.state==OFF) {    
        Sunpower_Corrected_Average_Down.sendCommand(Sunpower_Corrected.averageSince(now.minusMinutes((Jaloezie_Sunpower_Time_Mean_Down.state as DecimalType).intValue),"influxdb") as Number )                
        Sunpower_Corrected_Average_Up.sendCommand(Sunpower_Corrected.averageSince(now.minusMinutes((Jaloezie_Sunpower_Time_Mean_Up.state as DecimalType).intValue),"influxdb") as Number )                
    }

    if (Sunpower_Corrected_Average_Down.state == NULL || PWS_solarradiation.state == UNDEF) {
            logInfo( "STARTUP","Sunpower_Corrected_Average_Down OR PWS_solarradiation still NULL (startup); rule skipped")
            return
    }
    
    if (Jaloezie_Global_SunControl.state==ON) {  
        if (Jaloezie_Debug.state==ON) {debug=true } else {debug=false }
        if (debug) {logInfo( "SUN","--->"+jPrefix+"-sun:" + Sunpower_Corrected.state as Number + String::format("W/m², sunhgt:%1$.1f", (LocalSunPositionElevation.state as QuantityType<Number>).doubleValue) + String::format("°, sunpos:%1$.1f", (LocalSunPositionAzimuth.state as QuantityType<Number>).doubleValue) + "°, wind:" + PWS_windspeedmph.state.format("%.1f") + "km/h") }
        
        var int i=0
        while ((i=i+1) <= 7) {
            val JaloezieName=JaloezieNames.get(i)
            //logInfo("SUN","1> "+JaloezieName)

			//return in geval van UNDEF voor Positie of VanePositie
			if ((sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state == UNDEF) || (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state == UNDEF)) {
			    if (debug) {logInfo("SUN", "S> "+ JaloezieName+": "+ (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state)+" / "+(sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state))}
			    return;
			}

            val space="     ".substring(0,11-JaloezieName.length ) //space=lengte afhankelijk van Jaloezienaam lengte tbv uitlijning in logs
            var XtraInfo=""
            if ( sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_SunControl" ].state  as Number !=0 ) { // _SunControl: 0="UIT", 1="Op/Neer",2="Open/Dicht"
                //if (debug) {logInfo("SUN","    " + JaloezieName +" StartLoop: blocked state=" + sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_blocked" ].state + "  ▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state)} 
                if (sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_blocked" ].state!=ON) { //'_blocked' voorkomt aanpassing (en dus stoppen) tijdens omhoog of dicht gaan van jaloezie  en bij hoge windsterkte
                    //testregel om te zien of 'JaloezieSunControl_ForceOn.state' wel op tijd ON is. ivm soms niet in 1x reageren op drukknop
                    if ( ((sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number) < 95) || triggeringItemName=="JaloezieSunControl_ForceOn" ) { //Jaloezie niet helemaal dicht (of bijna dicht; overdag, als er geregeld mag worden)' of schakel geforceerd in (gebruik triggeringItemName ipv JaloezieSunControl_ForceOn.state ivm nog niet aangepaste state bij trigger)
                        val CalcResult= calc_slatpos.apply(WindowPosition.get(i))
						if (JaloezieSunControl_ForceOn.state==ON) {logInfo("SUN","   >" + JaloezieName + space + " ForceOn-> "+ CalcResult )} 

                        //if (debug) {logInfo("SUN","    " + JaloezieName +" CalcResult: "+ CalcResult )} 
                        var slatpos=Integer::parseInt(CalcResult.split(':').get(0))
                        if ( slatpos > (sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_minSlatpos" ].state as Number) ) {     //begrens lamel op minimum ingestelde waarde (hoger getal is dichter)
                            XtraInfo=" (slatpos "+slatpos+" verlaagd ivm maximum van " + (sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_minSlatpos" ].state as Number) + ")"
                            //logInfo("####", XtraInfo)
                            slatpos=(sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_minSlatpos" ].state as Number).intValue 
                        }
                        //logInfo("SUN", "   -" + JaloezieName  + " (" + i + ")" +": Result: " + CalcResult+ " slatpos="+slatpos)

                        if (CalcResult.split(':').get(1)=="UP") { 
                            if (sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_SunControl" ].state as Number ==1){      //OP/NEER functie staat AAN
                                if (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state as Number > 0) {   //is nog niet omhoog
                                    sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_blocked" ].sendCommand(ON) //blokkeer aanpassingen tijdelijk tot jaloezie omhoog is
                                    sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].sendCommand(UP)
                                    logInfo("SUN","   >" + JaloezieName + space + " UP  : gaat omhoog (+blok 60 sec.) [▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + "]" )
                                    
                                    //logInfo( "SUN","    "+JaloezieName + space +" BLOK: geblokkeerd gedurende 60 seconden (na UP)" )
                                    createTimer(now.plusSeconds(60),  [ |
                                        //logInfo( "SUN","    "+JaloezieName + space +" weer actief na blokkade van 60 seconden" ) 
                                        sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_blocked" ].sendCommand(OFF)
                                    ])
                                }
                                else{
                                    if (debug) {logInfo("SUN","   >" + JaloezieName + space  + " UP  : geen actie; is al omhoog [▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + "]")}
                                }                    
                            }
                            // OP/NEER functie staat NIET AAN
                            else{  
                                if (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state as Number != 0) {   //is niet omhoog
                                    val orientation_diff=slatpos - sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number
                                    if ( Math::abs(orientation_diff.intValue) > 5 ){ 
                                        logInfo("SUN","   >" + JaloezieName + space + " UP  : OP/NEER functie staat UIT nu default-open [SlatPos was:" + (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number) + " nu " + slatpos + "]"+XtraInfo)
                                        sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].sendCommand(slatpos)
                                    }
                                    else{
                                        if (debug) {logInfo("SUN","   >" + JaloezieName + space + " UP  : OP/NEER functie staat UIT en is al default-open [▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + "]")}
                                    }
                                }
                                else{
                                    if (debug) {logInfo("SUN","   >" + JaloezieName + space + " UP  : OP/NEER functie staat UIT; geen actie want is helemaal omhoog [▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + "]") }
                                }
                            }
                        }

                        if (CalcResult.split(':').get(1)=="DOWN") {
                            //Jaloezie is omhoog; eerst naar beneden
                            if (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state as Number == 0) {
                                logInfo("SUN","   >" + JaloezieName + space + " DOWN: gaat omlaag en set lamellen [SlatPos was:" + (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number) + " nu " + slatpos + "] en geblokkeerd gedurende 60 seconden" )
                                sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_blocked" ].sendCommand(ON) //blokkeer aanpassingen tijdelijk tot jaloezie omlaag is

                                //Ander mechanisme voor aansturing positie en lamelpositie tussen KLF200 en Connexoon
                                if (ControlledByConnexoon.state==ON) {  
                                    sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"_SetClosureAndOrientation" ].sendCommand("100,"+slatpos.toString())
                                }
                                else{
                                    val veluxActions = getActions("velux", "velux:klf200:192_168_178_231")
                                    if (veluxActions !== null) {
                                        val succeeded = veluxActions.moveMainAndVane("velux:rollershutter:192_168_178_231:"+JaloezieName, 100, slatpos)
                                        if (succeeded==true){
                                            logInfo("SUN","OK >" + JaloezieName + space + " veluxActions=" + veluxActions + " Set moveMainAndVane OK")
                                        }
                                        else {
                                            logInfo("SUN","ERR>" + JaloezieName + space + " veluxActions=" + veluxActions + " Unable to set moveMainAndVane")
                                        }
                                        Thread::sleep(250)  //probeersel 7-8-2023 om te testen of gelijktijdig naar beneden gaan nu betrouwbaarder werkt.
                                    }
                                    else{
                                        logInfo("SUN","ERR>" + JaloezieName + space + " Unable to get veluxActions")
                                    }
                                }
                                    

                                    //logInfo( "SUN","    "+JaloezieName + space +" BLOK: geblokkeerd gedurende 60 seconden (na DOWN SetClosureAndOrientation)" )
                                    createTimer(now.plusSeconds(60),  [ |
                                        //logInfo( "SUN","    "+JaloezieName+space +" weer actief na blokkade van 60 seconden" ) 
                                        sJaloezie.members.findFirst[ t | t.name == JaloezieName+"_blocked" ].sendCommand(OFF)
                                    ])
                            }
                            else {  
                            //Jaloezie is NIET omhoog
                                val orientation_diff=slatpos - sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number
                                if ( Math::abs(orientation_diff.intValue) >= 5 ){  //pas instellen bij groot verschil tussen huidige stand en gewenste stand
                                    logInfo("SUN","   >" + JaloezieName + space + " DOWN: stel lamellen in [SlatPos was:" + (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number) + " nu " + slatpos + "]"+XtraInfo )
                                    sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].sendCommand(slatpos)
                                }
                                else{
                                    if (debug) {logInfo("SUN","   >" + JaloezieName + space + " DOWN: is al SET [SlatPos is:" + (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number) + ", berekend " + slatpos + " ;verschil < 5 ] (▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + ")" ) }
                                }
                            }

                        }

                        if (CalcResult.split(':').get(1)=="SET") { 
                            if (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state as Number != 0) {   //is niet omhoog
                                if (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number !=0) {  //lamel niet in 'op'-stand (gaat naar boven)
                                    //pas lamel instellen bij groot verschil tussen huidige stand en gewenste stand
                                    val orientation_diff=slatpos - sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number
                                    if ( Math::abs(orientation_diff.intValue) >= 5 ){  
                                            logInfo("SUN","   >" + JaloezieName + space + " SET : stel lamellen in [SlatPos was:" + (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number) + " nu " + slatpos + "]"+XtraInfo )
                                            sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].sendCommand(slatpos)
                                    }
                                    else{
                                            if (debug) {logInfo("SUN","   >" + JaloezieName + space + " SET : geen actie; SlatPos is:" + (sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state as Number) + ", berekend " + slatpos + "; verschil < 5"+XtraInfo ) }
                                    }
                                }
                                else{
                                    logInfo("SUN","   >" + JaloezieName + space + " SET : niet instellen want lamel staat in 'op'-stand; gaat naar boven")
                                }
                            }
                            else {
                                if (debug) {logInfo("SUN","   >" + JaloezieName + space + " SET : lamellen niet instellen; is omhoog [▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + "]")}
                            }
                          
                        }
                    }
                    else {
                        if (debug) {logInfo("SUN", "   >" + JaloezieName  + space +  " SKIP: lamellen zijn DICHT [▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + "]")}
                    }
                }
                else{
                    if (debug) {logInfo("SUN","    " + JaloezieName + space +" SKIP: geblokkeerd [▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + "]")} 
                }

            }
            else {
                if (debug) {logInfo("SUN", "   >" + JaloezieName  + space +  " SKIP: besturing is UIT(_SunControl=0) [▲▼=" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"Position" ].state+ " ⦼ =" + sJaloezie.members.findFirst[ t | t.name == jPrefix+JaloezieName+"VanePosition" ].state + "]")}
            }
        }  //einde loop per raam  
        if (JaloezieSunControl_ForceOn.state==ON) {
            JaloezieSunControl_ForceOn.postUpdate(OFF) 
        }
    }
end

rule "2 Limit Jaloezie_Sunpower_Threshold_Up"
when 
    Item Jaloezie_Sunpower_Threshold_Up received command
then
    createTimer(now.plusSeconds(2), [ |
        if(Jaloezie_Sunpower_Threshold_Up.state>Jaloezie_Sunpower_Threshold_Down.state as Number){
            Jaloezie_Sunpower_Threshold_Up.sendCommand(Jaloezie_Sunpower_Threshold_Down.state as Number)
    }   ]) 
end 

 

@GeVaSta sorry for the delay. I will look at your code, and see if I can figure out what is happening.

Hi Andrew. That is nice.
Last days I noticed a few time a No Contact message from a shutter from a window in the same wall as the shutters who did not respond. I had during the time the problems occured, the loglevel (accidentally) at Error. Perhaps there was a communicationproblem in that time which I have not noticed.
Meanwhile I relocated the KLF200 to get rid of this communication problems.

And I am back after I decided to upgrade to OpenHAB 4. I can still control my windows and shutters but I get a lot of warnings about messages not being slip messages:

19:19:09.566 [DEBUG] [x.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:51a12fefea:Rollo_Kids_O_u:position,REFRESH) called.
19:19:09.567 [DEBUG] [ernal.handler.ChannelActuatorPosition] - handleRefresh(velux:rollershutter:51a12fefea:Rollo_Kids_O_u:position,position,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@17b9e8c) called.
19:19:09.567 [DEBUG] [ternal.bridge.slip.SCgetProductStatus] - getRequestCommand() returns GW_STATUS_REQUEST_REQ (0x305).
19:19:09.568 [DEBUG] [.internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.100.29] GW_STATUS_REQUEST_REQ => started => Thread[OH-velux:klf200:51a12fefea-1,5,main]
19:19:09.570 [DEBUG] [.internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.100.29] GW_STATUS_REQUEST_REQ => GW_STATUS_REQUEST_REQ => sending data length => 26
19:19:09.571 [DEBUG] [ux.internal.bridge.slip.io.Connection] - io() on 192.168.100.29: sending packet of size 33.
19:19:09.723 [DEBUG] [ux.internal.bridge.slip.io.Connection] - io() on 192.168.100.29: received packet with 10 bytes.
19:19:09.724 [DEBUG] [.internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.100.29] GW_STATUS_REQUEST_REQ => GW_STATUS_REQUEST_CFM => received data length => 3
19:19:09.725 [DEBUG] [ternal.bridge.slip.SCgetProductStatus] - setResponse(GW_STATUS_REQUEST_CFM with 3 bytes of data) called.
19:19:09.726 [DEBUG] [ternal.bridge.slip.SCgetProductStatus] - setResponse(): returned status: OK - Command is accepted.
19:19:11.833 [DEBUG] [ge.slip.io.DataInputStreamWithTimeout] - readSlipMessage() => no slip message
19:19:11.834 [DEBUG] [ux.internal.bridge.slip.io.Connection] - io() on 192.168.100.29: received packet with 0 bytes.
19:19:11.835 [DEBUG] [.internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.100.29] GW_STATUS_REQUEST_REQ => no response => aborting
19:19:11.836 [DEBUG] [.internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.100.29] GW_STATUS_REQUEST_REQ => finished => failure
19:19:11.837 [WARN ] [x.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:51a12fefea:Rollo_Kids_O_u:position,REFRESH): updating of item velux:rollershutter:51a12fefea:Rollo_Kids_O_u:position (type velux:rollershutter/position) failed.
19:19:11.838 [DEBUG] [x.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:51a12fefea:Rollo_kids_W_o:position,REFRESH) called.
19:19:11.839 [DEBUG] [ernal.handler.ChannelActuatorPosition] - handleRefresh(velux:rollershutter:51a12fefea:Rollo_kids_W_o:position,position,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@17b9e8c) called.
19:19:11.840 [DEBUG] [ternal.bridge.slip.SCgetProductStatus] - getRequestCommand() returns GW_STATUS_REQUEST_REQ (0x305).
19:19:11.841 [DEBUG] [.internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.100.29] GW_STATUS_REQUEST_REQ => started => Thread[OH-velux:klf200:51a12fefea-1,5,main]
19:19:11.842 [DEBUG] [.internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.100.29] GW_STATUS_REQUEST_REQ => GW_STATUS_REQUEST_REQ => sending data length => 26
19:19:11.843 [DEBUG] [ux.internal.bridge.slip.io.Connection] - io() on 192.168.100.29: sending packet of size 33.
19:19:12.045 [DEBUG] [ux.internal.bridge.slip.io.Connection] - io() on 192.168.100.29: received packet with 10 bytes.
19:19:12.046 [DEBUG] [.internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.100.29] GW_STATUS_REQUEST_REQ => GW_STATUS_REQUEST_CFM => received data length => 3
19:19:12.047 [DEBUG] [ternal.bridge.slip.SCgetProductStatus] - setResponse(GW_STATUS_REQUEST_CFM with 3 bytes of data) called.
19:19:12.048 [DEBUG] [ternal.bridge.slip.SCgetProductStatus] - setResponse(): returned status: OK - Command is accepted.

No idea what has changed and how to fix this. Any help would be very much appreciated. Thanks!

In your post there is only one WARN message, all the rest are debug messages indicating the flow of the binding.

Is your concern about that one WARN message?
Is it the huge amount of DEBUG messages?

If the latter, set logging for Velux to something such that debug messages won’t be logged.

I noticed when upgrading to OH4.1 that suddenly each “update” event for every single item was logged in events.log (previously only “changed” events). I found the way to disable the update logging in the forum. Something has changed in logging.

Yes, I enabled DEBUG logging in order to get to the bottom of this. The 4 DEBUG lines before the WARN message are probably the cause. If it is just a change in the logging behavior then it would be great if you could point me to how to change that. It is pretty annoying to get these WARN messages every few seconds. Thanks!

@sloth0815 please disable the bridge thing in OH, power off the KLF, then power it on again, and then reenable the bridge thing.

Unfortunately, that did not get rid of the warning messages.

To me the stream of messages looks like OH requests status update of the product, the KLF200 acknowledges receipt of OH’s request, but never (two second time-out) feeds back the current status of the product (is the KLF200 still requesting the status and does it itself not receive a status from the product?).

I’ve read of some people that had to relocate their KLF200 for better performance, possibly to a location with better reception for all products. But that is just an observation as I am in the lucky position that all products are close enough and am only experiencing the KLF200 zombie state a couple of times each year (for which I have now put in a smart plug to power cycle if that occurs).

Ok. Then please try the following (most extreme) actions…

  1. disable the bridge thing in OH
  2. power off the KLF (wait 15 seconds)
  3. power the KLF on again (wait 15 seconds)
  4. use your remote control to command all windows and shutters fully open, and then fully closed again (make sure that all motors reach the stop position in both cases)
  5. reenable the bridge thing