Merge pull request #152 from solidjb/master

Support for elapsed time to jetty and tomcat access logs

logback-access/pom.xml

@@ -50,6 +50,13 @@
       <optional>true</optional>
     </dependency>
 
+    <dependency>
+      <groupId>org.apache.tomcat</groupId>
+      <artifactId>tomcat-coyote</artifactId>
+      <scope>compile</scope>
+      <optional>true</optional>
+    </dependency>
+
     <dependency>
       <groupId>org.eclipse.jetty</groupId>
       <artifactId>jetty-server</artifactId>
@@ -58,7 +65,7 @@
     </dependency>
 
     <dependency>
-       <groupId>org.codehaus.janino</groupId>
+      <groupId>org.codehaus.janino</groupId>
       <artifactId>janino</artifactId>
       <scope>compile</scope>
       <optional>true</optional>
@@ -141,13 +148,13 @@
                 Bnd's analysis of java code.
             -->
             <Import-Package>
-                ch.qos.logback.core.rolling,
-                ch.qos.logback.core.rolling.helper,
-                javax.servlet.*;version="2.5",
-                javax.*;resolution:=optional,
-                org.apache.catalina.*;version="${tomcat.version}";resolution:=optional,
-                org.eclipse.jetty.*;version="${jetty.version}";resolution:=optional,
-                *
+              ch.qos.logback.core.rolling,
+              ch.qos.logback.core.rolling.helper,
+              javax.servlet.*;version="2.5",
+              javax.*;resolution:=optional,
+              org.apache.catalina.*;version="${tomcat.version}";resolution:=optional,
+              org.eclipse.jetty.*;version="${jetty.version}";resolution:=optional,
+              *
             </Import-Package>
             <Bundle-RequiredExecutionEnvironment>J2SE-1.5
             </Bundle-RequiredExecutionEnvironment>

logback-access/src/main/java/ch/qos/logback/access/PatternLayout.java

@@ -13,11 +13,9 @@
  */
 package ch.qos.logback.access;
 
-import java.util.HashMap;
-import java.util.Map;
-
 import ch.qos.logback.access.pattern.ContentLengthConverter;
 import ch.qos.logback.access.pattern.DateConverter;
+import ch.qos.logback.access.pattern.ElapsedTimeConverter;
 import ch.qos.logback.access.pattern.EnsureLineSeparation;
 import ch.qos.logback.access.pattern.FullRequestConverter;
 import ch.qos.logback.access.pattern.FullResponseConverter;
@@ -46,6 +44,9 @@
 import ch.qos.logback.core.pattern.color.*;
 import ch.qos.logback.core.pattern.parser.Parser;
 
+import java.util.HashMap;
+import java.util.Map;
+
 /**
  * <p>
  * This class is a module-specific implementation of
@@ -54,10 +55,10 @@
  * way to format the logging output that is just as easy and flexible as the
  * usual <code>PatternLayout</code>.
  * </p>
- * <p>
+ * <p/>
  * For more information about this layout, please refer to the online manual at
  * http://logback.qos.ch/manual/layouts.html#AccessPatternLayout
- * 
+ *
  * @author Ceki G&uuml;lc&uuml;
  * @author S&eacute;bastien Pennec
  */
@@ -122,22 +123,22 @@ public class PatternLayout extends PatternLayoutBase<IAccessEvent> {
     defaultConverterMap.put("server", ServerNameConverter.class.getName());
 
     defaultConverterMap.put("localPort", LocalPortConverter.class.getName());
-    
+
     defaultConverterMap.put("requestAttribute", RequestAttributeConverter.class
         .getName());
     defaultConverterMap.put("reqAttribute", RequestAttributeConverter.class
         .getName());
-    
+
     defaultConverterMap
         .put("reqCookie", RequestCookieConverter.class.getName());
     defaultConverterMap
-    .put("requestCookie", RequestCookieConverter.class.getName());
+        .put("requestCookie", RequestCookieConverter.class.getName());
+
 
-
     defaultConverterMap.put("responseHeader", ResponseHeaderConverter.class
         .getName());
-    
-    
+
+
     defaultConverterMap.put("requestParameter", RequestParameterConverter.class
         .getName());
     defaultConverterMap.put("reqParameter", RequestParameterConverter.class
@@ -150,7 +151,9 @@ public class PatternLayout extends PatternLayoutBase<IAccessEvent> {
     defaultConverterMap.put("fullRequest", FullRequestConverter.class.getName());
     defaultConverterMap.put("fullResponse", FullResponseConverter.class.getName());
 
-
+    defaultConverterMap.put("elapsedTime", ElapsedTimeConverter.class.getName());
+    defaultConverterMap.put("D", ElapsedTimeConverter.class.getName());
+
     defaultConverterMap.put("n", LineSeparatorConverter.class.getName());
 
     defaultConverterMap.put("black", BlackCompositeConverter.class.getName());
@@ -171,7 +174,7 @@ public class PatternLayout extends PatternLayoutBase<IAccessEvent> {
     defaultConverterMap.put("boldWhite", BoldWhiteCompositeConverter.class.getName());
   }
 
-  
+
   public PatternLayout() {
     // set a default value for pattern
     setPattern(CLF_PATTERN);

logback-access/src/main/java/ch/qos/logback/access/jetty/JettyServerAdapter.java

@@ -13,27 +13,26 @@
  */
 package ch.qos.logback.access.jetty;
 
-import java.util.Enumeration;
-import java.util.HashMap;
-import java.util.Map;
-
+import ch.qos.logback.access.spi.ServerAdapter;
 import org.eclipse.jetty.http.HttpFields;
 import org.eclipse.jetty.server.Request;
 import org.eclipse.jetty.server.Response;
 
-import ch.qos.logback.access.spi.ServerAdapter;
+import java.util.Enumeration;
+import java.util.HashMap;
+import java.util.Map;
 
 /**
  * A jetty specific implementation of the {@link ServerAdapter} interface.
- * 
+ *
  * @author Sébastien Pennec
  * @author Ceki Gulcu
  */
 public class JettyServerAdapter implements ServerAdapter {
 
   Request request;
   Response response;
-  
+
   public JettyServerAdapter(Request jettyRequest, Response jettyResponse) {
     this.request = jettyRequest;
     this.response = jettyResponse;
@@ -47,6 +46,10 @@ public int getStatusCode() {
     return response.getStatus();
   }
 
+  public long getRequestTimestamp() {
+    return request.getTimeStamp();
+  }
+
   public Map<String, String> buildResponseHeaderMap() {
     Map<String, String> responseHeaderMap = new HashMap<String, String>();
     HttpFields httpFields = response.getHttpFields();
@@ -58,5 +61,5 @@ public Map<String, String> buildResponseHeaderMap() {
     }
     return responseHeaderMap;
   }
-  
+
 }

logback-access/src/main/java/ch/qos/logback/access/pattern/ElapsedTimeConverter.java

@@ -0,0 +1,24 @@
+/**
+ * Logback: the reliable, generic, fast and flexible logging framework.
+ * Copyright (C) 1999-2013, QOS.ch. All rights reserved.
+ *
+ * This program and the accompanying materials are dual-licensed under
+ * either the terms of the Eclipse Public License v1.0 as published by
+ * the Eclipse Foundation
+ *
+ *   or (per the licensee's choosing)
+ *
+ * under the terms of the GNU Lesser General Public License version 2.1
+ * as published by the Free Software Foundation.
+ */
+package ch.qos.logback.access.pattern;
+
+import ch.qos.logback.access.spi.IAccessEvent;
+
+public class ElapsedTimeConverter extends AccessConverter {
+
+  public String convert(IAccessEvent accessEvent) {
+    return Long.toString(accessEvent.getElapsedTime());
+  }
+
+}

logback-access/src/main/java/ch/qos/logback/access/spi/AccessEvent.java

@@ -13,6 +13,13 @@
  */
 package ch.qos.logback.access.spi;
 
+import ch.qos.logback.access.AccessConstants;
+import ch.qos.logback.access.pattern.AccessConverter;
+import ch.qos.logback.access.servlet.Util;
+
+import javax.servlet.http.Cookie;
+import javax.servlet.http.HttpServletRequest;
+import javax.servlet.http.HttpServletResponse;
 import java.io.Serializable;
 import java.util.ArrayList;
 import java.util.Enumeration;
@@ -22,30 +29,22 @@
 import java.util.TreeMap;
 import java.util.Vector;
 
-import javax.servlet.http.Cookie;
-import javax.servlet.http.HttpServletRequest;
-import javax.servlet.http.HttpServletResponse;
-
-import ch.qos.logback.access.AccessConstants;
-import ch.qos.logback.access.pattern.AccessConverter;
-import ch.qos.logback.access.servlet.Util;
-
 // Contributors:  Joern Huxhorn (see also bug #110)
 
 /**
  * The Access module's internal representation of logging events. When the
  * logging component instance is called in the container to log then a
  * <code>AccessEvent</code> instance is created. This instance is passed
  * around to the different logback components.
- * 
+ *
  * @author Ceki G&uuml;lc&uuml;
  * @author S&eacute;bastien Pennec
  */
 public class AccessEvent implements Serializable, IAccessEvent {
 
-  
+
   private static final long serialVersionUID = 866718993618836343L;
-  
+
   private static final String EMPTY = "";
 
   private transient final HttpServletRequest httpRequest;
@@ -61,6 +60,7 @@ public class AccessEvent implements Serializable, IAccessEvent {
   String serverName;
   String requestContent;
   String responseContent;
+  long elapsedTime;
 
   Map<String, String> requestHeaderMap;
   Map<String, String[]> requestParameterMap;
@@ -79,27 +79,28 @@ public class AccessEvent implements Serializable, IAccessEvent {
   private long timeStamp = 0;
 
   public AccessEvent(HttpServletRequest httpRequest,
-      HttpServletResponse httpResponse, ServerAdapter adapter) {
+                     HttpServletResponse httpResponse, ServerAdapter adapter) {
     this.httpRequest = httpRequest;
     this.httpResponse = httpResponse;
     this.timeStamp = System.currentTimeMillis();
     this.serverAdapter = adapter;
+    this.elapsedTime = calculateElapsedTime();
   }
 
   /**
-   * Returns the underlying HttpServletRequest. After serialization the returned 
-   * value will be null. 
-   * 
+   * Returns the underlying HttpServletRequest. After serialization the returned
+   * value will be null.
+   *
    * @return
    */
   public HttpServletRequest getRequest() {
     return httpRequest;
   }
 
   /**
-   * Returns the underlying HttpServletResponse. After serialization the returned 
-   * value will be null. 
-   * 
+   * Returns the underlying HttpServletResponse. After serialization the returned
+   * value will be null.
+   *
    * @return
    */
   public HttpServletResponse getResponse() {
@@ -293,7 +294,7 @@ public Map<String, String[]> getRequestParameterMap() {
 
   /**
    * Attributes are not serialized
-   * 
+   *
    * @param key
    */
   public String getAttribute(String key) {
@@ -313,12 +314,12 @@ public String[] getRequestParameter(String key) {
     if (httpRequest != null) {
       String[] value = httpRequest.getParameterValues(key);
       if (value == null) {
-        return new String[] { NA };
+        return new String[]{ NA };
       } else {
         return value;
       }
     } else {
-      return new String[] { NA };
+      return new String[]{ NA };
     }
   }
 
@@ -358,6 +359,17 @@ public int getStatusCode() {
     return statusCode;
   }
 
+  public long getElapsedTime() {
+    return elapsedTime;
+  }
+
+  private long calculateElapsedTime() {
+    if (serverAdapter.getRequestTimestamp() < 0) {
+      return -1;
+    }
+    return getTimeStamp() - serverAdapter.getRequestTimestamp();
+  }
+
   public String getRequestContent() {
     if (requestContent != null) {
       return requestContent;
@@ -482,6 +494,7 @@ public void prepareForDeferredProcessing() {
     getRequestURL();
     getServerName();
     getTimeStamp();
+    getElapsedTime();
 
     getStatusCode();
     getContentLength();

logback-access/src/main/java/ch/qos/logback/access/spi/IAccessEvent.java

@@ -13,13 +13,13 @@
  */
 package ch.qos.logback.access.spi;
 
+import ch.qos.logback.core.spi.DeferredProcessingAware;
+
+import javax.servlet.http.HttpServletRequest;
+import javax.servlet.http.HttpServletResponse;
 import java.util.Enumeration;
 import java.util.List;
 import java.util.Map;
-import javax.servlet.http.HttpServletRequest;
-import javax.servlet.http.HttpServletResponse;
-
-import ch.qos.logback.core.spi.DeferredProcessingAware;
 
 // Contributors:  Joern Huxhorn (see also bug #110)
 
@@ -60,6 +60,11 @@ public interface IAccessEvent extends DeferredProcessingAware {
    */
   long getTimeStamp();
 
+  /**
+   * The time elapsed between receiving the request and logging it.
+   */
+  long getElapsedTime();
+
   String getRequestURI();
 
   /**

logback-access/src/main/java/ch/qos/logback/access/spi/ServerAdapter.java

@@ -24,6 +24,7 @@
  */
 public interface ServerAdapter {
 
+  long getRequestTimestamp();
   long getContentLength();
   int getStatusCode();
   Map<String, String> buildResponseHeaderMap();