[Velbus] Unloading the bridge fails predictably

[nagisa]

NB: this is not a request for somebody to fix the issue, I anticipate getting around to looking at it myself in near future.

To reproduce this issue, I have a things file that contains a single velbus bridge with a single device in it:

Bridge velbus:bridge:1 "Velbus" [ port="/dev/ttyACM0", timeUpdateInterval="1500" ] {
    vmbpirm   01 [ address = "01" ]
}

Every time this file is modified and saved, openhab will attempt to unload and reload the thing.

Expected Behavior

The thing is successfully reloaded, and the system works without significant interruptions.

Current Behavior

karaf[2811996]: [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'velbus:bridge:1' takes more than 5000ms.
karaf[2811996]: [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'velbus.things'
karaf[2810306]: [WARN ] [.core.thing.binding.BaseThingHandler] - Handler VelbusSerialBridgeHandler tried updating the thing status although the handler was already disposed.
{last message repeated a fair number of times}

Possible Solution

Need to investigate why disposing of the velbus thing does not work correctly.

Steps to Reproduce (for Bugs)

1. Set up openhab with a velbus thing via a configuration file as specified above;
2. Modify the configuration file and save it.

Context

Restarting every time I modify the configuration file is a major pain :)

Your Environment

• Version used: openHAB 3.4.2; Velbus binding 3.4.2
• Environment name and version: N/A
• Operating System and version: NixOS running on nVidia Jetson AGX, linux kernel 5.10, aarch64

[nagisa]

This is no longer a problem in OpenHAB 4.

[nagisa]

I’m actually still seeing this issue, and another related symptom I think is this binding making multiple connections to my TCP bridge, and producing trigger events multiple times (where the number of times is equivalent to the number of connections that are maintained with the velbustcp bridge):

12:37:36.842 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - velbus:vmbpirc:1:0C:input#CH7 triggered PRESSED
12:37:36.843 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - velbus:vmbpirc:1:0C:input#CH7 triggered PRESSED
12:37:36.843 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - velbus:vmbpirc:1:0C:input#CH7 triggered PRESSED
12:37:36.844 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - velbus:vmbpirc:1:0C:input#CH7 triggered PRESSED
12:37:36.844 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - velbus:vmbpirc:1:0C:input#CH7 triggered PRESSED
12:37:36.844 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - velbus:vmbpirc:1:0C:input#CH7 triggered PRESSED
12:37:36.845 [INFO ] [openhab.event.ChannelTriggeredEvent  ] - velbus:vmbpirc:1:0C:input#CH7 triggered PRESSED

Reproducible on 4.0.3.

[MDAR]

I've never tried adding any Thing other than the Velbus Bridge via a Text file.

Have you tried isolating the Module Things from the Bridge thing?

My use case is always

Text file for Bridge

Add Module Things via the UI

Add Bulk Items via Text files or one off Items via the UI

That said I have noticed that I sometimes get multiple notifications about a door bell press (Connected to a VMB7IN), which could well be a symptom of what you are describing

[nagisa]

I have noticed that I sometimes get multiple notifications about a door bell press (Connected to a VMB7IN), which could well be a symptom of what you are describing

A smoking gun would be seeing multiple of the same event in your OH logs. But it does sound similar indeed.

Have you tried isolating the Module Things from the Bridge thing?

I haven't done very much to debug this. I had a hard time contributing to OH effectively, so I've been slowly but surely migrating away from OH for my home automation needs. Velbus is the last remaining bastion, but I've been very slowly hacking away at improving the node-red velbus integration to fit my needs, so I don't anticipate spending time on reproducing or fixing this myself.