From 1bf0e240080ab44b68dcda539d4540e8ca1fae88 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gustavo=20Andr=C3=A9=20dos=20Santos=20Lopes?= Date: Fri, 6 Nov 2026 16:58:55 +0000 Subject: [PATCH] tracer: keep the trace of a request blocked during startup When AppSec blocks a request while PHP is still in request startup, it calls ddtrace_close_all_spans_and_flush(), which closes every open span and then force-flushes the tracer. The flush has to be forced because ddtrace_flush_tracer() otherwise discards traces while PG(during_request_startup) is set, to avoid reporting requests that never ran any PHP code. With DD_TRACE_AUTO_FLUSH_ENABLED=1 on a web SAPI, closing the root span in the first step already triggers the regular auto-flush. That flush is not forced: it serializes the closed spans, removes them from the tracer and then drops them because the request is still starting up. The forced flush that follows finds nothing left to send, so the trace of the blocked request, which carries the AppSec event, never reaches the agent. Auto-flush is only on by default for the CLI SAPI, where AppSec does not block requests, so this only affects users who enable it explicitly for php-fpm, CGI, Apache and the like. ddtrace_close_all_spans_and_flush() now suppresses the root-span auto-flush while it closes the spans, so that only its own forced flush sends them. Outside request startup this does not change what is sent: before, the auto-flush sent the trace and the forced flush found an empty buffer; now the forced flush sends it. The flag is restored on bailout so that a fatal error in a span close hook cannot leave auto-flush disabled for the rest of the request. Two alternatives were rejected. Passing the force flag into the auto-flush would require threading it through the span closing call chain for a single caller. Checking PG(during_request_startup) before serializing in ddtrace_flush_tracer() would leave the closed spans alive instead of dropping them, which changes behaviour for every request that ends without running PHP code, such as php-fpm status pages or missing scripts. The new test runs a php-cgi child that AppSec blocks in request init, with a mock agent in the parent, and checks that the trace arrives with auto-flush both off and on. Without the fix it fails only in the auto-flush case. Co-Authored-By: Claude Opus 5.5 --- .../req_abort_in_req_init_auto_flush.inc | 1 + .../req_abort_in_req_init_auto_flush.phpt | 162 ++++++++++++++++++ tracer/auto_flush.c | 15 +- tracer/ddtrace_globals.h | 3 + tracer/span.c | 2 +- 5 files changed, 181 insertions(+), 2 deletions(-) create mode 100644 appsec/tests/extension/req_abort_in_req_init_auto_flush.inc create mode 100644 appsec/tests/extension/req_abort_in_req_init_auto_flush.phpt diff --git a/appsec/tests/extension/req_abort_in_req_init_auto_flush.inc b/appsec/tests/extension/req_abort_in_req_init_auto_flush.inc new file mode 100644 index 0000000000..6e0c450472 --- /dev/null +++ b/appsec/tests/extension/req_abort_in_req_init_auto_flush.inc @@ -0,0 +1 @@ +THIS SHOULD NOT BE REACHED diff --git a/appsec/tests/extension/req_abort_in_req_init_auto_flush.phpt b/appsec/tests/extension/req_abort_in_req_init_auto_flush.phpt new file mode 100644 index 0000000000..fe7cc3667e --- /dev/null +++ b/appsec/tests/extension/req_abort_in_req_init_auto_flush.phpt @@ -0,0 +1,162 @@ +--TEST-- +Request aborted in request init still sends its trace with auto-flush enabled +--DESCRIPTION-- +When a request is blocked during request startup, the tracer closes all spans +and force-flushes them before the request is aborted. Closing the root span +used to trigger the regular auto-flush, which drops traces while PHP is still +in request startup, so the forced flush that followed found nothing to send. +This test runs a php-cgi child that is blocked in request init, with +auto-flush disabled and enabled, and checks that a mock agent receives the +trace of the blocked request in both cases. +--SKIPIF-- + +--ENV-- +DD_TRACE_ENABLED=0 +--FILE-- + '1', + 'DD_TRACE_GENERATE_ROOT_SPAN' => '1', + 'DD_TRACE_AUTO_FLUSH_ENABLED' => $auto_flush ? '1' : '0', + 'DD_TRACE_AGENT_URL' => "http://127.0.0.1:$port", + 'DD_SERVICE' => SERVICE, + 'REDIRECT_STATUS' => '1', + 'GATEWAY_INTERFACE' => 'CGI/1.1', + 'REQUEST_METHOD' => 'GET', + 'SCRIPT_FILENAME' => $script, + 'PATH_TRANSLATED' => $script, + 'REQUEST_URI' => '/blocked', + 'QUERY_STRING' => '', + ]); + + $cmd = [ + getenv('TEST_PHP_CGI_EXECUTABLE'), + '-n', + '-c', php_ini_loaded_file(), + '-d', 'extension_dir=' . ini_get('extension_dir'), + '-d', 'extension=ddtrace.so', + '-d', 'datadog.appsec.enabled=1', + '-d', 'datadog.appsec.testing_abort_rinit=1', + '-d', 'display_errors=0', + '-d', 'log_errors=0', + ]; + $cmdline = implode(' ', array_map('escapeshellarg', $cmd)); + + $proc = proc_open($cmdline, [ + 0 => ['file', '/dev/null', 'r'], + 1 => ['pipe', 'w'], + 2 => ['pipe', 'w'], + ], $pipes, null, $env); + if (!is_resource($proc)) { + die("could not start php-cgi\n"); + } + + $requests = []; + $exited_at = null; + while (true) { + $read = [$server]; + $w = $e = null; + if (stream_select($read, $w, $e, 0, 100000) > 0) { + $conn = stream_socket_accept($server, 1); + if ($conn) { + $req = read_http_request($conn); + if ($req !== null) { + $requests[] = $req; + } + fwrite($conn, "HTTP/1.1 200 OK\r\nContent-Type: application/json\r\n" + . "Content-Length: 2\r\nConnection: close\r\n\r\n{}"); + fclose($conn); + } + continue; + } + $status = proc_get_status($proc); + if (!$status['running']) { + // keep serving a little longer in case a send is still in flight + if ($exited_at === null) { + $exited_at = microtime(true); + } elseif (microtime(true) - $exited_at > 0.5) { + break; + } + } + } + + $stdout = stream_get_contents($pipes[1]); + stream_get_contents($pipes[2]); + fclose($pipes[1]); + fclose($pipes[2]); + proc_close($proc); + fclose($server); + + $blocked = strpos($stdout, '403 Forbidden') !== false + && strpos($stdout, 'THIS SHOULD NOT BE REACHED') === false; + + $trace_sent = false; + foreach ($requests as list($line, $body)) { + if (strpos($line, '/traces') !== false && strpos($body, SERVICE) !== false) { + $trace_sent = true; + } + } + + echo 'auto-flush ', $auto_flush ? 'on' : 'off', ': ', + 'blocked: ', $blocked ? 'yes' : 'no', ', ', + 'trace sent: ', $trace_sent ? 'yes' : 'no', "\n"; +} + +run_blocked_request(false); +run_blocked_request(true); + +?> +--EXPECT-- +auto-flush off: blocked: yes, trace sent: yes +auto-flush on: blocked: yes, trace sent: yes diff --git a/tracer/auto_flush.c b/tracer/auto_flush.c index 7d722b6f04..20928a3013 100644 --- a/tracer/auto_flush.c +++ b/tracer/auto_flush.c @@ -116,6 +116,19 @@ zend_result ddtrace_flush_tracer(bool force_on_startup, bool collect_cycles, boo void ddtrace_close_all_spans_and_flush() { - ddtrace_close_all_open_spans(true); + // Closing the root span normally triggers an auto-flush when it is + // enabled. That flush is not forced, so during request startup (e.g. when + // AppSec blocks the request in RINIT) it would serialize the closed spans + // and then drop them, leaving nothing for the forced flush below. Only + // the forced flush must send them. + zend_bool suppress_auto_flush = DDTRACE_G(suppress_auto_flush); + DDTRACE_G(suppress_auto_flush) = true; + zend_try { + ddtrace_close_all_open_spans(true); + } zend_catch { + DDTRACE_G(suppress_auto_flush) = suppress_auto_flush; + zend_bailout(); + } zend_end_try(); + DDTRACE_G(suppress_auto_flush) = suppress_auto_flush; ddtrace_flush_tracer(true, true, false); } diff --git a/tracer/ddtrace_globals.h b/tracer/ddtrace_globals.h index c1fbe26108..d0b3b9ee03 100644 --- a/tracer/ddtrace_globals.h +++ b/tracer/ddtrace_globals.h @@ -61,6 +61,9 @@ typedef struct { dogstatsd_client dogstatsd_client; #endif zend_bool in_shutdown; + // Set while ddtrace_close_all_spans_and_flush() closes the open spans, so + // that closing the root span does not trigger an auto-flush of its own. + zend_bool suppress_auto_flush; zend_long default_priority_sampling; zend_long propagated_priority_sampling; diff --git a/tracer/span.c b/tracer/span.c index 3192000a64..e4b1229e36 100644 --- a/tracer/span.c +++ b/tracer/span.c @@ -898,7 +898,7 @@ static void dd_close_entry_span_of_stack(ddtrace_span_stack *stack) { } #endif - if (closed_root_stack && get_DD_TRACE_AUTO_FLUSH_ENABLED() + if (closed_root_stack && get_DD_TRACE_AUTO_FLUSH_ENABLED() && !DDTRACE_G(suppress_auto_flush) && ddtrace_flush_tracer(false, get_DD_TRACE_FLUSH_COLLECT_CYCLES(), false) == FAILURE) { // In case we have root spans enabled, we need to always flush if we close that one (RSHUTDOWN) LOG(WARN, "Unable to auto flush the tracer");