[BTicino/OpenWebNet] New openHAB2 binding ready for testing

For those interested in Energy Management (WHO=18):

thanks to the work of @aconte80 on the openwebnet4j lib and binding, Energy Management has been added back to the official binding: a new PR is already waiting to be integrated in OH3 and will probably be included in the next OH 3.1.x Milestone.
Definition of Energy Management Things will be little different from the Testing version, but it will be documented in the binding README with examples.

So thanks :clap: to @aconte80 for starting contributing to this binding!

3 Likes

not a problem at all, thanks for feedback.

yes, this is what i wanted to ask with my message: if somebody else has similar observations. it seems you have…

thank you for replying. frankly i was unsure what you think about my information. now i will try to go deeper and catch some logs for you. “the rule” is not some special rule, i happens with several rules (also with shutters) that send more commands just behind each other. i only use jython-rules. just for example this is often not working:

@rule("Ambient shower on")
@when("Item iViBad_AmbienteDuschen received command 1")
@when("Item iBad_Cen_Duschen_Ein changed to PRESSED")
def ambient_shower_on(event):
    sendCommand("iBad_CenMH_Musik_Ein", "PRESSED")
    sendCommand("iBad_Li", "80")
    sendCommand("iBad_Dusche_Li", "ON")
    sendCommand("iBad_Waschtisch_Li", "ON")
    sendCommand("iBad_Ambiente_Li", "ON")
    ScriptExecution.createTimer(ZonedDateTime.now().plusSeconds(2), lambda: postUpdate("iViBad_AmbienteDuschen", "0"))

here iBad_Dusche_Li is the command often does not work. when i switch another command to this position the other command will be the problematic

ok, i am still on openhabian with oh2.5.12 and official openwebnet binding. reason why i didn´t have a warning in the logs from oh2.5 is that
log:get org.openhab.binding.openwebnet was set to INFO
and
log:get org.openwebnet4j was set to WARN
now i set both to DEBUG (sorry i forgot to set that before)

i just activated the posted function “ambient_shower_on” and accidentally the light from item iBad_Dusche_Li did not switch on, although in log it is shown as ON

here the log:

2021-02-26 17:10:36.479 [INFO ] [se.smarthome.model.script.bt_manager] - bt_manager data: *25*22#3*261##
2021-02-26 17:10:36.480 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.post_update_if_different' function is pending deprecation.
2021-02-26 17:10:36.484 [INFO ] [se.smarthome.model.script.bt_manager] - CenPlus 61 beginn langer Druck Taste 3 - iViBad_AmbienteDuschen start
2021-02-26 17:10:36.487 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.postUpdate' function is pending deprecation.
2021-02-26 17:10:36.492 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.497 [DEBUG] [jsr223.jython.core.utils            ] - New postUpdate value for 'iViHwr_PIr_Lux' is '10'
2021-02-26 17:10:36.501 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule '608bf2c0-d4cc-47e6-b16a-44d7d3343098' is executed.
2021-02-26 17:10:36.505 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iViBad_AmbienteDuschen-received-command1_254e4e6e74df11eba14fdca632261beb_254f11c074df11ebbc02dca632261beb' of rule '4ec5bf9a-a5c5-4dec-803b-67051cd5a749' is triggered.
2021-02-26 17:10:36.510 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*25*22#3*261##]
2021-02-26 17:10:36.511 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.512 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *25*22#3*261##
2021-02-26 17:10:36.519 [DEBUG] [nwebnet4j.communication.BUSConnector] - UNSUPPORTED FRAME: *25*22#3*261##, skipping it
2021-02-26 17:10:36.522 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.530 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.541 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.550 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.565 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule '4ec5bf9a-a5c5-4dec-803b-67051cd5a749' is executed.
2021-02-26 17:10:36.586 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - handleCommand() (command=80 - channel=openwebnet:bus_dimmer:bticino:Bad_Li:brightness)
2021-02-26 17:10:36.588 [DEBUG] [et.handler.OpenWebNetLightingHandler] - handleBrightnessCommand() command=80
2021-02-26 17:10:36.590 [DEBUG] [et.handler.OpenWebNetLightingHandler] -    DIM dimLightTo(80) bri=0 briBeforeOff=80
2021-02-26 17:10:36.592 [DEBUG] [et.handler.OpenWebNetLightingHandler] -    DIM newBrightness=80 newBrightnessWhat=DIMMER_LEVEL_8
2021-02-26 17:10:36.594 [DEBUG] [et.handler.OpenWebNetLightingHandler] -    DIM brightnessWhat OFF --> DIMMER_LEVEL_8  WHAT level change needed
2021-02-26 17:10:36.603 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD -------> *1*8*25#4#02##
2021-02-26 17:10:36.605 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD ====>>>> *1*8*25#4#02##
2021-02-26 17:10:36.607 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD |<--     NO DATA (size=0)
2021-02-26 17:10:36.614 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## Exception: Received null frame while reading responses to command
2021-02-26 17:10:36.620 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## trying NEW CMD connection...
2021-02-26 17:10:36.622 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## Establishing CMD connection to BUS Gateway on 172.20.90.1:20000...
2021-02-26 17:10:36.632 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## CMD socket connected
2021-02-26 17:10:36.634 [DEBUG] [nwebnet4j.communication.BUSConnector] - (HS) starting HANDSHAKE on channel BUS-CMD... 
2021-02-26 17:10:36.636 [DEBUG] [communication.BUSConnector.handshake] - (HS) ... STEP-1: receive ACK from GW
2021-02-26 17:10:36.637 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - handleCommand() (command=ON - channel=openwebnet:bus_on_off_switch:bticino:Bad_Dusche_Li:switch)
2021-02-26 17:10:36.639 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD <------- [*#*1##]
2021-02-26 17:10:36.639 [DEBUG] [et.handler.OpenWebNetLightingHandler] - handleSwitchCommand() (command=ON - channel=openwebnet:bus_on_off_switch:bticino:Bad_Dusche_Li:switch)
2021-02-26 17:10:36.641 [INFO ] [communication.BUSConnector.handshake] - (HS) BUS-CMD <<<<==HS *#*1##
2021-02-26 17:10:36.642 [WARN ] [et.handler.OpenWebNetLightingHandler] - Exception while processing command ON: CMD is not connected
2021-02-26 17:10:36.643 [DEBUG] [communication.BUSConnector.handshake] - (HS) ... STEP-1: first ACK received
2021-02-26 17:10:36.645 [DEBUG] [communication.BUSConnector.handshake] - (HS) ... STEP-2: send session request *99*0## ... 
2021-02-26 17:10:36.647 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD -------> *99*0##
2021-02-26 17:10:36.649 [INFO ] [communication.BUSConnector.handshake] - (HS) BUS-CMD HS==>>>> *99*0##
2021-02-26 17:10:36.651 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD <------- [*#*1##]
2021-02-26 17:10:36.653 [INFO ] [communication.BUSConnector.handshake] - (HS) BUS-CMD <<<<==HS *#*1##
2021-02-26 17:10:36.655 [DEBUG] [communication.BUSConnector.handshake] - (HS) ... STEP-2: NO_AUTH: second ACK received, GW has no pwd ==HANDSHAKE COMPLETED==
2021-02-26 17:10:36.657 [INFO ] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## ============ CMD CONNECTED ============
2021-02-26 17:10:36.659 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD -------> *1*8*25#4#02##
2021-02-26 17:10:36.661 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD ====>>>> *1*8*25#4#02##
2021-02-26 17:10:36.684 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - handleCommand() (command=ON - channel=openwebnet:bus_on_off_switch:bticino:Bad_Waschtisch_Li:switch)
2021-02-26 17:10:36.688 [DEBUG] [et.handler.OpenWebNetLightingHandler] - handleSwitchCommand() (command=ON - channel=openwebnet:bus_on_off_switch:bticino:Bad_Waschtisch_Li:switch)
2021-02-26 17:10:36.694 [INFO ] [.smarthome.model.script.musicControl] - item = iBad_CenMH_Musik_Ein
2021-02-26 17:10:36.697 [INFO ] [.smarthome.model.script.musicControl] - location = iBad
2021-02-26 17:10:36.700 [INFO ] [.smarthome.model.script.musicControl] - ictKey = CenMH_Musik_Ein
2021-02-26 17:10:36.702 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iBad_CenMH_Musik_Ein-changed_7cdd81b0720011eba319dca632261beb_7cdda8c0720011ebb527dca632261beb' of rule 'd6624e10-fcaf-48d9-8285-f866f805ddfb' is triggered.
2021-02-26 17:10:36.705 [INFO ] [.smarthome.model.script.musicControl] - state = PRESSED
2021-02-26 17:10:36.712 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - handleCommand() (command=ON - channel=openwebnet:bus_on_off_switch:bticino:Bad_Ambiente_Li:switch)
2021-02-26 17:10:36.711 [INFO ] [odel.script.musik_AusEinLauterLeiser] - Funktion aufgerufen: sendCommand(iBad_Musik, 1)
2021-02-26 17:10:36.714 [DEBUG] [et.handler.OpenWebNetLightingHandler] - handleSwitchCommand() (command=ON - channel=openwebnet:bus_on_off_switch:bticino:Bad_Ambiente_Li:switch)
2021-02-26 17:10:36.720 [INFO ] [se.smarthome.model.script.bt_manager] - bt_manager data: *1*1000#8*25#4#02##
2021-02-26 17:10:36.720 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.725 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'd6624e10-fcaf-48d9-8285-f866f805ddfb' is executed.
2021-02-26 17:10:36.738 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iBad_Li-changed_24b1723074df11eb92ffdca632261beb_24b20e7074df11eb8672dca632261beb' of rule 'ff4a6e5c-3c06-4fbd-afb7-a78b0964a594' is triggered.
2021-02-26 17:10:36.743 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD <------- [*#*1##]
2021-02-26 17:10:36.745 [DEBUG] [.openwebnet4j.communication.Response] - <*1*8*25#4#02##>   <<add   <*#*1##>
2021-02-26 17:10:36.764 [DEBUG] [.openwebnet4j.communication.Response] - now: <*1*8*25#4#02##>   <<==    [<*#*1##>]
2021-02-26 17:10:36.746 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iBad_Li-changed_253e970074df11ebac63dca632261beb_253f0c3074df11eba684dca632261beb' of rule 'e618bf20-a7b7-44fc-801f-ad643a1d6a9e' is triggered.
2021-02-26 17:10:36.765 [DEBUG] [j.communication.BUSConnector.message] - BUS-CMD   <<==   *#*1##
2021-02-26 17:10:36.767 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD <<<<==== [<*#*1##>]
2021-02-26 17:10:36.769 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## ^^^^^^^^ USED NEW    CONNECTION    ^^^^^^^^
2021-02-26 17:10:36.773 [DEBUG] [et.handler.OpenWebNetLightingHandler] -    DIM---END bri=80 briBeforeOff=80
2021-02-26 17:10:36.762 [INFO ] [thome.model.script.save_dimmer_level] - Item lBad_Li speichert neuen Dimmerlevel 80
2021-02-26 17:10:36.756 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.779 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD -------> *1*1*23#4#02##
2021-02-26 17:10:36.786 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD ====>>>> *1*1*23#4#02##
2021-02-26 17:10:36.788 [INFO ] [se.smarthome.model.script.bt_manager] - bt_manager data: *1*8*25#4#02##
2021-02-26 17:10:36.788 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'e618bf20-a7b7-44fc-801f-ad643a1d6a9e' is executed.
2021-02-26 17:10:36.797 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.postUpdate' function is pending deprecation.
2021-02-26 17:10:36.801 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ff4a6e5c-3c06-4fbd-afb7-a78b0964a594' is executed.
2021-02-26 17:10:36.808 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*1*8*25#4#02##]
2021-02-26 17:10:36.809 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *1*8*25#4#02##
2021-02-26 17:10:36.812 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*1*8*25#4#02##>) --> 1.25h4h02
2021-02-26 17:10:36.814 [DEBUG] [et.handler.OpenWebNetLightingHandler] - handleMessage(<*1*8*25#4#02##>) for thing: openwebnet:bus_dimmer:bticino:Bad_Li
2021-02-26 17:10:36.816 [DEBUG] [et.handler.OpenWebNetLightingHandler] -   $BRI updateBrightness(<*1*8*25#4#02##>)       || bri=80 briBeforeOff=80
2021-02-26 17:10:36.818 [DEBUG] [et.handler.OpenWebNetLightingHandler] -   $BRI delta=221ms < DELAY
2021-02-26 17:10:36.820 [DEBUG] [et.handler.OpenWebNetLightingHandler] -   $BRI a command was sent 221 < 900 ms --> no action needed
2021-02-26 17:10:36.821 [DEBUG] [et.handler.OpenWebNetLightingHandler] -   $BRI---END updateBrightness(<*1*8*25#4#02##>) || bri=80 briBeforeOff=80
2021-02-26 17:10:36.849 [INFO ] [se.smarthome.model.script.bt_manager] - bt_manager data: *25*24#3*261##
2021-02-26 17:10:36.864 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iBad_Musik-changed_7cdb10b0720011ebadd7dca632261beb_7cdb37c0720011ebbdafdca632261beb' of rule 'd6624e10-fcaf-48d9-8285-f866f805ddfb' is triggered.
2021-02-26 17:10:36.867 [INFO ] [.smarthome.model.script.musicControl] - item = iBad_Musik
2021-02-26 17:10:36.869 [INFO ] [.smarthome.model.script.musicControl] - location = iBad
2021-02-26 17:10:36.871 [INFO ] [.smarthome.model.script.musicControl] - ictKey = Musik
2021-02-26 17:10:36.873 [INFO ] [.smarthome.model.script.musicControl] - state = 1
2021-02-26 17:10:36.878 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*25*24#3*261##]
2021-02-26 17:10:36.879 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *25*24#3*261##
2021-02-26 17:10:36.881 [DEBUG] [nwebnet4j.communication.BUSConnector] - UNSUPPORTED FRAME: *25*24#3*261##, skipping it
2021-02-26 17:10:36.891 [INFO ] [se.smarthome.model.script.bt_manager] - bt_manager data: *1*1000#1*23#4#02##
2021-02-26 17:10:36.899 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.902 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD <------- [*#*1##]
2021-02-26 17:10:36.904 [DEBUG] [.openwebnet4j.communication.Response] - <*1*1*23#4#02##>   <<add   <*#*1##>
2021-02-26 17:10:36.907 [DEBUG] [.openwebnet4j.communication.Response] - now: <*1*1*23#4#02##>   <<==    [<*#*1##>]
2021-02-26 17:10:36.907 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.909 [DEBUG] [j.communication.BUSConnector.message] - BUS-CMD   <<==   *#*1##
2021-02-26 17:10:36.912 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD <<<<==== [<*#*1##>]
2021-02-26 17:10:36.912 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iJython_Busbefehl-received-update_3f1d9b21769d11eb9807dca632261beb_3f1e8580769d11eb8fc4dca632261beb' of rule '36f5ca5e-5b7c-4553-94a4-26b5cca7b711' is triggered.
2021-02-26 17:10:36.914 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## ^^^^^^^^ REUSED    CONNECTION    ^^^^^^^^
2021-02-26 17:10:36.915 [INFO ] [se.smarthome.model.script.bt_manager] - OWN-Befehl gesendet: *16*3*131##
2021-02-26 17:10:36.918 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD -------> *1*1*22#4#02##
2021-02-26 17:10:36.919 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD ====>>>> *1*1*22#4#02##
2021-02-26 17:10:36.918 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.938 [INFO ] [se.smarthome.model.script.bt_manager] - bt_manager data: *1*1*23#4#02##
2021-02-26 17:10:36.940 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iBad_Verstaerker-changed_7cdc492e720011ebb6b4dca632261beb_7cdc7040720011eb882adca632261beb' of rule 'd6624e10-fcaf-48d9-8285-f866f805ddfb' is triggered.
2021-02-26 17:10:36.939 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.948 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iJython_Busbefehl-received-update_3f1d9b21769d11eb9807dca632261beb_3f1e8580769d11eb8fc4dca632261beb' of rule '36f5ca5e-5b7c-4553-94a4-26b5cca7b711' is triggered.
2021-02-26 17:10:36.960 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:36.991 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'd6624e10-fcaf-48d9-8285-f866f805ddfb' is executed.
2021-02-26 17:10:36.994 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*1*1*23#4#02##]
2021-02-26 17:10:36.996 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *1*1*23#4#02##
2021-02-26 17:10:37.007 [INFO ] [se.smarthome.model.script.bt_manager] - bt_manager data: *1*1000#1*22#4#02##
2021-02-26 17:10:37.007 [INFO ] [.smarthome.model.script.musicControl] - item = iBad_Verstaerker
2021-02-26 17:10:37.011 [INFO ] [.smarthome.model.script.musicControl] - location = iBad
2021-02-26 17:10:37.000 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*1*1*23#4#02##>) --> 1.23h4h02
2021-02-26 17:10:37.017 [INFO ] [.smarthome.model.script.musicControl] - ictKey = Verstaerker
2021-02-26 17:10:37.020 [DEBUG] [et.handler.OpenWebNetLightingHandler] - handleMessage(<*1*1*23#4#02##>) for thing: openwebnet:bus_on_off_switch:bticino:Bad_Ambiente_Li
2021-02-26 17:10:37.022 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD <------- [*#*1##]
2021-02-26 17:10:37.024 [DEBUG] [.openwebnet4j.communication.Response] - <*1*1*22#4#02##>   <<add   <*#*1##>
2021-02-26 17:10:37.027 [DEBUG] [.openwebnet4j.communication.Response] - now: <*1*1*22#4#02##>   <<==    [<*#*1##>]
2021-02-26 17:10:37.025 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule '36f5ca5e-5b7c-4553-94a4-26b5cca7b711' is executed.
2021-02-26 17:10:37.026 [INFO ] [.smarthome.model.script.musicControl] - state = ON
2021-02-26 17:10:37.036 [DEBUG] [j.communication.BUSConnector.message] - BUS-CMD   <<==   *#*1##
2021-02-26 17:10:37.028 [DEBUG] [et.handler.OpenWebNetLightingHandler] -   1.23h4h02 ONOFF CHANGED to 1
2021-02-26 17:10:37.038 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD <<<<==== [<*#*1##>]
2021-02-26 17:10:37.040 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## ^^^^^^^^ REUSED    CONNECTION    ^^^^^^^^
2021-02-26 17:10:37.044 [INFO ] [thome.model.script.musik_Verstaerker] - Funktion aufgerufen: sendCommand(iJython_Busbefehl, *16*3*31##)
2021-02-26 17:10:37.052 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 17:10:37.054 [INFO ] [se.smarthome.model.script.bt_manager] - OWN-Befehl gesendet: *#16*31*#1*5*##
2021-02-26 17:10:37.060 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'd6624e10-fcaf-48d9-8285-f866f805ddfb' is executed.
2021-02-26 17:10:37.073 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule '36f5ca5e-5b7c-4553-94a4-26b5cca7b711' is executed.
2021-02-26 17:10:37.078 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-MON <------- [*1*1*22#4#02##]
2021-02-26 17:10:37.080 [INFO ] [unication.BUSConnector.message.event] - BUS-MON <<<<<<<< *1*1*22#4#02##
2021-02-26 17:10:37.089 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ownIdFromMessage(<*1*1*22#4#02##>) --> 1.22h4h02
2021-02-26 17:10:37.095 [DEBUG] [et.handler.OpenWebNetLightingHandler] - handleMessage(<*1*1*22#4#02##>) for thing: openwebnet:bus_on_off_switch:bticino:Bad_Waschtisch_Li
2021-02-26 17:10:37.105 [DEBUG] [et.handler.OpenWebNetLightingHandler] -   1.22h4h02 ONOFF CHANGED to 1
2021-02-26 17:10:37.150 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'Item-iJython_Busbefehl-received-update_3f1d9b21769d11eb9807dca632261beb_3f1e8580769d11eb8fc4dca632261beb' of rule '36f5ca5e-5b7c-4553-94a4-26b5cca7b711' is triggered.
2021-02-26 17:10:37.152 [INFO ] [se.smarthome.model.script.bt_manager] - OWN-Befehl gesendet: *16*3*31##
2021-02-26 17:10:37.160 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule '36f5ca5e-5b7c-4553-94a4-26b5cca7b711' is executed.

… and even another: my shutters close at nauticdusk. today the shutter iEWoK_Sitzfenster_Ja did not.

iEWoK_Sitzfenster_Ja has own-address *86#4#01##, the address *85#4#01## is shutter iEWoK_Tuere_Ja (what closed correct)

here the log:

2021-02-26 18:31:00.039 [INFO ] [home.model.script.shutter_management] - Guten Abend! Schließe iEWoK_Tuere_Ja
2021-02-26 18:31:00.047 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 18:31:00.072 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.postUpdate' function is pending deprecation.
2021-02-26 18:31:00.079 [INFO ] [home.model.script.shutter_management] - Guten Abend! Schließe iEWoK_Sitzfenster_Ja
2021-02-26 18:31:00.087 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 18:31:00.099 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.postUpdate' function is pending deprecation.
2021-02-26 18:31:00.108 [INFO ] [home.model.script.shutter_management] - Guten Abend! Schließe iEWoK_Essen_Ja
2021-02-26 18:31:00.116 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 18:31:00.126 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.postUpdate' function is pending deprecation.
2021-02-26 18:31:00.134 [INFO ] [home.model.script.shutter_management] - Guten Abend! Schließe iBalkon_Ro mit Spezialfunktion
2021-02-26 18:31:00.138 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - handleCommand() (command=DOWN - channel=openwebnet:bus_automation:bticino:EWoK_Tuere_Ja:shutter)
2021-02-26 18:31:00.138 [INFO ] [home.model.script.shutter_management] - Closing-Spezial für iBalkon_Ro
2021-02-26 18:31:00.151 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD -------> *2*2*85#4#01##
2021-02-26 18:31:00.153 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD ====>>>> *2*2*85#4#01##
2021-02-26 18:31:00.160 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD |<--     NO DATA (size=0)
2021-02-26 18:31:00.163 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## Exception: Received null frame while reading responses to command
2021-02-26 18:31:00.170 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## trying NEW CMD connection...
2021-02-26 18:31:00.173 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## Establishing CMD connection to BUS Gateway on 172.20.90.1:20000...
2021-02-26 18:31:00.183 [DEBUG] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## CMD socket connected
2021-02-26 18:31:00.189 [DEBUG] [nwebnet4j.communication.BUSConnector] - (HS) starting HANDSHAKE on channel BUS-CMD... 
2021-02-26 18:31:00.192 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.postUpdate' function is pending deprecation.
2021-02-26 18:31:00.199 [INFO ] [home.model.script.shutter_management] - Guten Abend! Schließe iEGFlur_TreppeFenster_Ro
2021-02-26 18:31:00.205 [DEBUG] [communication.BUSConnector.handshake] - (HS) ... STEP-1: receive ACK from GW
2021-02-26 18:31:00.209 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD <------- [*#*1##]
2021-02-26 18:31:00.212 [INFO ] [communication.BUSConnector.handshake] - (HS) BUS-CMD <<<<==HS *#*1##
2021-02-26 18:31:00.205 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 18:31:00.215 [DEBUG] [communication.BUSConnector.handshake] - (HS) ... STEP-1: first ACK received
2021-02-26 18:31:00.218 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 18:31:00.222 [DEBUG] [communication.BUSConnector.handshake] - (HS) ... STEP-2: send session request *99*0## ... 
2021-02-26 18:31:00.226 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - handleCommand() (command=DOWN - channel=openwebnet:bus_automation:bticino:EWoK_Sitzfenster_Ja:shutter)
2021-02-26 18:31:00.232 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD -------> *99*0##
2021-02-26 18:31:00.232 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.postUpdate' function is pending deprecation.
2021-02-26 18:31:00.247 [INFO ] [communication.BUSConnector.handshake] - (HS) BUS-CMD HS==>>>> *99*0##
2021-02-26 18:31:00.256 [INFO ] [home.model.script.shutter_management] - Guten Abend! Schließe iSchlafzi_Tuere_Ro
2021-02-26 18:31:00.252 [DEBUG] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD <------- [*#*1##]
2021-02-26 18:31:00.251 [DEBUG] [.handler.OpenWebNetAutomationHandler] - Exception while sending request for command DOWN: CMD is not connected
org.openwebnet4j.communication.OWNException: CMD is not connected
	at org.openwebnet4j.communication.OpenConnector.sendCommandSynch(OpenConnector.java:116) ~[bundleFile:?]
	at org.openwebnet4j.OpenGateway.sendInternal(OpenGateway.java:175) ~[bundleFile:?]
	at org.openwebnet4j.OpenGateway.send(OpenGateway.java:155) ~[bundleFile:?]
	at org.openhab.binding.openwebnet.handler.OpenWebNetThingHandler.send(OpenWebNetThingHandler.java:167) ~[bundleFile:?]
	at org.openhab.binding.openwebnet.handler.OpenWebNetAutomationHandler.handleShutterCommand(OpenWebNetAutomationHandler.java:186) [bundleFile:?]
	at org.openhab.binding.openwebnet.handler.OpenWebNetAutomationHandler.handleChannelCommand(OpenWebNetAutomationHandler.java:155) [bundleFile:?]
	at org.openhab.binding.openwebnet.handler.OpenWebNetThingHandler.handleCommand(OpenWebNetThingHandler.java:130) [bundleFile:?]
	at sun.reflect.GeneratedMethodAccessor926.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_212]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
	at com.sun.proxy.$Proxy21133.handleCommand(Unknown Source) [?:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:74) [bundleFile:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_212]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_212]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2021-02-26 18:31:00.273 [INFO ] [communication.BUSConnector.handshake] - (HS) BUS-CMD <<<<==HS *#*1##
2021-02-26 18:31:00.278 [DEBUG] [communication.BUSConnector.handshake] - (HS) ... STEP-2: NO_AUTH: second ACK received, GW has no pwd ==HANDSHAKE COMPLETED==
2021-02-26 18:31:00.281 [INFO ] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## ============ CMD CONNECTED ============
2021-02-26 18:31:00.282 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.sendCommand' function is pending deprecation.
2021-02-26 18:31:00.291 [INFO ] [nwebnet4j.communication.FrameChannel] - -FC-BUS-CMD -------> *2*2*85#4#01##
2021-02-26 18:31:00.295 [WARN ] [jsr223.jython.core.utils            ] - The 'core.utils.postUpdate' function is pending deprecation.
2021-02-26 18:31:00.299 [INFO ] [j.communication.BUSConnector.message] - BUS-CMD ====>>>> *2*2*85#4#01##

Hi @massi the version of OH that I have used is 2.5.10 because I must use a qpkg version for my QNAP NAS (recently I found OH 3.0).
This release works well with both version (official release and TESTING version) for the Light and Automation, but I’ve installed the TESTING version manually because I would like to use the thermo functionality of my 3550 central and the sensor of theft protection.
Do you have any suggestion?

Great job!!!
Gonna test it as available and hope Thermo will come soon :stuck_out_tongue:

Great news!!
As soon as I will migrate to 3.0 I’ll start testing

Sorry, no support for the TESTING version. Eventually OH 3 will include also Thermo.

Thank you @massi, I will try to migrate asap to OH 3.

hi @bastler, this a bug in the new lib:
when the CMD connection to the gateway is closed (it happens after 120s from last command sent) then when in a rule several actions are sent in parallel by OH, the first action will re-open the CMD connection and will go through, while other subsequent actions(commands) to the gateway will fail until the connection to the gw is restored. I will open an issue on github and work on a solution.

1 Like

hi @bastler, this a bug in the new lib:
when the CMD connection to the gateway is closed (it happens after 120s from last command sent) then when in a rule several actions are sent in parallel by OH, the first action will re-open the CMD connection and will go through, while other subsequent actions(commands) to the gateway will fail until the connection to the gw is restored. I will open an issue on github and work on a solution.

Hi Massi,

I have a similar problem in OH3. I use to open/close rollershutters as groups. It happens several times that OH3 misses to activate some rolleshutters when I open or close a group of them. If I run the command a second time then also the missed rolleshutters work. I wonder if this behavior could be due to the same bug you mentioned.
I could get the debug logs if you think it can help.

Thanks,

G

yes it’s the same cause. In fact any sequence of commands sent after a 120s interval is affected. I think in OH3 the problem is worse because commands in rules are sent in parallel tasks.
I opened this issue:

I have the same bug (OH3).
The only temporary solution I found is a dirty one, and I’m not sure if it is a good idea… but it seems to work quite ok for my setup for now.

I use a [ where=“0” ] bus_automation Thing and relative Rollershutter Item. This seems to move all the rollershutters, while using the OH group was always “forgetting” a rollershutter or two behind.

The con is that this command does not update the single rollershutters positions after they are moved. In order to update the positions, i have set a rule to listen to the commands given to the where=0 item and send the same command to all rollershutters individually. This way most of the times the positions are updated. The ugly part is that every time 2 consecutive commands are fired: so the rollershutters start to move (where=0 item command), then after 1,2,3,… seconds the single items receive the command from the rule with the result that the rollershutters stop and then start moving again.

Before this I also tried using a timer to give the commands to the rollershutters delayed from one another, but with mixed results, so not a reliable solution in my case.

.things

bus_automation           Generale_tapp        "Generale Tapparelle"             @ "Ingresso"            [ where="0" ]

bus_automation           Cucina_tapp1         "Tapparella 1 Cucina"             @ "Cucina"              [ where="91" ]
bus_automation           Cucina_tapp2         "Tapparella 2 Cucina"             @ "Cucina"              [ where="94" ]

...

.items

Rollershutter  iGenerale_tapp         "Generale Tapparelle"                             <rollershutter>  (gGenerale)                                [ "Blinds" ]       { channel="openwebnet:bus_automation:mybridge:Generale_tapp:shutter", ga="Blinds" [ name="Tutte le tapparelle" ] }

Rollershutter  iCucina_tapp1          "Tapparella 1 Cucina [chiusa: %d%%]"              <rollershutter>  (gCucina, gTapparelle, gTCucina)           [ "Blinds" ]       { channel="openwebnet:bus_automation:mybridge:Cucina_tapp1:shutter", autoupdate="true", ga="Blinds" [ roomHint="Cucina", name="Tapparella 1" ] }
Rollershutter  iCucina_tapp2          "Tapparella 2 Cucina [chiusa: %d%%]"              <rollershutter>  (gCucina, gTapparelle, gTCucina)           [ "Blinds" ]       { channel="openwebnet:bus_automation:mybridge:Cucina_tapp2:shutter", autoupdate="true", ga="Blinds" [ roomHint="Cucina", name="Tapparella 2" ] }

...

Group:Rollershutter:OR(UP, DOWN)    gTapparelle  "Tutte le tapparelle"          <rollershutter>   (gAppartamento)

.rules

rule "Traccia comando a iGenerale_tapp e aggiorna lo stato di tutti i membri di gTapparelle"
when 
Item iGenerale_tapp received command
then 
	logWarn("bticino.rules", ">>>>> iGenerale_tapp received command: " + receivedCommand) 
	// preparo un timer per aggiornare i vari item dopo 30 secondi (quindi di sicuro dopo che le tapparelle si sono spostate)
	createTimer(now.plusSeconds(30)) [ |
		gTapparelle.members.forEach[ item |
			item.sendCommand("REFRESH")
			//item.sendCommand( RefreshType.REFRESH )
		]
	]
	// fornisco lo stesso comando ai vari item per forzare l'aggiornamento dello status
	gTapparelle.members.forEach[ item |
		item.sendCommand(receivedCommand) 
		Thread::sleep(1000) 
	]
end

About the item.sendCommand("REFRESH") part - TBH I’m not sure if it is working, I left it there just-in-case.

Thank you for letting us now, I was having the same issue.
So, if we send a single command not more than 120s before sending the sequence, we should not face this issue. Right? This could be a temporary workaround.

Thank you Massimo for your development!
I was wondering if BTicino stuff was able to work with OpenHAB and since I found this post I decided to go for it!
So, thanks to this post, I decided to purchase BTicino stuff for my new house, purchase a Raspberry, and definetely start using openhab!
Thanks again! Cheers
Claudio

This is great news! As soon as it will be added I can test it and report back.
About Energy Management, i have a F520 with 3 toroids attached. Right now openHAB (v.2) tracks any single change, which translates in a huge amount of updates, almost every second, because it reports any small change of 1Watt. Is it possible to control this behaviour, somehow? On a time base (e.g. once a minute) or on a delta (e.g. track only if the change is >10W)? This could help to prevent unnecessary updates (and make the logs lighter - reducing frequent writing to the disk - preventing block wear).

Source code was merged into the main branch this sunday, binaries should be availlable within OH 3.1 M3.

@AEM It will work in the same way as before (updated almost every second) because It’s not possibile to set up a delta (>10W) or a time base.

Which logs are you referring to? However the binding logs have been reduced (there will not be a trace each second).

Hello Andrea, thank you for your answer. I use openHABian, the logs I am referring to are those available in Frontail (/var/log/openhab/openhab.log and /var/log/openhab/events.log), see attachment. It’s good to know the BTicino binding logs will be reduced (I remember I read something about it in one of the latest posts from @massi). Right now I am using the Remote openHAB Binding to receive on my OH3 energy management data from an OH2 installation (as posted here). When OH 3.1 M3 willl be released I will test it and report back. Thank you for your work!

I can confirm you that openhab.log were riduced but events.log is still the same because it’s outside the binding itself: it’s a statechange of an item and the openhab architecture will track it.
I actually don’t know if it’s possible to change this behaviour, I’ll look for it in the documentation.

2021-03-26 11:52:29.790 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘EnergyMeter_Power’ changed from 408 W to 419 W

2021-03-26 11:52:50.726 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘EnergyMeter_Power’ changed from 419 W to 407 W

2021-03-26 11:53:17.527 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘EnergyMeter_Power’ changed from 407 W to 431 W

2021-03-26 11:53:20.513 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘EnergyMeter_Power’ changed from 431 W to 497 W

Hello All,

On wikipedia Openwebnet I read that there are multiple WHO that could be exploited, I know this binding is work in progress and the result of the votes did not give the priority to other WHO. But is there an easy way to add a generic item where it is possible to configure the WHO WHAT WHERE ?

0 Scenario
1 Lighting
2 Automation
3 Load control
4 Temperature Control/Heating
5 Burglar Alarm/Intrusion
6 Door Entry System
7 Video Door Entry System/multimedia
9 Auxiliary
13 Gateway/interfaces management
14 Light+shutters actuators lock
15 CEN/Scenario Scheduler, switch
16 Sound System/Audio
17 Scenario programming
18 Energy Management
24 Lighting Management
25 CEN/Scenario Scheduler, buttons

for example with the OpenWeb Windows client i able to see what frame is to be send on the bus to do certain action, and it is possible to send some from OpenHab? I was thinking it would be a quick-win for Openhab user to be able to customise a generic frame. Especially for WHO=0 in order to call an existing scenario made on TouchSceen.

Would that be a cool feature ? how hard is it to add this to development ?
If so I would be happy to help testing it