JMSException due to bad headers?

[Douglas Fraser]

Hi everyone,

Does the error below ring a bell for anyone? I have switched to using a Camel-only app to route the NR feeds straight to a file, but the error below has occurred a few times for the TD feed and once for the TRUST feed.   It is annoying in that the Java process does not fail / stop so a watchdog wouldn't restart the process - and there is not a connection problem apparently so the connection failover logic / reconnect does not kick in. Thus things "hang" and only on a total restart of everything does new data start coming in again.

So...

1. does anyone use only Camel and how do you restart a route?

2. what might be the problem here?  readUnsignedShort is apparently the cause...

I hope this is not an example of how a bad client messes things up for others!

thanks,

doug

[WARN ] 2022-08-23 16:08:33.439 [Camel (camel-1) thread #1 - JmsConsumer[TD_ALL_SIG_AREA]] DefaultReactiveExecutor - Err

or executing reactive work due to javax.jms.JMSException: java.io.EOFException. This exception is ignored.
org.apache.camel.RuntimeCamelException: javax.jms.JMSException: java.io.EOFException
    at org.apache.camel.component.jms.JmsBinding.extractHeadersFromJms(JmsBinding.java:208) ~[nrdata_camel.jar:?]
    at org.apache.camel.component.jms.JmsMessage.populateInitialHeaders(JmsMessage.java:244) ~[nrdata_camel.jar:?]
    at org.apache.camel.support.DefaultMessage.createHeaders(DefaultMessage.java:331) ~[nrdata_camel.jar:?]
    at org.apache.camel.support.DefaultMessage.hasHeaders(DefaultMessage.java:305) ~[nrdata_camel.jar:?]
    at org.apache.camel.component.jms.JmsMessage.copyFrom(JmsMessage.java:119) ~[nrdata_camel.jar:?]
    at org.apache.camel.support.MessageSupport.copy(MessageSupport.java:179) ~[nrdata_camel.jar:?]
    at org.apache.camel.support.AbstractExchange.copy(AbstractExchange.java:138) ~[nrdata_camel.jar:?]
    at org.apache.camel.support.DefaultExchange.copy(DefaultExchange.java:27) ~[nrdata_camel.jar:?]
    at org.apache.camel.support.ExchangeHelper.createCopy(ExchangeHelper.java:322) ~[nrdata_camel.jar:?]
    at org.apache.camel.processor.errorhandler.RedeliveryErrorHandler.defensiveCopyExchangeIfNeeded(RedeliveryErrorH
andler.java:304) ~[nrdata_camel.jar:?]
    at org.apache.camel.processor.errorhandler.RedeliveryErrorHandler$RedeliveryTask.prepare(RedeliveryErrorHandler.
java:680) ~[nrdata_camel.jar:?]
    at org.apache.camel.processor.PrototypeTaskFactory.acquire(PrototypeTaskFactory.java:29) ~[nrdata_camel.jar:?]
    at org.apache.camel.processor.errorhandler.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:210) ~[nrd
ata_camel.jar:?]
    at org.apache.camel.impl.engine.CamelInternalProcessor.process(CamelInternalProcessor.java:399) ~[nrdata_camel.j
ar:?]
    at org.apache.camel.processor.Pipeline$PipelineTask.run(Pipeline.java:109) ~[nrdata_camel.jar:?]
    at org.apache.camel.impl.engine.DefaultReactiveExecutor$Worker.schedule(DefaultReactiveExecutor.java:189) [nrdat
a_camel.jar:?]
    at org.apache.camel.impl.engine.DefaultReactiveExecutor.scheduleMain(DefaultReactiveExecutor.java:61) [nrdata_ca
mel.jar:?]
    at org.apache.camel.processor.Pipeline.process(Pipeline.java:184) [nrdata_camel.jar:?]
    at org.apache.camel.impl.engine.CamelInternalProcessor.process(CamelInternalProcessor.java:399) [nrdata_camel.ja
r:?]
    at org.apache.camel.impl.engine.DefaultAsyncProcessorAwaitManager.process(DefaultAsyncProcessorAwaitManager.java
:83) [nrdata_camel.jar:?]
    at org.apache.camel.support.AsyncProcessorSupport.process(AsyncProcessorSupport.java:41) [nrdata_camel.jar:?]
    at org.apache.camel.component.jms.EndpointMessageListener.onMessage(EndpointMessageListener.java:132) [nrdata_ca
mel.jar:?]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerCon
tainer.java:736) [nrdata_camel.jar:?]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerConta
iner.java:696) [nrdata_camel.jar:?]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerCo
ntainer.java:674) [nrdata_camel.jar:?]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingM
essageListenerContainer.java:331) [nrdata_camel.jar:?]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMes
sageListenerContainer.java:270) [nrdata_camel.jar:?]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(D
efaultMessageListenerContainer.java:1237) [nrdata_camel.jar:?]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLo
op(DefaultMessageListenerContainer.java:1227) [nrdata_camel.jar:?]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessa
geListenerContainer.java:1120) [nrdata_camel.jar:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: javax.jms.JMSException: java.io.EOFException
    at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:80) ~[nrdata_camel.jar:?]
    at org.apache.activemq.command.ActiveMQMessage.getPropertyNames(ActiveMQMessage.java:331) ~[nrdata_camel.jar:?]
    at org.apache.camel.component.jms.JmsBinding.extractHeadersFromJms(JmsBinding.java:206) ~[nrdata_camel.jar:?]
    ... 32 more
Caused by: java.io.EOFException
    at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:345) ~[?:?]
    at java.io.DataInputStream.readUTF(DataInputStream.java:594) ~[?:?]
    at java.io.DataInputStream.readUTF(DataInputStream.java:569) ~[?:?]
    at org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap(MarshallingSupport.java:97) ~[nrdata_camel.
jar:?]
    at org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap(MarshallingSupport.java:78) ~[nrdata_camel.
jar:?]
    at org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap(MarshallingSupport.java:70) ~[nrdata_camel.
jar:?]
    at org.apache.activemq.command.Message.unmarsallProperties(Message.java:244) ~[nrdata_camel.jar:?]
    at org.apache.activemq.command.Message.getProperties(Message.java:210) ~[nrdata_camel.jar:?]
    at org.apache.activemq.command.ActiveMQMessage.getPropertyNames(ActiveMQMessage.java:316) ~[nrdata_camel.jar:?]
    at org.apache.camel.component.jms.JmsBinding.extractHeadersFromJms(JmsBinding.java:206) ~[nrdata_camel.jar:?]
    ... 32 more

[Peter Hicks]

Hi Doug

I have occasionally seen null messages when processing the TD and TRUST feeds, and I've never been able to get to the bottom of it.

It looks like you're running Camel inside a JAR - can you share details of which version of Camel it is, and how your route and CamelContext is configured?  The routes I'm using are really simple although in XML format:

    <route id="tsr">
      <from uri="remoteBrokerA:queue:NR.TSR"/>
      <to uri="localBroker:topic:NR.TSR"/>
    </route>
    <route id="archive-tsr">
      <from uri="localBroker:topic:NR.TSR"/>
      <transform>
        <simple>${date:now:yyyy-MM-dd HH:mm:ss.SSS} TSR ${in.body}\n</simple>
      </transform>
      <to uri="file:///home/activemq/logs/tsr/?fileName=tsr-${date:now:yyyyMMdd}.log&amp;fileExist=Append&amp;forceWrites=false"/>
    </route>

The errors still come up in ActiveMQ's log file, but the route continues processing data.

Peter

--
You received this message because you are subscribed to the Google Groups "A gathering place for the Open Rail Data community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to openraildata-t...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/openraildata-talk/dfe21639-a7bc-4d8c-ba50-a37af166de6en%40googlegroups.com.

[Douglas Fraser]

Hi Peter,

It is Camel 3.18.0 and uses Camel's ActiveMQComponent. The route is very simple - the from part is the ActiveMQComponent that connects to NR's broker etc and the to part is the file endpoint much like yours.  I assume you are routing to a localBroker for your own purposes, but we do not need that and so I made things Camel-only.

<route id="td" errorHandlerRef="deadLetterErrorHandler">
      <from uri="ntrod:topic:TD_ALL_SIG_AREA?clientId=TD-sy...@gmail.com&amp;durableSubscriptionName=RAILTDnr01"/>
      <to uri="file:/data/nrfeeds/td/?fileName=./${date:now:yyyy}/${date:now:MM}/${date:now:dd}-td.json&amp;fileExist=Append" />
    </route>

The deadLetterHandler is just a text file, but messages that can't be delivered are different than ones that can't be parsed... so that is not an issue. 

I am going to try and capture the raw data coming in to see if there really is a bad value in the headers. There are some other things I could try to debug exactly what is going on and restart the route...

As for your setup, you're connecting a broker to their broker I guess, so maybe ActiveMQ's component has some special sauce Camel's doesn't. Or you're using "queue" instead of "topic" like I am?  I thought it was supposed to be topic. Perhaps I need to set some setting correctly.

Doug

To view this discussion on the web, visit https://groups.google.com/d/msgid/openraildata-talk/CAKGkhzbTqD_DpQ0m8ZPobwvF4UfKKU%2BoUbPZnJeDJ_RCwjP-8w%40mail.gmail.com.

[Douglas Fraser]

I think I've tracked down the problem - I built Camel 3.18.1 myself and added some low level debug messages.  there is something going on with the byte array of the jms message that holds properties names.  sometimes it seems to be standard utf-8 (aka "transformation jms-xml" which makes sense), sometimes it is a byte array that can not be parsed correctly (still waiting for that to happen again) and sometimes the byte array is null.  The rest of the jms message looks to be fine, as far as I can tell.  Overall, I think this is a minor issue, but it annoys me.

I would have expected the property names array to be a constant one and not change between runs of my Camel app (start/stop/reconnect to NROD etc). So not sure what is going on there...

another thing - it has to happen again, but apparently 3.18.1 does not have the problem I saw before (with 3.18.0) where the Camel route falls over.  The first stack trace is different than the one I saw awhile ago, but unfortunately I lost the log file that had that due to a misconfiguration...   Perhaps something went awry on my Linux box in compiling the first Camel app vs the build of Camel and the Camel app on my Mac.

we are getting to the bottom of this, though (eventually)

.

[Douglas Fraser]

So far I have seen 3 variations on the ByteSequence that makes up the optional JMS PropertyNames - a null array (most of the time),

[0, 0, 0, 1, 0, 14, 116, 114, 97, 110, 115, 102, 111, 114, 109, 97, 116, 105, 111, 110, 9, 0, 7, 106, 109, 115, 45, 120, 109, 108] (or most of the time)

and

[0, 0, 0, 2, 0, 14, 116, 114, 97, 110, 115, 102, 111, 114, 109, 97, 116, 105, 111, 110, 9, 0, 7, 106, 109, 115, 45, 120, 109, 108]   (rarely)

The only difference is the first four bytes which is the count of properties in the array. The rest of it is the property name(s) and their values along with some info like the char count and value type. There is only one property: "transformation" and its value is "jms-xml".

So things would result in a EOFException and the message being lost or tossed due to the last variation - there is only 1 property, not two and thus a EOFException would get thrown because the array has no more data.

This is a minor thing, Camel/ActiveMQ ought to recover from it (I think the message gets dropped given the code), but I would say Network Rail/CACI should look into it as it may be causing issues elsewhere. But I do not know where or how to report this. 

As for why my Camel 3.18.0 only app was breaking, I'm not sure. Perhaps I thought the route was down because of latency issues on the feed, but this was happening nearly ever day and data was definitely getting lost. I haven't yet figured out how to configure things to restart the route...   I think it might be a problem with the build - on Linux, I was using prebuilt 3.18.0 Camel etc jars from Maven Central and on the Mac, I built Camel 3.18.1 myself. Or it was a change in Camel 3.18.1 that fixed the recovery process. In any case, I now have a custom 3.18.1 that overlooks this slight issue

hopefully this helps someone else,

doug

[Peter Hicks]

Hi Doug

On 29 Aug 2022, at 08:46, Douglas Fraser <sye1...@gmail.com> wrote:

So far I have seen 3 variations on the ByteSequence that makes up the optional JMS PropertyNames - a null array (most of the time),

[0, 0, 0, 1, 0, 14, 116, 114, 97, 110, 115, 102, 111, 114, 109, 97, 116, 105, 111, 110, 9, 0, 7, 106, 109, 115, 45, 120, 109, 108] (or most of the time)

and

[0, 0, 0, 2, 0, 14, 116, 114, 97, 110, 115, 102, 111, 114, 109, 97, 116, 105, 111, 110, 9, 0, 7, 106, 109, 115, 45, 120, 109, 108]   (rarely)

The only difference is the first four bytes which is the count of properties in the array. The rest of it is the property name(s) and their values along with some info like the char count and value type. There is only one property: "transformation" and its value is "jms-xml". 

So things would result in a EOFException and the message being lost or tossed due to the last variation - there is only 1 property, not two and thus a EOFException would get thrown because the array has no more data.

OK, that makes perfect sense - thank you for taking the time to look in to this so deeply and find the problem.

This is a minor thing, Camel/ActiveMQ ought to recover from it (I think the message gets dropped given the code), but I would say Network Rail/CACI should look into it as it may be causing issues elsewhere. But I do not know where or how to report this.  

What would really help would be a minimal example of the problem in a GitHub repository.  That way, other people can have a look at it and may be able to see where things are going wrong, and CACI will be able to reproduce the problem.

As for why my Camel 3.18.0 only app was breaking, I'm not sure. Perhaps I thought the route was down because of latency issues on the feed, but this was happening nearly ever day and data was definitely getting lost. I haven't yet figured out how to configure things to restart the route...   I think it might be a problem with the build - on Linux, I was using prebuilt 3.18.0 Camel etc jars from Maven Central and on the Mac, I built Camel 3.18.1 myself. Or it was a change in Camel 3.18.1 that fixed the recovery process. In any case, I now have a custom 3.18.1 that overlooks this slight issue 

Did this work with a previous version of Camel?  If so, is it possible there was a code change to Apache Camel which enforced checking the order of the list, raising an exception rather than failing silently?

Peter

[Douglas Fraser]

On Monday, August 29, 2022 at 9:18:59 AM UTC+1 Peter Hicks wrote:

Hi Doug

This is a minor thing, Camel/ActiveMQ ought to recover from it (I think the message gets dropped given the code), but I would say Network Rail/CACI should look into it as it may be causing issues elsewhere. But I do not know where or how to report this.  

What would really help would be a minimal example of the problem in a GitHub repository.  That way, other people can have a look at it and may be able to see where things are going wrong, and CACI will be able to reproduce the problem.

My Camel app is a very simple one that just runs the default Camel main() example to setup and run a route. The important thing is building with Camel 3.18.0 or 3.18.1 and having the logging be sufficient to display the problem. There is no consistency as to when or even if the TD/TRUST feeds send a message of this sort - I was running things overnight until just now and had no problems.  But I will make a repo with the part of Camel I added logging statements to.

;

 

As for why my Camel 3.18.0 only app was breaking, I'm not sure. Perhaps I thought the route was down because of latency issues on the feed, but this was happening nearly ever day and data was definitely getting lost. I haven't yet figured out how to configure things to restart the route...   I think it might be a problem with the build - on Linux, I was using prebuilt 3.18.0 Camel etc jars from Maven Central and on the Mac, I built Camel 3.18.1 myself. Or it was a change in Camel 3.18.1 that fixed the recovery process. In any case, I now have a custom 3.18.1 that overlooks this slight issue 

Did this work with a previous version of Camel?  If so, is it possible there was a code change to Apache Camel which enforced checking the order of the list, raising an exception rather than failing silently?

I haven't used anything but Camel 3.18 for my standalone app - I vaguely remember seeing something like this when I was running Camel in an ActiveMQ broker, but like you said, the feed would recover. So that version of Camel would be a few years old.

I suspect it might be a code change to Camel that makes it stop dumping the feed, but haven't nailed that down yet. An exception was always being thrown like it should be but higher layers were not handling it properly, I think.

Doug

[Douglas Fraser]

The repo I made can be found here: https://github.com/drfraser/NRODCamelTesting

No errors were seen overnight on the TD feed, so I have switched to the TRUST now as I did see this problem once on it

The latest error was due to propertyNames being [0, 0, 0, 1], i.e. 1 propertyName but no data. The fact that this has changed a number of times is really concerning - what is so unstable?

[Peter Hicks]

Hi Doug

Thanks for putting the repository up on GitHub - I'll try to take a look.

It may well be that there's a longstanding bug in the NROD codebase which causes this.  Are you running this against the existing, or the soon-to-be-released new platform?  Part of me hopes you'll say the former...!

Peter

--
You received this message because you are subscribed to the Google Groups "A gathering place for the Open Rail Data community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to openraildata-t...@googlegroups.com.

To view this discussion on the web, visit https://groups.google.com/d/msgid/openraildata-talk/253c713c-96f9-4792-96aa-bd025336da86n%40googlegroups.com.

[Douglas Fraser]

Hi Peter,

I just got a email response for the ticket that was created by my email to dsg_nrod...@caci.co.uk

https://caci.freshservice.com/helpdesk/tickets/82219

It said the ticket has been resolved, but as I do not have an account for the helpdesk website, I can't see it or any info....  Maybe you do?

And perhaps their fix is what started this problem of propertyNames being [0,0,0,1] which still makes things break. so I am not 100% sure it is fixed but we'll see over the next day or two if my currently running test gets any errors.

I am using the existing platform - I haven't heard anything about this new platform (like how to get an account) because I have not been working on this stuff for awhile.

Doug

[Peter Hicks]

Hi Doug

I'll only be able to see tickets I've raised.  Try resetting your password via the link on https://caci.myfreshworks.com/

It is quite useful to know why tickets have been closed!

Peter 

To view this discussion on the web, visit https://groups.google.com/d/msgid/openraildata-talk/caff7e61-e65a-4031-ba62-9d3aac0d93bfn%40googlegroups.com.