Chapter 20. Log

The log:clear command clears the log entries.

The log:display command displays the log entries.

By default, it displays the log entries of the rootLogger:

karaf@root()> log:display
2015-07-01 19:12:46,208 | INFO  | FelixStartLevel  | SecurityUtils                    | 16 - org.apache.sshd.core - 0.12.0 | BouncyCastle not registered, using the default JCE provider
2015-07-01 19:12:47,368 | INFO  | FelixStartLevel  | core                             | 68 - org.apache.aries.jmx.core - 1.1.1 | Starting JMX OSGi agent

You can also display the log entries from a specific logger, using the logger argument:

karaf@root()> log:display ssh
2015-07-01 19:12:46,208 | INFO  | FelixStartLevel  | SecurityUtils                    | 16 - org.apache.sshd.core - 0.12.0 | BouncyCastle not registered, using the default JCE provider

By default, all log entries will be displayed. It could be very long if your Apache Karaf container is running since a long time. You can limit the number of entries to display using the -n option:

karaf@root()> log:display -n 5
2015-07-01 06:53:24,143 | INFO  | JMX OSGi Agent   | core                             | 68 - org.apache.aries.jmx.core - 1.1.1 | Registering org.osgi.jmx.framework.BundleStateMBean to MBeanServer com.sun.jmx.mbeanserver.JmxMBeanServer@27cc75cb with name osgi.core:type=bundleState,version=1.7,framework=org.apache.felix.framework,uuid=5335370f-9dee-449f-9b1c-cabe74432ed1
2015-07-01 06:53:24,150 | INFO  | JMX OSGi Agent   | core                             | 68 - org.apache.aries.jmx.core - 1.1.1 | Registering org.osgi.jmx.framework.PackageStateMBean to MBeanServer com.sun.jmx.mbeanserver.JmxMBeanServer@27cc75cb with name osgi.core:type=packageState,version=1.5,framework=org.apache.felix.framework,uuid=5335370f-9dee-449f-9b1c-cabe74432ed1
2015-07-01 06:53:24,150 | INFO  | JMX OSGi Agent   | core                             | 68 - org.apache.aries.jmx.core - 1.1.1 | Registering org.osgi.jmx.framework.ServiceStateMBean to MBeanServer com.sun.jmx.mbeanserver.JmxMBeanServer@27cc75cb with name osgi.core:type=serviceState,version=1.7,framework=org.apache.felix.framework,uuid=5335370f-9dee-449f-9b1c-cabe74432ed1
2015-07-01 06:53:24,152 | INFO  | JMX OSGi Agent   | core                             | 68 - org.apache.aries.jmx.core - 1.1.1 | Registering org.osgi.jmx.framework.wiring.BundleWiringStateMBean to MBeanServer com.sun.jmx.mbeanserver.JmxMBeanServer@27cc75cb with name osgi.core:type=wiringState,version=1.1,framework=org.apache.felix.framework,uuid=5335370f-9dee-449f-9b1c-cabe74432ed1
2015-07-01 06:53:24,501 | INFO  | FelixStartLevel  | RegionsPersistenceImpl           | 78 - org.apache.karaf.region.persist - 4.0.0 | Loading region digraph persistence

You can also limit the number of entries stored and retained using the size property in etc/org.apache.karaf.log.cfg file:

#
# The number of log statements to be displayed using log:display. It also defines the number
# of lines searched for exceptions using log:display exception. You can override this value
# at runtime using -n in log:display.
#
size = 500

By default, each log level is displayed with a different color: ERROR/FATAL are in red, DEBUG in purple, INFO in cyan, etc. You can disable the coloring using the --no-color option.

The log entries format pattern doesn’t use the conversion pattern define in etc/org.ops4j.pax.logging.cfg file. By default, it uses the pattern property defined in etc/org.apache.karaf.log.cfg.

#
# The pattern used to format the log statement when using log:display. This pattern is according
# to the log4j2 layout. You can override this parameter at runtime using log:display with -p.
#
pattern = %d{ISO8601} | %-5.5p | %-16.16t | %-32.32c{1} | %X{bundle.id} - %X{bundle.name} - %X{bundle.version} | %m%n

You can also change the pattern dynamically (for one execution) using the -p option:

karaf@root()> log:display -p "\%d - \%c - \%m\%n"
2015-07-01 07:01:58,007 - org.apache.sshd.common.util.SecurityUtils - BouncyCastle not registered, using the default JCE provider
2015-07-01 07:01:58,725 - org.apache.aries.jmx.core - Starting JMX OSGi agent
2015-07-01 07:01:58,744 - org.apache.aries.jmx.core - Registering MBean with ObjectName [osgi.compendium:service=cm,version=1.3,framework=org.apache.felix.framework,uuid=6361fc65-8df4-4886-b0a6-479df2d61c83] for service with service.id [13]
2015-07-01 07:01:58,747 - org.apache.aries.jmx.core - Registering org.osgi.jmx.service.cm.ConfigurationAdminMBean to MBeanServer com.sun.jmx.mbeanserver.JmxMBeanServer@27cc75cb with name osgi.compendium:service=cm,version=1.3,framework=org.apache.felix.framework,uuid=6361fc65-8df4-4886-b0a6-479df2d61c83

The pattern is a regular Log4j2 pattern where you can use keywords such as %d for the date, %c for the class, %m for the log message, etc.

The log:exception-display command displays the last occurred exception.

As for log:display command, the log:exception-display command uses the rootLogger by default, but you can specify a logger with the logger argument.

The log:get command show the current log level of a logger.

By default, the log level shown is the one from the root logger:

karaf@root()> log:get
Logger                              │ Level
────────────────────────────────────┼──────
ROOT                                │ INFO
org.apache.aries.spifly             │ WARN
org.apache.karaf.jaas.modules.audit │ INFO
org.apache.sshd                     │ INFO

You can specify a particular logger using the logger argument:

karaf@root()> log:get ssh
INFO

The logger argument accepts the ALL keyword to display the log level of all logger (as a list).

For example, if you have defined your own logger in etc/org.ops4j.pax.logging.cfg file like this:

log4j2.logger.my.name = MyLogger
log4j2.logger.my.level = DEBUG

you can see the list of loggers with the corresponding log level:

karaf@root()> log:get ALL
Logger                              │ Level
────────────────────────────────────┼──────
MyLogger                            │ DEBUG
ROOT                                │ INFO
org.apache.aries.spifly             │ WARN
org.apache.karaf.jaas.modules.audit │ INFO
org.apache.sshd                     │ INFO

The log:list command is an alias to log:get ALL.

The log:log command allows you to manually add a message in the log. It’s interesting when you create Apache Karaf scripts:

karaf@root()> log:log "Hello World"
karaf@root()> log:display
12:55:21.706 INFO [pipe-log:log "Hello World"] Hello World

By default, the log level is INFO, but you can specify a different log level using the -l option:

karaf@root()> log:clear
karaf@root()> log:log -l ERROR "Hello World"
karaf@root()> log:display
12:55:41.460 ERROR [pipe-log:log "Hello World"] Hello World

The log:set command sets the log level of a logger.

By default, it changes the log level of the rootLogger:

karaf@root()> log:set DEBUG
karaf@root()> log:get
Logger                              │ Level
────────────────────────────────────┼──────
ROOT                                │ DEBUG
...

You can specify a particular logger using the logger argument, after the level one:

karaf@root()> log:set INFO my.logger
karaf@root()> log:get my.logger
Logger    | Level
-----------------
my.logger | INFO

The level argument accepts any Log4j2 log level: TRACE, DEBUG, INFO, WARN, ERROR, FATAL.

By it also accepts the DEFAULT special keyword.

The purpose of the DEFAULT keyword is to delete the current level of the logger (and only the level, the other properties like appender are not deleted) in order to use the level of the logger parent (logger are hierarchical).

For example, you have defined the following loggers (in etc/org.ops4j.pax.logging.cfg file):

rootLogger=INFO,out,osgi:*
my.logger=INFO,appender1
my.logger.custom=DEBUG,appender2

You can change the level of my.logger.custom logger:

karaf@root()> log:set INFO my.logger.custom

Now we have:

rootLogger=INFO,out,osgi:*
my.logger=INFO,appender1
my.logger.custom=INFO,appender2

You can use the DEFAULT keyword on my.logger.custom logger to remove the level:

karaf@root()> log:set DEFAULT my.logger.custom

Now we have:

rootLogger=INFO,out,osgi:*
my.logger=INFO,appender1
my.logger.custom=appender2

It means that, at runtime, the my.logger.custom logger uses the level of its parent my.logger, so INFO.

Now, if we use DEFAULT keyword with the my.logger logger:

karaf@root()> log:set DEFAULT my.logger

We have:

rootLogger=INFO,out,osgi:*
my.logger=appender1
my.logger.custom=appender2

So, both my.logger.custom and my.logger use the log level of the parent rootLogger.

It’s not possible to use DEFAULT keyword with the rootLogger and it doesn’t have parent.

The log:tail is exactly the same as log:display but it continuously displays the log entries.

You can use the same options and arguments as for the log:display command.

By default, it displays the entries from the rootLogger:

karaf@root()> log:tail
2015-07-01 07:40:28,152 | INFO  | FelixStartLevel  | SecurityUtils                    | 16 - org.apache.sshd.core - 0.9.0 | BouncyCastle not registered, using the default JCE provider
2015-07-01 07:40:28,909 | INFO  | FelixStartLevel  | core                             | 68 - org.apache.aries.jmx.core - 1.1.1 | Starting JMX OSGi agent
2015-07-01 07:40:28,928 | INFO  | FelixStartLevel  | core                             | 68 - org.apache.aries.jmx.core - 1.1.1 | Registering MBean with ObjectName [osgi.compendium:service=cm,version=1.3,framework=org.apache.felix.framework,uuid=b44a44b7-41cd-498f-936d-3b12d7aafa7b] for service with service.id [13]
2015-07-01 07:40:28,936 | INFO  | JMX OSGi Agent   | core                             | 68 - org.apache.aries.jmx.core - 1.1.1 | Registering org.osgi.jmx.service.cm.ConfigurationAdminMBean to MBeanServer com.sun.jmx.mbeanserver.JmxMBeanServer@27cc75cb with name osgi.compendium:service=cm,version=1.3,framework=org.apache.felix.framework,uuid=b44a44b7-41cd-498f-936d-3b12d7aafa7b

To exit from the log:tail command, just type CTRL-C.

Fuse-Karaf provides sample (commented out by default) configuration of Log4j2 sift appender and a logger using this appender in $FUSE_HOME/etc/org.ops4j.pax.logging.cfg file:

# Sift appender
log4j2.appender.mdc.type = Routing
log4j2.appender.mdc.name = SiftAppender
log4j2.appender.mdc.routes.type = Routes
# see: http://logging.apache.org/log4j/2.x/manual/appenders.html#Routes
log4j2.appender.mdc.routes.pattern = $\\{ctx:bundle.name}
log4j2.appender.mdc.routes.sift.type = Route
log4j2.appender.mdc.routes.sift.appender.type = RollingRandomAccessFile
log4j2.appender.mdc.routes.sift.appender.name = RollingFile
log4j2.appender.mdc.routes.sift.appender.fileName = ${karaf.data}/log/sift-$\\{ctx:bundle.name}.log
log4j2.appender.mdc.routes.sift.appender.filePattern = ${karaf.data}/log/sift-$\\{ctx:bundle.name}-%i.log.gz
log4j2.appender.mdc.routes.sift.appender.append = true
log4j2.appender.mdc.routes.sift.appender.layout.type = PatternLayout
log4j2.appender.mdc.routes.sift.appender.layout.pattern = ${log4j2.pattern}
log4j2.appender.mdc.routes.sift.appender.policies.type = Policies
log4j2.appender.mdc.routes.sift.appender.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.mdc.routes.sift.appender.policies.size.size = 16MB
log4j2.appender.mdc.routes.sift.appender.strategy.type = DefaultRolloverStrategy
log4j2.appender.mdc.routes.sift.appender.strategy.max = 20
...
# sample logger using Sift appender
#log4j2.logger.example.name = org.apache.camel
#log4j2.logger.example.level = INFO
#log4j2.logger.example.appenderRef.SiftAppender.ref = SiftAppender

The configuration is described in http://logging.apache.org/log4j/2.x/manual/appenders.html#RoutingAppender

pattern property of SIFT/Routing appender is what can be used to distinguish the target locations for logging.

There are different lookups available and described here: http://logging.apache.org/log4j/2.x/manual/lookups.html

the most important lookup is ctx one, which looks up the values (keys) in ThreadContext map (a.k.a. MDC).

The default configuration provided by Fuse Karaf uses ctx:bundle.name as the pattern, which means:

lookup bundle.name key in MDC

the bundle. prefixed keys are provided by pax-logging itself and there are 3 different values to choose from:

However, if Camel context is created with MDC support using (blueprint XML DSL):

<camelContext id="my-context" xmlns="http://camel.apache.org/schema/blueprint" useMDCLogging="true">

there will me more keys available in MDC/ThreadContext, which then can be used as a pattern in SIFT appender configuration:

See https://people.apache.org/~dkulp/camel/mdc-logging.html

So for example, in order to distinguish logging destination files by Camel’s route ID, please use:

log4j2.appender.mdc.routes.pattern = $\\{ctx:camel.routeId}
...
log4j2.appender.mdc.routes.sift.appender.fileName = ${karaf.data}/log/sift-$\\{ctx:camel.routeId}.log
log4j2.appender.mdc.routes.sift.appender.filePattern = ${karaf.data}/log/sift-$\\{ctx:camel.routeId}-%i.log.gz

One more thing - sole appender configuration is not enough - you have to attach it to some logger. Again, sample configuration contains:

# sample logger using Sift appender
#log4j2.logger.example.name = org.apache.camel
#log4j2.logger.example.level = INFO
#log4j2.logger.example.appenderRef.SiftAppender.ref = SiftAppender

(note that SiftAppender value of log4j2.logger.example.appenderRef.SiftAppender.ref property should match the value of log4j2.appender.mdc.name in the appender configuration).

Here, org.apache.camel is a logger name (or category name). This is exactly the same value that’s used in Camel’s log: endpoint. So if you have (in Camel route):

<to uri="log:org.apache.camel" />

The logging would work.

Another working configuration would be:

<to uri="log:my-special-logger" />

and:

log4j2.logger.example.name = my-special-logger
log4j2.logger.example.level = DEBUG
log4j2.logger.example.appenderRef.SiftAppender.ref = SiftAppender

You can apply a filter to an appender. A filter evaluates each log event and determines whether to send it to the log.

Log4j2 provides ready to use filters.

A nested appender is a special kind of appender that you use "inside" another appender. It allows you to create some kind of "routing" between a chain of appenders.

The most used "nested compliant" appenders are:

This kind of appender accepts an appenders property in the appender definition:

log4j2.appender.[appender-name].appenders=[comma-separated-list-of-appender-names]

For example, you can create an AsyncAppender named async and asynchronously dispatch the log events to a JMS appender:

log4j2.appender.async=org.apache.log4j2.AsyncAppender
log4j2.appender.async.appenders=jms

log4j2.appender.jms=org.apache.log4j2.net.JMSAppender
...

Sometimes, appenders can fail. For example, a RollingFileAppender tries to write to the filesystem, but the filesystem is full, or a JMS appender tries to send a message, but the JMS broker is unavailable.

Logging can be critical so it is important to know if the log appender fails.

Each log appender can delegate error handling to an error handler, which provides a chance to react to an appender error.

You can define the error handler that you want to use for each appender using the errorhandler property on the appender definition itself:

log4j2.appender.[appender-name].errorhandler=[error-handler-class]
log4j2.appender.[appender-name].errorhandler.root-ref=[true|false]
log4j2.appender.[appender-name].errorhandler.logger-ref=[logger-ref]
log4j2.appender.[appender-name].errorhandler.appender-ref=[appender-ref]

The routing appender is a OSGi oriented appender allowing you to split the log events based on MDC (Mapped Diagnostic Context) attributes.

MDC allows you to distinguish the different source of log events.

The routing appender provides OSGi-oriented MDC attributes by default:

You can use these MDC properties to create a log file per bundle:

log4j2.appender.routing.type = Routing
log4j2.appender.routing.name = Routing
log4j2.appender.routing.routes.type = Routes
log4j2.appender.routing.routes.pattern = $$\\{ctx:bundle.name\\}
log4j2.appender.routing.routes.bundle.type = Route
log4j2.appender.routing.routes.bundle.appender.type = RollingRandomAccessFile
log4j2.appender.routing.routes.bundle.appender.name = Bundle-$\\{ctx:bundle.name\}
log4j2.appender.routing.routes.bundle.appender.fileName = ${karaf.data}/log/bundle-$\\{ctx:bundle.name\\}.log
log4j2.appender.routing.routes.bundle.appender.filePattern = ${karaf.data}/log/bundle-$\\{ctx:bundle.name\\}.log.%d{yyyy-MM-dd}
log4j2.appender.routing.routes.bundle.appender.append = true
log4j2.appender.routing.routes.bundle.appender.layout.type = PatternLayout
log4j2.appender.routing.routes.bundle.appender.policies.type = Policies
log4j2.appender.routing.routes.bundle.appender.policies.time.type = TimeBasedTriggeringPolicy
log4j2.appender.routing.routes.bundle.appender.strategy.type = DefaultRolloverStrategy
log4j2.appender.routing.routes.bundle.appender.strategy.max = 31

log4j2.rootLogger.appenderRef.Routing.ref = Routing

By default, Apache Karaf provides a special stack trace renderer, adding some OSGi specific specific information.

In the stack trace, in addition of the class throwing the exception, you can find a pattern [id:name:version] at the end of each stack trace line, where:

It’s very helpful to diagnosing the source of an issue.

For example, in the following IllegalArgumentException stack trace, we can see the OSGi details about the source of the exception:

java.lang.IllegalArgumentException: Command not found:  *:foo
	at org.apache.felix.gogo.runtime.shell.Closure.execute(Closure.java:225)[21:org.apache.karaf.shell.console:4.0.0]
	at org.apache.felix.gogo.runtime.shell.Closure.executeStatement(Closure.java:162)[21:org.apache.karaf.shell.console:4.0.0]
	at org.apache.felix.gogo.runtime.shell.Pipe.run(Pipe.java:101)[21:org.apache.karaf.shell.console:4.0.0]
	at org.apache.felix.gogo.runtime.shell.Closure.execute(Closure.java:79)[21:org.apache.karaf.shell.console:4.0.0]
	at org.apache.felix.gogo.runtime.shell.CommandSessionImpl.execute(CommandSessionImpl.java:71)[21:org.apache.karaf.shell.console:4.0.0]
	at org.apache.karaf.shell.console.jline.Console.run(Console.java:169)[21:org.apache.karaf.shell.console:4.0.0]
	at java.lang.Thread.run(Thread.java:637)[:1.7.0_21]

You can use your own appenders in Apache Karaf.

The easiest way to do that is to package your appender as an OSGi bundle and attach it as a fragment of the org.ops4j.pax.logging.pax-logging-service bundle.

For example, you create MyAppender:

public class MyAppender extends AppenderSkeleton {
...
}

You compile and package as an OSGi bundle containing a MANIFEST looking like:

Manifest:
Bundle-SymbolicName: org.mydomain.myappender
Fragment-Host: org.ops4j.pax.logging.pax-logging-service
...

Copy your bundle in the Apache Karaf system folder. The system folder uses a standard Maven directory layout: groupId/artifactId/version.

In the etc/startup.properties configuration file, you define your bundle in the list before the pax-logging-service bundle.

You have to restart Apache Karaf with a clean run (purging the data folder) in order to reload the system bundles. You can now use your appender directly in etc/org.ops4j.pax.logging.cfg configuration file.