Hide
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:14:43:35,206 | INFO | - timer: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:14:43:40,182 | INFO | - timer: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:14:43:45,184 | INFO | - timer: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:14:43:50,184 | INFO | - timer: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:14:43:55,185 | INFO | - timer: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:14:43:35,206 | INFO | - timer: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:14:43:40,182 | INFO | - timer: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:14:43:45,184 | INFO | - timer: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:14:43:50,184 | INFO | - timer: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:14:43:55,185 | INFO | - timer: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:14:43:35,206 | INFO | - timer: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:14:43:40,182 | INFO | - timer: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" />
Show
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" />