Move reactive server instrumentation out of WebFilter

Prior to this commit, the Observation instrumentation for Reactive
server applications was implemented with a `WebFilter`. This allowed to
record observations and set up a tracing context for the controller
handlers.

The limitation of this approach is that all processing happening at a
lower level is not aware of any observation. Here, the
`HttpWebHandlerAdapter` handles several interesting aspects:

* logging of HTTP requests and responses at the TRACE level
* logging of client disconnect errors
* handling of unresolved errors

With the current instrumentation, these logging statements will miss the
tracing context information. As a result, this commit deprecates the
`ServerHttpObservationFilter` in favor of a more direct instrumentation
of the `HttpWebHandlerAdapter`. This enables a more precise
instrumentattion and allows to set up the current observation earlier in
the reactor context: log statements will now contain the relevant
information.

Fixes gh-30013
This commit is contained in:
Brian Clozel
2023-03-14 17:16:56 +01:00
parent e5ee369e70
commit 96a429a561
16 changed files with 419 additions and 31 deletions

View File

@@ -18,12 +18,14 @@ package org.springframework.http.server.reactive.observation;
import java.util.Collections;
import java.util.Map;
import java.util.Optional;
import io.micrometer.observation.transport.RequestReplyReceiverContext;
import org.springframework.http.server.reactive.ServerHttpRequest;
import org.springframework.http.server.reactive.ServerHttpResponse;
import org.springframework.lang.Nullable;
import org.springframework.web.server.ServerWebExchange;
/**
* Context that holds information for metadata collection regarding
@@ -36,6 +38,12 @@ import org.springframework.lang.Nullable;
*/
public class ServerRequestObservationContext extends RequestReplyReceiverContext<ServerHttpRequest, ServerHttpResponse> {
/**
* Name of the request attribute holding the {@link ServerRequestObservationContext context} for the current observation.
* @since 6.1.0
*/
public static final String CURRENT_OBSERVATION_CONTEXT_ATTRIBUTE = ServerRequestObservationContext.class.getName() + ".context";
private final Map<String, Object> attributes;
@Nullable
@@ -50,6 +58,16 @@ public class ServerRequestObservationContext extends RequestReplyReceiverContext
this.attributes = Collections.unmodifiableMap(attributes);
}
/**
* Get the current {@link ServerRequestObservationContext observation context} from the given exchange, if available.
* @param exchange the current exchange
* @return the current observation context
* @since 6.1.0
*/
public static Optional<ServerRequestObservationContext> findCurrent(ServerWebExchange exchange) {
return Optional.ofNullable(exchange.getAttribute(CURRENT_OBSERVATION_CONTEXT_ATTRIBUTE));
}
/**
* Return an immutable map of the current request attributes.
*/

View File

@@ -1,5 +1,5 @@
/*
* Copyright 2002-2022 the original author or authors.
* Copyright 2002-2023 the original author or authors.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
@@ -33,6 +33,7 @@ import org.springframework.http.server.reactive.observation.ServerRequestObserva
import org.springframework.web.server.ServerWebExchange;
import org.springframework.web.server.WebFilter;
import org.springframework.web.server.WebFilterChain;
import org.springframework.web.server.adapter.WebHttpHandlerBuilder;
/**
@@ -47,7 +48,9 @@ import org.springframework.web.server.WebFilterChain;
*
* @author Brian Clozel
* @since 6.0
* @deprecated since 6.1.0 in favor of {@link WebHttpHandlerBuilder}.
*/
@Deprecated(since = "6.1.0", forRemoval = true)
public class ServerHttpObservationFilter implements WebFilter {
/**

View File

@@ -1,5 +1,5 @@
/*
* Copyright 2002-2022 the original author or authors.
* Copyright 2002-2023 the original author or authors.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
@@ -20,8 +20,12 @@ import java.util.Map;
import java.util.Set;
import java.util.function.Function;
import io.micrometer.observation.Observation;
import io.micrometer.observation.ObservationRegistry;
import io.micrometer.observation.contextpropagation.ObservationThreadLocalAccessor;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.reactivestreams.Publisher;
import reactor.core.publisher.Mono;
import org.springframework.context.ApplicationContext;
@@ -36,11 +40,16 @@ import org.springframework.http.codec.multipart.Part;
import org.springframework.http.server.reactive.HttpHandler;
import org.springframework.http.server.reactive.ServerHttpRequest;
import org.springframework.http.server.reactive.ServerHttpResponse;
import org.springframework.http.server.reactive.observation.DefaultServerRequestObservationConvention;
import org.springframework.http.server.reactive.observation.ServerHttpObservationDocumentation;
import org.springframework.http.server.reactive.observation.ServerRequestObservationContext;
import org.springframework.http.server.reactive.observation.ServerRequestObservationConvention;
import org.springframework.lang.Nullable;
import org.springframework.util.Assert;
import org.springframework.util.StringUtils;
import org.springframework.web.server.ServerWebExchange;
import org.springframework.web.server.WebHandler;
import org.springframework.web.server.handler.ExceptionHandlingWebHandler;
import org.springframework.web.server.handler.WebHandlerDecorator;
import org.springframework.web.server.i18n.AcceptHeaderLocaleContextResolver;
import org.springframework.web.server.i18n.LocaleContextResolver;
@@ -55,6 +64,7 @@ import org.springframework.web.server.session.WebSessionManager;
*
* @author Rossen Stoyanchev
* @author Sebastien Deleuze
* @author Brian Clozel
* @since 5.0
*/
public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHandler {
@@ -75,6 +85,8 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
private static final Set<String> DISCONNECTED_CLIENT_EXCEPTIONS =
Set.of("AbortedException", "ClientAbortException", "EOFException", "EofException");
private static final ServerRequestObservationConvention DEFAULT_OBSERVATION_CONVENTION = new DefaultServerRequestObservationConvention();
private static final Log logger = LogFactory.getLog(HttpWebHandlerAdapter.class);
@@ -91,6 +103,12 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
@Nullable
private ForwardedHeaderTransformer forwardedHeaderTransformer;
@Nullable
private ObservationRegistry observationRegistry;
@Nullable
private ServerRequestObservationConvention observationConvention;
@Nullable
private ApplicationContext applicationContext;
@@ -192,6 +210,44 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
return this.forwardedHeaderTransformer;
}
/**
* Configure a {@link ObservationRegistry} for recording server exchange observations.
* By default, a {@link ObservationRegistry#NOOP no-op} instance will be used.
* @param observationRegistry the observation registry to use
* @since 6.1.0
*/
public void setObservationRegistry(ObservationRegistry observationRegistry) {
this.observationRegistry = observationRegistry;
}
/**
* Return the configured {@link ObservationRegistry}.
* @since 6.1.0
*/
@Nullable
public ObservationRegistry getObservationRegistry() {
return this.observationRegistry;
}
/**
* Configure a {@link ServerRequestObservationConvention} for server exchanges observations.
* By default, a {@link DefaultServerRequestObservationConvention} instance will be used.
* @param observationConvention the observation convention to use
* @since 6.1.0
*/
public void setObservationConvention(ServerRequestObservationConvention observationConvention) {
this.observationConvention = observationConvention;
}
/**
* Return the Observation convention configured for server exchanges observations.
* @since 6.1.0
*/
@Nullable
public ServerRequestObservationConvention getObservationConvention() {
return this.observationConvention;
}
/**
* Configure the {@code ApplicationContext} associated with the web application,
* if it was initialized with one via
@@ -247,9 +303,12 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
exchange.getLogPrefix() + formatRequest(exchange.getRequest()) +
(traceOn ? ", headers=" + formatHeaders(exchange.getRequest().getHeaders()) : ""));
ServerRequestObservationContext observationContext = new ServerRequestObservationContext(exchange.getRequest(),
exchange.getResponse(), exchange.getAttributes());
exchange.getAttributes().put(ServerRequestObservationContext.CURRENT_OBSERVATION_CONTEXT_ATTRIBUTE, observationContext);
return getDelegate().handle(exchange)
.doOnSuccess(aVoid -> logResponse(exchange))
.onErrorResume(ex -> handleUnresolvedError(exchange, ex))
.transformDeferred(call -> transform(exchange, observationContext, call))
.then(cleanupMultipart(exchange))
.then(Mono.defer(response::setComplete));
}
@@ -271,6 +330,42 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
return "HTTP " + request.getMethod() + " \"" + request.getPath() + query + "\"";
}
private Publisher<Void> transform(ServerWebExchange exchange, ServerRequestObservationContext observationContext, Mono<Void> call) {
Observation observation = ServerHttpObservationDocumentation.HTTP_REACTIVE_SERVER_REQUESTS.observation(this.observationConvention,
DEFAULT_OBSERVATION_CONVENTION, () -> observationContext, this.observationRegistry);
observation.start();
return call
.doOnSuccess(aVoid -> {
logResponse(exchange);
stopObservation(observation, exchange);
})
.onErrorResume(ex -> handleUnresolvedError(exchange, observationContext, ex))
.doOnCancel(() -> cancelObservation(observationContext, observation))
.contextWrite(context -> context.put(ObservationThreadLocalAccessor.KEY, observation));
}
private void stopObservation(Observation observation, ServerWebExchange exchange) {
Throwable throwable = exchange.getAttribute(ExceptionHandlingWebHandler.HANDLED_WEB_EXCEPTION);
if (throwable != null) {
observation.error(throwable);
}
ServerHttpResponse response = exchange.getResponse();
if (response.isCommitted()) {
observation.stop();
}
else {
response.beforeCommit(() -> {
observation.stop();
return Mono.empty();
});
}
}
private void cancelObservation(ServerRequestObservationContext observationContext, Observation observation) {
observationContext.setConnectionAborted(true);
observation.stop();
}
private void logResponse(ServerWebExchange exchange) {
LogFormatUtils.traceDebug(logger, traceOn -> {
HttpStatusCode status = exchange.getResponse().getStatusCode();
@@ -284,7 +379,7 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
responseHeaders.toString() : responseHeaders.isEmpty() ? "{}" : "{masked}";
}
private Mono<Void> handleUnresolvedError(ServerWebExchange exchange, Throwable ex) {
private Mono<Void> handleUnresolvedError(ServerWebExchange exchange, ServerRequestObservationContext observationContext, Throwable ex) {
ServerHttpRequest request = exchange.getRequest();
ServerHttpResponse response = exchange.getResponse();
String logPrefix = exchange.getLogPrefix();
@@ -304,6 +399,7 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
lostClientLogger.debug(logPrefix + "Client went away: " + ex +
" (stacktrace at TRACE level for '" + DISCONNECTED_CLIENT_LOG_CATEGORY + "')");
}
observationContext.setConnectionAborted(true);
return Mono.empty();
}
else {

View File

@@ -1,5 +1,5 @@
/*
* Copyright 2002-2022 the original author or authors.
* Copyright 2002-2023 the original author or authors.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
@@ -22,6 +22,7 @@ import java.util.List;
import java.util.function.Consumer;
import java.util.function.Function;
import io.micrometer.observation.ObservationRegistry;
import reactor.blockhound.BlockHound;
import reactor.blockhound.integration.BlockHoundIntegration;
@@ -31,6 +32,8 @@ import org.springframework.core.annotation.AnnotationAwareOrderComparator;
import org.springframework.http.codec.ServerCodecConfigurer;
import org.springframework.http.server.reactive.HttpHandler;
import org.springframework.http.server.reactive.HttpHandlerDecoratorFactory;
import org.springframework.http.server.reactive.observation.DefaultServerRequestObservationConvention;
import org.springframework.http.server.reactive.observation.ServerRequestObservationConvention;
import org.springframework.lang.Nullable;
import org.springframework.util.Assert;
import org.springframework.util.ObjectUtils;
@@ -104,6 +107,12 @@ public final class WebHttpHandlerBuilder {
@Nullable
private ForwardedHeaderTransformer forwardedHeaderTransformer;
@Nullable
private ObservationRegistry observationRegistry;
@Nullable
private ServerRequestObservationConvention observationConvention;
/**
* Private constructor to use when initialized from an ApplicationContext.
@@ -126,6 +135,8 @@ public final class WebHttpHandlerBuilder {
this.codecConfigurer = other.codecConfigurer;
this.localeContextResolver = other.localeContextResolver;
this.forwardedHeaderTransformer = other.forwardedHeaderTransformer;
this.observationRegistry = other.observationRegistry;
this.observationConvention = other.observationConvention;
this.httpHandlerDecorator = other.httpHandlerDecorator;
}
@@ -359,6 +370,28 @@ public final class WebHttpHandlerBuilder {
return (this.forwardedHeaderTransformer != null);
}
/**
* Configure a {@link ObservationRegistry} for recording server exchange observations.
* By default, a {@link ObservationRegistry#NOOP no-op} registry will be configured.
* @param observationRegistry the observation registry
* @since 6.1.0
*/
public WebHttpHandlerBuilder observationRegistry(ObservationRegistry observationRegistry) {
this.observationRegistry = observationRegistry;
return this;
}
/**
* Configure a {@link ServerRequestObservationConvention} to use for server observations.
* By default, a {@link DefaultServerRequestObservationConvention} will be used.
* @param observationConvention the convention to use for all recorded observations
* @since 6.1.0
*/
public WebHttpHandlerBuilder observationConvention(ServerRequestObservationConvention observationConvention) {
this.observationConvention = observationConvention;
return this;
}
/**
* Configure a {@link Function} to decorate the {@link HttpHandler} returned
* by this builder which effectively wraps the entire
@@ -404,6 +437,12 @@ public final class WebHttpHandlerBuilder {
if (this.forwardedHeaderTransformer != null) {
adapted.setForwardedHeaderTransformer(this.forwardedHeaderTransformer);
}
if (this.observationRegistry != null) {
adapted.setObservationRegistry(this.observationRegistry);
}
if (this.observationConvention != null) {
adapted.setObservationConvention(this.observationConvention);
}
if (this.applicationContext != null) {
adapted.setApplicationContext(this.applicationContext);
}

View File

@@ -1,5 +1,5 @@
/*
* Copyright 2002-2020 the original author or authors.
* Copyright 2002-2023 the original author or authors.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
@@ -38,6 +38,13 @@ import org.springframework.web.server.WebHandler;
*/
public class ExceptionHandlingWebHandler extends WebHandlerDecorator {
/**
* Name of the {@link ServerWebExchange#getAttributes() attribute} that
* contains the exception handled by {@link WebExceptionHandler WebExceptionHandlers}.
* @since 6.0.8
*/
public static String HANDLED_WEB_EXCEPTION = ExceptionHandlingWebHandler.class.getSimpleName() + ".handledException";
private final List<WebExceptionHandler> exceptionHandlers;
@@ -74,7 +81,8 @@ public class ExceptionHandlingWebHandler extends WebHandlerDecorator {
}
for (WebExceptionHandler handler : this.exceptionHandlers) {
completion = completion.onErrorResume(ex -> handler.handle(exchange, ex));
completion = completion.doOnError(error -> exchange.getAttributes().put(HANDLED_WEB_EXCEPTION, error))
.onErrorResume(ex -> handler.handle(exchange, ex));
}
return completion;
}