Designer frozen until an rpc exception

r.lebohec · January 20, 2023, 9:33am

Taking an import of multiple instances in interactive or direct mode, the designer freezes until the following error appears:

Blockquotecom.inductiveautomation.ignition.client.gateway_interface.GatewayException: Results for asynchronous rpc call were not received within the specified amount of time [60000 ms] for task '21e196ae-20c3-4893-bc2b-d55bcfb864bb'
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.newGatewayException(GatewayInterface.java:351)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:321)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:278)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.invoke(GatewayInterface.java:954)
at com.inductiveautomation.ignition.client.tags.impl.GatewayTagInterface.creatorModify(GatewayTagInterface.java:233)
at com.inductiveautomation.ignition.client.tags.impl.ClientTagManagerImpl.creatorModify(ClientTagManagerImpl.java:431)
at com.inductiveautomation.ignition.designer.tags.creator.TagCreatorSession$modifyStaging$2.invokeSuspend(TagCreatorSession.kt:153)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:571)
at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:750)
at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:678)
at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:665)
Caused by: java.util.concurrent.TimeoutException: Results for asynchronous rpc call were not received within the specified amount of time [60000 ms] for task '21e196ae-20c3-4893-bc2b-d55bcfb864bb'
at com.inductiveautomation.ignition.client.util.gui.progress.ClientProgressManager$RunningTask.waitForResult(ClientProgressManager.java:453)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:305)
... 11 more

09:56:35.798 [Tags-TreeLoader-1] WARN com.inductiveautomation.ignition.client.gateway_interface.GatewayConnectionManager - Connection to Gateway lost, due to exception.
com.inductiveautomation.ignition.client.gateway_interface.GatewayException: Read timed out
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.newGatewayException(GatewayInterface.java:351)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.getResponse(GatewayInterface.java:543)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:283)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:278)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.invoke(GatewayInterface.java:954)
at com.inductiveautomation.ignition.client.tags.impl.GatewayTagInterface$GatewayProviderProxy.browseAsync(GatewayTagInterface.java:318)
at com.inductiveautomation.ignition.client.tags.impl.ClientTagManagerImpl.browseAsync(ClientTagManagerImpl.java:203)
at com.inductiveautomation.ignition.designer.tags.tree.node.TagProviderSource.browse$suspendImpl(TagFrameNodes.kt:231)
at com.inductiveautomation.ignition.designer.tags.tree.node.TagProviderSource.browse(TagFrameNodes.kt)
at com.inductiveautomation.ignition.designer.tags.tree.node.NoUdtTagSource.browse(TagFrameNodes.kt:209)
at com.inductiveautomation.ignition.designer.tags.tree.node.AbstractTagTreeNode$executeChildrenBrowse$1.invokeSuspend(TagFrameNodes.kt:286)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:274)
at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
at com.inductiveautomation.ignition.designer.tags.tree.node.AbstractTagTreeNode.executeChildrenBrowse(TagFrameNodes.kt:285)
at com.inductiveautomation.ignition.client.tags.tree.node.AbstractBrowseNode$Loader.doRun(AbstractBrowseNode.java:539)
at com.inductiveautomation.ignition.client.tags.tree.node.AbstractBrowseNode$Loader.run(AbstractBrowseNode.java:583)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.base/java.net.SocketInputStream.socketRead0(Native Method)
at java.base/java.net.SocketInputStream.socketRead(Unknown Source)
at java.base/java.net.SocketInputStream.read(Unknown Source)
at java.base/java.net.SocketInputStream.read(Unknown Source)
at java.base/java.io.BufferedInputStream.fill(Unknown Source)
at java.base/java.io.BufferedInputStream.read1(Unknown Source)
at java.base/java.io.BufferedInputStream.read(Unknown Source)
at java.base/sun.net.www.http.HttpClient.parseHTTPHeader(Unknown Source)
at java.base/sun.net.www.http.HttpClient.parseHTTP(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
at java.base/java.net.HttpURLConnection.getResponseCode(Unknown Source)
at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.getResponse(GatewayInterface.java:437)
... 25 common frames omitted

I think that the thread (designer / gateway) processing the task goes into timeout although it is carried out correctly on the gateway. Is there an adjustable parameter for this type of relatively long processing other than the memory allocated to the designer?

On the gateway side, timeout exceptions appear on expressions of imported tags using the 'tag()' function

INFO   | jvm 1    | 2023/01/20 10:04:36 | E [Scripting[system_util_tag]    ] [09:04:36]: Error during blocking read of tags through scripting. tag=COND_INHIB_ALARMES
INFO   | jvm 1    | 2023/01/20 10:04:36 | java.util.concurrent.TimeoutException: null
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.util.concurrent.CompletableFuture.timedGet(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.script.GatewayTagUtilities.readBlockingImpl(GatewayTagUtilities.java:232)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.script.builtin.AbstractTagUtilities.readBlocking(AbstractTagUtilities.java:484)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at jdk.internal.reflect.GeneratedMethodAccessor17.invoke(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:190)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:552)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.core.PyObject.__call__(PyObject.java:461)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.core.PyObject.__call__(PyObject.java:465)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.pycode._pyx1115.valueToDetail$2(<module:shared.tag.event>:163)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.pycode._pyx1115.call_function(<module:shared.tag.event>)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.core.PyTableCode.call(PyTableCode.java:173)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:306)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.core.PyFunction.function___call__(PyFunction.java:474)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.core.PyFunction.__call__(PyFunction.java:469)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at org.python.core.PyFunction.__call__(PyFunction.java:464)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:846)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:828)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$TrackingProjectScriptManager.runFunction(ProjectScriptLifecycle.java:832)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.expressions.functions.ScriptFunction.execute(ScriptFunction.java:79)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.expressions.FunctionExpression.execute(FunctionExpression.java:69)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.evaluation.BoundPropEvalPropertySet$BoundValue.evaluate(BoundPropEvalPropertySet.java:253)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.evaluation.BoundPropEvalPropertySet$BoundValue.evalAndGet(BoundPropEvalPropertySet.java:293)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.evaluation.BoundPropEvalPropertySet.getOrDefault(BoundPropEvalPropertySet.java:143)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.config.AbstractExtendedPropertySet.getImpl(AbstractExtendedPropertySet.java:56)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.config.AbstractExtendedPropertySet.getOrDefault(AbstractExtendedPropertySet.java:78)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.config.PropertyValueSource.getValues(PropertyValueSource.java:30)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.config.MutablePropertyValueSource.merge(MutablePropertyValueSource.java:16)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.config.BasicPropertySet.<init>(BasicPropertySet.java:47)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.common.config.BasicPropertySet.<init>(BasicPropertySet.java:42)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.evaluation.Alarm$AlarmPropertyModel.snapshotData(Alarm.java:1280)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.evaluation.Alarm.captureEventData(Alarm.java:806)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.evaluation.Alarm.finishTransitionEvent(Alarm.java:859)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.evaluation.Alarm.initTransitionEvent(Alarm.java:831)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.evaluation.Alarm.evaluate(Alarm.java:627)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.alarming.AlarmManagerImpl$AlarmEvaluatorImpl.evaluate(AlarmManagerImpl.java:707)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.tags.actors.factories.alarming.AlarmingActor.processValue(AlarmingActor.java:226)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.tags.runtime.nodes.ExecutableTag.processValueThroughObservers(ExecutableTag.java:464)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.tags.runtime.nodes.ExecutableTag.valueChanged(ExecutableTag.java:451)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.tags.actors.factories.value.AbstractValueGeneratingActor.fireValueChange(AbstractValueGeneratingActor.java:73)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.tags.actors.factories.value.AbstractValueGeneratingActor.fireValueChange(AbstractValueGeneratingActor.java:45)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at com.inductiveautomation.ignition.gateway.tags.actors.factories.value.AbstractExpressionActor.run(AbstractExpressionActor.java:160)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2023/01/20 10:04:36 | 	at java.base/java.lang.Thread.run(Unknown Source)

I think this is due to the fact that the instances being imported are dependent on each other at the level of certain expressions.

Any suggestions?

Thanks

pturmel · January 20, 2023, 12:42pm

Smaller import batches. That timeout is hardcoded and has been that way forever. Segregate the expression tags that use the tag() function. Import those last.

ggross · January 20, 2023, 4:00pm

As Phil mentioned, there isn't a good solution to this problem other than doing smaller imports. As you noted, because the task is happening on the Gateway itself, even though the browser times out, the tags will eventually finish importing. The problems with this are:

You Designer becomes unresponsive during the entire import process leaving you questioning what is going on. This is the primary reason there is a hard coded timeout.
You aren't provided with any errors that occurred during the import process
It will never be clear to you when this process completes other than by watching CPU and Memory use on the Gateway
It puts a lot of stress on the Gateway and will lead to blocked threads until the process completes

This is one of the things I want us to make better at some point, but right now smaller batches of imports is going to be your only option.

Garth

r.lebohec · January 23, 2023, 7:55am

Thanks @pturmel @ggross ,

I feared this answer but in the meantime it will be necessary to make a reason and make smaller imports.
Please let me know if there are any developments on the subject.