mirror of
https://github.com/coder/coder.git
synced 2026-09-24 15:04:27 +08:00
feat: include rotated agent logs in support bundles (#26055)
Support bundles previously captured only the active coder-agent.log, losing history across agent restarts. Add an optional `after` filter to the agent's /debug/logs endpoint: without it the endpoint is unchanged (active log only, 10 MiB cap); with it the response includes the active log plus rotated coder-agent-*.log files modified after the cutoff, newest first. Support bundles request the last 24h. Closes #25395
This commit is contained in:
Ehab Younes
@@ -2289,26 +2289,6 @@ func (a *agent) HandleHTTPDebugManifest(w http.ResponseWriter, r *http.Request)
|
||||
}
|
||||
}
|
||||
|
||||
func (a *agent) HandleHTTPDebugLogs(w http.ResponseWriter, r *http.Request) {
|
||||
logPath := filepath.Join(a.logDir, "coder-agent.log")
|
||||
f, err := os.Open(logPath)
|
||||
if err != nil {
|
||||
a.logger.Error(r.Context(), "open agent log file", slog.Error(err), slog.F("path", logPath))
|
||||
w.WriteHeader(http.StatusInternalServerError)
|
||||
_, _ = fmt.Fprintf(w, "could not open log file: %s", err)
|
||||
return
|
||||
}
|
||||
defer f.Close()
|
||||
|
||||
// Limit to 10MiB.
|
||||
w.WriteHeader(http.StatusOK)
|
||||
_, err = io.Copy(w, io.LimitReader(f, 10*1024*1024))
|
||||
if err != nil && !errors.Is(err, io.EOF) {
|
||||
a.logger.Error(r.Context(), "read agent log file", slog.Error(err))
|
||||
return
|
||||
}
|
||||
}
|
||||
|
||||
func (a *agent) HTTPDebug() http.Handler {
|
||||
r := chi.NewRouter()
|
||||
|
||||
|
||||
@@ -3659,6 +3659,15 @@ func TestAgent_DebugServer(t *testing.T) {
|
||||
randLogStr, err := cryptorand.String(32)
|
||||
require.NoError(t, err)
|
||||
require.NoError(t, os.WriteFile(logPath, []byte(randLogStr), 0o600))
|
||||
newRotatedLogPath := filepath.Join(logDir, "coder-agent-2026-05-17T20-00-00.000.log")
|
||||
oldRotatedLogPath := filepath.Join(logDir, "coder-agent-2026-05-17T19-00-00.000.log")
|
||||
require.NoError(t, os.WriteFile(newRotatedLogPath, []byte("new rotated log"), 0o600))
|
||||
require.NoError(t, os.WriteFile(oldRotatedLogPath, []byte("old rotated log"), 0o600))
|
||||
now := time.Now()
|
||||
newRotatedModTime := now.Add(-time.Minute)
|
||||
oldRotatedModTime := now.Add(-48 * time.Hour)
|
||||
require.NoError(t, os.Chtimes(newRotatedLogPath, newRotatedModTime, newRotatedModTime))
|
||||
require.NoError(t, os.Chtimes(oldRotatedLogPath, oldRotatedModTime, oldRotatedModTime))
|
||||
derpMap, _ := tailnettest.RunDERPAndSTUN(t)
|
||||
//nolint:dogsled
|
||||
conn, _, _, _, agnt := setupAgentWithSecrets(t, agentsdk.Manifest{
|
||||
@@ -3806,6 +3815,85 @@ func TestAgent_DebugServer(t *testing.T) {
|
||||
require.NoError(t, err)
|
||||
require.NotEmpty(t, string(resBody))
|
||||
require.Contains(t, string(resBody), randLogStr)
|
||||
require.NotContains(t, string(resBody), "new rotated log")
|
||||
})
|
||||
|
||||
t.Run("LogsIncludeActiveOnlyWithAfter", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
ctx := testutil.Context(t, testutil.WaitLong)
|
||||
url := srv.URL + "/debug/logs?after=" + newRotatedModTime.Add(time.Minute).UTC().Format(time.RFC3339Nano)
|
||||
req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)
|
||||
require.NoError(t, err)
|
||||
|
||||
res, err := srv.Client().Do(req)
|
||||
require.NoError(t, err)
|
||||
require.Equal(t, http.StatusOK, res.StatusCode)
|
||||
defer res.Body.Close()
|
||||
resBody, err := io.ReadAll(res.Body)
|
||||
require.NoError(t, err)
|
||||
body := string(resBody)
|
||||
require.Contains(t, body, randLogStr)
|
||||
require.Contains(t, body, "coder-agent.log")
|
||||
require.NotContains(t, body, "new rotated log")
|
||||
require.NotContains(t, body, "old rotated log")
|
||||
})
|
||||
|
||||
t.Run("LogsIncludeRotatedWithAfter", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
ctx := testutil.Context(t, testutil.WaitLong)
|
||||
url := srv.URL + "/debug/logs?after=" + newRotatedModTime.Add(-time.Minute).UTC().Format(time.RFC3339Nano)
|
||||
req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)
|
||||
require.NoError(t, err)
|
||||
|
||||
res, err := srv.Client().Do(req)
|
||||
require.NoError(t, err)
|
||||
require.Equal(t, http.StatusOK, res.StatusCode)
|
||||
defer res.Body.Close()
|
||||
resBody, err := io.ReadAll(res.Body)
|
||||
require.NoError(t, err)
|
||||
body := string(resBody)
|
||||
require.Contains(t, body, randLogStr)
|
||||
require.Contains(t, body, "coder-agent.log")
|
||||
require.Contains(t, body, "coder-agent-2026-05-17T20-00-00.000.log")
|
||||
require.Contains(t, body, "new rotated log")
|
||||
require.NotContains(t, body, "old rotated log")
|
||||
})
|
||||
|
||||
t.Run("LogsIncludeRotatedWithOlderAfter", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
ctx := testutil.Context(t, testutil.WaitLong)
|
||||
url := srv.URL + "/debug/logs?after=" + oldRotatedModTime.Add(-time.Minute).UTC().Format(time.RFC3339Nano)
|
||||
req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)
|
||||
require.NoError(t, err)
|
||||
|
||||
res, err := srv.Client().Do(req)
|
||||
require.NoError(t, err)
|
||||
require.Equal(t, http.StatusOK, res.StatusCode)
|
||||
defer res.Body.Close()
|
||||
resBody, err := io.ReadAll(res.Body)
|
||||
require.NoError(t, err)
|
||||
body := string(resBody)
|
||||
require.Contains(t, body, randLogStr)
|
||||
require.Contains(t, body, "new rotated log")
|
||||
require.Contains(t, body, "old rotated log")
|
||||
require.Less(t, strings.Index(body, randLogStr), strings.Index(body, "new rotated log"))
|
||||
require.Less(t, strings.Index(body, "new rotated log"), strings.Index(body, "old rotated log"))
|
||||
})
|
||||
|
||||
t.Run("LogsInvalidAfter", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
ctx := testutil.Context(t, testutil.WaitLong)
|
||||
req, err := http.NewRequestWithContext(ctx, http.MethodGet, srv.URL+"/debug/logs?after=nope", nil)
|
||||
require.NoError(t, err)
|
||||
|
||||
res, err := srv.Client().Do(req)
|
||||
require.NoError(t, err)
|
||||
defer res.Body.Close()
|
||||
require.Equal(t, http.StatusBadRequest, res.StatusCode)
|
||||
})
|
||||
}
|
||||
|
||||
|
||||
@@ -0,0 +1,203 @@
|
||||
package agent
|
||||
|
||||
import (
|
||||
"context"
|
||||
"fmt"
|
||||
"io"
|
||||
"io/fs"
|
||||
"net/http"
|
||||
"os"
|
||||
"regexp"
|
||||
"slices"
|
||||
"strings"
|
||||
"time"
|
||||
|
||||
"golang.org/x/xerrors"
|
||||
|
||||
"cdr.dev/slog/v3"
|
||||
)
|
||||
|
||||
const (
|
||||
activeAgentLogName = "coder-agent.log"
|
||||
debugLogsActiveMaxBytes = 10 * 1024 * 1024
|
||||
debugLogsCombinedMaxBytes = 100 * 1024 * 1024
|
||||
// debugLogsWriteTimeout gives slow links well over the server's 20s
|
||||
// WriteTimeout to stream the combined logs.
|
||||
debugLogsWriteTimeout = 5 * time.Minute
|
||||
)
|
||||
|
||||
// coderAgentRotatedLogPattern matches lumberjack's rotated filenames, e.g.
|
||||
// coder-agent-2026-05-17T20-00-00.000.log.
|
||||
var coderAgentRotatedLogPattern = regexp.MustCompile(`^coder-agent-\d{4}-\d{2}-\d{2}T\d{2}-\d{2}-\d{2}\.\d{3}\.log$`)
|
||||
|
||||
type agentLogFile struct {
|
||||
name string
|
||||
size int64
|
||||
modTime time.Time
|
||||
}
|
||||
|
||||
func (a *agent) HandleHTTPDebugLogs(w http.ResponseWriter, r *http.Request) {
|
||||
after, hasAfter, err := parseDebugLogsAfter(r)
|
||||
if err != nil {
|
||||
http.Error(w, err.Error(), http.StatusBadRequest)
|
||||
return
|
||||
}
|
||||
|
||||
// Confine reads to logDir so a symlink there cannot escape it.
|
||||
root, err := os.OpenRoot(a.logDir)
|
||||
if err != nil {
|
||||
a.logger.Error(r.Context(), "open agent log dir", slog.Error(err), slog.F("log_dir", a.logDir))
|
||||
w.WriteHeader(http.StatusInternalServerError)
|
||||
_, _ = fmt.Fprintf(w, "could not open log dir: %s", err)
|
||||
return
|
||||
}
|
||||
defer root.Close()
|
||||
|
||||
if !hasAfter {
|
||||
a.writeActiveDebugLog(w, r, root)
|
||||
return
|
||||
}
|
||||
|
||||
// Streaming the combined logs can exceed the server's 20s WriteTimeout,
|
||||
// so extend the deadline for this response.
|
||||
if err := http.NewResponseController(w).SetWriteDeadline(time.Now().Add(debugLogsWriteTimeout)); err != nil {
|
||||
a.logger.Warn(r.Context(), "extend debug log write deadline", slog.Error(err))
|
||||
}
|
||||
|
||||
// Open the required active log before the 200 so failures return 500.
|
||||
active, err := root.Open(activeAgentLogName)
|
||||
if err != nil {
|
||||
a.logger.Error(r.Context(), "open agent log file", slog.Error(err), slog.F("name", activeAgentLogName))
|
||||
w.WriteHeader(http.StatusInternalServerError)
|
||||
_, _ = fmt.Fprintf(w, "could not open log file: %s", err)
|
||||
return
|
||||
}
|
||||
activeInfo, err := active.Stat()
|
||||
if err != nil {
|
||||
_ = active.Close()
|
||||
a.logger.Error(r.Context(), "stat agent log file", slog.Error(err), slog.F("name", activeAgentLogName))
|
||||
w.WriteHeader(http.StatusInternalServerError)
|
||||
_, _ = fmt.Fprintf(w, "could not stat log file: %s", err)
|
||||
return
|
||||
}
|
||||
w.WriteHeader(http.StatusOK)
|
||||
remaining := int64(debugLogsCombinedMaxBytes)
|
||||
// Cap the active log at its own limit so it can't consume the whole
|
||||
// budget and starve the rotated logs.
|
||||
n, truncated, err := writeAgentLogSection(w, active, activeAgentLogName, activeInfo.Size(), activeInfo.ModTime(), "", min(remaining, debugLogsActiveMaxBytes))
|
||||
remaining -= n
|
||||
_ = active.Close()
|
||||
if err != nil {
|
||||
a.logger.Error(r.Context(), "read agent log file", slog.Error(err), slog.F("name", activeAgentLogName))
|
||||
return
|
||||
}
|
||||
|
||||
// Then rotated logs after the cutoff, newest first.
|
||||
rotated, err := rotatedAgentLogFiles(r.Context(), a.logger, root, after)
|
||||
if err != nil {
|
||||
a.logger.Error(r.Context(), "find rotated agent log files", slog.Error(err), slog.F("log_dir", a.logDir))
|
||||
return
|
||||
}
|
||||
for _, file := range rotated {
|
||||
if remaining <= 0 {
|
||||
truncated = true
|
||||
break
|
||||
}
|
||||
f, err := root.Open(file.name)
|
||||
if err != nil {
|
||||
a.logger.Warn(r.Context(), "open rotated agent log file", slog.Error(err), slog.F("name", file.name))
|
||||
continue
|
||||
}
|
||||
var fileTruncated bool
|
||||
n, fileTruncated, err = writeAgentLogSection(w, f, file.name, file.size, file.modTime, "\n", remaining)
|
||||
remaining -= n
|
||||
truncated = truncated || fileTruncated
|
||||
_ = f.Close()
|
||||
if err != nil {
|
||||
a.logger.Error(r.Context(), "read rotated agent log file", slog.Error(err), slog.F("name", file.name))
|
||||
return
|
||||
}
|
||||
}
|
||||
if truncated {
|
||||
a.logger.Warn(r.Context(), "agent debug logs response truncated", slog.F("limit_bytes", debugLogsCombinedMaxBytes))
|
||||
}
|
||||
}
|
||||
|
||||
func parseDebugLogsAfter(r *http.Request) (after time.Time, hasAfter bool, err error) {
|
||||
raw := strings.TrimSpace(r.URL.Query().Get("after"))
|
||||
if raw == "" {
|
||||
return time.Time{}, false, nil
|
||||
}
|
||||
after, err = time.Parse(time.RFC3339Nano, raw)
|
||||
if err != nil {
|
||||
return time.Time{}, false, xerrors.Errorf("after must be an RFC3339 timestamp: %w", err)
|
||||
}
|
||||
return after, true, nil
|
||||
}
|
||||
|
||||
func (a *agent) writeActiveDebugLog(w http.ResponseWriter, r *http.Request, root *os.Root) {
|
||||
f, err := root.Open(activeAgentLogName)
|
||||
if err != nil {
|
||||
a.logger.Error(r.Context(), "open agent log file", slog.Error(err), slog.F("name", activeAgentLogName))
|
||||
w.WriteHeader(http.StatusInternalServerError)
|
||||
_, _ = fmt.Fprintf(w, "could not open log file: %s", err)
|
||||
return
|
||||
}
|
||||
defer f.Close()
|
||||
|
||||
w.WriteHeader(http.StatusOK)
|
||||
_, err = io.Copy(w, io.LimitReader(f, debugLogsActiveMaxBytes))
|
||||
if err != nil {
|
||||
a.logger.Error(r.Context(), "read agent log file", slog.Error(err))
|
||||
return
|
||||
}
|
||||
}
|
||||
|
||||
// writeAgentLogSection writes a separator and header for the file, then streams
|
||||
// up to budget bytes of r. It returns the bytes written and, from size (r's
|
||||
// full length), whether r was truncated.
|
||||
func writeAgentLogSection(w io.Writer, r io.Reader, name string, size int64, modTime time.Time, separator string, budget int64) (written int64, truncated bool, err error) {
|
||||
header := separator + fmt.Sprintf("=== %s (mtime %s) ===\n", name, modTime.UTC().Format(time.RFC3339Nano))
|
||||
if int64(len(header)) > budget {
|
||||
return 0, size > 0, nil
|
||||
}
|
||||
if _, err := io.WriteString(w, header); err != nil {
|
||||
return 0, false, err
|
||||
}
|
||||
contentBudget := budget - int64(len(header))
|
||||
n, err := io.Copy(w, io.LimitReader(r, contentBudget))
|
||||
return int64(len(header)) + n, size > contentBudget, err
|
||||
}
|
||||
|
||||
// rotatedAgentLogFiles returns rotated logs after the cutoff, newest first,
|
||||
// excluding the active log and any non-regular files such as symlinks.
|
||||
func rotatedAgentLogFiles(ctx context.Context, logger slog.Logger, root *os.Root, after time.Time) ([]agentLogFile, error) {
|
||||
entries, err := fs.ReadDir(root.FS(), ".")
|
||||
if err != nil {
|
||||
return nil, xerrors.Errorf("read log directory: %w", err)
|
||||
}
|
||||
rotated := make([]agentLogFile, 0, len(entries))
|
||||
for _, entry := range entries {
|
||||
base := entry.Name()
|
||||
if !coderAgentRotatedLogPattern.MatchString(base) {
|
||||
continue
|
||||
}
|
||||
info, err := entry.Info()
|
||||
if err != nil {
|
||||
logger.Warn(ctx, "stat rotated agent log file", slog.Error(err), slog.F("name", base))
|
||||
continue
|
||||
}
|
||||
if !info.Mode().IsRegular() || info.ModTime().Before(after) {
|
||||
continue
|
||||
}
|
||||
rotated = append(rotated, agentLogFile{
|
||||
name: base,
|
||||
size: info.Size(),
|
||||
modTime: info.ModTime(),
|
||||
})
|
||||
}
|
||||
slices.SortFunc(rotated, func(a, b agentLogFile) int {
|
||||
return b.modTime.Compare(a.modTime)
|
||||
})
|
||||
return rotated, nil
|
||||
}
|
||||
@@ -0,0 +1,103 @@
|
||||
package agent
|
||||
|
||||
import (
|
||||
"net"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"os"
|
||||
"path/filepath"
|
||||
"runtime"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/stretchr/testify/require"
|
||||
|
||||
"cdr.dev/slog/v3"
|
||||
"cdr.dev/slog/v3/sloggers/slogtest"
|
||||
)
|
||||
|
||||
func TestHandleHTTPDebugLogsWithAfterCapsResponse(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
logDir := t.TempDir()
|
||||
activePath := filepath.Join(logDir, "coder-agent.log")
|
||||
f, err := os.Create(activePath)
|
||||
require.NoError(t, err)
|
||||
// A huge active log must not starve the rotated logs.
|
||||
require.NoError(t, f.Truncate(debugLogsCombinedMaxBytes+1))
|
||||
require.NoError(t, f.Close())
|
||||
|
||||
rotatedPath := filepath.Join(logDir, "coder-agent-2026-05-17T20-00-00.000.log")
|
||||
require.NoError(t, os.WriteFile(rotatedPath, []byte("rotated marker\n"), 0o600))
|
||||
rotatedModTime := time.Now().Add(-time.Minute)
|
||||
require.NoError(t, os.Chtimes(rotatedPath, rotatedModTime, rotatedModTime))
|
||||
|
||||
a := &agent{
|
||||
logger: slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug),
|
||||
logDir: logDir,
|
||||
}
|
||||
req := httptest.NewRequest(http.MethodGet, "/debug/logs?after="+time.Now().Add(-time.Hour).UTC().Format(time.RFC3339Nano), nil)
|
||||
res := httptest.NewRecorder()
|
||||
|
||||
a.HandleHTTPDebugLogs(res, req)
|
||||
|
||||
require.Equal(t, http.StatusOK, res.Code)
|
||||
body := res.Body.String()
|
||||
// Active is capped at its own limit, so the rotated log still fits.
|
||||
require.Less(t, int64(len(body)), int64(debugLogsCombinedMaxBytes))
|
||||
require.Contains(t, body, "coder-agent.log")
|
||||
require.Contains(t, body, "rotated marker")
|
||||
}
|
||||
|
||||
func TestHandleHTTPDebugLogsWithAfterOpenFailure(t *testing.T) {
|
||||
t.Parallel()
|
||||
if runtime.GOOS == "windows" {
|
||||
t.Skip("unix sockets only")
|
||||
}
|
||||
|
||||
logDir, err := os.MkdirTemp("/tmp", "coder-debuglogs-")
|
||||
require.NoError(t, err)
|
||||
t.Cleanup(func() {
|
||||
_ = os.RemoveAll(logDir)
|
||||
})
|
||||
activePath := filepath.Join(logDir, "coder-agent.log")
|
||||
listener, err := net.Listen("unix", activePath)
|
||||
require.NoError(t, err)
|
||||
t.Cleanup(func() {
|
||||
_ = listener.Close()
|
||||
})
|
||||
|
||||
a := &agent{
|
||||
logger: slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug),
|
||||
logDir: logDir,
|
||||
}
|
||||
req := httptest.NewRequest(http.MethodGet, "/debug/logs?after="+time.Now().Add(-time.Minute).UTC().Format(time.RFC3339Nano), nil)
|
||||
res := httptest.NewRecorder()
|
||||
|
||||
a.HandleHTTPDebugLogs(res, req)
|
||||
|
||||
require.Equal(t, http.StatusInternalServerError, res.Code)
|
||||
require.Contains(t, res.Body.String(), "could not open log file")
|
||||
}
|
||||
|
||||
func TestRotatedAgentLogFilesReadsLogDirLiterally(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
root := t.TempDir()
|
||||
logDir := filepath.Join(root, "logs[abc]")
|
||||
require.NoError(t, os.Mkdir(logDir, 0o700))
|
||||
activePath := filepath.Join(logDir, "coder-agent.log")
|
||||
rotatedPath := filepath.Join(logDir, "coder-agent-2026-05-18T00-00-00.000.log")
|
||||
require.NoError(t, os.WriteFile(activePath, []byte("active log"), 0o600))
|
||||
require.NoError(t, os.WriteFile(rotatedPath, []byte("rotated log"), 0o600))
|
||||
|
||||
dirRoot, err := os.OpenRoot(logDir)
|
||||
require.NoError(t, err)
|
||||
t.Cleanup(func() { _ = dirRoot.Close() })
|
||||
|
||||
files, err := rotatedAgentLogFiles(t.Context(), slogtest.Make(t, nil), dirRoot, time.Now().Add(-time.Minute))
|
||||
|
||||
require.NoError(t, err)
|
||||
require.Len(t, files, 1)
|
||||
require.Equal(t, "coder-agent-2026-05-18T00-00-00.000.log", files[0].name)
|
||||
}
|
||||
Reference in New Issue
Block a user