Ubuntu Ignition service fails

Hi all,

We are running Ignition 8.1.10 on an Ubuntu server. Oct. 5’th we had some performance issues and rebooted it. After the reboot Ignition never started up. Re-installed Ignition and it solved the issue.

Today, oct. 8’th Ignition stopped again. No reboot, but we created a snapshot of the server in about the same time. It really should not affect the server, and it did not stop during the nightly snapshot.

Any ideas ?

*** UPDATE ***

Creating another snapshot caused it to fail again.

Check Ignition’s wrapper.log file for more information about what is causing the service to fail.

STATUS | wrapper | 2021/10/08 08:50:56 | TERM trapped. Shutting down.
INFO | jvm 1 | 2021/10/08 08:50:56 | I [o.e.j.s.AbstractConnector ] [08:50:56]: Stopped ServerConnector@65b4331d{HTTP/1.1, (http/1.1)}{0.0.0.0:8088}
INFO | jvm 1 | 2021/10/08 08:50:56 | W [P.WebSocketChannel ] [08:50:56]: Websocket connection closed unexpectedly. code=1006, reason=Disconnected
INFO | jvm 1 | 2021/10/08 08:50:56 | I [p.ClientSession ] [08:50:56]: WebSocket disconnected from session. session-project=REMOVED
INFO | jvm 1 | 2021/10/08 08:50:56 | I [o.e.j.s.AbstractConnector ] [08:50:56]: Stopped ServerConnector@7ed930be{SSL, (ssl, http/1.1)}{0.0.0.0:8043}
INFO | jvm 1 | 2021/10/08 08:50:56 | I [o.e.j.s.AbstractConnector ] [08:50:56]: Stopped ServerConnector@1d68afd3{SSL, (ssl, http/1.1)}{0.0.0.0:8060}
INFO | jvm 1 | 2021/10/08 08:50:56 | I [o.e.j.s.session ] [08:50:56]: node0 Stopped scavenging
INFO | jvm 1 | 2021/10/08 08:50:56 | I [IgnitionGateway ] [08:50:56]: Ignition[state=RUNNING] ContextState = STOPPING
INFO | jvm 1 | 2021/10/08 08:50:56 | I [IgnitionGateway ] [08:50:56]: Ignition Gateway shutting down…
INFO | jvm 1 | 2021/10/08 08:50:56 | W [R.Manager ] [08:50:56]: Auto-Detect public HTTP address was disabled but no http addresses were provided. reverting to auto-detect enabled.
INFO | jvm 1 | 2021/10/08 08:50:56 | I [g.ModuleManager ] [08:50:56]: ModuleManager shutting down…
INFO | jvm 1 | 2021/10/08 08:50:56 | I [g.ModuleManager ] [08:50:56]: Shutting down module ‘com.inductiveautomation.reporting’ v6.1.10 (b2021090812)… module-name=Reporting
INFO | jvm 1 | 2021/10/08 08:50:56 | I [g.ModuleManager ] [08:50:56]: Shutdown of module “com.inductiveautomation.reporting” completed in 108 ms module-name=Reporting
INFO | jvm 1 | 2021/10/08 08:50:56 | I [g.ModuleManager ] [08:50:56]: Shutting down module ‘com.inductiveautomation.opcua.drivers.modbus’ v7.1.10 (b2021090812)… module-name=Modbus Driver
INFO | jvm 1 | 2021/10/08 08:50:56 | I [g.ModuleManager ] [08:50:56]: Shutdown of module “com.inductiveautomation.opcua.drivers.modbus” completed in 10 ms module-name=Modbus Driver
INFO | jvm 1 | 2021/10/08 08:50:56 | I [g.ModuleManager ] [08:50:56]: Shutting down module ‘com.inductiveautomation.opcua.drivers.tcpudp’ v6.1.10 (b2021090812)… module-name=UDP and TCP Drivers
INFO | jvm 1 | 2021/10/08 08:50:56 | I [g.ModuleManager ] [08:50:56]: Shutdown of module “com.inductiveautomation.opcua.drivers.tcpudp” completed in 0 ms module-name=UDP and TCP Drivers
INFO | jvm 1 | 2021/10/08 08:50:56 | I [g.ModuleManager ] [08:50:56]: Shutting down module ‘com.inductiveautomation.perspective’ v2.1.10 (b2021090812)… module-name=Perspective
INFO | jvm 1 | 2021/10/08 08:50:56 | E [P.GatewayHook ] [08:50:56]: Uncaught throwable in the Perspective Gateway Event Bus module-name=Perspective

This seems to be the moment the server shuts down. Sending the logs to support for them to have a look as well.

That means something in your system deliberately sent a shutdown signal to Ignition.

Ok, thanks. This log is from the server trying to start (I recon). Is it possible to see why it wont start?

INFO | jvm 1 | 2021/10/08 08:52:23 | WARNING: An illegal reflective access operation has occurred
INFO | jvm 1 | 2021/10/08 08:52:23 | WARNING: Illegal reflective access by com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl (file:/usr/local/bin/ignition/lib/core/gateway/gateway-8.1.10.jar) to field java.lang.ClassLoader.usr_paths
INFO | jvm 1 | 2021/10/08 08:52:23 | WARNING: Please consider reporting this to the maintainers of com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl
INFO | jvm 1 | 2021/10/08 08:52:23 | WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
INFO | jvm 1 | 2021/10/08 08:52:23 | WARNING: All illegal access operations will be denied in a future release
INFO | jvm 1 | 2021/10/08 08:52:24 | I [o.e.j.s.AbstractConnector ] [08:52:24]: Started ServerConnector@6c1a610b{SSL, (ssl, http/1.1)}{0.0.0.0:8043}
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp:
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: Encountered an error running main:
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: MultiException[java.io.IOException: Failed to bind to 0.0.0.0/0.0.0.0:8088, java.io.IOException: Failed to bind to 0.0.0.0/0.0.0.0:8060]
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.util.MultiException.ifExceptionThrow(MultiException.java:122)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.Server.doStart(Server.java:413)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at com.inductiveautomation.catapult.IgnitionServer.start(IgnitionServer.java:1177)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at com.inductiveautomation.ignition.gateway.web.WebResourceManagerImpl.start(WebResourceManagerImpl.java:325)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at com.inductiveautomation.ignition.gateway.IgnitionGateway.start(IgnitionGateway.java:560)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at com.inductiveautomation.ignition.gateway.IgnitionGateway.main(IgnitionGateway.java:294)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at com.inductiveautomation.catapult.Catapult.main(Catapult.java:8)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/java.lang.reflect.Method.invoke(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:349)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/java.lang.Thread.run(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: Suppressed: java.io.IOException: Failed to bind to 0.0.0.0/0.0.0.0:8088
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:349)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:310)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:234)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.Server.doStart(Server.java:401)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: … 12 more
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: Caused by: java.net.BindException: Address already in use
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.Net.bind0(Native Method)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.Net.bind(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.Net.bind(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.ServerSocketChannelImpl.bind(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.ServerSocketAdaptor.bind(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:344)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: … 17 more
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: Suppressed: java.io.IOException: Failed to bind to 0.0.0.0/0.0.0.0:8060
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:349)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:310)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:234)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.Server.doStart(Server.java:401)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: … 12 more
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: Caused by: java.net.BindException: Address already in use
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.Net.bind0(Native Method)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.Net.bind(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.Net.bind(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.ServerSocketChannelImpl.bind(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at java.base/sun.nio.ch.ServerSocketAdaptor.bind(Unknown Source)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:344)
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: … 17 more
INFO | jvm 1 | 2021/10/08 08:52:24 | WrapperSimpleApp Error: Caused by: [CIRCULAR REFERENCE: java.io.IOException: Failed to bind to 0.0.0.0/0.0.0.0:8088]
INFO | jvm 1 | 2021/10/08 08:52:24 | I [SystemInfo ] [08:52:24]: os.name=“linux”, os.arch=“amd64”.
INFO | jvm 1 | 2021/10/08 08:52:24 | I [SystemInfo ] [08:52:24]: Validating native library “ignition-x64”…
INFO | jvm 1 | 2021/10/08 08:52:24 | I [SystemInfo ] [08:52:24]: Validated ignition-x64 (libignition-x64.so)
INFO | jvm 1 | 2021/10/08 08:52:24 | I [SystemInfo ] [08:52:24]: Loading native library “ignition-x64”…
INFO | jvm 1 | 2021/10/08 08:52:24 | I [SystemInfo ] [08:52:24]: Native library load complete
INFO | jvm 1 | 2021/10/08 08:52:23 | W [R.Manager ] [08:52:23]: Auto-Detect public HTTP address was disabled but no http addresses were provided. reverting to auto-detect enabled.
INFO | jvm 1 | 2021/10/08 08:52:23 | I [R.S.S.InternalDb ] [08:52:23]: Internal db synchronizer disk cache initialized. State id=0eb22c01-5264-4a54-a260-8cebde1d904a
INFO | jvm 1 | 2021/10/08 08:52:23 | I [o.e.j.s.h.ContextHandler ] [08:52:23]: Started c.i.c.MainWebAppContext@5b8dfc84{Ignition,/,file:///usr/local/bin/ignition/webserver/webapps/main/,AVAILABLE}
INFO | jvm 1 | 2021/10/08 08:52:23 | I [R.StateMonitoring ] [08:52:23]: Redundancy state changed: Role=Independent, Activity level=Active, Project state=Good, History level=Full
INFO | jvm 1 | 2021/10/08 08:52:23 | I [o.e.j.s.AbstractConnector ] [08:52:23]: Started ServerConnector@1e7cdf8{HTTP/1.1, (http/1.1)}{0.0.0.0:8088}
INFO | jvm 1 | 2021/10/08 08:52:23 | I [g.InternalDatabaseManager ] [08:52:23]: Starting up…
INFO | jvm 1 | 2021/10/08 08:52:23 | I [P.InternalDatabase ] [08:52:23]: Looking for existing internal database “config.idb”…
INFO | jvm 1 | 2021/10/08 08:52:23 | I [P.InternalDatabase ] [08:52:23]: … found existing.
INFO | jvm 1 | 2021/10/08 08:52:23 | I [P.InternalDatabase ] [08:52:23]: internal database “config.idb” started up successfully.
INFO | jvm 1 | 2021/10/08 08:52:23 | I [P.InternalDatabase ] [08:52:23]: Registering autobackup task [owner=Internal DB Autobackup, name=internal database “config.idb”]

It looks like something else is already bound to ports 8088 and 8060 when this instance of Ignition is attempting to start. Try something like sudo netstat -peanut and look for local addresses listening on those ports. Then take a look at the right column for the process ID and go from there.

1 Like