MDC quirks, parallel multicast

[Jan Winkler <wi...@pinerecords.com>]

Hello,

I've been poking around Camel's MDC logging, and I have a few questions to
ask.

Consider the following route:

  from("direct:start")
      .to("log:com.example.LOG?level=WARN")
      .multicast()
          .parallelProcessing()
          .timeout(50)
          .to("log:com.example.LOG?level=WARN")
          .to("log:com.example.LOG?level=WARN")
          .to("log:com.example.LOG?level=WARN")
          .process(exchange -> {
              try {
                  log.warn("causing a timeout...");
                  Thread.sleep(200);
                  log.error("...but we haven't, actually.");
              } finally {
                  log.warn("thread done");
              }
          })
          .aggregationStrategy((exchange, exchange1) -> {
              log.warn("aggregating");
              return exchange;
          })
      .end()
      .to("log:com.example.LOG?level=WARN");

With MDC logging enabled, after
producerTemplate.requestBody("direct:start", "TESTBODY"), the log looks
like this (the first square brackets contain MDC correlation id, the log
is filtered to show only relevant entries, i. e., those corresponding to
logging calls in the route definition above):

  W 00:21:49.844 [                                ] [main                                                            ] c.e.LOG   - Exchange[ExchangePattern: InOut, BodyType: String, Body: TESTBODY]
  W 00:21:49.853 [ID-xxxxx-40869-1487114509043-0-2] [Camel (camel-1) thread #4 - Multicast                           ] c.e.Route - causing a timeout...
  W 00:21:49.853 [ID-xxxxx-40869-1487114509043-0-2] [Camel (camel-1) thread #1 - Multicast                           ] c.e.LOG   - Exchange[ExchangePattern: InOut, BodyType: String, Body: TESTBODY]
  W 00:21:49.853 [ID-xxxxx-40869-1487114509043-0-2] [Camel (camel-1) thread #2 - Multicast                           ] c.e.LOG   - Exchange[ExchangePattern: InOut, BodyType: String, Body: TESTBODY]
  W 00:21:49.859 [ID-xxxxx-40869-1487114509043-0-2] [Camel (camel-1) thread #0 - Multicast                           ] c.e.LOG   - Exchange[ExchangePattern: InOut, BodyType: String, Body: TESTBODY]
  W 00:21:49.859 [                                ] [Camel (camel-1) thread #3 - MulticastProcessor-AggregateTask    ] c.e.Route - aggregating
  W 00:21:49.860 [                                ] [Camel (camel-1) thread #3 - MulticastProcessor-AggregateTask    ] c.e.Route - aggregating
  W 00:21:49.860 [                                ] [Camel (camel-1) thread #3 - MulticastProcessor-AggregateTask    ] c.e.Route - aggregating
  W 00:21:49.903 [                                ] [Camel (camel-1) thread #3 - MulticastProcessor-AggregateTask    ] o.a.c.p.MulticastProcessor - Parallel processing timed out after 50 millis for number 3. This task will be cancelled and will not be aggregated.
  W 00:21:49.905 [                                ] [main                                                            ] c.e.LOG   - Exchange[ExchangePattern: InOut, BodyType: String, Body: TESTBODY]
  W 00:21:49.934 [ID-xxxxx-40869-1487114509043-0-2] [Camel (camel-1) thread #4 - Multicast                           ] c.e.Route - thread done

I'd expect all these entries to have correlation id set, as well as all
the other camel MDC variables, but that's not the case.

  1) The log calls at the route start and end lack MDC variables.

  2) The AggregatorTask logging -- and thus AggregationStrategy, too --
     lacks MDC as well. This holds true even without
     .parallelProcessing().

Why? Am I doing something wrong? Are these bugs?

Libs used:

  - camel 2.18.2
  - slf4j 1.7.22
  - logback-classic 1.1.9
  - spring-boot 1.5.1.RELEASE

Cheers,

Jan

PS. If needed, I can provide a simple spring boot project.