Hello,
I just noticed an issue in our app, that http redelivery was sending
extra messages to the target url. I first thought it to be related to
jms transactions, but with a closer look this happens with just a
simple retry.
Here is a simple test case to view the result. The message should be
sent twice (original and retry), but it gets sent four times.
import org.apache.camel.Exchange;
import org.apache.camel.LoggingLevel;
import org.apache.camel.builder.RouteBuilder;
import org.springframework.stereotype.Component;
@Component
public class TestRoute extends RouteBuilder {
private static final String DIRECT_EXHAUSTED = "direct:exhausted";
private static final long DEFAULT_RESPONSE_CODE = 503;
public static final String SINK = "http://localhost:29999/sink";;
@Override
public void configure() {
errorHandler(deadLetterChannel(DIRECT_EXHAUSTED).maximumRedeliveries(1).redeliveryDelay(10000).logExhausted(false));
from("timer:camel-timer?repeatCount=1")
.setBody(constant("Hello world!"))
.log(LoggingLevel.INFO, "This is request ")
.to(SINK);
from(DIRECT_EXHAUSTED)
.routeId("exhausted")
.log(LoggingLevel.INFO, "Retries exhausted ${exception}");
from("jetty:"+SINK)
.log("Request headers: ${headers}")
.setHeader(Exchange.HTTP_RESPONSE_CODE,
constant(DEFAULT_RESPONSE_CODE))
.log("Finished");
}
}
When I set http activity logging to be used, it sent the message only
twice and failed with a null pointer exception in the logger. I
created a simpler logger to just log the invocations without anything
that could fail when values are null
import org.apache.camel.Exchange;
import org.apache.camel.component.http.HttpActivityListener;
import org.apache.hc.core5.http.HttpEntity;
import org.apache.hc.core5.http.HttpHost;
import org.apache.hc.core5.http.HttpResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.apache.hc.core5.http.HttpRequest;
@Component
public class HttpActivityLogger implements HttpActivityListener {
private static final Logger LOGGER =
LoggerFactory.getLogger(HttpActivityLogger.class);
@Override
public void onRequestSubmitted(Object source, Exchange exchange,
HttpHost host, HttpRequest request, HttpEntity entity) {
LOGGER.info("{} onRequestSubmitted: {}", exchange, source);
LOGGER.trace("{} Stack trace: {}", exchange,
Thread.currentThread().getStackTrace());
}
@Override
public void onResponseReceived(Object source, Exchange exchange,
HttpHost host, HttpResponse response, HttpEntity entity, long elapsed)
{
LOGGER.info("{} Spent {} milliseconds", exchange, elapsed);
}
}
Here is the log from the execution where the extra call with null
exchange occurs a few milliseconds later that the original
2025-09-25T10:32:22.403+03:00 Apache Camel 4.10.6 (camel-1) started in
362ms (build:0ms init:0ms start:362ms boot:985ms)
2025-09-25T10:32:22.405+03:00 Started CamelTestApplication in 2.671
seconds (process running for 3.157)
2025-09-25T10:32:23.416+03:00 This is request
2025-09-25T10:32:23.455+03:00
Exchange[DDE7F0CB4616F92-0000000000000000] onRequestSubmitted:
org.apache.camel.component.http.HttpEndpoint$1@427b9a63
2025-09-25T10:32:23.548+03:00 Request headers: {Accept-Encoding=gzip,
x-gzip, deflate, CamelHttpMethod=POST, CamelHttpPath=,
CamelHttpQuery=null, CamelHttpUri=/sink,
CamelHttpUrl=http://localhost:29999/sink,
CamelServletContextPath=/sink, Connection=keep-alive,
Content-Length=12, Host=localhost:29999,
User-Agent=Apache-HttpClient/5.5 (Java/17.0.15)}
2025-09-25T10:32:23.548+03:00 Finished
2025-09-25T10:32:23.562+03:00
Exchange[DDE7F0CB4616F92-0000000000000000] Spent 106 milliseconds
2025-09-25T10:32:24.574+03:00 null onRequestSubmitted:
org.apache.camel.component.http.HttpEndpoint$1@427b9a63
2025-09-25T10:32:24.576+03:00 Request headers: {Accept-Encoding=gzip,
x-gzip, deflate, CamelHttpMethod=POST, CamelHttpPath=,
CamelHttpQuery=null, CamelHttpUri=/sink,
CamelHttpUrl=http://localhost:29999/sink,
CamelServletContextPath=/sink, Connection=keep-alive,
Content-Length=12, Host=localhost:29999,
User-Agent=Apache-HttpClient/5.5 (Java/17.0.15)}
2025-09-25T10:32:24.576+03:00 Finished
2025-09-25T10:32:24.577+03:00 null Spent 3 milliseconds
2025-09-25T10:32:34.591+03:00
Exchange[DDE7F0CB4616F92-0000000000000000] onRequestSubmitted:
org.apache.camel.component.http.HttpEndpoint$1@427b9a63
2025-09-25T10:32:34.592+03:00 Request headers: {Accept-Encoding=gzip,
x-gzip, deflate, CamelHttpMethod=POST, CamelHttpPath=,
CamelHttpQuery=null, CamelHttpUri=/sink,
CamelHttpUrl=http://localhost:29999/sink,
CamelServletContextPath=/sink, Connection=keep-alive,
Content-Length=12, Host=localhost:29999,
User-Agent=Apache-HttpClient/5.5 (Java/17.0.15)}
2025-09-25T10:32:34.593+03:00 Finished
2025-09-25T10:32:34.594+03:00
Exchange[DDE7F0CB4616F92-0000000000000000] Spent 2 milliseconds
2025-09-25T10:32:35.599+03:00 null onRequestSubmitted:
org.apache.camel.component.http.HttpEndpoint$1@427b9a63
2025-09-25T10:32:35.601+03:00 Request headers: {Accept-Encoding=gzip,
x-gzip, deflate, CamelHttpMethod=POST, CamelHttpPath=,
CamelHttpQuery=null, CamelHttpUri=/sink,
CamelHttpUrl=http://localhost:29999/sink,
CamelServletContextPath=/sink, Connection=keep-alive,
Content-Length=12, Host=localhost:29999,
User-Agent=Apache-HttpClient/5.5 (Java/17.0.15)}
2025-09-25T10:32:35.601+03:00 Finished
2025-09-25T10:32:35.602+03:00 null Spent 2 milliseconds
2025-09-25T10:32:35.606+03:00 Retries exhausted
org.apache.camel.http.base.HttpOperationFailedException: HTTP
operation failed invoking http://localhost:29999/sink with statusCode:
503
To me this looks like a bug in the retry logic, based on the exchange
being null in that unwanted call.
I tested this with camel 4.14.0 and 4.10.6 and both behave the same way.
--
Veijo Länsikunnas
