OH3.4.1 Velux - Rollershutter state not updating

Hi,

I am still on OH3.4.1 but have upgraded my Velux binding to 3.4.2 Snapshot from #14255 as I have saw, that there are changes on how to handle somfy devices (even this did not fixed my issue)

KLF200: Software version 0.2.0.0.71.0, Hardware version 6.14.3

Bridge thing:

UID: velux:klf200:192_168_58_13
label: Velux Bridge
thingTypeUID: velux:klf200
configuration:
  tcpPort: 51200
  retries: 5
  isBulkRetrievalEnabled: true
  password: xxxx
  protocol: slip
  refreshMsecs: 10000
  ipAddress: 192.168.58.13
  isSequentialEnforced: false
  isProtocolTraceEnabled: false
  timeoutMsecs: 10000

Rollershutter thing:

UID: velux:rollershutter:192_168_58_13:Rollo_links
label: Schlafzimmer Rollo links
thingTypeUID: velux:rollershutter
configuration:
  name: Rollolinks
  inverted: false
  serial: 00:00:00:00:00:00:00:00
bridgeUID: velux:klf200:192_168_58_13

Issue: I have two somfy battery powered rollershutter connected: from time to time (very unspecific & random) one rollershutter is not working anymore when trying to control the device via the binding.

I have put the binding into debug mode and saw that the device is reporting state 4: As per documentation this is “blocked by an object”. However when I operate the device not via the binding, but directly via the remote control, everything is working fine. After I used the remote control, the device is also working again via the binding.

Questions:

  1. Is there any chance for additional debugging to understand, why the KLF200 reports the device with status 4?
  2. Even if the devices operate normal, their state is reported with 5, whats WRONG_SYSTEMKEY. Anything to worry about, that I can change?
  3. Within the log I also find an error message, thats only listed as debug. Is this by purpose?

2023-08-16 07:26:24.888 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.

Below the log from one refresh cycle.

Before (whats not in the log, as the binding was not in debug mode):

  1. The rollershutter was closed at 100% and also the item was showing 100% closed. Both as expected
  2. A rule has send 85% command to Rollo links, item state updated successfully, but rollershutter not moving in real life
  3. After a few minutes a rule has send 0% command to Rollo links. Again no movement of the device
  4. I have recognized the error, but the binding in debug mode and found the following log:

(Even device Rollo links is still closed at 100%, it is reported as 88.7% open as per my understanding
(B1E4 hex = 45450 decimal) / (C800 hex = 51200 decimal) = 88.7%)

Thanks in advance for any help. Please let me know if I have missed something or can provide additional details.

2023-08-16 07:26:24.881 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-4,5,main] starting cycle 3006.
2023-08-16 07:26:24.883 [DEBUG] [nternal.bridge.slip.SCgetHouseStatus] - getRequestCommand() returns GW_OPENHAB_RECEIVEONLY (0xfffffffd).
2023-08-16 07:26:24.883 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommand(velux:rollershutter:192_168_58_13:Rollo_links:position,REFRESH) called.
2023-08-16 07:26:24.885 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_OPENHAB_RECEIVEONLY => started => Thread[OH-velux:klf200:192_168_58_13-1,5,main] 
2023-08-16 07:26:24.885 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommand(velux:rollershutter:192_168_58_13:Rollo_rechts:position,REFRESH) called.
2023-08-16 07:26:24.886 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_OPENHAB_RECEIVEONLY => finished => success
2023-08-16 07:26:24.887 [DEBUG] [.internal.handler.VeluxBridgeHandler] - refreshSchedulerJob() initiated by Thread[OH-thingHandler-4,5,main] finished cycle 3006.
2023-08-16 07:26:24.888 [DEBUG] [nal.bridge.VeluxBridgeGetHouseStatus] - evaluateState() finished with failure.
2023-08-16 07:26:24.890 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:192_168_58_13:Rollo_links:position,REFRESH) called.
2023-08-16 07:26:24.892 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleRefresh(velux:rollershutter:192_168_58_13:Rollo_links:position,position,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@657db6) called.
2023-08-16 07:26:24.894 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - getRequestCommand() returns GW_GET_NODE_INFORMATION_REQ (0x200).
2023-08-16 07:26:24.896 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => started => Thread[OH-velux:klf200:192_168_58_13-1,5,main] 
2023-08-16 07:26:24.898 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_REQ => sending data length => 1
2023-08-16 07:26:24.900 [DEBUG] [x.internal.bridge.slip.io.Connection] - io() on 192.168.58.13: sending packet of size 8.
2023-08-16 07:26:25.053 [DEBUG] [x.internal.bridge.slip.io.Connection] - io() on 192.168.58.13: received packet with 9 bytes.
2023-08-16 07:26:25.056 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => received data length => 2
2023-08-16 07:26:25.058 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_CFM with 2 bytes of data) called.
2023-08-16 07:26:25.061 [DEBUG] [x.internal.bridge.slip.io.Connection] - io() on 192.168.58.13: received packet with 131 bytes.
2023-08-16 07:26:25.069 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data length => 124
2023-08-16 07:26:25.072 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_NTF with 124 bytes of data) called.
2023-08-16 07:26:25.075 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): device provided invalid serial number, using name 'Rollolinks' instead.
2023-08-16 07:26:25.077 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => finished => success
2023-08-16 07:26:25.080 [DEBUG] [nternal.things.VeluxExistingProducts] - update() newProduct:VeluxProduct(v2, creator:GW_GET_NODE_INFORMATION_REQ, dataSource:GATEWAY, name:Rollolinks, typeId:SLIDER_SHUTTER, bridgeIndex:0, state:4, serial:Rollolinks, position:B1E4, target:0000, functionalParameters:null) (identical)
2023-08-16 07:26:25.083 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Rollolinks, typeId:SLIDER_SHUTTER, bridgeIndex:0, state:4, serial:Rollolinks, position:B1E4, target:0000, functionalParameters:null) (unchanged)
2023-08-16 07:26:25.085 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(): updating channel velux:rollershutter:192_168_58_13:Rollo_links:position to 0.
2023-08-16 07:26:25.089 [DEBUG] [.internal.handler.VeluxBridgeHandler] - handleCommandCommsJob(velux:rollershutter:192_168_58_13:Rollo_rechts:position,REFRESH) called.
2023-08-16 07:26:25.092 [DEBUG] [rnal.handler.ChannelActuatorPosition] - handleRefresh(velux:rollershutter:192_168_58_13:Rollo_rechts:position,position,org.openhab.binding.velux.internal.handler.VeluxBridgeHandler@657db6) called.
2023-08-16 07:26:25.094 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - getRequestCommand() returns GW_GET_NODE_INFORMATION_REQ (0x200).
2023-08-16 07:26:25.097 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => started => Thread[OH-velux:klf200:192_168_58_13-1,5,main] 
2023-08-16 07:26:25.099 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_REQ => sending data length => 1
2023-08-16 07:26:25.102 [DEBUG] [x.internal.bridge.slip.io.Connection] - io() on 192.168.58.13: sending packet of size 8.
2023-08-16 07:26:25.306 [DEBUG] [x.internal.bridge.slip.io.Connection] - io() on 192.168.58.13: received packet with 9 bytes.
2023-08-16 07:26:25.308 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_CFM => received data length => 2
2023-08-16 07:26:25.309 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_CFM with 2 bytes of data) called.
2023-08-16 07:26:25.311 [DEBUG] [x.internal.bridge.slip.io.Connection] - io() on 192.168.58.13: received packet with 131 bytes.
2023-08-16 07:26:25.315 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => GW_GET_NODE_INFORMATION_NTF => received data length => 124
2023-08-16 07:26:25.316 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(GW_GET_NODE_INFORMATION_NTF with 124 bytes of data) called.
2023-08-16 07:26:25.318 [DEBUG] [ux.internal.bridge.slip.SCgetProduct] - setResponse(): device provided invalid serial number, using name 'Rollorechts' instead.
2023-08-16 07:26:25.320 [DEBUG] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() [192.168.58.13] GW_GET_NODE_INFORMATION_REQ => finished => success
2023-08-16 07:26:25.322 [DEBUG] [nternal.things.VeluxExistingProducts] - update() newProduct:VeluxProduct(v2, creator:GW_GET_NODE_INFORMATION_REQ, dataSource:GATEWAY, name:Rollorechts, typeId:SLIDER_SHUTTER, bridgeIndex:1, state:5, serial:Rollorechts, position:C800, target:C800, functionalParameters:null) (identical)
2023-08-16 07:26:25.323 [DEBUG] [nternal.things.VeluxExistingProducts] - update() theProduct:VeluxProduct(v2, creator:GW_GET_ALL_NODES_INFORMATION_REQ, dataSource:GATEWAY, name:Rollorechts, typeId:SLIDER_SHUTTER, bridgeIndex:1, state:5, serial:Rollorechts, position:C800, target:C800, functionalParameters:null) (unchanged)

The device is reporting the blocked status over its wireless link to the KLF, and the KLF is simply reacting to what comes in. There is no way to make the KLF ‘unreact’.

I could imagine that the blocked status might occur if the device motor is not strong enough to overcome friction. So I would suggest lubricating the wheels, gears and slides. Also try replacing the batteries.

Thanks for your quick reply.

My hope was to get some additional information via the slip api, why the device is not responding.

I do not believe it is because of battery: The rollershutters are just a few month old, battery therefore quite new and the device is mounted in south direction with little to no shadow during the day. Therefore battery gets charged by the solar panel every day.

Also on motor not being strong enough I am unsure about for the following reasons:
when controlling the device via the somfy remote control its working immediately without delay or slower speed. If there would be some friction, I would also recognize this when controlling the device not only via binding, but also via remote control (I have two roller shutters next to each other and the opperate at same speed).

Therefore I still believe, that the issue is with KLF200 device or the SLIP API and I have done the following:

  1. deleted and re-added the device (as there is also status 5 / WRONG_SYSTEMKEY reported)
  2. changed wifi settings to always on, so that in case of error I can login into klf200 to review log or check if I still can control the device via klf200 directly or not

If there is friction, then using the manual control might cause sending the blocked flag to the KLF. i.e. manual operation msy look as if it is working, but may actually exacerbate the problem with the KLF.

In any case, I dont think there is anything I could change in the binding to eliminate this issue. If the device says it is sick, and causes the KLF to stop the command, then nothing in the binding can make it ‘un-sick’…

Maybe a misunderstanding:
The remote control is not connected to the klf200 at all, but directly working with the rollershutters.
If I press a button on the remote control then the rollershutter is working as expected, not sure how this would then exacerbate the problem.

Agree for now. With the changes from yesterday, today my wake up rule was also working correctly and rollershutters opening as expected. Fingers crossed, that it will stay the same

Remote controller tells the shutter to move / shutter moves / but detects internal friction / so informs KLF of error state / so when binding wants to move the shutter, the KLF is in error state, so cannot issue a move command to the shutter…