Rollershutter % Position does not work in 2.5.0.M2

[Gozilla01]

I just put the desired % in the paper UI. I have manually configured the shutter run about one year ago and never changed it. Until yesterday the % command worked as expected, I suppose something has been changed in the binding. Do you have a rollershutter to do a test? https://community.openhab.org/t/bticino-openwebnet-new-openhab2-binding-ready-for-testing/43377/534

[Gozilla01]

I verified is a bug. I commented the instruction moveSchedule.cancel (false); line 381 of the OpenWebNetAutomationHandler file. It immediately kills the scheduler as soon as the command arrives v2.4.0-b9-2 to 2.5.0-M2 the file OpenWebNetAutomationHandler does not change. The only thing that could influence is the FIX correction # 29 2019-03-16 21:41:26.593 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*1000#1*91##> what=UP From the tests with this change it now works. Did you enter it for special reasons?

[mvalla]

cannot reproduce the bug. Line 381 of 2.5.0.M2 IS NOT moveSchedule.cancel (false) : https://github.com/mvalla/openhab2-addons/blob/d9839d5b8bf7a451eea3a5ae5f321a3f40a15f0c/addons/binding/org.openhab.binding.openwebnet/src/main/java/org/openhab/binding/openwebnet/handler/OpenWebNetAutomationHandler.java#L381

[Gozilla01]

I succeeded in reproducing the problem. See if you receive the command ....*1000#..... during the movement. In my opinion this is the problem.

Sorry this line https://github.com/mvalla/openhab2-addons/blob/d9839d5b8bf7a451eea3a5ae5f321a3f40a15f0c/addons/binding/org.openhab.binding.openwebnet/src/main/java/org/openhab/binding/openwebnet/handler/OpenWebNetAutomationHandler.java#L361

[mvalla]

The issue from @enrico.mcc does not say he sends a command during movement: in this case it’s expected that previous command is cancelled. If you can reproduce the issue @enrico.mcc explained in his post, copy the log here.

[Gozilla01]

I know what enrico.mcc says I tell you that I have done some tests and the movement with the percentage, the same symptom of enrico.mcc, also does not work for me I don't send any commands during the move, but I get the *1000# from the bus

[mvalla]

Post the log here, using code fences correctly

[Gozilla01]

Log during the movement

2019-03-17 10:11:32.753 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *#13**22*10*11*31*000*00*17*03*2019## 2019-03-17 10:11:32.755 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## handleManagementDimension not processed 2019-03-17 10:11:32.758 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== RECEIVED <<<<< <*#13**22*10*11*31*000*00*17*03*2019##> 2019-03-17 10:11:32.761 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== GatewayManagement WHAT = null ==> /var/log/openhab2/events.log <== 2019-03-17 10:11:39.438 [ome.event.ItemCommandEvent] - Item 'Tapparella_Sala' received command 85 ==> /var/log/openhab2/openhab.log <== 2019-03-17 10:11:39.450 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - ==OWN:ThingHandler== handleCommand() (command=85 - channel=openwebnet:bus_automation:mybridge:mytap_sala:shutter) ==> /var/log/openhab2/events.log <== 2019-03-17 10:11:39.454 [nt.ItemStatePredictedEvent] - Tapparella_Sala predicted to become 85 ==> /var/log/openhab2/openhab.log <== 2019-03-17 10:11:39.455 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # 85% requested ==> /var/log/openhab2/events.log <== 2019-03-17 10:11:39.459 [vent.ItemStateChangedEvent] - Tapparella_Sala changed from 92 to 85 2019-03-17 10:11:39.462 [GroupItemStateChangedEvent] - G_Shutters changed from 92.00000000 to 85.00000000 through Tapparella_Sala ==> /var/log/openhab2/openhab.log <== 2019-03-17 10:11:39.461 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # target moveTime=1750 2019-03-17 10:11:39.465 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # Starting schedule... 2019-03-17 10:11:39.469 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # ...schedule started, now sending highPriority command... 2019-03-17 10:11:39.472 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> *2*1*91## 2019-03-17 10:11:39.474 [DEBUG] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## CANNOT read from socket: read returned -1 2019-03-17 10:11:39.477 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## read returned -1 2019-03-17 10:11:39.479 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## let's try with a NEW SESSION... 2019-03-17 10:11:39.481 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## Trying openCommandSession() socket.... (192.168.1.40:20000) 2019-03-17 10:11:39.485 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... starting HANDSHAKE ... 2019-03-17 10:11:39.486 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== *#*1## 2019-03-17 10:11:39.488 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> *99*0## 2019-03-17 10:11:39.492 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== *#825521941## 2019-03-17 10:11:39.494 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> *#4294572255## 2019-03-17 10:11:39.498 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== *#*1## 2019-03-17 10:11:39.500 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## ... CONNECTED command session 192.168.1.40:20000 2019-03-17 10:11:39.502 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> *2*1*91## 2019-03-17 10:11:39.591 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - COM RECEIVED <<<<<<<<<<<<============ *#*1## 2019-03-17 10:11:39.593 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## HIGH-PRIORITY no sleep! 2019-03-17 10:11:39.595 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*1000#1*91## 2019-03-17 10:11:39.597 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## COMMAND TRANSLATION, WHAT=UP 2019-03-17 10:11:39.598 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # ...gateway.sendHighPriority() returned 2019-03-17 10:11:39.599 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== RECEIVED <<<<< <*2*1000#1*91##> 2019-03-17 10:11:39.601 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.91 2019-03-17 10:11:39.602 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*1000#1*91##> what=UP ==> /var/log/openhab2/openhab.log <== 2019-03-17 10:11:39.611 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # MOVING 1 - startedMovingAt=1552813899610 - 39.610 2019-03-17 10:11:39.614 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # [[[ internalState=1 positionEst=92 - calibrating=-1 shutterRun=25000 ]]] 2019-03-17 10:11:39.642 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*1*91## 2019-03-17 10:11:39.644 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== RECEIVED <<<<< <*2*1*91##> 2019-03-17 10:11:39.646 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.91 2019-03-17 10:11:39.648 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*1*91##> what=UP 2019-03-17 10:11:39.651 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # current positionEst=92 2019-03-17 10:11:39.653 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # movedTime=40 2019-03-17 10:11:39.654 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # movedSteps: 0 UP(-) 2019-03-17 10:11:39.656 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # 92 - 0 = 92 2019-03-17 10:11:39.658 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # MOVING 1 - startedMovingAt=1552813899657 - 39.657 2019-03-17 10:11:39.660 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # [[[ internalState=1 positionEst=92 - calibrating=-1 shutterRun=25000 ]]] 2019-03-17 10:12:04.698 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *#13**22*10*12*03*000*00*17*03*2019## 2019-03-17 10:12:04.701 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## handleManagementDimension not processed 2019-03-17 10:12:04.704 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== RECEIVED <<<<< <*#13**22*10*12*03*000*00*17*03*2019##> 2019-03-17 10:12:04.706 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== GatewayManagement WHAT = null 2019-03-17 10:12:06.129 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*0*91## 2019-03-17 10:12:06.132 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== RECEIVED <<<<< <*2*0*91##> 2019-03-17 10:12:06.135 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.91 2019-03-17 10:12:06.137 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*0*91##> what=STOP 2019-03-17 10:12:06.141 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # current positionEst=92 2019-03-17 10:12:06.143 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # movedTime=26483 2019-03-17 10:12:06.147 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # movedSteps: 106 UP(-) ==> /var/log/openhab2/openhab.log <== 2019-03-17 10:12:06.150 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # 92 - 106 = -14 2019-03-17 10:12:06.155 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 91 # [[[ internalState=0 positionEst=0 - calibrating=-1 shutterRun=25000 ]]] ==> /var/log/openhab2/events.log <== 2019-03-17 10:12:06.164 [vent.ItemStateChangedEvent] - Tapparella_Sala changed from 85 to 0 2019-03-17 10:12:06.174 [GroupItemStateChangedEvent] - G_Shutters changed from 85.00000000 to 0.00000000 through Tapparella_Sala ==> /var/log/openhab2/openhab.log <== 2019-03-17 10:12:25.746 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## sending MON keepalive ACK 2019-03-17 10:12:25.749 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - MON SENDING ======>>>>>> *#*1##

[mvalla]

After % command is sent and therefore a DOWN is sent, the BUS notifies 4 messages: 2 STOP events (who knows why!): one 1000#0 and one 0, and then 2 DOWN events one 1000#2 and one 2:

11:28:44.629 [INFO ] - MON RECEIVED  <<<<<<<<<<< *2*1000#0*53##
11:28:44.656 [INFO ] - MON RECEIVED  <<<<<<<<<<< *2*0*53##
11:28:44.688 [INFO ] - MON RECEIVED  <<<<<<<<<<< *2*1000#2*53##
11:28:44.723 [INFO ] - MON RECEIVED  <<<<<<<<<<< *2*2*53##

this breaks the current go-to-percent logic of the binding. This did not happen in in beta9-2 because the 1000#x events where ignored. It will be fixed in next release.

[Gozilla01]

I honestly didn't understand if the OWN 1000#x is just information / event Consequently must it be supported and not managed?

[mvalla]

in fact, if I understand correctly the OWN official docs, the 1000#x is sent when the command is sent to A-PL as an additional event. So it should be accepted (no WARN/ERROR), but just ignored. The binding should only care about the other events *2*/*0*/*1*.

[mvalla]

fixed in 2.5.0.M2-1