Anonymous avatar Anonymous committed 80c67c5

XW-374 - TimerInterceptor - support setting log category

git-svn-id: http://svn.opensymphony.com/svn/xwork/trunk@961 e221344d-f017-0410-9bd5-d282ab1896d7

Comments (0)

Files changed (3)

src/java/com/opensymphony/xwork/interceptor/TimerInterceptor.java

  * <!-- END SNIPPET: description -->
  *
  * <!-- START SNIPPET: parameters -->
- * TODO: Describe the paramters for this Interceptor.
+ *
+ * <ul>
+ *
+ * <li>logLevel (optional) - what log level should we use (<code>trace, debug, info, warn, error, fatal</code>)? - defaut is <code>info</code></li>
+ *
+ * <li>logCategory (optional) - If provided we would use this category (eg. <code>com.mycompany.app</code>).
+ * Default is to use <code>com.opensymphony.xwork.interceptor.TimerInterceptor</code>.</li>
+ *
+ * </ul>
+ *
+ * The parameters above enables us to log all action execution times in our own logfile.
+ *
  * <!-- END SNIPPET: parameters -->
  *
  * <!-- START SNIPPET: extending -->
- * TODO: Discuss some possible extension of the Interceptor.
+ * This interceptor can be extended to provide custom message format. Users should override the
+ * <code>invokeUnderTiming</code> method.
  * <!-- END SNIPPET: extending -->
  *
  * <pre>
  * <!-- END SNIPPET: example -->
  * </pre>
  *
+ * This second example uses our own log category at debug level.
+ *
+ * <pre>
+ * <!-- START SNIPPET: example2 -->
+ * &lt;!-- records only the action's execution time --&gt;
+ * &lt;action name="someAction" class="com.examples.SomeAction"&gt;
+ *     &lt;interceptor-ref name="completeStack"/&gt;
+ *     &lt;interceptor-ref name="timer"&gt;
+ *         &lt;param name="logLevel"&gt;debug&lt;/param&gt;
+ *         &lt;param name="logCategory"&gt;com.mycompany.myapp.actiontime&lt;/param&gt;
+ *     &lt;interceptor-ref/&gt;
+ *     &lt;result name="success"&gt;good_result.ftl&lt;/result&gt;
+ * &lt;/action&gt;
+ *
+ * &lt;!-- records action's execution time as well as other interceptors--&gt;
+ * &lt;action name="someAction" class="com.examples.SomeAction"&gt;
+ *     &lt;interceptor-ref name="timer"/&gt;
+ *     &lt;interceptor-ref name="completeStack"/&gt;
+ *     &lt;result name="success"&gt;good_result.ftl&lt;/result&gt;
+ * &lt;/action&gt;
+ * <!-- END SNIPPET: example2 -->
+ * </pre>
+ *
  * @author Jason Carreira
+ * @author Claus Ibsen
  */
 public class TimerInterceptor implements Interceptor {
-    private static final Log log = LogFactory.getLog(TimerInterceptor.class);
+    protected static final Log log = LogFactory.getLog(TimerInterceptor.class);
+
+    protected Log categoryLogger;
+    protected String logCategory;
+    protected String logLevel;
+
+    public String getLogCategory() {
+        return logCategory;
+    }
+
+    public void setLogCategory(String logCatgory) {
+        this.logCategory = logCatgory;
+    }
+
+    public String getLogLevel() {
+        return logLevel;
+    }
+
+    public void setLogLevel(String logLevel) {
+        this.logLevel = logLevel;
+    }
 
     public void destroy() {
     }
     }
 
     public String intercept(ActionInvocation invocation) throws Exception {
-        if (log.isInfoEnabled()) {
-            long startTime = System.currentTimeMillis();
-            String result = invocation.invoke();
-            long executionTime = System.currentTimeMillis() - startTime;
-            String namespace = invocation.getProxy().getNamespace();
-            StringBuffer message = new StringBuffer("Processed action ");
-
-            if ((namespace != null) && (namespace.trim().length() > 0)) {
-                message.append(namespace).append("/");
+        if (! shouldLog()) {
+            return invocation.invoke();
+        } else {
+            return invokeUnderTiming(invocation);
+        }
+    }
+
+    /**
+     * Is called to invoke the action invocation and time the execution time.
+     *
+     * @param invocation  the action invocation.
+     * @return the result of the action execution.
+     * @throws Exception  can be thrown from the action.
+     */
+    protected String invokeUnderTiming(ActionInvocation invocation) throws Exception {
+        long startTime = System.currentTimeMillis();
+        String result = invocation.invoke();
+        long executionTime = System.currentTimeMillis() - startTime;
+
+        StringBuffer message = new StringBuffer(100);
+        message.append("Executed action [");
+        String namespace = invocation.getProxy().getNamespace();
+        if ((namespace != null) && (namespace.trim().length() > 0)) {
+            message.append(namespace).append("/");
+        }
+        message.append(invocation.getProxy().getActionName());
+        message.append("!");
+        message.append(invocation.getProxy().getMethod());
+        message.append("] took ").append(executionTime).append(" ms.");
+
+        doLog(getLoggerToUse(), message.toString());
+
+        return result;
+    }
+
+    /**
+     * Determines if we should log the time.
+     *
+     * @return  true to log, false to not log.
+     */
+    protected boolean shouldLog() {
+        // default check first
+        if (logLevel == null && logCategory == null) {
+            return log.isInfoEnabled();
+        }
+
+        // okay user have set some parameters
+        return isLoggerEnabled(getLoggerToUse(), logLevel);
+    }
+
+    /**
+     * Get's the logger to use.
+     *
+     * @return the logger to use.
+     */
+    protected Log getLoggerToUse() {
+        if (logCategory != null) {
+            if (categoryLogger == null) {
+                // init category logger
+                categoryLogger = LogFactory.getLog(logCategory);
+                if (logLevel == null) {
+                    logLevel = "info"; // use info as default if not provided
+                }
             }
+            return categoryLogger;
+        }
 
-            message.append(invocation.getProxy().getActionName());
-            message.append(" in ").append(executionTime).append("ms.");
-            log.info(message.toString());
+        return log;
+    }
 
-            return result;
+    /**
+     * Performs the actual logging.
+     *
+     * @param logger  the provided logger to use.
+     * @param message  the message to log.
+     */
+    protected void doLog(Log logger, String message) {
+        if (logLevel == null) {
+            logger.info(message);
+            return;
+        }
+
+        if ("debug".equalsIgnoreCase(logLevel)) {
+            logger.debug(message);
+        } else if ("info".equalsIgnoreCase(logLevel)) {
+            logger.info(message);
+        } else if ("warn".equalsIgnoreCase(logLevel)) {
+            logger.warn(message);
+        } else if ("error".equalsIgnoreCase(logLevel)) {
+            logger.error(message);
+        } else if ("fatal".equalsIgnoreCase(logLevel)) {
+            logger.fatal(message);
+        } else if ("trace".equalsIgnoreCase(logLevel)) {
+            logger.trace(message);
         } else {
-            return invocation.invoke();
+            throw new IllegalArgumentException("LogLevel [" + logLevel + "] is not supported");
         }
     }
 
-    public int hashCode() {
-        return 11;
+    /**
+     * Is the given logger enalbed at the given level?
+     *
+     * @param logger  the logger.
+     * @param level   the level to check if <code>isXXXEnabled</code>.
+     * @return <tt>true</tt> if enabled, <tt>false</tt> if not.
+     */
+    private static boolean isLoggerEnabled(Log logger, String level) {
+        if ("debug".equalsIgnoreCase(level)) {
+            return logger.isDebugEnabled();
+        } else if ("info".equalsIgnoreCase(level)) {
+            return logger.isInfoEnabled();
+        } else if ("warn".equalsIgnoreCase(level)) {
+            return logger.isWarnEnabled();
+        } else if ("error".equalsIgnoreCase(level)) {
+            return logger.isErrorEnabled();
+        } else if ("fatal".equalsIgnoreCase(level)) {
+            return logger.isFatalEnabled();
+        } else if ("trace".equalsIgnoreCase(level)) {
+            return logger.isTraceEnabled();
+        } else {
+            throw new IllegalArgumentException("LogLevel [" + level + "] is not supported");
+        }
     }
 
-    public boolean equals(Object obj) {
-        return obj instanceof TimerInterceptor;
-    }
 }

src/test/com/opensymphony/xwork/interceptor/TimerInterceptorTest.java

+/*
+ * Copyright (c) 2002-2006 by OpenSymphony
+ * All rights reserved.
+ */
+package com.opensymphony.xwork.interceptor;
+
+import com.opensymphony.xwork.SimpleFooAction;
+import com.opensymphony.xwork.XWorkTestCase;
+import com.opensymphony.xwork.mock.MockActionInvocation;
+import com.opensymphony.xwork.mock.MockActionProxy;
+import org.apache.commons.logging.Log;
+
+/**
+ * Unit test for {@link TimerInterceptor}.
+ *
+ * @author Claus Ibsen
+ */
+public class TimerInterceptorTest extends XWorkTestCase {
+
+    private MyTimerInterceptor interceptor;
+    private MockActionInvocation mai;
+    private MockActionProxy ap;
+
+
+    public void testTimerInterceptor() throws Exception {
+        TimerInterceptor real = new TimerInterceptor();
+        real.init();
+        real.intercept(mai);
+        real.destroy();
+    }
+
+    public void testInvalidLogLevel() throws Exception {
+        TimerInterceptor real = new TimerInterceptor();
+        real.setLogLevel("xxx");
+        real.init();
+        try {
+            real.intercept(mai);
+            fail("Should not have reached this point.");
+        } catch (IllegalArgumentException e) {
+        	// success
+        }
+    }
+
+    public void testDefault() throws Exception {
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myApp/myAction!execute] took "));
+        assertSame(interceptor.logger, TimerInterceptor.log);
+    }
+
+    public void testNoNamespace() throws Exception {
+        ap.setNamespace(null);
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myAction!execute] took "));
+        assertSame(interceptor.logger, TimerInterceptor.log);
+    }
+
+    public void testInputMethod() throws Exception {
+        ap.setMethod("input");
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myApp/myAction!input] took "));
+        assertSame(interceptor.logger, TimerInterceptor.log);
+    }
+
+    public void testTraceLevel() throws Exception {
+        interceptor.setLogLevel("trace");
+        interceptor.intercept(mai);
+        assertNull(interceptor.message); // no default logging at trace level
+        assertEquals("trace", interceptor.getLogLevel());
+    }
+
+    public void testDebugLevel() throws Exception {
+        interceptor.setLogLevel("debug");
+        interceptor.intercept(mai);
+        assertNull(interceptor.message); // no default logging at debug level
+    }
+
+    public void testInfoLevel() throws Exception {
+        interceptor.setLogLevel("info");
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myApp/myAction!execute] took "));
+        assertSame(interceptor.logger, TimerInterceptor.log);
+    }
+
+    public void testWarnLevel() throws Exception {
+        interceptor.setLogLevel("warn");
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myApp/myAction!execute] took "));
+        assertSame(interceptor.logger, TimerInterceptor.log);
+    }
+
+    public void testErrorLevel() throws Exception {
+        interceptor.setLogLevel("error");
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myApp/myAction!execute] took "));
+        assertSame(interceptor.logger, TimerInterceptor.log);
+    }
+
+    public void testFatalLevel() throws Exception {
+        interceptor.setLogLevel("fatal");
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myApp/myAction!execute] took "));
+        assertSame(interceptor.logger, TimerInterceptor.log);
+    }
+
+    public void testLogCategory() throws Exception {
+        interceptor.setLogCategory("com.mycompany.myapp.actiontiming");
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myApp/myAction!execute] took "));
+        assertNotSame(interceptor.logger, TimerInterceptor.log);
+    }
+
+    public void testLogCategoryLevel() throws Exception {
+        interceptor.setLogCategory("com.mycompany.myapp.actiontiming");
+        interceptor.setLogLevel("debug");
+        interceptor.intercept(mai);
+        assertTrue(interceptor.message.startsWith("Executed action [myApp/myAction!execute] took "));
+        assertNotSame(interceptor.logger, TimerInterceptor.log);
+        assertEquals("com.mycompany.myapp.actiontiming", interceptor.getLogCategory());
+    }
+
+    protected void setUp() throws Exception {
+        super.setUp();
+        interceptor = new MyTimerInterceptor();
+        interceptor.init();
+
+        mai = new MockActionInvocation();
+        ap = new MockActionProxy();
+        ap.setActionName("myAction");
+        ap.setNamespace("myApp");
+        ap.setMethod("execute");
+        mai.setAction(new SimpleFooAction());
+        mai.setProxy(ap);
+    }
+
+    protected void tearDown() throws Exception {
+        super.tearDown();
+        interceptor.destroy();
+        ap = null;
+        mai = null;
+    }
+
+    private class MyTimerInterceptor extends TimerInterceptor {
+
+        private Log logger;
+        private String message;
+
+        protected void doLog(Log logger, String message) {
+            super.doLog(logger, message);
+
+            this.logger = logger;
+            this.message = message;
+        }
+    }
+
+}

src/test/log4j.properties

 
 # set to debug to let the code be executed when doing unit test for this interceptor
 log4j.category.com.opensymphony.xwork.interceptor.ParametersInterceptor=DEBUG
+
+# set to debug for testing timer interceptor with custom log category
+log4j.category.com.mycompany.myapp.actiontiming=DEBUG
Tip: Filter by directory path e.g. /media app.js to search for public/media/app.js.
Tip: Use camelCasing e.g. ProjME to search for ProjectModifiedEvent.java.
Tip: Filter by extension type e.g. /repo .js to search for all .js files in the /repo directory.
Tip: Separate your search with spaces e.g. /ssh pom.xml to search for src/ssh/pom.xml.
Tip: Use ↑ and ↓ arrow keys to navigate and return to view the file.
Tip: You can also navigate files with Ctrl+j (next) and Ctrl+k (previous) and view the file with Ctrl+o.
Tip: You can also navigate files with Alt+j (next) and Alt+k (previous) and view the file with Alt+o.