I have noticed that Ignition Gateway takes long time(539 seconds) to start when not connected to the Internet. However it starts in 7 seconds when the Internet is connected.
Here is the wrapper log excerpts:-
INFO | jvm 1 | 2018/04/02 16:53:56 | I [G.Manager ] [20:53:56]: WSChannel manager started.
INFO | jvm 1 | 2018/04/02 16:53:56 | I [c.i.i.g.g.WSChannelManager ] [20:53:56]: GAN channel manager started successfully.
INFO | jvm 1 | 2018/04/02 16:53:57 | I [g.ModuleManager ] [20:53:56]: Starting up…
INFO | jvm 1 | 2018/04/02 16:53:57 | I [g.ModuleManager ] [20:53:56]: Starting up module ‘help’ v4.9.5 (b2017111615)… module-name=User Manual
INFO | jvm 1 | 2018/04/02 16:53:57 | I [g.ModuleManager ] [20:53:56]: Starting up module ‘xopc’ v4.9.5 (b2017111615)… module-name=OPC-UA
INFO | jvm 1 | 2018/04/02 16:53:57 | I [c.i.x.s.c.XOPCGatewayHook ] [20:53:56]: OPC-UA Server module starting up. module-name=OPC-UA
INFO | jvm 1 | 2018/04/02 16:53:57 | FROM GATEWAY
INFO | jvm 1 | 2018/04/02 16:53:57 | I [nanomsg Testing Tool ] [20:53:57]: The nanomsg gateway startup script was executed
INFO | jvm 1 | 2018/04/02 17:02:49 | W [c.i.x.s.c.XOPCModule ] [21:02:49]: java.lang.Exception: Could not find Inet4Address “localhost”. module-name=OPC-UA
…
…
…
INFO | jvm 1 | 2018/04/02 17:02:50 | I [g.ModuleManager ] [21:02:50]: Starting up module ‘symfact’ v5.9.5 (b2017111623)… module-name=Symbol Factory
INFO | jvm 1 | 2018/04/02 17:02:50 | I [g.ModuleManager ] [21:02:50]: Starting up module ‘fpmi’ v9.9.5 (b2017111615)… module-name=Vision
INFO | jvm 1 | 2018/04/02 17:02:51 | I [g.ModuleManager ] [21:02:50]: Starting up module ‘fsql’ v8.9.5 (b2017111615)… module-name=SQL Bridge
…
INFO | jvm 1 | 2018/04/02 17:02:51 | I [g.ModuleManager ] [21:02:51]: Starting up module ‘udp-driver’ v4.9.5 (b2017111615)… module-name=UDP and TCP Drivers
INFO | jvm 1 | 2018/04/02 17:02:51 | I [g.ModuleManager ] [21:02:51]: Starting up module ‘modbus-driver2’ v5.9.5 (b2017111615)… module-name=Modbus Driver
INFO | jvm 1 | 2018/04/02 17:02:51 | I [SRContext ] [21:02:51]: Ignition["/main", state=STARTING] ContextState = RUNNING
INFO | jvm 1 | 2018/04/02 17:02:51 | I [SRContext ] [21:02:51]: Gateway started in 539 seconds.
We need to stop and start Gateways as we have 2 independent servers of which only one can be up at a time so that clients do not accidentally connect to the standby server. After switching to Standby server Ignition Gateway is restarted.
These servers will be accessed only through a local network without access to internet. I am wondering what is causing the delay when internet connection is missing.
You already bolded the problem. If you don’t have a network connection, you must have a local DNS or you must have proper entries in /etc/hosts for anything that might need to be looked up. Basically, your servers themselves (not Ignition) are misconfigured for disconnected operation. ‘localhost’ is a name that must be resolvable.
3 Likes
Thank you for your quick response. There was some improvement after I changed the name ‘localhost’ to the server’s IP. Gateway modules start time was reduced to ~200 seconds. After uninstalling the OPC-UA module it starts modules start in ~5 seconds. However there is some delay even before wrapper logs start and some wait time during initializing.
STATUS | wrapper | 2018/04/03 15:08:42 | --> Wrapper Started as Daemon
STATUS | wrapper | 2018/04/03 15:09:38 | Java Service Wrapper Standard Edition 64-bit 3.5.29
STATUS | wrapper | 2018/04/03 15:09:38 | Copyright © 1999-2016 Tanuki Software, Ltd. All Rights Reserved.
STATUS | wrapper | 2018/04/03 15:09:38 | http://wrapper.tanukisoftware.com
STATUS | wrapper | 2018/04/03 15:09:38 | Licensed to Inductive Automation for Inductive Automation
STATUS | wrapper | 2018/04/03 15:09:38 |
STATUS | wrapper | 2018/04/03 15:09:38 | Launching a JVM…
INFO | jvm 1 | 2018/04/03 15:09:38 | WrapperManager: Initializing…
INFO | jvm 1 | 2018/04/03 15:09:38 | 15:09:38,783 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [/var/lib/ignition/data//logback.xml] at [file:/var/lib/ignition/data/logback.xml]
INFO | jvm 1 | 2018/04/03 15:10:34 | 15:10:34,887 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
INFO | jvm 1 | 2018/04/03 15:10:34 | 15:10:34,890 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SysoutAppender]
I do not understand why is this delay introduced only when not connected to internet
Put a proper localhost entry in your /etc/hosts file. ‘localhost’ must be resolvable.
localhost entry was added to the hosts file
What is in /etc/resolv.conf when not connected to the internet?
resolv.conf has the entry
nameserver 127.0.0.1
and hosts file
127.0.0.1 localhost localhost.localdomain localhost4 localhost4.localdomain4
After enabling detailed logging in wrapper.log we see it takes ~1min initializing logs
STATUS | wrapper | 2018/04/04 14:35:04 | --> Wrapper Started as Daemon
STATUS | wrapper | 2018/04/04 14:36:00 | Java Service Wrapper Standard Edition 64-bit 3.5.29
STATUS | wrapper | 2018/04/04 14:36:00 | Copyright © 1999-2016 Tanuki Software, Ltd. All Rights Reserved.
STATUS | wrapper | 2018/04/04 14:36:00 | http://wrapper.tanukisoftware.com
STATUS | wrapper | 2018/04/04 14:36:00 | Licensed to Inductive Automation for Inductive Automation
STATUS | wrapper | 2018/04/04 14:36:00 |
STATUS | wrapper | 2018/04/04 14:36:01 | Launching a JVM…
INFO | jvm 1 | 2018/04/04 14:36:01 | WrapperManager: Initializing…
INFO | jvm 1 | 2018/04/04 14:36:01 | 14:36:01,452 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [/var/lib/ignition/data//logback.xml] at [file:/var/lib/ignition/data/logback.xml]
INFO | jvm 1 | 2018/04/04 14:36:03 | Uncaught exception during getContextState():java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:08 | Received GetMainContextDetailsRequest…
INFO | jvm 1 | 2018/04/04 14:36:08 | …returning GetMainContextDetailsResponse (2ms)
INFO | jvm 1 | 2018/04/04 14:36:09 | java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:09 | at com.inductiveautomation.catapult.Catapult$CatapultRequestReceiverImpl.getWebServerState(Catapult.java:318)
INFO | jvm 1 | 2018/04/04 14:36:09 | at com.inductiveautomation.catapult.Catapult$CatapultRequestReceiverImpl.requestReceieved(Catapult.java:692)
INFO | jvm 1 | 2018/04/04 14:36:09 | at com.inductiveautomation.catapult.CatapultRequestServer.handleRequest(CatapultRequestServer.java:60)
INFO | jvm 1 | 2018/04/04 14:36:09 | at com.inductiveautomation.catapult.CatapultRequestServer.access$100(CatapultRequestServer.java:27)
INFO | jvm 1 | 2018/04/04 14:36:09 | at com.inductiveautomation.catapult.CatapultRequestServer$RequestFileMonitor$2.run(CatapultRequestServer.java:118)
INFO | jvm 1 | 2018/04/04 14:36:09 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
INFO | jvm 1 | 2018/04/04 14:36:09 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
INFO | jvm 1 | 2018/04/04 14:36:09 | at java.lang.Thread.run(Thread.java:748)
INFO | jvm 1 | 2018/04/04 14:36:19 | Uncaught exception during getContextState():java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:20 | Received GetMainContextDetailsRequest…
INFO | jvm 1 | 2018/04/04 14:36:20 | …returning GetMainContextDetailsResponse (0ms)
INFO | jvm 1 | 2018/04/04 14:36:21 | java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:21 | at com.inductiveautomation.catapult.Catapult$CatapultRequestReceiverImpl.getWebServerState(Catapult.java:318)
INFO | jvm 1 | 2018/04/04 14:36:21 | at com.inductiveautomation.catapult.Catapult$CatapultRequestReceiverImpl.requestReceieved(Catapult.java:692)
INFO | jvm 1 | 2018/04/04 14:36:21 | at com.inductiveautomation.catapult.CatapultRequestServer.handleRequest(CatapultRequestServer.java:60)
INFO | jvm 1 | 2018/04/04 14:36:21 | at com.inductiveautomation.catapult.CatapultRequestServer.access$100(CatapultRequestServer.java:27)
INFO | jvm 1 | 2018/04/04 14:36:21 | at com.inductiveautomation.catapult.CatapultRequestServer$RequestFileMonitor$2.run(CatapultRequestServer.java:118)
INFO | jvm 1 | 2018/04/04 14:36:21 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
INFO | jvm 1 | 2018/04/04 14:36:21 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
INFO | jvm 1 | 2018/04/04 14:36:21 | at java.lang.Thread.run(Thread.java:748)
INFO | jvm 1 | 2018/04/04 14:36:31 | Uncaught exception during getContextState():java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:33 | Received GetMainContextDetailsRequest…
INFO | jvm 1 | 2018/04/04 14:36:33 | …returning GetMainContextDetailsResponse (0ms)
INFO | jvm 1 | 2018/04/04 14:36:34 | java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:34 | at com.inductiveautomation.catapult.Catapult$CatapultRequestReceiverImpl.getWebServerState(Catapult.java:318)
INFO | jvm 1 | 2018/04/04 14:36:34 | at com.inductiveautomation.catapult.Catapult$CatapultRequestReceiverImpl.requestReceieved(Catapult.java:692)
INFO | jvm 1 | 2018/04/04 14:36:34 | at com.inductiveautomation.catapult.CatapultRequestServer.handleRequest(CatapultRequestServer.java:60)
INFO | jvm 1 | 2018/04/04 14:36:34 | at com.inductiveautomation.catapult.CatapultRequestServer.access$100(CatapultRequestServer.java:27)
INFO | jvm 1 | 2018/04/04 14:36:34 | at com.inductiveautomation.catapult.CatapultRequestServer$RequestFileMonitor$2.run(CatapultRequestServer.java:118)
INFO | jvm 1 | 2018/04/04 14:36:34 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
INFO | jvm 1 | 2018/04/04 14:36:34 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
INFO | jvm 1 | 2018/04/04 14:36:34 | at java.lang.Thread.run(Thread.java:748)
INFO | jvm 1 | 2018/04/04 14:36:44 | Uncaught exception during getContextState():java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:45 | Received GetMainContextDetailsRequest…
INFO | jvm 1 | 2018/04/04 14:36:45 | …returning GetMainContextDetailsResponse (0ms)
INFO | jvm 1 | 2018/04/04 14:36:46 | java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:46 | at com.inductiveautomation.catapult.Catapult$CatapultRequestReceiverImpl.getWebServerState(Catapult.java:318)
INFO | jvm 1 | 2018/04/04 14:36:46 | at com.inductiveautomation.catapult.Catapult$CatapultRequestReceiverImpl.requestReceieved(Catapult.java:692)
INFO | jvm 1 | 2018/04/04 14:36:46 | at com.inductiveautomation.catapult.CatapultRequestServer.handleRequest(CatapultRequestServer.java:60)
INFO | jvm 1 | 2018/04/04 14:36:46 | at com.inductiveautomation.catapult.CatapultRequestServer.access$100(CatapultRequestServer.java:27)
INFO | jvm 1 | 2018/04/04 14:36:46 | at com.inductiveautomation.catapult.CatapultRequestServer$RequestFileMonitor$2.run(CatapultRequestServer.java:118)
INFO | jvm 1 | 2018/04/04 14:36:46 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
INFO | jvm 1 | 2018/04/04 14:36:46 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
INFO | jvm 1 | 2018/04/04 14:36:46 | at java.lang.Thread.run(Thread.java:748)
INFO | jvm 1 | 2018/04/04 14:36:56 | Uncaught exception during getContextState():java.lang.NullPointerException
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,531 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,534 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SysoutAppender]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,539 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,558 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [com.inductiveautomation.logging.SQLiteAppender]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,564 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [DB]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,660 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@4347da67 - Driver name=SQLiteJDBC
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,660 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@4347da67 - Driver version=native
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,660 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@4347da67 - supportsGetGeneratedKeys=true
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,667 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,668 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SysoutAsync]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,669 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SysoutAppender] to ch.qos.logback.classic.AsyncAppender[SysoutAsync]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,669 |-INFO in ch.qos.logback.classic.AsyncAppender[SysoutAsync] - Attaching appender named [SysoutAppender] to AsyncAppender.
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,669 |-INFO in ch.qos.logback.classic.AsyncAppender[SysoutAsync] - Setting discardingThreshold to 51
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,669 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,669 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [DBAsync]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,669 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [DB] to ch.qos.logback.classic.AsyncAppender[DBAsync]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,669 |-INFO in ch.qos.logback.classic.AsyncAppender[DBAsync] - Attaching appender named [DB] to AsyncAppender.
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,669 |-INFO in ch.qos.logback.classic.AsyncAppender[DBAsync] - Setting discardingThreshold to 51
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,670 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,670 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SysoutAsync] to Logger[ROOT]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,670 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [DBAsync] to Logger[ROOT]
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,670 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
INFO | jvm 1 | 2018/04/04 14:36:57 | 14:36:57,671 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@22235534 - Registering current configuration as safe fallback point
INFO | jvm 1 | 2018/04/04 14:36:57 | Scheduling logfile maintenance. Last maintenance: Wed Dec 31 19:00:00 EST 1969, events since then: 0
INFO | jvm 1 | 2018/04/04 14:36:57 | Starting logfile maintenance. Max entries: 50000
INFO | jvm 1 | 2018/04/04 14:36:57 | Cleaned up 428 rows in 6 ms. Vacuum performed: false
INFO | jvm 1 | 2018/04/04 14:36:57 | I [o.e.j.u.log ] [18:36:57]: Logging initialized @56613ms
I agree that a good localhost resolve is the most robust way, but can we use the IP address in the host override as a workaround?
So, with nameserver 127.0.0.1, your server must be running a local resolver (often dnsmasq in Linux) and that resolver cannot get an answer to inquiries when no network is available. Causing delays. Probably from reverse IP lookups for logging. Anyways, use netstat to find out what process is listening on port 53, if any. Also, consider uninstalling any resolver you might have running, or reconfigure it to not try to ask the internet for name resolution.
1 Like
When servers don’t have Internet access, commented out all references to name servers in /etc/resolv.conf. This solved the delay in starting up Ignition.
Thanks for all your help.