Saturday, November 9, 2013

Logging - using ThreadLocal to log messages in one single thread



Logging in your application can be a costly operation. Although frameworks like Log4j provide async logging, it is still costlier. Although the eventual cost of logging depends on to what you are writing your logs to, typically this is a file or a database and this can be a costly operation.

One cool logging strategy is to log everything that happens in one thread at the completion of the thread. Instead of calling your logger multiple times in a thread, just call it once with all the logging information at the end of the thread. The code snippet below can be used to implement such logging.

The code below is written for a web application with a CustomHttpServletRequest. How to write a custom request object is explained in my previous post, link here. CustomHttpServletRequest can safely be replaced with HttpServletRequest in the code below.

Set a cookie enableDebug = true when sending a request to webapp, this will log the debug messages else it will log only error messages. Call ThreadLogger.logStartOfRequest() method to kickoff the enableDebug. In one of my previous posts this gets called from a filter.

This can be slightly modified to work not just for your web applications,  but also for your standalone apps.
(just comment logStartOfRequest() method and find some other way to enableDebug).

import java.io.ByteArrayOutputStream;
import java.io.OutputStreamWriter;
import java.io.PrintWriter;
import java.util.Collections;
import java.util.Enumeration;
import java.util.List;

import javax.servlet.http.Cookie;

public class ThreadLogger {

    private static final String TYPE_MESSAGE = "] ";
    private static final String TYPE_WARNING = "] WARN ";
    private static final String TYPE_ERROR = "] ERROR ";

    private static final class LogBuffer {
        private final ByteArrayOutputStream out;
        private final PrintWriter pw;

        /**
         * Initializes a new instance.
         */
        public LogBuffer() {
            out = new ByteArrayOutputStream();
            pw = new PrintWriter(new OutputStreamWriter(out), true);
        }

        public void appendEntry(String caller, String message, String type,
                Throwable t) {
            pw.print('[');
            pw.print(caller);
            pw.print(type);
            pw.println(message);

            if (t != null) {
                t.printStackTrace(pw);
            }
        }

        /**
         * Returns the content of the buffer, and resets the object for
         * continued use.
         */
        public String toString() {
            final String content = out.toString();
            out.reset();

            return content;
        }
    }

    private static final ThreadLocal<LogBuffer> content = new ThreadLocal<LogBuffer>();
    private static final ThreadLocal<Boolean> enabled = new ThreadLocal<Boolean>();

    private static LogBuffer getLogBuffer() {
        LogBuffer result = content.get();
        if (result == null) {
            result = new LogBuffer();
            content.set(result);
        }
        return result;
    }

    private static void appendCookie(StringBuilder sw, Cookie cookie) {
        if (cookie != null) {
            sw.append("\n  cookie[");
            sw.append(cookie.getName());
            sw.append("] = ");
            sw.append(cookie.getValue());
        }
    }

    private static void appendHeader(StringBuilder sw, String name,
            CustomHttpServletRequestWrapper request) {

        @SuppressWarnings("unchecked")
        final List<String> values = Collections.list(request.getHeaders(name));
        if (values.size() > 0) {
            sw.append("\n  header[").append(name).append("] = ");
            for (int index = 0; index < values.size(); index++) {
                if (index > 0) {
                    sw.append(", ");
                }

                sw.append(values.get(index));

            }
        }
    }

    private static void appendParameter(StringBuilder sw, String name,
            CustomHttpServletRequestWrapper request) {
        String value = request.getParameter(name);
        if (value != null) {
            sw.append("\n  param[");
            sw.append(name);
            sw.append("] = ");

            if (name.contains("username") || name.contains("password")) {
                // truncate username and password for security purposes
                sw.append(value.substring(0, 1) + "........");
            } else {
                sw.append(value);
            }
        }
    }

    private static void appendHeaders(final StringBuilder sb,
            CustomHttpServletRequestWrapper request) {
        Enumeration<String> names = request.getHeaderNames();
        while (names.hasMoreElements()) {
            String name = names.nextElement();
            if (!"Cookie".equalsIgnoreCase(name)) {
                appendHeader(sb, name, request);
            }
        }
    }

    private static void appendParameters(final StringBuilder sb,
            CustomHttpServletRequestWrapper request) {
        Enumeration<String> names = request.getParameterNames();
        while (names.hasMoreElements()) {
            String name = names.nextElement();
            appendParameter(sb, name, request);
        }
    }

    private static void appendCookies(final StringBuilder sb,
            CustomHttpServletRequestWrapper request) {

        Cookie[] cookies = request.getCookies();

        if (cookies != null) {
            for (Cookie cookie : cookies) {
                appendCookie(sb, cookie);

            }
        }

    }

    // this must be called to enableDebug mode if it is set.
    public static void logStartOfRequest(String caller,
            CustomHttpServletRequestWrapper request) {
        final StringBuilder sw = new StringBuilder(256);

        sw.append(" ").append(request.getMethod()).append(" request from ")
                .append(request.getRemoteAddr());
        sw.append("\n  queryString = " + request.getQueryString());

        appendHeaders(sw, request);
        appendParameters(sw, request);
        appendCookies(sw, request);

        getLogBuffer().appendEntry(caller, sw.toString(), TYPE_MESSAGE, null);
        Cookie enableDebug = getCookieValue(request, "enableDebug");

        if (enableDebug != null && "true".equals(enableDebug.getValue())) {
            enabled.set(true);
        }
    }

    public static void flush() {
        if (Boolean.TRUE.equals(enabled.get())) {
            LogBuffer buffer = content.get();
            System.out.print(buffer.toString()); // log it to a log file using
                                                    // Log4j
        }
        content.remove();
        enabled.remove();
    }

    public static void message(String caller, String message) {
        getLogBuffer().appendEntry(caller, message, TYPE_MESSAGE, null);
    }

    public static void warn(String caller, String message) {
        getLogBuffer().appendEntry(caller, message, TYPE_WARNING, null);
    }

    public static void warn(String caller, String message, Throwable t) {
        getLogBuffer().appendEntry(caller, message, TYPE_WARNING, t);
    }

    public static void error(String caller, String message) {
        enabled.set(true);
        getLogBuffer().appendEntry(caller, message, TYPE_ERROR, null);
    }

    public static void error(String caller, String message, Throwable t) {
        enabled.set(true);
        getLogBuffer().appendEntry(caller, message, TYPE_ERROR, t);
    }

    private static Cookie getCookieValue(
            CustomHttpServletRequestWrapper request, String name) {
        Cookie[] cookies = request.getCookies();

        if (cookies != null) {
            for (Cookie cookie : cookies) {
                if (cookie.getName().equals(name)) {
                    return cookie;
                }
            }
        }

        return null;
    }

}

No comments:

Post a Comment