445823 Moved RequestLog calling to HttpChannel

Simplified the RequestLogHandler.  It no longer set's async listeners or tries to catch exeptions etc.
Instead it simply sets the RequestLog instance on the HttpChannel.   The HttpChannel#onCompleted method
then uses the log (if set) as the last thing before recycling the connection.  It uses the actual
bytes written (eg after compression) and the actual status sent (eg if sent from a bad message).

jetty-server/src/main/java/org/eclipse/jetty/server/AbstractNCSARequestLog.java

@@ -83,10 +83,10 @@ protected StringBuilder initialValue()
      * Writes the request and response information to the output stream.
      *
      * @see org.eclipse.jetty.server.RequestLog#log(org.eclipse.jetty.server.Request,
-     *      org.eclipse.jetty.server.Response)
+     *      int, long)
      */
     @Override
-    public void log(Request request, Response response)
+    public void log(Request request, int status, long written)
     {
         try
         {
@@ -136,30 +136,28 @@ public void log(Request request, Response response)
             buf.append(request.getProtocol());
             buf.append("\" ");
 
-            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)));
 
-            long responseLength = response.getLongContentLength();
-            if (responseLength >= 0)
+            if (written >= 0)
             {
                 buf.append(' ');
-                if (responseLength > 99999)
-                    buf.append(responseLength);
+                if (written > 99999)
+                    buf.append(written);
                 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));
+                    if (written > 9999)
+                        buf.append((char)('0' + ((written / 10000) % 10)));
+                    if (written > 999)
+                        buf.append((char)('0' + ((written / 1000) % 10)));
+                    if (written > 99)
+                        buf.append((char)('0' + ((written / 100) % 10)));
+                    if (written > 9)
+                        buf.append((char)('0' + ((written / 10) % 10)));
+                    buf.append((char)('0' + (written) % 10));
                 }
                 buf.append(' ');
             }
@@ -168,7 +166,7 @@ public void log(Request request, Response response)
 
 
             if (_extended)
-                logExtended(request, response, buf);
+                logExtended(request, buf);
 
             if (_logCookies)
             {
@@ -216,12 +214,10 @@ public void log(Request request, Response response)
      * Writes extended request and response information to the output stream.
      *
      * @param request  request object
-     * @param response response object
      * @param b        StringBuilder to write to
      * @throws IOException
      */
     protected void logExtended(Request request,
-                               Response response,
                                StringBuilder b) throws IOException
     {
         String referer = request.getHeader(HttpHeader.REFERER.toString());

jetty-server/src/main/java/org/eclipse/jetty/server/HttpChannel.java

@@ -25,6 +25,7 @@
 import java.util.List;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicInteger;
+
 import javax.servlet.DispatcherType;
 import javax.servlet.RequestDispatcher;
 import javax.servlet.http.HttpServletRequest;
@@ -43,6 +44,7 @@
 import org.eclipse.jetty.server.HttpChannelState.Action;
 import org.eclipse.jetty.server.handler.ContextHandler;
 import org.eclipse.jetty.server.handler.ErrorHandler;
+import org.eclipse.jetty.util.BufferUtil;
 import org.eclipse.jetty.util.Callback;
 import org.eclipse.jetty.util.SharedBlockingCallback.Blocker;
 import org.eclipse.jetty.util.log.Log;
@@ -96,6 +98,9 @@ protected static HttpChannel setCurrentHttpChannel(HttpChannel channel)
     private final Response _response;
     private MetaData.Response _committedInfo;
     private RequestLog _requestLog;
+
+    /** Bytes written after interception (eg after compression) */
+    private long _written;
 
     public HttpChannel(Connector connector, HttpConfiguration configuration, EndPoint endPoint, HttpTransport transport, HttpInput input)
     {
@@ -133,6 +138,21 @@ public HttpTransport getHttpTransport()
         return _transport;
     }
 
+    public RequestLog getRequestLog()
+    {
+        return _requestLog;
+    }
+
+    public void setRequestLog(RequestLog requestLog)
+    {
+        _requestLog = requestLog;
+    }
+
+    public MetaData.Response getCommittedInfo()
+    {
+        return _committedInfo;
+    }
+
     /**
      * Get the idle timeout.
      * <p>This is implemented as a call to {@link EndPoint#getIdleTimeout()}, but may be
@@ -212,6 +232,7 @@ public void recycle()
         _response.recycle();
         _committedInfo=null;
         _requestLog=null;
+        _written=0;
     }
 
     @Override
@@ -401,7 +422,7 @@ public boolean handle()
             finally
             {
                 _request.setHandled(true);
-                _transport.completed();
+                onCompleted();
             }
         }
 
@@ -507,8 +528,9 @@ public void onRequestComplete()
 
     public void onCompleted()
     {
-        if (_requestLog!=null)
-            _requestLog.log(_request,_response);        
+        if (_requestLog!=null )
+            _requestLog.log(_request,_committedInfo==null?-1:_committedInfo.getStatus(), _written);   
+        _transport.completed();
     }
 
     public void onEarlyEOF()
@@ -545,6 +567,7 @@ public void onBadMessage(int status, String reason)
                 _state.completed();
             else 
                 throw new IllegalStateException();
+            onCompleted();
         }
     }
 
@@ -555,15 +578,14 @@ protected boolean sendResponse(MetaData.Response info, ByteBuffer content, boole
         {
             // We need an info to commit
             if (info==null)
-                info = _response.newResponseInfo();
+                info = _response.newResponseMetaData();
             commit(info);
 
             // wrap callback to process 100 responses
             final int status=info.getStatus();
             final Callback committed = (status<200&&status>=100)?new Commit100Callback(callback):new CommitCallback(callback);
 
             // committing write
-            _committedInfo=info;
             _transport.send(info, _request.isHead(), content, complete, committed);
         }
         else if (info==null)
@@ -597,6 +619,7 @@ protected boolean sendResponse(MetaData.Response info, ByteBuffer content, boole
 
     protected void commit (MetaData.Response info)
     {
+        _committedInfo=info;
         if (LOG.isDebugEnabled())
             LOG.debug("Commit {} to {}",info,this);
     }
@@ -616,6 +639,7 @@ public boolean isCommitted()
     @Override
     public void write(ByteBuffer content, boolean complete, Callback callback)
     {
+        _written+=BufferUtil.length(content);
         sendResponse(null,content,complete,callback);
     }
 

jetty-server/src/main/java/org/eclipse/jetty/server/HttpChannelState.java

@@ -514,7 +514,6 @@ protected void completed()
 
             event.completed();
         }
-        _channel.onCompleted();
     }
 
     protected void recycle()

jetty-server/src/main/java/org/eclipse/jetty/server/HttpOutput.java

@@ -64,7 +64,10 @@ public interface Interceptor
     private final HttpChannel _channel;
     private final SharedBlockingCallback _writeBlock;
     private Interceptor _filter;
+
+    /** Bytes written via the write API (excludes bytes written via sendContent). Used to autocommit once content length is written. */
     private long _written;
+
     private ByteBuffer _aggregate;
     private int _bufferSize;
     private int _commitSize;

jetty-server/src/main/java/org/eclipse/jetty/server/RequestLog.java

@@ -26,5 +26,5 @@
  */
 public interface RequestLog extends LifeCycle
 {
-    public void log(Request request, Response response);
+    public void log(Request request, int status, long written);
 }

jetty-server/src/main/java/org/eclipse/jetty/server/Response.java

@@ -1239,7 +1239,7 @@ public void resetBuffer()
         _out.resetBuffer();
     }
 
-    protected MetaData.Response newResponseInfo()
+    protected MetaData.Response newResponseMetaData()
     {
         return new MetaData.Response(_channel.getRequest().getHttpVersion(), getStatus(), getReason(), _fields, getLongContentLength());
     }

jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java

@@ -28,6 +28,7 @@
 import javax.servlet.http.HttpServletResponse;
 
 import org.eclipse.jetty.server.AsyncContextState;
+import org.eclipse.jetty.server.HttpChannel;
 import org.eclipse.jetty.server.Request;
 import org.eclipse.jetty.server.RequestLog;
 import org.eclipse.jetty.server.Response;
@@ -46,41 +47,7 @@
  */
 public class RequestLogHandler extends HandlerWrapper
 {
-    private static final Logger LOG = Log.getLogger(RequestLogHandler.class);
     private RequestLog _requestLog;
-    private final AsyncListener _listener = new AsyncListener()
-    {
-
-        @Override
-        public void onTimeout(AsyncEvent event) throws IOException
-        {
-
-        }
-
-        @Override
-        public void onStartAsync(AsyncEvent event) throws IOException
-        {
-            event.getAsyncContext().addListener(this);
-        }
-
-        @Override
-        public void onError(AsyncEvent event) throws IOException
-        {
-            HttpServletResponse response = (HttpServletResponse)event.getAsyncContext().getResponse();
-            if (!response.isCommitted())
-                response.setStatus(500);
-
-        }
-
-        @Override
-        public void onComplete(AsyncEvent event) throws IOException
-        {
-            AsyncContextState context = (AsyncContextState)event.getAsyncContext();
-            Request request=context.getHttpChannelState().getBaseRequest();
-            Response response=request.getResponse();
-            _requestLog.log(request,response);
-        }
-    };
 
     /* ------------------------------------------------------------ */
     /*
@@ -90,29 +57,9 @@ public void onComplete(AsyncEvent event) throws IOException
     public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response)
             throws IOException, ServletException
     {
-        try
-        {
-            super.handle(target, baseRequest, request, response);
-        }
-        catch(Error|IOException|ServletException|RuntimeException e)
-        {
-            if (!response.isCommitted() && !baseRequest.getHttpChannelState().isAsync())
-                response.setStatus(500);
-            throw e;
-        }
-        finally
-        {
-            if (_requestLog != null && baseRequest.getDispatcherType().equals(DispatcherType.REQUEST))
-            {
-                if (baseRequest.getHttpChannelState().isAsync())
-                {
-                    if (baseRequest.getHttpChannelState().isInitial())
-                        baseRequest.getAsyncContext().addListener(_listener);
-                }
-                else
-                    _requestLog.log(baseRequest, (Response)response);
-            }
-        }
+        baseRequest.getHttpChannel().setRequestLog(_requestLog);
+        if (_handler!=null)
+            _handler.handle(target,baseRequest, request, response);
     }
 
     /* ------------------------------------------------------------ */
@@ -128,35 +75,5 @@ public RequestLog getRequestLog()
         return _requestLog;
     }
 
-    /* ------------------------------------------------------------ */
-    @Override
-    protected void doStart() throws Exception
-    {
-        if (_requestLog==null)
-        {
-            LOG.warn("!RequestLog");
-            _requestLog=new NullRequestLog();
-        }
-        super.doStart();
-    }
-
-    /* ------------------------------------------------------------ */
-    @Override
-    protected void doStop() throws Exception
-    {
-        super.doStop();
-        if (_requestLog instanceof NullRequestLog)
-            _requestLog=null;
-    }
 
-    /* ------------------------------------------------------------ */
-    /* ------------------------------------------------------------ */
-    /* ------------------------------------------------------------ */
-    private static class NullRequestLog extends AbstractLifeCycle implements RequestLog
-    {
-        @Override
-        public void log(Request request, Response response)
-        {            
-        }
-    }
 }

jetty-server/src/test/java/org/eclipse/jetty/server/handler/BadRequestLogHandlerTest.java

@@ -43,7 +43,6 @@
 import org.eclipse.jetty.server.Connector;
 import org.eclipse.jetty.server.Request;
 import org.eclipse.jetty.server.RequestLog;
-import org.eclipse.jetty.server.Response;
 import org.eclipse.jetty.server.Server;
 import org.eclipse.jetty.server.ServerConnector;
 import org.eclipse.jetty.util.IO;
@@ -72,9 +71,9 @@ public static class CaptureLog extends AbstractLifeCycle implements RequestLog
         public List<String> captured = new ArrayList<>();
 
         @Override
-        public void log(Request request, Response response)
+        public void log(Request request, int status, long written)
         {
-            captured.add(String.format("%s %s %s %03d",request.getMethod(),request.getHttpURI(),request.getProtocol(),response.getStatus()));
+            captured.add(String.format("%s %s %s %03d",request.getMethod(),request.getHttpURI(),request.getProtocol(),status));
         }
     }
 

jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogHandlerTest.java

@@ -76,9 +76,9 @@ public static class CaptureLog extends AbstractLifeCycle implements RequestLog
         public List<String> captured = new ArrayList<>();
 
         @Override
-        public void log(Request request, Response response)
+        public void log(Request request, int status, long written)
         {
-            captured.add(String.format("%s %s %s %03d",request.getMethod(),request.getRequestURI(),request.getProtocol(),response.getStatus()));
+            captured.add(String.format("%s %s %s %03d",request.getMethod(),request.getRequestURI(),request.getProtocol(),status));
         }
     }
 
@@ -663,9 +663,9 @@ public void testLogHandlerCollection_DispatchErrorHandler() throws Exception
         server.addBean(errorDispatcher);
 
         ContextHandlerCollection contexts = new ContextHandlerCollection();
-        ContextHandler errorContext = new ContextHandler("errorok");
+        ContextHandler errorContext = new ContextHandler("/errorok");
         errorContext.setHandler(new OKErrorHandler());
-        ContextHandler testContext = new ContextHandler("test");
+        ContextHandler testContext = new ContextHandler("/test");
         testContext.setHandler(testHandler);
         contexts.addHandler(errorContext);
         contexts.addHandler(testContext);