Ignition 8.0.16 - error Timer already cancelled in vision when logoff/login user

mazeyrat · June 26, 2020, 2:08pm

Ignition 8.0.14
@PGriffith
In Vision, when we disconnect the user and reconnect it, we have a lots of error, especially:

15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/softPhone/status': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/blink': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/nbDesktop': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/softPhoneIsRegistered': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/tokenENE': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/tokenREJ': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/tokenSIG': Timer already cancelled.

The vision client tag with these expression aren’t updated after the disconect/reconnect user

Here is the full client stack trace:

15:47:29.252 [AWT-EventQueue-0] INFO Common.BasicExecutionEngine - Execution engine 'ClientExecEngine' shut down in 0ms
15:47:29.252 [AWT-EventQueue-0] INFO com.inductiveautomation.ignition.client.gateway_interface.GatewayConnectionManager - Updated login state. Logged in? false, Username: null, Roles: null, Security Zones: null
gexcept null java.lang.IllegalStateException
	at com.inductiveautomation.factorypmi.application.runtime.ClientContextImpl.getScriptManager(ClientContextImpl.java:543)
	at com.inductiveautomation.factorypmi.application.VisionClientContextDelegateAdapter.getScriptManager(VisionClientContextDelegateAdapter.java:124)
	at com.inductiveautomation.ignition.common.expressions.functions.ScriptFunction.execute(ScriptFunction.java:74)
	at com.inductiveautomation.ignition.common.expressions.FunctionExpression.execute(FunctionExpression.java:69)
	at com.inductiveautomation.factorypmi.application.sqltags.project.ExpressionTagBinding.childInteractionUpdated(ExpressionTagBinding.java:44)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.actionPerformed(AbstractPollingFunction.java:109)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction$1.run(AbstractPollingFunction.java:62)
	at java.base/java.util.TimerThread.mainLoop(Unknown Source)
	at java.base/java.util.TimerThread.run(Unknown Source)


15:47:31.997 [ForkJoinPool.commonPool-worker-27] WARN Common.BasicExecutionEngine - Execution rejected... running in calling thread [ForkJoinPool.commonPool-worker-27] immediately. [com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher@5bac4051]
15:47:31.997 [ForkJoinPool.commonPool-worker-27] ERROR Tags.Scripting.ScriptDispatcher - ([client]_intern/hightlightEqtPath, valueChanged) Error executing tag event script: null
java.lang.IllegalStateException: null
	at com.inductiveautomation.factorypmi.application.runtime.ClientContextImpl.getScriptManager(ClientContextImpl.java:543)
	at com.inductiveautomation.factorypmi.application.VisionClientContextDelegateAdapter.getScriptManager(VisionClientContextDelegateAdapter.java:124)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$FunctionInvokerImpl.run(TagScriptManager.java:474)
	at com.inductiveautomation.ignition.common.sqltags.scripts.AbstractTagScript.invoke(AbstractTagScript.java:33)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$Task.invoke(TagScriptManager.java:442)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher.run(TagScriptManager.java:405)
	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine.executeOnce(BasicExecutionEngine.java:373)
	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine.executeOnce(BasicExecutionEngine.java:357)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher.maybeSchedule(TagScriptManager.java:394)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher.push(TagScriptManager.java:367)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher.invoke(TagScriptManager.java:326)
	at com.inductiveautomation.factorypmi.application.sqltags.AbstractClientTag.fireScriptEvent(AbstractClientTag.java:481)
	at com.inductiveautomation.factorypmi.application.sqltags.AbstractClientTag.setCurrentValue(AbstractClientTag.java:229)
	at com.inductiveautomation.factorypmi.application.sqltags.project.ProjectTag.setCurrentValue(ProjectTag.java:80)
	at com.inductiveautomation.factorypmi.application.sqltags.project.ProjectTagManager.write(ProjectTagManager.java:535)
	at com.inductiveautomation.ignition.client.sqltags.impl.SubManagerAdapter.lambda$writeAsync$1(SubManagerAdapter.java:166)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool.scan(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(Unknown Source)
15:47:34.387 [ClientPanel-LoginTask] INFO com.inductiveautomation.ignition.client.gateway_interface.GatewayConnectionManager - Skipping local challenge - directory doesn't exist.
15:47:34.387 [ClientPanel-LoginTask] INFO com.inductiveautomation.ignition.client.gateway_interface.GatewayConnectionManager - Updated login state. Logged in? true, Username: admin, Roles: [Administrator, BIL_cmd, BIL_param, ENE_cmd, ENE_param, GTC_ack_alarme, GTC_courbe, GTC_debug, GTC_param_role, GTC_visu, SAE_param, SIG_cmd, SIG_param, SIG_rejeu, SON_cmd, SON_param, STA_cmd, STA_param, SYS_cmd, SYS_param, TEL_cmd, TEL_param, VID_cmd, VID_param], Security Zones: null
Successfully read project CSTVG_GTC.proj from cache.
Cache file CSTVG_GTC.proj loaded sucessfully from cache, downloading diff...
15:47:34.856 [ProjectDownloader] INFO Vision.DownloadProjectPane - Starting download of 478 bytes
15:47:34.871 [ProjectDownloader] INFO tags.manager.gwinterface - Tag poll rate changed to 250 ms
15:47:34.871 [ClientExecEngine-1] INFO tags.subscriptions - Changing connected quality to 'Good'
15:47:35.340 [ProjectDownloader] ERROR Scripting.ScriptManager.STVG_GTC - Warning: collision at system.util.modifyTranslation
15:47:35.340 [ProjectDownloader] ERROR Scripting.ScriptManager.STVG_GTC - Warning: collision at system.util.translate
15:47:35.340 [ProjectDownloader] ERROR Scripting.ScriptManager.STVG_GTC - Warning: collision at system.util.initialize
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/softPhone/status': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/blink': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/nbDesktop': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/softPhoneIsRegistered': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/tokenENE': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/tokenREJ': Timer already cancelled.
15:47:35.434 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/tokenSIG': Timer already cancelled.
15:47:35.465 [AWT-EventQueue-0] INFO vision.App - Starting Up...
15:47:35.934 [AWT-EventQueue-0] INFO Localization.ClientLocalizationManager - Setting current locale to 'fr'
15:47:36.481 [AWT-EventQueue-0] WARN Vision.Binding.ExpressionPropertyAdapter - Error executing expression binding on
BandeauHaut.Root Container.TemNotification.isPopupOpen
java.lang.Exception: Error executing expression binding on
BandeauHaut.Root Container.TemNotification.isPopupOpen
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.runExpression(ExpressionPropertyAdapter.java:92)
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.startup(ExpressionPropertyAdapter.java:113)
	at com.inductiveautomation.factorypmi.application.binding.DefaultInteractionController.startupBindings(DefaultInteractionController.java:355)
	at com.inductiveautomation.factorypmi.application.binding.DefaultInteractionController.startupAdapters(DefaultInteractionController.java:360)
	at com.inductiveautomation.factorypmi.application.FPMIWindow.startup(FPMIWindow.java:344)
	at com.inductiveautomation.factorypmi.application.VisionDesktop$RuntimeWindowOpener.openWindow(VisionDesktop.java:549)
	at com.inductiveautomation.factorypmi.application.VisionDesktop.openWindow(VisionDesktop.java:188)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.lambda$openWindowImpl$5(NavUtilities.java:393)
	at com.inductiveautomation.factorypmi.application.script.builtin.WindowUtilities.doGUIAction(WindowUtilities.java:808)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.openWindowImpl(NavUtilities.java:336)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.openWindow(NavUtilities.java:326)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilitiesDispatcher.openWindow(NavUtilitiesDispatcher.java:143)
	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.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:188)
	at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:524)
	at org.python.core.PyObject.__call__(PyObject.java:480)
	at org.python.core.PyObject.__call__(PyObject.java:484)
	at org.python.pycode._pyx144.initPrimaryMonitor$4(<module:project.nav.windows>:132)
	at org.python.pycode._pyx144.call_function(<module:project.nav.windows>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx152.run$1(<module:project.clientevents.startup>:115)
	at org.python.pycode._pyx152.call_function(<module:project.clientevents.startup>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx146.f$0(<startup script>:3)
	at org.python.pycode._pyx146.call_function(<startup script>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyCode.call(PyCode.java:18)
	at org.python.core.Py.runCode(Py.java:1614)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:782)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:753)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:715)
	at com.inductiveautomation.factorypmi.application.FPMIApp.startup(FPMIApp.java:490)
	at com.inductiveautomation.factorypmi.application.runtime.ClientPanel.lambda$startupApp$7(ClientPanel.java:698)
	at java.desktop/java.awt.event.InvocationEvent.dispatch(Unknown Source)
	at java.desktop/java.awt.EventQueue.dispatchEventImpl(Unknown Source)
	at java.desktop/java.awt.EventQueue$4.run(Unknown Source)
	at java.desktop/java.awt.EventQueue$4.run(Unknown Source)
	at java.base/java.security.AccessController.doPrivileged(Native Method)
	at java.base/java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source)
	at java.desktop/java.awt.EventQueue.dispatchEvent(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEvents(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEvents(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.run(Unknown Source)
Caused by: java.lang.IllegalStateException: Timer already cancelled.
	at java.base/java.util.Timer.sched(Unknown Source)
	at java.base/java.util.Timer.schedule(Unknown Source)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.startTask(AbstractPollingFunction.java:65)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.setPollRate(AbstractPollingFunction.java:95)
	at com.inductiveautomation.ignition.common.expressions.functions.ScriptFunction.execute(ScriptFunction.java:72)
	at com.inductiveautomation.ignition.common.expressions.FunctionExpression.execute(FunctionExpression.java:69)
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.runExpression(ExpressionPropertyAdapter.java:83)
	... 52 common frames omitted
15:47:36.481 [AWT-EventQueue-0] WARN Vision.Binding.ExpressionPropertyAdapter - Error executing expression binding on
BandeauHaut.Root Container.TemVideo.isPopupVisible
java.lang.Exception: Error executing expression binding on
BandeauHaut.Root Container.TemVideo.isPopupVisible
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.runExpression(ExpressionPropertyAdapter.java:92)
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.startup(ExpressionPropertyAdapter.java:113)
	at com.inductiveautomation.factorypmi.application.binding.DefaultInteractionController.startupBindings(DefaultInteractionController.java:355)
	at com.inductiveautomation.factorypmi.application.binding.DefaultInteractionController.startupAdapters(DefaultInteractionController.java:360)
	at com.inductiveautomation.factorypmi.application.FPMIWindow.startup(FPMIWindow.java:344)
	at com.inductiveautomation.factorypmi.application.VisionDesktop$RuntimeWindowOpener.openWindow(VisionDesktop.java:549)
	at com.inductiveautomation.factorypmi.application.VisionDesktop.openWindow(VisionDesktop.java:188)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.lambda$openWindowImpl$5(NavUtilities.java:393)
	at com.inductiveautomation.factorypmi.application.script.builtin.WindowUtilities.doGUIAction(WindowUtilities.java:808)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.openWindowImpl(NavUtilities.java:336)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.openWindow(NavUtilities.java:326)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilitiesDispatcher.openWindow(NavUtilitiesDispatcher.java:143)
	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.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:188)
	at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:524)
	at org.python.core.PyObject.__call__(PyObject.java:480)
	at org.python.core.PyObject.__call__(PyObject.java:484)
	at org.python.pycode._pyx144.initPrimaryMonitor$4(<module:project.nav.windows>:132)
	at org.python.pycode._pyx144.call_function(<module:project.nav.windows>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx152.run$1(<module:project.clientevents.startup>:115)
	at org.python.pycode._pyx152.call_function(<module:project.clientevents.startup>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx146.f$0(<startup script>:3)
	at org.python.pycode._pyx146.call_function(<startup script>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyCode.call(PyCode.java:18)
	at org.python.core.Py.runCode(Py.java:1614)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:782)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:753)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:715)
	at com.inductiveautomation.factorypmi.application.FPMIApp.startup(FPMIApp.java:490)
	at com.inductiveautomation.factorypmi.application.runtime.ClientPanel.lambda$startupApp$7(ClientPanel.java:698)
	at java.desktop/java.awt.event.InvocationEvent.dispatch(Unknown Source)
	at java.desktop/java.awt.EventQueue.dispatchEventImpl(Unknown Source)
	at java.desktop/java.awt.EventQueue$4.run(Unknown Source)
	at java.desktop/java.awt.EventQueue$4.run(Unknown Source)
	at java.base/java.security.AccessController.doPrivileged(Native Method)
	at java.base/java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source)
	at java.desktop/java.awt.EventQueue.dispatchEvent(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEvents(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEvents(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.run(Unknown Source)
Caused by: java.lang.IllegalStateException: Timer already cancelled.
	at java.base/java.util.Timer.sched(Unknown Source)
	at java.base/java.util.Timer.schedule(Unknown Source)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.startTask(AbstractPollingFunction.java:65)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.setPollRate(AbstractPollingFunction.java:95)
	at com.inductiveautomation.ignition.common.expressions.functions.ScriptFunction.execute(ScriptFunction.java:72)
	at com.inductiveautomation.ignition.common.expressions.FunctionExpression.execute(FunctionExpression.java:69)
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.runExpression(ExpressionPropertyAdapter.java:83)
	... 52 common frames omitted
15:47:36.496 [AWT-EventQueue-0] WARN Vision.Binding.ExpressionPropertyAdapter - Error executing expression binding on
BandeauHaut.Root Container.isBuzzerPlaying
java.lang.Exception: Error executing expression binding on
BandeauHaut.Root Container.isBuzzerPlaying
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.runExpression(ExpressionPropertyAdapter.java:92)
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.startup(ExpressionPropertyAdapter.java:113)
	at com.inductiveautomation.factorypmi.application.binding.DefaultInteractionController.startupBindings(DefaultInteractionController.java:355)
	at com.inductiveautomation.factorypmi.application.binding.DefaultInteractionController.startupAdapters(DefaultInteractionController.java:360)
	at com.inductiveautomation.factorypmi.application.FPMIWindow.startup(FPMIWindow.java:344)
	at com.inductiveautomation.factorypmi.application.VisionDesktop$RuntimeWindowOpener.openWindow(VisionDesktop.java:549)
	at com.inductiveautomation.factorypmi.application.VisionDesktop.openWindow(VisionDesktop.java:188)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.lambda$openWindowImpl$5(NavUtilities.java:393)
	at com.inductiveautomation.factorypmi.application.script.builtin.WindowUtilities.doGUIAction(WindowUtilities.java:808)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.openWindowImpl(NavUtilities.java:336)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.openWindow(NavUtilities.java:326)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilitiesDispatcher.openWindow(NavUtilitiesDispatcher.java:143)
	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.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:188)
	at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:524)
	at org.python.core.PyObject.__call__(PyObject.java:480)
	at org.python.core.PyObject.__call__(PyObject.java:484)
	at org.python.pycode._pyx144.initPrimaryMonitor$4(<module:project.nav.windows>:132)
	at org.python.pycode._pyx144.call_function(<module:project.nav.windows>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx152.run$1(<module:project.clientevents.startup>:115)
	at org.python.pycode._pyx152.call_function(<module:project.clientevents.startup>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx146.f$0(<startup script>:3)
	at org.python.pycode._pyx146.call_function(<startup script>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyCode.call(PyCode.java:18)
	at org.python.core.Py.runCode(Py.java:1614)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:782)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:753)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:715)
	at com.inductiveautomation.factorypmi.application.FPMIApp.startup(FPMIApp.java:490)
	at com.inductiveautomation.factorypmi.application.runtime.ClientPanel.lambda$startupApp$7(ClientPanel.java:698)
	at java.desktop/java.awt.event.InvocationEvent.dispatch(Unknown Source)
	at java.desktop/java.awt.EventQueue.dispatchEventImpl(Unknown Source)
	at java.desktop/java.awt.EventQueue$4.run(Unknown Source)
	at java.desktop/java.awt.EventQueue$4.run(Unknown Source)
	at java.base/java.security.AccessController.doPrivileged(Native Method)
	at java.base/java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source)
	at java.desktop/java.awt.EventQueue.dispatchEvent(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEvents(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEvents(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.run(Unknown Source)
Caused by: java.lang.IllegalStateException: Timer already cancelled.
	at java.base/java.util.Timer.sched(Unknown Source)
	at java.base/java.util.Timer.schedule(Unknown Source)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.startTask(AbstractPollingFunction.java:65)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.setPollRate(AbstractPollingFunction.java:95)
	at com.inductiveautomation.ignition.common.expressions.functions.ScriptFunction.execute(ScriptFunction.java:72)
	at com.inductiveautomation.ignition.common.expressions.FunctionExpression.execute(FunctionExpression.java:69)
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.runExpression(ExpressionPropertyAdapter.java:83)
	... 52 common frames omitted
15:47:36.903 [AWT-EventQueue-0] WARN Vision.Binding.ExpressionPropertyAdapter - Error executing expression binding on
BandeauGauche.Root Container.nbScreen
java.lang.Exception: Error executing expression binding on
BandeauGauche.Root Container.nbScreen
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.runExpression(ExpressionPropertyAdapter.java:92)
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.startup(ExpressionPropertyAdapter.java:113)
	at com.inductiveautomation.factorypmi.application.binding.DefaultInteractionController.startupBindings(DefaultInteractionController.java:355)
	at com.inductiveautomation.factorypmi.application.binding.DefaultInteractionController.startupAdapters(DefaultInteractionController.java:360)
	at com.inductiveautomation.factorypmi.application.FPMIWindow.startup(FPMIWindow.java:344)
	at com.inductiveautomation.factorypmi.application.VisionDesktop$RuntimeWindowOpener.openWindow(VisionDesktop.java:549)
	at com.inductiveautomation.factorypmi.application.VisionDesktop.openWindow(VisionDesktop.java:188)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.lambda$openWindowImpl$5(NavUtilities.java:393)
	at com.inductiveautomation.factorypmi.application.script.builtin.WindowUtilities.doGUIAction(WindowUtilities.java:808)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.openWindowImpl(NavUtilities.java:336)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilities.openWindow(NavUtilities.java:326)
	at com.inductiveautomation.factorypmi.application.script.builtin.NavUtilitiesDispatcher.openWindow(NavUtilitiesDispatcher.java:143)
	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.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:188)
	at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:524)
	at org.python.core.PyObject.__call__(PyObject.java:480)
	at org.python.core.PyObject.__call__(PyObject.java:484)
	at org.python.pycode._pyx144.initPrimaryMonitor$4(<module:project.nav.windows>:132)
	at org.python.pycode._pyx144.call_function(<module:project.nav.windows>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx152.run$1(<module:project.clientevents.startup>:115)
	at org.python.pycode._pyx152.call_function(<module:project.clientevents.startup>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx146.f$0(<startup script>:3)
	at org.python.pycode._pyx146.call_function(<startup script>)
	at org.python.core.PyTableCode.call(PyTableCode.java:171)
	at org.python.core.PyCode.call(PyCode.java:18)
	at org.python.core.Py.runCode(Py.java:1614)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:782)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:753)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:715)
	at com.inductiveautomation.factorypmi.application.FPMIApp.startup(FPMIApp.java:490)
	at com.inductiveautomation.factorypmi.application.runtime.ClientPanel.lambda$startupApp$7(ClientPanel.java:698)
	at java.desktop/java.awt.event.InvocationEvent.dispatch(Unknown Source)
	at java.desktop/java.awt.EventQueue.dispatchEventImpl(Unknown Source)
	at java.desktop/java.awt.EventQueue$4.run(Unknown Source)
	at java.desktop/java.awt.EventQueue$4.run(Unknown Source)
	at java.base/java.security.AccessController.doPrivileged(Native Method)
	at java.base/java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source)
	at java.desktop/java.awt.EventQueue.dispatchEvent(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEvents(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.pumpEvents(Unknown Source)
	at java.desktop/java.awt.EventDispatchThread.run(Unknown Source)
Caused by: java.lang.IllegalStateException: Timer already cancelled.
	at java.base/java.util.Timer.sched(Unknown Source)
	at java.base/java.util.Timer.schedule(Unknown Source)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.startTask(AbstractPollingFunction.java:65)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.setPollRate(AbstractPollingFunction.java:95)
	at com.inductiveautomation.ignition.common.expressions.functions.ScriptFunction.execute(ScriptFunction.java:72)
	at com.inductiveautomation.ignition.common.expressions.FunctionExpression.execute(FunctionExpression.java:69)
	at com.inductiveautomation.factorypmi.application.binding.ExpressionPropertyAdapter.runExpression(ExpressionPropertyAdapter.java:83)
	... 52 common frames omitted

PGriffith · June 26, 2020, 2:27pm

Are you in contact with support on this? This might require a backup/live view of your system.

mazeyrat · June 26, 2020, 2:41pm

no, I hoped that the stack trace was enough…
I can provide a gateway backup if necessary or call the support

PGriffith · June 26, 2020, 2:46pm

The stack tells me what’s wrong, but not how to get into that state. The AbstractPollingFunction code that’s the source of the IllegalStateException hasn’t changed at all since 2018, so it seems unlikely it’s a new regression. If nothing else, support getting a .gwbk should be good so the defect analysts can try to replicate.

alexraymond · July 23, 2020, 10:52pm

I’ve been having this same problem for quite a while. Any expression with runScript function stops working after changing user. Has the issue been identified?

pturmel · July 24, 2020, 12:03pm

The chain in the earlier backtrace suggests that the code in the runScript tried to open a window, and that window open attempt threw an exception in window startup. That exception propagated back into the runScript expression, which stops tag evaluation.

Anything you call with runScript had better catch all exceptions.

alexraymond · July 24, 2020, 10:06pm

That makes sense, but I have had exceptions in my functions called by runScript before and the expression never stopped functioning. In fact, I’d get a new error every time it executed on the timer. So certain errors cause the expression to stop functioning? It’s hard to know what is causing the error when the only thing in the log is that the timer was cancelled.

mazeyrat · September 24, 2020, 4:04pm

I have still this issue with Ignition 8.0.16
In the vision client, each time the user is log out with:

system.security.logout()

and then I log in the same user,
all vision client tag with expression doesn’t work anymore !

17:39:58.496 [AWT-EventQueue-0] INFO vision.App - Shutting Down...
17:39:58.727 [AWT-EventQueue-0] INFO com.bouyguesenergiesservices.ignition.client.macrocommand.ClientHook - shutdown() - com.bouyguesenergiesservices.macrocommand
17:39:58.728 [AWT-EventQueue-0] INFO com.bouyguesenergiesservices.ignition.client.snmp.ClientHook - shutdown() - com.bouyguesenergiesservices.snmppingdriver
17:39:58.729 [AWT-EventQueue-0] INFO com.bouyguesenergiesservices.ignition.client.audit.ClientHook - shutdown() - com.bouyguesenergiesservices.audit
17:39:58.729 [AWT-EventQueue-0] INFO com.bouyguesenergiesservices.ignition.client.utils.ClientHook - shutdown() - com.bouyguesenergiesservices.utils
17:39:58.730 [AWT-EventQueue-0] INFO Common.BasicExecutionEngine - Execution engine 'ExecEngine-1' shut down in 0ms
17:39:58.731 [AWT-EventQueue-0] WARN Common.BasicExecutionEngine - Tried to unregister non existent unit [client-tag-subscription validation].
17:39:58.732 [AWT-EventQueue-0] INFO Common.BasicExecutionEngine - Execution engine 'ClientExecEngine' shut down in 0ms
17:39:58.736 [AWT-EventQueue-0] INFO com.inductiveautomation.ignition.client.gateway_interface.GatewayConnectionManager - Updated login state. Logged in? false, Username: null, Roles: null, Security Zones: null
17:39:58.828 [ForkJoinPool.commonPool-worker-5] WARN Common.BasicExecutionEngine - Execution rejected... running in calling thread [ForkJoinPool.commonPool-worker-5] immediately. [com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher@41259c49]
17:39:58.831 [ForkJoinPool.commonPool-worker-5] ERROR Tags.Scripting.ScriptDispatcher - ([client]_intern/hightlightEqtPath, valueChanged) Error executing tag event script: null
java.lang.IllegalStateException: null
	at com.inductiveautomation.factorypmi.application.runtime.ClientContextImpl.getScriptManager(ClientContextImpl.java:545)
	at com.inductiveautomation.factorypmi.application.VisionClientContextDelegateAdapter.getScriptManager(VisionClientContextDelegateAdapter.java:124)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$FunctionInvokerImpl.run(TagScriptManager.java:474)
	at com.inductiveautomation.ignition.common.sqltags.scripts.AbstractTagScript.invoke(AbstractTagScript.java:33)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$Task.invoke(TagScriptManager.java:442)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher.run(TagScriptManager.java:405)
	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine.executeOnce(BasicExecutionEngine.java:373)
	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine.executeOnce(BasicExecutionEngine.java:357)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher.maybeSchedule(TagScriptManager.java:394)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher.push(TagScriptManager.java:367)
	at com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher.invoke(TagScriptManager.java:326)
	at com.inductiveautomation.factorypmi.application.sqltags.AbstractClientTag.fireScriptEvent(AbstractClientTag.java:481)
	at com.inductiveautomation.factorypmi.application.sqltags.AbstractClientTag.setCurrentValue(AbstractClientTag.java:229)
	at com.inductiveautomation.factorypmi.application.sqltags.project.ProjectTag.setCurrentValue(ProjectTag.java:80)
	at com.inductiveautomation.factorypmi.application.sqltags.project.ProjectTagManager.write(ProjectTagManager.java:535)
	at com.inductiveautomation.ignition.client.sqltags.impl.SubManagerAdapter.lambda$writeAsync$1(SubManagerAdapter.java:166)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool.scan(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(Unknown Source)
Exception in thread "client-expr-pollingfunc-timer" java.lang.IllegalStateException
	at com.inductiveautomation.factorypmi.application.runtime.ClientContextImpl.getScriptManager(ClientContextImpl.java:545)
	at com.inductiveautomation.factorypmi.application.VisionClientContextDelegateAdapter.getScriptManager(VisionClientContextDelegateAdapter.java:124)
	at com.inductiveautomation.ignition.common.expressions.functions.ScriptFunction.execute(ScriptFunction.java:74)
	at com.inductiveautomation.ignition.common.expressions.FunctionExpression.execute(FunctionExpression.java:69)
	at com.inductiveautomation.factorypmi.application.sqltags.project.ExpressionTagBinding.childInteractionUpdated(ExpressionTagBinding.java:44)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction.actionPerformed(AbstractPollingFunction.java:109)
	at com.inductiveautomation.ignition.common.expressions.functions.AbstractPollingFunction$1.run(AbstractPollingFunction.java:62)
	at java.base/java.util.TimerThread.mainLoop(Unknown Source)
	at java.base/java.util.TimerThread.run(Unknown Source)
17:40:02.751 [ClientPanel-LoginTask] INFO com.inductiveautomation.ignition.client.gateway_interface.GatewayConnectionManager - Updated login state. Logged in? true, Username: admin, Roles: [Administrator, ENE_cmd, ENE_param, GTC_ack_alarme, GTC_courbe, GTC_debug, GTC_param_role, GTC_visu, SON_cmd, SON_param, STA_cmd, STA_param, SYS_cmd, SYS_param, TEL_param, VID_param], Security Zones: null
Successfully read project CTDLM_GTC.proj from cache.
Cache file CTDLM_GTC.proj loaded sucessfully from cache, downloading diff...
17:40:03.046 [ProjectDownloader] INFO Vision.DownloadProjectPane - Starting download of 478 bytes
17:40:03.053 [ProjectDownloader] INFO tags.manager.gwinterface - Tag poll rate changed to 250 ms
17:40:03.053 [ClientExecEngine-2] INFO tags.subscriptions - Changing connected quality to 'Good'
17:40:03.703 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.macrocommand.ClientHook - startup() - com.bouyguesenergiesservices.macrocommand
17:40:03.704 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.macrocommand.ClientHook - License is Activated - com.bouyguesenergiesservices.macrocommand
17:40:03.704 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.snmp.ClientHook - startup() - com.bouyguesenergiesservices.snmppingdriver
17:40:03.704 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.snmp.ClientHook - License is Activated - com.bouyguesenergiesservices.snmppingdriver
17:40:03.704 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.audit.ClientHook - startup() - com.bouyguesenergiesservices.audit
17:40:03.704 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.audit.ClientHook - License is Activated - com.bouyguesenergiesservices.audit
17:40:03.705 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.utils.ClientHook - startup() - com.bouyguesenergiesservices.utils
17:40:03.705 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.utils.ClientHook - License is Activated - com.bouyguesenergiesservices.utils
17:40:03.705 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.macrocommand.ClientHook - initializeScriptManager() - com.bouyguesenergiesservices.macrocommand
17:40:03.708 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.audit.ClientHook - initializeScriptManager() - com.bouyguesenergiesservices.audit
17:40:03.711 [ProjectDownloader] INFO com.bouyguesenergiesservices.ignition.client.utils.ClientHook - initializeScriptManager() - com.bouyguesenergiesservices.utils
17:40:03.721 [ProjectDownloader] WARN Common.BundleUtil - java.util.MissingResourceException: Can't find bundle for base name com/bouyguesenergiesservices/ignition/common/utils/AbstractCache, locale fr
17:40:03.732 [ProjectDownloader] ERROR Scripting.ScriptManager.TDLM_GTC - Warning: collision at system.util.modifyTranslation
17:40:03.733 [ProjectDownloader] ERROR Scripting.ScriptManager.TDLM_GTC - Warning: collision at system.util.translate
17:40:03.733 [ProjectDownloader] ERROR Scripting.ScriptManager.TDLM_GTC - Warning: collision at system.util.initialize
17:40:04.180 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/blink': Timer already cancelled.
17:40:04.186 [ProjectDownloader] WARN Vision.ClientTag - Error creating tag binding for client tag '[client]_intern/nbDesktop': Timer already cancelled.
17:40:04.205 [AWT-EventQueue-0] INFO vision.App - Starting Up...
17:40:04.502 [AWT-EventQueue-0] INFO Localization.ClientLocalizationManager - Setting current locale to 'fr'

The first client tag with error is:

[client]_intern/hightlightEqtPath

This client tag has the following expression:
getSecond(now(500))%2

17:39:58.828 [ForkJoinPool.commonPool-worker-5] WARN Common.BasicExecutionEngine - Execution rejected... running in calling thread [ForkJoinPool.commonPool-worker-5] immediately. [com.inductiveautomation.ignition.common.sqltags.scripts.TagScriptManager$TagScriptDispatcher@41259c49]
17:39:58.831 [ForkJoinPool.commonPool-worker-5] ERROR Tags.Scripting.ScriptDispatcher - ([client]_intern/hightlightEqtPath, valueChanged) Error executing tag event script: null
java.lang.IllegalStateException: null

Exception in thread "client-expr-pollingfunc-timer" java.lang.IllegalStateException
Timer already cancelled.

mazeyrat · September 25, 2020, 10:16am

In fact in VISION 8.0.16 after the log out / log in:

all client tags with expression
all vision property binding with expression

trigger the following message: Timer already cancelled
and doesn’t execute anymore !

Ticket #130996