From 76f52edfa8e04aaee349506e47eec7117fdd8f9b Mon Sep 17 00:00:00 2001 From: Marko Petzold Date: Wed, 28 Oct 2026 19:43:58 +0100 Subject: [PATCH 1/2] refactor: streamline log query handling and improve compose log integration --- src/container/compose.go | 63 +-------- src/container/logquery_test.go | 34 +---- src/logging/applog.go | 13 +- src/logging/query.go | 241 +++++++++++++++++++++++++-------- src/logging/query_test.go | 204 +++++++++++++++++++++++----- 5 files changed, 365 insertions(+), 190 deletions(-) diff --git a/src/container/compose.go b/src/container/compose.go index 1a4182f..96bf962 100644 --- a/src/container/compose.go +++ b/src/container/compose.go @@ -7,7 +7,6 @@ import ( "encoding/json" "errors" "fmt" - "io" "os" "os/exec" "path/filepath" @@ -623,7 +622,7 @@ func (c *Compose) DownRemoveOrphansContext(ctx context.Context, dockerComposePat // caller predating time-windowed queries expects. Since and Until are RFC3339 // or Unix-seconds strings: resolve relative durations with common.ParseLogTime // before filling them in, so the device's clock is applied exactly once and the -// same absolute window reaches both the Docker and the compose path. +// same absolute window reaches every container a read covers. type LogQuery struct { Tail uint64 Since string @@ -631,30 +630,6 @@ type LogQuery struct { Timestamps bool } -// ComposeArgs renders the query as `docker compose logs` flags. -// -// --no-color is unconditional: compose only auto-disables colour when it -// detects a TTY, and an ANSI escape that survives into a log line is noise for -// every consumer we have. -func (q LogQuery) ComposeArgs() []string { - args := []string{"logs", "--no-color"} - if q.Tail > 0 { - args = append(args, "--tail", strconv.FormatUint(q.Tail, 10)) - } else { - args = append(args, "--tail", "all") - } - if q.Timestamps { - args = append(args, "--timestamps") - } - if q.Since != "" { - args = append(args, "--since", q.Since) - } - if q.Until != "" { - args = append(args, "--until", q.Until) - } - return args -} - // DockerOptions renders the query as option keys for Container.Logs. func (q LogQuery) DockerOptions() common.Dict { options := common.Dict{"follow": false, "stdout": true, "stderr": true} @@ -685,39 +660,15 @@ func ListComposeProjectContainers(ctx context.Context, cont Container, composeAp project := common.NormalizeComposeProjectName(composeAppName) return cont.ListContainers(ctx, common.Dict{ "all": true, - "filters": filters.NewArgs(filters.Arg("label", "com.docker.compose.project="+project)), + "filters": filters.NewArgs(filters.Arg("label", ComposeProjectLabel+"="+project)), }) } -// ComposeConfigFilesLabel carries the compose file(s) a container was created -// from — the same value `docker compose ls` reports as ConfigFiles. -const ComposeConfigFilesLabel = "com.docker.compose.project.config_files" - -// Logs reads the logs of a whole compose project. -// -// Every service in the project is included, each line prefixed with its service -// name — for a multi-container app that prefix is the only thing identifying -// which service spoke, so it is deliberately kept. Output is CombinedOutput, so -// compose's own progress and warning text on stderr is interleaved with the -// container output. -func (c *Compose) Logs(ctx context.Context, dockerComposePath string, query LogQuery) (io.ReadCloser, error) { - binary := c.binary - if binary == "" { - binary = "docker" - } - - args := append([]string{"compose", "-f", dockerComposePath}, query.ComposeArgs()...) - - output, err := exec.CommandContext(ctx, binary, args...).CombinedOutput() //nolint:gosec // G204: fixed docker compose CLI; arguments are compose file paths and fixed flags, values as separate argv entries - if err != nil { - return nil, err - } - - reader := strings.NewReader(string(output)) - readCloser := io.NopCloser(reader) - - return readCloser, nil -} +// Labels docker compose stamps on every container it creates. +const ( + ComposeProjectLabel = "com.docker.compose.project" + ComposeServiceLabel = "com.docker.compose.service" +) func (c *Compose) LogStream(dockerComposePath string) (chan string, error) { // c.logStreamMapMutex.Lock() diff --git a/src/container/logquery_test.go b/src/container/logquery_test.go index 697f96d..6977bc0 100644 --- a/src/container/logquery_test.go +++ b/src/container/logquery_test.go @@ -7,11 +7,10 @@ import ( "github.com/stretchr/testify/assert" ) -// The two renderers below are the whole contract between a windowed log query -// and the two very different things that can serve it — the Docker API and the -// compose CLI. Getting a flag name or a zero-value default wrong here is -// invisible at compile time and shows up as "the time range was ignored", so -// they are asserted directly rather than through a daemon. +// The renderer below is the whole contract between a windowed log query and the +// Docker API that serves it. Getting an option name or a zero-value default +// wrong here is invisible at compile time and shows up as "the time range was +// ignored", so it is asserted directly rather than through a daemon. func TestLogQueryDockerOptions(t *testing.T) { t.Run("zero value reads everything without timestamps", func(t *testing.T) { @@ -41,31 +40,6 @@ func TestLogQueryDockerOptions(t *testing.T) { }) } -func TestLogQueryComposeArgs(t *testing.T) { - t.Run("zero value reads everything", func(t *testing.T) { - args := LogQuery{}.ComposeArgs() - - assert.Equal(t, []string{"logs", "--no-color", "--tail", "all"}, args) - }) - - t.Run("renders every bound as a flag", func(t *testing.T) { - args := LogQuery{ - Tail: 50, - Since: "2026-08-04T09:00:00Z", - Until: "2026-08-04T09:15:00Z", - Timestamps: true, - }.ComposeArgs() - - assert.Equal(t, []string{ - "logs", "--no-color", - "--tail", "50", - "--timestamps", - "--since", "2026-08-04T09:00:00Z", - "--until", "2026-08-04T09:15:00Z", - }, args) - }) -} - func TestLogsOptionsFromDict(t *testing.T) { t.Run("maps every recognised key", func(t *testing.T) { options := logsOptionsFromDict(common.Dict{ diff --git a/src/logging/applog.go b/src/logging/applog.go index 6582435..fe72e3b 100644 --- a/src/logging/applog.go +++ b/src/logging/applog.go @@ -727,23 +727,12 @@ func (lm *LogManager) getNonAgentLogsCompose(containerName string) ([]string, er } if containsOnlyAgentLogs || len(history) == 0 { - reader, err := lm.composeLogs(context.Background(), containerName, container.LogQuery{Tail: 50}) + containerHistory, _, err := lm.composeLogs(context.Background(), containerName, container.LogQuery{Tail: 50}) if err != nil { log.Warn().Err(err).Msgf("No log history found for: %s", containerName) return []string{}, nil } - var containerHistory []string - scanner := bufio.NewScanner(reader) - for scanner.Scan() { - containerHistory = append(containerHistory, scanner.Text()) - } - - err = reader.Close() - if err != nil { - log.Error().Err(err).Msg("failed to close reader after getting logs") - } - return containerHistory, nil } diff --git a/src/logging/query.go b/src/logging/query.go index 9e30592..8b53f90 100644 --- a/src/logging/query.go +++ b/src/logging/query.go @@ -2,14 +2,17 @@ package logging import ( "bufio" + "bytes" "context" "errors" "io" "reagent/container" "reagent/errdefs" + "sort" "strings" "time" + "github.com/docker/docker/pkg/stdcopy" "github.com/rs/zerolog/log" ) @@ -21,9 +24,10 @@ import ( // SQLite LogHistory table is a single JSON blob per app/stage with no timestamp // column, written only when a log stream ends. Docker's json-file driver is the // one store on the device that stamps every record, so a query goes there -// first, falls back to the compose CLI for multi-container apps, and only drops -// to the agent's history when the container is gone — flagging that the -// requested window was NOT applied rather than pretending it was. +// first — to the app's container, or to every container of a multi-container +// app — and only drops to the agent's history when the containers are gone, +// flagging that the requested window was NOT applied rather than pretending it +// was. const ( // MaxQueryLines bounds the lines a single query may return, before the byte @@ -106,11 +110,13 @@ func (lm *LogManager) QueryLogs(ctx context.Context, request LogQueryRequest) (L Until: formatBound(request.Until), } - lines, source, err := lm.readWindow(ctx, request.ContainerName, query) + read, err := lm.readWindow(ctx, request.ContainerName, query) if err != nil { return LogQueryResult{}, err } + lines := read.Lines + // Drop the newest `Offset` lines, then keep the newest `tail` of what is left. if request.Offset > 0 { if uint64(len(lines)) <= request.Offset { @@ -128,17 +134,12 @@ func (lm *LogManager) QueryLogs(ctx context.Context, request LogQueryRequest) (L lines, trimmedBytes := trimToBytes(lines, MaxQueryBytes) - result := LogQueryResult{ - Lines: lines, - Source: source, - Truncated: truncated || trimmedBytes, - } - - if source == sourceDocker { - result.OldestAvailable = lm.oldestAvailable(ctx, request.ContainerName) - } - - return result, nil + return LogQueryResult{ + Lines: lines, + Source: read.Source, + Truncated: truncated || trimmedBytes, + OldestAvailable: read.OldestAvailable, + }, nil } const ( @@ -147,7 +148,8 @@ const ( sourceHistory = "history" ) -// readWindow tries Docker, then compose, then the agent's own history. +// readWindow tries Docker, then the containers of a compose project, then the +// agent's own history. Its answer is not yet trimmed to the caps. // // The probe order is self-detecting rather than asking the app store what kind // of app this is: a compose project has no container under the plain name, so @@ -157,59 +159,149 @@ func (lm *LogManager) readWindow( ctx context.Context, containerName string, query container.LogQuery, -) ([]string, string, error) { +) (LogQueryResult, error) { reader, err := lm.Container.Logs(ctx, containerName, query.DockerOptions()) if err == nil { - return scanLines(reader), sourceDocker, nil + return LogQueryResult{ + Lines: readLogLines(reader), + Source: sourceDocker, + OldestAvailable: lm.oldestAvailable(ctx, containerName), + }, nil } if !errdefs.IsContainerNotFound(err) { - return nil, "", err + return LogQueryResult{}, err } - composeReader, composeErr := lm.composeLogs(ctx, containerName, query) + lines, oldest, composeErr := lm.composeLogs(ctx, containerName, query) if composeErr == nil { - return scanLines(composeReader), sourceCompose, nil + return LogQueryResult{Lines: lines, Source: sourceCompose, OldestAvailable: oldest}, nil } - log.Debug().Err(composeErr).Msgf("no compose project for %s, falling back to stored history", containerName) + if !errors.Is(composeErr, errNoComposeProject) { + // The project's containers exist but could not be read. Serving history + // here would present an empty or stale log as the app's answer and hide + // the failure that matters. + return LogQueryResult{}, composeErr + } history, historyErr := lm.GetLogHistory(containerName) if historyErr != nil { // Report the reason the *live* read failed: that the container is gone is // the useful fact, not that a fallback store was also empty. - return nil, "", err + return LogQueryResult{}, err } - return history, sourceHistory, nil + return LogQueryResult{Lines: history, Source: sourceHistory}, nil } -// composeLogs reads a compose app's logs, finding its compose file through the -// label Docker keeps on every container of the project. That lookup is one -// Docker API call; the `docker compose ls` it replaces was a CLI spawn of its -// own, paid before the `compose logs` spawn that does the actual read. -func (lm *LogManager) composeLogs(ctx context.Context, containerName string, query container.LogQuery) (io.ReadCloser, error) { +// errNoComposeProject means no container carries the app's compose project +// label: the app is not a compose app, or its containers are gone. +var errNoComposeProject = errors.New("compose project not found") + +// composeLogs reads every container of a compose app through the Docker API and +// merges them into one timeline, newest Tail lines across the whole app. Each +// line carries the prefix `docker compose logs` gives it ("web-1 | …"): for a +// multi-container app that prefix is the only thing saying which service spoke, +// and the console's live tail, which follows `compose logs -f`, prints the same. +// +// This used to shell out to `docker compose logs`. That re-parses the compose +// file — without the --env-file the app was started with — and costs two +// process spawns that run to seconds on a loaded device; any failure fell +// through to the stored history, which for a compose app is usually empty, so +// the logs looked absent while the containers were right there. The daemon +// needs no compose file, and can also say how far back each container's log +// goes, which the CLI could not. +// +// Every container is read with timestamps because the merge needs them; they +// are dropped again when the caller did not ask for them. +func (lm *LogManager) composeLogs(ctx context.Context, containerName string, query container.LogQuery) ([]string, time.Time, error) { containers, err := container.ListComposeProjectContainers(ctx, lm.Container, containerName+"_compose") if err != nil { - return nil, err + return nil, time.Time{}, err + } + + if len(containers) == 0 { + return nil, time.Time{}, errNoComposeProject } + stamped := query + stamped.Timestamps = true + + var merged []composeLine + var oldest time.Time + for _, c := range containers { - if configFiles := c.Labels[container.ComposeConfigFilesLabel]; configFiles != "" { - return lm.Container.Compose().Logs(ctx, configFiles, query) + reader, err := lm.Container.Logs(ctx, c.ID, stamped.DockerOptions()) + if err != nil { + // Removed between the listing and the read: nothing left to say. + if errdefs.IsContainerNotFound(err) { + continue + } + return nil, time.Time{}, err + } + + prefix := composeLogPrefix(c) + + // A record Docker split for length carries its own stamp, but should one + // arrive without, it stays next to the line it continues. + var last time.Time + for _, line := range readLogLines(reader) { + if at := parseLeadingTimestamp(line); !at.IsZero() { + last = at + } + merged = append(merged, composeLine{at: last, prefix: prefix, text: line}) + } + + // The app's log reaches back as far as its longest-lived container's. + first := lm.oldestAvailable(ctx, c.ID) + if !first.IsZero() && (oldest.IsZero() || first.Before(oldest)) { + oldest = first } } - return nil, errors.New("compose project not found") + sort.SliceStable(merged, func(i, j int) bool { return merged[i].at.Before(merged[j].at) }) + + if query.Tail > 0 && uint64(len(merged)) > query.Tail { + merged = merged[uint64(len(merged))-query.Tail:] + } + + lines := make([]string, 0, len(merged)) + for _, entry := range merged { + text := entry.text + if !query.Timestamps { + text = dropLeadingTimestamp(text) + } + lines = append(lines, entry.prefix+text) + } + + return lines, oldest, nil +} + +type composeLine struct { + at time.Time + prefix string + text string +} + +// composeLogPrefix is what `docker compose logs` puts in front of a container's +// lines: the container name without its project ("web-1"), or the whole name +// when the service sets its own container_name. +func composeLogPrefix(c container.ContainerResult) string { + name := c.Labels[container.ComposeServiceLabel] + if len(c.Names) > 0 { + full := strings.TrimPrefix(c.Names[0], "/") + name = strings.TrimPrefix(full, c.Labels[container.ComposeProjectLabel]+"-") + } + + return name + " | " } // oldestAvailable reads the first line the daemon will still serve. // // Docker offers no "head", so this opens an unbounded stream and closes it // after one line. Because the daemon streams, that costs a single line rather -// than the whole log. The compose path has no equivalent — its CLI buffers the -// entire output before returning — so compose answers leave this unset and the -// caller reports the retention floor as unknown. +// than the whole log. func (lm *LogManager) oldestAvailable(ctx context.Context, containerName string) time.Time { reader, err := lm.Container.Logs(ctx, containerName, container.LogQuery{Timestamps: true}.DockerOptions()) if err != nil { @@ -242,27 +334,68 @@ func parseLeadingTimestamp(line string) time.Time { return parsed } -// stripStreamHeader removes Docker's 8-byte multiplexing frame header. -// -// Containers the agent starts get Tty: true (apps/run_app.go), which turns -// multiplexing off, so in practice this is a no-op. It is here for containers -// created some other way, where the header would otherwise arrive as binary -// inside a log line and be handed to whoever asked for the logs. -// -// The header is [stream, 0, 0, 0, size0..size3]. Matching on the three NUL -// bytes rather than trimming a cutset of control characters matters: the four -// size bytes are arbitrary and are frequently printable, so a cutset trim stops -// in the wrong place and corrupts the line. -func stripStreamHeader(line string) string { - if len(line) < 8 { +// dropLeadingTimestamp removes the stamp parseLeadingTimestamp reads. A line +// without one is returned unchanged. +func dropLeadingTimestamp(line string) string { + field, rest, _ := strings.Cut(line, " ") + if _, err := time.Parse(time.RFC3339Nano, field); err != nil { return line } - if line[0] > 2 || line[1] != 0 || line[2] != 0 || line[3] != 0 { + + return rest +} + +// stripStreamHeader removes Docker's 8-byte multiplexing frame header from the +// start of a line. readLogLines demultiplexes whole streams; this covers the +// single line oldestAvailable reads without doing so. +func stripStreamHeader(line string) string { + if len(line) < 8 || !isStreamHeader([]byte(line[:8])) { return line } return line[8:] } +// isStreamHeader reports whether head is a multiplexing frame header: +// [stream, 0, 0, 0, size0..size3]. +// +// Matching on the three NUL bytes rather than on a cutset of control characters +// matters: the four size bytes are arbitrary and frequently printable. A TTY +// stream cannot be mistaken for one when Docker stamps it — every line then +// starts with a digit. +func isStreamHeader(head []byte) bool { + return len(head) >= 8 && head[0] <= 2 && head[1] == 0 && head[2] == 0 && head[3] == 0 +} + +// readLogLines reads a log stream to the end, demultiplexing it first when +// Docker framed it. +// +// A container without a TTY gets a multiplexed stream: every write is framed +// behind an 8-byte header, and one frame can hold several lines or part of one, +// so stripping a header off the front of each line is not enough. Containers +// the agent starts itself run with Tty: true (apps/run_app.go) and stream raw; +// compose services only get a TTY when their author asked for one. +func readLogLines(reader io.ReadCloser) []string { + defer func() { + if err := reader.Close(); err != nil { + log.Debug().Err(err).Msg("failed to close log reader") + } + }() + + buffered := bufio.NewReader(reader) + head, _ := buffered.Peek(8) + if !isStreamHeader(head) { + return scanLines(buffered) + } + + var plain bytes.Buffer + if _, err := stdcopy.StdCopy(&plain, &plain, buffered); err != nil { + // What was demultiplexed before the failure is still worth returning. + log.Debug().Err(err).Msg("log demultiplexing ended early") + } + + return scanLines(&plain) +} + // formatBound renders a window bound the way the Docker daemon and the compose // CLI both accept. The zero time means "no bound". func formatBound(bound time.Time) string { @@ -272,13 +405,7 @@ func formatBound(bound time.Time) string { return bound.UTC().Format(time.RFC3339) } -func scanLines(reader io.ReadCloser) []string { - defer func() { - if err := reader.Close(); err != nil { - log.Debug().Err(err).Msg("failed to close log reader") - } - }() - +func scanLines(reader io.Reader) []string { var lines []string scanner := bufio.NewScanner(reader) scanner.Buffer(make([]byte, 0, 64*1024), maxLogLineBytes) diff --git a/src/logging/query_test.go b/src/logging/query_test.go index 639e085..d927e43 100644 --- a/src/logging/query_test.go +++ b/src/logging/query_test.go @@ -1,22 +1,21 @@ package logging import ( + "bytes" "context" "errors" "fmt" "io" - "os" - "path/filepath" "reagent/common" "reagent/container" "reagent/errdefs" - "reagent/testutil/builders" "reagent/testutil/mocks" "strings" "testing" "time" "github.com/docker/docker/api/types/filters" + "github.com/docker/docker/pkg/stdcopy" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" @@ -192,60 +191,195 @@ func TestQueryLogsFallback(t *testing.T) { assert.True(t, result.OldestAvailable.IsZero()) }) - // The project's compose file comes from the label Docker keeps on its - // containers. `docker compose ls` used to find it: a CLI spawn of its own, - // ahead of the `compose logs` spawn — on a small device, seconds of a - // console's first load. - t.Run("reads a compose project through its label, without compose ls", func(t *testing.T) { + t.Run("surfaces a real docker failure instead of quietly serving history", func(t *testing.T) { lm, cont, _, _ := newTestManager(t) + cont.EXPECT().Logs(mock.Anything, "prod_1_logapp", mock.Anything). + Return(nil, errors.New("permission denied on the docker socket")) - dir := t.TempDir() - callsFile := filepath.Join(dir, "calls.log") - script := fmt.Sprintf("#!/bin/sh\necho \"$@\" >> %q\necho 'web-1 | hello'\n", callsFile) - binPath := filepath.Join(dir, "fake-docker") - require.NoError(t, os.WriteFile(binPath, []byte(script), 0o755)) + _, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp"}) - cont.EXPECT().Logs(mock.Anything, "prod_1_logapp", mock.Anything). - Return(nil, errdefs.ContainerNotFound(errors.New("No such container"))) - cont.EXPECT().ListContainers(mock.Anything, mock.MatchedBy(func(options common.Dict) bool { - args, ok := options["filters"].(filters.Args) - return ok && args.ExactMatch("label", "com.docker.compose.project=prod_1_logapp_compose") - })).Return([]container.ContainerResult{{ - Labels: map[string]string{container.ComposeConfigFilesLabel: "/apps/logapp/docker-compose.json"}, - }}, nil) - cont.EXPECT().Compose().Return(container.NewComposeWithBinary(builders.DefaultTestConfig(), binPath)) + assert.Error(t, err) + }) - result, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp", Tail: 10}) + t.Run("refuses an empty container name", func(t *testing.T) { + lm, _, _, _ := newTestManager(t) + + _, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: " "}) + + assert.Error(t, err) + }) +} + +// composeContainer is one container of the test app's compose project, as the +// Docker API lists it: named --1, with a leading slash. +func composeContainer(service string) container.ContainerResult { + return container.ContainerResult{ + ID: service + "-id", + Names: []string{"/prod_1_logapp_compose-" + service + "-1"}, + Labels: map[string]string{ + container.ComposeProjectLabel: "prod_1_logapp_compose", + container.ComposeServiceLabel: service, + }, + } +} + +// composeProject makes prod_1_logapp a compose app: Docker knows no container +// under the plain name, and the project label lists the given ones. Any call to +// Compose() fails the test — the read must not need the compose CLI. +func composeProject(cont *mocks.Container, containers ...container.ContainerResult) { + cont.EXPECT().Logs(mock.Anything, "prod_1_logapp", mock.Anything). + Return(nil, errdefs.ContainerNotFound(errors.New("No such container"))) + cont.EXPECT().ListContainers(mock.Anything, mock.MatchedBy(func(options common.Dict) bool { + args, ok := options["filters"].(filters.Args) + return ok && args.ExactMatch("label", "com.docker.compose.project=prod_1_logapp_compose") + })).Return(containers, nil) +} + +func TestQueryLogsCompose(t *testing.T) { + const web = "2026-08-04T09:00:01Z web listening\n2026-08-04T09:00:03Z web request failed\n" + const db = "2026-08-04T09:00:00Z db starting\n2026-08-04T09:00:02Z db ready\n" + + t.Run("merges every service into one timeline", func(t *testing.T) { + lm, cont, _, _ := newTestManager(t) + composeProject(cont, composeContainer("web"), composeContainer("db")) + alwaysReturn(cont, "web-id", web) + alwaysReturn(cont, "db-id", db) + + result, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp"}) require.NoError(t, err) assert.Equal(t, "compose", result.Source) - assert.Equal(t, []string{"web-1 | hello"}, result.Lines) + assert.Equal(t, []string{ + "db-1 | 2026-08-04T09:00:00Z db starting", + "web-1 | 2026-08-04T09:00:01Z web listening", + "db-1 | 2026-08-04T09:00:02Z db ready", + "web-1 | 2026-08-04T09:00:03Z web request failed", + }, result.Lines) + // The app's log reaches back as far as its oldest container's does. + assert.Equal(t, time.Date(2026, 8, 4, 9, 0, 0, 0, time.UTC), result.OldestAvailable.UTC()) + }) + + // Docker applies the tail per container, so each is over-read; the tail + // that matters is the app's. + t.Run("keeps the newest lines of the app, not of each service", func(t *testing.T) { + lm, cont, _, _ := newTestManager(t) + composeProject(cont, composeContainer("web"), composeContainer("db")) + alwaysReturn(cont, "web-id", web) + alwaysReturn(cont, "db-id", db) + + result, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp", Tail: 2}) - calls, err := os.ReadFile(callsFile) require.NoError(t, err) - assert.Equal(t, "compose -f /apps/logapp/docker-compose.json logs --no-color --tail 10 --timestamps\n", string(calls), - "exactly one CLI spawn, the read itself") + assert.Equal(t, []string{ + "db-1 | 2026-08-04T09:00:02Z db ready", + "web-1 | 2026-08-04T09:00:03Z web request failed", + }, result.Lines) }) - t.Run("surfaces a real docker failure instead of quietly serving history", func(t *testing.T) { + t.Run("drops the stamps the merge needed when none were asked for", func(t *testing.T) { lm, cont, _, _ := newTestManager(t) - cont.EXPECT().Logs(mock.Anything, "prod_1_logapp", mock.Anything). - Return(nil, errors.New("permission denied on the docker socket")) + composeProject(cont, composeContainer("web"), composeContainer("db")) + + var asked []common.Dict + for _, id := range []string{"web-id", "db-id"} { + body := map[string]string{"web-id": web, "db-id": db}[id] + cont.EXPECT().Logs(mock.Anything, id, mock.Anything). + RunAndReturn(func(_ context.Context, _ string, options common.Dict) (io.ReadCloser, error) { + asked = append(asked, options) + return reader(body), nil + }) + } - _, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp"}) + result, err := lm.QueryLogs(context.Background(), LogQueryRequest{ + ContainerName: "prod_1_logapp", + NoTimestamps: true, + }) - assert.Error(t, err) + require.NoError(t, err) + assert.Equal(t, []string{ + "db-1 | db starting", + "web-1 | web listening", + "db-1 | db ready", + "web-1 | web request failed", + }, result.Lines) + for _, options := range asked { + assert.Equal(t, true, options["timestamps"]) + } }) - t.Run("refuses an empty container name", func(t *testing.T) { - lm, _, _, _ := newTestManager(t) + // A compose service runs without a TTY unless its author asked for one, so + // Docker frames its stream — and a frame can hold several lines, or end in + // the middle of one. + t.Run("demultiplexes a service without a TTY", func(t *testing.T) { + lm, cont, _, _ := newTestManager(t) + composeProject(cont, composeContainer("worker")) - _, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: " "}) + var framed bytes.Buffer + stdout := stdcopy.NewStdWriter(&framed, stdcopy.Stdout) + stderr := stdcopy.NewStdWriter(&framed, stdcopy.Stderr) + _, _ = stdout.Write([]byte("2026-08-04T09:00:00Z first\n2026-08-04T09:00:01Z sec")) + _, _ = stdout.Write([]byte("ond\n")) + _, _ = stderr.Write([]byte("2026-08-04T09:00:02Z boom\n")) + alwaysReturn(cont, "worker-id", framed.String()) + + result, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp"}) + + require.NoError(t, err) + assert.Equal(t, []string{ + "worker-1 | 2026-08-04T09:00:00Z first", + "worker-1 | 2026-08-04T09:00:01Z second", + "worker-1 | 2026-08-04T09:00:02Z boom", + }, result.Lines) + assert.False(t, result.OldestAvailable.IsZero()) + }) + + t.Run("names a service with its own container_name as compose does", func(t *testing.T) { + lm, cont, _, _ := newTestManager(t) + broker := composeContainer("broker") + broker.Names = []string{"/my-broker"} + composeProject(cont, broker) + alwaysReturn(cont, "broker-id", "2026-08-04T09:00:00Z up\n") + + result, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp"}) + + require.NoError(t, err) + assert.Equal(t, []string{"my-broker | 2026-08-04T09:00:00Z up"}, result.Lines) + }) + + t.Run("skips a container removed between listing and read", func(t *testing.T) { + lm, cont, _, _ := newTestManager(t) + composeProject(cont, composeContainer("web"), composeContainer("db")) + cont.EXPECT().Logs(mock.Anything, "web-id", mock.Anything). + Return(nil, errdefs.ContainerNotFound(errors.New("No such container"))) + alwaysReturn(cont, "db-id", db) + + result, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp"}) + + require.NoError(t, err) + assert.Equal(t, "compose", result.Source) + assert.Len(t, result.Lines, 2) + }) + + // The containers are there; serving the (usually empty) stored history + // would present a failed read as an app that said nothing. + t.Run("surfaces a failed read instead of serving history", func(t *testing.T) { + lm, cont, _, _ := newTestManager(t) + composeProject(cont, composeContainer("web")) + cont.EXPECT().Logs(mock.Anything, "web-id", mock.Anything). + Return(nil, errors.New("permission denied on the docker socket")) + + _, err := lm.QueryLogs(context.Background(), LogQueryRequest{ContainerName: "prod_1_logapp"}) assert.Error(t, err) }) } +func TestDropLeadingTimestamp(t *testing.T) { + assert.Equal(t, "hello world", dropLeadingTimestamp("2026-08-04T09:12:04.123456789Z hello world")) + assert.Equal(t, "", dropLeadingTimestamp("2026-08-04T09:12:04Z ")) + assert.Equal(t, "no timestamp here", dropLeadingTimestamp("no timestamp here")) +} + func TestParseLeadingTimestamp(t *testing.T) { t.Run("reads Docker's RFC3339Nano prefix", func(t *testing.T) { parsed := parseLeadingTimestamp("2026-08-04T09:12:04.123456789Z modbus dial failed") From 7c6bb67844fba45059b9367dfe34fd3f033a89ed Mon Sep 17 00:00:00 2001 From: Marko Petzold Date: Wed, 28 Oct 2026 19:44:04 +0100 Subject: [PATCH 2/2] release reagent v1.4.6 --- availableVersions.json | 8 ++++---- src/release/version.txt | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/availableVersions.json b/availableVersions.json index e2a1b17..880a3e5 100644 --- a/availableVersions.json +++ b/availableVersions.json @@ -1,6 +1,6 @@ { - "production": "1.4.5", - "test": "1.4.5", - "local": "1.4.5", - "all": "1.4.5" + "production": "1.4.6", + "test": "1.4.6", + "local": "1.4.6", + "all": "1.4.6" } diff --git a/src/release/version.txt b/src/release/version.txt index 03e5161..7b5753f 100644 --- a/src/release/version.txt +++ b/src/release/version.txt @@ -1 +1 @@ -1.4.5 \ No newline at end of file +1.4.6 \ No newline at end of file