diff --git a/.gitlab/generate-tracer.php b/.gitlab/generate-tracer.php index bf7fbc8f54..8509e5d062 100644 --- a/.gitlab/generate-tracer.php +++ b/.gitlab/generate-tracer.php @@ -138,6 +138,11 @@ function before_script_steps($with_docker_auth = false) { # Build nts docker exec ${CONTAINER_NAME} powershell.exe "cd app; switch-php nts; C:\php\SDK\phpize.bat; .\configure.bat --enable-debug-pack; nmake" + # Harden the phpize-provided run-tests.php: tree-kill a timed-out test and + # make its retry-run file write resilient to a briefly-held Windows lock, so + # one hung test cannot abort the whole suite (see the script for details). + docker exec ${CONTAINER_NAME} powershell.exe "cd app; C:\php\php.exe .gitlab\patch-run-tests-windows.php run-tests.php" + # Set test environment variables docker exec ${CONTAINER_NAME} powershell.exe "setx DD_AUTOLOAD_NO_COMPILE true; setx DATADOG_HAVE_DEV_ENV 1; setx DD_TRACE_GIT_METADATA_ENABLED 0" @@ -149,7 +154,11 @@ function before_script_steps($with_docker_auth = false) { # Run extension tests - docker exec ${CONTAINER_NAME} powershell.exe 'cd app; $env:_DD_DEBUG_SIDECAR_LOG_LEVEL=trace; $env:_DD_DEBUG_SIDECAR_LOG_METHOD="""file://${pwd}\sidecar.log"""; C:\php\php.exe -n -d memory_limit=-1 -d output_buffering=0 run-tests.php -g FAIL,XFAIL,BORK,WARN,LEAK,XLEAK,SKIP --show-diff -p C:\php\php.exe -d "extension=${pwd}\x64\Release\php_ddtrace.dll" "${pwd}\tests\ext"' + # _DD_TEST_HANG_WATCHDOG_SEC arms an in-extension teardown watchdog: if a + # request's teardown wedges, it dumps the main-thread stack and aborts the + # child before run-tests.php's 60s timeout, turning a silent hang into an + # actionable stack and a plain failure (no suite-killing timeout+retry). + docker exec ${CONTAINER_NAME} powershell.exe 'cd app; $env:_DD_DEBUG_SIDECAR_LOG_LEVEL=trace; $env:_DD_DEBUG_SIDECAR_LOG_METHOD="""file://${pwd}\sidecar.log"""; $env:_DD_TEST_HANG_WATCHDOG_SEC=40; C:\php\php.exe -n -d memory_limit=-1 -d output_buffering=0 run-tests.php -g FAIL,XFAIL,BORK,WARN,LEAK,XLEAK,SKIP --show-diff -p C:\php\php.exe -d "extension=${pwd}\x64\Release\php_ddtrace.dll" "${pwd}\tests\ext"' after_script: - | docker exec ${CONTAINER_NAME} cmd.exe /s /c xcopy /y /c /s /e C:\ProgramData\Microsoft\Windows\WER\ReportQueue .\app\dumps\ diff --git a/.gitlab/patch-run-tests-windows.php b/.gitlab/patch-run-tests-windows.php new file mode 100644 index 0000000000..fdc4ffd053 --- /dev/null +++ b/.gitlab/patch-run-tests-windows.php @@ -0,0 +1,111 @@ +.php file. run-tests.php then `goto retry`s the test, re-writes + * that file via save_text() -> file_put_contents() which returns false on the + * locked file -> error() -> exit(1), fatally aborting the whole suite mid-run. + * + * This applies two surgical, anchor-asserted patches to the copy of + * run-tests.php that phpize.bat drops into the build dir: + * 1. taskkill /T /F the timed-out process tree before proc_terminate. + * 2. Retry the save_text() write with a short backoff instead of aborting. + * + * The Windows matrix spans PHP 7.2-8.5 and run-tests.php differs between them, + * so a missing anchor is a no-op (status quo, no regression) rather than a hard + * error -- the in-extension hang watchdog covers every version regardless. Only + * a genuinely ambiguous (>1) match is treated as fatal. + */ + +$path = $argv[1] ?? 'run-tests.php'; +if (!is_file($path)) { + fwrite(STDERR, "patch-run-tests-windows: '$path' not found\n"); + exit(1); +} + +$src = file_get_contents($path); + +// Match the file's existing line endings so anchors compare and patched output +// stays consistent whether the SDK ships run-tests.php with LF or CRLF. +$crlf = strpos($src, "\r\n") !== false; + +/** @return void */ +function apply(string &$src, string $find, string $replace, string $label): void +{ + global $crlf; + if ($crlf) { + $find = str_replace("\n", "\r\n", $find); + $replace = str_replace("\n", "\r\n", $replace); + } + $count = substr_count($src, $find); + if ($count === 0) { + echo "patch-run-tests-windows: anchor '$label' not present; skipping\n"; + return; + } + if ($count > 1) { + fwrite(STDERR, "patch-run-tests-windows: anchor '$label' matched $count times; ambiguous, aborting\n"); + exit(1); + } + $src = str_replace($find, $replace, $src); + echo "patch-run-tests-windows: applied '$label'\n"; +} + +// 1. Kill the whole process tree on timeout so the test file's lock is released +// before the retry re-writes it. +apply( + $src, + <<<'PHP' + $data .= "\n ** ERROR: process timed out **\n"; + proc_terminate($proc, 9); +PHP, + <<<'PHP' + $data .= "\n ** ERROR: process timed out **\n"; + $dd_status = @proc_get_status($proc); + if (isset($dd_status['pid'])) { + @exec('taskkill /T /F /PID ' . (int)$dd_status['pid'] . ' 2>NUL'); + } + proc_terminate($proc, 9); +PHP, + 'timeout tree-kill' +); + +// 2. Make the test-file write resilient to a briefly-held Windows lock so a +// retry write cannot escalate to a suite-killing exit(1). +apply( + $src, + <<<'PHP' + if ($filename_copy && $filename_copy != $filename && file_put_contents($filename_copy, $text) === false) { + error("Cannot open file '" . $filename_copy . "' (save_text)"); + } + + if (file_put_contents($filename, $text) === false) { + error("Cannot open file '" . $filename . "' (save_text)"); + } +PHP, + <<<'PHP' + $dd_write = static function (string $f, string $t): bool { + for ($i = 0; $i < 30; $i++) { + if (file_put_contents($f, $t) !== false) { + return true; + } + usleep(100000); + } + return false; + }; + + if ($filename_copy && $filename_copy != $filename && !$dd_write($filename_copy, $text)) { + error("Cannot open file '" . $filename_copy . "' (save_text)"); + } + + if (!$dd_write($filename, $text)) { + error("Cannot open file '" . $filename . "' (save_text)"); + } +PHP, + 'save_text retry' +); + +file_put_contents($path, $src); +echo "patch-run-tests-windows: patched $path\n"; diff --git a/config.w32 b/config.w32 index 5ff5b2e9d7..7f8c8d733f 100644 --- a/config.w32 +++ b/config.w32 @@ -23,6 +23,7 @@ if (PHP_DDTRACE != 'no') { DDTRACE_EXT_SOURCES += " endpoints.c"; DDTRACE_EXT_SOURCES += " excluded_modules.c"; DDTRACE_EXT_SOURCES += " git.c"; + DDTRACE_EXT_SOURCES += " hang_watchdog_windows.c"; DDTRACE_EXT_SOURCES += " handlers_api.c"; DDTRACE_EXT_SOURCES += " handlers_pcntl.c"; DDTRACE_EXT_SOURCES += " logging.c"; diff --git a/ext/datadog.c b/ext/datadog.c index fc2cd4622c..97b9df6601 100644 --- a/ext/datadog.c +++ b/ext/datadog.c @@ -17,6 +17,7 @@ #include "sidecar.h" #include "signals.h" #include "startup_logging.h" +#include "hang_watchdog_windows.h" #include "telemetry.h" #include "zend_hrtime.h" #ifndef _WIN32 @@ -628,6 +629,10 @@ static void dd_shutdown_observer() { static PHP_RSHUTDOWN_FUNCTION(datadog) { UNUSED(module_number, type); + // CI-only (opt-in via _DD_TEST_HANG_WATCHDOG_SEC): guard against a teardown + // hang wedging the whole request. No-op elsewhere. + ddtrace_arm_teardown_hang_watchdog(); + // We deliberately select to not free some data structures, as to avoid the overhead of freeing them. // Just proper destruction can have significant and easily measurable overhead on applications. // Prior to PHP 7.2 fast shutdown was an opcache only feature diff --git a/ext/hang_watchdog_windows.c b/ext/hang_watchdog_windows.c new file mode 100644 index 0000000000..070a80b631 --- /dev/null +++ b/ext/hang_watchdog_windows.c @@ -0,0 +1,191 @@ +#ifdef _WIN32 + +#include "hang_watchdog_windows.h" + +#include +// dbghelp.h must follow windows.h. +#include +#include +#include +#include +#include +#include + +static volatile LONG dd_watchdog_armed = 0; +static HANDLE dd_watchdog_main_thread = NULL; + +// Write straight to the OS stdout handle: the main thread is suspended while we +// dump and may hold the CRT stdio lock, so fwrite/printf could deadlock. +static void dd_watchdog_write(const char *buf, size_t len) { + HANDLE h = GetStdHandle(STD_OUTPUT_HANDLE); + if (h == NULL || h == INVALID_HANDLE_VALUE) { + return; + } + DWORD written; + WriteFile(h, buf, (DWORD)len, &written, NULL); +} + +static void dd_watchdog_puts(const char *s) { dd_watchdog_write(s, strlen(s)); } + +static void dd_watchdog_dump_stack(void) { + HANDLE process = GetCurrentProcess(); + HANDLE thread = dd_watchdog_main_thread; + if (thread == NULL) { + return; + } + + if (SuspendThread(thread) == (DWORD)-1) { + return; + } + + CONTEXT ctx; + memset(&ctx, 0, sizeof(ctx)); + ctx.ContextFlags = CONTEXT_FULL; + if (!GetThreadContext(thread, &ctx)) { + ResumeThread(thread); + return; + } + + // Guaranteed lock-free datum: the raw faulting PC. Even if the symbolized + // walk below wedges (e.g. the suspended thread holds a heap/loader lock), + // this address is already emitted for offline symbolization with the PDB. + char pc[128]; + int pcn = snprintf(pc, sizeof(pc), + "hang watchdog: main-thread PC = 0x%llx\n", + (unsigned long long)ctx.Rip); + if (pcn > 0) { + dd_watchdog_write(pc, (size_t)pcn); + } + + SymSetOptions(SYMOPT_UNDNAME | SYMOPT_DEFERRED_LOADS | SYMOPT_LOAD_LINES); + SymInitialize(process, NULL, TRUE); + + STACKFRAME64 frame; + memset(&frame, 0, sizeof(frame)); + frame.AddrPC.Offset = ctx.Rip; + frame.AddrPC.Mode = AddrModeFlat; + frame.AddrFrame.Offset = ctx.Rbp; + frame.AddrFrame.Mode = AddrModeFlat; + frame.AddrStack.Offset = ctx.Rsp; + frame.AddrStack.Mode = AddrModeFlat; + + // Union guarantees SYMBOL_INFO's 8-byte alignment while reserving the + // trailing space its variable-length Name field needs. + union { + SYMBOL_INFO info; + char buf[sizeof(SYMBOL_INFO) + MAX_SYM_NAME * sizeof(char)]; + } symstore; + char line[1200]; + for (int i = 0; i < 128; i++) { + if (!StackWalk64(IMAGE_FILE_MACHINE_AMD64, process, thread, &frame, &ctx, + NULL, SymFunctionTableAccess64, SymGetModuleBase64, + NULL)) { + break; + } + DWORD64 addr = frame.AddrPC.Offset; + if (addr == 0) { + break; + } + + DWORD64 mod_base = SymGetModuleBase64(process, addr); + char mod_name[MAX_PATH] = "?"; + if (mod_base) { + GetModuleBaseNameA(process, (HMODULE)(uintptr_t)mod_base, mod_name, + sizeof(mod_name)); + } + DWORD64 rva = mod_base ? addr - mod_base : 0; + + SYMBOL_INFO *sym = &symstore.info; + memset(&symstore, 0, sizeof(symstore)); + sym->SizeOfStruct = sizeof(SYMBOL_INFO); + sym->MaxNameLen = MAX_SYM_NAME; + DWORD64 disp = 0; + int n; + if (SymFromAddr(process, addr, &disp, sym)) { + IMAGEHLP_LINE64 src; + memset(&src, 0, sizeof(src)); + src.SizeOfStruct = sizeof(src); + DWORD line_disp = 0; + if (SymGetLineFromAddr64(process, addr, &line_disp, &src)) { + n = snprintf(line, sizeof(line), + " #%02d %s!%s+0x%llx (%s:%lu) [%s+0x%llx]\n", i, + mod_name, sym->Name, (unsigned long long)disp, + src.FileName, (unsigned long)src.LineNumber, + mod_name, (unsigned long long)rva); + } else { + n = snprintf(line, sizeof(line), + " #%02d %s!%s+0x%llx [%s+0x%llx]\n", i, mod_name, + sym->Name, (unsigned long long)disp, mod_name, + (unsigned long long)rva); + } + } else { + n = snprintf(line, sizeof(line), " #%02d %s+0x%llx [0x%llx]\n", i, + mod_name, (unsigned long long)rva, + (unsigned long long)addr); + } + if (n > 0) { + // snprintf returns the would-be length; clamp so an over-long + // (e.g. mangled Rust) frame cannot over-read past `line`. + size_t wlen = n < (int)sizeof(line) ? (size_t)n : sizeof(line) - 1; + dd_watchdog_write(line, wlen); + } + } + + SymCleanup(process); + ResumeThread(thread); +} + +static DWORD WINAPI dd_watchdog_thread(LPVOID param) { + DWORD timeout_ms = (DWORD)(uintptr_t)param; + Sleep(timeout_ms); + + // Wording deliberately avoids run-tests.php's flaky-retry keywords + // ("timed out", "deadlock", ...) so this is reported as a plain failure. + dd_watchdog_puts( + "\n===== ddtrace hang watchdog fired =====\n" + "Request teardown did not finish within budget; dumping the main-thread\n" + "stack, then aborting so the test suite keeps running.\n"); + dd_watchdog_dump_stack(); + dd_watchdog_puts("===== ddtrace hang watchdog: end =====\n"); + FlushFileBuffers(GetStdHandle(STD_OUTPUT_HANDLE)); + + // Abort via TerminateProcess (not exit()): the CRT/atexit path may be the + // very thing wedged. The clean process kill also releases the file handles + // that would otherwise make run-tests.php's retry-write fail on Windows. + TerminateProcess(GetCurrentProcess(), 3); + return 0; +} + +void ddtrace_arm_teardown_hang_watchdog(void) { + const char *env = getenv("_DD_TEST_HANG_WATCHDOG_SEC"); + if (env == NULL || env[0] == '\0') { + return; + } + long secs = strtol(env, NULL, 10); + if (secs <= 0) { + return; + } + if (secs > 3600) { + secs = 3600; // guard the ms cast against overflow + } + if (InterlockedCompareExchange(&dd_watchdog_armed, 1, 0) != 0) { + return; // arm at most once per process + } + + // GetCurrentThread() is a pseudo-handle only valid on the calling thread, so + // hand the watchdog a real, duplicated handle to the main thread. + if (!DuplicateHandle(GetCurrentProcess(), GetCurrentThread(), + GetCurrentProcess(), &dd_watchdog_main_thread, 0, FALSE, + DUPLICATE_SAME_ACCESS)) { + dd_watchdog_main_thread = NULL; + return; + } + + HANDLE t = CreateThread(NULL, 0, dd_watchdog_thread, + (LPVOID)(uintptr_t)(DWORD)(secs * 1000), 0, NULL); + if (t != NULL) { + CloseHandle(t); + } +} + +#endif // _WIN32 diff --git a/ext/hang_watchdog_windows.h b/ext/hang_watchdog_windows.h new file mode 100644 index 0000000000..63652d20ac --- /dev/null +++ b/ext/hang_watchdog_windows.h @@ -0,0 +1,16 @@ +#ifndef DATADOG_HANG_WATCHDOG_WINDOWS_H +#define DATADOG_HANG_WATCHDOG_WINDOWS_H + +// Windows-only CI diagnostic. Arms a watchdog thread at request teardown; if +// teardown does not finish within _DD_TEST_HANG_WATCHDOG_SEC seconds it dumps +// the main thread's stack to stdout and terminates the process. This converts a +// silent >60s run-tests.php per-test timeout (which on Windows cascades into a +// suite-killing locked-file retry) into an early exit with an actionable stack. +// No-op unless _DD_TEST_HANG_WATCHDOG_SEC holds a positive integer. +#ifdef _WIN32 +void ddtrace_arm_teardown_hang_watchdog(void); +#else +static inline void ddtrace_arm_teardown_hang_watchdog(void) {} +#endif + +#endif // DATADOG_HANG_WATCHDOG_WINDOWS_H