October 26 /

LoggingFilter in Magnolia: a simple way to monitor things


Warning: WP_Syntax::substituteToken(): Argument #1 ($match) must be passed by reference, value given in /membri/maips21/wp-content/plugins/wp-syntax/wp-syntax.php on line 380

Warning: WP_Syntax::substituteToken(): Argument #1 ($match) must be passed by reference, value given in /membri/maips21/wp-content/plugins/wp-syntax/wp-syntax.php on line 380

There are moments during web development where things, for any reason, start to go wrong.

In a recent project, we started to have charset encoding issues about request header (injected by a SSO system and a reverse proxy). So, how can we test what goes through the request, or better, through the Magnolia filter chain?

First option: enable Tomcat RequestDumper valve or filter (see here or here). It is not ok, because Magnolia has a “nested” filter chain and sometimes, things changes between a filter chain step and the other. Tomcat RequestDumper only dump request when it is caught from client, not after it has been dispatched to Magnolia filter chain. And then, it is also not “hot”, we need to restart tomcat.

Second option: inside a Magnolia page/template/paragraph we can use ${ctx.requestParam} to dump it. But again, it is not what we want (headers are not exposed, we need to know the exact parameter name..)

So, what can we do? Developing a custom LoggingFilter can help us.

First, write the LoggerFilter java class.

package com.tinext.ecp.magnolia.common.filters;
 
import info.magnolia.cms.filters.AbstractMgnlFilter;
 
import java.io.IOException;
import java.util.Enumeration;
 
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
 
import org.apache.commons.lang.StringUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
 
public class LoggerFilter extends AbstractMgnlFilter {
 
	private static final Logger log = LoggerFactory.getLogger(LoggerFilter.class);
 
	private static final String DEBUG = "debug";
	private static final String INFO = "info";
	private static final String WARN = "warn";
 
	// filter settings
	private String logLevel = DEBUG;
	private boolean logRequest = true;
	private boolean logHeaders = true;
	private boolean logParameters = true;
 
	@Override
	public void doFilter(final HttpServletRequest request, final HttpServletResponse response, final FilterChain chain) throws IOException, ServletException {
 
		if (isEnabled()) {
 
			log("**************************************** LoggerFilter ****************************************");
 
			if (logRequest) {
				logRequest(request);
			}
 
			log("**************************************** ------------ ****************************************");
		}
 
		// important
		chain.doFilter(request, response);
 
	}
 
	private void logRequest(final HttpServletRequest request) {
		if (null != request) {
 
			// request parameters
			if (logParameters) {
				for (final Enumeration e = request.getParameterNames(); e.hasMoreElements();) {
					final String name = e.nextElement();
					final String value = request.getParameter(name);
					log("Request parameter [{}] has value of [{}]", name, value);
				}
			}
 
			// request headers
			if (logHeaders) {
				for (final Enumeration e = request.getHeaderNames(); e.hasMoreElements();) {
					final String name = e.nextElement();
					final String value = request.getHeader(name);
					log.debug("Request header [{}] has value of [{}]", name, value);
				}
			}
 
		} else {
			log("Request is null");
		}
 
	}
 
	private void log(final String msg) {
		log(msg, new Object[] {});
	}
 
	private void log(final String msg, final Object o1, final Object o2) {
		log(msg, new Object[] { o1, o2 });
	}
 
	private void log(final String msg, final Object[] args) {
		if (StringUtils.isNotEmpty(msg)) {
			if (StringUtils.equals(logLevel, WARN)) {
				log.warn(msg, args);
			} else if (StringUtils.equals(logLevel, INFO)) {
				log.info(msg, args);
			} else {
				log.debug(msg, args);
			}
		}
	}
 
	public String getLogLevel() {
		return logLevel;
	}
 
	public void setLogLevel(final String logLevel) {
		this.logLevel = logLevel;
	}
 
	public boolean isLogRequest() {
		return logRequest;
	}
 
	public void setLogRequest(final boolean logRequest) {
		this.logRequest = logRequest;
	}
 
	public boolean isLogHeaders() {
		return logHeaders;
	}
 
	public void setLogHeaders(final boolean logHeaders) {
		this.logHeaders = logHeaders;
	}
 
	public boolean isLogParameters() {
		return logParameters;
	}
 
	public void setLogParameters(final boolean logParameters) {
		this.logParameters = logParameters;
	}
 
}

Now we need to configure the filter:

Pay attention: a wrong configuration, at this point, can seriously break (read: make unavailable!!!) your Magnolia instance.
Best practice: copy an existing filter node from its position to a safe place (e.g.: an existing /modules/xyz). Configure it in that place and then, better after a backup, move it under /server/filters position again.

With this approach, you can set the log level (by default it is set to debug, but you can set it to warn or info) and you can select what to log (request, headers, parameters…). Changes reflects at runtime and the bypasses node avoid to log each (a lot!!) request to Magnolia AdminCentral.

This is the output:

2011-10-26 10:13:05,249 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: **************************************** LoggerFilter ****************************************
2011-10-26 10:13:05,249 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [host] has value of [www.mysite.local:8090]
2011-10-26 10:13:05,249 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [user-agent] has value of [Mozilla/5.0 (Windows NT 6.1; WOW64; rv:7.0.1) Gecko/20100101 Firefox/7.0.1]
2011-10-26 10:13:05,249 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [accept] has value of [text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8]
2011-10-26 10:13:05,249 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [accept-language] has value of [it-it,it;q=0.8,en-us;q=0.5,en;q=0.3]
2011-10-26 10:13:05,249 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [accept-encoding] has value of [gzip, deflate]
2011-10-26 10:13:05,249 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [accept-charset] has value of [ISO-8859-1,utf-8;q=0.7,*;q=0.7]
2011-10-26 10:13:05,250 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [connection] has value of [keep-alive]
2011-10-26 10:13:05,250 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [referer] has value of [http://www.mysite.local:8090/magnoliaAuthor/.magnolia/installer/status]
2011-10-26 10:13:05,250 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [cookie] has value of [JSESSIONID=310FC959199EE6F3FD8494532643BD66]
2011-10-26 10:13:05,250 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [pragma] has value of [no-cache]
2011-10-26 10:13:05,250 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: Request header [cache-control] has value of [no-cache]
2011-10-26 10:13:05,250 DEBUG om.tinext.ecp.magnolia.common.filters.LoggerFilter: **************************************** ------------ ****************************************

Hope it helps!!!

PS: it is similar (but maybe more simple) to what info.magnolia.debug.DumpHeadersFilter does but in this case we can have different behaviours on different environments only changing filter configurations. For instance:

  • Env A: test
    • logLevel = debug
    • logRequest = true
  • Env B: pre-prod
    • logLevel = info
    • logRequest = true
    • logHeaders = false (because we don’t need them on that env)
  • Env C: prod
    • logLevel = warn (because log4j has been set to be “silent”)
    • logRequest = true
    • logHeaders = true
    • logParameters = false (because we don’t need them on that env)

On the other hand, DumpHeadersFilter class let you to print even request headers after than the filter chain has ended (for that reason, I will update my LoggerFilter!!!)

Latest articles

Matteo Pelucco Written by:

4 Comments

  1. Jan
    October 26

    Nice. Was about to suggest the DHF when I read your last line 😀

    Can you elaborate more on the differences between one and the other?

  2. Matteo Pelucco
    October 26

    Done! 🙂 Thanks Jan, again..

  3. Greg
    October 26

    Yup, I like the configurability of your filter. How about patching the one in magnolia-core to add this feature?

  4. Matteo Pelucco
    October 26

    Why not Grég? Give me a minute and I will send you a patch 🙂

Leave a Reply to Greg

Your email address will not be published. Required fields are marked *


six − = 0