From 48236be4a261377ec95806933414e66a6ec5fc96 Mon Sep 17 00:00:00 2001 From: Rossen Stoyanchev Date: Wed, 9 Jul 2014 00:30:22 -0400 Subject: [PATCH] STOMP and WebSocket messaging related logging updates This change removes most logging at INFO level and also ensures the amount of information logged at DEBUG level is useful, brief, and not duplicated. Also added is custom logging for STOMP frames to ensure very readable and consise output. Issue: SPR-11934 --- .../messaging/handler/HandlerMethod.java | 7 +- .../support/HeaderMethodArgumentResolver.java | 3 - .../AbstractMethodMessageHandler.java | 44 +++---- ...andlerMethodArgumentResolverComposite.java | 6 +- ...dlerMethodReturnValueHandlerComposite.java | 8 +- .../invocation/InvocableHandlerMethod.java | 12 +- .../messaging/simp/SimpAttributes.java | 8 +- .../simp/SimpMessageHeaderAccessor.java | 48 ++++++++ .../SendToMethodReturnValueHandler.java | 3 - .../SubscriptionMethodReturnValueHandler.java | 14 ++- .../broker/AbstractBrokerMessageHandler.java | 24 ++-- .../broker/DefaultSubscriptionRegistry.java | 2 +- .../broker/SimpleBrokerMessageHandler.java | 38 +++--- .../AbstractMessageBrokerConfiguration.java | 9 +- .../stomp/StompBrokerRelayMessageHandler.java | 108 +++++++++--------- .../messaging/simp/stomp/StompCommand.java | 22 ++-- .../messaging/simp/stomp/StompDecoder.java | 12 +- .../messaging/simp/stomp/StompEncoder.java | 2 - .../simp/stomp/StompHeaderAccessor.java | 70 +++++++++++- .../user/DefaultUserDestinationResolver.java | 4 + .../user/UserDestinationMessageHandler.java | 13 ++- .../support/AbstractMessageChannel.java | 5 +- .../support/AbstractSubscribableChannel.java | 4 +- .../support/ChannelInterceptorChain.java | 23 +--- .../messaging/support/GenericMessage.java | 3 +- .../support/MessageHeaderAccessor.java | 86 ++++++++++++++ .../SimpAttributesContextHolderTests.java | 14 ++- .../simp/SimpMessageHeaderAccessorTests.java | 66 +++++++++++ .../SimpleBrokerMessageHandlerTests.java | 13 +-- .../MessageBrokerConfigurationTests.java | 8 +- .../simp/stomp/StompHeaderAccessorTests.java | 21 ++++ .../support/MessageHeaderAccessorTests.java | 77 +++++++++++++ .../adapter/AbstractWebSocketSession.java | 7 +- .../client/AbstractWebSocketClient.java | 2 +- .../client/ConnectionManagerSupport.java | 8 +- .../client/jetty/JettyWebSocketClient.java | 8 +- .../standard/StandardWebSocketClient.java | 8 +- .../config/WebSocketMessageBrokerStats.java | 4 +- .../handler/BeanCreatingHandlerProvider.java | 10 +- .../ConcurrentWebSocketSessionDecorator.java | 2 +- .../LoggingWebSocketHandlerDecorator.java | 12 +- .../PerConnectionWebSocketHandler.java | 7 +- .../messaging/StompSubProtocolHandler.java | 24 ++-- .../SubProtocolWebSocketHandler.java | 9 +- .../support/DefaultHandshakeHandler.java | 62 ++++------ .../support/HandshakeInterceptorChain.java | 5 +- .../HttpSessionHandshakeInterceptor.java | 13 --- .../support/WebSocketHttpRequestHandler.java | 10 +- .../client/AbstractClientSockJsSession.java | 16 +-- .../sockjs/client/AbstractXhrTransport.java | 15 +-- .../client/DefaultTransportRequest.java | 12 +- .../sockjs/client/JettyXhrTransport.java | 14 +-- .../client/RestTemplateXhrTransport.java | 14 +-- .../sockjs/client/WebSocketTransport.java | 2 +- .../sockjs/support/AbstractSockJsService.java | 43 ++++--- .../support/SockJsHttpRequestHandler.java | 4 +- .../TransportHandlingSockJsService.java | 45 +++----- ...AbstractHttpReceivingTransportHandler.java | 4 +- .../AbstractHttpSendingTransportHandler.java | 11 +- .../handler/AbstractTransportHandler.java | 3 +- .../handler/DefaultSockJsService.java | 4 +- .../session/AbstractSockJsSession.java | 13 ++- .../session/WebSocketServerSockJsSession.java | 14 +-- .../HttpSendingTransportHandlerTests.java | 4 + src/asciidoc/index.adoc | 2 +- 65 files changed, 763 insertions(+), 425 deletions(-) create mode 100644 spring-messaging/src/test/java/org/springframework/messaging/simp/SimpMessageHeaderAccessorTests.java diff --git a/spring-messaging/src/main/java/org/springframework/messaging/handler/HandlerMethod.java b/spring-messaging/src/main/java/org/springframework/messaging/handler/HandlerMethod.java index f03fb78779..76f5d795a1 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/handler/HandlerMethod.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/handler/HandlerMethod.java @@ -21,7 +21,6 @@ import java.lang.reflect.Method; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; - import org.springframework.beans.factory.BeanFactory; import org.springframework.core.BridgeMethodResolver; import org.springframework.core.MethodParameter; @@ -44,7 +43,6 @@ import org.springframework.util.ClassUtils; */ public class HandlerMethod { - /** Logger that is available to subclasses */ protected final Log logger = LogFactory.getLog(HandlerMethod.class); private final Object bean; @@ -238,6 +236,11 @@ public class HandlerMethod { return this.bean.hashCode() * 31 + this.method.hashCode(); } + public String getShortLogMessage() { + int args = method.getParameterTypes().length; + return getBeanType().getName() + "#" + this.method.getName() + "[" + args + " args]"; + } + @Override public String toString() { return this.method.toGenericString(); diff --git a/spring-messaging/src/main/java/org/springframework/messaging/handler/annotation/support/HeaderMethodArgumentResolver.java b/spring-messaging/src/main/java/org/springframework/messaging/handler/annotation/support/HeaderMethodArgumentResolver.java index ec8c21b6c1..070855e004 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/handler/annotation/support/HeaderMethodArgumentResolver.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/handler/annotation/support/HeaderMethodArgumentResolver.java @@ -80,9 +80,6 @@ public class HeaderMethodArgumentResolver extends AbstractNamedValueMethodArgume if (name.startsWith("nativeHeaders.")) { name = name.substring("nativeHeaders.".length()); - if (logger.isDebugEnabled()) { - logger.debug("Looking up native header '" + name + "'"); - } } if ((nativeHeaders == null) || !nativeHeaders.containsKey(name)) { diff --git a/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/AbstractMethodMessageHandler.java b/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/AbstractMethodMessageHandler.java index 401dbb18a8..89a3922779 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/AbstractMethodMessageHandler.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/AbstractMethodMessageHandler.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. @@ -322,26 +322,23 @@ public abstract class AbstractMethodMessageHandler @Override public void handleMessage(Message message) throws MessagingException { - String destination = getDestination(message); if (destination == null) { return; } - String lookupDestination = getLookupDestination(destination); if (lookupDestination == null) { return; } - - if (logger.isDebugEnabled()) { - logger.debug("Handling message to " + destination); - } - MessageHeaderAccessor headerAccessor = MessageHeaderAccessor.getMutableAccessor(message); headerAccessor.setHeader(DestinationPatternsMessageCondition.LOOKUP_DESTINATION_HEADER, lookupDestination); headerAccessor.setLeaveMutable(true); message = MessageBuilder.createMessage(message.getPayload(), headerAccessor.getMessageHeaders()); + if (logger.isDebugEnabled()) { + logger.debug("Searching methods to handle " + headerAccessor.getShortLogMessage(message.getPayload())); + } + handleMessageInternal(message, lookupDestination); headerAccessor.setImmutable(); } @@ -377,24 +374,20 @@ public abstract class AbstractMethodMessageHandler if (mappingsByUrl != null) { addMatchesToCollection(mappingsByUrl, message, matches); } - if (matches.isEmpty()) { // No direct hits, go through all mappings Set allMappings = this.handlerMethods.keySet(); addMatchesToCollection(allMappings, message, matches); } - if (matches.isEmpty()) { handleNoMatch(handlerMethods.keySet(), lookupDestination, message); return; } - Comparator comparator = new MatchComparator(getMappingComparator(message)); Collections.sort(matches, comparator); if (logger.isTraceEnabled()) { - logger.trace("Found " + matches.size() + " matching mapping(s) for [" + - lookupDestination + "] : " + matches); + logger.trace("Found " + matches.size() + " methods: " + matches); } Match bestMatch = matches.get(0); @@ -440,18 +433,14 @@ public abstract class AbstractMethodMessageHandler protected void handleMatch(T mapping, HandlerMethod handlerMethod, String lookupDestination, Message message) { - if (logger.isDebugEnabled()) { - logger.debug("Message matched to " + handlerMethod); + logger.debug("Invoking " + handlerMethod.getShortLogMessage()); } - handlerMethod = handlerMethod.createWithResolvedBean(); InvocableHandlerMethod invocable = new InvocableHandlerMethod(handlerMethod); invocable.setMessageMethodArgumentResolvers(this.argumentResolvers); - try { Object returnValue = invocable.invoke(message); - MethodParameter returnType = handlerMethod.getReturnType(); if (void.class.equals(returnType.getParameterType())) { return; @@ -467,26 +456,27 @@ public abstract class AbstractMethodMessageHandler } protected void processHandlerMethodException(HandlerMethod handlerMethod, Exception ex, Message message) { - + if (logger.isDebugEnabled()) { + logger.debug("Searching methods to handle " + ex.getClass().getSimpleName()); + } Class beanType = handlerMethod.getBeanType(); AbstractExceptionHandlerMethodResolver resolver = this.exceptionHandlerCache.get(beanType); if (resolver == null) { resolver = createExceptionHandlerMethodResolverFor(beanType); this.exceptionHandlerCache.put(beanType, resolver); } - Method method = resolver.resolveMethod(ex); if (method == null) { logger.error("Unhandled exception", ex); return; } - InvocableHandlerMethod invocable = new InvocableHandlerMethod(handlerMethod.getBean(), method); invocable.setMessageMethodArgumentResolvers(this.argumentResolvers); - + if (logger.isDebugEnabled()) { + logger.debug("Invoking " + invocable.getShortLogMessage()); + } try { Object returnValue = invocable.invoke(message, ex); - MethodParameter returnType = invocable.getReturnType(); if (void.class.equals(returnType.getParameterType())) { return; @@ -497,17 +487,21 @@ public abstract class AbstractMethodMessageHandler logger.error("Error while handling exception", t); return; } - } protected abstract AbstractExceptionHandlerMethodResolver createExceptionHandlerMethodResolverFor(Class beanType); protected void handleNoMatch(Set ts, String lookupDestination, Message message) { if (logger.isDebugEnabled()) { - logger.debug("No matching method found."); + logger.debug("No matching methods."); } } + @Override + public String toString() { + return getClass().getSimpleName() + "[prefixes=" + getDestinationPrefixes() + "]"; + } + /** * A thin wrapper around a matched HandlerMethod and its matched mapping for diff --git a/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodArgumentResolverComposite.java b/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodArgumentResolverComposite.java index 71cdc08367..92558e7b1d 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodArgumentResolverComposite.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodArgumentResolverComposite.java @@ -1,5 +1,5 @@ /* - * Copyright 2002-2012 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. @@ -22,8 +22,6 @@ import java.util.List; import java.util.Map; import java.util.concurrent.ConcurrentHashMap; -import org.apache.commons.logging.Log; -import org.apache.commons.logging.LogFactory; import org.springframework.core.MethodParameter; import org.springframework.messaging.Message; import org.springframework.util.Assert; @@ -38,8 +36,6 @@ import org.springframework.util.Assert; */ public class HandlerMethodArgumentResolverComposite implements HandlerMethodArgumentResolver { - protected final Log logger = LogFactory.getLog(getClass()); - private final List argumentResolvers = new LinkedList(); private final Map argumentResolverCache = diff --git a/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodReturnValueHandlerComposite.java b/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodReturnValueHandlerComposite.java index 4c8059f4de..1337d287ae 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodReturnValueHandlerComposite.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodReturnValueHandlerComposite.java @@ -27,6 +27,8 @@ import org.springframework.messaging.Message; import org.springframework.util.Assert; /** + * A HandlerMethodReturnValueHandler that wraps and delegates to others. + * * @author Rossen Stoyanchev * @since 4.0 */ @@ -79,9 +81,6 @@ public class HandlerMethodReturnValueHandlerComposite implements HandlerMethodRe private HandlerMethodReturnValueHandler getReturnValueHandler(MethodParameter returnType) { for (HandlerMethodReturnValueHandler handler : this.returnValueHandlers) { if (handler.supportsReturnType(returnType)) { - if (logger.isTraceEnabled()) { - logger.trace("Processing return value with " + handler); - } return handler; } } @@ -94,6 +93,9 @@ public class HandlerMethodReturnValueHandlerComposite implements HandlerMethodRe HandlerMethodReturnValueHandler handler = getReturnValueHandler(returnType); Assert.notNull(handler, "No handler for return value type [" + returnType.getParameterType().getName() + "]"); + if (logger.isTraceEnabled()) { + logger.trace("Processing return value with " + handler); + } handler.handleReturnValue(returnValue, returnType, message); } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/InvocableHandlerMethod.java b/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/InvocableHandlerMethod.java index c011cbcfdf..5795032b2f 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/InvocableHandlerMethod.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/InvocableHandlerMethod.java @@ -96,15 +96,11 @@ public class InvocableHandlerMethod extends HandlerMethod { public final Object invoke(Message message, Object... providedArgs) throws Exception { Object[] args = getMethodArgumentValues(message, providedArgs); if (logger.isTraceEnabled()) { - StringBuilder sb = new StringBuilder("Invoking ["); - sb.append(getBeanType().getSimpleName()).append("."); - sb.append(getMethod().getName()).append("] method with arguments "); - sb.append(Arrays.asList(args)); - logger.trace(sb.toString()); + logger.trace("Resolved arguments: " + Arrays.asList(args)); } Object returnValue = invoke(args); if (logger.isTraceEnabled()) { - logger.trace("Method [" + getMethod().getName() + "] returned [" + returnValue + "]"); + logger.trace("Returned value: " + returnValue); } return returnValue; } @@ -136,8 +132,8 @@ public class InvocableHandlerMethod extends HandlerMethod { } } if (args[i] == null) { - String msg = getArgumentResolutionErrorMessage("No suitable resolver for argument", i); - throw new IllegalStateException(msg); + String error = getArgumentResolutionErrorMessage("No suitable resolver for argument", i); + throw new IllegalStateException(error); } } return args; diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/SimpAttributes.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/SimpAttributes.java index 08d3eb774c..ef45f1e2f0 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/SimpAttributes.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/SimpAttributes.java @@ -72,9 +72,11 @@ public class SimpAttributes { MessageHeaders headers = message.getHeaders(); String sessionId = SimpMessageHeaderAccessor.getSessionId(headers); Map sessionAttributes = SimpMessageHeaderAccessor.getSessionAttributes(headers); - if (sessionId == null || sessionAttributes == null) { - throw new IllegalStateException( - "Message does not contain SiMP session id or attributes: " + message); + if (sessionId == null) { + throw new IllegalStateException("No session id in " + message); + } + if (sessionAttributes == null) { + throw new IllegalStateException("No session attributes in " + message); } return new SimpAttributes(sessionId, sessionAttributes); } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/SimpMessageHeaderAccessor.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/SimpMessageHeaderAccessor.java index d93351fdb8..8a437e9194 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/SimpMessageHeaderAccessor.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/SimpMessageHeaderAccessor.java @@ -20,11 +20,13 @@ import java.security.Principal; import java.util.List; import java.util.Map; +import org.apache.commons.logging.Log; import org.springframework.messaging.Message; import org.springframework.messaging.support.IdTimestampMessageHeaderInitializer; import org.springframework.messaging.support.MessageHeaderAccessor; import org.springframework.messaging.support.NativeMessageHeaderAccessor; import org.springframework.util.Assert; +import org.springframework.util.CollectionUtils; /** * A base class for working with message headers in simple messaging protocols that @@ -241,4 +243,50 @@ public class SimpMessageHeaderAccessor extends NativeMessageHeaderAccessor { return (Principal) headers.get(USER_HEADER); } + @Override + public String getShortLogMessage(Object payload) { + if (getMessageType() == null) { + return super.getDetailedLogMessage(payload); + } + StringBuilder sb = getBaseLogMessage(); + if (!CollectionUtils.isEmpty(getSessionAttributes())) { + sb.append(" attributes[").append(getSessionAttributes().size()).append("]"); + } + sb.append(getShortPayloadLogMessage(payload)); + return sb.toString(); + } + + @SuppressWarnings("unchecked") + @Override + public String getDetailedLogMessage(Object payload) { + if (getMessageType() == null) { + return super.getDetailedLogMessage(payload); + } + StringBuilder sb = getBaseLogMessage(); + if (!CollectionUtils.isEmpty(getSessionAttributes())) { + sb.append(" attributes=").append(getSessionAttributes()); + } + if (!CollectionUtils.isEmpty((Map>) getHeader(NATIVE_HEADERS))) { + sb.append(" nativeHeaders=").append((Map>) getHeader(NATIVE_HEADERS)); + } + sb.append(getDetailedPayloadLogMessage(payload)); + return sb.toString(); + } + + private StringBuilder getBaseLogMessage() { + StringBuilder sb = new StringBuilder(); + sb.append(getMessageType().name()); + if (getDestination() != null) { + sb.append(" destination=").append(getDestination()); + } + if (getSubscriptionId() != null) { + sb.append(" subscriptionId=").append(getSubscriptionId()); + } + sb.append(" session=").append(getSessionId()); + if (getUser() != null) { + sb.append(" user=").append(getUser().getName()); + } + return sb; + } + } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SendToMethodReturnValueHandler.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SendToMethodReturnValueHandler.java index 510a66ba16..52df84b56d 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SendToMethodReturnValueHandler.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SendToMethodReturnValueHandler.java @@ -137,7 +137,6 @@ public class SendToMethodReturnValueHandler implements HandlerMethodReturnValueH if (returnValue == null) { return; } - MessageHeaders headers = message.getHeaders(); String sessionId = SimpMessageHeaderAccessor.getSessionId(headers); @@ -161,7 +160,6 @@ public class SendToMethodReturnValueHandler implements HandlerMethodReturnValueH this.messagingTemplate.convertAndSendToUser(user, destination, returnValue, createHeaders(sessionId)); } } - return; } else { SendTo sendTo = returnType.getMethodAnnotation(SendTo.class); @@ -182,7 +180,6 @@ public class SendToMethodReturnValueHandler implements HandlerMethodReturnValueH } protected String[] getTargetDestinations(Annotation annotation, Message message, String defaultPrefix) { - if (annotation != null) { String[] value = (String[]) AnnotationUtils.getValue(annotation); if (!ObjectUtils.isEmpty(value)) { diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SubscriptionMethodReturnValueHandler.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SubscriptionMethodReturnValueHandler.java index 693e16f7af..6f68679539 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SubscriptionMethodReturnValueHandler.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SubscriptionMethodReturnValueHandler.java @@ -16,6 +16,8 @@ package org.springframework.messaging.simp.annotation.support; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.springframework.core.MethodParameter; import org.springframework.messaging.Message; import org.springframework.messaging.MessageHeaders; @@ -45,6 +47,9 @@ import org.springframework.util.Assert; */ public class SubscriptionMethodReturnValueHandler implements HandlerMethodReturnValueHandler { + private static Log logger = LogFactory.getLog(SubscriptionMethodReturnValueHandler.class); + + private final MessageSendingOperations messagingTemplate; private MessageHeaderInitializer headerInitializer; @@ -87,13 +92,10 @@ public class SubscriptionMethodReturnValueHandler implements HandlerMethodReturn } @Override - public void handleReturnValue(Object returnValue, MethodParameter returnType, Message message) - throws Exception { - + public void handleReturnValue(Object returnValue, MethodParameter returnType, Message message) throws Exception { if (returnValue == null) { return; } - MessageHeaders headers = message.getHeaders(); String destination = SimpMessageHeaderAccessor.getDestination(headers); String sessionId = SimpMessageHeaderAccessor.getSessionId(headers); @@ -102,6 +104,10 @@ public class SubscriptionMethodReturnValueHandler implements HandlerMethodReturn Assert.state(subscriptionId != null, "No subscriptionId in message=" + message + ", method=" + returnType.getMethod()); + if (logger.isDebugEnabled()) { + logger.debug("Reply to @SubscribeMapping: " + returnValue); + } + this.messagingTemplate.convertAndSend(destination, returnValue, createHeaders(sessionId, subscriptionId)); } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/AbstractBrokerMessageHandler.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/AbstractBrokerMessageHandler.java index b26a380209..a6e9152658 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/AbstractBrokerMessageHandler.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/AbstractBrokerMessageHandler.java @@ -130,15 +130,15 @@ public abstract class AbstractBrokerMessageHandler } @Override - public final void start() { + public void start() { synchronized (this.lifecycleMonitor) { - if (logger.isDebugEnabled()) { - logger.debug("Starting..."); + if (logger.isInfoEnabled()) { + logger.info("Starting..."); } startInternal(); this.running = true; - if (logger.isDebugEnabled()) { - logger.debug("Started."); + if (logger.isInfoEnabled()) { + logger.info("Started."); } } } @@ -147,15 +147,15 @@ public abstract class AbstractBrokerMessageHandler } @Override - public final void stop() { + public void stop() { synchronized (this.lifecycleMonitor) { - if (logger.isDebugEnabled()) { - logger.debug("Stopping..."); + if (logger.isInfoEnabled()) { + logger.info("Stopping..."); } stopInternal(); this.running = false; if (logger.isDebugEnabled()) { - logger.debug("Stopped."); + logger.info("Stopped."); } } } @@ -172,7 +172,7 @@ public abstract class AbstractBrokerMessageHandler } @Override - public final void handleMessage(Message message) { + public void handleMessage(Message message) { if (!this.running) { if (logger.isTraceEnabled()) { logger.trace(this + " not running yet. Ignoring " + message); @@ -200,7 +200,7 @@ public abstract class AbstractBrokerMessageHandler boolean shouldPublish = this.brokerAvailable.compareAndSet(false, true); if (this.eventPublisher != null && shouldPublish) { if (logger.isInfoEnabled()) { - logger.info("Publishing " + this.availableEvent); + logger.info(this.availableEvent); } this.eventPublisher.publishEvent(this.availableEvent); } @@ -210,7 +210,7 @@ public abstract class AbstractBrokerMessageHandler boolean shouldPublish = this.brokerAvailable.compareAndSet(true, false); if (this.eventPublisher != null && shouldPublish) { if (logger.isInfoEnabled()) { - logger.info("Publishing " + this.notAvailableEvent); + logger.info(this.notAvailableEvent); } this.eventPublisher.publishEvent(this.notAvailableEvent); } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/DefaultSubscriptionRegistry.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/DefaultSubscriptionRegistry.java index ed102fe0df..d1a95a8aeb 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/DefaultSubscriptionRegistry.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/broker/DefaultSubscriptionRegistry.java @@ -275,7 +275,7 @@ public class DefaultSubscriptionRegistry extends AbstractSubscriptionRegistry { @Override public String toString() { - return "registry[" + sessions.size() + " session(s)]"; + return "registry[" + sessions.size() + " sessions]"; } } 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 65ad766e4d..01cfca499f 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 @@ -25,6 +25,7 @@ import org.springframework.messaging.SubscribableChannel; import org.springframework.messaging.simp.SimpMessageHeaderAccessor; import org.springframework.messaging.simp.SimpMessageType; import org.springframework.messaging.support.MessageBuilder; +import org.springframework.messaging.support.MessageHeaderAccessor; import org.springframework.messaging.support.MessageHeaderInitializer; import org.springframework.util.Assert; import org.springframework.util.MultiValueMap; @@ -138,35 +139,44 @@ public class SimpleBrokerMessageHandler extends AbstractBrokerMessageHandler { return; } + SimpMessageHeaderAccessor accessor = MessageHeaderAccessor.getAccessor(message, SimpMessageHeaderAccessor.class); + if (accessor == null) { + throw new IllegalStateException( + "No header accessor (not using the SimpMessagingTemplate?): " + message); + } + if (SimpMessageType.MESSAGE.equals(messageType)) { + if (logger.isDebugEnabled()) { + logger.debug("Processing " + accessor.getShortLogMessage(message.getPayload())); + } sendMessageToSubscribers(destination, message); } else if (SimpMessageType.CONNECT.equals(messageType)) { - if (logger.isInfoEnabled()) { - logger.info("Handling CONNECT: " + message); + if (logger.isDebugEnabled()) { + logger.debug("Processing " + accessor.getShortLogMessage(EMPTY_PAYLOAD)); } - SimpMessageHeaderAccessor accessor = SimpMessageHeaderAccessor.create(SimpMessageType.CONNECT_ACK); - initHeaders(accessor); - accessor.setSessionId(sessionId); - accessor.setHeader(SimpMessageHeaderAccessor.CONNECT_MESSAGE_HEADER, message); - Message connectAck = MessageBuilder.createMessage(EMPTY_PAYLOAD, accessor.getMessageHeaders()); - this.clientOutboundChannel.send(connectAck); + SimpMessageHeaderAccessor connectAck = SimpMessageHeaderAccessor.create(SimpMessageType.CONNECT_ACK); + initHeaders(connectAck); + connectAck.setSessionId(sessionId); + connectAck.setHeader(SimpMessageHeaderAccessor.CONNECT_MESSAGE_HEADER, message); + Message messageOut = MessageBuilder.createMessage(EMPTY_PAYLOAD, connectAck.getMessageHeaders()); + this.clientOutboundChannel.send(messageOut); } else if (SimpMessageType.DISCONNECT.equals(messageType)) { - if (logger.isInfoEnabled()) { - logger.info("Handling DISCONNECT: " + message); + if (logger.isDebugEnabled()) { + logger.debug("Processing " + accessor.getShortLogMessage(EMPTY_PAYLOAD)); } this.subscriptionRegistry.unregisterAllSubscriptions(sessionId); } else if (SimpMessageType.SUBSCRIBE.equals(messageType)) { if (logger.isDebugEnabled()) { - logger.debug("Handling SUBSCRIBE: " + message); + logger.debug("Processing " + accessor.getShortLogMessage(EMPTY_PAYLOAD)); } this.subscriptionRegistry.registerSubscription(message); } else if (SimpMessageType.UNSUBSCRIBE.equals(messageType)) { if (logger.isDebugEnabled()) { - logger.debug("Handling UNSUBSCRIBE: " + message); + logger.debug("Processing " + accessor.getShortLogMessage(EMPTY_PAYLOAD)); } this.subscriptionRegistry.unregisterSubscription(message); } @@ -180,8 +190,8 @@ public class SimpleBrokerMessageHandler extends AbstractBrokerMessageHandler { protected void sendMessageToSubscribers(String destination, Message message) { MultiValueMap subscriptions = this.subscriptionRegistry.findSubscriptions(message); - if ((subscriptions.size() > 0) && logger.isTraceEnabled()) { - logger.trace("Sending to " + subscriptions.size() + " subscriber(s): " + message); + if ((subscriptions.size() > 0) && logger.isDebugEnabled()) { + logger.debug("Broadcasting to " + subscriptions.size() + " sessions."); } for (String sessionId : subscriptions.keySet()) { for (String subscriptionId : subscriptions.get(sessionId)) { diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/config/AbstractMessageBrokerConfiguration.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/config/AbstractMessageBrokerConfiguration.java index 60e798df9d..b3ba9db005 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/config/AbstractMessageBrokerConfiguration.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/config/AbstractMessageBrokerConfiguration.java @@ -357,17 +357,20 @@ public abstract class AbstractMessageBrokerConfiguration implements ApplicationC private static final AbstractBrokerMessageHandler noopBroker = new AbstractBrokerMessageHandler() { @Override - protected void startInternal() { + public void start() { } @Override - protected void stopInternal() { + public void stop() { + } + + @Override + public void handleMessage(Message message) { } @Override protected void handleMessageInternal(Message message) { } - }; } 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 a2a267284b..34ecb1ce90 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 @@ -72,6 +72,8 @@ import org.springframework.util.concurrent.ListenableFutureTask; */ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler { + public static final String SYSTEM_SESSION_ID = "_system_"; + private static final byte[] EMPTY_PAYLOAD = new byte[0]; private static final ListenableFutureTask EMPTY_TASK = new ListenableFutureTask(new VoidCallable()); @@ -380,14 +382,18 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler logger.info("Connecting \"system\" session to " + this.relayHost + ":" + this.relayPort); } - StompHeaderAccessor headers = StompHeaderAccessor.create(StompCommand.CONNECT); - headers.setAcceptVersion("1.1,1.2"); - headers.setLogin(this.systemLogin); - headers.setPasscode(this.systemPasscode); - headers.setHeartbeat(this.systemHeartbeatSendInterval, this.systemHeartbeatReceiveInterval); - headers.setHost(getVirtualHost()); + StompHeaderAccessor accessor = StompHeaderAccessor.create(StompCommand.CONNECT); + accessor.setAcceptVersion("1.1,1.2"); + accessor.setLogin(this.systemLogin); + accessor.setPasscode(this.systemPasscode); + accessor.setHeartbeat(this.systemHeartbeatSendInterval, this.systemHeartbeatReceiveInterval); + accessor.setHost(getVirtualHost()); + accessor.setSessionId(SYSTEM_SESSION_ID); + if (logger.isDebugEnabled()) { + logger.debug("Forwarding " + accessor.getShortLogMessage(EMPTY_PAYLOAD)); + } - SystemStompConnectionHandler handler = new SystemStompConnectionHandler(headers); + SystemStompConnectionHandler handler = new SystemStompConnectionHandler(accessor); this.connectionHandlers.put(handler.getSessionId(), handler); this.stats.incrementConnectCount(); @@ -416,7 +422,7 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler String sessionId = SimpMessageHeaderAccessor.getSessionId(message.getHeaders()); if (!isBrokerAvailable()) { - if (sessionId == null || SystemStompConnectionHandler.SESSION_ID.equals(sessionId)) { + if (sessionId == null || SYSTEM_SESSION_ID.equals(sessionId)) { throw new MessageDeliveryException("Message broker not active. Consider subscribing to " + "receive BrokerAvailabilityEvent's from an ApplicationListener Spring bean."); } @@ -459,7 +465,7 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler logger.error("Only STOMP SEND supported from within the server side. Ignoring " + message); return; } - sessionId = SystemStompConnectionHandler.SESSION_ID; + sessionId = SYSTEM_SESSION_ID; stompAccessor.setSessionId(sessionId); } @@ -470,7 +476,7 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler if (StompCommand.CONNECT.equals(command)) { if (logger.isDebugEnabled()) { - logger.debug("STOMP CONNECT in session " + sessionId + " (" + getConnectionCount() + " connections)."); + logger.debug(stompAccessor.getShortLogMessage(EMPTY_PAYLOAD)); } stompAccessor = (stompAccessor.isMutable() ? stompAccessor : StompHeaderAccessor.wrap(message)); stompAccessor.setLogin(this.clientLogin); @@ -508,8 +514,7 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler @Override public String toString() { - return "StompBrokerRelay[broker=" + this.relayHost + ":" + this.relayPort + - ", " + getConnectionCount() + " connection(s)]"; + return "StompBrokerRelay[" + this.relayHost + ":" + this.relayPort + "]"; } @@ -544,8 +549,8 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler @Override public void afterConnected(TcpConnection connection) { - if (logger.isInfoEnabled()) { - logger.info("TCP connection established. Forwarding: " + this.connectHeaders); + if (logger.isDebugEnabled()) { + logger.debug("TCP connection opened in session=" + getSessionId()); } this.tcpConnection = connection; connection.send(MessageBuilder.createMessage(EMPTY_PAYLOAD, this.connectHeaders.getMessageHeaders())); @@ -601,24 +606,24 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler @Override public void handleMessage(Message message) { - StompHeaderAccessor headerAccessor = MessageHeaderAccessor.getAccessor(message, StompHeaderAccessor.class); - headerAccessor.setSessionId(this.sessionId); + StompHeaderAccessor accessor = MessageHeaderAccessor.getAccessor(message, StompHeaderAccessor.class); + accessor.setSessionId(this.sessionId); - if (StompCommand.CONNECTED.equals(headerAccessor.getCommand())) { - if (logger.isInfoEnabled()) { - logger.info("Received STOMP CONNECTED: " + headerAccessor); + StompCommand command = accessor.getCommand(); + if (StompCommand.CONNECTED.equals(command)) { + if (logger.isDebugEnabled()) { + logger.debug("Received " + accessor.getShortLogMessage(EMPTY_PAYLOAD)); } - afterStompConnected(headerAccessor); + afterStompConnected(accessor); } - else if (StompCommand.ERROR.equals(headerAccessor.getCommand()) && logger.isErrorEnabled()) { - logger.error("Received STOMP ERROR: " + message); + else if (logger.isErrorEnabled() && StompCommand.ERROR.equals(command)) { + logger.error("Received " + accessor.getShortLogMessage(message.getPayload())); } else if (logger.isTraceEnabled()) { - logger.trace(headerAccessor.isHeartbeat() ? - "Received heartbeat in session " + this.sessionId : "Received " + headerAccessor); + logger.trace("Received " + accessor.getDetailedLogMessage(message.getPayload())); } - headerAccessor.setImmutable(); + accessor.setImmutable(); sendMessageToClient(message); } @@ -688,8 +693,8 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler return; } try { - if (logger.isInfoEnabled()) { - logger.info("TCP connection to broker closed in session " + this.sessionId); + if (logger.isDebugEnabled()) { + logger.debug("TCP connection to broker closed in session " + this.sessionId); } sendStompErrorFrameToClient("Connection to broker closed."); } @@ -729,14 +734,16 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler * @return a future to wait for the result */ @SuppressWarnings("unchecked") - public ListenableFuture forward(Message message, final StompHeaderAccessor accessor) { + public ListenableFuture forward(final Message message, final StompHeaderAccessor accessor) { + TcpConnection conn = this.tcpConnection; if (!this.isStompConnected) { if (this.isRemoteClientSession) { if (logger.isDebugEnabled()) { - logger.debug("TCP connection closed already, ignoring " + message); + logger.debug("TCP connection closed already, ignoring " + + accessor.getShortLogMessage((byte[]) message.getPayload())); } return EMPTY_TASK; } @@ -744,7 +751,8 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler throw new IllegalStateException("Cannot forward messages " + (conn != null ? "before STOMP CONNECTED. " : "while inactive. ") + "Consider subscribing to receive BrokerAvailabilityEvent's from " + - "an ApplicationListener Spring bean. Dropped " + message); + "an ApplicationListener Spring bean. Dropped " + + accessor.getShortLogMessage((byte[]) message.getPayload())); } } @@ -752,20 +760,15 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler MessageBuilder.createMessage(message.getPayload(), accessor.getMessageHeaders()) : message; StompCommand command = accessor.getCommand(); - if (accessor.isHeartbeat()) { - logger.trace("Forwarding heartbeat in session " + this.sessionId); - } - else if (StompCommand.SUBSCRIBE.equals(command) && logger.isDebugEnabled()) { - logger.debug("Forwarding SUBSCRIBE: " + messageToSend); - } - else if (StompCommand.UNSUBSCRIBE.equals(command) && logger.isDebugEnabled()) { - logger.debug("Forwarding UNSUBSCRIBE: " + messageToSend); - } - else if (StompCommand.DISCONNECT.equals(command) && logger.isInfoEnabled()) { - logger.info("Forwarding DISCONNECT: " + messageToSend); + if (logger.isDebugEnabled() && + StompCommand.SEND.equals(command) || + StompCommand.SUBSCRIBE.equals(command) || + StompCommand.UNSUBSCRIBE.equals(command) || + StompCommand.DISCONNECT.equals(command)) { + logger.debug("Forwarding " + accessor.getShortLogMessage((byte[]) message.getPayload())); } else if (logger.isTraceEnabled()) { - logger.trace("Forwarding " + command + ": " + messageToSend); + logger.trace("Forwarding " + accessor.getDetailedLogMessage((byte[]) message.getPayload())); } ListenableFuture future = conn.send((Message) messageToSend); @@ -779,10 +782,12 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler @Override public void onFailure(Throwable t) { if (tcpConnection != null) { - handleTcpConnectionFailure("failed to forward " + messageToSend, t); + handleTcpConnectionFailure("failed to forward " + + accessor.getShortLogMessage((byte[]) message.getPayload()), t); } else if (logger.isErrorEnabled()) { - logger.error("Failed to forward " + messageToSend); + logger.error("Failed to forward " + + accessor.getShortLogMessage((byte[]) message.getPayload())); } } }); @@ -810,8 +815,7 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler */ public void clearConnection() { if (logger.isDebugEnabled()) { - logger.debug("Cleaning up connection state for session " + sessionId + " (" + - (getConnectionCount() - 1) + " remaining connections)."); + logger.debug("Cleaning up connection state for session " + this.sessionId); } if (this.isRemoteClientSession) { @@ -823,8 +827,8 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler TcpConnection conn = this.tcpConnection; this.tcpConnection = null; if (conn != null) { - if (logger.isInfoEnabled()) { - logger.info("Closing TCP connection in session " + this.sessionId); + if (logger.isDebugEnabled()) { + logger.debug("Closing TCP connection in session " + this.sessionId); } conn.close(); } @@ -838,15 +842,15 @@ public class StompBrokerRelayMessageHandler extends AbstractBrokerMessageHandler private class SystemStompConnectionHandler extends StompConnectionHandler { - public static final String SESSION_ID = "stompRelaySystemSessionId"; - - public SystemStompConnectionHandler(StompHeaderAccessor connectHeaders) { - super(SESSION_ID, connectHeaders, false); + super(SYSTEM_SESSION_ID, connectHeaders, false); } @Override protected void afterStompConnected(StompHeaderAccessor connectedHeaders) { + if (logger.isInfoEnabled()) { + logger.info("\"System\" session connected."); + } super.afterStompConnected(connectedHeaders); publishBrokerAvailableEvent(); } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompCommand.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompCommand.java index 448d3dc152..5f4cae8cf3 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompCommand.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompCommand.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. @@ -24,6 +24,8 @@ import java.util.Map; import org.springframework.messaging.simp.SimpMessageType; /** + * Represents a STOMP command. + * * @author Rossen Stoyanchev * @since 4.0 */ @@ -32,15 +34,15 @@ public enum StompCommand { // client CONNECT, STOMP, - SEND, + DISCONNECT, SUBSCRIBE, UNSUBSCRIBE, + SEND, ACK, NACK, BEGIN, COMMIT, ABORT, - DISCONNECT, // server CONNECTED, @@ -48,13 +50,8 @@ public enum StompCommand { RECEIPT, ERROR; + private static Map messageTypes = new HashMap(); - - private static Collection destinationRequired = Arrays.asList(SEND, SUBSCRIBE, MESSAGE); - private static Collection subscriptionIdRequired = Arrays.asList(SUBSCRIBE, UNSUBSCRIBE, MESSAGE); - private static Collection contentLengthRequired = Arrays.asList(SEND, MESSAGE, ERROR); - private static Collection bodyAllowed = Arrays.asList(SEND, MESSAGE, ERROR); - static { messageTypes.put(StompCommand.CONNECT, SimpMessageType.CONNECT); messageTypes.put(StompCommand.STOMP, SimpMessageType.CONNECT); @@ -65,6 +62,13 @@ public enum StompCommand { messageTypes.put(StompCommand.DISCONNECT, SimpMessageType.DISCONNECT); } + private static Collection destinationRequired = Arrays.asList(SEND, SUBSCRIBE, MESSAGE); + private static Collection subscriptionIdRequired = Arrays.asList(SUBSCRIBE, UNSUBSCRIBE, MESSAGE); + private static Collection contentLengthRequired = Arrays.asList(SEND, MESSAGE, ERROR); + private static Collection bodyAllowed = Arrays.asList(SEND, MESSAGE, ERROR); + + + public SimpMessageType getMessageType() { SimpMessageType type = messageTypes.get(this); return (type != null) ? type : SimpMessageType.OTHER; diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompDecoder.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompDecoder.java index d9d46ba381..bddb751446 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompDecoder.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompDecoder.java @@ -24,7 +24,6 @@ import java.util.List; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; - import org.springframework.messaging.Message; import org.springframework.messaging.support.MessageBuilder; import org.springframework.messaging.support.MessageHeaderInitializer; @@ -51,7 +50,8 @@ public class StompDecoder { static final byte[] HEARTBEAT_PAYLOAD = new byte[] {'\n'}; - private final Log logger = LogFactory.getLog(StompDecoder.class); + private static final Log logger = LogFactory.getLog(StompDecoder.class); + private MessageHeaderInitializer headerInitializer; @@ -157,7 +157,7 @@ public class StompDecoder { headerAccessor.setLeaveMutable(true); decodedMessage = MessageBuilder.createMessage(payload, headerAccessor.getMessageHeaders()); if (logger.isTraceEnabled()) { - logger.trace("Decoded " + decodedMessage); + logger.trace("Decoded " + headerAccessor.getDetailedLogMessage(payload)); } } else { @@ -176,13 +176,13 @@ public class StompDecoder { } } else { - if (logger.isTraceEnabled()) { - logger.trace("Decoded heartbeat."); - } StompHeaderAccessor headerAccessor = StompHeaderAccessor.createForHeartbeat(); initHeaders(headerAccessor); headerAccessor.setLeaveMutable(true); decodedMessage = MessageBuilder.createMessage(HEARTBEAT_PAYLOAD, headerAccessor.getMessageHeaders()); + if (logger.isTraceEnabled()) { + logger.trace("Decoded " + headerAccessor.getDetailedLogMessage(null)); + } } return decodedMessage; } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompEncoder.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompEncoder.java index 3a311e3a4c..beb5dd03bd 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompEncoder.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompEncoder.java @@ -26,7 +26,6 @@ import java.util.Map.Entry; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; - import org.springframework.messaging.Message; import org.springframework.messaging.simp.SimpMessageHeaderAccessor; import org.springframework.messaging.simp.SimpMessageType; @@ -74,7 +73,6 @@ public final class StompEncoder { DataOutputStream output = new DataOutputStream(baos); if (SimpMessageType.HEARTBEAT.equals(SimpMessageHeaderAccessor.getMessageType(headers))) { - logger.trace("Encoded heartbeat"); output.write(StompDecoder.HEARTBEAT_PAYLOAD); } else { diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompHeaderAccessor.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompHeaderAccessor.java index b3af75f71a..a45731fd79 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompHeaderAccessor.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/stomp/StompHeaderAccessor.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. @@ -16,6 +16,7 @@ package org.springframework.messaging.simp.stomp; +import java.nio.charset.Charset; import java.util.Arrays; import java.util.Collections; import java.util.List; @@ -62,6 +63,7 @@ public class StompHeaderAccessor extends SimpMessageHeaderAccessor { private static final long[] DEFAULT_HEARTBEAT = new long[] {0, 0}; + // STOMP header names public static final String STOMP_ID_HEADER = "id"; @@ -438,6 +440,71 @@ public class StompHeaderAccessor extends SimpMessageHeaderAccessor { setNativeHeader(STOMP_VERSION_HEADER, version); } + // Logging related + + @Override + public String getShortLogMessage(Object payload) { + if (StompCommand.SUBSCRIBE.equals(getCommand())) { + return "SUBSCRIBE " + getDestination() + " id=" + getSubscriptionId() + appendSession(); + } + else if (StompCommand.UNSUBSCRIBE.equals(getCommand())) { + return "UNSUBSCRIBE id=" + getSubscriptionId() + appendSession(); + } + else if (StompCommand.SEND.equals(getCommand())) { + return "SEND " + getDestination() + appendSession() + appendPayload(payload); + } + else if (StompCommand.CONNECT.equals(getCommand())) { + return "CONNECT" + (getUser() != null ? " user=" + getUser().getName() : "") + appendSession(); + } + else if (StompCommand.CONNECTED.equals(getCommand())) { + return "CONNECTED heart-beat=" + Arrays.toString(getHeartbeat()) + appendSession(); + } + else if (StompCommand.DISCONNECT.equals(getCommand())) { + return "DISCONNECT" + (getReceipt() != null ? " receipt=" + getReceipt() : "") + appendSession(); + } + else { + return getDetailedLogMessage(payload); + } + } + + @Override + public String getDetailedLogMessage(Object payload) { + if (isHeartbeat()) { + return "heart-beat in session " + getSessionId(); + } + StompCommand command = getCommand(); + if (command == null) { + return super.getDetailedLogMessage(payload); + } + StringBuilder sb = new StringBuilder(); + sb.append(command.name()).append(" ").append(getNativeHeaders()).append(appendSession()); + if (getUser() != null) { + sb.append(", user=").append(getUser().getName()); + } + if (command.isBodyAllowed()) { + sb.append(appendPayload(payload)); + } + return sb.toString(); + } + + private String appendSession() { + return " session=" + getSessionId(); + } + + private String appendPayload(Object payload) { + Assert.isInstanceOf(byte[].class, payload); + byte[] bytes = (byte[]) payload; + String contentType = (getContentType() != null ? " " + getContentType().toString() : ""); + if (bytes.length == 0 || getContentType() == null || !isReadableContentType()) { + return contentType; + } + Charset charset = getContentType().getCharSet(); + charset = (charset != null ? charset : StompDecoder.UTF8_CHARSET); + return (bytes.length < 80) ? + contentType + " payload=" + new String(bytes, charset) : + contentType + " payload=" + new String(Arrays.copyOf(bytes, 80), charset) + "...(truncated)"; + } + private static class StompPasscode { @@ -452,4 +519,5 @@ public class StompHeaderAccessor extends SimpMessageHeaderAccessor { return "[PROTECTED]"; } } + } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/simp/user/DefaultUserDestinationResolver.java b/spring-messaging/src/main/java/org/springframework/messaging/simp/user/DefaultUserDestinationResolver.java index 23d99969c1..1ddef54efc 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/simp/user/DefaultUserDestinationResolver.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/simp/user/DefaultUserDestinationResolver.java @@ -181,6 +181,10 @@ public class DefaultUserDestinationResolver implements UserDestinationResolver { return sourceDestinationWithoutPrefix + "-user" + sessionId; } + @Override + public String toString() { + return "DefaultUserDestinationResolver[prefix=" + this.destinationPrefix + "]"; + } private static class DestinationInfo { 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 2c89021f16..651aad343d 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 @@ -172,7 +172,7 @@ public class UserDestinationMessageHandler implements MessageHandler, SmartLifec Set destinations = result.getTargetDestinations(); if (destinations.isEmpty()) { if (logger.isTraceEnabled()) { - logger.trace("No user destinations for " + message); + logger.trace("No user destinations found for " + result.getSourceDestination()); } return; } @@ -183,10 +183,10 @@ public class UserDestinationMessageHandler implements MessageHandler, SmartLifec headerAccessor.setNativeHeader(header, result.getSubscribeDestination()); message = MessageBuilder.createMessage(message.getPayload(), headerAccessor.getMessageHeaders()); } + if (logger.isDebugEnabled()) { + logger.debug("Translated " + result.getSourceDestination() + " -> " + destinations); + } for (String destination : destinations) { - if (logger.isTraceEnabled()) { - logger.trace("Sending " + message); - } this.brokerMessagingTemplate.send(destination, message); } } @@ -197,4 +197,9 @@ public class UserDestinationMessageHandler implements MessageHandler, SmartLifec } } + @Override + public String toString() { + return "UserDestinationMessageHandler[" + this.userDestinationResolver + "]"; + } + } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/support/AbstractMessageChannel.java b/spring-messaging/src/main/java/org/springframework/messaging/support/AbstractMessageChannel.java index 70dfb407c7..4324b5bbab 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/support/AbstractMessageChannel.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/support/AbstractMessageChannel.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. @@ -101,9 +101,6 @@ public abstract class AbstractMessageChannel implements MessageChannel, BeanName @Override public final boolean send(Message message, long timeout) { Assert.notNull(message, "Message must not be null"); - if (logger.isTraceEnabled()) { - logger.trace(this + " sending " + message); - } message = this.interceptorChain.preSend(message, this); if (message == null) { return false; diff --git a/spring-messaging/src/main/java/org/springframework/messaging/support/AbstractSubscribableChannel.java b/spring-messaging/src/main/java/org/springframework/messaging/support/AbstractSubscribableChannel.java index 82cb9e4cc6..7edf2d53fd 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/support/AbstractSubscribableChannel.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/support/AbstractSubscribableChannel.java @@ -47,7 +47,7 @@ public abstract class AbstractSubscribableChannel extends AbstractMessageChannel boolean result = this.handlers.add(handler); if (result) { if (logger.isDebugEnabled()) { - logger.debug(this + " subscribed " + handler); + logger.debug(getBeanName() + " added " + handler); } } return result; @@ -58,7 +58,7 @@ public abstract class AbstractSubscribableChannel extends AbstractMessageChannel boolean result = this.handlers.remove(handler); if (result) { if (logger.isDebugEnabled()) { - logger.debug(this + " unsubscribed " + handler); + logger.debug(getBeanName() + " removed " + handler); } } return result; diff --git a/spring-messaging/src/main/java/org/springframework/messaging/support/ChannelInterceptorChain.java b/spring-messaging/src/main/java/org/springframework/messaging/support/ChannelInterceptorChain.java index 99cd64be9c..7fd9e900cd 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/support/ChannelInterceptorChain.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/support/ChannelInterceptorChain.java @@ -56,37 +56,23 @@ class ChannelInterceptorChain { public Message preSend(Message message, MessageChannel channel) { - Message originalMessage = message; for (ChannelInterceptor interceptor : this.interceptors) { message = interceptor.preSend(message, channel); if (message == null) { - if (logger.isTraceEnabled()) { - logger.trace("preSend returned null (precluding the send)"); - } + logger.debug("preSend returned null precluding send"); return null; } } - if (logger.isDebugEnabled()) { - if (message != originalMessage) { - logger.debug("preSend returned modified message, new message=" + message); - } - } return message; } public void postSend(Message message, MessageChannel channel, boolean sent) { - if (logger.isTraceEnabled()) { - logger.trace("postSend (sent=" + sent + ")"); - } for (ChannelInterceptor interceptor : this.interceptors) { interceptor.postSend(message, channel, sent); } } public boolean preReceive(MessageChannel channel) { - if (logger.isTraceEnabled()) { - logger.trace("preReceive on channel '" + channel + "'"); - } for (ChannelInterceptor interceptor : this.interceptors) { if (!interceptor.preReceive(channel)) { return false; @@ -96,12 +82,6 @@ class ChannelInterceptorChain { } public Message postReceive(Message message, MessageChannel channel) { - if (message != null && logger.isTraceEnabled()) { - logger.trace("postReceive on channel '" + channel + "', message: " + message); - } - else if (logger.isTraceEnabled()) { - logger.trace("postReceive on channel '" + channel + "', message is null"); - } for (ChannelInterceptor interceptor : this.interceptors) { message = interceptor.postReceive(message, channel); if (message == null) { @@ -111,5 +91,4 @@ class ChannelInterceptorChain { return message; } - } diff --git a/spring-messaging/src/main/java/org/springframework/messaging/support/GenericMessage.java b/spring-messaging/src/main/java/org/springframework/messaging/support/GenericMessage.java index 786f65e14c..b29f509c66 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/support/GenericMessage.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/support/GenericMessage.java @@ -94,8 +94,7 @@ public class GenericMessage implements Message, Serializable { sb.append("[Payload byte[").append(((byte[]) this.payload).length).append("]]"); } else { - sb.append("[Payload ").append(this.payload.getClass().getSimpleName()); - sb.append(" content=").append(this.payload).append("]"); + sb.append("[Payload=").append(this.payload).append("]"); } sb.append("[Headers=").append(this.headers).append("]"); return sb.toString(); diff --git a/spring-messaging/src/main/java/org/springframework/messaging/support/MessageHeaderAccessor.java b/spring-messaging/src/main/java/org/springframework/messaging/support/MessageHeaderAccessor.java index 3b0b510257..fbafc560df 100644 --- a/spring-messaging/src/main/java/org/springframework/messaging/support/MessageHeaderAccessor.java +++ b/spring-messaging/src/main/java/org/springframework/messaging/support/MessageHeaderAccessor.java @@ -16,7 +16,9 @@ package org.springframework.messaging.support; +import java.nio.charset.Charset; import java.util.ArrayList; +import java.util.Arrays; import java.util.HashMap; import java.util.List; import java.util.Map; @@ -28,9 +30,11 @@ import org.apache.commons.logging.LogFactory; import org.springframework.messaging.Message; import org.springframework.messaging.MessageChannel; import org.springframework.messaging.MessageHeaders; +import org.springframework.messaging.simp.stomp.StompDecoder; import org.springframework.util.Assert; import org.springframework.util.IdGenerator; import org.springframework.util.MimeType; +import org.springframework.util.MimeTypeUtils; import org.springframework.util.ObjectUtils; import org.springframework.util.PatternMatchUtils; import org.springframework.util.StringUtils; @@ -111,6 +115,13 @@ import org.springframework.util.StringUtils; */ public class MessageHeaderAccessor { + private static final MimeType[] readableMimeTypes = new MimeType[] { + MimeTypeUtils.APPLICATION_JSON, MimeTypeUtils.APPLICATION_XML, + new MimeType("text", "*"), new MimeType("application", "*+json"), new MimeType("application", "*+xml") + }; + public static final Charset DEFAULT_CHARSET = Charset.forName("UTF-8"); + + protected Log logger = LogFactory.getLog(getClass()); private final MutableMessageHeaders headers; @@ -469,6 +480,81 @@ public class MessageHeaderAccessor { } + /** + * Return a concise message for logging purposes. + * @param payload the payload that corresponds to the headers. + * @return the message + */ + public String getShortLogMessage(Object payload) { + return "headers=" + this.headers.toString() + getShortPayloadLogMessage(payload); + } + + /** + * Return a more detailed message for logging purposes. + * @param payload the payload that corresponds to the headers. + * @return the message + */ + public String getDetailedLogMessage(Object payload) { + return "headers=" + this.headers.toString() + getDetailedPayloadLogMessage(payload); + } + + protected String getShortPayloadLogMessage(Object payload) { + if (payload instanceof String) { + String payloadText = (String) payload; + return (payloadText.length() < 80) ? + " payload=" + payloadText : + " payload=" + payloadText.substring(0, 80) + "...(truncated)"; + } + else if (payload instanceof byte[]) { + byte[] bytes = (byte[]) payload; + if (isReadableContentType()) { + Charset charset = getContentType().getCharSet(); + charset = (charset != null ? charset : DEFAULT_CHARSET); + return (bytes.length < 80) ? + " payload=" + new String(bytes, charset) : + " payload=" + new String(Arrays.copyOf(bytes, 80), charset) + "...(truncated)"; + } + else { + return " payload=byte[" + bytes.length + "]"; + } + } + else { + String payloadText = payload.toString(); + return (payloadText.length() < 80) ? + " payload=" + payloadText : + " payload=" + ObjectUtils.identityToString(payload); + } + } + + protected String getDetailedPayloadLogMessage(Object payload) { + if (payload instanceof String) { + return " payload=" + ((String) payload); + } + else if (payload instanceof byte[]) { + byte[] bytes = (byte[]) payload; + if (isReadableContentType()) { + Charset charset = getContentType().getCharSet(); + charset = (charset != null ? charset : DEFAULT_CHARSET); + return " payload=" + new String(bytes, charset); + } + else { + return " payload=byte[" + bytes.length + "]"; + } + } + else { + return " payload=" + payload; + } + } + + protected boolean isReadableContentType() { + for (MimeType mimeType : readableMimeTypes) { + if (mimeType.includes(getContentType())) { + return true; + } + } + return false; + } + @Override public String toString() { return getClass().getSimpleName() + "[headers=" + this.headers + "]"; diff --git a/spring-messaging/src/test/java/org/springframework/messaging/simp/SimpAttributesContextHolderTests.java b/spring-messaging/src/test/java/org/springframework/messaging/simp/SimpAttributesContextHolderTests.java index 689a579089..8fe77ad390 100644 --- a/spring-messaging/src/test/java/org/springframework/messaging/simp/SimpAttributesContextHolderTests.java +++ b/spring-messaging/src/test/java/org/springframework/messaging/simp/SimpAttributesContextHolderTests.java @@ -110,12 +110,22 @@ public class SimpAttributesContextHolderTests { } @Test - public void setAttributesFromMessageWithMissingHeaders() { + public void setAttributesFromMessageWithMissingSessionId() { this.thrown.expect(IllegalStateException.class); - this.thrown.expectMessage(startsWith("Message does not contain SiMP session id or attributes")); + this.thrown.expectMessage(startsWith("No session id in")); SimpAttributesContextHolder.setAttributesFromMessage(new GenericMessage("")); } + @Test + public void setAttributesFromMessageWithMissingSessionAttributes() { + this.thrown.expect(IllegalStateException.class); + this.thrown.expectMessage(startsWith("No session attributes in")); + SimpMessageHeaderAccessor headerAccessor = SimpMessageHeaderAccessor.create(); + headerAccessor.setSessionId("session1"); + Message message = MessageBuilder.createMessage("", headerAccessor.getMessageHeaders()); + SimpAttributesContextHolder.setAttributesFromMessage(message); + } + @Test public void currentAttributes() { SimpAttributesContextHolder.setAttributes(this.simpAttributes); diff --git a/spring-messaging/src/test/java/org/springframework/messaging/simp/SimpMessageHeaderAccessorTests.java b/spring-messaging/src/test/java/org/springframework/messaging/simp/SimpMessageHeaderAccessorTests.java new file mode 100644 index 0000000000..dfd6244a8e --- /dev/null +++ b/spring-messaging/src/test/java/org/springframework/messaging/simp/SimpMessageHeaderAccessorTests.java @@ -0,0 +1,66 @@ +/* + * 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. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.springframework.messaging.simp; + +import org.junit.Test; + +import java.util.Collections; + +import static org.junit.Assert.assertEquals; + +/** + * Unit tests for SimpMessageHeaderAccessor. + * + * @author Rossen Stoyanchev + */ +public class SimpMessageHeaderAccessorTests { + + + @Test + public void getShortLogMessage() { + assertEquals("MESSAGE session=null payload=p", SimpMessageHeaderAccessor.create().getShortLogMessage("p")); + } + + @Test + public void getLogMessageWithValuesSet() { + SimpMessageHeaderAccessor accessor = SimpMessageHeaderAccessor.create(); + accessor.setDestination("/destination"); + accessor.setSubscriptionId("subscription"); + accessor.setSessionId("session"); + accessor.setUser(new TestPrincipal("user")); + accessor.setSessionAttributes(Collections.singletonMap("key", "value")); + + assertEquals("MESSAGE destination=/destination subscriptionId=subscription " + + "session=session user=user attributes[1] payload=p", accessor.getShortLogMessage("p")); + } + + @Test + public void getDetailedLogMessageWithValuesSet() { + SimpMessageHeaderAccessor accessor = SimpMessageHeaderAccessor.create(); + accessor.setDestination("/destination"); + accessor.setSubscriptionId("subscription"); + accessor.setSessionId("session"); + accessor.setUser(new TestPrincipal("user")); + accessor.setSessionAttributes(Collections.singletonMap("key", "value")); + accessor.setNativeHeader("nativeKey", "nativeValue"); + + assertEquals("MESSAGE destination=/destination subscriptionId=subscription " + + "session=session user=user attributes={key=value} nativeHeaders=" + + "{nativeKey=[nativeValue]} payload=p", accessor.getDetailedLogMessage("p")); + } + +} diff --git a/spring-messaging/src/test/java/org/springframework/messaging/simp/broker/SimpleBrokerMessageHandlerTests.java b/spring-messaging/src/test/java/org/springframework/messaging/simp/broker/SimpleBrokerMessageHandlerTests.java index d6360616b9..5ec39873f0 100644 --- a/spring-messaging/src/test/java/org/springframework/messaging/simp/broker/SimpleBrokerMessageHandlerTests.java +++ b/spring-messaging/src/test/java/org/springframework/messaging/simp/broker/SimpleBrokerMessageHandlerTests.java @@ -109,7 +109,7 @@ public class SimpleBrokerMessageHandlerTests { SimpMessageHeaderAccessor headers = SimpMessageHeaderAccessor.create(SimpMessageType.DISCONNECT); headers.setSessionId(sess1); - Message message = MessageBuilder.withPayload(new byte[0]).copyHeaders(headers.toMap()).build(); + Message message = MessageBuilder.createMessage(new byte[0], headers.getMessageHeaders()); this.messageHandler.handleMessage(message); this.messageHandler.handleMessage(createMessage("/foo", "message1")); @@ -141,28 +141,23 @@ public class SimpleBrokerMessageHandlerTests { protected Message createSubscriptionMessage(String sessionId, String subcriptionId, String destination) { - SimpMessageHeaderAccessor headers = SimpMessageHeaderAccessor.create(SimpMessageType.SUBSCRIBE); headers.setSubscriptionId(subcriptionId); headers.setDestination(destination); headers.setSessionId(sessionId); - - return MessageBuilder.withPayload("").copyHeaders(headers.toMap()).build(); + return MessageBuilder.createMessage("", headers.getMessageHeaders()); } protected Message createConnectMessage(String sessionId) { SimpMessageHeaderAccessor headers = SimpMessageHeaderAccessor.create(SimpMessageType.CONNECT); headers.setSessionId(sessionId); - - return MessageBuilder.withPayload("").setHeaders(headers).build(); + return MessageBuilder.createMessage("", headers.getMessageHeaders()); } protected Message createMessage(String destination, String payload) { - SimpMessageHeaderAccessor headers = SimpMessageHeaderAccessor.create(SimpMessageType.MESSAGE); headers.setDestination(destination); - - return MessageBuilder.withPayload(payload).copyHeaders(headers.toMap()).build(); + return MessageBuilder.createMessage("", headers.getMessageHeaders()); } protected boolean assertCapturedMessage(String sessionId, String subcriptionId, String destination) { diff --git a/spring-messaging/src/test/java/org/springframework/messaging/simp/config/MessageBrokerConfigurationTests.java b/spring-messaging/src/test/java/org/springframework/messaging/simp/config/MessageBrokerConfigurationTests.java index 3e5fa408c8..fa9a4d61ed 100644 --- a/spring-messaging/src/test/java/org/springframework/messaging/simp/config/MessageBrokerConfigurationTests.java +++ b/spring-messaging/src/test/java/org/springframework/messaging/simp/config/MessageBrokerConfigurationTests.java @@ -166,7 +166,7 @@ public class MessageBrokerConfigurationTests { headers.setSessionId("sess1"); headers.setSubscriptionId("subs1"); headers.setDestination("/foo"); - Message message = MessageBuilder.withPayload(new byte[0]).setHeaders(headers).build(); + Message message = MessageBuilder.createMessage(new byte[0], headers.getMessageHeaders()); // subscribe broker.handleMessage(message); @@ -174,7 +174,7 @@ public class MessageBrokerConfigurationTests { headers = StompHeaderAccessor.create(StompCommand.SEND); headers.setSessionId("sess1"); headers.setDestination("/foo"); - message = MessageBuilder.withPayload("bar".getBytes()).setHeaders(headers).build(); + message = MessageBuilder.createMessage("bar".getBytes(), headers.getMessageHeaders()); // message broker.handleMessage(message); @@ -235,7 +235,7 @@ public class MessageBrokerConfigurationTests { headers.setSessionId("sess1"); headers.setSessionAttributes(new ConcurrentHashMap<>()); headers.setDestination("/foo"); - Message message = MessageBuilder.withPayload(new byte[0]).setHeaders(headers).build(); + Message message = MessageBuilder.createMessage(new byte[0], headers.getMessageHeaders()); messageHandler.handleMessage(message); @@ -256,7 +256,7 @@ public class MessageBrokerConfigurationTests { StompHeaderAccessor headers = StompHeaderAccessor.create(StompCommand.SEND); headers.setDestination("/user/joe/foo"); - Message message = MessageBuilder.withPayload(new byte[0]).setHeaders(headers).build(); + Message message = MessageBuilder.createMessage(new byte[0], headers.getMessageHeaders()); messageHandler.handleMessage(message); diff --git a/spring-messaging/src/test/java/org/springframework/messaging/simp/stomp/StompHeaderAccessorTests.java b/spring-messaging/src/test/java/org/springframework/messaging/simp/stomp/StompHeaderAccessorTests.java index 31c5172958..37a0939d09 100644 --- a/spring-messaging/src/test/java/org/springframework/messaging/simp/stomp/StompHeaderAccessorTests.java +++ b/spring-messaging/src/test/java/org/springframework/messaging/simp/stomp/StompHeaderAccessorTests.java @@ -17,6 +17,7 @@ package org.springframework.messaging.simp.stomp; import java.io.UnsupportedEncodingException; +import java.nio.charset.Charset; import java.util.List; import java.util.Map; @@ -31,6 +32,7 @@ import org.springframework.messaging.support.MessageBuilder; import org.springframework.messaging.support.MessageHeaderAccessor; import org.springframework.util.AlternativeJdkIdGenerator; import org.springframework.util.LinkedMultiValueMap; +import org.springframework.util.MimeType; import org.springframework.util.MimeTypeUtils; import org.springframework.util.MultiValueMap; @@ -44,6 +46,7 @@ import static org.junit.Assert.*; */ public class StompHeaderAccessorTests { + private static final Charset UTF_8 = Charset.forName("UTF-8"); @Test public void createWithCommand() { @@ -240,4 +243,22 @@ public class StompHeaderAccessorTests { assertSame(headerAccessor, MessageHeaderAccessor.getAccessor(message, StompHeaderAccessor.class)); } + @Test + public void getShortLogMessage() { + StompHeaderAccessor accessor = StompHeaderAccessor.create(StompCommand.SEND); + accessor.setDestination("/foo"); + accessor.setContentType(MimeTypeUtils.APPLICATION_JSON); + accessor.setSessionId("123"); + String actual = accessor.getShortLogMessage("payload".getBytes(Charset.forName("UTF-8"))); + assertEquals("SEND /foo session=123 application/json payload=payload", actual); + + StringBuilder sb = new StringBuilder(); + for (int i = 0; i < 80; i++) { + sb.append("a"); + } + final String payload = sb.toString() + " > 80"; + actual = accessor.getShortLogMessage(payload.getBytes(UTF_8)); + assertEquals("SEND /foo session=123 application/json payload=" + sb + "...(truncated)", actual); + } + } diff --git a/spring-messaging/src/test/java/org/springframework/messaging/support/MessageHeaderAccessorTests.java b/spring-messaging/src/test/java/org/springframework/messaging/support/MessageHeaderAccessorTests.java index 74665a7e35..f5e6829245 100644 --- a/spring-messaging/src/test/java/org/springframework/messaging/support/MessageHeaderAccessorTests.java +++ b/spring-messaging/src/test/java/org/springframework/messaging/support/MessageHeaderAccessorTests.java @@ -16,19 +16,23 @@ package org.springframework.messaging.support; +import java.nio.charset.Charset; import java.util.Arrays; import java.util.HashMap; import java.util.HashSet; import java.util.Map; import java.util.UUID; +import org.hamcrest.CoreMatchers; import org.junit.Rule; import org.junit.Test; import org.junit.rules.ExpectedException; import org.springframework.messaging.Message; import org.springframework.messaging.MessageHeaders; import org.springframework.util.IdGenerator; +import org.springframework.util.MimeTypeUtils; +import static org.hamcrest.CoreMatchers.startsWith; import static org.junit.Assert.*; /** @@ -38,6 +42,8 @@ import static org.junit.Assert.*; */ public class MessageHeaderAccessorTests { + private static final Charset UTF_8 = Charset.forName("UTF-8"); + @Rule public final ExpectedException thrown = ExpectedException.none(); @@ -250,6 +256,77 @@ public class MessageHeaderAccessorTests { assertNotNull(headers.getTimestamp()); } + @Test + public void getShortLogMessagePayload() { + MessageHeaderAccessor accessor = new MessageHeaderAccessor(); + accessor.setContentType(MimeTypeUtils.TEXT_PLAIN); + + assertEquals("headers={contentType=text/plain} payload=p", accessor.getShortLogMessage("p")); + assertEquals("headers={contentType=text/plain} payload=p", accessor.getShortLogMessage("p".getBytes(UTF_8))); + assertEquals("headers={contentType=text/plain} payload=p", accessor.getShortLogMessage(new Object() { + @Override + public String toString() { + return "p"; + } + })); + + StringBuilder sb = new StringBuilder(); + for (int i = 0; i < 80; i++) { + sb.append("a"); + } + final String payload = sb.toString() + " > 80"; + + String actual = accessor.getShortLogMessage(payload); + assertEquals("headers={contentType=text/plain} payload=" + sb + "...(truncated)", actual); + + actual = accessor.getShortLogMessage(payload.getBytes(UTF_8)); + assertEquals("headers={contentType=text/plain} payload=" + sb + "...(truncated)", actual); + + actual = accessor.getShortLogMessage(new Object() { + @Override + public String toString() { + return payload; + } + }); + assertThat(actual, startsWith("headers={contentType=text/plain} payload=" + getClass().getName() + "$")); + } + + @Test + public void getDetailedLogMessagePayload() { + MessageHeaderAccessor accessor = new MessageHeaderAccessor(); + accessor.setContentType(MimeTypeUtils.TEXT_PLAIN); + + assertEquals("headers={contentType=text/plain} payload=p", accessor.getDetailedLogMessage("p")); + assertEquals("headers={contentType=text/plain} payload=p", accessor.getDetailedLogMessage("p".getBytes(UTF_8))); + assertEquals("headers={contentType=text/plain} payload=p", accessor.getDetailedLogMessage(new Object() { + @Override + public String toString() { + return "p"; + } + })); + + StringBuilder sb = new StringBuilder(); + for (int i = 0; i < 80; i++) { + sb.append("a"); + } + final String payload = sb.toString() + " > 80"; + + String actual = accessor.getDetailedLogMessage(payload); + assertEquals("headers={contentType=text/plain} payload=" + sb + " > 80", actual); + + actual = accessor.getDetailedLogMessage(payload.getBytes(UTF_8)); + assertEquals("headers={contentType=text/plain} payload=" + sb + " > 80", actual); + + actual = accessor.getDetailedLogMessage(new Object() { + @Override + public String toString() { + return payload; + } + }); + assertEquals("headers={contentType=text/plain} payload=" + sb + " > 80", actual); + } + + public static class TestMessageHeaderAccessor extends MessageHeaderAccessor { 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 396b01889e..ff3a6827dd 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 @@ -40,7 +40,8 @@ import org.springframework.web.socket.WebSocketSession; */ public abstract class AbstractWebSocketSession implements NativeWebSocketSession { - protected final Log logger = LogFactory.getLog(getClass()); + protected static final Log logger = LogFactory.getLog(NativeWebSocketSession.class); + private T nativeSession; @@ -133,8 +134,8 @@ public abstract class AbstractWebSocketSession implements NativeWebSocketSess @Override public final void close(CloseStatus status) throws IOException { checkNativeSessionInitialized(); - if (logger.isInfoEnabled()) { - logger.info("Closing " + this); + if (logger.isDebugEnabled()) { + logger.debug("Closing " + this); } closeInternal(status); } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/client/AbstractWebSocketClient.java b/spring-websocket/src/main/java/org/springframework/web/socket/client/AbstractWebSocketClient.java index dbec02cd99..59c61df706 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/client/AbstractWebSocketClient.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/client/AbstractWebSocketClient.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. diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/client/ConnectionManagerSupport.java b/spring-websocket/src/main/java/org/springframework/web/socket/client/ConnectionManagerSupport.java index 1fbbc203ea..5ebedbb517 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/client/ConnectionManagerSupport.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/client/ConnectionManagerSupport.java @@ -122,8 +122,8 @@ public abstract class ConnectionManagerSupport implements SmartLifecycle { protected void startInternal() { synchronized (lifecycleMonitor) { - if (logger.isDebugEnabled()) { - logger.debug("Starting " + this.getClass().getSimpleName()); + if (logger.isInfoEnabled()) { + logger.info("Starting " + this.getClass().getSimpleName()); } this.isRunning = true; openConnection(); @@ -136,8 +136,8 @@ public abstract class ConnectionManagerSupport implements SmartLifecycle { public final void stop() { synchronized (this.lifecycleMonitor) { if (isRunning()) { - if (logger.isDebugEnabled()) { - logger.debug("Stopping " + this.getClass().getSimpleName()); + if (logger.isInfoEnabled()) { + logger.info("Stopping " + this.getClass().getSimpleName()); } try { stopInternal(); diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/client/jetty/JettyWebSocketClient.java b/spring-websocket/src/main/java/org/springframework/web/socket/client/jetty/JettyWebSocketClient.java index 485c920d52..f9e6f8a9d1 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/client/jetty/JettyWebSocketClient.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/client/jetty/JettyWebSocketClient.java @@ -128,8 +128,8 @@ public class JettyWebSocketClient extends AbstractWebSocketClient implements Sma synchronized (this.lifecycleMonitor) { if (!isRunning()) { try { - if (logger.isDebugEnabled()) { - logger.debug("Starting Jetty WebSocketClient"); + if (logger.isInfoEnabled()) { + logger.info("Starting Jetty WebSocketClient"); } this.client.start(); } @@ -145,8 +145,8 @@ public class JettyWebSocketClient extends AbstractWebSocketClient implements Sma synchronized (this.lifecycleMonitor) { if (isRunning()) { try { - if (logger.isDebugEnabled()) { - logger.debug("Stopping Jetty WebSocketClient"); + if (logger.isInfoEnabled()) { + logger.info("Stopping Jetty WebSocketClient"); } this.client.stop(); } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/client/standard/StandardWebSocketClient.java b/spring-websocket/src/main/java/org/springframework/web/socket/client/standard/StandardWebSocketClient.java index fdea416dde..2c6bce9cd6 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/client/standard/StandardWebSocketClient.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/client/standard/StandardWebSocketClient.java @@ -176,14 +176,14 @@ public class StandardWebSocketClient extends AbstractWebSocketClient { @Override public void beforeRequest(Map> requestHeaders) { requestHeaders.putAll(this.headers); - if (logger.isDebugEnabled()) { - logger.debug("Handshake request headers: " + requestHeaders); + if (logger.isTraceEnabled()) { + logger.trace("Handshake request headers: " + requestHeaders); } } @Override public void afterResponse(HandshakeResponse response) { - if (logger.isDebugEnabled()) { - logger.debug("Handshake response headers: " + response.getHeaders()); + if (logger.isTraceEnabled()) { + logger.trace("Handshake response headers: " + response.getHeaders()); } } } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/config/WebSocketMessageBrokerStats.java b/spring-websocket/src/main/java/org/springframework/web/socket/config/WebSocketMessageBrokerStats.java index c5ede88445..55eaa4bc5d 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/config/WebSocketMessageBrokerStats.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/config/WebSocketMessageBrokerStats.java @@ -67,7 +67,7 @@ public class WebSocketMessageBrokerStats { private ScheduledFuture loggingTask; - private long loggingPeriod = 15 * 60 * 1000; + private long loggingPeriod = 30 * 60 * 1000; public void setSubProtocolWebSocketHandler(SubProtocolWebSocketHandler webSocketHandler) { @@ -102,7 +102,7 @@ public class WebSocketMessageBrokerStats { public void setSockJsTaskScheduler(ThreadPoolTaskScheduler sockJsTaskScheduler) { this.sockJsTaskScheduler = sockJsTaskScheduler.getScheduledThreadPoolExecutor(); - this.loggingTask = initLoggingTask(3 * 60 * 1000); + this.loggingTask = initLoggingTask(1 * 60 * 1000); } private ScheduledFuture initLoggingTask(long initialDelay) { diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/handler/BeanCreatingHandlerProvider.java b/spring-websocket/src/main/java/org/springframework/web/socket/handler/BeanCreatingHandlerProvider.java index 36ccc029ae..045d77a162 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/handler/BeanCreatingHandlerProvider.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/handler/BeanCreatingHandlerProvider.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. @@ -60,9 +60,6 @@ public class BeanCreatingHandlerProvider implements BeanFactoryAware { } public T getHandler() { - if (logger.isTraceEnabled()) { - logger.trace("Creating instance for handler type " + this.handlerType); - } if (this.beanFactory == null) { logger.warn("No BeanFactory available, attempting to use default constructor"); return BeanUtils.instantiate(this.handlerType); @@ -74,16 +71,13 @@ public class BeanCreatingHandlerProvider implements BeanFactoryAware { public void destroy(T handler) { if (this.beanFactory != null) { - if (logger.isTraceEnabled()) { - logger.trace("Destroying handler instance " + handler); - } this.beanFactory.destroyBean(handler); } } @Override public String toString() { - return "BeanCreatingHandlerProvider [handlerClass=" + this.handlerType + "]"; + return "BeanCreatingHandlerProvider[handlerType=" + this.handlerType + "]"; } } 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 3b3aa5fe5d..1945dee2fa 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 @@ -45,7 +45,7 @@ import org.springframework.web.socket.WebSocketSession; */ public class ConcurrentWebSocketSessionDecorator extends WebSocketSessionDecorator { - private static final Log logger = LogFactory.getLog(ConcurrentWebSocketSessionDecorator.class); + private static final Log logger = LogFactory.getLog("_" + ConcurrentWebSocketSessionDecorator.class.getName()); private final Queue> buffer = new LinkedBlockingQueue>(); 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 7b1bcde8df..d4645aaeea 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 @@ -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. @@ -31,7 +31,7 @@ import org.springframework.web.socket.WebSocketSession; */ public class LoggingWebSocketHandlerDecorator extends WebSocketHandlerDecorator { - private final Log logger = LogFactory.getLog(LoggingWebSocketHandlerDecorator.class); + private static final Log logger = LogFactory.getLog(LoggingWebSocketHandlerDecorator.class); public LoggingWebSocketHandlerDecorator(WebSocketHandler delegate) { @@ -41,8 +41,8 @@ public class LoggingWebSocketHandlerDecorator extends WebSocketHandlerDecorator @Override public void afterConnectionEstablished(WebSocketSession session) throws Exception { - if (logger.isInfoEnabled()) { - logger.info("Connection established " + session); + if (logger.isDebugEnabled()) { + logger.debug("New " + session); } super.afterConnectionEstablished(session); } @@ -65,8 +65,8 @@ public class LoggingWebSocketHandlerDecorator extends WebSocketHandlerDecorator @Override public void afterConnectionClosed(WebSocketSession session, CloseStatus closeStatus) throws Exception { - if (logger.isInfoEnabled()) { - logger.info("Connection closed with " + closeStatus + " in " + session + ", "); + if (logger.isDebugEnabled()) { + logger.debug(session + " closed with " + closeStatus); } super.afterConnectionClosed(session, closeStatus); } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/handler/PerConnectionWebSocketHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/handler/PerConnectionWebSocketHandler.java index 86d1a6c288..557d76853e 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/handler/PerConnectionWebSocketHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/handler/PerConnectionWebSocketHandler.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. @@ -50,6 +50,7 @@ public class PerConnectionWebSocketHandler implements WebSocketHandler, BeanFact private static final Log logger = LogFactory.getLog(PerConnectionWebSocketHandler.class); + private final BeanCreatingHandlerProvider provider; private final Map handlers = @@ -113,7 +114,7 @@ public class PerConnectionWebSocketHandler implements WebSocketHandler, BeanFact } } catch (Throwable t) { - logger.warn("Error while destroying handler", t); + logger.warn("Error while destroying " + handler, t); } } @@ -124,7 +125,7 @@ public class PerConnectionWebSocketHandler implements WebSocketHandler, BeanFact @Override public String toString() { - return "PerConnectionWebSocketHandlerProxy [handlerType=" + this.provider.getHandlerType() + "]"; + return "PerConnectionWebSocketHandlerProxy[handlerType=" + this.provider.getHandlerType() + "]"; } } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/messaging/StompSubProtocolHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/messaging/StompSubProtocolHandler.java index a11a8aa2c9..d631e136fa 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/messaging/StompSubProtocolHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/messaging/StompSubProtocolHandler.java @@ -198,8 +198,9 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE messages = decoder.decode(byteBuffer); if (messages.isEmpty()) { if (logger.isTraceEnabled()) { - logger.trace("Incomplete STOMP frame content received, bufferSize=" + - decoder.getBufferSize() + ", bufferSizeLimit=" + decoder.getBufferSizeLimit() + "."); + logger.trace("Incomplete STOMP frame content received in session " + + session + ", bufferSize=" + decoder.getBufferSize() + + ", bufferSizeLimit=" + decoder.getBufferSizeLimit() + "."); } return; } @@ -219,9 +220,7 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE MessageHeaderAccessor.getAccessor(message, StompHeaderAccessor.class); if (logger.isTraceEnabled()) { - logger.trace(headerAccessor.isHeartbeat() ? - "Received heartbeat from broker in session " + session.getId() + "." : - "Received message from broker in session " + session.getId() + ": " + message + "."); + logger.trace("From client: " + headerAccessor.getShortLogMessage(message.getPayload())); } headerAccessor.setSessionId(session.getId()); @@ -264,9 +263,6 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE private void publishEvent(ApplicationEvent event) { try { - if (logger.isInfoEnabled()) { - logger.info("Publishing " + event); - } this.eventPublisher.publishEvent(event); } catch (Throwable ex) { @@ -300,9 +296,7 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE StompCommand command = stompAccessor.getCommand(); if (StompCommand.MESSAGE.equals(command)) { if (stompAccessor.getSubscriptionId() == null) { - if (logger.isWarnEnabled()) { - logger.warn("No STOMP \"subscription\" header in " + message); - } + logger.warn("No STOMP \"subscription\" header in " + message); } String origDestination = stompAccessor.getFirstNativeHeader(SimpMessageHeaderAccessor.ORIGINAL_DESTINATION); if (origDestination != null) { @@ -418,10 +412,6 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE if (heartbeat[1] > 0) { session = WebSocketSessionDecorator.unwrap(session); if (session instanceof SockJsSession) { - if (logger.isDebugEnabled()) { - logger.debug("STOMP heartbeats enabled. " + - "Turning off SockJS heartbeats in " + session.getId() + "."); - } ((SockJsSession) session).disableHeartbeat(); } } @@ -482,6 +472,10 @@ public class StompSubProtocolHandler implements SubProtocolHandler, ApplicationE return MessageBuilder.createMessage(EMPTY_PAYLOAD, headerAccessor.getMessageHeaders()); } + @Override + public String toString() { + return "StompSubProtocolHandler" + getSupportedProtocols(); + } private class Stats { 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 48ebc195ce..d0e642a01e 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 @@ -265,9 +265,6 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler, this.stats.incrementSessionCount(session); session = new ConcurrentWebSocketSessionDecorator(session, getSendTimeLimit(), getSendBufferSizeLimit()); this.sessions.put(session.getId(), new WebSocketSessionHolder(session)); - if (logger.isDebugEnabled()) { - logger.debug("Started session " + session.getId() + " (" + this.sessions.size() + " sessions)"); - } findProtocolHandler(session).afterSessionStarted(session, this.clientInboundChannel); } @@ -422,7 +419,7 @@ 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)"); + logger.debug("Clearing session " + session.getId()); } if (this.sessions.remove(session.getId()) != null) { this.stats.decrementSessionCount(session); @@ -435,6 +432,10 @@ public class SubProtocolWebSocketHandler implements WebSocketHandler, return false; } + @Override + public String toString() { + return "SubProtocolWebSocketHandler" + getProtocolHandlers(); + } private static class WebSocketSessionHolder { diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/server/support/DefaultHandshakeHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/server/support/DefaultHandshakeHandler.java index 7fcca12782..a563da2796 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/server/support/DefaultHandshakeHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/server/support/DefaultHandshakeHandler.java @@ -156,24 +156,23 @@ public class DefaultHandshakeHandler implements HandshakeHandler { WebSocketHandler wsHandler, Map attributes) throws HandshakeFailureException { WebSocketHttpHeaders headers = new WebSocketHttpHeaders(request.getHeaders()); - - if (logger.isDebugEnabled()) { - logger.debug("Initiating handshake for " + request.getURI() + ", headers=" + headers); + if (logger.isTraceEnabled()) { + logger.trace("Processing request " + request.getURI() + " with headers=" + headers); } - try { if (!HttpMethod.GET.equals(request.getMethod())) { response.setStatusCode(HttpStatus.METHOD_NOT_ALLOWED); response.getHeaders().setAllow(Collections.singleton(HttpMethod.GET)); - logger.debug("Only HTTP GET is allowed, current method is " + request.getMethod()); + if (logger.isErrorEnabled()) { + logger.error("Handshake failed due to unexpected HTTP method: " + request.getMethod()); + } return false; } if (!"WebSocket".equalsIgnoreCase(headers.getUpgrade())) { handleInvalidUpgradeHeader(request, response); return false; } - if (!headers.getConnection().contains("Upgrade") && - !headers.getConnection().contains("upgrade")) { + if (!headers.getConnection().contains("Upgrade") && !headers.getConnection().contains("upgrade")) { handleInvalidConnectHeader(request, response); return false; } @@ -187,7 +186,9 @@ public class DefaultHandshakeHandler implements HandshakeHandler { } String wsKey = headers.getSecWebSocketKey(); if (wsKey == null) { - logger.debug("Missing \"Sec-WebSocket-Key\" header"); + if (logger.isErrorEnabled()) { + logger.error("Missing \"Sec-WebSocket-Key\" header"); + } response.setStatusCode(HttpStatus.BAD_REQUEST); return false; } @@ -198,33 +199,30 @@ public class DefaultHandshakeHandler implements HandshakeHandler { } String subProtocol = selectProtocol(headers.getSecWebSocketProtocol(), wsHandler); - if (logger.isDebugEnabled()) { - logger.debug("Selected sub-protocol: '" + subProtocol + "'"); - } - List requested = headers.getSecWebSocketExtensions(); List supported = this.requestUpgradeStrategy.getSupportedExtensions(request); List extensions = filterRequestedExtensions(request, requested, supported); - Principal user = determineUser(request, wsHandler, attributes); - if (logger.isDebugEnabled()) { - logger.debug("Upgrading request, sub-protocol=" + subProtocol + ", extensions=" + extensions); + if (logger.isTraceEnabled()) { + logger.trace("Upgrading to WebSocket"); } - this.requestUpgradeStrategy.upgrade(request, response, subProtocol, extensions, user, wsHandler, attributes); - return true; } protected void handleInvalidUpgradeHeader(ServerHttpRequest request, ServerHttpResponse response) throws IOException { - logger.debug("Invalid Upgrade header " + request.getHeaders().getUpgrade()); + if (logger.isErrorEnabled()) { + logger.error("Handshake failed due to invalid Upgrade header: " + request.getHeaders().getUpgrade()); + } response.setStatusCode(HttpStatus.BAD_REQUEST); response.getBody().write("Can \"Upgrade\" only to \"WebSocket\".".getBytes("UTF-8")); } protected void handleInvalidConnectHeader(ServerHttpRequest request, ServerHttpResponse response) throws IOException { - logger.debug("Invalid Connection header " + request.getHeaders().getConnection()); + if (logger.isErrorEnabled()) { + logger.error("Handshake failed due to invalid Connection header " + request.getHeaders().getConnection()); + } response.setStatusCode(HttpStatus.BAD_REQUEST); response.getBody().write("\"Connection\" must be \"upgrade\".".getBytes("UTF-8")); } @@ -232,17 +230,11 @@ public class DefaultHandshakeHandler implements HandshakeHandler { protected boolean isWebSocketVersionSupported(WebSocketHttpHeaders httpHeaders) { String version = httpHeaders.getSecWebSocketVersion(); String[] supportedVersions = getSupportedVersions(); - if (logger.isDebugEnabled()) { - logger.debug("Requested version=" + version + ", supported=" + Arrays.toString(supportedVersions)); - } for (String supportedVersion : supportedVersions) { if (supportedVersion.trim().equals(version)) { return true; } } - if (logger.isDebugEnabled()) { - logger.debug("Version " + version + " is not a supported WebSocket version"); - } return false; } @@ -251,12 +243,14 @@ public class DefaultHandshakeHandler implements HandshakeHandler { } protected void handleWebSocketVersionNotSupported(ServerHttpRequest request, ServerHttpResponse response) { - if (logger.isDebugEnabled()) { - logger.debug("WebSocket version not supported: " + request.getHeaders().get("Sec-WebSocket-Version")); + if (logger.isErrorEnabled()) { + String version = request.getHeaders().getFirst("Sec-WebSocket-Version"); + logger.error("Handshake failed due to unsupported WebSocket version: " + version + + ". Supported versions: " + Arrays.toString(getSupportedVersions())); } response.setStatusCode(HttpStatus.UPGRADE_REQUIRED); - response.getHeaders().put(WebSocketHttpHeaders.SEC_WEBSOCKET_VERSION, Arrays.asList( - StringUtils.arrayToCommaDelimitedString(getSupportedVersions()))); + response.getHeaders().put(WebSocketHttpHeaders.SEC_WEBSOCKET_VERSION, + Arrays.asList(StringUtils.arrayToCommaDelimitedString(getSupportedVersions()))); } protected boolean isValidOrigin(ServerHttpRequest request) { @@ -277,11 +271,6 @@ public class DefaultHandshakeHandler implements HandshakeHandler { protected String selectProtocol(List requestedProtocols, WebSocketHandler webSocketHandler) { if (requestedProtocols != null) { List handlerProtocols = determineHandlerSupportedProtocols(webSocketHandler); - if (logger.isDebugEnabled()) { - logger.debug("Requested sub-protocol(s): " + requestedProtocols + - ", WebSocketHandler supported sub-protocol(s): " + handlerProtocols + - ", configured sub-protocol(s): " + this.supportedProtocols); - } for (String protocol : requestedProtocols) { if (handlerProtocols.contains(protocol.toLowerCase())) { return protocol; @@ -322,11 +311,6 @@ public class DefaultHandshakeHandler implements HandshakeHandler { protected List filterRequestedExtensions(ServerHttpRequest request, List requested, List supported) { - if (requested != null) { - if (logger.isDebugEnabled()) { - logger.debug("Requested extension(s): " + requested + ", supported extension(s): " + supported); - } - } return requested; } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/server/support/HandshakeInterceptorChain.java b/spring-websocket/src/main/java/org/springframework/web/socket/server/support/HandshakeInterceptorChain.java index 2e1be47bba..dc26caba13 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/server/support/HandshakeInterceptorChain.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/server/support/HandshakeInterceptorChain.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. @@ -57,6 +57,9 @@ public class HandshakeInterceptorChain { for (int i = 0; i < this.interceptors.size(); i++) { HandshakeInterceptor interceptor = this.interceptors.get(i); if (!interceptor.beforeHandshake(request, response, this.wsHandler, attributes)) { + if (logger.isDebugEnabled()) { + logger.debug(interceptor + " return false precluding handshake."); + } applyAfterHandshake(request, response, null); return false; } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/server/support/HttpSessionHandshakeInterceptor.java b/spring-websocket/src/main/java/org/springframework/web/socket/server/support/HttpSessionHandshakeInterceptor.java index a2e1e8bc6b..4da9e7ef84 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/server/support/HttpSessionHandshakeInterceptor.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/server/support/HttpSessionHandshakeInterceptor.java @@ -21,9 +21,6 @@ import java.util.Enumeration; import java.util.Map; import javax.servlet.http.HttpSession; -import org.apache.commons.logging.Log; -import org.apache.commons.logging.LogFactory; - import org.springframework.http.server.ServerHttpRequest; import org.springframework.http.server.ServerHttpResponse; import org.springframework.http.server.ServletServerHttpRequest; @@ -41,8 +38,6 @@ import org.springframework.web.socket.server.HandshakeInterceptor; */ public class HttpSessionHandshakeInterceptor implements HandshakeInterceptor { - private static final Log logger = LogFactory.getLog(HttpSessionHandshakeInterceptor.class); - private Collection attributeNames; @@ -74,16 +69,8 @@ public class HttpSessionHandshakeInterceptor implements HandshakeInterceptor { while (names.hasMoreElements()) { String name = names.nextElement(); if (CollectionUtils.isEmpty(this.attributeNames) || this.attributeNames.contains(name)) { - if (logger.isTraceEnabled()) { - logger.trace("Adding HTTP session attribute to handshake attributes: " + name); - } attributes.put(name, session.getAttribute(name)); } - else { - if (logger.isTraceEnabled()) { - logger.trace("Skipped HTTP session attribute"); - } - } } } } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/server/support/WebSocketHttpRequestHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/server/support/WebSocketHttpRequestHandler.java index f768e33556..1be811288c 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/server/support/WebSocketHttpRequestHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/server/support/WebSocketHttpRequestHandler.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. @@ -25,6 +25,8 @@ import javax.servlet.ServletException; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.springframework.http.server.ServerHttpRequest; import org.springframework.http.server.ServerHttpResponse; import org.springframework.http.server.ServletServerHttpRequest; @@ -52,6 +54,9 @@ import org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator; */ public class WebSocketHttpRequestHandler implements HttpRequestHandler { + private static final Log logger = LogFactory.getLog(WebSocketHttpRequestHandler.class); + + private final HandshakeHandler handshakeHandler; private final WebSocketHandler wsHandler; @@ -113,6 +118,9 @@ public class WebSocketHttpRequestHandler implements HttpRequestHandler { HandshakeFailureException failure = null; try { + if (logger.isDebugEnabled()) { + logger.debug(servletRequest.getMethod() + " " + servletRequest.getRequestURI()); + } Map attributes = new HashMap(); if (!chain.applyBeforeHandshake(request, response, attributes)) { return; diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractClientSockJsSession.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractClientSockJsSession.java index 825b8a0c8a..825cdb9594 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractClientSockJsSession.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractClientSockJsSession.java @@ -157,8 +157,8 @@ public abstract class AbstractClientSockJsSession implements WebSocketSession { @Override public final void close(CloseStatus status) { Assert.isTrue(status != null && isUserSetStatus(status), "Invalid close status: " + status); - if (logger.isInfoEnabled()) { - logger.info("Closing session with " + status + " in " + this); + if (logger.isDebugEnabled()) { + logger.debug("Closing session with " + status + " in " + this); } closeInternal(status); } @@ -213,8 +213,8 @@ public abstract class AbstractClientSockJsSession implements WebSocketSession { } private void handleOpenFrame() { - if (logger.isInfoEnabled()) { - logger.info("Processing SockJS open frame in " + this); + if (logger.isDebugEnabled()) { + logger.debug("Processing SockJS open frame in " + this); } if (State.NEW.equals(state)) { this.state = State.OPEN; @@ -280,8 +280,8 @@ public abstract class AbstractClientSockJsSession implements WebSocketSession { if (data.length == 2) { closeStatus = new CloseStatus(Integer.valueOf(data[0]), data[1]); } - if (logger.isInfoEnabled()) { - logger.info("Processing SockJS close frame with " + closeStatus + " in " + this); + if (logger.isDebugEnabled()) { + logger.debug("Processing SockJS close frame with " + closeStatus + " in " + this); } } catch (IOException ex) { @@ -311,8 +311,8 @@ public abstract class AbstractClientSockJsSession implements WebSocketSession { this.closeStatus = (this.closeStatus != null ? this.closeStatus : closeStatus); Assert.state(this.closeStatus != null, "CloseStatus not available"); - if (logger.isInfoEnabled()) { - logger.info("Transport closed with " + this.closeStatus + " in " + this); + if (logger.isDebugEnabled()) { + logger.debug("Transport closed with " + this.closeStatus + " in " + this); } this.state = State.CLOSED; diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractXhrTransport.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractXhrTransport.java index 9ef2218528..44ee209102 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractXhrTransport.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/AbstractXhrTransport.java @@ -104,8 +104,8 @@ public abstract class AbstractXhrTransport implements XhrTransport { } throw new HttpServerErrorException(response.getStatusCode()); } - if (logger.isDebugEnabled()) { - logger.debug("SockJS Info request (url=" + infoUrl + ") response: " + response); + if (logger.isTraceEnabled()) { + logger.trace("SockJS Info request (url=" + infoUrl + ") response: " + response); } return response.getBody(); } @@ -114,8 +114,8 @@ public abstract class AbstractXhrTransport implements XhrTransport { @Override public void executeSendRequest(URI url, TextMessage message) { - if (logger.isDebugEnabled()) { - logger.debug("Starting XHR send, url=" + url); + if (logger.isTraceEnabled()) { + logger.trace("Starting XHR send, url=" + url); } ResponseEntity response = executeSendRequestInternal(url, this.xhrSendRequestHeaders, message); if (response.getStatusCode() != HttpStatus.NO_CONTENT) { @@ -124,8 +124,8 @@ public abstract class AbstractXhrTransport implements XhrTransport { } throw new HttpServerErrorException(response.getStatusCode()); } - if (logger.isDebugEnabled()) { - logger.debug("XHR send request (url=" + url + ") response: " + response); + if (logger.isTraceEnabled()) { + logger.trace("XHR send request (url=" + url + ") response: " + response); } } @@ -139,7 +139,8 @@ public abstract class AbstractXhrTransport implements XhrTransport { URI receiveUrl = request.getTransportUrl(); if (logger.isDebugEnabled()) { - logger.debug("Opening XHR session, receive url=" + receiveUrl); + logger.debug("Starting XHR " + + (isXhrStreamingDisabled() ? "Polling" : "Streaming") + "session url=" + receiveUrl); } HttpHeaders handshakeHeaders = new HttpHeaders(); diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/DefaultTransportRequest.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/DefaultTransportRequest.java index fd1e630f77..9b9862a372 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/DefaultTransportRequest.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/DefaultTransportRequest.java @@ -133,8 +133,8 @@ class DefaultTransportRequest implements TransportRequest { public void connect(WebSocketHandler handler, SettableListenableFuture future) { - if (logger.isDebugEnabled()) { - logger.debug("Starting " + this); + if (logger.isTraceEnabled()) { + logger.trace("Starting " + this); } ConnectCallback connectCallback = new ConnectCallback(handler, future); scheduleConnectTimeoutTask(connectCallback); @@ -144,14 +144,14 @@ class DefaultTransportRequest implements TransportRequest { private void scheduleConnectTimeoutTask(ConnectCallback connectHandler) { if (this.timeoutScheduler != null) { - if (logger.isDebugEnabled()) { - logger.debug("Scheduling connect to time out after " + this.timeoutValue + " milliseconds"); + if (logger.isTraceEnabled()) { + logger.trace("Scheduling connect to time out after " + this.timeoutValue + " ms."); } Date timeoutDate = new Date(System.currentTimeMillis() + this.timeoutValue); this.timeoutScheduler.schedule(connectHandler, timeoutDate); } - else if (logger.isDebugEnabled()) { - logger.debug("Connect timeout task not scheduled. Is SockJsClient configured with a TaskScheduler?"); + else if (logger.isTraceEnabled()) { + logger.trace("Connect timeout task not scheduled (no TaskScheduler configured)."); } } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/JettyXhrTransport.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/JettyXhrTransport.java index a4f8e23870..d8221b7462 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/JettyXhrTransport.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/JettyXhrTransport.java @@ -136,8 +136,8 @@ public class JettyXhrTransport extends AbstractXhrTransport implements XhrTransp } private void executeReceiveRequest(URI url, HttpHeaders headers, SockJsResponseListener listener) { - if (logger.isDebugEnabled()) { - logger.debug("Starting XHR receive request, url=" + url); + if (logger.isTraceEnabled()) { + logger.trace("Starting XHR receive request, url=" + url); } Request httpRequest = this.httpClient.newRequest(url).method(HttpMethod.POST); addHttpHeaders(httpRequest, headers); @@ -182,9 +182,9 @@ public class JettyXhrTransport extends AbstractXhrTransport implements XhrTransp @Override public void onHeaders(Response response) { - if (logger.isDebugEnabled()) { + if (logger.isTraceEnabled()) { // Convert to HttpHeaders to avoid "\n" - logger.debug("XHR receive headers: " + toHttpHeaders(response.getHeaders())); + logger.trace("XHR receive headers: " + toHttpHeaders(response.getHeaders())); } } @@ -193,7 +193,7 @@ public class JettyXhrTransport extends AbstractXhrTransport implements XhrTransp while (true) { if (this.sockJsSession.isDisconnected()) { if (logger.isDebugEnabled()) { - logger.debug("SockJS sockJsSession closed. Closing ClientHttpResponse."); + logger.debug("SockJS sockJsSession closed, closing response."); } response.abort(new SockJsException("Session closed.", this.sockJsSession.getId(), null)); return; @@ -228,8 +228,8 @@ public class JettyXhrTransport extends AbstractXhrTransport implements XhrTransp if (this.outputStream.size() > 0) { handleFrame(); } - if (logger.isDebugEnabled()) { - logger.debug("XHR receive request completed."); + if (logger.isTraceEnabled()) { + logger.trace("XHR receive request completed."); } executeReceiveRequest(this.transportUrl, this.receiveHeaders, this); } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/RestTemplateXhrTransport.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/RestTemplateXhrTransport.java index 1f25be4009..375e8e0ccb 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/RestTemplateXhrTransport.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/RestTemplateXhrTransport.java @@ -125,8 +125,8 @@ public class RestTemplateXhrTransport extends AbstractXhrTransport implements Xh break; } try { - if (logger.isDebugEnabled()) { - logger.debug("Starting XHR receive request, url=" + receiveUrl); + if (logger.isTraceEnabled()) { + logger.trace("Starting XHR receive request, url=" + receiveUrl); } getRestTemplate().execute(receiveUrl, HttpMethod.POST, requestCallback, responseExtractor); requestCallback = requestCallbackAfterHandshake; @@ -215,15 +215,15 @@ public class RestTemplateXhrTransport extends AbstractXhrTransport implements Xh if (!HttpStatus.OK.equals(response.getStatusCode())) { throw new HttpServerErrorException(response.getStatusCode()); } - if (logger.isDebugEnabled()) { - logger.debug("XHR receive headers: " + response.getHeaders()); + if (logger.isTraceEnabled()) { + logger.trace("XHR receive headers: " + response.getHeaders()); } InputStream is = response.getBody(); ByteArrayOutputStream os = new ByteArrayOutputStream(); while (true) { if (this.sockJsSession.isDisconnected()) { if (logger.isDebugEnabled()) { - logger.debug("SockJS sockJsSession closed. Closing ClientHttpResponse."); + logger.debug("SockJS sockJsSession closed, closing response."); } response.close(); break; @@ -233,8 +233,8 @@ public class RestTemplateXhrTransport extends AbstractXhrTransport implements Xh if (os.size() > 0) { handleFrame(os); } - if (logger.isDebugEnabled()) { - logger.debug("XHR receive completed"); + if (logger.isTraceEnabled()) { + logger.trace("XHR receive completed"); } break; } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/WebSocketTransport.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/WebSocketTransport.java index ef36a96840..bcecab47c2 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/WebSocketTransport.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/client/WebSocketTransport.java @@ -70,7 +70,7 @@ public class WebSocketTransport implements Transport { URI url = request.getTransportUrl(); WebSocketHttpHeaders headers = new WebSocketHttpHeaders(request.getHandshakeHeaders()); if (logger.isDebugEnabled()) { - logger.debug("Opening WebSocket connection, url=" + url); + logger.debug("Starting WebSocket session url=" + url); } this.webSocketClient.doHandshake(handler, headers, url).addCallback( new ListenableFutureCallback() { diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/AbstractSockJsService.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/AbstractSockJsService.java index 788ca6bb69..df275d9b53 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/AbstractSockJsService.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/AbstractSockJsService.java @@ -268,54 +268,64 @@ public abstract class AbstractSockJsService implements SockJsService { String sockJsPath, WebSocketHandler wsHandler) throws SockJsException { if (sockJsPath == null) { - if (logger.isErrorEnabled()) { - logger.error("Expected SockJS path. Failing request: " + request.getURI()); - } + logger.error("Expected SockJS path. Failing request: " + request.getURI()); response.setStatusCode(HttpStatus.NOT_FOUND); return; } - if (logger.isTraceEnabled()) { - logger.trace(request.getMethod() + " with SockJS path [" + sockJsPath + "]"); - } try { request.getHeaders(); } catch (InvalidMediaTypeException ex) { - if (logger.isDebugEnabled()) { - logger.debug("Invalid media type ignored: " + ex.getMediaType()); - } + // As per SockJS protocol content-type can be ignored (it's always json) } + String requestInfo = logger.isDebugEnabled() ? request.getMethod() + " " + request.getURI() : ""; try { if (sockJsPath.equals("") || sockJsPath.equals("/")) { + logger.debug(requestInfo); response.getHeaders().setContentType(new MediaType("text", "plain", Charset.forName("UTF-8"))); response.getBody().write("Welcome to SockJS!\n".getBytes("UTF-8")); } else if (sockJsPath.equals("/info")) { + logger.debug(requestInfo); this.infoHandler.handle(request, response); } else if (sockJsPath.matches("/iframe[0-9-.a-z_]*.html")) { + logger.debug(requestInfo); this.iframeHandler.handle(request, response); } else if (sockJsPath.equals("/websocket")) { if (isWebSocketEnabled()) { + logger.debug(requestInfo); handleRawWebSocketRequest(request, response, wsHandler); } + else if (logger.isDebugEnabled()) { + logger.debug("WebSocket disabled, ignoring " + requestInfo); + } } else { String[] pathSegments = StringUtils.tokenizeToStringArray(sockJsPath.substring(1), "/"); if (pathSegments.length != 3) { - if (logger.isErrorEnabled()) { - logger.error("Expected \"/{server}/{session}/{transport}\" but got \"" + sockJsPath + "\""); - } + logger.error("Ignoring invalid transport request " + requestInfo); response.setStatusCode(HttpStatus.NOT_FOUND); return; } String serverId = pathSegments[0]; String sessionId = pathSegments[1]; String transport = pathSegments[2]; +<<<<<<< HEAD if (!validateRequest(serverId, sessionId, transport)) { +======= + + if (!isWebSocketEnabled() && transport.equals("websocket")) { + logger.debug("WebSocket transport is disabled, ignoring " + requestInfo); + response.setStatusCode(HttpStatus.NOT_FOUND); + return; + } + else if (!validateRequest(serverId, sessionId, transport)) { + logger.error("Ignoring transport request " + requestInfo); +>>>>>>> STOMP and WebSocket messaging related logging updates response.setStatusCode(HttpStatus.NOT_FOUND); return; } @@ -330,21 +340,23 @@ 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.error("Empty server, session, or transport value"); + logger.error("No server, session, or transport path segment"); return false; } - // Server and session id's must not contain "." if (serverId.contains(".") || sessionId.contains(".")) { +<<<<<<< HEAD logger.error("Server or session contain a \".\""); return false; } if (!isWebSocketEnabled() && transport.equals("websocket")) { logger.debug("Ignoring WebSocket request (transport disabled via SockJsService property)"); +======= + logger.error("Either server or session contains a \".\" which is not allowed by SockJS protocol."); +>>>>>>> STOMP and WebSocket messaging related logging updates return false; } - return true; } @@ -368,7 +380,6 @@ 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.trace("Skip adding CORS headers, response already contains \"Access-Control-Allow-Origin\""); return; } } diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/SockJsHttpRequestHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/SockJsHttpRequestHandler.java index c54be5ec3c..e5da6f9182 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/SockJsHttpRequestHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/support/SockJsHttpRequestHandler.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. @@ -43,6 +43,8 @@ import org.springframework.web.socket.sockjs.SockJsService; */ public class SockJsHttpRequestHandler implements HttpRequestHandler { + // No logging: HTTP transports too verbose and we don't know enough to log anything of value + private final SockJsService sockJsService; private final WebSocketHandler webSocketHandler; diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/TransportHandlingSockJsService.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/TransportHandlingSockJsService.java index 271ae0d91a..25a3c969eb 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/TransportHandlingSockJsService.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/TransportHandlingSockJsService.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. @@ -27,6 +27,8 @@ import java.util.Map; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ScheduledFuture; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.springframework.http.HttpMethod; import org.springframework.http.HttpStatus; import org.springframework.http.server.ServerHttpRequest; @@ -192,16 +194,14 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem TransportType transportType = TransportType.fromValue(transport); if (transportType == null) { - if (logger.isErrorEnabled()) { - logger.error("Unknown transport type: " + transportType); - } + logger.error("Unknown transport type for " + request.getURI()); response.setStatusCode(HttpStatus.NOT_FOUND); return; } TransportHandler transportHandler = this.handlers.get(transportType); if (transportHandler == null) { - logger.error("Transport handler not found"); + logger.error("No TransportHandler for " + request.getURI()); response.setStatusCode(HttpStatus.NOT_FOUND); return; } @@ -239,7 +239,9 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem else { response.setStatusCode(HttpStatus.NOT_FOUND); if (logger.isDebugEnabled()) { - logger.debug("Session not found, sessionId=" + sessionId); + logger.debug("Session not found, sessionId=" + sessionId + + ". The session may have been closed " + + "(e.g. missed heart-beat) while a message was coming in."); } return; } @@ -277,17 +279,11 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem if (session != null) { return session; } - if (this.sessionCleanupTask == null) { scheduleSessionTask(); } - - if (logger.isDebugEnabled()) { - logger.debug("Creating new SockJS session, sessionId=" + sessionId); - } session = sessionFactory.createSession(sessionId, handler, attributes); this.sessions.put(sessionId, session); - return session; } @@ -297,31 +293,24 @@ public class TransportHandlingSockJsService extends AbstractSockJsService implem if (this.sessionCleanupTask != null) { return; } + final List removedSessionIds = new ArrayList(); this.sessionCleanupTask = getTaskScheduler().scheduleAtFixedRate(new Runnable() { @Override public void run() { - try { - int count = sessions.size(); - if (logger.isTraceEnabled() && (count != 0)) { - logger.trace("Checking " + count + " session(s) for timeouts [" + getName() + "]"); - } - for (SockJsSession session : sessions.values()) { + for (SockJsSession session : sessions.values()) { + try { if (session.getTimeSinceLastActive() > getDisconnectDelay()) { - if (logger.isTraceEnabled()) { - logger.trace("Removing " + session + " for [" + getName() + "]"); - } - session.close(); sessions.remove(session.getId()); + session.close(); } } - if (logger.isTraceEnabled() && count > 0) { - logger.trace(sessions.size() + " remaining session(s) [" + getName() + "]"); + catch (Throwable ex) { + logger.error("Failed to close " + session, ex); } } - catch (Throwable ex) { - if (logger.isErrorEnabled()) { - logger.error("Failed to complete session timeout checks for [" + getName() + "]", ex); - } + if (logger.isDebugEnabled() && !removedSessionIds.isEmpty()) { + logger.debug("Closed " + removedSessionIds.size() + " sessions " + removedSessionIds); + removedSessionIds.clear(); } } }, getDisconnectDelay()); diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpReceivingTransportHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpReceivingTransportHandler.java index c055f10c5b..e96c725bc9 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpReceivingTransportHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpReceivingTransportHandler.java @@ -37,6 +37,7 @@ import org.springframework.web.socket.sockjs.transport.session.AbstractHttpSockJ */ public abstract class AbstractHttpReceivingTransportHandler extends AbstractTransportHandler { + @Override public final void handleRequest(ServerHttpRequest request, ServerHttpResponse response, WebSocketHandler wsHandler, SockJsSession wsSession) throws SockJsException { @@ -70,16 +71,13 @@ public abstract class AbstractHttpReceivingTransportHandler extends AbstractTran handleReadError(response, "Failed to read message(s)", sockJsSession.getId()); return; } - if (messages == null) { handleReadError(response, "Payload expected.", sockJsSession.getId()); return; } - if (logger.isTraceEnabled()) { logger.trace("Received message(s): " + Arrays.asList(messages)); } - response.setStatusCode(getResponseStatus()); response.getHeaders().setContentType(new MediaType("text", "plain", UTF8_CHARSET)); diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpSendingTransportHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpSendingTransportHandler.java index d15c35a4fd..b21847ac14 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpSendingTransportHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractHttpSendingTransportHandler.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. @@ -63,12 +63,14 @@ public abstract class AbstractHttpSendingTransportHandler extends AbstractTransp if (sockJsSession.isNew()) { if (logger.isDebugEnabled()) { - logger.debug("Opening " + getTransportType() + " connection."); + logger.debug(request.getMethod() + " " + request.getURI()); } sockJsSession.handleInitialRequest(request, response, getFrameFormat(request)); } else if (sockJsSession.isClosed()) { - logger.debug("Connection already closed (but not removed yet)."); + if (logger.isDebugEnabled()) { + logger.debug("Connection already closed (but not removed yet) for " + sockJsSession); + } SockJsFrame frame = SockJsFrame.closeFrameGoAway(); try { response.getBody().write(frame.getContentBytes()); @@ -76,7 +78,6 @@ public abstract class AbstractHttpSendingTransportHandler extends AbstractTransp catch (IOException ex) { throw new SockJsException("Failed to send " + frame, sockJsSession.getId(), ex); } - return; } else if (!sockJsSession.isActive()) { if (logger.isTraceEnabled()) { @@ -86,7 +87,7 @@ public abstract class AbstractHttpSendingTransportHandler extends AbstractTransp } else { if (logger.isDebugEnabled()) { - logger.debug("Another " + getTransportType() + " connection still open: " + sockJsSession); + logger.debug("Another " + getTransportType() + " connection still open for " + sockJsSession); } String formattedFrame = getFrameFormat(request).format(SockJsFrame.closeFrameAnotherConnectionOpen()); try { diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractTransportHandler.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractTransportHandler.java index 652ec69191..6baa4a967a 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractTransportHandler.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/AbstractTransportHandler.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. @@ -32,6 +32,7 @@ public abstract class AbstractTransportHandler implements TransportHandler { protected static final Charset UTF8_CHARSET = Charset.forName("UTF-8"); + protected final Log logger = LogFactory.getLog(this.getClass()); private SockJsServiceConfig serviceConfig; diff --git a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/DefaultSockJsService.java b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/DefaultSockJsService.java index 1d3f263ed4..6a1f1ed522 100644 --- a/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/DefaultSockJsService.java +++ b/spring-websocket/src/main/java/org/springframework/web/socket/sockjs/transport/handler/DefaultSockJsService.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. @@ -90,7 +90,7 @@ public class DefaultSockJsService extends TransportHandlingSockJsService { catch (Exception ex) { Log logger = LogFactory.getLog(DefaultSockJsService.class); if (logger.isWarnEnabled()) { - logger.warn("Failed to create default WebSocketTransportHandler", ex); + logger.warn("Failed to create a default WebSocketTransportHandler", ex); } } if (overrides != null) { 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 cbc610040d..7f46f4008f 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 @@ -55,6 +55,7 @@ public abstract class AbstractSockJsSession implements SockJsSession { protected final Log logger = LogFactory.getLog(getClass()); + /** * Log category to use on network IO exceptions after a client has gone away. * @@ -65,7 +66,7 @@ public abstract class AbstractSockJsSession implements SockJsSession { * *

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 INFO level, while a full stack trace is shown at TRACE level. + * is logged at DEBUG level, while a full stack trace is shown at TRACE level. * * @see #disconnectedClientLogger */ @@ -268,8 +269,8 @@ public abstract class AbstractSockJsSession implements SockJsSession { @Override public final void close(CloseStatus status) throws IOException { if (isOpen()) { - if (logger.isInfoEnabled()) { - logger.info("Closing SockJS session " + getId() + " with " + status); + if (logger.isDebugEnabled()) { + logger.debug("Closing SockJS session " + getId() + " with " + status); } this.state = State.CLOSED; try { @@ -362,8 +363,8 @@ public abstract class AbstractSockJsSession implements SockJsSession { if (disconnectedClientLogger.isTraceEnabled()) { disconnectedClientLogger.trace("Looks like the client has gone away", failure); } - else if (disconnectedClientLogger.isInfoEnabled()) { - disconnectedClientLogger.info("Looks like the client has gone away: " + + else if (disconnectedClientLogger.isDebugEnabled()) { + disconnectedClientLogger.debug("Looks like the client has gone away: " + nestedException.getMessage() + " (For full stack trace, set the '" + DISCONNECTED_CLIENT_LOG_CATEGORY + "' log category to TRACE level)"); } @@ -426,7 +427,7 @@ public abstract class AbstractSockJsSession implements SockJsSession { @Override public String toString() { - return getClass().getSimpleName() + "[id=" + getId() + ", uri=" + getUri() + "]"; + return getClass().getSimpleName() + "[id=" + getId() + "]"; } 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 4cec12db6d..276afa3954 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 @@ -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. @@ -180,7 +180,6 @@ public class WebSocketServerSockJsSession extends AbstractSockJsSession implemen public void handleMessage(TextMessage message, WebSocketSession wsSession) throws Exception { String payload = message.getPayload(); if (StringUtils.isEmpty(payload)) { - logger.trace("Ignoring empty message"); return; } String[] messages; @@ -217,7 +216,7 @@ public class WebSocketServerSockJsSession extends AbstractSockJsSession implemen @Override protected void writeFrameInternal(SockJsFrame frame) throws IOException { if (logger.isTraceEnabled()) { - logger.trace("Write " + frame); + logger.trace("Writing " + frame); } TextMessage message = new TextMessage(frame.getContent()); this.webSocketSession.sendMessage(message); @@ -233,13 +232,4 @@ 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/sockjs/transport/handler/HttpSendingTransportHandlerTests.java b/spring-websocket/src/test/java/org/springframework/web/socket/sockjs/transport/handler/HttpSendingTransportHandlerTests.java index dcab42610e..fe308d24b1 100644 --- a/spring-websocket/src/test/java/org/springframework/web/socket/sockjs/transport/handler/HttpSendingTransportHandlerTests.java +++ b/spring-websocket/src/test/java/org/springframework/web/socket/sockjs/transport/handler/HttpSendingTransportHandlerTests.java @@ -58,6 +58,8 @@ public class HttpSendingTransportHandlerTests extends AbstractHttpRequestTests this.sockJsConfig = new StubSockJsServiceConfig(); this.sockJsConfig.setTaskScheduler(this.taskScheduler); + + setRequest("POST", "/"); } @Test @@ -100,6 +102,7 @@ public class HttpSendingTransportHandlerTests extends AbstractHttpRequestTests assertEquals("\"callback\" parameter required", this.servletResponse.getContentAsString()); resetRequestAndResponse(); + setRequest("POST", "/"); this.servletRequest.setQueryString("c=callback"); this.servletRequest.addParameter("c", "callback"); transportHandler.handleRequest(this.request, this.response, this.webSocketHandler, session); @@ -136,6 +139,7 @@ public class HttpSendingTransportHandlerTests extends AbstractHttpRequestTests assertEquals("\"callback\" parameter required", this.servletResponse.getContentAsString()); resetRequestAndResponse(); + setRequest("POST", "/"); this.servletRequest.setQueryString("c=callback"); this.servletRequest.addParameter("c", "callback"); transportHandler.handleRequest(this.request, this.response, this.webSocketHandler, session); diff --git a/src/asciidoc/index.adoc b/src/asciidoc/index.adoc index c78466ffe9..f35a9f6361 100644 --- a/src/asciidoc/index.adoc +++ b/src/asciidoc/index.adoc @@ -38700,7 +38700,7 @@ infrastructure components automatically gather stats and counters that provide important insight into the internal state of the application. The configuration also declares a bean of type `WebSocketMessageBrokerStats` that gathers all available information in one place and by default logs it at INFO once -every 15 minutes. This bean can be exported to JMX through Spring's +every 30 minutes. This bean can be exported to JMX through Spring's `MBeanExporter` for viewing at runtime for example through JDK's jconsole. Below is a summary of the available information.