Repository: incubator-htrace Updated Branches: refs/heads/master a9eb2316c -> 4a19eb444
HTRACE-101. Add better error-checking to the Java HTrace client (cmccabe) Project: http://git-wip-us.apache.org/repos/asf/incubator-htrace/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-htrace/commit/4a19eb44 Tree: http://git-wip-us.apache.org/repos/asf/incubator-htrace/tree/4a19eb44 Diff: http://git-wip-us.apache.org/repos/asf/incubator-htrace/diff/4a19eb44 Branch: refs/heads/master Commit: 4a19eb44407c56ee53957a9b330c2c05285d3c10 Parents: a9eb231 Author: Colin P. Mccabe <[email protected]> Authored: Fri Jan 30 19:15:58 2015 -0800 Committer: Colin P. Mccabe <[email protected]> Committed: Mon Feb 2 15:40:18 2015 -0800 ---------------------------------------------------------------------- .../src/main/java/org/apache/htrace/Trace.java | 86 +++++++---- .../main/java/org/apache/htrace/TraceScope.java | 31 +++- .../main/java/org/apache/htrace/TraceTree.java | 12 ++ .../src/main/java/org/apache/htrace/Tracer.java | 10 ++ .../java/org/apache/htrace/TestBadClient.java | 150 +++++++++++++++++++ .../java/org/apache/htrace/TestSampler.java | 3 +- .../java/org/apache/htrace/TraceCreator.java | 8 +- pom.xml | 2 +- 8 files changed, 259 insertions(+), 43 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-htrace/blob/4a19eb44/htrace-core/src/main/java/org/apache/htrace/Trace.java ---------------------------------------------------------------------- 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.Random; 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. + * + * 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 Description of the span to be created. + * @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)) { http://git-wip-us.apache.org/repos/asf/incubator-htrace/blob/4a19eb44/htrace-core/src/main/java/org/apache/htrace/TraceScope.java ---------------------------------------------------------------------- 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 @@ public class TraceScope implements Closeable { * @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 @@ public class TraceScope implements Closeable { @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); } } } http://git-wip-us.apache.org/repos/asf/incubator-htrace/blob/4a19eb44/htrace-core/src/main/java/org/apache/htrace/TraceTree.java ---------------------------------------------------------------------- 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 class TraceTree { 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(); + } } http://git-wip-us.apache.org/repos/asf/incubator-htrace/blob/4a19eb44/htrace-core/src/main/java/org/apache/htrace/Tracer.java ---------------------------------------------------------------------- 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 @@ public class Tracer { 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 http://git-wip-us.apache.org/repos/asf/incubator-htrace/blob/4a19eb44/htrace-core/src/test/java/org/apache/htrace/TestBadClient.java ---------------------------------------------------------------------- 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); + } +} http://git-wip-us.apache.org/repos/asf/incubator-htrace/blob/4a19eb44/htrace-core/src/test/java/org/apache/htrace/TestSampler.java ---------------------------------------------------------------------- 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.HashMap; 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 @@ public class TestSampler { @Test public void testAlwaysSampler() { - TraceScope cur = Trace.startSpan("test", new TraceInfo(0, 0)); + TraceScope cur = Trace.startSpan("test"); Assert.assertNotNull(cur); cur.close(); } http://git-wip-us.apache.org/repos/asf/incubator-htrace/blob/4a19eb44/htrace-core/src/test/java/org/apache/htrace/TraceCreator.java ---------------------------------------------------------------------- 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 class TraceCreator { } 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 +} http://git-wip-us.apache.org/repos/asf/incubator-htrace/blob/4a19eb44/pom.xml ---------------------------------------------------------------------- diff --git a/pom.xml b/pom.xml index e02250f..97e7993 100644 --- a/pom.xml +++ b/pom.xml @@ -289,7 +289,7 @@ language governing permissions and limitations under the License. --> <dependency> <groupId>junit</groupId> <artifactId>junit</artifactId> - <version>4.10</version> + <version>4.11</version> <scope>test</scope> </dependency> <dependency>
