feat: add long trace and span id to context (#147)

src/docs/asciidoc/module-config.adoc

@@ -387,6 +387,16 @@ NOTE: OpenTelemetry Trace Context is extracted/injected using configured Propaga
 
 ===== Context Injection
 
+To help with the context propagation, module allows to inject context into flow variables. This context includes following trace attributes -
+
+- *TRACE_TRANSACTION_ID* - An internal transaction id within Mule Context
+- *traceId* - Trace id of the current request
+- *traceIdLongLowPart* - Long value of the Trace Id Low part
+- *spanId* - Span Id for the component used for creating context
+- OpenTelemetry Trace attributes such as *traceparent*, *tracestate*
+
+Context can be injected in two ways, as described below.
+
 ====== Auto Injection to Flow Variables
 Extension uses a processor interceptor. OpenTelemetry's tracing context will be automatically added to a flow variable before the first processor is invoked.
 It is always injected under a key **OTEL_TRACE_CONTEXT**.
@@ -403,6 +413,8 @@ When the flow execution starts, OpenTelemetry context is injected into flow vari
 
 WARNING: This context relates to the main flow span and if used for propagation to external services then span rendering may not look accurate.See processor interceptor below.
 
+NOTE: OTEL_TRACE_CONTEXT.spanId will be of the flow container span.
+
 Following examples show a **W3C Trace Context** extracted from incoming http request and injected into flow variables:
 
 image::auto-context-flow-injection.png[600,600,title="Context Injection - First Processor",align="center"]
@@ -415,7 +427,9 @@ image::auto-context-flow-injection-2.png[600,600,title="Context Injection - Firs
 
 For the context propagation accuracy, certain processors are intercepted to inject current span's context into the flow variable.
 
-By default, any processors in `ee,mule,validations,aggregators,json,oauth,scripting,tracing,oauth2-provider,xml,wss,spring,java,avio-logger` namespaces are excluded from this context injection, with one exception.
+NOTE: *OTEL_TRACE_CONTEXT.spanId* will be of the span of the intercepted component.
+
+By default, any processors in the `ee,mule,validations,aggregators,json,oauth,scripting,tracing,oauth2-provider,xml,wss,spring,java,avio-logger` namespaces are excluded from this context injection, with one exception.
 
 There is one exception in `mule` namespace - `flow-ref`. All `flow-ref` 's are intercepted for context injection. Module's flow processing is capable of extracting this flow-ref context to create accurate parent-child span relationship between calling and referenced flows.
 
@@ -432,7 +446,9 @@ image::processor-interceptor-configuration.png[600, 600, title="Trace Level - Pr
 ====== Manual Injection
 If needed, `<opentelemetry:get-trace-context />` operation can be used to manually inject trace context into flow.
 
-**NOTE:** `target` must be used to set operation output to a flow variable.
+NOTE: `target` must be used to set operation output to a flow variable.
+
+NOTE: *OTEL_TRACE_CONTEXT.spanId* will be of the flow container span.
 
 WARNING: Similar to link:module-config.adoc#_first_processor_interceptor[First Processor Interceptor], tis context relates to the main flow span and if used for propagation to external services then span rendering may not look accurate.
 
@@ -501,6 +517,68 @@ Once you have configured the module in your application, there may be a need to
 - Alternately, you can set the `mule.otel.tracing.disabled` system property to `true`.
 - To re-enable the tracing, just reset the property to `false` (default value).
 
+=== Logs Correlation
+
+When APM backends are used to capture Logs as well as Traces, they might support log and trace correlation.
+Depending on the APM, some specific attributes maybe needed in the log records to correlate them to the corresponding traces.
+
+Most commonly used attributes include -
+
+- Trace Id
+* Loggers can access the current trace id with `vars.OTEL_TRACE_CONTEXT.traceId`
+* Some APM backends (eg. DataDog) may require the Long trace Id instead of the 32-hex-character trace Id value. In that case, `vars.OTEL_TRACE_CONTEXT.traceIdLongLowPart` (since v1.6.0) can be used.
+- Span Id
+* Introduced with v1.5.0, Loggers can access the flow container span id with `vars.OTEL_TRACE_CONTEXT.spanId`
+* Some APM backends (eg. DataDog) may require the Long span Id instead of the 16-hex-character span Id value. In that case, `vars.OTEL_TRACE_CONTEXT.spanIdLong` (since v1.6.0) can be used.
+- Service name
+* Usually a static value, name of the application which can be injected through application properties such as `${domain}`
+- Deployment Environment
+* Usually a static value, name of the environment which can be injected through application properties such as `${mule.env}`
+
+==== Using Mule Tracing Module
+To add trace ID and span ID, you may add a mule tracing module to target the Mule application.
+
+[source,xml]
+----
+ <dependency>
+ <groupId>org.mule.modules</groupId>
+ <artifactId>mule-tracing-module</artifactId>
+ <version>1.0.0</version>
+ <classifier>mule-plugin</classifier>
+ </dependency>
+----
+
+In the first APIKit flow, add tracing module operations -
+
+[source,xml]
+----
+ <tracing:set-logging-variable doc:name="Set Trace Id"
+ variableName="#['trace_id']"
+ value="#[vars.OTEL_TRACE_CONTEXT.traceId]"/>
+ <tracing:set-logging-variable doc:name="Set Span Id"
+ variableName="#['span_id']"
+ value="#[vars.OTEL_TRACE_CONTEXT.spanId default '']" />
+----
+
+==== Use Log4J JSON Layout
+
+When logging with Log4J, JSONLayout can be used to structure the log records with additional attributes.
+
+.Example JSONLayout writing to CONSOLE
+[source, xml]
+----
+ <!-- Console JSON layout that can be used to see full JSON format that will be sent for log aggregation in a real environment -->
+ <console name = "CONSOLE_JSON" target = "SYSTEM_OUT">
+ <JSONLayout includeTimeMillis="true" compact="false" eventEol="true" objectMessageAsJsonObject="true" properties="true" stacktraceAsString="true">
+ <KeyValuePair key="trace_id" value="${ctx:trace_id}"/>
+ <KeyValuePair key="span_id" value="${ctx:span_id}"/>
+ <KeyValuePair key="service.name" value="$${sys:domain}"/>
+ <KeyValuePair key="deployment.environment" value="$${env:mule.env}"/>
+ <KeyValuePair key="timestamp" value="$${date:yyyy-MM-dd'T'HH:mm:ss.SSSZZZZ}" />
+ </JSONLayout>
+ </console>
+----
+
 === Generated Documentation
 
 * link:./opentelemetry-documentation.html[Connector documentation]

src/main/java/com/avioconsulting/mule/opentelemetry/internal/connection/OpenTelemetryConnection.java

@@ -35,6 +35,8 @@
 
 public class OpenTelemetryConnection implements TraceContextHandler {
 
+ public static final String TRACE_ID_LONG_LOW_PART = "traceIdLongLowPart";
+ public static final String SPAN_ID_LONG = "spanIdLong";
  private final Logger logger = LoggerFactory.getLogger(OpenTelemetryConnection.class);
 
  /**
@@ -197,8 +199,10 @@ public Map<String, String> getTraceContext(String transactionId, ComponentLocati
  componentLocation);
  Map<String, String> traceContext = new HashMap<>(10);
  traceContext.put(TRACE_TRANSACTION_ID, transactionId);
- traceContext.put(TRACE_ID, getTransactionStore().getTraceIdForTransaction(transactionId));
+ traceContext.put(TRACE_ID, transactionContext.getTraceId());
+ traceContext.put(TRACE_ID_LONG_LOW_PART, transactionContext.getTraceIdLongLowPart());
  traceContext.put(SPAN_ID, transactionContext.getSpanId());
+ traceContext.put(SPAN_ID_LONG, transactionContext.getSpanIdLong());
  injectTraceContext(transactionContext.getContext(), traceContext,
  HashMapTextMapSetter.INSTANCE);
  logger.debug("Created trace context '{}' for TRACE_TRANSACTION_ID={}, Component Location '{}'", traceContext,

src/main/java/com/avioconsulting/mule/opentelemetry/internal/store/TransactionContext.java

@@ -1,22 +1,63 @@
 package com.avioconsulting.mule.opentelemetry.internal.store;
 
+import com.avioconsulting.mule.opentelemetry.internal.util.EncodingUtil;
 import io.opentelemetry.api.trace.Span;
+import io.opentelemetry.api.trace.SpanId;
+import io.opentelemetry.api.trace.TraceId;
 import io.opentelemetry.context.Context;
 
 import java.util.Objects;
 
 public class TransactionContext {
- private Context context;
- private String spanId;
+ private Context context = Context.current();
+
+ /**
+ * Get the 16-hex-character lowercase string span id
+ */
+ private String spanId = SpanId.getInvalid();
+ /**
+ * Trace id is a 32-hex-character lowercase string built with two
+ * 16-hex-character lowercase strings,
+ * each representing a long value encoded to hex.
+ * First 16 characters represent High-long and the last 16 characters represent
+ * Low-long values making the trace id.
+ */
+ private String traceId = TraceId.getInvalid();
+
+ /**
+ * This method returns the String formatted Long value of span id. See
+ * {@link TransactionContext#getSpanId()}.
+ * Example: Span Id - "53f9aa133a283c1a"
+ * Long Low Id - "6051054573905787930"
+ */
+ private String spanIdLong = "0";
+
+ /**
+ * This method returns the String formatted Long value of the Low part of the
+ * trace id. See {@link TransactionContext#getTraceId()}.
+ * Example: Trace Id - fbc14552c62fbabc6a4bc6817cd983ce
+ * High-part - "fbc14552c62fbabc"
+ * Low-part - "6a4bc6817cd983ce"
+ * Long Low Id - "7659433850721371086"
+ */
+ private String traceIdLongLowPart = "0";
 
  public static TransactionContext of(Span span) {
- return new TransactionContext()
+ TransactionContext transactionContext = new TransactionContext()
  .setContext(span.storeInContext(Context.current()))
- .setSpanId(span.getSpanContext().getSpanId());
+ .setSpanId(span.getSpanContext().getSpanId())
+ .setTraceId(span.getSpanContext().getTraceId());
+ if (SpanId.isValid(transactionContext.getSpanId())) {
+ transactionContext.setSpanIdLong(EncodingUtil.longFromBase16Hex(transactionContext.getSpanId()));
+ }
+ if (TraceId.isValid(transactionContext.getTraceId())) {
+ transactionContext.setTraceIdLongLowPart(EncodingUtil.traceIdLong(transactionContext.getTraceId())[1]);
+ }
+ return transactionContext;
  }
 
  public static TransactionContext current() {
- return new TransactionContext().setContext(Context.current());
+ return new TransactionContext();
  }
 
  public Context getContext() {
@@ -37,18 +78,48 @@ public TransactionContext setSpanId(String spanId) {
  return this;
  }
 
+ public String getTraceId() {
+ return traceId;
+ }
+
+ public TransactionContext setTraceId(String traceId) {
+ this.traceId = traceId;
+ return this;
+ }
+
+ public String getSpanIdLong() {
+ return spanIdLong;
+ }
+
+ public TransactionContext setSpanIdLong(String spanIdLong) {
+ this.spanIdLong = spanIdLong;
+ return this;
+ }
+
+ public String getTraceIdLongLowPart() {
+ return traceIdLongLowPart;
+ }
+
+ public TransactionContext setTraceIdLongLowPart(String traceIdLongLowPart) {
+ this.traceIdLongLowPart = traceIdLongLowPart;
+ return this;
+ }
+
  @Override
  public boolean equals(Object o) {
  if (this == o)
  return true;
  if (o == null || getClass() != o.getClass())
  return false;
  TransactionContext that = (TransactionContext) o;
- return Objects.equals(getContext(), that.getContext()) && Objects.equals(getSpanId(), that.getSpanId());
+ return Objects.equals(getContext(), that.getContext()) && Objects.equals(getSpanId(), that.getSpanId())
+ && Objects.equals(getTraceId(), that.getTraceId())
+ && Objects.equals(getSpanIdLong(), that.getSpanIdLong())
+ && Objects.equals(getTraceIdLongLowPart(), that.getTraceIdLongLowPart());
  }
 
  @Override
  public int hashCode() {
- return Objects.hash(getContext(), getSpanId());
+ return Objects.hash(getContext(), getSpanId(), getTraceId(), getSpanIdLong(), getTraceIdLongLowPart());
  }
 }

src/main/java/com/avioconsulting/mule/opentelemetry/internal/util/EncodingUtil.java

@@ -0,0 +1,17 @@
+package com.avioconsulting.mule.opentelemetry.internal.util;
+
+import static java.lang.Long.parseUnsignedLong;
+import static java.lang.Long.toUnsignedString;
+
+public class EncodingUtil {
+ public static String longFromBase16Hex(String inputHex) {
+ long longValue = parseUnsignedLong(inputHex, 16);
+ return toUnsignedString(longValue);
+ }
+
+ public static String[] traceIdLong(String inputHex) {
+ String hiLong = longFromBase16Hex(inputHex.substring(0, 16));
+ String lowLong = longFromBase16Hex(inputHex.substring(16));
+ return new String[] { hiLong, lowLong };
+ }
+}

src/test/java/com/avioconsulting/mule/opentelemetry/MuleOpenTelemetryOperationsTest.java

@@ -49,6 +49,13 @@ public void testHttpTracing_GetTraceContext() throws Exception {
  .getVariables().get("OTEL_CONTEXT");
  assertThat(otel_trace_context_from_interceptor.getValue())
  .containsExactlyEntriesOf(otel_context_from_operation.getValue());
+ assertThat(otel_trace_context_from_interceptor.getValue())
+ .containsKeys("traceId", "spanId", "spanIdLong", "traceIdLongLowPart", "TRACE_TRANSACTION_ID");
+ assertThat(otel_trace_context_from_interceptor.getValue())
+ .hasEntrySatisfying("spanIdLong", (value) -> assertThat(Long.parseUnsignedLong(value)).isNotEqualTo(0));
+ assertThat(otel_trace_context_from_interceptor.getValue())
+ .hasEntrySatisfying("traceIdLongLowPart",
+ (value) -> assertThat(Long.parseUnsignedLong(value)).isNotEqualTo(0));
  }
 
 }

src/test/java/com/avioconsulting/mule/opentelemetry/internal/store/TransactionContextTest.java

@@ -0,0 +1,46 @@
+package com.avioconsulting.mule.opentelemetry.internal.store;
+
+import io.opentelemetry.api.trace.Span;
+import io.opentelemetry.api.trace.SpanContext;
+import io.opentelemetry.context.Context;
+import org.assertj.core.api.Assertions;
+import org.junit.Test;
+
+import static org.junit.Assert.*;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
+
+public class TransactionContextTest {
+
+ @Test
+ public void current() {
+ TransactionContext transactionContext = TransactionContext.current();
+ Assertions.assertThat(transactionContext)
+ .extracting("spanId", "spanIdLong", "traceId", "traceIdLongLowPart")
+ .containsOnly("0000000000000000", "0", "00000000000000000000000000000000", "0");
+ Assertions.assertThat(transactionContext.getContext())
+ .as("Current Context")
+ .isNotNull();
+ }
+
+ @Test
+ public void ofValidSpan() {
+ Span span = mock(Span.class);
+ SpanContext spanContext = mock(SpanContext.class);
+ when(spanContext.getSpanId()).thenReturn("53f9aa133a283c1a");
+ when(spanContext.getTraceId()).thenReturn("fbc14552c62fbabc6a4bc6817cd983ce");
+ when(span.getSpanContext()).thenReturn(spanContext);
+ when(span.storeInContext(any(Context.class))).thenReturn(Context.current());
+
+ TransactionContext transactionContext = TransactionContext.of(span);
+ Assertions.assertThat(transactionContext)
+ .extracting("spanId", "spanIdLong", "traceId", "traceIdLongLowPart")
+ .containsOnly("53f9aa133a283c1a", "6051054573905787930", "fbc14552c62fbabc6a4bc6817cd983ce",
+ "7659433850721371086");
+ Assertions.assertThat(transactionContext.getContext())
+ .as("Current Context")
+ .isNotNull();
+ }
+
+}