Organize Your Logs With a Cool Java EE 6 Trick

Picture this — it’s 9:00 Friday night, and you’ve just gotten a phone call asking why the hell a key part of your system is down… after verifying that something’s definitely busted, you open up the only resource you have — your system logs… it doesn’t take you long to find some exceptions, but they don’t tell you much of the story… pretty soon, you realize there are 5 or 6 different errors being thrown, plus messages from areas of the system that appear to be working fine… to boot, it’s the middle of your busiest time of the year, which means that you may have a few thousand users on the system at this very moment… yikes — how the heck do you make heads or tails of this mess?

Logging — no longer an afterthought

Ok, so four or five days later, when you finally sort out your issue, it’s time to make things better before that happens again… it’s time to actually put some thought behind your logging practices… first stop — learn how to log, and put some standards in place! I’m not going to elaborate on the details of that article, because I think the author does a fine job… frankly, I was hooked when he defined the logs as a ‘secondary interface’ of your system — your support staff (i.e. — you) can’t see what your customers are looking at in their browsers, so you need to make damn sure that you’re providing enough information in your logs for you to understand what’s going on!

Let’s be real, though — the traffic on your system hasn’t gone down any since that fateful Friday (luckily), and you don’t have the time to rework all of the logging in your system… there has to be a way to put some incremental improvements in here that will make your life easier the next time things catch fire, even if that’s tomorrow…

Adding the Context without the Pain — or a single change to your core code

Ultimately, you were able to make some sense out of that catastrophe by realizing your logging framework was providing you with a subtle piece of context — the thread name… seems innocuous, but in most Servlet containers, it’s enough to identify that each line in the log belonged to a particular thread — or request… It’s not perfect though — you didn’t have any messages in your logs that stated “Starting GET request for /shoppingcart/buySomething.html”, so you couldn’t tell exactly where each request started and ended… luckily, with Java EE 6 and a good logging framework, it’s not hard to get there…

Before I dig in, though, let’s get acquainted with the Mapped Diagnostics Context, or MDC — hopefully, your logging system supports it (log4j does, so most folks will be covered)… MDC provides the ability to attach pieces of context to the thread of execution you’re in, and allows for you to add this info on all log messages…

The following example shows a piece of code that uses the MDC in SLF4J — a logging framework much like the Apache Commons Logging framework that can provide a single interface to multiple logging run-times — excellent for building libraries when you don’t want to impose a logging system on your users… Anyway, on to the show:

public class RequestLoggingContext implements Filter {
private static final String SESSION_CONTEXT = "session-context";

...

@Override
public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException {
if(req instanceof HttpServletRequest) {
HttpServletRequest httpRequest = (HttpServletRequest)req;
session = httpRequest.getSession(false);

if(session != null)
MDC.put(SESSION_CONTEXT, session.getId());
}

chain.doFilter(req, resp);

if(session != null) {
MDC.remove(SESSION_CONTEXT);
}
}
}

Pretty simple — two static methods on the ‘MDC’ class — ‘put’ and ‘remove’… while I’m not a particular fan of the static API, this is about as simple as it gets (incidentaly, this is the only ‘unfortunate’ use of static methods that I have seen in SLF4J — they use the standard method of having static factory classes, but that at least makes sense, and has precedent)… so what the heck did this do? Well, we now have the ability to refer to that “session-context” as a part of our logging ‘Pattern’, using the “%X{session-context}” flag — like so:





%d{HH:mm:ss.SSS} [session-context=%X{session-context}][%thread] %-5level %logger{36} - %msg%n







BTW, that is not a log4j config file — it’s a Logback config… Logback is the ‘native’ implementation of the SLF4J library that’s written by the same folks who brought you Log4J — kind of a ‘take two’, if you will… anyway, it should be obvious that it’s driven heavily from Log4J’s configuration 🙂

So we have now added context to our logging system — and all without disturbing a single line of code in our existing system… but wait, there’s more!

The Trick

One of the interesting additions to Java EE 6 is the combination of Servlet Annotations, and web fragments — this allows library authors to self configure the use of their library, where previously the end user would need to make additions to the web.xml… a great use of Convention Over Configuration, and very powerful, indeed!

So let’s take the above code sample and expand it to include a randomly generated context id for each HttpRequest, and some basic log messages to delineate the start and end of every request:

@WebFilter("/*")
@WebListener
public class RequestLoggingContext implements Filter, HttpSessionListener {
private static final String REQUEST_CONTEXT = "request-context";
private static final String SESSION_CONTEXT = "session-context";

private Logger log = LoggerFactory.getLogger(RequestLoggingContext.class);

@Inject
private ContextGenerator contextGenerator;

@Override
public void init(FilterConfig fc) throws ServletException {
}

@Override
public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException {
MDC.put(REQUEST_CONTEXT, contextGenerator.generateContextId());

StringBuilder msg = new StringBuilder();
if(req instanceof HttpServletRequest) {
HttpServletRequest httpRequest = (HttpServletRequest)req;
HttpSession session = httpRequest.getSession(false);

if(session != null)
MDC.put(SESSION_CONTEXT, session.getId());

//Build Detailed Message
msg.append("Starting ");
msg.append(httpRequest.getMethod());
msg.append(" request for URL '");
msg.append(httpRequest.getRequestURL());
if(httpRequest.getMethod().equalsIgnoreCase("get") && httpRequest.getQueryString() != null) {
msg.append('?');
msg.append(httpRequest.getQueryString());
}
msg.append("'.");
}

if(msg.length() == 0) {
msg.append("Starting new request for Server '");
msg.append(req.getScheme());
msg.append(":\\");
msg.append(req.getServerName());
msg.append(':');
msg.append(req.getServerPort());
msg.append('/');
}

log.info(msg.toString());
long startTime = System.currentTimeMillis();

chain.doFilter(req, resp);

msg.setLength(0);
msg.append("Request processing complete. Time Elapsed -- ");
msg.append(System.currentTimeMillis() - startTime);
msg.append(" ms.");
log.info(msg.toString());

if(((HttpServletRequest)req).getSession(false) != null) {
MDC.remove(SESSION_CONTEXT);
}
MDC.remove(REQUEST_CONTEXT);
}

@Override
public void destroy() {
}

@Override
public void sessionCreated(HttpSessionEvent hse) {
MDC.put(SESSION_CONTEXT, hse.getSession().getId());
}

@Override
public void sessionDestroyed(HttpSessionEvent hse) {
}
}

All that’s left is to literally throw that in its’ own .jar file, put it in your WEB-INF/lib folder, and add either or both of the ‘context’ keys to your logging config and presto — you have logging context! (I have omitted the definition of the ContextGenerator class for brevity — it just generates a random string) Now your logs will look something like this:

INFO: 00:02:11.140 [request-context=sonqc52zbqia][http-thread-pool-8080-(1)] INFO  c.m.l.support.RequestLoggingContext - Starting GET request for URL 'http://localhost:8080/Test/'.
INFO: 00:02:12.156 [request-context=sonqc52zbqia][http-thread-pool-8080-(1)] INFO c.m.l.i.TimingLogInterceptor - Executing com.test.facade.LoadHomeFacade.loadData
INFO: 00:02:12.156 [request-context=sonqc52zbqia][http-thread-pool-8080-(1)] INFO c.m.l.i.TimingLogInterceptor - Doing something interesting.
INFO: 00:10:36.250 [request-context=sonqc52zbqia][http-thread-pool-8080-(1)] INFO c.m.l.support.RequestLoggingContext - Request processing complete. Time Elapsed -- 719 ms.

So now, without touching a single line of existing code or modifying a single class, we can now clearly associate any logging message in our system with other messages generated on that request, and we have clear delineation of where each request begins and ends, and how long it took to execute… pretty damn sweet! So now when your system blows up next Friday night, you’ll be a bit more prepared to sort things out before the weekend is over! (just don’t throw out those scripts that sort based on ‘request-context’!)

Final Word

Final word? I guess that means there’s more — three things, actually… first — there is absolutely nothing preventing you from putting the above in place if you’re on an earlier version of the Java EE spec (and let’s face it — that’s pretty much all of us!)… The only thing you lose is the self configuration, so you’ll need to add the appropriate and elements to your web.xml

Second, if you’re on Java EE 6 (wow, that was fast!), and your application already makes use of Servlet Filters, whether they’re ‘self configured’ or not, you may need to do some configuration in your web.xml to provide an explicit ordering — note that this is not strictly required, although it is probably a good idea :)…

And finally, I mentioned above that Log4J users were in luck when it came to supporting MDC… unfortunately, the JDK Logging API doesn’t support MDC (come on! Why not! Am I the only one who seems to think they haven’t advanced this API in the last five years!?) — those users aren’t entirely out of luck, though… there is a way to ‘subclass’ the JDK Logger and add logging info to the front or end of any logging message, although it’s tricky — unfortunately, I don’t have this code handy anymore, but perhaps I’ll sit down and figure it out again if I’m so inclined one day (of course, if I get feedback to do this, it might make me more inclined 🙂 )

Now don’t forget to get back and add better logging messages to your code!

M

<!–
google_ad_client = “pub-3840214761639097”;
/* 300×250, created 8/9/09 */
google_ad_slot = “7488975184”;
google_ad_width = 300;
google_ad_height = 250;
//–>

<script type="text/javascript"
src=”http://pagead2.googlesyndication.com/pagead/show_ads.js”&gt;

@DataSourceDefinition — A Hidden Gem from Java EE 6

In the old days, DataSources were configured — well, they were configured in lots of different ways… That’s because there was no ‘one way’ to do it — in JBoss, you created an XML file that ended in ‘-ds.xml’ and dumped it in the deploy folder… in Glassfish, you either use the admin console or muck with the domain.xml file… in WebLogic you used the web console… and this was all well and good — until I worked with an IT guy who told me just how much of a pain in the ass it was…

Up until then, it wasn’t such a big deal to me — I set it up once, and that was that… then I ran into this guy a few jobs ago who liked to bitch and complain about how much harder it was to deploy our application than the .NET or Ruby apps he was used to… he had to deploy our data source, then he had to deploy our JMS configurations — only then would our application work… in the other platforms, that was all built into the app (I’ll have to take his word for it, since I haven’t actually deployed anything in either platform)… I was a but surprised at first, and then I realized that maybe he had a point… nah, it couldn’t be, he must just be having a bad day (lots of us were having bad days back then 🙂 )…

Then I ran into Grails, which is dead simple — you have a Groovy configuration file that has your db info in it… you even have the ability to specify different ‘environments’, which can change depending on how you create your archives or run your app… pretty slick…

The Gem

Well, lo and behold, we now have something that’s nearly equivalent in Java EE 6 — the @DataSourceDefinition attribute… it’s a new attribute that you can put on a class that provides a standard mechanism to configure a JDBC DataSource into JNDI, and as expected, it can work with local JNDI scopes or the new global scope, meaning you can have an Environment Configuration that uses this attribute making it shareable across your server… it works like this:


import javax.annotation.sql.DataSourceDefinition;
import org.jboss.seam.envconfig.Bind;
import org.jboss.seam.envconfig.EnvironmentBinding;

@DataSourceDefinition (
className="org.apache.derby.jdbc.ClientDataSource",
name="java:global/jdbc/AppDB",
serverName="localhost",
portNumber=1527,
user="user",
password="password",
databaseName="dev-db"
)
public class Config {
...
}

As you would expect, that annotation will create a DataSource that will point to a local Derby db, and stick it into JNDI at the global address ‘java:global/jdbc/AppDB’, which your application, or other applications can refer to as needed… no separate deployment and no custom server-based implementation — this code should be portable across any Java EE 6 server (including the Web Profile!)…

It’s almost perfect!

In typical Java EE style, there’s one thing that just doesn’t appear to be working the way I’d like it — it doesn’t appear to honor JCDI Alternatives (at least not in Glassfish)… Here’s what I’m thinking — we should be able to have a different Config class for each of our different environments… in other words, we’d have a QAConfig that pointed to a different Derby db, a StagingConfig that pointed to a MySQL db somewhere on another server, and a ProductionConfig that pointed to kick ass, clustered MySQL db… we could then use Alternatives to turn on the ones that we want in certain environments with a simple XML change, and not have to muck with code… unfortunately, it doesn’t appear to work — it appears in Glassfish that it is processing them in an undeterministic order, with (presumably) the class that is processed last overwriting the others that came before it…

There is a solution, though, and it is on the lookup side of the equation — using JCDI Alternatives, we can selectively lookup the DataSource that we’re interested in, and then enable that Managed Bean in the beans.xml file… it’s definitely not ideal, since we need to actually inject all of our DataSources into JNDI in all scenarios, but it works, it’s something I can live with, and is probably easily fixed in a later Java EE release… Update: Looks like it’s in the plan, according to this link — thanks, Gavin 🙂

Here’s how it works — first the ‘common’ case, probably for a Development environment:


@RequestScoped
public class DSProvider {
@Resource (lookup="java:global/jdbc/AppDB")
private DataSource normal;

public DataSource getDataSource() {
return normal;
}
}

Simple enough — has a field that looks up ‘jdbc/AppDB’ from JNDI, and provides a getter… now for QA:


@RequestScoped @Alternative
public class QADSProvider extends DSProvider{
@Resource (lookup="java:global/jdbc/AppQADB")
private DataSource normal;

public DataSource getDataSource() {
return normal;
}
}

Pretty much the same, except this does the lookup from ‘jdbc/AppQADB’, and it is annotated with @Alternative… so how do these things work together? Take a look:


@Named
public class Test {
@Inject
private DSProvider dsProvider;

...
}

Again, simple — we’re injecting a DSProvider instance here, and presumably running a few fancy queries… Nothing Dev-ish or QA-ish here at all, which is the beauty of Alternatives… finally, when building the .war file for QA, we turn on our Alternative in the beans.xml, like so:




com.mcorey.alternativedatasource.QADSProvider


You’ll notice that this solution requires us to rebuild our .war file for QA, which I obviously don’t like — not to worry, there will be support for this in the Seam 3 Environment Configuration Module, which will effectively create a binding by mapping from one JNDI key to another… I have no idea what the syntax will look like at this point, but it should be pretty straight forward, and will allow us to — you guessed it — build our .war one, and copy it from place to place without modification…

M

http://pagead2.googlesyndication.com/pagead/show_ads.js

What’s cool in Java EE 6 — Singleton EJB’s and Pruning

Well, with the all the excitement about the addition of JSR 330 Dependency Injection into the EE 6 platform, I figured I’d switch gears a bit and talk about the changes in a different spec — this time, the EJB spec… Now, this spec is enormous — 618 pages to be exact — but luckily, we can ignore most of it! I mean seriously, who wants to read about EJB QL, 2.1 Client Views and the like… I’d rather dig into the meatier stuff, like…

Singleton Session Beans
We all know the Singleton pattern — it may be one of the most well known designs patterns, and it’s easy to understand… basically, if something’s a singleton, then there’s only one of ’em… ever… that means if you lose it or break it, it’s gone for good… ok, that last part isn’t true, and really the parts before that aren’t quite true, either — in most implementations of the Singleton pattern, folks conveniently forget to account for the fact that Enterprise applications often live in clusters, and instead they make singletons so that there is only one per virtual machine… most of the time this is fine — they’re often used for things like Service Locators, which were used back in the olden days of EJB 2 as a convenient way to do all the nasty JNDI lookups for EJB’s…

Enter Singleton Session Beans… these are pretty much what you’d expect them to be — an EJB that you can only find one of per JVM (the spec is specific about that last part, so really, they’re only Singletons part of the time)… frankly, I was somewhat underwhelmed when I first heard of them, but they do add one interesting capability that I’ve needed on several EJB applications in the past, and have never had in an easy, portable way to pull off — the ability to execute on application startup…

This can be achieved with a few simple annotations, like so:

@Singleton
@Startup
public class InitBean {
@PostConstruct
@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)
public void initializeSomeStuff() {
...
}

I know, lot’s of annotations on that sucker, but it’s pretty straight forward:

  • @Singleton — defines this as a Singleton Session Bean… big surprise here, eh?
  • @Startup — this is an indication to the app server that this class must be created and initialized at application startup, and yes, the spec uses the ‘must’, so there’s no soft language here
  • @PostConstruct and @TransactionAttribute — these are the old tags that we all know and love…

Anyone who’s read this blog before may notice a hidden gem in here that makes all of this worthwhile… I’ll give you a hint — go read this entry on @PostConstruct… yes, that’s right, this is a Transactional @PostConstruct method… and it will work! They got this one right when they wrote the EJB 3.1 spec, in that it guarantees that @PostConstruct methods will obey your @TransactionAttribute attributes! Now if only they would extend this capability to all EJB’s, we’d have all of our problems solved! Ok, perhaps not all of them…

So anyway, you can do pretty much whatever you want in here, including initializing 3rd party systems, creating timers, sending email, truncating all of your database tables, etc… what most intrigues me, though, is data bootstrapping, similar to what you get with the Grails Bootstrap class:

...

@PostConstruct
@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)
public void setupUserData() {

List expectedUsers = getExpectedUsers();

for (User u : expectedUsers) {
User found = em.find(User.class, u.getId());
if (found == null) {
log.info("Persisting user "+u.getUsername());
em.persist(u);
} else if (!found.equals(u)) {
log.info("Updating user "+u.getUsername());
em.merge(u);
} else {
log.info("No need to update user "+u.getUsername());
}
}
}

...

In other words, this Singleton will ensure that your standard set of users will always be available upon application startup — if this is something you want only in a development environment, you can configure each machine with environment information via JNDI, System properties, or a configuration that is set in your build so that it only takes these actions on a development environment — it is a great way to ensure a consistent development environment across your team…

A Word about Pruning
Ok, this is, by far, my favorite feature of Java EE 6 — and it’s not even a feature! That’s right, we’re finally going to be able to actually remove some of the stuff that’s been added to Java EE over the years! This could include a wide variety of things, but just think — some day in the near future, you won’t have to sift through details about Entity Beans, outdated communication protocols like JAX-RPC, EJB Home interfaces… instead, it will all be gone! Unfortunately, this day hasn’t come just yet — they’re just telling us that they’re planning to do it some day, but at least it’s a step in the right direction… now I have to wonder — will Java EE 7 actually be a smaller spec than EE 6? Now that would be impressive 🙂

In the meantime, you can get a little hint of the pruning goodness by taking advantage of the new Web Profile — this is a nice customization of the spec that removes a lot of the stuff that most folks don’t use anyway, but that is still pretty useful in some cases… unfortunately, you still do have to thumb past all of the extra stuff if you decide to go diving into the spec documents…

Conclusion
It seems odd to me that it took so long for Java EE to standardize such a simple, but useful piece of functionality as startup logic — to me, this is more important than the fact that this EJB is a (kind-of-)Singleton! Sure, I’ve always been able to do this through an eagerly loaded Servlet, or with WebLogic or JBoss specific code, but the Servlet solution is just plain weird if I’m not acting upon my web container, and this is obviously more portable than an app-server specific piece of functionality… the above example just seems a little less… dirty to me 🙂

But who am I to complain about a nice new feature 🙂

M