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