Skip to content

Commit

Permalink
STOMP and WebSocket messaging related logging updates
Browse files Browse the repository at this point in the history 
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
  • Loading branch information
@rstoyanchev
rstoyanchev committed Jul 9, 2014
1 parent ab4864d commit 48236be
Show file tree
Hide file tree
Showing 65 changed files with 763 additions and 425 deletions.
7 changes: 5 additions & 2 deletions spring-messaging/src/main/java/org/springframework/messaging/handler/HandlerMethod.java
View file
Expand Up @@ -21,7 +21,6 @@

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;
Expand All @@ -44,7 +43,6 @@
*/
public class HandlerMethod {

/** Logger that is available to subclasses */
protected final Log logger = LogFactory.getLog(HandlerMethod.class);

private final Object bean;
Expand Down Expand Up @@ -238,6 +236,11 @@ public int hashCode() {
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();
Expand Down
3 changes: 0 additions & 3 deletions ...rg/springframework/messaging/handler/annotation/support/HeaderMethodArgumentResolver.java
View file
Expand Up @@ -80,9 +80,6 @@ private Object getNativeHeaderValue(Message<?> message, String name) {

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)) {
Expand Down
44 changes: 19 additions & 25 deletions ...n/java/org/springframework/messaging/handler/invocation/AbstractMethodMessageHandler.java
View file
@@ -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.
Expand Down Expand Up @@ -322,26 +322,23 @@ protected HandlerMethod createHandlerMethod(Object handler, Method method) {

@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();
}
Expand Down Expand Up @@ -377,24 +374,20 @@ protected void handleMessageInternal(Message<?> message, String lookupDestinatio
if (mappingsByUrl != null) {
addMatchesToCollection(mappingsByUrl, message, matches);
}

if (matches.isEmpty()) {
// No direct hits, go through all mappings
Set<T> allMappings = this.handlerMethods.keySet();
addMatchesToCollection(allMappings, message, matches);
}

if (matches.isEmpty()) {
handleNoMatch(handlerMethods.keySet(), lookupDestination, message);
return;
}

Comparator<Match> 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);
Expand Down Expand Up @@ -440,18 +433,14 @@ private void addMatchesToCollection(Collection<T> mappingsToCheck, Message<?> me


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;
Expand All @@ -467,26 +456,27 @@ protected void handleMatch(T mapping, HandlerMethod handlerMethod, String lookup
}

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;
Expand All @@ -497,17 +487,21 @@ protected void processHandlerMethodException(HandlerMethod handlerMethod, Except
logger.error("Error while handling exception", t);
return;
}

}

protected abstract AbstractExceptionHandlerMethodResolver createExceptionHandlerMethodResolverFor(Class<?> beanType);

protected void handleNoMatch(Set<T> 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
Expand Down
6 changes: 1 addition & 5 deletions .../springframework/messaging/handler/invocation/HandlerMethodArgumentResolverComposite.java
View file
@@ -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.
Expand All @@ -22,8 +22,6 @@
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;
Expand All @@ -38,8 +36,6 @@
*/
public class HandlerMethodArgumentResolverComposite implements HandlerMethodArgumentResolver {

protected final Log logger = LogFactory.getLog(getClass());

private final List<HandlerMethodArgumentResolver> argumentResolvers = new LinkedList<HandlerMethodArgumentResolver>();

private final Map<MethodParameter, HandlerMethodArgumentResolver> argumentResolverCache =
Expand Down
8 changes: 5 additions & 3 deletions ...pringframework/messaging/handler/invocation/HandlerMethodReturnValueHandlerComposite.java
View file
Expand Up @@ -27,6 +27,8 @@
import org.springframework.util.Assert;

/**
* A HandlerMethodReturnValueHandler that wraps and delegates to others.
*
* @author Rossen Stoyanchev
* @since 4.0
*/
Expand Down Expand Up @@ -79,9 +81,6 @@ public boolean supportsReturnType(MethodParameter returnType) {
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;
}
}
Expand All @@ -94,6 +93,9 @@ public void handleReturnValue(Object returnValue, MethodParameter returnType, Me

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

Expand Down
12 changes: 4 additions & 8 deletions ...rc/main/java/org/springframework/messaging/handler/invocation/InvocableHandlerMethod.java
View file
Expand Up @@ -96,15 +96,11 @@ public void setParameterNameDiscoverer(ParameterNameDiscoverer parameterNameDisc
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;
}
Expand Down Expand Up @@ -136,8 +132,8 @@ private Object[] getMethodArgumentValues(Message<?> message, Object... providedA
}
}
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;
Expand Down
8 changes: 5 additions & 3 deletions spring-messaging/src/main/java/org/springframework/messaging/simp/SimpAttributes.java
View file
Expand Up @@ -72,9 +72,11 @@ public static SimpAttributes fromMessage(Message<?> message) {
MessageHeaders headers = message.getHeaders();
String sessionId = SimpMessageHeaderAccessor.getSessionId(headers);
Map<String, Object> 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);
}
Expand Down
48 changes: 48 additions & 0 deletions ...messaging/src/main/java/org/springframework/messaging/simp/SimpMessageHeaderAccessor.java
View file
Expand Up @@ -20,11 +20,13 @@
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
Expand Down Expand Up @@ -241,4 +243,50 @@ public static Principal getUser(Map<String, Object> headers) {
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<String, List<String>>) getHeader(NATIVE_HEADERS))) {
sb.append(" nativeHeaders=").append((Map<String, List<String>>) 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;
}

}
3 changes: 0 additions & 3 deletions ...org/springframework/messaging/simp/annotation/support/SendToMethodReturnValueHandler.java
View file
Expand Up @@ -137,7 +137,6 @@ public void handleReturnValue(Object returnValue, MethodParameter returnType, Me
if (returnValue == null) {
return;
}

MessageHeaders headers = message.getHeaders();
String sessionId = SimpMessageHeaderAccessor.getSessionId(headers);

Expand All @@ -161,7 +160,6 @@ public void handleReturnValue(Object returnValue, MethodParameter returnType, Me
this.messagingTemplate.convertAndSendToUser(user, destination, returnValue, createHeaders(sessionId));
}
}
return;
}
else {
SendTo sendTo = returnType.getMethodAnnotation(SendTo.class);
Expand All @@ -182,7 +180,6 @@ protected String getUserName(Message<?> message, MessageHeaders headers) {
}

protected String[] getTargetDestinations(Annotation annotation, Message<?> message, String defaultPrefix) {

if (annotation != null) {
String[] value = (String[]) AnnotationUtils.getValue(annotation);
if (!ObjectUtils.isEmpty(value)) {
Expand Down

0 comments on commit 48236be

Please sign in to comment.