novox/mesh-catalog
6
0
Fork 0
Code Issues Pull Requests 4 Actions Packages Projects Releases Wiki Activity

docker: say where the runtime's event history begins, so a short history never reads as a quiet one (hq issue 348)

Browse Source 
docker_events asked for three hours across the 2026-10-09 resolver outage on the control node answered
zero events: the runtime keeps only its last ~256 events in memory, and health-check execs filled them
with the last ten minutes. The answer now carries held, oldest_held and complete, and a history line
when the window reaches further back than what the runtime still holds. The type filter moves into the
tool, since the history's start is only known from all of it.
This commit is contained in:
jochen
2026-10-09 15:04:45 +02:00
parent 2b2397abe0
commit 3d8b52c9f4
3 changed files with 101 additions and 5 deletions
Download Patch File Download Diff File Expand all files Collapse all files
modules/docker/cmd/docker-tools/docker.go
+47 -3
View File
@@ -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 {
modules/docker/cmd/docker-tools/docker_test.go
+52 -1
View File
@@ -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)
}
}
modules/docker/cmd/docker-tools/main.go
+2 -1
View File
@@ -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: <what it was>] — 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: <what it was>] — 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"},