[BTicino/OpenWebNet] New openHAB2 binding ready for testing

Hello @massi
I’m having the same issue again, but now I see a different message on the log:

2021-01-24 21:10:03.099 [DEBUG] [ebnet.handler.OpenWebNetThingHandler] - handleCommand() (command=OFF - channel=openwebnet:bus_on_off_switch:MH202_00035001e89b:18:switch)

2021-01-24 21:10:03.102 [DEBUG] [et.handler.OpenWebNetLightingHandler] - handleSwitchCommand() (command=OFF - channel=openwebnet:bus_on_off_switch:MH202_00035001e89b:18:switch)

2021-01-24 21:10:03.107 [WARN ] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## Exception: Received null frame while reading responses to command

2021-01-24 21:10:03.111 [WARN ] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## trying NEW CMD connection...

2021-01-24 21:10:03.133 [WARN ] [communication.BUSConnector.handshake] - (HS) ... STEP-2: cannot authenticate with gateway (unexpected answer: *#971908##)

2021-01-24 21:10:03.135 [ERROR] [nwebnet4j.communication.BUSConnector] - ##BUS-conn## openCommandConnection() returned exception (Cannot authenticate with gateway: handshake failed at STEP-2 (unexpected answer: *#971908##)) while opening NEW CMD connection

2021-01-24 21:10:03.136 [ERROR] [webnet4j.communication.OpenConnector] - ##OPEN-conn## IOException while sending frame *1*0*18## or reading response: Cannot create NEW CMD connection to send message *1*0*18##

2021-01-24 21:10:03.138 [WARN ] [et.handler.OpenWebNetLightingHandler] - Exception while processing command OFF: IOException while sending frame *1*0*18## or reading response: Cannot create NEW CMD connection to send message *1*0*18##

2021-01-24 21:10:05.119 [WARN ] [nwebnet4j.communication.BUSConnector] - (HS) ... handshake not completed but timeout expired, closing BUS-CMD channel

What do you recommend?

Hello @mrteo90, I think I know what is happening…
But I need more logs, do this:

  • from Karaf console:
    • log:set DEBUG org.openhab.binding.openwebnet
    • log:set DEBUG org.openwebnet4j

Both log:set commands are important to log OWN commands exchanged between the binding and the OpenWebNet gateway.

Log files are written to either userdata/log (manual setup) or /var/log/openhab2 (Linux and RaspberryPi image setup)

Copy the log file when the error happens and send it to me via private message

Bye

I didn’t know about the vote… I’m still on OH2, I migrated on OH3 but did some dumb mistake the day after and didn’t have a backup yet, so I put a backup of OH2 :smiley:
I will migrate again to OH3 soon and I only have WHO =1 and WHO=4 in my home.
Thanks @massi for all the work!

Hi,
perhaps it’s better seen in here, in the Openwebnet Club.

Can anyone help me with the new OH3 and official binding? MH200N is online but I don’t know how to use it from that on. I don’t know how to do the second inbox scan to discover BUS devices and I can’t use my .items file from OH2.

Please help!

Hello Chris,
I am using OH3, but with .things and .items files, which is not probably the best with OH3, but I found it easier as a first step coming from OH2.

In my case, lights and rollershutters worked OOB with the old .things files I was using on OH2, I think I didn’t edit anything. Just to be sure, you are using Lighting and Shutters (who 1 and 2 in Openwebnet), right? Because CEN and power management are not supported ATM in the OH3 binding (I was using them myself in OH2, am waiting for them to be implemented - willing to support / test if needed!).

First I suggest you use only one approach: scan vs text files. A mix of the two seems like a solution that will not be easy to maintain and that can be a headache to work with.

If you decide to use text files, can you post them here?
If you decide to use the UI and scan for things, I am not sure I can help, maybe someone else has a clue there. If things don’t appear automatically in your inbox, you can try to scan going to things > " + " round button in the bottom right corner of the page > OpenWebNet (BTicino/Legrand) Binding > “Scan” button in the top center of the page. I just tried and it seems to work for me (I use a MyHomeSERVER1).

To temporary support features that were available in OH2 and are not (yet) available in OH3, you can use the Remote openHAB Binding.

Of course this means you need to have 2 openHAB servers: one with OH3 and one with OH2.

In my case, for example, I have transfered everything to OH3, including all the BTicino lights and rollershutters.
The only thing that I have left in my old OH2 server is the power management of my F520, since it is not supported in OH3 ATM.

So on OH2 (with the last “TESTING” release) I have:

bticino.things

Bridge  openwebnet:bus_gateway:mybridge           "MyHOMEServer1"                   @ "Bagno Piccolo"       [ host="192.168.2.100", passwd="********" ] {  
    // ENERGY MANAGEMENT (F520)
    bus_energy_central_unit  F520_Generale        "Consumo Generale"                @ "Power"               [ where="51" ] // Ta
    bus_energy_central_unit  F520_Luci            "Consumo Luci"                    @ "Power"               [ where="52" ] // Tb
    bus_energy_central_unit  F520_Lavastoviglie   "Consumo Lavastoviglie"           @ "Power"               [ where="53" ] // Tc
}

bticino.items

// ENERGY MANAGEMENT (F520)
Number        iF520_Generale         "Consumo [%.0f W]"     <energy>    (gPower, gPower_Load)    { channel="openwebnet:bus_energy_central_unit:mybridge:F520_Generale:power" }
Number        iF520_Luci             "Consumo [%.0f W]"     <energy>    (gPower, gPower_Load)    { channel="openwebnet:bus_energy_central_unit:mybridge:F520_Luci:power" }
Number        iF520_Lavastoviglie    "Consumo [%.0f W]"     <energy>    (gPower, gPower_Load)    { channel="openwebnet:bus_energy_central_unit:mybridge:F520_Lavastoviglie:power" }

In OH3, once you install the Remote openHAB Binding, if you want to use the UI, you can do a scan and it will find the OH2 server. If you add it, it will list all the available OH2 items as channels of your thing.

If you want to use text files, which is my approach, you can do as follows:

remoteopenhab.things

Bridge remoteopenhab:server:oh2 "OH2 server" [ host="192.168.2.151", port=8443, useHttps=true, trustedCertificate=true ] {
    Thing thing F520_Generale_rem 		"Consumo Generale" 			[ thingUID="openwebnet:bus_energy_central_unit:mybridge:F520_Generale" ]
    Thing thing F520_Luci_rem 			"Consumo Luci" 				[ thingUID="openwebnet:bus_energy_central_unit:mybridge:F520_Luci" ]
    Thing thing F520_Lavastoviglie_rem 	"Consumo Lavastoviglie" 	[ thingUID="openwebnet:bus_energy_central_unit:mybridge:F520_Lavastoviglie" ]
}

(note the Thing thing... are not strictly necessary, the server is enough -it depends if you want also your things from OH2 listed as things in OH3 for some reason)

remoteopenhab.items

Number   iF520_Generale_rem         "Consumo Generale [%.0f W]"         <energy>     (gPower, gPower_Load, gGenerale)   [ "Sensor" ]     { channel="remoteopenhab:server:oh2:iF520_Generale" }
Number   iF520_Luci_rem             "Consumo Luci [%.0f W]"             <energy>     (gPower, gPower_Load, gGenerale)   [ "Sensor" ]     { channel="remoteopenhab:server:oh2:iF520_Luci" }
Number   iF520_Lavastoviglie_rem    "Consumo Lavastoviglie [%.0f W]"    <energy>     (gPower, gPower_Load, gCucina)     [ "Sensor" ]     { channel="remoteopenhab:server:oh2:iF520_Lavastoviglie" }

That’s it, now you have your items from OH2 available in OH3. :slightly_smiling_face:

And you shoud see it also in the Logs:

Hello,

I’ve installed a 2.5.10 openhab version for my QNAP NAS with the last library for openwebnet (lib-0.9.24) released from Massimo recently.
I’m using a webserver F453AV with an old version of the firmware.
With the discover I didn’t find anything, but if I add manually switch and dimmer or roller shutter i have not problem and all run perfectly.
For thermo I’m using the central bticino 3550 with local scs thermostat L4692.
Unfortunately when I configure a thermostat I have this message: (UNINITIALIZED)

I append some record of the log where I found the WHO=4 that is referred to thermo section if it can help to understand where is the problem:
==OWN== ownId=4.2
2021-02-12 20:28:23.688 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.2 has NO DEVICE associated, ignoring it
2021-02-12 20:28:24.207 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #42100219##
2021-02-12 20:28:24.208 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.21
2021-02-12 20:28:24.208 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.21 has NO DEVICE associated, ignoring it
2021-02-12 20:28:24.727 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #42200200##
2021-02-12 20:28:24.728 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.22
2021-02-12 20:28:24.728 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.22 has NO DEVICE associated, ignoring it
2021-02-12 20:28:25.257 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #42300210##
2021-02-12 20:28:25.258 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.23
2021-02-12 20:28:25.258 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.23 has NO DEVICE associated, ignoring it
2021-02-12 20:28:25.777 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #42400212##
2021-02-12 20:28:25.777 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.24
2021-02-12 20:28:25.778 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.24 has NO DEVICE associated, ignoring it
2021-02-12 20:28:25.874 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #13*#0203000##
2021-02-12 20:28:25.875 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## handleManagementDimension not processed
2021-02-12 20:28:25.875 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== GatewayManagement WHAT = null, ignoring
2021-02-12 20:28:26.297 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #45200209##
2021-02-12 20:28:26.297 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.52
2021-02-12 20:28:26.298 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.52 has NO DEVICE associated, ignoring it
2021-02-12 20:28:26.816 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #45300210##
2021-02-12 20:28:26.817 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.53
2021-02-12 20:28:26.817 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.53 has NO DEVICE associated, ignoring it
2021-02-12 20:28:27.347 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #45400211##
2021-02-12 20:28:27.348 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.54
2021-02-12 20:28:27.348 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ownId=4.54 has NO DEVICE associated, ignoring it
2021-02-12 20:28:48.946 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< 31*#4##
2021-02-12 20:28:48.946 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## WHO=LOAD_CONTROL IS DEPRECATED and NOT SUPPORTED, frame=31*#4##
2021-02-12 20:28:48.947 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## Exception while processing frame: 31*#4## (RECEIVED FRAME NOT RECOGNIZED: 31*#4##)
2021-02-12 20:28:48.986 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< 31*#4##
2021-02-12 20:28:48.986 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## WHO=LOAD_CONTROL IS DEPRECATED and NOT SUPPORTED, frame=31*#4##
2021-02-12 20:28:48.986 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## Exception while processing frame: 31*#4## (RECEIVED FRAME NOT RECOGNIZED: 31*#4##)
2021-02-12 20:29:14.727 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< 31*#5##
2021-02-12 20:29:14.727 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## WHO=LOAD_CONTROL IS DEPRECATED and NOT SUPPORTED, frame=31*#5##
2021-02-12 20:29:14.757 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## Exception while processing frame: 31*#5## (RECEIVED FRAME NOT RECOGNIZED: 31*#5##)
2021-02-12 20:29:33.611 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## sending MON keepalive ACK
2021-02-12 20:29:33.612 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - MON SENDING ======>>>>>> #1##
2021-02-12 20:29:40.498 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< 31
#6##
2021-02-12 20:29:40.498 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## WHO=LOAD_CONTROL IS DEPRECATED and NOT SUPPORTED, frame=31
#6##
2021-02-12 20:29:40.498 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## Exception while processing frame: 31*#6## (RECEIVED FRAME NOT RECOGNIZED: 31*#6##)
2021-02-12 20:29:40.538 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< 31*#6##
2021-02-12 20:29:40.538 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## WHO=LOAD_CONTROL IS DEPRECATED and NOT SUPPORTED, frame=31*#6##
2021-02-12 20:29:40.538 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## Exception while processing frame: 31*#6## (RECEIVED FRAME NOT RECOGNIZED: 31*#6##)
2021-02-12 20:29:50.993 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #13**1512##
2021-02-12 20:29:50.993 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## server MODEL=Unknown
2021-02-12 20:29:50.994 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== GatewayManagement WHAT = null, ignoring
2021-02-12 20:30:06.269 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< 31*#7##
2021-02-12 20:30:06.270 [DEBUG] [penwebnet.message.OpenMessageFactory] - ##openwebnet## WHO=LOAD_CONTROL IS DEPRECATED and NOT SUPPORTED, frame=31*#7##
2021-02-12 20:30:06.270 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## Exception while processing frame: 31*#7## (RECEIVED FRAME NOT RECOGNIZED: 31*#7##)

@massi have you some idea about what I can do to fix this problem?

new release is not compatible fo openhab 3 ?

ACtually in openhab 3 we dont have who for : Dry contact , thermalregolatoin and other.

IS IT CORRECT ?

there is a “testing”-binding that you have to download and install manually. this works with dry contact and thermo - but this is an old binding and does not work with oh3.

if you install the actual version in oh3 this is in developement and (as you can read in the documentation of the binding) still only lightning and automation is supported.

Thanks for your reply and sorry for the delay…I‘m setting up a new server with Docker/Traefik/OH3/Nextcloud/Pihole etc using trusted TLS certs for every domain (yes I got an A+ :grinning_face_with_smiling_eyes: on security scans) as I‘m a noob this took me several days…

Meanwhile, I had a look at OH3 and found the automatic discovery. It is not very intuitive tbh. I managed to get a light and rollershutter to work and now with my new dockerized server running, I‘ll import all the stuff. There‘s lots of new stuff to discover (labels, localisations…). I never had a sitemap…used OH2 with Alexa only.
I‘ve read that thermo doesn‘t work, in fact, I don‘t need it (yet).
I‘ll keep you updated…

Now, returning to that Git I still have to discover…backups…new stuff to learn…hundreds of tutorials to read…biting nails in frustration…

Hi @gibro69 and welcome to the community.

The last official OH2 version is in fact 2.5.12 so you should install that one.
Regarding the openwebnet binding: as it’s well described above in this thread there are 2 versions for OH2: the TESTING version, which has Thermo but is not supported anymore (old implementation), and the 2.5.12 official version which has Lights and Automation.
You cannot install both at the same time.
It’s not clear to me which one you installed in your setup. The testing one has to be installed manually with the jar and following the instructions linked above.
Things may be not initialized until you associate an Item to them.
The log you copied does not say much and it is also not using “code fences” so it’s very difficult to read.

In any case I would suggest you install and invest time on OH3 instead: the openwebnet binding is already there with Lights and Automation, this is the only supported version and it will be expanded and improved to have other features/WHOs (time permitting).

Hello @massi ,

I didn’t have issues with the binding for a while, until today.
In the meanwhile I updated to OH 3.0.1.
I’m sending you the logs via PM.

Thanks!

i woud like to report an observation i made:

shortly i did a complete new install from scratch of openhabian with oh3 on a rpi4 (4gb). installed the official own-binding and imported bticino things and items as i use textual config.

on first view everything worked fine. but then i realized very often the (already well known) warning

[nwebnet4j.communication.BUSConnector] - ##BUS-conn## trying NEW CMD connection...

the strange thing is that this warning mostly appears when switching several things just direct behind each other (for example a rule switches some lights). also strange that in logfile all (for example) lights are shown as switched, even in sitemap the state is changed. but it did not switch, and vor example on bticino-touchscreen it is correct shown as not switched.

for example i have one rule that switches three lights during a rule at one time. it is always the same light that is missing. if i switch the lights in the rule then the new light at the same position is not switched.

this does happen with lights and also with shutters. in oh3 i observe this problem many times a day.

again i did a install from scratch but now openhabian with oh2.5.12 and also installed the official own-binding.

here it is a little different: it happens very rare, about 1-2 times a week. if it happens i don´t see any warning in the log. but rest is similar: a rule that switches some items just behind each other, all items are shown as switched in log and in sitemap, but in reality one item did not switch.

i actually went back to oh2.5 but i do a new install of oh3 from scratch to check if the behavior is the same and to be able to switch between oh25. and oh3 for testing purposes if wanted.

the “error” message is no error at all, see here ([BTicino/OpenWebNet] New openHAB2 binding ready for testing - #1363 by massi) and here ([BTicino/OpenWebNet] New openHAB2 binding ready for testing - #1431 by massi)
will be fixed in 3.1.0.
not sure if this is somehow connected to your finding about switching items in parallel

thanks for your reply

i know, because of that i wrote “well known” warning. but in the past i think everyone thought it is “only” a warning and does not matter. but now i realized that (at least in oh3) it causes problems as described above.

sorry, just didn’t catch that you are aware of this warning…
about your other finding: I thought about that, and maybe I’ve a similar issue which I had already forgotten. I had a rule to switch of 2 access points at the same time and switch them back on another time. The thing I noticed: Sometimes the second AP didn’t turn on (and maybe sometimes they didn’t turn off either).
I did a workaround, split this rule into 2 and fire them with 5 seconds pause in between. Always works. Maybe this is something similar to your finding.

It looks like a bug.
Difficult to see what could be the problem without:

  1. the rule you use
  2. a log at DEBUG level when this happens
  3. more context info like the WHERE of the light that does not get switched

If you want to provide this info to help identify the problem, use OH 3.0.1.

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.