Skip to content

Commit 48236be

Browse files
rstoyanchevrstoyanchev
committed
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
1 parent ab4864d commit 48236be

File tree

65 files changed

+763
-425
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

65 files changed

+763
-425
lines changed

‎spring-messaging/src/main/java/org/springframework/messaging/handler/HandlerMethod.java

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -21,7 +21,6 @@
2121

2222
import org.apache.commons.logging.Log;
2323
import org.apache.commons.logging.LogFactory;
24-
2524
import org.springframework.beans.factory.BeanFactory;
2625
import org.springframework.core.BridgeMethodResolver;
2726
import org.springframework.core.MethodParameter;
@@ -44,7 +43,6 @@
4443
*/
4544
public class HandlerMethod {
4645

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

5048
private final Object bean;
@@ -238,6 +236,11 @@ public int hashCode() {
238236
return this.bean.hashCode() * 31 + this.method.hashCode();
239237
}
240238

239+
public String getShortLogMessage() {
240+
int args = method.getParameterTypes().length;
241+
return getBeanType().getName() + "#" + this.method.getName() + "[" + args + " args]";
242+
}
243+
241244
@Override
242245
public String toString() {
243246
return this.method.toGenericString();

‎spring-messaging/src/main/java/org/springframework/messaging/handler/annotation/support/HeaderMethodArgumentResolver.java

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -80,9 +80,6 @@ private Object getNativeHeaderValue(Message<?> message, String name) {
8080

8181
if (name.startsWith("nativeHeaders.")) {
8282
name = name.substring("nativeHeaders.".length());
83-
if (logger.isDebugEnabled()) {
84-
logger.debug("Looking up native header '" + name + "'");
85-
}
8683
}
8784

8885
if ((nativeHeaders == null) || !nativeHeaders.containsKey(name)) {

‎spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/AbstractMethodMessageHandler.java

Lines changed: 19 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/*
2-
* Copyright 2002-2013 the original author or authors.
2+
* Copyright 2002-2014 the original author or authors.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License");
55
* you may not use this file except in compliance with the License.
@@ -322,26 +322,23 @@ protected HandlerMethod createHandlerMethod(Object handler, Method method) {
322322

323323
@Override
324324
public void handleMessage(Message<?> message) throws MessagingException {
325-
326325
String destination = getDestination(message);
327326
if (destination == null) {
328327
return;
329328
}
330-
331329
String lookupDestination = getLookupDestination(destination);
332330
if (lookupDestination == null) {
333331
return;
334332
}
335-
336-
if (logger.isDebugEnabled()) {
337-
logger.debug("Handling message to " + destination);
338-
}
339-
340333
MessageHeaderAccessor headerAccessor = MessageHeaderAccessor.getMutableAccessor(message);
341334
headerAccessor.setHeader(DestinationPatternsMessageCondition.LOOKUP_DESTINATION_HEADER, lookupDestination);
342335
headerAccessor.setLeaveMutable(true);
343336
message = MessageBuilder.createMessage(message.getPayload(), headerAccessor.getMessageHeaders());
344337

338+
if (logger.isDebugEnabled()) {
339+
logger.debug("Searching methods to handle " + headerAccessor.getShortLogMessage(message.getPayload()));
340+
}
341+
345342
handleMessageInternal(message, lookupDestination);
346343
headerAccessor.setImmutable();
347344
}
@@ -377,24 +374,20 @@ protected void handleMessageInternal(Message<?> message, String lookupDestinatio
377374
if (mappingsByUrl != null) {
378375
addMatchesToCollection(mappingsByUrl, message, matches);
379376
}
380-
381377
if (matches.isEmpty()) {
382378
// No direct hits, go through all mappings
383379
Set<T> allMappings = this.handlerMethods.keySet();
384380
addMatchesToCollection(allMappings, message, matches);
385381
}
386-
387382
if (matches.isEmpty()) {
388383
handleNoMatch(handlerMethods.keySet(), lookupDestination, message);
389384
return;
390385
}
391-
392386
Comparator<Match> comparator = new MatchComparator(getMappingComparator(message));
393387
Collections.sort(matches, comparator);
394388

395389
if (logger.isTraceEnabled()) {
396-
logger.trace("Found " + matches.size() + " matching mapping(s) for [" +
397-
lookupDestination + "] : " + matches);
390+
logger.trace("Found " + matches.size() + " methods: " + matches);
398391
}
399392

400393
Match bestMatch = matches.get(0);
@@ -440,18 +433,14 @@ private void addMatchesToCollection(Collection<T> mappingsToCheck, Message<?> me
440433

441434

442435
protected void handleMatch(T mapping, HandlerMethod handlerMethod, String lookupDestination, Message<?> message) {
443-
444436
if (logger.isDebugEnabled()) {
445-
logger.debug("Message matched to " + handlerMethod);
437+
logger.debug("Invoking " + handlerMethod.getShortLogMessage());
446438
}
447-
448439
handlerMethod = handlerMethod.createWithResolvedBean();
449440
InvocableHandlerMethod invocable = new InvocableHandlerMethod(handlerMethod);
450441
invocable.setMessageMethodArgumentResolvers(this.argumentResolvers);
451-
452442
try {
453443
Object returnValue = invocable.invoke(message);
454-
455444
MethodParameter returnType = handlerMethod.getReturnType();
456445
if (void.class.equals(returnType.getParameterType())) {
457446
return;
@@ -467,26 +456,27 @@ protected void handleMatch(T mapping, HandlerMethod handlerMethod, String lookup
467456
}
468457

469458
protected void processHandlerMethodException(HandlerMethod handlerMethod, Exception ex, Message<?> message) {
470-
459+
if (logger.isDebugEnabled()) {
460+
logger.debug("Searching methods to handle " + ex.getClass().getSimpleName());
461+
}
471462
Class<?> beanType = handlerMethod.getBeanType();
472463
AbstractExceptionHandlerMethodResolver resolver = this.exceptionHandlerCache.get(beanType);
473464
if (resolver == null) {
474465
resolver = createExceptionHandlerMethodResolverFor(beanType);
475466
this.exceptionHandlerCache.put(beanType, resolver);
476467
}
477-
478468
Method method = resolver.resolveMethod(ex);
479469
if (method == null) {
480470
logger.error("Unhandled exception", ex);
481471
return;
482472
}
483-
484473
InvocableHandlerMethod invocable = new InvocableHandlerMethod(handlerMethod.getBean(), method);
485474
invocable.setMessageMethodArgumentResolvers(this.argumentResolvers);
486-
475+
if (logger.isDebugEnabled()) {
476+
logger.debug("Invoking " + invocable.getShortLogMessage());
477+
}
487478
try {
488479
Object returnValue = invocable.invoke(message, ex);
489-
490480
MethodParameter returnType = invocable.getReturnType();
491481
if (void.class.equals(returnType.getParameterType())) {
492482
return;
@@ -497,17 +487,21 @@ protected void processHandlerMethodException(HandlerMethod handlerMethod, Except
497487
logger.error("Error while handling exception", t);
498488
return;
499489
}
500-
501490
}
502491

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

505494
protected void handleNoMatch(Set<T> ts, String lookupDestination, Message<?> message) {
506495
if (logger.isDebugEnabled()) {
507-
logger.debug("No matching method found.");
496+
logger.debug("No matching methods.");
508497
}
509498
}
510499

500+
@Override
501+
public String toString() {
502+
return getClass().getSimpleName() + "[prefixes=" + getDestinationPrefixes() + "]";
503+
}
504+
511505

512506
/**
513507
* A thin wrapper around a matched HandlerMethod and its matched mapping for

‎spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodArgumentResolverComposite.java

Lines changed: 1 addition & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/*
2-
* Copyright 2002-2012 the original author or authors.
2+
* Copyright 2002-2014 the original author or authors.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License");
55
* you may not use this file except in compliance with the License.
@@ -22,8 +22,6 @@
2222
import java.util.Map;
2323
import java.util.concurrent.ConcurrentHashMap;
2424

25-
import org.apache.commons.logging.Log;
26-
import org.apache.commons.logging.LogFactory;
2725
import org.springframework.core.MethodParameter;
2826
import org.springframework.messaging.Message;
2927
import org.springframework.util.Assert;
@@ -38,8 +36,6 @@
3836
*/
3937
public class HandlerMethodArgumentResolverComposite implements HandlerMethodArgumentResolver {
4038

41-
protected final Log logger = LogFactory.getLog(getClass());
42-
4339
private final List<HandlerMethodArgumentResolver> argumentResolvers = new LinkedList<HandlerMethodArgumentResolver>();
4440

4541
private final Map<MethodParameter, HandlerMethodArgumentResolver> argumentResolverCache =

‎spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/HandlerMethodReturnValueHandlerComposite.java

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,8 @@
2727
import org.springframework.util.Assert;
2828

2929
/**
30+
* A HandlerMethodReturnValueHandler that wraps and delegates to others.
31+
*
3032
* @author Rossen Stoyanchev
3133
* @since 4.0
3234
*/
@@ -79,9 +81,6 @@ public boolean supportsReturnType(MethodParameter returnType) {
7981
private HandlerMethodReturnValueHandler getReturnValueHandler(MethodParameter returnType) {
8082
for (HandlerMethodReturnValueHandler handler : this.returnValueHandlers) {
8183
if (handler.supportsReturnType(returnType)) {
82-
if (logger.isTraceEnabled()) {
83-
logger.trace("Processing return value with " + handler);
84-
}
8584
return handler;
8685
}
8786
}
@@ -94,6 +93,9 @@ public void handleReturnValue(Object returnValue, MethodParameter returnType, Me
9493

9594
HandlerMethodReturnValueHandler handler = getReturnValueHandler(returnType);
9695
Assert.notNull(handler, "No handler for return value type [" + returnType.getParameterType().getName() + "]");
96+
if (logger.isTraceEnabled()) {
97+
logger.trace("Processing return value with " + handler);
98+
}
9799
handler.handleReturnValue(returnValue, returnType, message);
98100
}
99101

‎spring-messaging/src/main/java/org/springframework/messaging/handler/invocation/InvocableHandlerMethod.java

Lines changed: 4 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -96,15 +96,11 @@ public void setParameterNameDiscoverer(ParameterNameDiscoverer parameterNameDisc
9696
public final Object invoke(Message<?> message, Object... providedArgs) throws Exception {
9797
Object[] args = getMethodArgumentValues(message, providedArgs);
9898
if (logger.isTraceEnabled()) {
99-
StringBuilder sb = new StringBuilder("Invoking [");
100-
sb.append(getBeanType().getSimpleName()).append(".");
101-
sb.append(getMethod().getName()).append("] method with arguments ");
102-
sb.append(Arrays.asList(args));
103-
logger.trace(sb.toString());
99+
logger.trace("Resolved arguments: " + Arrays.asList(args));
104100
}
105101
Object returnValue = invoke(args);
106102
if (logger.isTraceEnabled()) {
107-
logger.trace("Method [" + getMethod().getName() + "] returned [" + returnValue + "]");
103+
logger.trace("Returned value: " + returnValue);
108104
}
109105
return returnValue;
110106
}
@@ -136,8 +132,8 @@ private Object[] getMethodArgumentValues(Message<?> message, Object... providedA
136132
}
137133
}
138134
if (args[i] == null) {
139-
String msg = getArgumentResolutionErrorMessage("No suitable resolver for argument", i);
140-
throw new IllegalStateException(msg);
135+
String error = getArgumentResolutionErrorMessage("No suitable resolver for argument", i);
136+
throw new IllegalStateException(error);
141137
}
142138
}
143139
return args;

‎spring-messaging/src/main/java/org/springframework/messaging/simp/SimpAttributes.java

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -72,9 +72,11 @@ public static SimpAttributes fromMessage(Message<?> message) {
7272
MessageHeaders headers = message.getHeaders();
7373
String sessionId = SimpMessageHeaderAccessor.getSessionId(headers);
7474
Map<String, Object> sessionAttributes = SimpMessageHeaderAccessor.getSessionAttributes(headers);
75-
if (sessionId == null || sessionAttributes == null) {
76-
throw new IllegalStateException(
77-
"Message does not contain SiMP session id or attributes: " + message);
75+
if (sessionId == null) {
76+
throw new IllegalStateException("No session id in " + message);
77+
}
78+
if (sessionAttributes == null) {
79+
throw new IllegalStateException("No session attributes in " + message);
7880
}
7981
return new SimpAttributes(sessionId, sessionAttributes);
8082
}

‎spring-messaging/src/main/java/org/springframework/messaging/simp/SimpMessageHeaderAccessor.java

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,11 +20,13 @@
2020
import java.util.List;
2121
import java.util.Map;
2222

23+
import org.apache.commons.logging.Log;
2324
import org.springframework.messaging.Message;
2425
import org.springframework.messaging.support.IdTimestampMessageHeaderInitializer;
2526
import org.springframework.messaging.support.MessageHeaderAccessor;
2627
import org.springframework.messaging.support.NativeMessageHeaderAccessor;
2728
import org.springframework.util.Assert;
29+
import org.springframework.util.CollectionUtils;
2830

2931
/**
3032
* A base class for working with message headers in simple messaging protocols that
@@ -241,4 +243,50 @@ public static Principal getUser(Map<String, Object> headers) {
241243
return (Principal) headers.get(USER_HEADER);
242244
}
243245

246+
@Override
247+
public String getShortLogMessage(Object payload) {
248+
if (getMessageType() == null) {
249+
return super.getDetailedLogMessage(payload);
250+
}
251+
StringBuilder sb = getBaseLogMessage();
252+
if (!CollectionUtils.isEmpty(getSessionAttributes())) {
253+
sb.append(" attributes[").append(getSessionAttributes().size()).append("]");
254+
}
255+
sb.append(getShortPayloadLogMessage(payload));
256+
return sb.toString();
257+
}
258+
259+
@SuppressWarnings("unchecked")
260+
@Override
261+
public String getDetailedLogMessage(Object payload) {
262+
if (getMessageType() == null) {
263+
return super.getDetailedLogMessage(payload);
264+
}
265+
StringBuilder sb = getBaseLogMessage();
266+
if (!CollectionUtils.isEmpty(getSessionAttributes())) {
267+
sb.append(" attributes=").append(getSessionAttributes());
268+
}
269+
if (!CollectionUtils.isEmpty((Map<String, List<String>>) getHeader(NATIVE_HEADERS))) {
270+
sb.append(" nativeHeaders=").append((Map<String, List<String>>) getHeader(NATIVE_HEADERS));
271+
}
272+
sb.append(getDetailedPayloadLogMessage(payload));
273+
return sb.toString();
274+
}
275+
276+
private StringBuilder getBaseLogMessage() {
277+
StringBuilder sb = new StringBuilder();
278+
sb.append(getMessageType().name());
279+
if (getDestination() != null) {
280+
sb.append(" destination=").append(getDestination());
281+
}
282+
if (getSubscriptionId() != null) {
283+
sb.append(" subscriptionId=").append(getSubscriptionId());
284+
}
285+
sb.append(" session=").append(getSessionId());
286+
if (getUser() != null) {
287+
sb.append(" user=").append(getUser().getName());
288+
}
289+
return sb;
290+
}
291+
244292
}

‎spring-messaging/src/main/java/org/springframework/messaging/simp/annotation/support/SendToMethodReturnValueHandler.java

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -137,7 +137,6 @@ public void handleReturnValue(Object returnValue, MethodParameter returnType, Me
137137
if (returnValue == null) {
138138
return;
139139
}
140-
141140
MessageHeaders headers = message.getHeaders();
142141
String sessionId = SimpMessageHeaderAccessor.getSessionId(headers);
143142

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

184182
protected String[] getTargetDestinations(Annotation annotation, Message<?> message, String defaultPrefix) {
185-
186183
if (annotation != null) {
187184
String[] value = (String[]) AnnotationUtils.getValue(annotation);
188185
if (!ObjectUtils.isEmpty(value)) {

0 commit comments

Comments
 (0)