Locating script errors from Wrapper log

Ignition
1

Is there a way to pinpoint exactly what script and where from the wrapper log?

I have this logged:

Error during blocking read of tags through scripting. project-name=<PROJECTNAME>
java.util.concurrent.TimeoutException: null
at java.base/java.util.concurrent.CompletableFuture.timedGet(Unknown Source)
at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source)
at com.inductiveautomation.ignition.gateway.script.GatewayTagUtilities.readBlockingImpl(GatewayTagUtilities.java:190)
at com.inductiveautomation.ignition.common.script.builtin.AbstractTagUtilities.readBlocking(AbstractTagUtilities.java:401)
at jdk.internal.reflect.GeneratedMethodAccessor132.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:539)
at org.python.core.PyObject.__call__(PyObject.java:480)
at org.python.core.PyObject.__call__(PyObject.java:484)
at org.python.pycode._pyx59492.refresh$1(<custom-method refresh>:32)
at org.python.pycode._pyx59492.call_function(<custom-method refresh>)
at org.python.core.PyTableCode.call(PyTableCode.java:171)
at org.python.core.PyBaseCode.call(PyBaseCode.java:139)
at org.python.core.PyFunction.__call__(PyFunction.java:413)
at org.python.core.PyMethod.__call__(PyMethod.java:126)
at org.python.pycode._pyx59490.onMessageReceived$1(<function:onMessageReceived>:2)
at org.python.pycode._pyx59490.call_function(<function:onMessageReceived>)
at org.python.core.PyTableCode.call(PyTableCode.java:171)
at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
at org.python.core.PyFunction.function___call__(PyFunction.java:471)
at org.python.core.PyFunction.__call__(PyFunction.java:466)
at org.python.core.PyFunction.__call__(PyFunction.java:461)
at com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:842)
at com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:824)
at com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$TrackingProjectScriptManager.runFunction(ProjectScriptLifecycle.java:687)
at com.inductiveautomation.ignition.common.script.ScriptManager$ScriptFunctionImpl.invoke(ScriptManager.java:993)
at com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$AutoRecompilingScriptFunction.invoke(ProjectScriptLifecycle.java:752)
at com.inductiveautomation.perspective.gateway.script.ScriptFunctionHelper.invoke(ScriptFunctionHelper.java:133)
at com.inductiveautomation.perspective.gateway.model.MessageHandlerCollection$MessageHandlerImpl$1.lambda$invoke$0(MessageHandlerCollection.java:81)
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)

From this I can gather that there’s a script calling system.tag.readBlocking being called from a custom method called refresh. Apart from that though, I have no further context. I’ve found 6 locations that have a refresh custom method, but what if I had 100?

Is there some other way that I can narrow this down from the log?
How would IA go about finding the culprit?

2

I would start at line 32 in the custom method refresh.

at org.python.pycode._pyx59492.refresh$1(<custom-method refresh>:32)

3

But what if there are 100 custom methods called refresh ?
I agree that the traces we get are esoteric at best, figuring out the source of an error is a pain in the rear end.

4

Then i would say you would have a naming issue to deal with.

1 Like
5

Really ? Do you think it seems wrong to have a refresh method on several classes ?

Now imagine instead of refresh, the culprit is __str__ or __iter__. How do you fix the naming issue ?

6

If you have lots of components that all need a refresh method, then they should all be called refresh for consistency and for sanity. But the logs just say that a refresh method has the issue without any context of which component on what view :frowning:

7

Well, don’t discount the rest of the stack.

You’ve also got a project name, via MDC key:
project-name=<PROJECTNAME>
And you know that it’s a message handler, by the function name:

at org.python.pycode._pyx59490.onMessageReceived$1(<function:onMessageReceived>:2)

And more specifically, you know that it’s a Perspective message handler:

at com.inductiveautomation.perspective.gateway.model.MessageHandlerCollection$MessageHandlerImpl$1.lambda$invoke$0(MessageHandlerCollection.java:81)

Honestly, in this particular scenario, I think that is as much context as we can give you; on line 2 of a message handler in Perspective in project PROJECTNAME you’re calling a project script called refresh, which is trying to read some tag(s) and timing out.

I guess I could see an argument for trace/debug logging for invoked messages, or something like that (I don’t see any from a quick glance in the code, but there could still be some), but as an example this is a pretty good stacktrace compared to some I’ve seen :slight_smile:

8

What about this one?

Uncaught Throwable during execution. view=Packaging/Wine Delivery/Line 4/SHF Delivery@C, project-name=<PROJECTNAME>
java.lang.IllegalArgumentException: Malformed path: 1
at com.inductiveautomation.ignition.common.JsonPath.parse(JsonPath.java:242)
at com.inductiveautomation.perspective.gateway.property.PropertyTree.write(PropertyTree.java:424)
at com.inductiveautomation.perspective.gateway.model.ElementBindingHarness.writeToTarget(ElementBindingHarness.java:57)
at com.inductiveautomation.perspective.gateway.model.AbstractBindingHarness.valueReady(AbstractBindingHarness.java:343)
at com.inductiveautomation.perspective.gateway.model.AbstractBindingHarness$TransformSequencer.lambda$transformComplete$0(AbstractBindingHarness.java:289)
at com.inductiveautomation.perspective.gateway.api.LoggingContext.lambda$mdcWrap$0(LoggingContext.java:41)
at com.inductiveautomation.ignition.common.util.ExecutionQueue$PollAndExecute.run(ExecutionQueue.java:210)
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)
9

No script in that one. Just a binding.

10

There isn’t really any identifying info though telling me which binding it is on what component - I don’t know if that’s even possible information to add, but it would certainly help to narrow down which component has the error. I don’t see any errors on the page itself :confused:

11

On binding errors you should have an overlay showing you that you have a binding issue unless you have the overlays disabled.

12

perspective.ComponentModel (or ViewModel or PageModel) on trace should have some extra context that helps debug that.

13

Ah cool, I do have some of those as well. I don’t suppose there’s any way to link them together?

14

I’m not really sure what you mean by that.

15

To link the binding error above with the ComponentModel etc. errors

16

at com.inductiveautomation.perspective.gateway.model.ElementBindingHarness.writeToTarget(ElementBindingHarness.java:57)

Line 56 of ElementBindingHarness is this:
targetComponent.getLogger().tracef("%s writing %s=\"%s\"", typeCode, targetProperty, value);
getLogger() should be perspective.ComponentModel (or Page or View) - so if that logger is on trace, you should see that trace log immediately before the error above.