diff --git a/dev/com.ibm.ws.logging/src/com/ibm/ws/logging/collector/CollectorConstants.java b/dev/com.ibm.ws.logging/src/com/ibm/ws/logging/collector/CollectorConstants.java index cd8e1705a438..e92899d469b8 100644 --- a/dev/com.ibm.ws.logging/src/com/ibm/ws/logging/collector/CollectorConstants.java +++ b/dev/com.ibm.ws.logging/src/com/ibm/ws/logging/collector/CollectorConstants.java @@ -52,5 +52,8 @@ public class CollectorConstants { public static final String ACCESS_TRACE_W3C_HEADER_NAME = "traceparent"; public static final String ACCESS_TRACE_JAEGER_HEADER_NAME = "uber-trace-id"; public static final String ACCESS_TRACE_B3_HEADER_NAME = "b3"; + public static final String ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME = "X-B3-TraceId"; + public static final String ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME = "X-B3-SpanId"; + public static final String ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME = "X-B3-Sampled"; } diff --git a/dev/com.ibm.ws.transport.http/src/com/ibm/ws/http/logging/source/AccessLogSource.java b/dev/com.ibm.ws.transport.http/src/com/ibm/ws/http/logging/source/AccessLogSource.java index 69c10ef96b75..fa64d0e79511 100644 --- a/dev/com.ibm.ws.transport.http/src/com/ibm/ws/http/logging/source/AccessLogSource.java +++ b/dev/com.ibm.ws.transport.http/src/com/ibm/ws/http/logging/source/AccessLogSource.java @@ -603,6 +603,15 @@ private static SetterFormatter createSetterFormatter(Configuration config, Forma fieldSetters.add((ald, alrd) -> ald.setRequestHeader(CollectorConstants.ACCESS_TRACE_JAEGER_HEADER_NAME, AccessLogRequestHeaderValue.getHeaderValue(alrd.getResponse(), alrd.getRequest(), CollectorConstants.ACCESS_TRACE_JAEGER_HEADER_NAME))); + fieldSetters.add((ald, alrd) -> ald.setRequestHeader(CollectorConstants.ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME, + AccessLogRequestHeaderValue.getHeaderValue(alrd.getResponse(), alrd.getRequest(), + CollectorConstants.ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME))); + fieldSetters.add((ald, alrd) -> ald.setRequestHeader(CollectorConstants.ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME, + AccessLogRequestHeaderValue.getHeaderValue(alrd.getResponse(), alrd.getRequest(), + CollectorConstants.ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME))); + fieldSetters.add((ald, alrd) -> ald.setRequestHeader(CollectorConstants.ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME, + AccessLogRequestHeaderValue.getHeaderValue(alrd.getResponse(), alrd.getRequest(), + CollectorConstants.ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME))); } else if (accessLogFieldsTelemetryConfig.equals("logFormat")) { formatters[5] = populateCustomTelemetryFormatters(fieldsToAddTelemetryLogging, CollectorConstants.KEYS_TELEMETRY_LOGGING); @@ -618,7 +627,15 @@ private static SetterFormatter createSetterFormatter(Configuration config, Forma fieldSetters.add((ald, alrd) -> ald.setRequestHeader(CollectorConstants.ACCESS_TRACE_JAEGER_HEADER_NAME, AccessLogRequestHeaderValue.getHeaderValue(alrd.getResponse(), alrd.getRequest(), CollectorConstants.ACCESS_TRACE_JAEGER_HEADER_NAME))); - + fieldSetters.add((ald, alrd) -> ald.setRequestHeader(CollectorConstants.ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME, + AccessLogRequestHeaderValue.getHeaderValue(alrd.getResponse(), alrd.getRequest(), + CollectorConstants.ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME))); + fieldSetters.add((ald, alrd) -> ald.setRequestHeader(CollectorConstants.ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME, + AccessLogRequestHeaderValue.getHeaderValue(alrd.getResponse(), alrd.getRequest(), + CollectorConstants.ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME))); + fieldSetters.add((ald, alrd) -> ald.setRequestHeader(CollectorConstants.ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME, + AccessLogRequestHeaderValue.getHeaderValue(alrd.getResponse(), alrd.getRequest(), + CollectorConstants.ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME))); } newSF.setSettersAndFormatters(fieldSetters, formatters); diff --git a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal/src/io/openliberty/microprofile/telemetry20/logging/internal/MpTelemetryLogFieldConstants.java b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal/src/io/openliberty/microprofile/telemetry20/logging/internal/MpTelemetryLogFieldConstants.java index 057c4906985c..4caf67ebf7c2 100644 --- a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal/src/io/openliberty/microprofile/telemetry20/logging/internal/MpTelemetryLogFieldConstants.java +++ b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal/src/io/openliberty/microprofile/telemetry20/logging/internal/MpTelemetryLogFieldConstants.java @@ -155,5 +155,8 @@ public class MpTelemetryLogFieldConstants { public static final String ACCESS_TRACE_W3C_HEADER_NAME = "traceparent"; public static final String ACCESS_TRACE_JAEGER_HEADER_NAME = "uber-trace-id"; public static final String ACCESS_TRACE_B3_HEADER_NAME = "b3"; + public static final String ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME = "X-B3-TraceId"; + public static final String ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME = "X-B3-SpanId"; + public static final String ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME = "X-B3-Sampled"; } diff --git a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal/src/io/openliberty/microprofile/telemetry20/logging/internal/MpTelemetryLogMappingUtils.java b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal/src/io/openliberty/microprofile/telemetry20/logging/internal/MpTelemetryLogMappingUtils.java index 1ad69a6429ef..094c753f4aed 100644 --- a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal/src/io/openliberty/microprofile/telemetry20/logging/internal/MpTelemetryLogMappingUtils.java +++ b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal/src/io/openliberty/microprofile/telemetry20/logging/internal/MpTelemetryLogMappingUtils.java @@ -348,6 +348,10 @@ private static void mapAccessToOpenTelemetry(LogRecordBuilder builder, String ev Object value = null; Span customSpan = null; + String b3MultiTrace = null; + String b3MultiSpan = null; + String b3MultiSampling = null; + for (Iterator element = kvpList.iterator(); element.hasNext();) { KeyValuePair next = element.next(); key = next.getKey(); @@ -366,6 +370,12 @@ private static void mapAccessToOpenTelemetry(LogRecordBuilder builder, String ev if (key.contains(MpTelemetryLogFieldConstants.ACCESS_TRACE_W3C_HEADER_NAME) || key.contains(MpTelemetryLogFieldConstants.ACCESS_TRACE_B3_HEADER_NAME) || key.contains(MpTelemetryLogFieldConstants.ACCESS_TRACE_JAEGER_HEADER_NAME)) { customSpan = createSpan(key, (String) value); + } else if (key.contains(MpTelemetryLogFieldConstants.ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME)) { + b3MultiSpan = (String) value; + } else if (key.contains(MpTelemetryLogFieldConstants.ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME)) { + b3MultiTrace = (String) value; + } else if (key.contains(MpTelemetryLogFieldConstants.ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME)) { + b3MultiSampling = (String) value; } else { String[] headerSplit = ((String) value).split(","); for (int i = 0; i < headerSplit.length; i++) { @@ -400,8 +410,13 @@ else if (value instanceof Integer) // Set the Attributes to the builder. builder.setAllAttributes(attributes.build()); + if (customSpan == null && b3MultiSpan != null && b3MultiTrace != null) { + customSpan = createSpan(MpTelemetryLogFieldConstants.ACCESS_REQUEST_HEADER_PREFIX + MpTelemetryLogFieldConstants.ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME, + b3MultiTrace + "-" + b3MultiSpan + "-" + b3MultiSampling); + } + // Set the Span and Trace IDs from the current context. We're not on the same thread at the point when access logs are collected - // so we need to extract the trace/span ID from the 'traceparent' request header. + // so we need to extract the trace/span ID from each propagators' respective request headers. if (customSpan != null) { builder.setContext(Context.current().with(customSpan)); } else @@ -410,7 +425,7 @@ else if (value instanceof Integer) } /* - * Create a span using the extracted requestHeader data for the propagators w3c, b3, and jaeger. + * Create a span using the extracted requestHeader data for the propagators w3c, b3, b3multi, and jaeger. */ private static Span createSpan(String key, String requestHeader) { @@ -418,13 +433,24 @@ private static Span createSpan(String key, String requestHeader) { try { if (key.equals(MpTelemetryLogFieldConstants.ACCESS_REQUEST_HEADER_PREFIX + MpTelemetryLogFieldConstants.ACCESS_TRACE_W3C_HEADER_NAME)) { // Check the w3c format for the "traceparent" header. This is the default otel propagator String[] traceSplit = requestHeader.split("-"); - customSpanContext = SpanContext.create(traceSplit[1], traceSplit[2], TraceFlags.getSampled(), TraceState.getDefault()); + TraceFlags sampling = isSampledValue(traceSplit[3]) ? TraceFlags.getSampled() : TraceFlags.getDefault(); + + customSpanContext = SpanContext.create(traceSplit[1], traceSplit[2], sampling, TraceState.getDefault()); } else if (key.equals(MpTelemetryLogFieldConstants.ACCESS_REQUEST_HEADER_PREFIX + MpTelemetryLogFieldConstants.ACCESS_TRACE_B3_HEADER_NAME)) { // Check the b3 format for the "b3" header String[] traceSplit = requestHeader.split("-"); - customSpanContext = SpanContext.create(traceSplit[0], traceSplit[1], TraceFlags.getSampled(), TraceState.getDefault()); + TraceFlags sampling = isSampledValue(traceSplit[2]) ? TraceFlags.getSampled() : TraceFlags.getDefault(); + + customSpanContext = SpanContext.create(traceSplit[0], traceSplit[1], sampling, TraceState.getDefault()); } else if (key.equals(MpTelemetryLogFieldConstants.ACCESS_REQUEST_HEADER_PREFIX + MpTelemetryLogFieldConstants.ACCESS_TRACE_JAEGER_HEADER_NAME)) { // Check the Jaeger format for the "uber-trace-id" header String[] traceSplit = requestHeader.split(":"); - customSpanContext = SpanContext.create(traceSplit[0], traceSplit[1], TraceFlags.getSampled(), TraceState.getDefault()); + TraceFlags sampling = isSampledValue(traceSplit[3]) ? TraceFlags.getSampled() : TraceFlags.getDefault(); + + customSpanContext = SpanContext.create(traceSplit[0], traceSplit[1], sampling, TraceState.getDefault()); + } else if (key.equals(MpTelemetryLogFieldConstants.ACCESS_REQUEST_HEADER_PREFIX + MpTelemetryLogFieldConstants.ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME)) { // Check the Jaeger format for the "uber-trace-id" header + String[] traceSplit = requestHeader.split("-"); + TraceFlags sampling = isSampledValue(traceSplit[2]) ? TraceFlags.getSampled() : TraceFlags.getDefault(); + + customSpanContext = SpanContext.create(traceSplit[0], traceSplit[1], sampling, TraceState.getDefault()); } } catch (Exception e) { @@ -441,6 +467,13 @@ private static Span createSpan(String key, String requestHeader) { } + /* + * Checks to see if the sampling value is enabled. Trace propagators will pass either 1 or 01 to indicate true. + */ + private static boolean isSampledValue(String sampledValue) { + return "1".equals(sampledValue) || "01".equals(sampledValue); + } + /** * Maps the Liberty Log levels to the OpenTelemetry Severity. * diff --git a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TelemetryAccessTest.java b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TelemetryAccessTest.java index 6487236372b2..58184f93ab18 100644 --- a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TelemetryAccessTest.java +++ b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TelemetryAccessTest.java @@ -486,6 +486,40 @@ public void testTelemetryAccessJaegerTraceLogs() throws Exception { TestUtils.checkJsonMessage(accessLine, expectedAccessFieldsMap); } + /* + * Verify that the b3 multi propagator is properly associating traces and spans with the access log + */ + @Test + public void testTelemetryAccessB3MultiTraceLogs() throws Exception { + RemoteFile messageLogFile = server.getDefaultLogFile(); + RemoteFile consoleLogFile = server.getConsoleLogFile(); + + // Configure access feature and access source + setConfig(server, messageLogFile, SERVER_XML_ACCESS_SOURCE_DEFAULT); + + // Trigger an access log event + TestUtils.runAccessApp(server, "runAccessApp", "b3multi"); + + // Wait for the access log message to be bridged over + String accessLine = server.waitForStringInLog("INFO2 'GET /MpTelemetryLogApp/AccessURL HTTP/1.1'", consoleLogFile); + assertFalse("The access log event does NOT contain a valid trace and span id", accessLine.contains(ZERO_SPAN_TRACE_ID)); + + // Check if the expected key-value pair is correctly formatted and mapped to OTel. + Map expectedAccessFieldsMap = new HashMap() { + { + put("http.request.method", "GET"); + put("http.response.status_code", "200"); + put("io.openliberty.access_log.url.path", "/MpTelemetryLogApp/AccessURL"); + put("network.local.port", Integer.toString(server.getHttpDefaultPort())); + put("io.openliberty.type", "liberty_accesslog"); + put("network.protocol.name", "HTTP"); + put("network.protocol.version", "1.1"); + put("io.openliberty.sequence", ""); // since, the sequence can be random, have to make sure the sequence field is still present. + } + }; + TestUtils.checkJsonMessage(accessLine, expectedAccessFieldsMap); + } + /* * Verify that invalid trace headers are properly handled and a debug message is logged. */ diff --git a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TelemetryAuditCheckpointTest.java b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TelemetryAuditCheckpointTest.java index 3efb30a8dac1..c3d08dbac188 100644 --- a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TelemetryAuditCheckpointTest.java +++ b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TelemetryAuditCheckpointTest.java @@ -89,7 +89,7 @@ public void testTelemetryAuditLogs() throws Exception { assertEquals("Expected no audit messages on restore", 0, linesConsoleLog.size()); // generate JMX_MBEAN_REGISTER audit message by hitting the root of the server - TestUtils.runGetMethod("http://" + server.getHostname() + ":" + server.getHttpDefaultPort(), null, null); + TestUtils.runGetMethod("http://" + server.getHostname() + ":" + server.getHttpDefaultPort(), null); String line = server.waitForStringInLog("JMXService", server.getConsoleLogFile()); assertNotNull("The JMXService audit event was not not found.", line); } diff --git a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TestUtils.java b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TestUtils.java index 9535171ece04..e440adc59cbb 100644 --- a/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TestUtils.java +++ b/dev/io.openliberty.microprofile.telemetry.2.0.logging.internal_2_fat/fat/src/io/openliberty/microprofile/telemetry/logging/internal_fat/TestUtils.java @@ -19,6 +19,7 @@ import java.net.HttpURLConnection; import java.net.URL; import java.util.ArrayList; +import java.util.HashMap; import java.util.Map; import javax.json.Json; @@ -42,9 +43,15 @@ public class TestUtils { public static String W3C_TRACE_DATA = "00-0af7651916cd43dd8448eb211c80319c-b9c7c989f97918e1-01"; public static String B3_TRACE_DATA = "e5fee0b8184e2a838aafe4aa959aa21c-4626864da5e71e37-1"; public static String JAEGER_TRACE_DATA = "322b8ac131b128bcaf56c0c41b84aff5:956ff8b1abbd7993:0:1"; + public static String B3_MULTI_TRACE_DATA = "0af7651916cd43dd8448eb211c80319c"; + public static String B3_MULTI_SPAN_DATA = "b9c7c989f97918e1"; + public static String B3_MULTI_SAMPLING_DATA = "1"; public static final String ACCESS_TRACE_W3C_HEADER_NAME = "traceparent"; public static final String ACCESS_TRACE_JAEGER_HEADER_NAME = "uber-trace-id"; public static final String ACCESS_TRACE_B3_HEADER_NAME = "b3"; + public static final String ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME = "X-B3-TraceId"; + public static final String ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME = "X-B3-SpanId"; + public static final String ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME = "X-B3-Sampled"; public static void runApp(LibertyServer server, String type) { String url = "http://" + server.getHostname() + ":" + server.getHttpDefaultPort() + "/MpTelemetryLogApp"; @@ -69,7 +76,7 @@ public static void runApp(LibertyServer server, String type) { Log.info(c, "runApp", "---> Running the application with url : " + url); try { - runGetMethod(url, null, null); + runGetMethod(url, null); } catch (Exception e) { Log.info(c, "runApp", " ---> Exception : " + e.getMessage()); } @@ -79,33 +86,33 @@ public static void runAccessApp(LibertyServer server, String type, String propag String url = "http://" + server.getHostname() + ":" + server.getHttpDefaultPort() + "/MpTelemetryLogApp/AccessURL"; Log.info(c, "runApp", "---> Running the application with url : " + url); - String requestHeader = null; - String traceData = null; + HashMap requestHeaderData = new HashMap<>(); + if (propagator.equals("w3c")) { - requestHeader = ACCESS_TRACE_W3C_HEADER_NAME; - traceData = W3C_TRACE_DATA; + requestHeaderData.put(ACCESS_TRACE_W3C_HEADER_NAME, W3C_TRACE_DATA); } else if (propagator.equals("b3")) { - requestHeader = ACCESS_TRACE_B3_HEADER_NAME; - traceData = B3_TRACE_DATA; + requestHeaderData.put(ACCESS_TRACE_B3_HEADER_NAME, B3_TRACE_DATA); } else if (propagator.equals("jaeger")) { - requestHeader = ACCESS_TRACE_JAEGER_HEADER_NAME; - traceData = JAEGER_TRACE_DATA; + requestHeaderData.put(ACCESS_TRACE_JAEGER_HEADER_NAME, JAEGER_TRACE_DATA); + } else if (propagator.equals("b3multi")) { + requestHeaderData.put(ACCESS_TRACE_B3_MULTI_TRACE_HEADER_NAME, B3_MULTI_TRACE_DATA); + requestHeaderData.put(ACCESS_TRACE_B3_MULTI_SPAN_HEADER_NAME, B3_MULTI_SPAN_DATA); + requestHeaderData.put(ACCESS_TRACE_B3_MULTI_SAMPLING_HEADER_NAME, B3_MULTI_SAMPLING_DATA); } else if (propagator.equals("invalidHeaderValue")) { - requestHeader = ACCESS_TRACE_JAEGER_HEADER_NAME; - traceData = W3C_TRACE_DATA; + requestHeaderData.put(ACCESS_TRACE_JAEGER_HEADER_NAME, W3C_TRACE_DATA); } try { - if (requestHeader != null) - runGetMethod(url, requestHeader, traceData); + if (!requestHeaderData.isEmpty()) + runGetMethod(url, requestHeaderData); else - runGetMethod(url, null, null); + runGetMethod(url, null); } catch (Exception e) { Log.info(c, "runApp", " ---> Exception : " + e.getMessage()); } } - static String runGetMethod(String urlStr, String requestHeader, String requestValue) throws Exception { + static String runGetMethod(String urlStr, HashMap requestHeaderData) throws Exception { Log.info(c, "runGetMethod", "URL = " + urlStr); URL url = new URL(urlStr); HttpURLConnection con = (HttpURLConnection) url.openConnection(); @@ -115,8 +122,11 @@ static String runGetMethod(String urlStr, String requestHeader, String requestVa con.setUseCaches(false); con.setRequestMethod("GET"); - if (requestHeader != null) { - con.setRequestProperty(requestHeader, requestValue); + if (!requestHeaderData.isEmpty()) { + for (Map.Entry entry : requestHeaderData.entrySet()) { + con.setRequestProperty(entry.getKey(), entry.getValue()); + } + } InputStream is = con.getInputStream();