Skip to content

Commit e8e84e7

Browse files
mafredrimafredri
committed
feat(agent): send devcontainer CLI logs to coderd during recreate
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 4d00b76 commit e8e84e7

File tree

7 files changed

+321
-25
lines changed

7 files changed

+321
-25
lines changed

‎agent/agent_test.go

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

‎agent/agentcontainers/api.go

Lines changed: 62 additions & 7 deletions
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,23 @@ 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+
}
101115
}
102116
}
103117
}
@@ -112,6 +126,27 @@ func WithWatcher(w watcher.Watcher) Option {
112126
}
113127
}
114128

129+
// ScriptLogger is an interface for sending devcontainer logs to the
130+
// controlplane.
131+
type ScriptLogger interface {
132+
Send(ctx context.Context, log ...agentsdk.Log) error
133+
Flush(context.Context) error
134+
}
135+
136+
// noopScriptLogger is a no-op implementation of the ScriptLogger
137+
// interface.
138+
type noopScriptLogger struct{}
139+
140+
func (noopScriptLogger) Send(ctx context.Context, log ...agentsdk.Log) error { return nil }
141+
func (noopScriptLogger) Flush(ctx context.Context) error { return nil }
142+
143+
// WithScriptLogger sets the script logger provider for devcontainer operations.
144+
func WithScriptLogger(scriptLogger func(logSourceID uuid.UUID) ScriptLogger) Option {
145+
return func(api *API) {
146+
api.scriptLogger = scriptLogger
147+
}
148+
}
149+
115150
// NewAPI returns a new API with the given options applied.
116151
func NewAPI(logger slog.Logger, options ...Option) *API {
117152
ctx, cancel := context.WithCancel(context.Background())
@@ -127,6 +162,7 @@ func NewAPI(logger slog.Logger, options ...Option) *API {
127162
devcontainerNames: make(map[string]struct{}),
128163
knownDevcontainers: []codersdk.WorkspaceAgentDevcontainer{},
129164
configFileModifiedTimes: make(map[string]time.Time),
165+
scriptLogger: func(uuid.UUID) ScriptLogger { return noopScriptLogger{} },
130166
}
131167
for _, opt := range options {
132168
opt(api)
@@ -423,7 +459,26 @@ func (api *API) handleRecreate(w http.ResponseWriter, r *http.Request) {
423459
return
424460
}
425461

426-
_, err = api.dccli.Up(ctx, workspaceFolder, configPath, WithRemoveExistingContainer())
462+
// Send logs via agent logging facilities.
463+
logSourceID := api.devcontainerLogSourceIDs[workspaceFolder]
464+
if logSourceID == uuid.Nil {
465+
// Fallback to the external log source ID if not found.
466+
logSourceID = agentsdk.ExternalLogSourceID
467+
}
468+
scriptLogger := api.scriptLogger(logSourceID)
469+
defer func() {
470+
flushCtx, cancel := context.WithTimeout(api.ctx, 5*time.Second)
471+
defer cancel()
472+
if err := scriptLogger.Flush(flushCtx); err != nil {
473+
api.logger.Error(flushCtx, "flush devcontainer logs failed", slog.Error(err))
474+
}
475+
}()
476+
infoW := agentsdk.LogsWriter(ctx, scriptLogger.Send, logSourceID, codersdk.LogLevelInfo)
477+
defer infoW.Close()
478+
errW := agentsdk.LogsWriter(ctx, scriptLogger.Send, logSourceID, codersdk.LogLevelError)
479+
defer errW.Close()
480+
481+
_, err = api.dccli.Up(ctx, workspaceFolder, configPath, WithOutput(infoW, errW), WithRemoveExistingContainer())
427482
if err != nil {
428483
httpapi.Write(ctx, w, http.StatusInternalServerError, codersdk.Response{
429484
Message: "Could not recreate devcontainer",

‎agent/agentcontainers/api_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -564,7 +564,7 @@ func TestAPI(t *testing.T) {
564564
}
565565

566566
if len(tt.knownDevcontainers) > 0 {
567-
apiOptions = append(apiOptions, agentcontainers.WithDevcontainers(tt.knownDevcontainers))
567+
apiOptions = append(apiOptions, agentcontainers.WithDevcontainers(tt.knownDevcontainers, nil))
568568
}
569569

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

0 commit comments

Comments
 (0)