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");