Apache Camel handles redelivery of messages based on two principles
- internally
- externally
The internal redelivery is essentially the Camel error handler that
allows you to retry processing a failed message. This is all handled by
Camel itself.
However the situation changes when the redelivery is commenced
externally, such as from a message broker like Apache ActiveMQ.
Previously from a Camel point of view, when the message broker was
redelivering a message, it was regarded as a new message.
This made it a bit harder for end users of Camel to figure out this was a redelivered message, and also how to correlate logs.
This has been improved in the upcoming releases of Apache Camel and Fuse Mediation Router.
Example
Given you have configured a Camel route to consume messages from ActiveMQ and use transactions as shown in the following snippet.
<route id="myRoute">
<from uri="activemq:queue:foo"/>
<transacted/>
<process ref="myProcessor"/>
<process ref="myOtherProcessor"/>
</route>
The route is kept simple for demonstrations purpose. However it indicate
the route is transacted, which allows Camel to support externally
redeliveries.
We have configured the Camel activemq component to use JMS transacted acknowledgment (transacted=true)
<bean id="activemq" class="org.apache.activemq.camel.component.ActiveMQComponent">
<property name="connectionFactory" ref="poolConnectionFactory"/>
<property name="transacted" value="true"/>
<property name="transactionManager" ref="jmsTransactionManager"/>
</bean>
Now suppose Camel consumes a message from the foo queue. And processing
the message fails upon the first two attempts, and on the 3rd attempt
the message is processed successfully.
Camel will by default log at WARN level when a transaction is rolled
back. What has been improved is the details in this log, which now
includes information whether the message was externally redelivered, as
well both the message id and exchange id. This allows you to correlate
the logs. More about this a bit later. Notice in the 1st attempt, we
have redelivered(false), and in the 2nd attempt its redelivered(true).
Also notice that the MessageID is the same, where as ExchangeID is
unique.
1st attempt
Transaction rollback (0x3e4ac866) redelivered(false) for (MessageId:
ID:davsclaus.lan-55814-1328257420734-2:2:1:1:1 on ExchangeId:
ID-davsclaus-lan-55809-1328257419533-0-3) caught:
java.lang.IllegalArgumentException: Forced exception
2nd attempt
Transaction rollback (0x3e4ac866) redelivered(true) for (MessageId:
ID:davsclaus.lan-55814-1328257420734-2:2:1:1:1 on ExchangeId:
ID-davsclaus-lan-55809-1328257419533-0-4) caught:
java.lang.IllegalArgumentException: Forced exception
3rd attempt
Success, no WARN logging.
Configuring logging details
When a transaction is rolled back, Camel will not log the stracktrace,
so its less noisy. But you can configure the logging details from the
Camel transaction error handler as shown below. If you want to see the
failed exception and stack trace, then you can set the logStackTrace and
logExhausted options to true.
<errorHandler id="txEH" type="TransactionErrorHandler" rollbackLoggingLevel="WARN">
<redeliveryPolicy logStackTrace="false" logExhausted="false"/>
</errorHandler>
That is not all, the activemq component can also configure logging
details. The activemq component will be default log any uncaught
exceptions at WARN level including stack traces. So out of the box you
may see the exception being logged twice. One time by the Camel
transaction error handler, and a 2nd time by the activemq component. You
can customize the logging level on the activemq, so for example to
suppress logging, you can disable logging using the two errorHandler
options as shown below:
<bean id="activemq" class="org.apache.activemq.camel.component.ActiveMQComponent">
<property name="connectionFactory" ref="poolConnectionFactory"/>
<property name="transacted" value="true"/>
<property name="transactionManager" ref="jmsTransactionManager"/>
<property name="errorHandlerLoggingLevel" value="OFF"/>
<property name="errorHandlerLogStackTrace" value="false"/>
</bean>
Okay so lets take a look at how to correlate the logs.
Correlating logs
When ActiveMQ redeliveries a message, it will use the same MessageID,
which allows you to correlate the logs. So in the example above. You can
correlate the message by MessageID, which ends with 2:2:1:1. It can get
even easier if you enable
MDC logging, which means you can have a column in the log file, that contains the MessageID.
Here is a example where we use MDC logging, and have exchangeId and
messageId in two columns. We have shortened the ids, as the are often
unique in the last part. So we have kept the last 10 chars, configured
by %-10.10X{exchangeId} - %-10.10X{messageId}. I also added a route step to log the message using <to uri="log:before"/>.
1st message
INFO before - 471691-0-3 - -2:2:1:1:1 -
Exchange[ExchangePattern:InOnly, BodyType:String, Body:Hello World]
WARN TransactionErrorHandler - 471691-0-3 - -2:2:1:1:1 -
Transaction rollback (0x4ab34646) redelivered(false) for (MessageId:
ID:davsclaus.lan-56013-1328258472923-2:2:1:1:1 on ExchangeId:
ID-davsclaus-lan-56008-1328258471691-0-3) caught:
java.lang.IllegalArgumentException: Forced exception
2nd message
INFO before - 471691-0-4 - -2:2:1:1:1 -
Exchange[ExchangePattern:InOnly, BodyType:String, Body:Hello World]
WARN TransactionErrorHandler - 471691-0-4 - -2:2:1:1:1 -
Transaction rollback (0x4ab34646) redelivered(true) for (MessageId:
ID:davsclaus.lan-56013-1328258472923-2:2:1:1:1 on ExchangeId:
ID-davsclaus-lan-56008-1328258471691-0-4) caught:
java.lang.IllegalArgumentException: Forced exception
3rd message
INFO before - 471691-0-5 - -2:2:1:1:1 -
Exchange[ExchangePattern:InOnly, BodyType:String, Body:Hello World]
So what you can see is that the exchangeID is unique, as it goes 0-3, 0-4, 0-5. Where as MessageID is the same as its 2:2:1:1:1.
That is not all, I have also added a new JMX attribute, so you from JMX
can see how many external redelivered messages a Camel route has
processed.
JMX Statistics
So the JMX statistics for the route would be as follows for this example.
1st message
ExchangesTotal: 1
ExchangesCompleted: 0
ExchangesFailed: 1
ExternalRedeliveries: 0
Redeliveries: 0 (internal)
2nd message
ExchangesTotal: 2
ExchangesCompleted: 0
ExchangesFailed: 2
ExternalRedeliveries: 1
Redeliveries: 0 (internal)
3rd message
ExchangesTotal: 3
ExchangesCompleted: 1
ExchangesFailed: 2
ExternalRedeliveries: 2
Redeliveries: 0 (internal)
The new attribute is ExternalRedeliveries. Notice in the 3rd message, we
can see that we have processed 3 messages, however 2 of them failed,
and 1 was successfully. Beforehand you could not see from this
information that it was in face the same message. It could just as well
be 3 different messages, where it just happens only 1 could be
processed successfully. Now you can know how many unique messages a
route has processed by calculating: ExchangesTotal -
ExternalRedeliveries. So in our example that would mean: 3 - 2 = 1.
I am considering improving this a bit more. I fell that that Camel
should log at INFO level if a external redelivered message was
committed. This would allow you to see this from the logs. This allows
you to know that the message was eventually processed successfully. As
the alternative would be that ActiveMQ would move the message to its
Dead Letter Queue. And when this happens, Camel would not know, and you
cannot see this from the Camel logs. Likewise I consider making
adjusting the logging levels for transaction begin and commit
configurable. They are currently fixed at DEBUG level.
If you have feedback upon this then feel free to comment on the blog, or reach out to the Camel community.
by
Comments