[IGN-11148]Locating script errors from Wrapper log

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?

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

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

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.

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

1 Like

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 ?

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:

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:

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)

No script in that one. Just a binding.

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:

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

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

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

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

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

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.

I don't fully understand why this would be enough context. You could also specify the view and the component it is triggered on, or can't you?

No, you're right, that's a fair point. Generally errors from Perspective are set up with an appropriate MDC context that'll give you a much better time locating where the error happened, but message handlers appear to have missed that treatment. I just filed a ticket to remedy that.

3 Likes

Sounds good!