AsyncRequestLog.java

package grails.plugin.lightweightdeploy.logging;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.classic.spi.LoggingEvent;
import ch.qos.logback.core.Appender;
import ch.qos.logback.core.spi.AppenderAttachableImpl;
import com.codahale.metrics.Clock;

import java.util.*;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.atomic.AtomicInteger;
import org.eclipse.jetty.http.HttpHeaders;
import org.eclipse.jetty.server.Authentication;
import org.eclipse.jetty.server.Request;
import org.eclipse.jetty.server.RequestLog;
import org.eclipse.jetty.server.Response;
import org.eclipse.jetty.util.DateCache;
import org.eclipse.jetty.util.component.AbstractLifeCycle;
import org.slf4j.MDC;

import javax.servlet.http.Cookie;

public class AsyncRequestLog extends AbstractLifeCycle implements RequestLog {
    private static final AtomicInteger THREAD_COUNTER = new AtomicInteger();
    private static final int BATCH_SIZE = 10000;
    private List<String> cookies;

    private class Dispatcher implements Runnable {
        private volatile boolean running = true;
        private final List<String> statements = new ArrayList<String>(BATCH_SIZE);

        @Override
        public void run() {
            while (running) {
                try {
                    statements.add(queue.take());
                    queue.drainTo(statements, BATCH_SIZE);

                    for (String statement : statements) {
                        final LoggingEvent event = new LoggingEvent();
                        event.setLevel(Level.INFO);
                        event.setMessage(statement);
                        appenders.appendLoopOnAppenders(event);
                    }

                    statements.clear();
                } catch (InterruptedException ignored) {
                    Thread.currentThread().interrupt();
                }
            }
        }

        public void stop() {
            this.running = false;
        }
    }

    private final Clock clock;
    @SuppressWarnings("ThreadLocalNotStaticFinal")
    private final ThreadLocal<DateCache> dateCache;
    private final BlockingQueue<String> queue;
    private final Dispatcher dispatcher;
    private final Thread dispatchThread;
    private final AppenderAttachableImpl<ILoggingEvent> appenders;

    public AsyncRequestLog(Clock clock,
                           AppenderAttachableImpl<ILoggingEvent> appenders,
                           final TimeZone timeZone,
                           List<String> cookies) {
        this.clock = clock;
        this.cookies = cookies;
        this.queue = new LinkedBlockingQueue<String>();
        this.dispatcher = new Dispatcher();
        this.dispatchThread = new Thread(dispatcher);
        dispatchThread.setName("async-request-log-dispatcher-" + THREAD_COUNTER.incrementAndGet());
        dispatchThread.setDaemon(true);

        this.dateCache = new ThreadLocal<DateCache>() {
            @Override
            protected DateCache initialValue() {
                final DateCache cache = new DateCache("dd/MMM/yyyy:HH:mm:ss Z", Locale.US);
                cache.setTimeZoneID(timeZone.getID());
                return cache;
            }
        };

        this.appenders = appenders;
    }


    @Override
    protected void doStart() throws Exception {
        final Iterator<Appender<ILoggingEvent>> iterator = appenders.iteratorForAppenders();
        while (iterator.hasNext()) {
            iterator.next().start();
        }
        dispatchThread.start();
    }

    @Override
    protected void doStop() throws Exception {
        dispatcher.stop();
        final Iterator<Appender<ILoggingEvent>> iterator = appenders.iteratorForAppenders();
        while (iterator.hasNext()) {
            iterator.next().stop();
        }
    }

    @Override
    public void log(Request request, Response response) {
        // copied almost entirely from NCSARequestLog
        final StringBuilder buf = new StringBuilder(256);
        String address = request.getHeader(HttpHeaders.X_FORWARDED_FOR);
        if (address == null) {
            address = request.getRemoteAddr();
        }

        buf.append(address);
        buf.append(" - ");
        final Authentication authentication = request.getAuthentication();
        if (authentication instanceof Authentication.User) {
            buf.append(((Authentication.User) authentication).getUserIdentity()
                                                             .getUserPrincipal()
                                                             .getName());
        } else {
            buf.append('-');
        }

        buf.append(" [");
        buf.append(dateCache.get().format(request.getTimeStamp()));

        buf.append("] \"");
        buf.append(request.getMethod());
        buf.append(' ');
        buf.append(request.getUri().toString());
        buf.append(' ');
        buf.append(request.getProtocol());
        buf.append("\" ");
        if (request.getAsyncContinuation().isInitial()) {
            int status = response.getStatus();
            if (status <= 0) {
                status = 404;
            }
            buf.append((char) ('0' + ((status / 100) % 10)));
            buf.append((char) ('0' + ((status / 10) % 10)));
            buf.append((char) ('0' + (status % 10)));
        } else {
            buf.append("Async");
        }

        final long responseLength = response.getContentCount();
        if (responseLength >= 0) {
            buf.append(' ');
            if (responseLength > 99999) {
                buf.append(responseLength);
            } else {
                if (responseLength > 9999) {
                    buf.append((char) ('0' + ((responseLength / 10000) % 10)));
                }
                if (responseLength > 999) {
                    buf.append((char) ('0' + ((responseLength / 1000) % 10)));
                }
                if (responseLength > 99) {
                    buf.append((char) ('0' + ((responseLength / 100) % 10)));
                }
                if (responseLength > 9) {
                    buf.append((char) ('0' + ((responseLength / 10) % 10)));
                }
                buf.append((char) ('0' + (responseLength % 10)));
            }
        } else {
            buf.append(" -");
        }

        buf.append(' ');
        String referer = request.getHeader(HttpHeaders.REFERER);
        if (referer == null) {
            buf.append("\"-\"");
        } else {
            buf.append('"');
            buf.append(referer);
            buf.append('"');
        }

        buf.append(' ');
        String agent = request.getHeader(HttpHeaders.USER_AGENT);
        if (agent == null) {
            buf.append("\"-\"");
        } else {
            buf.append('"');
            buf.append(agent);
            buf.append('"');
        }

        final long now = clock.getTime();
        final long dispatchTime = request.getDispatchTime();

        buf.append(' ');
        buf.append(now - ((dispatchTime == 0) ? request.getTimeStamp() : dispatchTime));

        buf.append(' ');
        buf.append(now - request.getTimeStamp());

        buf.append(' ');
        buf.append(request.getAttribute("requestId"));

        buf.append(" \"");
        if (request.getCookies() != null) {
            boolean firstCookie = true;
            for (Cookie cookie : request.getCookies()) {
                if (cookies.contains(cookie.getName())) {
                    if (!firstCookie) buf.append("; ");
                    buf.append(cookie.getName());
                    buf.append('=');
                    buf.append(cookie.getValue());
                    if (firstCookie) firstCookie = false;
                }
            }
        }
        buf.append('"');

        queue.add(buf.toString());
    }
}