Polish error logging for HTTP reactive server classes

This commit is contained in:
Rossen Stoyanchev 2016-09-16 16:08:30 -04:00
parent 80ff5ae9c5
commit b2ccdfbc9e
7 changed files with 47 additions and 43 deletions

View File

@ -18,6 +18,7 @@ package org.springframework.http.server.reactive;
import java.util.function.Function; import java.util.function.Function;
import org.apache.commons.logging.Log;
import reactor.core.publisher.Mono; import reactor.core.publisher.Mono;
import reactor.ipc.netty.http.HttpChannel; import reactor.ipc.netty.http.HttpChannel;
@ -35,6 +36,9 @@ import io.netty.handler.codec.http.HttpResponseStatus;
*/ */
public class ReactorHttpHandlerAdapter implements Function<HttpChannel, Mono<Void>> { public class ReactorHttpHandlerAdapter implements Function<HttpChannel, Mono<Void>> {
private static Log logger = LogFactory.getLog(ReactorHttpHandlerAdapter.class);
private final HttpHandler httpHandler; private final HttpHandler httpHandler;
@ -51,10 +55,11 @@ public class ReactorHttpHandlerAdapter implements Function<HttpChannel, Mono<Voi
ReactorServerHttpResponse adaptedResponse = new ReactorServerHttpResponse(channel, bufferFactory); ReactorServerHttpResponse adaptedResponse = new ReactorServerHttpResponse(channel, bufferFactory);
return this.httpHandler.handle(adaptedRequest, adaptedResponse) return this.httpHandler.handle(adaptedRequest, adaptedResponse)
.otherwise(ex -> { .otherwise(ex -> {
LogFactory.getLog(ReactorHttpHandlerAdapter.class).error("Could not complete request", ex); logger.debug("Could not complete request", ex);
channel.status(HttpResponseStatus.INTERNAL_SERVER_ERROR); channel.status(HttpResponseStatus.INTERNAL_SERVER_ERROR);
return Mono.empty(); return Mono.empty();
}); })
.doOnSuccess(aVoid -> logger.debug("Successfully completed request"));
} }
} }

View File

@ -42,14 +42,14 @@ public class ReactorServerHttpRequest extends AbstractServerHttpRequest {
private final HttpChannel channel; private final HttpChannel channel;
private final NettyDataBufferFactory dataBufferFactory; private final NettyDataBufferFactory bufferFactory;
public ReactorServerHttpRequest(HttpChannel request,
NettyDataBufferFactory dataBufferFactory) { public ReactorServerHttpRequest(HttpChannel request, NettyDataBufferFactory bufferFactory) {
Assert.notNull("'request' must not be null"); Assert.notNull("'request' must not be null");
Assert.notNull(dataBufferFactory, "'dataBufferFactory' must not be null"); Assert.notNull(bufferFactory, "'bufferFactory' must not be null");
this.channel = request; this.channel = request;
this.dataBufferFactory = dataBufferFactory; this.bufferFactory = bufferFactory;
} }
@ -90,7 +90,7 @@ public class ReactorServerHttpRequest extends AbstractServerHttpRequest {
@Override @Override
public Flux<DataBuffer> getBody() { public Flux<DataBuffer> getBody() {
return this.channel.receive().retain().map(this.dataBufferFactory::wrap); return this.channel.receive().retain().map(this.bufferFactory::wrap);
} }
} }

View File

@ -49,9 +49,8 @@ public class ReactorServerHttpResponse extends AbstractServerHttpResponse
private final HttpChannel channel; private final HttpChannel channel;
public ReactorServerHttpResponse(HttpChannel response, public ReactorServerHttpResponse(HttpChannel response, DataBufferFactory bufferFactory) {
DataBufferFactory dataBufferFactory) { super(bufferFactory);
super(dataBufferFactory);
Assert.notNull("'response' must not be null."); Assert.notNull("'response' must not be null.");
this.channel = response; this.channel = response;
} }
@ -77,10 +76,9 @@ public class ReactorServerHttpResponse extends AbstractServerHttpResponse
} }
@Override @Override
protected Mono<Void> writeAndFlushWithInternal( protected Mono<Void> writeAndFlushWithInternal(Publisher<Publisher<DataBuffer>> publisher) {
Publisher<Publisher<DataBuffer>> publisher) { Publisher<Publisher<ByteBuf>> body = Flux.from(publisher)
Publisher<Publisher<ByteBuf>> body = Flux.from(publisher). .map(ReactorServerHttpResponse::toByteBufs);
map(ReactorServerHttpResponse::toByteBufs);
return this.channel.sendAndFlush(body); return this.channel.sendAndFlush(body);
} }

View File

@ -22,6 +22,7 @@ import io.reactivex.netty.protocol.http.server.HttpServerRequest;
import io.reactivex.netty.protocol.http.server.HttpServerResponse; import io.reactivex.netty.protocol.http.server.HttpServerResponse;
import io.reactivex.netty.protocol.http.server.RequestHandler; import io.reactivex.netty.protocol.http.server.RequestHandler;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory; import org.apache.commons.logging.LogFactory;
import org.reactivestreams.Publisher; import org.reactivestreams.Publisher;
import reactor.adapter.RxJava1Adapter; import reactor.adapter.RxJava1Adapter;
@ -39,6 +40,9 @@ import org.springframework.util.Assert;
*/ */
public class RxNettyHttpHandlerAdapter implements RequestHandler<ByteBuf, ByteBuf> { public class RxNettyHttpHandlerAdapter implements RequestHandler<ByteBuf, ByteBuf> {
private static Log logger = LogFactory.getLog(RxNettyHttpHandlerAdapter.class);
private final HttpHandler httpHandler; private final HttpHandler httpHandler;
@ -55,10 +59,11 @@ public class RxNettyHttpHandlerAdapter implements RequestHandler<ByteBuf, ByteBu
RxNettyServerHttpResponse adaptedResponse = new RxNettyServerHttpResponse(response, bufferFactory); RxNettyServerHttpResponse adaptedResponse = new RxNettyServerHttpResponse(response, bufferFactory);
Publisher<Void> result = this.httpHandler.handle(adaptedRequest, adaptedResponse) Publisher<Void> result = this.httpHandler.handle(adaptedRequest, adaptedResponse)
.otherwise(ex -> { .otherwise(ex -> {
LogFactory.getLog(RxNettyHttpHandlerAdapter.class).error("Could not complete request", ex); logger.debug("Could not complete request", ex);
response.setStatus(HttpResponseStatus.INTERNAL_SERVER_ERROR); response.setStatus(HttpResponseStatus.INTERNAL_SERVER_ERROR);
return Mono.empty(); return Mono.empty();
}); })
.doOnSuccess(aVoid -> logger.debug("Successfully completed request"));
return RxJava1Adapter.publisherToObservable(result); return RxJava1Adapter.publisherToObservable(result);
} }

View File

@ -114,7 +114,7 @@ public class ServletHttpHandlerAdapter extends HttpServlet {
@Override @Override
public void onError(Throwable ex) { public void onError(Throwable ex) {
logger.error("Error from request handling. Completing the request.", ex); logger.debug("Could not complete request", ex);
HttpServletResponse response = (HttpServletResponse) this.asyncContext.getResponse(); HttpServletResponse response = (HttpServletResponse) this.asyncContext.getResponse();
response.setStatus(HttpServletResponse.SC_INTERNAL_SERVER_ERROR); response.setStatus(HttpServletResponse.SC_INTERNAL_SERVER_ERROR);
this.asyncContext.complete(); this.asyncContext.complete();
@ -122,6 +122,7 @@ public class ServletHttpHandlerAdapter extends HttpServlet {
@Override @Override
public void onComplete() { public void onComplete() {
logger.debug("Successfully completed request");
this.asyncContext.complete(); this.asyncContext.complete();
} }
} }

View File

@ -78,7 +78,7 @@ public class UndertowHttpHandlerAdapter implements io.undertow.server.HttpHandle
@Override @Override
public void onError(Throwable ex) { public void onError(Throwable ex) {
logger.error("Error from request handling. Completing the request.", ex); logger.debug("Could not complete request", ex);
if (!exchange.isResponseStarted() && exchange.getStatusCode() <= 500) { if (!exchange.isResponseStarted() && exchange.getStatusCode() <= 500) {
exchange.setStatusCode(500); exchange.setStatusCode(500);
} }
@ -87,6 +87,7 @@ public class UndertowHttpHandlerAdapter implements io.undertow.server.HttpHandle
@Override @Override
public void onComplete() { public void onComplete() {
logger.debug("Successfully completed request");
exchange.endExchange(); exchange.endExchange();
} }
}); });

View File

@ -40,39 +40,35 @@ import org.springframework.web.server.WebHandler;
* @since 5.0 * @since 5.0
*/ */
public class ExceptionHandlingWebHandler extends WebHandlerDecorator { public class ExceptionHandlingWebHandler extends WebHandlerDecorator {
private static Log logger = LogFactory.getLog(ExceptionHandlingWebHandler.class);
/** /**
* Log category to use on network IO exceptions after a client has gone away. * Log category to use on network IO exceptions after a client has gone away.
* <p>The Servlet API does not provide notifications when a client disconnects; * <p>Servlet containers do not expose notifications when a client disconnects;
* see <a href="https://java.net/jira/browse/SERVLET_SPEC-44">SERVLET_SPEC-44</a>. * see <a href="https://java.net/jira/browse/SERVLET_SPEC-44">SERVLET_SPEC-44</a>.
* Therefore network IO failures may occur simply because a client has gone away, * Therefore network IO failures may occur simply because a client has gone away,
* and that can fill the logs with unnecessary stack traces. * and that can fill the logs with unnecessary stack traces.
* <p>We make a best effort to identify such network failures, on a per-server * <p>We make a best effort to identify such network failures, on a per-server
* basis, and log them under a separate log category. A simple one-line message * basis and log them under a separate log category. A simple one-line message
* is logged at DEBUG level, while a full stack trace is shown at TRACE level. * is logged at DEBUG level instead while a full stack trace is shown at TRACE.
* @see #disconnectedClientLogger
*/ */
private static final String DISCONNECTED_CLIENT_LOG_CATEGORY = private static final String DISCONNECTED_CLIENT_LOG_CATEGORY =
"org.springframework.web.server.handler.DisconnectedClient"; ExceptionHandlingWebHandler.class.getName() + ".DisconnectedClient";
/**
* Separate logger to use on network IO failure after a client has gone away.
* @see #DISCONNECTED_CLIENT_LOG_CATEGORY
*/
private static final Log disconnectedClientLogger = LogFactory.getLog(DISCONNECTED_CLIENT_LOG_CATEGORY); private static final Log disconnectedClientLogger = LogFactory.getLog(DISCONNECTED_CLIENT_LOG_CATEGORY);
private static final Set<String> disconnectedClientExceptions; private static final Set<String> DISCONNECTED_CLIENT_EXCEPTIONS;
static { static {
Set<String> set = new HashSet<>(3); Set<String> set = new HashSet<>(3);
set.add("ClientAbortException"); // Tomcat set.add("ClientAbortException"); // Tomcat
set.add("EOFException"); // Tomcat set.add("EOFException"); // Tomcat
set.add("EofException"); // Jetty set.add("EofException"); // Jetty
// java.io.IOException "Broken pipe" on WildFly, Glassfish (already covered) // java.io.IOException("Broken pipe") on WildFly (already covered)
disconnectedClientExceptions = Collections.unmodifiableSet(set); DISCONNECTED_CLIENT_EXCEPTIONS = Collections.unmodifiableSet(set);
} }
private static Log logger = LogFactory.getLog(ExceptionHandlingWebHandler.class);
private final List<WebExceptionHandler> exceptionHandlers; private final List<WebExceptionHandler> exceptionHandlers;
@ -82,7 +78,8 @@ public class ExceptionHandlingWebHandler extends WebHandlerDecorator {
} }
private static List<WebExceptionHandler> initList(WebExceptionHandler[] list) { private static List<WebExceptionHandler> initList(WebExceptionHandler[] list) {
return (list != null ? Collections.unmodifiableList(Arrays.asList(list)): Collections.emptyList()); return (list != null ? Collections.unmodifiableList(Arrays.asList(list)):
Collections.emptyList());
} }
@ -110,20 +107,19 @@ public class ExceptionHandlingWebHandler extends WebHandlerDecorator {
} }
private Mono<? extends Void> handleUnresolvedException(ServerWebExchange exchange, Throwable ex) { private Mono<? extends Void> handleUnresolvedException(ServerWebExchange exchange, Throwable ex) {
logError(ex); logException(ex);
exchange.getResponse().setStatusCode(HttpStatus.INTERNAL_SERVER_ERROR); exchange.getResponse().setStatusCode(HttpStatus.INTERNAL_SERVER_ERROR);
return Mono.empty(); return Mono.empty();
} }
private void logError(Throwable t) { private void logException(Throwable ex) {
@SuppressWarnings("serial") @SuppressWarnings("serial")
NestedCheckedException nestedException = new NestedCheckedException("", t) {}; NestedCheckedException nestedException = new NestedCheckedException("", ex) {};
if ("Broken pipe".equalsIgnoreCase(nestedException.getMostSpecificCause().getMessage()) || if ("Broken pipe".equalsIgnoreCase(nestedException.getMostSpecificCause().getMessage()) ||
disconnectedClientExceptions.contains(t.getClass().getSimpleName())) { DISCONNECTED_CLIENT_EXCEPTIONS.contains(ex.getClass().getSimpleName())) {
if (disconnectedClientLogger.isTraceEnabled()) { if (disconnectedClientLogger.isTraceEnabled()) {
disconnectedClientLogger.trace("Looks like the client has gone away", t); disconnectedClientLogger.trace("Looks like the client has gone away", ex);
} }
else if (disconnectedClientLogger.isDebugEnabled()) { else if (disconnectedClientLogger.isDebugEnabled()) {
disconnectedClientLogger.debug("Looks like the client has gone away: " + disconnectedClientLogger.debug("Looks like the client has gone away: " +
@ -132,9 +128,7 @@ public class ExceptionHandlingWebHandler extends WebHandlerDecorator {
} }
} }
else { else {
if (logger.isDebugEnabled()) { logger.debug("Could not complete request", ex);
logger.debug("Could not complete request", t);
}
} }
} }