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