Thing File based configuration not loaded correctly after changing

Question

Thing File based configuration not loaded correctly after changing

Closed this issue 2 months ago · 33 comments

Hello,

I changed the thing file

from

Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_links" @ "Bedroom" [deviceIp="ip", password="password"]
Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechts" @ "Bedroom" [deviceIp="ip", password="password"]

to

Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_linksd" @ "Bedroom" [deviceIp="ip", password="password"]
Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechtsd" @ "Bedroom" [deviceIp="ip", password="password"]

this is the log

2024-04-10 13:53:54.527 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'shelly.things'
2024-04-10 13:53:54.549 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Unerwarteter Fehler - WebSocket connection closed abnormal
2024-04-10 13:53:54.556 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Unerwarteter Fehler - WebSocket connection closed abnormal
2024-04-10 13:53:56.549 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from ONLINE to UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus.
2024-04-10 13:53:56.556 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from ONLINE to UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus.
2024-04-10 13:53:56.772 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. to ONLINE
2024-04-10 13:53:56.882 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. to ONLINE

than change it back to

Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_links" @ "Bedroom" [deviceIp="ip", password="password"]
Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechts" @ "Bedroom" [deviceIp="ip", password="password"]

seeing this in the log

2024-04-10 13:54:47.340 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'shelly.things'

but this in the ui

No update was loaded

Answer 1 · 2024-04-29T10:49:40.000Z

As I understand, you only change the thing label.
Can you please tell us if this is something that does not work only for Shelly things or for any thing ?

And what is your running OH version ?

Answer 2 · 2024-04-29T16:11:31.000Z

@lolodomo yes, for any binding/thing you do ..it doesn't matter if you only change the label or the settings of the thing....so just a change...also item files I see this behavior....

I recognized this behavior in OH4.2M2

OH4.2M2 on latest openhabian release

Answer 3 · 2024-05-01T15:34:51.000Z

I am able to reproduce. We can change several times the thing label and it is properly updated. The problem is only when you try to restore the initial value. This change is apparently ignored even if the logs show that the file is reloaded.

Answer 4 · 2024-05-01T15:41:49.000Z

@jimtng ! do you think your PR #4076 could also fix this issue ? If not, with your knowledge of how the loading of things is working, do you understand the current issue ?

Answer 5 · 2024-05-01T20:02:48.000Z

I haven't tested this scenario specifically. Without tracing it at runtime, I "suspect" this is what's happening:

Version 1 was loaded
.things file changed, Version 2 loaded, but due to the leak, Version 1 is still retained in memory, and Version 2 added to the thingsMap. This issue/leak is fixed in #4076.
.things changed back to Version 1, but because it wasn't cleared off thingsMap in the previous change, a match is found, and therefore the file isn't reloaded.

#4076 should fix this issue

Answer 6 · 2024-05-01T20:08:10.000Z

Ok, I will test again once #4076 is merged.

Answer 7 · 2024-05-02T20:12:35.000Z

#4076 is merged

Answer 8 · 2024-05-02T20:48:06.000Z

Yes it's merged, but it hasn't yet made it into the latest snapshot. Hopefully within the next 12 hours!

Answer 9 · 2024-05-03T07:06:13.000Z

Tested with snapshot 4064 including #4076. The problem is now different, it is now possible to restore the initial value. But now the very first change after startup is "ignored". The next ones are OK.
@jimtng : any idea ?

Answer 10 · 2024-05-03T07:18:04.000Z

Is it possible to update the issue title to precise that it concerns Thing files ?

Answer 11 · 2024-05-04T02:31:23.000Z

@lolodomo better title now?

Answer 12 · 2024-05-04T03:36:20.000Z

Tested with snapshot 4064 including #4076. The problem is now different, it is now possible to restore the initial value. But now the very first change after startup is "ignored". The next ones are OK.

I can't seem to reproduce this issue. Can you tell me the steps to reproduce it?

Here's what I did:

Create a test.things file:

Thing astro:sun:home "test1" [ geolocation="52.5200066,13.4049540,100", interval=60 ]
Thing astro:moon:home "test1" [ geolocation="52.5200066,13.4049540", interval=60 ]

Stop openhab
Start openhab
Run a script to show the label of the astro:sun:home - it logged it as "test1"
Modified the test.things file and changed the label to "test2"
Rerun the script to show the label, it now logged as "test2" so it appears that it did get updated.

Answer 13 · 2024-05-04T09:26:16.000Z

My scenario was:

Having a file astro.things file in conf/things containing

Thing astro:sun:local "Astro" @ "Extérieur" [ geolocation="xxxx" ]

Start OH
Edit the file by changing the thing label and save & quit the file => I see the log about file loading but when I refresh the page in Main UI showing the list of things, the label is unchanged. Confirmed by running the console command "things list | grep astro".
Edit the file by changing the thing label and save & quit the file => I see the log about file loading and now when I refresh the page in Main UI showing the list of things, the label is correct. Confirmed by running the console command "things list | grep astro".

Tested on RPI. The file is on the SD card (so not a network share) and edited using vi.

Answer 14 · 2024-05-04T12:29:52.000Z

My scenario was:

Having a file astro.things file in conf/things containing
Thing astro:sun:local "Astro" @ "Extérieur" [ geolocation="xxxx" ]
Start OH

Edit the file by changing the thing label and save & quit the file => I see the log about file loading but when I refresh the page in Main UI showing the list of things, the label is unchanged. Confirmed by running the console command "things list | grep astro".

Edit the file by changing the thing label and save & quit the file => I see the log about file loading and now when I refresh the page in Main UI showing the list of things, the label is correct. Confirmed by running the console command "things list | grep astro".

I'm still not able to reproduce the problem.

I tried your things file verbatim (including geolocation="xxxx"). As a result I got

Astro parameters geolocation could not be split into latitude and longitude, disabling thing 'astro:sun:local'

But upon changing the label, it did get updated on the Main UI (I had to refresh the browser).

I then tried entering an actual coordinate in the .things file:

Thing astro:sun:local "Astro" @ "Extérieur" [ geolocation="52.5200066,13.4049540,100" ]

Stopped openhab
Started it, confirming the label in Main UI
Then this time using vim to edit the file locally (not over samba), then saved the changes with :wq
the new label showed up on main ui.

Answer 15 · 2024-05-04T12:41:52.000Z

Of course, I do not use "xxxx" as geolocation, it was just to not provide a real position.

If you are sure it works, I will try again.

Answer 16 · 2024-05-05T07:45:50.000Z

My server was restarted yesterday. This morning, I tried again and I reproduced the problem. The first change of thing label is not applied even if the change of file is detected. Next changes are fine, even returning to the original thing label.

@miloit : can you confirm my experience with #4076 merged ?

Answer 17 · 2024-05-05T09:07:40.000Z

@lolodomo can confirm same behaviour as before

I am on openHAB 4.2.0 (Build #4065)

I changed the file shelly.things from
Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_links" @ "Bedroom" [deviceIp="ip", password="password"] Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechts" @ "Bedroom" [deviceIp="ip", password="password"]

to

Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_linkse" @ "Bedroom" [deviceIp="ip", password="password"] Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechtse" @ "Bedroom" [deviceIp="ip", password="password"]

in the log I see
2024-05-05 10:57:28.575 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'shelly.things'

But still the old description in the UI

I stopped openhab started new now it was changed....tried it 2 times the same scenario....means only new loaded with a restart

Answer 18 · 2024-05-05T09:41:35.000Z

Is it only at the first change or at any next change ?
For me, it works well except the first change.

Please note that the list of things in Main UI is not automatically updated, you have to refresh it.

Answer 19 · 2024-05-05T09:48:48.000Z

Only first change

Answer 20 · 2024-05-05T10:49:32.000Z

Only first change

Well, we have the same result.

@jimtng : that is strange that you can't reproduce it.

Answer 21 · 2024-05-05T13:40:40.000Z

Can I log it somehow more?

Answer 22 · 2024-05-05T13:45:34.000Z

I was testing it on snapshot build 4064 and couldn't replicate the problem.
I then tried installing build 4065 but encountered a problem when installing the astro binding, maybe because the addon build wasn't done yet (I don't quite understand how the packaging system works). So I tried build 4064 again and still cannot reproduce the problem.

I stopped openhab
Then started it again
Loaded the Main UI page to see the thing label as set in the file
Then edited the .things file to change the label (add / remove a letter or so)
Then refreshed the Main UI page, the change of label I made is reflected on the Things page

Answer 23 · 2024-05-05T15:10:17.000Z

I think there's still a bug. I'm now able to reproduce this under a different set of conditions. Looking into it more!

Answer 24 · 2024-05-05T15:54:04.000Z

The Bug I found was this:

When you have a .things file that contain Things from multiple bindings (e.g. Astro and Shelly), it won't work properly. This is a regression that was introduced in #4076

However, I still haven't been able to reproduce the problem when the .things file only contain things from the same binding.

In any case, could you please test this jar file? You will need to clear openhab cache and tmp dirs. Note I had to add a fake .zip extension. This is not a zip file. Just rename and remove the .zip extension and do not unzip it.

org.openhab.core.model.thing-4.2.0-SNAPSHOT.jar.zip

This file needs to be placed inside ./runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing/4.2.0-SNAPSHOT/ - please back up your original org.openhab.core.model.thing-4.2.0-SNAPSHOT.jar file first!

Answer 25 · 2024-05-05T19:20:58.000Z

@jimtng Which one do I need to replace?

1)./srv/openhab-sys/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing.runtime

2)./srv/openhab-sys/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing.runtime/4.2.0-SNAPSHOT/org.openhab.core.model.thing.runtime-4.2.0-SNAPSHOT.jar

3)./srv/openhab-sys/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing.ide

4)./srv/openhab-sys/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing.ide/4.2.0-SNAPSHOT/org.openhab.core.model.thing.ide-4.2.0-SNAPSHOT.jar

5)./srv/openhab-sys/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing

6)./srv/openhab-sys/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing/4.2.0-SNAPSHOT/org.openhab.core.model.thing-4.2.0-SNAPSHOT.jar

7)./usr/share/openhab/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing.runtime

8)./usr/share/openhab/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing.runtime/4.2.0-SNAPSHOT/org.openhab.core.model.thing.runtime-4.2.0-SNAPSHOT.jar

9)./usr/share/openhab/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing.ide

10)./usr/share/openhab/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing.ide/4.2.0-SNAPSHOT/org.openhab.core.model.thing.ide-4.2.0-SNAPSHOT.jar

11)./usr/share/openhab/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing

12)./usr/share/openhab/runtime/system/org/openhab/core/bundles/org.openhab.core.model.thing/4.2.0-SNAPSHOT/org.openhab.core.model.thing-4.2.0-SNAPSHOT.jar

Answer 26 · 2024-05-05T19:35:30.000Z

In the meantime I tested also other thing files....the first time it's not changing but than it seems to be fine

Answer 27 · 2024-05-05T19:57:32.000Z

@jimtng Which one do I need to replace?

The one with the exact same name.
I don't know why you have two.

Answer 28 · 2024-05-05T20:20:45.000Z

the second one is just a link :) so I have only one.....I used find to find the location

Answer 29 · 2024-05-05T20:31:25.000Z

@jimtng looks good for me.....now

I am on openHAB 4.2.0 (Build #4065) with the jar file replaced as @jimtng wrote

I changed the file shelly.things from
Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_links" @ "Bedroom" [deviceIp="ip", password="password"] Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechts" @ "Bedroom" [deviceIp="ip", password="password"]
to

Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_linkse" @ "Bedroom" [deviceIp="ip", password="password"] Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechtse" @ "Bedroom" [deviceIp="ip", password="password"]
in the log I see

2024-05-05 22:30:40.510 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'shelly.things'
2024-05-05 22:30:40.630 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Unerwarteter Fehler - WebSocket connection closed abnormal
2024-05-05 22:30:40.656 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Unerwarteter Fehler - WebSocket connection closed abnormal
2024-05-05 22:30:42.617 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from ONLINE to UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus.
2024-05-05 22:30:42.654 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from ONLINE to UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus.
2024-05-05 22:30:43.046 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. to ONLINE
2024-05-05 22:30:43.081 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. to ONLINE

already on the first attemp

changed back from

Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_linkse" @ "Bedroom" [deviceIp="ip", password="password"] Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechtse" @ "Bedroom" [deviceIp="ip", password="password"]
to

Thing shelly:shellyplus1pm:441793cea354 "Plus1PM_Bett_links" @ "Bedroom" [deviceIp="ip", password="password"] Thing shelly:shellyplus1pm:d4d4da7cbde0 "Plus1PM_Bett_rechts" @ "Bedroom" [deviceIp="ip", password="password"]
in the log I see

2024-05-05 22:30:40.510 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'shelly.things' 2024-05-05 22:30:40.630 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Unerwarteter Fehler - WebSocket connection closed abnormal 2024-05-05 22:30:40.656 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Unerwarteter Fehler - WebSocket connection closed abnormal 2024-05-05 22:30:42.617 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from ONLINE to UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. 2024-05-05 22:30:42.654 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from ONLINE to UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. 2024-05-05 22:30:43.046 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:d4d4da7cbde0' changed from UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. to ONLINE 2024-05-05 22:30:43.081 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:441793cea354' changed from UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. to ONLINE

Answer 30 · 2024-05-05T22:34:30.000Z

@lolodomo would you mind testing too please

Answer 31 · 2024-05-06T00:07:45.000Z

@miloit thanks for testing. I take it that the jar I supplied did fix the problem?

Would you mind testing the following:

only change the first thing then save the file and watch the log, and
only change the second thing then save the file and watch the log

It should log that only the changed thing would go offline -> online and the unchanged thing should remain online.

Answer 32 · 2024-05-06T05:21:19.000Z

@jimtng Yes the jar file fixed the problem

Also the second situation is running fine for me....

Answer 33 · 2024-05-07T13:35:55.000Z

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

https://community.openhab.org/t/since-4-2-0-snapshot-build-4065-and-later-unable-to-resolve-root-missing-requirement/155842/5