feat: Keep track of seen containers to set "Since" time more accurately

Before, logs where always truncated to latest container start. To get rid
of this restriction containers are kept track of, not just if their
active, but ever (as long as they fit in cache and are not removed) Log
streams end when containers terminate and if the container starts again
using the --since time will print logs that were already printed on
earlier starts of the container. If the container has been seen earlier
logs will be printed from latest start/finish time. Unless --since is
later than the start time which is unlikely unless retrying a failed log
stream is done (which is not merged yet).

Author: hogklint

README.md

@@ -52,7 +52,7 @@ The `container query` is a regular expression of the container name; you could p
  `--no-follow`               | `false`                         | Exit when all logs have been shown.
  `--only-log-lines`          | `false`                         | Print only log lines
  `--output`, `-o`            | `default`                       | Specify predefined template. Currently support: [default, raw, json, extjson, ppextjson]
- `--since`, `-s`             | `48h0m0s`                       | Return logs newer than a relative duration like 5s, 2m, or 3h. The duration is truncated at container start time.
+ `--since`, `-s`             | `48h0m0s`                       | Return logs newer than a relative duration like 5s, 2m, or 3h.
  `--stdin`                   | `false`                         | Parse logs from stdin. All Docker related flags are ignored when it is set.
  `--tail`                    | `-1`                            | The number of lines from the end of the logs to show. Defaults to -1, showing all logs.
  `--template`                |                                 | Template to use for log lines, leave empty to use --output flag.

cmd/tailfincmd/cmd.go

@@ -348,7 +348,7 @@ func (o *options) AddFlags(fs *pflag.FlagSet) {
 	fs.StringArrayVarP(&o.label, "label", "l", o.label, "Label query to filter on. One `key` or `key=value` per flag instance.")
 	fs.IntVar(&o.maxLogRequests, "max-log-requests", o.maxLogRequests, "Maximum number of concurrent logs to request. Defaults to 50, but 5 when specifying --no-follow")
 	fs.StringVarP(&o.output, "output", "o", o.output, "Specify predefined template. Currently support: [default, raw, json, extjson, ppextjson]")
-	fs.DurationVarP(&o.since, "since", "s", o.since, "Return logs newer than a relative duration like 5s, 2m, or 3h. The duration is truncated at container start time.")
+	fs.DurationVarP(&o.since, "since", "s", o.since, "Return logs newer than a relative duration like 5s, 2m, or 3h.")
 	fs.Int64Var(&o.tail, "tail", o.tail, "The number of lines from the end of the logs to show. Defaults to -1, showing all logs.")
 	fs.StringVar(&o.template, "template", o.template, "Template to use for log lines, leave empty to use --output flag.")
 	fs.StringVarP(&o.templateFile, "template-file", "T", o.templateFile, "Path to template to use for log lines, leave empty to use --output flag. It overrides --template option.")

stern/docker_stern.go

@@ -38,6 +38,7 @@ func RunDocker(ctx context.Context, client *dockerclient.Client, config *DockerC
 			target.Tty,
 			target.StartedAt,
 			target.FinishedAt,
+			target.SeenPreviously,
 			config.Template,
 			config.Out,
 			config.ErrOut,
@@ -55,7 +56,9 @@ func RunDocker(ctx context.Context, client *dockerclient.Client, config *DockerC
 		containerExcludeFilter: config.ExcludeContainerQuery,
 		composeProjectFilter:   config.ComposeProjectQuery,
 		imageFilter:            config.ImageQuery,
-	})
+	},
+		max(config.MaxLogRequests*2, 100),
+	)
 
 	tailTarget := func(target *DockerTarget) error {
 		tail := newTail(target)

stern/docker_tail.go

@@ -25,6 +25,7 @@ type DockerTail struct {
 	Tty            bool
 	StartedAt      time.Time
 	FinishedAt     string
+	SeenPreviously bool
 	composeColor   *color.Color
 	containerColor *color.Color
 	Options        *TailOptions
@@ -42,6 +43,7 @@ func NewDockerTail(
 	tty bool,
 	startedAt time.Time,
 	finishedAt string,
+	seenPreviously bool,
 	tmpl *template.Template,
 	out, errOut io.Writer,
 	options *TailOptions,
@@ -56,6 +58,7 @@ func NewDockerTail(
 		Tty:            tty,
 		StartedAt:      startedAt,
 		FinishedAt:     finishedAt,
+		SeenPreviously: seenPreviously,
 		Options:        options,
 		composeColor:   composeColor,
 		containerColor: containerColor,
@@ -99,22 +102,21 @@ func (t *DockerTail) Close() {
 	close(t.closed)
 }
 
-// The maximum "since time" is the time the container was last started. Because logs are sometimes missing when using
-// the start time, the finished time is used instead (because there are no logs between the finish and start time). If
-// the Options.SinceTime is after the finished time it'll be used with the same reasoning in addition to it might be
-// after the start time, which in that case is the desired "since time".
+// Since log streams end when containers terminate tailfin must keep track of when a container has been previously
+// tailed and use a "since"-time from last finish/start. Otherwise it will include logs from previous starts thus
+// printing logs already printed.
 func (t *DockerTail) getSinceTime() time.Time {
-	finished, err := time.Parse(time.RFC3339, t.FinishedAt)
-	// If there's no finish time it should mean the container only started once so it's safe to use the options time. The
-	// same applies if the finish time is earlier than the option time.
-	if err != nil ||
-		finished.Before(t.Options.DockerSinceTime) ||
+	if !t.SeenPreviously ||
 		t.StartedAt.Before(t.Options.DockerSinceTime) {
 		return t.Options.DockerSinceTime
 	}
 
-	// Sometimes early logs are missing if StartedAt is used
-	if finished.Before(t.StartedAt) {
+	// If there's no finish time it should mean the container only started once so it's safe to use the options time.
+	finished, err := time.Parse(time.RFC3339, t.FinishedAt)
+	if err != nil {
+		return t.Options.DockerSinceTime
+	} else if finished.Before(t.StartedAt) {
+		// Sometimes early logs are missing if StartedAt is used
 		return finished
 	}
 	return t.StartedAt

stern/docker_tail_test.go

@@ -15,71 +15,80 @@ func TestGetSinceTime(t *testing.T) {
 		startTime   time.Time
 		finishTime  string
 		optionsTime time.Time
+		seen        bool
 		expected    time.Time
 	}{
 		{
-			desc:        "invalid finish, earlier start",
+			desc:        "invalid finish, seen",
 			startTime:   t1,
 			finishTime:  "",
 			optionsTime: t2,
+			seen:        true,
 			expected:    t2,
 		},
 		{
-			desc:        "invalid finish, later start",
-			startTime:   t2,
-			finishTime:  "",
-			optionsTime: t1,
-			expected:    t1,
-		},
-		{
-			desc:        "finish earlier than option",
+			desc:        "finish earlier than option, seen",
 			startTime:   t3,
 			finishTime:  t1.Format(time.RFC3339),
 			optionsTime: t2,
-			expected:    t2,
+			seen:        true,
+			expected:    t1,
 		},
 		{
-			desc:        "start earlier than option",
+			desc:        "start earlier than option, seen",
 			startTime:   t1,
 			finishTime:  t3.Format(time.RFC3339),
 			optionsTime: t2,
+			seen:        true,
 			expected:    t2,
 		},
 		{
-			desc:        "option later than both 1",
+			desc:        "option later than both, seen",
 			startTime:   t2,
 			finishTime:  t1.Format(time.RFC3339),
 			optionsTime: t3,
+			seen:        true,
 			expected:    t3,
 		},
 		{
-			desc:        "option later than both 2",
-			startTime:   t1,
-			finishTime:  t2.Format(time.RFC3339),
-			optionsTime: t3,
-			expected:    t3,
-		},
-		{
-			desc:        "truncated to start",
+			desc:        "truncated to start, seen",
 			startTime:   t2,
 			finishTime:  t3.Format(time.RFC3339),
 			optionsTime: t1,
+			seen:        true,
 			expected:    t2,
 		},
 		{
-			desc:        "truncated to finish",
+			desc:        "truncated to finish, seen",
 			startTime:   t3,
 			finishTime:  t2.Format(time.RFC3339),
 			optionsTime: t1,
+			seen:        true,
 			expected:    t2,
 		},
+		{
+			desc:        "start earlier than option, not seen",
+			startTime:   t1,
+			finishTime:  t2.Format(time.RFC3339),
+			optionsTime: t3,
+			seen:        false,
+			expected:    t3,
+		},
+		{
+			desc:        "start later than option, not seen",
+			startTime:   t2,
+			finishTime:  t3.Format(time.RFC3339),
+			optionsTime: t1,
+			seen:        false,
+			expected:    t1,
+		},
 	}
 	for _, tt := range tests {
 		t.Run(tt.desc, func(t *testing.T) {
 			options := &TailOptions{
 				DockerSinceTime: tt.optionsTime,
 			}
-			tail := NewDockerTail(nil, "", "", "", false, tt.startTime, tt.finishTime, nil, io.Discard, io.Discard, options)
+			tail := NewDockerTail(nil, "", "", "", false, tt.startTime, tt.finishTime, tt.seen, nil, io.Discard, io.Discard, options)
 
 			actual := tail.getSinceTime()
 			if tt.expected != actual {

stern/docker_target.go

@@ -7,6 +7,7 @@ import (
 	"time"
 
 	"github.com/docker/docker/api/types"
+	"github.com/hashicorp/golang-lru/v2"
 	"k8s.io/klog/v2"
 )
 
@@ -17,6 +18,7 @@ type DockerTarget struct {
 	Tty            bool
 	StartedAt      time.Time
 	FinishedAt     string
+	SeenPreviously bool
 }
 
 type dockerTargetFilterConfig struct {
@@ -29,13 +31,20 @@ type dockerTargetFilterConfig struct {
 type dockerTargetFilter struct {
 	config           dockerTargetFilterConfig
 	activeContainers map[string]time.Time
+	seenContainers   *lru.Cache[string, bool]
 	mu               sync.RWMutex
 }
 
-func newDockerTargetFilter(filterConfig dockerTargetFilterConfig) *dockerTargetFilter {
+func newDockerTargetFilter(filterConfig dockerTargetFilterConfig, lruCacheSize int) *dockerTargetFilter {
+	lru, err := lru.New[string, bool](lruCacheSize)
+	if err != nil {
+		panic(err)
+	}
+
 	return &dockerTargetFilter{
 		config:           filterConfig,
 		activeContainers: make(map[string]time.Time),
+		seenContainers:   lru,
 	}
 }
 
@@ -73,6 +82,7 @@ func (f *dockerTargetFilter) visit(container types.ContainerJSON, visitor func(t
 		Tty:            container.Config.Tty,
 		StartedAt:      startedAt,
 		FinishedAt:     container.State.FinishedAt,
+		SeenPreviously: f.seenContainers.Contains(container.ID),
 	}
 
 	if f.shouldAdd(target) {
@@ -95,6 +105,7 @@ func (f *dockerTargetFilter) shouldAdd(t *DockerTarget) bool {
 		return false
 	}
 
+	f.seenContainers.Add(t.Id, true)
 	return true
 }
 
@@ -151,14 +162,21 @@ func (f *dockerTargetFilter) matchingImageFilter(containerImage string) bool {
 	return false
 }
 
-func (f *dockerTargetFilter) forget(containerId string) {
+func (f *dockerTargetFilter) inactive(containerId string) {
+	f.seenContainers.Add(containerId, true)
 	f.mu.Lock()
 	defer f.mu.Unlock()
 
-	klog.V(7).InfoS("Forget container", "target", containerId)
+	klog.V(7).InfoS("Inactive container", "target", containerId)
 	delete(f.activeContainers, containerId)
 }
 
+func (f *dockerTargetFilter) forget(containerId string) {
+	klog.V(7).InfoS("Forget container", "target", containerId)
+	// Actively remove container from LRU cache to minimize the risk of old (but not removed) containers getting evicted
+	f.seenContainers.Remove(containerId)
+}
+
 func (f *dockerTargetFilter) isActive(t *DockerTarget) bool {
 	f.mu.RLock()
 	defer f.mu.RUnlock()

stern/docker_watch.go

@@ -14,7 +14,7 @@ func WatchDockers(ctx context.Context, config *DockerConfig, filter *dockerTarge
 	added := make(chan *DockerTarget)
 	go func() {
 		visitor := func(t *DockerTarget) {
-			klog.V(7).InfoS("New container", "id", t.Id, "name", t.Name)
+			klog.V(7).InfoS("Active container", "id", t.Id, "name", t.Name)
 			added <- t
 		}
 		ctx, cancel := context.WithCancel(ctx)
@@ -24,6 +24,7 @@ func WatchDockers(ctx context.Context, config *DockerConfig, filter *dockerTarge
 		args := filters.NewArgs()
 		args.Add("event", string(events.ActionDie))
 		args.Add("event", string(events.ActionStart))
+		args.Add("event", string(events.ActionDestroy))
 		for _, label := range config.Label {
 			args.Add("label", label)
 		}
@@ -52,6 +53,8 @@ func WatchDockers(ctx context.Context, config *DockerConfig, filter *dockerTarge
 					klog.V(8).InfoS("Container inspect", "id", e.ID, "container JSON", container)
 					filter.visit(container, visitor)
 				case events.ActionDie:
+					filter.inactive(e.ID)
+				case events.ActionDestroy:
 					filter.forget(e.ID)
 				}
 			case <-ctx.Done():