Spring/spring-framework
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Fine-tune WebFlux logging at HTTP/WebSocket level

Browse Source 
1. Use special category prefix "spring-web.reactivestreams" for logging
of reactive streams signals in spring-web, since those are quite
verbose would fill the logs at TRACE.

2. Add and use loggers in request and websocket session implementations
separate from reactive streams bridge for regular TRACE logging.

3. Improve log messages and add where missing (e.g. for Reactor)

Issue: SPR-16898
This commit is contained in:
Rossen Stoyanchev
2018-07-06 17:33:16 -04:00
parent 7746878b50
commit 2874dd75ca
18 changed files with 218 additions and 150 deletions
Download Patch File Download Diff File Expand all files Collapse all files

28
spring-webflux/src/main/java/org/springframework/web/reactive/socket/adapter/AbstractListenerWebSocketSession.java
View File

@@ -94,15 +94,10 @@ public abstract class AbstractListenerWebSocketSession<T> extends AbstractWebSoc
DataBufferFactory bufferFactory, @Nullable MonoProcessor<Void> completionMono) {
super(delegate, id, info, bufferFactory);
this.receivePublisher = new WebSocketReceivePublisher(initLogPrefix(info, id));
this.receivePublisher = new WebSocketReceivePublisher();
this.completionMono = completionMono;
}
private static String initLogPrefix(HandshakeInfo info, String id) {
return info.getLogPrefix() != null ? info.getLogPrefix() : "[" + id + "] ";
}
protected WebSocketSendProcessor getSendProcessor() {
WebSocketSendProcessor sendProcessor = this.sendProcessor;
@@ -229,11 +224,8 @@ public abstract class AbstractListenerWebSocketSession<T> extends AbstractWebSoc
private volatile Queue<Object> pendingMessages = Queues.unbounded(Queues.SMALL_BUFFER_SIZE).get();
WebSocketReceivePublisher(String logPrefix) {
super(logPrefix);
if (logger.isDebugEnabled()) {
logger.debug(getLogPrefix() + "Session id '" + getId() + "' for " + getHandshakeInfo().getUri());
}
WebSocketReceivePublisher() {
super(AbstractListenerWebSocketSession.this.getLogPrefix());
}
@@ -241,8 +233,8 @@ public abstract class AbstractListenerWebSocketSession<T> extends AbstractWebSoc
protected void checkOnDataAvailable() {
resumeReceiving();
int size = this.pendingMessages.size();
if (logger.isTraceEnabled()) {
logger.trace(getLogPrefix() + "checkOnDataAvailable (" + size + " pending)");
if (rsReadLogger.isTraceEnabled()) {
rsReadLogger.trace(getLogPrefix() + "checkOnDataAvailable (" + size + " pending)");
}
if (size > 0) {
onDataAvailable();
@@ -264,6 +256,9 @@ public abstract class AbstractListenerWebSocketSession<T> extends AbstractWebSoc
if (logger.isTraceEnabled()) {
logger.trace(getLogPrefix() + "Received " + message);
}
else if (rsReadLogger.isTraceEnabled()) {
rsReadLogger.trace(getLogPrefix() + "Received " + message);
}
if (!this.pendingMessages.offer(message)) {
throw new IllegalStateException(
"Too many messages. Please ensure WebSocketSession.receive() is subscribed to.");
@@ -291,6 +286,9 @@ public abstract class AbstractListenerWebSocketSession<T> extends AbstractWebSoc
if (logger.isTraceEnabled()) {
logger.trace(getLogPrefix() + "Sending " + message);
}
else if (rsWriteLogger.isTraceEnabled()) {
rsWriteLogger.trace(getLogPrefix() + "Sending " + message);
}
return sendMessage(message);
}
@@ -310,8 +308,8 @@ public abstract class AbstractListenerWebSocketSession<T> extends AbstractWebSoc
* async completion callback into simple flow control.
*/
public void setReadyToSend(boolean ready) {
if (ready && logger.isTraceEnabled()) {
logger.trace(getLogPrefix() + "Ready to send");
if (ready && rsWriteLogger.isTraceEnabled()) {
rsWriteLogger.trace(getLogPrefix() + "Ready to send");
}
this.isReady = ready;
}

30
spring-webflux/src/main/java/org/springframework/web/reactive/socket/adapter/AbstractWebSocketSession.java
View File

@@ -21,6 +21,8 @@ import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.function.Function;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.reactivestreams.Publisher;
import reactor.core.publisher.Flux;
import reactor.core.publisher.Mono;
@@ -43,6 +45,8 @@ import org.springframework.web.reactive.socket.WebSocketSession;
*/
public abstract class AbstractWebSocketSession<T> implements WebSocketSession {
protected final Log logger = LogFactory.getLog(getClass());
private final T delegate;
private final String id;
@@ -53,23 +57,32 @@ public abstract class AbstractWebSocketSession<T> implements WebSocketSession {
private final Map<String, Object> attributes = new ConcurrentHashMap<>();
private final String logPrefix;
/**
* Create a new WebSocket session.
*/
protected AbstractWebSocketSession(T delegate, String id, HandshakeInfo handshakeInfo,
DataBufferFactory bufferFactory) {
protected AbstractWebSocketSession(T delegate, String id, HandshakeInfo info, DataBufferFactory bufferFactory) {
Assert.notNull(delegate, "Native session is required.");
Assert.notNull(id, "Session id is required.");
Assert.notNull(handshakeInfo, "HandshakeInfo is required.");
Assert.notNull(info, "HandshakeInfo is required.");
Assert.notNull(bufferFactory, "DataBuffer factory is required.");
this.delegate = delegate;
this.id = id;
this.handshakeInfo = handshakeInfo;
this.handshakeInfo = info;
this.bufferFactory = bufferFactory;
this.attributes.putAll(handshakeInfo.getAttributes());
this.attributes.putAll(info.getAttributes());
this.logPrefix = initLogPrefix(info, id);
if (logger.isDebugEnabled()) {
logger.debug(getLogPrefix() + "Session id \"" + getId() + "\" for " + getHandshakeInfo().getUri());
}
}
private static String initLogPrefix(HandshakeInfo info, String id) {
return info.getLogPrefix() != null ? info.getLogPrefix() : "[" + id + "] ";
}
@@ -97,6 +110,11 @@ public abstract class AbstractWebSocketSession<T> implements WebSocketSession {
return this.attributes;
}
protected String getLogPrefix() {
return this.logPrefix;
}
@Override
public abstract Flux<WebSocketMessage> receive();

15
spring-webflux/src/main/java/org/springframework/web/reactive/socket/adapter/ReactorNettyWebSocketSession.java
View File

@@ -56,12 +56,23 @@ public class ReactorNettyWebSocketSession
return getDelegate().getInbound()
.aggregateFrames(DEFAULT_FRAME_MAX_SIZE)
.receiveFrames()
.map(super::toMessage);
.map(super::toMessage)
.doOnNext(message -> {
if (logger.isTraceEnabled()) {
logger.trace(getLogPrefix() + "Received " + message);
}
});
}
@Override
public Mono<Void> send(Publisher<WebSocketMessage> messages) {
Flux<WebSocketFrame> frames = Flux.from(messages).map(this::toFrame);
Flux<WebSocketFrame> frames = Flux.from(messages)
.doOnNext(message -> {
if (logger.isTraceEnabled()) {
logger.trace(getLogPrefix() + "Sending " + message);
}
})
.map(this::toFrame);
return getDelegate().getOutbound()
.options(NettyPipeline.SendOptions::flushOnEach)
.sendObject(frames)

18
spring-webflux/src/test/java/org/springframework/web/reactive/socket/WebSocketIntegrationTests.java
View File

@@ -64,17 +64,11 @@ public class WebSocketIntegrationTests extends AbstractWebSocketIntegrationTests
Flux<String> input = Flux.range(1, count).map(index -> "msg-" + index);
ReplayProcessor<Object> output = ReplayProcessor.create(count);
this.client.execute(getUrl("/echo"),
session -> {
logger.debug("Starting to send messages");
return session
.send(input.doOnNext(s -> logger.debug("outbound " + s)).map(session::textMessage))
.thenMany(session.receive().take(count).map(WebSocketMessage::getPayloadAsText))
.subscribeWith(output)
.doOnNext(s -> logger.debug("inbound " + s))
.then();
})
.doOnSuccessOrError((aVoid, ex) -> logger.debug("Done: " + (ex != null ? ex.getMessage() : "success")))
this.client.execute(getUrl("/echo"), session -> session
.send(input.map(session::textMessage))
.thenMany(session.receive().take(count).map(WebSocketMessage::getPayloadAsText))
.subscribeWith(output)
.then())
.block(TIMEOUT);
assertEquals(input.collectList().block(TIMEOUT), output.collectList().block(TIMEOUT));
@@ -181,7 +175,7 @@ public class WebSocketIntegrationTests extends AbstractWebSocketIntegrationTests
@Override
public Mono<Void> handle(WebSocketSession session) {
String protocol = session.getHandshakeInfo().getSubProtocol();
WebSocketMessage message = session.textMessage(protocol);
WebSocketMessage message = session.textMessage(protocol != null ? protocol : "none");
return session.send(Mono.just(message));
}
}

5
spring-webflux/src/test/resources/log4j2-test.xml
View File

@@ -9,11 +9,6 @@
<Logger name="org.springframework.core.codec" level="debug" />
<Logger name="org.springframework.http" level="debug" />
<Logger name="org.springframework.web" level="debug" />
<!-- temporarily while we resolve random failures -->
<Logger name="org.springframework.web.reactive.socket.WebSocketIntegrationTests" level="debug" />
<Logger name="org.springframework.web.reactive.socket.adapter" level="trace" />
<Logger name="reactor" level="info" />
<Logger name="io.reactivex" level="info" />
<Root level="info">