In an application that embeds an Apache Felix OSGi container, one of the first issues encountered is logging.
OSGi defines a standard log service through which code is expected to send log messages. However, most applications will be using third-party code that is not OSGi-aware and this code will therefore obviously not use an OSGi log service. Additionally, the available OSGi log service implementations tend to be rather feature-light compared to logging systems such as Logback and log4j, so even OSGi-aware code tends to shy away from the standard OSGi service. Finally, the Apache Felix implementation will use a custom logging implementation for any log messages generated by the framework itself if an OSGi log service has not been installed.
This leads to a rather chaotic arrangement. OSGi-aware code may or may not be logging to an OSGi log service that may or may not be present. Third party code will typically be using its own logging implementation. Messages coming from the Felix implementation itself may be going straight to the program’s standard error output, or it may be going to the available OSGi log service if there is one.
What would undoubtedly be preferable is if all messages were to go via a single logging API, including any log messages produced by the host, with all logging configured once by the host. In practice, there are four specific requirements:
Any log messages produced by the Apache Felix implementation must be logged to the host’s logging implementation.
Any log messages produced by code on the host must be logged to the host’s logging implementation.
Any log messages produced by OSGi-unaware code inside the OSGi container must be logged to the host’s logging implementation.
Any log messages produced by OSGi-aware code that is logging to the standard OSGi log service must end up being logged via the host’s logging implementation.
Technically, point 2 is trivial, but is listed here as an extra constraint (in other words, whatever logging solution is eventually picked must not break any existing logging solution for the host).
Thankfully, this problem can be alleviated with the SLF4J API, a custom OSGi log service and the abuse of the standard OSGi org.osgi.framework.system.packages.extra configuration property 1. No attempt is made to capture the log messages of code that does not log via the SLF4J API!
Directly quoting the SLF4J site:
The Simple Logging Facade for Java (SLF4J) serves as a simple facade or abstraction for various logging frameworks (e.g. java.util.logging, logback, log4j) allowing the end user to plug in the desired logging framework at deployment time.
In the author’s experience, most modern well-written library code is using this API rather than depending on specific implementations of it directly. Software that isn’t should be considered broken and should be patched. The key to making the desired logging arrangement work, then, is to expose the host’s logging implementation by making the SLF4J API available to the container. The SLF4J API jars are already published as OSGi bundles, and therefore doing this is trivial.
The assumption is that the host application will have the SLF4J API present on the classpath, in addition to a concrete logging implementation such as Logback or Log4j. By making the host’s SLF4J API available to the container directly, any bundles inside the container that use SLF4J will in effect send all of their messages through the host’s logging implementation. This can be achieved trivially by passing in the list of org.slf4j packages that should be exposed to the container via OSGi framework configuration properties. The standard org.osgi.framework.system.packages.extra property specifies a list of packages that will be resolved on the host when imported by a bundle inside the container:
Map<String, String> config = ...;
/*
* Expose the host's SLF4J API to the container. This ensures that
* any time a package requires SLF4J, the actual implementation will
* be resolved to the one on the host.
*/
final StringBuilder sb = new StringBuilder(128);
sb.append("org.slf4j; version=1.7.21");
sb.append(",");
sb.append("org.slf4j.*; version=1.7.21");
config.put("org.osgi.framework.system.packages.extra", sb.toString());
...
final Framework framework = frameworkFactory.newFramework(config);
framework.start();This solves requirement 3 above: Any code inside the container that tries to instantiate an SLF4J logger and log messages will end up doing so via the host’s logging implementation.
Now, it’s necessary to install a custom OSGi log service implementation that logs all messages using SLF4J. Thankfully, doing this is also trivial.
In OSGi, the log service is somewhat analogous to the SLF4J API: It is responsible for receiving log messages but is not responsible for actually putting those messages anywhere. OSGi also defines a log reader service, which is somewhat analogous to a concrete logging implementation such as Logback. A log reader service listens for log messages written to the log service and writes them to an implementation specific location. The basic implementation provided by Apache Felix simply writes messages to the program’s standard output. To be precise then, it’s actually necessary to implement a log reader service that logs all messages via SLF4J.
import org.osgi.service.log.LogEntry;
import org.osgi.service.log.LogListener;
import org.osgi.service.log.LogService;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
/**
* An SLF4J-based log reader.
*/
public final class SLF4JLogReader implements LogListener
{
private static final Logger LOG;
static {
LOG = LoggerFactory.getLogger(SLF4JLogReader.class);
}
SLF4JLogReader()
{
}
@Override
public void logged(final LogEntry entry)
{
final int level = entry.getLevel();
switch (level) {
case LogService.LOG_DEBUG: {
SLF4JLogReader.debug(entry);
break;
}
case LogService.LOG_ERROR: {
SLF4JLogReader.error(entry);
break;
}
case LogService.LOG_INFO: {
SLF4JLogReader.info(entry);
break;
}
case LogService.LOG_WARNING: {
SLF4JLogReader.warn(entry);
break;
}
default: {
SLF4JLogReader.warn(entry);
break;
}
}
}
private static void warn(final LogEntry entry)
{
final String name = entry.getBundle().getSymbolicName();
final String message = entry.getMessage();
final Throwable ex = entry.getException();
if (ex != null) {
SLF4JLogReader.LOG.warn("[{}]: {}: ", name, message, ex);
} else {
SLF4JLogReader.LOG.warn("[{}]: {}", name, message);
}
}
private static void info(final LogEntry entry)
{
final String name = entry.getBundle().getSymbolicName();
final String message = entry.getMessage();
final Throwable ex = entry.getException();
if (ex != null) {
SLF4JLogReader.LOG.info("[{}]: {}: ", name, message, ex);
} else {
SLF4JLogReader.LOG.info("[{}]: {}", name, message);
}
}
private static void error(final LogEntry entry)
{
final String name = entry.getBundle().getSymbolicName();
final String message = entry.getMessage();
final Throwable ex = entry.getException();
if (ex != null) {
SLF4JLogReader.LOG.error("[{}]: {}: ", name, message, ex);
} else {
SLF4JLogReader.LOG.error("[{}]: {}", name, message);
}
}
private static void debug(final LogEntry entry)
{
final String name = entry.getBundle().getSymbolicName();
final String message = entry.getMessage();
final Throwable ex = entry.getException();
if (ex != null) {
SLF4JLogReader.LOG.debug("[{}]: {}: ", name, message, ex);
} else {
SLF4JLogReader.LOG.debug("[{}]: {}", name, message);
}
}
}The above needs a bundle activator to register and unregister the log reader service. None of the following code is in any way specific to the logging implementation and should be sufficiently familiar to anyone that has written an OSGi service.
import org.osgi.framework.Bundle;
import org.osgi.framework.BundleActivator;
import org.osgi.framework.BundleContext;
import org.osgi.framework.InvalidSyntaxException;
import org.osgi.framework.ServiceEvent;
import org.osgi.framework.ServiceListener;
import org.osgi.framework.ServiceReference;
import org.osgi.service.log.LogReaderService;
import org.osgi.util.tracker.ServiceTracker;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.util.Iterator;
import java.util.LinkedList;
import java.util.List;
/**
* A bundle activator that adds an SLF4J-based log reader for every available
* log service.
*/
public final class Activator implements BundleActivator
{
private static final Logger LOG;
static {
LOG = LoggerFactory.getLogger(Activator.class);
}
private final SLF4JLogReader logger;
private final List<LogReaderService> readers;
private final ServiceListener listener;
private ServiceTracker<LogReaderService, LogReaderService> tracker;
public Activator()
{
this.logger = new SLF4JLogReader();
this.readers = new LinkedList<>();
/*
* Create a service listener that adds an SLF4J-based log reader every
* time a log service appears, and removes it when the log service
* disappears.
*/
this.listener = event -> {
final ServiceReference<?> ref = event.getServiceReference();
if (ref == null) {
return;
}
final Bundle bundle = ref.getBundle();
if (bundle == null) {
return;
}
final BundleContext context = bundle.getBundleContext();
if (context == null) {
return;
}
final LogReaderService reader = (LogReaderService) context.getService(ref);
if (reader != null) {
if (event.getType() == ServiceEvent.REGISTERED) {
LOG.debug("adding a log listener to {}", reader);
this.readers.add(reader);
reader.addLogListener(this.logger);
} else if (event.getType() == ServiceEvent.UNREGISTERING) {
LOG.debug("removing a log listener from {}", reader);
reader.removeLogListener(Activator.this.logger);
this.readers.remove(reader);
}
}
};
}
@Override
public void start(
final BundleContext context)
throws Exception
{
this.tracker =
new ServiceTracker<>(context, LogReaderService.class.getName(), null);
this.tracker.open();
final Object[] current_readers = this.tracker.getServices();
if (current_readers != null) {
for (int index = 0; index < current_readers.length; index++) {
final LogReaderService reader =
(LogReaderService) current_readers[index];
LOG.debug("adding a log listener to {}", reader);
this.readers.add(reader);
reader.addLogListener(this.logger);
}
}
final String filter =
"(objectclass=" + LogReaderService.class.getName() + ")";
try {
context.addServiceListener(this.listener, filter);
} catch (final InvalidSyntaxException e) {
Activator.LOG.error("error adding service listener: ", e);
}
}
@Override
public void stop(
final BundleContext context)
throws Exception
{
final Iterator<LogReaderService> iter = this.readers.iterator();
while (iter.hasNext()) {
final LogReaderService reader = iter.next();
LOG.debug("removing a log listener from {}", reader);
reader.removeLogListener(this.logger);
iter.remove();
}
this.tracker.close();
}
}With the above installed as a service, any code that logs to the standard OSGi log service will end up having its log events passed to the SLF4JLogReader implementation and ultimately to the host’s SLF4J implementation. This solves requirement 4!
Finally, any messages logged by Apache Felix must also be captured. The problem here is that the framework will produce log messages before any bundles have been installed and therefore those messages will be missed.
Felix provides a proprietary configuration property, felix.log.logger, that allows passing in an implementation of org.apache.felix.framework.Logger to be used by the framework for logging messages. An implementation of this is also trivial:
private static final class FelixLogger extends org.apache.felix.framework.Logger
{
private static final Logger LOG;
static {
LOG = LoggerFactory.getLogger(FelixLogger.class);
}
FelixLogger()
{
}
@Override
protected void doLog(
final Bundle bundle,
final ServiceReference sr,
final int level,
final String msg,
final Throwable throwable)
{
switch (level) {
case LOG_DEBUG: {
LOG.debug(
"[{}]: {}: ",
bundle.getSymbolicName(),
msg,
throwable);
break;
}
case LOG_ERROR: {
LOG.error(
"[{}]: {}: ",
bundle.getSymbolicName(),
msg,
throwable);
break;
}
case LOG_INFO: {
LOG.info("[{}]: {}: ", bundle.getSymbolicName(), msg, throwable);
break;
}
case LOG_WARNING: {
LOG.warn("[{}]: {}: ", bundle.getSymbolicName(), msg, throwable);
break;
}
}
}
@Override
protected void doLog(
final int level,
final String msg,
final Throwable throwable)
{
switch (level) {
case LOG_DEBUG: {
LOG.debug("{}: ", msg, throwable);
break;
}
case LOG_ERROR: {
LOG.error("{}: ", msg, throwable);
break;
}
case LOG_INFO: {
LOG.info("{}: ", msg, throwable);
break;
}
case LOG_WARNING: {
LOG.warn("{}: ", msg, throwable);
break;
}
}
}
}Unfortunately, the standard OSGi API accepts a map of configuration properties of type Map<String, String>, but passing in an instance of FelixLogger would require a map of type Map<String, Object>. Therefore, it’s necessary to abuse the Java subtyping rules to cast Map<String, Object> → Map<String, String> and rely on the fact that a standard OSGi implementation would not look at any property keys that would cause a runtime class cast exception.
final Map<String, Object> config = new HashMap<>();
config.put(FelixConstants.LOG_LEVEL_PROP, "999");
config.put(FelixConstants.LOG_LOGGER_PROP, new FelixLogger());
final Object cast = config;
@SuppressWarnings("unchecked")
final Map<String, String> config_strings = (Map<String, String>) cast;
final Framework framework = frameworkFactory.newFramework(config_strings);
framework.start();Placing all of the above into bundles as necessary, and adding a few test bundles that attempt to log to SLF4J and attempt to log to the standard OSGi log service, the program produces the following output (see comments inline):
[ 192] DEBUG com.io7m.osgilog2.main.Main: root: /tmp/osgilog2
[ 196] DEBUG com.io7m.osgilog2.main.Main: root cache: /tmp/osgilog2/cache
[ 196] DEBUG com.io7m.osgilog2.main.Main: root lib: /tmp/osgilog2/lib
[ 203] DEBUG com.io7m.osgilog2.main.Main: starting framework
[ 400] DEBUG com.io7m.osgilog2.main.Main: security manager: java.lang.SecurityManager@731a74c
[ 400] DEBUG com.io7m.osgilog2.main.Main: installing bundles
[ 400] DEBUG com.io7m.osgilog2.main.Main: installing org.apache.felix.framework.security (file:/tmp/osgilog2/lib/org.apache.felix.framework.security.jar)
[ 440] DEBUG com.io7m.osgilog2.main.Main: installing org.apache.felix.log (file:/tmp/osgilog2/lib/org.apache.felix.log.jar)
[ 442] DEBUG com.io7m.osgilog2.main.Main: installing logservice (file:/tmp/osgilog2/lib/logservice.jar)
[ 444] DEBUG com.io7m.osgilog2.main.Main: installing test-osgi-logging (file:/tmp/osgilog2/lib/test-osgi-logging.jar)
[ 446] DEBUG com.io7m.osgilog2.main.Main: installing test-logback (file:/tmp/osgilog2/lib/test-logback.jar)
[ 448] DEBUG com.io7m.osgilog2.main.Main: starting: org.apache.felix.framework.security [1]
[ 449] DEBUG com.io7m.osgilog2.main.Main: starting: org.apache.felix.log [2]The following lines are prefixed with Main$FelixLogger, which is sufficient to demonstrate that the Felix framework is logging messages via the provided FelixLogger:
[ 459] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [org.apache.felix.log [2](R 2.0)] osgi.wiring.package; (&(osgi.wiring.package=org.osgi.framework)(version>=1.4.0)(!(version>=2.0.0))) -> [org.apache.felix.framework [0](R 0)]:
[ 472] DEBUG com.io7m.osgilog2.main.Main: starting: com.io7m.osgilog2.logservice [3]
[ 484] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.logservice [3](R 3.0)] osgi.wiring.package; (&(osgi.wiring.package=org.osgi.framework)(version>=1.8.0)(!(version>=2.0.0))) -> [org.apache.felix.framework [0](R 0)]:
[ 484] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.logservice [3](R 3.0)] osgi.wiring.package; (&(osgi.wiring.package=org.osgi.service.log)(version>=1.3.0)(!(version>=2.0.0))) -> [org.apache.felix.log [2](R 2.0)]:
[ 484] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.logservice [3](R 3.0)] osgi.wiring.package; (&(osgi.wiring.package=org.osgi.util.tracker)(version>=1.5.0)(!(version>=2.0.0))) -> [org.apache.felix.framework [0](R 0)]:
[ 484] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.logservice [3](R 3.0)] osgi.wiring.package; (&(osgi.wiring.package=org.slf4j)(version>=1.7.0)(!(version>=2.0.0))) -> [org.apache.felix.framework [0](R 0)]:
[ 484] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.logservice [3](R 3.0)] osgi.ee; (&(osgi.ee=JavaSE)(version=1.8)) -> [org.apache.felix.framework [0](R 0)]:
[ 556] DEBUG com.io7m.osgilog2.logservice.Activator: adding a log listener to org.apache.felix.log.LogReaderServiceImpl@47db50c5
[ 557] DEBUG com.io7m.osgilog2.main.Main: starting: com.io7m.osgilog2.test-osgi-logging [4]Some of the following lines are prefixed with SLF4JLogReader, which is sufficient to demonstrate that the custom OSGi log service is receiving and printing messages:
[ 557] INFO com.io7m.osgilog2.logservice.SLF4JLogReader: [com.io7m.osgilog2.logservice]: BundleEvent STARTED
[ 560] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.test-osgi-logging [4](R 4.0)] osgi.wiring.package; (&(osgi.wiring.package=org.osgi.framework)(version>=1.8.0)(!(version>=2.0.0))) -> [org.apache.felix.framework [0](R 0)]:
[ 561] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.test-osgi-logging [4](R 4.0)] osgi.wiring.package; (&(osgi.wiring.package=org.osgi.service.log)(version>=1.3.0)(!(version>=2.0.0))) -> [org.apache.felix.log [2](R 2.0)]:
[ 561] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.test-osgi-logging [4](R 4.0)] osgi.wiring.package; (&(osgi.wiring.package=org.osgi.util.tracker)(version>=1.5.0)(!(version>=2.0.0))) -> [org.apache.felix.framework [0](R 0)]:
[ 561] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.test-osgi-logging [4](R 4.0)] osgi.ee; (&(osgi.ee=JavaSE)(version=1.8)) -> [org.apache.felix.framework [0](R 0)]:
[ 561] INFO com.io7m.osgilog2.logservice.SLF4JLogReader: [com.io7m.osgilog2.test-osgi-logging]: BundleEvent RESOLVED
[ 562] ERROR com.io7m.osgilog2.logservice.SLF4JLogReader: [com.io7m.osgilog2.test-osgi-logging]: LOG SERVICE HELLO!Some of the following lines are prefixed with test_logback.Activator, which is sufficient to demonstrate that messages written to an SLF4J logger instantiated inside the container are making it to the host’s logging system:
[ 563] DEBUG com.io7m.osgilog2.main.Main: starting: com.io7m.osgilog2.test-logback [5]
[ 563] INFO com.io7m.osgilog2.logservice.SLF4JLogReader: [com.io7m.osgilog2.test-osgi-logging]: BundleEvent STARTED
[ 568] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.test-logback [5](R 5.0)] osgi.wiring.package; (&(osgi.wiring.package=org.osgi.framework)(version>=1.8.0)(!(version>=2.0.0))) -> [org.apache.felix.framework [0](R 0)]:
[ 568] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.test-logback [5](R 5.0)] osgi.wiring.package; (&(osgi.wiring.package=org.slf4j)(version>=1.7.0)(!(version>=2.0.0))) -> [org.apache.felix.framework [0](R 0)]:
[ 568] DEBUG com.io7m.osgilog2.main.Main$FelixLogger: WIRE: [com.io7m.osgilog2.test-logback [5](R 5.0)] osgi.ee; (&(osgi.ee=JavaSE)(version=1.8)) -> [org.apache.felix.framework [0](R 0)]:
[ 569] INFO com.io7m.osgilog2.logservice.SLF4JLogReader: [com.io7m.osgilog2.test-logback]: BundleEvent RESOLVED
[ 570] DEBUG com.io7m.osgilog2.test_logback.Activator: starting test-logback
[ 570] DEBUG com.io7m.osgilog2.test_logback.Activator: code source: (file:/tmp/osgilog2/lib/test-logback.jar <no signer certificates>)
[ 570] DEBUG com.io7m.osgilog2.main.Main: bundle org.apache.felix.framework.security [1] is RESOLVED
[ 570] INFO com.io7m.osgilog2.logservice.SLF4JLogReader: [com.io7m.osgilog2.test-logback]: BundleEvent STARTED
[ 570] DEBUG com.io7m.osgilog2.main.Main: bundle org.apache.felix.log [2] is ACTIVE
[ 570] DEBUG com.io7m.osgilog2.main.Main: bundle com.io7m.osgilog2.logservice [3] is ACTIVE
[ 570] DEBUG com.io7m.osgilog2.main.Main: bundle com.io7m.osgilog2.test-osgi-logging [4] is ACTIVE
[ 570] DEBUG com.io7m.osgilog2.main.Main: bundle com.io7m.osgilog2.test-logback [5] is ACTIVE
[ 570] DEBUG com.io7m.osgilog2.main.Main: shutting down
[ 571] DEBUG com.io7m.osgilog2.test_logback.Activator: stopping test-logback
[ 572] INFO com.io7m.osgilog2.logservice.SLF4JLogReader: [com.io7m.osgilog2.test-logback]: BundleEvent STOPPED
[ 572] DEBUG com.io7m.osgilog2.logservice.Activator: removing a log listener from org.apache.felix.log.LogReaderServiceImpl@47db50c5
[ 575] DEBUG com.io7m.osgilog2.main.Main: exitingThe Pax Logging project attempts to provide a superset of the functionality described above. It has the advantage of providing access to more logging APIs inside the container with the disadvantages of reduced run-time performance and drastically higher complexity. In essence, the Pax Logging project defines an OSGi log service that forwards all messages to the host, and exposes copies of the various logging APIs inside the container that actually forward messages to this logging service.
The performance cost is simply from the overhead of creating OSGi log events inside the implementation. The methods described in this document have no overhead for the most common case of OSGi-unaware code writing log messages to SLF4J: A call to SLF4J inside the container is physically identical to a call to SLF4J by the host. The method described is also somewhat specific to Apache Felix but only for those log messages generated by the OSGi framework itself.
All of the code described here is available at:
It’s questionable whether this use of the property could really be considered abusive. Some consider the use of the property at all to be abusive!↩︎