Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Trace Stapler request processing #148

Merged
merged 3 commits into from
Oct 11, 2018
Merged

Trace Stapler request processing #148

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
dc48730
Trace Stapler request processing
daniel-beck Oct 9, 2018
3b3105f
Merge remote-tracking branch 'stapler/master' into telemetry
daniel-beck Oct 10, 2018
d33d285
Address review feedback
daniel-beck Oct 11, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions core/src/main/java/org/kohsuke/stapler/Dispatcher.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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<String> 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,
Expand Down
40 changes: 40 additions & 0 deletions core/src/main/java/org/kohsuke/stapler/EvaluationTrace.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -38,6 +42,8 @@
public class EvaluationTrace {
private final List<String> traces = new ArrayList<String>();

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
Expand All @@ -61,4 +67,38 @@ 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<ApplicationTracer> tracers = getTracers();
for (ApplicationTracer tracer : tracers) {
tracer.record(req, message);
}
}

private static volatile List<ApplicationTracer> tracers;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pointless for this to be volatile, since you have the synchronized block.


@Nonnull
private static List<ApplicationTracer> getTracers() {
synchronized (ApplicationTracer.class) {
if (tracers == null) {
List<ApplicationTracer> t = new ArrayList<>();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You do not need a separate variable. You can initialize tracers directly, since it is protected by a synchronization barrier.

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;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This should really be inside the synchronized block. I think it is harmless to have it outside, since there will be a synchronization barrier before, but definitely not the best style.

}
}
}
1 change: 1 addition & 0 deletions core/src/main/java/org/kohsuke/stapler/IndexDispatcher.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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());

Expand Down
12 changes: 12 additions & 0 deletions core/src/main/java/org/kohsuke/stapler/MetaClass.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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));
Expand All @@ -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));
Expand All @@ -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));
Expand All @@ -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));
Expand All @@ -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));
Expand All @@ -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));
Expand All @@ -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));
Expand All @@ -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+"\")");

Expand Down Expand Up @@ -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+"\",...)");

Expand All @@ -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);
Expand Down Expand Up @@ -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());

Expand Down
4 changes: 4 additions & 0 deletions core/src/main/java/org/kohsuke/stapler/Stapler.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -682,10 +682,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;
Expand Down Expand Up @@ -718,6 +720,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++)+']');

Expand Down Expand Up @@ -785,6 +788,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;
Expand Down
1 change: 1 addition & 0 deletions core/src/main/java/org/kohsuke/stapler/StaticViewFacet.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
1 change: 1 addition & 0 deletions groovy/src/main/java/org/kohsuke/stapler/jelly/groovy/GroovyFacet.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -82,6 +82,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);

Expand Down
12 changes: 7 additions & 5 deletions jelly/src/main/java/org/kohsuke/stapler/jelly/JellyClassTearOff.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down
13 changes: 7 additions & 6 deletions jelly/src/main/java/org/kohsuke/stapler/jelly/JellyFacet.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -89,13 +89,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);
}

Expand Down