github.com/docker/docker@v299999999.0.0-20200612211812-aaf470eca7b5+incompatible/daemon/logger/copier_test.go (about) 1 package logger // import "github.com/docker/docker/daemon/logger" 2 3 import ( 4 "bytes" 5 "encoding/json" 6 "io" 7 "os" 8 "strings" 9 "sync" 10 "testing" 11 "time" 12 ) 13 14 type TestLoggerJSON struct { 15 *json.Encoder 16 mu sync.Mutex 17 delay time.Duration 18 } 19 20 func (l *TestLoggerJSON) Log(m *Message) error { 21 if l.delay > 0 { 22 time.Sleep(l.delay) 23 } 24 l.mu.Lock() 25 defer l.mu.Unlock() 26 return l.Encode(m) 27 } 28 29 func (l *TestLoggerJSON) Close() error { return nil } 30 31 func (l *TestLoggerJSON) Name() string { return "json" } 32 33 type TestSizedLoggerJSON struct { 34 *json.Encoder 35 mu sync.Mutex 36 } 37 38 func (l *TestSizedLoggerJSON) Log(m *Message) error { 39 l.mu.Lock() 40 defer l.mu.Unlock() 41 return l.Encode(m) 42 } 43 44 func (*TestSizedLoggerJSON) Close() error { return nil } 45 46 func (*TestSizedLoggerJSON) Name() string { return "sized-json" } 47 48 func (*TestSizedLoggerJSON) BufSize() int { 49 return 32 * 1024 50 } 51 52 func TestCopier(t *testing.T) { 53 stdoutLine := "Line that thinks that it is log line from docker stdout" 54 stderrLine := "Line that thinks that it is log line from docker stderr" 55 stdoutTrailingLine := "stdout trailing line" 56 stderrTrailingLine := "stderr trailing line" 57 58 var stdout bytes.Buffer 59 var stderr bytes.Buffer 60 for i := 0; i < 30; i++ { 61 if _, err := stdout.WriteString(stdoutLine + "\n"); err != nil { 62 t.Fatal(err) 63 } 64 if _, err := stderr.WriteString(stderrLine + "\n"); err != nil { 65 t.Fatal(err) 66 } 67 } 68 69 // Test remaining lines without line-endings 70 if _, err := stdout.WriteString(stdoutTrailingLine); err != nil { 71 t.Fatal(err) 72 } 73 if _, err := stderr.WriteString(stderrTrailingLine); err != nil { 74 t.Fatal(err) 75 } 76 77 var jsonBuf bytes.Buffer 78 79 jsonLog := &TestLoggerJSON{Encoder: json.NewEncoder(&jsonBuf)} 80 81 c := NewCopier( 82 map[string]io.Reader{ 83 "stdout": &stdout, 84 "stderr": &stderr, 85 }, 86 jsonLog) 87 c.Run() 88 wait := make(chan struct{}) 89 go func() { 90 c.Wait() 91 close(wait) 92 }() 93 select { 94 case <-time.After(1 * time.Second): 95 t.Fatal("Copier failed to do its work in 1 second") 96 case <-wait: 97 } 98 dec := json.NewDecoder(&jsonBuf) 99 for { 100 var msg Message 101 if err := dec.Decode(&msg); err != nil { 102 if err == io.EOF { 103 break 104 } 105 t.Fatal(err) 106 } 107 if msg.Source != "stdout" && msg.Source != "stderr" { 108 t.Fatalf("Wrong Source: %q, should be %q or %q", msg.Source, "stdout", "stderr") 109 } 110 if msg.Source == "stdout" { 111 if string(msg.Line) != stdoutLine && string(msg.Line) != stdoutTrailingLine { 112 t.Fatalf("Wrong Line: %q, expected %q or %q", msg.Line, stdoutLine, stdoutTrailingLine) 113 } 114 } 115 if msg.Source == "stderr" { 116 if string(msg.Line) != stderrLine && string(msg.Line) != stderrTrailingLine { 117 t.Fatalf("Wrong Line: %q, expected %q or %q", msg.Line, stderrLine, stderrTrailingLine) 118 } 119 } 120 } 121 } 122 123 // TestCopierLongLines tests long lines without line breaks 124 func TestCopierLongLines(t *testing.T) { 125 // Long lines (should be split at "defaultBufSize") 126 stdoutLongLine := strings.Repeat("a", defaultBufSize) 127 stderrLongLine := strings.Repeat("b", defaultBufSize) 128 stdoutTrailingLine := "stdout trailing line" 129 stderrTrailingLine := "stderr trailing line" 130 131 var stdout bytes.Buffer 132 var stderr bytes.Buffer 133 134 for i := 0; i < 3; i++ { 135 if _, err := stdout.WriteString(stdoutLongLine); err != nil { 136 t.Fatal(err) 137 } 138 if _, err := stderr.WriteString(stderrLongLine); err != nil { 139 t.Fatal(err) 140 } 141 } 142 143 if _, err := stdout.WriteString(stdoutTrailingLine); err != nil { 144 t.Fatal(err) 145 } 146 if _, err := stderr.WriteString(stderrTrailingLine); err != nil { 147 t.Fatal(err) 148 } 149 150 var jsonBuf bytes.Buffer 151 152 jsonLog := &TestLoggerJSON{Encoder: json.NewEncoder(&jsonBuf)} 153 154 c := NewCopier( 155 map[string]io.Reader{ 156 "stdout": &stdout, 157 "stderr": &stderr, 158 }, 159 jsonLog) 160 c.Run() 161 wait := make(chan struct{}) 162 go func() { 163 c.Wait() 164 close(wait) 165 }() 166 select { 167 case <-time.After(1 * time.Second): 168 t.Fatal("Copier failed to do its work in 1 second") 169 case <-wait: 170 } 171 dec := json.NewDecoder(&jsonBuf) 172 for { 173 var msg Message 174 if err := dec.Decode(&msg); err != nil { 175 if err == io.EOF { 176 break 177 } 178 t.Fatal(err) 179 } 180 if msg.Source != "stdout" && msg.Source != "stderr" { 181 t.Fatalf("Wrong Source: %q, should be %q or %q", msg.Source, "stdout", "stderr") 182 } 183 if msg.Source == "stdout" { 184 if string(msg.Line) != stdoutLongLine && string(msg.Line) != stdoutTrailingLine { 185 t.Fatalf("Wrong Line: %q, expected 'stdoutLongLine' or 'stdoutTrailingLine'", msg.Line) 186 } 187 } 188 if msg.Source == "stderr" { 189 if string(msg.Line) != stderrLongLine && string(msg.Line) != stderrTrailingLine { 190 t.Fatalf("Wrong Line: %q, expected 'stderrLongLine' or 'stderrTrailingLine'", msg.Line) 191 } 192 } 193 } 194 } 195 196 func TestCopierSlow(t *testing.T) { 197 stdoutLine := "Line that thinks that it is log line from docker stdout" 198 var stdout bytes.Buffer 199 for i := 0; i < 30; i++ { 200 if _, err := stdout.WriteString(stdoutLine + "\n"); err != nil { 201 t.Fatal(err) 202 } 203 } 204 205 var jsonBuf bytes.Buffer 206 // encoder := &encodeCloser{Encoder: json.NewEncoder(&jsonBuf)} 207 jsonLog := &TestLoggerJSON{Encoder: json.NewEncoder(&jsonBuf), delay: 100 * time.Millisecond} 208 209 c := NewCopier(map[string]io.Reader{"stdout": &stdout}, jsonLog) 210 c.Run() 211 wait := make(chan struct{}) 212 go func() { 213 c.Wait() 214 close(wait) 215 }() 216 <-time.After(150 * time.Millisecond) 217 c.Close() 218 select { 219 case <-time.After(200 * time.Millisecond): 220 t.Fatal("failed to exit in time after the copier is closed") 221 case <-wait: 222 } 223 } 224 225 func TestCopierWithSized(t *testing.T) { 226 var jsonBuf bytes.Buffer 227 expectedMsgs := 2 228 sizedLogger := &TestSizedLoggerJSON{Encoder: json.NewEncoder(&jsonBuf)} 229 logbuf := bytes.NewBufferString(strings.Repeat(".", sizedLogger.BufSize()*expectedMsgs)) 230 c := NewCopier(map[string]io.Reader{"stdout": logbuf}, sizedLogger) 231 232 c.Run() 233 // Wait for Copier to finish writing to the buffered logger. 234 c.Wait() 235 c.Close() 236 237 recvdMsgs := 0 238 dec := json.NewDecoder(&jsonBuf) 239 for { 240 var msg Message 241 if err := dec.Decode(&msg); err != nil { 242 if err == io.EOF { 243 break 244 } 245 t.Fatal(err) 246 } 247 if msg.Source != "stdout" { 248 t.Fatalf("Wrong Source: %q, should be %q", msg.Source, "stdout") 249 } 250 if len(msg.Line) != sizedLogger.BufSize() { 251 t.Fatalf("Line was not of expected max length %d, was %d", sizedLogger.BufSize(), len(msg.Line)) 252 } 253 recvdMsgs++ 254 } 255 if recvdMsgs != expectedMsgs { 256 t.Fatalf("expected to receive %d messages, actually received %d", expectedMsgs, recvdMsgs) 257 } 258 } 259 260 func checkIdentical(t *testing.T, msg Message, expectedID string, expectedTS time.Time) { 261 if msg.PLogMetaData.ID != expectedID { 262 t.Fatalf("IDs are not he same across partials. Expected: %s Received: %s", 263 expectedID, msg.PLogMetaData.ID) 264 } 265 if msg.Timestamp != expectedTS { 266 t.Fatalf("Timestamps are not the same across partials. Expected: %v Received: %v", 267 expectedTS.Format(time.UnixDate), msg.Timestamp.Format(time.UnixDate)) 268 } 269 } 270 271 // Have long lines and make sure that it comes out with PartialMetaData 272 func TestCopierWithPartial(t *testing.T) { 273 stdoutLongLine := strings.Repeat("a", defaultBufSize) 274 stderrLongLine := strings.Repeat("b", defaultBufSize) 275 stdoutTrailingLine := "stdout trailing line" 276 stderrTrailingLine := "stderr trailing line" 277 normalStr := "This is an impartial message :)" 278 279 var stdout bytes.Buffer 280 var stderr bytes.Buffer 281 var normalMsg bytes.Buffer 282 283 for i := 0; i < 3; i++ { 284 if _, err := stdout.WriteString(stdoutLongLine); err != nil { 285 t.Fatal(err) 286 } 287 if _, err := stderr.WriteString(stderrLongLine); err != nil { 288 t.Fatal(err) 289 } 290 } 291 292 if _, err := stdout.WriteString(stdoutTrailingLine + "\n"); err != nil { 293 t.Fatal(err) 294 } 295 if _, err := stderr.WriteString(stderrTrailingLine + "\n"); err != nil { 296 t.Fatal(err) 297 } 298 if _, err := normalMsg.WriteString(normalStr + "\n"); err != nil { 299 t.Fatal(err) 300 } 301 302 var jsonBuf bytes.Buffer 303 304 jsonLog := &TestLoggerJSON{Encoder: json.NewEncoder(&jsonBuf)} 305 306 c := NewCopier( 307 map[string]io.Reader{ 308 "stdout": &stdout, 309 "normal": &normalMsg, 310 "stderr": &stderr, 311 }, 312 jsonLog) 313 c.Run() 314 wait := make(chan struct{}) 315 go func() { 316 c.Wait() 317 close(wait) 318 }() 319 select { 320 case <-time.After(1 * time.Second): 321 t.Fatal("Copier failed to do its work in 1 second") 322 case <-wait: 323 } 324 325 dec := json.NewDecoder(&jsonBuf) 326 expectedMsgs := 9 327 recvMsgs := 0 328 var expectedPartID1, expectedPartID2 string 329 var expectedTS1, expectedTS2 time.Time 330 331 for { 332 var msg Message 333 334 if err := dec.Decode(&msg); err != nil { 335 if err == io.EOF { 336 break 337 } 338 t.Fatal(err) 339 } 340 if msg.Source != "stdout" && msg.Source != "stderr" && msg.Source != "normal" { 341 t.Fatalf("Wrong Source: %q, should be %q or %q or %q", msg.Source, "stdout", "stderr", "normal") 342 } 343 344 if msg.Source == "stdout" { 345 if string(msg.Line) != stdoutLongLine && string(msg.Line) != stdoutTrailingLine { 346 t.Fatalf("Wrong Line: %q, expected 'stdoutLongLine' or 'stdoutTrailingLine'", msg.Line) 347 } 348 349 if msg.PLogMetaData.ID == "" { 350 t.Fatalf("Expected partial metadata. Got nothing") 351 } 352 353 if msg.PLogMetaData.Ordinal == 1 { 354 expectedPartID1 = msg.PLogMetaData.ID 355 expectedTS1 = msg.Timestamp 356 } else { 357 checkIdentical(t, msg, expectedPartID1, expectedTS1) 358 } 359 if msg.PLogMetaData.Ordinal == 4 && !msg.PLogMetaData.Last { 360 t.Fatalf("Last is not set for last chunk") 361 } 362 } 363 364 if msg.Source == "stderr" { 365 if string(msg.Line) != stderrLongLine && string(msg.Line) != stderrTrailingLine { 366 t.Fatalf("Wrong Line: %q, expected 'stderrLongLine' or 'stderrTrailingLine'", msg.Line) 367 } 368 369 if msg.PLogMetaData.ID == "" { 370 t.Fatalf("Expected partial metadata. Got nothing") 371 } 372 373 if msg.PLogMetaData.Ordinal == 1 { 374 expectedPartID2 = msg.PLogMetaData.ID 375 expectedTS2 = msg.Timestamp 376 } else { 377 checkIdentical(t, msg, expectedPartID2, expectedTS2) 378 } 379 if msg.PLogMetaData.Ordinal == 4 && !msg.PLogMetaData.Last { 380 t.Fatalf("Last is not set for last chunk") 381 } 382 } 383 384 if msg.Source == "normal" && msg.PLogMetaData != nil { 385 t.Fatalf("Normal messages should not have PartialLogMetaData") 386 } 387 recvMsgs++ 388 } 389 390 if expectedMsgs != recvMsgs { 391 t.Fatalf("Expected msgs: %d Recv msgs: %d", expectedMsgs, recvMsgs) 392 } 393 } 394 395 type BenchmarkLoggerDummy struct { 396 } 397 398 func (l *BenchmarkLoggerDummy) Log(m *Message) error { PutMessage(m); return nil } 399 400 func (l *BenchmarkLoggerDummy) Close() error { return nil } 401 402 func (l *BenchmarkLoggerDummy) Name() string { return "dummy" } 403 404 func BenchmarkCopier64(b *testing.B) { 405 benchmarkCopier(b, 1<<6) 406 } 407 func BenchmarkCopier128(b *testing.B) { 408 benchmarkCopier(b, 1<<7) 409 } 410 func BenchmarkCopier256(b *testing.B) { 411 benchmarkCopier(b, 1<<8) 412 } 413 func BenchmarkCopier512(b *testing.B) { 414 benchmarkCopier(b, 1<<9) 415 } 416 func BenchmarkCopier1K(b *testing.B) { 417 benchmarkCopier(b, 1<<10) 418 } 419 func BenchmarkCopier2K(b *testing.B) { 420 benchmarkCopier(b, 1<<11) 421 } 422 func BenchmarkCopier4K(b *testing.B) { 423 benchmarkCopier(b, 1<<12) 424 } 425 func BenchmarkCopier8K(b *testing.B) { 426 benchmarkCopier(b, 1<<13) 427 } 428 func BenchmarkCopier16K(b *testing.B) { 429 benchmarkCopier(b, 1<<14) 430 } 431 func BenchmarkCopier32K(b *testing.B) { 432 benchmarkCopier(b, 1<<15) 433 } 434 func BenchmarkCopier64K(b *testing.B) { 435 benchmarkCopier(b, 1<<16) 436 } 437 func BenchmarkCopier128K(b *testing.B) { 438 benchmarkCopier(b, 1<<17) 439 } 440 func BenchmarkCopier256K(b *testing.B) { 441 benchmarkCopier(b, 1<<18) 442 } 443 444 func piped(b *testing.B, iterations int, delay time.Duration, buf []byte) io.Reader { 445 r, w, err := os.Pipe() 446 if err != nil { 447 b.Fatal(err) 448 return nil 449 } 450 go func() { 451 for i := 0; i < iterations; i++ { 452 time.Sleep(delay) 453 if n, err := w.Write(buf); err != nil || n != len(buf) { 454 if err != nil { 455 b.Error(err) 456 } 457 b.Error("short write") 458 } 459 } 460 w.Close() 461 }() 462 return r 463 } 464 465 func benchmarkCopier(b *testing.B, length int) { 466 b.StopTimer() 467 buf := []byte{'A'} 468 for len(buf) < length { 469 buf = append(buf, buf...) 470 } 471 buf = append(buf[:length-1], []byte{'\n'}...) 472 b.StartTimer() 473 for i := 0; i < b.N; i++ { 474 c := NewCopier( 475 map[string]io.Reader{ 476 "buffer": piped(b, 10, time.Nanosecond, buf), 477 }, 478 &BenchmarkLoggerDummy{}) 479 c.Run() 480 c.Wait() 481 c.Close() 482 } 483 }