RPC ImportError... sometimes

Sometimes.... :nauseated_face:
I have an RPC that works 90% of the time, and 10% of the time errors out with:

ImportError: No module named mymodule

The error is repeatable, a function call that errors will always error, and a function call that works will always work. I'm thinking it has to be argument related, but for the life of me I can't figure out what's going on.

Skipping details for brevity, the script module does some stuff, then makes the RPC. Importantly, data is not modified in any way between the script function call and the RPC function call (the data that arrives in the arguments goes straight to the arguments for the RPC).

 override fun runAsync(name: String, data: Any) {
      ...
      val handle = runAsyncRPC(name, data)
      ...

The actual RPC signature is:

fun runAsyncRPC(name: String, data: Any): AsyncRPCHandle

data class AsyncRPCHandle(
    val function: String,
    val id: String
) : java.io.Serializable

It's the data argument that is giving me grief. It's typed as Any so that it can take either a dictionary or an instance of a module-specific class.

Hopefully I'm not leaving too much out, but here's an example of the weirdness I'm seeing:

data1 = system.mymodule.makeData(...)
data2 = system.mymodule.makeDataAnotherWay(...)

type(data1) == type(data2) # True
data1 == data2 # True

from com.mymodule import MyDataClass
type(data1) == MyDataClass # True
type(data2) == MyDataClass # True
isinstance(data1, MyDataClass) # True
isinstance(data2, MyDataClass) # True

system.mymodule.runAsync('name', data1) # works
system.mymodule.runAsync('name', data2) # ImportError: No module named mymodule

At first I thought it was something to do with using Any in the function signature so I tried changing the RPC signature to:

fun runAsyncRPC(name: String, data: MyDataClass): AsyncRPCHandle

just to see if it would help, but with no success.

Things look okay system.mymodule.makeDataAnotherWay(...) function, there are no errors in the gateway, and everything looks good in the client up until the exact line of the RPC.

Any ideas?

No other errors anywhere in the gateway logs that might be useful to troubleshoot?

Specific nit - why not just use an overload (write the method twice, once accepting PyDictionary, once accepting MyModuleClass) instead of a way-too-broad input type?
Or, at the very least, accept Serializable instead of Any so you've got a chance of making it over the RPC bridge.

Nothing. It doesn't look like the gateway is aware when the RPC fails. Any specific loggers I should look at?

That's a good question. I agree it should be definitely at least be specified as Serializable instead of Any - I've made that change and it's still demonstrating the same behavior.

The module is a driver-type device: system.mymodule.runAsync(name, data) sends data to named connection (sent from the gateway), and returns a future that will complete once the transaction is finished. Depending on the configuration of the connection, data needs to be parsed into one of several different formats (JSON, XML, CSV, TSV, etc.) before being sent.

It seemed easiest to have the connection do the parsing itself (since it knows the required format based on it's own configuration). A connection uses an InputParser that knows how to parse all allowed input types into all of the available output types. The InputParser either:

  1. Successfully parses the input, or
  2. Fails to parse the input (schema reasons), or
  3. Throws a UnsupportedOperationException error if it's not possible to convert the input into the required output format (i.e. MyModuleClass cannot be parsed into CSV, but can be parsed into XML or JSON).

The goal of leaving the data parameter as generic as possible was to have the InputParser be the only place I have to define new message types and serialization methods.

Are you sure this is anything related to your java/kotlin code? The JVM doesn't have an import error. (Imports in java are compile-time conveniences, not runtime operations.)

Since you mentioned Futures, you should know that a whenComplete() operation will likely run on a java thread, supplied by the JVM, that is utterly divorced from any of Ignition's normal thread locals for context tracking.

2 Likes

I can't really think of a reason an RPC method would cause an import error in scripting. The two layers are pretty well insulated from each other.

Unfortunately, it's hard to troubleshoot in a vacuum... can you demonstrate the same problem in the Vision client as well as the designer? Can you see anything else odd about the scripting state after this fails? Does the next execution of the same script work and fail up to the same point? Are you doing anything to hop threads, clear threadlocals, etc? Coroutines?

I've got a PyCompletableFuture class; the whenComplete() callback is ran through scriptManager.runFunction(callback, *args). The scriptManager is the one I'm receiving during the initializeScriptManager module hook:

One? That gets called for every project in the gateway, each slightly different.

Yeah, that seems like it could definitely be the source of the problem. You should be registering your namespace in initializeScriptManager, but definitely not hanging onto the instance you get (that'll get called often).

I think you can just use context.getScriptManager() whenever you need a script manager.

1 Like

Ah great, I'm doing that now but still encountering the same error.

Yeah I totally understand, here's some more details:

  1. The failure happens in both the Designer and in a Vision client.

  2. The failure does not happen in the Gateway scope.

    • A script that fails in the designer will work in both a Gateway message handler and in a Perspective session.
  3. A failure results in no errors in the Gateway log.

  4. Nothing seems weird about the scripting state after a failure.

    • A script that fails will always fail.
    • A script that works will always work.
  5. The only difference between in a working script and a failing script is the way I'm constructing the data object being passed to system.mymodule.runAsync(name, data).

    • I'm constructing the data object in two different ways:
      1. a shortcut method (system.mymodule.makeDataShort(params)), that takes a only few parameters, fills in a bunch of others with defaults, and then calls a constructor and returns the new object.
      2. a more verbose method (system.mymodule.makeDataFull(params)), that can take a lot of parameters, calls the same constructor and returns the new object.
    • The data objects (MyDataClass) are Kotlin data class objects.
    • For my testing, I am creating identical data objects using Method 1 and Method 2.
      • The objects pass the default data class equality check.
    • A data object from Method 1 will always fail.
  6. Each connection owns a single-threaded dispatcher for sending data/receiving responses. Client responses are eventually completed through Ignition's PushNotification system. Everything seems to be working as expected here (as long as the code reaches this point, lol).

Full Traceback of Failure
Java Traceback:
Traceback (most recent call last):
  File "<input>", line 1, in <module>
  File "<module:testing>", line 58, in willThrowError
	at com.sun.proxy.$Proxy48.runAsyncRPC(Unknown Source)
	at com.mussonindustrial.ignition.bartender.client.rpc.ClientAsyncRPCExecutor.runAsyncRPC(ClientAsyncRPCExecutor.kt)
	at com.mussonindustrial.ignition.bartender.client.rpc.ClientAsyncRPCExecutor.runAsync(ClientAsyncRPCExecutor.kt:44)
	at com.mussonindustrial.ignition.bartender.client.scripting.ClientExecuteScriptModule.runAsync(ClientExecuteScriptModule.kt:25)
	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)

java.lang.reflect.UndeclaredThrowableException: java.lang.reflect.UndeclaredThrowableException
	at org.python.core.Py.JavaError(Py.java:547)
	at org.python.core.Py.JavaError(Py.java:538)
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:192)
	at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:552)
	at org.python.core.PyObject.__call__(PyObject.java:477)
	at org.python.core.PyObject.__call__(PyObject.java:481)
	at org.python.pycode._pyx156.willThrowError$2(<module:testing>:59)
	at org.python.pycode._pyx156.call_function(<module:testing>)
	at org.python.core.PyTableCode.call(PyTableCode.java:173)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:119)
	at org.python.core.PyFunction.__call__(PyFunction.java:406)
	at org.python.pycode._pyx155.f$0(<.input>:1)
	at org.python.pycode._pyx155.call_function(<.input>)
	at org.python.core.PyTableCode.call(PyTableCode.java:173)
	at org.python.core.PyCode.call(PyCode.java:18)
	at org.python.core.Py.runCode(Py.java:1687)
	at org.python.core.Py.exec(Py.java:1731)
	at org.python.util.PythonInterpreter.exec(PythonInterpreter.java:277)
	at org.python.util.InteractiveInterpreter.runcode(InteractiveInterpreter.java:130)
	at com.inductiveautomation.ignition.designer.gui.tools.jythonconsole.JythonConsole$ConsoleWorker.doInBackground(JythonConsole.java:626)
	at com.inductiveautomation.ignition.designer.gui.tools.jythonconsole.JythonConsole$ConsoleWorker.doInBackground(JythonConsole.java:614)
	at java.desktop/javax.swing.SwingWorker$1.call(Unknown Source)
	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
	at java.desktop/javax.swing.SwingWorker.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.lang.reflect.UndeclaredThrowableException
	at com.sun.proxy.$Proxy48.runAsyncRPC(Unknown Source)
	at com.mussonindustrial.ignition.bartender.client.rpc.ClientAsyncRPCExecutor.runAsyncRPC(ClientAsyncRPCExecutor.kt)
	at com.mussonindustrial.ignition.bartender.client.rpc.ClientAsyncRPCExecutor.runAsync(ClientAsyncRPCExecutor.kt:44)
	at com.mussonindustrial.ignition.bartender.client.scripting.ClientExecuteScriptModule.runAsync(ClientExecuteScriptModule.kt:25)
	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:190)
	... 24 more

Caused by: com.inductiveautomation.ignition.client.gateway_interface.GatewayException: ImportError: No module named mussonindustrial
	at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.newGatewayException(GatewayInterface.java:360)
	at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:334)
	at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:287)
	at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.moduleInvokeSafe(GatewayInterface.java:930)
	at com.inductiveautomation.ignition.client.gateway_interface.ModuleRPCFactory$DynamicRPCHandler.invoke(ModuleRPCFactory.java:53)
	... 33 more

Caused by: ImportError: No module named mussonindustrial
	at org.python.core.Py.ImportError(Py.java:329)
	at org.python.core.imp.import_logic(imp.java:1290)
	at org.python.core.imp.import_module_level(imp.java:1369)
	at org.python.core.imp.importName(imp.java:1504)
	at org.python.core.PyType$TypeResolver.readResolve(PyType.java:2674)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(null)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(null)
	at java.lang.reflect.Method.invoke(null)
	at java.io.ObjectStreamClass.invokeReadResolve(null)
	at java.io.ObjectInputStream.readOrdinaryObject(null)
	at java.io.ObjectInputStream.readObject0(null)
	at java.io.ObjectInputStream.defaultReadFields(null)
	at java.io.ObjectInputStream.readSerialData(null)
	at java.io.ObjectInputStream.readOrdinaryObject(null)
	at java.io.ObjectInputStream.readObject0(null)
	at java.io.ObjectInputStream.readObject(null)
	at java.io.ObjectInputStream.readObject(null)
	at java.util.ArrayList.readObject(null)
	at jdk.internal.reflect.GeneratedMethodAccessor88.invoke(null)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(null)
	at java.lang.reflect.Method.invoke(null)
	at java.io.ObjectStreamClass.invokeReadObject(null)
	at java.io.ObjectInputStream.readSerialData(null)
	at java.io.ObjectInputStream.readOrdinaryObject(null)
	at java.io.ObjectInputStream.readObject0(null)
	at java.io.ObjectInputStream.defaultReadFields(null)
	at java.io.ObjectInputStream.readSerialData(null)
	at java.io.ObjectInputStream.readOrdinaryObject(null)
	at java.io.ObjectInputStream.readObject0(null)
	at java.io.ObjectInputStream.defaultReadFields(null)
	at java.io.ObjectInputStream.readSerialData(null)
	at java.io.ObjectInputStream.readOrdinaryObject(null)
	at java.io.ObjectInputStream.readObject0(null)
	at java.io.ObjectInputStream.readObject(null)
	at java.io.ObjectInputStream.readObject(null)
	at com.inductiveautomation.ignition.gateway.servlets.gateway.functions.ModuleInvoke.decodeToObject(ModuleInvoke.java:212)
	at com.inductiveautomation.ignition.gateway.servlets.gateway.functions.ModuleInvoke.invoke(ModuleInvoke.java:104)
	at com.inductiveautomation.ignition.gateway.servlets.Gateway.doPost(Gateway.java:435)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:523)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
	at com.inductiveautomation.ignition.gateway.bootstrap.MapServlet.service(MapServlet.java:86)
	at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1410)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:764)
	at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1665)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:578)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1570)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at com.inductiveautomation.catapult.handlers.RemoteHostNameLookupHandler.handle(RemoteHostNameLookupHandler.java:121)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:301)
	at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:51)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:141)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.server.Server.handle(Server.java:563)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$0(HttpChannel.java:505)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:762)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:497)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:282)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:416)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:385)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:272)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.lambda$new$0(AdaptiveExecutionStrategy.java:140)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
	at java.lang.Thread.run(null)

Traceback (most recent call last):
  File "<input>", line 1, in <module>
  File "<module:testing>", line 58, in willThrowError
	at com.sun.proxy.$Proxy48.runAsyncRPC(Unknown Source)
	at com.mussonindustrial.ignition.bartender.client.rpc.ClientAsyncRPCExecutor.runAsyncRPC(ClientAsyncRPCExecutor.kt)
	at com.mussonindustrial.ignition.bartender.client.rpc.ClientAsyncRPCExecutor.runAsync(ClientAsyncRPCExecutor.kt:44)
	at com.mussonindustrial.ignition.bartender.client.scripting.ClientExecuteScriptModule.runAsync(ClientExecuteScriptModule.kt:25)
	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)
java.lang.reflect.UndeclaredThrowableException: java.lang.reflect.UndeclaredThrowableException

Context for the stack trace:

interface ModuleRPCAsync {
    @Throws(IllegalArgumentException::class)
    fun runAsyncRPC(connectionName: String, data: Serializable): AsyncRPCHandle
}

interface ModuleRPC :
    ...
    ModuleRPCAsync,
    ...

class ClientAsyncRPCExecutor :
    ModuleRPCAsync by ModuleRPCFactory.create(Meta.MODULE_ID, ModuleRPC::class.java),
    FilteredPushNotificationListener(Meta.MODULE_ID, "RunAsyncResponse") {

    fun runAsync(context: ClientContext, connectionName: String, data: Serializable): PyCompletableFuture<Response> {
       ...
       val handle = runAsyncRPC(connectionName, data)
       ...
}

class ClientExecuteScriptModule(
        private val asyncRPCExecutor: ClientAsyncRPCExecutor,
        private val context: ClientContext
) : ExecuteScriptModule {
        @ScriptFunction(docBundlePrefix = BUNDLE_PREFIX)
        @KeywordArgs(
                names = ["connectionName", "data"],
                types = [String::class, Any::class],
        )
        @Throws(Exception::class)
        override fun runAsync(connectionName: String, data: Serializable): PyCompletableFuture<Response> {
                return asyncRPCExecutor.runAsync(context, connectionName, data)
        }
}