001/* 002 * Copyright 2002-2017 the original author or authors. 003 * 004 * Licensed under the Apache License, Version 2.0 (the "License"); 005 * you may not use this file except in compliance with the License. 006 * You may obtain a copy of the License at 007 * 008 * https://www.apache.org/licenses/LICENSE-2.0 009 * 010 * Unless required by applicable law or agreed to in writing, software 011 * distributed under the License is distributed on an "AS IS" BASIS, 012 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 013 * See the License for the specific language governing permissions and 014 * limitations under the License. 015 */ 016 017package org.springframework.aop.interceptor; 018 019import java.util.Set; 020import java.util.regex.Matcher; 021import java.util.regex.Pattern; 022 023import org.aopalliance.intercept.MethodInvocation; 024import org.apache.commons.logging.Log; 025 026import org.springframework.core.Constants; 027import org.springframework.util.Assert; 028import org.springframework.util.ClassUtils; 029import org.springframework.util.StopWatch; 030import org.springframework.util.StringUtils; 031 032/** 033 * {@code MethodInterceptor} implementation that allows for highly customizable 034 * method-level tracing, using placeholders. 035 * 036 * <p>Trace messages are written on method entry, and if the method invocation succeeds 037 * on method exit. If an invocation results in an exception, then an exception message 038 * is written. The contents of these trace messages is fully customizable and special 039 * placeholders are available to allow you to include runtime information in your log 040 * messages. The placeholders available are: 041 * 042 * <p><ul> 043 * <li>{@code $[methodName]} - replaced with the name of the method being invoked</li> 044 * <li>{@code $[targetClassName]} - replaced with the name of the class that is 045 * the target of the invocation</li> 046 * <li>{@code $[targetClassShortName]} - replaced with the short name of the class 047 * that is the target of the invocation</li> 048 * <li>{@code $[returnValue]} - replaced with the value returned by the invocation</li> 049 * <li>{@code $[argumentTypes]} - replaced with a comma-separated list of the 050 * short class names of the method arguments</li> 051 * <li>{@code $[arguments]} - replaced with a comma-separated list of the 052 * {@code String} representation of the method arguments</li> 053 * <li>{@code $[exception]} - replaced with the {@code String} representation 054 * of any {@code Throwable} raised during the invocation</li> 055 * <li>{@code $[invocationTime]} - replaced with the time, in milliseconds, 056 * taken by the method invocation</li> 057 * </ul> 058 * 059 * <p>There are restrictions on which placeholders can be used in which messages: 060 * see the individual message properties for details on the valid placeholders. 061 * 062 * @author Rob Harrop 063 * @author Juergen Hoeller 064 * @since 1.2 065 * @see #setEnterMessage 066 * @see #setExitMessage 067 * @see #setExceptionMessage 068 * @see SimpleTraceInterceptor 069 */ 070@SuppressWarnings("serial") 071public class CustomizableTraceInterceptor extends AbstractTraceInterceptor { 072 073 /** 074 * The {@code $[methodName]} placeholder. 075 * Replaced with the name of the method being invoked. 076 */ 077 public static final String PLACEHOLDER_METHOD_NAME = "$[methodName]"; 078 079 /** 080 * The {@code $[targetClassName]} placeholder. 081 * Replaced with the fully-qualifed name of the {@code Class} 082 * of the method invocation target. 083 */ 084 public static final String PLACEHOLDER_TARGET_CLASS_NAME = "$[targetClassName]"; 085 086 /** 087 * The {@code $[targetClassShortName]} placeholder. 088 * Replaced with the short name of the {@code Class} of the 089 * method invocation target. 090 */ 091 public static final String PLACEHOLDER_TARGET_CLASS_SHORT_NAME = "$[targetClassShortName]"; 092 093 /** 094 * The {@code $[returnValue]} placeholder. 095 * Replaced with the {@code String} representation of the value 096 * returned by the method invocation. 097 */ 098 public static final String PLACEHOLDER_RETURN_VALUE = "$[returnValue]"; 099 100 /** 101 * The {@code $[argumentTypes]} placeholder. 102 * Replaced with a comma-separated list of the argument types for the 103 * method invocation. Argument types are written as short class names. 104 */ 105 public static final String PLACEHOLDER_ARGUMENT_TYPES = "$[argumentTypes]"; 106 107 /** 108 * The {@code $[arguments]} placeholder. 109 * Replaced with a comma separated list of the argument values for the 110 * method invocation. Relies on the {@code toString()} method of 111 * each argument type. 112 */ 113 public static final String PLACEHOLDER_ARGUMENTS = "$[arguments]"; 114 115 /** 116 * The {@code $[exception]} placeholder. 117 * Replaced with the {@code String} representation of any 118 * {@code Throwable} raised during method invocation. 119 */ 120 public static final String PLACEHOLDER_EXCEPTION = "$[exception]"; 121 122 /** 123 * The {@code $[invocationTime]} placeholder. 124 * Replaced with the time taken by the invocation (in milliseconds). 125 */ 126 public static final String PLACEHOLDER_INVOCATION_TIME = "$[invocationTime]"; 127 128 /** 129 * The default message used for writing method entry messages. 130 */ 131 private static final String DEFAULT_ENTER_MESSAGE = "Entering method '" + 132 PLACEHOLDER_METHOD_NAME + "' of class [" + PLACEHOLDER_TARGET_CLASS_NAME + "]"; 133 134 /** 135 * The default message used for writing method exit messages. 136 */ 137 private static final String DEFAULT_EXIT_MESSAGE = "Exiting method '" + 138 PLACEHOLDER_METHOD_NAME + "' of class [" + PLACEHOLDER_TARGET_CLASS_NAME + "]"; 139 140 /** 141 * The default message used for writing exception messages. 142 */ 143 private static final String DEFAULT_EXCEPTION_MESSAGE = "Exception thrown in method '" + 144 PLACEHOLDER_METHOD_NAME + "' of class [" + PLACEHOLDER_TARGET_CLASS_NAME + "]"; 145 146 /** 147 * The {@code Pattern} used to match placeholders. 148 */ 149 private static final Pattern PATTERN = Pattern.compile("\\$\\[\\p{Alpha}+\\]"); 150 151 /** 152 * The {@code Set} of allowed placeholders. 153 */ 154 private static final Set<Object> ALLOWED_PLACEHOLDERS = 155 new Constants(CustomizableTraceInterceptor.class).getValues("PLACEHOLDER_"); 156 157 158 /** 159 * The message for method entry. 160 */ 161 private String enterMessage = DEFAULT_ENTER_MESSAGE; 162 163 /** 164 * The message for method exit. 165 */ 166 private String exitMessage = DEFAULT_EXIT_MESSAGE; 167 168 /** 169 * The message for exceptions during method execution. 170 */ 171 private String exceptionMessage = DEFAULT_EXCEPTION_MESSAGE; 172 173 174 /** 175 * Set the template used for method entry log messages. 176 * This template can contain any of the following placeholders: 177 * <ul> 178 * <li>{@code $[targetClassName]}</li> 179 * <li>{@code $[targetClassShortName]}</li> 180 * <li>{@code $[argumentTypes]}</li> 181 * <li>{@code $[arguments]}</li> 182 * </ul> 183 */ 184 public void setEnterMessage(String enterMessage) throws IllegalArgumentException { 185 Assert.hasText(enterMessage, "enterMessage must not be empty"); 186 checkForInvalidPlaceholders(enterMessage); 187 Assert.doesNotContain(enterMessage, PLACEHOLDER_RETURN_VALUE, 188 "enterMessage cannot contain placeholder " + PLACEHOLDER_RETURN_VALUE); 189 Assert.doesNotContain(enterMessage, PLACEHOLDER_EXCEPTION, 190 "enterMessage cannot contain placeholder " + PLACEHOLDER_EXCEPTION); 191 Assert.doesNotContain(enterMessage, PLACEHOLDER_INVOCATION_TIME, 192 "enterMessage cannot contain placeholder " + PLACEHOLDER_INVOCATION_TIME); 193 this.enterMessage = enterMessage; 194 } 195 196 /** 197 * Set the template used for method exit log messages. 198 * This template can contain any of the following placeholders: 199 * <ul> 200 * <li>{@code $[targetClassName]}</li> 201 * <li>{@code $[targetClassShortName]}</li> 202 * <li>{@code $[argumentTypes]}</li> 203 * <li>{@code $[arguments]}</li> 204 * <li>{@code $[returnValue]}</li> 205 * <li>{@code $[invocationTime]}</li> 206 * </ul> 207 */ 208 public void setExitMessage(String exitMessage) { 209 Assert.hasText(exitMessage, "exitMessage must not be empty"); 210 checkForInvalidPlaceholders(exitMessage); 211 Assert.doesNotContain(exitMessage, PLACEHOLDER_EXCEPTION, 212 "exitMessage cannot contain placeholder" + PLACEHOLDER_EXCEPTION); 213 this.exitMessage = exitMessage; 214 } 215 216 /** 217 * Set the template used for method exception log messages. 218 * This template can contain any of the following placeholders: 219 * <ul> 220 * <li>{@code $[targetClassName]}</li> 221 * <li>{@code $[targetClassShortName]}</li> 222 * <li>{@code $[argumentTypes]}</li> 223 * <li>{@code $[arguments]}</li> 224 * <li>{@code $[exception]}</li> 225 * </ul> 226 */ 227 public void setExceptionMessage(String exceptionMessage) { 228 Assert.hasText(exceptionMessage, "exceptionMessage must not be empty"); 229 checkForInvalidPlaceholders(exceptionMessage); 230 Assert.doesNotContain(exceptionMessage, PLACEHOLDER_RETURN_VALUE, 231 "exceptionMessage cannot contain placeholder " + PLACEHOLDER_RETURN_VALUE); 232 this.exceptionMessage = exceptionMessage; 233 } 234 235 236 /** 237 * Writes a log message before the invocation based on the value of {@code enterMessage}. 238 * If the invocation succeeds, then a log message is written on exit based on the value 239 * {@code exitMessage}. If an exception occurs during invocation, then a message is 240 * written based on the value of {@code exceptionMessage}. 241 * @see #setEnterMessage 242 * @see #setExitMessage 243 * @see #setExceptionMessage 244 */ 245 @Override 246 protected Object invokeUnderTrace(MethodInvocation invocation, Log logger) throws Throwable { 247 String name = ClassUtils.getQualifiedMethodName(invocation.getMethod()); 248 StopWatch stopWatch = new StopWatch(name); 249 Object returnValue = null; 250 boolean exitThroughException = false; 251 try { 252 stopWatch.start(name); 253 writeToLog(logger, 254 replacePlaceholders(this.enterMessage, invocation, null, null, -1)); 255 returnValue = invocation.proceed(); 256 return returnValue; 257 } 258 catch (Throwable ex) { 259 if (stopWatch.isRunning()) { 260 stopWatch.stop(); 261 } 262 exitThroughException = true; 263 writeToLog(logger, replacePlaceholders( 264 this.exceptionMessage, invocation, null, ex, stopWatch.getTotalTimeMillis()), ex); 265 throw ex; 266 } 267 finally { 268 if (!exitThroughException) { 269 if (stopWatch.isRunning()) { 270 stopWatch.stop(); 271 } 272 writeToLog(logger, replacePlaceholders( 273 this.exitMessage, invocation, returnValue, null, stopWatch.getTotalTimeMillis())); 274 } 275 } 276 } 277 278 /** 279 * Replace the placeholders in the given message with the supplied values, 280 * or values derived from those supplied. 281 * @param message the message template containing the placeholders to be replaced 282 * @param methodInvocation the {@code MethodInvocation} being logged. 283 * Used to derive values for all placeholders except {@code $[exception]} 284 * and {@code $[returnValue]}. 285 * @param returnValue any value returned by the invocation. 286 * Used to replace the {@code $[returnValue]} placeholder. May be {@code null}. 287 * @param throwable any {@code Throwable} raised during the invocation. 288 * The value of {@code Throwable.toString()} is replaced for the 289 * {@code $[exception]} placeholder. May be {@code null}. 290 * @param invocationTime the value to write in place of the 291 * {@code $[invocationTime]} placeholder 292 * @return the formatted output to write to the log 293 */ 294 protected String replacePlaceholders(String message, MethodInvocation methodInvocation, 295 Object returnValue, Throwable throwable, long invocationTime) { 296 297 Matcher matcher = PATTERN.matcher(message); 298 299 StringBuffer output = new StringBuffer(); 300 while (matcher.find()) { 301 String match = matcher.group(); 302 if (PLACEHOLDER_METHOD_NAME.equals(match)) { 303 matcher.appendReplacement(output, Matcher.quoteReplacement(methodInvocation.getMethod().getName())); 304 } 305 else if (PLACEHOLDER_TARGET_CLASS_NAME.equals(match)) { 306 String className = getClassForLogging(methodInvocation.getThis()).getName(); 307 matcher.appendReplacement(output, Matcher.quoteReplacement(className)); 308 } 309 else if (PLACEHOLDER_TARGET_CLASS_SHORT_NAME.equals(match)) { 310 String shortName = ClassUtils.getShortName(getClassForLogging(methodInvocation.getThis())); 311 matcher.appendReplacement(output, Matcher.quoteReplacement(shortName)); 312 } 313 else if (PLACEHOLDER_ARGUMENTS.equals(match)) { 314 matcher.appendReplacement(output, 315 Matcher.quoteReplacement(StringUtils.arrayToCommaDelimitedString(methodInvocation.getArguments()))); 316 } 317 else if (PLACEHOLDER_ARGUMENT_TYPES.equals(match)) { 318 appendArgumentTypes(methodInvocation, matcher, output); 319 } 320 else if (PLACEHOLDER_RETURN_VALUE.equals(match)) { 321 appendReturnValue(methodInvocation, matcher, output, returnValue); 322 } 323 else if (throwable != null && PLACEHOLDER_EXCEPTION.equals(match)) { 324 matcher.appendReplacement(output, Matcher.quoteReplacement(throwable.toString())); 325 } 326 else if (PLACEHOLDER_INVOCATION_TIME.equals(match)) { 327 matcher.appendReplacement(output, Long.toString(invocationTime)); 328 } 329 else { 330 // Should not happen since placeholders are checked earlier. 331 throw new IllegalArgumentException("Unknown placeholder [" + match + "]"); 332 } 333 } 334 matcher.appendTail(output); 335 336 return output.toString(); 337 } 338 339 /** 340 * Adds the {@code String} representation of the method return value 341 * to the supplied {@code StringBuffer}. Correctly handles 342 * {@code null} and {@code void} results. 343 * @param methodInvocation the {@code MethodInvocation} that returned the value 344 * @param matcher the {@code Matcher} containing the matched placeholder 345 * @param output the {@code StringBuffer} to write output to 346 * @param returnValue the value returned by the method invocation. 347 */ 348 private void appendReturnValue( 349 MethodInvocation methodInvocation, Matcher matcher, StringBuffer output, Object returnValue) { 350 351 if (methodInvocation.getMethod().getReturnType() == void.class) { 352 matcher.appendReplacement(output, "void"); 353 } 354 else if (returnValue == null) { 355 matcher.appendReplacement(output, "null"); 356 } 357 else { 358 matcher.appendReplacement(output, Matcher.quoteReplacement(returnValue.toString())); 359 } 360 } 361 362 /** 363 * Adds a comma-separated list of the short {@code Class} names of the 364 * method argument types to the output. For example, if a method has signature 365 * {@code put(java.lang.String, java.lang.Object)} then the value returned 366 * will be {@code String, Object}. 367 * @param methodInvocation the {@code MethodInvocation} being logged. 368 * Arguments will be retrieved from the corresponding {@code Method}. 369 * @param matcher the {@code Matcher} containing the state of the output 370 * @param output the {@code StringBuffer} containing the output 371 */ 372 private void appendArgumentTypes(MethodInvocation methodInvocation, Matcher matcher, StringBuffer output) { 373 Class<?>[] argumentTypes = methodInvocation.getMethod().getParameterTypes(); 374 String[] argumentTypeShortNames = new String[argumentTypes.length]; 375 for (int i = 0; i < argumentTypeShortNames.length; i++) { 376 argumentTypeShortNames[i] = ClassUtils.getShortName(argumentTypes[i]); 377 } 378 matcher.appendReplacement(output, 379 Matcher.quoteReplacement(StringUtils.arrayToCommaDelimitedString(argumentTypeShortNames))); 380 } 381 382 /** 383 * Checks to see if the supplied {@code String} has any placeholders 384 * that are not specified as constants on this class and throws an 385 * {@code IllegalArgumentException} if so. 386 */ 387 private void checkForInvalidPlaceholders(String message) throws IllegalArgumentException { 388 Matcher matcher = PATTERN.matcher(message); 389 while (matcher.find()) { 390 String match = matcher.group(); 391 if (!ALLOWED_PLACEHOLDERS.contains(match)) { 392 throw new IllegalArgumentException("Placeholder [" + match + "] is not valid"); 393 } 394 } 395 } 396 397}