Massive issues after upgrade to OH 2.5.0

Hi,
I just did an update from OH 2.4 to OH 2.5.0
My Platform is running on Ubuntu, on a “Mini-PC”, with 8GB memory. Software-wise the system is up-to-date. I run around 2000 items on 100 things (Homematic, HUE, various stuff over IP), total around 7000 lines of code in my rules. Around 20 Sitempas and 20 Dashboards in HabPanel.

After the upgrade the system seems to be broken on various ends. Of course it starts and producing logs, but my smarthome is not really smart anymore.,. :frowning:

The biggest pain points right now: (perhaps related to each other)

  • When i press a button in HABPanel (the normal button widget, with for instance a Homematic Switch behind) it issues the command but doesn’t update the state in HABPanel. Only after a reload of the page the correct state is visible (either via browser reload or via the refresh in HABPanel). I tried with Chrome and Firefox, private Tabs, Clear Browser Cache and also cleaned the openhab cache, nothing helped…) I have found a similar thread in the community, but related to group items. The state change is written in the event.log
  • when I come over the openhab-cli (console) I can update some of my items with a smarthome:send <> <>, for instance the above mentioned homematic state, but others i can’t. again saving the items files doesn’t help.

Anyone any ideas on above mentioned issues?

thanks
martin

i just made some further tests, it seems that all my items which are provisioned via an *.item file are not working anymore. I cannot update their state, although there is a received command in the event log.

setting log level to trace and looking into openhab.log shows me:

> 2020-01-03 18:08:00.636 [TRACE] [shd.server.session.ServerSessionImpl] - encode(ServerSessionImpl[openhab@/127.0.0.1:59278]) packet #211 [chunk #1](51/51) 5e 00 00 00 00 00 00 00 2a 1b 5b 37 44 1b 5b 39 36 6d 73 6d 61 72 74 68 6f 6d 65 3a 73 74 61 74 75 73 1b 5b 30 6d 20 74 65 73 74 69 74 65 6d 32 1b 5b 4b                                           ^.......*.[7D.[96msmarthome:status.[0m.testitem2.[K
> 2020-01-03 18:08:00.950 [TRACE] [shd.server.session.ServerSessionImpl] - encode(ServerSessionImpl[openhab@/127.0.0.1:59278]) packet #212 [chunk #1](42/42) 5e 00 00 00 00 00 00 00 21 1b 5b 31 35 44 1b 5b 39 36 6d 65 6e 64 1b 5b 30 6d 20 74 65 73 74 69 74 65 6d 32 20 4f 4e 1b 5b 4b                                                                      ^.......!.[15D.[96mend.[0m.testitem2.ON.[K
> 2020-01-03 18:08:02.704 [TRACE] [shd.server.session.ServerSessionImpl] - encode(ServerSessionImpl[openhab@/127.0.0.1:59278]) packet #213 [chunk #1](41/41) 5e 00 00 00 00 00 00 00 20 1b 5b 31 36 44 1b 5b 39 36 6d 74 61 74 75 73 1b 5b 30 6d 20 74 65 73 74 69 74 65 6d 32 1b 5b 4b                                                                         ^.........[16D.[96mtatus.[0m.testitem2.[K
> 2020-01-03 18:08:03.576 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Executing command: 'smarthome:status testitem2'
> 2020-01-03 18:08:03.583 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Command: 'smarthome:status testitem2' returned 'null'
> 2020-01-03 18:08:04.230 [TRACE] [shd.server.session.ServerSessionImpl] - encode(ServerSessionImpl[openhab@/127.0.0.1:59278]) packet #219 [chunk #1](44/44) 5e 00 00 00 00 00 00 00 23 1b 5b 39 36 6d 73 6d 61 72 74 68 6f 6d 65 3a 73 74 61 74 75 73 1b 5b 30 6d 20 74 65 73 74 69 74 65 6d 32                                                                ^.......#.[96msmarthome:status.[0m.testitem2
> 2020-01-03 18:08:05.497 [TRACE] [shd.server.session.ServerSessionImpl] - encode(ServerSessionImpl[openhab@/127.0.0.1:59278]) packet #222 [chunk #1](51/51) 5e 00 00 00 00 00 00 00 2a 1b 5b 37 44 1b 5b 39 36 6d 73 6d 61 72 74 68 6f 6d 65 3a 73 74 61 74 75 73 1b 5b 30 6d 20 74 65 73 74 69 74 65 6d 32 1b 5b 4b                                           ^.......*.[7D.[96msmarthome:status.[0m.testitem2.[K
> 2020-01-03 18:08:06.056 [TRACE] [shd.server.session.ServerSessionImpl] - encode(ServerSessionImpl[openhab@/127.0.0.1:59278]) packet #223 [chunk #1](42/42) 5e 00 00 00 00 00 00 00 21 1b 5b 31 35 44 1b 5b 39 36 6d 65 6e 64 1b 5b 30 6d 20 74 65 73 74 69 74 65 6d 32 20 4f 4e 1b 5b 4b                                                                      ^.......!.[15D.[96mend.[0m.testitem2.ON.[K
> 2020-01-03 18:08:06.852 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Executing command: 'smarthome:send testitem2 ON'
> 2020-01-03 18:08:06.861 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Command: 'smarthome:send testitem2 ON' returned 'null'
> 2020-01-03 18:08:07.454 [TRACE] [shd.server.session.ServerSessionImpl] - encode(ServerSessionImpl[openhab@/127.0.0.1:59278]) packet #229 [chunk #1](45/45) 5e 00 00 00 00 00 00 00 24 1b 5b 39 36 6d 73 6d 61 72 74 68 6f 6d 65 3a 73 65 6e 64 1b 5b 30 6d 20 74 65 73 74 69 74 65 6d 32 20 4f 4e                                                             ^.......$.[96msmarthome:send.[0m.testitem2.ON
> 2020-01-03 18:08:07.683 [TRACE] [shd.server.session.ServerSessionImpl] - encode(ServerSessionImpl[openhab@/127.0.0.1:59278]) packet #230 [chunk #1](41/41) 5e 00 00 00 00 00 00 00 20 1b 5b 31 36 44 1b 5b 39 36 6d 74 61 74 75 73 1b 5b 30 6d 20 74 65 73 74 69 74 65 6d 32 1b 5b 4b                                                                         ^.........[16D.[96mtatus.[0m.testitem2.[K
> 2020-01-03 18:08:08.157 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Executing command: 'smarthome:status testitem2'
> 2020-01-03 18:08:08.164 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Command: 'smarthome:status testitem2' returned 'null'

That little snipped of logs is not useful.

Stop openHAB and return the logging level to info. We should be able to see what we need to at that level.

Then watch the log as OH starts up. Do you see any errors? What are they? Do you see your .items files loading?

hi,
I was already afraid that this snipped is not useful, anyhow I thought perhaps someone has the same in his/her logs. at this point in time the item files were loaded, otherwise I assume the smarthome:send command won’T say “successful”. Also I saw my update in the event.log, but it didn’t reach the item state.

Startup didn’t show any meaningful/consistent errors, although it was strange., I started 5 times, and 3 times it looked like the item files were loaded after the rule files… I saw a lot of errors from my rule files that the items are missing. after some minutes it stopped.
but it also started “normal”, and there were no specific errors, but I’ll grep through the log later on again.

Any errors are meaningful.

That’s a long time issue that has been around since OH 2.0. For some people, some times, Rules are loaded before Items and then the Rules start to explode because Items don’t exist.

There is also a known bug that only occurs on the first startup after an upgrade where Items just appear not to exist. But a restart seems to clear that up.

oh, good to know. I never faced that issue during the last years, but that explains some of the issues.

Interesting, I’ll have a look if I can find some more information on that one.

Meanwhile I made a downgrade to 2.4.0 again, and everything is back to normal.
I have to deeper analyse the logs I captured during my short 2.5.0 journey, and I have to investigate a way to upgrade without total service loss …