diff --git a/Sources/Basics/Observability.swift b/Sources/Basics/Observability.swift index 404d42a85c4..24d965e5002 100644 --- a/Sources/Basics/Observability.swift +++ b/Sources/Basics/Observability.swift @@ -56,6 +56,10 @@ public class ObservabilitySystem { func handleDiagnostic(scope: ObservabilityScope, diagnostic: Diagnostic) { self.underlying(scope, diagnostic) } + + func print(message: String) { + self.diagnosticsHandler.print(message: message) + } } public static var NOOP: ObservabilityScope { @@ -128,6 +132,10 @@ public final class ObservabilityScope: DiagnosticsEmitterProtocol, Sendable, Cus return parent?.errorsReportedInAnyScope ?? false } + public func print(message: String) { + self.diagnosticsHandler.print(message: message) + } + // DiagnosticsEmitterProtocol public func emit(_ diagnostic: Diagnostic) { var diagnostic = diagnostic @@ -150,6 +158,10 @@ public final class ObservabilityScope: DiagnosticsEmitterProtocol, Sendable, Cus self.underlying.handleDiagnostic(scope: scope, diagnostic: diagnostic) } + public func print(message: String) { + self.underlying.print(message: message) + } + var errorsReported: Bool { self._errorsReported.get() ?? false } @@ -160,6 +172,8 @@ public final class ObservabilityScope: DiagnosticsEmitterProtocol, Sendable, Cus public protocol DiagnosticsHandler: Sendable { func handleDiagnostic(scope: ObservabilityScope, diagnostic: Diagnostic) + + func print(message: String) } /// Helper protocol to share default behavior. diff --git a/Sources/CoreCommands/SwiftCommandObservabilityHandler.swift b/Sources/CoreCommands/SwiftCommandObservabilityHandler.swift index aa49fffcc94..ffcbfbbae6a 100644 --- a/Sources/CoreCommands/SwiftCommandObservabilityHandler.swift +++ b/Sources/CoreCommands/SwiftCommandObservabilityHandler.swift @@ -116,6 +116,12 @@ public struct SwiftCommandObservabilityHandler: ObservabilityHandlerProvider { } } + func print(message: String) { + self.queue.async(group: self.sync) { + self.write(message) + } + } + // for raw output reporting func print(_ output: String, verbose: Bool) { self.queue.async(group: self.sync) { diff --git a/Sources/SwiftBuildSupport/SwiftBuildSystem.swift b/Sources/SwiftBuildSupport/SwiftBuildSystem.swift index bf0e98161cf..5598310fcb4 100644 --- a/Sources/SwiftBuildSupport/SwiftBuildSystem.swift +++ b/Sources/SwiftBuildSupport/SwiftBuildSystem.swift @@ -174,6 +174,359 @@ private final class PlanningOperationDelegate: SWBPlanningOperationDelegate, Sen } } +/// Convenience extensions to extract taskID and targetID from the LocationContext. +extension SwiftBuildMessage.LocationContext { + var taskID: Int? { + switch self { + case .task(let id, _), .globalTask(let id): + return id + case .target, .global: + return nil + } + } + + var targetID: Int? { + switch self { + case .task(_, let id), .target(let id): + return id + case .global, .globalTask: + return nil + } + } +} + +/// Handler for SwiftBuildMessage events sent by the SWBBuildOperation. +public final class SwiftBuildSystemMessageHandler { + private let observabilityScope: ObservabilityScope + private let logLevel: Basics.Diagnostic.Severity + private var buildState: BuildState = .init() + private var tasksEmitted: Set = [] + + let progressAnimation: ProgressAnimationProtocol + var serializedDiagnosticPathsByTargetName: [String: [Basics.AbsolutePath]] = [:] + + private var unprocessedDiagnostics: [SwiftBuildMessage.DiagnosticInfo] = [] + + public init( + observabilityScope: ObservabilityScope, + outputStream: OutputByteStream, + logLevel: Basics.Diagnostic.Severity + ) + { + self.observabilityScope = observabilityScope + self.logLevel = logLevel + self.progressAnimation = ProgressAnimation.ninja( + stream: outputStream, + verbose: self.logLevel.isVerbose + ) + } + + struct BuildState { + private var targetsByID: [Int: SwiftBuild.SwiftBuildMessage.TargetStartedInfo] = [:] + private var activeTasks: [Int: SwiftBuild.SwiftBuildMessage.TaskStartedInfo] = [:] + private var taskDataBuffer: TaskDataBuffer = [:] + private var taskIDToSignature: [Int: String] = [:] + var collectedBacktraceFrames = SWBBuildOperationCollectedBacktraceFrames() + + struct TaskDataBuffer: ExpressibleByDictionaryLiteral { + typealias Key = String + typealias Value = Data + + private var taskSignatureBuffer: [Key: Value] = [:] + private var taskIDBuffer: [Int: Data] = [:] + private var targetIDBuffer: [Int: Data] = [:] + private var globalBuffer: Data = Data() + + subscript(key: String) -> Value? { + self.taskSignatureBuffer[key] + } + + subscript(key: String, default defaultValue: Value) -> Value { + get { self.taskSignatureBuffer[key] ?? defaultValue } + set { self.taskSignatureBuffer[key] = newValue } + } + + subscript(key: SwiftBuildMessage.LocationContext, default defaultValue: Value) -> Value { + get { + // Check each ID kind and try to fetch the associated buffer. + // If unable to get a non-nil result, then follow through to the + // next check. + if let taskID = key.taskID, + let result = self.taskIDBuffer[taskID] { + return result + } else if let targetID = key.targetID, + let result = self.targetIDBuffer[targetID] { + return result + } else if !self.globalBuffer.isEmpty { + return self.globalBuffer + } else { + return defaultValue + } + } + + set { + if let taskID = key.taskID { + self.taskIDBuffer[taskID] = newValue + if let targetID = key.targetID { + self.targetIDBuffer[targetID] = newValue + } + } else if let targetID = key.targetID { + self.targetIDBuffer[targetID] = newValue + } else { + self.globalBuffer = newValue + } + } + } + + subscript(key: SwiftBuildMessage.LocationContext2) -> Value? { + get { + if let taskSignature = key.taskSignature { + return self.taskSignatureBuffer[taskSignature] + } else if let targetID = key.targetID { + return self.targetIDBuffer[targetID] + } + + return nil + } + + set { + if let taskSignature = key.taskSignature { + self.taskSignatureBuffer[taskSignature] = newValue + } else if let targetID = key.targetID { + self.targetIDBuffer[targetID] = newValue + } + } + } + + subscript(task: SwiftBuildMessage.TaskStartedInfo) -> Value? { + get { + guard let result = self.taskSignatureBuffer[task.taskSignature] else { + // Default to checking targetID and taskID. + if let result = self.taskIDBuffer[task.taskID] { + return result + } else if let targetID = task.targetID, + let result = self.targetIDBuffer[targetID] { + return result + } + + // Return global buffer if none of the above are found. + return self.globalBuffer + } + + return result + } + } + + init(dictionaryLiteral elements: (String, Data)...) { + for (key, value) in elements { + self.taskSignatureBuffer[key] = value + } + } + } + + mutating func started(task: SwiftBuild.SwiftBuildMessage.TaskStartedInfo) throws { + if activeTasks[task.taskID] != nil { + throw Diagnostics.fatalError + } + activeTasks[task.taskID] = task + taskIDToSignature[task.taskID] = task.taskSignature + } + + mutating func completed(task: SwiftBuild.SwiftBuildMessage.TaskCompleteInfo) throws -> SwiftBuild.SwiftBuildMessage.TaskStartedInfo { + guard let task = activeTasks[task.taskID] else { + throw Diagnostics.fatalError + } + return task + } + + mutating func started(target: SwiftBuild.SwiftBuildMessage.TargetStartedInfo) throws { + if targetsByID[target.targetID] != nil { + throw Diagnostics.fatalError + } + targetsByID[target.targetID] = target + } + + func target(for task: SwiftBuild.SwiftBuildMessage.TaskStartedInfo) throws -> SwiftBuild.SwiftBuildMessage.TargetStartedInfo? { + guard let id = task.targetID else { + return nil + } + guard let target = targetsByID[id] else { + throw Diagnostics.fatalError + } + return target + } + + func taskSignature(for id: Int) -> String? { + if let signature = taskIDToSignature[id] { + return signature + } + return nil + } + + mutating func appendToBuffer(_ info: SwiftBuildMessage.OutputInfo) { + // Attempt to key by taskSignature; at times this may not be possible, + // in which case we'd need to fall back to using LocationContext. + guard let taskSignature = info.locationContext2.taskSignature else { + // If we cannot find the task signature from the locationContext2, + // use deprecated locationContext instead to find task signature. + // If this fails to find an associated task signature, track + // relevant IDs from the location context in the task buffer. + if let taskID = info.locationContext.taskID, + let taskSignature = self.taskSignature(for: taskID) { + self.taskDataBuffer[taskSignature, default: .init()].append(info.data) + } + + // TODO bp: extra tracking for taskIDs/targetIDs/possible global buffers + self.taskDataBuffer[info.locationContext, default: .init()].append(info.data) + + return + } + + self.taskDataBuffer[taskSignature, default: .init()].append(info.data) + } + + func dataBuffer(for task: SwiftBuild.SwiftBuildMessage.TaskStartedInfo) -> Data? { + guard let data = taskDataBuffer[task.taskSignature] else { + // Fallback to checking taskID and targetID. + return taskDataBuffer[task] + } + + // todo bp "-fno-color-diagnostics", + + return data + } + } + + private func emitInfoAsDiagnostic(info: SwiftBuildMessage.DiagnosticInfo) { + let fixItsDescription = if info.fixIts.hasContent { + ": " + info.fixIts.map { String(describing: $0) }.joined(separator: ", ") + } else { + "" + } + let message = if let locationDescription = info.location.userDescription { + "\(locationDescription) \(info.message)\(fixItsDescription)" + } else { + "\(info.message)\(fixItsDescription)" + } + let severity: Diagnostic.Severity = switch info.kind { + case .error: .error + case .warning: .warning + case .note: .info + case .remark: .debug + } + self.observabilityScope.emit(severity: severity, message: "\(message)\n") + + for childDiagnostic in info.childDiagnostics { + emitInfoAsDiagnostic(info: childDiagnostic) + } + } + + private func emitDiagnosticCompilerOutput(_ info: SwiftBuildMessage.TaskStartedInfo) { + // Don't redundantly emit tasks. + guard !self.tasksEmitted.contains(info.taskSignature) else { + return + } + // Assure we have a data buffer to decode. + guard let buffer = buildState.dataBuffer(for: info) else { + return + } + + // Decode the buffer to a string + let decodedOutput = String(decoding: buffer, as: UTF8.self) + + // Emit message. + // Note: This is a temporary workaround until we can re-architect + // how we'd like to format and handle diagnostic output. + observabilityScope.print(message: decodedOutput) + + // Record that we've emitted the output for a given task signature. + self.tasksEmitted.insert(info.taskSignature) + } + + func emitEvent(_ message: SwiftBuild.SwiftBuildMessage, _ buildSystem: SwiftBuildSystem) throws { + guard !self.logLevel.isQuiet else { return } + switch message { + case .buildCompleted(let info): + progressAnimation.complete(success: info.result == .ok) + if info.result == .cancelled { + buildSystem.delegate?.buildSystemDidCancel(buildSystem) + } else { + buildSystem.delegate?.buildSystem(buildSystem, didFinishWithResult: info.result == .ok) + } + case .didUpdateProgress(let progressInfo): + var step = Int(progressInfo.percentComplete) + if step < 0 { step = 0 } + let message = if let targetName = progressInfo.targetName { + "\(targetName) \(progressInfo.message)" + } else { + "\(progressInfo.message)" + } + progressAnimation.update(step: step, total: 100, text: message) + buildSystem.delegate?.buildSystem(buildSystem, didUpdateTaskProgress: message) + case .diagnostic(let info): + if info.appendToOutputStream { + emitInfoAsDiagnostic(info: info) + } else { + unprocessedDiagnostics.append(info) + } + case .output(let info): + // Append to buffer-per-task storage + buildState.appendToBuffer(info) + case .taskStarted(let info): + try buildState.started(task: info) + + if let commandLineDisplay = info.commandLineDisplayString { + self.observabilityScope.emit(info: "\(info.executionDescription)\n\(commandLineDisplay)") + } else { + self.observabilityScope.emit(info: "\(info.executionDescription)") + } + + let targetInfo = try buildState.target(for: info) + buildSystem.delegate?.buildSystem(buildSystem, willStartCommand: BuildSystemCommand(info, targetInfo: targetInfo)) + buildSystem.delegate?.buildSystem(buildSystem, didStartCommand: BuildSystemCommand(info, targetInfo: targetInfo)) + case .taskComplete(let info): + let startedInfo = try buildState.completed(task: info) + + // If we've captured the compiler output with formatted diagnostics, emit them. + emitDiagnosticCompilerOutput(startedInfo) + + if info.result != .success { + self.observabilityScope.emit(severity: .error, message: "\(startedInfo.ruleInfo) failed with a nonzero exit code. Command line: \(startedInfo.commandLineDisplayString ?? "")") + } + let targetInfo = try buildState.target(for: startedInfo) + buildSystem.delegate?.buildSystem(buildSystem, didFinishCommand: BuildSystemCommand(startedInfo, targetInfo: targetInfo)) + if let targetName = targetInfo?.targetName { + try serializedDiagnosticPathsByTargetName[targetName, default: []].append(contentsOf: startedInfo.serializedDiagnosticsPaths.compactMap { + try Basics.AbsolutePath(validating: $0.pathString) + }) + } + if buildSystem.enableTaskBacktraces { + if let id = SWBBuildOperationBacktraceFrame.Identifier(taskSignatureData: Data(startedInfo.taskSignature.utf8)), + let backtrace = SWBTaskBacktrace(from: id, collectedFrames: buildState.collectedBacktraceFrames) { + let formattedBacktrace = backtrace.renderTextualRepresentation() + if !formattedBacktrace.isEmpty { + self.observabilityScope.emit(info: "Task backtrace:\n\(formattedBacktrace)") + } + } + } + case .targetStarted(let info): + try buildState.started(target: info) + case .backtraceFrame(let info): + if buildSystem.enableTaskBacktraces { + buildState.collectedBacktraceFrames.add(frame: info) + } + case .planningOperationStarted, .planningOperationCompleted, .reportBuildDescription, .reportPathMap, .preparedForIndex, .buildStarted, .preparationComplete, .targetUpToDate, .targetComplete, .taskUpToDate: + break + case .buildDiagnostic, .targetDiagnostic, .taskDiagnostic: + break // deprecated + case .buildOutput, .targetOutput, .taskOutput: + break // deprecated + @unknown default: + break + } + } +} + public final class SwiftBuildSystem: SPMBuildCore.BuildSystem { private let buildParameters: BuildParameters private let packageGraphLoader: () async throws -> ModulesGraph @@ -233,6 +586,10 @@ public final class SwiftBuildSystem: SPMBuildCore.BuildSystem { public var hasIntegratedAPIDigesterSupport: Bool { true } + public var enableTaskBacktraces: Bool { + self.buildParameters.outputParameters.enableTaskBacktraces + } + public init( buildParameters: BuildParameters, packageGraphLoader: @escaping () async throws -> ModulesGraph, @@ -537,12 +894,12 @@ public final class SwiftBuildSystem: SPMBuildCore.BuildSystem { return try await withService(connectionMode: .inProcessStatic(swiftbuildServiceEntryPoint)) { service in let derivedDataPath = self.buildParameters.dataPath - let progressAnimation = ProgressAnimation.ninja( - stream: self.outputStream, - verbose: self.logLevel.isVerbose + let buildMessageHandler = SwiftBuildSystemMessageHandler( + observabilityScope: self.observabilityScope, + outputStream: self.outputStream, + logLevel: self.logLevel ) - var serializedDiagnosticPathsByTargetName: [String: [Basics.AbsolutePath]] = [:] do { try await withSession(service: service, name: self.buildParameters.pifManifest.pathString, toolchainPath: self.buildParameters.toolchain.toolchainDir, packageManagerResourcesDirectory: self.packageManagerResourcesDirectory) { session, _ in self.outputStream.send("Building for \(self.buildParameters.configuration == .debug ? "debugging" : "production")...\n") @@ -582,148 +939,6 @@ public final class SwiftBuildSystem: SPMBuildCore.BuildSystem { let request = try await self.makeBuildRequest(session: session, configuredTargets: configuredTargets, derivedDataPath: derivedDataPath, symbolGraphOptions: symbolGraphOptions) - struct BuildState { - private var targetsByID: [Int: SwiftBuild.SwiftBuildMessage.TargetStartedInfo] = [:] - private var activeTasks: [Int: SwiftBuild.SwiftBuildMessage.TaskStartedInfo] = [:] - var collectedBacktraceFrames = SWBBuildOperationCollectedBacktraceFrames() - - mutating func started(task: SwiftBuild.SwiftBuildMessage.TaskStartedInfo) throws { - if activeTasks[task.taskID] != nil { - throw Diagnostics.fatalError - } - activeTasks[task.taskID] = task - } - - mutating func completed(task: SwiftBuild.SwiftBuildMessage.TaskCompleteInfo) throws -> SwiftBuild.SwiftBuildMessage.TaskStartedInfo { - guard let task = activeTasks[task.taskID] else { - throw Diagnostics.fatalError - } - return task - } - - mutating func started(target: SwiftBuild.SwiftBuildMessage.TargetStartedInfo) throws { - if targetsByID[target.targetID] != nil { - throw Diagnostics.fatalError - } - targetsByID[target.targetID] = target - } - - mutating func target(for task: SwiftBuild.SwiftBuildMessage.TaskStartedInfo) throws -> SwiftBuild.SwiftBuildMessage.TargetStartedInfo? { - guard let id = task.targetID else { - return nil - } - guard let target = targetsByID[id] else { - throw Diagnostics.fatalError - } - return target - } - } - - func emitEvent(_ message: SwiftBuild.SwiftBuildMessage, buildState: inout BuildState) throws { - guard !self.logLevel.isQuiet else { return } - switch message { - case .buildCompleted(let info): - progressAnimation.complete(success: info.result == .ok) - if info.result == .cancelled { - self.delegate?.buildSystemDidCancel(self) - } else { - self.delegate?.buildSystem(self, didFinishWithResult: info.result == .ok) - } - case .didUpdateProgress(let progressInfo): - var step = Int(progressInfo.percentComplete) - if step < 0 { step = 0 } - let message = if let targetName = progressInfo.targetName { - "\(targetName) \(progressInfo.message)" - } else { - "\(progressInfo.message)" - } - progressAnimation.update(step: step, total: 100, text: message) - self.delegate?.buildSystem(self, didUpdateTaskProgress: message) - case .diagnostic(let info): - func emitInfoAsDiagnostic(info: SwiftBuildMessage.DiagnosticInfo) { - let fixItsDescription = if info.fixIts.hasContent { - ": " + info.fixIts.map { String(describing: $0) }.joined(separator: ", ") - } else { - "" - } - let message = if let locationDescription = info.location.userDescription { - "\(locationDescription) \(info.message)\(fixItsDescription)" - } else { - "\(info.message)\(fixItsDescription)" - } - let severity: Diagnostic.Severity = switch info.kind { - case .error: .error - case .warning: .warning - case .note: .info - case .remark: .debug - } - self.observabilityScope.emit(severity: severity, message: "\(message)\n") - - for childDiagnostic in info.childDiagnostics { - emitInfoAsDiagnostic(info: childDiagnostic) - } - } - - emitInfoAsDiagnostic(info: info) - case .output(let info): - self.observabilityScope.emit(info: "\(String(decoding: info.data, as: UTF8.self))") - case .taskStarted(let info): - try buildState.started(task: info) - - if let commandLineDisplay = info.commandLineDisplayString { - self.observabilityScope.emit(info: "\(info.executionDescription)\n\(commandLineDisplay)") - } else { - self.observabilityScope.emit(info: "\(info.executionDescription)") - } - - if self.logLevel.isVerbose { - if let commandLineDisplay = info.commandLineDisplayString { - self.outputStream.send("\(info.executionDescription)\n\(commandLineDisplay)") - } else { - self.outputStream.send("\(info.executionDescription)") - } - } - let targetInfo = try buildState.target(for: info) - self.delegate?.buildSystem(self, willStartCommand: BuildSystemCommand(info, targetInfo: targetInfo)) - self.delegate?.buildSystem(self, didStartCommand: BuildSystemCommand(info, targetInfo: targetInfo)) - case .taskComplete(let info): - let startedInfo = try buildState.completed(task: info) - if info.result != .success { - self.observabilityScope.emit(severity: .error, message: "\(startedInfo.ruleInfo) failed with a nonzero exit code. Command line: \(startedInfo.commandLineDisplayString ?? "")") - } - let targetInfo = try buildState.target(for: startedInfo) - self.delegate?.buildSystem(self, didFinishCommand: BuildSystemCommand(startedInfo, targetInfo: targetInfo)) - if let targetName = targetInfo?.targetName { - serializedDiagnosticPathsByTargetName[targetName, default: []].append(contentsOf: startedInfo.serializedDiagnosticsPaths.compactMap { - try? Basics.AbsolutePath(validating: $0.pathString) - }) - } - if self.buildParameters.outputParameters.enableTaskBacktraces { - if let id = SWBBuildOperationBacktraceFrame.Identifier(taskSignatureData: Data(startedInfo.taskSignature.utf8)), - let backtrace = SWBTaskBacktrace(from: id, collectedFrames: buildState.collectedBacktraceFrames) { - let formattedBacktrace = backtrace.renderTextualRepresentation() - if !formattedBacktrace.isEmpty { - self.observabilityScope.emit(info: "Task backtrace:\n\(formattedBacktrace)") - } - } - } - case .targetStarted(let info): - try buildState.started(target: info) - case .backtraceFrame(let info): - if self.buildParameters.outputParameters.enableTaskBacktraces { - buildState.collectedBacktraceFrames.add(frame: info) - } - case .planningOperationStarted, .planningOperationCompleted, .reportBuildDescription, .reportPathMap, .preparedForIndex, .buildStarted, .preparationComplete, .targetUpToDate, .targetComplete, .taskUpToDate: - break - case .buildDiagnostic, .targetDiagnostic, .taskDiagnostic: - break // deprecated - case .buildOutput, .targetOutput, .taskOutput: - break // deprecated - @unknown default: - break - } - } - let operation = try await session.createBuildOperation( request: request, delegate: PlanningOperationDelegate(), @@ -731,7 +946,6 @@ public final class SwiftBuildSystem: SPMBuildCore.BuildSystem { ) var buildDescriptionID: SWBBuildDescriptionID? = nil - var buildState = BuildState() for try await event in try await operation.start() { if case .reportBuildDescription(let info) = event { if buildDescriptionID != nil { @@ -739,7 +953,7 @@ public final class SwiftBuildSystem: SPMBuildCore.BuildSystem { } buildDescriptionID = SWBBuildDescriptionID(info.buildDescriptionID) } - try emitEvent(event, buildState: &buildState) + try buildMessageHandler.emitEvent(event, self) } await operation.waitForCompletion() @@ -747,8 +961,8 @@ public final class SwiftBuildSystem: SPMBuildCore.BuildSystem { switch operation.state { case .succeeded: guard !self.logLevel.isQuiet else { return } - progressAnimation.update(step: 100, total: 100, text: "") - progressAnimation.complete(success: true) + buildMessageHandler.progressAnimation.update(step: 100, total: 100, text: "") + buildMessageHandler.progressAnimation.complete(success: true) let duration = ContinuousClock.Instant.now - buildStartTime let formattedDuration = duration.formatted(.units(allowed: [.seconds], fractionalPart: .show(length: 2, rounded: .up))) self.outputStream.send("Build complete! (\(formattedDuration))\n") @@ -815,7 +1029,7 @@ public final class SwiftBuildSystem: SPMBuildCore.BuildSystem { } return BuildResult( - serializedDiagnosticPathsByTargetName: .success(serializedDiagnosticPathsByTargetName), + serializedDiagnosticPathsByTargetName: .success(buildMessageHandler.serializedDiagnosticPathsByTargetName), symbolGraph: SymbolGraphResult( outputLocationForTarget: { target, buildParameters in return ["\(buildParameters.triple.archName)", "\(target).symbolgraphs"]