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

Ouch, this one is nasty and a probable cause:

EDIT: I will prepare a PR shortly.

1 Like

Sorry, missed that, no exception, logs are going like that:

...
==> /var/log/openhab/openhab.log <==
2023-07-29 14:38:58.034 [INFO ] [ernal.transceiver.EnOceanTransceiver] - Transceiver shutdown
2023-07-29 14:38:58.036 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-29 14:38:58.037 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyAMA0
2023-07-29 14:38:58.038 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.

==> /var/log/openhab/events.log <==
2023-07-29 14:39:06.219 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Flur_DG_Sensor_lastupd' changed from 2023-07-29T14:24:03.154710077+0200 to 2023-07-29T14:39:06.213113728+0200
2023-07-29 14:39:06.225 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Flur_DG_Sensor_Humid' changed from 61.568627450980394 to 61.1764705882353
2023-07-29 14:39:32.144 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Flur_OG_Sensor_Temp' changed from 21.915933528836753 °C to 21.837732160312804 °C
2023-07-29 14:39:32.146 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Flur_OG_Sensor_lastupd' changed from 2023-07-29T14:26:10.245697049+0200 to 2023-07-29T14:39:32.138127827+0200
2023-07-29 14:39:32.148 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Flur_OG_Sensor_Humid' changed from 65.09803921568627 to 64.70588235294117
2023-07-29 14:39:42.095 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Heute_BB' changed from 2023-07-29T14:38:42.087+0200 to 2023-07-29T14:39:42.088+0200

==> /var/log/openhab/openhab.log <==
2023-07-29 14:39:58.040 [INFO ] [ernal.transceiver.EnOceanTransceiver] - Transceiver shutdown
2023-07-29 14:39:58.042 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-29 14:39:58.043 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyAMA0
2023-07-29 14:39:58.044 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-29 14:40:00.321 [INFO ] [org.openhab.core.model.script.STR   ] - Zirkulationspumpe Technikraum. Ein
2023-07-29 14:40:00.336 [INFO ] [org.openhab.core.model.script.STR   ] - Zirkulationspumpe Countdown. 5min.

==> /var/log/openhab/events.log <==
2023-07-29 14:40:00.324 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ShellyS_B52AA7_Schalter' received command ON
2023-07-29 14:40:00.326 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'ShellyS_B52AA7_Schalter' predicted to become ON
2023-07-29 14:40:00.330 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_Schalter' changed from OFF to ON
2023-07-29 14:40:03.575 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 0 to 5
2023-07-29 14:40:08.401 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Buero_Aktor_Kanal1_lastupd' changed from 2023-07-29T14:25:05.310343797+0200 to 2023-07-29T14:40:08.395489531+0200
2023-07-29 14:40:09.577 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 5 to 3.73
2023-07-29 14:40:13.816 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Esszimmer_Aktor_lastupd' changed from 2023-07-29T14:35:14.581008406+0200 to 2023-07-29T14:40:13.812373530+0200
2023-07-29 14:40:14.077 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Wohnzimmer_Aktor_lastupd' changed from 2023-07-29T14:35:14.844983259+0200 to 2023-07-29T14:40:14.073248467+0200
2023-07-29 14:40:14.078 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Wohnzimmer_Aktor_qos' changed from 1 to 2
2023-07-29 14:40:14.339 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Wohnzimmer_Aktor_lastupd' changed from 2023-07-29T14:40:14.073248467+0200 to 2023-07-29T14:40:14.334166570+0200
2023-07-29 14:40:14.597 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Esszimmer_Aktor_lastupd' changed from 2023-07-29T14:40:13.812373530+0200 to 2023-07-29T14:40:14.593583534+0200
2023-07-29 14:40:14.861 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Flur_EG_Aktor_lastupd' changed from 2023-07-29T14:30:14.830381359+0200 to 2023-07-29T14:40:14.855850722+0200
2023-07-29 14:40:15.868 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_207A54_WifiSignal' changed from 3 to 2
2023-07-29 14:40:24.582 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.73 to 3.61
2023-07-29 14:40:30.909 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_207A54_WifiSignal' changed from 2 to 3
2023-07-29 14:40:39.581 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.61 to 3.70
2023-07-29 14:40:42.099 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Heute_BB' changed from 2023-07-29T14:39:42.088+0200 to 2023-07-29T14:40:42.090+0200
2023-07-29 14:40:54.584 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.70 to 3.65

==> /var/log/openhab/openhab.log <==
2023-07-29 14:40:58.045 [INFO ] [ernal.transceiver.EnOceanTransceiver] - Transceiver shutdown
2023-07-29 14:40:58.046 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-29 14:40:58.046 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyAMA0
2023-07-29 14:40:58.047 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.

==> /var/log/openhab/events.log <==
2023-07-29 14:41:09.582 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.65 to 3.81
2023-07-29 14:41:10.402 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.81 to 3.72
2023-07-29 14:41:13.786 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_2110E6_WifiSignal' changed from 3 to 2
2023-07-29 14:41:24.582 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.72 to 3.75
2023-07-29 14:41:25.550 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.75 to 3.60
2023-07-29 14:41:39.585 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.60 to 3.80
2023-07-29 14:41:40.619 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.80 to 3.62
2023-07-29 14:41:42.095 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Heute_BB' changed from 2023-07-29T14:40:42.090+0200 to 2023-07-29T14:41:42.091+0200
2023-07-29 14:41:46.402 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_207A54_WifiSignal' changed from 3 to 2
2023-07-29 14:41:54.588 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.62 to 3.69
2023-07-29 14:41:55.758 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.69 to 3.72

==> /var/log/openhab/openhab.log <==
2023-07-29 14:41:58.047 [INFO ] [ernal.transceiver.EnOceanTransceiver] - Transceiver shutdown
2023-07-29 14:41:58.048 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.
2023-07-29 14:41:58.049 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyAMA0
2023-07-29 14:41:58.049 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EnOceanBridgeHandler tried updating the thing status although the handler was already disposed.

==> /var/log/openhab/events.log <==
2023-07-29 14:42:09.588 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.72 to 3.69
2023-07-29 14:42:10.817 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.69 to 3.77
2023-07-29 14:42:24.585 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.77 to 3.63
2023-07-29 14:42:25.868 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.63 to 3.70
2023-07-29 14:42:39.585 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.70 to 3.73
2023-07-29 14:42:40.918 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ShellyS_B52AA7_CurrentW' changed from 3.73 to 3.70
...

Quick find! Pretty sure that is the cause.

1 Like

@fnu - can you test this version? org.openhab.binding.enocean-4.1.0-SNAPSHOT.jar

Issue created:

And pull request:

1 Like

@lsiepel Hope that helps.

Can you also test with this version? org.openhab.binding.enocean-4.1.0-SNAPSHOT.jar

See also openHAB 4 migration FAQ

@laursen
Sure, I started the version 4.1.1-1 before about 15 minutes. The EnOceanUSB300 comes online and it is till now.

Just to be sure, you uninstalled the bundled binding first, and restarted openHAB after that?

Sure. Copying to addons folder, taking “enocean” out of and “serial” into my bindings list at addon.cfg, also initiating clean cache.

openhab> bundle:list -s | grep binding
236 │ Active │  80 │ 4.1.0.202307291301     │ org.openhab.binding.enocean
254 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.astro
255 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.avmfritz
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.serial
261 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.shelly
262 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.vdr
263 │ Active │  80 │ 4.0.1                  │ org.openhab.binding.yamahareceiver

Reading that list, it looks to me like enocean binding out of addons folder is loaded before the list from addons.cfg … therefore I still see that usbserial warning on startup of that external .jar.

Have then try tested several OH4 restarts and also system reboots. In some cases enocean bridge was listed offline, but came up postponed after OH stated “Started HABPanel at /habpanel”, what I always assume as the final startup message for openhab.

In majority of the cases correct start, every bridge and device online after “Started HABPanel at /habpanel”

So, maybe that logic taken out here came in to prevent that ocassional postponed startup behaviour? Just guessing …

That repeated 60sec message rotation from above has been gone with that snapshot :+1:t2:

Could you provide a KAR file, so testers do not struggle with missing serial transport ?

I would advise to install for example the alarmdecoder binding which also uses openhab-transport-serial. I’m not familiar with how to produce a correct KAR file.

That is quite simple to answer:

mvn clean install karaf:kar ….

Better than the need of addin an unused binding :wink:

1 Like

Here we go:
org.openhab.binding.enocean-4.1.0-SNAPSHOT.kar

FYI @fnu and @backflip

1 Like

@laursen
Not exactly, what I did is:

apt remove openhab
apt-get install openhab=4.0.1-1
$OPENHAB_RUNTIME/bin/restore $OPENHAB_BACKUPS/openhab-backup-23_07_29-16_59_22.zip
service openhab start

I don’t know how to handle this .jar files…

Okay, I’m not sure where that would leave you, so just to be clear:

  • Uninstall the binding using Main UI.
  • Copy org.openhab.binding.enocean-4.1.0-SNAPSHOT.kar into your addons directory, for example /usr/share/openhab/addons in openHABian.
  • Restart openHAB (because the binding from the 4.0.1 distribution would already have wild-running jobs which will not be stopped by uninstalling the binding).

Ok, thanks, but I’m little confused here.

First, downloaded filename is “org.openhab.binding.enocean-4.1.0-SNAPSHOT.mid”?

Second, one .kar file just for enocean? How to handle that, same as the .jar file?

Actually I don’t mind to load an unused binding just for testing purpose, there will be a clean way sometime afterwards … :wink:

===

One point bothers me actually more, my clean install from today using openhabian 1.8 image, does show (again) an empty source for openhab repository:

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

openhabian@openhabian:~ $ cat /etc/apt/sources.list.d/openhab.list

Pretty much same like my the one I maintained till that morning, after it got pointed to “openhab 4” branch … the new one never got changed, it started up that way by default … sorry for that offtopic.

Yes, a .kar file is just another package. In this case, it will include all dependenvies (serial transport layer), so you don’t need any unused binding with serial tranport and you will not see any “unresolved rquirements” errors in the log.

I’m sorry, I shared it through Google Drive which seems to think it’s an audio file. I hope you were able to download it anyway.

You can either use the .jar - and install another unused binding to include the dependency, or use console commands to install that dependency. Or you can use the .kar where the dependency should be included. Besides the dependency issue the files are identical, so it’s completely up to you.

In either case I would still be interested in the test result, so please report back if the stability is restored compared to 4.0.0/4.0.1.

@laursen
Now I did it with the .kar file but with OH v4-0-0-1. It was not running anymore. Than I installed the EnOcean binding again with the gui. Now it is running since 20 minutes and looks good at the moment.

I don’t know for how long it ran stable before the fix, so please update when either it fails, or when it has significantly passed the previous amount of stability. :slight_smile:

EDIT: Sorry, I misread. You installed from the UI? Then you would get the official 4.0.1 version of the binding which is known to cause problems. If you then also copied the .kar file into your addons directory, you would be running two instances. I may have misunderstod…