sling-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bdelacre...@apache.org
Subject svn commit: r1636373 - in /sling/trunk/bundles/engine: ./ src/main/java/org/apache/sling/engine/impl/debug/ src/main/java/org/apache/sling/engine/impl/request/ src/main/resources/OSGI-INF/metatype/ src/test/java/org/apache/sling/engine/impl/request/
Date Mon, 03 Nov 2014 15:21:57 GMT
Author: bdelacretaz
Date: Mon Nov  3 15:21:56 2014
New Revision: 1636373

URL: http://svn.apache.org/r1636373
Log:
SLING-4114 - Compact and more specific logs from RequestProgressTrackerLogFilter - contributed
by Julian Sedding, thanks!

Added:
    sling/trunk/bundles/engine/src/test/java/org/apache/sling/engine/impl/request/SlingRequestProgressTrackerTest.java
Modified:
    sling/trunk/bundles/engine/pom.xml
    sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java
    sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/request/SlingRequestProgressTracker.java
    sling/trunk/bundles/engine/src/main/resources/OSGI-INF/metatype/metatype.properties

Modified: sling/trunk/bundles/engine/pom.xml
URL: http://svn.apache.org/viewvc/sling/trunk/bundles/engine/pom.xml?rev=1636373&r1=1636372&r2=1636373&view=diff
==============================================================================
--- sling/trunk/bundles/engine/pom.xml (original)
+++ sling/trunk/bundles/engine/pom.xml Mon Nov  3 15:21:56 2014
@@ -45,6 +45,7 @@
     <properties>
         <site.jira.version.id>12314287</site.jira.version.id>
         <site.javadoc.exclude>**.impl.**</site.javadoc.exclude>
+        <sling.java.version>6</sling.java.version>
     </properties>
 
     <build>

Modified: sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java
URL: http://svn.apache.org/viewvc/sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java?rev=1636373&r1=1636372&r2=1636373&view=diff
==============================================================================
--- sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java
(original)
+++ sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java
Mon Nov  3 15:21:56 2014
@@ -18,36 +18,47 @@
  */
 package org.apache.sling.engine.impl.debug;
 
-import java.io.IOException;
-import java.util.Iterator;
-
-import javax.servlet.Filter;
-import javax.servlet.FilterChain;
-import javax.servlet.FilterConfig;
-import javax.servlet.ServletException;
-import javax.servlet.ServletRequest;
-import javax.servlet.ServletResponse;
-
+import org.apache.felix.scr.annotations.Activate;
 import org.apache.felix.scr.annotations.Component;
 import org.apache.felix.scr.annotations.Properties;
 import org.apache.felix.scr.annotations.Property;
 import org.apache.felix.scr.annotations.Service;
 import org.apache.sling.api.SlingHttpServletRequest;
+import org.apache.sling.api.request.RequestPathInfo;
 import org.apache.sling.api.request.RequestProgressTracker;
+import org.apache.sling.commons.osgi.PropertiesUtil;
+import org.apache.sling.engine.impl.request.SlingRequestProgressTracker;
+import org.osgi.service.component.ComponentContext;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
+import javax.servlet.Filter;
+import javax.servlet.FilterChain;
+import javax.servlet.FilterConfig;
+import javax.servlet.ServletException;
+import javax.servlet.ServletRequest;
+import javax.servlet.ServletResponse;
+import java.io.IOException;
+import java.util.Arrays;
+import java.util.Dictionary;
+import java.util.Iterator;
+
 /**
  * Filter that dumps the output of the RequestProgressTracker to the log after
  * processing the request.
  *
  */
-@Component
+@Component(
+        metatype = true,
+        immediate = true,
+        label = "%rpt.log.name",
+        description = "%rpt.log.description"
+)
 @Service
 @Properties({
-    @Property(name="service.description", value="RequestProgressTracker dump filter"),
-    @Property(name="service.vendor", value="The Apache Software Foundation"),
-    @Property(name="filter.scope", value="request")
+    @Property(name="service.description", value="RequestProgressTracker dump filter", propertyPrivate
= true),
+    @Property(name="service.vendor", value="The Apache Software Foundation", propertyPrivate
= true),
+    @Property(name="filter.scope", value="request", propertyPrivate = true)
 })
 public class RequestProgressTrackerLogFilter implements Filter {
 
@@ -55,6 +66,26 @@ public class RequestProgressTrackerLogFi
 
     private int requestCounter;
 
+    private static final String[] DEFAULT_EXTENSIONS = new String[0];
+    private String[] extensions = DEFAULT_EXTENSIONS;
+    @Property(value = {}, cardinality = Integer.MAX_VALUE)
+    private static final String NAME_EXTENSIONS = "extensions";
+
+    private static final int DEFAULT_MIN_DURATION = 0;
+    private int minDurationMs = DEFAULT_MIN_DURATION;
+    @Property(intValue = DEFAULT_MIN_DURATION)
+    private static final String NAME_MIN_DURATION = "minDurationMs";
+
+    private static final int DEFAULT_MAX_DURATION = Integer.MAX_VALUE;
+    private int maxDurationMs = DEFAULT_MAX_DURATION;
+    @Property(intValue = DEFAULT_MAX_DURATION)
+    private static final String NAME_MAX_DURATION = "maxDurationMs";
+
+    private static final boolean DEFAULT_COMPACT_LOG_FORMAT = false;
+    private boolean compactLogFormat = DEFAULT_COMPACT_LOG_FORMAT;
+    @Property(boolValue = DEFAULT_COMPACT_LOG_FORMAT)
+    private static final String NAME_COMPACT_LOG_FORMAT = "compactLogFormat";
+
     public void init(FilterConfig filterConfig) throws ServletException {
     }
 
@@ -64,17 +95,15 @@ public class RequestProgressTrackerLogFi
         chain.doFilter(request, response);
 
         if (request instanceof SlingHttpServletRequest) {
-            final RequestProgressTracker t = ((SlingHttpServletRequest) request).getRequestProgressTracker();
-            t.done();
-
-            if (log.isDebugEnabled()) {
-                int requestId = 0;
-                synchronized (getClass()) {
-                    requestId = ++requestCounter;
-                }
-                final Iterator<String> it = t.getMessages();
-                while (it.hasNext()) {
-                    log.debug("REQUEST_{} - " + it.next(), requestId);
+            final SlingHttpServletRequest slingRequest = (SlingHttpServletRequest) request;
+            final RequestProgressTracker rpt = slingRequest.getRequestProgressTracker();
+            rpt.done();
+
+            if (log.isDebugEnabled() && allowDuration(rpt) && allowExtension(extractExtension(slingRequest)))
{
+                if (compactLogFormat) {
+                    logCompactFormat(rpt);
+                } else {
+                    logDefaultFormat(rpt);
                 }
             }
         }
@@ -83,4 +112,85 @@ public class RequestProgressTrackerLogFi
     public void destroy() {
     }
 
+    private void logCompactFormat(RequestProgressTracker rpt) {
+        final Iterator<String> messages = rpt.getMessages();
+        final StringBuilder sb = new StringBuilder("\n");
+        while (messages.hasNext()) {
+            sb.append(messages.next());
+        }
+        sb.setLength(sb.length() - 1);
+        log.debug(sb.toString());
+    }
+
+    private void logDefaultFormat(RequestProgressTracker rpt) {
+        int requestId = 0;
+        synchronized (getClass()) {
+            requestId = ++requestCounter;
+        }
+        final Iterator<String> it = rpt.getMessages();
+        while (it.hasNext()) {
+            log.debug("REQUEST_{} - " + it.next(), requestId);
+        }
+    }
+
+    private String extractExtension(SlingHttpServletRequest request) {
+        final RequestPathInfo requestPathInfo = request.getRequestPathInfo();
+        String extension = requestPathInfo.getExtension();
+        if (extension == null) {
+            final String pathInfo = requestPathInfo.getResourcePath();
+            final int extensionIndex = pathInfo.lastIndexOf('.') + 1;
+            extension = pathInfo.substring(extensionIndex);
+        }
+        return extension;
+    }
+
+    private boolean allowExtension(final String extension) {
+        return extensions.length == 0 || Arrays.binarySearch(extensions, extension) >
-1;
+    }
+
+    private boolean allowDuration(final RequestProgressTracker rpt) {
+        if (rpt instanceof SlingRequestProgressTracker) {
+            long duration = ((SlingRequestProgressTracker) rpt).getDuration();
+            return minDurationMs <= duration && duration <= maxDurationMs;
+        } else {
+            log.debug("Logged requests can only be filtered by duration if the SlingRequestProgressTracker
is used.");
+            return true;
+        }
+
+    }
+
+    /**
+     * Sorts the String array and removes any empty values, which are
+     * assumed to be sorted to the beginning.
+     *
+     * @param strings An array of Strings
+     * @return The sorted array with empty strings removed.
+     */
+    private String[] sortAndClean(String[] strings) {
+        if (strings.length == 0) {
+            return strings;
+        }
+
+        Arrays.sort(strings);
+        int skip = 0;
+        for (int i = strings.length - 1; i > -1; i--) {
+            // skip all empty strings that are sorted to the beginning of the array
+            if (strings[i].length() == 0) {
+                skip++;
+            }
+        }
+        return skip == 0 ? strings : Arrays.copyOfRange(strings, skip, strings.length);
+    }
+
+    @Activate
+    private void activate(ComponentContext ctx) {
+        final Dictionary p = ctx.getProperties();
+        // extensions needs to be sorted for Arrays.binarySearch() to work
+        extensions = sortAndClean(PropertiesUtil.toStringArray(p.get(NAME_EXTENSIONS), DEFAULT_EXTENSIONS));
+        minDurationMs = PropertiesUtil.toInteger(p.get(NAME_MIN_DURATION), DEFAULT_MIN_DURATION);
+        maxDurationMs = PropertiesUtil.toInteger(p.get(NAME_MAX_DURATION), DEFAULT_MAX_DURATION);
+        compactLogFormat = PropertiesUtil.toBoolean(p.get(NAME_COMPACT_LOG_FORMAT), DEFAULT_COMPACT_LOG_FORMAT);
+        log.debug("activated: extensions = {}, min = {}, max = {}, compact = {}",
+                new Object[]{extensions, minDurationMs, maxDurationMs, compactLogFormat});
+    }
 }
\ No newline at end of file

Modified: sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/request/SlingRequestProgressTracker.java
URL: http://svn.apache.org/viewvc/sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/request/SlingRequestProgressTracker.java?rev=1636373&r1=1636372&r2=1636373&view=diff
==============================================================================
--- sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/request/SlingRequestProgressTracker.java
(original)
+++ sling/trunk/bundles/engine/src/main/java/org/apache/sling/engine/impl/request/SlingRequestProgressTracker.java
Mon Nov  3 15:21:56 2014
@@ -92,13 +92,6 @@ import org.apache.sling.api.request.Requ
 public class SlingRequestProgressTracker implements RequestProgressTracker {
 
     /**
-     * The <em>printf</em> format to dump a tracking line.
-     *
-     * @see #dumpText(PrintWriter)
-     */
-    private static final String DUMP_FORMAT = "%1$7d (%2$tF %2$tT) %3$s%n";
-
-    /**
      * The name of the timer tracking the processing time of the complete
      * process.
      */
@@ -113,24 +106,29 @@ public class SlingRequestProgressTracker
     /** TIMER_END format explanation */
     private static final String TIMER_END_FORMAT = "{<elapsed msec>,<timer name>}
<optional message>";
 
+    /** The leading millisecond number is left-padded with white-space to this width. */
+    private static final int PADDING_WIDTH = 7;
+
     /**
      * The system time at creation of this instance or the last {@link #reset()}.
      */
     private long processingStart;
 
     /**
+     * The system time when {@link #done()} was called or -1 while processing is in progress.
+     */
+    private long processingEnd;
+
+    /**
      * The list of tracking entries.
      */
     private final List<TrackingEntry> entries = new ArrayList<TrackingEntry>();
-
     /**
      * Map of named timers indexed by timer name storing the system time of
      * start of the respective timer.
      */
     private final Map<String, Long> namedTimerEntries = new HashMap<String, Long>();
 
-    private boolean done;
-
     /**
      * Creates a new request progress tracker.
      */
@@ -143,14 +141,14 @@ public class SlingRequestProgressTracker
      * initial timer entry
      */
     public void reset() {
-        done = false;
-
         // remove all entries
         entries.clear();
         namedTimerEntries.clear();
 
         // enter initial messages
         processingStart = startTimerInternal(REQUEST_PROCESSING_TIMER);
+        processingEnd = -1;
+
         entries.add(new TrackingEntry(COMMENT_PREFIX + "timer_end format is " + TIMER_END_FORMAT));
     }
 
@@ -167,11 +165,9 @@ public class SlingRequestProgressTracker
 
             public String next() {
                 // throws NoSuchElementException if no entries any more
-                TrackingEntry entry = entryIter.next();
-
-                long offset = entry.getTimeStamp() - processingStart;
-                return String.format(DUMP_FORMAT, offset, entry.getTimeStamp(),
-                    entry.getMessage());
+                final TrackingEntry entry = entryIter.next();
+                final long offset = entry.getTimeStamp() - getTimeStamp();
+                return formatMessage(offset, entry.getMessage());
             }
 
             public void remove() {
@@ -180,6 +176,17 @@ public class SlingRequestProgressTracker
         };
     }
 
+    private String formatMessage(long offset, String message) {
+        // Set exact length to avoid array copies within StringBuilder
+        final StringBuilder sb = new StringBuilder(PADDING_WIDTH + 1 +  message.length()
+ 1);
+        final String offsetStr = Long.toString(offset);
+        for (int i = PADDING_WIDTH - offsetStr.length(); i > 0; i--) {
+            sb.append(' ');
+        }
+        sb.append(offsetStr).append(' ').append(message).append('\n');
+        return sb.toString();
+    }
+
     /**
      * Dumps the process timer entries to the given writer, one entry per line.
      * See the class comments for the rough format of each message line.
@@ -265,11 +272,21 @@ public class SlingRequestProgressTracker
     }
 
     public void done() {
-        if(done) return;
+        if(processingEnd != -1) return;
         logTimer(REQUEST_PROCESSING_TIMER, REQUEST_PROCESSING_TIMER);
-        done = true;
+        processingEnd = System.currentTimeMillis();
+    }
+
+    private long getTimeStamp() {
+        return processingStart;
     }
 
+    public long getDuration() {
+        if (processingEnd != -1) {
+            return processingEnd - processingStart;
+        }
+        return System.currentTimeMillis() - processingStart;
+    }
 
     /** Process tracker entry keeping timestamp, tag and message */
     private static class TrackingEntry {

Modified: sling/trunk/bundles/engine/src/main/resources/OSGI-INF/metatype/metatype.properties
URL: http://svn.apache.org/viewvc/sling/trunk/bundles/engine/src/main/resources/OSGI-INF/metatype/metatype.properties?rev=1636373&r1=1636372&r2=1636373&view=diff
==============================================================================
--- sling/trunk/bundles/engine/src/main/resources/OSGI-INF/metatype/metatype.properties (original)
+++ sling/trunk/bundles/engine/src/main/resources/OSGI-INF/metatype/metatype.properties Mon
Nov  3 15:21:56 2014
@@ -128,3 +128,27 @@ request.log.service.outputtype.descripti
  or "RequestLog Service" to use a named OSGi service registered with the \
  service interface "org.apache.sling.engine.RequestLog" and a service property \
  "requestlog.name" equal to the Logger Name setting.
+
+
+#
+# RequestProgressTrackerLogFilter
+rpt.log.name = Apache Sling Request Progress Tracker Log Filter
+rpt.log.description = Filter that enables logging of request progress tracker \
+ information. To enable the log output, the category \
+ org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter needs to be \
+ logged on debug level.
+extensions.name = Extension filter
+extensions.description = Only requests with the listed extensions will be logged. \
+ If no extensions are configured all requests are logged. Empty by default.
+minDurationMs.name = Min duration (ms)
+minDurationMs.description = Only requests that take at least the minimum duration \
+ in milliseconds are logged. Default is 0.
+maxDurationMs.name = Max duration (ms)
+maxDurationMs.description = Only requests that take at most the maximum duration \
+ in milliseconds are logged. Default is 2147483647, i.e. Integer.MAX_VALUE.
+compactLogFormat.name = Compact Log Format
+compactLogFormat.description = Whether or not to use the compact format. In compact \
+ one log entry is logged per request, detailing the request progress tracker \
+ information in individual lines, like stack-traces. This keeps log files smaller \
+ and makes them more readable. In the older (non-compact) format, one log entry is \
+ printed per line, thus potentially containing more noise. Default is false.

Added: sling/trunk/bundles/engine/src/test/java/org/apache/sling/engine/impl/request/SlingRequestProgressTrackerTest.java
URL: http://svn.apache.org/viewvc/sling/trunk/bundles/engine/src/test/java/org/apache/sling/engine/impl/request/SlingRequestProgressTrackerTest.java?rev=1636373&view=auto
==============================================================================
--- sling/trunk/bundles/engine/src/test/java/org/apache/sling/engine/impl/request/SlingRequestProgressTrackerTest.java
(added)
+++ sling/trunk/bundles/engine/src/test/java/org/apache/sling/engine/impl/request/SlingRequestProgressTrackerTest.java
Mon Nov  3 15:21:56 2014
@@ -0,0 +1,55 @@
+package org.apache.sling.engine.impl.request;
+
+import org.junit.Ignore;
+import org.junit.Test;
+
+import java.util.Iterator;
+
+import static org.junit.Assert.assertEquals;
+
+public class SlingRequestProgressTrackerTest {
+
+    @Test
+    public void messageFormatting() {
+        final SlingRequestProgressTracker tracker = new SlingRequestProgressTracker();
+        tracker.startTimer("foo");
+        tracker.log("one {0}, two {1}, three {2}", "eins", "zwei", "drei");
+        tracker.startTimer("bar");
+        tracker.logTimer("bar");
+        tracker.logTimer("foo");
+        tracker.done();
+
+        final String[] expected = {
+                "TIMER_START{Request Processing}\n",
+                "COMMENT timer_end format is {<elapsed msec>,<timer name>} <optional
message>\n",
+                "TIMER_START{foo}\n",
+                "LOG one eins, two zwei, three drei\n",
+                "TIMER_START{bar}\n",
+                "TIMER_END{?,bar}\n",
+                "TIMER_END{?,foo}\n",
+                "TIMER_END{?,Request Processing} Request Processing\n"
+        };
+
+        final Iterator<String> messages = tracker.getMessages();
+        int messageCounter = 0;
+        while (messages.hasNext()) {
+            final String m = messages.next();
+            final String e = expected[messageCounter++];
+            if (e.startsWith("TIMER_END{")) {
+                // account for the counter in the string
+                assertEquals(substringAfter(e, ','), substringAfter(m, ','));
+            } else {
+                // strip off counter
+                assertEquals(e, m.substring(8));
+            }
+        }
+
+        assertEquals(expected.length, messageCounter);
+    }
+
+    private String substringAfter(String string, char ch) {
+        final int pos = string.indexOf(ch);
+        return string.substring(pos);
+    }
+
+}



Mime
View raw message