Upgrade to 3.4.0-SNAPSHOT issues on Windows 10 from openHAB 3.3.0.M5

Mark_VG · August 9, 2022, 1:19pm

Platform information:
- OS: Windows 10/10.0 (amd64)
- Java Runtime Environment: _11.0.14.1 (Zulu11.54+25-CA)
- openHAB version: openHAB 3.3.0.M5

Hi All
Tried to upgrade from openHAB 3.3.0.M5 to 3.4.0-SNAPSHOT on my Windows 10 machine.

Powershell update.ps1 ran with the following error/warning:

Execute 'POST' instructions for version 3.4.0-SNAPSHOT

Performing post-update tasks for version [3.4.0] :
Could not move C:\openhab\userdata/jsondb/org.openhab.core.transform.TransformationConfiguration.json to C:\openhab\userdata/jsondb/org.openhab.core.transform.Transformation.json

More complete output:
Update Output.txt (3.7 KB)

Checked the folder and see no such file.

On startup of openHAB I get the following:

15:00:03.946 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSMarkatHoylake' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.152 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSEthanatHoylake' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.213 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSAnneatHome' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.217 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'ShellyGateshelly1a4cf12f41d5e10163199231_Input' with pattern 'MAP(doors.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.232 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSRileyatHoylake' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.440 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSRileyatHome' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.534 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSEthanatWilden' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.565 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSAnneatMeadow' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.599 [WARN ] [se.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: ShellyUNIshellyunie8db84d6b3e510163199230_VoltageADC
15:00:04.728 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSEthanatHome' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.754 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSAnneatHoylake' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.931 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSRileyatWilden' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:04.968 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPS_Presence_Home' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:05.017 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'ShellyGarageDoorshelly1a4cf12f486ac10163199232_Input' with pattern 'MAP(doors.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.
15:00:05.020 [WARN ] [.rest.core.item.EnrichedItemDTOMapper] - Failed transforming the state 'NULL' on item 'GPSMarkatHome' with pattern 'MAP(presence.map):%s': Couldn't transform value because transformation service of type 'MAP' is not available.

Which I assume are caused by the update error/warning?

Also get the following for my CADDX binding:

15:00:56.133 [ERROR] [rnal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.caddx.internal.handler.CaddxBridgeHandler@162b5828': For input string: "15.0"
java.lang.NumberFormatException: For input string: "15.0"
        at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:?]
        at java.lang.Integer.parseInt(Integer.java:652) ~[?:?]
        at java.lang.Integer.valueOf(Integer.java:957) ~[?:?]
        at java.lang.Integer.decode(Integer.java:1436) ~[?:?]
        at org.openhab.binding.caddx.internal.CaddxMessage.<init>(CaddxMessage.java:111) ~[?:?]
        at org.openhab.binding.caddx.internal.handler.CaddxBridgeHandler.sendCommand(CaddxBridgeHandler.java:258) ~[?:?]
        at org.openhab.binding.caddx.internal.handler.CaddxBridgeHandler.lambda$0(CaddxBridgeHandler.java:165) ~[?:?]
        at java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1603) ~[?:?]
        at org.openhab.binding.caddx.internal.handler.CaddxBridgeHandler.initialize(CaddxBridgeHandler.java:165) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor112.invoke(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
15:00:56.483 [ERROR] [.core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'caddx:bridge:e59e4935': For input string: "15.0"
java.lang.NumberFormatException: For input string: "15.0"
        at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:?]
        at java.lang.Integer.parseInt(Integer.java:652) ~[?:?]
        at java.lang.Integer.valueOf(Integer.java:957) ~[?:?]
        at java.lang.Integer.decode(Integer.java:1436) ~[?:?]
        at org.openhab.binding.caddx.internal.CaddxMessage.<init>(CaddxMessage.java:111) ~[?:?]
        at org.openhab.binding.caddx.internal.handler.CaddxBridgeHandler.sendCommand(CaddxBridgeHandler.java:258) ~[?:?]
        at org.openhab.binding.caddx.internal.handler.CaddxBridgeHandler.lambda$0(CaddxBridgeHandler.java:165) ~[?:?]
        at java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1603) ~[?:?]
        at org.openhab.binding.caddx.internal.handler.CaddxBridgeHandler.initialize(CaddxBridgeHandler.java:165) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor112.invoke(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]

I have reverted back to my 3.3.0.M5 backup after trying the update 3 times.

Any assistance would be greatly appreciated.
Mark

rlkoshak · August 9, 2022, 2:35pm

The could not move error can be ignored I think. You likely never had the org.openhab.core.transform.TransformationConfiguration file in the first place so there was no file to move to its new name. That’s the file where UI configured transformations (e.g. defining the .map file in the UI) will be stored. But since the UI part of that isn’t merged yet, you likely wouldn’t have that file yet.

No, that error is telling you that the Map transformation add-on is not installed. That’s not unusual immediately after an upgrade because OH has to download and reinstall the latest versions of all the add-ons and that can take some time. Do you see any errors installing add-ons in your logs? After you wait a bit do the errors go away? Is the Map Transform add-on installed?

That’s a different and unrelated error. The error checking was firmed up which caused some Thing configs to be called out with invalid configs. I think the easiest fix is to delete and recreate the Thing that is generating the error.

Mark_VG · August 10, 2022, 7:51am

Hi Rich

As usual you seem to have been correct.

So I decided to rather go from 3.3.0.M5 to 3.3.0.

Got the same errors/warnings etc. But after a restart for the THING all the errors seem to have cleared.
Also restarted openHAB and all OK on restart.

EDIT: But I have to restart the Bridge THING manually on a restart of openHAB

I am now seeing the following is wrapper.log:

STATUS | wrapper  | 2022/08/10 14:05:00 | --> Wrapper Started as Service
STATUS | wrapper  | 2022/08/10 14:05:01 | Launching a JVM...
INFO   | jvm 1    | 2022/08/10 14:05:03 | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
INFO   | jvm 1    | 2022/08/10 14:05:03 |   Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.
INFO   | jvm 1    | 2022/08/10 14:05:03 | 
INFO   | jvm 1    | 2022/08/10 14:05:31 | Exception in thread "Thread-16" java.lang.IllegalStateException: Executor has been shut down
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at org.apache.sshd.common.util.ValidateUtils.createFormattedException(ValidateUtils.java:213)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at org.apache.sshd.common.util.ValidateUtils.throwIllegalStateException(ValidateUtils.java:207)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at org.apache.sshd.common.util.ValidateUtils.checkState(ValidateUtils.java:184)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at org.apache.sshd.common.util.threads.NoCloseExecutor.execute(NoCloseExecutor.java:100)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at java.base/sun.nio.ch.AsynchronousChannelGroupImpl.executeOnPooledThread(AsynchronousChannelGroupImpl.java:188)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at java.base/sun.nio.ch.Invoker.invokeIndirectly(Invoker.java:213)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at java.base/sun.nio.ch.Invoker.invokeIndirectly(Invoker.java:314)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at java.base/sun.nio.ch.WindowsAsynchronousServerSocketChannelImpl$AcceptTask.failed(WindowsAsynchronousServerSocketChannelImpl.java:286)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at java.base/sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:389)
INFO   | jvm 1    | 2022/08/10 14:05:31 | 	at java.base/java.lang.Thread.run(Thread.java:829)
INFO   | jvm 1    | 2022/08/10 14:05:41 | Warning: Nashorn engine is planned to be removed from a future JDK release
INFO   | jvm 1    | 2022/08/10 14:05:42 | Warning: Nashorn engine is planned to be removed from a future JDK release

I do not recall seeing this error before? And also see the timestamp is actually an hour earlier than the entries in openhab.log?

rlkoshak · August 10, 2022, 1:27pm

I’ve never seen anything like these. They are not part of OH directly. It’s failing somewhere in org.apache.sshd.common which I believe is what Karaf uses so you can ssh into the console.

Mark_VG · August 10, 2022, 1:33pm

Thanks Rich. All seems to be working (except for having to restart the Bridge THING). Will see what happens when I go to 3.4.0.SNAPSHOT maybe.