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

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) {

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;
 		}
 

spring-messaging/src/main/java/org/springframework/messaging/simp/user/UserDestinationMessageHandler.java

@@ -171,8 +171,8 @@ public class UserDestinationMessageHandler implements MessageHandler, SmartLifec
 		}
 		Set<String> 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);
 		}

spring-websocket/src/main/java/org/springframework/web/socket/adapter/AbstractWebSocketSession.java

@@ -144,7 +144,12 @@ public abstract class AbstractWebSocketSession<T> 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]";
+		}
 	}
 
 }

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<Session> {
 
+	private String id;
+
+	private URI uri;
+
 	private HttpHeaders headers;
 
+	private String acceptedProtocol;
+
 	private List<WebSocketExtension> extensions;
 
 	private Principal user;
 
-	private String acceptedProtocol;
-
 
 	/**
 	 * Create a new {@link JettyWebSocketSession} instance.
@@ -81,51 +85,48 @@ public class JettyWebSocketSession extends AbstractWebSocketSession<Session> {
 	@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<WebSocketExtension> 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<Session> {
 		return getNativeSession().getPolicy().getMaxBinaryMessageSize();
 	}
 
-	@Override
-	public List<WebSocketExtension> getExtensions() {
-		checkNativeSessionInitialized();
-		if(this.extensions == null) {
-			List<ExtensionConfig> source = getNativeSession().getUpgradeResponse().getExtensions();
-			this.extensions = new ArrayList<WebSocketExtension>(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<Session> {
 	@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<ExtensionConfig> source = getNativeSession().getUpgradeResponse().getExtensions();
+		this.extensions = new ArrayList<WebSocketExtension>(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

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<Session> {
 
+	private String id;
+
+	private URI uri;
+
 	private final HttpHeaders handshakeHeaders;
 
-	private final InetSocketAddress localAddress;
+	private String acceptedProtocol;
 
-	private final InetSocketAddress remoteAddress;
+	private List<WebSocketExtension> extensions;
 
 	private Principal user;
 
-	private String acceptedProtocol;
+	private final InetSocketAddress localAddress;
 
-	private List<WebSocketExtension> extensions;
+	private final InetSocketAddress remoteAddress;
 
 
 	/**
@@ -89,25 +93,24 @@ public class StandardWebSocketSession extends AbstractWebSocketSession<Session>
 			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<Session>
 	}
 
 	@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<WebSocketExtension> getExtensions() {
+		checkNativeSessionInitialized();
+		return this.extensions;
+	}
+
+	public Principal getPrincipal() {
+		return this.user;
 	}
 
 	@Override
@@ -134,12 +144,6 @@ public class StandardWebSocketSession extends AbstractWebSocketSession<Session>
 		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<Session>
 		return getNativeSession().getMaxBinaryMessageBufferSize();
 	}
 
-	@Override
-	public List<WebSocketExtension> getExtensions() {
-		checkNativeSessionInitialized();
-		if(this.extensions == null) {
-			List<Extension> source = getNativeSession().getNegotiatedExtensions();
-			this.extensions = new ArrayList<WebSocketExtension>(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<Session>
 	@Override
 	public void initializeNativeSession(Session session) {
 		super.initializeNativeSession(session);
+
+		this.id = session.getId();
+		this.uri = session.getRequestURI();
+
+		this.acceptedProtocol = session.getNegotiatedSubprotocol();
+
+		List<Extension> source = getNativeSession().getNegotiatedExtensions();
+		this.extensions = new ArrayList<WebSocketExtension>(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

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();
+	}
+
 }

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);
 	}

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 + "]";
 		}
 	}
 

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() + "]";
 	}
 
 

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]";
+		}
+	}
 }

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);
 	}
 

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);

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);
 	}