Wicket’s RequestLogger

Stefanovich

April 8th, 2009 - 2,281 views

Wicket provides you with a build-in request logger. It can give you a lot of information. See also example below. To activate this logger you have to enable the logger and setup (in our case) some Log4j configuration. In this post I’ll show you how to get this done.

The example below shows you how to enable the requestLogger when the application is started in “Development” mode.

//Check if we are not in deployment mode.
if (!DEPLOYMENT.equalsIgnoreCase(getConfigurationType())) {

  //Get the logger
  IRequestLoggerSettings reqLogger = Application.get().getRequestLoggerSettings();

  //Enable the logger
  reqLogger.setRequestLoggerEnabled(true);

  /**
  * Set the window of all the requests that is kept in memory for viewing. Default is 2000, You
  * can set this to 0 then only Sessions data is recorded (number of request, total time, latest
  * size)
  */
  reqLogger.setRequestsWindowSize(3000);
}

If you want to log everything to a specific rolling file you can add the following lines to your log4j.properties file. It will create a file for you with a max. size of 10MB. All Wicket requests will be logged into this file and not in the ‘general’ log.

log4j.category.org.apache.wicket.protocol.http.RequestLogger = info,reqLogger
log4j.additivity.org.apache.wicket.protocol.http.RequestLogger=false
log4j.appender.reqLogger=org.apache.log4j.RollingFileAppender
log4j.appender.reqLogger.File=D:/logs/wicketRequestLogger.txt
log4j.appender.reqLogger.MaxFileSize=10MB
log4j.appender.reqLogger.MaxBackupIndex=10
log4j.appender.reqLogger.layout=org.apache.log4j.PatternLayout
log4j.appender.reqLogger.layout.ConversionPattern=%d %-5p - %-26.26c{1} - %m\n

Example logging:
2009-04-08 16:18:32,878 INFO – RequestLogger-
time=687,
event=Interface[target:Login$LoginForm(bodyTag:loginForm),
page: eu.company.desktop.wicket.ui.login.Login(0),
interface: IFormSubmitListener.onFormSubmitted],
response=org.apache.wicket.request.target.basic.RedirectRequestTarget@1c82b58,
sessionid=C488C8A534D1D853FD1F7A80C5647A52.jvm1,
sessionsize=16239,
sessionstart=Wed Apr 08 14:18:23 GMT 2009,
requests=12,
totaltime=3499,
activerequests=1,
maxmem=532M,
total=163M,
used=93M

That’s it.

Disclaimer: The requestLogger is very powerfull. I just started experimenting with it, so I don’t know all ins and outs yet.

Daan

April 8th, 2009 at 22:00

Hi Stefan,

I am also experimenting with the Wicket RequestLogger, triggered by the presentation of Martijn on the Wicket Meetup.

A few days ago I mailed Martijn if the code for analyzing this logfile is somewhere online. Unfortunately, this isn’t the case.

Are you guys going to invest time in writing a log file analyzer for Wicket logs? Maybe we can collaborate on that?

Regards,

April 8th, 2009 at 22:15

We didn’t plan to do that (yet). Currently we are very busy with a release. I was also thinking to send Martijn a mail. It’s a pitty that it is not open source, because it looked very nice in his presentation.

April 8th, 2009 at 22:18

Daan,

Have you already seen the InspectorBug class? (wicket.examples.debug package) I couldn’t found a demo if this functionallity but I am very curious what it exactly does.

Regards,
Stefan

April 12th, 2009 at 09:27

Yeah, I have seen the InspectorBug class too. I am building a separate wicket-examples jar (it’s a war now) to check how it works.

- Daan

Avner Linder

July 26th, 2009 at 14:16

Hi,
I’ve tried activating the RequestLogger and in many cases duplicate entries appear at the log file for the same request, for example:
2009-07-26 15:00:32,224 INFO - RequestLogger - time=796,event=null,response=[ResourceStreamRequestTarget[resourceStream=org.apache.wicket.markup.html.DynamicWebResource$1@137937,fileName=null],sessionid=11jxsgdnkz6c4,sessionsize=54608,sessionstart=Sun Jul 26 15:00:26 IDT 2009,requests=7,totaltime=4789,activerequests=1,maxmem=66M,total=32M,used=19M 2009-07-26 15:00:32,239 INFO - RequestLogger - time=796,event=null,response=[ResourceStreamRequestTarget[resourceStream=org.apache.wicket.markup.html.DynamicWebResource$1@1e8c1ec,fileName=null],sessionid=11jxsgdnkz6c4,sessionsize=54608,sessionstart=Sun Jul 26 15:00:26 IDT 2009,requests=8,totaltime=5585,activerequests=2,maxmem=66M,total=32M,used=19M

I inspected the call-hierarchy of IRequestLogger.logResponseTarget and found out that it is being called twice by Wicket framework, once for each of the steps: PROCESS_EVENTS and RESPOND

logResponseTarget(IRequestTarget) - org.apache.wicket.protocol.http.WebApplication respond(RequestCycle) - org.apache.wicket.request.AbstractRequestCycleProcessor processEventsAndRespond() - org.apache.wicket.RequestCycle step() - org.apache.wicket.RequestCycle respond() - org.apache.wicket.RequestCycle step() - org.apache.wicket.RequestCycle

any ideas how to prevent the duplicate log entries?

I plan to extend the default RequestLogger, and then I could log events only at one of the steps.
However, the RequestLogger doesn’t have access to the RequestCylce.currentStep

any ideas?

Avner

July 26th, 2009 at 14:23

Here’s the call-hierarchy again (copied from eclipse), this time more readable (i hope):
logResponseTarget(IRequestTarget) - org.apache.wicket.protocol.http.WebApplication respond(RequestCycle) - org.apache.wicket.request.AbstractRequestCycleProcessor processEventsAndRespond() - org.apache.wicket.RequestCycle step() - org.apache.wicket.RequestCycle respond() - org.apache.wicket.RequestCycle step() - org.apache.wicket.RequestCycle

You can see that respond() is the only caller of logResponseTarget().
You can also see that respond() is being called twice from the step() method, once for each step.

July 26th, 2009 at 14:46

Hmm I don’t know. Anyone else?

Verhage

September 23rd, 2009 at 22:10

Use additivity=false in your log4j.xml.

Bet you’ve configured some loggers up in the hierarchy along org.apache.wicket.

VolkomenJuist.nl

Categories

Recent Posts