diff --git a/pom.xml b/pom.xml index a6eb68e..9f9cd5e 100644 --- a/pom.xml +++ b/pom.xml @@ -54,6 +54,11 @@ oshi-core 6.9.2 + + io.opentelemetry + opentelemetry-sdk + 1.58.0 + com.github.spotbugs spotbugs-annotations diff --git a/src/main/java/io/apitally/common/ApitallyClient.java b/src/main/java/io/apitally/common/ApitallyClient.java index b664a78..16b735e 100644 --- a/src/main/java/io/apitally/common/ApitallyClient.java +++ b/src/main/java/io/apitally/common/ApitallyClient.java @@ -69,6 +69,7 @@ public enum HubRequestStatus { public final RequestCounter requestCounter; public final RequestLogger requestLogger; + public final SpanCollector spanCollector; public final ValidationErrorCounter validationErrorCounter; public final ServerErrorCounter serverErrorCounter; public final ConsumerRegistry consumerRegistry; @@ -85,6 +86,10 @@ public ApitallyClient(String clientId, String env, RequestLoggingConfig requestL this.requestCounter = new RequestCounter(); this.requestLogger = new RequestLogger(requestLoggingConfig); + this.spanCollector = + new SpanCollector( + requestLoggingConfig.isEnabled() + && requestLoggingConfig.isTracingEnabled()); this.validationErrorCounter = new ValidationErrorCounter(); this.serverErrorCounter = new ServerErrorCounter(); this.consumerRegistry = new ConsumerRegistry(); diff --git a/src/main/java/io/apitally/common/ApitallyAppender.java b/src/main/java/io/apitally/common/LogAppender.java similarity index 91% rename from src/main/java/io/apitally/common/ApitallyAppender.java rename to src/main/java/io/apitally/common/LogAppender.java index 42c0833..ae9a517 100644 --- a/src/main/java/io/apitally/common/ApitallyAppender.java +++ b/src/main/java/io/apitally/common/LogAppender.java @@ -9,8 +9,8 @@ import java.util.List; import org.slf4j.LoggerFactory; -public class ApitallyAppender extends AppenderBase { - private static final String NAME = "ApitallyAppender"; +public class LogAppender extends AppenderBase { + private static final String NAME = "ApitallyLogAppender"; private static final int MAX_BUFFER_SIZE = 1000; private static final int MAX_MESSAGE_LENGTH = 2048; @@ -26,7 +26,7 @@ public static synchronized void register() { return; } - ApitallyAppender appender = new ApitallyAppender(); + LogAppender appender = new LogAppender(); appender.setContext(loggerContext); appender.setName(NAME); appender.start(); diff --git a/src/main/java/io/apitally/common/RequestLogger.java b/src/main/java/io/apitally/common/RequestLogger.java index d0f3aa9..1d92819 100644 --- a/src/main/java/io/apitally/common/RequestLogger.java +++ b/src/main/java/io/apitally/common/RequestLogger.java @@ -9,6 +9,7 @@ import io.apitally.common.dto.Request; import io.apitally.common.dto.RequestLogItem; import io.apitally.common.dto.Response; +import io.apitally.common.dto.SpanData; import java.io.IOException; import java.net.MalformedURLException; import java.net.URL; @@ -139,7 +140,12 @@ public void setSuspendUntil(long timestamp) { } public void logRequest( - Request request, Response response, Exception exception, List logs) { + Request request, + Response response, + Exception exception, + List logs, + List spans, + String traceId) { if (!enabled || suspendUntil != null && suspendUntil > System.currentTimeMillis()) { return; } @@ -179,7 +185,13 @@ public void logRequest( logs = null; } - RequestLogItem item = new RequestLogItem(request, response, exceptionDto, logs); + if (!config.isTracingEnabled()) { + spans = null; + traceId = null; + } + + RequestLogItem item = + new RequestLogItem(request, response, exceptionDto, logs, spans, traceId); pendingWrites.add(item); if (pendingWrites.size() > MAX_PENDING_WRITES) { @@ -290,6 +302,12 @@ public void writeToFile() throws IOException { if (item.getLogs() != null && !item.getLogs().isEmpty()) { itemNode.set("logs", objectMapper.valueToTree(item.getLogs())); } + if (item.getSpans() != null && !item.getSpans().isEmpty()) { + itemNode.set("spans", objectMapper.valueToTree(item.getSpans())); + } + if (item.getTraceId() != null && !item.getTraceId().isEmpty()) { + itemNode.put("trace_id", item.getTraceId()); + } String serializedItem = objectMapper.writeValueAsString(itemNode); currentFile.writeLine(serializedItem.getBytes(StandardCharsets.UTF_8)); diff --git a/src/main/java/io/apitally/common/RequestLoggingConfig.java b/src/main/java/io/apitally/common/RequestLoggingConfig.java index 9f0688d..34c6fa6 100644 --- a/src/main/java/io/apitally/common/RequestLoggingConfig.java +++ b/src/main/java/io/apitally/common/RequestLoggingConfig.java @@ -12,6 +12,7 @@ public class RequestLoggingConfig { private boolean responseBodyIncluded = false; private boolean exceptionIncluded = true; private boolean logCaptureEnabled = false; + private boolean tracingEnabled = false; private List queryParamMaskPatterns = new ArrayList<>(); private List headerMaskPatterns = new ArrayList<>(); private List bodyFieldMaskPatterns = new ArrayList<>(); @@ -82,6 +83,14 @@ public void setLogCaptureEnabled(boolean logCaptureEnabled) { this.logCaptureEnabled = logCaptureEnabled; } + public boolean isTracingEnabled() { + return tracingEnabled; + } + + public void setTracingEnabled(boolean tracingEnabled) { + this.tracingEnabled = tracingEnabled; + } + public List getQueryParamMaskPatterns() { return queryParamMaskPatterns; } diff --git a/src/main/java/io/apitally/common/SpanCollector.java b/src/main/java/io/apitally/common/SpanCollector.java new file mode 100644 index 0000000..01a562f --- /dev/null +++ b/src/main/java/io/apitally/common/SpanCollector.java @@ -0,0 +1,180 @@ +package io.apitally.common; + +import io.apitally.common.dto.SpanData; +import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.SpanContext; +import io.opentelemetry.api.trace.SpanKind; +import io.opentelemetry.api.trace.StatusCode; +import io.opentelemetry.api.trace.Tracer; +import io.opentelemetry.context.Context; +import io.opentelemetry.context.Scope; +import io.opentelemetry.sdk.trace.ReadWriteSpan; +import io.opentelemetry.sdk.trace.ReadableSpan; +import io.opentelemetry.sdk.trace.SpanProcessor; +import java.util.ArrayList; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ConcurrentLinkedQueue; + +public class SpanCollector implements SpanProcessor { + private final boolean enabled; + private volatile Tracer tracer; + private final Map> includedSpanIds = new ConcurrentHashMap<>(); + private final Map> collectedSpans = + new ConcurrentHashMap<>(); + + public SpanCollector(boolean enabled) { + this.enabled = enabled; + } + + public void setTracer(Tracer tracer) { + this.tracer = tracer; + } + + public SpanHandle startCollection() { + if (!enabled || tracer == null) { + return null; + } + + Span span = tracer.spanBuilder("root").setSpanKind(SpanKind.INTERNAL).startSpan(); + Scope scope = Context.current().with(span).makeCurrent(); + SpanContext spanContext = span.getSpanContext(); + String traceId = spanContext.getTraceId(); + + Set spanIds = ConcurrentHashMap.newKeySet(); + spanIds.add(spanContext.getSpanId()); + includedSpanIds.put(traceId, spanIds); + collectedSpans.put(traceId, new ConcurrentLinkedQueue<>()); + + return new SpanHandle(traceId, span, scope, this); + } + + List getAndClearSpans(String traceId) { + if (traceId == null) { + return null; + } + + includedSpanIds.remove(traceId); + ConcurrentLinkedQueue spans = collectedSpans.remove(traceId); + return spans != null ? new ArrayList<>(spans) : null; + } + + @Override + public void onStart(Context parentContext, ReadWriteSpan span) { + if (!enabled) { + return; + } + + SpanContext spanContext = span.getSpanContext(); + String traceId = spanContext.getTraceId(); + String spanId = spanContext.getSpanId(); + + Set included = includedSpanIds.get(traceId); + if (included == null) { + return; + } + + SpanContext parentSpanContext = span.getParentSpanContext(); + if (parentSpanContext.isValid() && included.contains(parentSpanContext.getSpanId())) { + included.add(spanId); + } + } + + @Override + public boolean isStartRequired() { + return enabled; + } + + @Override + public void onEnd(ReadableSpan span) { + if (!enabled) { + return; + } + + SpanContext spanContext = span.getSpanContext(); + String traceId = spanContext.getTraceId(); + String spanId = spanContext.getSpanId(); + + Set included = includedSpanIds.get(traceId); + if (included == null || !included.contains(spanId)) { + return; + } + + SpanData data = serializeSpan(span); + ConcurrentLinkedQueue spans = collectedSpans.get(traceId); + if (spans != null) { + spans.add(data); + } + } + + @Override + public boolean isEndRequired() { + return enabled; + } + + private SpanData serializeSpan(ReadableSpan span) { + io.opentelemetry.sdk.trace.data.SpanData spanData = span.toSpanData(); + SpanContext spanContext = spanData.getSpanContext(); + SpanContext parentSpanContext = spanData.getParentSpanContext(); + + String parentSpanId = parentSpanContext.isValid() ? parentSpanContext.getSpanId() : null; + String status = + spanData.getStatus().getStatusCode() != StatusCode.UNSET + ? spanData.getStatus().getStatusCode().name() + : null; + + Map attributes = null; + if (!spanData.getAttributes().isEmpty()) { + Map attrMap = new HashMap<>(); + spanData.getAttributes().forEach((key, value) -> attrMap.put(key.getKey(), value)); + attributes = attrMap; + } + + return new SpanData( + spanContext.getSpanId(), + parentSpanId, + spanData.getName(), + spanData.getKind().name(), + spanData.getStartEpochNanos(), + spanData.getEndEpochNanos(), + status, + attributes); + } + + public static class SpanHandle { + private final String traceId; + private final Span span; + private final Scope scope; + private final SpanCollector collector; + + SpanHandle(String traceId, Span span, Scope scope, SpanCollector collector) { + this.traceId = traceId; + this.span = span; + this.scope = scope; + this.collector = collector; + } + + public String getTraceId() { + return traceId; + } + + public void setName(String name) { + span.updateName(name); + } + + public List end() { + scope.close(); + span.end(); + return collector.getAndClearSpans(traceId); + } + } + + void resetForTest() { + this.tracer = null; + this.includedSpanIds.clear(); + this.collectedSpans.clear(); + } +} diff --git a/src/main/java/io/apitally/common/dto/RequestLogItem.java b/src/main/java/io/apitally/common/dto/RequestLogItem.java index 4e934ec..5c4dec7 100644 --- a/src/main/java/io/apitally/common/dto/RequestLogItem.java +++ b/src/main/java/io/apitally/common/dto/RequestLogItem.java @@ -10,14 +10,23 @@ public class RequestLogItem extends BaseDto { private final Response response; private final ExceptionDto exception; private final List logs; + private final List spans; + private final String traceId; public RequestLogItem( - Request request, Response response, ExceptionDto exception, List logs) { + Request request, + Response response, + ExceptionDto exception, + List logs, + List spans, + String traceId) { this.uuid = UUID.randomUUID().toString(); this.request = request; this.response = response; this.exception = exception; this.logs = logs; + this.spans = spans; + this.traceId = traceId; } @JsonProperty("uuid") @@ -44,4 +53,14 @@ public ExceptionDto getException() { public List getLogs() { return logs; } + + @JsonProperty("spans") + public List getSpans() { + return spans; + } + + @JsonProperty("trace_id") + public String getTraceId() { + return traceId; + } } diff --git a/src/main/java/io/apitally/common/dto/SpanData.java b/src/main/java/io/apitally/common/dto/SpanData.java new file mode 100644 index 0000000..69bb03a --- /dev/null +++ b/src/main/java/io/apitally/common/dto/SpanData.java @@ -0,0 +1,76 @@ +package io.apitally.common.dto; + +import com.fasterxml.jackson.annotation.JsonInclude; +import com.fasterxml.jackson.annotation.JsonProperty; +import java.util.Map; + +@JsonInclude(JsonInclude.Include.NON_NULL) +public class SpanData { + private final String spanId; + private final String parentSpanId; + private final String name; + private final String kind; + private final long startTime; + private final long endTime; + private final String status; + private final Map attributes; + + public SpanData( + String spanId, + String parentSpanId, + String name, + String kind, + long startTime, + long endTime, + String status, + Map attributes) { + this.spanId = spanId; + this.parentSpanId = parentSpanId; + this.name = name; + this.kind = kind; + this.startTime = startTime; + this.endTime = endTime; + this.status = status; + this.attributes = attributes; + } + + @JsonProperty("span_id") + public String getSpanId() { + return spanId; + } + + @JsonProperty("parent_span_id") + public String getParentSpanId() { + return parentSpanId; + } + + @JsonProperty("name") + public String getName() { + return name; + } + + @JsonProperty("kind") + public String getKind() { + return kind; + } + + @JsonProperty("start_time") + public long getStartTime() { + return startTime; + } + + @JsonProperty("end_time") + public long getEndTime() { + return endTime; + } + + @JsonProperty("status") + public String getStatus() { + return status; + } + + @JsonProperty("attributes") + public Map getAttributes() { + return attributes; + } +} diff --git a/src/main/java/io/apitally/spring/ApitallyAutoConfiguration.java b/src/main/java/io/apitally/spring/ApitallyAutoConfiguration.java index 62f9753..93c84a7 100644 --- a/src/main/java/io/apitally/spring/ApitallyAutoConfiguration.java +++ b/src/main/java/io/apitally/spring/ApitallyAutoConfiguration.java @@ -1,7 +1,7 @@ package io.apitally.spring; -import io.apitally.common.ApitallyAppender; import io.apitally.common.ApitallyClient; +import io.apitally.common.LogAppender; import io.apitally.common.dto.Path; import java.util.List; import java.util.Map; @@ -31,7 +31,11 @@ public ApitallyClient apitallyClient( if (properties.getRequestLogging().isEnabled() && properties.getRequestLogging().isLogCaptureEnabled()) { - ApitallyAppender.register(); + LogAppender.register(); + } + if (properties.getRequestLogging().isEnabled() + && properties.getRequestLogging().isTracingEnabled()) { + ApitallySpanCollector.getInstance().setDelegate(client.spanCollector); } return client; diff --git a/src/main/java/io/apitally/spring/ApitallyFilter.java b/src/main/java/io/apitally/spring/ApitallyFilter.java index ce847ac..dd04a42 100644 --- a/src/main/java/io/apitally/spring/ApitallyFilter.java +++ b/src/main/java/io/apitally/spring/ApitallyFilter.java @@ -1,14 +1,17 @@ package io.apitally.spring; -import io.apitally.common.ApitallyAppender; import io.apitally.common.ApitallyClient; import io.apitally.common.ConsumerRegistry; +import io.apitally.common.LogAppender; import io.apitally.common.RequestLogger; +import io.apitally.common.RequestLoggingConfig; +import io.apitally.common.SpanCollector; import io.apitally.common.dto.Consumer; import io.apitally.common.dto.Header; import io.apitally.common.dto.LogRecord; import io.apitally.common.dto.Request; import io.apitally.common.dto.Response; +import io.apitally.common.dto.SpanData; import jakarta.servlet.FilterChain; import jakarta.servlet.ServletException; import jakarta.servlet.ServletOutputStream; @@ -27,6 +30,7 @@ import org.springframework.validation.FieldError; import org.springframework.web.bind.MethodArgumentNotValidException; import org.springframework.web.filter.OncePerRequestFilter; +import org.springframework.web.method.HandlerMethod; import org.springframework.web.servlet.HandlerMapping; import org.springframework.web.util.ContentCachingRequestWrapper; import org.springframework.web.util.ContentCachingResponseWrapper; @@ -51,18 +55,20 @@ protected void doFilterInternal( return; } + RequestLoggingConfig requestLoggingConfig = client.requestLogger.getConfig(); + final boolean requestLoggingEnabled = requestLoggingConfig.isEnabled(); + String requestContentType = request.getContentType(); final boolean shouldCacheRequest = - client.requestLogger.getConfig().isEnabled() - && client.requestLogger.getConfig().isRequestBodyIncluded() + requestLoggingEnabled + && requestLoggingConfig.isRequestBodyIncluded() && requestContentType != null && RequestLogger.ALLOWED_CONTENT_TYPES.stream() .anyMatch( allowedContentType -> requestContentType.startsWith(allowedContentType)); final boolean shouldCacheResponse = - client.requestLogger.getConfig().isEnabled() - && client.requestLogger.getConfig().isResponseBodyIncluded(); + requestLoggingEnabled && requestLoggingConfig.isResponseBodyIncluded(); ContentCachingRequestWrapper cachingRequest = shouldCacheRequest ? new ContentCachingRequestWrapper(request) : null; ContentCachingResponseWrapper cachingResponse = @@ -71,16 +77,20 @@ protected void doFilterInternal( cachingResponse == null ? new CountingResponseWrapper(response) : null; final boolean shouldCaptureLogs = - client.requestLogger.getConfig().isEnabled() - && client.requestLogger.getConfig().isLogCaptureEnabled(); + requestLoggingEnabled && requestLoggingConfig.isLogCaptureEnabled(); + final boolean shouldCaptureSpans = + requestLoggingEnabled && requestLoggingConfig.isTracingEnabled(); Exception exception = null; final long startTime = System.currentTimeMillis(); if (shouldCaptureLogs) { - ApitallyAppender.startCapture(); + LogAppender.startCapture(); } + final SpanCollector.SpanHandle spanHandle = + shouldCaptureSpans ? client.spanCollector.startCollection() : null; + try { filterChain.doFilter( cachingRequest != null ? cachingRequest : request, @@ -89,22 +99,45 @@ protected void doFilterInternal( exception = e; throw e; } finally { - final List capturedLogs = - shouldCaptureLogs ? ApitallyAppender.endCapture() : null; - final long responseTimeInMillis = System.currentTimeMillis() - startTime; - final String path = - (String) request.getAttribute(HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE); - - // Get request and response body - final byte[] requestBody = - cachingRequest != null ? cachingRequest.getContentAsByteArray() : new byte[0]; - final byte[] responseBody = - cachingResponse != null ? cachingResponse.getContentAsByteArray() : new byte[0]; - if (cachingResponse != null) { - cachingResponse.copyBodyToResponse(); - } - try { + final long responseTimeInMillis = System.currentTimeMillis() - startTime; + final String path = + (String) + request.getAttribute( + HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE); + + // End span collection and get spans + List spans = null; + String traceId = null; + if (spanHandle != null) { + Object handler = + request.getAttribute(HandlerMapping.BEST_MATCHING_HANDLER_ATTRIBUTE); + if (handler instanceof HandlerMethod handlerMethod) { + String controllerName = handlerMethod.getBeanType().getSimpleName(); + String methodName = handlerMethod.getMethod().getName(); + spanHandle.setName(controllerName + "." + methodName); + } + spans = spanHandle.end(); + traceId = spanHandle.getTraceId(); + } + + // End log capture and get logs + final List capturedLogs = + shouldCaptureLogs ? LogAppender.endCapture() : null; + + // Get request and response body + final byte[] requestBody = + cachingRequest != null + ? cachingRequest.getContentAsByteArray() + : new byte[0]; + final byte[] responseBody = + cachingResponse != null + ? cachingResponse.getContentAsByteArray() + : new byte[0]; + if (cachingResponse != null) { + cachingResponse.copyBodyToResponse(); + } + // Register consumer and get consumer identifier final Consumer consumer = ConsumerRegistry.consumerFromObject( @@ -179,7 +212,9 @@ protected void doFilterInternal( responseSize, responseBody), exception, - capturedLogs); + capturedLogs, + spans, + traceId); } // Add validation error to counter diff --git a/src/main/java/io/apitally/spring/ApitallySpanCollector.java b/src/main/java/io/apitally/spring/ApitallySpanCollector.java new file mode 100644 index 0000000..00bda4c --- /dev/null +++ b/src/main/java/io/apitally/spring/ApitallySpanCollector.java @@ -0,0 +1,77 @@ +package io.apitally.spring; + +import io.apitally.common.SpanCollector; +import io.opentelemetry.api.GlobalOpenTelemetry; +import io.opentelemetry.api.trace.Tracer; +import io.opentelemetry.context.Context; +import io.opentelemetry.sdk.OpenTelemetrySdk; +import io.opentelemetry.sdk.trace.ReadWriteSpan; +import io.opentelemetry.sdk.trace.ReadableSpan; +import io.opentelemetry.sdk.trace.SdkTracerProvider; +import io.opentelemetry.sdk.trace.SpanProcessor; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +public class ApitallySpanCollector implements SpanProcessor { + private static final Logger logger = LoggerFactory.getLogger(ApitallySpanCollector.class); + private static final ApitallySpanCollector INSTANCE = new ApitallySpanCollector(); + private volatile SpanCollector delegate; + + public static ApitallySpanCollector getInstance() { + return INSTANCE; + } + + private ApitallySpanCollector() {} + + public void setDelegate(SpanCollector spanCollector) { + this.delegate = spanCollector; + if (spanCollector != null) { + initializeTracer(spanCollector); + } + } + + private void initializeTracer(SpanCollector spanCollector) { + try { + SdkTracerProvider provider = SdkTracerProvider.builder().addSpanProcessor(this).build(); + OpenTelemetrySdk sdk = OpenTelemetrySdk.builder().setTracerProvider(provider).build(); + Tracer tracer; + try { + GlobalOpenTelemetry.set(sdk); + tracer = sdk.getTracer("apitally"); + } catch (IllegalStateException e) { + tracer = GlobalOpenTelemetry.getTracer("apitally"); + } + spanCollector.setTracer(tracer); + } catch (Exception e) { + logger.warn("Failed to setup OpenTelemetry tracer", e); + } + } + + @Override + public void onStart(Context parentContext, ReadWriteSpan span) { + if (delegate != null) { + delegate.onStart(parentContext, span); + } + } + + @Override + public boolean isStartRequired() { + return delegate != null && delegate.isStartRequired(); + } + + @Override + public void onEnd(ReadableSpan span) { + if (delegate != null) { + delegate.onEnd(span); + } + } + + @Override + public boolean isEndRequired() { + return delegate != null && delegate.isEndRequired(); + } + + public SpanCollector.SpanHandle startCollection() { + return delegate != null ? delegate.startCollection() : null; + } +} diff --git a/src/test/java/io/apitally/common/ApitallyClientTest.java b/src/test/java/io/apitally/common/ApitallyClientTest.java index 4334218..6973cfe 100644 --- a/src/test/java/io/apitally/common/ApitallyClientTest.java +++ b/src/test/java/io/apitally/common/ApitallyClientTest.java @@ -67,7 +67,7 @@ void testSync() { new byte[0]); Response response = new Response(200, 0.123, responseHeaders, 13L, "{\"items\": []}".getBytes()); - client.requestLogger.logRequest(request, response, null, null); + client.requestLogger.logRequest(request, response, null, null, null, null); client.requestLogger.maintain(); List paths = Arrays.asList(new Path("GET", "/items")); diff --git a/src/test/java/io/apitally/common/ApitallyAppenderTest.java b/src/test/java/io/apitally/common/LogAppenderTest.java similarity index 81% rename from src/test/java/io/apitally/common/ApitallyAppenderTest.java rename to src/test/java/io/apitally/common/LogAppenderTest.java index be0c943..7f26828 100644 --- a/src/test/java/io/apitally/common/ApitallyAppenderTest.java +++ b/src/test/java/io/apitally/common/LogAppenderTest.java @@ -15,15 +15,15 @@ import org.junit.jupiter.api.Test; import org.slf4j.LoggerFactory; -public class ApitallyAppenderTest { +public class LogAppenderTest { - private ApitallyAppender appender; + private LogAppender appender; private LoggerContext loggerContext; @BeforeEach void setUp() { loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory(); - appender = new ApitallyAppender(); + appender = new LogAppender(); appender.setContext(loggerContext); appender.setName("TestApitallyAppender"); appender.start(); @@ -31,15 +31,15 @@ void setUp() { @AfterEach void tearDown() { - ApitallyAppender.endCapture(); + LogAppender.endCapture(); appender.stop(); } @Test void testStartCaptureAndEndCapture() { - ApitallyAppender.startCapture(); + LogAppender.startCapture(); appender.doAppend(createLoggingEvent("Test message")); - List logs = ApitallyAppender.endCapture(); + List logs = LogAppender.endCapture(); assertNotNull(logs); assertEquals(1, logs.size()); @@ -51,18 +51,18 @@ void testStartCaptureAndEndCapture() { @Test void testNoCaptureWhenNotStarted() { appender.doAppend(createLoggingEvent("Test message")); - List logs = ApitallyAppender.endCapture(); + List logs = LogAppender.endCapture(); assertNull(logs); } @Test void testMaxBufferSizeLimit() { - ApitallyAppender.startCapture(); + LogAppender.startCapture(); for (int i = 0; i < 1100; i++) { appender.doAppend(createLoggingEvent("Message " + i)); } - List logs = ApitallyAppender.endCapture(); + List logs = LogAppender.endCapture(); assertNotNull(logs); assertEquals(1000, logs.size()); @@ -70,9 +70,9 @@ void testMaxBufferSizeLimit() { @Test void testMessageTruncation() { - ApitallyAppender.startCapture(); + LogAppender.startCapture(); appender.doAppend(createLoggingEvent("A".repeat(3000))); - List logs = ApitallyAppender.endCapture(); + List logs = LogAppender.endCapture(); assertNotNull(logs); assertEquals(1, logs.size()); diff --git a/src/test/java/io/apitally/common/RequestLoggerTest.java b/src/test/java/io/apitally/common/RequestLoggerTest.java index b9342c6..adbf2ff 100644 --- a/src/test/java/io/apitally/common/RequestLoggerTest.java +++ b/src/test/java/io/apitally/common/RequestLoggerTest.java @@ -11,6 +11,7 @@ import io.apitally.common.dto.LogRecord; import io.apitally.common.dto.Request; import io.apitally.common.dto.Response; +import io.apitally.common.dto.SpanData; import java.io.IOException; import java.util.ArrayList; import java.util.Base64; @@ -34,6 +35,7 @@ void setUp() { requestLoggingConfig.setResponseHeadersIncluded(true); requestLoggingConfig.setResponseBodyIncluded(true); requestLoggingConfig.setLogCaptureEnabled(true); + requestLoggingConfig.setTracingEnabled(true); requestLogger = new RequestLogger(requestLoggingConfig); } @@ -72,7 +74,29 @@ void testEndToEnd() { "test.Logger", "INFO", "Test log message")); - requestLogger.logRequest(request, response, exception, logs); + List spans = new ArrayList<>(); + spans.add( + new SpanData( + "a1b2c3d4e5f6a7b8", + null, + "root", + "INTERNAL", + 1000000L, + 2000000L, + null, + null)); + spans.add( + new SpanData( + "b2c3d4e5f6a7b8c9", + "a1b2c3d4e5f6a7b8", + "child", + "INTERNAL", + 1100000L, + 1900000L, + "OK", + null)); + String traceId = "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6"; + requestLogger.logRequest(request, response, exception, logs, spans, traceId); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(1, items.length); @@ -114,6 +138,14 @@ void testEndToEnd() { assertEquals("INFO", logsNode.get(0).get("level").asText()); assertEquals("Test log message", logsNode.get(0).get("message").asText()); + assertEquals("a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6", jsonNode.get("trace_id").asText()); + JsonNode spansNode = jsonNode.get("spans"); + assertTrue(spansNode.isArray()); + assertEquals(2, spansNode.size()); + assertEquals("root", spansNode.get(0).get("name").asText()); + assertEquals("child", spansNode.get(1).get("name").asText()); + assertEquals("a1b2c3d4e5f6a7b8", spansNode.get(1).get("parent_span_id").asText()); + requestLogger.clear(); items = getLoggedItems(requestLogger); @@ -151,7 +183,7 @@ void testExcludeBasedOnOptions() { Response response = new Response(200, 0.123, responseHeaders, 16L, "{\"key\": \"value\"}".getBytes()); - requestLogger.logRequest(request, response, null, null); + requestLogger.logRequest(request, response, null, null, null, null); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(1, items.length); @@ -188,7 +220,7 @@ public boolean shouldExclude(Request request, Response response) { Response response = new Response(200, 0.123, new Header[0], 13L, "{\"items\": []}".getBytes()); - requestLogger.logRequest(request, response, null, null); + requestLogger.logRequest(request, response, null, null, null, null); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(0, items.length); @@ -209,7 +241,7 @@ void testExcludeBasedOnPath() { Response response = new Response(200, 0.123, new Header[0], 17L, "{\"healthy\": true}".getBytes()); - requestLogger.logRequest(request, response, null, null); + requestLogger.logRequest(request, response, null, null, null, null); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(0, items.length); @@ -233,7 +265,7 @@ void testExcludeBasedOnUserAgent() { new byte[0]); Response response = new Response(200, 0, new Header[0], 0L, new byte[0]); - requestLogger.logRequest(request, response, null, null); + requestLogger.logRequest(request, response, null, null, null, null); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(0, items.length); @@ -264,7 +296,7 @@ void testMaskHeaders() { new byte[0]); Response response = new Response(200, 0, new Header[0], 0L, new byte[0]); - requestLogger.logRequest(request, response, null, null); + requestLogger.logRequest(request, response, null, null, null, null); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(1, items.length); @@ -300,7 +332,7 @@ void testMaskQueryParams() { new byte[0]); Response response = new Response(200, 0, new Header[0], 0L, new byte[0]); - requestLogger.logRequest(request, response, null, null); + requestLogger.logRequest(request, response, null, null, null, null); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(1, items.length); @@ -357,7 +389,7 @@ public byte[] maskResponseBody(Request request, Response response) { 4L, "test".getBytes()); - requestLogger.logRequest(request, response, null, null); + requestLogger.logRequest(request, response, null, null, null, null); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(1, items.length); @@ -407,7 +439,7 @@ void testMaskBodyFields() { (long) responseBodyJson.getBytes().length, responseBodyJson.getBytes()); - requestLogger.logRequest(request, response, null, null); + requestLogger.logRequest(request, response, null, null, null, null); JsonNode[] items = getLoggedItems(requestLogger); assertEquals(1, items.length); diff --git a/src/test/java/io/apitally/common/SpanCollectorTest.java b/src/test/java/io/apitally/common/SpanCollectorTest.java new file mode 100644 index 0000000..95a08d4 --- /dev/null +++ b/src/test/java/io/apitally/common/SpanCollectorTest.java @@ -0,0 +1,161 @@ +package io.apitally.common; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import io.apitally.common.dto.SpanData; +import io.apitally.spring.ApitallySpanCollector; +import io.opentelemetry.api.GlobalOpenTelemetry; +import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.StatusCode; +import io.opentelemetry.api.trace.Tracer; +import java.util.List; +import java.util.Set; +import java.util.stream.Collectors; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +class SpanCollectorTest { + + private SpanCollector collector; + + @BeforeEach + void setUp() { + GlobalOpenTelemetry.resetForTest(); + ApitallySpanCollector.getInstance().setDelegate(null); + } + + @AfterEach + void tearDown() { + if (collector != null) { + collector.resetForTest(); + } + ApitallySpanCollector.getInstance().setDelegate(null); + GlobalOpenTelemetry.resetForTest(); + } + + private SpanCollector createAndRegisterCollector(boolean enabled) { + collector = new SpanCollector(enabled); + ApitallySpanCollector.getInstance().setDelegate(collector); + return collector; + } + + @Test + void testDisabledCollector() { + SpanCollector collector = createAndRegisterCollector(false); + + SpanCollector.SpanHandle handle = collector.startCollection(); + assertNull(handle); + } + + @Test + void testEnabledCollector() { + SpanCollector collector = createAndRegisterCollector(true); + + SpanCollector.SpanHandle handle = collector.startCollection(); + assertNotNull(handle); + assertNotNull(handle.getTraceId()); + assertEquals(32, handle.getTraceId().length()); + + List spans = handle.end(); + assertNotNull(spans); + assertEquals(1, spans.size()); + assertEquals("root", spans.get(0).getName()); + assertNull(spans.get(0).getParentSpanId()); + } + + @Test + void testCollectorWithChildSpans() { + SpanCollector collector = createAndRegisterCollector(true); + + SpanCollector.SpanHandle handle = collector.startCollection(); + Tracer tracer = GlobalOpenTelemetry.getTracer("test"); + + Span child1 = tracer.spanBuilder("child1").startSpan(); + child1.end(); + + Span child2 = tracer.spanBuilder("child2").startSpan(); + child2.end(); + + handle.setName("TestController.getTest"); + + List spans = handle.end(); + assertNotNull(spans); + assertEquals(3, spans.size()); + + Set spanNames = spans.stream().map(SpanData::getName).collect(Collectors.toSet()); + assertTrue(spanNames.contains("TestController.getTest")); + assertTrue(spanNames.contains("child1")); + assertTrue(spanNames.contains("child2")); + + SpanData rootSpan = + spans.stream() + .filter(s -> s.getName().equals("TestController.getTest")) + .findFirst() + .orElse(null); + assertNotNull(rootSpan); + assertNull(rootSpan.getParentSpanId()); + + SpanData childSpan = + spans.stream().filter(s -> s.getName().equals("child1")).findFirst().orElse(null); + assertNotNull(childSpan); + assertEquals(rootSpan.getSpanId(), childSpan.getParentSpanId()); + } + + @Test + void testDoesNotCollectUnrelatedSpans() { + SpanCollector collector = createAndRegisterCollector(true); + Tracer tracer = GlobalOpenTelemetry.getTracer("test"); + + Span outsideSpan = tracer.spanBuilder("outsideSpan").startSpan(); + outsideSpan.end(); + + SpanCollector.SpanHandle handle = collector.startCollection(); + + Span insideSpan = tracer.spanBuilder("insideSpan").startSpan(); + insideSpan.end(); + + List spans = handle.end(); + assertNotNull(spans); + + Set spanNames = spans.stream().map(SpanData::getName).collect(Collectors.toSet()); + assertTrue(spanNames.contains("root")); + assertTrue(spanNames.contains("insideSpan")); + assertFalse(spanNames.contains("outsideSpan")); + } + + @Test + void testSpanDataSerialization() { + SpanCollector collector = createAndRegisterCollector(true); + + SpanCollector.SpanHandle handle = collector.startCollection(); + Tracer tracer = GlobalOpenTelemetry.getTracer("test"); + + Span span = tracer.spanBuilder("testSpan").startSpan(); + span.setAttribute("http.method", "GET"); + span.setAttribute("http.status_code", 200); + span.setStatus(StatusCode.OK); + span.end(); + + List spans = handle.end(); + assertNotNull(spans); + + SpanData testSpan = + spans.stream().filter(s -> s.getName().equals("testSpan")).findFirst().orElse(null); + assertNotNull(testSpan); + assertEquals(16, testSpan.getSpanId().length()); + assertEquals("INTERNAL", testSpan.getKind()); + assertTrue(testSpan.getStartTime() > 0); + assertTrue(testSpan.getEndTime() > 0); + assertTrue(testSpan.getEndTime() >= testSpan.getStartTime()); + + assertEquals("OK", testSpan.getStatus()); + assertNotNull(testSpan.getAttributes()); + assertEquals("GET", testSpan.getAttributes().get("http.method")); + assertEquals(200L, testSpan.getAttributes().get("http.status_code")); + } +} diff --git a/src/test/java/io/apitally/spring/ApitallyFilterTest.java b/src/test/java/io/apitally/spring/ApitallyFilterTest.java index d032447..c596f14 100644 --- a/src/test/java/io/apitally/spring/ApitallyFilterTest.java +++ b/src/test/java/io/apitally/spring/ApitallyFilterTest.java @@ -5,8 +5,8 @@ import com.fasterxml.jackson.databind.JsonNode; import com.fasterxml.jackson.databind.ObjectMapper; -import io.apitally.common.ApitallyAppender; import io.apitally.common.ApitallyClient; +import io.apitally.common.LogAppender; import io.apitally.common.RequestLogger; import io.apitally.common.TempGzipFile; import io.apitally.common.dto.Consumer; @@ -19,6 +19,7 @@ import java.util.Base64; import java.util.List; import java.util.Map; +import java.util.stream.StreamSupport; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.slf4j.Logger; @@ -51,9 +52,14 @@ class ApitallyFilterTest { static class TestConfig { @Bean public ApitallyClient apitallyClient(ApitallyProperties properties) { - ApitallyAppender.register(); - return new ApitallyClient( - properties.getClientId(), properties.getEnv(), properties.getRequestLogging()); + LogAppender.register(); + ApitallyClient client = + new ApitallyClient( + properties.getClientId(), + properties.getEnv(), + properties.getRequestLogging()); + ApitallySpanCollector.getInstance().setDelegate(client.spanCollector); + return client; } @Bean @@ -289,6 +295,7 @@ void testRequestLogger() { apitallyClient.requestLogger.getConfig().setRequestBodyIncluded(true); apitallyClient.requestLogger.getConfig().setResponseBodyIncluded(true); apitallyClient.requestLogger.getConfig().setLogCaptureEnabled(true); + apitallyClient.requestLogger.getConfig().setTracingEnabled(true); apitallyClient.requestLogger.clear(); ResponseEntity response = restTemplate.getForEntity("/items", String.class); @@ -321,6 +328,14 @@ void testRequestLogger() { assertTrue(firstItem.get("logs").size() > 0); assertTrue(firstItem.get("logs").get(0).get("message").asText().contains("Getting items")); + // Verify spans were captured + assertTrue(firstItem.has("spans")); + assertTrue(firstItem.get("spans").isArray()); + assertTrue(firstItem.get("spans").size() >= 2); // root span + child span + assertTrue( + StreamSupport.stream(firstItem.get("spans").spliterator(), false) + .anyMatch(span -> span.get("name").asText().equals("fetchItems"))); + // Verify POST request logging with request body JsonNode secondItem = items[1]; assertEquals("POST", secondItem.get("request").get("method").asText()); diff --git a/src/test/java/io/apitally/spring/app/TestController.java b/src/test/java/io/apitally/spring/app/TestController.java index a4f7b44..017e0b1 100644 --- a/src/test/java/io/apitally/spring/app/TestController.java +++ b/src/test/java/io/apitally/spring/app/TestController.java @@ -1,6 +1,9 @@ package io.apitally.spring.app; import io.apitally.spring.ApitallyConsumer; +import io.opentelemetry.api.GlobalOpenTelemetry; +import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.Tracer; import jakarta.servlet.http.HttpServletRequest; import jakarta.validation.ConstraintViolationException; import jakarta.validation.Valid; @@ -35,11 +38,18 @@ public List getItems( HttpServletRequest request, @RequestParam(required = false) @Size(min = 2, max = 10) String name) { logger.info("Getting items with filter: {}", name != null ? name : "none"); + ApitallyConsumer consumer = new ApitallyConsumer("tester", "Tester", "Test Group"); request.setAttribute("apitallyConsumer", consumer); + + Tracer tracer = GlobalOpenTelemetry.getTracer("test"); + Span childSpan = tracer.spanBuilder("fetchItems").startSpan(); + childSpan.setAttribute("filter", name != null ? name : "none"); List items = new ArrayList(); items.add(new TestItem(1, "bob")); items.add(new TestItem(2, "alice")); + childSpan.end(); + logger.debug("Returning {} items", items.size()); return items; } diff --git a/src/test/resources/application.yml b/src/test/resources/application.yml index 2393dce..f93d993 100644 --- a/src/test/resources/application.yml +++ b/src/test/resources/application.yml @@ -8,6 +8,8 @@ apitally: request-body-included: true response-body-included: true response-headers-included: true + log-capture-enabled: true + tracing-enabled: true callbacks-class: io.apitally.spring.app.RequestLoggingCallbacks spring: