mirror of
https://github.com/coder/coder.git
synced 2026-10-16 14:48:56 +08:00
## What Runs the workspace agent logger at `Info` with a slog flight recorder (`v3.2.0`) instead of unconditionally at `Debug`. Entries below the current log level are kept in a rolling in-memory ring and flushed to the sinks when the agent loses its connection to coderd (and before any `Error`+ log), so the detail leading up to a failure is available without writing debug logs during normal operation. Implements CLIENT-672 (connection-log RFC req 13) for the workspace agent. Depends on the `cdr.dev/slog/v3` `v3.2.0` bump (already on `main`). ## How - `cli/agent.go`: - The main agent logger is `AppendSinks(...).Leveled(level).FlightRecorder(flightRecorderSize)`, where `level` is `Info` by default and `Debug` under the global `-v` / `CODER_VERBOSE`. The recorder is always attached; at `Debug` it is inert, which keeps the setup correct if the configured level changes in the future. The reaper logger is unchanged. - New `--agent-flight-recorder-size` / `CODER_AGENT_FLIGHT_RECORDER_SIZE` (default `1000`, `0` disables the flight recorder), so the ring size is configurable per RFC req 13. The agent flag is distinct from CLI-4's global `--flight-recorder-size` (#29752) so the two don't collide when `coder agent` inherits the root global. - `workspaceAgent` is a `RootCmd` method so it reuses the root command's global verbose flag instead of defining an agent-specific one. - `agent/agent.go` (`runLoop`): on a lost coderd connection (the `io.EOF` disconnect and the generic run error) the agent calls `logger.Flush(ctx)` to emit the recorded history and then logs at `Warn`. These are `Warn` rather than `Error` because reconnectable disconnects are expected and `slogtest` fails tests on any `Error` log; the manual flush is what surfaces the recorded detail. Graceful shutdown paths (`ctx` canceled, agent closed) are not flushed. - Tests: `agent.TestAgent_FlushFlightRecorderOnDisconnect` covers the flush-on-disconnect path; `cli.TestWorkspaceAgent/DisabledServers` runs with verbose since its debug messages are otherwise recorded. Golden `--help` output regenerated. ## Default log verbosity change This changes the default agent-log verbosity. Today `coder-agent.log` receives `Debug` unconditionally; with this change, normal operation logs `Info`, and recorded below-level entries are emitted only when the agent loses its coderd connection (via a manual flush) or before any `Error`+ log, or always under `-v` / `CODER_VERBOSE`. This is the intended behavior of the feature: a quiet steady state with full detail retained for diagnosing failures. Operators who want the previous always-debug output can run with `-v` / `CODER_VERBOSE`. ## Alignment with #29752 (CLI) This mirrors the CLI-4 (CLI log buffer) design so the two implementations agree: - **Level model:** Info by default, debug available on demand via the global `-v` / `CODER_VERBOSE`. - **Flight recorder size:** default `1000`, `0` disables. CLI-4 exposes a global `--flight-recorder-size`; the agent uses a distinct `--agent-flight-recorder-size` / `CODER_AGENT_FLIGHT_RECORDER_SIZE` (the `CODER_AGENT_*` env convention) so the inherited global and the agent flag coexist without collision. - **Flush trigger:** the recorded history is emitted before any `Error`+ log via slog's auto-flush. The agent additionally flushes manually on a lost coderd connection, which it logs at `Warn` (reconnectable, and `Error` would fail `slogtest`-based tests); the CLI's failures are fatal, so it relies on the auto-flush-on-error. <details> <summary>Rollout context</summary> Cross-repo sequence: coder/slog flight recorder (released as v3.2.0) -> go.mod bump in coder/coder (#29600, merged) -> this PR (CLIENT-672, agent) and CLI-4 (CLI), which are independent consumers and can merge in any order. </details> --- <sub>Opened by Coder Agents on behalf of @aqandrew.</sub>
260 lines
7.7 KiB
Go
260 lines
7.7 KiB
Go
package cli_test
|
|
|
|
import (
|
|
"fmt"
|
|
"net/http"
|
|
"os"
|
|
"path/filepath"
|
|
"runtime"
|
|
"strings"
|
|
"sync/atomic"
|
|
"testing"
|
|
|
|
"github.com/stretchr/testify/assert"
|
|
"github.com/stretchr/testify/require"
|
|
|
|
"github.com/coder/coder/v2/agent"
|
|
"github.com/coder/coder/v2/cli/clitest"
|
|
"github.com/coder/coder/v2/coderd"
|
|
"github.com/coder/coder/v2/coderd/coderdtest"
|
|
"github.com/coder/coder/v2/coderd/database"
|
|
"github.com/coder/coder/v2/coderd/database/dbfake"
|
|
"github.com/coder/coder/v2/codersdk"
|
|
"github.com/coder/coder/v2/testutil"
|
|
)
|
|
|
|
func TestWorkspaceAgent(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
t.Run("LogDirectory", func(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
client, db := coderdtest.NewWithDatabase(t, nil)
|
|
user := coderdtest.CreateFirstUser(t, client)
|
|
r := dbfake.WorkspaceBuild(t, db, database.WorkspaceTable{
|
|
OrganizationID: user.OrganizationID,
|
|
OwnerID: user.UserID,
|
|
}).
|
|
WithAgent().
|
|
Do()
|
|
logDir := t.TempDir()
|
|
inv, _ := clitest.New(t,
|
|
"agent",
|
|
"--auth", "token",
|
|
"--agent-token", r.AgentToken,
|
|
"--agent-url", client.URL.String(),
|
|
"--log-dir", logDir,
|
|
"--socket-path", testutil.AgentSocketPath(t),
|
|
)
|
|
|
|
clitest.Start(t, inv)
|
|
|
|
coderdtest.AwaitWorkspaceAgents(t, client, r.Workspace.ID)
|
|
|
|
require.Eventually(t, func() bool {
|
|
info, err := os.Stat(filepath.Join(logDir, "coder-agent.log"))
|
|
if err != nil {
|
|
return false
|
|
}
|
|
return info.Size() > 0
|
|
}, testutil.WaitLong, testutil.IntervalMedium)
|
|
})
|
|
|
|
t.Run("PostStartup", func(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
client, db := coderdtest.NewWithDatabase(t, nil)
|
|
user := coderdtest.CreateFirstUser(t, client)
|
|
r := dbfake.WorkspaceBuild(t, db, database.WorkspaceTable{
|
|
OrganizationID: user.OrganizationID,
|
|
OwnerID: user.UserID,
|
|
}).WithAgent().Do()
|
|
|
|
logDir := t.TempDir()
|
|
inv, _ := clitest.New(t,
|
|
"agent",
|
|
"--auth", "token",
|
|
"--agent-token", r.AgentToken,
|
|
"--agent-url", client.URL.String(),
|
|
"--log-dir", logDir,
|
|
"--socket-path", testutil.AgentSocketPath(t),
|
|
)
|
|
// Set the subsystems for the agent.
|
|
inv.Environ.Set(agent.EnvAgentSubsystem, fmt.Sprintf("%s,%s", codersdk.AgentSubsystemExectrace, codersdk.AgentSubsystemEnvbox))
|
|
|
|
clitest.Start(t, inv)
|
|
|
|
resources := coderdtest.NewWorkspaceAgentWaiter(t, client, r.Workspace.ID).
|
|
MatchResources(matchAgentWithSubsystems).Wait()
|
|
require.Len(t, resources, 1)
|
|
require.Len(t, resources[0].Agents, 1)
|
|
require.Len(t, resources[0].Agents[0].Subsystems, 2)
|
|
// Sorted
|
|
require.Equal(t, codersdk.AgentSubsystemEnvbox, resources[0].Agents[0].Subsystems[0])
|
|
require.Equal(t, codersdk.AgentSubsystemExectrace, resources[0].Agents[0].Subsystems[1])
|
|
})
|
|
t.Run("Headers&DERPHeaders", func(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
// Create a coderd API instance the hard way since we need to change the
|
|
// handler to inject our custom /derp handler.
|
|
dv := coderdtest.DeploymentValues(t)
|
|
dv.DERP.Config.BlockDirect = true
|
|
setHandler, cancelFunc, serverURL, newOptions := coderdtest.NewOptions(t, &coderdtest.Options{
|
|
DeploymentValues: dv,
|
|
})
|
|
|
|
// We set the handler after server creation for the access URL.
|
|
coderAPI := coderd.New(newOptions)
|
|
setHandler(coderAPI.RootHandler)
|
|
provisionerCloser := coderdtest.NewProvisionerDaemon(t, coderAPI)
|
|
t.Cleanup(func() {
|
|
_ = provisionerCloser.Close()
|
|
})
|
|
client := codersdk.New(serverURL, codersdk.WithHTTPClient(coderdtest.NewIsolatedHTTPClient(serverURL)))
|
|
t.Cleanup(func() {
|
|
cancelFunc()
|
|
_ = provisionerCloser.Close()
|
|
_ = coderAPI.Close()
|
|
client.HTTPClient.CloseIdleConnections()
|
|
})
|
|
|
|
var (
|
|
admin = coderdtest.CreateFirstUser(t, client)
|
|
member, memberUser = coderdtest.CreateAnotherUser(t, client, admin.OrganizationID)
|
|
called atomic.Int64
|
|
derpCalled atomic.Int64
|
|
)
|
|
|
|
setHandler(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
|
// Ignore client requests
|
|
if r.Header.Get("X-Testing") == "agent" {
|
|
assert.Equal(t, "Ethan was Here!", r.Header.Get("Cool-Header"))
|
|
assert.Equal(t, "very-wow-"+client.URL.String(), r.Header.Get("X-Process-Testing"))
|
|
assert.Equal(t, "more-wow", r.Header.Get("X-Process-Testing2"))
|
|
if strings.HasPrefix(r.URL.Path, "/derp") {
|
|
derpCalled.Add(1)
|
|
} else {
|
|
called.Add(1)
|
|
}
|
|
}
|
|
coderAPI.RootHandler.ServeHTTP(w, r)
|
|
}))
|
|
r := dbfake.WorkspaceBuild(t, coderAPI.Database, database.WorkspaceTable{
|
|
OrganizationID: memberUser.OrganizationIDs[0],
|
|
OwnerID: memberUser.ID,
|
|
}).WithAgent().Do()
|
|
|
|
coderURLEnv := "$CODER_URL"
|
|
if runtime.GOOS == "windows" {
|
|
coderURLEnv = "%CODER_URL%"
|
|
}
|
|
|
|
logDir := t.TempDir()
|
|
agentInv, _ := clitest.New(t,
|
|
"agent",
|
|
"--auth", "token",
|
|
"--agent-token", r.AgentToken,
|
|
"--agent-url", client.URL.String(),
|
|
"--log-dir", logDir,
|
|
"--agent-header", "X-Testing=agent",
|
|
"--agent-header", "Cool-Header=Ethan was Here!",
|
|
"--agent-header-command", "printf X-Process-Testing=very-wow-"+coderURLEnv+"'\\r\\n'X-Process-Testing2=more-wow",
|
|
"--socket-path", testutil.AgentSocketPath(t),
|
|
)
|
|
clitest.Start(t, agentInv)
|
|
coderdtest.NewWorkspaceAgentWaiter(t, client, r.Workspace.ID).
|
|
MatchResources(matchAgentWithVersion).Wait()
|
|
|
|
ctx := testutil.Context(t, testutil.WaitLong)
|
|
clientInv, root := clitest.New(t,
|
|
"-v",
|
|
"--no-feature-warning",
|
|
"--no-version-warning",
|
|
"ping", r.Workspace.Name,
|
|
"-n", "1",
|
|
)
|
|
clitest.SetupConfig(t, member, root)
|
|
err := clientInv.WithContext(ctx).Run()
|
|
require.NoError(t, err)
|
|
|
|
require.Greater(t, called.Load(), int64(0), "expected coderd to be reached with custom headers")
|
|
require.Greater(t, derpCalled.Load(), int64(0), "expected /derp to be called with custom headers")
|
|
})
|
|
|
|
t.Run("DisabledServers", func(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
client, db := coderdtest.NewWithDatabase(t, nil)
|
|
user := coderdtest.CreateFirstUser(t, client)
|
|
r := dbfake.WorkspaceBuild(t, db, database.WorkspaceTable{
|
|
OrganizationID: user.OrganizationID,
|
|
OwnerID: user.UserID,
|
|
}).WithAgent().Do()
|
|
|
|
logDir := t.TempDir()
|
|
inv, _ := clitest.New(t,
|
|
"agent",
|
|
"--auth", "token",
|
|
"--agent-token", r.AgentToken,
|
|
"--agent-url", client.URL.String(),
|
|
"--log-dir", logDir,
|
|
// The disabled-server messages are logged at debug. Run verbose so
|
|
// they are written to the log file instead of recorded in memory.
|
|
"--verbose",
|
|
"--pprof-address", "",
|
|
"--prometheus-address", "",
|
|
"--debug-address", "",
|
|
"--socket-path", testutil.AgentSocketPath(t),
|
|
)
|
|
|
|
clitest.Start(t, inv)
|
|
|
|
// Verify the agent is connected and working.
|
|
resources := coderdtest.NewWorkspaceAgentWaiter(t, client, r.Workspace.ID).
|
|
MatchResources(matchAgentWithVersion).Wait()
|
|
require.Len(t, resources, 1)
|
|
require.Len(t, resources[0].Agents, 1)
|
|
require.NotEmpty(t, resources[0].Agents[0].Version)
|
|
|
|
// Verify the servers are not listening by checking the log for disabled
|
|
// messages.
|
|
require.Eventually(t, func() bool {
|
|
logContent, err := os.ReadFile(filepath.Join(logDir, "coder-agent.log"))
|
|
if err != nil {
|
|
return false
|
|
}
|
|
logStr := string(logContent)
|
|
return strings.Contains(logStr, "pprof address is empty, disabling pprof server") &&
|
|
strings.Contains(logStr, "prometheus address is empty, disabling prometheus server") &&
|
|
strings.Contains(logStr, "debug address is empty, disabling debug server")
|
|
}, testutil.WaitLong, testutil.IntervalMedium)
|
|
})
|
|
}
|
|
|
|
func matchAgentWithVersion(rs []codersdk.WorkspaceResource) bool {
|
|
if len(rs) < 1 {
|
|
return false
|
|
}
|
|
if len(rs[0].Agents) < 1 {
|
|
return false
|
|
}
|
|
if rs[0].Agents[0].Version == "" {
|
|
return false
|
|
}
|
|
return true
|
|
}
|
|
|
|
func matchAgentWithSubsystems(rs []codersdk.WorkspaceResource) bool {
|
|
if len(rs) < 1 {
|
|
return false
|
|
}
|
|
if len(rs[0].Agents) < 1 {
|
|
return false
|
|
}
|
|
if len(rs[0].Agents[0].Subsystems) < 1 {
|
|
return false
|
|
}
|
|
return true
|
|
}
|