diff options
Diffstat (limited to 'container-core/src/main')
9 files changed, 175 insertions, 44 deletions
diff --git a/container-core/src/main/java/com/yahoo/container/di/componentgraph/core/ComponentNode.java b/container-core/src/main/java/com/yahoo/container/di/componentgraph/core/ComponentNode.java index dcc024ef2b1..31dc5e7cb77 100644 --- a/container-core/src/main/java/com/yahoo/container/di/componentgraph/core/ComponentNode.java +++ b/container-core/src/main/java/com/yahoo/container/di/componentgraph/core/ComponentNode.java @@ -156,7 +156,7 @@ public class ComponentNode extends Node { Duration duration = Duration.between(start, Instant.now()); log.log(duration.compareTo(Duration.ofMinutes(1)) > 0 ? INFO : FINE, () -> "Finished constructing " + idAndType() + " in " + duration); - } catch (InvocationTargetException | InstantiationException | IllegalAccessException e) { + } catch (InvocationTargetException | InstantiationException | IllegalAccessException | IllegalArgumentException | ClassCastException e) { StackTraceElement dependencyInjectorMarker = new StackTraceElement("============= Dependency Injection =============", "newInstance", null, -1); throw removeStackTrace(new ComponentConstructorException("Error constructing " + idAndType() + ": " + e.getMessage(), cutStackTraceAtConstructor(e.getCause(), dependencyInjectorMarker))); } diff --git a/container-core/src/main/java/com/yahoo/container/logging/AccessLogEntry.java b/container-core/src/main/java/com/yahoo/container/logging/AccessLogEntry.java index e4af680726a..0eb4485936d 100644 --- a/container-core/src/main/java/com/yahoo/container/logging/AccessLogEntry.java +++ b/container-core/src/main/java/com/yahoo/container/logging/AccessLogEntry.java @@ -8,6 +8,7 @@ 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; @@ -31,11 +32,23 @@ import static java.util.stream.Collectors.toMap; */ public class AccessLogEntry { + public record Content(String type, long length, byte[] body) {} + private final Object monitor = new Object(); private HitCounts hitCounts; private TraceNode traceNode; private ListMap<String,String> keyValues=null; + private Content content; + + public void setContent(Content entity) { + synchronized (monitor) { + requireNull(this.content); + this.content = entity; + } + } + + public Optional<Content> getContent() { synchronized (monitor) { return Optional.ofNullable(content); } } public void setHitCounts(final HitCounts hitCounts) { synchronized (monitor) { diff --git a/container-core/src/main/java/com/yahoo/container/logging/JSONFormatter.java b/container-core/src/main/java/com/yahoo/container/logging/JSONFormatter.java index f1e865cd596..1f42f8ded97 100644 --- a/container-core/src/main/java/com/yahoo/container/logging/JSONFormatter.java +++ b/container-core/src/main/java/com/yahoo/container/logging/JSONFormatter.java @@ -1,15 +1,16 @@ // Copyright Vespa.ai. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.container.logging; -import com.yahoo.json.Jackson; import com.fasterxml.jackson.core.JsonEncoding; import com.fasterxml.jackson.core.JsonFactory; import com.fasterxml.jackson.core.JsonGenerator; +import com.yahoo.json.Jackson; import com.yahoo.yolean.trace.TraceNode; import java.io.IOException; import java.io.OutputStream; import java.security.Principal; +import java.util.Base64; import java.util.Collection; import java.util.Objects; import java.util.logging.Level; @@ -102,6 +103,15 @@ public class JSONFormatter implements LogWriter<RequestLogEntry> { trace.accept(new TraceRenderer(generator, timestamp)); } + var content = entry.content().orElse(null); + if (content != null) { + generator.writeObjectFieldStart("content"); + generator.writeStringField("type", content.type()); + generator.writeNumberField("length", content.length()); + generator.writeStringField("body", Base64.getEncoder().encodeToString(content.body())); + generator.writeEndObject(); + } + // Only add search sub block of this is a search request if (isSearchRequest(entry)) { HitCounts hitCounts = entry.hitCounts().get(); diff --git a/container-core/src/main/java/com/yahoo/container/logging/RequestLogEntry.java b/container-core/src/main/java/com/yahoo/container/logging/RequestLogEntry.java index 0092d67b0fa..a5f82a8b637 100644 --- a/container-core/src/main/java/com/yahoo/container/logging/RequestLogEntry.java +++ b/container-core/src/main/java/com/yahoo/container/logging/RequestLogEntry.java @@ -1,6 +1,7 @@ // Copyright Vespa.ai. 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.logging.AccessLogEntry.Content; import com.yahoo.yolean.trace.TraceNode; import java.security.Principal; @@ -50,6 +51,7 @@ public class RequestLogEntry { private final Principal sslPrincipal; private final HitCounts hitCounts; private final TraceNode traceNode; + private final Content content; private final SortedMap<String, Collection<String>> extraAttributes; private RequestLogEntry(Builder builder) { @@ -76,6 +78,7 @@ public class RequestLogEntry { this.sslPrincipal = builder.sslPrincipal; this.hitCounts = builder.hitCounts; this.traceNode = builder.traceNode; + this.content = builder.content; this.extraAttributes = copyExtraAttributes(builder.extraAttributes); } @@ -102,6 +105,7 @@ public class RequestLogEntry { public Optional<Principal> sslPrincipal() { return Optional.ofNullable(sslPrincipal); } public Optional<HitCounts> hitCounts() { return Optional.ofNullable(hitCounts); } public Optional<TraceNode> traceNode() { return Optional.ofNullable(traceNode); } + public Optional<Content> content() { return Optional.ofNullable(content); } public SortedSet<String> extraAttributeKeys() { return Collections.unmodifiableSortedSet((SortedSet<String>)extraAttributes.keySet()); } public Collection<String> extraAttributeValues(String key) { return Collections.unmodifiableCollection(extraAttributes.get(key)); } @@ -145,6 +149,7 @@ public class RequestLogEntry { private Principal userPrincipal; private HitCounts hitCounts; private TraceNode traceNode; + private Content content; private Principal sslPrincipal; private final Map<String, Collection<String>> extraAttributes = new HashMap<>(); @@ -171,6 +176,7 @@ public class RequestLogEntry { public Builder sslPrincipal(Principal sslPrincipal) { this.sslPrincipal = requireNonNull(sslPrincipal); return this; } public Builder hitCounts(HitCounts hitCounts) { this.hitCounts = requireNonNull(hitCounts); return this; } public Builder traceNode(TraceNode traceNode) { this.traceNode = requireNonNull(traceNode); return this; } + public Builder content(Content content) { this.content = requireNonNull(content); return this; } public Builder addExtraAttribute(String key, String value) { this.extraAttributes.computeIfAbsent(requireNonNull(key), __ -> new ArrayList<>()).add(requireNonNull(value)); return this; diff --git a/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLog.java b/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLog.java index ccb41ca3055..6c071a162d1 100644 --- a/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLog.java +++ b/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLog.java @@ -57,6 +57,7 @@ class AccessLogRequestLog extends AbstractLifeCycle implements org.eclipse.jetty int peerPort = request.getRemotePort(); long startTime = request.getTimeStamp(); long endTime = System.currentTimeMillis(); + Integer statusCodeOverride = (Integer) request.getAttribute(HttpRequestDispatch.ACCESS_LOG_STATUS_CODE_OVERRIDE); builder.peerAddress(peerAddress) .peerPort(peerPort) .localPort(getLocalPort(request)) @@ -64,7 +65,7 @@ class AccessLogRequestLog extends AbstractLifeCycle implements org.eclipse.jetty .duration(Duration.ofMillis(Math.max(0, endTime - startTime))) .responseSize(response.getHttpChannel().getBytesWritten()) .requestSize(request.getHttpInput().getContentReceived()) - .statusCode(response.getCommittedMetaData().getStatus()); + .statusCode(statusCodeOverride != null ? statusCodeOverride : response.getCommittedMetaData().getStatus()); addNonNullValue(builder, request.getMethod(), RequestLogEntry.Builder::httpMethod); addNonNullValue(builder, request.getRequestURI(), RequestLogEntry.Builder::rawPath); @@ -116,6 +117,7 @@ class AccessLogRequestLog extends AbstractLifeCycle implements org.eclipse.jetty } addNonNullValue(builder, accessLogEntry.getHitCounts(), RequestLogEntry.Builder::hitCounts); addNonNullValue(builder, accessLogEntry.getTrace(), RequestLogEntry.Builder::traceNode); + accessLogEntry.getContent().ifPresent(builder::content); } http2StreamId(request).ifPresent(streamId -> builder.addExtraAttribute("http2-stream-id", Integer.toString(streamId))); diff --git a/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLoggingRequestHandler.java b/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLoggingRequestHandler.java index 2c9cffa6786..31fd55bb987 100644 --- a/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLoggingRequestHandler.java +++ b/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLoggingRequestHandler.java @@ -1,18 +1,36 @@ // Copyright Vespa.ai. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.jdisc.http.server.jetty; -import com.google.common.base.Preconditions; +import ai.vespa.utils.BytesQuantity; import com.yahoo.container.logging.AccessLogEntry; import com.yahoo.jdisc.Request; import com.yahoo.jdisc.handler.AbstractRequestHandler; +import com.yahoo.jdisc.handler.CompletionHandler; import com.yahoo.jdisc.handler.ContentChannel; import com.yahoo.jdisc.handler.DelegatedRequestHandler; import com.yahoo.jdisc.handler.RequestHandler; import com.yahoo.jdisc.handler.ResponseHandler; +import com.yahoo.jdisc.http.ConnectorConfig; +import com.yahoo.jdisc.http.HttpHeaders; import com.yahoo.jdisc.http.HttpRequest; +import java.io.ByteArrayOutputStream; +import java.nio.ByteBuffer; +import java.util.List; import java.util.Map; +import java.util.Objects; import java.util.Optional; +import java.util.Random; +import java.util.TreeMap; +import java.util.concurrent.atomic.AtomicLong; +import java.util.function.Function; +import java.util.function.Predicate; +import java.util.regex.Matcher; +import java.util.regex.Pattern; +import java.util.stream.Collectors; +import java.util.stream.IntStream; + +import static com.yahoo.jdisc.http.server.jetty.RequestUtils.getConnector; /** * A wrapper RequestHandler that enables access logging. By wrapping the request handler, we are able to wrap the @@ -23,6 +41,7 @@ import java.util.Optional; * Does not otherwise interfere with the request processing of the delegate request handler. * * @author bakksjo + * @author bjorncs */ public class AccessLoggingRequestHandler extends AbstractRequestHandler implements DelegatedRequestHandler { public static final String CONTEXT_KEY_ACCESS_LOG_ENTRY @@ -38,27 +57,87 @@ public class AccessLoggingRequestHandler extends AbstractRequestHandler implemen (AccessLogEntry) requestContextMap.get(CONTEXT_KEY_ACCESS_LOG_ENTRY)); } - private final RequestHandler delegate; + private final org.eclipse.jetty.server.Request jettyRequest; + private final RequestHandler delegateRequestHandler; private final AccessLogEntry accessLogEntry; + private final List<String> pathPrefixes; + private final List<Double> samplingRate; + private final List<Long> maxSize; + private final Random rng = new Random(); public AccessLoggingRequestHandler( - final RequestHandler delegateRequestHandler, - final AccessLogEntry accessLogEntry) { - this.delegate = delegateRequestHandler; + org.eclipse.jetty.server.Request jettyRequest, + RequestHandler delegateRequestHandler, + AccessLogEntry accessLogEntry) { + this.jettyRequest = jettyRequest; + this.delegateRequestHandler = delegateRequestHandler; this.accessLogEntry = accessLogEntry; + var cfg = getConnector(jettyRequest).connectorConfig().accessLog().content(); + this.pathPrefixes = cfg.stream().map(e -> e.pathPrefix()).toList(); + this.samplingRate = cfg.stream().map(e -> e.sampleRate()).toList(); + this.maxSize = cfg.stream().map(e -> e.maxSize()).toList(); } @Override public ContentChannel handleRequest(final Request request, final ResponseHandler handler) { - Preconditions.checkArgument(request instanceof HttpRequest, "Expected HttpRequest, got " + request); final HttpRequest httpRequest = (HttpRequest) request; httpRequest.context().put(CONTEXT_KEY_ACCESS_LOG_ENTRY, accessLogEntry); - return delegate.handleRequest(request, handler); + var methodsWithEntity = List.of(HttpRequest.Method.POST, HttpRequest.Method.PUT, HttpRequest.Method.PATCH); + var originalContentChannel = delegateRequestHandler.handleRequest(request, handler); + var uriPath = request.getUri().getPath(); + if (methodsWithEntity.contains(httpRequest.getMethod())) { + for (int i = 0; i < pathPrefixes.size(); i++) { + if (uriPath.startsWith(pathPrefixes.get(i))) { + if (samplingRate.get(i) > rng.nextDouble()) { + return new ContentLoggingContentChannel(originalContentChannel, maxSize.get(i)); + } + } + } + } + return originalContentChannel; } - @Override public RequestHandler getDelegate() { - return delegate; + return delegateRequestHandler; + } + + private class ContentLoggingContentChannel implements ContentChannel { + final AtomicLong length = new AtomicLong(); + final ByteArrayOutputStream accumulatedRequestContent; + final ContentChannel originalContentChannel; + final long contentLoggingMaxSize; + + public ContentLoggingContentChannel(ContentChannel originalContentChannel, long contentLoggingMaxSize) { + this.originalContentChannel = originalContentChannel; + this.contentLoggingMaxSize = contentLoggingMaxSize; + var contentLength = jettyRequest.getContentLength(); + this.accumulatedRequestContent = new ByteArrayOutputStream(contentLength == -1 ? 128 : contentLength); + } + + @Override + public void write(ByteBuffer buf, CompletionHandler handler) { + length.addAndGet(buf.remaining()); + var bytesToLog = Math.min(buf.remaining(), contentLoggingMaxSize - accumulatedRequestContent.size()); + if (bytesToLog > 0) accumulatedRequestContent.write(buf.array(), buf.arrayOffset() + buf.position(), (int)bytesToLog); + if (originalContentChannel != null) originalContentChannel.write(buf, handler); + } + + @Override + public void close(CompletionHandler handler) { + var bytes = accumulatedRequestContent.toByteArray(); + accessLogEntry.setContent(new AccessLogEntry.Content( + Objects.requireNonNullElse(jettyRequest.getHeader(HttpHeaders.Names.CONTENT_TYPE), ""), + length.get(), + bytes)); + accumulatedRequestContent.reset(); + length.set(0); + if (originalContentChannel != null) originalContentChannel.close(handler); + } + + @Override + public void onError(Throwable error) { + if (originalContentChannel != null) originalContentChannel.onError(error); + } } } diff --git a/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/HttpRequestDispatch.java b/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/HttpRequestDispatch.java index a2c2a5df4df..9d873f75516 100644 --- a/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/HttpRequestDispatch.java +++ b/container-core/src/main/java/com/yahoo/jdisc/http/server/jetty/HttpRequestDispatch.java @@ -42,9 +42,10 @@ import static com.yahoo.jdisc.http.server.jetty.RequestUtils.getConnector; */ class HttpRequestDispatch { - private static final Logger log = Logger.getLogger(HttpRequestDispatch.class.getName()); + public static final String ACCESS_LOG_STATUS_CODE_OVERRIDE = "com.yahoo.jdisc.http.server.jetty.ACCESS_LOG_STATUS_CODE_OVERRIDE"; - private final static String CHARSET_ANNOTATION = ";charset="; + private static final Logger log = Logger.getLogger(HttpRequestDispatch.class.getName()); + private static final String CHARSET_ANNOTATION = ";charset="; private final JDiscContext jDiscContext; private final Request jettyRequest; @@ -129,10 +130,12 @@ class HttpRequestDispatch { error, () -> "Network connection was unexpectedly terminated: " + jettyRequest.getRequestURI()); metricReporter.prematurelyClosed(); + asyncCtx.getRequest().setAttribute(ACCESS_LOG_STATUS_CODE_OVERRIDE, 499); } else if (isErrorOfType(error, TimeoutException.class)) { log.log(Level.FINE, error, () -> "Request/stream was timed out by Jetty: " + jettyRequest.getRequestURI()); + asyncCtx.getRequest().setAttribute(ACCESS_LOG_STATUS_CODE_OVERRIDE, 408); } else if (!isErrorOfType(error, OverloadException.class, BindingNotFoundException.class, RequestException.class)) { log.log(Level.WARNING, "Request failed: " + jettyRequest.getRequestURI(), error); } @@ -211,7 +214,8 @@ class HttpRequestDispatch { new FilteringRequestHandler(context.filterResolver(), (Request)servletRequest), servletRequest, context.removeRawPostBodyForWwwUrlEncodedPost()); - return new AccessLoggingRequestHandler(requestHandler, accessLogEntry); + return new AccessLoggingRequestHandler( + (Request) servletRequest, requestHandler, accessLogEntry); } private static RequestHandler wrapHandlerIfFormPost(RequestHandler requestHandler, diff --git a/container-core/src/main/java/com/yahoo/processing/request/CompoundName.java b/container-core/src/main/java/com/yahoo/processing/request/CompoundName.java index b4536a1c56b..440df4f9be9 100644 --- a/container-core/src/main/java/com/yahoo/processing/request/CompoundName.java +++ b/container-core/src/main/java/com/yahoo/processing/request/CompoundName.java @@ -8,6 +8,7 @@ import java.util.ArrayList; import java.util.Arrays; import java.util.List; import java.util.Map; +import java.util.Objects; import static com.yahoo.text.Lowercase.toLowerCase; @@ -74,41 +75,52 @@ public final class CompoundName { * @param compounds the compounds of this name */ private CompoundName(String name, String [] compounds, boolean useCache) { - if (name == null) throw new NullPointerException("Name can not be null"); - - this.name = name; + this.name = Objects.requireNonNull(name, "Name can not be null"); this.lowerCasedName = toLowerCase(name); - if (compounds.length == 1 && compounds[0].isEmpty()) { - this.compounds = List.of(); - this.hashCode = 0; - rest = this; - first = this; + if (compounds.length == 1) { + if (compounds[0].isEmpty()) { + this.compounds = List.of(); + this.hashCode = 0; + rest = first = this; + return; + } + this.compounds = new ImmutableArrayList(compounds); + this.hashCode = this.compounds.hashCode(); + rest = first = empty; return; } - this.compounds = new ImmutableArrayList(compounds); - this.hashCode = this.compounds.hashCode(); - - if (compounds.length > 1) { - String restName = name.substring(compounds[0].length()+1); - if (useCache) { - rest = cache.computeIfAbsent(restName, (key) -> new CompoundName(key, Arrays.copyOfRange(compounds, 1, compounds.length), useCache)); - } else { - rest = new CompoundName(restName, Arrays.copyOfRange(compounds, 1, compounds.length), useCache); + CompoundName[] children = new CompoundName[compounds.length]; + for (int i = 0; i + 1 < children.length; i++) { + int start = 0, end = i == 0 ? -1 : children[0].name.length(); + for (int j = 0; j + i < children.length; j++) { + end += compounds[j + i].length() + 1; + if (end == start) throw new IllegalArgumentException("'" + name + "' is not a legal compound name. " + + "Consecutive, leading or trailing dots are not allowed."); + String subName = this.name.substring(start, end); + CompoundName cached = cache.get(subName); + children[j] = cached != null ? cached + : new CompoundName(subName, + this.lowerCasedName.substring(start, end), + Arrays.copyOfRange(compounds, j, j + i + 1), + i == 0 ? empty : children[j + 1], + i == 0 ? empty : children[j]); + if (useCache && cached == null) cache.put(subName, children[j]); + start += compounds[j].length() + 1; } - } else { - rest = empty; } + this.compounds = new ImmutableArrayList(compounds); + this.hashCode = this.compounds.hashCode(); + this.rest = children[1]; + this.first = children[0]; + } - if (compounds.length > 1) { - String firstName = name.substring(0, name.length() - (compounds[compounds.length-1].length()+1)); - if (useCache) { - first = cache.computeIfAbsent(firstName, (key) -> new CompoundName(key, Arrays.copyOfRange(compounds, 0, compounds.length-1), useCache)); - } else { - first = new CompoundName(firstName, Arrays.copyOfRange(compounds, 0, compounds.length-1), useCache); - } - } else { - first = empty; - } + private CompoundName(String name, String lowerCasedName, String[] compounds, CompoundName rest, CompoundName first) { + this.name = name; + this.lowerCasedName = lowerCasedName; + this.compounds = new ImmutableArrayList(compounds); + this.hashCode = this.compounds.hashCode(); + this.rest = rest; + this.first = first; } private static List<String> parse(String s) { diff --git a/container-core/src/main/resources/configdefinitions/jdisc.http.jdisc.http.connector.def b/container-core/src/main/resources/configdefinitions/jdisc.http.jdisc.http.connector.def index 2906f75a1f5..44750b15324 100644 --- a/container-core/src/main/resources/configdefinitions/jdisc.http.jdisc.http.connector.def +++ b/container-core/src/main/resources/configdefinitions/jdisc.http.jdisc.http.connector.def @@ -154,3 +154,8 @@ accessLog.remoteAddressHeaders[] string # HTTP request headers that contain remote port accessLog.remotePortHeaders[] string + +# Path prefixes for which content should be logged +accessLog.content[].pathPrefix string +accessLog.content[].maxSize long +accessLog.content[].sampleRate double |