diff --git a/Makefile b/Makefile index 03080c4f2..9c1215f55 100644 --- a/Makefile +++ b/Makefile @@ -33,10 +33,9 @@ DSYM_PATH := bin/$(BUILD_CONFIGURATION)/bundle/container-dSYM.zip CODESIGN_OPTS ?= --force --sign - --timestamp=none # Conditionally use a temporary data directory for integration tests -ifeq ($(strip $(APP_ROOT)),) - SYSTEM_START_OPTS := -else - SYSTEM_START_OPTS := --app-root "$(strip $(APP_ROOT))" +SYSTEM_START_OPTS := +ifneq ($(strip $(APP_ROOT)),) + SYSTEM_START_OPTS += --app-root "$(strip $(APP_ROOT))" endif MACOS_VERSION := $(shell sw_vers -productVersion) @@ -77,7 +76,8 @@ release: all .PHONY: init-block init-block: - @scripts/install-init.sh + @echo Building initfs if containerization is in edit mode + @scripts/install-init.sh $(SYSTEM_START_OPTS) .PHONY: install install: installer-pkg @@ -144,15 +144,17 @@ test: .PHONY: install-kernel install-kernel: + @echo Stopping system before installing kernel @bin/container system stop || true - @bin/container system start --timeout 60 --enable-kernel-install $(SYSTEM_START_OPTS) + @echo Starting system to install kernel + @bin/container --debug system start --timeout 60 --enable-kernel-install $(SYSTEM_START_OPTS) .PHONY: coverage coverage: init-block - @echo Ensuring apiserver stopped before the CLI integration tests... + @echo Ensuring apiserver stopped before the coverage analysis @bin/container system stop && sleep 3 && scripts/ensure-container-stopped.sh - @bin/container system start $(SYSTEM_START_OPTS) && \ - echo "Starting unit tests" && \ + @bin/container --debug system start $(SYSTEM_START_OPTS) && \ + echo "Starting coverage analysis" && \ { \ exit_code=0; \ $(SWIFT) test --no-parallel --enable-code-coverage -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) || exit_code=1 ; \ @@ -176,28 +178,28 @@ integration: init-block @echo Ensuring apiserver stopped before the CLI integration tests... @bin/container system stop && sleep 3 && scripts/ensure-container-stopped.sh @echo Running the integration tests... - @bin/container system start --timeout 60 $(SYSTEM_START_OPTS) && \ + @bin/container --debug system start --timeout 60 $(SYSTEM_START_OPTS) && \ echo "Starting CLI integration tests" && \ { \ exit_code=0; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLINetwork || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunLifecycle || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIExecCommand || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLICreateCommand || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand1 || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand2 || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand3 || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIPruneCommand || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRegistry || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIStatsCommand || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIImagesCommand || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunBase || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunInitImage || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIBuildBase || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIVolumes || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIKernelSet || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIAnonymousVolumes || exit_code=1 ; \ - $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLINoParallelCases || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLINetwork || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunLifecycle || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIExecCommand || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLICreateCommand || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand1 || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand2 || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand3 || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIPruneCommand || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRegistry || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIStatsCommand || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIImagesCommand || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunBase || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunInitImage || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIBuildBase || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIVolumes || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIKernelSet || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIAnonymousVolumes || exit_code=1 ; \ + $(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLINoParallelCases || exit_code=1 ; \ echo Ensuring apiserver stopped after the CLI integration tests ; \ scripts/ensure-container-stopped.sh ; \ exit $${exit_code} ; \ diff --git a/Package.resolved b/Package.resolved index 615c17e87..240da9127 100644 --- a/Package.resolved +++ b/Package.resolved @@ -1,5 +1,5 @@ { - "originHash" : "d795ef49c10b5084c12106f45c7da08aaf2a3d9355228499729eeb55501ee0ed", + "originHash" : "a56ef20b6ccea8fbcb75f115f2e59e1cc053f290e373dc29cafdd494368027c1", "pins" : [ { "identity" : "async-http-client", @@ -15,8 +15,8 @@ "kind" : "remoteSourceControl", "location" : "https://github.com/apple/containerization.git", "state" : { - "revision" : "3f4eee7d2a4ae0d9587416f199e0b2edcf263a6f", - "version" : "0.25.0" + "revision" : "c45e36e740036406cccbed8031b57049cf458a04", + "version" : "0.26.1" } }, { diff --git a/Package.swift b/Package.swift index 8bbfe929d..7b4b792cb 100644 --- a/Package.swift +++ b/Package.swift @@ -23,7 +23,7 @@ import PackageDescription let releaseVersion = ProcessInfo.processInfo.environment["RELEASE_VERSION"] ?? "0.0.0" let gitCommit = ProcessInfo.processInfo.environment["GIT_COMMIT"] ?? "unspecified" let builderShimVersion = "0.8.0" -let scVersion = "0.25.0" +let scVersion = "0.26.1" let package = Package( name: "container", @@ -98,6 +98,7 @@ let package = Package( "ContainerPlugin", "ContainerResource", "ContainerVersion", + "ContainerXPC", "TerminalProgress", ], path: "Sources/ContainerCommands" diff --git a/Sources/ContainerCommands/Container/ContainerPrune.swift b/Sources/ContainerCommands/Container/ContainerPrune.swift index 9fcd76eea..59953974f 100644 --- a/Sources/ContainerCommands/Container/ContainerPrune.swift +++ b/Sources/ContainerCommands/Container/ContainerPrune.swift @@ -45,7 +45,12 @@ extension Application { try await client.delete(id: container.id) prunedContainerIds.append(container.id) } catch { - log.error("Failed to prune container \(container.id): \(error)") + log.error( + "failed to prune container", + metadata: [ + "id": "\(container.id)", + "error": "\(error)", + ]) } } diff --git a/Sources/ContainerCommands/Image/ImagePrune.swift b/Sources/ContainerCommands/Image/ImagePrune.swift index 12fa02134..e3eabf88a 100644 --- a/Sources/ContainerCommands/Image/ImagePrune.swift +++ b/Sources/ContainerCommands/Image/ImagePrune.swift @@ -61,7 +61,12 @@ extension Application { try await ClientImage.delete(reference: image.reference, garbageCollect: false) prunedImages.append(image.reference) } catch { - log.error("Failed to prune image \(image.reference): \(error)") + log.error( + "failed to prune image", + metadata: [ + "ref": "\(image.reference)", + "error": "\(error)", + ]) } } diff --git a/Sources/ContainerCommands/Network/NetworkPrune.swift b/Sources/ContainerCommands/Network/NetworkPrune.swift index 93875ed28..38e9e6b71 100644 --- a/Sources/ContainerCommands/Network/NetworkPrune.swift +++ b/Sources/ContainerCommands/Network/NetworkPrune.swift @@ -55,7 +55,7 @@ extension Application.NetworkCommand { // Note: This failure may occur due to a race condition between the network/ // container collection above and a container run command that attaches to a // network listed in the networksToPrune collection. - log.error("Failed to prune network \(network.id): \(error)") + log.error("failed to prune network", metadata: ["id": "\(network.id)", "error": "\(error)"]) } } diff --git a/Sources/ContainerCommands/System/SystemLogs.swift b/Sources/ContainerCommands/System/SystemLogs.swift index 8bd6cfa48..b00008e9b 100644 --- a/Sources/ContainerCommands/System/SystemLogs.swift +++ b/Sources/ContainerCommands/System/SystemLogs.swift @@ -58,7 +58,7 @@ extension Application { do { var args = ["log"] args.append(self.follow ? "stream" : "show") - args.append(contentsOf: ["--info", "--debug"]) + args.append(contentsOf: ["--info", logOptions.debug ? "--debug" : nil].compactMap { $0 }) if !self.follow { args.append(contentsOf: ["--last", last]) } diff --git a/Sources/ContainerCommands/System/SystemStart.swift b/Sources/ContainerCommands/System/SystemStart.swift index ec33fcdf9..004eba4a5 100644 --- a/Sources/ContainerCommands/System/SystemStart.swift +++ b/Sources/ContainerCommands/System/SystemStart.swift @@ -18,6 +18,7 @@ import ArgumentParser import ContainerAPIClient import ContainerPersistence import ContainerPlugin +import ContainerXPC import ContainerizationError import Foundation import TerminalProgress @@ -48,9 +49,15 @@ extension Application { var kernelInstall: Bool? @Option( - name: .long, - help: "Number of seconds to wait for API service to become responsive") - var timeout: Double = 10.0 + help: "Number of seconds to wait for API service to become responsive", + transform: { + guard let timeoutSeconds = Double($0) else { + throw ValidationError("Invalid timeout value: \($0)") + } + return .seconds(timeoutSeconds) + } + ) + var timeout: Duration = XPCClient.xpcRegistrationTimeout @OptionGroup public var logOptions: Flags.Logging @@ -98,7 +105,7 @@ extension Application { // Now ping our friendly daemon. Fail if we don't get a response. do { print("Verifying apiserver is running...") - _ = try await ClientHealthCheck.ping(timeout: .seconds(timeout)) + _ = try await ClientHealthCheck.ping(timeout: timeout) } catch { throw ContainerizationError( .internalError, @@ -124,7 +131,7 @@ extension Application { do { try await pullCommand.run() } catch { - log.error("failed to install base container filesystem: \(error)") + log.error("failed to install base container filesystem", metadata: ["error": "\(error)"]) } } diff --git a/Sources/ContainerCommands/Volume/VolumePrune.swift b/Sources/ContainerCommands/Volume/VolumePrune.swift index 7d65692a0..4a685e659 100644 --- a/Sources/ContainerCommands/Volume/VolumePrune.swift +++ b/Sources/ContainerCommands/Volume/VolumePrune.swift @@ -57,7 +57,12 @@ extension Application.VolumeCommand { try await ClientVolume.delete(name: volume.name) prunedVolumes.append(volume.name) } catch { - log.error("Failed to prune volume \(volume.name): \(error)") + log.error( + "failed to prune volume", + metadata: [ + "id": "\(volume.name)", + "error": "\(error)", + ]) } } diff --git a/Sources/ContainerPlugin/PluginLoader.swift b/Sources/ContainerPlugin/PluginLoader.swift index 90693d5f0..0cab3f496 100644 --- a/Sources/ContainerPlugin/PluginLoader.swift +++ b/Sources/ContainerPlugin/PluginLoader.swift @@ -206,7 +206,8 @@ extension PluginLoader { plugin: Plugin, pluginStateRoot: URL? = nil, args: [String]? = nil, - instanceId: String? = nil + instanceId: String? = nil, + debug: Bool = false, ) throws { // We only care about loading plugins that have a service // to expose; otherwise, they may just be CLI commands. @@ -223,9 +224,10 @@ extension PluginLoader { env[ApplicationRoot.environmentName] = appRoot.path(percentEncoded: false) env[InstallRoot.environmentName] = installRoot.path(percentEncoded: false) + let processedArgs = (args ?? ["start"]) + (debug ? ["--debug"] : []) let plist = LaunchPlist( label: id, - arguments: [plugin.binaryURL.path] + (args ?? ["start"]) + serviceConfig.defaultArguments, + arguments: [plugin.binaryURL.path] + processedArgs + serviceConfig.defaultArguments, environment: env, limitLoadToSessionType: [.Aqua, .Background, .System], runAtLoad: serviceConfig.runAtLoad, diff --git a/Sources/ContainerXPC/XPCClient.swift b/Sources/ContainerXPC/XPCClient.swift index 9fd1891ce..fee917f9a 100644 --- a/Sources/ContainerXPC/XPCClient.swift +++ b/Sources/ContainerXPC/XPCClient.swift @@ -19,6 +19,13 @@ import ContainerizationError import Foundation public final class XPCClient: Sendable { + /// The maximum amount of time to wait for a request to a recently + /// registered XPC service. Once a service has launched, XPC + /// requests only have milliseconds of overhead, but in some instances, + /// macOS can take 5 seconds (or considerably longer) to launch a + /// service after it has been registered. + public static let xpcRegistrationTimeout: Duration = .seconds(60) + private nonisolated(unsafe) let connection: xpc_connection_t private let q: DispatchQueue? private let service: String diff --git a/Sources/ContainerXPC/XPCServer.swift b/Sources/ContainerXPC/XPCServer.swift index 3dd6b557a..eb8c0805a 100644 --- a/Sources/ContainerXPC/XPCServer.swift +++ b/Sources/ContainerXPC/XPCServer.swift @@ -117,7 +117,11 @@ public struct XPCServer: Sendable { // a final XPC_ERROR_CONNECTION_INVALID message. // We can ignore this if we know we have already handled // the request. - self.log.error("xpc client handler connection error \(object.errorDescription ?? "no description")") + self.log.error( + "xpc client handler connection error", + metadata: [ + "error": "\(object.errorDescription ?? "no description")" + ]) } default: fatalError("unhandled xpc object type: \(xpc_get_type(object))") @@ -195,14 +199,14 @@ public struct XPCServer: Sendable { let response = try await handler(message) xpc_connection_send_message(connection, response.underlying) } catch let error as ContainerizationError { - log.error("handler for \(route) threw error \(error)") + log.error("route handler threw an error", metadata: ["route": "\(route)", "error": "\(error)"]) Self.replyWithError( connection: connection, object: object, err: error ) } catch { - log.error("handler for \(route) threw error \(error)") + log.error("route handler threw an error", metadata: ["route": "\(route)", "error": "\(error)"]) let message = XPCMessage(object: object) let reply = message.reply() diff --git a/Sources/Helpers/APIServer/APIServer+Start.swift b/Sources/Helpers/APIServer/APIServer+Start.swift index 53175b91c..31f476bdd 100644 --- a/Sources/Helpers/APIServer/APIServer+Start.swift +++ b/Sources/Helpers/APIServer/APIServer+Start.swift @@ -46,9 +46,9 @@ extension APIServer { func run() async throws { let commandName = Self.configuration.commandName ?? "container-apiserver" let log = APIServer.setupLogger(debug: debug) - log.info("starting \(commandName)") + log.info("starting helper", metadata: ["name": "\(commandName)"]) defer { - log.info("stopping \(commandName)") + log.info("stopping helper", metadata: ["name": "\(commandName)"]) } do { @@ -56,12 +56,12 @@ extension APIServer { var routes = [XPCRoute: XPCServer.RouteHandler]() let pluginLoader = try initializePluginLoader(log: log) try await initializePlugins(pluginLoader: pluginLoader, log: log, routes: &routes) - let containersService = try initializeContainerService( + let containersService = try initializeContainersService( pluginLoader: pluginLoader, log: log, routes: &routes ) - let networkService = try await initializeNetworkService( + let networkService = try await initializeNetworksService( pluginLoader: pluginLoader, containersService: containersService, log: log, @@ -131,7 +131,7 @@ extension APIServer { */ } } catch { - log.error("\(commandName) failed", metadata: ["error": "\(error)"]) + log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"]) APIServer.exit(withError: error) } } @@ -222,13 +222,14 @@ extension APIServer { routes[XPCRoute.getDefaultKernel] = harness.getDefaultKernel } - private func initializeContainerService(pluginLoader: PluginLoader, log: Logger, routes: inout [XPCRoute: XPCServer.RouteHandler]) throws -> ContainersService { - log.info("initializing container service") + private func initializeContainersService(pluginLoader: PluginLoader, log: Logger, routes: inout [XPCRoute: XPCServer.RouteHandler]) throws -> ContainersService { + log.info("initializing containers service") let service = try ContainersService( appRoot: appRoot, pluginLoader: pluginLoader, - log: log + log: log, + debugHelpers: debug ) let harness = ContainersHarness(service: service, log: log) @@ -250,20 +251,21 @@ extension APIServer { return service } - private func initializeNetworkService( + private func initializeNetworksService( pluginLoader: PluginLoader, containersService: ContainersService, log: Logger, routes: inout [XPCRoute: XPCServer.RouteHandler] ) async throws -> NetworksService { - log.info("initializing network service") + log.info("initializing networks service") let resourceRoot = appRoot.appendingPathComponent("networks") let service = try await NetworksService( pluginLoader: pluginLoader, resourceRoot: resourceRoot, containersService: containersService, - log: log + log: log, + debugHelpers: debug ) let defaultNetwork = try await service.list() diff --git a/Sources/Helpers/APIServer/DirectoryWatcher.swift b/Sources/Helpers/APIServer/DirectoryWatcher.swift index 31693221b..78f75ea79 100644 --- a/Sources/Helpers/APIServer/DirectoryWatcher.swift +++ b/Sources/Helpers/APIServer/DirectoryWatcher.swift @@ -44,7 +44,7 @@ public class DirectoryWatcher { throw ContainerizationError(.invalidState, message: "failed to start watching on \(directoryURL.path)") } - log.info("starting directory watcher for \(directoryURL.path)") + log.info("starting directory watcher", metadata: ["path": "\(directoryURL.path)"]) let descriptor = open(directoryURL.path, O_EVTONLY) diff --git a/Sources/Helpers/Images/ImagesHelper.swift b/Sources/Helpers/Images/ImagesHelper.swift index c3d98e187..a817d9017 100644 --- a/Sources/Helpers/Images/ImagesHelper.swift +++ b/Sources/Helpers/Images/ImagesHelper.swift @@ -59,10 +59,11 @@ extension ImagesHelper { func run() async throws { let commandName = ImagesHelper._commandName let log = setupLogger() - log.info("starting \(commandName)") + log.info("starting helper", metadata: ["name": "\(commandName)"]) defer { - log.info("stopping \(commandName)") + log.info("stopping helper", metadata: ["name": "\(commandName)"]) } + do { log.info("configuring XPC server") var routes = [String: XPCServer.RouteHandler]() @@ -76,7 +77,7 @@ extension ImagesHelper { log.info("starting XPC server") try await xpc.listen() } catch { - log.error("\(commandName) failed", metadata: ["error": "\(error)"]) + log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"]) ImagesHelper.exit(withError: error) } } diff --git a/Sources/Helpers/NetworkVmnet/NetworkVmnetHelper+Start.swift b/Sources/Helpers/NetworkVmnet/NetworkVmnetHelper+Start.swift index e1aa3d62a..71b9e6817 100644 --- a/Sources/Helpers/NetworkVmnet/NetworkVmnetHelper+Start.swift +++ b/Sources/Helpers/NetworkVmnet/NetworkVmnetHelper+Start.swift @@ -67,9 +67,9 @@ extension NetworkVmnetHelper { func run() async throws { let commandName = NetworkVmnetHelper._commandName let log = setupLogger(id: id, debug: debug) - log.info("starting \(commandName)") + log.info("starting helper", metadata: ["name": "\(commandName)"]) defer { - log.info("stopping \(commandName)") + log.info("stopping helper", metadata: ["name": "\(commandName)"]) } do { @@ -110,7 +110,7 @@ extension NetworkVmnetHelper { log.info("starting XPC server") try await xpc.listen() } catch { - log.error("\(commandName) failed", metadata: ["error": "\(error)"]) + log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"]) NetworkVmnetHelper.exit(withError: error) } } diff --git a/Sources/Helpers/RuntimeLinux/RuntimeLinuxHelper+Start.swift b/Sources/Helpers/RuntimeLinux/RuntimeLinuxHelper+Start.swift index 3dc331527..1f45e94aa 100644 --- a/Sources/Helpers/RuntimeLinux/RuntimeLinuxHelper+Start.swift +++ b/Sources/Helpers/RuntimeLinux/RuntimeLinuxHelper+Start.swift @@ -47,12 +47,11 @@ extension RuntimeLinuxHelper { } func run() async throws { - let commandName = Self._commandName + let commandName = RuntimeLinuxHelper._commandName let log = RuntimeLinuxHelper.setupLogger(debug: debug, metadata: ["uuid": "\(uuid)"]) - - log.info("starting \(commandName)") + log.info("starting helper", metadata: ["name": "\(commandName)"]) defer { - log.info("stopping \(commandName)") + log.info("stopping helper", metadata: ["name": "\(commandName)"]) } let eventLoopGroup = MultiThreadedEventLoopGroup(numberOfThreads: System.coreCount) @@ -118,7 +117,7 @@ extension RuntimeLinuxHelper { _ = try await group.next() } } catch { - log.error("\(commandName) failed", metadata: ["error": "\(error)"]) + log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"]) try? await eventLoopGroup.shutdownGracefully() RuntimeLinuxHelper.Start.exit(withError: error) } diff --git a/Sources/Services/ContainerAPIService/Client/ClientHealthCheck.swift b/Sources/Services/ContainerAPIService/Client/ClientHealthCheck.swift index f20445009..ac59d3d90 100644 --- a/Sources/Services/ContainerAPIService/Client/ClientHealthCheck.swift +++ b/Sources/Services/ContainerAPIService/Client/ClientHealthCheck.swift @@ -27,7 +27,7 @@ extension ClientHealthCheck { XPCClient(service: serviceIdentifier) } - public static func ping(timeout: Duration? = .seconds(5)) async throws -> SystemHealth { + public static func ping(timeout: Duration? = XPCClient.xpcRegistrationTimeout) async throws -> SystemHealth { let client = Self.newClient() let request = XPCMessage(route: .ping) let reply = try await client.send(request, responseTimeout: timeout) diff --git a/Sources/Services/ContainerAPIService/Client/ClientNetwork.swift b/Sources/Services/ContainerAPIService/Client/ClientNetwork.swift index 3d37a69cd..ef7014461 100644 --- a/Sources/Services/ContainerAPIService/Client/ClientNetwork.swift +++ b/Sources/Services/ContainerAPIService/Client/ClientNetwork.swift @@ -36,7 +36,7 @@ extension ClientNetwork { private static func xpcSend( client: XPCClient, message: XPCMessage, - timeout: Duration? = .seconds(15) + timeout: Duration? = XPCClient.xpcRegistrationTimeout ) async throws -> XPCMessage { try await client.send(message, responseTimeout: timeout) } diff --git a/Sources/Services/ContainerAPIService/Client/Constants.swift b/Sources/Services/ContainerAPIService/Client/Constants.swift index 2fa2404c4..c5ab8fe63 100644 --- a/Sources/Services/ContainerAPIService/Client/Constants.swift +++ b/Sources/Services/ContainerAPIService/Client/Constants.swift @@ -14,6 +14,8 @@ // limitations under the License. //===----------------------------------------------------------------------===// +/// Global constants for the container API clients. public enum Constants { + /// The keychain ID to use for registry credentials. public static let keychainID = "com.apple.container.registry" } diff --git a/Sources/Services/ContainerAPIService/Client/ContainerClient.swift b/Sources/Services/ContainerAPIService/Client/ContainerClient.swift index 99d145bca..6b8ad2266 100644 --- a/Sources/Services/ContainerAPIService/Client/ContainerClient.swift +++ b/Sources/Services/ContainerAPIService/Client/ContainerClient.swift @@ -39,7 +39,7 @@ public struct ContainerClient: Sendable { @discardableResult private func xpcSend( message: XPCMessage, - timeout: Duration? = .seconds(15) + timeout: Duration? = XPCClient.xpcRegistrationTimeout ) async throws -> XPCMessage { try await xpcClient.send(message, responseTimeout: timeout) } diff --git a/Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift b/Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift index eb48d41a0..83ece08d9 100644 --- a/Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift +++ b/Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift @@ -50,24 +50,32 @@ public actor ContainersService { private static let launchdDomainString = try! ServiceManager.getDomainString() private let log: Logger + private let debugHelpers: Bool private let containerRoot: URL private let pluginLoader: PluginLoader private let runtimePlugins: [Plugin] private let exitMonitor: ExitMonitor - private let lock = AsyncLock() + private let lock: AsyncLock private var containers: [String: ContainerState] // FIXME: Find a better mechanism for services running on the APIServer to work with each other private weak var networksService: NetworksService? - public init(appRoot: URL, pluginLoader: PluginLoader, log: Logger) throws { + public init( + appRoot: URL, + pluginLoader: PluginLoader, + log: Logger, + debugHelpers: Bool = false + ) throws { let containerRoot = appRoot.appendingPathComponent("containers") try FileManager.default.createDirectory(at: containerRoot, withIntermediateDirectories: true) self.exitMonitor = ExitMonitor(log: log) + self.lock = AsyncLock(log: log) self.containerRoot = containerRoot self.pluginLoader = pluginLoader self.log = log + self.debugHelpers = debugHelpers self.runtimePlugins = pluginLoader.findPlugins().filter { $0.hasType(.runtime) } self.containers = try Self.loadAtBoot(root: containerRoot, loader: pluginLoader, log: log) } @@ -109,7 +117,7 @@ public actor ContainersService { } } catch { try? FileManager.default.removeItem(at: dir) - log.warning("failed to load container at \(dir.path): \(error)") + log.warning("failed to load container", metadata: ["path": "\(dir.path)", "error": "\(error)"]) } } return results @@ -117,7 +125,20 @@ public actor ContainersService { /// List containers matching the given filters. public func list(filters: ContainerListFilters = .all) async throws -> [ContainerSnapshot] { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)" + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)" + ] + ) + } return self.containers.values.compactMap { state -> ContainerSnapshot? in let snapshot = state.snapshot @@ -146,8 +167,11 @@ public actor ContainersService { /// Execute an operation with the current container list while maintaining atomicity /// This prevents race conditions where containers are created during the operation - public func withContainerList(_ operation: @Sendable @escaping ([ContainerSnapshot]) async throws -> T) async throws -> T { - try await lock.withLock { context in + public func withContainerList( + logMetadata: Logger.Metadata? = nil, + _ operation: @Sendable @escaping ([ContainerSnapshot]) async throws -> T + ) async throws -> T { + try await lock.withLock(logMetadata: logMetadata) { context in let snapshots = await self.containers.values.map { $0.snapshot } return try await operation(snapshots) } @@ -156,7 +180,7 @@ public actor ContainersService { /// Calculate disk usage for containers /// - Returns: Tuple of (total count, active count, total size, reclaimable size) public func calculateDiskUsage() async -> (Int, Int, UInt64, UInt64) { - await lock.withLock { _ in + await lock.withLock(logMetadata: ["acquirer": "\(#function)"]) { _ in var totalSize: UInt64 = 0 var reclaimableSize: UInt64 = 0 var activeCount = 0 @@ -181,7 +205,7 @@ public actor ContainersService { /// Get set of image references used by containers (for disk usage calculation) /// - Returns: Set of image references currently in use public func getActiveImageReferences() async -> Set { - await lock.withLock { _ in + await lock.withLock(logMetadata: ["acquirer": "\(#function)"]) { _ in var imageRefs = Set() for (_, state) in await self.containers { imageRefs.insert(state.snapshot.configuration.image.reference) @@ -225,9 +249,24 @@ public actor ContainersService { /// Create a new container from the provided id and configuration. public func create(configuration: ContainerConfiguration, kernel: Kernel, options: ContainerCreateOptions, initImage: String? = nil) async throws { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(configuration.id)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(configuration.id)", + ] + ) + } - try await self.lock.withLock { context in + try await self.lock.withLock(logMetadata: ["acquirer": "\(#function)", "id": "\(configuration.id)"]) { context in guard await self.containers[configuration.id] == nil else { throw ContainerizationError( .exists, @@ -282,13 +321,31 @@ public actor ContainersService { let systemPlatform = kernel.platform // Fetch init image (custom or default) - self.log.info("Using init image: \(initImage ?? ClientImage.initImageRef)") + self.log.debug( + "ContainersService: get init block", + metadata: [ + "id": "\(configuration.id)" + ] + ) let initFilesystem = try await self.getInitBlock(for: systemPlatform.ociPlatform(), imageRef: initImage) do { + self.log.debug( + "create snapshot", + metadata: [ + "id": "\(configuration.id)", + "ref": "\(configuration.image.reference)", + ]) let containerImage = ClientImage(description: configuration.image) let imageFs = try await containerImage.getCreateSnapshot(platform: configuration.platform) + self.log.debug( + "configure runtime", + metadata: [ + "id": "\(configuration.id)", + "kernel": "\(kernel.path)", + "initfs": "\(initImage ?? ClientImage.initImageRef)", + ]) let runtimeConfig = RuntimeConfiguration( path: path, initialFilesystem: initFilesystem, @@ -315,8 +372,24 @@ public actor ContainersService { /// Bootstrap the init process of the container. public func bootstrap(id: String, stdio: [FileHandle?]) async throws { - self.log.debug("\(#function)") - try await self.lock.withLock { context in + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } + + try await self.lock.withLock(logMetadata: ["acquirer": "\(#function)", "id": "\(id)"]) { context in var state = try await self.getContainerState(id: id, context: context) // We've already bootstrapped this container. Ideally we should be able to @@ -347,7 +420,8 @@ public actor ContainersService { plugin: self.runtimePlugins.first { $0.name == config.runtimeHandler }!, loader: self.pluginLoader, configuration: config, - path: path + path: path, + debug: self.debugHelpers ) let runtime = state.snapshot.configuration.runtimeHandler @@ -370,7 +444,13 @@ public actor ContainersService { do { try await self.networksService?.deallocate(attachment: allocatedAttach.attachment) } catch { - self.log.error("failed to deallocate network attachment in \(id) for \(allocatedAttach.attachment.network): \(error)") + self.log.error( + "failed to deallocate network attachment", + metadata: [ + "id": "\(id)", + "network": "\(allocatedAttach.attachment.network)", + "error": "\(error)", + ]) } } @@ -381,7 +461,6 @@ public actor ContainersService { await self.exitMonitor.stopTracking(id: id) try? ServiceManager.deregister(fullServiceLabel: label) - throw error } } @@ -394,7 +473,24 @@ public actor ContainersService { config: ProcessConfiguration, stdio: [FileHandle?] ) async throws { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + "command": "\(config.arguments.isEmpty ? "" : config.arguments[0])", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } let state = try self._getContainerState(id: id) let client = try state.getClient() @@ -409,9 +505,26 @@ public actor ContainersService { /// createProcess, or the init process of the container which requires /// id == processID. public func startProcess(id: String, processID: String) async throws { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + ] + ) + } - try await self.lock.withLock { context in + try await self.lock.withLock(logMetadata: ["acquirer": "\(#function)", "id": "\(id)", "processId": "\(processID)"]) { context in var state = try await self.getContainerState(id: id, context: context) let isInit = Self.isInitProcess(id: id, processID: processID) @@ -429,9 +542,9 @@ public actor ContainersService { do { let log = self.log let waitFunc: ExitMonitor.WaitHandler = { - log.info("registering container \(id) with exit monitor") + log.info("registering container with exit monitor") let code = try await client.wait(id) - log.info("container \(id) finished in exit monitor, exit code \(code)") + log.info("container finished in exit monitor", metadata: ["id": "\(id)", "rc": "\(code)"]) return code } @@ -445,7 +558,6 @@ public actor ContainersService { } catch { await self.exitMonitor.stopTracking(id: id) try? await client.stop(options: ContainerStopOptions.default) - throw error } } @@ -453,7 +565,25 @@ public actor ContainersService { /// Send a signal to the container. public func kill(id: String, processID: String, signal: Int64) async throws { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + "signal": "\(signal)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + ] + ) + } let state = try self._getContainerState(id: id) let client = try state.getClient() @@ -463,7 +593,22 @@ public actor ContainersService { /// Stop all containers inside the sandbox, aborting any processes currently /// executing inside the container, before stopping the underlying sandbox. public func stop(id: String, options: ContainerStopOptions) async throws { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } let state = try self._getContainerState(id: id) @@ -486,6 +631,25 @@ public actor ContainersService { } public func dial(id: String, port: UInt32) async throws -> FileHandle { + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "port": "\(port)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "port": "\(port)", + ] + ) + } + let state = try self._getContainerState(id: id) let client = try state.getClient() return try await client.dial(port) @@ -494,7 +658,24 @@ public actor ContainersService { /// Wait waits for the container's init process or exec to exit and returns the /// exit status. public func wait(id: String, processID: String) async throws -> ExitStatus { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + ] + ) + } let state = try self._getContainerState(id: id) let client = try state.getClient() @@ -503,7 +684,24 @@ public actor ContainersService { /// Resize resizes the container's PTY if one exists. public func resize(id: String, processID: String, size: Terminal.Size) async throws { - self.log.debug("\(#function)") + log.trace( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + ] + ) + defer { + log.trace( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "processId": "\(processID)", + ] + ) + } let state = try self._getContainerState(id: id) let client = try state.getClient() @@ -512,7 +710,22 @@ public actor ContainersService { // Get the logs for the container. public func logs(id: String) async throws -> [FileHandle] { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } // Logs doesn't care if the container is running or not, just that // the bundle is there, and that the files actually exist. We do @@ -536,7 +749,22 @@ public actor ContainersService { /// Get statistics for the container. public func stats(id: String) async throws -> ContainerStats { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } let state = try self._getContainerState(id: id) let client = try state.getClient() @@ -545,7 +773,24 @@ public actor ContainersService { /// Delete a container and its resources. public func delete(id: String, force: Bool) async throws { - self.log.debug("\(#function)") + log.info( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + "force": "\(force)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } + let state = try self._getContainerState(id: id) switch state.snapshot.status { case .running: @@ -561,8 +806,22 @@ public actor ContainersService { ) let client = try state.getClient() try await client.stop(options: opts) - try await self.lock.withLock { context in + try await self.lock.withLock(logMetadata: ["acquirer": "\(#function)", "id": "\(id)"]) { context in + self.log.info( + "ContainersService: attempt cleanup", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) try await self.cleanUp(id: id, context: context) + self.log.info( + "ContainersService: successful cleanup", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) } case .stopping: throw ContainerizationError( @@ -570,14 +829,29 @@ public actor ContainersService { message: "container \(id) is \(state.snapshot.status) and can not be deleted" ) default: - try await self.lock.withLock { context in + try await self.lock.withLock(logMetadata: ["acquirer": "\(#function)", "id": "\(id)"]) { context in try await self.cleanUp(id: id, context: context) } } } public func containerDiskUsage(id: String) async throws -> UInt64 { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } let containerPath = self.containerRoot.appendingPathComponent(id).path @@ -585,14 +859,14 @@ public actor ContainersService { } private func handleContainerExit(id: String, code: ExitStatus? = nil) async throws { - try await self.lock.withLock { [self] context in + try await self.lock.withLock(logMetadata: ["acquirer": "\(#function)", "id": "\(id)"]) { [self] context in try await handleContainerExit(id: id, code: code, context: context) } } private func handleContainerExit(id: String, code: ExitStatus?, context: AsyncLock.Context) async throws { if let code { - self.log.info("Handling container \(id) exit. Code \(code)") + self.log.info("handling container exit", metadata: ["id": "\(id)", "rc": "\(code)"]) } var state: ContainerState @@ -609,7 +883,7 @@ public actor ContainersService { await self.exitMonitor.stopTracking(id: id) // Shutdown and deregister the sandbox service - self.log.info("Shutting down sandbox service for \(id)") + self.log.info("shutting down sandbox service", metadata: ["id": "\(id)"]) let path = self.containerRoot.appendingPathComponent(id) let bundle = ContainerResource.Bundle(path: path) @@ -626,7 +900,7 @@ public actor ContainersService { do { try await client.shutdown() } catch { - self.log.error("Failed to shutdown sandbox service for \(id): \(error)") + self.log.error("failed to shutdown sandbox service", metadata: ["id": "\(id)", "error": "\(error)"]) } } @@ -635,19 +909,25 @@ public actor ContainersService { // the process was killed externally. do { try ServiceManager.deregister(fullServiceLabel: label) - self.log.info("Deregistered sandbox service for \(id)") + self.log.info("deregistered sandbox service", metadata: ["id": "\(id)"]) } catch { - self.log.error("Failed to deregister sandbox service for \(id): \(error)") + self.log.error("failed to deregister sandbox service", metadata: ["id": "\(id)", "error": "\(error)"]) } // Best effort deallocate network attachments for the container. Don't throw on // failure so we can continue with state cleanup. - self.log.info("Deallocating network attachments for \(id)") + self.log.info("deallocating network attachments", metadata: ["id": "\(id)"]) for allocatedAttach in state.allocatedAttachments { do { try await self.networksService?.deallocate(attachment: allocatedAttach.attachment) } catch { - self.log.error("failed to deallocate network attachment in \(id) for \(allocatedAttach.attachment.network): \(error)") + self.log.error( + "failed to deallocate network attachment", + metadata: [ + "id": "\(id)", + "network": "\(allocatedAttach.attachment.network)", + "error": "\(error)", + ]) } } @@ -668,7 +948,22 @@ public actor ContainersService { } private func _cleanUp(id: String) async throws { - self.log.debug("\(#function)") + log.debug( + "ContainersService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + log.debug( + "ContainersService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } // Did the exit container handler win? if self.containers[id] == nil { @@ -688,7 +983,7 @@ public actor ContainersService { do { config = try bundle.configuration } catch { - self.log.warning("Unable to read bundle configuration during cleanup for container \(id): \(error)") + self.log.warning("failed to read bundle configuration during cleanup for container", metadata: ["id": "\(id)", "error": "\(error)"]) } // Only try to deregister service if we have a valid config @@ -706,7 +1001,7 @@ public actor ContainersService { do { try bundle.delete() } catch { - self.log.warning("Failed to delete bundle for container \(id): \(error)") + self.log.warning("failed to delete bundle for container", metadata: ["id": "\(id)", "error": "\(error)"]) } self.containers.removeValue(forKey: id) @@ -735,14 +1030,15 @@ public actor ContainersService { plugin: Plugin, loader: PluginLoader, configuration: ContainerConfiguration, - path: URL + path: URL, + debug: Bool ) throws { let args = [ "start", "--root", path.path, "--uuid", configuration.id, - "--debug", - ] + debug ? "--debug" : nil, + ].compactMap { $0 } try loader.registerWithLaunchd( plugin: plugin, pluginStateRoot: path, diff --git a/Sources/Services/ContainerAPIService/Server/Kernel/KernelService.swift b/Sources/Services/ContainerAPIService/Server/Kernel/KernelService.swift index a152a53a5..84c55a532 100644 --- a/Sources/Services/ContainerAPIService/Server/Kernel/KernelService.swift +++ b/Sources/Services/ContainerAPIService/Server/Kernel/KernelService.swift @@ -38,7 +38,25 @@ public actor KernelService { /// Copies a kernel binary from a local path on disk into the managed kernels directory /// as the default kernel for the provided platform. public func installKernel(kernelFile url: URL, platform: SystemPlatform = .linuxArm, force: Bool) throws { - self.log.info("KernelService: \(#function) - kernelFile: \(url), platform: \(String(describing: platform))") + log.debug( + "KernelService: enter", + metadata: [ + "func": "\(#function)", + "kernelFile": "\(url)", + "platform": "\(String(describing: platform))", + ] + ) + defer { + log.debug( + "KernelService: exit", + metadata: [ + "func": "\(#function)", + "kernelFile": "\(url)", + "platform": "\(String(describing: platform))", + ] + ) + } + let kFile = url.resolvingSymlinksInPath() let destPath = self.kernelDirectory.appendingPathComponent(kFile.lastPathComponent) if force { @@ -64,7 +82,26 @@ public actor KernelService { /// as the default kernel for the provided platform. /// The parameter `tar` maybe a location to a local file on disk, or a remote URL. public func installKernelFrom(tar: URL, kernelFilePath: String, platform: SystemPlatform, progressUpdate: ProgressUpdateHandler?, force: Bool) async throws { - self.log.info("KernelService: \(#function) - tar: \(tar), kernelFilePath: \(kernelFilePath), platform: \(String(describing: platform))") + log.debug( + "KernelService: enter", + metadata: [ + "func": "\(#function)", + "tar": "\(tar)", + "kernelFilePath": "\(kernelFilePath)", + "platform": "\(String(describing: platform))", + ] + ) + defer { + log.debug( + "KernelService: exit", + metadata: [ + "func": "\(#function)", + "tar": "\(tar)", + "kernelFilePath": "\(kernelFilePath)", + "platform": "\(String(describing: platform))", + ] + ) + } let tempDir = FileManager.default.uniqueTemporaryDirectory() defer { @@ -78,7 +115,7 @@ public actor KernelService { let downloadTask = await taskManager.startTask() var tarFile = tar if !FileManager.default.fileExists(atPath: tar.absoluteString) { - self.log.debug("KernelService: Downloading \(tar)") + self.log.debug("KernelService: start download", metadata: ["tar": "\(tar)"]) tarFile = tempDir.appendingPathComponent(tar.lastPathComponent) var downloadProgressUpdate: ProgressUpdateHandler? if let progressUpdate { @@ -100,7 +137,25 @@ public actor KernelService { } private func setDefaultKernel(name: String, platform: SystemPlatform) throws { - self.log.info("KernelService: \(#function) - name: \(name), platform: \(String(describing: platform))") + log.debug( + "KernelService: enter", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + "platform": "\(String(describing: platform))", + ] + ) + defer { + log.debug( + "KernelService: exit", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + "platform": "\(String(describing: platform))", + ] + ) + } + let kernelPath = self.kernelDirectory.appendingPathComponent(name) guard FileManager.default.fileExists(atPath: kernelPath.path) else { throw ContainerizationError(.notFound, message: "kernel not found at \(kernelPath)") @@ -112,7 +167,23 @@ public actor KernelService { } public func getDefaultKernel(platform: SystemPlatform = .linuxArm) async throws -> Kernel { - self.log.info("KernelService: \(#function) - platform: \(String(describing: platform))") + log.debug( + "KernelService: enter", + metadata: [ + "func": "\(#function)", + "platform": "\(String(describing: platform))", + ] + ) + defer { + log.debug( + "KernelService: exit", + metadata: [ + "func": "\(#function)", + "platform": "\(String(describing: platform))", + ] + ) + } + let name = "\(Self.defaultKernelNamePrefix)\(platform.architecture)" let defaultKernelPath = self.kernelDirectory.appendingPathComponent(name).resolvingSymlinksInPath() guard FileManager.default.fileExists(atPath: defaultKernelPath.path) else { diff --git a/Sources/Services/ContainerAPIService/Server/Networks/NetworksService.swift b/Sources/Services/ContainerAPIService/Server/Networks/NetworksService.swift index 90ac19fc5..7966f77d2 100644 --- a/Sources/Services/ContainerAPIService/Server/Networks/NetworksService.swift +++ b/Sources/Services/ContainerAPIService/Server/Networks/NetworksService.swift @@ -37,6 +37,7 @@ public actor NetworksService { private let resourceRoot: URL private let containersService: ContainersService private let log: Logger + private let debugHelpers: Bool private let store: FilesystemEntityStore private let networkPlugins: [Plugin] @@ -49,12 +50,14 @@ public actor NetworksService { pluginLoader: PluginLoader, resourceRoot: URL, containersService: ContainersService, - log: Logger + log: Logger, + debugHelpers: Bool = false, ) async throws { self.pluginLoader = pluginLoader self.resourceRoot = resourceRoot self.containersService = containersService self.log = log + self.debugHelpers = debugHelpers try FileManager.default.createDirectory(at: resourceRoot, withIntermediateDirectories: true) self.store = try FilesystemEntityStore( @@ -97,12 +100,17 @@ public actor NetworksService { try await registerService(configuration: configuration) } catch { log.error( - "failed to start network: \(error)", + "failed to start network", metadata: [ - "id": "\(configuration.id)" + "id": "\(configuration.id)", + "error": "\(error)", ]) } + // This call will normally take ~20-100ms to complete after service + // registration, but on a fresh system (e.g. CI runner), it may take + // 5 seconds or considerably more from the registration of this first + // network service to its execution. let client = try Self.getClient(configuration: configuration) var networkState = try await client.state() @@ -141,7 +149,9 @@ public actor NetworksService { /// List all networks registered with the service. public func list() async throws -> [NetworkState] { - log.info("network service: list") + log.debug("NetworksService: enter", metadata: ["func": "\(#function)"]) + defer { log.debug("NetworksService: exit", metadata: ["func": "\(#function)"]) } + return serviceStates.reduce(into: [NetworkState]()) { $0.append($1.value.networkState) } @@ -149,11 +159,22 @@ public actor NetworksService { /// Create a new network from the provided configuration. public func create(configuration: NetworkConfiguration) async throws -> NetworkState { - log.info( - "network service: create", + log.debug( + "NetworksService: enter", metadata: [ - "id": "\(configuration.id)" - ]) + "func": "\(#function)", + "id": "\(configuration.id)", + ] + ) + defer { + log.debug( + "NetworksService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(configuration.id)", + ] + ) + } //Ensure that the network is not named "none" if configuration.id == ClientNetwork.noNetworkName { @@ -213,6 +234,23 @@ public actor NetworksService { /// Delete a network. public func delete(id: String) async throws { + log.debug( + "NetworksService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + log.debug( + "NetworksService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } + // check actor busy state guard !busyNetworks.contains(id) else { throw ContainerizationError(.exists, message: "network \(id) has a pending operation") @@ -223,10 +261,11 @@ public actor NetworksService { defer { busyNetworks.remove(id) } log.info( - "network service: delete", + "deleting network", metadata: [ "id": "\(id)" - ]) + ] + ) try await stateLock.withLock { _ in guard let serviceState = await self.serviceStates[id] else { @@ -243,7 +282,7 @@ public actor NetworksService { } // prevent container operations while we atomically check and delete - try await self.containersService.withContainerList { containers in + try await self.containersService.withContainerList(logMetadata: ["acquirer": "\(#function)", "id": "\(id)"]) { containers in // find all containers that refer to the network var referringContainers = Set() for container in containers { @@ -369,6 +408,9 @@ public actor NetworksService { "--mode", configuration.mode.rawValue, ] + if debugHelpers { + args.append("--debug") + } if let ipv4Subnet = configuration.ipv4Subnet { var existingCidrs: [CIDRv4] = [] diff --git a/Sources/Services/ContainerAPIService/Server/Plugin/PluginsService.swift b/Sources/Services/ContainerAPIService/Server/Plugin/PluginsService.swift index 726ca56d2..c3b676d0e 100644 --- a/Sources/Services/ContainerAPIService/Server/Plugin/PluginsService.swift +++ b/Sources/Services/ContainerAPIService/Server/Plugin/PluginsService.swift @@ -33,10 +33,11 @@ public actor PluginsService { /// if none are explicitly specified. public func loadAll( _ plugins: [Plugin]? = nil, + debug: Bool = false ) throws { let registerPlugins = plugins ?? pluginLoader.findPlugins() for plugin in registerPlugins { - try pluginLoader.registerWithLaunchd(plugin: plugin) + try pluginLoader.registerWithLaunchd(plugin: plugin, debug: debug) loaded[plugin.name] = plugin } } @@ -54,14 +55,14 @@ public actor PluginsService { // MARK: XPC API surface. /// Load a single plugin, doing nothing if the plugin is already loaded. - public func load(name: String) throws { + public func load(name: String, debug: Bool = false) throws { guard self.loaded[name] == nil else { return } guard let plugin = pluginLoader.findPlugin(name: name) else { throw Error.pluginNotFound(name) } - try pluginLoader.registerWithLaunchd(plugin: plugin) + try pluginLoader.registerWithLaunchd(plugin: plugin, debug: debug) self.loaded[plugin.name] = plugin } diff --git a/Sources/Services/ContainerAPIService/Server/Volumes/VolumesService.swift b/Sources/Services/ContainerAPIService/Server/Volumes/VolumesService.swift index b03afb659..20d5f18da 100644 --- a/Sources/Services/ContainerAPIService/Server/Volumes/VolumesService.swift +++ b/Sources/Services/ContainerAPIService/Server/Volumes/VolumesService.swift @@ -51,29 +51,112 @@ public actor VolumesService { driverOpts: [String: String] = [:], labels: [String: String] = [:] ) async throws -> Volume { - try await lock.withLock { _ in + log.debug( + "VolumesService: enter", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + ] + ) + defer { + log.debug( + "VolumesService: exit", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + ] + ) + } + + return try await lock.withLock { _ in try await self._create(name: name, driver: driver, driverOpts: driverOpts, labels: labels) } } public func delete(name: String) async throws { + log.debug( + "VolumesService: enter", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + ] + ) + defer { + log.debug( + "VolumesService: exit", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + ] + ) + } + try await lock.withLock { _ in try await self._delete(name: name) } } public func list() async throws -> [Volume] { - try await store.list() + log.debug( + "VolumesService: enter", + metadata: [ + "func": "\(#function)" + ] + ) + defer { + log.debug( + "VolumesService: exit", + metadata: [ + "func": "\(#function)" + ] + ) + } + + return try await store.list() } public func inspect(_ name: String) async throws -> Volume { - try await lock.withLock { _ in + log.debug( + "VolumesService: enter", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + ] + ) + defer { + log.debug( + "VolumesService: exit", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + ] + ) + } + + return try await lock.withLock { _ in try await self._inspect(name) } } /// Calculate disk usage for a single volume public func volumeDiskUsage(name: String) async throws -> UInt64 { + log.debug( + "VolumesService: enter", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + ] + ) + defer { + log.debug( + "VolumesService: exit", + metadata: [ + "func": "\(#function)", + "name": "\(name)", + ] + ) + } + let volumePath = self.volumePath(for: name) return self.calculateDirectorySize(at: volumePath) } @@ -81,11 +164,26 @@ public actor VolumesService { /// Calculate disk usage for volumes /// - Returns: Tuple of (total count, active count, total size, reclaimable size) public func calculateDiskUsage() async throws -> (Int, Int, UInt64, UInt64) { - try await lock.withLock { _ in + log.debug( + "VolumesService: enter", + metadata: [ + "func": "\(#function)" + ] + ) + defer { + log.debug( + "VolumesService: exit", + metadata: [ + "func": "\(#function)" + ] + ) + } + + return try await lock.withLock { _ in let allVolumes = try await self.store.list() // Atomically get active volumes with container list - return try await self.containersService.withContainerList { containers in + return try await self.containersService.withContainerList(logMetadata: ["acquirer": "\(#function)"]) { containers in var inUseSet = Set() // Find all mounted volumes @@ -239,7 +337,7 @@ public actor VolumesService { try await store.create(volume) - log.info("Created volume", metadata: ["name": "\(name)", "driver": "\(driver)", "isAnonymous": "\(volume.isAnonymous)"]) + log.info("created volume", metadata: ["name": "\(name)", "driver": "\(driver)", "isAnonymous": "\(volume.isAnonymous)"]) return volume } @@ -255,7 +353,7 @@ public actor VolumesService { } // Check if volume is in use by any container atomically - try await containersService.withContainerList { containers in + try await containersService.withContainerList(logMetadata: ["acquirer": "\(#function)", "name": "\(name)"]) { containers in for container in containers { for mount in container.configuration.mounts { if mount.isVolume && mount.volumeName == name { @@ -268,7 +366,7 @@ public actor VolumesService { try self.removeVolumeDirectory(for: name) } - log.info("Deleted volume", metadata: ["name": "\(name)"]) + log.info("deleted volume", metadata: ["name": "\(name)"]) } private func _inspect(_ name: String) async throws -> Volume { diff --git a/Sources/Services/ContainerImagesService/Server/ContentStoreService.swift b/Sources/Services/ContainerImagesService/Server/ContentStoreService.swift index 1a6d1d1d8..9332428b9 100644 --- a/Sources/Services/ContainerImagesService/Server/ContentStoreService.swift +++ b/Sources/Services/ContainerImagesService/Server/ContentStoreService.swift @@ -33,34 +33,127 @@ public actor ContentStoreService { } public func get(digest: String) async throws -> URL? { - self.log.trace("ContentStoreService: \(#function) digest \(digest)") + self.log.trace( + "ContentStoreService: enter", + metadata: [ + "func": "\(#function)", + "digest": "\(digest)", + ] + ) + defer { + self.log.trace( + "ContentStoreService: exit", + metadata: [ + "func": "\(#function)", + "digest": "\(digest)", + ] + ) + } + return try await self.contentStore.get(digest: digest)?.path } @discardableResult public func delete(digests: [String]) async throws -> ([String], UInt64) { - self.log.debug("ContentStoreService: \(#function) digests \(digests)") + self.log.trace( + "ContentStoreService: enter", + metadata: [ + "func": "\(#function)", + "digests": "\(digests)", + ] + ) + defer { + self.log.trace( + "ContentStoreService: exit", + metadata: [ + "func": "\(#function)", + "digests": "\(digests)", + ] + ) + } + return try await self.contentStore.delete(digests: digests) } @discardableResult public func delete(keeping: [String]) async throws -> ([String], UInt64) { - self.log.debug("ContentStoreService: \(#function) digests \(keeping)") + self.log.debug( + "ContentStoreService: enter", + metadata: [ + "func": "\(#function)", + "keeping": "\(keeping)", + ] + ) + defer { + self.log.debug( + "ContentStoreService: exit", + metadata: [ + "func": "\(#function)", + "keeping": "\(keeping)", + ] + ) + } + return try await self.contentStore.delete(keeping: keeping) } public func newIngestSession() async throws -> (id: String, ingestDir: URL) { - self.log.debug("ContentStoreService: \(#function)") + self.log.debug( + "ContentStoreService: enter", + metadata: [ + "func": "\(#function)" + ] + ) + defer { + self.log.debug( + "ContentStoreService: exit", + metadata: [ + "func": "\(#function)" + ] + ) + } return try await self.contentStore.newIngestSession() } public func completeIngestSession(_ id: String) async throws -> [String] { - self.log.debug("ContentStoreService: \(#function) id \(id)") + self.log.debug( + "ContentStoreService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + self.log.debug( + "ContentStoreService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } + return try await self.contentStore.completeIngestSession(id) } public func cancelIngestSession(_ id: String) async throws { - self.log.debug("ContentStoreService: \(#function) id \(id)") + self.log.debug( + "ContentStoreService: enter", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + defer { + self.log.debug( + "ContentStoreService: exit", + metadata: [ + "func": "\(#function)", + "id": "\(id)", + ] + ) + } + return try await self.contentStore.cancelIngestSession(id) } } diff --git a/Sources/Services/ContainerImagesService/Server/ImageService.swift b/Sources/Services/ContainerImagesService/Server/ImagesService.swift similarity index 64% rename from Sources/Services/ContainerImagesService/Server/ImageService.swift rename to Sources/Services/ContainerImagesService/Server/ImagesService.swift index 61bb4f6e0..2fb06ed1c 100644 --- a/Sources/Services/ContainerImagesService/Server/ImageService.swift +++ b/Sources/Services/ContainerImagesService/Server/ImagesService.swift @@ -1,5 +1,5 @@ //===----------------------------------------------------------------------===// -// Copyright © 2025-2026 Apple Inc. and the container project authors. +// Copyright © 2026 Apple Inc. and the container project authors. // // Licensed under the Apache License, Version 2.0 (the "License"); // you may not use this file except in compliance with the License. @@ -56,15 +56,48 @@ public actor ImagesService { } public func list() async throws -> [ImageDescription] { - self.log.info("ImagesService: \(#function)") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)" + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)" + ] + ) + } + return try await imageStore.list().map { $0.description.fromCZ } } public func pull(reference: String, platform: Platform?, insecure: Bool, progressUpdate: ProgressUpdateHandler?, maxConcurrentDownloads: Int = 3) async throws -> ImageDescription { - self.log.info( - "ImagesService: \(#function) - ref: \(reference), platform: \(String(describing: platform)), insecure: \(insecure), maxConcurrentDownloads: \(maxConcurrentDownloads)") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "ref": "\(reference)", + "platform": "\(String(describing: platform))", + "insecure": "\(insecure)", + "maxConcurrentDownloads": "\(maxConcurrentDownloads)", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "ref": "\(reference)", + "platform": "\(String(describing: platform))", + ] + ) + } + let img = try await Self.withAuthentication(ref: reference) { auth in try await self.imageStore.pull( reference: reference, platform: platform, insecure: insecure, auth: auth, progress: ContainerizationProgressAdapter.handler(from: progressUpdate), @@ -77,7 +110,26 @@ public actor ImagesService { } public func push(reference: String, platform: Platform?, insecure: Bool, progressUpdate: ProgressUpdateHandler?) async throws { - self.log.info("ImagesService: \(#function) - ref: \(reference), platform: \(String(describing: platform)), insecure: \(insecure)") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "ref": "\(reference)", + "platform": "\(String(describing: platform))", + "insecure": "\(insecure)", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "ref": "\(reference)", + "platform": "\(String(describing: platform))", + ] + ) + } + try await Self.withAuthentication(ref: reference) { auth in try await self.imageStore.push( reference: reference, platform: platform, insecure: insecure, auth: auth, progress: ContainerizationProgressAdapter.handler(from: progressUpdate)) @@ -85,18 +137,68 @@ public actor ImagesService { } public func tag(old: String, new: String) async throws -> ImageDescription { - self.log.info("ImagesService: \(#function) - old: \(old), new: \(new)") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "old": "\(old)", + "new": "\(new)", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "old": "\(old)", + "new": "\(new)", + ] + ) + } + let img = try await self.imageStore.tag(existing: old, new: new) return img.description.fromCZ } public func delete(reference: String, garbageCollect: Bool) async throws { - self.log.info("ImagesService: \(#function) - ref: \(reference)") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "ref": "\(reference)", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "ref": "\(reference)", + ] + ) + } + try await self.imageStore.delete(reference: reference, performCleanup: garbageCollect) } public func save(references: [String], out: URL, platform: Platform?) async throws { - self.log.info("ImagesService: \(#function) - references: \(references) , platform: \(String(describing: platform))") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "references": "\(references)", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "references": "\(references)", + ] + ) + } + let tempDir = FileManager.default.uniqueTemporaryDirectory() defer { try? FileManager.default.removeItem(at: tempDir) @@ -109,7 +211,23 @@ public actor ImagesService { public func load(from tarFile: URL, force: Bool) async throws -> ([ImageDescription], [String]) { let archivePathname = tarFile.absolutePath() - self.log.info("ImagesService: \(#function) from: \(archivePathname)") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "archivePath": "\(archivePathname)", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "archivePath": "\(archivePathname)", + ] + ) + } + let reader = try ArchiveReader(file: tarFile) let tempDir = FileManager.default.uniqueTemporaryDirectory() defer { @@ -129,6 +247,21 @@ public actor ImagesService { } public func cleanUpOrphanedBlobs() async throws -> ([String], UInt64) { + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)" + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)" + ] + ) + } + let images = try await self._list() let freedSnapshotBytes = try await self.snapshotStore.clean(keepingSnapshotsFor: images) let (deleted, freedContentBytes) = try await self.imageStore.cleanUpOrphanedBlobs() @@ -139,6 +272,23 @@ public actor ImagesService { /// - Parameter activeReferences: Set of image references currently in use by containers /// - Returns: Tuple of (total count, active count, total size, reclaimable size) public func calculateDiskUsage(activeReferences: Set) async throws -> (Int, Int, UInt64, UInt64) { + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "references": "\(activeReferences)", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "references": "\(activeReferences)", + ] + ) + } + let images = try await self._list() var totalSize: UInt64 = 0 var reclaimableSize: UInt64 = 0 @@ -190,19 +340,73 @@ public actor ImagesService { extension ImagesService { public func unpack(description: ImageDescription, platform: Platform?, progressUpdate: ProgressUpdateHandler?) async throws { - self.log.info("ImagesService: \(#function) - description: \(description), platform: \(String(describing: platform))") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "description": "\(description)", + "platform": "\(String(describing: platform))", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "description": "\(description)", + "platform": "\(String(describing: platform))", + ] + ) + } + let img = try await self._get(description) try await self.snapshotStore.unpack(image: img, platform: platform, progressUpdate: progressUpdate) } public func deleteImageSnapshot(description: ImageDescription, platform: Platform?) async throws { - self.log.info("ImagesService: \(#function) - description: \(description), platform: \(String(describing: platform))") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "description": "\(description)", + "platform": "\(String(describing: platform))", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "description": "\(description)", + "platform": "\(String(describing: platform))", + ] + ) + } + let img = try await self._get(description) try await self.snapshotStore.delete(for: img, platform: platform) } public func getImageSnapshot(description: ImageDescription, platform: Platform) async throws -> Filesystem { - self.log.info("ImagesService: \(#function) - description: \(description), platform: \(String(describing: platform))") + self.log.debug( + "ImagesService: enter", + metadata: [ + "func": "\(#function)", + "description": "\(description)", + "platform": "\(String(describing: platform))", + ] + ) + defer { + self.log.debug( + "ImagesService: exit", + metadata: [ + "func": "\(#function)", + "description": "\(description)", + "platform": "\(String(describing: platform))", + ] + ) + } + let img = try await self._get(description) return try await self.snapshotStore.get(for: img, platform: platform) } diff --git a/Sources/Services/ContainerNetworkService/Server/NetworkService.swift b/Sources/Services/ContainerNetworkService/Server/NetworkService.swift index f40bdf772..d0cc20f79 100644 --- a/Sources/Services/ContainerNetworkService/Server/NetworkService.swift +++ b/Sources/Services/ContainerNetworkService/Server/NetworkService.swift @@ -24,14 +24,14 @@ import Logging public actor NetworkService: Sendable { private let network: any Network - private let log: Logger? + private let log: Logger private var allocator: AttachmentAllocator private var macAddresses: [UInt32: MACAddress] /// Set up a network service for the specified network. public init( network: any Network, - log: Logger? = nil + log: Logger ) async throws { let state = await network.state guard case .running(_, let status) = state else { @@ -57,6 +57,9 @@ public actor NetworkService: Sendable { @Sendable public func allocate(_ message: XPCMessage) async throws -> XPCMessage { + log.debug("enter", metadata: ["func": "\(#function)"]) + defer { log.debug("exit", metadata: ["func": "\(#function)"]) } + let state = await network.state guard case .running(_, let status) = state else { throw ContainerizationError(.invalidState, message: "invalid network state - network \(state.id) must be running") @@ -79,7 +82,7 @@ public actor NetworkService: Sendable { ipv6Address: ipv6Address, macAddress: macAddress ) - log?.info( + log.info( "allocated attachment", metadata: [ "hostname": "\(hostname)", @@ -101,16 +104,22 @@ public actor NetworkService: Sendable { @Sendable public func deallocate(_ message: XPCMessage) async throws -> XPCMessage { + log.debug("enter", metadata: ["func": "\(#function)"]) + defer { log.debug("exit", metadata: ["func": "\(#function)"]) } + let hostname = try message.hostname() if let index = try await allocator.deallocate(hostname: hostname) { macAddresses.removeValue(forKey: index) } - log?.info("released attachments", metadata: ["hostname": "\(hostname)"]) + log.info("released attachments", metadata: ["hostname": "\(hostname)"]) return message.reply() } @Sendable public func lookup(_ message: XPCMessage) async throws -> XPCMessage { + log.debug("enter", metadata: ["func": "\(#function)"]) + defer { log.debug("exit", metadata: ["func": "\(#function)"]) } + let state = await network.state guard case .running(_, let status) = state else { throw ContainerizationError(.invalidState, message: "invalid network state - network \(state.id) must be running") @@ -138,7 +147,7 @@ public actor NetworkService: Sendable { ipv6Address: ipv6Address, macAddress: macAddress ) - log?.debug( + log.debug( "lookup attachment", metadata: [ "hostname": "\(hostname)", @@ -150,8 +159,11 @@ public actor NetworkService: Sendable { @Sendable public func disableAllocator(_ message: XPCMessage) async throws -> XPCMessage { + log.debug("enter", metadata: ["func": "\(#function)"]) + defer { log.debug("exit", metadata: ["func": "\(#function)"]) } + let success = await allocator.disableAllocator() - log?.info("attempted allocator disable", metadata: ["success": "\(success)"]) + log.info("attempted allocator disable", metadata: ["success": "\(success)"]) let reply = message.reply() reply.setAllocatorDisabled(success) return reply diff --git a/Sources/Services/ContainerSandboxService/Client/SandboxClient.swift b/Sources/Services/ContainerSandboxService/Client/SandboxClient.swift index 76df65a17..6f1cdd2d8 100644 --- a/Sources/Services/ContainerSandboxService/Client/SandboxClient.swift +++ b/Sources/Services/ContainerSandboxService/Client/SandboxClient.swift @@ -47,14 +47,14 @@ public struct SandboxClient: Sendable { /// Create a SandboxClient by ID and runtime string. The returned client is ready to be used /// without additional steps. - public static func create(id: String, runtime: String) async throws -> SandboxClient { + public static func create(id: String, runtime: String, timeout: Duration = XPCClient.xpcRegistrationTimeout) async throws -> SandboxClient { let label = Self.machServiceLabel(runtime: runtime, id: id) let client = XPCClient(service: label) let request = XPCMessage(route: SandboxRoutes.createEndpoint.rawValue) let response: XPCMessage do { - response = try await client.send(request, responseTimeout: .seconds(5)) + response = try await client.send(request, responseTimeout: timeout) } catch { throw ContainerizationError( .internalError, diff --git a/Sources/Services/ContainerSandboxService/Server/SandboxService.swift b/Sources/Services/ContainerSandboxService/Server/SandboxService.swift index da9d0bf68..0abb93461 100644 --- a/Sources/Services/ContainerSandboxService/Server/SandboxService.swift +++ b/Sources/Services/ContainerSandboxService/Server/SandboxService.swift @@ -85,7 +85,9 @@ public actor SandboxService { /// with the sandbox service. @Sendable public func createEndpoint(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`createEndpoint` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + let endpoint = xpc_endpoint_create(self.connection) let reply = message.reply() reply.set(key: SandboxKeys.sandboxServiceEndpoint.rawValue, value: endpoint) @@ -100,7 +102,8 @@ public actor SandboxService { /// - Returns: An XPC message with no parameters. @Sendable public func bootstrap(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`bootstrap` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } // Create the bundle if it doesn't exist yet if !self.bundleExists(at: self.root) { @@ -231,7 +234,7 @@ public actor SandboxService { try await self.cleanUpContainer(containerInfo: ctrInfo) await self.setState(.created) } catch { - self.log.error("Failed to clean up container: \(error)") + self.log.error("failed to clean up container", metadata: ["error": "\(error)"]) } throw error } @@ -249,7 +252,9 @@ public actor SandboxService { /// - Returns: An XPC message with no parameters. @Sendable public func startProcess(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`startProcess` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + return try await self.lock.withLock { lock in let id = try message.id() let containerInfo = try await self.getContainer() @@ -275,7 +280,9 @@ public actor SandboxService { /// - statistics: JSON serialization of the `ContainerStats`. @Sendable public func statistics(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`statistics` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + return try await self.lock.withLock { lock in let containerInfo = try await self.getContainer() let stats = try await containerInfo.container.statistics() @@ -307,7 +314,8 @@ public actor SandboxService { /// - Returns: An XPC message with no parameters. @Sendable public func shutdown(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`shutdown` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } return try await self.lock.withLock { _ in switch await self.state { @@ -339,7 +347,9 @@ public actor SandboxService { /// - Returns: An XPC message with no parameters. @Sendable public func createProcess(_ message: XPCMessage) async throws -> XPCMessage { - log.info("`createProcess` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + return try await self.lock.withLock { [self] _ in switch await self.state { case .running, .booted: @@ -387,7 +397,9 @@ public actor SandboxService { /// that contains the state information. @Sendable public func state(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`state` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + var status: RuntimeStatus = .unknown var networks: [Attachment] = [] var cs: ContainerSnapshot? @@ -431,7 +443,9 @@ public actor SandboxService { /// - Returns: An XPC message with no parameters. @Sendable public func stop(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`stop` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + return try await self.lock.withLock { _ in switch await self.state { case .running, .booted: @@ -450,7 +464,7 @@ public actor SandboxService { } try await self.cleanUpContainer(containerInfo: ctr, exitStatus: exitStatus) } catch { - self.log.error("Failed to clean up container: \(error)") + self.log.error("failed to clean up container", metadata: ["error": "\(error)"]) } await self.setState(.stopped(exitStatus.exitCode)) default: @@ -470,7 +484,9 @@ public actor SandboxService { /// - Returns: An XPC message with no parameters. @Sendable public func kill(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`kill` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + return try await self.lock.withLock { [self] _ in switch await self.state { case .running: @@ -511,7 +527,9 @@ public actor SandboxService { /// - Returns: An XPC message with no parameters. @Sendable public func resize(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`resize` xpc handler") + self.log.trace("enter", metadata: ["func": "\(#function)"]) + defer { self.log.trace("exit", metadata: ["func": "\(#function)"]) } + switch self.state { case .running: let id = try message.id() @@ -566,7 +584,9 @@ public actor SandboxService { /// - exitCode: The exit code for the process. @Sendable public func wait(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`wait` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + guard let id = message.string(key: SandboxKeys.id.rawValue) else { throw ContainerizationError(.invalidArgument, message: "missing id in wait xpc message") } @@ -620,7 +640,9 @@ public actor SandboxService { /// - fd: The file descriptor for the vsock. @Sendable public func dial(_ message: XPCMessage) async throws -> XPCMessage { - self.log.info("`dial` xpc handler") + self.log.debug("enter", metadata: ["func": "\(#function)"]) + defer { self.log.debug("exit", metadata: ["func": "\(#function)"]) } + switch self.state { case .running, .booted: let port = message.uint64(key: SandboxKeys.port.rawValue) @@ -788,7 +810,7 @@ public actor SandboxService { } private func onContainerExit(id: String, exitStatus: ExitStatus) async throws { - self.log.info("init process exited with: \(exitStatus)") + self.log.info("init process exited", metadata: ["status": "\(exitStatus)"]) try await self.lock.withLock { [self] _ in let ctrInfo = try await getContainer() @@ -803,7 +825,7 @@ public actor SandboxService { do { try await cleanUpContainer(containerInfo: ctrInfo, exitStatus: exitStatus) } catch { - self.log.error("Failed to clean up container: \(error)") + self.log.error("failed to clean up container", metadata: ["error": "\(error)"]) } await setState(.stopped(exitStatus.exitCode)) } @@ -1036,7 +1058,7 @@ public actor SandboxService { do { try await container.stop() } catch { - self.log.error("failed to stop container during cleanup: \(error)") + self.log.error("failed to stop container during cleanup", metadata: ["error": "\(error)"]) } await self.stopSocketForwarders() @@ -1366,9 +1388,9 @@ extension SandboxService { containerRootFilesystem: runtimeConfig.containerRootFilesystem, options: runtimeConfig.options ) - self.log.info("Created bundle from runtime configuration at \(runtimeConfig.path)") + self.log.info("created bundle", metadata: ["configPath": "\(runtimeConfig.path)"]) } catch { - self.log.error("Failed to create bundle \(error)") + self.log.error("failed to create bundle", metadata: ["error": "\(error)"]) throw error } } diff --git a/Tests/CLITests/Subcommands/Containers/TestCLIExec.swift b/Tests/CLITests/Subcommands/Containers/TestCLIExec.swift index eab8529e8..503b97ee7 100644 --- a/Tests/CLITests/Subcommands/Containers/TestCLIExec.swift +++ b/Tests/CLITests/Subcommands/Containers/TestCLIExec.swift @@ -123,7 +123,10 @@ class TestCLIExecCommand: CLITest { _ = try doExec(name: name, cmd: ["sleep", "infinity"]) } catch CLIError.executionFailed(let message) { // There's no nice way to check fail reason here - #expect(message.contains("is not running"), "expected container is not running if exec failed") + #expect( + message.contains("is not running") || message.contains("failed to create process"), + "expected container is not running if exec failed" + ) } // Give time for the exec (or start) error handling settles down diff --git a/Tests/CLITests/Subcommands/Networks/TestCLINetwork.swift b/Tests/CLITests/Subcommands/Networks/TestCLINetwork.swift index e44c5e271..89fbc87bc 100644 --- a/Tests/CLITests/Subcommands/Networks/TestCLINetwork.swift +++ b/Tests/CLITests/Subcommands/Networks/TestCLINetwork.swift @@ -22,7 +22,6 @@ import ContainerizationOS import Foundation import Testing -@Suite(.serialized) class TestCLINetwork: CLITest { private static let retries = 10 private static let retryDelaySeconds = Int64(3) @@ -36,7 +35,7 @@ class TestCLINetwork: CLITest { } @available(macOS 26, *) - @Test(.disabled()) func testNetworkCreateAndUse() async throws { + @Test func testNetworkCreateAndUse() async throws { do { let name = getLowercasedTestName() let networkDeleteArgs = ["network", "delete", name] @@ -90,7 +89,7 @@ class TestCLINetwork: CLITest { } @available(macOS 26, *) - @Test(.disabled()) func testNetworkDeleteWithContainer() async throws { + @Test func testNetworkDeleteWithContainer() async throws { do { // prep: delete container and network, ignoring if it doesn't exist let name = getLowercasedTestName() @@ -137,7 +136,7 @@ class TestCLINetwork: CLITest { } @available(macOS 26, *) - @Test(.disabled()) func testNetworkLabels() async throws { + @Test func testNetworkLabels() async throws { do { // prep: delete container and network, ignoring if it doesn't exist let name = getLowercasedTestName() @@ -193,7 +192,7 @@ class TestCLINetwork: CLITest { } @available(macOS 26, *) - @Test(.disabled()) func testIsolatedNetwork() async throws { + @Test func testIsolatedNetwork() async throws { do { let name = getLowercasedTestName() let networkDeleteArgs = ["network", "delete", name] diff --git a/Tests/ContainerPluginTests/PluginLoaderTest.swift b/Tests/ContainerPluginTests/PluginLoaderTest.swift index 5c90af56f..5ab5cb5f9 100644 --- a/Tests/ContainerPluginTests/PluginLoaderTest.swift +++ b/Tests/ContainerPluginTests/PluginLoaderTest.swift @@ -173,6 +173,84 @@ struct PluginLoaderTest { #expect(filtered.isEmpty) } + @Test + func testRegisterWithLaunchdDebugTrue() async throws { + let tempURL = FileManager.default.temporaryDirectory.appendingPathComponent(UUID().uuidString) + defer { try? FileManager.default.removeItem(at: tempURL) } + let factory = try setupMock(tempURL: tempURL) + let loader = try PluginLoader( + appRoot: tempURL, + installRoot: URL(filePath: "/usr/local/"), + pluginDirectories: [tempURL], + pluginFactories: [factory] + ) + + let plugin = loader.findPlugin(name: "service")! + let stateRoot = tempURL.appendingPathComponent("test-state") + try loader.registerWithLaunchd(plugin: plugin, pluginStateRoot: stateRoot, debug: true) + + let plistURL = stateRoot.appendingPathComponent("service.plist") + #expect(FileManager.default.fileExists(atPath: plistURL.path)) + + let plistData = try Data(contentsOf: plistURL) + let plist = try PropertyListSerialization.propertyList(from: plistData, format: nil) as! [String: Any] + let programArguments = plist["ProgramArguments"] as! [String] + + #expect(programArguments.contains("--debug")) + } + + @Test + func testRegisterWithLaunchdDebugFalse() async throws { + let tempURL = FileManager.default.temporaryDirectory.appendingPathComponent(UUID().uuidString) + defer { try? FileManager.default.removeItem(at: tempURL) } + let factory = try setupMock(tempURL: tempURL) + let loader = try PluginLoader( + appRoot: tempURL, + installRoot: URL(filePath: "/usr/local/"), + pluginDirectories: [tempURL], + pluginFactories: [factory] + ) + + let plugin = loader.findPlugin(name: "service")! + let stateRoot = tempURL.appendingPathComponent("test-state") + try loader.registerWithLaunchd(plugin: plugin, pluginStateRoot: stateRoot, debug: false) + + let plistURL = stateRoot.appendingPathComponent("service.plist") + #expect(FileManager.default.fileExists(atPath: plistURL.path)) + + let plistData = try Data(contentsOf: plistURL) + let plist = try PropertyListSerialization.propertyList(from: plistData, format: nil) as! [String: Any] + let programArguments = plist["ProgramArguments"] as! [String] + + #expect(!programArguments.contains("--debug")) + } + + @Test + func testRegisterWithLaunchdDebugDefault() async throws { + let tempURL = FileManager.default.temporaryDirectory.appendingPathComponent(UUID().uuidString) + defer { try? FileManager.default.removeItem(at: tempURL) } + let factory = try setupMock(tempURL: tempURL) + let loader = try PluginLoader( + appRoot: tempURL, + installRoot: URL(filePath: "/usr/local/"), + pluginDirectories: [tempURL], + pluginFactories: [factory] + ) + + let plugin = loader.findPlugin(name: "service")! + let stateRoot = tempURL.appendingPathComponent("test-state") + try loader.registerWithLaunchd(plugin: plugin, pluginStateRoot: stateRoot) + + let plistURL = stateRoot.appendingPathComponent("service.plist") + #expect(FileManager.default.fileExists(atPath: plistURL.path)) + + let plistData = try Data(contentsOf: plistURL) + let plist = try PropertyListSerialization.propertyList(from: plistData, format: nil) as! [String: Any] + let programArguments = plist["ProgramArguments"] as! [String] + + #expect(!programArguments.contains("--debug")) + } + private func setupMock(tempURL: URL) throws -> MockPluginFactory { let cliConfig = PluginConfig(abstract: "cli", author: "CLI", servicesConfig: nil) let cliPlugin: Plugin = Plugin(binaryURL: URL(filePath: "/bin/cli"), config: cliConfig) diff --git a/scripts/install-init.sh b/scripts/install-init.sh index 26e120d91..e8a3c5689 100755 --- a/scripts/install-init.sh +++ b/scripts/install-init.sh @@ -13,10 +13,53 @@ # See the License for the specific language governing permissions and # limitations under the License. +usage() { + cat <&2 + usage + fi + START_ARGS+=(--app-root "$2") + shift 2 + ;; + -l|--log-root) + if [[ -z "$2" || "$2" == -* ]]; then + echo "Option $1 requires an argument." >&2 + usage + fi + START_ARGS+=(--log-root "$2") + shift 2 + ;; + -h|--help) + usage + ;; + *) + echo "Invalid option: $1" >&2 + usage + ;; + esac +done + SWIFT="/usr/bin/swift" IMAGE_NAME="vminit:latest" -DEST_DIR="${1:-$(git rev-parse --show-toplevel)/bin}" -mkdir -p "${DEST_DIR}" CONTAINERIZATION_VERSION="$(${SWIFT} package show-dependencies --format json | jq -r '.dependencies[] | select(.identity == "containerization") | .version')" if [ "${CONTAINERIZATION_VERSION}" == "unspecified" ] ; then @@ -28,8 +71,12 @@ if [ "${CONTAINERIZATION_VERSION}" == "unspecified" ] ; then echo "Creating InitImage" make -C ${CONTAINERIZATION_PATH} init ${CONTAINERIZATION_PATH}/bin/cctl images save -o /tmp/init.tar ${IMAGE_NAME} + # Sleep because commands after stop and start are racy. - bin/container system stop && sleep 3 && bin/container system start && sleep 3 + bin/container system stop + sleep 3 + bin/container --debug system start "${START_ARGS[@]}" + sleep 3 bin/container i load -i /tmp/init.tar rm /tmp/init.tar fi