I have opened an issue #65
v2.4.0-b9-2
I did a discovery test Lighting with A = 4 and PL = 14
Works correctly with version 2.5.0-M2
Hi @enrico.mcc I did a test (OH 2.4.0, binding 2.5.0.M2) and cannot reproduce your problem. After shutterRun has been set, if I send from PaperUI a % command the shutters goes directly to that %.
I suggest you try the following checkpoints, doing a % command after each step to check if it works:
- form PaperUI open or close your shutter completely (0% / 100%), using arrows, to be sure the current position of the shutter is known to the binding. This is always needed after a OH restart since the binding does not know anymore where the shutter position is. A warning message is sent if shutterRun is OK but current position is unknown
- check the OH logs for errors/warnings (and post them here!)
- remove and then add again the shutter Thing/Item. If you use file configuration (.things), you can just comment the correct
bus_automationline, restart OH, then un-comment the line again and then restart OH again
let me know if any of the steps helps
massi
Hi Massi,
I am on openhab 2.5, but already was on that version before updating the binding
About the checks:
- done, no changes in behaviour.
If I manually stop the movement the right % is shown (e.g. if I stop the run after half of the total run time 50% is shown in the current state).
So the position tracking is working.
My feeling is that something is wrong in managing the commands in %
Rebooting made no changes
I will post the pertinent logs
Here the logs after I sent a 10% command; after the rollershutter moved past 30/40% I sent a “stop” command:
2019-03-17 11:28:44.478 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - ==OWN:ThingHandler== handleCommand() (command=10 - channel=openwebnet:bus_automation:ef0da2a6:53:shutter)
2019-03-17 11:28:44.480 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # 10% requested
2019-03-17 11:28:44.482 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # target moveTime=3600
2019-03-17 11:28:44.484 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # Starting schedule...
2019-03-17 11:28:44.486 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # ...schedule started, now sending highPriority command...
2019-03-17 11:28:44.488 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> *2*2*53##
2019-03-17 11:28:44.496 [DEBUG] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## CANNOT read from socket: read returned -1
2019-03-17 11:28:44.501 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## read returned -1
2019-03-17 11:28:44.503 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## let's try with a NEW SESSION...
2019-03-17 11:28:44.505 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## Trying openCommandSession() socket.... (192.168.1.11:20000)
2019-03-17 11:28:44.508 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... starting HANDSHAKE ...
2019-03-17 11:28:44.511 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== *#*1##
2019-03-17 11:28:44.513 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> *99*0##
2019-03-17 11:28:44.517 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== *98*2##
2019-03-17 11:28:44.518 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> *#*1##
2019-03-17 11:28:44.522 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== *#14031314061300150812021014150613081503080015010206140403010903020905101005131107110002110201000302040907090700000806021004070410##
2019-03-17 11:28:44.526 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> *#02060213100410110911110506040006070312050604090705040711130214121006110500090012131303061105051315080207011402050501130209001211*00031514041501071307050700130912100108051514151001010911080004071402011503110111151208040901081202060115040907140904110807071510##
2019-03-17 11:28:44.529 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== *#08020508040610130210140710090106150603110909140215030209090506070600030901031300120712051101061413040314111409151403071204091100##
2019-03-17 11:28:44.532 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> *#*1##
2019-03-17 11:28:44.534 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## ... CONNECTED command session 192.168.1.11:20000
2019-03-17 11:28:44.536 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> *2*2*53##
2019-03-17 11:28:44.629 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*1000#0*53##
2019-03-17 11:28:44.631 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## COMMAND TRANSLATION, WHAT=STOP
2019-03-17 11:28:44.633 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.53
2019-03-17 11:28:44.635 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*1000#0*53##> what=STOP
2019-03-17 11:28:44.637 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # [[[ internalState=0 positionEst=0 - calibrating=-1 shutterRun=36000 ]]]
2019-03-17 11:28:44.656 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*0*53##
2019-03-17 11:28:44.658 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.53
2019-03-17 11:28:44.660 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*0*53##> what=STOP
2019-03-17 11:28:44.662 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # [[[ internalState=0 positionEst=0 - calibrating=-1 shutterRun=36000 ]]]
2019-03-17 11:28:44.688 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*1000#2*53##
2019-03-17 11:28:44.690 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## COMMAND TRANSLATION, WHAT=DOWN
2019-03-17 11:28:44.691 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - COM RECEIVED <<<<<<<<<<<<============ *#*1##
2019-03-17 11:28:44.693 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## HIGH-PRIORITY no sleep!
2019-03-17 11:28:44.694 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # ...gateway.sendHighPriority() returned
2019-03-17 11:28:44.697 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.53
2019-03-17 11:28:44.699 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*1000#2*53##> what=DOWN
2019-03-17 11:28:44.701 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # MOVING 2 - startedMovingAt=1552818524700 - 44.700
2019-03-17 11:28:44.702 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # [[[ internalState=2 positionEst=0 - calibrating=-1 shutterRun=36000 ]]]
2019-03-17 11:28:44.723 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*2*53##
2019-03-17 11:28:44.726 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.53
2019-03-17 11:28:44.728 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*2*53##> what=DOWN
2019-03-17 11:28:44.729 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # current positionEst=0
2019-03-17 11:28:44.730 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # movedTime=29
2019-03-17 11:28:44.732 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # movedSteps: 0 DOWN(+)
2019-03-17 11:28:44.733 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # 0 + 0 = 0
2019-03-17 11:28:44.735 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # MOVING 2 - startedMovingAt=1552818524734 - 44.734
2019-03-17 11:28:44.736 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # [[[ internalState=2 positionEst=0 - calibrating=-1 shutterRun=36000 ]]]
2019-03-17 11:28:46.839 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *#18*51*113*481##
2019-03-17 11:28:46.862 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=18.51
2019-03-17 11:28:46.877 [DEBUG] [bnet.handler.OpenWebNetEnergyHandler] - ==OWN:EnergyHandler== updateActivePower() for thing: openwebnet:bus_energy_central_unit:ef0da2a6:51
2019-03-17 11:28:47.837 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *#18*51*113*544##
2019-03-17 11:28:47.840 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=18.51
2019-03-17 11:28:47.842 [DEBUG] [bnet.handler.OpenWebNetEnergyHandler] - ==OWN:EnergyHandler== updateActivePower() for thing: openwebnet:bus_energy_central_unit:ef0da2a6:51
2019-03-17 11:28:48.835 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *#18*51*113*608##
2019-03-17 11:28:48.838 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=18.51
2019-03-17 11:28:48.840 [DEBUG] [bnet.handler.OpenWebNetEnergyHandler] - ==OWN:EnergyHandler== updateActivePower() for thing: openwebnet:bus_energy_central_unit:ef0da2a6:51
2019-03-17 11:28:49.417 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - No tr064 service found for service id urn:WANDSLIfConfig-com:serviceId:WANDSLInterfaceConfig1
2019-03-17 11:28:49.424 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Error constructing request SOAP msg for getting parameter. null
2019-03-17 11:28:49.426 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Could not determine data to be sent to FritzBox!
2019-03-17 11:28:49.431 [ERROR] [b.core.service.AbstractActiveService] - Error while executing background thread FritzboxTr064 Refresh Service
java.lang.NullPointerException: null
at org.openhab.binding.fritzboxtr064.internal.FritzboxTr064Binding.execute(FritzboxTr064Binding.java:219) ~[?:?]
at org.openhab.core.binding.AbstractActiveBinding$BindingActiveService.execute(AbstractActiveBinding.java:148) ~[192:org.openhab.core.compat1x:2.5.0.201901231358]
at org.openhab.core.service.AbstractActiveService$RefreshThread.run(AbstractActiveService.java:170) [192:org.openhab.core.compat1x:2.5.0.201901231358]
2019-03-17 11:28:51.187 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-binding-modbus1'
2019-03-17 11:28:56.745 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - ==OWN:ThingHandler== handleCommand() (command=STOP - channel=openwebnet:bus_automation:ef0da2a6:53:shutter)
2019-03-17 11:28:56.754 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> *2*0*53##
2019-03-17 11:28:56.812 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - COM RECEIVED <<<<<<<<<<<<============ *#*1##
2019-03-17 11:28:56.812 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*1000#0*53##
2019-03-17 11:28:56.816 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## COMMAND TRANSLATION, WHAT=STOP
2019-03-17 11:28:56.820 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.53
2019-03-17 11:28:56.826 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*1000#0*53##> what=STOP
2019-03-17 11:28:56.828 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # current positionEst=0
2019-03-17 11:28:56.830 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # movedTime=12094
2019-03-17 11:28:56.832 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # movedSteps: 34 DOWN(+)
2019-03-17 11:28:56.834 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # 0 + 34 = 34
2019-03-17 11:28:56.836 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< *2*0*53##
2019-03-17 11:28:56.838 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # [[[ internalState=0 positionEst=34 - calibrating=-1 shutterRun=36000 ]]]
2019-03-17 11:28:56.851 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=2.53
2019-03-17 11:28:56.860 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*0*53##> what=STOP
2019-03-17 11:28:56.862 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== # 53 # [[[ internalState=0 positionEst=34 - calibrating=-1 shutterRun=36000 ]]]
2019-03-17 11:28:44.699 [DEBUG] [.handler.OpenWebNetAutomationHandler] - ==OWN:AutomationHandler== updateAutomationState() - msg=<*2*1000#2*53##> what=DOWN
Yes, you have the same problem as me, here
@enrico.mcc @gozilla01
after you share the logs, I now understand the problem.
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 before because the 1000#x events where (wrongly) ignored, in particular the third event. So this also explains why this was working in beta9-2.
It requires some precise fixing of the logic, it will be fixed in 2.5.0.M3 of the binding.
Bye
Massi
Thank you Massi! 
easy question: why after binding upgrade (from 2.4 to 2.5) i cannot use rollershutters (ar reported as bug with 2.5), and also if i rollback to 2.4 binding (including clear cache, reinstall features and replacing jar file with old one that worked) it won’t show current position of rollershutters and i cannot manage them?
thanks guys!
Difficult answer
Yesterday I wanted to run tests for the bug percentage, I was not able to install the beta9.2 on OH 2.4.0.
The shutters work, the bug concerns if you want to move them with the change of the percentage value.
Hi Massimo,
could you help me ? I have a problem with my Legrand 088328 gateway. It was working well until today.
I have the following issue into my log after reseting my opanhabian I still have the problem.
I have Raspberry PI 3 model B
Here is my log:
2019-03-18 19:40:31.742 [me.event.InboxRemovedEvent] - Discovery Result with UID ‘openwebnet:dongle:7249800’ has been removed.
2019-03-18 19:40:31.825 [hingStatusInfoChangedEvent] - ‘openwebnet:dongle:7249800’ changed from UNINITIALIZED to INITIALIZING
2019-03-18 19:40:31.881 [hingStatusInfoChangedEvent] - ‘openwebnet:dongle:7249800’ changed from INITIALIZING to UNINITIALIZED (HANDLER_INITIALIZING_ERROR)
Thank for your help !
Bye
Jerome
Hi Jerome, which versions of the openwebnet binding and openHAB are you using?
Can you post more lines of the logs (before 19:40) and use code fences (document button above here in the msg edit window)
M
Yes i forgot to specify the rollershutters works but not in % mode 
To use other versions of binding i had to clear cache,reinstall features and then put the jar file. Was recognized but wont work 
Ruben Fuser
In my opinion, the problem concerns the change of licenses from V1 to V2 in OH.
But I’m not sure.
i agree with you the problem doesn’t concern to the add-on but to something else…because if i rollback the add-on to a previous version, everything should work again as expected, but it doesn’t
Hi Massimo,
I’m using the 2.5.0-M2
2019-03-18 22:42:45.427 [hingStatusInfoChangedEvent] - 'openwebnet:dongle:7249800' changed from UNINITIALIZED (HANDLER_INITIALIZING_ERROR) to UNINITIALIZED
2019-03-18 22:42:48.756 [hingStatusInfoChangedEvent] - 'openwebnet:dongle:7249800' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2019-03-18 22:42:51.675 [hingStatusInfoChangedEvent] - 'openwebnet:dongle:7249800' changed from UNINITIALIZED (DISABLED) to INITIALIZING
==> /var/log/openhab2/openhab.log <==
2019-03-18 22:42:51.671 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.openwebnet.handler.OpenWebNetBridgeHandler@95dc77': null
java.lang.NullPointerException: null
at org.openhab.binding.openwebnet.handler.OpenWebNetBridgeHandler.ownIdFromMessage(OpenWebNetBridgeHandler.java:531) ~[?:?]
at org.openhab.binding.openwebnet.handler.OpenWebNetBridgeHandler.testTransformations(OpenWebNetBridgeHandler.java:607) ~[?:?]
at org.openhab.binding.openwebnet.handler.OpenWebNetBridgeHandler.initialize(OpenWebNetBridgeHandler.java:123) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
==> /var/log/openhab2/events.log <==
2019-03-18 22:42:51.715 [hingStatusInfoChangedEvent] - 'openwebnet:dongle:7249800' changed from INITIALIZING to UNINITIALIZED (HANDLER_INITIALIZING_ERROR)
==> /var/log/openhab2/openhab.log <==
2019-03-18 22:42:51.700 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'openwebnet:dongle:7249800': null
java.lang.NullPointerException: null
at org.openhab.binding.openwebnet.handler.OpenWebNetBridgeHandler.ownIdFromMessage(OpenWebNetBridgeHandler.java:531) ~[?:?]
at org.openhab.binding.openwebnet.handler.OpenWebNetBridgeHandler.testTransformations(OpenWebNetBridgeHandler.java:607) ~[?:?]
at org.openhab.binding.openwebnet.handler.OpenWebNetBridgeHandler.initialize(OpenWebNetBridgeHandler.java:123) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
Here is the full log with the error
features request:
- support for the bticino living now smart system (zigbee)