// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.container.jdisc; import com.google.inject.Inject; import com.yahoo.container.handler.Timing; import com.yahoo.container.http.AccessLogUtil; import com.yahoo.container.logging.AccessLog; import com.yahoo.container.logging.AccessLogEntry; import com.yahoo.jdisc.Metric; import com.yahoo.jdisc.Response; import com.yahoo.jdisc.handler.CompletionHandler; import com.yahoo.jdisc.handler.ContentChannel; import com.yahoo.jdisc.http.server.jetty.AccessLoggingRequestHandler; import com.yahoo.log.LogLevel; import com.yahoo.yolean.Exceptions; import java.io.IOException; import java.io.OutputStream; import java.net.InetSocketAddress; import java.net.SocketAddress; import java.net.URI; import java.util.Optional; import java.util.concurrent.Executor; /** * A request handler base class extending the features of * ThreadedHttpRequestHandler with access logging. * * @author Steinar Knutsen */ public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler { private AccessLog accessLog; public LoggingRequestHandler(Executor executor, AccessLog accessLog) { this(executor, accessLog, null); } public static class Context { final Executor executor; final AccessLog accessLog; final Metric metric; @Inject public Context(Executor executor, AccessLog accessLog, Metric metric) { this.executor = executor; this.accessLog = accessLog; this.metric = metric; } public Context(Context other) { this.executor = other.executor; this.accessLog = other.accessLog; this.metric = other.metric; } public Executor getExecutor() { return executor; } public AccessLog getAccessLog() { return accessLog; } public Metric getMetric() { return metric; } } public static Context testOnlyContext() { return new Context(new Executor() { @Override public void execute(Runnable command) { command.run(); } }, AccessLog.voidAccessLog(), null); } @Inject public LoggingRequestHandler(Context ctx) { this(ctx.executor, ctx.accessLog, ctx.metric); } public LoggingRequestHandler(Context ctx, boolean allowAsyncResponse) { this(ctx.executor, ctx.accessLog, ctx.metric, allowAsyncResponse); } public LoggingRequestHandler(Executor executor, AccessLog accessLog, Metric metric) { this(executor, accessLog, metric, false); } public LoggingRequestHandler(Executor executor, AccessLog accessLog, Metric metric, boolean allowAsyncResponse) { super(executor, metric, allowAsyncResponse); this.accessLog = accessLog; } @Override protected LoggingCompletionHandler createLoggingCompletionHandler(long startTime, long renderStartTime, HttpResponse response, HttpRequest httpRequest, ContentChannelOutputStream rendererWiring) { return new LoggingHandler(startTime, renderStartTime, httpRequest, response, rendererWiring); } private static String getClientIP(com.yahoo.jdisc.http.HttpRequest httpRequest) { SocketAddress clientAddress = httpRequest.getRemoteAddress(); if (clientAddress == null) return "0.0.0.0"; return clientAddress.toString(); } private static long getEvalStart(Timing timing, long startTime) { if (timing == null || timing.getQueryStartTime() == 0L) { return startTime; } else { return timing.getQueryStartTime(); } } private static String remoteHostAddress(com.yahoo.jdisc.http.HttpRequest httpRequest) { SocketAddress remoteAddress = httpRequest.getRemoteAddress(); if (remoteAddress == null) return "0.0.0.0"; if (remoteAddress instanceof InetSocketAddress) { return ((InetSocketAddress) remoteAddress).getAddress().getHostAddress(); } else { throw new RuntimeException("Expected remote address of type InetSocketAddress, got " + remoteAddress.getClass().getName()); } } private void logTimes(long startTime, String sourceIP, long renderStartTime, long commitStartTime, long endTime, String req, String normalizedQuery, Timing t) { // note: intentionally only taking time since request was received long totalTime = endTime - startTime; long timeoutInterval = Long.MAX_VALUE; long requestOverhead = 0; long summaryStartTime = 0; if (t != null) { timeoutInterval = t.getTimeout(); requestOverhead = t.getQueryStartTime() - startTime; summaryStartTime = t.getSummaryStartTime(); } if (totalTime <= timeoutInterval) { return; } StringBuilder b = new StringBuilder(); b.append(normalizedQuery); b.append(" from ").append(sourceIP).append(". "); if (requestOverhead > 0) { b.append("Time from HTTP connection open to request reception "); b.append(requestOverhead).append(" ms. "); } if (summaryStartTime != 0) { b.append("Request time: "); b.append(summaryStartTime - startTime).append(" ms. "); b.append("Summary fetch time: "); b.append(renderStartTime - summaryStartTime).append(" ms. "); } else { long spentSearching = renderStartTime - startTime; b.append("Processing time: ").append(spentSearching).append(" ms. "); } b.append("Result rendering/transfer: "); b.append(commitStartTime - renderStartTime).append(" ms. "); b.append("End transaction: "); b.append(endTime - commitStartTime).append(" ms. "); b.append("Total: ").append(totalTime).append(" ms. "); b.append("Timeout: ").append(timeoutInterval).append(" ms. "); b.append("Request string: ").append(req); log.log(LogLevel.WARNING, "Slow execution. " + b); } private static class NullResponse extends ExtendedResponse { NullResponse(int status) { super(status); } @Override public void render(OutputStream output, ContentChannel networkChannel, CompletionHandler handler) throws IOException { // NOP } } private class LoggingHandler implements LoggingCompletionHandler { private final long startTime; private final long renderStartTime; private long commitStartTime; private final HttpRequest httpRequest; private final HttpResponse httpResponse; private final ContentChannelOutputStream rendererWiring; private final ExtendedResponse extendedResponse; LoggingHandler(long startTime, long renderStartTime, HttpRequest httpRequest, HttpResponse httpResponse, ContentChannelOutputStream rendererWiring) { this.startTime = startTime; this.renderStartTime = renderStartTime; this.commitStartTime = renderStartTime; this.httpRequest = httpRequest; this.httpResponse = httpResponse; this.rendererWiring = rendererWiring; this.extendedResponse = actualOrNullObject(httpResponse); } /** Set the commit start time to the current time */ @Override public void markCommitStart() { this.commitStartTime = System.currentTimeMillis(); } private ExtendedResponse actualOrNullObject(HttpResponse response) { if (response instanceof ExtendedResponse) { return (ExtendedResponse) response; } else { return new NullResponse(Response.Status.OK); } } @Override public void completed() { long endTime = System.currentTimeMillis(); writeToLogs(endTime); } @Override public void failed(Throwable throwable) { long endTime = System.currentTimeMillis(); writeToLogs(endTime); if (log.isLoggable(LogLevel.DEBUG)) { log.log(LogLevel.DEBUG, "Got exception when writing to client: " + Exceptions.toMessageString(throwable)); } } private void writeToLogs(long endTime) { com.yahoo.jdisc.http.HttpRequest jdiscRequest = httpRequest.getJDiscRequest(); logTimes(startTime, getClientIP(jdiscRequest), renderStartTime, commitStartTime, endTime, jdiscRequest.getUri().toString(), extendedResponse.getParsedQuery(), extendedResponse.getTiming()); Optional jdiscRequestAccessLogEntry = AccessLoggingRequestHandler.getAccessLogEntry(jdiscRequest); if (jdiscRequestAccessLogEntry.isPresent()) { // This means we are running with Jetty, not Netty. // Actual logging will be done by the Jetty integration; here, we just need to populate. httpResponse.populateAccessLogEntry(jdiscRequestAccessLogEntry.get()); return; } // We are running without Jetty. No access logging will be done at container level, so we do it here. // TODO: Remove when netty support is removed. AccessLogEntry accessLogEntry = new AccessLogEntry(); populateAccessLogEntryNotCreatedByHttpServer( accessLogEntry, jdiscRequest, extendedResponse.getTiming(), httpRequest.getUri().toString(), commitStartTime, startTime, rendererWiring.written(), httpResponse.getStatus()); httpResponse.populateAccessLogEntry(accessLogEntry); accessLog.log(accessLogEntry); } } private void populateAccessLogEntryNotCreatedByHttpServer(AccessLogEntry logEntry, com.yahoo.jdisc.http.HttpRequest httpRequest, Timing timing, String fullRequest, long commitStartTime, long startTime, long written, int status) { try { InetSocketAddress remoteAddress = AccessLogUtil.getRemoteAddress(httpRequest); long evalStartTime = getEvalStart(timing, startTime); logEntry.setIpV4Address(remoteHostAddress(httpRequest)); logEntry.setTimeStamp(evalStartTime); logEntry.setDurationBetweenRequestResponse(commitStartTime - evalStartTime); logEntry.setReturnedContentSize(written); logEntry.setStatusCode(status); if (remoteAddress != null) { logEntry.setRemoteAddress(remoteAddress); logEntry.setRemotePort(remoteAddress.getPort()); } URI uri = AccessLogUtil.getUri(httpRequest); setDeprecatedUri(logEntry, uri); logEntry.setRawPath(uri.getRawPath()); logEntry.setRawQuery(uri.getRawQuery()); logEntry.setUserAgent(AccessLogUtil.getUserAgentHeader(httpRequest)); logEntry.setReferer(AccessLogUtil.getReferrerHeader(httpRequest)); logEntry.setHttpMethod(AccessLogUtil.getHttpMethod(httpRequest)); logEntry.setHttpVersion(AccessLogUtil.getHttpVersion(httpRequest)); } catch (Exception e) { log.log(LogLevel.WARNING, "Could not populate the access log [" + fullRequest + "]", e); } } @SuppressWarnings("deprecation") private static void setDeprecatedUri(AccessLogEntry logEntry, URI uri) { logEntry.setURI(uri); } }