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:
...N:%X{username}...
produces
...N:JohnDoe...
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");
special.add(MarkerFactory.getMarker("init"))
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 = "my.bundle.symbolic.name";
public static final Marker bundleMarker = createBundleMarker();
private static final Marker createBundleMarker() {
Marker bundleMarker = MarkerFactory.getMarker(ID);
bundleMarker.add(MarkerFactory.getMarker("IS_MARKER"));
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.:
... - [B:my.symbolic.bundle.name] ...
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
... - [B:my.symbolic.bundle.name] ...
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:
org.eclipse.riena.communication.publisher.ServicePublishBinder
We add the prefix "X."
You also see a Bundlename (from our BundleConverter)
org.eclipse.riena.core
We got the name from Context of the catched ExtendedLogEntry:
getBundle().getSymbolicName()
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":
- Part 1: An overview
- Part 2: How to catch all log events from "classic" logging - frameworks
- Part 3: How to catch all log events from OSGI Log Services
- Part 4: How to start logging bundles the right way inside an OSGI Enterprise application
- Part 5: Configuration, Fragment-Bundles, Markers
- Part 6: ... follows (Stay tuned...)
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
No comments:
Post a Comment