Skip to content

Commit 3ad0914

Browse files
authored
Fix CI integration test coldstart issues. (#1230)
- Closes #1206. - Closes #1185. - Closes #507. - Addresses existing log messages for #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.
1 parent d100ec9 commit 3ad0914

35 files changed

Lines changed: 1208 additions & 200 deletions

File tree

Makefile

Lines changed: 30 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -33,10 +33,9 @@ DSYM_PATH := bin/$(BUILD_CONFIGURATION)/bundle/container-dSYM.zip
3333
CODESIGN_OPTS ?= --force --sign - --timestamp=none
3434

3535
# Conditionally use a temporary data directory for integration tests
36-
ifeq ($(strip $(APP_ROOT)),)
37-
SYSTEM_START_OPTS :=
38-
else
39-
SYSTEM_START_OPTS := --app-root "$(strip $(APP_ROOT))"
36+
SYSTEM_START_OPTS :=
37+
ifneq ($(strip $(APP_ROOT)),)
38+
SYSTEM_START_OPTS += --app-root "$(strip $(APP_ROOT))"
4039
endif
4140

4241
MACOS_VERSION := $(shell sw_vers -productVersion)
@@ -77,7 +76,8 @@ release: all
7776

7877
.PHONY: init-block
7978
init-block:
80-
@scripts/install-init.sh
79+
@echo Building initfs if containerization is in edit mode
80+
@scripts/install-init.sh $(SYSTEM_START_OPTS)
8181

8282
.PHONY: install
8383
install: installer-pkg
@@ -144,15 +144,17 @@ test:
144144

145145
.PHONY: install-kernel
146146
install-kernel:
147+
@echo Stopping system before installing kernel
147148
@bin/container system stop || true
148-
@bin/container system start --timeout 60 --enable-kernel-install $(SYSTEM_START_OPTS)
149+
@echo Starting system to install kernel
150+
@bin/container --debug system start --timeout 60 --enable-kernel-install $(SYSTEM_START_OPTS)
149151

150152
.PHONY: coverage
151153
coverage: init-block
152-
@echo Ensuring apiserver stopped before the CLI integration tests...
154+
@echo Ensuring apiserver stopped before the coverage analysis
153155
@bin/container system stop && sleep 3 && scripts/ensure-container-stopped.sh
154-
@bin/container system start $(SYSTEM_START_OPTS) && \
155-
echo "Starting unit tests" && \
156+
@bin/container --debug system start $(SYSTEM_START_OPTS) && \
157+
echo "Starting coverage analysis" && \
156158
{ \
157159
exit_code=0; \
158160
$(SWIFT) test --no-parallel --enable-code-coverage -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) || exit_code=1 ; \
@@ -176,28 +178,28 @@ integration: init-block
176178
@echo Ensuring apiserver stopped before the CLI integration tests...
177179
@bin/container system stop && sleep 3 && scripts/ensure-container-stopped.sh
178180
@echo Running the integration tests...
179-
@bin/container system start --timeout 60 $(SYSTEM_START_OPTS) && \
181+
@bin/container --debug system start --timeout 60 $(SYSTEM_START_OPTS) && \
180182
echo "Starting CLI integration tests" && \
181183
{ \
182184
exit_code=0; \
183-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLINetwork || exit_code=1 ; \
184-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunLifecycle || exit_code=1 ; \
185-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIExecCommand || exit_code=1 ; \
186-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLICreateCommand || exit_code=1 ; \
187-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand1 || exit_code=1 ; \
188-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand2 || exit_code=1 ; \
189-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand3 || exit_code=1 ; \
190-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIPruneCommand || exit_code=1 ; \
191-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRegistry || exit_code=1 ; \
192-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIStatsCommand || exit_code=1 ; \
193-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIImagesCommand || exit_code=1 ; \
194-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunBase || exit_code=1 ; \
195-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunInitImage || exit_code=1 ; \
196-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIBuildBase || exit_code=1 ; \
197-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIVolumes || exit_code=1 ; \
198-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIKernelSet || exit_code=1 ; \
199-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIAnonymousVolumes || exit_code=1 ; \
200-
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLINoParallelCases || exit_code=1 ; \
185+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLINetwork || exit_code=1 ; \
186+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunLifecycle || exit_code=1 ; \
187+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIExecCommand || exit_code=1 ; \
188+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLICreateCommand || exit_code=1 ; \
189+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand1 || exit_code=1 ; \
190+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand2 || exit_code=1 ; \
191+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunCommand3 || exit_code=1 ; \
192+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIPruneCommand || exit_code=1 ; \
193+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRegistry || exit_code=1 ; \
194+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIStatsCommand || exit_code=1 ; \
195+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIImagesCommand || exit_code=1 ; \
196+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunBase || exit_code=1 ; \
197+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIRunInitImage || exit_code=1 ; \
198+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIBuildBase || exit_code=1 ; \
199+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIVolumes || exit_code=1 ; \
200+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIKernelSet || exit_code=1 ; \
201+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLIAnonymousVolumes || exit_code=1 ; \
202+
$(SWIFT) test -c $(BUILD_CONFIGURATION) $(SWIFT_CONFIGURATION) --filter TestCLINoParallelCases || exit_code=1 ; \
201203
echo Ensuring apiserver stopped after the CLI integration tests ; \
202204
scripts/ensure-container-stopped.sh ; \
203205
exit $${exit_code} ; \

Package.resolved

Lines changed: 3 additions & 3 deletions
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

Package.swift

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,7 @@ import PackageDescription
2323
let releaseVersion = ProcessInfo.processInfo.environment["RELEASE_VERSION"] ?? "0.0.0"
2424
let gitCommit = ProcessInfo.processInfo.environment["GIT_COMMIT"] ?? "unspecified"
2525
let builderShimVersion = "0.8.0"
26-
let scVersion = "0.25.0"
26+
let scVersion = "0.26.1"
2727

2828
let package = Package(
2929
name: "container",
@@ -98,6 +98,7 @@ let package = Package(
9898
"ContainerPlugin",
9999
"ContainerResource",
100100
"ContainerVersion",
101+
"ContainerXPC",
101102
"TerminalProgress",
102103
],
103104
path: "Sources/ContainerCommands"

Sources/ContainerCommands/Container/ContainerPrune.swift

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -45,7 +45,12 @@ extension Application {
4545
try await client.delete(id: container.id)
4646
prunedContainerIds.append(container.id)
4747
} catch {
48-
log.error("Failed to prune container \(container.id): \(error)")
48+
log.error(
49+
"failed to prune container",
50+
metadata: [
51+
"id": "\(container.id)",
52+
"error": "\(error)",
53+
])
4954
}
5055
}
5156

Sources/ContainerCommands/Image/ImagePrune.swift

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -61,7 +61,12 @@ extension Application {
6161
try await ClientImage.delete(reference: image.reference, garbageCollect: false)
6262
prunedImages.append(image.reference)
6363
} catch {
64-
log.error("Failed to prune image \(image.reference): \(error)")
64+
log.error(
65+
"failed to prune image",
66+
metadata: [
67+
"ref": "\(image.reference)",
68+
"error": "\(error)",
69+
])
6570
}
6671
}
6772

Sources/ContainerCommands/Network/NetworkPrune.swift

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -55,7 +55,7 @@ extension Application.NetworkCommand {
5555
// Note: This failure may occur due to a race condition between the network/
5656
// container collection above and a container run command that attaches to a
5757
// network listed in the networksToPrune collection.
58-
log.error("Failed to prune network \(network.id): \(error)")
58+
log.error("failed to prune network", metadata: ["id": "\(network.id)", "error": "\(error)"])
5959
}
6060
}
6161

Sources/ContainerCommands/System/SystemLogs.swift

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -58,7 +58,7 @@ extension Application {
5858
do {
5959
var args = ["log"]
6060
args.append(self.follow ? "stream" : "show")
61-
args.append(contentsOf: ["--info", "--debug"])
61+
args.append(contentsOf: ["--info", logOptions.debug ? "--debug" : nil].compactMap { $0 })
6262
if !self.follow {
6363
args.append(contentsOf: ["--last", last])
6464
}

Sources/ContainerCommands/System/SystemStart.swift

Lines changed: 12 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ import ArgumentParser
1818
import ContainerAPIClient
1919
import ContainerPersistence
2020
import ContainerPlugin
21+
import ContainerXPC
2122
import ContainerizationError
2223
import Foundation
2324
import TerminalProgress
@@ -48,9 +49,15 @@ extension Application {
4849
var kernelInstall: Bool?
4950

5051
@Option(
51-
name: .long,
52-
help: "Number of seconds to wait for API service to become responsive")
53-
var timeout: Double = 10.0
52+
help: "Number of seconds to wait for API service to become responsive",
53+
transform: {
54+
guard let timeoutSeconds = Double($0) else {
55+
throw ValidationError("Invalid timeout value: \($0)")
56+
}
57+
return .seconds(timeoutSeconds)
58+
}
59+
)
60+
var timeout: Duration = XPCClient.xpcRegistrationTimeout
5461

5562
@OptionGroup
5663
public var logOptions: Flags.Logging
@@ -98,7 +105,7 @@ extension Application {
98105
// Now ping our friendly daemon. Fail if we don't get a response.
99106
do {
100107
print("Verifying apiserver is running...")
101-
_ = try await ClientHealthCheck.ping(timeout: .seconds(timeout))
108+
_ = try await ClientHealthCheck.ping(timeout: timeout)
102109
} catch {
103110
throw ContainerizationError(
104111
.internalError,
@@ -124,7 +131,7 @@ extension Application {
124131
do {
125132
try await pullCommand.run()
126133
} catch {
127-
log.error("failed to install base container filesystem: \(error)")
134+
log.error("failed to install base container filesystem", metadata: ["error": "\(error)"])
128135
}
129136
}
130137

Sources/ContainerCommands/Volume/VolumePrune.swift

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -57,7 +57,12 @@ extension Application.VolumeCommand {
5757
try await ClientVolume.delete(name: volume.name)
5858
prunedVolumes.append(volume.name)
5959
} catch {
60-
log.error("Failed to prune volume \(volume.name): \(error)")
60+
log.error(
61+
"failed to prune volume",
62+
metadata: [
63+
"id": "\(volume.name)",
64+
"error": "\(error)",
65+
])
6166
}
6267
}
6368

Sources/ContainerPlugin/PluginLoader.swift

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -206,7 +206,8 @@ extension PluginLoader {
206206
plugin: Plugin,
207207
pluginStateRoot: URL? = nil,
208208
args: [String]? = nil,
209-
instanceId: String? = nil
209+
instanceId: String? = nil,
210+
debug: Bool = false,
210211
) throws {
211212
// We only care about loading plugins that have a service
212213
// to expose; otherwise, they may just be CLI commands.
@@ -223,9 +224,10 @@ extension PluginLoader {
223224
env[ApplicationRoot.environmentName] = appRoot.path(percentEncoded: false)
224225
env[InstallRoot.environmentName] = installRoot.path(percentEncoded: false)
225226

227+
let processedArgs = (args ?? ["start"]) + (debug ? ["--debug"] : [])
226228
let plist = LaunchPlist(
227229
label: id,
228-
arguments: [plugin.binaryURL.path] + (args ?? ["start"]) + serviceConfig.defaultArguments,
230+
arguments: [plugin.binaryURL.path] + processedArgs + serviceConfig.defaultArguments,
229231
environment: env,
230232
limitLoadToSessionType: [.Aqua, .Background, .System],
231233
runAtLoad: serviceConfig.runAtLoad,

0 commit comments

Comments
 (0)