From 86de4169088235ccbfcd4264963ca49178c9ff14 Mon Sep 17 00:00:00 2001 From: Rossen Stoyanchev Date: Sat, 28 Jun 2014 14:01:13 -0400 Subject: [PATCH] More WebSocket logging updates Update WebSocketSession toString methods to include the handshake URI and add id and URI fields to ensure they're available after close(). Log WebSocket session open and close events at INFO. Remove trace messages for destinations that do not match. Issue: SPR-11884 --- .../broker/SimpleBrokerMessageHandler.java | 8 --- .../stomp/StompBrokerRelayMessageHandler.java | 3 - .../user/UserDestinationMessageHandler.java | 6 +- .../adapter/AbstractWebSocketSession.java | 7 +- .../adapter/jetty/JettyWebSocketSession.java | 71 ++++++++++--------- .../standard/StandardWebSocketSession.java | 68 +++++++++--------- .../ConcurrentWebSocketSessionDecorator.java | 6 ++ .../LoggingWebSocketHandlerDecorator.java | 10 +-- .../SubProtocolWebSocketHandler.java | 11 ++- .../session/AbstractSockJsSession.java | 5 +- .../session/WebSocketServerSockJsSession.java | 9 +++ .../jetty/JettyWebSocketSessionTests.java | 1 - .../StandardWebSocketHandlerAdapterTests.java | 1 + .../StandardWebSocketSessionTests.java | 1 - 14 files changed, 107 insertions(+), 100 deletions(-) diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/SimpleBrokerMessageHandler.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/SimpleBrokerMessageHandler.java index c29978bb083..65ad766e4d2 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/SimpleBrokerMessageHandler.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/SimpleBrokerMessageHandler.java @@ -135,9 +135,6 @@ public class SimpleBrokerMessageHandler extends AbstractBrokerMessageHandler { String sessionId = SimpMessageHeaderAccessor.getSessionId(headers); if (!checkDestinationPrefix(destination)) { - if (logger.isTraceEnabled()) { - logger.trace("No match on destination in " + message); - } return; } @@ -173,11 +170,6 @@ public class SimpleBrokerMessageHandler extends AbstractBrokerMessageHandler { } this.subscriptionRegistry.unregisterSubscription(message); } - else { - if (logger.isTraceEnabled()) { - logger.trace("Unsupported message type in " + message); - } - } } private void initHeaders(SimpMessageHeaderAccessor accessor) { diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompBrokerRelayMessageHandler.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompBrokerRelayMessageHandler.java index ec07d15bfdc..697e3d1f8c4 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompBrokerRelayMessageHandler.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompBrokerRelayMessageHandler.java @@ -454,9 +454,6 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler String destination = stompAccessor.getDestination(); if ((command != null) && command.requiresDestination() && !checkDestinationPrefix(destination)) { - if (logger.isTraceEnabled()) { - logger.trace("No match on destination. Ignoring " + message); - } return; } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/user/UserDestinationMessageHandler.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/user/UserDestinationMessageHandler.java index cd36efa5c45..2c89021f169 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/user/UserDestinationMessageHandler.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/user/UserDestinationMessageHandler.java @@ -171,8 +171,8 @@ public class UserDestinationMessageHandler implements MessageHandler, SmartLifec } Set destinations = result.getTargetDestinations(); if (destinations.isEmpty()) { - if (logger.isDebugEnabled()) { - logger.debug("Use destination not resolved (no active sessions?): " + message); + if (logger.isTraceEnabled()) { + logger.trace("No user destinations for " + message); } return; } @@ -185,7 +185,7 @@ public class UserDestinationMessageHandler implements MessageHandler, SmartLifec } for (String destination : destinations) { if (logger.isTraceEnabled()) { - logger.trace("Sending message with resolved user destination: " + message); + logger.trace("Sending " + message); } this.brokerMessagingTemplate.send(destination, message); } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/adapter/AbstractWebSocketSession.java b/spring-websocket/src/main/java/org/springframework/web/socket/adapter/AbstractWebSocketSession.java index d2be486a282..396b01889e5 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/adapter/AbstractWebSocketSession.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/adapter/AbstractWebSocketSession.java @@ -144,7 +144,12 @@ public abstract class AbstractWebSocketSession implements NativeWebSocketSess @Override public String toString() { - return this.getClass().getSimpleName() + "[id=" + getId() + "]"; + if (this.nativeSession != null) { + return getClass().getSimpleName() + "[id=" + getId() + ", uri=" + getUri() + "]"; + } + else { + return getClass().getSimpleName() + "[nativeSession=null]"; + } } } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/adapter/jetty/JettyWebSocketSession.java b/spring-websocket/src/main/java/org/springframework/web/socket/adapter/jetty/JettyWebSocketSession.java index b780cfb2de7..cf76a001ab8 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/adapter/jetty/JettyWebSocketSession.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/adapter/jetty/JettyWebSocketSession.java @@ -46,14 +46,18 @@ import org.springframework.web.socket.adapter.AbstractWebSocketSession; */ public class JettyWebSocketSession extends AbstractWebSocketSession { + private String id; + + private URI uri; + private HttpHeaders headers; + private String acceptedProtocol; + private List extensions; private Principal user; - private String acceptedProtocol; - /** * Create a new {@link JettyWebSocketSession} instance. @@ -81,51 +85,48 @@ public class JettyWebSocketSession extends AbstractWebSocketSession { @Override public String getId() { checkNativeSessionInitialized(); - return ObjectUtils.getIdentityHexString(getNativeSession()); + return this.id; } @Override public URI getUri() { checkNativeSessionInitialized(); - return getNativeSession().getUpgradeRequest().getRequestURI(); + return this.uri; } @Override public HttpHeaders getHandshakeHeaders() { checkNativeSessionInitialized(); - if (this.headers == null) { - this.headers = new HttpHeaders(); - this.headers.putAll(getNativeSession().getUpgradeRequest().getHeaders()); - this.headers = HttpHeaders.readOnlyHttpHeaders(headers); - } return this.headers; } @Override - public Principal getPrincipal() { - if (this.user != null) { - return this.user; - } + public String getAcceptedProtocol() { checkNativeSessionInitialized(); - return (isOpen() ? getNativeSession().getUpgradeRequest().getUserPrincipal() : null); + return this.acceptedProtocol; } @Override - public InetSocketAddress getLocalAddress() { + public List getExtensions() { checkNativeSessionInitialized(); - return getNativeSession().getLocalAddress(); + return this.extensions; } @Override - public InetSocketAddress getRemoteAddress() { + public Principal getPrincipal() { + return this.user; + } + + @Override + public InetSocketAddress getLocalAddress() { checkNativeSessionInitialized(); - return getNativeSession().getRemoteAddress(); + return getNativeSession().getLocalAddress(); } @Override - public String getAcceptedProtocol() { + public InetSocketAddress getRemoteAddress() { checkNativeSessionInitialized(); - return this.acceptedProtocol; + return getNativeSession().getRemoteAddress(); } @Override @@ -152,19 +153,6 @@ public class JettyWebSocketSession extends AbstractWebSocketSession { return getNativeSession().getPolicy().getMaxBinaryMessageSize(); } - @Override - public List getExtensions() { - checkNativeSessionInitialized(); - if(this.extensions == null) { - List source = getNativeSession().getUpgradeResponse().getExtensions(); - this.extensions = new ArrayList(source.size()); - for(ExtensionConfig e : source) { - this.extensions.add(new WebSocketExtension(e.getName(), e.getParameters())); - } - } - return this.extensions; - } - @Override public boolean isOpen() { return ((getNativeSession() != null) && getNativeSession().isOpen()); @@ -173,10 +161,25 @@ public class JettyWebSocketSession extends AbstractWebSocketSession { @Override public void initializeNativeSession(Session session) { super.initializeNativeSession(session); + + this.id = ObjectUtils.getIdentityHexString(getNativeSession()); + this.uri = session.getUpgradeRequest().getRequestURI(); + + this.headers = new HttpHeaders(); + this.headers.putAll(getNativeSession().getUpgradeRequest().getHeaders()); + this.headers = HttpHeaders.readOnlyHttpHeaders(headers); + + this.acceptedProtocol = session.getUpgradeResponse().getAcceptedSubProtocol(); + + List source = getNativeSession().getUpgradeResponse().getExtensions(); + this.extensions = new ArrayList(source.size()); + for(ExtensionConfig e : source) { + this.extensions.add(new WebSocketExtension(e.getName(), e.getParameters())); + } + if (this.user == null) { this.user = session.getUpgradeRequest().getUserPrincipal(); } - this.acceptedProtocol = session.getUpgradeResponse().getAcceptedSubProtocol(); } @Override diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/adapter/standard/StandardWebSocketSession.java b/spring-websocket/src/main/java/org/springframework/web/socket/adapter/standard/StandardWebSocketSession.java index 53ee1aae793..2ddfec02ce3 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/adapter/standard/StandardWebSocketSession.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/adapter/standard/StandardWebSocketSession.java @@ -47,17 +47,21 @@ import org.springframework.web.socket.adapter.AbstractWebSocketSession; */ public class StandardWebSocketSession extends AbstractWebSocketSession { + private String id; + + private URI uri; + private final HttpHeaders handshakeHeaders; - private final InetSocketAddress localAddress; + private String acceptedProtocol; - private final InetSocketAddress remoteAddress; + private List extensions; private Principal user; - private String acceptedProtocol; + private final InetSocketAddress localAddress; - private List extensions; + private final InetSocketAddress remoteAddress; /** @@ -89,25 +93,24 @@ public class StandardWebSocketSession extends AbstractWebSocketSession InetSocketAddress localAddress, InetSocketAddress remoteAddress, Principal user) { super(attributes); - headers = (headers != null) ? headers : new HttpHeaders(); this.handshakeHeaders = HttpHeaders.readOnlyHttpHeaders(headers); + this.user = user; this.localAddress = localAddress; this.remoteAddress = remoteAddress; - this.user = user; } @Override public String getId() { checkNativeSessionInitialized(); - return getNativeSession().getId(); + return this.id; } @Override public URI getUri() { checkNativeSessionInitialized(); - return getNativeSession().getRequestURI(); + return this.uri; } @Override @@ -116,12 +119,19 @@ public class StandardWebSocketSession extends AbstractWebSocketSession } @Override - public Principal getPrincipal() { - if (this.user != null) { - return this.user; - } + public String getAcceptedProtocol() { checkNativeSessionInitialized(); - return (isOpen() ? getNativeSession().getUserPrincipal() : null); + return this.acceptedProtocol; + } + + @Override + public List getExtensions() { + checkNativeSessionInitialized(); + return this.extensions; + } + + public Principal getPrincipal() { + return this.user; } @Override @@ -134,12 +144,6 @@ public class StandardWebSocketSession extends AbstractWebSocketSession return this.remoteAddress; } - @Override - public String getAcceptedProtocol() { - checkNativeSessionInitialized(); - return this.acceptedProtocol; - } - @Override public void setTextMessageSizeLimit(int messageSizeLimit) { checkNativeSessionInitialized(); @@ -164,19 +168,6 @@ public class StandardWebSocketSession extends AbstractWebSocketSession return getNativeSession().getMaxBinaryMessageBufferSize(); } - @Override - public List getExtensions() { - checkNativeSessionInitialized(); - if(this.extensions == null) { - List source = getNativeSession().getNegotiatedExtensions(); - this.extensions = new ArrayList(source.size()); - for(Extension e : source) { - this.extensions.add(new StandardToWebSocketExtensionAdapter(e)); - } - } - return this.extensions; - } - @Override public boolean isOpen() { return (getNativeSession() != null && getNativeSession().isOpen()); @@ -185,10 +176,21 @@ public class StandardWebSocketSession extends AbstractWebSocketSession @Override public void initializeNativeSession(Session session) { super.initializeNativeSession(session); + + this.id = session.getId(); + this.uri = session.getRequestURI(); + + this.acceptedProtocol = session.getNegotiatedSubprotocol(); + + List source = getNativeSession().getNegotiatedExtensions(); + this.extensions = new ArrayList(source.size()); + for(Extension e : source) { + this.extensions.add(new StandardToWebSocketExtensionAdapter(e)); + } + if(this.user == null) { this.user = session.getUserPrincipal(); } - this.acceptedProtocol = session.getNegotiatedSubprotocol(); } @Override diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/handler/ConcurrentWebSocketSessionDecorator.java b/spring-websocket/src/main/java/org/springframework/web/socket/handler/ConcurrentWebSocketSessionDecorator.java index fbca2ff04ca..3b3aa5fe5da 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/handler/ConcurrentWebSocketSessionDecorator.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/handler/ConcurrentWebSocketSessionDecorator.java @@ -168,4 +168,10 @@ public class ConcurrentWebSocketSessionDecorator extends WebSocketSessionDecorat super.close(status); } + + @Override + public String toString() { + return getDelegate().toString(); + } + } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/handler/LoggingWebSocketHandlerDecorator.java b/spring-websocket/src/main/java/org/springframework/web/socket/handler/LoggingWebSocketHandlerDecorator.java index 2c081bb625e..7b1bcde8df8 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/handler/LoggingWebSocketHandlerDecorator.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/handler/LoggingWebSocketHandlerDecorator.java @@ -41,8 +41,8 @@ public class LoggingWebSocketHandlerDecorator extends WebSocketHandlerDecorator @Override public void afterConnectionEstablished(WebSocketSession session) throws Exception { - if (logger.isDebugEnabled()) { - logger.debug("Connection established, " + session + ", uri=" + session.getUri()); + if (logger.isInfoEnabled()) { + logger.info("Connection established " + session); } super.afterConnectionEstablished(session); } @@ -58,15 +58,15 @@ public class LoggingWebSocketHandlerDecorator extends WebSocketHandlerDecorator @Override public void handleTransportError(WebSocketSession session, Throwable exception) throws Exception { if (logger.isErrorEnabled()) { - logger.error("Transport error for " + session, exception); + logger.error("Transport error in " + session, exception); } super.handleTransportError(session, exception); } @Override public void afterConnectionClosed(WebSocketSession session, CloseStatus closeStatus) throws Exception { - if (logger.isDebugEnabled()) { - logger.debug("Connection closed for " + session + ", " + closeStatus); + if (logger.isInfoEnabled()) { + logger.info("Connection closed with " + closeStatus + " in " + session + ", "); } super.afterConnectionClosed(session, closeStatus); } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/messaging/SubProtocolWebSocketHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/messaging/SubProtocolWebSocketHandler.java index ab0adb1a9de..c8d624f520a 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/messaging/SubProtocolWebSocketHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/messaging/SubProtocolWebSocketHandler.java @@ -376,7 +376,8 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler, } WebSocketSession session = holder.getSession(); if (logger.isErrorEnabled()) { - logger.error("No messages received after " + timeSinceCreated + " ms. Closing " + holder + "."); + logger.error("No messages received after " + timeSinceCreated + " ms. " + + "Closing " + holder.getSession() + "."); } try { session.close(CloseStatus.PROTOCOL_ERROR); @@ -446,12 +447,8 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler, @Override public String toString() { - if (this.session instanceof ConcurrentWebSocketSessionDecorator) { - return ((ConcurrentWebSocketSessionDecorator) this.session).getLastSession().toString(); - } - else { - return this.session.toString(); - } + return "WebSocketSessionHolder[=session=" + this.session + ", createTime=" + + this.createTime + ", hasHandledMessages=" + this.handledMessages + "]"; } } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/AbstractSockJsSession.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/AbstractSockJsSession.java index 01e3a30f40f..d95abf3f36a 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/AbstractSockJsSession.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/AbstractSockJsSession.java @@ -424,12 +424,9 @@ public abstract class AbstractSockJsSession implements SockJsSession { } } - @Override public String toString() { - long currentTime = System.currentTimeMillis(); - return getClass().getSimpleName() + "[id=" + this.id + ", state=" + this.state + ", sinceCreated=" + - (currentTime - this.timeCreated) + ", sinceLastActive=" + (currentTime - this.timeLastActive) + "]"; + return getClass().getSimpleName() + "[id=" + getId() + ", uri=" + getUri() + "]"; } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/WebSocketServerSockJsSession.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/WebSocketServerSockJsSession.java index 8b937dadcfc..4cec12db6de 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/WebSocketServerSockJsSession.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/WebSocketServerSockJsSession.java @@ -233,4 +233,13 @@ public class WebSocketServerSockJsSession extends AbstractSockJsSession implemen } } + @Override + public String toString() { + if (getNativeSession() != null) { + return super.toString(); + } + else { + return "WebSocketServerSockJsSession[id=" + getId() + ", uri=null]"; + } + } } diff --git a/spring-websocket/src/test/java/org/springframework/web/socket/adapter/jetty/JettyWebSocketSessionTests.java b/spring-websocket/src/test/java/org/springframework/web/socket/adapter/jetty/JettyWebSocketSessionTests.java index 74b4273217f..a0b2e9c0c6f 100644 --- a/spring-websocket/src/test/java/org/springframework/web/socket/adapter/jetty/JettyWebSocketSessionTests.java +++ b/spring-websocket/src/test/java/org/springframework/web/socket/adapter/jetty/JettyWebSocketSessionTests.java @@ -101,7 +101,6 @@ public class JettyWebSocketSessionTests { reset(nativeSession); assertNull(session.getPrincipal()); - verify(nativeSession).isOpen(); verifyNoMoreInteractions(nativeSession); } diff --git a/spring-websocket/src/test/java/org/springframework/web/socket/adapter/standard/StandardWebSocketHandlerAdapterTests.java b/spring-websocket/src/test/java/org/springframework/web/socket/adapter/standard/StandardWebSocketHandlerAdapterTests.java index fa3639e83f2..4919a8d5cd9 100644 --- a/spring-websocket/src/test/java/org/springframework/web/socket/adapter/standard/StandardWebSocketHandlerAdapterTests.java +++ b/spring-websocket/src/test/java/org/springframework/web/socket/adapter/standard/StandardWebSocketHandlerAdapterTests.java @@ -55,6 +55,7 @@ public class StandardWebSocketHandlerAdapterTests { @Test public void onOpen() throws Throwable { + when(this.session.getId()).thenReturn("123"); this.adapter.onOpen(this.session, null); verify(this.webSocketHandler).afterConnectionEstablished(this.webSocketSession); diff --git a/spring-websocket/src/test/java/org/springframework/web/socket/adapter/standard/StandardWebSocketSessionTests.java b/spring-websocket/src/test/java/org/springframework/web/socket/adapter/standard/StandardWebSocketSessionTests.java index ef2cf002beb..2d5cd40e671 100644 --- a/spring-websocket/src/test/java/org/springframework/web/socket/adapter/standard/StandardWebSocketSessionTests.java +++ b/spring-websocket/src/test/java/org/springframework/web/socket/adapter/standard/StandardWebSocketSessionTests.java @@ -86,7 +86,6 @@ public class StandardWebSocketSessionTests { reset(nativeSession); assertNull(session.getPrincipal()); - verify(nativeSession).isOpen(); verifyNoMoreInteractions(nativeSession); }