[shelly] Log "spam" after upgrade to openHAB 3.4 from 3.3

[unf]

Expected Behavior

No warning messages.

Current Behavior

After upgrading openHAB & addon packages from version 3.3 onto 3.4 my log files are "spamed" with thoses messages:

...
2022-12-21 19:51:50.188 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ShellyRelayHandler tried updating the thing status although the handler was already disposed.

2022-12-21 19:51:50.191 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ShellyRelayHandler tried updating the thing status although the handler was already disposed.
...

No comparable messages in previous version 3.3, not even before of that in 3.2.

Steps to Reproduce (for Bugs)

1. Stop openhab instance and restart it without Shelly binding, none of those warning in log.
2. Stop openhab instance again, restart with Shelly binding, the messages are again flooding log files.

Context

It is impossible to live read log files, on CLI or on WebIF PaperUI due to message flooding and depended things, more IO to SD-Card, size of log files, more log file switches, outrunning history etc.

Your Environment

openHABian (64-bit) 1.7.x, Raspberry Pi 4 with EnOcean Pi.

binding = astro,avmfritz,enocean,hpprinter,network,ntp,openweathermap,shelly,vdr,yamahareceiver
misc = homekit
persistence = mapdb
transformation = scale
ui = basic,habpanel

[jlaur]

@markus7017 - would you be able to have a look at this?

[Sirmike2]

Hi,
I have the same problem.

Version:
openHAB 4.0.0
Build 3254

[Miker-SX]

Hi,
i have also the same poblem.
The problem exist since i made the upgrade from Version 3.3.0 to 3.4.0
Cleaning up the cache did not bring success.

[aromedia1]

Hi,
the same problem after upgrade to 3.4.0
Before everything works fine with Shelly EM3 and Shelly Switch 2.5
Even after deinstalling all Shelly Items and the Shelly Binding, clean-cache doesn't stop the spaming log entries
Only after reboot no more entries appear.

I've gave it a second chance and install the Shelly Binding again. But only by installing the binding the log entries start again.

[unf]

That annoying issue is still there and to clarify that, the only change was updating from openHAB 3.3 to 3.4 packages, offered and forced by openHABian ...

So, should we consider to forcibly going back to openHAB 3.3 packages and tie setup to that older version?

[unf]

Hmm, interesting, got an eMail about another message here, confirming same issue ... but can't see it here.

Nevertheless, openhabian offered updated packages openHAB 3.4.1, gave them a chance, but that mentioned continous message spam is still there.

On top I have seen similar message in log for openweathermap binding at the time of restart after upgrading openHAB packages to 3.4.1, but those disappeared directly while/after loading related openweather things & items.

2023-01-10 13:24:14.710 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OpenWeatherMapAPIHandler tried updating the thing status although the handler was already disposed.
2023-01-10 13:24:14.711 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OpenWeatherMapAPIHandler tried updating the thing status although the handler was already disposed.
2023-01-10 13:24:14.713 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OpenWeatherMapAPIHandler tried updating the thing status although the handler was already disposed.
2023-01-10 13:24:14.714 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OpenWeatherMapAPIHandler tried updating the thing status although the handler was already disposed.
2023-01-10 13:24:14.715 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OpenWeatherMapAPIHandler tried updating the thing status although the handler was already disposed.
2023-01-10 13:24:14.830 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler OpenWeatherMapAPIHandler tried updating the thing status although the handler was already disposed.

[SebastianCornea]

I had the same issue, but upgrade to 3.4.1 and a reboot fixed it.

[unf]

Not here, upgrade procedure is always, "systemctl stop openhab.service", "systemctl daemon-reload", "openhab-cli clean-cache" ... update packages per openhabian-config "Upgrade System" ... reboot.

[blizzard4591]

I have the same issue, with version 3.4.1 - cache was cleaned, no change. Any ideas?

[unf]

My openHABian system still faces the issue, and might even cause further issues. I need to reboot my system on weekly base, as its eating much more memory over the time than before ... I hope its just that log spam and not a general issue with 3.4.x.

I still consider to step back to 3.3.0 packages and lock them for updates.

[lsiepel]

Seen some similar issues here and on the community forums as the OP has with astro + shelly combination.
Also seen it with astro + elerotransmitter
I wonder if all of you have the astro binding installed, maybe it is not related at all, just something i noticed.

[unf]

@Isiepel Yes, you're right I have astro binding running. How did you solve that on your's?

Without the astro binding, a bigger portion of my automation would not work anymore ... so disabling it, is not an option.

openHABian with package version 3.3.0 was very, very reliable, whereas 3.4.x version causes too much interaction for my taste meanwhile ...

[stefan-hoehn]

@lsiepel I am hardly using my installed astro binding and I have a dev system running on 4.0 where it wouldn't hurt at all to try out thing. Is there any particular test case you can tell me step by step, I should try reproduce?

[lsiepel]

on of automation would not work anymore ... so disabling it, is not an option.

openHABian with package version 3.3.0 was very, very reli

I don't experience any problems, as i use astro without elerotransmitter / shelly / openweathermap. I made changes to the Astro binding, adding more null annotations and fix some events being scheduled while a date is missing. It might be related, might be not. Source here: https://github.com/lsiepel/openhab-addons/tree/astr-sat
If you are able to test, i can build a 3.4.x jar.

[stefan-hoehn]

I'd rather try it out on 4.0 as this is my dev system and it is also happening there. Did you add the annotations to astro 4.0 as well (I may have overlooked them in the git history)? If yes, I am happy to install that version or even build something for 4.0. Just give me the test steps, so I reproduce them, ie.

1. Configure the following on astro: tellme what to configure...
2. run OH and check if none if the mentioned logs come up.
3. upgrade to the latest version (it will restart OH automatically) and see if the logs come up on Shelly and or Astro
4. don't restart OH but reboot the server (in my case RP4) and see if the logs still come up.

^would these steps make sense?

[lsiepel]

4.0.0 jar: https://1drv.ms/u/s!AnMcxmvEeupwjplSpgTYXFV3-YBWHg?e=gRpZgX
Source here: https://github.com/lsiepel/openhab-addons/tree/astr-sat

Steps seem right, i would suggest to link several (maybe all) moon and sun channels, so that the jobs are scheduled.

Maybe step 5 would be a recurring step: initialize a shelly thing. As that also seem to 'hit' something.

[unf]

To add that information from my side, I stepped down again to openHAB version 3.3.0 packages, log is "clean" again, means zero "Handler" messages. And system is noticeable more responsive again, the lags I realized here and there over the the last weeks are also gone again.

So, none of the other packages part in the base OS updated also over the last weeks caused any of the issues. Means it does come in somehow with openHAB 3.4.x packages ...

Which bindings got changed from 3.3.0 to 3.4.x? Just astro?

[unf]

Tried with another attempt, reimage sd-card with very latest openHABian image, with restoring my ASCII configuration files at "/etc/openhab" afterwards. After restart, past restoring my configuration files, no "Handler" messages flooding logs.

But for homekit I could configuration files restore just in a second attempt, what needed again a restart/reboot. After having homekit.json restored and system restart, "Handler" messages are again flooding logs.

Downgrade again to openhab 3.3.0, keeping configuration files & homekit.json, kept logs again clean.

PS.: My old installation based on openhabian image 1.7.4, the new one is 1.7.5. I used a different sd-card, the old system is still available.
PPS.: I keep that status quo for now, I need a running system, don't have a comparable dev system and foremost, my job is eating my time actually ...

[lolodomo]

Which bindings got changed from 3.3.0 to 3.4.x? Just astro?

You can get this liste from the OH 3.4 release notes.

Note that there was a major change in the Shelly binding to support more "devices".

[lolodomo]

I take a quick look to the code and I can see that initialize in class ShellyBaseHandler is scheduling a thread 2 seconds later but this thread is not cancelled later, in particular in case dispose is called for any reason by the thing manager. In that case, the thread will run while the thing handler was already disposed !
I think the reason of this issue is there and it was easy to find.

I also noticed that initialize is not setting any thing status before returning, while it should. Edit: it is set at the very beginning of the init job, so it should be not so bad.

I will try to propose a fix.

[unf]

@lolodomo Wow, super, thanks for looking into that. Might have been an easy task for a/the coder ... but maybe not for just users ...

So, if that commit has been passed proofing & verification and got finally merged, how to get that into stable openhab 3.4.x world?

[lolodomo]

So, if that commit has been passed proofing & verification and got finally merged, how to get that into stable openhab 3.4.x world?

OH maintainers will have to decide if the fix has to be put also in 3.4.x branch, certainly considering how critical is the issue.

[unf]

certainly considering how critical is the issue.

Ok, looking to my setup it looked critical, as memory got eaten up, forcing the little RPi to swap out till that virtual memory also has been eaten up. The result, out-of-memory locks ...

[lolodomo]

What I fixed should happen only when the thing manager disposes a handler and initializes a new one. Normally, it should not happen in normal circumstances. If it happens often, there is probably another issue.

[lsiepel]

If a 3.4.x build of the pr is shared, it could be tested and check to see what is left to fix.

[aromedia1]

After complete Update, cleaned-cache and reinstalling the shelly add-on, same "spam" messages occur in the logs every 15 seconds
[WARN ] [.core.thing.binding.BaseThingHandler] - Handler ShellyRelayHandler tried updating the thing status although the handler was already disposed.

[lsiepel]

After complete Update, cleaned-cache and reinstalling the shelly add-on, same "spam" messages occur in the logs every 15 seconds
[WARN ] [.core.thing.binding.BaseThingHandler] - Handler ShellyRelayHandler tried updating the thing status although the handler was already disposed.

Can you create an issue with log files and details?

[BasvanH]

This issue still persists. Im on 3.4.3. It happens when you restart openhab without rebooting the OS.

@lsiepel, I can provide you with logs. What do yo need?

[unf]

@BasvanH This thread got closed, later another one opened, same topic.

But in the other thread we got the hint to change CoLoT from "mcast" to peer mode, pls. read from here:

#14401 (comment)

You can do that for the bunch using openHAB shelly binding's "Shelly Manager" ...

[BasvanH]

Thanks @unf for pointing me to that issue. Changing to peer mode has silenced the warnings.

[openhab-bot]

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/new-netatmo-binding-starting-oh-3-3-m5/135777/262