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);
+ }
+
+}
|