[BUG-13789] Gateway Logs: Unhandled Intent failure

Hello,

Just noticed this showing up in my gateway logs:

Intent	06May2019 11:00:48	Unhandled Intent failure.
java.lang.ClassCastException: cannot assign instance of com.inductiveautomation.ignition.common.StringPath to field com.inductiveautomation.ignition.common.project.resource.ResourcePath.path of type com.inductiveautomation.ignition.common.StringPath$CaseSensitiveStringPath in instance of com.inductiveautomation.ignition.common.project.resource.ResourcePath

at java.base/java.io.ObjectStreamClass$FieldReflector.setObjFieldValues(Unknown Source)

at java.base/java.io.ObjectStreamClass$FieldReflector.checkObjectFieldValueTypes(Unknown Source)

at java.base/java.io.ObjectStreamClass.checkObjFieldValueTypes(Unknown Source)

at java.base/java.io.ObjectInputStream.defaultCheckFieldValues(Unknown Source)

at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)

at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)

at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)

at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)

at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)

at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.readArray(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)

at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)

at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)

at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)

at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)

at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)

at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.readArray(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)

at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)

at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)

at java.base/java.io.ObjectInputStream.readObject(Unknown Source)

at com.inductiveautomation.metro.impl.codecs.JavaSerializationCodec.decode(JavaSerializationCodec.java:41)

at com.inductiveautomation.metro.impl.CentralManagerImpl.handleLocal(CentralManagerImpl.java:432)

at com.inductiveautomation.metro.impl.ConnectionWatcher.handle(ConnectionWatcher.java:420)

at com.inductiveautomation.metro.impl.ConnectionWatcher.handle(ConnectionWatcher.java:43)

at com.inductiveautomation.metro.impl.protocol.websocket.WebSocketConnection.forward(WebSocketConnection.java:1605)

at com.inductiveautomation.metro.impl.protocol.websocket.WebSocketConnection.onDataReceived(WebSocketConnection.java:1496)

at com.inductiveautomation.metro.impl.protocol.websocket.servlet.DataChannelServlet.doPost(DataChannelServlet.java:220)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

at com.inductiveautomation.ignition.gateway.bootstrap.MapServlet.service(MapServlet.java:86)

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:335)

at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:61)

at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.server.Server.handle(Server.java:530)

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256)

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)

at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:289)

at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:149)

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)

at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)

at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)


I’m currently running the v8 nightly, java version 11.0.2+7-LTS

Has anyone seen this/know what may be causing this?

Thanks!

-Paul

It looks like a bug, thanks for reporting.

Do you have a nightly gateway hooked up to an 8.0.0 release gateway or something like that?

yes – currently have 2 of our 6 ignition gateway pairs running the nightly – the remaining are still on the official v8.0.0 release… was hoping to wait for another official release before updating the remainder.

@paul.bouillon,

Can you provide any additional information on what you may have been doing at the time when this error occurred? I am unable to duplicate this error and I would like to ensure it gets resolved properly. Some of the questions I have based on where we believe the issue would have occurred:

  1. Were project resources being transferred between Gateways of the same version (e.g. both 8.0.1-RC2) or were they between different versions (e.g. 8.0.0 -> 8.0.1-RC2)?
  2. What version of Ignition was the Controller running?
  3. What type of resources were being transferred?
  4. Did any of the resources that were being transferred get renamed in either Ignition itself, or via the filesystem?

Thanks,
Garth

Hi Garth,

Absolutely – I notice the error logging twice concurrently (usually the same timestamp or within 5 seconds of eachother) after saving gateway scripts. After editing a gateway script in the designer – I see the error log almost immediately.

  1. Were project resources being transferred between Gateways of the same version (e.g. both 8.0.1-RC2) or were they between different versions (e.g. 8.0.0 -> 8.0.1-RC2)?

The error occurred while saving (or re-starting gateway event scripts) not while transferring project resources. Our redundant/backup gateway is still on v8.0.0 (master is on a nightly build)

  1. What version of Ignition was the Controller running?

A nightly build from last week (think it was Thursday… no version number indicated – just says “Dev Version”)

  1. What type of resources were being transferred?

Was not transferring any resources that I know of… perhaps the gateway event scripts to the redundant/backup gateway?

  1. Did any of the resources that were being transferred get renamed in either Ignition itself, or via the filesystem?

Not that I know of.

Thanks for your help!

-Paul

Thanks for providing that information. With that information we were able to reproduce the issue, and a fix will be implemented to prevent this specific error. You almost certainly would not have seen this issue in production.

This issue looks to only be possible when your Master and Backup nodes are running on different versions of Ignition. Normally when this occurs, you would get an error noting a version mis-match between the Gateways. Since we are providing nighties that are versioned in a way that allows mismatched versions to connect you were able to get into this state and are seeing the problem. The fix should be in a nightly build within the next couple of days, but you should be able to make it go away by ensuring all Redundant pair are running the same version of Ignition.

When this is fixed, it will only be resolved in 8.0.1+ versions of Ignition. If any of the nodes are 8.0.0, then this error will continue to appear when a sync occurs.

Thanks,
Garth

2 Likes

Hello there,

I'm seeing this error message in my logs, and I have no idea what it means or what it comes from.

It seems there were a few occurrences at the end of last month, every day at the same time (the one on October 31 that looks to be one hour early is explained by the switch to winter time on October 30 (I'm in France))

Here are the ones from October 29 without filters, you can see they seem to happen at the same time as WebSocketConnection or SubscriptionManager errors.

Then, the error stopped for a while, and started showing up again 2 days ago, but now more regularly:

It appears almost every hour, with a few gaps or 'duplicates'.

A lot (but not all) of them are accompanied by either a SebSocketConnection error or SubscriptionManager warning.

What do I do now ? Where do I look, what do I test ?
I'm running it by the forum's users before taking it to support, just in case (the time difference between support and France makes the process quite slow :X)

I've never seen "Intent" in Ignition. I've familiar with the concept as used in Android--perhaps there's a Perspective Mobile app that is waking up and sending these?

It's a gateway network thing.

Cut off in that screenshot should be a "+" to the right that hopefully has an exception stack trace.

Yes there is, though I can't make much of it:

stacktrace

java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.server.HttpInput$ErrorState.noContent(HttpInput.java:1149)
at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:333)
at com.inductiveautomation.metro.utils.MeterTrackedInputStream.read(MeterTrackedInputStream.java:66)
at java.base/java.io.ObjectInputStream$PeekInputStream.read(Unknown Source)
at java.base/java.io.ObjectInputStream$PeekInputStream.readFully(Unknown Source)
at java.base/java.io.ObjectInputStream$BlockDataInputStream.readUTFBody(Unknown Source)
at java.base/java.io.ObjectInputStream$BlockDataInputStream.readUTF(Unknown Source)
at java.base/java.io.ObjectInputStream.readString(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject(Unknown Source)
at java.base/java.util.HashMap.readObject(Unknown Source)
at java.base/jdk.internal.reflect.GeneratedMethodAccessor40.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.base/java.lang.reflect.Method.invoke(Unknown Source)
at java.base/java.io.ObjectStreamClass.invokeReadObject(Unknown Source)
at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)
at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)
at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)
at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)
at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)
at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)
at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)
at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)
at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)
at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)
at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)
at java.base/java.io.ObjectInputStream.readArray(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)
at java.base/java.io.ObjectInputStream.defaultReadFields(Unknown Source)
at java.base/java.io.ObjectInputStream.readSerialData(Unknown Source)
at java.base/java.io.ObjectInputStream.readOrdinaryObject(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject0(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject(Unknown Source)
at java.base/java.io.ObjectInputStream.readObject(Unknown Source)
at com.inductiveautomation.metro.impl.codecs.JavaSerializationCodec.decode(JavaSerializationCodec.java:65)
at com.inductiveautomation.metro.impl.CentralManagerImpl.handleLocal(CentralManagerImpl.java:429)
at com.inductiveautomation.metro.impl.ConnectionWatcher.handle(ConnectionWatcher.java:429)
at com.inductiveautomation.metro.impl.ConnectionWatcher.handle(ConnectionWatcher.java:44)
at com.inductiveautomation.metro.impl.protocol.websocket.WebSocketConnection.forward(WebSocketConnection.java:1401)
at com.inductiveautomation.metro.impl.protocol.websocket.WebSocketConnection.onDataReceived(WebSocketConnection.java:1293)
at com.inductiveautomation.metro.impl.protocol.websocket.servlet.DataChannelServlet.doPost(DataChannelServlet.java:262)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at com.inductiveautomation.metro.impl.protocol.websocket.servlet.DataChannelServlet.service(DataChannelServlet.java:188)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at com.inductiveautomation.ignition.gateway.bootstrap.MapServlet.service(MapServlet.java:86)
at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1450)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)
at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1631)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at com.inductiveautomation.catapult.handlers.RemoteHostNameLookupHandler.handle(RemoteHostNameLookupHandler.java:121)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:322)
at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:516)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555)
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410)
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171)
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113)
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.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
... 1 common frames omitted

Similar purpose? (Subscribable cross-process messaging in Android, fwiw.)

Indeed. It looks like a message deserialization didn't get far enough for the trace to even show what kind of message.

Hello Kevin,

Any clue ?
Should I open a ticket with support ?

Probably make a support ticket, not really my area of expertise.

Looking at the stack trace though it just looks like a comms timeout between 2 gateways. Maybe a firewall interfering or something. Don't know.

Alright, thanks.

My ticket list is getting longer than winter nights in the artic :smiley: