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

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 class ExceptionWebSocketHandlerDecorator extends WebSocketHandlerDecorato
 	}
 
 	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 class LoggingWebSocketHandlerDecorator extends WebSocketHandlerDecorator
 
 	@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 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
 				}
 			}
 			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 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
 			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 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
 			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 class SubProtocolWebSocketHandler implements WebSocketHandler,
 		}
 		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 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem
 		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 class TransportHandlingSockJsService extends AbstractSockJsService implem
 							}
 						}
 						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 @@ public abstract class AbstractHttpSockJsSession extends AbstractSockJsSession {
 						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 abstract class AbstractSockJsSession implements SockJsSession {
 					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 abstract class AbstractSockJsSession implements SockJsSession {
 	 * 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 abstract class AbstractSockJsSession implements SockJsSession {
 			close(closeStatus);
 		}
 		catch (Throwable closeException) {
-			logger.error("Failure while closing " + this, closeException);
+			logger.debug("Failure while closing " + this, closeException);
 		}
 	}
 
@@ -370,7 +372,7 @@ public abstract class AbstractSockJsSession implements SockJsSession {
 			}
 		}
 		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 @@ public abstract class AbstractSockJsSession implements SockJsSession {
 			}
 		}
 		catch (Throwable ex) {
-			logger.error("Failure while cancelling heartbeat in session " + getId(), ex);
+			logger.debug("Failure while cancelling heartbeat in session " + getId(), ex);
 		}
 	}