[velux] New OpenHAB2 binding - feedback welcome!

gs4711 · July 17, 2019, 1:49pm

got some ideas … you have defined ten scenes on the KLF, did you?

    Scene "RS2_0" (index 1) with silent mode and 1 actions
    Scene "RS2_100" (index 2) with silent mode and 1 actions
    Scene "RS3_0" (index 0) with silent mode and 1 actions
    Scene "RS3_100" (index 4) with silent mode and 1 actions
    Scene "RS4_0" (index 3) with non-silent mode and 1 actions
    Scene "RS4_100" (index 5) with non-silent mode and 1 actions
    Scene "RS5_0" (index 6) with non-silent mode and 1 actions      .
    Scene "RS5_100" (index 7) with non-silent mode and 1 actions
    Scene "RS6_0" (index 8) with non-silent mode and 1 actions
    Scene "RS6_100" (index 9) with non-silent mode and 6 actions

In addition, you’re declaring a virtual rollershutter RS2 with the following definitions:

level 0 = scene V_Shutter_2_0
level 100 = V_Shutter_2_100

In that case the binding is not able to activate scene named “V_Shutter_2_100” according to the logfile:

2019-07-17 14:12:04.432 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): found COMMAND DOWN.
2019-07-17 14:12:04.434 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): working on virtual rollershutter.
2019-07-17 14:12:04.440 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): current level is 0.
2019-07-17 14:12:04.449 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): next level is 100.
2019-07-17 14:12:04.469 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): execution scene null.

Next minor release will contain more descriptive error messages.

gs4711 · July 17, 2019, 1:57pm

For your convenience org.openhab.binding.velux-1.14.0.201907171351.jar

johannesbonn · July 17, 2019, 6:59pm

Hi @gs4711,

your config seems to be ok. here is my logging. Hope it helps:

log velux.txt (96.6 KB)

I think it started at 2019-07-17 20:52:15.568

Thank you for your support!

gs4711 · July 17, 2019, 8:11pm

Hi @johannesbonn,

thanks for the trace. The logged sequence looks fine to me - but the code which was run is probably missing the handling of the inverted actuator (two log lines with handleCommandOnChannel(): actuatorSerial=56:36:13:32:13:0A:04:DE are simply missing).

Could you please tell me the minor revision of the binding (or just replace it by the most recent one)?

Regards, Guenther

lukqw · July 18, 2019, 9:05am

Thanks I’ve fixed my velux.items File. It wasn’t really clear to me that the names are supposed to be exactly the ones from the KLF.

2019-07-18 10:58:17.044 [ome.event.ItemCommandEvent] - Item 'RS2' received command UP

==> /var/log/openhab2/openhab.log <==

2019-07-18 10:58:17.048 [TRACE] [.binding.velux.internal.VeluxBinding] - receiveCommand(RS2,UP) called.

2019-07-18 10:58:17.058 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand(RS2,UP) called.

2019-07-18 10:58:17.058 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveUpdate(RS2,UP) called.

2019-07-18 10:58:17.063 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(RS2) called.

==> /var/log/openhab2/events.log <==

2019-07-18 10:58:17.067 [vent.ItemStateChangedEvent] - RS2 changed from NULL to 0

==> /var/log/openhab2/openhab.log <==

2019-07-18 10:58:17.070 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns 0,RS2_0,100,RS2_100.

2019-07-18 10:58:17.074 [TRACE] [binding.velux.internal.VeluxItemType] - isWritable() returns true.

2019-07-18 10:58:17.077 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand() is about to send update to item RS2.

2019-07-18 10:58:17.081 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand() working with VeluxBindingProvider org.openhab.binding.velux.internal.VeluxGenericBindingProvider@344d5f.

2019-07-18 10:58:17.084 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(item=RS2,command=UP,config=org.openhab.binding.velux.internal.VeluxRSBindingConfig@1db8314,provider=org.openhab.binding.velux.internal.VeluxGenericBindingProvider@344d5f) called.

2019-07-18 10:58:17.087 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - updateOH() called.

2019-07-18 10:58:17.090 [TRACE] [g.velux.things.VeluxExistingProducts] - isDirty() returns false.

2019-07-18 10:58:17.093 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - updateOH() finished.

2019-07-18 10:58:17.097 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): openHAB items updated.

2019-07-18 10:58:17.100 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): found COMMAND UP.

2019-07-18 10:58:17.103 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): working on virtual rollershutter.

2019-07-18 10:58:17.106 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getLevel() returning 0.

2019-07-18 10:58:17.109 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): current level is 0.

2019-07-18 10:58:17.113 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getNextDescendingLevel() called.

2019-07-18 10:58:17.116 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getNextDescendingLevel() returning 0.

2019-07-18 10:58:17.119 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): next level is 0.

2019-07-18 10:58:17.122 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getSceneName(0) called.

2019-07-18 10:58:17.124 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getSceneName() returning RS2_0.

2019-07-18 10:58:17.125 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): scene name is RS2_0.

2019-07-18 10:58:17.129 [TRACE] [ing.velux.things.VeluxExistingScenes] - get(RS2_0) called.

2019-07-18 10:58:17.130 [TRACE] [ing.velux.things.VeluxExistingScenes] - isRegistered(RS2_0) returns true.

2019-07-18 10:58:17.133 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): executing scene Scene "RS2_0" (index 1) with silent mode and 1 actions with index 1.

2019-07-18 10:58:17.133 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveUpdate(RS2,0) called.

2019-07-18 10:58:17.136 [TRACE] [ing.velux.bridge.VeluxBridgeRunScene] - execute(1) called.

2019-07-18 10:58:17.137 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeAPI() called.

2019-07-18 10:58:17.138 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(run Scene) called.

2019-07-18 10:58:17.139 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.

2019-07-18 10:58:17.141 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(run Scene,authenticated) called.

2019-07-18 10:58:17.142 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.

2019-07-18 10:58:17.143 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeAPI() called.

2019-07-18 10:58:17.144 [TRACE] [ding.velux.bridge.json.JsonBridgeAPI] - bridgeDirectCommunicate(org.openhab.binding.velux.bridge.json.JCrunScene@4eca7e,true) called.

2019-07-18 10:58:17.146 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeDirectCommunicate(run Scene,authenticated) called.

2019-07-18 10:58:17.147 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeCommunicate(): using SAP http://10.3.0.10:80/api/v1/scenes.

2019-07-18 10:58:17.150 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() to http://10.3.0.10:80/api/v1/scenes using request {"action":"run","params":{"id":1}}.
2019-07-18 10:58:24.162 [ERROR] [org.openhab.io.net.http.HttpUtil    ] - Fatal transport error: java.net.SocketTimeoutException: Read timed out

2019-07-18 10:58:24.164 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): Exception occurred during I/O: transport error.

2019-07-18 10:58:24.166 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): wait time 7000 msecs.

2019-07-18 10:58:31.170 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() to http://10.3.0.10:80/api/v1/scenes using request {"action":"run","params":{"id":1}}.

2019-07-18 10:58:38.185 [ERROR] [org.openhab.io.net.http.HttpUtil    ] - Fatal transport error: java.net.SocketTimeoutException: Read timed out

2019-07-18 10:58:38.187 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): Exception occurred during I/O: transport error.

2019-07-18 10:58:38.189 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): wait time 14000 msecs.

2019-07-18 10:58:52.193 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() to http://10.3.0.10:80/api/v1/scenes using request {"action":"run","params":{"id":1}}.

2019-07-18 10:58:59.210 [ERROR] [org.openhab.io.net.http.HttpUtil    ] - Fatal transport error: java.net.SocketTimeoutException: Read timed out

2019-07-18 10:58:59.214 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): Exception occurred during I/O: transport error.

2019-07-18 10:58:59.215 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): wait time 28000 msecs.

2019-07-18 10:59:27.220 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() to http://10.3.0.10:80/api/v1/scenes using request {"action":"run","params":{"id":1}}.

2019-07-18 10:59:34.235 [ERROR] [org.openhab.io.net.http.HttpUtil    ] - Fatal transport error: java.net.SocketTimeoutException: Read timed out

2019-07-18 10:59:34.237 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): Exception occurred during I/O: transport error.

2019-07-18 10:59:34.239 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): wait time 56000 msecs.

2019-07-18 11:00:30.244 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() to http://10.3.0.10:80/api/v1/scenes using request {"action":"run","params":{"id":1}}.

2019-07-18 11:00:37.259 [ERROR] [org.openhab.io.net.http.HttpUtil    ] - Fatal transport error: java.net.SocketTimeoutException: Read timed out

2019-07-18 11:00:37.261 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): Exception occurred during I/O: transport error.

2019-07-18 11:00:37.263 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): wait time 112000 msecs.

I am not currently in range of my velux shutters, is that why I’m getting these errors when trying to control them? I think other than this issue everything is properly configured.

gs4711 · July 18, 2019, 10:06am

Hi @lukqw,

for whatever reason the response of the web interface of the KLF is a little bit slower (than normally expected). To eliminate those error messages regarding

java.net.SocketTimeoutException: Read timed out

I’d suggest to increase the timeoutMsecs parameter in the binding configuration.

lukqw · July 18, 2019, 10:29am

I’ve increased the msecs to 10000 now. I’ll look if there are any more errors occuring.

Let me rephrase the question: This error occurs continously when I try to control one of the correctly configured scenes. What should happen when the KLF is not in range of the velux shutters and therefore can’t control them?

I think that is why those SocketTimeoutExceptions appear at the end of the logs, since i want to “run” scene with id 1.

lukqw · July 18, 2019, 10:40am

Turning up the msecs to 12000 I think I got what I need

2019-07-18 12:37:55.439 [ome.event.ItemCommandEvent] - Item 'RS6' received command UP

==> /var/log/openhab2/openhab.log <==

2019-07-18 12:37:55.444 [TRACE] [.binding.velux.internal.VeluxBinding] - receiveCommand(RS6,UP) called.

2019-07-18 12:37:55.446 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand(RS6,UP) called.

2019-07-18 12:37:55.447 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveUpdate(RS6,UP) called.

2019-07-18 12:37:55.449 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(RS6) called.

2019-07-18 12:37:55.453 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns 0,RS6_0,100,RS6_100.

2019-07-18 12:37:55.457 [TRACE] [binding.velux.internal.VeluxItemType] - isWritable() returns true.

2019-07-18 12:37:55.460 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand() is about to send update to item RS6.

2019-07-18 12:37:55.464 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand() working with VeluxBindingProvider org.openhab.binding.velux.internal.VeluxGenericBindingProvider@a6cd79.

2019-07-18 12:37:55.467 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(item=RS6,command=UP,config=org.openhab.binding.velux.internal.VeluxRSBindingConfig@1eae840,provider=org.openhab.binding.velux.internal.VeluxGenericBindingProvider@a6cd79) called.

2019-07-18 12:37:55.471 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - updateOH() called.

2019-07-18 12:37:55.474 [TRACE] [g.velux.things.VeluxExistingProducts] - isDirty() returns false.

==> /var/log/openhab2/events.log <==

2019-07-18 12:37:55.474 [vent.ItemStateChangedEvent] - RS6 changed from NULL to 0

==> /var/log/openhab2/openhab.log <==

2019-07-18 12:37:55.478 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - updateOH() finished.

2019-07-18 12:37:55.481 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): openHAB items updated.

2019-07-18 12:37:55.485 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): found COMMAND UP.

2019-07-18 12:37:55.489 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): working on virtual rollershutter.

2019-07-18 12:37:55.492 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getLevel() returning 0.

2019-07-18 12:37:55.496 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): current level is 0.

2019-07-18 12:37:55.499 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getNextDescendingLevel() called.

2019-07-18 12:37:55.502 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getNextDescendingLevel() returning 0.

2019-07-18 12:37:55.504 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): next level is 0.

2019-07-18 12:37:55.506 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getSceneName(0) called.

2019-07-18 12:37:55.508 [TRACE] [.velux.internal.VeluxRSBindingConfig] - getSceneName() returning RS6_0.

2019-07-18 12:37:55.510 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): scene name is RS6_0.

2019-07-18 12:37:55.513 [TRACE] [ing.velux.things.VeluxExistingScenes] - get(RS6_0) called.

2019-07-18 12:37:55.515 [TRACE] [ing.velux.things.VeluxExistingScenes] - isRegistered(RS6_0) returns true.

2019-07-18 12:37:55.517 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): executing scene Scene "RS6_0" (index 8) with non-silent mode and 1 actions with index 8.

2019-07-18 12:37:55.519 [TRACE] [ing.velux.bridge.VeluxBridgeRunScene] - execute(8) called.

2019-07-18 12:37:55.520 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeAPI() called.

2019-07-18 12:37:55.522 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(run Scene) called.

2019-07-18 12:37:55.523 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.

2019-07-18 12:37:55.525 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(run Scene,authenticated) called.

2019-07-18 12:37:55.526 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.

2019-07-18 12:37:55.528 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeAPI() called.

2019-07-18 12:37:55.529 [TRACE] [ding.velux.bridge.json.JsonBridgeAPI] - bridgeDirectCommunicate(org.openhab.binding.velux.bridge.json.JCrunScene@5c02f9,true) called.

2019-07-18 12:37:55.531 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeDirectCommunicate(run Scene,authenticated) called.

2019-07-18 12:37:55.532 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeCommunicate(): using SAP http://10.3.0.10:80/api/v1/scenes.

2019-07-18 12:37:55.535 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() to http://10.3.0.10:80/api/v1/scenes using request {"action":"run","params":{"id":8}}.

2019-07-18 12:38:05.714 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io(): wait time 12000 msecs.

2019-07-18 12:38:07.255 [DEBUG] [.binding.velux.internal.VeluxBinding] - execute() called.

2019-07-18 12:38:07.257 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): working with VeluxBindingProvider org.openhab.binding.velux.internal.VeluxGenericBindingProvider@a6cd79.

2019-07-18 12:38:07.259 [TRACE] [internal.VeluxGenericBindingProvider] - getInBindingItemNames() returns [V_3_S_CLOSED, V_6_S_CLOSED, V_5_S_OPEN, V_4_S_OPEN, V_6_S_OPEN, V_2_S_CLOSED, V_STATUS, RS2, V_2_S_OPEN, RS4, RS3, V_3_S_OPEN, V_5_S_CLOSED, RS6, RS5, V_FIRMWARE, V_CHECK, V_4_S_CLOSED].

2019-07-18 12:38:07.261 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_3_S_CLOSED) called.

2019-07-18 12:38:07.263 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns RS3_100.

2019-07-18 12:38:07.266 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns false.

2019-07-18 12:38:07.268 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): ignoring item V_3_S_CLOSED as not-refreshable.

2019-07-18 12:38:07.270 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_6_S_CLOSED) called.

2019-07-18 12:38:07.272 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns RS6_100.

2019-07-18 12:38:07.274 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns false.

2019-07-18 12:38:07.276 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): ignoring item V_6_S_CLOSED as not-refreshable.

2019-07-18 12:38:07.277 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_5_S_OPEN) called.

2019-07-18 12:38:07.280 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns RS5_0.

2019-07-18 12:38:07.282 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns false.

2019-07-18 12:38:07.284 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): ignoring item V_5_S_OPEN as not-refreshable.

2019-07-18 12:38:07.286 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_4_S_OPEN) called.

2019-07-18 12:38:07.288 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns RS4_0.

2019-07-18 12:38:07.290 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns false.

2019-07-18 12:38:07.292 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): ignoring item V_4_S_OPEN as not-refreshable.

2019-07-18 12:38:07.294 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_6_S_OPEN) called.

2019-07-18 12:38:07.296 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns RS6_0.

2019-07-18 12:38:07.298 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns false.

2019-07-18 12:38:07.300 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): ignoring item V_6_S_OPEN as not-refreshable.

2019-07-18 12:38:07.302 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_2_S_CLOSED) called.

2019-07-18 12:38:07.304 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns RS2_100.

2019-07-18 12:38:07.306 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns false.

2019-07-18 12:38:07.308 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): ignoring item V_2_S_CLOSED as not-refreshable.

2019-07-18 12:38:07.310 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_STATUS) called.

2019-07-18 12:38:07.312 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns thing=bridge;channel=status.

2019-07-18 12:38:07.314 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns true.

2019-07-18 12:38:07.316 [TRACE] [binding.velux.internal.VeluxItemType] - getRefreshDivider() returns 1.

2019-07-18 12:38:07.318 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): refreshing item V_STATUS.

2019-07-18 12:38:07.320 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(item=V_STATUS,command=null,config=org.openhab.binding.velux.internal.VeluxBindingConfig@aefa93,provider=org.openhab.binding.velux.internal.VeluxGenericBindingProvider@a6cd79) called.

2019-07-18 12:38:17.717 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() got response )]}',.{"token":"FzRaZK87dwD+cT4iFHxxcw==","result":false,"deviceStatus":"BUSY","data":{},"errors":[207]}.

2019-07-18 12:38:17.720 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() cleaned response {"token":"FzRaZK87dwD+cT4iFHxxcw==","result":false,"deviceStatus":"BUSY","data":{},"errors":[207]}.

2019-07-18 12:38:17.725 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeCommunicate(): communication result is false, returning details.

2019-07-18 12:38:17.727 [TRACE] [ing.velux.bridge.VeluxBridgeRunScene] - execute() finished with failure.

2019-07-18 12:38:17.729 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel() done.

2019-07-18 12:38:17.732 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - updateOH() called.

2019-07-18 12:38:17.732 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand() done.

2019-07-18 12:38:17.734 [TRACE] [g.velux.things.VeluxExistingProducts] - isDirty() returns false.

2019-07-18 12:38:17.734 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveUpdate(RS6,0) called.

2019-07-18 12:38:17.736 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - updateOH() finished.

2019-07-18 12:38:17.738 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): openHAB items updated.

2019-07-18 12:38:17.740 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): work on refresh.

2019-07-18 12:38:17.742 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_STATUS) called.

2019-07-18 12:38:17.744 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns thing=bridge;channel=status.

2019-07-18 12:38:17.746 [TRACE] [binding.velux.internal.VeluxItemType] - isReadable() returns true.

2019-07-18 12:38:17.747 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): refreshing item V_STATUS.

2019-07-18 12:38:17.750 [TRACE] [velux.bridge.VeluxBridgeDeviceStatus] - VeluxBridgeDeviceStatus(constructor) called.

2019-07-18 12:38:17.751 [TRACE] [velux.bridge.VeluxBridgeDeviceStatus] - retrieve() called. About to query device status.

2019-07-18 12:38:17.753 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeAPI() called.

2019-07-18 12:38:17.755 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(get device status) called.

2019-07-18 12:38:17.757 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.

2019-07-18 12:38:17.759 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(get device status,authenticated) called.

2019-07-18 12:38:17.761 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.

2019-07-18 12:38:17.764 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeAPI() called.

2019-07-18 12:38:17.766 [TRACE] [ding.velux.bridge.json.JsonBridgeAPI] - bridgeDirectCommunicate(org.openhab.binding.velux.bridge.json.JCgetDeviceStatus@dd333e,true) called.

2019-07-18 12:38:17.768 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeDirectCommunicate(get device status,authenticated) called.

2019-07-18 12:38:17.770 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - bridgeCommunicate(): using SAP http://10.3.0.10:80/api/v1/device.

2019-07-18 12:38:17.775 [TRACE] [ng.velux.bridge.json.JsonVeluxBridge] - io() to http://10.3.0.10:80/api/v1/device using request {"action":"getDeviceStatus","params":{}}.

Thank you @gs4711

gs4711 · July 18, 2019, 10:48am

Sorry, @lukqw, for the confusion … now I’ve hopefully got your question:

With KLF firmware one you will not recognize this failure situation: The binding will return a success in spite of the loss of signal.
With the 2.x firmware, you’ll notice the unavailability of the actuator as the device position will be reported as unknown.

Regards, Guenther

lukqw · July 18, 2019, 11:00am

Alright thanks for clearing that up!
Let me bring up one more case, sorry for the long log output: Here I tried to play the scene RS6_0

openhab.log (68.7 KB)

Let me highlight the important stuff:

io() to http://10.3.0.10:80/api/v1/scenes using request {"action":"run","params":{"id":8}}

tells the KLF to execute scene 8.

And with every response to future requests:

io() to http://10.3.0.10:80/api/v1/device using request {"action":"getDeviceStatus","params":{}}.

I get the same response:

io() cleaned response {"token":"4RBZBW9fTE+yMzBwYlj4Ig==","result":false,"deviceStatus":"BUSY","data":{},"errors":[207]}.

Except for the last and then subsequent responses where I get ERROR instead of BUSY

io() cleaned response {"token":"4RBZBW9fTE+yMzBwYlj4Ig==","result":true,"deviceStatus":"ERROR","data":{},"errors":[]}.

I get this ERROR response forever, and can “fix” it by restarting the binding/openhab2.

gs4711 · July 18, 2019, 11:29am

Good point, @lukqw !

I’ll check with a Velux engineer about the reason of this behaviour of the KLF200. In between a possible solution could be to tear down the connection.

lukqw · July 18, 2019, 12:13pm

Thanks in advance!

funcat · July 18, 2019, 3:02pm

Hi all,
First of all, many many thanks for all the work here.
I bought a klf-200 with stock 2.xx and have openhab-2.4 (indeed for this thread …).
After hours of check/review/config/tests, i now have a successfull installed KLF, with corect web and API access, and 13 devices configured inside (12 somfy roller shutter and 1 garage door somfy).
From webgui, all is installed correctly and fully functional and operational (the 32 scenes are all OK)
From openhab, binding is OK (“succefull logged in” …) but it can discover only 1 actuator.
So far my problem is closed to another user (Antares), because the actuator has only a name without serial (00:00:00 …) and other are on the status “update() failed as actuator (with index **) is not registered”.
TLTR :

KLF webgui : all 13 devices OK, can control everything
Openhab binding : connected, but only see 1 device (random?) with no serial (and i can control it with slider for exemple, with serial 00:00:00…)

I can post many logs if needed.
Is there a tip/advice to ‘force’ discovering all my 13 devices in openhab ?
Many thanks

gs4711 · July 18, 2019, 3:33pm

Hi Fabien @funcat,

thanks for your explanation. You are one of the first Somfy users and I’m glad to get in contact with you for solving the issues with such io-homecontrolled devices!

According to the statements of the Velux engineer, the gateway should be enable to handle it on the API. Could you please enhance the log level to trace and activate a bridge:reload channel?

Best regards, Guenther

Kim_Andersen · July 18, 2019, 4:23pm

Hi @gs4711

This is what happens everytime my rule fire for running my Velux windows:

2019-07-18 18:10:06.339 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.348 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.376 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.383 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.413 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.420 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.434 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.441 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.467 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.478 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.502 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.512 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.530 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.537 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.551 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.555 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_COMMAND_RUN_STATUS_NTF, continuing.
2019-07-18 18:10:06.558 [WARN ] [binding.velux.bridge.slip.SCrunScene] - setResponse(): received GW_SESSION_FINISHED_NTF.

gs4711 · July 18, 2019, 5:02pm

Hello @Kim_Andersen,

this looks like left-over debugging code to me … come back soon.

Kim_Andersen · July 18, 2019, 5:04pm

It´s not… This is the info log level.
I´ll activate the debug level so we can see whats happning. Stay tuned!

funcat · July 18, 2019, 5:06pm

Hi Guenther,
I added a reload channel, but cannot upload file logs because i am a new user.
To simplify i remove all devices and scene from klf200 and let only 2 devices and 2 scenes.
Devices : “bureau”, “chambre”
Schenes : “chambremy”, “chamnbredown” (linked to device “chambre”)
Result is the same : only 1 device found with 00 serial.

Some log extract :

2019-07-18 18:53:18.978 [TRACE] [.binding.velux.internal.VeluxBinding] - receiveCommand(Velux_Reload,ON) called.
2019-07-18 18:53:18.982 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand(Velux_Reload,ON) called.
2019-07-18 18:53:18.987 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(Velux_Reload) called.
2019-07-18 18:53:18.992 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns thing=bridge;channel=reload.
2019-07-18 18:53:18.996 [TRACE] [binding.velux.internal.VeluxItemType] - isWritable() returns false.
2019-07-18 18:53:19.000 [TRACE] [binding.velux.internal.VeluxItemType] - isExecutable() returns true.
2019-07-18 18:53:19.004 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand() is about to send update to item Velux_Reload.
2019-07-18 18:53:19.008 [TRACE] [.binding.velux.internal.VeluxBinding] - internalReceiveCommand() working with VeluxBindingProvider org.openhab.binding.velux.internal.VeluxGenericBindingProvider@1cf0407.
2019-07-18 18:53:19.012 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(item=Velux_Reload,command=ON,config=org.openhab.binding.velux.internal.VeluxBindingConfig@1e3e35,provider=org.openhab.binding.velux.internal.VeluxGenericBindingProvider@1cf0407) called.
2019-07-18 18:53:19.016 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - updateOH() called.
2019-07-18 18:53:19.021 [TRACE] [g.velux.things.VeluxExistingProducts] - isDirty() returns false.
2019-07-18 18:53:19.025 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - updateOH() finished.
2019-07-18 18:53:19.029 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): openHAB items updated.
2019-07-18 18:53:19.033 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): found COMMAND ON.
2019-07-18 18:53:19.038 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): about to reload informations from veluxBridge.
2019-07-18 18:53:19.042 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated() called.
2019-07-18 18:53:19.046 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated(): choosing SLIP as communication method.
2019-07-18 18:53:19.050 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeLogin() called.
2019-07-18 18:53:19.054 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2019-07-18 18:53:19.057 [TRACE] [ab.binding.velux.bridge.slip.SClogin] - setPassword(qMavQ8tcSt) called.
2019-07-18 18:53:19.060 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(Authenticate / login,unauthenticated) called.
2019-07-18 18:53:19.063 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.
2019-07-18 18:53:19.065 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2019-07-18 18:53:19.068 [TRACE] [ding.velux.bridge.slip.SlipBridgeAPI] - bridgeDirectCommunicate(org.openhab.binding.velux.bridge.slip.SClogin@17d1037,false) called.
2019-07-18 18:53:19.071 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(Authenticate / login,unauthenticated) called.
2019-07-18 18:53:19.074 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ,unauthenticated) called.
2019-07-18 18:53:19.077 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_PASSWORD_ENTER_REQ with 32 bytes of data.
2019-07-18 18:53:19.080 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) for command 0x3000 with data size 32 called.
2019-07-18 18:53:19.083 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 23 30 00 71 4D 61 76 51 38 74 63 53 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 61.
2019-07-18 18:53:19.087 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): transportEncoding=00 23 30 00 71 4D 61 76 51 38 74 63 53 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 61.
2019-07-18 18:53:19.090 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - encode() for data size 37 called.
2019-07-18 18:53:19.093 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - encode() provides transfer encoding: C0 00 23 30 00 71 4D 61 76 51 38 74 63 53 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 61 C0.
2019-07-18 18:53:19.096 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): sending 39 bytes to 192.168.0.23:51200.
2019-07-18 18:53:19.098 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(192.168.0.23,51200,39 bytes) called.
2019-07-18 18:53:19.102 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): sending packet with 39 bytes: C0 00 23 30 00 71 4D 61 76 51 38 74 63 53 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 61 C0
2019-07-18 18:53:19.105 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - send() called, writing 39 bytes.
2019-07-18 18:53:19.109 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - send() finished after having send 39 bytes: C0 00 23 30 00 71 4D 61 76 51 38 74 63 53 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 61 C0
2019-07-18 18:53:19.112 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): wait time 2000 msecs.
2019-07-18 18:53:21.115 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): receiving bytes.
2019-07-18 18:53:21.118 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() called.
2019-07-18 18:53:21.124 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() finished after having read 8 bytes: C0 00 04 30 01 00 35 C0
2019-07-18 18:53:21.128 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 8 bytes: C0 00 04 30 01 00 35 C0
2019-07-18 18:53:21.132 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io() finished.
2019-07-18 18:53:21.136 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): received packet C0 00 04 30 01 00 35 C0.
2019-07-18 18:53:21.141 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() for packet size 8 called.
2019-07-18 18:53:21.145 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() provides payload: 00 04 30 01 00 35.
2019-07-18 18:53:21.149 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 6.
2019-07-18 18:53:21.153 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x3001 .
2019-07-18 18:53:21.157 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 1 bytes: 00.
2019-07-18 18:53:21.162 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x3001 and data 00.
2019-07-18 18:53:21.166 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x3001 .
2019-07-18 18:53:21.170 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 1 bytes: 00.
2019-07-18 18:53:21.174 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_PASSWORD_ENTER_CFM with 1 bytes of data.
2019-07-18 18:53:21.178 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): passes back command 0x3001 and data 00.
2019-07-18 18:53:21.182 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(GW_PASSWORD_ENTER_CFM with 1 bytes of data) called.
2019-07-18 18:53:21.184 [TRACE] [ab.binding.velux.bridge.slip.SClogin] - setResponse(): handling response GW_PASSWORD_ENTER_CFM (0x3001).
2019-07-18 18:53:21.187 [TRACE] [ab.binding.velux.bridge.slip.SClogin] - isLengthValid() called for GW_PASSWORD_ENTER_CFM (0x3001) with 1 bytes of data.
2019-07-18 18:53:21.190 [TRACE] [ab.binding.velux.bridge.slip.SClogin] - isLengthValid() returns true.
2019-07-18 18:53:21.192 [INFO ] [ab.binding.velux.bridge.slip.SClogin] - velux bridge connection successfully established (login succeeded).
2019-07-18 18:53:21.195 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(): returned status: The request was successful.
2019-07-18 18:53:21.197 [TRACE] [ab.binding.velux.bridge.slip.SClogin] - setResponse(): finished=true,success=true.
2019-07-18 18:53:21.200 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ) returns success.
2019-07-18 18:53:21.203 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeLogin(): communication succeeded.
2019-07-18 18:53:21.205 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeLogin(): storing authentication token for further access.
2019-07-18 18:53:21.208 [TRACE] [ab.binding.velux.bridge.slip.SClogin] - getAuthToken() called, returning qMavQ8tcSt.
2019-07-18 18:53:21.210 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated(): Querying bridge state.
2019-07-18 18:53:21.213 [TRACE] [velux.bridge.VeluxBridgeDeviceStatus] - VeluxBridgeDeviceStatus(constructor) called.
2019-07-18 18:53:21.215 [TRACE] [velux.bridge.VeluxBridgeDeviceStatus] - retrieve() called. About to query device status.
2019-07-18 18:53:21.218 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2019-07-18 18:53:21.220 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(Get Bridge Device Status) called.
2019-07-18 18:53:21.223 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.
2019-07-18 18:53:21.225 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(Get Bridge Device Status,authenticated) called.
2019-07-18 18:53:21.228 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.
2019-07-18 18:53:21.230 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2019-07-18 18:53:21.233 [TRACE] [ding.velux.bridge.slip.SlipBridgeAPI] - bridgeDirectCommunicate(org.openhab.binding.velux.bridge.slip.SCgetDeviceStatus@48aaf9,true) called.
2019-07-18 18:53:21.235 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(Get Bridge Device Status,authenticated) called.
2019-07-18 18:53:21.238 [DEBUG] [.velux.bridge.slip.SCgetDeviceStatus] - getRequestCommand() returns GW_GET_STATE_REQ (0xc).
2019-07-18 18:53:21.240 [TRACE] [.velux.bridge.slip.SCgetDeviceStatus] - getRequestDataAsArrayOfBytes() returns data.
2019-07-18 18:53:21.243 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_GET_STATE_REQ,authenticated) called.
2019-07-18 18:53:21.246 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_GET_STATE_REQ with 0 bytes of data.
2019-07-18 18:53:21.248 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) for command 0xc with data size 0 called.
2019-07-18 18:53:21.251 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 03 00 0C 0F.
2019-07-18 18:53:21.254 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): transportEncoding=00 03 00 0C 0F.
2019-07-18 18:53:21.256 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - encode() for data size 5 called.
2019-07-18 18:53:21.259 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - encode() provides transfer encoding: C0 00 03 00 0C 0F C0.
2019-07-18 18:53:21.262 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): sending 7 bytes to 192.168.0.23:51200.
2019-07-18 18:53:21.264 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(192.168.0.23,51200,7 bytes) called.
2019-07-18 18:53:21.267 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): sending packet with 7 bytes: C0 00 03 00 0C 0F C0
2019-07-18 18:53:21.270 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - send() called, writing 7 bytes.
2019-07-18 18:53:21.273 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - send() finished after having send 7 bytes: C0 00 03 00 0C 0F C0
2019-07-18 18:53:21.276 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): wait time 2000 msecs.
2019-07-18 18:53:23.279 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): receiving bytes.
2019-07-18 18:53:23.282 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() called.
2019-07-18 18:53:23.289 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() finished after having read 13 bytes: C0 00 09 00 0D 02 00 00 00 00 00 06 C0
2019-07-18 18:53:23.293 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 13 bytes: C0 00 09 00 0D 02 00 00 00 00 00 06 C0
2019-07-18 18:53:23.297 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io() finished.
2019-07-18 18:53:23.301 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): received packet C0 00 09 00 0D 02 00 00 00 00 00 06 C0.
2019-07-18 18:53:23.305 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() for packet size 13 called.
2019-07-18 18:53:23.310 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() provides payload: 00 09 00 0D 02 00 00 00 00 00 06.
2019-07-18 18:53:23.314 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 11.
2019-07-18 18:53:23.318 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x0D .
2019-07-18 18:53:23.322 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 6 bytes: 02 00 00 00 00 00.
2019-07-18 18:53:23.327 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x0D and data 02 00 00 00 00 00.
2019-07-18 18:53:23.331 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x0D .
2019-07-18 18:53:23.335 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 6 bytes: 02 00 00 00 00 00.
2019-07-18 18:53:23.340 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_GET_STATE_CFM with 6 bytes of data.
2019-07-18 18:53:23.344 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): passes back command 0xd and data 02 00 00 00 00 00.
2019-07-18 18:53:23.348 [DEBUG] [.velux.bridge.slip.SCgetDeviceStatus] - setResponse(GW_GET_STATE_CFM with 6 bytes of data) called.
2019-07-18 18:53:23.352 [TRACE] [.velux.bridge.slip.SCgetDeviceStatus] - setResponse(): handling response GW_GET_STATE_CFM (0xd).
2019-07-18 18:53:23.356 [TRACE] [.velux.bridge.slip.SCgetDeviceStatus] - isLengthValid() called for GW_GET_STATE_CFM (0xd) with 6 bytes of data.
2019-07-18 18:53:23.360 [TRACE] [.velux.bridge.slip.SCgetDeviceStatus] - isLengthValid() returns true.
2019-07-18 18:53:23.364 [TRACE] [.velux.bridge.slip.SCgetDeviceStatus] - setResponse(): finished=true,success=true.
2019-07-18 18:53:23.368 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_GET_STATE_REQ) returns success.
2019-07-18 18:53:23.372 [TRACE] [ab.binding.velux.things.VeluxGwState] - VeluxGwState() created.
2019-07-18 18:53:23.376 [TRACE] [.velux.bridge.slip.SCgetDeviceStatus] - getState() returns GW_S_GWM/GW_SS_IDLE (Gateway mode, with one or more actuator nodes in the system table., Idle state.).
2019-07-18 18:53:23.380 [TRACE] [velux.bridge.VeluxBridgeDeviceStatus] - retrieve() finished successfully with result Gateway mode, with one or more actuator nodes in the system table., Idle state..
2019-07-18 18:53:23.384 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated(): Fetching existing scenes.
2019-07-18 18:53:23.387 [TRACE] [nding.velux.bridge.VeluxBridgeScenes] - getScenes() called.
2019-07-18 18:53:23.391 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2019-07-18 18:53:23.395 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Scenes) called.
2019-07-18 18:53:23.399 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.
2019-07-18 18:53:23.403 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Scenes,authenticated) called.
2019-07-18 18:53:23.407 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.
2019-07-18 18:53:23.411 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2019-07-18 18:53:23.414 [TRACE] [ding.velux.bridge.slip.SlipBridgeAPI] - bridgeDirectCommunicate(org.openhab.binding.velux.bridge.slip.SCgetScenes@8e46fb,true) called.
2019-07-18 18:53:23.418 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(Retrieve Scenes,authenticated) called.
2019-07-18 18:53:23.421 [DEBUG] [inding.velux.bridge.slip.SCgetScenes] - getRequestCommand() returns GW_GET_SCENE_LIST_REQ (0x40c).
2019-07-18 18:53:23.424 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_GET_SCENE_LIST_REQ,authenticated) called.
2019-07-18 18:53:23.427 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_GET_SCENE_LIST_REQ with 0 bytes of data.
2019-07-18 18:53:23.430 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) for command 0x40c with data size 0 called.
2019-07-18 18:53:23.432 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 03 04 0C 0B.
2019-07-18 18:53:23.435 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): transportEncoding=00 03 04 0C 0B.
2019-07-18 18:53:23.438 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - encode() for data size 5 called.
2019-07-18 18:53:23.441 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - encode() provides transfer encoding: C0 00 03 04 0C 0B C0.
2019-07-18 18:53:23.444 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): sending 7 bytes to 192.168.0.23:51200.
2019-07-18 18:53:23.446 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(192.168.0.23,51200,7 bytes) called.
2019-07-18 18:53:23.449 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): sending packet with 7 bytes: C0 00 03 04 0C 0B C0
2019-07-18 18:53:23.452 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - send() called, writing 7 bytes.
2019-07-18 18:53:23.455 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - send() finished after having send 7 bytes: C0 00 03 04 0C 0B C0
2019-07-18 18:53:23.458 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): wait time 2000 msecs.
2019-07-18 18:53:24.286 [DEBUG] [.binding.velux.internal.VeluxBinding] - execute() called.
2019-07-18 18:53:24.289 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): working with VeluxBindingProvider org.openhab.binding.velux.internal.VeluxGenericBindingProvider@1cf0407.
2019-07-18 18:53:24.293 [TRACE] [internal.VeluxGenericBindingProvider] - getInBindingItemNames() returns [V_DG_M_W, Velux_Check, Velux_Firmware, Velux_Status, Velux_Reload].
2019-07-18 18:53:24.296 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(V_DG_M_W) called.
2019-07-18 18:53:24.299 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns 00:00:00:00:00:00:00:00.
2019-07-18 18:53:24.303 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns true.
2019-07-18 18:53:24.306 [TRACE] [binding.velux.internal.VeluxItemType] - getRefreshDivider() returns 20.
2019-07-18 18:53:24.309 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): refresh cycle not yet come for item V_DG_M_W.
2019-07-18 18:53:24.313 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(Velux_Check) called.
2019-07-18 18:53:24.316 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns thing=bridge;channel=check.
2019-07-18 18:53:24.320 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns true.
2019-07-18 18:53:24.323 [TRACE] [binding.velux.internal.VeluxItemType] - getRefreshDivider() returns 5760.
2019-07-18 18:53:24.327 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): refresh cycle not yet come for item Velux_Check.
2019-07-18 18:53:24.330 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(Velux_Firmware) called.
2019-07-18 18:53:24.333 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns thing=bridge;channel=firmware.
2019-07-18 18:53:24.337 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns false.
2019-07-18 18:53:24.340 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): ignoring item Velux_Firmware as not-refreshable.
2019-07-18 18:53:24.344 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName(Velux_Status) called.
2019-07-18 18:53:24.347 [TRACE] [internal.VeluxGenericBindingProvider] - getConfigForItemName() returns thing=bridge;channel=status.
2019-07-18 18:53:24.350 [TRACE] [binding.velux.internal.VeluxItemType] - isToBeRefreshed() returns true.
2019-07-18 18:53:24.354 [TRACE] [binding.velux.internal.VeluxItemType] - getRefreshDivider() returns 1.
2019-07-18 18:53:24.357 [TRACE] [.binding.velux.internal.VeluxBinding] - execute(): refreshing item Velux_Status.
2019-07-18 18:53:24.360 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(item=Velux_Status,command=null,config=org.openhab.binding.velux.internal.VeluxBindingConfig@95dd7,provider=org.openhab.binding.velux.internal.VeluxGenericBindingProvider@1cf0407) called.
2019-07-18 18:53:25.461 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): receiving bytes.
2019-07-18 18:53:25.464 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() called.
2019-07-18 18:53:25.469 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() finished after having read 8 bytes: C0 00 04 04 0D 02 0F C0
2019-07-18 18:53:25.472 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 8 bytes: C0 00 04 04 0D 02 0F C0
2019-07-18 18:53:25.475 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io() finished.
2019-07-18 18:53:25.478 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): received packet C0 00 04 04 0D 02 0F C0.
2019-07-18 18:53:25.481 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() for packet size 8 called.
2019-07-18 18:53:25.484 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() provides payload: 00 04 04 0D 02 0F.
2019-07-18 18:53:25.488 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 6.
2019-07-18 18:53:25.501 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x40D .
2019-07-18 18:53:25.508 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 1 bytes: 02.
2019-07-18 18:53:25.511 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x40D and data 02.
2019-07-18 18:53:25.514 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x40D .
2019-07-18 18:53:25.518 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 1 bytes: 02.
2019-07-18 18:53:25.521 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_GET_SCENE_LIST_CFM with 1 bytes of data.
2019-07-18 18:53:25.524 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): passes back command 0x40d and data 02.
2019-07-18 18:53:25.528 [DEBUG] [inding.velux.bridge.slip.SCgetScenes] - setResponse(GW_GET_SCENE_LIST_CFM with 1 bytes of data) called.
2019-07-18 18:53:25.531 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): handling response GW_GET_SCENE_LIST_CFM (0x40d).
2019-07-18 18:53:25.534 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - isLengthValid() called for GW_GET_SCENE_LIST_CFM (0x40d) with 1 bytes of data.
2019-07-18 18:53:25.559 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - isLengthValid() returns true.
2019-07-18 18:53:25.562 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): 2 scenes defined.
2019-07-18 18:53:25.565 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): finished=false,success=false.
2019-07-18 18:53:25.569 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): receiving from 192.168.0.23:51200.
2019-07-18 18:53:25.572 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(192.168.0.23,51200,0 bytes) called.
2019-07-18 18:53:25.575 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): receiving bytes.
2019-07-18 18:53:25.578 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() called.
2019-07-18 18:53:25.590 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() finished after having read 139 bytes: C0 00 87 04 0E 02 00 63 68 61 6D 62 72 65 6D 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 63 68 61 6D 62 72 65 64 6F 77 6E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 88 C0
2019-07-18 18:53:25.610 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 139 bytes: C0 00 87 04 0E 02 00 63 68 61 6D 62 72 65 6D 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 63 68 61 6D 62 72 65 64 6F 77 6E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 88 C0
2019-07-18 18:53:25.615 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io() finished.
2019-07-18 18:53:25.623 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): received packet C0 00 87 04 0E 02 00 63 68 61 6D 62 72 65 6D 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 63 68 61 6D 62 72 65 64 6F 77 6E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 88 C0.
2019-07-18 18:53:25.628 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() for packet size 139 called.
2019-07-18 18:53:25.635 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() provides payload: 00 87 04 0E 02 00 63 68 61 6D 62 72 65 6D 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 63 68 61 6D 62 72 65 64 6F 77 6E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 88.
2019-07-18 18:53:25.640 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 137.
2019-07-18 18:53:25.642 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x40E .
2019-07-18 18:53:25.648 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 132 bytes: 02 00 63 68 61 6D 62 72 65 6D 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 63 68 61 6D 62 72 65 64 6F 77 6E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2019-07-18 18:53:25.652 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x40E and data 02 00 63 68 61 6D 62 72 65 6D 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 63 68 61 6D 62 72 65 64 6F 77 6E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2019-07-18 18:53:25.654 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x40E .
2019-07-18 18:53:25.658 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 132 bytes: 02 00 63 68 61 6D 62 72 65 6D 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 63 68 61 6D 62 72 65 64 6F 77 6E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2019-07-18 18:53:25.661 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_GET_SCENE_LIST_NTF with 132 bytes of data.
2019-07-18 18:53:25.667 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): passes back command 0x40e and data 02 00 63 68 61 6D 62 72 65 6D 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 63 68 61 6D 62 72 65 64 6F 77 6E 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2019-07-18 18:53:25.669 [DEBUG] [inding.velux.bridge.slip.SCgetScenes] - setResponse(GW_GET_SCENE_LIST_NTF with 132 bytes of data) called.
2019-07-18 18:53:25.672 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): handling response GW_GET_SCENE_LIST_NTF (0x40e).
2019-07-18 18:53:25.675 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): NTF number of objects=2.
2019-07-18 18:53:25.677 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): scene 0, name chambremy.
2019-07-18 18:53:25.680 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): scene 1, name chambredown.
2019-07-18 18:53:25.682 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): 0 scenes remaining.
2019-07-18 18:53:25.684 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): finished.
2019-07-18 18:53:25.686 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - setResponse(): finished=true,success=true.
2019-07-18 18:53:25.688 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_GET_SCENE_LIST_REQ) returns success.
2019-07-18 18:53:25.690 [TRACE] [inding.velux.bridge.slip.SCgetScenes] - getScenes(): returning 2 scenes.
2019-07-18 18:53:25.692 [TRACE] [nding.velux.bridge.VeluxBridgeScenes] - getScenes() found scene Scene "chambremy" (index 0) with non-silent mode and 0 actions.
2019-07-18 18:53:25.694 [TRACE] [nding.velux.bridge.VeluxBridgeScenes] - getScenes() storing scene Scene "chambremy" (index 0) with non-silent mode and 0 actions.
2019-07-18 18:53:25.695 [TRACE] [ing.velux.things.VeluxExistingScenes] - isRegistered(chambremy) returns true.
2019-07-18 18:53:25.698 [TRACE] [nding.velux.bridge.VeluxBridgeScenes] - getScenes() stored scene Scene "chambremy" (index 0) with non-silent mode and 0 actions.
2019-07-18 18:53:25.699 [TRACE] [nding.velux.bridge.VeluxBridgeScenes] - getScenes() found scene Scene "chambredown" (index 1) with non-silent mode and 0 actions.
2019-07-18 18:53:25.702 [TRACE] [nding.velux.bridge.VeluxBridgeScenes] - getScenes() storing scene Scene "chambredown" (index 1) with non-silent mode and 0 actions.
2019-07-18 18:53:25.703 [TRACE] [ing.velux.things.VeluxExistingScenes] - isRegistered(chambredown) returns true.
2019-07-18 18:53:25.705 [TRACE] [nding.velux.bridge.VeluxBridgeScenes] - getScenes() stored scene Scene "chambredown" (index 1) with non-silent mode and 0 actions.
2019-07-18 18:53:25.707 [DEBUG] [nding.velux.bridge.VeluxBridgeScenes] - getScenes() finally has found scenes 2 members: Scene "chambremy" (index 0) with non-silent mode and 0 actions,Scene "chambredown" (index 1) with non-silent mode and 0 actions.
2019-07-18 18:53:25.709 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - Found velux scenes:
2019-07-18 18:53:25.711 [TRACE] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated(): Fetching existing actuators/products.
2019-07-18 18:53:25.713 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - getProducts() called.
2019-07-18 18:53:25.714 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2019-07-18 18:53:25.716 [TRACE] [ng.velux.bridge.VeluxBridgeActuators] - getProducts() working on bulk retrieval.
2019-07-18 18:53:25.717 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Products) called.
2019-07-18 18:53:25.719 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.
2019-07-18 18:53:25.721 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - bridgeCommunicate(Retrieve Products,authenticated) called.
2019-07-18 18:53:25.723 [TRACE] [hab.binding.velux.bridge.VeluxBridge] - isAuthenticated() returns true.
2019-07-18 18:53:25.724 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2019-07-18 18:53:25.726 [TRACE] [ding.velux.bridge.slip.SlipBridgeAPI] - bridgeDirectCommunicate(org.openhab.binding.velux.bridge.slip.SCgetProducts@1797f28,true) called.
2019-07-18 18:53:25.728 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(Retrieve Products,authenticated) called.
2019-07-18 18:53:25.730 [DEBUG] [ding.velux.bridge.slip.SCgetProducts] - getRequestCommand() returns GW_GET_ALL_NODES_INFORMATION_REQ (0x202).
2019-07-18 18:53:25.731 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_GET_ALL_NODES_INFORMATION_REQ,authenticated) called.
2019-07-18 18:53:25.733 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_GET_ALL_NODES_INFORMATION_REQ with 0 bytes of data.
2019-07-18 18:53:25.735 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) for command 0x202 with data size 0 called.
2019-07-18 18:53:25.737 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 03 02 02 03.
2019-07-18 18:53:25.739 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): transportEncoding=00 03 02 02 03.
2019-07-18 18:53:25.741 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - encode() for data size 5 called.
2019-07-18 18:53:25.743 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - encode() provides transfer encoding: C0 00 03 02 02 03 C0.
2019-07-18 18:53:25.745 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): sending 7 bytes to 192.168.0.23:51200.
2019-07-18 18:53:25.746 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(192.168.0.23,51200,7 bytes) called.
2019-07-18 18:53:25.748 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): sending packet with 7 bytes: C0 00 03 02 02 03 C0
2019-07-18 18:53:25.750 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - send() called, writing 7 bytes.
2019-07-18 18:53:25.752 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - send() finished after having send 7 bytes: C0 00 03 02 02 03 C0
2019-07-18 18:53:25.754 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): wait time 2000 msecs.
2019-07-18 18:53:27.756 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): receiving bytes.
2019-07-18 18:53:27.759 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() called.
2019-07-18 18:53:27.762 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() finished after having read 9 bytes: C0 00 05 02 03 00 02 06 C0
2019-07-18 18:53:27.764 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 9 bytes: C0 00 05 02 03 00 02 06 C0
2019-07-18 18:53:27.766 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io() finished.
2019-07-18 18:53:27.769 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): received packet C0 00 05 02 03 00 02 06 C0.
2019-07-18 18:53:27.771 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() for packet size 9 called.
2019-07-18 18:53:27.773 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() provides payload: 00 05 02 03 00 02 06.
2019-07-18 18:53:27.776 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 7.
2019-07-18 18:53:27.778 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x203 .
2019-07-18 18:53:27.780 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 2 bytes: 00 02.
2019-07-18 18:53:27.782 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x203 and data 00 02.
2019-07-18 18:53:27.785 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x203 .
2019-07-18 18:53:27.787 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 2 bytes: 00 02.
2019-07-18 18:53:27.789 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_GET_ALL_NODES_INFORMATION_CFM with 2 bytes of data.
2019-07-18 18:53:27.791 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): passes back command 0x203 and data 00 02.
2019-07-18 18:53:27.793 [DEBUG] [ding.velux.bridge.slip.SCgetProducts] - setResponse(GW_GET_ALL_NODES_INFORMATION_CFM with 2 bytes of data) called.
2019-07-18 18:53:27.796 [TRACE] [ding.velux.bridge.slip.SCgetProducts] - setResponse(): handling response GW_GET_ALL_NODES_INFORMATION_CFM (0x203).
2019-07-18 18:53:27.798 [TRACE] [ding.velux.bridge.slip.SCgetProducts] - setResponse(): got GW_GET_ALL_NODES_INFORMATION_CFM.
2019-07-18 18:53:27.800 [TRACE] [ding.velux.bridge.slip.SCgetProducts] - isLengthValid() called for GW_GET_ALL_NODES_INFORMATION_CFM (0x203) with 2 bytes of data.
2019-07-18 18:53:27.802 [TRACE] [ding.velux.bridge.slip.SCgetProducts] - isLengthValid() returns true.
2019-07-18 18:53:27.804 [TRACE] [ding.velux.bridge.slip.SCgetProducts] - setResponse(): status=0.
2019-07-18 18:53:27.806 [TRACE] [ding.velux.bridge.slip.SCgetProducts] - setResponse(): TotalNumberOfNodes=2.
2019-07-18 18:53:27.809 [TRACE] [ding.velux.bridge.slip.SCgetProducts] - setResponse(): returned status: OK - Request accepted.
2019-07-18 18:53:27.811 [TRACE] [ding.velux.bridge.slip.SCgetProducts] - setResponse(): finished=false,success=false.
2019-07-18 18:53:27.813 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): receiving from 192.168.0.23:51200.
2019-07-18 18:53:27.815 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(192.168.0.23,51200,0 bytes) called.
2019-07-18 18:53:27.817 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): receiving bytes.
2019-07-18 18:53:27.819 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() called.
2019-07-18 18:53:27.825 [TRACE] [g.velux.bridge.slip.io.SSLconnection] - receive() finished after having read 131 bytes: C0 00 7F 02 04 00 00 00 00 62 75 72 65 61 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 80 00 00 00 00 00 00 00 00 00 00 00 00 00 05 28 00 28 00 F7 FF F7 FF F7 FF F7 FF 00 00 5D 30 A4 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 25 C0
2019-07-18 18:53:27.829 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 131 bytes: C0 00 7F 02 04 00 00 00 00 62 75 72 65 61 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 80 00 00 00 00 00 00 00 00 00 00 00 00 00 05 28 00 28 00 F7 FF F7 FF F7 FF F7 FF 00 00 5D 30 A4 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 25 C0
2019-07-18 18:53:27.831 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - io() finished.
2019-07-18 18:53:27.834 [TRACE] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): received packet C0 00 7F 02 04 00 00 00 00 62 75 72 65 61 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 80 00 00 00 00 00 00 00 00 00 00 00 00 00 05 28 00 28 00 F7 FF F7 FF F7 FF F7 FF 00 00 5D 30 A4 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 25 C0.
2019-07-18 18:53:27.836 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() for packet size 131 called.
2019-07-18 18:53:27.840 [TRACE] [g.velux.bridge.slip.util.SlipRFC1055] - decode() provides payload: 00 7F 02 04 00 00 00 00 62 75 72 65 61 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 80 00 00 00 00 00 00 00 00 00 00 00 00 00 05 28 00 28 00 F7 FF F7 FF F7 FF F7 FF 00 00 5D 30 A4 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 25.
2019-07-18 18:53:27.842 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 129.
2019-07-18 18:53:27.844 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getCommand() returns 0x204 .
2019-07-18 18:53:27.847 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - getData() returns 124 bytes: 00 00 00 00 62 75 72 65 61 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 80 00 00 00 00 00 00 00 00 00 00 00 00 00 05 28 00 28 00 F7 FF F7 FF F7 FF F7 FF 00 00 5D 30 A4 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.
2019-07-18 18:53:27.850 [TRACE] [.velux.bridge.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized with command 0x204 and data 00 00 00 00 62 75 72 65 61 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 80 00 00 00 00 00 00 00 00 00 00 00 00 00 05 28 00 28 00 F7 FF F7 FF F7 FF F7 FF 00 00 5D 30 A4 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00.

Kim_Andersen · July 18, 2019, 5:17pm

This is a debug snap… (notice is RAR compressed)

Velux debug level.rar.txt (3.3 KB)

gs4711 · July 18, 2019, 5:40pm

The output looks pretty good and enlightens the problem with Somfy devices…

00 7F 02 04 00 00 00 00 62 75 72 65 61 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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 80 00 00 00 00 00 00 00 00 00 00 00 00 00 05 28 00 28 00 F7 FF F7 FF F7 FF F7 FF 00 00 5D 30 A4 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 25. means:

Nodeid := 00
Order = 00 00
Placement = 00
Name = 62 75 72 65 61 75 00 00 00 00 00 00 00 00 00 00 …
Velocity = 01
Subtype = 00 80
ProductGroup = 00
ProductType = 00
NodeVariation = 00
PowerMode = 00
BuildNumber = 00
SerialNumber = 00 00 00 00 00 00 00 00
…

Therefore the binding will register the 1st actuator and discard the 2nd one (as it is a duplicated serial number named 00:00:00:00:00:00:00:00). This calls for a Somfy hack … please me check with Velux whether they know about this non-conformant io-homecontrol behaviour.