Propagates logs and reports 128-bit trace IDs (1.1.x) (#453)

This supports 128-bit traces via a new field traceIdHigh, which matches
other zipkin implementations. In encoded form, the trace ID is simply
twice as long (32 hex characters).

With this change in, a 128-bit trace propagated will not be downgraded
to 64-bits when sending downstream, reporting to Zipkin or adding to
the logging context.

This will be followed by a change to support initiating 128-bit traces.

Author: adriancole

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java

@@ -137,6 +137,7 @@ public class Span {
 	private final long begin;
 	private long end = 0;
 	private final String name;
+	private final long traceIdHigh;
 	private final long traceId;
 	private List<Long> parents = new ArrayList<>();
 	private final long spanId;
@@ -166,6 +167,7 @@ public Span(Span current, Span savedSpan) {
 		this.begin = current.getBegin();
 		this.end = current.getEnd();
 		this.name = current.getName();
+		this.traceIdHigh = current.getTraceIdHigh();
 		this.traceId = current.getTraceId();
 		this.parents = current.getParents();
 		this.spanId = current.getSpanId();
@@ -179,36 +181,61 @@ public Span(Span current, Span savedSpan) {
 		this.savedSpan = savedSpan;
 	}
 
+	/**
+	 * @deprecated please use {@link SpanBuilder}
+	 */
+	@Deprecated
 	public Span(long begin, long end, String name, long traceId, List<Long> parents,
 			long spanId, boolean remote, boolean exportable, String processId) {
 		this(begin, end, name, traceId, parents, spanId, remote, exportable, processId,
 				null);
 	}
 
+	/**
+	 * @deprecated please use {@link SpanBuilder}
+	 */
+	@Deprecated
 	public Span(long begin, long end, String name, long traceId, List<Long> parents,
 			long spanId, boolean remote, boolean exportable, String processId,
 			Span savedSpan) {
-		if (begin > 0) { // conventionally, 0 indicates unset
+		this(new SpanBuilder()
+				.begin(begin)
+				.end(end)
+				.name(name)
+				.traceId(traceId)
+				.parents(parents)
+				.spanId(spanId)
+				.remote(remote)
+				.exportable(exportable)
+				.processId(processId)
+				.savedSpan(savedSpan));
+	}
+
+	Span(SpanBuilder builder) {
+		if (builder.begin > 0) { // conventionally, 0 indicates unset
 			this.startNanos = null; // don't know the start tick
-			this.begin = begin;
+			this.begin = builder.begin;
 		} else {
 			this.startNanos = nanoTime();
 			this.begin = System.currentTimeMillis();
 		}
-		if (end > 0) {
-			this.end = end;
-			this.durationMicros = (end - begin) * 1000;
+		if (builder.end > 0) {
+			this.end = builder.end;
+			this.durationMicros = (this.end - this.begin) * 1000;
 		}
-		this.name = name != null ? name : "";
-		this.traceId = traceId;
-		this.parents = parents;
-		this.spanId = spanId;
-		this.remote = remote;
-		this.exportable = exportable;
-		this.processId = processId;
-		this.savedSpan = savedSpan;
+		this.name = builder.name != null ? builder.name : "";
+		this.traceIdHigh = builder.traceIdHigh;
+		this.traceId = builder.traceId;
+		this.parents.addAll(builder.parents);
+		this.spanId = builder.spanId;
+		this.remote = builder.remote;
+		this.exportable = builder.exportable;
+		this.processId = builder.processId;
+		this.savedSpan = builder.savedSpan;
 		this.tags = new ConcurrentHashMap<>();
+		this.tags.putAll(builder.tags);
 		this.logs = new ConcurrentLinkedQueue<>();
+		this.logs.addAll(builder.logs);
 	}
 
 	public static SpanBuilder builder() {
@@ -358,7 +385,30 @@ public long getSpanId() {
 	}
 
 	/**
-	 * A pseudo-unique (random) number assigned to the trace associated with this span
+	 * When non-zero, the trace containing this span uses 128-bit trace identifiers.
+	 *
+	 * <p>{@code traceIdHigh} corresponds to the high bits in big-endian format and
+	 * {@link #getTraceId()} corresponds to the low bits.
+	 *
+	 * <p>Ex. to convert the two fields to a 128bit opaque id array, you'd use code like below.
+	 * <pre>{@code
+	 * ByteBuffer traceId128 = ByteBuffer.allocate(16);
+	 * traceId128.putLong(span.getTraceIdHigh());
+	 * traceId128.putLong(span.getTraceId());
+	 * traceBytes = traceId128.array();
+	 * }</pre>
+	 *
+	 * @see #traceIdString()
+	 * @since 1.0.11
+	 */
+	public long getTraceIdHigh() {
+		return this.traceIdHigh;
+	}
+
+	/**
+	 * Unique 8-byte identifier for a trace, set on all spans within it.
+	 *
+	 * @see #getTraceIdHigh() for notes about 128-bit trace identifiers
 	 */
 	public long getTraceId() {
 		return this.traceId;
@@ -413,8 +463,27 @@ public boolean isExportable() {
 		return this.exportable;
 	}
 
+	/**
+	 * Returns the 16 or 32 character hex representation of the span's trace ID
+	 *
+	 * @since 1.0.11
+	 */
+	public String traceIdString() {
+		if (this.traceIdHigh != 0) {
+			char[] result = new char[32];
+			writeHexLong(result, 0, this.traceIdHigh);
+			writeHexLong(result, 16, this.traceId);
+			return new String(result);
+		}
+		char[] result = new char[16];
+		writeHexLong(result, 0, this.traceId);
+		return new String(result);
+	}
+
 	/**
 	 * Represents given long id as 16-character lower-hex string
+	 *
+	 * @see #traceIdString()
 	 */
 	public static String idToHex(long id) {
 		char[] data = new char[16];
@@ -449,29 +518,40 @@ static void writeHexByte(char[] data, int pos, byte b) {
 	public static long hexToId(String hexString) {
 		Assert.hasText(hexString, "Can't convert empty hex string to long");
 		int length = hexString.length();
-		if (length < 1 || length > 32) throw new IllegalArgumentException("Malformed id");
+		if (length < 1 || length > 32) throw new IllegalArgumentException("Malformed id: " + hexString);
 
 		// trim off any high bits
-		int i = length > 16 ? length - 16 : 0;
+		int beginIndex = length > 16 ? length - 16 : 0;
+
+		return hexToId(hexString, beginIndex);
+	}
 
+	/**
+	 * Parses a 16 character lower-hex string with no prefix into an unsigned long, starting at the
+	 * specified index.
+	 *
+	 * @since 1.0.11
+	 */
+	public static long hexToId(String lowerHex, int index) {
+		Assert.hasText(lowerHex, "Can't convert empty hex string to long");
 		long result = 0;
-		for (; i < length; i++) {
-			char c = hexString.charAt(i);
+		for (int endIndex = Math.min(index + 16, lowerHex.length()); index < endIndex; index++) {
+			char c = lowerHex.charAt(index);
 			result <<= 4;
 			if (c >= '0' && c <= '9') {
 				result |= c - '0';
 			} else if (c >= 'a' && c <= 'f') {
 				result |= c - 'a' + 10;
 			} else {
-				throw new IllegalArgumentException("Malformed id");
+				throw new IllegalArgumentException("Malformed id: " + lowerHex);
 			}
 		}
 		return result;
 	}
 
 	@Override
 	public String toString() {
-		return "[Trace: " + idToHex(this.traceId) + ", Span: " + idToHex(this.spanId)
+		return "[Trace: " + traceIdString() + ", Span: " + idToHex(this.spanId)
 				+ ", Parent: " + getParentIdIfPresent() + ", exportable:" + this.exportable + "]";
 	}
 
@@ -481,31 +561,36 @@ private String getParentIdIfPresent() {
 
 	@Override
 	public int hashCode() {
-		final int prime = 31;
-		int result = 1;
-		result = prime * result + (int) (this.spanId ^ (this.spanId >>> 32));
-		result = prime * result + (int) (this.traceId ^ (this.traceId >>> 32));
-		return result;
+		int h = 1;
+		h *= 1000003;
+		h ^= (this.traceIdHigh >>> 32) ^ this.traceIdHigh;
+		h *= 1000003;
+		h ^= (this.traceId >>> 32) ^ this.traceId;
+		h *= 1000003;
+		h ^= (this.spanId >>> 32) ^ this.spanId;
+		h *= 1000003;
+		return h;
 	}
 
 	@Override
-	public boolean equals(Object obj) {
-		if (this == obj)
+	public boolean equals(Object o) {
+		if (o == this) {
 			return true;
-		if (obj == null)
-			return false;
-		if (getClass() != obj.getClass())
-			return false;
-		Span other = (Span) obj;
-		if (this.spanId != other.spanId)
-			return false;
-		return this.traceId == other.traceId;
+		}
+		if (o instanceof Span) {
+			Span that = (Span) o;
+			return (this.traceIdHigh == that.traceIdHigh)
+					&& (this.traceId == that.traceId)
+					&& (this.spanId == that.spanId);
+		}
+		return false;
 	}
 
 	public static class SpanBuilder {
 		private long begin;
 		private long end;
 		private String name;
+		private long traceIdHigh;
 		private long traceId;
 		private ArrayList<Long> parents = new ArrayList<>();
 		private long spanId;
@@ -541,6 +626,11 @@ public Span.SpanBuilder name(String name) {
 			return this;
 		}
 
+		public Span.SpanBuilder traceIdHigh(long traceIdHigh) {
+			this.traceIdHigh = traceIdHigh;
+			return this;
+		}
+
 		public Span.SpanBuilder traceId(long traceId) {
 			this.traceId = traceId;
 			return this;
@@ -602,22 +692,12 @@ public Span.SpanBuilder savedSpan(Span savedSpan) {
 		}
 
 		public Span build() {
-			Span span = new Span(this.begin, this.end, this.name, this.traceId,
-					this.parents, this.spanId, this.remote, this.exportable,
-					this.processId, this.savedSpan);
-			span.logs.addAll(this.logs);
-			span.tags.putAll(this.tags);
-			return span;
+			return new Span(this);
 		}
 
 		@Override
 		public String toString() {
-			return "SpanBuilder{" + "begin=" + this.begin + ", end=" + this.end
-					+ ", name=" + this.name + ", traceId=" + this.traceId + ", parents="
-					+ this.parents + ", spanId=" + this.spanId + ", remote=" + this.remote
-					+ ", exportable=" + this.exportable + ", processId='" + this.processId
-					+ '\'' + ", savedSpan=" + this.savedSpan + ", logs=" + this.logs
-					+ ", tags=" + this.tags + '}';
+			return new Span(this).toString();
 		}
 	}
 }

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/messaging/MessagingSpanExtractor.java

@@ -76,12 +76,14 @@ private Span extractSpanFromNewHeaders(Message<?> carrier, SpanBuilder spanBuild
 	private Span extractSpanFromHeaders(Message<?> carrier, SpanBuilder spanBuilder,
 			String traceIdHeader, String spanIdHeader, String spanSampledHeader,
 			String spanProcessIdHeader, String spanNameHeader, String spanParentIdHeader) {
-		long traceId = Span
-				.hexToId(getHeader(carrier, traceIdHeader));
+		String traceId = getHeader(carrier, traceIdHeader);
+		spanBuilder.traceIdHigh(traceId.length() == 32 ? Span.hexToId(traceId, 0) : 0);
+		spanBuilder.traceId(Span.hexToId(traceId));
+
 		long spanId = hasHeader(carrier, spanIdHeader)
 				? Span.hexToId(getHeader(carrier, spanIdHeader))
 				: this.random.nextLong();
-		spanBuilder = spanBuilder.traceId(traceId).spanId(spanId);
+		spanBuilder = spanBuilder.spanId(spanId);
 		spanBuilder.exportable(
 				Span.SPAN_SAMPLED.equals(getHeader(carrier, spanSampledHeader)));
 		String processId = getHeader(carrier, spanProcessIdHeader);

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/messaging/MessagingSpanInjector.java

@@ -95,7 +95,7 @@ private void addHeaders(Span span, Message<?> initialMessage,
 			MessageHeaderAccessor accessor, Map<String, String> headers, String traceIdHeader,
 			String spanIdHeader, String parentIdHeader, String spanNameHeader, String processIdHeader,
 			String spanSampledHeader, String spanHeader) {
-		addHeader(headers, traceIdHeader, Span.idToHex(span.getTraceId()));
+		addHeader(headers, traceIdHeader, span.traceIdString());
 		addHeader(headers, spanIdHeader, Span.idToHex(span.getSpanId()));
 		if (span.isExportable()) {
 			addAnnotations(this.traceKeys, initialMessage, span);

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/HttpServletRequestExtractor.java

@@ -58,32 +58,33 @@ public Span joinTrace(HttpServletRequest carrier) {
 			String uri = this.urlPathHelper.getPathWithinApplication(carrier);
 			boolean skip = this.skipPattern.matcher(uri).matches()
 					|| Span.SPAN_NOT_SAMPLED.equals(carrier.getHeader(Span.SAMPLED_NAME));
-			long traceId = Span
-					.hexToId(carrier.getHeader(Span.TRACE_ID_NAME));
-			long spanId = spanId(carrier, traceId);
-			return buildParentSpan(carrier, uri, skip, traceId, spanId);
+			long spanId = spanId(carrier);
+			return buildParentSpan(carrier, uri, skip, spanId);
 		} catch (Exception e) {
 			log.error("Exception occurred while trying to extract span from carrier", e);
 			return null;
 		}
 	}
 
-	private long spanId(HttpServletRequest carrier, long traceId) {
+	private long spanId(HttpServletRequest carrier) {
 		String spanId = carrier.getHeader(Span.SPAN_ID_NAME);
 		if (spanId == null) {
 			if (log.isDebugEnabled()) {
 				log.debug("Request is missing a span id but it has a trace id. We'll assume that this is "
-						+ "a root span with span id equal to trace id");
+						+ "a root span with span id equal to the lower 64-bits of the trace id");
 			}
-			return traceId;
+			return Span.hexToId(carrier.getHeader(Span.TRACE_ID_NAME));
 		} else {
 			return Span.hexToId(spanId);
 		}
 	}
 
-	private Span buildParentSpan(HttpServletRequest carrier, String uri, boolean skip,
-			long traceId, long spanId) {
-		SpanBuilder span = Span.builder().traceId(traceId).spanId(spanId);
+	private Span buildParentSpan(HttpServletRequest carrier, String uri, boolean skip, long spanId) {
+		String traceId = carrier.getHeader(Span.TRACE_ID_NAME);
+		SpanBuilder span = Span.builder()
+			.traceIdHigh(traceId.length() == 32 ? Span.hexToId(traceId, 0) : 0)
+			.traceId(Span.hexToId(traceId))
+			.spanId(spanId);
 		String processId = carrier.getHeader(Span.PROCESS_ID_NAME);
 		String parentName = carrier.getHeader(Span.SPAN_NAME_NAME);
 		if (StringUtils.hasText(parentName)) {

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/HttpRequestInjector.java

@@ -32,7 +32,7 @@ class HttpRequestInjector implements SpanInjector<HttpRequest> {
 
 	@Override
 	public void inject(Span span, HttpRequest carrier) {
-		setIdHeader(carrier, Span.TRACE_ID_NAME, span.getTraceId());
+		setHeader(carrier, Span.TRACE_ID_NAME, span.traceIdString());
 		setIdHeader(carrier, Span.SPAN_ID_NAME, span.getSpanId());
 		setHeader(carrier, Span.SAMPLED_NAME, span.isExportable() ? Span.SPAN_SAMPLED : Span.SPAN_NOT_SAMPLED);
 		setHeader(carrier, Span.SPAN_NAME_NAME, span.getName());

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/RequestContextInjector.java

@@ -41,7 +41,7 @@ public void inject(Span span, RequestContext carrier) {
 			return;
 		}
 		setHeader(requestHeaders, Span.SPAN_ID_NAME, span.getSpanId());
-		setHeader(requestHeaders, Span.TRACE_ID_NAME, span.getTraceId());
+		setHeader(requestHeaders, Span.TRACE_ID_NAME, span.traceIdString());
 		setHeader(requestHeaders, Span.SPAN_NAME_NAME, span.getName());
 		setHeader(requestHeaders, Span.SAMPLED_NAME, span.isExportable() ?
 				Span.SPAN_SAMPLED : Span.SPAN_NOT_SAMPLED);

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jSpanLogger.java

@@ -49,7 +49,7 @@ public Slf4jSpanLogger(String nameSkipPattern) {
 	public void logStartedSpan(Span parent, Span span) {
 		MDC.put(Span.SPAN_ID_NAME, Span.idToHex(span.getSpanId()));
 		MDC.put(Span.SPAN_EXPORT_NAME, String.valueOf(span.isExportable()));
-		MDC.put(Span.TRACE_ID_NAME, Span.idToHex(span.getTraceId()));
+		MDC.put(Span.TRACE_ID_NAME, span.traceIdString());
 		log("Starting span: {}", span);
 		if (parent != null) {
 			log("With parent: {}", parent);
@@ -59,7 +59,7 @@ public void logStartedSpan(Span parent, Span span) {
 	@Override
 	public void logContinuedSpan(Span span) {
 		MDC.put(Span.SPAN_ID_NAME, Span.idToHex(span.getSpanId()));
-		MDC.put(Span.TRACE_ID_NAME, Span.idToHex(span.getTraceId()));
+		MDC.put(Span.TRACE_ID_NAME, span.traceIdString());
 		MDC.put(Span.SPAN_EXPORT_NAME, String.valueOf(span.isExportable()));
 		log("Continued span: {}", span);
 	}