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

Fine tune STOMP and WebSocket related logging

Browse Source 
Optimize logging with tracking the opening and closing of WebSocket
sessions and STOMP broker connections in mind.

While the volume of messages makes it impractical to log every message
at anything higher than TRACE, the opening and closing of connections
is more manageable and can be logged at INFO. This makes it possible to
drop to INFO in production and get useful information without getting
too much in a short period of time.

The logging is also optimized to avoid providing the same information
from multiple places since messages pass through multiple layers.

Issue: SPR-11884
This commit is contained in:
Rossen Stoyanchev
2014-06-27 03:39:47 -04:00
parent b2f6445058
commit 113fd1180a
34 changed files with 480 additions and 490 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -133,8 +133,8 @@ public abstract class AbstractWebSocketSession<T> implements NativeWebSocketSess
@Override
public final void close(CloseStatus status) throws IOException {
checkNativeSessionInitialized();
if (logger.isDebugEnabled()) {
logger.debug("Closing " + this);
if (logger.isInfoEnabled()) {
logger.info("Closing " + this);
}
closeInternal(status);
}
@@ -144,7 +144,7 @@ public abstract class AbstractWebSocketSession<T> implements NativeWebSocketSess
@Override
public String toString() {
return "WebSocket session id=" + getId();
return this.getClass().getSimpleName() + "[id=" + getId() + "]";
}
}

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

@@ -50,7 +50,7 @@ public class LoggingWebSocketHandlerDecorator extends WebSocketHandlerDecorator
@Override
public void handleMessage(WebSocketSession session, WebSocketMessage<?> message) throws Exception {
if (logger.isTraceEnabled()) {
logger.trace(message + ", " + session);
logger.trace("Handling " + message + " in " + session);
}
super.handleMessage(session, message);
}

2
spring-websocket/src/main/java/org/springframework/web/socket/messaging/SessionConnectEvent.java
View File

@@ -73,6 +73,6 @@ public class SessionConnectEvent extends ApplicationEvent {
@Override
public String toString() {
return "SessionConnectEvent: message=" + message;
return "SessionConnectEvent" + this.message;
}
}

2
spring-websocket/src/main/java/org/springframework/web/socket/messaging/SessionConnectedEvent.java
View File

@@ -56,6 +56,6 @@ public class SessionConnectedEvent extends ApplicationEvent {
@Override
public String toString() {
return "SessionConnectedEvent: message=" + message;
return "SessionConnectedEvent" + this.message;
}
}

3
spring-websocket/src/main/java/org/springframework/web/socket/messaging/SessionDisconnectEvent.java
View File

@@ -68,6 +68,7 @@ public class SessionDisconnectEvent extends ApplicationEvent {
@Override
public String toString() {
return "SessionDisconnectEvent: sessionId=" + this.sessionId;
return "SessionDisconnectEvent[sessionId=" + this.sessionId +
(this.status != null ? this.status.toString() : "closeStatus=null") + "]";
}
}

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

@@ -39,7 +39,6 @@ import org.springframework.messaging.simp.SimpMessageHeaderAccessor;
import org.springframework.messaging.simp.SimpMessageType;
import org.springframework.messaging.simp.stomp.BufferingStompDecoder;
import org.springframework.messaging.simp.stomp.StompCommand;
import org.springframework.messaging.simp.stomp.StompConversionException;
import org.springframework.messaging.simp.stomp.StompDecoder;
import org.springframework.messaging.simp.stomp.StompEncoder;
import org.springframework.messaging.simp.stomp.StompHeaderAccessor;
@@ -188,31 +187,31 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
messages = decoder.decode(byteBuffer);
if (messages.isEmpty()) {
logger.debug("Incomplete STOMP frame content received," + "buffered=" +
decoder.getBufferSize() + ", buffer size limit=" + decoder.getBufferSizeLimit());
if (logger.isTraceEnabled()) {
logger.trace("Incomplete STOMP frame content received, bufferSize=" +
decoder.getBufferSize() + ", bufferSizeLimit=" + decoder.getBufferSizeLimit() + ".");
}
return;
}
}
catch (Throwable ex) {
logger.error("Failed to parse WebSocket message to STOMP." +
"Sending STOMP ERROR to client, sessionId=" + session.getId(), ex);
if (logger.isErrorEnabled()) {
logger.error("Failed to parse " + webSocketMessage +
" in session " + session.getId() + ". Sending STOMP ERROR to client.", ex);
}
sendErrorMessage(session, ex);
return;
}
for (Message<byte[]> message : messages) {
try {
StompHeaderAccessor headerAccessor =
MessageHeaderAccessor.getAccessor(message, StompHeaderAccessor.class);
if (logger.isTraceEnabled()) {
if (headerAccessor.isHeartbeat()) {
logger.trace("Received heartbeat from client session=" + session.getId());
}
else {
logger.trace("Received message from client session=" + session.getId());
}
logger.trace(headerAccessor.isHeartbeat() ?
"Received heartbeat from broker in session " + session.getId() + "." :
"Received message from broker in session " + session.getId() + ": " + message + ".");
}
headerAccessor.setSessionId(session.getId());
@@ -233,19 +232,23 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
}
}
catch (Throwable ex) {
logger.error("Parsed STOMP message but could not send it to to message channel. " +
"Sending STOMP ERROR to client, sessionId=" + session.getId(), ex);
logger.error("Failed to send STOMP message from client to application MessageChannel" +
" in session " + session.getId() + ". Sending STOMP ERROR to client.", ex);
sendErrorMessage(session, ex);
}
}
}
private void publishEvent(ApplicationEvent event) {
try {
if (logger.isInfoEnabled()) {
logger.info("Publishing " + event);
}
this.eventPublisher.publishEvent(event);
}
catch (Throwable ex) {
logger.error("Error while publishing " + event, ex);
logger.error("Error publishing " + event + ".", ex);
}
}
@@ -257,7 +260,7 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
session.sendMessage(new TextMessage(bytes));
}
catch (Throwable ex) {
// ignore
logger.error("Failed to send STOMP ERROR to client.", ex);
}
}
@@ -267,45 +270,17 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
@SuppressWarnings("unchecked")
@Override
public void handleMessageToClient(WebSocketSession session, Message<?> message) {
if (!(message.getPayload() instanceof byte[])) {
logger.error("Ignoring message, expected byte[] content: " + message);
logger.error("Expected byte[] payload. Ignoring " + message + ".");
return;
}
MessageHeaderAccessor accessor = MessageHeaderAccessor.getAccessor(message, MessageHeaderAccessor.class);
if (accessor == null) {
logger.error("No header accessor: " + message);
return;
}
StompHeaderAccessor stompAccessor;
if (accessor instanceof StompHeaderAccessor) {
stompAccessor = (StompHeaderAccessor) accessor;
}
else if (accessor instanceof SimpMessageHeaderAccessor) {
stompAccessor = StompHeaderAccessor.wrap(message);
if (SimpMessageType.CONNECT_ACK.equals(stompAccessor.getMessageType())) {
StompHeaderAccessor connectedHeaders = StompHeaderAccessor.create(StompCommand.CONNECTED);
connectedHeaders.setVersion(getVersion(stompAccessor));
connectedHeaders.setHeartbeat(0, 0); // no heart-beat support with simple broker
stompAccessor = connectedHeaders;
}
else if (stompAccessor.getCommand() == null || StompCommand.SEND.equals(stompAccessor.getCommand())) {
stompAccessor.updateStompCommandAsServerMessage();
}
}
else {
// Should not happen
logger.error("Unexpected header accessor type: " + accessor);
return;
}
StompHeaderAccessor stompAccessor = getStompHeaderAccessor(message);
StompCommand command = stompAccessor.getCommand();
if (StompCommand.MESSAGE.equals(command)) {
if (stompAccessor.getSubscriptionId() == null) {
logger.error("Ignoring message, no subscriptionId header: " + message);
return;
if (logger.isWarnEnabled()) {
logger.warn("No STOMP \"subscription\" header in " + message);
}
}
String origDestination = stompAccessor.getFirstNativeHeader(SimpMessageHeaderAccessor.ORIGINAL_DESTINATION);
if (origDestination != null) {
@@ -320,19 +295,16 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
publishEvent(new SessionConnectedEvent(this, (Message<byte[]>) message));
}
}
try {
byte[] bytes = this.stompEncoder.encode(stompAccessor.getMessageHeaders(), (byte[]) message.getPayload());
TextMessage textMessage = new TextMessage(bytes);
session.sendMessage(textMessage);
session.sendMessage(new TextMessage(bytes));
}
catch (SessionLimitExceededException ex) {
// Bad session, just get out
throw ex;
}
catch (Throwable ex) {
logger.error("Failed to send WebSocket message to client, sessionId=" + session.getId(), ex);
logger.error("Failed to send WebSocket message to client in session " + session.getId() + ".", ex);
command = StompCommand.ERROR;
}
finally {
@@ -347,58 +319,93 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
}
}
private StompHeaderAccessor getStompHeaderAccessor(Message<?> message) {
MessageHeaderAccessor accessor = MessageHeaderAccessor.getAccessor(message, MessageHeaderAccessor.class);
if (accessor == null) {
// Shouldn't happen (only broker broadcasts directly to clients)
throw new IllegalStateException("No header accessor in " + message + ".");
}
StompHeaderAccessor stompAccessor;
if (accessor instanceof StompHeaderAccessor) {
stompAccessor = (StompHeaderAccessor) accessor;
}
else if (accessor instanceof SimpMessageHeaderAccessor) {
stompAccessor = StompHeaderAccessor.wrap(message);
if (SimpMessageType.CONNECT_ACK.equals(stompAccessor.getMessageType())) {
stompAccessor = convertConnectAcktoStompConnected(stompAccessor);
}
else if (stompAccessor.getCommand() == null || StompCommand.SEND.equals(stompAccessor.getCommand())) {
stompAccessor.updateStompCommandAsServerMessage();
}
}
else {
// Shouldn't happen (only broker broadcasts directly to clients)
throw new IllegalStateException(
"Unexpected header accessor type: " + accessor.getClass() + " in " + message + ".");
}
return stompAccessor;
}
/**
* The simple broker produces {@code SimpMessageType.CONNECT_ACK} that's not STOMP
* specific and needs to be turned into a STOMP CONNECTED frame.
*/
private StompHeaderAccessor convertConnectAcktoStompConnected(StompHeaderAccessor connectAckHeaders) {
String name = StompHeaderAccessor.CONNECT_MESSAGE_HEADER;
Message<?> message = (Message<?>) connectAckHeaders.getHeader(name);
Assert.notNull(message, "Original STOMP CONNECT not found in " + connectAckHeaders);
StompHeaderAccessor connectHeaders = MessageHeaderAccessor.getAccessor(message, StompHeaderAccessor.class);
String version;
Set<String> acceptVersions = connectHeaders.getAcceptVersion();
if (acceptVersions.contains("1.2")) {
version = "1.2";
}
else if (acceptVersions.contains("1.1")) {
version = "1.1";
}
else if (acceptVersions.isEmpty()) {
version = null;
}
else {
throw new IllegalArgumentException("Unsupported STOMP version '" + acceptVersions + "'");
}
StompHeaderAccessor connectedHeaders = StompHeaderAccessor.create(StompCommand.CONNECTED);
connectedHeaders.setVersion(version);
connectedHeaders.setHeartbeat(0, 0); // not supported
return connectedHeaders;
}
protected StompHeaderAccessor toMutableAccessor(StompHeaderAccessor headerAccessor, Message<?> message) {
return (headerAccessor.isMutable() ? headerAccessor : StompHeaderAccessor.wrap(message));
}
private String getVersion(StompHeaderAccessor connectAckHeaders) {
String name = StompHeaderAccessor.CONNECT_MESSAGE_HEADER;
Message<?> connectMessage = (Message<?>) connectAckHeaders.getHeader(name);
Assert.notNull(connectMessage, "CONNECT_ACK does not contain original CONNECT " + connectAckHeaders);
StompHeaderAccessor connectHeaders =
MessageHeaderAccessor.getAccessor(connectMessage, StompHeaderAccessor.class);
Set<String> acceptVersions = connectHeaders.getAcceptVersion();
if (acceptVersions.contains("1.2")) {
return "1.2";
}
else if (acceptVersions.contains("1.1")) {
return "1.1";
}
else if (acceptVersions.isEmpty()) {
return null;
}
else {
throw new StompConversionException("Unsupported version '" + acceptVersions + "'");
}
}
private StompHeaderAccessor afterStompSessionConnected(
Message<?> message, StompHeaderAccessor headerAccessor, WebSocketSession session) {
private StompHeaderAccessor afterStompSessionConnected(Message<?> message, StompHeaderAccessor accessor,
WebSocketSession session) {
Principal principal = session.getPrincipal();
if (principal != null) {
headerAccessor = toMutableAccessor(headerAccessor, message);
headerAccessor.setNativeHeader(CONNECTED_USER_HEADER, principal.getName());
accessor = toMutableAccessor(accessor, message);
accessor.setNativeHeader(CONNECTED_USER_HEADER, principal.getName());
if (this.userSessionRegistry != null) {
String userName = resolveNameForUserSessionRegistry(principal);
String userName = getSessionRegistryUserName(principal);
this.userSessionRegistry.registerSessionId(userName, session.getId());
}
}
long[] heartbeat = headerAccessor.getHeartbeat();
long[] heartbeat = accessor.getHeartbeat();
if (heartbeat[1] > 0) {
session = WebSocketSessionDecorator.unwrap(session);
if (session instanceof SockJsSession) {
logger.debug("STOMP heartbeats negotiated, disabling SockJS heartbeats.");
if (logger.isDebugEnabled()) {
logger.debug("STOMP heartbeats enabled. " +
"Turning off SockJS heartbeats in " + session.getId() + ".");
}
((SockJsSession) session).disableHeartbeat();
}
}
return headerAccessor;
return accessor;
}
private String resolveNameForUserSessionRegistry(Principal principal) {
private String getSessionRegistryUserName(Principal principal) {
String userName = principal.getName();
if (principal instanceof DestinationUserNameProvider) {
userName = ((DestinationUserNameProvider) principal).getDestinationUserName();
@@ -421,25 +428,18 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE
@Override
public void afterSessionEnded(WebSocketSession session, CloseStatus closeStatus, MessageChannel outputChannel) {
this.decoders.remove(session.getId());
Principal principal = session.getPrincipal();
if ((this.userSessionRegistry != null) && (principal != null)) {
String userName = resolveNameForUserSessionRegistry(principal);
if (principal != null && this.userSessionRegistry != null) {
String userName = getSessionRegistryUserName(principal);
this.userSessionRegistry.unregisterSessionId(userName, session.getId());
}
if (this.eventPublisher != null) {
publishEvent(new SessionDisconnectEvent(this, session.getId(), closeStatus));
}
Message<?> message = createDisconnectMessage(session);
SimpAttributes simpAttributes = SimpAttributes.fromMessage(message);
try {
if (logger.isDebugEnabled()) {
logger.debug("WebSocket session ended, sending DISCONNECT message to broker");
}
SimpAttributesContextHolder.setAttributes(simpAttributes);
outputChannel.send(message);
}

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

@@ -19,10 +19,8 @@ package org.springframework.web.socket.messaging;
import java.io.IOException;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.HashSet;
import java.util.List;
import java.util.Map;
import java.util.Set;
import java.util.TreeMap;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.locks.ReentrantLock;
@@ -82,9 +80,11 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
private final SubscribableChannel clientOutboundChannel;
private final Map<String, SubProtocolHandler> protocolHandlers =
private final Map<String, SubProtocolHandler> protocolHandlerLookup =
new TreeMap<String, SubProtocolHandler>(String.CASE_INSENSITIVE_ORDER);
private final List<SubProtocolHandler> protocolHandlers = new ArrayList<SubProtocolHandler>();
private SubProtocolHandler defaultProtocolHandler;
private final Map<String, WebSocketSessionHolder> sessions = new ConcurrentHashMap<String, WebSocketSessionHolder>();
@@ -116,6 +116,7 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
* @param protocolHandlers the sub-protocol handlers to use
*/
public void setProtocolHandlers(List<SubProtocolHandler> protocolHandlers) {
this.protocolHandlerLookup.clear();
this.protocolHandlers.clear();
for (SubProtocolHandler handler: protocolHandlers) {
addProtocolHandler(handler);
@@ -123,7 +124,7 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
}
public List<SubProtocolHandler> getProtocolHandlers() {
return new ArrayList<SubProtocolHandler>(protocolHandlers.values());
return new ArrayList<SubProtocolHandler>(this.protocolHandlerLookup.values());
}
@@ -131,27 +132,26 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
* Register a sub-protocol handler.
*/
public void addProtocolHandler(SubProtocolHandler handler) {
List<String> protocols = handler.getSupportedProtocols();
if (CollectionUtils.isEmpty(protocols)) {
logger.warn("No sub-protocols, ignoring handler " + handler);
logger.error("No sub-protocols for " + handler + ".");
return;
}
for (String protocol: protocols) {
SubProtocolHandler replaced = this.protocolHandlers.put(protocol, handler);
SubProtocolHandler replaced = this.protocolHandlerLookup.put(protocol, handler);
if ((replaced != null) && (replaced != handler) ) {
throw new IllegalStateException("Failed to map handler " + handler
+ " to protocol '" + protocol + "', it is already mapped to handler " + replaced);
throw new IllegalStateException("Can't map " + handler +
" to protocol '" + protocol + "'. Already mapped to " + replaced + ".");
}
}
this.protocolHandlers.add(handler);
}
/**
* Return the sub-protocols keyed by protocol name.
*/
public Map<String, SubProtocolHandler> getProtocolHandlerMap() {
return this.protocolHandlers;
return this.protocolHandlerLookup;
}
/**
@@ -161,7 +161,7 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
*/
public void setDefaultProtocolHandler(SubProtocolHandler defaultProtocolHandler) {
this.defaultProtocolHandler = defaultProtocolHandler;
if (this.protocolHandlers.isEmpty()) {
if (this.protocolHandlerLookup.isEmpty()) {
setProtocolHandlers(Arrays.asList(defaultProtocolHandler));
}
}
@@ -177,7 +177,7 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
* Return all supported protocols.
*/
public List<String> getSubProtocols() {
return new ArrayList<String>(this.protocolHandlers.keySet());
return new ArrayList<String>(this.protocolHandlerLookup.keySet());
}
@@ -216,6 +216,7 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
@Override
public final void start() {
Assert.isTrue(this.defaultProtocolHandler != null || !this.protocolHandlers.isEmpty(), "No handlers");
synchronized (this.lifecycleMonitor) {
this.clientOutboundChannel.subscribe(this);
this.running = true;
@@ -225,11 +226,8 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
@Override
public final void stop() {
synchronized (this.lifecycleMonitor) {
this.running = false;
this.clientOutboundChannel.unsubscribe(this);
// Notify sessions to stop flushing messages
for (WebSocketSessionHolder holder : this.sessions.values()) {
try {
holder.getSession().close(CloseStatus.GOING_AWAY);
@@ -254,45 +252,44 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
session = new ConcurrentWebSocketSessionDecorator(session, getSendTimeLimit(), getSendBufferSizeLimit());
this.sessions.put(session.getId(), new WebSocketSessionHolder(session));
if (logger.isDebugEnabled()) {
logger.debug("Started session " + session.getId() + ", number of sessions=" + this.sessions.size());
logger.debug("Started session " + session.getId() + " (" + this.sessions.size() + " sessions)");
}
findProtocolHandler(session).afterSessionStarted(session, this.clientInboundChannel);
}
protected final SubProtocolHandler findProtocolHandler(WebSocketSession session) {
String protocol = null;
try {
protocol = session.getAcceptedProtocol();
}
catch (Exception ex) {
logger.warn("Ignoring protocol in WebSocket session after failure to obtain it: " + ex.toString());
// Shouldn't happen
logger.error("Failed to obtain session.getAcceptedProtocol(). Will use the " +
"default protocol handler (if configured).", ex);
}
SubProtocolHandler handler;
if (!StringUtils.isEmpty(protocol)) {
handler = this.protocolHandlers.get(protocol);
Assert.state(handler != null,
"No handler for sub-protocol '" + protocol + "', handlers=" + this.protocolHandlers);
handler = this.protocolHandlerLookup.get(protocol);
Assert.state(handler != null, "No handler for '" + protocol + "' among " + this.protocolHandlerLookup);
}
else {
if (this.defaultProtocolHandler != null) {
handler = this.defaultProtocolHandler;
}
else if (this.protocolHandlers.size() == 1) {
handler = this.protocolHandlers.get(0);
}
else {
Set<SubProtocolHandler> handlers = new HashSet<SubProtocolHandler>(this.protocolHandlers.values());
if (handlers.size() == 1) {
handler = handlers.iterator().next();
}
else {
throw new IllegalStateException(
"No sub-protocol was requested and a default sub-protocol handler was not configured");
}
throw new IllegalStateException("Multiple protocol handlers configured and " +
"no protocol was negotiated. Consider configuring a default SubProtocolHandler.");
}
}
return handler;
}
/**
* Handle an inbound message from a WebSocket client.
*/
@Override
public void handleMessage(WebSocketSession session, WebSocketMessage<?> message) throws Exception {
SubProtocolHandler protocolHandler = findProtocolHandler(session);
@@ -308,16 +305,19 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
checkSessions();
}
/**
* Handle an outbound Spring Message to a WebSocket client.
*/
@Override
public void handleMessage(Message<?> message) throws MessagingException {
String sessionId = resolveSessionId(message);
if (sessionId == null) {
logger.error("sessionId not found in message " + message);
logger.error("Couldn't find sessionId in " + message);
return;
}
WebSocketSessionHolder holder = this.sessions.get(sessionId);
if (holder == null) {
logger.error("Session not found for session with id '" + sessionId + "', ignoring message " + message);
logger.error("No session for " + message);
return;
}
WebSocketSession session = holder.getSession();
@@ -327,22 +327,20 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
catch (SessionLimitExceededException ex) {
try {
logger.error("Terminating '" + session + "'", ex);
// Session may be unresponsive so clear first
clearSession(session, ex.getStatus());
clearSession(session, ex.getStatus()); // clear first, session may be unresponsive
session.close(ex.getStatus());
}
catch (Exception secondException) {
logger.error("Exception terminating '" + sessionId + "'", secondException);
logger.error("Failure while closing session " + sessionId + ".", secondException);
}
}
catch (Exception e) {
logger.error("Failed to send message to client " + message + " in " + session, e);
logger.error("Failed to send message to client in " + session + ": " + message, e);
}
}
private String resolveSessionId(Message<?> message) {
for (SubProtocolHandler handler : this.protocolHandlers.values()) {
for (SubProtocolHandler handler : this.protocolHandlerLookup.values()) {
String sessionId = handler.resolveSessionId(message);
if (sessionId != null) {
return sessionId;
@@ -366,8 +364,8 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
if (!isRunning() && currentTime - this.lastSessionCheckTime < TIME_TO_FIRST_MESSAGE) {
return;
}
try {
if (this.sessionCheckLock.tryLock()) {
if (this.sessionCheckLock.tryLock()) {
try {
for (WebSocketSessionHolder holder : this.sessions.values()) {
if (holder.hasHandledMessages()) {
continue;
@@ -378,19 +376,19 @@ 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 + ".");
}
try {
session.close(CloseStatus.PROTOCOL_ERROR);
}
catch (Throwable t) {
logger.error("Failed to close " + session, t);
logger.error("Failure while closing " + session, t);
}
}
}
}
finally {
this.sessionCheckLock.unlock();
finally {
this.sessionCheckLock.unlock();
}
}
}
@@ -404,6 +402,9 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler,
}
private void clearSession(WebSocketSession session, CloseStatus closeStatus) throws Exception {
if (logger.isDebugEnabled()) {
logger.debug("Clearing session " + session.getId() + " (" + this.sessions.size() + " remain)");
}
this.sessions.remove(session.getId());
findProtocolHandler(session).afterSessionEnded(session, closeStatus, this.clientInboundChannel);
}

4
spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractClientSockJsSession.java
View File

@@ -241,8 +241,8 @@ public abstract class AbstractClientSockJsSession implements WebSocketSession {
private void handleMessageFrame(SockJsFrame frame) {
if (!isOpen()) {
if (logger.isWarnEnabled()) {
logger.warn("Ignoring received message due to state=" + this.state + " in " + this);
if (logger.isErrorEnabled()) {
logger.error("Ignoring received message due to state=" + this.state + " in " + this);
}
return;
}

26
spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/AbstractSockJsService.java
View File

@@ -266,23 +266,23 @@ public abstract class AbstractSockJsService implements SockJsService {
String sockJsPath, WebSocketHandler wsHandler) throws SockJsException {
if (sockJsPath == null) {
if (logger.isWarnEnabled()) {
logger.warn("No SockJS path provided, URI=\"" + request.getURI());
if (logger.isErrorEnabled()) {
logger.error("Expected SockJS path. Failing request: " + request.getURI());
}
response.setStatusCode(HttpStatus.NOT_FOUND);
return;
}
if (logger.isDebugEnabled()) {
logger.debug(request.getMethod() + " with SockJS path [" + sockJsPath + "]");
if (logger.isTraceEnabled()) {
logger.trace(request.getMethod() + " with SockJS path [" + sockJsPath + "]");
}
try {
request.getHeaders();
}
catch (InvalidMediaTypeException ex) {
if (logger.isWarnEnabled()) {
logger.warn("Invalid media type ignored: " + ex.getMediaType());
if (logger.isDebugEnabled()) {
logger.debug("Invalid media type ignored: " + ex.getMediaType());
}
}
@@ -305,8 +305,8 @@ public abstract class AbstractSockJsService implements SockJsService {
else {
String[] pathSegments = StringUtils.tokenizeToStringArray(sockJsPath.substring(1), "/");
if (pathSegments.length != 3) {
if (logger.isWarnEnabled()) {
logger.warn("Expected \"/{server}/{session}/{transport}\" but got \"" + sockJsPath + "\"");
if (logger.isErrorEnabled()) {
logger.error("Expected \"/{server}/{session}/{transport}\" but got \"" + sockJsPath + "\"");
}
response.setStatusCode(HttpStatus.NOT_FOUND);
return;
@@ -330,18 +330,18 @@ public abstract class AbstractSockJsService implements SockJsService {
protected boolean validateRequest(String serverId, String sessionId, String transport) {
if (!StringUtils.hasText(serverId) || !StringUtils.hasText(sessionId) || !StringUtils.hasText(transport)) {
logger.warn("Empty server, session, or transport value");
logger.error("Empty server, session, or transport value");
return false;
}
// Server and session id's must not contain "."
if (serverId.contains(".") || sessionId.contains(".")) {
logger.warn("Server or session contain a \".\"");
logger.error("Server or session contain a \".\"");
return false;
}
if (!isWebSocketEnabled() && transport.equals("websocket")) {
logger.warn("Websocket transport is disabled");
logger.debug("Ignoring WebSocket request (transport disabled via SockJsService property).");
return false;
}
@@ -370,7 +370,7 @@ public abstract class AbstractSockJsService implements SockJsService {
try {
// Perhaps a CORS Filter has already added this?
if (!CollectionUtils.isEmpty(responseHeaders.get("Access-Control-Allow-Origin"))) {
logger.debug("Skip adding CORS headers, response already contains \"Access-Control-Allow-Origin\"");
logger.trace("Skip adding CORS headers, response already contains \"Access-Control-Allow-Origin\"");
return;
}
}
@@ -407,7 +407,7 @@ public abstract class AbstractSockJsService implements SockJsService {
}
protected void sendMethodNotAllowed(ServerHttpResponse response, HttpMethod... httpMethods) {
logger.debug("Sending Method Not Allowed (405)");
logger.error("Sending Method Not Allowed (405)");
response.setStatusCode(HttpStatus.METHOD_NOT_ALLOWED);
response.getHeaders().setAllow(new HashSet<HttpMethod>(Arrays.asList(httpMethods)));
}

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

@@ -156,7 +156,7 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem
TransportHandler transportHandler = this.handlers.get(TransportType.WEBSOCKET);
if (!(transportHandler instanceof HandshakeHandler)) {
logger.warn("No handler for raw WebSocket messages");
logger.error("No handler configured for raw WebSocket messages");
response.setStatusCode(HttpStatus.NOT_FOUND);
return;
}
@@ -192,8 +192,8 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem
TransportType transportType = TransportType.fromValue(transport);
if (transportType == null) {
if (logger.isDebugEnabled()) {
logger.debug("Unknown transport type: " + transportType);
if (logger.isErrorEnabled()) {
logger.error("Unknown transport type: " + transportType);
}
response.setStatusCode(HttpStatus.NOT_FOUND);
return;
@@ -201,7 +201,7 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem
TransportHandler transportHandler = this.handlers.get(transportType);
if (transportHandler == null) {
logger.debug("Transport handler not found");
logger.error("Transport handler not found");
response.setStatusCode(HttpStatus.NOT_FOUND);
return;
}
@@ -238,7 +238,9 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem
}
else {
response.setStatusCode(HttpStatus.NOT_FOUND);
logger.warn("Session not found, sessionId=" + sessionId);
if (logger.isDebugEnabled()) {
logger.debug("Session not found, sessionId=" + sessionId);
}
return;
}
}
@@ -281,7 +283,7 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem
}
if (logger.isDebugEnabled()) {
logger.debug("Creating new session with session id \"" + sessionId + "\"");
logger.debug("Creating new SockJS session, sessionId=" + sessionId);
}
session = sessionFactory.createSession(sessionId, handler, attributes);
this.sessions.put(sessionId, session);

14
spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpSendingTransportHandler.java
View File

@@ -62,11 +62,13 @@ public abstract class AbstractHttpSendingTransportHandler extends AbstractTransp
AbstractHttpSockJsSession sockJsSession) throws SockJsException {
if (sockJsSession.isNew()) {
logger.debug("Opening " + getTransportType() + " connection");
if (logger.isDebugEnabled()) {
logger.debug("Opening " + getTransportType() + " connection.");
}
sockJsSession.handleInitialRequest(request, response, getFrameFormat(request));
}
else if (sockJsSession.isClosed()) {
logger.debug("Connection already closed (but not removed yet)");
logger.debug("Connection already closed (but not removed yet).");
SockJsFrame frame = SockJsFrame.closeFrameGoAway();
try {
response.getBody().write(frame.getContentBytes());
@@ -77,11 +79,15 @@ public abstract class AbstractHttpSendingTransportHandler extends AbstractTransp
return;
}
else if (!sockJsSession.isActive()) {
logger.debug("starting " + getTransportType() + " async request");
if (logger.isTraceEnabled()) {
logger.trace("Starting " + getTransportType() + " async request.");
}
sockJsSession.handleSuccessiveRequest(request, response, getFrameFormat(request));
}
else {
logger.debug("another " + getTransportType() + " connection still open: " + sockJsSession);
if (logger.isDebugEnabled()) {
logger.debug("Another " + getTransportType() + " connection still open: " + sockJsSession);
}
String formattedFrame = getFrameFormat(request).format(SockJsFrame.closeFrameAnotherConnectionOpen());
try {
response.getBody().write(formattedFrame.getBytes(SockJsFrame.CHARSET));

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

@@ -322,7 +322,6 @@ public abstract class AbstractHttpSockJsSession extends AbstractSockJsSession {
if (control != null && !control.isCompleted()) {
if (control.isStarted()) {
try {
logger.debug("Completing asynchronous request");
control.complete();
}
catch (Throwable ex) {

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

@@ -65,7 +65,7 @@ public abstract class AbstractSockJsSession implements SockJsSession {
*
* <p>We make a best effort to identify such network failures, on a per-server
* basis, and log them under a separate log category. A simple one-line message
* is logged at DEBUG level, while a full stack trace is shown at TRACE level.
* is logged at INFO level, while a full stack trace is shown at TRACE level.
*
* @see #disconnectedClientLogger
*/
@@ -225,16 +225,10 @@ public abstract class AbstractSockJsSession implements SockJsSession {
}
/**
* Invoked in reaction to the underlying connection being closed by the remote side
* (or the WebSocket container) in order to perform cleanup and notify the
* {@link WebSocketHandler}. This is in contrast to {@link #close()} that pro-actively
* closes the connection.
* Invoked when the underlying connection is closed.
*/
public final void delegateConnectionClosed(CloseStatus status) throws Exception {
if (!isClosed()) {
if (logger.isDebugEnabled()) {
logger.debug(this + " was closed, " + status);
}
try {
updateLastActiveTime();
cancelHeartbeat();
@@ -260,8 +254,7 @@ public abstract class AbstractSockJsSession implements SockJsSession {
/**
* {@inheritDoc}
*
* <p>Performs cleanup and notifies the {@link WebSocketHandler}.
* <p>Perform cleanup and notify the {@link WebSocketHandler}.
*/
@Override
public final void close() throws IOException {
@@ -270,22 +263,21 @@ public abstract class AbstractSockJsSession implements SockJsSession {
/**
* {@inheritDoc}
* <p>Performs cleanup and notifies the {@link WebSocketHandler}.
* <p>Perform cleanup and notify the {@link WebSocketHandler}.
*/
@Override
public final void close(CloseStatus status) throws IOException {
if (isOpen()) {
if (logger.isDebugEnabled()) {
logger.debug("Closing " + this + ", " + status);
if (logger.isInfoEnabled()) {
logger.info("Closing SockJS session " + getId() + " with " + status);
}
try {
if (isActive() && !CloseStatus.SESSION_NOT_RELIABLE.equals(status)) {
try {
// bypass writeFrame
writeFrameInternal(SockJsFrame.closeFrame(status.getCode(), status.getReason()));
}
catch (Throwable ex) {
logger.warn("Failed to send SockJS close frame: " + ex.getMessage());
logger.debug("Failure while send SockJS close frame", ex);
}
}
updateLastActiveTime();
@@ -298,7 +290,7 @@ public abstract class AbstractSockJsSession implements SockJsSession {
this.handler.afterConnectionClosed(this, status);
}
catch (Throwable ex) {
logger.error("Unhandled error for " + this, ex);
logger.error("Error from WebSocketHandler.afterConnectionClosed in " + this, ex);
}
}
}
@@ -313,19 +305,19 @@ public abstract class AbstractSockJsSession implements SockJsSession {
/**
* Close due to error arising from SockJS transport handling.
*/
public void tryCloseWithSockJsTransportError(Throwable ex, CloseStatus closeStatus) {
public void tryCloseWithSockJsTransportError(Throwable error, CloseStatus closeStatus) {
logger.error("Closing due to transport error for " + this);
try {
delegateError(ex);
delegateError(error);
}
catch (Throwable delegateEx) {
catch (Throwable delegateException) {
// ignore
}
try {
close(closeStatus);
}
catch (Throwable closeEx) {
// ignore
catch (Throwable closeException) {
logger.error("Failure while closing " + this, closeException);
}
}
@@ -343,11 +335,17 @@ public abstract class AbstractSockJsSession implements SockJsSession {
catch (Throwable ex) {
logWriteFrameFailure(ex);
try {
// Force disconnect (so we won't try to send close frame)
disconnect(CloseStatus.SERVER_ERROR);
}
catch (Throwable disconnectFailure) {
logger.error("Failure while closing " + this, disconnectFailure);
}
try {
close(CloseStatus.SERVER_ERROR);
}
catch (Throwable ex2) {
// ignore
catch (Throwable t) {
// Nothing of consequence, already forced disconnect
}
throw new SockJsTransportFailureException("Failed to write " + frame, this.getId(), ex);
}
@@ -364,8 +362,8 @@ public abstract class AbstractSockJsSession implements SockJsSession {
if (disconnectedClientLogger.isTraceEnabled()) {
disconnectedClientLogger.trace("Looks like the client has gone away", failure);
}
else if (disconnectedClientLogger.isDebugEnabled()) {
disconnectedClientLogger.debug("Looks like the client has gone away: " +
else if (disconnectedClientLogger.isInfoEnabled()) {
disconnectedClientLogger.info("Looks like the client has gone away: " +
nestedException.getMessage() + " (For full stack trace, set the '" +
DISCONNECTED_CLIENT_LOG_CATEGORY + "' log category to TRACE level)");
}
@@ -388,7 +386,7 @@ public abstract class AbstractSockJsSession implements SockJsSession {
if (this.heartbeatDisabled) {
return;
}
Assert.state(this.config.getTaskScheduler() != null, "No TaskScheduler configured for heartbeat");
Assert.state(this.config.getTaskScheduler() != null, "Expecteded SockJS TaskScheduler.");
cancelHeartbeat();
if (!isActive()) {
return;
@@ -405,20 +403,24 @@ public abstract class AbstractSockJsSession implements SockJsSession {
}
}, time);
if (logger.isTraceEnabled()) {
logger.trace("Scheduled heartbeat after " + this.config.getHeartbeatTime() / 1000 + " seconds");
logger.trace("Scheduled heartbeat in session " + getId());
}
}
protected void cancelHeartbeat() {
try {
ScheduledFuture<?> task = this.heartbeatTask;
this.heartbeatTask = null;
ScheduledFuture<?> task = this.heartbeatTask;
this.heartbeatTask = null;
if ((task != null) && !task.isDone()) {
if (logger.isTraceEnabled()) {
logger.trace("Cancelling heartbeat");
if ((task != null) && !task.isDone()) {
if (logger.isTraceEnabled()) {
logger.trace("Cancelling heartbeat in session " + getId());
}
task.cancel(false);
}
task.cancel(false);
}
catch (Throwable ex) {
logger.error("Failure while cancelling heartbeat in session " + getId(), ex);
}
}
@@ -426,7 +428,7 @@ public abstract class AbstractSockJsSession implements SockJsSession {
@Override
public String toString() {
long currentTime = System.currentTimeMillis();
return "SockJsSession[id=" + this.id + ", state=" + this.state + ", sinceCreated=" +
return getClass().getSimpleName() + "[id=" + this.id + ", state=" + this.state + ", sinceCreated=" +
(currentTime - this.timeCreated) + ", sinceLastActive=" + (currentTime - this.timeLastActive) + "]";
}

15
spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/session/WebSocketServerSockJsSession.java
View File

@@ -24,8 +24,6 @@ import java.util.List;
import java.util.Map;
import java.util.Queue;
import java.util.concurrent.LinkedBlockingDeque;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;
import org.springframework.http.HttpHeaders;
import org.springframework.util.Assert;
@@ -54,7 +52,9 @@ public class WebSocketServerSockJsSession extends AbstractSockJsSession implemen
private final Queue<String> initSessionCache = new LinkedBlockingDeque<String>();
private final Lock initSessionLock = new ReentrantLock();
private final Object initSessionLock = new Object();
private volatile boolean disconnected;
public WebSocketServerSockJsSession(String id, SockJsServiceConfig config,
@@ -174,7 +174,7 @@ public class WebSocketServerSockJsSession extends AbstractSockJsSession implemen
@Override
public boolean isActive() {
return ((this.webSocketSession != null) && this.webSocketSession.isOpen());
return (this.webSocketSession != null && this.webSocketSession.isOpen() && !this.disconnected);
}
public void handleMessage(TextMessage message, WebSocketSession wsSession) throws Exception {
@@ -225,8 +225,11 @@ public class WebSocketServerSockJsSession extends AbstractSockJsSession implemen
@Override
protected void disconnect(CloseStatus status) throws IOException {
if (isActive()) {
this.webSocketSession.close(status);
synchronized (this) {
if (isActive()) {
this.disconnected = true;
this.webSocketSession.close(status);
}
}
}

2
spring-websocket/src/test/java/org/springframework/web/socket/messaging/SubProtocolWebSocketHandlerTests.java
View File

@@ -116,7 +116,7 @@ public class SubProtocolWebSocketHandlerTests {
@Test
public void emptySubProtocol() throws Exception {
this.session.setAcceptedProtocol("");
this.webSocketHandler.setDefaultProtocolHandler(defaultHandler);
this.webSocketHandler.setDefaultProtocolHandler(this.defaultHandler);
this.webSocketHandler.afterConnectionEstablished(session);
verify(this.defaultHandler).afterSessionStarted(