From dc487300b3b0f9e808fba8bc2090b1fff9f3144f Mon Sep 17 00:00:00 2001 From: Daniel Beck Date: Wed, 10 Oct 2018 00:26:55 +0200 Subject: [PATCH 1/2] Trace Stapler request processing --- .../java/org/kohsuke/stapler/Dispatcher.java | 10 +++++ .../org/kohsuke/stapler/EvaluationTrace.java | 42 +++++++++++++++++++ .../org/kohsuke/stapler/IndexDispatcher.java | 1 + .../java/org/kohsuke/stapler/MetaClass.java | 12 ++++++ .../java/org/kohsuke/stapler/Stapler.java | 4 ++ .../org/kohsuke/stapler/StaticViewFacet.java | 1 + .../stapler/jelly/groovy/GroovyFacet.java | 1 + .../stapler/jelly/JellyClassTearOff.java | 12 +++--- .../org/kohsuke/stapler/jelly/JellyFacet.java | 13 +++--- 9 files changed, 85 insertions(+), 11 deletions(-) diff --git a/core/src/main/java/org/kohsuke/stapler/Dispatcher.java b/core/src/main/java/org/kohsuke/stapler/Dispatcher.java index 47aad32682..5c8ea7c421 100644 --- a/core/src/main/java/org/kohsuke/stapler/Dispatcher.java +++ b/core/src/main/java/org/kohsuke/stapler/Dispatcher.java @@ -26,6 +26,9 @@ import javax.servlet.ServletException; import java.io.IOException; import java.lang.reflect.InvocationTargetException; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.List; import java.util.logging.Level; import java.util.logging.Logger; @@ -66,6 +69,13 @@ public static void traceEval(StaplerRequest req, StaplerResponse rsp, Object nod ((RequestImpl)req).tokens.assembleOriginalRestOfPath())); } + public static void anonymizedTraceEval(StaplerRequest req, StaplerResponse rsp, Object node, String format, String... args) { + List arg = new ArrayList<>(); + arg.add(node == null ? "(null)" : node.getClass().getName()); + arg.addAll(Arrays.asList(args)); + EvaluationTrace.ApplicationTracer.trace(req, String.format(format, arg.toArray())); + } + public static void traceEval(StaplerRequest req, StaplerResponse rsp, Object node, String prefix, String suffix) { trace(req,rsp,String.format("-> evaluate(%s<%s>%s,\"%s\")", prefix,node,suffix, diff --git a/core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java b/core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java index fdb24373d9..24286affb8 100644 --- a/core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java +++ b/core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java @@ -23,9 +23,13 @@ package org.kohsuke.stapler; +import javax.annotation.Nonnull; import java.util.List; import java.util.ArrayList; import java.io.PrintWriter; +import java.util.ServiceLoader; +import java.util.logging.Level; +import java.util.logging.Logger; import static org.kohsuke.stapler.Stapler.escape; @@ -38,6 +42,8 @@ public class EvaluationTrace { private final List traces = new ArrayList(); + private static final Logger LOGGER = Logger.getLogger(EvaluationTrace.class.getName()); + public void trace(StaplerResponse rsp, String msg) { traces.add(msg); // Firefox Live HTTP header plugin cannot nicely render multiple headers @@ -61,4 +67,40 @@ public static EvaluationTrace get(StaplerRequest req) { * Used for counting trace header. */ private static final String KEY = EvaluationTrace.class.getName(); + + public abstract static class ApplicationTracer { + protected abstract void record(StaplerRequest req, String message); + + public static void trace(StaplerRequest req, String message) { + List tracers = getTracers(); + for (ApplicationTracer tracer : tracers) { + tracer.record(req, message); + } + } + + private static List tracers; + + @Nonnull + private static List getTracers() { + if (tracers == null) { + synchronized (ApplicationTracer.class) { + if (tracers == null) { + List t = new ArrayList<>(); + for (ApplicationTracer tracer : ServiceLoader.load(EvaluationTrace.ApplicationTracer.class, Stapler.getCurrent().getWebApp().getClassLoader())) { + try { + t.add(tracer); + } catch (Exception e) { + // robustness + if (LOGGER.isLoggable(Level.FINE)) { + LOGGER.log(Level.FINE, "Exception thrown when notifying tracer", e); + } + } + } + tracers = t; + } + } + } + return tracers; + } + } } diff --git a/core/src/main/java/org/kohsuke/stapler/IndexDispatcher.java b/core/src/main/java/org/kohsuke/stapler/IndexDispatcher.java index 5cdb6a23ac..4e2804893a 100644 --- a/core/src/main/java/org/kohsuke/stapler/IndexDispatcher.java +++ b/core/src/main/java/org/kohsuke/stapler/IndexDispatcher.java @@ -20,6 +20,7 @@ public boolean dispatch(RequestImpl req, ResponseImpl rsp, Object node) throws I if (req.tokens.hasMore()) return false; // applicable only when there's no more token + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: Index: %s", f.getName()); if (traceable()) trace(req, rsp, "-> <%s>.%s(...)", node, f.getName()); diff --git a/core/src/main/java/org/kohsuke/stapler/MetaClass.java b/core/src/main/java/org/kohsuke/stapler/MetaClass.java index 979c2ddaf2..a16ef5b6a1 100644 --- a/core/src/main/java/org/kohsuke/stapler/MetaClass.java +++ b/core/src/main/java/org/kohsuke/stapler/MetaClass.java @@ -124,6 +124,7 @@ public class MetaClass extends TearOffSupport { } else { dispatchers.add(new NameBasedDispatcher(name) { public boolean doDispatch(RequestImpl req, ResponseImpl rsp, Object node) throws IllegalAccessException, InvocationTargetException, ServletException, IOException { + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#%s", ff.getName()); if (traceable()) trace(req, rsp, "-> <%s>.%s(...)", node, ff.getName()); return ff.bindAndInvokeAndServeResponse(node, req, rsp); @@ -181,6 +182,7 @@ public boolean doDispatch(RequestImpl req, ResponseImpl rsp, Object node) throws if(role!=null && !req.isUserInRole(role)) throw new IllegalAccessException("Needs to be in role "+role); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#%s", f.getName()); if(traceable()) traceEval(req,rsp,node,f.getName()); req.getStapler().invoke(req, rsp, f.get(node)); @@ -204,6 +206,7 @@ public String toString() { dispatchers.add(new NameBasedDispatcher(name) { public boolean doDispatch(RequestImpl req, ResponseImpl rsp, Object node) throws IOException, ServletException, IllegalAccessException, InvocationTargetException { + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#%s()", ff.getName()); if(traceable()) traceEval(req,rsp,node,ff.getName()+"()"); req.getStapler().invoke(req,rsp, ff.invoke(req, rsp, node)); @@ -223,6 +226,7 @@ public String toString() { final Function ff = f.contextualize(new TraversalMethodContext(name)); dispatchers.add(new NameBasedDispatcher(name) { public boolean doDispatch(RequestImpl req, ResponseImpl rsp, Object node) throws IOException, ServletException, IllegalAccessException, InvocationTargetException { + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#%s(...)", ff.getName()); if(traceable()) traceEval(req,rsp,node,ff.getName()+"(...)"); req.getStapler().invoke(req,rsp, ff.invoke(req, rsp, node, req)); @@ -243,6 +247,7 @@ public String toString() { dispatchers.add(new NameBasedDispatcher(name,1) { public boolean doDispatch(RequestImpl req, ResponseImpl rsp, Object node) throws IOException, ServletException, IllegalAccessException, InvocationTargetException { String token = req.tokens.next(); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#%s(String)", ff.getName()); if(traceable()) traceEval(req,rsp,node,ff.getName()+"(\""+token+"\")"); req.getStapler().invoke(req,rsp, ff.invoke(req, rsp, node,token)); @@ -263,6 +268,7 @@ public String toString() { dispatchers.add(new NameBasedDispatcher(name,1) { public boolean doDispatch(RequestImpl req, ResponseImpl rsp, Object node) throws IOException, ServletException, IllegalAccessException, InvocationTargetException { int idx = req.tokens.nextAsInt(); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#%s(int)", ff.getName()); if(traceable()) traceEval(req,rsp,node,ff.getName()+"("+idx+")"); req.getStapler().invoke(req,rsp, ff.invoke(req, rsp, node,idx)); @@ -284,6 +290,7 @@ public String toString() { dispatchers.add(new NameBasedDispatcher(name,1) { public boolean doDispatch(RequestImpl req, ResponseImpl rsp, Object node) throws IOException, ServletException, IllegalAccessException, InvocationTargetException { long idx = req.tokens.nextAsLong(); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#%s(long)", ff.getName()); if(traceable()) traceEval(req,rsp,node,ff.getName()+"("+idx+")"); req.getStapler().invoke(req,rsp, ff.invoke(req, rsp, node,idx)); @@ -302,6 +309,7 @@ public boolean dispatch(RequestImpl req, ResponseImpl rsp, Object node) throws I return false; try { int index = req.tokens.nextAsInt(); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s[idx]"); if (traceable()) traceEval(req, rsp, node, "", "[" + index + "]"); req.getStapler().invoke(req, rsp, klass.getArrayElement(node, index)); @@ -328,6 +336,7 @@ public boolean dispatch(RequestImpl req, ResponseImpl rsp, Object node) throws I return false; try { String key = req.tokens.peek(); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: Map access"); if(traceable()) traceEval(req,rsp,"",".get(\""+key+"\")"); @@ -366,6 +375,7 @@ public boolean dispatch(RequestImpl req, ResponseImpl rsp, Object node) throws I if(!req.tokens.hasMore()) return false; String token = req.tokens.next(); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#getDynamic(...)"); if(traceable()) traceEval(req,rsp,node,"getDynamic(\""+token+"\",...)"); @@ -392,6 +402,7 @@ public String toString() { final Function ff = f.contextualize(new WebMethodContext(WebMethodContext.DYNAMIC)); dispatchers.add(new Dispatcher() { public boolean dispatch(RequestImpl req, ResponseImpl rsp, Object node) throws IllegalAccessException, InvocationTargetException, ServletException, IOException { + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#doDynamic(...)"); if(traceable()) trace(req,rsp,"-> <%s>.doDynamic(...)",node); return ff.bindAndInvokeAndServeResponse(node,req,rsp); @@ -456,6 +467,7 @@ public boolean doDispatch(RequestImpl req, ResponseImpl rsp, Object node) throws req.stapler.getWebApp().getCrumbIssuer().validateCrumb(req,req.getHeader("Crumb")); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s#%s", f.getName()); if(traceable()) trace(req,rsp,"-> <%s>.%s(...)",node, f.getName()); diff --git a/core/src/main/java/org/kohsuke/stapler/Stapler.java b/core/src/main/java/org/kohsuke/stapler/Stapler.java index af3a01e338..cf6efa3848 100644 --- a/core/src/main/java/org/kohsuke/stapler/Stapler.java +++ b/core/src/main/java/org/kohsuke/stapler/Stapler.java @@ -663,10 +663,12 @@ public void invoke(HttpServletRequest req, HttpServletResponse rsp, Object root, * @see #invoke(RequestImpl, ResponseImpl, Object) */ boolean tryInvoke(RequestImpl req, ResponseImpl rsp, Object node ) throws IOException, ServletException { + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: Dispatch"); if(traceable()) traceEval(req,rsp,node); if(node instanceof StaplerProxy) { + Dispatcher.anonymizedTraceEval(req,rsp,node,"%s: StaplerProxy.getTarget()"); if(traceable()) traceEval(req,rsp,node,"((StaplerProxy)",").getTarget()"); Object n = null; @@ -699,6 +701,7 @@ boolean tryInvoke(RequestImpl req, ResponseImpl rsp, Object node ) throws IOExce int count = 0; for (Object subject : list) { if (subject==null) continue; + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: StaplerOverridable.getOverrides()[i]"); if(traceable()) traceEval(req,rsp,node,"((StaplerOverridable)",").getOverrides()["+(count++)+']'); @@ -766,6 +769,7 @@ boolean tryInvoke(RequestImpl req, ResponseImpl rsp, Object node ) throws IOExce } if(node instanceof StaplerFallback) { + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: StaplerFallback.getStaplerFallback()"); if(traceable()) traceEval(req,rsp,node,"((StaplerFallback)",").getStaplerFallback()"); Object n; diff --git a/core/src/main/java/org/kohsuke/stapler/StaticViewFacet.java b/core/src/main/java/org/kohsuke/stapler/StaticViewFacet.java index b6d935bb90..10f520c2b4 100644 --- a/core/src/main/java/org/kohsuke/stapler/StaticViewFacet.java +++ b/core/src/main/java/org/kohsuke/stapler/StaticViewFacet.java @@ -55,6 +55,7 @@ public boolean dispatch(RequestImpl req, ResponseImpl rsp, Object node) throws I req.tokens.next(); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: Static view: %s", next); if (traceable()) { // Null not expected here trace(req,rsp,"-> %s on <%s>", next, node); diff --git a/groovy/src/main/java/org/kohsuke/stapler/jelly/groovy/GroovyFacet.java b/groovy/src/main/java/org/kohsuke/stapler/jelly/groovy/GroovyFacet.java index d727cd9f22..bcb1ccc1d5 100644 --- a/groovy/src/main/java/org/kohsuke/stapler/jelly/groovy/GroovyFacet.java +++ b/groovy/src/main/java/org/kohsuke/stapler/jelly/groovy/GroovyFacet.java @@ -77,6 +77,7 @@ public boolean dispatch(RequestImpl req, ResponseImpl rsp, Object node) throws I req.tokens.next(); + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: Groovy facet: %s", next + ".groovy"); if(traceable()) trace(req,rsp,"Invoking "+next+".groovy"+" on "+node+" for "+req.tokens); diff --git a/jelly/src/main/java/org/kohsuke/stapler/jelly/JellyClassTearOff.java b/jelly/src/main/java/org/kohsuke/stapler/jelly/JellyClassTearOff.java index da91c71e05..7d847a00ed 100644 --- a/jelly/src/main/java/org/kohsuke/stapler/jelly/JellyClassTearOff.java +++ b/jelly/src/main/java/org/kohsuke/stapler/jelly/JellyClassTearOff.java @@ -29,6 +29,7 @@ import static org.kohsuke.stapler.Dispatcher.trace; import static org.kohsuke.stapler.Dispatcher.traceable; +import org.kohsuke.stapler.Dispatcher; import org.kohsuke.stapler.Facet; import org.kohsuke.stapler.MetaClass; import org.kohsuke.stapler.StaplerRequest; @@ -101,12 +102,13 @@ public boolean serveIndexJelly(StaplerRequest req, StaplerResponse rsp, Object n try { Script script = findScript("index.jelly"); if(script!=null) { + String src = "index.jelly"; + if (script instanceof JellyViewScript) { + JellyViewScript jvs = (JellyViewScript) script; + src = jvs.getName(); + } + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: Jelly index: %s", src); if(traceable()) { - String src = "index.jelly"; - if (script instanceof JellyViewScript) { - JellyViewScript jvs = (JellyViewScript) script; - src = jvs.getName(); - } trace(req,rsp,"-> %s on <%s>",src,node); } facet.scriptInvoker.invokeScript(req, rsp, script, node); diff --git a/jelly/src/main/java/org/kohsuke/stapler/jelly/JellyFacet.java b/jelly/src/main/java/org/kohsuke/stapler/jelly/JellyFacet.java index a47a2310d8..71f6bacbb8 100644 --- a/jelly/src/main/java/org/kohsuke/stapler/jelly/JellyFacet.java +++ b/jelly/src/main/java/org/kohsuke/stapler/jelly/JellyFacet.java @@ -84,13 +84,14 @@ public boolean dispatch(RequestImpl req, ResponseImpl rsp, Object node) throws I req.tokens.next(); + // Null not expected here + String src = next+".jelly"; + if (script instanceof JellyViewScript) { + JellyViewScript jvs = (JellyViewScript) script; + src = jvs.getName(); + } + Dispatcher.anonymizedTraceEval(req, rsp, node, "%s: Jelly facet: %s", src); if (traceable()) { - // Null not expected here - String src = next+".jelly"; - if (script instanceof JellyViewScript) { - JellyViewScript jvs = (JellyViewScript) script; - src = jvs.getName(); - } trace(req,rsp,"-> %s on <%s>", src, node); } From d33d285f792f15f29242ef0e3616b47771e00851 Mon Sep 17 00:00:00 2001 From: Daniel Beck Date: Thu, 11 Oct 2018 14:33:09 +0200 Subject: [PATCH 2/2] Address review feedback --- .../org/kohsuke/stapler/EvaluationTrace.java | 26 +++++++++---------- 1 file changed, 12 insertions(+), 14 deletions(-) diff --git a/core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java b/core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java index 24286affb8..cd774fbaaf 100644 --- a/core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java +++ b/core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java @@ -78,26 +78,24 @@ public static void trace(StaplerRequest req, String message) { } } - private static List tracers; + private static volatile List tracers; @Nonnull private static List getTracers() { - if (tracers == null) { - synchronized (ApplicationTracer.class) { - if (tracers == null) { - List t = new ArrayList<>(); - for (ApplicationTracer tracer : ServiceLoader.load(EvaluationTrace.ApplicationTracer.class, Stapler.getCurrent().getWebApp().getClassLoader())) { - try { - t.add(tracer); - } catch (Exception e) { - // robustness - if (LOGGER.isLoggable(Level.FINE)) { - LOGGER.log(Level.FINE, "Exception thrown when notifying tracer", e); - } + synchronized (ApplicationTracer.class) { + if (tracers == null) { + List t = new ArrayList<>(); + for (ApplicationTracer tracer : ServiceLoader.load(EvaluationTrace.ApplicationTracer.class, Stapler.getCurrent().getWebApp().getClassLoader())) { + try { + t.add(tracer); + } catch (Exception e) { + // robustness + if (LOGGER.isLoggable(Level.FINE)) { + LOGGER.log(Level.FINE, "Exception thrown when notifying tracer", e); } } - tracers = t; } + tracers = t; } } return tracers;