[Bug-7829] Ignition upgrade to 8.1.28 failed

zxcslo · June 3, 2023, 8:28am

Today I was trying to upgrade my Ignition from 8.1.27 to 8.1.28 and the gateway won't start:
Screenshot_19

Summary

STATUS | wrapperm | 2023/06/03 10:19:01 | Starting the Ignition Gateway service...
STATUS | wrapper  | 2023/06/03 10:19:01 | --> Wrapper Started as Service
STATUS | wrapper  | 2023/06/03 10:19:01 | Java Service Wrapper Standard Edition 64-bit 3.5.42
STATUS | wrapper  | 2023/06/03 10:19:01 |   Copyright (C) 1999-2020 Tanuki Software, Ltd. All Rights Reserved.
STATUS | wrapper  | 2023/06/03 10:19:01 |     http://wrapper.tanukisoftware.com
STATUS | wrapper  | 2023/06/03 10:19:01 |   Licensed to Inductive Automation for Inductive Automation
STATUS | wrapper  | 2023/06/03 10:19:01 | 
STATUS | wrapper  | 2023/06/03 10:19:02 | Launching a JVM...
INFO   | jvm 1    | 2023/06/03 10:19:02 | WrapperManager: Initializing...
INFO   | jvm 1    | 2023/06/03 10:19:02 | 10:19:02,758 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [data\\logback.xml] at [file:/C:/Program%20Files/Inductive%20Automation/Ignition/data/logback.xml]
INFO   | jvm 1    | 2023/06/03 10:19:02 | 10:19:02,827 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
INFO   | jvm 1    | 2023/06/03 10:19:02 | 10:19:02,828 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SysoutAppender]
INFO   | jvm 1    | 2023/06/03 10:19:02 | 10:19:02,831 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
INFO   | jvm 1    | 2023/06/03 10:19:02 | 10:19:02,844 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [com.inductiveautomation.logging.SQLiteAppender]
INFO   | jvm 1    | 2023/06/03 10:19:02 | 10:19:02,850 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [DB]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,955 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@5f9b188e - Driver name=SQLite JDBC
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,956 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@5f9b188e - Driver version=3.41.2.1
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,956 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@5f9b188e - supportsGetGeneratedKeys=true
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,963 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,964 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SysoutAsync]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,964 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SysoutAppender] to ch.qos.logback.classic.AsyncAppender[SysoutAsync]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,965 |-INFO in ch.qos.logback.classic.AsyncAppender[SysoutAsync] - Attaching appender named [SysoutAppender] to AsyncAppender.
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,965 |-INFO in ch.qos.logback.classic.AsyncAppender[SysoutAsync] - Setting discardingThreshold to 51
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,967 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,967 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [DBAsync]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,967 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [DB] to ch.qos.logback.classic.AsyncAppender[DBAsync]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,967 |-INFO in ch.qos.logback.classic.AsyncAppender[DBAsync] - Attaching appender named [DB] to AsyncAppender.
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,967 |-INFO in ch.qos.logback.classic.AsyncAppender[DBAsync] - Setting discardingThreshold to 51
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,969 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,969 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SysoutAsync] to Logger[ROOT]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,969 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [DBAsync] to Logger[ROOT]
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,969 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,970 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@683c594c - Registering current configuration as safe fallback point
INFO   | jvm 1    | 2023/06/03 10:19:03 | 10:19:02,996 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@414f8a82 - Propagating INFO level on Logger[ROOT] onto the JUL framework
INFO   | jvm 1    | 2023/06/03 10:19:03 | E [IgnitionGateway               ] [08:19:03]: Error initializing web manager:  
INFO   | jvm 1    | 2023/06/03 10:19:03 | java.lang.IllegalArgumentException: Malformed \uxxxx encoding.
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at java.base/java.util.Properties.loadConvert(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at java.base/java.util.Properties.load0(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at java.base/java.util.Properties.load(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at com.inductiveautomation.ignition.gateway.web.WebResourceManagerImpl.readInstallProperties(WebResourceManagerImpl.java:447)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at com.inductiveautomation.ignition.gateway.web.WebResourceManagerImpl.<init>(WebResourceManagerImpl.java:113)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.<init>(IgnitionGateway.java:523)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.main(IgnitionGateway.java:298)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at com.inductiveautomation.catapult.Catapult.main(Catapult.java:8)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:349)
INFO   | jvm 1    | 2023/06/03 10:19:03 | 	at java.base/java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp: 
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: Encountered an error running main:
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: java.lang.NullPointerException
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.start(IgnitionGateway.java:578)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.main(IgnitionGateway.java:300)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at com.inductiveautomation.catapult.Catapult.main(Catapult.java:8)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:349)
INFO   | jvm 1    | 2023/06/03 10:19:03 | WrapperSimpleApp Error: 	at java.base/java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2023/06/03 10:19:03 | I [C.SecureRandomProvider        ] [08:19:03]: Secure random seed generated in 0ms 
STATUS | wrapper  | 2023/06/03 10:19:05 | <-- Wrapper Stopped
ERROR  | wrapperm | 2023/06/03 10:19:06 | The Ignition Gateway service was launched, but failed to start.
ERROR  | wrapperm | 2023/06/03 10:19:06 | Please check the log file for more information: C:\Program Files\Inductive Automation\Ignition\logs\wrapper.log

I downgraded back to 8.1.27 and the gateway is starting normal...
I also tried 8.1.29 SNAPSHOT and the gateway also won't start...

This is on Windows x64 2016 LTSB... (on VMWare Virtual machine)...

zxcslo · June 3, 2023, 10:10am

OK, I found that if I delete the IgnitionGateway.exe file from C:\Program Files\Inductive Automation\Ignition folder, then the 8.1.28 installation goes through OK and the gateway will start normally.
But then, if I start the 8.1.28 installation AGAIN and upgrade, the gateway will NOT start.
And if I delete the IgnitionGateway.exe again and start the 8.1.28 install, the gateway will start...

avaughn · June 4, 2023, 3:53am

Could you upload your install.log and install-info.txt files from after the upgrade? The log file should be in the logs folder and install-info.txt is in the lib folder.

zxcslo · June 4, 2023, 5:24am

There is NO install.log created for this upgrade...
There are only the old install logs from previous upgrades...
Screenshot_20
And this is the install-info.txt:
Screenshot_21

zxcslo · June 4, 2023, 5:41am

I found another log file in the user .ignition folder...
install.log (149.2 KB)

avaughn · June 4, 2023, 6:35am

I’ll have to look into it more on Monday, but it seems like it may be failing due to the backslash in the username.

Is the username showing as the same on 8.1.27?

zxcslo · June 4, 2023, 6:41am

~~Yes.~~
Actualy NO. See the post bellow...

zxcslo · June 4, 2023, 7:08am

You're right.
If I delete DESKTOP-8T2EMTA\ from the username in install-info.txt, then the Ignition service will start normally...

zxcslo · June 4, 2023, 7:23am

This is the install-info.txt before upgrade:
before_upgrade

and this is after upgrade:
after_upgrade
and the Ignition service won't start.
If I delete DESKTOP-8T2EMTA\ from username, then the Ignition service will start.

avaughn · June 5, 2023, 2:03pm

I was able to replicate this, and it's the \u that's tripping it up. This will also happen on 8.1.27, so I'm curious as to why DESKTOP-8T2EMTA\ was added to the username. From what I see, it gets added when using a specific user account to run the Ignition service.

Between the installation of 8.1.27 and the upgrade to 8.1.28 did you change the account the Ignition service is running as?

zxcslo · June 5, 2023, 4:10pm

No. Service is always running as System (default).

I tried with various upgrades, from 8.1.21, 8.1.23, 8.1.26 and 8.1.27 to 8.1.28 and it's always the same:
Prior to upgrade, the username is without PC name and backslash, after the upgrade to 8.1.28, PC name and backslash are added...

avaughn · June 5, 2023, 4:17pm

I filed an internal ticket to get this addressed, but it looks like the optimal solution is to escape the \u with a second backslash.

jcoffman · June 5, 2023, 4:18pm

This works and the easiest way is to supply the user CLI argument during install

zxcslo · June 5, 2023, 4:21pm

You mean, until this is resolved from your (IA) side...?

jcoffman · June 5, 2023, 4:59pm

Yes. The ticket is filed already, but this will get you up and running in the mean time.

avaughn · June 5, 2023, 5:29pm

Do you have the "Allow service to interact with desktop" option selected?

pturmel · June 5, 2023, 5:39pm

Curious. I was under the impression that that setting was a no-op now-a-days.

zxcslo · June 5, 2023, 5:50pm

No, never.

avaughn · June 5, 2023, 5:50pm

I'll be completely honest, I've never even noticed that option before and don't know anything about it. Checking it though did seem to cause the username to update during install/upgrade to include the user origin and backslash.

Edit: I see from this thread that it's mentioned after Windows 7 it isn't really usable.

avaughn · June 5, 2023, 8:06pm

Not sure why DESKTOP-8T2EMTA\ is getting added in the first place then. I did do some testing and noticed that once it started to get added during upgrades, I had to restart my entire system to get it to stop.

Ultimately, for now the best thing to do is to manually set the username so it doesn't include the \u or escape it with an extra \. Or change the user name to not start with u. Then once the fix is in place in a future update, you won't have to worry about it.