MDC Sift logging is not consistently produced

Enable SIFT in org.ops4j.pax.logging.cfg as follows: # Root logger log4j.rootLogger = INFO, out, sift, osgi:VmLogAppender . . . # Sift appender log4j.appender.sift=org.apache.log4j.sift.MDCSiftingAppender #log4j.appender.sift.key=bundle.name log4j.appender.sift.key=camel.contextId log4j.appender.sift. default =servicemix log4j.appender.sift.appender=org.apache.log4j.FileAppender log4j.appender.sift.appender.layout=org.apache.log4j.PatternLayout log4j.appender.sift.appender.layout.ConversionPattern=%d{ABSOLUTE} | %-5.5p | %-16.16t | %-32.32c{1} | %m%n #log4j.appender.sift.appender.file=${karaf.data}/log/$\\{bundle.name\\}.log log4j.appender.sift.appender.file=${karaf.data}/log/$\\{camel.contextId\\}.log log4j.appender.sift.appender.append= true Start the 6.1 container. Extract the CamelTest.zip and please review the camel-context.xml file in the blueprint directory. Deploy the bundle into the Fuse 6.1 container, and then start the bundle. The Camel context is driven by a timer that fires off 5 messages - one at a time - that are sent and received to and from the embedded A-MQ broker. The Camel context and its routes generate the following (expected) INFO log statements, which are fully reflected in the fuse.log: 14:43:35,194 | INFO | - timer: //foo11 | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route has fired: 02-43-35 14:43:35,206 | INFO | - timer: //foo11 | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:entered with 02-43-35 14:43:35,260 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg1: message received = 02-43-35 14:43:35,283 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg2: message received = [rcvMsg1] 02-43-35 14:43:35,298 | INFO | r[TOOL.DEFAULT2] | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:completed with [rcvMsg2] [rcvMsg1] 02-43-35 14:43:35,299 | INFO | r[TOOL.DEFAULT2] | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route completed: [rcvMsg2] [rcvMsg1] 02-43-35 14:43:40,182 | INFO | - timer: //foo11 | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route has fired: 02-43-40 14:43:40,182 | INFO | - timer: //foo11 | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:entered with 02-43-40 14:43:40,185 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg1: message received = 02-43-40 14:43:40,189 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg2: message received = [rcvMsg1] 02-43-40 14:43:40,191 | INFO | r[TOOL.DEFAULT2] | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:completed with [rcvMsg2] [rcvMsg1] 02-43-40 14:43:40,191 | INFO | r[TOOL.DEFAULT2] | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route completed: [rcvMsg2] [rcvMsg1] 02-43-40 14:43:45,183 | INFO | - timer: //foo11 | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route has fired: 02-43-45 14:43:45,184 | INFO | - timer: //foo11 | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:entered with 02-43-45 14:43:45,187 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg1: message received = 02-43-45 14:43:45,192 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg2: message received = [rcvMsg1] 02-43-45 14:43:45,193 | INFO | r[TOOL.DEFAULT2] | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:completed with [rcvMsg2] [rcvMsg1] 02-43-45 14:43:45,194 | INFO | r[TOOL.DEFAULT2] | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route completed: [rcvMsg2] [rcvMsg1] 02-43-45 14:43:50,184 | INFO | - timer: //foo11 | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route has fired: 02-43-50 14:43:50,184 | INFO | - timer: //foo11 | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:entered with 02-43-50 14:43:50,186 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg1: message received = 02-43-50 14:43:50,189 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg2: message received = [rcvMsg1] 02-43-50 14:43:50,191 | INFO | r[TOOL.DEFAULT2] | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:completed with [rcvMsg2] [rcvMsg1] 02-43-50 14:43:50,192 | INFO | r[TOOL.DEFAULT2] | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route completed: [rcvMsg2] [rcvMsg1] 02-43-50 14:43:55,184 | INFO | - timer: //foo11 | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route has fired: 02-43-55 14:43:55,185 | INFO | - timer: //foo11 | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:entered with 02-43-55 14:43:55,187 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg1: message received = 02-43-55 14:43:55,234 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | rcvMsg2: message received = [rcvMsg1] 02-43-55 14:43:55,305 | INFO | r[TOOL.DEFAULT2] | sendMsg | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | direct:sendMsg:completed with [rcvMsg2] [rcvMsg1] 02-43-55 14:43:55,306 | INFO | r[TOOL.DEFAULT2] | timer-driver | 139 - org.apache.camel.camel-core - 2.12.0.redhat-611454 | Timer route completed: [rcvMsg2] [rcvMsg1] 02-43-55 However, if you look at the SIFT produced foo.bar.context.log, you'll note only partial output: 14:43:35,194 | INFO | - timer: //foo11 | timer-driver | Timer route has fired: 02-43-35 14:43:35,206 | INFO | - timer: //foo11 | sendMsg | direct:sendMsg:entered with 02-43-35 14:43:35,260 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | rcvMsg1: message received = 02-43-35 14:43:35,283 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | rcvMsg2: message received = [rcvMsg1] 02-43-35 14:43:35,298 | INFO | r[TOOL.DEFAULT2] | sendMsg | direct:sendMsg:completed with [rcvMsg2] [rcvMsg1] 02-43-35 14:43:35,299 | INFO | r[TOOL.DEFAULT2] | timer-driver | Timer route completed: [rcvMsg2] [rcvMsg1] 02-43-35 14:43:40,182 | INFO | - timer: //foo11 | timer-driver | Timer route has fired: 02-43-40 14:43:40,182 | INFO | - timer: //foo11 | sendMsg | direct:sendMsg:entered with 02-43-40 14:43:40,185 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | rcvMsg1: message received = 02-43-40 14:43:40,189 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | rcvMsg2: message received = [rcvMsg1] 02-43-40 14:43:45,183 | INFO | - timer: //foo11 | timer-driver | Timer route has fired: 02-43-45 14:43:45,184 | INFO | - timer: //foo11 | sendMsg | direct:sendMsg:entered with 02-43-45 14:43:45,187 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | rcvMsg1: message received = 02-43-45 14:43:45,192 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | rcvMsg2: message received = [rcvMsg1] 02-43-45 14:43:50,184 | INFO | - timer: //foo11 | timer-driver | Timer route has fired: 02-43-50 14:43:50,184 | INFO | - timer: //foo11 | sendMsg | direct:sendMsg:entered with 02-43-50 14:43:50,186 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | rcvMsg1: message received = 02-43-50 14:43:50,189 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | rcvMsg2: message received = [rcvMsg1] 02-43-50 14:43:55,184 | INFO | - timer: //foo11 | timer-driver | Timer route has fired: 02-43-55 14:43:55,185 | INFO | - timer: //foo11 | sendMsg | direct:sendMsg:entered with 02-43-55 14:43:55,187 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | rcvMsg1: message received = 02-43-55 14:43:55,234 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | rcvMsg2: message received = [rcvMsg1] 02-43-55 You'll note that only the first firing has the following complete and expected set of INFO statements: 14:43:35,194 | INFO | - timer: //foo11 | timer-driver | Timer route has fired: 02-43-35 14:43:35,206 | INFO | - timer: //foo11 | sendMsg | direct:sendMsg:entered with 02-43-35 14:43:35,260 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | rcvMsg1: message received = 02-43-35 14:43:35,283 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | rcvMsg2: message received = [rcvMsg1] 02-43-35 14:43:35,298 | INFO | r[TOOL.DEFAULT2] | sendMsg | direct:sendMsg:completed with [rcvMsg2] [rcvMsg1] 02-43-35 14:43:35,299 | INFO | r[TOOL.DEFAULT2] | timer-driver | Timer route completed: [rcvMsg2] [rcvMsg1] 02-43-35 Firings 2-5 have a partial set; take for example firing #2. 14:43:40,182 | INFO | - timer: //foo11 | timer-driver | Timer route has fired: 02-43-40 14:43:40,182 | INFO | - timer: //foo11 | sendMsg | direct:sendMsg:entered with 02-43-40 14:43:40,185 | INFO | r[TOOL.DEFAULT1] | rcvMsg1 | rcvMsg1: message received = 02-43-40 14:43:40,189 | INFO | r[TOOL.DEFAULT2] | rcvMsg2 | rcvMsg2: message received = [rcvMsg1] 02-43-40 What's missing are those INFO statements that follow the second send; i.e., <to uri= "jms:TOOL.DEFAULT2" pattern= "InOut" />