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.
