1 /*
2 * Copyright (c) 2002-2006 by OpenSymphony
3 * All rights reserved.
4 */
5 package com.opensymphony.xwork2.interceptor;
6
7 import com.opensymphony.xwork2.ActionInvocation;
8 import com.opensymphony.xwork2.util.logging.Logger;
9 import com.opensymphony.xwork2.util.logging.LoggerFactory;
10
11 /**
12 * <!-- START SNIPPET: description -->
13 * This interceptor logs the amount of time in milliseconds. In order for this interceptor to work properly, the
14 * logging framework must be set to at least the <tt>INFO</tt> level.
15 * This interceptor relies on the <a href="http://jakarta.apache.org/commons/logging/">Commons Logging API</a> to
16 * report its execution-time value.
17 * <!-- END SNIPPET: description -->
18 *
19 * <!-- START SNIPPET: parameters -->
20 *
21 * <ul>
22 *
23 * <li>logLevel (optional) - what log level should we use (<code>trace, debug, info, warn, error, fatal</code>)? - defaut is <code>info</code></li>
24 *
25 * <li>logCategory (optional) - If provided we would use this category (eg. <code>com.mycompany.app</code>).
26 * Default is to use <code>com.opensymphony.xwork2.interceptor.TimerInterceptor</code>.</li>
27 *
28 * </ul>
29 *
30 * The parameters above enables us to log all action execution times in our own logfile.
31 *
32 * <!-- END SNIPPET: parameters -->
33 *
34 * <!-- START SNIPPET: extending -->
35 * This interceptor can be extended to provide custom message format. Users should override the
36 * <code>invokeUnderTiming</code> method.
37 * <!-- END SNIPPET: extending -->
38 *
39 * <pre>
40 * <!-- START SNIPPET: example -->
41 * <!-- records only the action's execution time -->
42 * <action name="someAction" class="com.examples.SomeAction">
43 * <interceptor-ref name="completeStack"/>
44 * <interceptor-ref name="timer"/>
45 * <result name="success">good_result.ftl</result>
46 * </action>
47 *
48 * <!-- records action's execution time as well as other interceptors-->
49 * <action name="someAction" class="com.examples.SomeAction">
50 * <interceptor-ref name="timer"/>
51 * <interceptor-ref name="completeStack"/>
52 * <result name="success">good_result.ftl</result>
53 * </action>
54 * <!-- END SNIPPET: example -->
55 * </pre>
56 *
57 * This second example uses our own log category at debug level.
58 *
59 * <pre>
60 * <!-- START SNIPPET: example2 -->
61 * <!-- records only the action's execution time -->
62 * <action name="someAction" class="com.examples.SomeAction">
63 * <interceptor-ref name="completeStack"/>
64 * <interceptor-ref name="timer">
65 * <param name="logLevel">debug</param>
66 * <param name="logCategory">com.mycompany.myapp.actiontime</param>
67 * <interceptor-ref/>
68 * <result name="success">good_result.ftl</result>
69 * </action>
70 *
71 * <!-- records action's execution time as well as other interceptors-->
72 * <action name="someAction" class="com.examples.SomeAction">
73 * <interceptor-ref name="timer"/>
74 * <interceptor-ref name="completeStack"/>
75 * <result name="success">good_result.ftl</result>
76 * </action>
77 * <!-- END SNIPPET: example2 -->
78 * </pre>
79 *
80 * @author Jason Carreira
81 * @author Claus Ibsen
82 */
83 public class TimerInterceptor extends AbstractInterceptor {
84 protected static final Logger LOG = LoggerFactory.getLogger(TimerInterceptor.class);
85
86 protected Logger categoryLogger;
87 protected String logCategory;
88 protected String logLevel;
89
90 public String getLogCategory() {
91 return logCategory;
92 }
93
94 public void setLogCategory(String logCatgory) {
95 this.logCategory = logCatgory;
96 }
97
98 public String getLogLevel() {
99 return logLevel;
100 }
101
102 public void setLogLevel(String logLevel) {
103 this.logLevel = logLevel;
104 }
105
106 @Override
107 public String intercept(ActionInvocation invocation) throws Exception {
108 if (! shouldLog()) {
109 return invocation.invoke();
110 } else {
111 return invokeUnderTiming(invocation);
112 }
113 }
114
115 /**
116 * Is called to invoke the action invocation and time the execution time.
117 *
118 * @param invocation the action invocation.
119 * @return the result of the action execution.
120 * @throws Exception can be thrown from the action.
121 */
122 protected String invokeUnderTiming(ActionInvocation invocation) throws Exception {
123 long startTime = System.currentTimeMillis();
124 String result = invocation.invoke();
125 long executionTime = System.currentTimeMillis() - startTime;
126
127 StringBuilder message = new StringBuilder(100);
128 message.append("Executed action [");
129 String namespace = invocation.getProxy().getNamespace();
130 if ((namespace != null) && (namespace.trim().length() > 0)) {
131 message.append(namespace).append("/");
132 }
133 message.append(invocation.getProxy().getActionName());
134 message.append("!");
135 message.append(invocation.getProxy().getMethod());
136 message.append("] took ").append(executionTime).append(" ms.");
137
138 doLog(getLoggerToUse(), message.toString());
139
140 return result;
141 }
142
143 /**
144 * Determines if we should log the time.
145 *
146 * @return true to log, false to not log.
147 */
148 protected boolean shouldLog() {
149 // default check first
150 if (logLevel == null && logCategory == null) {
151 return LOG.isInfoEnabled();
152 }
153
154 // okay user have set some parameters
155 return isLoggerEnabled(getLoggerToUse(), logLevel);
156 }
157
158 /**
159 * Get's the logger to use.
160 *
161 * @return the logger to use.
162 */
163 protected Logger getLoggerToUse() {
164 if (logCategory != null) {
165 if (categoryLogger == null) {
166 // init category logger
167 categoryLogger = LoggerFactory.getLogger(logCategory);
168 if (logLevel == null) {
169 logLevel = "info"; // use info as default if not provided
170 }
171 }
172 return categoryLogger;
173 }
174
175 return LOG;
176 }
177
178 /**
179 * Performs the actual logging.
180 *
181 * @param logger the provided logger to use.
182 * @param message the message to log.
183 */
184 protected void doLog(Logger logger, String message) {
185 if (logLevel == null) {
186 logger.info(message);
187 return;
188 }
189
190 if ("debug".equalsIgnoreCase(logLevel)) {
191 logger.debug(message);
192 } else if ("info".equalsIgnoreCase(logLevel)) {
193 logger.info(message);
194 } else if ("warn".equalsIgnoreCase(logLevel)) {
195 logger.warn(message);
196 } else if ("error".equalsIgnoreCase(logLevel)) {
197 logger.error(message);
198 } else if ("fatal".equalsIgnoreCase(logLevel)) {
199 logger.fatal(message);
200 } else if ("trace".equalsIgnoreCase(logLevel)) {
201 logger.trace(message);
202 } else {
203 throw new IllegalArgumentException("LogLevel [" + logLevel + "] is not supported");
204 }
205 }
206
207 /**
208 * Is the given logger enalbed at the given level?
209 *
210 * @param logger the logger.
211 * @param level the level to check if <code>isXXXEnabled</code>.
212 * @return <tt>true</tt> if enabled, <tt>false</tt> if not.
213 */
214 private static boolean isLoggerEnabled(Logger logger, String level) {
215 if ("debug".equalsIgnoreCase(level)) {
216 return logger.isDebugEnabled();
217 } else if ("info".equalsIgnoreCase(level)) {
218 return logger.isInfoEnabled();
219 } else if ("warn".equalsIgnoreCase(level)) {
220 return logger.isWarnEnabled();
221 } else if ("error".equalsIgnoreCase(level)) {
222 return logger.isErrorEnabled();
223 } else if ("fatal".equalsIgnoreCase(level)) {
224 return logger.isFatalEnabled();
225 } else if ("trace".equalsIgnoreCase(level)) {
226 return logger.isTraceEnabled();
227 } else {
228 throw new IllegalArgumentException("LogLevel [" + level + "] is not supported");
229 }
230 }
231
232 }