Container events fired between the initial scan and the event listener are lost

[paskal]

Affected component

app/discovery, the initial container scan and the Docker event listener. Everything below was verified against master at d4e7080, with Docker 29.7.2.

Mechanism

NewEventNotif publishes the snapshot of running containers first and starts the listener only afterwards, app/discovery/events.go:84-91:

// first get all currently running containers
if err := res.emitRunningContainers(); err != nil {
    return nil, errors.Wrap(err, "failed to emit containers")
}

go func() {
    res.activate(dockerClient) // activate listener for new container events
}()

activate subscribes at app/discovery/events.go:112, so between the moment the daemon composes the container list and the moment the client is connected to /events, docker-logger is subscribed to nothing. An event fired in that interval is not dropped inside the client, it never reaches it: no connection to /events exists yet, and when go-dockerclient connects it does not ask for a replay, so the daemon sends only what happens from then on. AddEventListener returning does not mark the end of the interval either, since enableEventMonitoring merely spawns the monitor goroutine, vendor/github.com/fsouza/go-dockerclient/event.go:208-219:

if !eventState.enabled {
    eventState.enabled = true
    atomic.StoreInt64(&eventState.lastSeen, 0)
    eventState.C = make(chan *APIEvents, 100)
    eventState.errC = make(chan error, 1)
    go eventState.monitorEvents(c, opts)
}

That goroutine waits for listeners and then opens the connection through connectWithRetry, so the interval ends at a point the caller cannot observe.

There is no later rescan. Both directions lose containers, and the missed stop is the worse of the two because it leaves the container ID occupied in logStreams.

A separate mechanism applies once the subscription is live: the client publishes with a non-blocking send, vendor/github.com/fsouza/go-dockerclient/event.go:340-345, and discards events for a listener which is not ready. That one is what #62 addresses by buffering the listener channel, and it is not the cause of what follows.

Reproduction

The interval is short on an idle host, so the harness widens it deterministically: a proxy in front of the docker socket holds back the response to the first request, the container listing, until the script releases it, which happens only after the container transition has completed. The daemon composes the list at the normal time, docker-logger receives it afterwards, and nothing depends on a race. This has the same shape as a loaded daemon answering /containers/json slowly.

slowsock/main.go:

// slowsock proxies a docker socket and holds back the response to the first request, the container
// listing, until a release file appears. this widens the interval between the daemon composing that
// list and docker-logger subscribing to /events
package main

import (
	"bytes"
	"io"
	"log"
	"net"
	"os"
	"sync/atomic"
	"time"
)

func main() {
	listen, upstream, release := os.Args[1], os.Args[2], os.Args[3]
	os.Remove(listen)
	ln, err := net.Listen("unix", listen)
	if err != nil {
		log.Fatal(err)
	}
	var n int64
	for {
		c, err := ln.Accept()
		if err != nil {
			return
		}
		go func(c net.Conn) {
			defer c.Close()
			u, err := net.Dial("unix", upstream)
			if err != nil {
				return
			}
			defer u.Close()
			first := atomic.AddInt64(&n, 1) == 1
			go io.Copy(u, c) // the request goes upstream at once, the daemon composes the list now
			if first {
				buf := make([]byte, 64*1024)
				nr, err := u.Read(buf)
				if err != nil {
					return
				}
				log.Print("holding the container listing response")
				for deadline := time.Now().Add(60 * time.Second); time.Now().Before(deadline); {
					if _, err := os.Stat(release); err == nil {
						break
					}
					time.Sleep(50 * time.Millisecond)
				}
				log.Print("releasing the container listing response")
				io.Copy(c, bytes.NewReader(buf[:nr]))
			}
			io.Copy(c, u)
		}(c)
	}
}

repro.sh, which takes the binary to test and the scenario:

#!/bin/bash
# $1 docker-logger binary, $2 scenario: start | stop
set -u
BIN="$1"; SCEN="${2:-start}"; HERE=$(dirname "$0")
WORK=$(mktemp -d); SOCK="$WORK/docker.sock"; RELEASE="$WORK/release"
cleanup() {
  [ -n "${DL:-}" ] && kill "$DL" 2>/dev/null
  [ -n "${PROXY:-}" ] && kill "$PROXY" 2>/dev/null
  docker rm -f gap-test >/dev/null 2>&1
  rm -rf "$WORK"
}
trap cleanup EXIT
waitfor() { # waitfor <seconds> <command...>
  local deadline=$((SECONDS + $1)); shift
  until "$@"; do
    [ $SECONDS -ge $deadline ] && { echo "timed out waiting for: $*" >&2; exit 1; }
    sleep 0.05
  done
}

docker rm -f gap-test >/dev/null 2>&1
if [ "$SCEN" = stop ]; then
  docker run -d --name gap-test alpine sh -c 'while true; do echo tick; sleep 1; done' >/dev/null
  sleep 2
else
  docker create --name gap-test alpine sh -c 'while true; do echo tick; sleep 1; done' >/dev/null
fi

"$HERE/slowsock-bin" "$SOCK" /var/run/docker.sock "$RELEASE" > "$WORK/proxy.log" 2>&1 &
PROXY=$!
waitfor 10 test -S "$SOCK"
"$BIN" -d "unix://$SOCK" --files --loc="$WORK" --dbg --include=gap-test > "$WORK/dl.out" 2>&1 &
DL=$!

# the daemon has composed the listing and the proxy is holding its response
waitfor 30 grep -q "holding the container listing response" "$WORK/proxy.log"
if [ "$SCEN" = stop ]; then docker stop -t 0 gap-test >/dev/null; else docker start gap-test >/dev/null; fi
touch "$RELEASE"                       # transition is complete, let the listing through
waitfor 30 grep -q "completed initial emit" "$WORK/dl.out"
sleep 10

echo "--- scenario: $SCEN, binary: $(basename "$BIN") ---"
if [ "$SCEN" = stop ]; then
  docker start gap-test >/dev/null     # same container ID returns after the missed stop
  sleep 10
  echo "docker-logger log file: $(wc -l < "$WORK/gap-test.log" 2>/dev/null || echo 0) lines"
  echo "container produced:     $(docker logs gap-test 2>&1 | wc -l | tr -d ' ') lines"
else
  [ -s "$WORK/gap-test.log" ] && echo "RESULT: streamed, $(wc -l < "$WORK/gap-test.log") lines" || echo "RESULT: MISSED, no log file"
fi
grep -hE "total containers|running container added|new event|dbl-start|stream from .* terminated" "$WORK/dl.out" |
  sed -E 's/\{[a-z/]+\.go:[0-9]+ [^}]+\} //; s/^/  /'

Build the binaries being compared:

git -C docker-logger checkout d4e7080 && (cd docker-logger/app && go build -o /tmp/dl-master .)

Observed result

Output as produced by the script, which strips the {file:line func} field from each log line. Shown here with the leading date dropped, container IDs shortened and the Group: field removed for width; nothing else is changed.

A missed start, ./repro.sh /tmp/dl-master start. The container is started while the listing response is held back, so it is in neither source:

--- scenario: start, binary: dl-master ---
RESULT: MISSED, no log file
  09:04:25.513 [DEBUG] total containers = 3

No running container added line for gap-test, no new event line for it, and no log file, while docker ps shows it up and docker logs gap-test keeps producing output.

A missed stop, ./repro.sh /tmp/dl-master stop. The container is stopped inside the interval, so the listing still carries it:

--- scenario: stop, binary: dl-master ---
docker-logger log file:        3 lines
container produced:     14 lines
  09:04:48.044 [DEBUG] total containers = 4
  09:04:48.044 [DEBUG] running container added, {ContainerID:b49ea13... ContainerName:gap-test TS:09:04:44 Status:true}
  09:04:48.063 [INFO]  stream from b49ea13... terminated
  09:04:58.372 [INFO]  new event {ContainerID:b49ea13... ContainerName:gap-test TS:09:04:58.368488094 Status:true}
  09:04:58.372 [WARN]  ignore dbl-start {ContainerID:b49ea13... ContainerName:gap-test TS:09:04:58.368488094 Status:true}

A streamer is created from the stale listing for a container which is already gone, Logs returns at once and the goroutine exits, but the entry stays in logStreams with its writers open. The container then comes back under the same ID, its start event arrives normally, and it is rejected as a duplicate at app/main.go:132. Logging stays frozen until the next recognised down transition clears the entry at app/main.go:154-164: in a separate run the file sat at 4 lines after the ignored start, and resumed, reaching 20 lines, after a further stop and start.

The branch in #62, tested at 8ccd534, behaves identically in both scenarios, no log file for the missed start and 3 lines against 14 for the missed stop, so its buffering does not cover this.

Without the proxy the interval is real but short, and I could not force a miss from a shell script, because docker start latency on the test host varies by more than its width. For scale: on an idle host with two containers, 93 ms elapsed between entering NewEventNotif (create events notif at 08:03:58.105) and the listing being processed (total containers = 2 at 08:03:58.198). That figure is an upper bound on one part of the interval and includes the local setup done in between; the interval itself begins inside the call, when the daemon captures the list, and ends when the /events connection is up. I would expect it to widen with daemon load and container count, though I did not measure that.

Impact

A container silently produces no logs until it is restarted, or, in the missed stop case, is silently not logged from the moment it comes back until the next stop and start cycle, with the writers of the dead streamer left open in the meantime. Both fail quietly. The exposure is largest exactly where docker-logger is normally deployed: a host with many containers, and a compose stack which starts docker-logger alongside everything else.

Options

1. Subscribe before listing. Start activate first, then take the snapshot. This narrows the interval but does not close it, because AddEventListener returns once the local listener is registered while the /events connection is opened later by monitorEvents, with no signal for when that happens. It also needs the snapshot reconciled against whatever arrives while it is being collected, otherwise a stop which lands before the snapshot entry is ignored as unmapped and the snapshot then recreates the streamer for a dead container.

2. Have the daemon replay, with AddEventListenerWithOptions and Since set to a timestamp taken before ListContainers. The daemon re-delivers the interval, which is the only option that recovers the events rather than shrinking the window in which they are lost. What it does not give you for free:

   • Ordering. The client dispatches every event in its own goroutine, vendor/github.com/fsouza/go-dockerclient/event.go:277-280, so a pair can arrive reversed. I saw this in the prototype run below, where the down event stamped 09:05:25.348 was delivered before the one stamped 09:05:25.378; harmless there, since both are down events. It is not harmless in general: a start followed by a stop, delivered reversed, leaves a streamer attached to a container which has exited, and a stop followed by a start, delivered reversed, leaves a running container unlogged. Rejecting events older than the last one seen for that container ID, using Event.TS, would need the timestamp recorded even for the events runEventLoop currently ignores.
   • Duplicates. The existing guards absorb a repeated start (app/main.go:132) and an unmapped stop (app/main.go:157), but a replayed stop/start pair legitimately closes and recreates a streamer. Every reattachment reads the tail again, Tail: "10" at app/logger/logger.go:42-50, so up to ten lines are written twice; this is not specific to replay, it happens on an ordinary restart too, but replay makes it more frequent. In one prototype run the file ended at 17 lines against the 14 the container produced; how many lines are doubled depends on how much output preceded the stop, and the run shown below happens not to show it.
   • Bounds. Moby keeps a bounded ring of past events, 256 across all event types, so an interval in which the daemon emits more than that still loses the oldest.
   • Clock. Since is interpreted by the daemon, so for a remote daemon the timestamp should come from the daemon rather than from the docker-logger host, and it needs subsecond precision, otherwise up to a second of extra history is replayed on every start.
   • It also wants the buffered listener channel from Fix startup deadlock and event loss in discovery #62 underneath it, since the replay arrives as a burst into the non-blocking send at vendor/.../event.go:340-345.

3. Leave it and treat the interval as a known limitation.

I prototyped option 2 with the extra method behind an optional interface, so the exported discovery.DockerClient stays as it is. The patch below applies to #62 at 8ccd534, which supplies the buffered listener channel:

diff --git a/app/discovery/events.go b/app/discovery/events.go
index 88dae17..7fb5168 100644
--- a/app/discovery/events.go
+++ b/app/discovery/events.go
@@ -3,6 +3,7 @@ package discovery
 import (
 	"regexp"
 	"slices"
+	"strconv"
 	"strings"
 	"time"

@@ -19,6 +20,7 @@ type EventNotif struct {
 	includesRegexp *regexp.Regexp
 	excludesRegexp *regexp.Regexp
 	eventsCh       chan Event
+	since          time.Time
 	listenerErr    chan error // communicates activate() failure back to the caller
 }

@@ -87,6 +89,7 @@ func NewEventNotif(dockerClient DockerClient, opts EventNotifOpts) (*EventNotif,
 		includesRegexp: includesRe,
 		excludesRegexp: excludesRe,
 		listenerErr:    make(chan error, 1),
+		since:          time.Now(),
 	}

 	// first get all currently running containers, the caller can't consume events until this returns
@@ -125,7 +128,16 @@ func (e *EventNotif) Err() <-chan error {
 // on failure or channel close, it closes eventsCh to signal consumers.
 func (e *EventNotif) activate(client DockerClient) {
 	dockerEventsCh := make(chan *docker.APIEvents, dockerEventsChBuffer)
-	if err := client.AddEventListener(dockerEventsCh); err != nil {
+	addListener := func() error { return client.AddEventListener(dockerEventsCh) }
+	if c, ok := client.(interface {
+		AddEventListenerWithOptions(opts docker.EventsOptions, listener chan<- *docker.APIEvents) error
+	}); ok {
+		addListener = func() error {
+			since := strconv.FormatFloat(float64(e.since.UnixNano())/1e9, 'f', 9, 64)
+			return c.AddEventListenerWithOptions(docker.EventsOptions{Since: since}, dockerEventsCh)
+		}
+	}
+	if err := addListener(); err != nil {
 		log.Printf("[ERROR] can't add event listener, %v", err)
 		e.listenerErr <- errors.Wrap(err, "can't add event listener")
 		close(e.eventsCh)

git -C docker-logger checkout 8ccd534 && git -C docker-logger apply option2.patch
(cd docker-logger/app && go build -o /tmp/dl-option2 .)

Both scenarios recover with it. The missed start is streamed, caught via the replayed event rather than the snapshot, and the missed stop clears the stale entry and re-attaches when the container returns, the trailing Status:true here being the live event for that return:

--- scenario: start, binary: dl-option2 ---
RESULT: streamed,       11 lines
  09:05:10.641 [DEBUG] total containers = 2
  09:05:10.651 [INFO]  new event {ContainerID:c84f9b3... TS:09:05:10.578127168 Status:true}

--- scenario: stop, binary: dl-option2 ---
docker-logger log file:       13 lines
container produced:     14 lines
  09:05:25.428 [DEBUG] total containers = 3
  09:05:25.428 [DEBUG] running container added, {ContainerID:764647d... TS:09:05:21 Status:true}
  09:05:25.442 [INFO]  new event {ContainerID:764647d... TS:09:05:25.348487717 Status:false}
  09:05:25.442 [INFO]  stream from 764647d... terminated
  09:05:25.448 [INFO]  new event {ContainerID:764647d... TS:09:05:25.378037009 Status:false}
  09:05:35.845 [INFO]  new event {ContainerID:764647d... TS:09:05:35.841892208 Status:true}

Recommendation

Option 2, since it is the only one which recovers the lost events rather than shrinking the window, with two decisions I would rather leave to you.

The first is the interface: adding AddEventListenerWithOptions to discovery.DockerClient is the direct version, source-incompatible for an outside implementation and requiring the mock to be regenerated, while the optional interface in the patch keeps the exported interface untouched at the price of a fallback path which never runs in production.

The second is how far to take the reconciliation: replay alone fixes both failures above but leaves the duplicated tail and the reordering, and handling those properly needs the per-container timestamp bookkeeping described in option 2. Either shape wants regression tests covering the replayed events.

[paskal]

Re-checked against master at 43fb2cd, which now carries both #62 and #63: the behaviour is unchanged. The missed start produces no log file at all, and the missed stop leaves the file at 3 lines against the 14 the container produced, with the return of the container rejected at app/main.go:132. The line numbers quoted in the description still point at the same code after both merges.