From 5b0394b3f3d0c6603bd93c405c45e703759baff4 Mon Sep 17 00:00:00 2001 From: Byoungchan Lee Date: Thu, 23 Oct 2025 15:30:21 +0900 Subject: [PATCH] Add detailed logging on AsyncProcess to help diagnose hangs See https://github.com/swiftlang/swift-package-manager/issues/9274 for context. The existing logging is insufficient to diagnose hangs in AsyncProcess, so adding more detailed logging around process start, output, and termination should help identify where things are going wrong. - Added `SWIFTPM_DEBUG_PROCESS_IO` environment variable to enable low-level I/O thread debugging without interfering with normal observability output - Added `processTrackingID` (8-character UUID prefix) to uniquely identify each process instance in logs for correlation across multiple concurrent processes - Added `logProcessIODebug()` helper that writes directly to stderr when debug mode is enabled, bypassing all handlers to capture issues even when the observability system has problems - Instrumented all critical synchronization points in the I/O thread lifecycle After this change, AsyncProcess will log detailed information about process lifecycle events, including when processes are started, when output is received, and when processes terminate. This should provide better visibility into where hangs may be occurring during dependency resolution. Users experiencing hangs can now run: ``` SWIFTPM_DEBUG_PROCESS_IO=1 swift package resolve 2>&1 | tee debug.log ``` --- Sources/Basics/Concurrency/AsyncProcess.swift | 137 +++++++++++++----- 1 file changed, 103 insertions(+), 34 deletions(-) diff --git a/Sources/Basics/Concurrency/AsyncProcess.swift b/Sources/Basics/Concurrency/AsyncProcess.swift index 86222f8fa67..1d322e7e8fc 100644 --- a/Sources/Basics/Concurrency/AsyncProcess.swift +++ b/Sources/Basics/Concurrency/AsyncProcess.swift @@ -159,6 +159,22 @@ extension DispatchQueue { ) } +// MARK: - Process Logging + +/// Enable detailed process I/O thread debugging by setting SWIFTPM_DEBUG_PROCESS_IO=1 +/// This is a low-level debugging flag for diagnosing process hangs and defunct processes. +private let debugProcessIO = Environment.current["SWIFTPM_DEBUG_PROCESS_IO"] != nil + +/// Helper to log process I/O events for debugging hangs. +/// Only active when SWIFTPM_DEBUG_PROCESS_IO=1 is set. +private func logProcessIODebug(_ message: String) { + if debugProcessIO { + // Use fputs to stderr for low-level debugging that bypasses all handlers + fputs("[AsyncProcess] \(message)\n", stderr) + fflush(stderr) + } +} + /// Process allows spawning new subprocesses and working with them. /// /// Note: This class is thread safe. @@ -265,6 +281,9 @@ package final class AsyncProcess { private static var _loggingHandler: LoggingHandler? private static let loggingHandlerLock = NSLock() + /// Unique identifier for tracking this process instance in logs + private let processTrackingID: String = UUID().uuidString.prefix(8).description + /// Global logging handler. Use with care! preferably use instance level instead of setting one globally. @available( *, @@ -484,9 +503,15 @@ package final class AsyncProcess { loggingHandler(self.arguments.map { $0.spm_shellEscaped() }.joined(separator: " ")) } + // Additional low-level debugging for process I/O hangs (only with SWIFTPM_DEBUG_PROCESS_IO=1) + logProcessIODebug( + "[\(self.processTrackingID)] SPAWN: \(self.arguments.map { $0.spm_shellEscaped() }.joined(separator: " "))" + ) + // Look for executable. let executable = self.arguments[0] guard let executablePath = AsyncProcess.findExecutable(executable, workingDirectory: workingDirectory) else { + logProcessIODebug("[\(self.processTrackingID)] ERROR: Executable not found: \(executable)") throw AsyncProcess.Error.missingExecutableProgram(program: executable) } @@ -686,9 +711,12 @@ package final class AsyncProcess { let rv = posix_spawnp(&self.processID, argv.cArray[0]!, &fileActions, &attributes, argv.cArray, env.cArray) guard rv == 0 else { + logProcessIODebug("[\(self.processTrackingID)] ERROR: posix_spawnp failed with rv=\(rv)") throw SystemError.posix_spawn(rv, self.arguments) } + logProcessIODebug("[\(self.processTrackingID)] SPAWNED: PID=\(self.processID), cmd=\(self.arguments[0])") + do { // Close the local read end of the input pipe. try close(fd: stdinPipe[0]) @@ -696,6 +724,7 @@ package final class AsyncProcess { let group = DispatchGroup() if !self.outputRedirection.redirectsOutput { // no stdout or stderr in this case + logProcessIODebug("[\(self.processTrackingID)] I/O: No output redirection, skipping I/O threads") self.stateLock.withLock { self.state = .outputReady(stdout: .success([]), stderr: .success([])) } @@ -710,28 +739,42 @@ package final class AsyncProcess { // Create a thread and start reading the output on it. group.enter() - let stdoutThread = Thread { [weak self] in - if let readResult = self?.readOutput( + logProcessIODebug("[\(self.processTrackingID)] I/O: stdout thread group.enter()") + + let stdoutThread = Thread { [weak self, processTrackingID] in + logProcessIODebug("[\(processTrackingID)] I/O: stdout thread started") + + guard let self else { + logProcessIODebug( + "[\(processTrackingID)] I/O: stdout thread - self is nil, calling group.leave()" + ) + group.leave() + return + } + + let readResult = self.readOutput( onFD: outputPipe[0], outputClosure: outputClosures?.stdoutClosure - ) { - pendingLock.withLock { - if let stderrResult = pending { - self?.stateLock.withLock { - self?.state = .outputReady(stdout: readResult, stderr: stderrResult) - } - } else { - pending = readResult + ) + logProcessIODebug("[\(processTrackingID)] I/O: stdout thread read completed") + + pendingLock.withLock { + if let stderrResult = pending { + // TODO: this is more of an error + self.stateLock.withLock { + self.state = .outputReady(stdout: readResult, stderr: stderrResult) } + logProcessIODebug("[\(processTrackingID)] I/O: stdout thread - both ready") + } else { + pending = readResult + logProcessIODebug( + "[\(processTrackingID)] I/O: stdout thread - stored result, waiting for stderr" + ) } - group.leave() - } else if let stderrResult = (pendingLock.withLock { pending }) { - // TODO: this is more of an error - self?.stateLock.withLock { - self?.state = .outputReady(stdout: .success([]), stderr: stderrResult) - } - group.leave() } + + group.leave() + logProcessIODebug("[\(processTrackingID)] I/O: stdout thread finished") } // Only schedule a thread for stderr if no redirect was requested. @@ -742,30 +785,42 @@ package final class AsyncProcess { // Create a thread and start reading the stderr output on it. group.enter() - stderrThread = Thread { [weak self] in - if let readResult = self?.readOutput( + logProcessIODebug("[\(self.processTrackingID)] I/O: stderr thread group.enter()") + + stderrThread = Thread { [weak self, processTrackingID] in + logProcessIODebug("[\(processTrackingID)] I/O: stderr thread started") + + guard let self else { + logProcessIODebug("[\(processTrackingID)] I/O: stderr thread - self is nil") + return + } + + let readResult = self.readOutput( onFD: stderrPipe[0], outputClosure: outputClosures?.stderrClosure - ) { - pendingLock.withLock { - if let stdoutResult = pending { - self?.stateLock.withLock { - self?.state = .outputReady(stdout: stdoutResult, stderr: readResult) - } - } else { - pending = readResult + ) + logProcessIODebug("[\(processTrackingID)] I/O: stderr thread read completed") + + pendingLock.withLock { + if let stdoutResult = pending { + // TODO: this is more of an error + self.stateLock.withLock { + self.state = .outputReady(stdout: stdoutResult, stderr: readResult) } + logProcessIODebug("[\(processTrackingID)] I/O: stderr thread - both ready") + } else { + pending = readResult + logProcessIODebug( + "[\(processTrackingID)] I/O: stderr thread - stored result, waiting for stdout" + ) } - group.leave() - } else if let stdoutResult = (pendingLock.withLock { pending }) { - // TODO: this is more of an error - self?.stateLock.withLock { - self?.state = .outputReady(stdout: stdoutResult, stderr: .success([])) - } - group.leave() } + + group.leave() + logProcessIODebug("[\(processTrackingID)] I/O: stderr thread finished") } } else { + logProcessIODebug("[\(self.processTrackingID)] I/O: stderr redirected to stdout") pendingLock.withLock { pending = .success([]) // no stderr in this case } @@ -776,8 +831,10 @@ package final class AsyncProcess { self.state = .readingOutput(sync: group) } + logProcessIODebug("[\(self.processTrackingID)] I/O: Starting I/O threads") stdoutThread.start() stderrThread?.start() + logProcessIODebug("[\(self.processTrackingID)] I/O: I/O threads started, waiting for completion") } return stdinStream @@ -832,11 +889,18 @@ package final class AsyncProcess { completion(.failure(error)) case .readingOutput(let sync): self.stateLock.unlock() + logProcessIODebug("[\(self.processTrackingID)] WAIT: Waiting for I/O threads to complete") + sync.notify(queue: self.completionQueue) { self.waitUntilExit(completion) } case .outputReady(let stdoutResult, let stderrResult): defer { self.stateLock.unlock() } + + logProcessIODebug( + "[\(self.processTrackingID)] WAIT: I/O ready, waiting for process exit (PID=\(self.processID))" + ) + // Wait until process finishes execution. #if os(Windows) precondition(self._process != nil, "The process is not yet launched.") @@ -851,11 +915,16 @@ package final class AsyncProcess { result = waitpid(self.processID, &exitStatusCode, 0) } if result == -1 { + logProcessIODebug("[\(self.processTrackingID)] ERROR: waitpid failed with errno=\(errno)") self.state = .failed(SystemError.waitpid(errno)) } let normalExit = !WIFSIGNALED(result) #endif + logProcessIODebug( + "[\(self.processTrackingID)] EXIT: Process exited with status=\(exitStatusCode), normal=\(normalExit)" + ) + // Construct the result. let executionResult = AsyncProcessResult( arguments: arguments,