[Bug-12976]Build 8.0.0-beta0 (b2019030402):Error uninstalling, installing or restarting custom module

Ignition Early Access
1

Hi,

In Ignition 8 when uninstalling, installing or restarting a signed custom module we receive the following error: Cannot call startup when state=STOPPED. See log for details.

Module has being upgraded from 7.9… Any advise would be highly appreciated. Thanks in advance.

For reference purposes adding here stack trace when restarting module

INFO   | jvm 2    | 2019/03/04 15:00:19 | I [g.ModuleManager               ] [21:00:19]: Restarting module "com.ipg-la.BACKSTAFF" 
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [g.ModuleManager               ] [21:00:19]: Shutting down module 'com.ipg-la.BACKSTAFF' v4.7.0 (b20190108)... module-name=BACKSTAFF
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [c.i.s.g.h.IPGGatewayHook      ] [21:00:19]: IPGGatewayHook - shutdown: BACKSTAFF module stopped. module-name=BACKSTAFF
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [g.ModuleManager               ] [21:00:19]: Shutdown of module "com.ipg-la.BACKSTAFF" completed in 1 ms module-name=BACKSTAFF
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [g.ModuleManager               ] [21:00:19]: Starting up module 'com.ipg-la.BACKSTAFF' (v4.7.0 (b20190108))... 
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [c.i.s.g.h.IPGGatewayHook      ] [21:00:19]: IPGGatewayHook: Entering BACKSTAFF module setup. 
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [c.i.s.g.d.ContextManager      ] [21:00:19]: ContextManager instance created 
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [c.i.s.g.h.IPGGatewayHook      ] [21:00:19]: IPGGatewayHook: Exiting BACKSTAFF module setup. 
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [g.ModuleManager               ] [21:00:19]: Starting up module 'com.ipg-la.BACKSTAFF' v4.7.0 (b20190108)... module-name=BACKSTAFF
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [c.i.s.g.h.IPGGatewayHook      ] [21:00:19]: IPGGatewayHook: Entering BACKSTAFF module startup. module-name=BACKSTAFF
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [c.i.s.g.h.IPGGatewayHook      ] [21:00:19]: IPGGatewayHook - startup: BACKSTAFF interval set every 15000 milliseconds module-name=BACKSTAFF
INFO   | jvm 2    | 2019/03/04 15:00:19 | I [c.i.s.g.h.IPGGatewayHook      ] [21:00:19]: IPGGatewayHook - startup: BACKSTAFF module started. module-name=BACKSTAFF
INFO   | jvm 2    | 2019/03/04 15:00:20 | I [c.i.s.g.a.IPGModuleAPIImpl    ] [21:00:20]: IPGModuleAPIImpl - Gateway instance created request-origin=192.168.111.86, session-user=admin, session-project=BACKSTAFF, session-id=C433BE74
INFO   | jvm 2    | 2019/03/04 15:00:20 | I [c.i.s.g.h.IPGGatewayHook      ] [21:00:20]: IPGGatewayHook: adding BACKSTAFF to ScriptManager in Gateway Hook 
INFO   | jvm 2    | 2019/03/04 15:00:20 | I [c.i.s.g.h.IPGGatewayHook      ] [21:00:20]: IPGGatewayHook: BACKSTAFF added to ScriptManager in Gateway Hook 
INFO   | jvm 2    | 2019/03/04 15:00:20 | E [c.i.i.g.w.c.ConfirmationPanel$1] [21:00:20]: java.lang.IllegalStateException: Cannot call startup when state=STOPPED 
INFO   | jvm 2    | 2019/03/04 15:00:20 | java.lang.IllegalStateException: Cannot call startup when state=STOPPED
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at com.inductiveautomation.ignition.common.lifecycle.AbstractLifecycle.startup(AbstractLifecycle.java:20)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at com.inductiveautomation.ignition.gateway.project.IgnitionProjectManager.restartScripting(IgnitionProjectManager.java:125)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl.executeModuleOperation(ModuleManagerImpl.java:936)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl.restartModuleInternal(ModuleManagerImpl.java:834)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl.restartModule(ModuleManagerImpl.java:826)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at com.inductiveautomation.ignition.gateway.web.pages.config.ModulePage$RestartAction.execute(ModulePage.java:563)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at com.inductiveautomation.ignition.gateway.web.components.ConfirmationPanel$1.onClick(ConfirmationPanel.java:50)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.markup.html.link.Link.onLinkClicked(Link.java:189)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.RequestListenerInterface.internalInvoke(RequestListenerInterface.java:258)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.RequestListenerInterface.invoke(RequestListenerInterface.java:216)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.invokeListener(ListenerInterfaceRequestHandler.java:240)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.respond(ListenerInterfaceRequestHandler.java:226)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.request.cycle.RequestCycle$HandlerExecutor.respond(RequestCycle.java:814)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.request.RequestHandlerStack.execute(RequestHandlerStack.java:64)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.request.cycle.RequestCycle.execute(RequestCycle.java:253)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.request.cycle.RequestCycle.processRequest(RequestCycle.java:210)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.request.cycle.RequestCycle.processRequestAndDetach(RequestCycle.java:281)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.protocol.http.WicketFilter.processRequest(WicketFilter.java:188)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.apache.wicket.protocol.http.WicketFilter.doFilter(WicketFilter.java:245)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at com.inductiveautomation.ignition.gateway.bootstrap.GatewayFilter.doFilter(GatewayFilter.java:74)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1629)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:335)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:61)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.Server.handle(Server.java:530)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)
INFO   | jvm 2    | 2019/03/04 15:00:20 | 	at java.base/java.lang.Thread.run(Unknown Source)
2

Looks like a bug on our side with the new project script lifecycle maintenance. I’ll file a report for it.

1 Like
3

Hi all,

I ran into an issue where my tags stopped receiving data, effectively making all of the data stale. I tried restarting the OPA UA module, and it resulted in this error. It also popped up on the modules page, but it strangely still shows the module as “running”.

My next step is to restart the service and see if that brings the tags back, but i’m not sure why this crashed. Ideas?

java.lang.IllegalStateException: Cannot call startup when state=STOPPED

at com.inductiveautomation.ignition.common.lifecycle.AbstractLifecycle.startup(AbstractLifecycle.java:20)

at com.inductiveautomation.ignition.gateway.project.IgnitionProjectManager.restartScripting(IgnitionProjectManager.java:125)

at com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl.executeModuleOperation(ModuleManagerImpl.java:899)

at com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl.restartModuleInternal(ModuleManagerImpl.java:797)

at com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl.restartModule(ModuleManagerImpl.java:789)

at com.inductiveautomation.ignition.gateway.web.pages.config.ModulePage$RestartAction.execute(ModulePage.java:563)

at com.inductiveautomation.ignition.gateway.web.components.ConfirmationPanel$1.onClick(ConfirmationPanel.java:50)

at org.apache.wicket.markup.html.link.Link.onLinkClicked(Link.java:189)

at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.base/java.lang.reflect.Method.invoke(Unknown Source)

at org.apache.wicket.RequestListenerInterface.internalInvoke(RequestListenerInterface.java:258)

at org.apache.wicket.RequestListenerInterface.invoke(RequestListenerInterface.java:216)

at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.invokeListener(ListenerInterfaceRequestHandler.java:240)

at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.respond(ListenerInterfaceRequestHandler.java:226)

at org.apache.wicket.request.cycle.RequestCycle$HandlerExecutor.respond(RequestCycle.java:814)

at org.apache.wicket.request.RequestHandlerStack.execute(RequestHandlerStack.java:64)

at org.apache.wicket.request.cycle.RequestCycle.execute(RequestCycle.java:253)

at org.apache.wicket.request.cycle.RequestCycle.processRequest(RequestCycle.java:210)

at org.apache.wicket.request.cycle.RequestCycle.processRequestAndDetach(RequestCycle.java:281)

at org.apache.wicket.protocol.http.WicketFilter.processRequest(WicketFilter.java:188)

at org.apache.wicket.protocol.http.WicketFilter.doFilter(WicketFilter.java:245)

at com.inductiveautomation.ignition.gateway.bootstrap.GatewayFilter.doFilter(GatewayFilter.java:74)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1629)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:335)

at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:61)

at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.server.Server.handle(Server.java:530)

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256)

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)

at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)

at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)

at java.base/java.lang.Thread.run(Unknown Source)

Thread dump attached here. thread_dump.zip (9.0 KB)

Wrapper log here.wrapper.zip (162.5 KB)

For reference, we have the usual Ignition OPA-UA Server connection, and a Kepware EX Server 6 connection as well. Both of those seem to be fine though, so not sure where this is coming from.

Cheers,
Roger

4

@roger_larson yep, an issue on our side - same as the parent comment in this thread. Thanks for the report!

6

Good to know, and no problem.

Just as a heads up, restarting the service fixes the problem, at least until the problem reoccurs via whatever the trigger is.

7

This issue was fixed in the build that was uploaded today (3/7).
Please let us know if you continue to see this behavior after upgrading.

1 Like
8

Many thanks. Just verified it.

3 Likes