EnOcean USB300 initialization fails with OH 4.0.0.M3 and OH 4.0.0.#3512

[fnu (Frank)]

@hmerk

Having the binding added to addons.cfg and placed in the addons folder might lead to having two versions loaded and therefore causing trouble.

You’re right, but in my case it was the solution … basically starting with false acting & false conclusion, my bad.

Before testing that first .jar from here:

EnOcean USB300 initialization fails with OH 4.0.0.M3 and OH 4.0.0.#3512

OK, it’s definitely the commit with the null annotation refactoring. Before trying to find the issue, I have reverted it on a branch made from the 4.0.0 tag, and made a JAR release. Testers other than me, you are welcome to confirm if it works for you (do not forget to uninstall the binding from you runtime environment before installing the JAR in you addons folder). EDIT : testers, see below for another jar to test Now, as you said, it is not an easy task . I will try to pinp…

I have taken “enocean” out of my list in addon.cfg. After clean cache and restart of OH4, I haven’t seen any EnOcean devices in my setup anymore, so conclusion enocean binding has not been loaded and added it again to my addons.cfg. That made it work somehow, as you say most probably with parallel loaded enocean bindings … internal & external …

Today I started over clean, no enocean in addon.cfg, just .jar in addons folder, no enocean bridge and no devices after OH4 start. Checking karaf console for active bindings, enocean is missing:

openhab> bundle:list -s | grep binding
253 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.astro
254 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.avmfritz
255 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.hpprinter
256 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.network
257 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.ntp
258 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.openweathermap
259 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.shelly
260 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.vdr
261 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.yamahareceiver
270 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.serial

Same using that 4.1.0-SNAPSHOT from here:

EnOcean USB300 initialization fails with OH 4.0.0.M3 and OH 4.0.0.#3512

Hello all. You can find the relative test release here. It fixes the issues introduces in OH 4.0.0 (at least, the easy to spot ones) This is a test release. It could have other bugs and it is less stable than the previous (revert) release you could find here. But if you manage to take some time and test it, making a fix for everyone else in the next release will be faster. Disclaimer : I’m not a maintainer or regular contributor of this binding and just happen to fix this because I encounter…

But I also figured out “transport-serial” not being installed with both externally loaded bindings, but that is a prerequisite to communicate with the enocean bridge:

openhab> feature:list -s | grep serial
openhab-core-io-transport-serial-javacomm         │ 4.0.0            │          │ Uninstalled │ distro-4.0.0             │
openhab-transport-serial                          │ 4.0.0            │          │ Uninstalled │ distro-4.0.0             │ Serial Transport
openhab.tp-serial-javacomm                        │ 4.0.0            │          │ Uninstalled │ distro-4.0.0             │
openhab.tp-serial-rxtx                            │ 4.0.0            │          │ Uninstalled │ distro-4.0.0             │

To get those feature(s) I try tested to load serial binding as workaround in my binding list at addon.cfg:

binding = astro,avmfritz,hpprinter,network,ntp,openweathermap,shelly,serial,vdr,yamahareceiver

After that both external enocean bindings are loading, also feature “transport-serial” with that “serial binding” workaround:

openhab> feature:list -s | grep serial
openhab-core-io-transport-serial-javacomm         │ 4.0.0            │          │ Uninstalled │ distro-4.0.0             │
openhab-transport-serial                          │ 4.0.0            │          │ Started     │ distro-4.0.0             │ Serial Transport
openhab.tp-serial-javacomm                        │ 4.0.0            │          │ Uninstalled │ distro-4.0.0             │
openhab.tp-serial-rxtx                            │ 4.0.0            │          │ Started     │ distro-4.0.0             │

openhab> bundle:list -s | grep binding
236 │ Active │  80 │ 4.1.0.202307252320     │ org.openhab.binding.enocean
254 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.astro
255 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.avmfritz
256 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.hpprinter
257 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.network
258 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.ntp
259 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.openweathermap
260 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.serial
261 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.shelly
262 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.vdr
263 │ Active │  80 │ 4.0.0                  │ org.openhab.binding.yamahareceiver

That 4.1.0-SNAPSHOT throws a lot messages like that:

2023-07-28 22:25:22.380 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-28 22:25:22.381 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyAMA0
2023-07-28 22:25:22.381 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-28 22:26:22.382 [INFO ] [ernal.transceiver.EnOceanTransceiver] - Transceiver shutdown
2023-07-28 22:26:22.384 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-28 22:26:22.386 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyAMA0
2023-07-28 22:26:22.387 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.

With the other one logs are more clean, albeit not perfect.

And I still get that unresolved requirement “usbserial” on startup with both external bindings.

[hmerk (Hans-Jörg Merk)]

I would completely upgrade to the new openHAB 4.0.1 Patch Release which provides a fixed version of the binding.

[fnu (Frank)]

Sure, will do, when available in openhabian repository.

[laursen (Jacob Laursen)]

It is already.

[backflip (Stefan Keller)]

I suffered with the same issue after upgrade from 3.4.2 to 4.0.0. After installing 4.0.1 my EnOcean USB300 is working proper again.

[fnu (Frank)]

Hmm, ok, then something got screwed in openhabian, apt doesn’t offer the update:

openhabian@openhabian:~ $ sudo apt policy openhab
openhab:
  Installiert:           4.0.0-1
  Installationskandidat: 4.0.0-1
  Versionstabelle:
 *** 4.0.0-1 100
        100 /var/lib/dpkg/status

Not even the source repository is shown, making in look like it got installed manually.

Installation is defined on:

What repository do I need at “/etc/apt/…”?

[fnu (Frank)]

Ok, spend some more time to clean install from scratch using openHABian image 1.8, restoring my file based setup. Setup comes now up with openhab 4.0.1.

All my devices are listed, seeming to work, but logs show constantly every 60sec:

2023-07-29 12:39:13.511 [INFO ] [ernal.transceiver.EnOceanTransceiver] - Transceiver shutdown
2023-07-29 12:39:13.513 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-29 12:39:13.513 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyAMA0
2023-07-29 12:39:13.514 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.

EnOcean devices can be switched resp. are delivering telemetric data and my EnOcean TF sensors are delivering humidity & temperatur. But unsure if enocean bridge is going down and up every 60sec …

[laursen (Jacob Laursen)]

I went back in the thread and it seems you didn’t have this issue with the fully reverted version that @dalgwen provided as a JAR? That would mean there are more issues with the refactoring. I don’t know if @lsiepel would be able to help analysing this?

[fnu (Frank)]

@laursen

I went back in the thread and it seems you didn’t have this issue with the fully reverted version that @dalgwen provided as a JAR?

Yes, that’s correct.

But, I have seen same repeating log messages with 4.1.0-SNAPSHOT by @dalgwen from above.

[Edit]
Needed serial features are in place:

openhab> feature:list -s| grep serial
openhab-core-io-transport-serial-javacomm         │ 4.0.1            │          │ Uninstalled │ distro-4.0.1             │
openhab-transport-serial                          │ 4.0.1            │          │ Started     │ distro-4.0.1             │ Serial Transport
openhab.tp-serial-javacomm                        │ 4.0.1            │          │ Uninstalled │ distro-4.0.1             │
openhab.tp-serial-rxtx                            │ 4.0.1            │          │ Started     │ distro-4.0.1             │

And I added again that to /etc/default/openhab, memory settings were given by installation …

EXTRA_JAVA_OPTS="-Xms192m -Xmx768m -Dgnu.io.rxtx.SerialPorts=/dev/ttyAMA0"

[backflip (Stefan Keller)]

I’m sorry to confusing you all. I did some trying with my EnOcean USB300 issue.
Environment:
Nuc i5 with Ubuntu 22.04.2 LTS
OH 4.0.1

After a few hours where I was happy beacuse my gui said everything looks god, suddenly I got some log entries:

 tail -f /var/log/openhab/*.log | grep -e ERROR -e WARN
2023-07-29 12:55:05.365 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'enocean:bridge:f424041d7c' changed from OFFLINE (CONFIGURATION_ERROR): Port could not be found to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2023-07-29 12:55:05.375 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'enocean:bridge:f424041d7c' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_ERROR): Port could not be found
2023-07-29 12:56:05.380 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'enocean:bridge:f424041d7c' changed from OFFLINE (CONFIGURATION_ERROR): Port could not be found to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2023-07-29 12:56:05.388 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'enocean:bridge:f424041d7c' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_ERROR): Port could not be found
2023-07-29 12:57:05.392 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'enocean:bridge:f424041d7c' changed from OFFLINE (CONFIGURATION_ERROR): Port could not be found to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2023-07-29 12:57:05.402 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'enocean:bridge:f424041d7c' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_ERROR): Port could not be found

The strange thing is, that even there is a config error and the thing (EnOcean Bridge) is not running, because the port was not found, the EnOcean rollershutter is working (at least at the last hour, and it is still working). I’m using EnOcean for the blind buttons (and other stuff) and control the homematic rollershutter.

[lsiepel (Leo)]

I’ll look into this this weekend, probably this evening.

[Lolodomo]

When you have such log “Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.”, that often means you have two versions of the binding running.
Check that you have not one remaining jar file for the binding in addons folder. If not, just restarting OH should avoid this warning. If not, the binding is probably badly implemented.

[laursen (Jacob Laursen)]

Good point. @fnu - please verify this before @lsiepel jumps in.

[lsiepel (Leo)]

@backflip Could you raise an issue on Github?

Just had a quick look. And the ‘Port could not be found’ is only set when initiliazing, and that is only called after 1. binding start or 2. when the thing went offline and it is trying to get back online.
As the binding was working well for some time, it must be 2.

Now the question is why did it go offline. Probably because some message send/received went wrong. To pinpoint that, i like to get some more detailed logs. Could you supply the Github issue with some debug logs? And/or some steps that you take to replicate the issue? events occuring, or devices you use in your network.

The more relevant details you provide, the sooner i can come up with a fix.

[fnu (Frank)]

@Lolodomo

Check that you have not one remaining jar file for the binding in addons folder.

Let me quote myself:

@fnu

Ok, spend some more time to clean install from scratch using openHABian image 1.8, restoring my file based setup. Setup comes now up with openhab 4.0.1.

New image, new SD card. Some more information:

openhab> bundle:list -s | grep binding
253 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.astro
254 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.avmfritz
255 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.enocean
256 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.hpprinter
257 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.network
258 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.ntp
259 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.openweathermap
260 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.shelly
261 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.vdr
262 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.yamahareceiver

openhabian@openhabian:~ $ ll /usr/share/openhab/addons/
insgesamt 376M
drwxrwxr-x 2 openhab openhab 4,0K 29. Jul 11:55 ./
drwxrwxr-x 4 openhab openhab 4,0K 29. Jul 11:55 ../
-rw-rw-r-- 1 openhab openhab 376M 28. Jul 17:41 openhab-addons-4.0.1.kar
-rw-rw-r-- 1 openhab openhab   70 28. Jul 17:41 README

[laursen (Jacob Laursen)]

Can you remove the .kar file and/or check if the binding is also installed from Main UI? I assume you are on 4.0.1 now. If you had two bindings running simultaneously you might have to restart openHAB after removing one of them.

[fnu (Frank)]

@laursen

Can you remove the .kar file

Sure can do, but that’s given by the image I flashed newly to a new SD card, 2 or 3h ago …

@laursen

check if the binding is also installed from Main UI

I never install bindings from MainUI or karaf console, I just maintain my bindings list in addon.cfg:

# A comma-separated list of bindings to install (e.g. "binding = knx,sonos,zwave")
#binding =
binding = astro,avmfritz,enocean,hpprinter,network,ntp,openweathermap,shelly,vdr,yamahareceiver

That way they are also shown as installed in MainUI:

[laursen (Jacob Laursen)]

I’m not that much into the details that I can assess from that if you are running two bindings, but I suspect you might. Since the .kar file is in the addons folder, what happens if you remove enocean from the list in addon.cfg?

EDIT: Sorry, I misread. I thought I saw the binding, but actually openhab-addons-4.0.1.kar - you definitely shouldn’t remove that.

[fnu (Frank)]

That’s I wanted to ask already … its a fresh clean install, I just restored my custom files into /etc/openhab and also homekit.json.

[laursen (Jacob Laursen)]

@lsiepel

The more relevant details you provide, the sooner i can come up with a fix.

Is there an error or warning logged (even by the framework) before the repeating ones (60 s) starts being logged? I’m wondering if there could be an unhandled exception thrown before that.

Another clue could be a wild-running job, for example null annotation refactoring could be introducing local variables for jobs. A common bug would be assigning a newly started job to a local variable rather than an instance variable, and thus it would become wild-running. And would also keep a serial port allocation.