Friday, October 31, 2008

Index BlogSeries Logging in OSGI Enterprise Applications

I got responses that its not easy to read the blog series
"Logging in OSGI Enterprise Applications" in chronological order.

So here's the index:

Logging in OSGI Enterprise Applications, Part 5

This (fifth) part of my blog series "Logging in OSGI Enterprise Applications" will show you some important elements of configuring the logging framework LOGBack we use as SLF4J implementation:

I dont want to talk about the configuration of a logging framework itself - you should be familiar with this. If you're using LOGBack inside an OSGI Enterprise Application there are some special things to watch and problems to solve.

If we're logging in a non-OSGI Java Application we normaly want to know which class logs the event. Logging from an OSGI Enterprise Application its also important to know which bundle causes the LogEvent. Using OSGI LogServices you also have this information from BundleContext..

Its a good practice to name the Logger with the class name - normaly as static Logger defined in each class. This works with all logging frameworks like Log4J, Commons-Logging, java.util.logging or SLF4J.

Using SLF4J as Logging API you can also describe the source of the Log Event more detailed with:
  • MDC (Mapped Diagnostic Contexts)
  • Marker 

MDC is implemented by Log4J and LOGBack. MDC is great to store informations from a client user session: per ex. Username, IP etc. Its a Map and you're free to store what you like. To  access these informations in the Layout of an Appender is easy: 
The LOGBack User Manual chapter 7 (here) explains it in detail and gives you some examples.

Marker and Bundles

Marker are part of the SLF4J API and they mark (as the name says ;-) Log Messages. At the moment only LOGBack implements Marker.  
From the MarkerFactory for a given String we always get the same Marker: 
    Marker marker = MarkerFactory.getMarker("MyMarker");

Marker can reference other Marker - so you can build an object graph of Marker:
    Marker special = MarkerFactory.getMarker("special");

In our OSGI Enterprise Application we're using Marker to log the Name of the bundle.

For each bundle we define once (per ex. in the Activator):

    private static final Logger logger = LoggerFactory.getLogger(MyActivator.class);
    public static final String ID = "";
    public static final Marker bundleMarker = createBundleMarker();
    private static final Marker createBundleMarker() {
        Marker bundleMarker = MarkerFactory.getMarker(ID);
return bundleMarker;

In all the other classes of a bundle we define:

    import static MyActivator.bundleMarker;
    private static final Logger logger = LoggerFactory.getLogger(Foo.class);

Then the logging statements are looking like:

    logger.debug(bundleMarker,"This is my {} message",xyz);

Remark: LOGBack replaces {} with xyz. toString(). More details later.

To get the marker in the logging - output we can simply use
    ... %marker ... 
in the Layout of an Appender. 

In our application we want to test if a Marker is a BundleMarker and then handle formatting the output different, per ex.: 
    ... - [] ...

To do this we have to extend ch.qos.logback.classic.pattern.ClassicConverter and overwrite the methode public String convert(LoggingEvent le).

In our LOGBack configuration (logback.xml or logback-test.xml) we have to insert a new ConversionRule:

then we can use it in the Layout of an Appender:
    ... %bundle ...
and we get as output
   ... - [] ...
or an empty String if the Marker is no BundleMarker.

Fragment Bundles

But thats not all - because the logback.classic Bundle doesnt know our BundleConverter class we need a Fragment-Bundle:

You remember: We already use another Fragment to use our configuration file from Logback Core Bundle:

Remark: perhaps you have noticed that the Manifest files above are using logback Version 0.9.11: there are new versions of SLF4J (Download Version 1.5.5) and LOGBack (Download Version 0.9.11). Because at the moment they are not found from SpringSource EnterpriseBundleRepository we have to build them by ourself. How to do this is explained in part 2 of this blog series.

Logoutput twice

It looks so good: we catch all LogEvents from all Logging Frameworks used from other Bundles and also from OSGI LogServices. But it can happen that you found some messages twice in your log output. What happens ? If you're using per ex. Eclipse Riena M4 you got messages twice:

Riena uses Listener to catch OSGI Logservices and logs them using Log4J. Log4J will found the way to our SLF4J / LOGBack implementation. So long so good.
But our own Logging Bundle org.ekkehard.osgi.over.slf4j also catches OSGI Logservices and loggs them using SLF4J / LOGBack.
And now we got some messages twice.

The good news first: in some days Riena will publish Milestone M5 and then you should be able to switch these Listeners from Riena-Logging off.
Because it can happen every day again using other 3rdParty bundles, here's the solution. We need an entry in our LOGBack configuration file logback.xml:

This will hide those output from org.eclipse.riena

Riena uses Equinox Extended OSGI Logservices, which contain an own Logger. We catch those ExtendedLogEvents and log the message using the Loggername from ExtendedLogEntry. To distinguish Logging - Output from our Listeners we add a prefix:

Now we know where the Logging - Output comes from and as a side-effect its easy to log all LogEvents originally logged from Equinox ExtendedLogServices per ex. at DEBUG Level:

Here's an example logging output catched by our Listener and logged to LOGBack:

23:25:41.846 DEBUG [X.o.e.r.c.publisher.ServicePublishBinder] - [B:org.eclipse.riena.core] service endpoints count: 792

ExtendedLogEntry uses this as Loggername:
We add the prefix "X."
You also see a Bundlename (from our BundleConverter)
We got the name from Context of the catched ExtendedLogEntry: 

Using Marker from LOGBack is an easy way to get the information of the Bundle logging the event and also not to loose the Bundlename if rooting LogEvents from OSGI LogServices to SLF4J/LOGBack.

What happens next ?

This blog series isn't finished, but we already talked about the most important informations about Logging in OSGI Enterprise Applications. Of course I'll continue this series next months because there are some more aspects to look at in detail. But expect next blog entries in a time-frame of 2-3 weeks for each.

Blog Series "Logging in OSGI Enterprise Applications":

Perhaps some of my older blogs about Logging und OSGI are also interesting:

New blog series coming soon

Now I'll also starting a new  blog series :

HowTo build an Equinox-Riena-EasyBeans-OSGI-Server“. 

After working through that blog series you'll get a complete server as Open Source (EPL) to try it out by yourself. This server of course also contains all of the logging aspects I talked about.

this blog in german

Monday, October 20, 2008

Logging in OSGI Enterprise Applications, Part 4

Part 4 will demonstrate how to start the logging - framework and all the bridges inside an OSGI Enterprise Application.

To remember: At the end of the last (third) part of my blog - series "Logging in OSGI Enterprise Applications" we were able to log all events from „classic“ log-frameworks, OSGI LogServices, BundleEvents and FrameworkEvents using a SLF4J Log - implementation (LOGBack):

If we want to use it all inside a complex OSGI Enterprise Application its important to start the bundles using the right start-level. We also have to decide which bundles can be auto-started from the framework and which not. 

As an example I'll use again my OSGI - Equinox - Riena - EasyBeans - Hibernate - Server. I'll talk in detail about this server later in one of the follow-ups.

From OSGI Launch Configuration:

Default Start - Level is set to 3. 
Our osgi-over-slf4j - Bundle must be started before (Start-Level = 2) and the EasyBeans - Agent - Bundle later (Start-Level = 4)

We also have to watch that some bundles cannot be started with Auto-Start = true ! These bundles will be started under control from EasyBeans Agent bundle.

What happens now starting the OSGI server application ?

  1. The OSGI - Framework Equinox will be started
  2. Our org.ekkehard.osgi.over.slf4j bundle will be started. The Activator calls in the start() method SLF4JBridgeHandler.install() to catch all log - events from java.util.logging - also the Activator contains Logger - Statements. All this causes starting and activating SLF4J - API and SLF4J - implementation (LOGBack) - bundles: our Logging Framework is alive !
  3. All bundles with Auto-Start = true will be started then from the Framework. This includes all Eclipse Riena bundles. Riena uses LOG4J - so the LOG4J - bridge will be started. Riena also uses Equinox - Extended - OSGI - Log - Services.
  4. After starting all Default - Start - Level - bundles, the easybeans.agent will be started. This agent starts all EasyBeans components and Hibernate. EasyBeans uses Commons - Logging and java.util.logging - Hibernate uses SLF4J. Then all our logging -  framework - bridges are started and active. EasyBeans then starts all Entity - bundles and EJB3 - bundles from our server and registers the EJB3 - Business - Interfaces (Local oder Remote) als OSGI - Services.
  5. The org.ekkehard.server bundle tracks OSGI Managed Services and recognizes, when all required services are configured from EasyBeans and Hibernate and ready-to-go. Then org.ekkehard.server registers Services as Remote Services for Eclipse Riena.

Remark: This is only a small part of all the activities and tasks happening while starting the server. More about 4. and 5. later in another blog series. Lets first finishing the logging.

No black holes ?

If we did it all well, then our SLF4J - Implementation LOGBack should start so early that we get all log - events and nothing is lost in space. 

To test this we configure our logback-test.xml as follows: set Root Level to DEBUG, output to Console, swich DEBUG - Mode of the configuration itself on and start the server.

You should get a log like this:

  • Line 1: equinox - osgi - Console
  • Line 2 - 7: Debug-output from LOGBack configuration
  • Line 8 - 9: Logging-output from osgi-over-slf4j - bundle

There's no other logging-output on the console before starting SLF4J / LOGBack :-)

The next blog will look at the configuration of LOGBack and some special Fragment - Bundles for configuration and also extending the LOGBack - implementation.

Perhaps some of my older blogs about Logging und OSGI are also interesting:

 the blog in german.

Saturday, October 11, 2008

Logging in OSGI Enterprise Applications, Part 3

Part 3 explains how to catch all log events logged by OSGI Bundles using  OSGI Log Services. 

In part 2 you've seen that catching log entries from "classic" Log - Frameworks was very easy:
  • ✓ Choose the right bundles
  • ✓ Create a config - file 
-thats all :-)
Remark: java.util.logging needs also this one-liner: SLF4JBridgeHandler.install();

Running an OSGI Enterprise Application you'll also find bundles logging their log - entries using OSGI Services:
  • org.osgi.service.log.LogService 
  • org.osgi.service.log.LogReaderService 

You have also to watch for Services extending the "normal" OSGI Log Services: Eclipse Riena per ex. uses from Equinox Incubator:
  • org.eclipse.equinox.log.ExtendedLogService 
  • org.eclipse.equinox.log.ExtendedLogReaderService

You can read Log entries using the LogReaderService. You only have to register your LogListener
The LogListener gets all LogEntry (ExtendedLogEntry), then you can log them using SLF4J-API to your LOGBack Implementation. 

You have to use the same config file (logback.xml or logback-test.xml) as described in part 2 (logging the entries from „classic“ Log - frameworks). Details about configuration will follow in another Blog of this series.

Short overview:

We already have following bundles used as bridges between „classic“ Log-Frameworks and SLF4J / LOGBack:

  • slf4j.api
  • log4j.over.slf4j
  • jcl.over.slf4j

There are also the bundles of the SLF4J - implementation LOGBack:

  • logback.core
  • logback.classic

You'll find more details in part 2 of this Blog series.

Bundle osgi.over.slf4j (a bridge between OSGI Service and LOG4J)

We need a bundle as bridge between OSGI Log Services and SLF4J / LOGBack. Please create a Plug-In project using PDE:

  • my.namespace.osgi.over.slf4j

Your MANIFEST.MF should look like:

This osgi.over.slf4j - bundle has its own org.slf4j.Logger:
We'll use this Logger to log events from this bundle itself and also to log all catched LogEntry from other bundles.

To track LogReader Services we can use a ServiceTracker:

We create our LogServiceTracker with this filter to get only services from type LogReaderService or ExtendedLogReaderService:

(|(objectClass=org.osgi.service.log.LogReaderService) (objectClass=org.eclipse.equinox.log.ExtendedLogReaderService))

A LogListener for „normal“ OSGI LogServices:
LogEntry will be logged using the Logger of our osgi.over.slf4j - bundle.

A LogListener for „extended“ Equinox OSGI LogServices:
ExtendedLogEntry already contains an own Logger
We'll use an org.slf4j.Logger with same name - but to distinguish we use a prefix („X.“). Details will follow in another Blog.

Then we delegate LogEntry and ExtendedLogEntry to the org.slf4j.Logger:
We have to map the OSGI LogService Levels. We can get the origin message and (optional) exception from LogEntry and delegate to our Logger.

Different from Log4J or Commons-Logging is using a Marker. Markers are part of the SLF4J API, but at the moment only the LOGBack - implementation uses them. We are using Marker to print the bundle-name and perhaps also the service-name. Then we know which bundle / service originally creates the LogEntry or ExtendedLogEntry
Remark: More about Marker you'll find in one of the next Blogs of this series.

Logging BundleEvent and FrameworkEvent 

Its a good idea also to log org.osgi.framework.BundleEvent and org.osgi.framework.FrameworkEvent

To do this we need these Listener:
Dependent from the Event - Type we create the message and level.
Remark: More about SLF4J - Marker in one of the follow-ups.


Now we are ready to catch and log all events from „classic“ Log-Frameworks, OSGI LogServices, BundleEvents or FrameworkEvents using SLF4J / LOGBack:

This was the third part of my blog series "Logging in OSGI Enterprise Applications":

Perhaps some of my older blogs about Logging und OSGI are also interesting:

the blog in german.