test logs

Author: jandro996

dd-java-agent/appsec/src/main/java/com/datadog/appsec/api/security/ApiSecuritySamplerImpl.java

@@ -4,6 +4,8 @@
 import datadog.trace.api.Config;
 import datadog.trace.api.time.SystemTimeSource;
 import datadog.trace.api.time.TimeSource;
+import datadog.trace.bootstrap.instrumentation.api.AgentSpan;
+import datadog.trace.bootstrap.instrumentation.api.AgentTracer;
 import java.util.Deque;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.ConcurrentLinkedDeque;
@@ -69,14 +71,21 @@ public boolean preSampleRequest(final @Nonnull AppSecRequestContext ctx) {
     }
     long hash = computeApiHash(route, method, statusCode);
     ctx.setApiSecurityEndpointHash(hash);
-    if (!isApiAccessExpired(hash)) {
+
+    long currentTime = timeSource.getCurrentTimeMillis();
+    boolean isExpired = isApiAccessExpired(hash);
+
+    if (!isExpired) {
+      logSamplingDecision("preSampleRequest", currentTime, false, "not expired");
       return false;
     }
     if (counter.tryAcquire()) {
       log.debug("API security sampling is required for this request (presampled)");
       ctx.setKeepOpenForApiSecurityPostProcessing(true);
+      logSamplingDecision("preSampleRequest", currentTime, true, "acquired semaphore");
       return true;
     }
+    logSamplingDecision("preSampleRequest", currentTime, false, "semaphore full");
     return false;
   }
 
@@ -91,7 +100,11 @@ public boolean sampleRequest(AppSecRequestContext ctx) {
       // This should never happen, it should have been short-circuited before.
       return false;
     }
-    return updateApiAccessIfExpired(hash);
+    long currentTime = timeSource.getCurrentTimeMillis();
+    boolean decision = updateApiAccessIfExpired(hash);
+    logSamplingDecision(
+        "sampleRequest", currentTime, decision, decision ? "sampled" : "already sampled");
+    return decision;
   }
 
   @Override
@@ -168,4 +181,27 @@ private long computeApiHash(final String route, final String method, final int s
     result = 31 * result + statusCode;
     return result;
   }
+
+  private void logSamplingDecision(String method, long timestamp, boolean decision, String reason) {
+    AgentSpan activeSpan = AgentTracer.get().activeSpan();
+    String traceId = "null";
+    String spanId = "null";
+
+    if (activeSpan != null) {
+      if (activeSpan.getTraceId() != null) {
+        traceId = activeSpan.getTraceId().toString();
+      }
+      spanId = String.valueOf(activeSpan.getSpanId());
+    }
+
+    log.info(
+        "[API_SECURITY_SAMPLING] method={}, timestamp={}, traceId={}, spanId={}, decision={}, reason={}, expirationTimeMs={}",
+        method,
+        timestamp,
+        traceId,
+        spanId,
+        decision,
+        reason,
+        expirationTimeInMs);
+  }
 }

dd-java-agent/appsec/src/main/java/com/datadog/appsec/api/security/AppSecSpanPostProcessor.java

@@ -31,30 +31,45 @@ public AppSecSpanPostProcessor(ApiSecuritySampler sampler, EventProducerService
 
   @Override
   public void process(@Nonnull AgentSpan span, @Nonnull BooleanSupplier timeoutCheck) {
+    long timestamp = System.currentTimeMillis();
+    String traceId = span.getTraceId() != null ? span.getTraceId().toString() : "null";
+    String spanId = String.valueOf(span.getSpanId());
+
     final RequestContext ctx_ = span.getRequestContext();
     if (ctx_ == null) {
+      logProcessingDecision(timestamp, traceId, spanId, false, "no request context", "start");
       return;
     }
     final AppSecRequestContext ctx = ctx_.getData(RequestContextSlot.APPSEC);
     if (ctx == null) {
+      logProcessingDecision(timestamp, traceId, spanId, false, "no appsec context", "start");
       return;
     }
 
     if (!ctx.isKeepOpenForApiSecurityPostProcessing()) {
+      logProcessingDecision(
+          timestamp, traceId, spanId, false, "not marked for post-processing", "start");
       return;
     }
 
     try {
       if (timeoutCheck.getAsBoolean()) {
         log.debug("Timeout detected, skipping API security post-processing");
+        logProcessingDecision(
+            timestamp, traceId, spanId, false, "timeout detected", "pre-sampling");
         return;
       }
       if (!sampler.sampleRequest(ctx)) {
         log.debug("Request not sampled, skipping API security post-processing");
+        logProcessingDecision(
+            timestamp, traceId, spanId, false, "request not sampled", "post-sampling");
         return;
       }
       log.debug("Request sampled, processing API security post-processing");
+      logProcessingDecision(
+          timestamp, traceId, spanId, true, "sampled, extracting schemas", "extracting");
       extractSchemas(ctx, ctx_.getTraceSegment());
+      logProcessingDecision(timestamp, traceId, spanId, true, "extraction completed", "completed");
     } finally {
       ctx.setKeepOpenForApiSecurityPostProcessing(false);
       try {
@@ -67,6 +82,7 @@ public void process(@Nonnull AgentSpan span, @Nonnull BooleanSupplier timeoutChe
         log.debug("Error closing AppSecRequestContext", e);
       }
       sampler.releaseOne();
+      logProcessingDecision(timestamp, traceId, spanId, false, "cleanup completed", "cleanup");
     }
   }
 
@@ -89,4 +105,21 @@ private void extractSchemas(final AppSecRequestContext ctx, final TraceSegment t
       log.debug("Subscriber info expired", e);
     }
   }
+
+  private void logProcessingDecision(
+      long timestamp,
+      String traceId,
+      String spanId,
+      boolean processed,
+      String reason,
+      String stage) {
+    log.info(
+        "[APPSEC_SPAN_POST_PROCESSING] timestamp={}, traceId={}, spanId={}, processed={}, reason={}, stage={}",
+        timestamp,
+        traceId,
+        spanId,
+        processed,
+        reason,
+        stage);
+  }
 }