Browse code

Logfile: Add tracing spans

This plumbs a context down the stack and handles cancellation as needed
so that we can have correlated traces from the API.

Signed-off-by: Brian Goff <cpuguy83@gmail.com>

Brian Goff authored on 2024/06/14 10:11:34
Showing 15 changed files
... ...
@@ -141,7 +141,7 @@ func (daemon *Daemon) containerAttach(c *container.Container, cfg *stream.Attach
141 141
 		if !ok {
142 142
 			return logger.ErrReadLogsNotSupported{}
143 143
 		}
144
-		logs := cLog.ReadLogs(logger.ReadConfig{Tail: -1})
144
+		logs := cLog.ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1})
145 145
 		defer logs.ConsumerGone()
146 146
 
147 147
 	LogLoop:
... ...
@@ -87,7 +87,7 @@ type pluginAdapterWithRead struct {
87 87
 	*pluginAdapter
88 88
 }
89 89
 
90
-func (a *pluginAdapterWithRead) ReadLogs(config ReadConfig) *LogWatcher {
90
+func (a *pluginAdapterWithRead) ReadLogs(ctx context.Context, config ReadConfig) *LogWatcher {
91 91
 	watcher := NewLogWatcher()
92 92
 
93 93
 	go func() {
... ...
@@ -101,6 +101,10 @@ func (a *pluginAdapterWithRead) ReadLogs(config ReadConfig) *LogWatcher {
101 101
 
102 102
 		dec := logdriver.NewLogEntryDecoder(stream)
103 103
 		for {
104
+			if ctx.Err() != nil {
105
+				return
106
+			}
107
+
104 108
 			var buf logdriver.LogEntry
105 109
 			if err := dec.Decode(&buf); err != nil {
106 110
 				if err == io.EOF {
... ...
@@ -127,6 +131,8 @@ func (a *pluginAdapterWithRead) ReadLogs(config ReadConfig) *LogWatcher {
127 127
 			// send the message unless the consumer is gone
128 128
 			select {
129 129
 			case watcher.Msg <- msg:
130
+			case <-ctx.Done():
131
+				return
130 132
 			case <-watcher.WatchConsumerGone():
131 133
 				return
132 134
 			}
... ...
@@ -1,6 +1,7 @@
1 1
 package logger // import "github.com/docker/docker/daemon/logger"
2 2
 
3 3
 import (
4
+	"context"
4 5
 	"encoding/binary"
5 6
 	"io"
6 7
 	"sync"
... ...
@@ -154,7 +155,7 @@ func TestAdapterReadLogs(t *testing.T) {
154 154
 	lr, ok := l.(LogReader)
155 155
 	assert.Check(t, ok, "Logger does not implement LogReader")
156 156
 
157
-	lw := lr.ReadLogs(ReadConfig{})
157
+	lw := lr.ReadLogs(context.TODO(), ReadConfig{})
158 158
 
159 159
 	for _, x := range testMsg {
160 160
 		select {
... ...
@@ -173,7 +174,7 @@ func TestAdapterReadLogs(t *testing.T) {
173 173
 	}
174 174
 	lw.ConsumerGone()
175 175
 
176
-	lw = lr.ReadLogs(ReadConfig{Follow: true})
176
+	lw = lr.ReadLogs(context.TODO(), ReadConfig{Follow: true})
177 177
 	for _, x := range testMsg {
178 178
 		select {
179 179
 		case msg := <-lw.Msg:
... ...
@@ -20,6 +20,8 @@ const (
20 20
 	waitInterval       = 250 * time.Millisecond
21 21
 )
22 22
 
23
+var _ logger.LogReader = (*journald)(nil)
24
+
23 25
 // Fields which we know are not user-provided attribute fields.
24 26
 var wellKnownFields = map[string]bool{
25 27
 	"MESSAGE":             true,
... ...
@@ -447,7 +449,7 @@ func (r *reader) signalReady() {
447 447
 	}
448 448
 }
449 449
 
450
-func (s *journald) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
450
+func (s *journald) ReadLogs(ctx context.Context, config logger.ReadConfig) *logger.LogWatcher {
451 451
 	r := &reader{
452 452
 		s:          s,
453 453
 		logWatcher: logger.NewLogWatcher(),
... ...
@@ -12,10 +12,12 @@ import (
12 12
 	"github.com/docker/docker/pkg/tailfile"
13 13
 )
14 14
 
15
+var _ logger.LogReader = (*JSONFileLogger)(nil)
16
+
15 17
 // ReadLogs implements the logger's LogReader interface for the logs
16 18
 // created by this driver.
17
-func (l *JSONFileLogger) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
18
-	return l.writer.ReadLogs(config)
19
+func (l *JSONFileLogger) ReadLogs(ctx context.Context, config logger.ReadConfig) *logger.LogWatcher {
20
+	return l.writer.ReadLogs(ctx, config)
19 21
 }
20 22
 
21 23
 func decodeLogLine(dec *json.Decoder, l *jsonlog.JSONLog) (*logger.Message, error) {
... ...
@@ -3,6 +3,7 @@ package jsonfilelog // import "github.com/docker/docker/daemon/logger/jsonfilelo
3 3
 import (
4 4
 	"bufio"
5 5
 	"bytes"
6
+	"context"
6 7
 	"fmt"
7 8
 	"io"
8 9
 	"os"
... ...
@@ -62,7 +63,7 @@ func BenchmarkJSONFileLoggerReadLogs(b *testing.B) {
62 62
 		}
63 63
 	}()
64 64
 
65
-	lw := jsonlogger.(*JSONFileLogger).ReadLogs(logger.ReadConfig{Follow: true})
65
+	lw := jsonlogger.(*JSONFileLogger).ReadLogs(context.TODO(), logger.ReadConfig{Follow: true})
66 66
 	for {
67 67
 		select {
68 68
 		case _, ok := <-lw.Msg:
... ...
@@ -18,8 +18,8 @@ import (
18 18
 // logger.defaultBufSize caps the size of Line field.
19 19
 const maxMsgLen int = 1e6 // 1MB.
20 20
 
21
-func (d *driver) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
22
-	return d.logfile.ReadLogs(config)
21
+func (d *driver) ReadLogs(ctx context.Context, config logger.ReadConfig) *logger.LogWatcher {
22
+	return d.logfile.ReadLogs(ctx, config)
23 23
 }
24 24
 
25 25
 func getTailReader(ctx context.Context, r loggerutils.SizeReaderAt, req int) (loggerutils.SizeReaderAt, int, error) {
... ...
@@ -8,6 +8,7 @@
8 8
 package logger // import "github.com/docker/docker/daemon/logger"
9 9
 
10 10
 import (
11
+	"context"
11 12
 	"sync"
12 13
 	"time"
13 14
 
... ...
@@ -88,7 +89,7 @@ type ReadConfig struct {
88 88
 // LogReader is the interface for reading log messages for loggers that support reading.
89 89
 type LogReader interface {
90 90
 	// ReadLogs reads logs from underlying logging backend.
91
-	ReadLogs(ReadConfig) *LogWatcher
91
+	ReadLogs(context.Context, ReadConfig) *LogWatcher
92 92
 }
93 93
 
94 94
 // LogWatcher is used when consuming logs read from the LogReader interface.
... ...
@@ -1,6 +1,7 @@
1 1
 package loggertest // import "github.com/docker/docker/daemon/logger/loggertest"
2 2
 
3 3
 import (
4
+	"context"
4 5
 	"fmt"
5 6
 	"runtime"
6 7
 	"strings"
... ...
@@ -93,63 +94,63 @@ func (tr Reader) testTail(t *testing.T, live bool) {
93 93
 
94 94
 	t.Run("Exact", func(t *testing.T) {
95 95
 		t.Parallel()
96
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: len(mm)})
96
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: len(mm)})
97 97
 		defer lw.ConsumerGone()
98 98
 		assert.DeepEqual(t, readAll(t, lw), expected, compareLog)
99 99
 	})
100 100
 
101 101
 	t.Run("LessThanAvailable", func(t *testing.T) {
102 102
 		t.Parallel()
103
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: 2})
103
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: 2})
104 104
 		defer lw.ConsumerGone()
105 105
 		assert.DeepEqual(t, readAll(t, lw), expected[len(mm)-2:], compareLog)
106 106
 	})
107 107
 
108 108
 	t.Run("MoreThanAvailable", func(t *testing.T) {
109 109
 		t.Parallel()
110
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: 100})
110
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: 100})
111 111
 		defer lw.ConsumerGone()
112 112
 		assert.DeepEqual(t, readAll(t, lw), expected, compareLog)
113 113
 	})
114 114
 
115 115
 	t.Run("All", func(t *testing.T) {
116 116
 		t.Parallel()
117
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: -1})
117
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1})
118 118
 		defer lw.ConsumerGone()
119 119
 		assert.DeepEqual(t, readAll(t, lw), expected, compareLog)
120 120
 	})
121 121
 
122 122
 	t.Run("Since", func(t *testing.T) {
123 123
 		t.Parallel()
124
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: -1, Since: mm[1].Timestamp.Truncate(time.Millisecond)})
124
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1, Since: mm[1].Timestamp.Truncate(time.Millisecond)})
125 125
 		defer lw.ConsumerGone()
126 126
 		assert.DeepEqual(t, readAll(t, lw), expected[1:], compareLog)
127 127
 	})
128 128
 
129 129
 	t.Run("MoreThanSince", func(t *testing.T) {
130 130
 		t.Parallel()
131
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: len(mm), Since: mm[1].Timestamp.Truncate(time.Millisecond)})
131
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: len(mm), Since: mm[1].Timestamp.Truncate(time.Millisecond)})
132 132
 		defer lw.ConsumerGone()
133 133
 		assert.DeepEqual(t, readAll(t, lw), expected[1:], compareLog)
134 134
 	})
135 135
 
136 136
 	t.Run("LessThanSince", func(t *testing.T) {
137 137
 		t.Parallel()
138
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: len(mm) - 2, Since: mm[1].Timestamp.Truncate(time.Millisecond)})
138
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: len(mm) - 2, Since: mm[1].Timestamp.Truncate(time.Millisecond)})
139 139
 		defer lw.ConsumerGone()
140 140
 		assert.DeepEqual(t, readAll(t, lw), expected[2:], compareLog)
141 141
 	})
142 142
 
143 143
 	t.Run("Until", func(t *testing.T) {
144 144
 		t.Parallel()
145
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: -1, Until: mm[2].Timestamp.Add(-time.Millisecond)})
145
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1, Until: mm[2].Timestamp.Add(-time.Millisecond)})
146 146
 		defer lw.ConsumerGone()
147 147
 		assert.DeepEqual(t, readAll(t, lw), expected[:2], compareLog)
148 148
 	})
149 149
 
150 150
 	t.Run("SinceAndUntil", func(t *testing.T) {
151 151
 		t.Parallel()
152
-		lw := lr.ReadLogs(logger.ReadConfig{Tail: -1, Since: mm[1].Timestamp.Truncate(time.Millisecond), Until: mm[1].Timestamp.Add(time.Millisecond)})
152
+		lw := lr.ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1, Since: mm[1].Timestamp.Truncate(time.Millisecond), Until: mm[1].Timestamp.Add(time.Millisecond)})
153 153
 		defer lw.ConsumerGone()
154 154
 		assert.DeepEqual(t, readAll(t, lw), expected[1:2], compareLog)
155 155
 	})
... ...
@@ -182,7 +183,7 @@ func (tr Reader) testTailEmptyLogs(t *testing.T, live bool) {
182 182
 		tt := tt
183 183
 		t.Run(tt.name, func(t *testing.T) {
184 184
 			t.Parallel()
185
-			lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{})
185
+			lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{})
186 186
 			defer lw.ConsumerGone()
187 187
 			assert.DeepEqual(t, readAll(t, lw), ([]*logger.Message)(nil), cmpopts.EquateEmpty())
188 188
 		})
... ...
@@ -204,7 +205,7 @@ func (tr Reader) TestFollow(t *testing.T) {
204 204
 				ContainerID:   fmt.Sprintf("followstart%d", i),
205 205
 				ContainerName: fmt.Sprintf("logloglog%d", i),
206 206
 			})(t)
207
-			lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Tail: tail, Follow: true})
207
+			lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Tail: tail, Follow: true})
208 208
 			defer lw.ConsumerGone()
209 209
 
210 210
 			doneReading := make(chan struct{})
... ...
@@ -232,7 +233,7 @@ func (tr Reader) TestFollow(t *testing.T) {
232 232
 		mm := makeTestMessages()
233 233
 		expected := logMessages(t, l, mm[0:1])
234 234
 
235
-		lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Tail: -1, Follow: true})
235
+		lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1, Follow: true})
236 236
 		defer lw.ConsumerGone()
237 237
 
238 238
 		doneReading := make(chan struct{})
... ...
@@ -257,7 +258,7 @@ func (tr Reader) TestFollow(t *testing.T) {
257 257
 
258 258
 		mm := makeTestMessages()
259 259
 
260
-		lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Tail: -1, Follow: true, Since: mm[2].Timestamp.Truncate(time.Millisecond)})
260
+		lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1, Follow: true, Since: mm[2].Timestamp.Truncate(time.Millisecond)})
261 261
 		defer lw.ConsumerGone()
262 262
 
263 263
 		doneReading := make(chan struct{})
... ...
@@ -282,7 +283,7 @@ func (tr Reader) TestFollow(t *testing.T) {
282 282
 
283 283
 		mm := makeTestMessages()
284 284
 
285
-		lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Tail: -1, Follow: true, Until: mm[2].Timestamp.Add(-time.Millisecond)})
285
+		lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1, Follow: true, Until: mm[2].Timestamp.Add(-time.Millisecond)})
286 286
 		defer lw.ConsumerGone()
287 287
 
288 288
 		doneReading := make(chan struct{})
... ...
@@ -307,7 +308,7 @@ func (tr Reader) TestFollow(t *testing.T) {
307 307
 
308 308
 		mm := makeTestMessages()
309 309
 
310
-		lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Tail: -1, Follow: true, Since: mm[1].Timestamp.Add(-time.Millisecond), Until: mm[2].Timestamp.Add(-time.Millisecond)})
310
+		lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1, Follow: true, Since: mm[1].Timestamp.Add(-time.Millisecond), Until: mm[2].Timestamp.Add(-time.Millisecond)})
311 311
 		defer lw.ConsumerGone()
312 312
 
313 313
 		doneReading := make(chan struct{})
... ...
@@ -334,7 +335,7 @@ func (tr Reader) TestFollow(t *testing.T) {
334 334
 		logMessages(t, l, mm[0:2])
335 335
 		syncLogger(t, l)
336 336
 
337
-		lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Tail: 0, Follow: true})
337
+		lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Tail: 0, Follow: true})
338 338
 		defer lw.ConsumerGone()
339 339
 
340 340
 		doneReading := make(chan struct{})
... ...
@@ -361,7 +362,7 @@ func (tr Reader) TestFollow(t *testing.T) {
361 361
 		expected := logMessages(t, l, mm[0:2])[1:]
362 362
 		syncLogger(t, l)
363 363
 
364
-		lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Tail: 1, Follow: true})
364
+		lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Tail: 1, Follow: true})
365 365
 		defer lw.ConsumerGone()
366 366
 
367 367
 		doneReading := make(chan struct{})
... ...
@@ -390,7 +391,7 @@ func (tr Reader) TestFollow(t *testing.T) {
390 390
 		assert.NilError(t, l.Close())
391 391
 
392 392
 		l = factory(t)
393
-		lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Tail: -1, Follow: true})
393
+		lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Tail: -1, Follow: true})
394 394
 		defer lw.ConsumerGone()
395 395
 
396 396
 		doneReading := make(chan struct{})
... ...
@@ -430,7 +431,7 @@ func (tr Reader) TestConcurrent(t *testing.T) {
430 430
 	}
431 431
 
432 432
 	// Follow all logs
433
-	lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Follow: true, Tail: -1})
433
+	lw := l.(logger.LogReader).ReadLogs(context.TODO(), logger.ReadConfig{Follow: true, Tail: -1})
434 434
 	defer lw.ConsumerGone()
435 435
 
436 436
 	// Log concurrently from two sources and close log
... ...
@@ -24,6 +24,8 @@ var builtInCacheLogOpts = map[string]bool{
24 24
 	cacheDisabledKey: true,
25 25
 }
26 26
 
27
+var _ logger.LogReader = (*loggerWithCache)(nil)
28
+
27 29
 // WithLocalCache wraps the passed in logger with a logger caches all writes locally
28 30
 // in addition to writing to the passed in logger.
29 31
 func WithLocalCache(l logger.Logger, info logger.Info) (logger.Logger, error) {
... ...
@@ -85,8 +87,8 @@ func (l *loggerWithCache) Name() string {
85 85
 	return l.l.Name()
86 86
 }
87 87
 
88
-func (l *loggerWithCache) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
89
-	return l.cache.(logger.LogReader).ReadLogs(config)
88
+func (l *loggerWithCache) ReadLogs(ctx context.Context, config logger.ReadConfig) *logger.LogWatcher {
89
+	return l.cache.(logger.LogReader).ReadLogs(ctx, config)
90 90
 }
91 91
 
92 92
 func (l *loggerWithCache) Close() error {
... ...
@@ -38,7 +38,7 @@ func (fl *follow) Do(ctx context.Context, f *os.File, read logPos) {
38 38
 	}()
39 39
 
40 40
 	for {
41
-		wrote, ok := fl.nextPos(read)
41
+		wrote, ok := fl.nextPos(ctx, read)
42 42
 		if !ok {
43 43
 			return
44 44
 		}
... ...
@@ -100,9 +100,11 @@ func (fl *follow) Do(ctx context.Context, f *os.File, read logPos) {
100 100
 
101 101
 // nextPos waits until the write position of the LogFile being followed has
102 102
 // advanced from current and returns the new position.
103
-func (fl *follow) nextPos(current logPos) (next logPos, ok bool) {
103
+func (fl *follow) nextPos(ctx context.Context, current logPos) (next logPos, ok bool) {
104 104
 	var st logReadState
105 105
 	select {
106
+	case <-ctx.Done():
107
+		return current, false
106 108
 	case <-fl.Watcher.WatchConsumerGone():
107 109
 		return current, false
108 110
 	case st = <-fl.LogFile.read:
... ...
@@ -14,10 +14,13 @@ import (
14 14
 	"sync"
15 15
 	"time"
16 16
 
17
+	"github.com/containerd/containerd/tracing"
17 18
 	"github.com/containerd/log"
18 19
 	"github.com/docker/docker/daemon/logger"
19 20
 	"github.com/docker/docker/pkg/pools"
20 21
 	"github.com/pkg/errors"
22
+	"go.opentelemetry.io/otel/attribute"
23
+	"go.opentelemetry.io/otel/trace"
21 24
 )
22 25
 
23 26
 // rotateFileMetadata is a metadata of the gzip header of the compressed log file
... ...
@@ -373,7 +376,12 @@ func (w *LogFile) Close() error {
373 373
 // ReadLogs decodes entries from log files.
374 374
 //
375 375
 // It is the caller's responsibility to call ConsumerGone on the LogWatcher.
376
-func (w *LogFile) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
376
+func (w *LogFile) ReadLogs(ctx context.Context, config logger.ReadConfig) *logger.LogWatcher {
377
+	ctx, span := tracing.StartSpan(ctx, "logger.LogFile.ReadLogs")
378
+	defer span.End()
379
+
380
+	span.SetAttributes(tracing.Attribute("config", config))
381
+
377 382
 	watcher := logger.NewLogWatcher()
378 383
 	// Lock out filesystem operations so that we can capture the read
379 384
 	// position and atomically open the corresponding log file, without the
... ...
@@ -385,43 +393,57 @@ func (w *LogFile) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
385 385
 	st := <-w.read
386 386
 	pos := st.pos
387 387
 	w.read <- st
388
-	go w.readLogsLocked(pos, config, watcher)
388
+	go w.readLogsLocked(ctx, pos, config, watcher)
389 389
 	return watcher
390 390
 }
391 391
 
392 392
 // tailFiles must be called with w.fsopMu locked for reads.
393 393
 // w.fsopMu.RUnlock() is called before returning.
394
-func (w *LogFile) tailFiles(config logger.ReadConfig, watcher *logger.LogWatcher, current SizeReaderAt, dec Decoder, fwd *forwarder) bool {
394
+func (w *LogFile) tailFiles(ctx context.Context, config logger.ReadConfig, watcher *logger.LogWatcher, current SizeReaderAt, dec Decoder, fwd *forwarder) (cont bool) {
395 395
 	if config.Tail == 0 {
396 396
 		w.fsopMu.RUnlock()
397 397
 		return true
398 398
 	}
399 399
 
400
-	files, err := w.openRotatedFiles(config)
400
+	ctx, span := tracing.StartSpan(ctx, "logger.Logfile.TailLogs")
401
+	defer func() {
402
+		span.SetAttributes(attribute.Bool("continue", cont))
403
+		span.End()
404
+	}()
405
+
406
+	files, err := w.openRotatedFiles(ctx, config)
401 407
 	w.fsopMu.RUnlock()
402 408
 
403 409
 	if err != nil {
410
+		// TODO: Should we allow this to continue (as in set `cont=true`) and not error out the log stream?
411
+		err = errors.Wrap(err, "error opening rotated log files")
412
+		span.SetStatus(err)
404 413
 		watcher.Err <- err
405 414
 		return false
406 415
 	}
407 416
 
408 417
 	if current.Size() > 0 {
409
-		files = append(files, &sizeReaderAtOpener{current})
418
+		files = append(files, &sizeReaderAtOpener{current, "current"})
410 419
 	}
411 420
 
412
-	return tailFiles(files, watcher, dec, w.getTailReader, config.Tail, fwd)
421
+	return tailFiles(ctx, files, watcher, dec, w.getTailReader, config.Tail, fwd)
413 422
 }
414 423
 
415 424
 type sizeReaderAtOpener struct {
416 425
 	SizeReaderAt
426
+	ref string
417 427
 }
418 428
 
419
-func (o *sizeReaderAtOpener) ReaderAt() (sizeReaderAtCloser, error) {
429
+func (o *sizeReaderAtOpener) ReaderAt(context.Context) (sizeReaderAtCloser, error) {
420 430
 	return &sizeReaderAtWithCloser{o, nil}, nil
421 431
 }
422 432
 
423 433
 func (o *sizeReaderAtOpener) Close() {}
424 434
 
435
+func (o *sizeReaderAtOpener) Ref() string {
436
+	return o.ref
437
+}
438
+
425 439
 type sizeReaderAtWithCloser struct {
426 440
 	SizeReaderAt
427 441
 	close func() error
... ...
@@ -459,12 +481,16 @@ func (r *sizeReaderAtWithCloser) Close() error {
459 459
 //
460 460
 // w.fsopMu must be locked for reading when calling this method.
461 461
 // w.fsopMu.RUnlock() is called before returning.
462
-func (w *LogFile) readLogsLocked(currentPos logPos, config logger.ReadConfig, watcher *logger.LogWatcher) {
462
+func (w *LogFile) readLogsLocked(ctx context.Context, currentPos logPos, config logger.ReadConfig, watcher *logger.LogWatcher) {
463
+	ctx, span := tracing.StartSpan(ctx, "logger.Logfile.ReadLogsLocked")
464
+	defer span.End()
465
+
463 466
 	defer close(watcher.Msg)
464 467
 
465 468
 	currentFile, err := open(w.f.Name())
466 469
 	if err != nil {
467 470
 		w.fsopMu.RUnlock()
471
+		span.SetStatus(err)
468 472
 		watcher.Err <- err
469 473
 		return
470 474
 	}
... ...
@@ -476,7 +502,7 @@ func (w *LogFile) readLogsLocked(currentPos logPos, config logger.ReadConfig, wa
476 476
 	fwd := newForwarder(config)
477 477
 
478 478
 	// At this point, w.tailFiles is responsible for unlocking w.fsopmu
479
-	ok := w.tailFiles(config, watcher, io.NewSectionReader(currentFile, 0, currentPos.size), dec, fwd)
479
+	ok := w.tailFiles(ctx, config, watcher, io.NewSectionReader(currentFile, 0, currentPos.size), dec, fwd)
480 480
 
481 481
 	if !ok {
482 482
 		return
... ...
@@ -491,12 +517,13 @@ func (w *LogFile) readLogsLocked(currentPos logPos, config logger.ReadConfig, wa
491 491
 		Watcher:   watcher,
492 492
 		Decoder:   dec,
493 493
 		Forwarder: fwd,
494
-	}).Do(context.TODO(), currentFile, currentPos)
494
+	}).Do(ctx, currentFile, currentPos)
495 495
 }
496 496
 
497 497
 type fileOpener interface {
498
-	ReaderAt() (ra sizeReaderAtCloser, err error)
498
+	ReaderAt(context.Context) (ra sizeReaderAtCloser, err error)
499 499
 	Close()
500
+	Ref() string
500 501
 }
501 502
 
502 503
 // simpleFileOpener just holds a reference to an already open file
... ...
@@ -506,10 +533,11 @@ type simpleFileOpener struct {
506 506
 	closed bool
507 507
 }
508 508
 
509
-func (o *simpleFileOpener) ReaderAt() (sizeReaderAtCloser, error) {
509
+func (o *simpleFileOpener) ReaderAt(context.Context) (sizeReaderAtCloser, error) {
510 510
 	if o.closed {
511 511
 		return nil, errors.New("file is closed")
512 512
 	}
513
+
513 514
 	if o.sz == 0 {
514 515
 		stat, err := o.f.Stat()
515 516
 		if err != nil {
... ...
@@ -520,6 +548,10 @@ func (o *simpleFileOpener) ReaderAt() (sizeReaderAtCloser, error) {
520 520
 	return &sizeReaderAtWithCloser{io.NewSectionReader(o.f, 0, o.sz), nil}, nil
521 521
 }
522 522
 
523
+func (o *simpleFileOpener) Ref() string {
524
+	return o.f.Name()
525
+}
526
+
523 527
 func (o *simpleFileOpener) Close() {
524 528
 	_ = o.f.Close()
525 529
 	o.closed = true
... ...
@@ -552,7 +584,17 @@ type compressedFileOpener struct {
552 552
 	ifBefore time.Time
553 553
 }
554 554
 
555
-func (cfo *compressedFileOpener) ReaderAt() (_ sizeReaderAtCloser, retErr error) {
555
+func (cfo *compressedFileOpener) ReaderAt(ctx context.Context) (_ sizeReaderAtCloser, retErr error) {
556
+	_, span := tracing.StartSpan(ctx, "logger.Logfile.Compressed.ReaderAt")
557
+	defer func() {
558
+		if retErr != nil {
559
+			span.SetStatus(retErr)
560
+		}
561
+		span.End()
562
+	}()
563
+
564
+	span.SetAttributes(attribute.String("file", cfo.f.Name()))
565
+
556 566
 	if cfo.closed {
557 567
 		return nil, errors.New("compressed file closed")
558 568
 	}
... ...
@@ -568,9 +610,14 @@ func (cfo *compressedFileOpener) ReaderAt() (_ sizeReaderAtCloser, retErr error)
568 568
 	extra := &rotateFileMetadata{}
569 569
 	err = json.Unmarshal(gzr.Header.Extra, extra)
570 570
 	if err == nil && !extra.LastTime.IsZero() && extra.LastTime.Before(cfo.ifBefore) {
571
+		span.SetAttributes(attribute.Bool("skip", true))
571 572
 		return &sizeReaderAtWithCloser{}, nil
572 573
 	}
574
+	if err == nil {
575
+		span.SetAttributes(attribute.Stringer("lastLogTime", extra.LastTime))
576
+	}
573 577
 
578
+	span.AddEvent("Start decompress")
574 579
 	return cfo.lf.decompress.Do(cfo.f)
575 580
 }
576 581
 
... ...
@@ -579,19 +626,27 @@ func (cfo *compressedFileOpener) Close() {
579 579
 	cfo.f.Close()
580 580
 }
581 581
 
582
+func (cfo *compressedFileOpener) Ref() string {
583
+	return cfo.f.Name()
584
+}
585
+
582 586
 type emptyFileOpener struct{}
583 587
 
584
-func (emptyFileOpener) ReaderAt() (sizeReaderAtCloser, error) {
588
+func (emptyFileOpener) ReaderAt(context.Context) (sizeReaderAtCloser, error) {
585 589
 	return &sizeReaderAtWithCloser{}, nil
586 590
 }
587 591
 
588 592
 func (emptyFileOpener) Close() {}
589 593
 
594
+func (emptyFileOpener) Ref() string {
595
+	return "null"
596
+}
597
+
590 598
 // openRotatedFiles returns a slice of files open for reading, in order from
591 599
 // oldest to newest, and calls w.fsopMu.RUnlock() before returning.
592 600
 //
593 601
 // This method must only be called with w.fsopMu locked for reading.
594
-func (w *LogFile) openRotatedFiles(config logger.ReadConfig) (_ []fileOpener, retErr error) {
602
+func (w *LogFile) openRotatedFiles(ctx context.Context, config logger.ReadConfig) (_ []fileOpener, retErr error) {
595 603
 	var out []fileOpener
596 604
 
597 605
 	defer func() {
... ...
@@ -603,7 +658,7 @@ func (w *LogFile) openRotatedFiles(config logger.ReadConfig) (_ []fileOpener, re
603 603
 	}()
604 604
 
605 605
 	for i := w.maxFiles; i > 1; i-- {
606
-		fo, err := w.openRotatedFile(i-1, config)
606
+		fo, err := w.openRotatedFile(ctx, i-1, config)
607 607
 		if err != nil {
608 608
 			return nil, err
609 609
 		}
... ...
@@ -613,7 +668,7 @@ func (w *LogFile) openRotatedFiles(config logger.ReadConfig) (_ []fileOpener, re
613 613
 	return out, nil
614 614
 }
615 615
 
616
-func (w *LogFile) openRotatedFile(i int, config logger.ReadConfig) (fileOpener, error) {
616
+func (w *LogFile) openRotatedFile(ctx context.Context, i int, config logger.ReadConfig) (fileOpener, error) {
617 617
 	f, err := open(fmt.Sprintf("%s.%d", w.f.Name(), i))
618 618
 	if err == nil {
619 619
 		return &simpleFileOpener{
... ...
@@ -650,6 +705,15 @@ type sizeReaderAtCloser interface {
650 650
 }
651 651
 
652 652
 func getTailFiles(ctx context.Context, files []fileOpener, nLines int, getTailReader GetTailReaderFunc) (_ []sizeReaderAtCloser, retErr error) {
653
+	ctx, span := tracing.StartSpan(ctx, "logger.Logfile.CollectTailFiles")
654
+	span.SetAttributes(attribute.Int("requested_lines", nLines))
655
+
656
+	defer func() {
657
+		if retErr != nil {
658
+			span.SetStatus(retErr)
659
+		}
660
+		span.End()
661
+	}()
653 662
 	out := make([]sizeReaderAtCloser, 0, len(files))
654 663
 
655 664
 	defer func() {
... ...
@@ -664,11 +728,14 @@ func getTailFiles(ctx context.Context, files []fileOpener, nLines int, getTailRe
664 664
 
665 665
 	if nLines <= 0 {
666 666
 		for _, fo := range files {
667
-			ra, err := fo.ReaderAt()
667
+			span.AddEvent("Open file", trace.WithAttributes(attribute.String("file", fo.Ref())))
668
+
669
+			ra, err := fo.ReaderAt(ctx)
668 670
 			if err != nil {
669 671
 				return nil, err
670 672
 			}
671 673
 			out = append(out, ra)
674
+
672 675
 		}
673 676
 		return out, nil
674 677
 	}
... ...
@@ -677,11 +744,19 @@ func getTailFiles(ctx context.Context, files []fileOpener, nLines int, getTailRe
677 677
 		if err := ctx.Err(); err != nil {
678 678
 			return nil, errors.Wrap(err, "stopping parsing files to tail due to error")
679 679
 		}
680
-		ra, err := files[i].ReaderAt()
680
+
681
+		fo := files[i]
682
+
683
+		fileAttr := attribute.String("file", fo.Ref())
684
+		span.AddEvent("Open file", trace.WithAttributes(fileAttr))
685
+
686
+		ra, err := fo.ReaderAt(ctx)
681 687
 		if err != nil {
682 688
 			return nil, err
683 689
 		}
684 690
 
691
+		span.AddEvent("Scan file to tail", trace.WithAttributes(fileAttr, attribute.Int("remaining_lines", nLines)))
692
+
685 693
 		tail, n, err := getTailReader(ctx, ra, nLines)
686 694
 		if err != nil {
687 695
 			ra.Close()
... ...
@@ -697,11 +772,10 @@ func getTailFiles(ctx context.Context, files []fileOpener, nLines int, getTailRe
697 697
 	return out, nil
698 698
 }
699 699
 
700
-func tailFiles(files []fileOpener, watcher *logger.LogWatcher, dec Decoder, getTailReader GetTailReaderFunc, nLines int, fwd *forwarder) (cont bool) {
701
-	ctx, cancel := context.WithCancel(context.Background())
700
+func tailFiles(ctx context.Context, files []fileOpener, watcher *logger.LogWatcher, dec Decoder, getTailReader GetTailReaderFunc, nLines int, fwd *forwarder) (cont bool) {
701
+	ctx, cancel := context.WithCancel(ctx)
702 702
 	defer cancel()
703 703
 
704
-	// TODO(@cpuguy83): we should plumb a context through instead of dealing with `WatchClose()` here.
705 704
 	go func() {
706 705
 		select {
707 706
 		case <-ctx.Done():
... ...
@@ -779,11 +853,19 @@ func newForwarder(config logger.ReadConfig) *forwarder {
779 779
 // dec without encountering a message with a timestamp which is after the
780 780
 // configured until time.
781 781
 func (fwd *forwarder) Do(ctx context.Context, watcher *logger.LogWatcher, next func() (*logger.Message, error)) (cont bool) {
782
+	ctx, span := tracing.StartSpan(ctx, "logger.Logfile.Forward")
783
+	defer func() {
784
+		span.SetAttributes(attribute.Bool("continue", cont))
785
+		span.End()
786
+	}()
787
+
782 788
 	for {
783 789
 		select {
784 790
 		case <-watcher.WatchConsumerGone():
791
+			span.AddEvent("watch consumer gone")
785 792
 			return false
786 793
 		case <-ctx.Done():
794
+			span.AddEvent(ctx.Err().Error())
787 795
 			return false
788 796
 		default:
789 797
 		}
... ...
@@ -791,8 +873,10 @@ func (fwd *forwarder) Do(ctx context.Context, watcher *logger.LogWatcher, next f
791 791
 		msg, err := next()
792 792
 		if err != nil {
793 793
 			if errors.Is(err, io.EOF) {
794
+				span.AddEvent("EOF")
794 795
 				return true
795 796
 			}
797
+			span.SetStatus(err)
796 798
 			log.G(ctx).WithError(err).Debug("Error while decoding log entry, not continuing")
797 799
 			return false
798 800
 		}
... ...
@@ -811,10 +895,13 @@ func (fwd *forwarder) Do(ctx context.Context, watcher *logger.LogWatcher, next f
811 811
 			log.G(ctx).Debug("Log is newer than requested window, skipping remaining logs")
812 812
 			return false
813 813
 		}
814
+
814 815
 		select {
815 816
 		case <-ctx.Done():
817
+			span.AddEvent(ctx.Err().Error())
816 818
 			return false
817 819
 		case <-watcher.WatchConsumerGone():
820
+			span.AddEvent("watch consumer gone")
818 821
 			return false
819 822
 		case watcher.Msg <- msg:
820 823
 		}
... ...
@@ -9,6 +9,7 @@ import (
9 9
 	"io"
10 10
 	"os"
11 11
 	"path/filepath"
12
+	"strconv"
12 13
 	"strings"
13 14
 	"testing"
14 15
 	"text/tabwriter"
... ...
@@ -78,8 +79,8 @@ func TestTailFiles(t *testing.T) {
78 78
 
79 79
 	makeOpener := func(ls ...SizeReaderAt) []fileOpener {
80 80
 		out := make([]fileOpener, 0, len(ls))
81
-		for _, rdr := range ls {
82
-			out = append(out, &sizeReaderAtOpener{rdr})
81
+		for i, rdr := range ls {
82
+			out = append(out, &sizeReaderAtOpener{rdr, strconv.Itoa(i)})
83 83
 		}
84 84
 		return out
85 85
 	}
... ...
@@ -98,7 +99,7 @@ func TestTailFiles(t *testing.T) {
98 98
 	started := make(chan struct{})
99 99
 	go func() {
100 100
 		close(started)
101
-		tailFiles(files, watcher, dec, tailReader, config.Tail, fwd)
101
+		tailFiles(context.TODO(), files, watcher, dec, tailReader, config.Tail, fwd)
102 102
 	}()
103 103
 	<-started
104 104
 
... ...
@@ -166,7 +167,7 @@ func TestTailFiles(t *testing.T) {
166 166
 		done := make(chan struct{})
167 167
 		go func() {
168 168
 			close(started)
169
-			tailFiles(files, watcher, &testJSONStreamDecoder{}, tailReader, config.Tail, fwd)
169
+			tailFiles(context.TODO(), files, watcher, &testJSONStreamDecoder{}, tailReader, config.Tail, fwd)
170 170
 			close(done)
171 171
 		}()
172 172
 
... ...
@@ -249,7 +250,7 @@ func TestCheckCapacityAndRotate(t *testing.T) {
249 249
 
250 250
 	t.Run("with log reader", func(t *testing.T) {
251 251
 		// Make sure rotate works with an active reader
252
-		lw := l.ReadLogs(logger.ReadConfig{Follow: true, Tail: 1000})
252
+		lw := l.ReadLogs(context.TODO(), logger.ReadConfig{Follow: true, Tail: 1000})
253 253
 		defer lw.ConsumerGone()
254 254
 
255 255
 		assert.NilError(t, l.WriteLogEntry(timestamp, []byte("hello world 0!\n")), ls)
... ...
@@ -1,6 +1,7 @@
1 1
 package logger // import "github.com/docker/docker/daemon/logger"
2 2
 
3 3
 import (
4
+	"context"
4 5
 	"errors"
5 6
 	"sync"
6 7
 	"sync/atomic"
... ...
@@ -20,19 +21,22 @@ type RingLogger struct {
20 20
 	wg        sync.WaitGroup
21 21
 }
22 22
 
23
-var _ SizedLogger = &RingLogger{}
23
+var (
24
+	_ SizedLogger = (*RingLogger)(nil)
25
+	_ LogReader   = (*ringWithReader)(nil)
26
+)
24 27
 
25 28
 type ringWithReader struct {
26 29
 	*RingLogger
27 30
 }
28 31
 
29
-func (r *ringWithReader) ReadLogs(cfg ReadConfig) *LogWatcher {
32
+func (r *ringWithReader) ReadLogs(ctx context.Context, cfg ReadConfig) *LogWatcher {
30 33
 	reader, ok := r.l.(LogReader)
31 34
 	if !ok {
32 35
 		// something is wrong if we get here
33 36
 		panic("expected log reader")
34 37
 	}
35
-	return reader.ReadLogs(cfg)
38
+	return reader.ReadLogs(ctx, cfg)
36 39
 }
37 40
 
38 41
 func newRingLogger(driver Logger, logInfo Info, maxSize int64) *RingLogger {
... ...
@@ -5,6 +5,7 @@ import (
5 5
 	"strconv"
6 6
 	"time"
7 7
 
8
+	"github.com/containerd/containerd/tracing"
8 9
 	"github.com/containerd/log"
9 10
 	"github.com/docker/docker/api/types/backend"
10 11
 	containertypes "github.com/docker/docker/api/types/container"
... ...
@@ -24,6 +25,14 @@ import (
24 24
 // if it returns nil, the config channel will be active and return log
25 25
 // messages until it runs out or the context is canceled.
26 26
 func (daemon *Daemon) ContainerLogs(ctx context.Context, containerName string, config *containertypes.LogsOptions) (messages <-chan *backend.LogMessage, isTTY bool, retErr error) {
27
+	ctx, span := tracing.StartSpan(ctx, "daemon.ContainerLogs")
28
+	defer func() {
29
+		if retErr != nil {
30
+			span.SetStatus(retErr)
31
+		}
32
+		span.End()
33
+	}()
34
+
27 35
 	lg := log.G(ctx).WithFields(log.Fields{
28 36
 		"module":    "daemon",
29 37
 		"method":    "(*Daemon).ContainerLogs",
... ...
@@ -96,7 +105,7 @@ func (daemon *Daemon) ContainerLogs(ctx context.Context, containerName string, c
96 96
 		Follow: follow,
97 97
 	}
98 98
 
99
-	logs := logReader.ReadLogs(readConfig)
99
+	logs := logReader.ReadLogs(ctx, readConfig)
100 100
 
101 101
 	// past this point, we can't possibly return any errors, so we can just
102 102
 	// start a goroutine and return to tell the caller not to expect errors