diff --git a/modules/docker/cmd/docker-tools/docker.go b/modules/docker/cmd/docker-tools/docker.go index 872b8f3d..7411ac21 100644 --- a/modules/docker/cmd/docker-tools/docker.go +++ b/modules/docker/cmd/docker-tools/docker.go @@ -991,16 +991,27 @@ func (c *Client) Volumes(ctx context.Context, unmountedOnly, sizes bool) (map[st } // Events is what the runtime did in a window ending now, the latest last. +// +// **The runtime keeps only its last events in memory** (about 256), and the images' own health checks +// make three exec events each per look: on a machine with a few checked containers that history is ten +// minutes long or less, all of it exec events (hq research 032). A window asked for further back than +// the history reaches is answered with what is still held AND says where the history begins, so an +// empty list never reads as "nothing happened" (hq issue 348: three hours asked across an outage, +// answered zero). The type filter is applied here rather than by the runtime, for the same reason: the +// history's start is only known from all of it. func (c *Client) Events(ctx context.Context, minutes int, kind string, limit int, execs bool) (map[string]any, error) { - args := []string{"events", "--since", fmt.Sprintf("%dm", minutes), "--until", "0s", "--format", "{{json .}}"} + return c.eventsAt(ctx, time.Now(), minutes, kind, limit, execs) +} + +func (c *Client) eventsAt(ctx context.Context, now time.Time, minutes int, kind string, limit int, execs bool) (map[string]any, error) { if kind != "" { switch kind { case "container", "image", "network", "volume", "daemon", "plugin", "builder": default: return nil, fmt.Errorf("type %q: container, image, network, volume, daemon, plugin or builder", kind) } - args = append(args, "--filter", "type="+kind) } + args := []string{"events", "--since", fmt.Sprintf("%dm", minutes), "--until", "0s", "--format", "{{json .}}"} out, err := c.docker(ctx, args...) if err != nil { return nil, err @@ -1015,6 +1026,9 @@ func (c *Client) Events(ctx context.Context, minutes int, kind string, limit int redacted := map[string]bool{} events := []map[string]any{} for _, e := range raw { + if kind != "" && e.Type != kind { + continue + } if !execs && strings.HasPrefix(e.Action, "exec_") { continue } @@ -1042,14 +1056,44 @@ func (c *Client) Events(ctx context.Context, minutes int, kind string, limit int if len(events) > limit { events = events[len(events)-limit:] } - answer := map[string]any{"minutes": minutes, "count": total, "shown": len(events), "events": events} + answer := map[string]any{"minutes": minutes, "count": total, "shown": len(events), "events": events, + "held": len(raw)} if len(redacted) > 0 { answer["redacted"] = sortedSet(redacted) answer["leak"] = "exec command lines carried secrets, which the runtime keeps in its events; docker_secrets_in_events names them (novox/hq issue 282)" } + for k, v := range historyReach(raw, now, minutes) { + answer[k] = v + } return answer, nil } +// historyGap is how much later than the window's start the runtime's oldest held event may be and the +// window still read as covered: events are not made every second. +const historyGap = 2 * time.Minute + +// historyReach says where the runtime's history begins when it begins after the window asked for: the +// oldest event it still holds, and that nothing before it can be answered from here. +func historyReach(raw []runtimeEvent, now time.Time, minutes int) map[string]any { + start := now.Add(-time.Duration(minutes) * time.Minute) + if len(raw) == 0 { + return map[string]any{"complete": false, + "history": "the runtime holds no events at all for this window: it keeps only its last events in memory, so this says nothing about what happened before now — ask the service manager's journal for the docker unit"} + } + oldest := time.Unix(0, raw[0].TimeNano) + for _, e := range raw { + if t := time.Unix(0, e.TimeNano); t.Before(oldest) { + oldest = t + } + } + if oldest.Sub(start) <= historyGap { + return map[string]any{"complete": true, "oldest_held": oldest.UTC().Format(time.RFC3339)} + } + return map[string]any{"complete": false, "oldest_held": oldest.UTC().Format(time.RFC3339), + "history": fmt.Sprintf("the runtime keeps only its last %d events in memory and its oldest is from %s; the window asked starts at %s, so what happened before %s is gone from here, not absent — the images' health checks fill the history with exec events (hq research 032)", + len(raw), oldest.UTC().Format(time.RFC3339), start.UTC().Format(time.RFC3339), oldest.UTC().Format("15:04:05Z"))} +} + func sortedSet(set map[string]bool) []string { out := make([]string, 0, len(set)) for k := range set { diff --git a/modules/docker/cmd/docker-tools/docker_test.go b/modules/docker/cmd/docker-tools/docker_test.go index 22774e83..41ff8eb7 100644 --- a/modules/docker/cmd/docker-tools/docker_test.go +++ b/modules/docker/cmd/docker-tools/docker_test.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "errors" + "fmt" "io/fs" "os" "reflect" @@ -307,7 +308,8 @@ func TestEventsAreABoundedWindowWithoutExecNoise(t *testing.T) { if len(evs) != 1 || evs[0]["action"] != "die" || evs[0]["mesh_held"] != true || evs[0]["exit_code"] != "137" { t.Fatalf("%v", evs) } - if !f.ran("docker events --since 30m --until 0s --format {{json .}} --filter type=container") { + // The type is filtered here, not by the runtime: the history's start is only known from all of it (issue 348). + if !f.ran("docker events --since 30m --until 0s --format {{json .}}") || f.ran("docker events --since 30m --until 0s --format {{json .}} --filter") { t.Fatalf("%+v", f.calls) } if _, err := client(f, 1000).Events(context.Background(), 30, "secret", 10, false); err == nil { @@ -362,3 +364,52 @@ func TestProblemsNameWhyAndUnlabelledIsTheCleanupList(t *testing.T) { t.Fatalf("%v %v", u, err) } } + +// eventLine is one line of `docker events --format '{{json .}}'`. +func eventLine(at time.Time, kind, action, name string) string { + return fmt.Sprintf(`{"Type":%q,"Action":%q,"Actor":{"ID":"abcdef0123456789","Attributes":{"name":%q}},"timeNano":%d}`+"\n", + kind, action, name, at.UnixNano()) +} + +// Issue 348: three hours asked across an outage answered zero, because the runtime's history held only the +// last ten minutes of health-check execs. The answer must say the history is short, not that nothing happened. +func TestEventsSayWhereTheRuntimesHistoryBeginsWhenTheWindowReachesFurther(t *testing.T) { + now := time.Date(2026, 10, 9, 11, 24, 0, 0, time.UTC) + var out strings.Builder + for i := 0; i < 250; i++ { + out.WriteString(eventLine(now.Add(-10*time.Minute+time.Duration(i)*2*time.Second), "container", "exec_die", "mailu-webmail")) + } + got, err := client((&fake{}).on("docker events", Ran{Stdout: out.String()}), 1000).eventsAt(context.Background(), now, 180, "", 200, false) + if err != nil { + t.Fatal(err) + } + if got["count"] != 0 || got["held"] != 250 { + t.Fatalf("count %v held %v, want 0 shown of 250 held", got["count"], got["held"]) + } + if got["complete"] != false || !strings.Contains(fmt.Sprint(got["history"]), "gone from here, not absent") || + got["oldest_held"] != "2026-10-09T11:14:00Z" { + t.Fatalf("an empty answer from a short history reads as quiet: %v", got) + } +} + +func TestEventsCoveringTheWholeWindowSayItIsCompleteAndFilterTheTypeHere(t *testing.T) { + now := time.Date(2026, 10, 9, 11, 24, 0, 0, time.UTC) + out := eventLine(now.Add(-59*time.Minute), "network", "destroy", "build-net") + + eventLine(now.Add(-30*time.Minute), "container", "die", "build-bus") + + eventLine(now.Add(-1*time.Minute), "network", "create", "build-net") + f := (&fake{}).on("docker events", Ran{Stdout: out}) + got, err := client(f, 1000).eventsAt(context.Background(), now, 60, "network", 200, false) + if err != nil { + t.Fatal(err) + } + if got["complete"] != true || got["count"] != 2 || got["history"] != nil { + t.Fatalf("a covered window: %v", got) + } + if f.ran("docker events --since 60m --until 0s --format {{json .}} --filter") { + t.Fatal("the type was filtered by the runtime, so the history's start is unknown") + } + got, _ = client((&fake{}).on("docker events", Ran{}), 1000).eventsAt(context.Background(), now, 60, "", 200, false) + if got["complete"] != false || got["history"] == nil { + t.Fatalf("no events at all reads as quiet: %v", got) + } +} diff --git a/modules/docker/cmd/docker-tools/main.go b/modules/docker/cmd/docker-tools/main.go index f5c812ea..9e95a39d 100644 --- a/modules/docker/cmd/docker-tools/main.go +++ b/modules/docker/cmd/docker-tools/main.go @@ -262,7 +262,8 @@ func tools(c *Client) []stdio.Tool { { Name: "docker_events", Description: "What the runtime did in a window ending now (default the last 60 minutes, at most 24 hours): containers created, started, died, health changes, images pulled — with mesh_held. Exec events are left out unless asked; " + - "an exec's command line is shown with any secret it carried as [redacted: ] — a value of the container's environment named like a secret, a password in a URI, the word after a password flag.", + "an exec's command line is shown with any secret it carried as [redacted: ] — a value of the container's environment named like a secret, a password in a URI, the word after a password flag. " + + "The runtime keeps only its last ~256 events in memory, which health-check execs fill in minutes: complete=false and history say where what it holds begins, and an empty list then means gone, not quiet.", Input: map[string]any{ "minutes": map[string]any{"type": "integer", "description": "how far back (default 60, at most 1440)"}, "type": map[string]any{"type": "string", "description": "only one kind: container, image, network, volume, daemon, plugin or builder"},