Fix CI integration test coldstart issues.#1230

jglogan · 2026-02-19T01:38:15Z

Closes [chore]: Fix CLINetwork tests. #1206.
Closes [Bug]: Local vminit:latest install doesn't honor APP_ROOT. #1185.
Closes [Request]: Consistent, useful behavior for --debug. #507.
Addresses existing log messages for [Request]: UX: Use stdout and stderr, and logging consistently in CLI commands. #642.
Nondeterministic CI errors are resulting from very slow launch times for the first runtime helper, which causes ContainersService to be locked for longer than our 20 sec timeout. Bumping the timeout to 60 seconds addresses this case for now.
Since many log messages needed to be changed to troubleshoot the issue, updated all log messages to use structured logging, and implemented consistent entry/exit logging for all service operations.
Added logging for ContainerService lock acquisition to help with finding root cause for the slow service startup.
Plumbed the --debug flag on both container system start and container system logs so that the flag is actually useful.
Updated the install-init.sh script so that can install in a custom app root directory.

- Closes apple#1206. - Closes apple#507. - Addresses existing log messages for apple#642. - Nondeterministic CI errors are resulting from very slow launch times for the first runtime helper, which causes ContainersService to be locked for longer than our 20 sec timeout. Bumping the timeout to 60 seconds addresses this case for now. - Since many log messages needed to be changed to troubleshoot the issue, updated all log messages to use structured logging, and implemented consistent entry/exit logging for all service operations. - Added logging for ContainerService lock acquisition to help with finding root cause for the slow service startup. - Plumbed the `--debug` flag on both `container system start` and `container system logs` so that the flag is actually useful. - Updated the `install-init.sh` script so that can install in a custom app root directory.

jglogan · 2026-02-19T03:13:32Z

scripts/install-init.sh

+            START_ARGS+=(--app-root "$2")
+            shift 2
+            ;;
+        -l|--log-root)


Nothing uses this yet, but it will be used when the CI log collection PR posts.

jglogan · 2026-02-19T03:14:07Z

scripts/install-init.sh

+
 SWIFT="/usr/bin/swift"
 IMAGE_NAME="vminit:latest"
-DEST_DIR="${1:-$(git rev-parse --show-toplevel)/bin}"


This is dead code, removed it

jglogan · 2026-02-19T03:14:33Z

scripts/install-init.sh

-	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[@]}"


This is the essential change to the script

jglogan · 2026-02-19T03:15:35Z

Sources/ContainerCommands/System/SystemLogs.swift

                var args = ["log"]
                args.append(self.follow ? "stream" : "show")
-                args.append(contentsOf: ["--info", "--debug"])
+                args.append(contentsOf: ["--info", logOptions.debug ? "--debug" : nil].compactMap { $0 })


Now we only pass debug into log stream for container --debug system logs.

jglogan · 2026-02-19T03:16:11Z

Sources/ContainerCommands/System/SystemStart.swift

+                return .seconds(timeoutSeconds)
+            }
+        )
+        var timeout: Duration = XPCClient.xpcRegistrationTimeout


Key point here is that we use the common timeout value now.

jglogan · 2026-02-19T03:18:34Z

Sources/ContainerPlugin/PluginLoader.swift

        env[ApplicationRoot.environmentName] = appRoot.path(percentEncoded: false)
        env[InstallRoot.environmentName] = installRoot.path(percentEncoded: false)

+        let processedArgs = (args ?? ["start"]) + (debug ? ["--debug"] : [])


This is the main change, adds --debug to the plugin startup as necessary.

The implication is that all plugins need to implement a start subcommand that accepts a --debug flag.

jglogan · 2026-02-19T03:19:13Z

Sources/ContainerXPC/XPCClient.swift

+    /// 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)


Our common timeout value, chosen to work with our slow service startup in CI.

jglogan · 2026-02-19T03:20:36Z

Sources/Helpers/APIServer/APIServer+Start.swift

            let commandName = Self.configuration.commandName ?? "container-apiserver"
            let log = APIServer.setupLogger(debug: debug)
-            log.info("starting \(commandName)")
+            log.info("starting helper", metadata: ["name": "\(commandName)"])


This pattern is used for startup/shutdown for all services.

jglogan · 2026-02-19T03:21:23Z

Sources/Helpers/APIServer/APIServer+Start.swift

                let pluginLoader = try initializePluginLoader(log: log)
                try await initializePlugins(pluginLoader: pluginLoader, log: log, routes: &routes)
-                let containersService = try initializeContainerService(
+                let containersService = try initializeContainersService(


Just some name nitpickery for "containers service" and "networks service".

jglogan · 2026-02-19T03:23:32Z

Sources/Helpers/APIServer/APIServer+Start.swift

                containersService: containersService,
-                log: log
+                log: log,
+                debugHelpers: debug


Propagate debug settings from API server to any network helpers we create.

jglogan · 2026-02-19T03:23:46Z

Sources/Helpers/APIServer/APIServer+Start.swift

                pluginLoader: pluginLoader,
-                log: log
+                log: log,
+                debugHelpers: debug


Propagate debug settings from API server to any runtime helpers we create.

jglogan · 2026-02-19T03:25:08Z

Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift

        let containerRoot = appRoot.appendingPathComponent("containers")
        try FileManager.default.createDirectory(at: containerRoot, withIntermediateDirectories: true)
        self.exitMonitor = ExitMonitor(log: log)
+        self.lock = AsyncLock(log: log)


Set up debug logging for lock acquisition/release

jglogan · 2026-02-19T03:26:53Z

Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift

    /// List containers matching the given filters.
    public func list(filters: ContainerListFilters = .all) async throws -> [ContainerSnapshot] {
-        self.log.debug("\(#function)")
+        log.debug(


This is the pattern we use everywhere for entry/exit on our service operations.

All information on entry metadata.

Only identifying information on exit metadata.

debug level, except trace for potentially busy calls like resize.

jglogan · 2026-02-19T03:27:48Z

Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift

-        try await lock.withLock { context in
+    public func withContainerList<T: Sendable>(
+        logMetadata: Logger.Metadata? = nil,
+        _ operation: @Sendable @escaping ([ContainerSnapshot]) async throws -> T


Allows us to trace locks from callers in other services using withContainerList(logMetadata:) { ... }

jglogan · 2026-02-19T03:29:08Z

Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift

    /// - 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


Our pattern for tracking ContainersService lock usage.

jglogan · 2026-02-19T03:30:37Z

Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift

            "--uuid", configuration.id,
-            "--debug",
-        ]
+            debug ? "--debug" : nil,


Propagate debug flag from API service to runtime helper.

jglogan · 2026-02-19T03:31:42Z

Sources/Services/ContainerAPIService/Server/Networks/NetworksService.swift

            "--mode",
            configuration.mode.rawValue,
        ]
+        if debugHelpers {


Propagate debug flag from API server to network helpers.

jglogan · 2026-02-19T03:36:15Z

Tests/CLITests/Subcommands/Networks/TestCLINetwork.swift

 import Foundation
 import Testing

-@Suite(.serialized)


Turn these tests back on and run them in parallel again.

jglogan · 2026-02-19T03:38:58Z

Makefile

 CODESIGN_OPTS ?= --force --sign - --timestamp=none

 # Conditionally use a temporary data directory for integration tests
-ifeq ($(strip $(APP_ROOT)),)


Don't do this anymore since we'll want to add other options (--log-root) soon. Make it so we can accumulate startup options.

ajemory

Made a few change suggestions -- I think it makes sense to make error/warning level logs with multiple metadata params span multiple lines, but not necessarily tied to the change. Let me know what you think. Otherwise, the changes look great. Thanks for tackling this!

ajemory · 2026-02-19T17:18:47Z

Sources/ContainerCommands/Network/NetworkPrune.swift

                    // 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)"])


Suggested change

log.error("failed to prune network", metadata: ["id": "\(network.id)", "error": "\(error)"])

log.error(

"failed to prune network",

metadata: [

"id": "\(network.id)",

"error": "\(error)",

])

This is reasonable. Let me do it in the follow-up (log collection PR) so we can start unblocking the PR backlog.

ajemory · 2026-02-19T17:24:15Z

Sources/Helpers/Images/ImagesHelper.swift

                try await xpc.listen()
            } catch {
-                log.error("\(commandName) failed", metadata: ["error": "\(error)"])
+                log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"])


Suggested change

log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"])

log.error(

"helper failed",

metadata: [

"name": "\(commandName)",

"error": "\(error)",

])

ajemory · 2026-02-19T17:25:36Z

Sources/Helpers/NetworkVmnet/NetworkVmnetHelper+Start.swift

                try await xpc.listen()
            } catch {
-                log.error("\(commandName) failed", metadata: ["error": "\(error)"])
+                log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"])


Suggested change

log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"])

log.error(

"helper failed",

metadata: [

"name": "\(commandName)",

"error": "\(error)",

])

ajemory · 2026-02-19T17:26:16Z

Sources/Helpers/RuntimeLinux/RuntimeLinuxHelper+Start.swift

                }
            } catch {
-                log.error("\(commandName) failed", metadata: ["error": "\(error)"])
+                log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"])


Suggested change

log.error("helper failed", metadata: ["name": "\(commandName)", "error": "\(error)"])

log.error(

"helper failed",

metadata: [

"name": "\(commandName)",

"error": "\(error)",

])

ajemory · 2026-02-19T17:28:38Z

Sources/Services/ContainerAPIService/Server/Containers/ContainersService.swift

            } 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)"])


Suggested change

log.warning("failed to load container", metadata: ["path": "\(dir.path)", "error": "\(error)"])

log.warning(

"failed to load container",

metadata: [

"path": "\(dir.path)",

"error": "\(error)",

])

github-actions bot added the cli label Feb 19, 2026

jglogan commented Feb 19, 2026

View reviewed changes

jglogan added 2 commits February 18, 2026 19:40

CZ 0.26.1 to fix tests, and self-review fixes.

d8e38ab

Remove test print.

baf9cb6

jglogan mentioned this pull request Feb 19, 2026

Honor APP_ROOT when installing locally built vminit image. #1186

Closed

Fix commandName for RuntimeLinuxHelper+Start.

b61cf0d

ajemory reviewed Feb 19, 2026

View reviewed changes

ajemory approved these changes Feb 19, 2026

View reviewed changes

jglogan merged commit 3ad0914 into apple:main Feb 19, 2026
3 checks passed

jglogan deleted the slow-launchd branch February 19, 2026 17:58

Conversation

jglogan commented Feb 19, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ajemory left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

jglogan commented Feb 19, 2026 •

edited

Loading