From bd9d35c912d4c08c8e73b876348278fa968eceaa Mon Sep 17 00:00:00 2001 From: Bjørn Christian Seime Date: Mon, 11 Jan 2021 16:46:32 +0100 Subject: Revert "Revert "Merge container-accesslogging into jdisc_http_service"" --- .../com/yahoo/container/logging/AccessLog.java | 32 ++ .../yahoo/container/logging/AccessLogEntry.java | 522 +++++++++++++++++++++ .../yahoo/container/logging/AccessLogHandler.java | 48 ++ .../container/logging/AccessLogInterface.java | 9 + .../yahoo/container/logging/AccessLogSampler.java | 37 ++ .../logging/CircularArrayAccessLogKeeper.java | 48 ++ .../java/com/yahoo/container/logging/Coverage.java | 64 +++ .../com/yahoo/container/logging/HitCounts.java | 78 +++ .../com/yahoo/container/logging/JSONAccessLog.java | 36 ++ .../com/yahoo/container/logging/JSONFormatter.java | 221 +++++++++ .../yahoo/container/logging/LogFileHandler.java | 397 ++++++++++++++++ .../com/yahoo/container/logging/LogFormatter.java | 191 ++++++++ .../com/yahoo/container/logging/TraceRenderer.java | 185 ++++++++ .../yahoo/container/logging/VespaAccessLog.java | 111 +++++ .../com/yahoo/container/logging/package-info.java | 5 + 15 files changed, 1984 insertions(+) create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLog.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogEntry.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogHandler.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogInterface.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogSampler.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/CircularArrayAccessLogKeeper.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/Coverage.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/HitCounts.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFormatter.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/TraceRenderer.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/package-info.java (limited to 'jdisc_http_service/src/main/java/com') diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLog.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLog.java new file mode 100644 index 00000000000..5c1a549070c --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLog.java @@ -0,0 +1,32 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + + +import com.google.inject.Inject; +import com.yahoo.component.provider.ComponentRegistry; + +/** + * Logs to all the configured access logs. + * + * @author Tony Vaagenes + */ +public class AccessLog { + + private ComponentRegistry implementers; + + @Inject + public AccessLog(ComponentRegistry implementers) { + this.implementers = implementers; + } + + public static AccessLog voidAccessLog() { + return new AccessLog(new ComponentRegistry<>()); + } + + public void log(AccessLogEntry accessLogEntry) { + for (AccessLogInterface log: implementers.allComponents()) { + log.log(accessLogEntry); + } + } + +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogEntry.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogEntry.java new file mode 100644 index 00000000000..d8085cc808b --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogEntry.java @@ -0,0 +1,522 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +import com.yahoo.collections.ListMap; +import com.yahoo.yolean.trace.TraceNode; + +import javax.security.auth.x500.X500Principal; +import java.net.InetAddress; +import java.net.InetSocketAddress; +import java.security.Principal; +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; +import java.util.Map; +import java.util.Optional; +import java.util.Set; +import java.util.function.Function; + +import static java.util.stream.Collectors.toMap; + +/** + *

Information to be logged in the access log.

+ * + *

This class contains the union of all information that can be + * logged with all the supported access log formats.

+ * + *

The add methods can be called multiple times, + * but the parameters should be different for each + * invocation of the same method.

+ * + * This class is thread-safe. + * + * @author Tony Vaagenes + * @author bakksjo + * @author bjorncs + */ +public class AccessLogEntry { + + // Sadly, there's no way to do compile-time validation of these field references. + private static final String[] FIELDS_EXCLUDED_FROM_TOSTRING = new String[] { + "monitor" + }; + + private final Object monitor = new Object(); + + private String ipV4AddressInDotDecimalNotation; + private long timeStampMillis; + private long durationBetweenRequestResponseMillis; + private long numBytesReturned; + + private String remoteAddress; + private int remotePort; + private String peerAddress; + private int peerPort; + + private String profile; + private String errorMessage; + private String fileName; + private String userAgent; + private String referer; + private String user; + private HitCounts hitCounts; + private String httpMethod; + private String httpVersion; + private String hostString; + private int statusCode; + private String scheme; + private int localPort; + private Principal principal; + private X500Principal sslPrincipal; + private String rawPath; + private String rawQuery; + private TraceNode traceNode; + + private ListMap keyValues=null; + + public void setProfile( String profile ) { + synchronized (monitor) { + requireNull(this.profile); + this.profile = profile; + } + } + + public String getProfile() { + synchronized (monitor) { + return profile; + } + } + + public void setErrorMessage(String errorMessage) { + synchronized (monitor) { + requireNull(this.errorMessage); + this.errorMessage = errorMessage; + } + } + + public String getErrorMessage() { + synchronized (monitor) { + return errorMessage; + } + } + + public void setFileName(String fileName) { + synchronized (monitor) { + requireNull(this.fileName); + this.fileName = fileName; + } + } + + public String getFileName() { + synchronized (monitor) { + return fileName; + } + } + + public void setUserAgent(String userAgent) { + synchronized (monitor) { + requireNull(this.userAgent); + this.userAgent = userAgent; + } + } + + public String getUserAgent() { + synchronized (monitor) { + return userAgent; + } + } + + public void setReferer(String referer) { + synchronized (monitor) { + requireNull(this.referer); + this.referer = referer; + } + } + + public String getReferer() { + synchronized (monitor) { + return referer; + } + } + + public void setUser(final String user) { + synchronized (monitor) { + requireNull(this.user); + this.user = user; + } + } + + public String getUser() { + synchronized (monitor) { + return user; + } + } + + public void setHitCounts(final HitCounts hitCounts) { + synchronized (monitor) { + requireNull(this.hitCounts); + this.hitCounts = hitCounts; + } + } + + public HitCounts getHitCounts() { + synchronized (monitor) { + return hitCounts; + } + } + + public void addKeyValue(String key,String value) { + synchronized (monitor) { + if (keyValues == null) { + keyValues = new ListMap<>(); + } + keyValues.put(key,value); + } + } + + public Map> getKeyValues() { + synchronized (monitor) { + if (keyValues == null) { + return null; + } + + final Map> newMapWithImmutableValues = mapValues( + keyValues.entrySet(), + valueList -> Collections.unmodifiableList(new ArrayList<>(valueList))); + return Collections.unmodifiableMap(newMapWithImmutableValues); + } + } + + private static Map mapValues( + final Set> entrySet, + final Function valueConverter) { + return entrySet.stream() + .collect(toMap( + entry -> entry.getKey(), + entry -> valueConverter.apply(entry.getValue()))); + } + + public enum HttpMethod { + GET, POST; + } + + public void setHttpMethod(HttpMethod method) { + setHttpMethod(method.toString()); + } + + public void setHttpMethod(String method) { + synchronized (monitor) { + requireNull(this.httpMethod); + this.httpMethod = method; + } + } + + public String getHttpMethod() { + synchronized (monitor) { + return httpMethod; + } + } + + public void setHttpVersion(final String httpVersion) { + synchronized (monitor) { + requireNull(this.httpVersion); + this.httpVersion = httpVersion; + } + } + + public String getHttpVersion() { + synchronized (monitor) { + return httpVersion; + } + } + + public void setHostString(String hostString) { + synchronized (monitor) { + requireNull(this.hostString); + this.hostString = hostString; + } + } + + public String getHostString() { + synchronized (monitor) { + return hostString; + } + } + + public void setIpV4Address(String ipV4AddressInDotDecimalNotation) { + synchronized (monitor) { + requireNull(this.ipV4AddressInDotDecimalNotation); + this.ipV4AddressInDotDecimalNotation = ipV4AddressInDotDecimalNotation; + } + } + + public String getIpV4Address() { + synchronized (monitor) { + return ipV4AddressInDotDecimalNotation; + } + } + + public void setTimeStamp(long numMillisSince1Jan1970AtMidnightUTC) { + synchronized (monitor) { + requireZero(this.timeStampMillis); + timeStampMillis = numMillisSince1Jan1970AtMidnightUTC; + } + } + + public long getTimeStampMillis() { + synchronized (monitor) { + return timeStampMillis; + } + } + + public void setDurationBetweenRequestResponse(long timeInMillis) { + synchronized (monitor) { + requireZero(this.durationBetweenRequestResponseMillis); + durationBetweenRequestResponseMillis = timeInMillis; + } + } + + public long getDurationBetweenRequestResponseMillis() { + synchronized (monitor) { + return durationBetweenRequestResponseMillis; + } + } + + public void setReturnedContentSize(int byteCount) { + setReturnedContentSize((long) byteCount); + } + + public void setReturnedContentSize(long byteCount) { + synchronized (monitor) { + requireZero(this.numBytesReturned); + numBytesReturned = byteCount; + } + } + + public long getReturnedContentSize() { + synchronized (monitor) { + return numBytesReturned; + } + } + + public void setRemoteAddress(String remoteAddress) { + synchronized (monitor) { + requireNull(this.remoteAddress); + this.remoteAddress = remoteAddress; + } + } + + public void setRemoteAddress(final InetSocketAddress remoteAddress) { + setRemoteAddress(getIpAddressAsString(remoteAddress)); + } + + private static String getIpAddressAsString(final InetSocketAddress remoteAddress) { + final InetAddress inetAddress = remoteAddress.getAddress(); + if (inetAddress == null) { + return null; + } + return inetAddress.getHostAddress(); + } + + public String getRemoteAddress() { + synchronized (monitor) { + return remoteAddress; + } + } + + public void setRemotePort(int remotePort) { + synchronized (monitor) { + requireZero(this.remotePort); + this.remotePort = remotePort; + } + } + + public int getRemotePort() { + synchronized (monitor) { + return remotePort; + } + } + + public void setPeerAddress(final String peerAddress) { + synchronized (monitor) { + requireNull(this.peerAddress); + this.peerAddress = peerAddress; + } + } + + public void setPeerPort(int peerPort) { + synchronized (monitor) { + requireZero(this.peerPort); + this.peerPort = peerPort; + } + } + + public int getPeerPort() { + synchronized (monitor) { + return peerPort; + } + } + + public String getPeerAddress() { + synchronized (monitor) { + return peerAddress; + } + } + + public void setStatusCode(int statusCode) { + synchronized (monitor) { + requireZero(this.statusCode); + this.statusCode = statusCode; + } + } + + public int getStatusCode() { + synchronized (monitor) { + return statusCode; + } + } + + public String getScheme() { + synchronized (monitor) { + return scheme; + } + } + + public void setScheme(String scheme) { + synchronized (monitor) { + requireNull(this.scheme); + this.scheme = scheme; + } + } + + public int getLocalPort() { + synchronized (monitor) { + return localPort; + } + } + + public void setLocalPort(int localPort) { + synchronized (monitor) { + requireZero(this.localPort); + this.localPort = localPort; + } + } + + public Principal getUserPrincipal() { + synchronized (monitor) { + return principal; + } + } + + public void setUserPrincipal(Principal principal) { + synchronized (monitor) { + requireNull(this.principal); + this.principal = principal; + } + } + + public Principal getSslPrincipal() { + synchronized (monitor) { + return sslPrincipal; + } + } + + public void setSslPrincipal(X500Principal sslPrincipal) { + synchronized (monitor) { + requireNull(this.sslPrincipal); + this.sslPrincipal = sslPrincipal; + } + } + + public void setRawPath(String rawPath) { + synchronized (monitor) { + requireNull(this.rawPath); + this.rawPath = rawPath; + } + } + + public String getRawPath() { + synchronized (monitor) { + return rawPath; + } + } + + public void setRawQuery(String rawQuery) { + synchronized (monitor) { + requireNull(this.rawQuery); + this.rawQuery = rawQuery; + } + } + + public Optional getRawQuery() { + synchronized (monitor) { + return Optional.ofNullable(rawQuery); + } + } + + public void setTrace(TraceNode traceNode) { + synchronized (monitor) { + requireNull(this.traceNode); + this.traceNode = traceNode; + } + } + public TraceNode getTrace() { + synchronized (monitor) { + return traceNode; + } + } + + @Override + public String toString() { + synchronized (monitor) { + return "AccessLogEntry{" + + "ipV4AddressInDotDecimalNotation='" + ipV4AddressInDotDecimalNotation + '\'' + + ", timeStampMillis=" + timeStampMillis + + ", durationBetweenRequestResponseMillis=" + durationBetweenRequestResponseMillis + + ", numBytesReturned=" + numBytesReturned + + ", remoteAddress='" + remoteAddress + '\'' + + ", remotePort=" + remotePort + + ", peerAddress='" + peerAddress + '\'' + + ", peerPort=" + peerPort + + ", profile='" + profile + '\'' + + ", errorMessage='" + errorMessage + '\'' + + ", fileName='" + fileName + '\'' + + ", userAgent='" + userAgent + '\'' + + ", referer='" + referer + '\'' + + ", user='" + user + '\'' + + ", hitCounts=" + hitCounts + + ", httpMethod='" + httpMethod + '\'' + + ", httpVersion='" + httpVersion + '\'' + + ", hostString='" + hostString + '\'' + + ", statusCode=" + statusCode + + ", scheme='" + scheme + '\'' + + ", localPort=" + localPort + + ", principal=" + principal + + ", sslPrincipal=" + sslPrincipal + + ", rawPath='" + rawPath + '\'' + + ", rawQuery='" + rawQuery + '\'' + + ", trace='" + traceNode + '\'' + + ", keyValues=" + keyValues + + '}'; + } + } + + private static void requireNull(final Object value) { + if (value != null) { + throw new IllegalStateException("Attempt to overwrite field that has been assigned. Value: " + value); + } + } + + private static void requireZero(final long value) { + if (value != 0) { + throw new IllegalStateException("Attempt to overwrite field that has been assigned. Value: " + value); + } + } + + private static void requireZero(final int value) { + if (value != 0) { + throw new IllegalStateException("Attempt to overwrite field that has been assigned. Value: " + value); + } + } + +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogHandler.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogHandler.java new file mode 100644 index 00000000000..488a6137cc2 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogHandler.java @@ -0,0 +1,48 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +import com.yahoo.container.core.AccessLogConfig; + +import java.util.logging.Logger; + +/** + * @author Bjorn Borud + */ +class AccessLogHandler { + + public Logger access = Logger.getAnonymousLogger(); + private LogFileHandler logFileHandler; + + public AccessLogHandler(AccessLogConfig.FileHandler config) { + access.setUseParentHandlers(false); + + logFileHandler = new LogFileHandler(config.compressOnRotation()); + + logFileHandler.setFilePattern(config.pattern()); + logFileHandler.setRotationTimes(config.rotation()); + + createSymlink(config, logFileHandler); + + LogFormatter lf = new LogFormatter(); + lf.messageOnly(true); + this.logFileHandler.setFormatter(lf); + access.addHandler(this.logFileHandler); + } + + private void createSymlink(AccessLogConfig.FileHandler config, LogFileHandler handler) { + if (!config.symlink().isEmpty()) + handler.setSymlinkName(config.symlink()); + } + + public void shutdown() { + logFileHandler.close(); + access.removeHandler(logFileHandler); + + if (logFileHandler!=null) + logFileHandler.shutdown(); + } + + void rotateNow() { + logFileHandler.rotateNow(); + } +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogInterface.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogInterface.java new file mode 100644 index 00000000000..2523174abef --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogInterface.java @@ -0,0 +1,9 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +/** + * @author Tony Vaagenes + */ +public interface AccessLogInterface { + void log(AccessLogEntry accessLogEntry); +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogSampler.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogSampler.java new file mode 100644 index 00000000000..12d29c2f333 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogSampler.java @@ -0,0 +1,37 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +import java.util.concurrent.atomic.AtomicLong; + +/** + * Samples entries from access log. It first samples every query until it have some data, and then sub-samples + * much less frequently to reduce CPU usage and latency impact. It only samples successful requests and requests + * that starts with /search. + * + * @author dybis + */ +public class AccessLogSampler implements AccessLogInterface { + + private final AtomicLong accessLineCounter = new AtomicLong(0); + private final CircularArrayAccessLogKeeper circularArrayAccessLogKeeper; + + public AccessLogSampler(CircularArrayAccessLogKeeper circularArrayAccessLogKeeper) { + this.circularArrayAccessLogKeeper = circularArrayAccessLogKeeper; + } + + @Override + public void log(AccessLogEntry accessLogEntry) { + if (accessLogEntry.getStatusCode() != 200) { + return; + } + String uriString = accessLogEntry.getRawPath(); + if (! uriString.startsWith("/search")) { + return; + } + final long count = accessLineCounter.incrementAndGet(); + if (count >= CircularArrayAccessLogKeeper.SIZE && count % CircularArrayAccessLogKeeper.SIZE != 0) { + return; + } + circularArrayAccessLogKeeper.addUri(uriString); + } +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/CircularArrayAccessLogKeeper.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/CircularArrayAccessLogKeeper.java new file mode 100644 index 00000000000..dc749c71613 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/CircularArrayAccessLogKeeper.java @@ -0,0 +1,48 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +import java.util.ArrayDeque; +import java.util.ArrayList; +import java.util.Deque; +import java.util.List; + +/** + * This class keeps some information from the access log from the requests in memory. It is thread-safe. + * + * @author dybis + */ +public class CircularArrayAccessLogKeeper { + public static final int SIZE = 1000; + private final Deque uris = new ArrayDeque<>(SIZE); + private final Object monitor = new Object(); + + /** + * This class is intended to be used with injection so it can be shared between other classes. + */ + public CircularArrayAccessLogKeeper() {} + + /** + * Creates a list of Uris. + * @return URIs as string + */ + public List getUris() { + final List uriList = new ArrayList<>(); + synchronized (monitor) { + uris.iterator().forEachRemaining(uri -> uriList.add(uri)); + } + return uriList; + } + + /** + * Add a new URI. It might remove an old entry to make space for new entry. + * @param uri uri as string + */ + public void addUri(String uri) { + synchronized (monitor) { + if (uris.size() == SIZE) { + uris.pop(); + } + uris.add(uri); + } + } +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/Coverage.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/Coverage.java new file mode 100644 index 00000000000..9d122b90641 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/Coverage.java @@ -0,0 +1,64 @@ +// Copyright 2020 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +/** + * Carry information about how the query covered the document corpus. + */ +public class Coverage { + private final long docs; + private final long active; + private final long soonActive; + private final int degradedReason; + private final static int DEGRADED_BY_MATCH_PHASE = 1; + private final static int DEGRADED_BY_TIMEOUT = 2; + private final static int DEGRADED_BY_ADAPTIVE_TIMEOUT = 4; + public Coverage(long docs, long active, long soonActive, int degradedReason) { + this.docs = docs; + this.active = active; + this.soonActive = soonActive; + this.degradedReason = degradedReason; + } + + public long getDocs() { + return docs; + } + + public long getActive() { + return active; + } + + public static int toDegradation(boolean degradeByMatchPhase, boolean degradedByTimeout, boolean degradedByAdaptiveTimeout) { + int v = 0; + if (degradeByMatchPhase) { + v |= DEGRADED_BY_MATCH_PHASE; + } + if (degradedByTimeout) { + v |= DEGRADED_BY_TIMEOUT; + } + if (degradedByAdaptiveTimeout) { + v |= DEGRADED_BY_ADAPTIVE_TIMEOUT; + } + return v; + } + + public long getSoonActive() { return soonActive; } + + public boolean isDegraded() { return (degradedReason != 0) || isDegradedByNonIdealState(); } + public boolean isDegradedByMatchPhase() { return (degradedReason & DEGRADED_BY_MATCH_PHASE) != 0; } + public boolean isDegradedByTimeout() { return (degradedReason & DEGRADED_BY_TIMEOUT) != 0; } + public boolean isDegradedByAdapativeTimeout() { return (degradedReason & DEGRADED_BY_ADAPTIVE_TIMEOUT) != 0; } + public boolean isDegradedByNonIdealState() { return (degradedReason == 0) && (getResultPercentage() != 100);} + + /** + * An int between 0 (inclusive) and 100 (inclusive) representing how many + * percent coverage the result sets this Coverage instance contains information + * about had. + */ + public int getResultPercentage() { + if (docs < active) { + return (int) Math.round(docs * 100.0d / active); + } + return 100; + } + +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/HitCounts.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/HitCounts.java new file mode 100644 index 00000000000..fed12281962 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/HitCounts.java @@ -0,0 +1,78 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +/** + * A wrapper for hit counts, modelled after a search system. + * Advanced database searches and similar could use these + * structures as well. + * + * @author Steinar Knutsen + */ +public class HitCounts { + + // see the javadoc for the accessors for short comments on each field + private final int retrievedHits; + private final int summaryCount; + private final long totalHitCount; + private final int requestedHits; + private final int requestedOffset; + private final Coverage coverage; + + HitCounts(int retrievedHits, int summaryCount, long totalHitCount, int requestedHits, int requestedOffset) { + this(retrievedHits, summaryCount, totalHitCount, requestedHits, requestedOffset, + new Coverage(1,1,1,0)); + } + + public HitCounts(int retrievedHits, int summaryCount, long totalHitCount, + int requestedHits, int requestedOffset, Coverage coverage) + { + + this.retrievedHits = retrievedHits; + this.summaryCount = summaryCount; + this.totalHitCount = totalHitCount; + this.requestedHits = requestedHits; + this.requestedOffset = requestedOffset; + this.coverage = coverage; + } + + /** + * The number of hits returned by the server. + * Compare to getRequestedHits(). + */ + public int getRetrievedHitCount() { + return retrievedHits; + } + + /** + * The number of hit summaries ("document contents") fetched. + */ + public int getSummaryCount() { + return summaryCount; + } + + /** + * The total number of matching hits + * for the request. + */ + public long getTotalHitCount() { + return totalHitCount; + } + + /** + * The number of hits requested by the user. + * Compare to getRetrievedHitCount(). + */ + public int getRequestedHits() { + return requestedHits; + } + + /** + * The user requested offset into the linear mapping of the result space. + */ + public int getRequestedOffset() { + return requestedOffset; + } + + public Coverage getCoverage() { return coverage; } + +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java new file mode 100644 index 00000000000..a84903467b6 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java @@ -0,0 +1,36 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +import com.yahoo.container.core.AccessLogConfig; + +import java.util.logging.Level; + +/** + * Log a message in Vespa JSON access log format. + * + * @author frodelu + * @author Tony Vaagenes + */ +public final class JSONAccessLog implements AccessLogInterface { + + private final AccessLogHandler logHandler; + + public JSONAccessLog(AccessLogConfig config) { + logHandler = new AccessLogHandler(config.fileHandler()); + } + + @Override + public void log(AccessLogEntry logEntry) { + logHandler.access.log(Level.INFO, new JSONFormatter(logEntry).format() + '\n'); + } + + // TODO: This is never called. We should have a DI provider and call this method from its deconstruct. + public void shutdown() { + logHandler.shutdown(); + } + + void rotateNow() { + logHandler.rotateNow(); + } + +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java new file mode 100644 index 00000000000..ae794e5b60a --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java @@ -0,0 +1,221 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +import com.fasterxml.jackson.core.JsonEncoding; +import com.fasterxml.jackson.core.JsonFactory; +import com.fasterxml.jackson.core.JsonGenerator; +import com.fasterxml.jackson.databind.ObjectMapper; +import com.yahoo.yolean.trace.TraceNode; + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.math.BigDecimal; +import java.math.RoundingMode; +import java.security.Principal; +import java.util.List; +import java.util.Map; +import java.util.Objects; +import java.util.logging.Level; +import java.util.logging.Logger; + +/** + * Formatting of an {@link AccessLogEntry} in the Vespa JSON access log format. + * + * @author frodelu + */ +public class JSONFormatter { + private static final String COVERAGE = "coverage"; + private static final String COVERAGE_COVERAGE = "coverage"; + private static final String COVERAGE_DOCUMENTS = "documents"; + private static final String COVERAGE_DEGRADE = "degraded"; + private static final String COVERAGE_DEGRADE_MATCHPHASE = "match-phase"; + private static final String COVERAGE_DEGRADE_TIMEOUT = "timeout"; + private static final String COVERAGE_DEGRADE_ADAPTIVE_TIMEOUT = "adaptive-timeout"; + private static final String COVERAGE_DEGRADED_NON_IDEAL_STATE = "non-ideal-state"; + + private AccessLogEntry accessLogEntry; + private final JsonFactory generatorFactory; + + private static Logger logger = Logger.getLogger(JSONFormatter.class.getName()); + + public JSONFormatter(final AccessLogEntry entry) { + accessLogEntry = entry; + generatorFactory = new JsonFactory(); + generatorFactory.setCodec(new ObjectMapper()); + } + + /** + * The main method for formatting the associated {@link AccessLogEntry} as a Vespa JSON access log string + * + * @return The Vespa JSON access log string without trailing newline + */ + public String format() { + ByteArrayOutputStream logLine = new ByteArrayOutputStream(); + try { + JsonGenerator generator = generatorFactory.createGenerator(logLine, JsonEncoding.UTF8); + generator.writeStartObject(); + generator.writeStringField("ip", accessLogEntry.getIpV4Address()); + generator.writeNumberField("time", toTimestampInSeconds(accessLogEntry.getTimeStampMillis())); + generator.writeNumberField("duration", durationAsSeconds(accessLogEntry.getDurationBetweenRequestResponseMillis())); + generator.writeNumberField("responsesize", accessLogEntry.getReturnedContentSize()); + generator.writeNumberField("code", accessLogEntry.getStatusCode()); + generator.writeStringField("method", accessLogEntry.getHttpMethod()); + generator.writeStringField("uri", getNormalizedURI(accessLogEntry.getRawPath(), accessLogEntry.getRawQuery().orElse(null))); + generator.writeStringField("version", accessLogEntry.getHttpVersion()); + generator.writeStringField("agent", accessLogEntry.getUserAgent()); + generator.writeStringField("host", accessLogEntry.getHostString()); + generator.writeStringField("scheme", accessLogEntry.getScheme()); + generator.writeNumberField("localport", accessLogEntry.getLocalPort()); + + Principal principal = accessLogEntry.getUserPrincipal(); + if (principal != null) { + generator.writeStringField("user-principal", principal.getName()); + } + + Principal sslPrincipal = accessLogEntry.getSslPrincipal(); + if (sslPrincipal != null) { + generator.writeStringField("ssl-principal", sslPrincipal.getName()); + } + + // Only add remote address/port fields if relevant + if (remoteAddressDiffers(accessLogEntry.getIpV4Address(), accessLogEntry.getRemoteAddress())) { + generator.writeStringField("remoteaddr", accessLogEntry.getRemoteAddress()); + if (accessLogEntry.getRemotePort() > 0) { + generator.writeNumberField("remoteport", accessLogEntry.getRemotePort()); + } + } + + // Only add peer address/port fields if relevant + if (accessLogEntry.getPeerAddress() != null) { + generator.writeStringField("peeraddr", accessLogEntry.getPeerAddress()); + + int peerPort = accessLogEntry.getPeerPort(); + if (peerPort > 0 && peerPort != accessLogEntry.getRemotePort()) { + generator.writeNumberField("peerport", peerPort); + } + } + + TraceNode trace = accessLogEntry.getTrace(); + if (trace != null) { + long timestamp = trace.timestamp(); + if (timestamp == 0L) { + timestamp = accessLogEntry.getTimeStampMillis(); + } + trace.accept(new TraceRenderer(generator, timestamp)); + } + + // Only add search sub block of this is a search request + if (isSearchRequest(accessLogEntry)) { + generator.writeObjectFieldStart("search"); + generator.writeNumberField("totalhits", getTotalHitCount(accessLogEntry.getHitCounts())); + generator.writeNumberField("hits", getRetrievedHitCount(accessLogEntry.getHitCounts())); + Coverage c = accessLogEntry.getHitCounts().getCoverage(); + if (c != null) { + generator.writeObjectFieldStart(COVERAGE); + generator.writeNumberField(COVERAGE_COVERAGE, c.getResultPercentage()); + generator.writeNumberField(COVERAGE_DOCUMENTS, c.getDocs()); + if (c.isDegraded()) { + generator.writeObjectFieldStart(COVERAGE_DEGRADE); + if (c.isDegradedByMatchPhase()) + generator.writeBooleanField(COVERAGE_DEGRADE_MATCHPHASE, c.isDegradedByMatchPhase()); + if (c.isDegradedByTimeout()) + generator.writeBooleanField(COVERAGE_DEGRADE_TIMEOUT, c.isDegradedByTimeout()); + if (c.isDegradedByAdapativeTimeout()) + generator.writeBooleanField(COVERAGE_DEGRADE_ADAPTIVE_TIMEOUT, c.isDegradedByAdapativeTimeout()); + if (c.isDegradedByNonIdealState()) + generator.writeBooleanField(COVERAGE_DEGRADED_NON_IDEAL_STATE, c.isDegradedByNonIdealState()); + generator.writeEndObject(); + } + generator.writeEndObject(); + } + generator.writeEndObject(); + } + + // Add key/value access log entries. Keys with single values are written as single + // string value fields while keys with multiple values are written as string arrays + Map> keyValues = accessLogEntry.getKeyValues(); + if (keyValues != null && !keyValues.isEmpty()) { + generator.writeObjectFieldStart("attributes"); + for (Map.Entry> entry : keyValues.entrySet()) { + if (entry.getValue().size() == 1) { + generator.writeStringField(entry.getKey(), entry.getValue().get(0)); + } else { + generator.writeFieldName(entry.getKey()); + generator.writeStartArray(); + for (String s : entry.getValue()) { + generator.writeString(s); + } + generator.writeEndArray(); + } + } + generator.writeEndObject(); + } + + generator.writeEndObject(); + generator.close(); + + } catch (IOException e) { + logger.log(Level.WARNING, "Unable to generate JSON access log entry: " + e.getMessage()); + } + + return logLine.toString(); + } + + + private boolean remoteAddressDiffers(String ipV4Address, String remoteAddress) { + return remoteAddress != null && !Objects.equals(ipV4Address, remoteAddress); + } + + private boolean isSearchRequest(AccessLogEntry logEntry) { + return logEntry != null && (logEntry.getHitCounts() != null); + } + + private long getTotalHitCount(HitCounts counts) { + if (counts == null) { + return 0; + } + + return counts.getTotalHitCount(); + } + + private int getRetrievedHitCount(HitCounts counts) { + if (counts == null) { + return 0; + } + + return counts.getRetrievedHitCount(); + } + + private BigDecimal toTimestampInSeconds(long numMillisSince1Jan1970AtMidnightUTC) { + BigDecimal timestampInSeconds = + new BigDecimal(numMillisSince1Jan1970AtMidnightUTC).divide(BigDecimal.valueOf(1000)); + + if (numMillisSince1Jan1970AtMidnightUTC/1000 > 0x7fffffff) { + logger.log(Level.WARNING, "A year 2038 problem occurred."); + logger.log(Level.INFO, "numMillisSince1Jan1970AtMidnightUTC: " + + numMillisSince1Jan1970AtMidnightUTC); + timestampInSeconds = + new BigDecimal(numMillisSince1Jan1970AtMidnightUTC) + .divide(BigDecimal.valueOf(1000)) + .remainder(BigDecimal.valueOf(0x7fffffff)); + } + return timestampInSeconds.setScale(3, RoundingMode.HALF_UP); + } + + private BigDecimal durationAsSeconds(long timeInMillis) { + BigDecimal duration = + new BigDecimal(timeInMillis).divide(BigDecimal.valueOf(1000)); + + if (timeInMillis > 0xffffffffL) { + logger.log(Level.WARNING, "Duration too long: " + timeInMillis); + duration = new BigDecimal(0xffffffff); + } + + return duration.setScale(3, RoundingMode.HALF_UP); + } + + private static String getNormalizedURI(String rawPath, String rawQuery) { + return rawQuery != null ? rawPath + "?" + rawQuery : rawPath; + } + +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java new file mode 100644 index 00000000000..75e9febc192 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java @@ -0,0 +1,397 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +import com.yahoo.concurrent.ThreadFactoryFactory; +import com.yahoo.io.NativeIO; +import com.yahoo.log.LogFileDb; +import com.yahoo.system.ProcessExecuter; +import com.yahoo.yolean.Exceptions; + +import java.io.File; +import java.io.FileInputStream; +import java.io.FileOutputStream; +import java.io.IOException; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.concurrent.ArrayBlockingQueue; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; +import java.util.logging.StreamHandler; +import java.util.zip.GZIPOutputStream; + +/** + *

Implements log file naming/rotating logic for container logs.

+ * + *

Overridden methods: publish

+ * + *

Added methods: setFilePattern, setRotationTimes, rotateNow (+ few others)

+ * + * @author Bob Travis + */ +public class LogFileHandler extends StreamHandler { + + private final static Logger logger = Logger.getLogger(LogFileHandler.class.getName()); + private final boolean compressOnRotation; + private long[] rotationTimes = {0}; //default to one log per day, at midnight + private String filePattern = "./log.%T"; // default to current directory, ms time stamp + private long nextRotationTime = 0; + private FileOutputStream currentOutputStream = null; + private volatile String fileName; + private String symlinkName = null; + private ArrayBlockingQueue logQueue = new ArrayBlockingQueue<>(100000); + private LogRecord rotateCmd = new LogRecord(Level.SEVERE, "rotateNow"); + private ExecutorService executor = Executors.newCachedThreadPool(ThreadFactoryFactory.getDaemonThreadFactory("logfilehandler.compression")); + private final NativeIO nativeIO = new NativeIO(); + private long lastDropPosition = 0; + + static private class LogThread extends Thread { + LogFileHandler logFileHandler; + long lastFlush = 0; + LogThread(LogFileHandler logFile) { + super("Logger"); + setDaemon(true); + logFileHandler = logFile; + } + @Override + public void run() { + try { + storeLogRecords(); + } catch (InterruptedException e) { + } catch (Exception e) { + com.yahoo.protect.Process.logAndDie("Failed storing log records", e); + } + + logFileHandler.flush(); + } + + private void storeLogRecords() throws InterruptedException { + while (!isInterrupted()) { + LogRecord r = logFileHandler.logQueue.poll(100, TimeUnit.MILLISECONDS); + if (r != null) { + if (r == logFileHandler.rotateCmd) { + logFileHandler.internalRotateNow(); + lastFlush = System.nanoTime(); + } else { + logFileHandler.internalPublish(r); + } + flushIfOld(3, TimeUnit.SECONDS); + } else { + flushIfOld(100, TimeUnit.MILLISECONDS); + } + } + } + + private void flushIfOld(long age, TimeUnit unit) { + long now = System.nanoTime(); + if (TimeUnit.NANOSECONDS.toMillis(now - lastFlush) > unit.toMillis(age)) { + logFileHandler.flush(); + lastFlush = now; + } + } + } + private final LogThread logThread; + + LogFileHandler() { + this(false); + } + + LogFileHandler(boolean compressOnRotation) + { + super(); + this.compressOnRotation = compressOnRotation; + logThread = new LogThread(this); + logThread.start(); + } + + /** + * Sends logrecord to file, first rotating file if needed. + * + * @param r logrecord to publish + */ + public void publish(LogRecord r) { + try { + logQueue.put(r); + } catch (InterruptedException e) { + } + } + + @Override + public synchronized void flush() { + super.flush(); + try { + if (currentOutputStream != null) { + long newPos = currentOutputStream.getChannel().position(); + if (newPos > lastDropPosition + 102400) { + nativeIO.dropPartialFileFromCache(currentOutputStream.getFD(), lastDropPosition, newPos, true); + lastDropPosition = newPos; + } + } + } catch (IOException e) { + logger.warning("Failed dropping from cache : " + Exceptions.toMessageString(e)); + } + } + + private void internalPublish(LogRecord r) { + // first check to see if new file needed. + // if so, use this.internalRotateNow() to do it + + long now = System.currentTimeMillis(); + if (nextRotationTime <= 0) { + nextRotationTime = getNextRotationTime(now); // lazy initialization + } + if (now > nextRotationTime || currentOutputStream == null) { + internalRotateNow(); + } + super.publish(r); + } + + /** + * Assign pattern for generating (rotating) file names. + * + * @param pattern See LogFormatter for definition + */ + void setFilePattern ( String pattern ) { + filePattern = pattern; + } + + /** + * Assign times for rotating output files. + * + * @param timesOfDay in millis, from midnight + * + */ + void setRotationTimes ( long[] timesOfDay ) { + rotationTimes = timesOfDay; + } + + /** Assign time for rotating output files + * + * @param prescription string form of times, in minutes + */ + void setRotationTimes ( String prescription ) { + setRotationTimes(calcTimesMinutes(prescription)); + } + + /** + * Find next rotation after specified time. + * + * @param now the specified time; if zero, current time is used. + * @return the next rotation time + */ + long getNextRotationTime (long now) { + if (now <= 0) { + now = System.currentTimeMillis(); + } + long nowTod = timeOfDayMillis(now); + long next = 0; + for (long rotationTime : rotationTimes) { + if (nowTod < rotationTime) { + next = rotationTime-nowTod + now; + break; + } + } + if (next == 0) { // didn't find one -- use 1st time 'tomorrow' + next = rotationTimes[0]+lengthOfDayMillis-nowTod + now; + } + + return next; + } + + void waitDrained() { + while(! logQueue.isEmpty()) { + try { + Thread.sleep(1); + } catch (InterruptedException e) { + } + } + flush(); + } + + private void checkAndCreateDir(String pathname) { + int lastSlash = pathname.lastIndexOf("/"); + if (lastSlash > -1) { + String pathExcludingFilename = pathname.substring(0, lastSlash); + File filepath = new File(pathExcludingFilename); + if (!filepath.exists()) { + filepath.mkdirs(); + } + } + } + + /** + * Force file rotation now, independent of schedule. + */ + void rotateNow () { + publish(rotateCmd); + } + + // Throw InterruptedException upwards rather than relying on isInterrupted to stop the thread as + // isInterrupted() returns false after interruption in p.waitFor + private void internalRotateNow() { + // figure out new file name, then + // use super.setOutputStream to switch to a new file + + String oldFileName = fileName; + long now = System.currentTimeMillis(); + fileName = LogFormatter.insertDate(filePattern, now); + flush(); + super.close(); + + try { + checkAndCreateDir(fileName); + FileOutputStream os = new FileOutputStream(fileName, true); // append mode, for safety + super.setOutputStream(os); + currentOutputStream = os; + lastDropPosition = 0; + LogFileDb.nowLoggingTo(fileName); + } + catch (IOException e) { + throw new RuntimeException("Couldn't open log file '" + fileName + "'", e); + } + + createSymlinkToCurrentFile(); + + nextRotationTime = 0; //figure it out later (lazy evaluation) + if ((oldFileName != null)) { + File oldFile = new File(oldFileName); + if (oldFile.exists()) { + if (compressOnRotation) { + executor.execute(() -> runCompression(oldFile)); + } else { + nativeIO.dropFileFromCache(oldFile); + } + } + } + } + + + static void runCompression(File oldFile) { + File gzippedFile = new File(oldFile.getPath() + ".gz"); + try (GZIPOutputStream compressor = new GZIPOutputStream(new FileOutputStream(gzippedFile), 0x100000); + FileInputStream inputStream = new FileInputStream(oldFile)) + { + byte [] buffer = new byte[0x400000]; // 4M buffer + + long totalBytesRead = 0; + NativeIO nativeIO = new NativeIO(); + for (int read = inputStream.read(buffer); read > 0; read = inputStream.read(buffer)) { + compressor.write(buffer, 0, read); + nativeIO.dropPartialFileFromCache(inputStream.getFD(), totalBytesRead, read, false); + totalBytesRead += read; + } + compressor.finish(); + compressor.flush(); + + oldFile.delete(); + nativeIO.dropFileFromCache(gzippedFile); + } catch (IOException e) { + logger.warning("Got '" + e + "' while compressing '" + oldFile.getPath() + "'."); + } + } + + /** Name files by date - create a symlink with a constant name to the newest file */ + private void createSymlinkToCurrentFile() { + if (symlinkName == null) return; + File f = new File(fileName); + File f2 = new File(f.getParent(), symlinkName); + String [] cmd = new String[]{"/bin/ln", "-sf", f.getName(), f2.getPath()}; + try { + int retval = new ProcessExecuter().exec(cmd).getFirst(); + // Detonator pattern: Think of all the fun we can have if ln isn't what we + // think it is, if it doesn't return, etc, etc + if (retval != 0) { + logger.warning("Command '" + Arrays.toString(cmd) + "' + failed with exitcode=" + retval); + } + } catch (IOException e) { + logger.warning("Got '" + e + "' while doing'" + Arrays.toString(cmd) + "'."); + } + } + + /** + * Calculate rotation times array, given times in minutes, as "0 60 ..." + * + */ + private static long[] calcTimesMinutes(String times) { + ArrayList list = new ArrayList<>(50); + int i = 0; + boolean etc = false; + + while (i < times.length()) { + if (times.charAt(i) == ' ') { i++; continue; } // skip spaces + int j = i; // start of string + i = times.indexOf(' ', i); + if (i == -1) i = times.length(); + if (times.charAt(j) == '.' && times.substring(j,i).equals("...")) { // ... + etc = true; + break; + } + list.add(Long.valueOf(times.substring(j,i))); + } + + int size = list.size(); + long[] longtimes = new long[size]; + for (i = 0; i 0) { + int newsize = size + (int)moreneeded; + long[] temp = new long[newsize]; + for (i=0; i + *
  • %Y YYYY 2003 + *
  • %m MM 08 + *
  • %x MMM Aug + *
  • %d dd 25 + *
  • %H HH 14 + *
  • %M mm 30 + *
  • %S ss 35 + *
  • %s SSS 123 + *
  • %Z Z -0400 + * + *Others: + *
      + *
    • %T Long.toString(time) + *
    • %% % + *
    + */ + public static String insertDate(String pattern, long time) { + DateFormat df = new SimpleDateFormat("yyyy.MM.dd:HH:mm:ss.SSS Z", Locale.US); + df.setTimeZone(TimeZone.getTimeZone("UTC")); + Date date = new Date(time); + String datetime = df.format(date); + StringBuilder result = new StringBuilder(); + int i=0; + while (i < pattern.length()) { + int j = pattern.indexOf('%',i); + if (j == -1 || j >= pattern.length()-1) { // done + result.append(pattern.substring(i)); // copy rest of pattern and quit + break; + } + result.append(pattern.substring(i, j)); + switch (pattern.charAt(j+1)) { + case 'Y': + result.append(datetime.substring(0,4)); // year + break; + case 'm': + result.append(datetime.substring(5,7)); // month + break; + case 'd': + result.append(datetime.substring(8,10)); // day of month + break; + case 'H': + result.append(datetime.substring(11,13)); // hour + break; + case 'M': + result.append(datetime.substring(14,16)); // minute + break; + case 'S': + result.append(datetime.substring(17,19)); // second + break; + case 's': + result.append(datetime.substring(20,23)); // thousanths + break; + case 'Z': + result.append(datetime.substring(24)); // time zone string + break; + case 'T': + result.append(Long.toString(time)); //time in Millis + break; + case 'x': + result.append(capitalize(dfMMM.format(date))); + break; + case '%': + result.append("%%"); + break; + default: + result.append("%"); // copy pattern escape and move on + j--; // only want to bump by one position.... + break; + } + i = j+2; + } + + return result.toString(); + } + + /** + * Private methods: timeStamp(LogRecord) + */ + private String timeStamp(LogRecord record) { + Date date = new Date(record.getMillis()); + String stamp; + switch (timestampFormat) { + case 0: + stamp = Long.toString(record.getMillis()); + break; + case 1: + stamp = ddMMMyyyy.format(date); + break; + case 2: + default: + stamp = yyyyMMdd.format(date); + break; + } + return stamp; + } + + /** Return the given string with the first letter in upper case */ + private static String capitalize(String string) { + if (Character.isUpperCase(string.charAt(0))) return string; + return Character.toUpperCase(string.charAt(0)) + string.substring(1); + } + +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/TraceRenderer.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/TraceRenderer.java new file mode 100644 index 00000000000..295786aa15d --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/TraceRenderer.java @@ -0,0 +1,185 @@ +package com.yahoo.container.logging; + +import com.yahoo.data.access.Inspectable; +import com.yahoo.data.access.Inspector; +import com.yahoo.data.access.simple.JsonRender; +import com.yahoo.yolean.trace.TraceNode; +import com.yahoo.yolean.trace.TraceVisitor; +import com.fasterxml.jackson.core.JsonGenerator; + +import java.io.IOException; + +public class TraceRenderer extends TraceVisitor { + private static final String TRACE_CHILDREN = "children"; + private static final String TRACE_MESSAGE = "message"; + private static final String TRACE_TIMESTAMP = "timestamp"; + private static final String TRACE = "trace"; + + private final long basetime; + private final JsonGenerator generator; + private final FieldConsumer fieldConsumer; + private boolean hasFieldName = false; + int emittedChildNesting = 0; + int currentChildNesting = 0; + private boolean insideOpenObject = false; + + public interface FieldConsumer { + void accept(Object object) throws IOException; + } + + private static class Consumer implements FieldConsumer { + private final JsonGenerator generator; + + Consumer(JsonGenerator generator) { + this.generator = generator; + } + + @Override + public void accept(Object object) throws IOException { + if (object instanceof Inspectable) { + renderInspectorDirect(((Inspectable) object).inspect()); + } else { + generator.writeObject(object); + } + } + private void renderInspectorDirect(Inspector data) throws IOException { + StringBuilder intermediate = new StringBuilder(); + JsonRender.render(data, intermediate, true); + generator.writeRawValue(intermediate.toString()); + } + } + + TraceRenderer(JsonGenerator generator, long basetime) { + this(generator, new Consumer(generator), basetime); + } + public TraceRenderer(JsonGenerator generator, FieldConsumer consumer, long basetime) { + this.generator = generator; + this.fieldConsumer = consumer; + this.basetime = basetime; + } + + @Override + public void entering(TraceNode node) { + ++currentChildNesting; + } + + @Override + public void leaving(TraceNode node) { + conditionalEndObject(); + if (currentChildNesting == emittedChildNesting) { + try { + generator.writeEndArray(); + generator.writeEndObject(); + } catch (IOException e) { + throw new TraceRenderWrapper(e); + } + --emittedChildNesting; + } + --currentChildNesting; + } + + @Override + public void visit(TraceNode node) { + try { + doVisit(node.timestamp(), node.payload(), node.children().iterator().hasNext()); + } catch (IOException e) { + throw new TraceRenderWrapper(e); + } + } + + private void doVisit(long timestamp, Object payload, boolean hasChildren) throws IOException { + boolean dirty = false; + if (timestamp != 0L) { + header(); + generator.writeStartObject(); + generator.writeNumberField(TRACE_TIMESTAMP, timestamp - basetime); + dirty = true; + } + if (payload != null) { + if (!dirty) { + header(); + generator.writeStartObject(); + } + generator.writeFieldName(TRACE_MESSAGE); + fieldConsumer.accept(payload); + dirty = true; + } + if (dirty) { + if (!hasChildren) { + generator.writeEndObject(); + } else { + setInsideOpenObject(true); + } + } + } + private void header() { + fieldName(); + for (int i = 0; i < (currentChildNesting - emittedChildNesting); ++i) { + startChildArray(); + } + emittedChildNesting = currentChildNesting; + } + + private void startChildArray() { + try { + conditionalStartObject(); + generator.writeArrayFieldStart(TRACE_CHILDREN); + } catch (IOException e) { + throw new TraceRenderWrapper(e); + } + } + + private void conditionalStartObject() throws IOException { + if (!isInsideOpenObject()) { + generator.writeStartObject(); + } else { + setInsideOpenObject(false); + } + } + + private void conditionalEndObject() { + if (isInsideOpenObject()) { + // This triggers if we were inside a data node with payload and + // subnodes, but none of the subnodes contained data + try { + generator.writeEndObject(); + setInsideOpenObject(false); + } catch (IOException e) { + throw new TraceRenderWrapper(e); + } + } + } + + private void fieldName() { + if (hasFieldName) { + return; + } + + try { + generator.writeFieldName(TRACE); + } catch (IOException e) { + throw new TraceRenderWrapper(e); + } + hasFieldName = true; + } + + boolean isInsideOpenObject() { + return insideOpenObject; + } + + void setInsideOpenObject(boolean insideOpenObject) { + this.insideOpenObject = insideOpenObject; + } + public static final class TraceRenderWrapper extends RuntimeException { + + /** + * Should never be serialized, but this is still needed. + */ + private static final long serialVersionUID = 2L; + + TraceRenderWrapper(IOException wrapped) { + super(wrapped); + } + + } +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java new file mode 100644 index 00000000000..054fc0fcbf7 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java @@ -0,0 +1,111 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +import com.yahoo.container.core.AccessLogConfig; + +import java.text.SimpleDateFormat; +import java.util.Date; +import java.util.TimeZone; +import java.util.logging.Level; + +/** + * @author Bjorn Borud + * @author Oyvind Bakksjo + */ +public final class VespaAccessLog implements AccessLogInterface { + + private static final ThreadLocal dateFormat = ThreadLocal.withInitial(VespaAccessLog::createDateFormat); + + private final AccessLogHandler logHandler; + + public VespaAccessLog(AccessLogConfig config) { + logHandler = new AccessLogHandler(config.fileHandler()); + } + + private static SimpleDateFormat createDateFormat() { + SimpleDateFormat format = new SimpleDateFormat("[dd/MMM/yyyy:HH:mm:ss Z]"); + format.setTimeZone(TimeZone.getTimeZone("UTC")); + return format; + } + + private static String getDate() { + return dateFormat.get().format(new Date()); + } + + private String getRequest(final String httpMethod, final String rawPath, final String rawQuery, final String httpVersion) { + return httpMethod + " " + (rawQuery != null ? rawPath + "?" + rawQuery : rawPath) + " " + httpVersion; + } + + private String getUser(String user) { + return (user == null) ? "-" : user; + } + + private void writeLog(String ipAddr, String user, String request, String referer, String agent, + long durationMillis, long byteCount, HitCounts hitcounts, int returnCode) + { + long ms = Math.max(0L, durationMillis); + StringBuilder sb = new StringBuilder() + .append(ipAddr) + .append(" - ") + .append(getUser(user)) + .append(' ') + .append(getDate()) + .append(" \"") + .append(request) + .append("\" ") + .append(returnCode) + .append(' ') + .append(byteCount) + .append(" \"") + .append(referer) + .append("\" \"") + .append(agent) + .append("\" ") + .append(ms/1000) + .append('.'); + decimalsOfSecondsFromMilliseconds(ms, sb); + sb.append(' ') + .append((hitcounts == null) ? 0 : hitcounts.getTotalHitCount()) + .append(" 0.0 ") + .append((hitcounts == null) ? 0 : hitcounts.getSummaryCount()) + .append('\n'); + logHandler.access.log(Level.INFO, sb.toString()); + } + + private void decimalsOfSecondsFromMilliseconds(long ms, StringBuilder sb) { + long dec = ms % 1000; + String numbers = String.valueOf(dec); + if (dec <= 9) { + sb.append("00"); + } else if (dec <= 99) { + sb.append('0'); + } + sb.append(numbers); + } + + /** + * TODO: This is never called. We should have a DI provider and call this method from its deconstruct. + */ + public void shutdown() { + if (logHandler!=null) + logHandler.shutdown(); + } + + @Override + public void log(final AccessLogEntry accessLogEntry) { + writeLog( + accessLogEntry.getIpV4Address(), + accessLogEntry.getUser(), + getRequest( + accessLogEntry.getHttpMethod(), + accessLogEntry.getRawPath(), + accessLogEntry.getRawQuery().orElse(null), + accessLogEntry.getHttpVersion()), + accessLogEntry.getReferer(), + accessLogEntry.getUserAgent(), + accessLogEntry.getDurationBetweenRequestResponseMillis(), + accessLogEntry.getReturnedContentSize(), + accessLogEntry.getHitCounts(), + accessLogEntry.getStatusCode()); + } +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/package-info.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/package-info.java new file mode 100644 index 00000000000..fc2abb7b609 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/package-info.java @@ -0,0 +1,5 @@ +// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +@ExportPackage +package com.yahoo.container.logging; + +import com.yahoo.osgi.annotation.ExportPackage; -- cgit v1.2.3