the-ninth
(Robert)
January 14, 2023, 4:33am
164
I have now logged an issue for this, describing the test case that leads to the issue, and two test cases that avoid the issue (either running a full down/up cycle or setting Shutter Run < auto-stop). For all three test cases log files on DEBUG level are included.
opened 04:13AM - 14 Jan 23 UTC
closed 03:11PM - 07 May 23 UTC
bug
## Expected Behavior
If the state is already at 0, the auto-stop should leave i… t at 0 and not set it back to UNDEF.
## Current Behavior
Test case that **does** lead to the issue:
1. Initial conditions:
Shutter is up
State is 0
**Shutter Run is 61 seconds**
Auto-stop of actuator is 60 seconds
2. Action: OH is rebooted
Result: state is UNDEF **(OK)**
3. Action: sending an UP command
Result: state changes to 0, but after the auto-stop of the actuator, state goes back to UNDEF. **(NOT OK)**
Here are the log entries of the processing of the auto-stop.
```
2023-01-11 07:15:44.022 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*2*0*51##]
2023-01-11 07:15:44.022 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *2*0*51##
2023-01-11 07:15:44.023 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*2*0*51##>) --> 2.51
2023-01-11 07:15:44.023 [DEBUG] [.handler.OpenWebNetAutomationHandler] - handleMessage(<*2*0*51##>) for thing: openwebnet:bus_automation:22eef285a7:51
2023-01-11 07:15:44.023 [DEBUG] [.handler.OpenWebNetAutomationHandler] - updateAutomationState() - msg=<*2*0*51##> what=STOP
2023-01-11 07:15:44.023 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # current positionEstimation=-1 movedTime=60943
2023-01-11 07:15:44.023 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # movedSteps: 99 UP(-)
2023-01-11 07:15:44.024 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # movingState=0 positionEstimation=-1 - calibrating=-1 shutterRun=61540
2023-01-11 07:15:44.041 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*2*0*51##]
2023-01-11 07:15:44.042 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *2*0*51##
2023-01-11 07:15:44.042 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*2*0*51##>) --> 2.51
2023-01-11 07:15:44.043 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownId=2.51 has NO DEVICE associated, ignoring it
```
Full log file of step 3: [UNDEF_Issue_After_Reboot.txt](https://github.com/openhab/openhab-addons/files/10416507/UNDEF_Issue_After_Reboot.txt)
Test case that **does not** lead to the issue, with down/up initialization:
1. Initial conditions:
Shutter is up
State is 0
**Shutter Run is 61 seconds**
Auto-stop of actuator is 60 seconds
2. Action: OH is rebooted
Result: state is UNDEF **(OK)**
3. Action: sending a DOWN command, waiting 120 seconds, then sending an UP command
Result: shutter fully closes, then fully opens again, state is 0 **(OK)**
4. Action: sending an UP command
Result: state is 0 and stays that way after auto-stop, the auto-stop is not interfering anymore. **(OK)**
Here are the log entries of the processing of the auto-stop.
```
2023-01-11 15:10:21.287 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*2*0*51##]
2023-01-11 15:10:21.288 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *2*0*51##
2023-01-11 15:10:21.288 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*2*0*51##>) --> 2.51
2023-01-11 15:10:21.289 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownId=2.51 has NO DEVICE associated, ignoring it
2023-01-11 15:10:21.294 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*2*0*51##]
2023-01-11 15:10:21.294 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *2*0*51##
2023-01-11 15:10:21.295 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*2*0*51##>) --> 2.51
2023-01-11 15:10:21.295 [DEBUG] [.handler.OpenWebNetAutomationHandler] - handleMessage(<*2*0*51##>) for thing: openwebnet:bus_automation:22eef285a7:51
2023-01-11 15:10:21.296 [DEBUG] [.handler.OpenWebNetAutomationHandler] - updateAutomationState() - msg=<*2*0*51##> what=STOP
2023-01-11 15:10:21.296 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # current positionEstimation=0 movedTime=60965
2023-01-11 15:10:21.296 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # movedSteps: 99 UP(-)
2023-01-11 15:10:21.296 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # 0 - 99 = -99
2023-01-11 15:10:21.296 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # movingState=0 positionEstimation=0 - calibrating=-1 shutterRun=61540
```
Full log file of step 4: [UNDEF_Issue_After_Initialization.txt](https://github.com/openhab/openhab-addons/files/10416508/UNDEF_Issue_After_Initialization.txt)
Test case that **does not** lead to the issue, with Shutter Run < auto-stop time:
* Initial conditions:
Shutter is up
State is 0
**Shutter Run is 48 seconds**
Auto-stop of actuator is 60 seconds
* Action: OH is rebooted
Result: state is UNDEF **(OK)**
* Action: sending an UP command
Result: state changes to 0 and stays that way, auto-stop is not interfering **(OK)**
Here are the log entries of the processing of the auto-stop.
```
2023-01-14 04:25:21.528 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*2*0*51##]
2023-01-14 04:25:21.529 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *2*0*51##
2023-01-14 04:25:21.530 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*2*0*51##>) --> 2.51
2023-01-14 04:25:21.530 [DEBUG] [.handler.OpenWebNetAutomationHandler] - handleMessage(<*2*0*51##>) for thing: openwebnet:bus_automation:22eef285a7:51
2023-01-14 04:25:21.530 [DEBUG] [.handler.OpenWebNetAutomationHandler] - updateAutomationState() - msg=<*2*0*51##> what=STOP
2023-01-14 04:25:21.530 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # current positionEstimation=-1 movedTime=60951
2023-01-14 04:25:21.531 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # movedSteps: 127 UP(-)
2023-01-14 04:25:21.531 [DEBUG] [.handler.OpenWebNetAutomationHandler] - # w:51 # movingState=0 positionEstimation=0 - calibrating=-1 shutterRun=48000
2023-01-14 04:25:21.541 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*2*0*51##]
2023-01-14 04:25:21.542 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *2*0*51##
2023-01-14 04:25:21.543 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*2*0*51##>) --> 2.51
2023-01-14 04:25:21.543 [DEBUG] [rnal.handler.OpenWebNetBridgeHandler] - ownId=2.51 has NO DEVICE associated, ignoring it
2023-01-14 04:25:26.571 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*#13**22*05*24*31*000*06*14*01*2023##]
```
Full log file of step 4: [UNDEF_Issue_With_Lower_ShutterRun.txt](https://github.com/openhab/openhab-addons/files/10416525/UNDEF_Issue_With_Lower_ShutterRun.txt)
## Possible Solution
## Steps to Reproduce (for Bugs)
See above.
## Context
Wrote a script that is sending an UP command to the shutters if winds are getting too strong. Then noticed that after an OH reboot, even with the UP command, the states always went back to UNDEF after 60 seconds, when the auto-stop was sent by the actuator.
## Your Environment
OH 3.4 in a Docker container installed on a Synology NAS.
I also logged the topic of auto-calibration and its working as documentation issue:
opened 06:03AM - 14 Jan 23 UTC
closed 07:34AM - 27 Jan 23 UTC
documentation
The [description of the shutter position and shutterRun parameter](https://www.o… penhab.org/addons/bindings/openwebnet/#shutter-position) also covers the auto calibration. However, it fails to mention that the auto calibration cannot measure actual runtime, but only measures the time between a command (up/down) being issued and the auto-stop sent by the actuator.
For older actuators that support only physical configuration or virtual configuration via My Home Suite the auto-stop is fixed to 60 seconds, newer actuators that support advanced configuration via the My Home Suite can be configured to other values.
The auto calibration sets the shutterRun to a value slightly higher than that, probably due to processing delays. E.g. if the auto-stop is set to 60 seconds, the shutterRun is set to about 61 seconds.
I am not sure if this should be considered an issue with the implementation (does the auto calibration make sense like that), especially since this seems to lead to [another issue](https://github.com/openhab/openhab-addons/issues/14215).
But at least it would be useful to clearly document how the auto calibration works and the implications of it reacting to auto-stop not actual shutter runtime.