HTRACE-101. Add better error-checking to the Java HTrace client (cmccabe)
diff --git a/htrace-core/src/main/java/org/apache/htrace/Trace.java b/htrace-core/src/main/java/org/apache/htrace/Trace.java
index 67bb731..353be25 100644
--- a/htrace-core/src/main/java/org/apache/htrace/Trace.java
+++ b/htrace-core/src/main/java/org/apache/htrace/Trace.java
@@ -16,6 +16,8 @@
*/
package org.apache.htrace;
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
import org.apache.htrace.impl.MilliSpan;
import org.apache.htrace.impl.TrueIfTracingSampler;
import org.apache.htrace.wrappers.TraceCallable;
@@ -26,57 +28,83 @@
import java.util.concurrent.Callable;
/**
- * The primary way to interact with the library. Provides methods to start
- * spans, as well as set necessary tracing information.
+ * The Trace class is the primary way to interact with the library. It provides
+ * methods to create and manipulate spans.
+ *
+ * A 'Span' represents a length of time. It has many other attributes such as a
+ * description, ID, and even potentially a set of key/value strings attached to
+ * it.
+ *
+ * Each thread in your application has a single currently active currentSpan
+ * associated with it. When this is non-null, it represents the current
+ * operation that the thread is doing. Spans are NOT thread-safe, and must
+ * never be used by multiple threads at once. With care, it is possible to
+ * safely pass a Span object between threads, but in most cases this is not
+ * necessary.
+ *
+ * A 'TraceScope' can either be empty, or contain a Span. TraceScope objects
+ * implement the Java's Closeable interface. Similar to file descriptors, they
+ * must be closed after they are created. When a TraceScope contains a Span,
+ * this span is closed when the scope is closed.
+ *
+ * The 'startSpan' methods in this class do a few things:
+ * <ul>
+ * <li>Create a new Span which has this thread's currentSpan as one of its parents.</li>
+ * <li>Set currentSpan to the new Span.</li>
+ * <li>Create a TraceSpan object to manage the new Span.</li>
+ * </ul>
+ *
+ * Closing a TraceScope does a few things:
+ * <ul>
+ * <li>It closes the span which the scope was managing.</li>
+ * <li>Set currentSpan to the previous currentSpan (which may be null).</li>
+ * </ul>
*/
public class Trace {
+ private static final Log LOG = LogFactory.getLog(Trace.class);
private final static Random random = new SecureRandom();
/**
- * Starts and returns a new span as the child of the current span if the
- * default sampler (TrueIfTracingSampler) returns true, otherwise returns the
- * NullSpan.
+ * Creates a new trace scope.
*
- * @param description Description of the span to be created.
+ * If this thread has a currently active trace span, the trace scope we create
+ * here will contain a new span descending from the currently active span.
+ * If there is no currently active trace span, the trace scope we create will
+ * be empty.
+ *
+ * @param description The description field for the new span to create.
*/
public static TraceScope startSpan(String description) {
return startSpan(description, TrueIfTracingSampler.INSTANCE);
}
/**
- * Starts and returns a new span as the child of the parameter 'parent'. This
- * will always return a new span, even if tracing wasn't previously enabled for
- * this thread.
+ * Creates a new trace scope.
*
- * @param description Description of the span to be created.
- * @param parent The parent that should be used to create the child span that is to
- * be returned.
+ * If this thread has a currently active trace span, it must be the 'parent'
+ * span that you pass in here as a parameter. The trace scope we create here
+ * will contain a new span which is a child of 'parent'.
+ *
+ * @param description The description field for the new span to create.
*/
public static TraceScope startSpan(String description, Span parent) {
- if (parent == null) return startSpan(description);
+ if (parent == null) {
+ return startSpan(description);
+ }
+ Span currentSpan = currentSpan();
+ if ((currentSpan != null) && (currentSpan != parent)) {
+ Tracer.clientError("HTrace client error: thread " +
+ Thread.currentThread().getName() + " tried to start a new Span " +
+ "with parent " + parent.toString() + ", but there is already a " +
+ "currentSpan " + currentSpan);
+ }
return continueSpan(parent.child(description));
}
- public static TraceScope startSpan(String description, TraceInfo tinfo) {
- if (tinfo == null) return continueSpan(null);
- Span newSpan = new MilliSpan(description, tinfo.traceId, tinfo.spanId,
- random.nextLong(), Tracer.getProcessId());
- return continueSpan(newSpan);
- }
-
public static <T> TraceScope startSpan(String description, Sampler<T> s) {
return startSpan(description, s, null);
}
- public static TraceScope startSpan(String description, Sampler<TraceInfo> s, TraceInfo tinfo) {
- Span span = null;
- if (isTracing() || s.next(tinfo)) {
- span = new MilliSpan(description, tinfo.traceId, tinfo.spanId,
- random.nextLong(), Tracer.getProcessId());
- }
- return continueSpan(span);
- }
-
public static <T> TraceScope startSpan(String description, Sampler<T> s, T info) {
Span span = null;
if (isTracing() || s.next(info)) {
diff --git a/htrace-core/src/main/java/org/apache/htrace/TraceScope.java b/htrace-core/src/main/java/org/apache/htrace/TraceScope.java
index 7773aad..3546e69 100644
--- a/htrace-core/src/main/java/org/apache/htrace/TraceScope.java
+++ b/htrace-core/src/main/java/org/apache/htrace/TraceScope.java
@@ -17,8 +17,12 @@
package org.apache.htrace;
import java.io.Closeable;
+import java.lang.Thread;
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
public class TraceScope implements Closeable {
+ private static final Log LOG = LogFactory.getLog(TraceScope.class);
/**
* the span for this scope
@@ -49,12 +53,18 @@
* @return the same Span object
*/
public Span detach() {
+ if (detached) {
+ Tracer.clientError("Tried to detach trace span " + span + " but " +
+ "it has already been detached.");
+ }
detached = true;
Span cur = Tracer.getInstance().currentSpan();
if (cur != span) {
- Tracer.LOG.debug("Closing trace span " + span + " but " +
- cur + " was top-of-stack");
+ Tracer.clientError("Tried to detach trace span " + span + " but " +
+ "it is not the current span for the " +
+ Thread.currentThread().getName() + " thread. You have " +
+ "probably forgotten to close or detach " + cur);
} else {
Tracer.getInstance().setCurrentSpan(savedSpan);
}
@@ -71,12 +81,19 @@
@Override
public void close() {
- if (span == null) return;
-
- if (!detached) {
- // The span is done
+ if ((span == null) || detached) {
+ return;
+ }
+ detached = true;
+ Span cur = Tracer.getInstance().currentSpan();
+ if (cur != span) {
+ Tracer.clientError("Tried to close trace span " + span + " but " +
+ "it is not the current span for the " +
+ Thread.currentThread().getName() + " thread. You have " +
+ "probably forgotten to close or detach " + cur);
+ } else {
span.stop();
- detach();
+ Tracer.getInstance().setCurrentSpan(savedSpan);
}
}
}
diff --git a/htrace-core/src/main/java/org/apache/htrace/TraceTree.java b/htrace-core/src/main/java/org/apache/htrace/TraceTree.java
index a005c55..7d0c368 100644
--- a/htrace-core/src/main/java/org/apache/htrace/TraceTree.java
+++ b/htrace-core/src/main/java/org/apache/htrace/TraceTree.java
@@ -158,4 +158,16 @@
public SpansByProcessId getSpansByProcessId() {
return spansByProcessId;
}
+
+ @Override
+ public String toString() {
+ StringBuilder bld = new StringBuilder();
+ String prefix = "";
+ for (Iterator<Span> iter = spansByParent.iterator(); iter.hasNext();) {
+ Span span = iter.next();
+ bld.append(prefix).append(span.toString());
+ prefix = "\n";
+ }
+ return bld.toString();
+ }
}
diff --git a/htrace-core/src/main/java/org/apache/htrace/Tracer.java b/htrace-core/src/main/java/org/apache/htrace/Tracer.java
index 614521c..a214e5a 100644
--- a/htrace-core/src/main/java/org/apache/htrace/Tracer.java
+++ b/htrace-core/src/main/java/org/apache/htrace/Tracer.java
@@ -43,6 +43,16 @@
protected static String processId = null;
/**
+ * Log a client error, and throw an exception.
+ *
+ * @param str The message to use in the log and the exception.
+ */
+ static void clientError(String str) {
+ LOG.error(str);
+ throw new RuntimeException(str);
+ }
+
+ /**
* Internal class for defered singleton idiom.
* <p/>
* https://en.wikipedia.org/wiki/Initialization_on_demand_holder_idiom
diff --git a/htrace-core/src/test/java/org/apache/htrace/TestBadClient.java b/htrace-core/src/test/java/org/apache/htrace/TestBadClient.java
new file mode 100644
index 0000000..cf060d5
--- /dev/null
+++ b/htrace-core/src/test/java/org/apache/htrace/TestBadClient.java
@@ -0,0 +1,150 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.htrace;
+
+import static org.junit.Assert.assertThat;
+import static org.junit.Assert.assertTrue;
+import static org.hamcrest.CoreMatchers.containsString;
+
+import org.apache.htrace.HTraceConfiguration;
+import org.apache.htrace.Span;
+import org.apache.htrace.SpanReceiver;
+import org.apache.htrace.TraceTree.SpansByParent;
+import org.apache.htrace.TraceTree;
+import org.apache.htrace.impl.AlwaysSampler;
+import org.apache.htrace.impl.LocalFileSpanReceiver;
+import org.apache.htrace.impl.POJOSpanReceiver;
+import org.apache.htrace.impl.StandardOutSpanReceiver;
+import org.junit.Assert;
+import org.junit.Test;
+
+import java.io.File;
+import java.util.Collection;
+import java.util.HashMap;
+import java.util.HashSet;
+import java.util.Map;
+
+public class TestBadClient {
+ /**
+ * Test closing an outer scope when an inner one is still active.
+ */
+ @Test
+ public void TestClosingOuterScope() throws Exception {
+ boolean gotException = false;
+ TraceScope outerScope = Trace.startSpan("outer", AlwaysSampler.INSTANCE);
+ TraceScope innerScope = Trace.startSpan("inner");
+ try {
+ outerScope.close();
+ } catch (RuntimeException e) {
+ assertThat(e.getMessage(),
+ containsString("You have probably forgotten to close or detach"));
+ gotException = true;
+ }
+ assertTrue("Expected to get exception because of improper " +
+ "scope closure.", gotException);
+ innerScope.close();
+ Tracer.getInstance().setCurrentSpan(null);
+ }
+
+ /**
+ * Test calling detach() two times on a scope object.
+ */
+ @Test
+ public void TestDoubleDetach() throws Exception {
+ boolean gotException = false;
+ TraceScope myScope = Trace.startSpan("myScope", AlwaysSampler.INSTANCE);
+ myScope.detach();
+ try {
+ myScope.detach();
+ } catch (RuntimeException e) {
+ assertThat(e.getMessage(),
+ containsString("it has already been detached."));
+ gotException = true;
+ }
+ assertTrue("Expected to get exception because of double TraceScope " +
+ "detach.", gotException);
+ }
+
+ private static class SpanHolder {
+ Span span;
+
+ void set(Span span) {
+ this.span = span;
+ }
+ }
+
+ /**
+ * Test correctly passing spans between threads using detach().
+ */
+ @Test
+ public void TestPassingSpanBetweenThreads() throws Exception {
+ final SpanHolder spanHolder = new SpanHolder();
+ Thread th = new Thread(new Runnable() {
+ @Override
+ public void run() {
+ TraceScope workerScope = Trace.startSpan("workerSpan",
+ AlwaysSampler.INSTANCE);
+ spanHolder.set(workerScope.getSpan());
+ workerScope.detach();
+ }
+ });
+ th.start();
+ th.join();
+
+ // Create new scope whose parent is the worker thread's span.
+ TraceScope outermost = Trace.startSpan("outermost", spanHolder.span);
+ TraceScope nested = Trace.startSpan("nested");
+ nested.close();
+ outermost.close();
+ // Create another span which also descends from the worker thread's span.
+ TraceScope nested2 = Trace.startSpan("nested2", spanHolder.span);
+ nested2.close();
+
+ // Close the worker thread's span.
+ spanHolder.span.stop();
+
+ // We can create another descendant, even though the worker thread's span
+ // has been stopped.
+ TraceScope lateChildScope = Trace.startSpan("lateChild", spanHolder.span);
+ lateChildScope.close();
+ }
+
+ /**
+ * Test trying to manually set our TraceScope's parent in a case where there
+ * is a currently active span.
+ */
+ @Test
+ public void TestIncorrectStartSpan() throws Exception {
+ // Create new scope
+ TraceScope outermost = Trace.startSpan("outermost",
+ AlwaysSampler.INSTANCE);
+ // Create nested scope
+ TraceScope nested = Trace.startSpan("nested", outermost.getSpan());
+ // Error
+ boolean gotException = false;
+ try {
+ TraceScope error = Trace.startSpan("error", outermost.getSpan());
+ error.close();
+ } catch (RuntimeException e) {
+ assertThat(e.getMessage(),
+ containsString("there is already a currentSpan"));
+ gotException = true;
+ }
+ assertTrue("Expected to get exception because of incorrect startSpan.",
+ gotException);
+ }
+}
diff --git a/htrace-core/src/test/java/org/apache/htrace/TestSampler.java b/htrace-core/src/test/java/org/apache/htrace/TestSampler.java
index 0cc7d97..e848e5e 100644
--- a/htrace-core/src/test/java/org/apache/htrace/TestSampler.java
+++ b/htrace-core/src/test/java/org/apache/htrace/TestSampler.java
@@ -20,7 +20,6 @@
import java.util.Map;
import org.apache.htrace.Sampler;
import org.apache.htrace.Trace;
-import org.apache.htrace.TraceInfo;
import org.apache.htrace.TraceScope;
import org.apache.htrace.impl.AlwaysSampler;
import org.apache.htrace.impl.NeverSampler;
@@ -64,7 +63,7 @@
@Test
public void testAlwaysSampler() {
- TraceScope cur = Trace.startSpan("test", new TraceInfo(0, 0));
+ TraceScope cur = Trace.startSpan("test");
Assert.assertNotNull(cur);
cur.close();
}
diff --git a/htrace-core/src/test/java/org/apache/htrace/TraceCreator.java b/htrace-core/src/test/java/org/apache/htrace/TraceCreator.java
index f577656..f79b01a 100644
--- a/htrace-core/src/test/java/org/apache/htrace/TraceCreator.java
+++ b/htrace-core/src/test/java/org/apache/htrace/TraceCreator.java
@@ -149,15 +149,15 @@
}
public void pretendRpcSend() {
- pretendRpcReceiveWithTraceInfo(TraceInfo.fromSpan(Trace.currentSpan()));
+ pretendRpcReceiveWithTraceInfo(Trace.currentSpan());
}
- public void pretendRpcReceiveWithTraceInfo(TraceInfo traceInfo) {
- TraceScope s = Trace.startSpan("received RPC", traceInfo);
+ public void pretendRpcReceiveWithTraceInfo(Span parent) {
+ TraceScope s = Trace.startSpan("received RPC", parent);
try {
importantWork1();
} finally {
s.close();
}
}
-}
\ No newline at end of file
+}
diff --git a/pom.xml b/pom.xml
index e02250f..97e7993 100644
--- a/pom.xml
+++ b/pom.xml
@@ -289,7 +289,7 @@
<dependency>
<groupId>junit</groupId>
<artifactId>junit</artifactId>
- <version>4.10</version>
+ <version>4.11</version>
<scope>test</scope>
</dependency>
<dependency>
