logging of events, thread pools and play plugins

[Alison Winters]

Hi guys,

Over the Christmas break our application mysteriously froze up - no
threads were running and it didn't respond to kill -3 for a thread
dump (we had to kill -9). I decided to add some more detailed logging
for next time, but I've had some trouble.

The first thing I wanted to do was set up a log4j MDC so we get more
logging context. With servlets we would use a filter, but in Play I
know I need to do a plugin:

public class LoggerPlugin extends PlayPlugin {

private static final ThreadLocal<Long> startTime = new
ThreadLocal<Long>();

@Override
public void beforeInvocation() {
startTime.set(System.currentTimeMillis());
Http.Request request = Http.Request.current();
if (request != null) {
MDC.put("method", request.method);
MDC.put("url", request.url);
MDC.put("remoteAddress", request.remoteAddress);
}
Logger.info("Starting invocation");
}

@Override
public void invocationFinally() {
Long endTime = startTime.get();
if (endTime == null) {
Logger.warn("Completed invocation - unknown start time");
} else {
Logger.info("Completed invocation in %d ms",
System.currentTimeMillis() - endTime);
}
MDC.remove("method");
MDC.remove("url");
MDC.remove("remoteAddress");
startTime.remove();
}
}

Note this is just a quick and dirty first version - I still need to
add an auto-generated unique request ID so we can grep the logfile and
follow the path of a particular request.

In any case, this code didn't work exactly as expected because the
Netty jobs don't always call beforeInvocation() before jumping to
invocationFinally(). For instance, all the static HTTP requests are
served directly inside the init() method and return false, thus
before()/after()/etc are never called. Of course if init() handles the
complete invocation then Http.Request.current() is never set so the
MDC parts of my plugin wouldn't work anyway, but at the very least I
should be able to catch the start time of each job that goes through
the Invoker. I think there should be a plugin event that fires before
init() is called, if not beforeInvocation() then perhaps
beforeInvocationInitialization() or something. Should I open a bug for
this?

For the time being I am instead implementing afterInvocation() and
onInvocationException(), which is kinda nice because I can log a
slightly different message depending on if there is an error or not,
but still.

Another problem is that I am adding more MDC context to set the user
ID in a controller using the @With/@Before/@Finally pattern.
Unfortunately if the application throws an exception (error 500) the
@Finally is never called, so I get a hanging user ID in my MDC. This
is because @Finally is only processed for Result type exceptions and
not PlayExceptions or other Exceptions. Is this a bug or intended? And
if it's intended, where am I supposed to add code that needs to wrap
any action invocation regardless of whether it succeeds or not? In
theory I should be able to use a plugin for this, but plugins don't
have access to the controller scope, so I can't get the session cookie
to inspect the user ID.

The other problem I'm having is trying to track what's happening with
threads that don't have a HTTP request set (e.g. mail, jobs etc).
There is no clear way to identify these threads. I've tried walking up
Thread.getCurrentThread().getStackTrace() to find the class name of
the job that was submitted to the Invoker, but that's not very
predictable because a lot of the code just uses a normal Play Job with
no other identifying features. I think one big win would be to name
the threads better so that log4j's %t pattern can print out a useful
thread name. Right now all the threads are named using
Executors.defaultThreadFactory() (naming convention: pool-x-thread-y)
- I think we should have a prefix set for each thread in Play. We
could do this by creating a PrefixedDefaultThreadFactory that wraps
Executors.defaultThreadFactory() and supplies a prefix for each thread
pool. In Play that would be netty-boss, netty-worker, mail, jobs and
"misc" (for the thread pool in Invoker.java). Is anyone interested in
a patch like this? It probably wouldn't be much work and it would make
the logging output much more useful.

A lot of stuff here, I hope Guillaume or someone else may be able to
help :)

Happy new year!

Alison

[Alison Winters]

I should mention with log format:

log4j.appender.Console.layout.ConversionPattern=%p %d{DATE} [%t]
[%X{remoteAddress}] [%X{method} %X{url}] [%X{userId}] %m%n

The logs look like this:

INFO 01 Jan 2011 13:01:37,240 [pool-5-thread-1] [0] [GET /] []
Starting invocation
... more logs ...
INFO 01 Jan 2011 13:01:37,544 [pool-5-thread-1] [0] [GET /] []
Completed invocation in 305 ms

Note that the "0" is because 127.0.0.1 is coming up as 0 because of
the localhost bug in Play 1.1 (fixed in 1.1.1 I think).

Alison

[Guillaume Bort]

Hi

> This is because @Finally is only processed for Result type exceptions and
> not PlayExceptions or other Exceptions. Is this a bug or intended?

I think it is a bug. I would say that finally should be called even
after an exception. Please report it.

> The other problem I'm having is trying to track what's happening with
> threads that don't have a HTTP request set (e.g. mail, jobs etc).
> There is no clear way to identify these threads

You can use the beforeActionInvocation for HTTP requests.

> --
> You received this message because you are subscribed to the Google Groups "play-framework" group.
> To post to this group, send email to play-fr...@googlegroups.com.
> To unsubscribe from this group, send email to play-framewor...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/play-framework?hl=en.
>
>

--
Guillaume Bort, http://guillaume.bort.fr

For anything work-related, use g...@zenexity.fr; for everything else,
write guillau...@gmail.com

[Alison Winters]

Hi Guillaume,

On Jan 3, 10:19 am, Guillaume Bort <guillaume.b...@gmail.com> wrote:
> > This is because @Finally is only processed for Result type exceptions and
> > not PlayExceptions or other Exceptions. Is this a bug or intended?
> I think it is a bug. I would say that finally should be called even
> after an exception. Please report it.
>

This is reported at
http://play.lighthouseapp.com/projects/57987-play-framework/tickets/524-controllers-finally-annotation-does-not-get-executed-on-exception

Should I also report a bug indicating that beforeInvocation() never
gets triggered if the invocation's init() method fails? I don't think
the solution here would be to move beforeInvocation(), rather we
should perhaps look at making a beforeInvocationInit() event.

> > The other problem I'm having is trying to track what's happening with
> > threads that don't have a HTTP request set (e.g. mail, jobs etc).
> > There is no clear way to identify these threads
> You can use the beforeActionInvocation for HTTP requests.
>

This is a good point. I've now updated my plugin to use
Scope.Session.current() to grab the userId at the plugin stage instead
of in the controller stage. This is more convenient than the @With/
@Before/@Finally approach because it keeps all the MDC code in the
same file. It also avoids the @Finally bug. What this doesn't help
with is identifying the difference between the various job threads on
the application. As mentioned, there are a number of thread pools,
e.g. for mail, for jobs, for HTTP. All of these thread pools use the
same naming convention ("pool-X-thread-y") so it's hard to tell what
is running (or failing), especially for jobs that aren't HTTP requests
and therefore have no MDC context. One way to get more context would
be to name the threads more specifically. Would you be interested in a
patch like this if I put it on github?

Alison

[Guillaume Bort]

> One way to get more context would
> be to name the threads more specifically. Would you be interested in a
> patch like this if I put it on github?

Yes of course.