Skip to content

Commit 3de0003

Browse files
mafredrimafredri
authored
feat(agent): send devcontainer CLI logs during recreate (#17845)
We need a way to surface what's happening to the user, since autostart logs here, it's natural we do so during re-create as well. Updates #16424
1 parent 6e1ba75 commit 3de0003

File tree

7 files changed

+342
-25
lines changed

7 files changed

+342
-25
lines changed

‎agent/agent_test.go

+175-11
Original file line numberDiff line numberDiff line change
@@ -1935,8 +1935,6 @@ func TestAgent_ReconnectingPTYContainer(t *testing.T) {
19351935
t.Skip("Set CODER_TEST_USE_DOCKER=1 to run this test")
19361936
}
19371937

1938-
ctx := testutil.Context(t, testutil.WaitLong)
1939-
19401938
pool, err := dockertest.NewPool("")
19411939
require.NoError(t, err, "Could not connect to docker")
19421940
ct, err := pool.RunWithOptions(&dockertest.RunOptions{
@@ -1948,10 +1946,10 @@ func TestAgent_ReconnectingPTYContainer(t *testing.T) {
19481946
config.RestartPolicy = docker.RestartPolicy{Name: "no"}
19491947
})
19501948
require.NoError(t, err, "Could not start container")
1951-
t.Cleanup(func() {
1949+
defer func() {
19521950
err := pool.Purge(ct)
19531951
require.NoError(t, err, "Could not stop container")
1954-
})
1952+
}()
19551953
// Wait for container to start
19561954
require.Eventually(t, func() bool {
19571955
ct, ok := pool.ContainerByName(ct.Container.Name)
@@ -1962,6 +1960,7 @@ func TestAgent_ReconnectingPTYContainer(t *testing.T) {
19621960
conn, _, _, _, _ := setupAgent(t, agentsdk.Manifest{}, 0, func(_ *agenttest.Client, o *agent.Options) {
19631961
o.ExperimentalDevcontainersEnabled = true
19641962
})
1963+
ctx := testutil.Context(t, testutil.WaitLong)
19651964
ac, err := conn.ReconnectingPTY(ctx, uuid.New(), 80, 80, "/bin/sh", func(arp *workspacesdk.AgentReconnectingPTYInit) {
19661965
arp.Container = ct.Container.ID
19671966
})
@@ -2005,9 +2004,6 @@ func TestAgent_DevcontainerAutostart(t *testing.T) {
20052004
t.Skip("Set CODER_TEST_USE_DOCKER=1 to run this test")
20062005
}
20072006

2008-
ctx := testutil.Context(t, testutil.WaitLong)
2009-
2010-
// Connect to Docker
20112007
pool, err := dockertest.NewPool("")
20122008
require.NoError(t, err, "Could not connect to docker")
20132009

@@ -2051,7 +2047,7 @@ func TestAgent_DevcontainerAutostart(t *testing.T) {
20512047
},
20522048
},
20532049
}
2054-
// nolint: dogsled
2050+
//nolint:dogsled
20552051
conn, _, _, _, _ := setupAgent(t, manifest, 0, func(_ *agenttest.Client, o *agent.Options) {
20562052
o.ExperimentalDevcontainersEnabled = true
20572053
})
@@ -2079,8 +2075,7 @@ func TestAgent_DevcontainerAutostart(t *testing.T) {
20792075

20802076
return false
20812077
}, testutil.WaitSuperLong, testutil.IntervalMedium, "no container with workspace folder label found")
2082-
2083-
t.Cleanup(func() {
2078+
defer func() {
20842079
// We can't rely on pool here because the container is not
20852080
// managed by it (it is managed by @devcontainer/cli).
20862081
err := pool.Client.RemoveContainer(docker.RemoveContainerOptions{
@@ -2089,13 +2084,15 @@ func TestAgent_DevcontainerAutostart(t *testing.T) {
20892084
Force: true,
20902085
})
20912086
assert.NoError(t, err, "remove container")
2092-
})
2087+
}()
20932088

20942089
containerInfo, err := pool.Client.InspectContainer(container.ID)
20952090
require.NoError(t, err, "inspect container")
20962091
t.Logf("Container state: status: %v", containerInfo.State.Status)
20972092
require.True(t, containerInfo.State.Running, "container should be running")
20982093

2094+
ctx := testutil.Context(t, testutil.WaitLong)
2095+
20992096
ac, err := conn.ReconnectingPTY(ctx, uuid.New(), 80, 80, "", func(opts *workspacesdk.AgentReconnectingPTYInit) {
21002097
opts.Container = container.ID
21012098
})
@@ -2124,6 +2121,173 @@ func TestAgent_DevcontainerAutostart(t *testing.T) {
21242121
require.NoError(t, err, "file should exist outside devcontainer")
21252122
}
21262123

2124+
// TestAgent_DevcontainerRecreate tests that RecreateDevcontainer
2125+
// recreates a devcontainer and emits logs.
2126+
//
2127+
// This tests end-to-end functionality of auto-starting a devcontainer.
2128+
// It runs "devcontainer up" which creates a real Docker container. As
2129+
// such, it does not run by default in CI.
2130+
//
2131+
// You can run it manually as follows:
2132+
//
2133+
// CODER_TEST_USE_DOCKER=1 go test -count=1 ./agent -run TestAgent_DevcontainerRecreate
2134+
func TestAgent_DevcontainerRecreate(t *testing.T) {
2135+
if os.Getenv("CODER_TEST_USE_DOCKER") != "1" {
2136+
t.Skip("Set CODER_TEST_USE_DOCKER=1 to run this test")
2137+
}
2138+
t.Parallel()
2139+
2140+
pool, err := dockertest.NewPool("")
2141+
require.NoError(t, err, "Could not connect to docker")
2142+
2143+
// Prepare temporary devcontainer for test (mywork).
2144+
devcontainerID := uuid.New()
2145+
devcontainerLogSourceID := uuid.New()
2146+
workspaceFolder := filepath.Join(t.TempDir(), "mywork")
2147+
t.Logf("Workspace folder: %s", workspaceFolder)
2148+
devcontainerPath := filepath.Join(workspaceFolder, ".devcontainer")
2149+
err = os.MkdirAll(devcontainerPath, 0o755)
2150+
require.NoError(t, err, "create devcontainer directory")
2151+
devcontainerFile := filepath.Join(devcontainerPath, "devcontainer.json")
2152+
err = os.WriteFile(devcontainerFile, []byte(`{
2153+
"name": "mywork",
2154+
"image": "busybox:latest",
2155+
"cmd": ["sleep", "infinity"]
2156+
}`), 0o600)
2157+
require.NoError(t, err, "write devcontainer.json")
2158+
2159+
manifest := agentsdk.Manifest{
2160+
// Set up pre-conditions for auto-starting a devcontainer, the
2161+
// script is used to extract the log source ID.
2162+
Devcontainers: []codersdk.WorkspaceAgentDevcontainer{
2163+
{
2164+
ID: devcontainerID,
2165+
Name: "test",
2166+
WorkspaceFolder: workspaceFolder,
2167+
},
2168+
},
2169+
Scripts: []codersdk.WorkspaceAgentScript{
2170+
{
2171+
ID: devcontainerID,
2172+
LogSourceID: devcontainerLogSourceID,
2173+
},
2174+
},
2175+
}
2176+
2177+
//nolint:dogsled
2178+
conn, client, _, _, _ := setupAgent(t, manifest, 0, func(_ *agenttest.Client, o *agent.Options) {
2179+
o.ExperimentalDevcontainersEnabled = true
2180+
})
2181+
2182+
ctx := testutil.Context(t, testutil.WaitLong)
2183+
2184+
// We enabled autostart for the devcontainer, so ready is a good
2185+
// indication that the devcontainer is up and running. Importantly,
2186+
// this also means that the devcontainer startup is no longer
2187+
// producing logs that may interfere with the recreate logs.
2188+
testutil.Eventually(ctx, t, func(context.Context) bool {
2189+
states := client.GetLifecycleStates()
2190+
return slices.Contains(states, codersdk.WorkspaceAgentLifecycleReady)
2191+
}, testutil.IntervalMedium, "devcontainer not ready")
2192+
2193+
t.Logf("Looking for container with label: devcontainer.local_folder=%s", workspaceFolder)
2194+
2195+
var container docker.APIContainers
2196+
testutil.Eventually(ctx, t, func(context.Context) bool {
2197+
containers, err := pool.Client.ListContainers(docker.ListContainersOptions{All: true})
2198+
if err != nil {
2199+
t.Logf("Error listing containers: %v", err)
2200+
return false
2201+
}
2202+
for _, c := range containers {
2203+
t.Logf("Found container: %s with labels: %v", c.ID[:12], c.Labels)
2204+
if v, ok := c.Labels["devcontainer.local_folder"]; ok && v == workspaceFolder {
2205+
t.Logf("Found matching container: %s", c.ID[:12])
2206+
container = c
2207+
return true
2208+
}
2209+
}
2210+
return false
2211+
}, testutil.IntervalMedium, "no container with workspace folder label found")
2212+
defer func(container docker.APIContainers) {
2213+
// We can't rely on pool here because the container is not
2214+
// managed by it (it is managed by @devcontainer/cli).
2215+
err := pool.Client.RemoveContainer(docker.RemoveContainerOptions{
2216+
ID: container.ID,
2217+
RemoveVolumes: true,
2218+
Force: true,
2219+
})
2220+
assert.Error(t, err, "container should be removed by recreate")
2221+
}(container)
2222+
2223+
ctx = testutil.Context(t, testutil.WaitLong) // Reset context.
2224+
2225+
// Capture logs via ScriptLogger.
2226+
logsCh := make(chan *proto.BatchCreateLogsRequest, 1)
2227+
client.SetLogsChannel(logsCh)
2228+
2229+
// Invoke recreate to trigger the destruction and recreation of the
2230+
// devcontainer, we do it in a goroutine so we can process logs
2231+
// concurrently.
2232+
go func(container docker.APIContainers) {
2233+
err := conn.RecreateDevcontainer(ctx, container.ID)
2234+
assert.NoError(t, err, "recreate devcontainer should succeed")
2235+
}(container)
2236+
2237+
t.Logf("Checking recreate logs for outcome...")
2238+
2239+
// Wait for the logs to be emitted, the @devcontainer/cli up command
2240+
// will emit a log with the outcome at the end suggesting we did
2241+
// receive all the logs.
2242+
waitForOutcomeLoop:
2243+
for {
2244+
batch := testutil.RequireReceive(ctx, t, logsCh)
2245+
2246+
if bytes.Equal(batch.LogSourceId, devcontainerLogSourceID[:]) {
2247+
for _, log := range batch.Logs {
2248+
t.Logf("Received log: %s", log.Output)
2249+
if strings.Contains(log.Output, "\"outcome\"") {
2250+
break waitForOutcomeLoop
2251+
}
2252+
}
2253+
}
2254+
}
2255+
2256+
t.Logf("Checking there's a new container with label: devcontainer.local_folder=%s", workspaceFolder)
2257+
2258+
// Make sure the container exists and isn't the same as the old one.
2259+
testutil.Eventually(ctx, t, func(context.Context) bool {
2260+
containers, err := pool.Client.ListContainers(docker.ListContainersOptions{All: true})
2261+
if err != nil {
2262+
t.Logf("Error listing containers: %v", err)
2263+
return false
2264+
}
2265+
for _, c := range containers {
2266+
t.Logf("Found container: %s with labels: %v", c.ID[:12], c.Labels)
2267+
if v, ok := c.Labels["devcontainer.local_folder"]; ok && v == workspaceFolder {
2268+
if c.ID == container.ID {
2269+
t.Logf("Found same container: %s", c.ID[:12])
2270+
return false
2271+
}
2272+
t.Logf("Found new container: %s", c.ID[:12])
2273+
container = c
2274+
return true
2275+
}
2276+
}
2277+
return false
2278+
}, testutil.IntervalMedium, "new devcontainer not found")
2279+
defer func(container docker.APIContainers) {
2280+
// We can't rely on pool here because the container is not
2281+
// managed by it (it is managed by @devcontainer/cli).
2282+
err := pool.Client.RemoveContainer(docker.RemoveContainerOptions{
2283+
ID: container.ID,
2284+
RemoveVolumes: true,
2285+
Force: true,
2286+
})
2287+
assert.NoError(t, err, "remove container")
2288+
}(container)
2289+
}
2290+
21272291
func TestAgent_Dial(t *testing.T) {
21282292
t.Parallel()
21292293

‎agent/agentcontainers/api.go

+71-7
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ import (
2020
"github.com/coder/coder/v2/agent/agentexec"
2121
"github.com/coder/coder/v2/coderd/httpapi"
2222
"github.com/coder/coder/v2/codersdk"
23+
"github.com/coder/coder/v2/codersdk/agentsdk"
2324
"github.com/coder/quartz"
2425
)
2526

@@ -43,6 +44,7 @@ type API struct {
4344
cl Lister
4445
dccli DevcontainerCLI
4546
clock quartz.Clock
47+
scriptLogger func(logSourceID uuid.UUID) ScriptLogger
4648

4749
// lockCh protects the below fields. We use a channel instead of a
4850
// mutex so we can handle cancellation properly.
@@ -52,6 +54,8 @@ type API struct {
5254
devcontainerNames map[string]struct{} // Track devcontainer names to avoid duplicates.
5355
knownDevcontainers []codersdk.WorkspaceAgentDevcontainer // Track predefined and runtime-detected devcontainers.
5456
configFileModifiedTimes map[string]time.Time // Track when config files were last modified.
57+
58+
devcontainerLogSourceIDs map[string]uuid.UUID // Track devcontainer log source IDs.
5559
}
5660

5761
// Option is a functional option for API.
@@ -91,13 +95,30 @@ func WithDevcontainerCLI(dccli DevcontainerCLI) Option {
9195
// WithDevcontainers sets the known devcontainers for the API. This
9296
// allows the API to be aware of devcontainers defined in the workspace
9397
// agent manifest.
94-
func WithDevcontainers(devcontainers []codersdk.WorkspaceAgentDevcontainer) Option {
98+
func WithDevcontainers(devcontainers []codersdk.WorkspaceAgentDevcontainer, scripts []codersdk.WorkspaceAgentScript) Option {
9599
return func(api *API) {
96-
if len(devcontainers) > 0 {
97-
api.knownDevcontainers = slices.Clone(devcontainers)
98-
api.devcontainerNames = make(map[string]struct{}, len(devcontainers))
99-
for _, devcontainer := range devcontainers {
100-
api.devcontainerNames[devcontainer.Name] = struct{}{}
100+
if len(devcontainers) == 0 {
101+
return
102+
}
103+
api.knownDevcontainers = slices.Clone(devcontainers)
104+
api.devcontainerNames = make(map[string]struct{}, len(devcontainers))
105+
api.devcontainerLogSourceIDs = make(map[string]uuid.UUID)
106+
for _, devcontainer := range devcontainers {
107+
api.devcontainerNames[devcontainer.Name] = struct{}{}
108+
for _, script := range scripts {
109+
// The devcontainer scripts match the devcontainer ID for
110+
// identification.
111+
if script.ID == devcontainer.ID {
112+
api.devcontainerLogSourceIDs[devcontainer.WorkspaceFolder] = script.LogSourceID
113+
break
114+
}
115+
}
116+
if api.devcontainerLogSourceIDs[devcontainer.WorkspaceFolder] == uuid.Nil {
117+
api.logger.Error(api.ctx, "devcontainer log source ID not found for devcontainer",
118+
slog.F("devcontainer", devcontainer.Name),
119+
slog.F("workspace_folder", devcontainer.WorkspaceFolder),
120+
slog.F("config_path", devcontainer.ConfigPath),
121+
)
101122
}
102123
}
103124
}
@@ -112,6 +133,27 @@ func WithWatcher(w watcher.Watcher) Option {
112133
}
113134
}
114135

136+
// ScriptLogger is an interface for sending devcontainer logs to the
137+
// controlplane.
138+
type ScriptLogger interface {
139+
Send(ctx context.Context, log ...agentsdk.Log) error
140+
Flush(ctx context.Context) error
141+
}
142+
143+
// noopScriptLogger is a no-op implementation of the ScriptLogger
144+
// interface.
145+
type noopScriptLogger struct{}
146+
147+
func (noopScriptLogger) Send(context.Context, ...agentsdk.Log) error { return nil }
148+
func (noopScriptLogger) Flush(context.Context) error { return nil }
149+
150+
// WithScriptLogger sets the script logger provider for devcontainer operations.
151+
func WithScriptLogger(scriptLogger func(logSourceID uuid.UUID) ScriptLogger) Option {
152+
return func(api *API) {
153+
api.scriptLogger = scriptLogger
154+
}
155+
}
156+
115157
// NewAPI returns a new API with the given options applied.
116158
func NewAPI(logger slog.Logger, options ...Option) *API {
117159
ctx, cancel := context.WithCancel(context.Background())
@@ -127,7 +169,10 @@ func NewAPI(logger slog.Logger, options ...Option) *API {
127169
devcontainerNames: make(map[string]struct{}),
128170
knownDevcontainers: []codersdk.WorkspaceAgentDevcontainer{},
129171
configFileModifiedTimes: make(map[string]time.Time),
172+
scriptLogger: func(uuid.UUID) ScriptLogger { return noopScriptLogger{} },
130173
}
174+
// The ctx and logger must be set before applying options to avoid
175+
// nil pointer dereference.
131176
for _, opt := range options {
132177
opt(api)
133178
}
@@ -426,7 +471,26 @@ func (api *API) handleDevcontainerRecreate(w http.ResponseWriter, r *http.Reques
426471
return
427472
}
428473

429-
_, err = api.dccli.Up(ctx, workspaceFolder, configPath, WithRemoveExistingContainer())
474+
// Send logs via agent logging facilities.
475+
logSourceID := api.devcontainerLogSourceIDs[workspaceFolder]
476+
if logSourceID == uuid.Nil {
477+
// Fallback to the external log source ID if not found.
478+
logSourceID = agentsdk.ExternalLogSourceID
479+
}
480+
scriptLogger := api.scriptLogger(logSourceID)
481+
defer func() {
482+
flushCtx, cancel := context.WithTimeout(api.ctx, 5*time.Second)
483+
defer cancel()
484+
if err := scriptLogger.Flush(flushCtx); err != nil {
485+
api.logger.Error(flushCtx, "flush devcontainer logs failed", slog.Error(err))
486+
}
487+
}()
488+
infoW := agentsdk.LogsWriter(ctx, scriptLogger.Send, logSourceID, codersdk.LogLevelInfo)
489+
defer infoW.Close()
490+
errW := agentsdk.LogsWriter(ctx, scriptLogger.Send, logSourceID, codersdk.LogLevelError)
491+
defer errW.Close()
492+
493+
_, err = api.dccli.Up(ctx, workspaceFolder, configPath, WithOutput(infoW, errW), WithRemoveExistingContainer())
430494
if err != nil {
431495
httpapi.Write(ctx, w, http.StatusInternalServerError, codersdk.Response{
432496
Message: "Could not recreate devcontainer",

‎agent/agentcontainers/api_test.go

+10-1
Original file line numberDiff line numberDiff line change
@@ -563,8 +563,17 @@ func TestAPI(t *testing.T) {
563563
agentcontainers.WithWatcher(watcher.NewNoop()),
564564
}
565565

566+
// Generate matching scripts for the known devcontainers
567+
// (required to extract log source ID).
568+
var scripts []codersdk.WorkspaceAgentScript
569+
for i := range tt.knownDevcontainers {
570+
scripts = append(scripts, codersdk.WorkspaceAgentScript{
571+
ID: tt.knownDevcontainers[i].ID,
572+
LogSourceID: uuid.New(),
573+
})
574+
}
566575
if len(tt.knownDevcontainers) > 0 {
567-
apiOptions = append(apiOptions, agentcontainers.WithDevcontainers(tt.knownDevcontainers))
576+
apiOptions = append(apiOptions, agentcontainers.WithDevcontainers(tt.knownDevcontainers, scripts))
568577
}
569578

570579
api := agentcontainers.NewAPI(logger, apiOptions...)

0 commit comments

Comments
 (0)