Log WebSocket connection issues at DEBUG level

WebSocket clients going away is an expected and common occurance.
Logging at ERROR level on failure to close a connection or on failures
to write data to a WebSocket sessions has a high potential for false
positives with very little to do. This change lowers the log level for
a number of log messages that fit this category.

This should be helped by the effort already spent for 4.1 to ensure
logging at DEBUG level doesn't produce excessive amounts of logging.

Issue: SPR-12155

Author: rstoyanchev

spring-websocket/src/main/java/org/springframework/web/socket/handler/ExceptionWebSocketHandlerDecorator.java

@@ -1,5 +1,5 @@
 /*
- * Copyright 2002-2013 the original author or authors.
+ * Copyright 2002-2014 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.
@@ -52,7 +52,9 @@ public void afterConnectionEstablished(WebSocketSession session) {
 	}
 
 	public static void tryCloseWithError(WebSocketSession session, Throwable exception, Log logger) {
-		logger.error("Closing due to exception for " + session, exception);
+		if (logger.isDebugEnabled()) {
+			logger.debug("Closing due to exception for " + session, exception);
+		}
 		if (session.isOpen()) {
 			try {
 				session.close(CloseStatus.SERVER_ERROR);

spring-websocket/src/main/java/org/springframework/web/socket/handler/LoggingWebSocketHandlerDecorator.java

@@ -57,8 +57,8 @@ public void handleMessage(WebSocketSession session, WebSocketMessage<?> message)
 
 	@Override
 	public void handleTransportError(WebSocketSession session, Throwable exception) throws Exception {
-		if (logger.isErrorEnabled()) {
-			logger.error("Transport error in " + session, exception);
+		if (logger.isDebugEnabled()) {
+			logger.debug("Transport error in " + session, exception);
 		}
 		super.handleTransportError(session, exception);
 	}

spring-websocket/src/main/java/org/springframework/web/socket/messaging/StompSubProtocolHandler.java

@@ -255,7 +255,7 @@ else if (StompCommand.UNSUBSCRIBE.equals(headerAccessor.getCommand())) {
 				}
 			}
 			catch (Throwable ex) {
-				logger.error("Failed to send STOMP message from client to application MessageChannel" +
+				logger.error("Failed to send client message to application via MessageChannel" +
 						" in session " + session.getId() + ". Sending STOMP ERROR to client.", ex);
 				sendErrorMessage(session, ex);
 
@@ -280,7 +280,8 @@ protected void sendErrorMessage(WebSocketSession session, Throwable error) {
 			session.sendMessage(new TextMessage(bytes));
 		}
 		catch (Throwable ex) {
-			logger.error("Failed to send STOMP ERROR to client.", ex);
+			// Could be part of normal workflow (e.g. browser tab closed)
+			logger.debug("Failed to send STOMP ERROR to client.", ex);
 		}
 	}
 
@@ -330,7 +331,8 @@ else if (StompCommand.CONNECTED.equals(command)) {
 			throw ex;
 		}
 		catch (Throwable ex) {
-			logger.error("Failed to send WebSocket message to client in session " + session.getId() + ".", ex);
+			// Could be part of normal workflow (e.g. browser tab closed)
+			logger.debug("Failed to send WebSocket message to client in session " + session.getId() + ".", ex);
 			command = StompCommand.ERROR;
 		}
 		finally {

spring-websocket/src/main/java/org/springframework/web/socket/messaging/SubProtocolWebSocketHandler.java

@@ -333,17 +333,20 @@ public void handleMessage(Message<?> message) throws MessagingException {
 		}
 		catch (SessionLimitExceededException ex) {
 			try {
-				logger.error("Terminating '" + session + "'", ex);
+				if (logger.isDebugEnabled()) {
+					logger.debug("Terminating '" + session + "'", ex);
+				}
 				this.stats.incrementLimitExceededCount();
 				clearSession(session, ex.getStatus()); // clear first, session may be unresponsive
 				session.close(ex.getStatus());
 			}
 			catch (Exception secondException) {
-				logger.error("Failure while closing session " + sessionId + ".", secondException);
+				logger.debug("Failure while closing session " + sessionId + ".", secondException);
 			}
 		}
 		catch (Exception e) {
-			logger.error("Failed to send message to client in " + session + ": " + message, e);
+			// Could be part of normal workflow (e.g. browser tab closed)
+			logger.debug("Failed to send message to client in " + session + ": " + message, e);
 		}
 	}
 

spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/TransportHandlingSockJsService.java

@@ -178,7 +178,7 @@ protected void handleRawWebSocketRequest(ServerHttpRequest request, ServerHttpRe
 		catch (Throwable ex) {
 			failure = new HandshakeFailureException("Uncaught failure for request " + request.getURI(), ex);
 		}
-		finally {
+			finally {
 			if (failure != null) {
 				chain.applyAfterHandshake(request, response, failure);
 				throw failure;
@@ -303,7 +303,8 @@ public void run() {
 							}
 						}
 						catch (Throwable ex) {
-							logger.error("Failed to close " + session, ex);
+							// Could be part of normal workflow (e.g. browser tab closed)
+							logger.debug("Failed to close " + session, ex);
 						}
 					}
 					if (logger.isDebugEnabled() && !removedSessionIds.isEmpty()) {

spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/AbstractHttpSockJsSession.java

@@ -323,7 +323,8 @@ protected void resetRequest() {
 						control.complete();
 					}
 					catch (Throwable ex) {
-						logger.error("Failed to complete request: " + ex.getMessage());
+						// Could be part of normal workflow (e.g. browser tab closed)
+						logger.debug("Failed to complete request: " + ex.getMessage());
 					}
 				}
 			}

spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/AbstractSockJsSession.java

@@ -291,7 +291,7 @@ public final void close(CloseStatus status) throws IOException {
 					this.handler.afterConnectionClosed(this, status);
 				}
 				catch (Throwable ex) {
-					logger.error("Error from WebSocketHandler.afterConnectionClosed in " + this, ex);
+					logger.debug("Error from WebSocketHandler.afterConnectionClosed in " + this, ex);
 				}
 			}
 		}
@@ -307,7 +307,9 @@ public final void close(CloseStatus status) throws IOException {
 	 * Close due to error arising from SockJS transport handling.
 	 */
 	public void tryCloseWithSockJsTransportError(Throwable error, CloseStatus closeStatus) {
-		logger.error("Closing due to transport error for " + this);
+		if (logger.isDebugEnabled()) {
+			logger.debug("Closing due to transport error for " + this);
+		}
 		try {
 			delegateError(error);
 		}
@@ -318,7 +320,7 @@ public void tryCloseWithSockJsTransportError(Throwable error, CloseStatus closeS
 			close(closeStatus);
 		}
 		catch (Throwable closeException) {
-			logger.error("Failure while closing " + this, closeException);
+			logger.debug("Failure while closing " + this, closeException);
 		}
 	}
 
@@ -370,7 +372,7 @@ else if (disconnectedClientLogger.isDebugEnabled()) {
 			}
 		}
 		else {
-			logger.error("Terminating connection after failure to send message to client.", failure);
+			logger.debug("Terminating connection after failure to send message to client.", failure);
 		}
 	}
 
@@ -421,7 +423,7 @@ protected void cancelHeartbeat() {
 			}
 		}
 		catch (Throwable ex) {
-			logger.error("Failure while cancelling heartbeat in session " + getId(), ex);
+			logger.debug("Failure while cancelling heartbeat in session " + getId(), ex);
 		}
 	}