github.com/lazyboychen7/engine@v17.12.1-ce-rc2+incompatible/daemon/logger/awslogs/cloudwatchlogs_test.go (about) 1 package awslogs 2 3 import ( 4 "errors" 5 "fmt" 6 "io/ioutil" 7 "net/http" 8 "net/http/httptest" 9 "os" 10 "reflect" 11 "regexp" 12 "runtime" 13 "strings" 14 "testing" 15 "time" 16 17 "github.com/aws/aws-sdk-go/aws" 18 "github.com/aws/aws-sdk-go/aws/awserr" 19 "github.com/aws/aws-sdk-go/aws/request" 20 "github.com/aws/aws-sdk-go/service/cloudwatchlogs" 21 "github.com/docker/docker/daemon/logger" 22 "github.com/docker/docker/daemon/logger/loggerutils" 23 "github.com/docker/docker/dockerversion" 24 "github.com/stretchr/testify/assert" 25 ) 26 27 const ( 28 groupName = "groupName" 29 streamName = "streamName" 30 sequenceToken = "sequenceToken" 31 nextSequenceToken = "nextSequenceToken" 32 logline = "this is a log line\r" 33 multilineLogline = "2017-01-01 01:01:44 This is a multiline log entry\r" 34 ) 35 36 // Generates i multi-line events each with j lines 37 func (l *logStream) logGenerator(lineCount int, multilineCount int) { 38 for i := 0; i < multilineCount; i++ { 39 l.Log(&logger.Message{ 40 Line: []byte(multilineLogline), 41 Timestamp: time.Time{}, 42 }) 43 for j := 0; j < lineCount; j++ { 44 l.Log(&logger.Message{ 45 Line: []byte(logline), 46 Timestamp: time.Time{}, 47 }) 48 } 49 } 50 } 51 52 func testEventBatch(events []wrappedEvent) *eventBatch { 53 batch := newEventBatch() 54 for _, event := range events { 55 eventlen := len([]byte(*event.inputLogEvent.Message)) 56 batch.add(event, eventlen) 57 } 58 return batch 59 } 60 61 func TestNewAWSLogsClientUserAgentHandler(t *testing.T) { 62 info := logger.Info{ 63 Config: map[string]string{ 64 regionKey: "us-east-1", 65 }, 66 } 67 68 client, err := newAWSLogsClient(info) 69 if err != nil { 70 t.Fatal(err) 71 } 72 realClient, ok := client.(*cloudwatchlogs.CloudWatchLogs) 73 if !ok { 74 t.Fatal("Could not cast client to cloudwatchlogs.CloudWatchLogs") 75 } 76 buildHandlerList := realClient.Handlers.Build 77 request := &request.Request{ 78 HTTPRequest: &http.Request{ 79 Header: http.Header{}, 80 }, 81 } 82 buildHandlerList.Run(request) 83 expectedUserAgentString := fmt.Sprintf("Docker %s (%s) %s/%s (%s; %s; %s)", 84 dockerversion.Version, runtime.GOOS, aws.SDKName, aws.SDKVersion, runtime.Version(), runtime.GOOS, runtime.GOARCH) 85 userAgent := request.HTTPRequest.Header.Get("User-Agent") 86 if userAgent != expectedUserAgentString { 87 t.Errorf("Wrong User-Agent string, expected \"%s\" but was \"%s\"", 88 expectedUserAgentString, userAgent) 89 } 90 } 91 92 func TestNewAWSLogsClientRegionDetect(t *testing.T) { 93 info := logger.Info{ 94 Config: map[string]string{}, 95 } 96 97 mockMetadata := newMockMetadataClient() 98 newRegionFinder = func() regionFinder { 99 return mockMetadata 100 } 101 mockMetadata.regionResult <- ®ionResult{ 102 successResult: "us-east-1", 103 } 104 105 _, err := newAWSLogsClient(info) 106 if err != nil { 107 t.Fatal(err) 108 } 109 } 110 111 func TestCreateSuccess(t *testing.T) { 112 mockClient := newMockClient() 113 stream := &logStream{ 114 client: mockClient, 115 logGroupName: groupName, 116 logStreamName: streamName, 117 } 118 mockClient.createLogStreamResult <- &createLogStreamResult{} 119 120 err := stream.create() 121 122 if err != nil { 123 t.Errorf("Received unexpected err: %v\n", err) 124 } 125 argument := <-mockClient.createLogStreamArgument 126 if argument.LogGroupName == nil { 127 t.Fatal("Expected non-nil LogGroupName") 128 } 129 if *argument.LogGroupName != groupName { 130 t.Errorf("Expected LogGroupName to be %s", groupName) 131 } 132 if argument.LogStreamName == nil { 133 t.Fatal("Expected non-nil LogStreamName") 134 } 135 if *argument.LogStreamName != streamName { 136 t.Errorf("Expected LogStreamName to be %s", streamName) 137 } 138 } 139 140 func TestCreateLogGroupSuccess(t *testing.T) { 141 mockClient := newMockClient() 142 stream := &logStream{ 143 client: mockClient, 144 logGroupName: groupName, 145 logStreamName: streamName, 146 logCreateGroup: true, 147 } 148 mockClient.createLogGroupResult <- &createLogGroupResult{} 149 mockClient.createLogStreamResult <- &createLogStreamResult{} 150 151 err := stream.create() 152 153 if err != nil { 154 t.Errorf("Received unexpected err: %v\n", err) 155 } 156 argument := <-mockClient.createLogStreamArgument 157 if argument.LogGroupName == nil { 158 t.Fatal("Expected non-nil LogGroupName") 159 } 160 if *argument.LogGroupName != groupName { 161 t.Errorf("Expected LogGroupName to be %s", groupName) 162 } 163 if argument.LogStreamName == nil { 164 t.Fatal("Expected non-nil LogStreamName") 165 } 166 if *argument.LogStreamName != streamName { 167 t.Errorf("Expected LogStreamName to be %s", streamName) 168 } 169 } 170 171 func TestCreateError(t *testing.T) { 172 mockClient := newMockClient() 173 stream := &logStream{ 174 client: mockClient, 175 } 176 mockClient.createLogStreamResult <- &createLogStreamResult{ 177 errorResult: errors.New("Error"), 178 } 179 180 err := stream.create() 181 182 if err == nil { 183 t.Fatal("Expected non-nil err") 184 } 185 } 186 187 func TestCreateAlreadyExists(t *testing.T) { 188 mockClient := newMockClient() 189 stream := &logStream{ 190 client: mockClient, 191 } 192 mockClient.createLogStreamResult <- &createLogStreamResult{ 193 errorResult: awserr.New(resourceAlreadyExistsCode, "", nil), 194 } 195 196 err := stream.create() 197 198 if err != nil { 199 t.Fatal("Expected nil err") 200 } 201 } 202 203 func TestPublishBatchSuccess(t *testing.T) { 204 mockClient := newMockClient() 205 stream := &logStream{ 206 client: mockClient, 207 logGroupName: groupName, 208 logStreamName: streamName, 209 sequenceToken: aws.String(sequenceToken), 210 } 211 mockClient.putLogEventsResult <- &putLogEventsResult{ 212 successResult: &cloudwatchlogs.PutLogEventsOutput{ 213 NextSequenceToken: aws.String(nextSequenceToken), 214 }, 215 } 216 events := []wrappedEvent{ 217 { 218 inputLogEvent: &cloudwatchlogs.InputLogEvent{ 219 Message: aws.String(logline), 220 }, 221 }, 222 } 223 224 stream.publishBatch(testEventBatch(events)) 225 if stream.sequenceToken == nil { 226 t.Fatal("Expected non-nil sequenceToken") 227 } 228 if *stream.sequenceToken != nextSequenceToken { 229 t.Errorf("Expected sequenceToken to be %s, but was %s", nextSequenceToken, *stream.sequenceToken) 230 } 231 argument := <-mockClient.putLogEventsArgument 232 if argument == nil { 233 t.Fatal("Expected non-nil PutLogEventsInput") 234 } 235 if argument.SequenceToken == nil { 236 t.Fatal("Expected non-nil PutLogEventsInput.SequenceToken") 237 } 238 if *argument.SequenceToken != sequenceToken { 239 t.Errorf("Expected PutLogEventsInput.SequenceToken to be %s, but was %s", sequenceToken, *argument.SequenceToken) 240 } 241 if len(argument.LogEvents) != 1 { 242 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 243 } 244 if argument.LogEvents[0] != events[0].inputLogEvent { 245 t.Error("Expected event to equal input") 246 } 247 } 248 249 func TestPublishBatchError(t *testing.T) { 250 mockClient := newMockClient() 251 stream := &logStream{ 252 client: mockClient, 253 logGroupName: groupName, 254 logStreamName: streamName, 255 sequenceToken: aws.String(sequenceToken), 256 } 257 mockClient.putLogEventsResult <- &putLogEventsResult{ 258 errorResult: errors.New("Error"), 259 } 260 261 events := []wrappedEvent{ 262 { 263 inputLogEvent: &cloudwatchlogs.InputLogEvent{ 264 Message: aws.String(logline), 265 }, 266 }, 267 } 268 269 stream.publishBatch(testEventBatch(events)) 270 if stream.sequenceToken == nil { 271 t.Fatal("Expected non-nil sequenceToken") 272 } 273 if *stream.sequenceToken != sequenceToken { 274 t.Errorf("Expected sequenceToken to be %s, but was %s", sequenceToken, *stream.sequenceToken) 275 } 276 } 277 278 func TestPublishBatchInvalidSeqSuccess(t *testing.T) { 279 mockClient := newMockClientBuffered(2) 280 stream := &logStream{ 281 client: mockClient, 282 logGroupName: groupName, 283 logStreamName: streamName, 284 sequenceToken: aws.String(sequenceToken), 285 } 286 mockClient.putLogEventsResult <- &putLogEventsResult{ 287 errorResult: awserr.New(invalidSequenceTokenCode, "use token token", nil), 288 } 289 mockClient.putLogEventsResult <- &putLogEventsResult{ 290 successResult: &cloudwatchlogs.PutLogEventsOutput{ 291 NextSequenceToken: aws.String(nextSequenceToken), 292 }, 293 } 294 295 events := []wrappedEvent{ 296 { 297 inputLogEvent: &cloudwatchlogs.InputLogEvent{ 298 Message: aws.String(logline), 299 }, 300 }, 301 } 302 303 stream.publishBatch(testEventBatch(events)) 304 if stream.sequenceToken == nil { 305 t.Fatal("Expected non-nil sequenceToken") 306 } 307 if *stream.sequenceToken != nextSequenceToken { 308 t.Errorf("Expected sequenceToken to be %s, but was %s", nextSequenceToken, *stream.sequenceToken) 309 } 310 311 argument := <-mockClient.putLogEventsArgument 312 if argument == nil { 313 t.Fatal("Expected non-nil PutLogEventsInput") 314 } 315 if argument.SequenceToken == nil { 316 t.Fatal("Expected non-nil PutLogEventsInput.SequenceToken") 317 } 318 if *argument.SequenceToken != sequenceToken { 319 t.Errorf("Expected PutLogEventsInput.SequenceToken to be %s, but was %s", sequenceToken, *argument.SequenceToken) 320 } 321 if len(argument.LogEvents) != 1 { 322 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 323 } 324 if argument.LogEvents[0] != events[0].inputLogEvent { 325 t.Error("Expected event to equal input") 326 } 327 328 argument = <-mockClient.putLogEventsArgument 329 if argument == nil { 330 t.Fatal("Expected non-nil PutLogEventsInput") 331 } 332 if argument.SequenceToken == nil { 333 t.Fatal("Expected non-nil PutLogEventsInput.SequenceToken") 334 } 335 if *argument.SequenceToken != "token" { 336 t.Errorf("Expected PutLogEventsInput.SequenceToken to be %s, but was %s", "token", *argument.SequenceToken) 337 } 338 if len(argument.LogEvents) != 1 { 339 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 340 } 341 if argument.LogEvents[0] != events[0].inputLogEvent { 342 t.Error("Expected event to equal input") 343 } 344 } 345 346 func TestPublishBatchAlreadyAccepted(t *testing.T) { 347 mockClient := newMockClient() 348 stream := &logStream{ 349 client: mockClient, 350 logGroupName: groupName, 351 logStreamName: streamName, 352 sequenceToken: aws.String(sequenceToken), 353 } 354 mockClient.putLogEventsResult <- &putLogEventsResult{ 355 errorResult: awserr.New(dataAlreadyAcceptedCode, "use token token", nil), 356 } 357 358 events := []wrappedEvent{ 359 { 360 inputLogEvent: &cloudwatchlogs.InputLogEvent{ 361 Message: aws.String(logline), 362 }, 363 }, 364 } 365 366 stream.publishBatch(testEventBatch(events)) 367 if stream.sequenceToken == nil { 368 t.Fatal("Expected non-nil sequenceToken") 369 } 370 if *stream.sequenceToken != "token" { 371 t.Errorf("Expected sequenceToken to be %s, but was %s", "token", *stream.sequenceToken) 372 } 373 374 argument := <-mockClient.putLogEventsArgument 375 if argument == nil { 376 t.Fatal("Expected non-nil PutLogEventsInput") 377 } 378 if argument.SequenceToken == nil { 379 t.Fatal("Expected non-nil PutLogEventsInput.SequenceToken") 380 } 381 if *argument.SequenceToken != sequenceToken { 382 t.Errorf("Expected PutLogEventsInput.SequenceToken to be %s, but was %s", sequenceToken, *argument.SequenceToken) 383 } 384 if len(argument.LogEvents) != 1 { 385 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 386 } 387 if argument.LogEvents[0] != events[0].inputLogEvent { 388 t.Error("Expected event to equal input") 389 } 390 } 391 392 func TestCollectBatchSimple(t *testing.T) { 393 mockClient := newMockClient() 394 stream := &logStream{ 395 client: mockClient, 396 logGroupName: groupName, 397 logStreamName: streamName, 398 sequenceToken: aws.String(sequenceToken), 399 messages: make(chan *logger.Message), 400 } 401 mockClient.putLogEventsResult <- &putLogEventsResult{ 402 successResult: &cloudwatchlogs.PutLogEventsOutput{ 403 NextSequenceToken: aws.String(nextSequenceToken), 404 }, 405 } 406 ticks := make(chan time.Time) 407 newTicker = func(_ time.Duration) *time.Ticker { 408 return &time.Ticker{ 409 C: ticks, 410 } 411 } 412 413 go stream.collectBatch() 414 415 stream.Log(&logger.Message{ 416 Line: []byte(logline), 417 Timestamp: time.Time{}, 418 }) 419 420 ticks <- time.Time{} 421 stream.Close() 422 423 argument := <-mockClient.putLogEventsArgument 424 if argument == nil { 425 t.Fatal("Expected non-nil PutLogEventsInput") 426 } 427 if len(argument.LogEvents) != 1 { 428 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 429 } 430 if *argument.LogEvents[0].Message != logline { 431 t.Errorf("Expected message to be %s but was %s", logline, *argument.LogEvents[0].Message) 432 } 433 } 434 435 func TestCollectBatchTicker(t *testing.T) { 436 mockClient := newMockClient() 437 stream := &logStream{ 438 client: mockClient, 439 logGroupName: groupName, 440 logStreamName: streamName, 441 sequenceToken: aws.String(sequenceToken), 442 messages: make(chan *logger.Message), 443 } 444 mockClient.putLogEventsResult <- &putLogEventsResult{ 445 successResult: &cloudwatchlogs.PutLogEventsOutput{ 446 NextSequenceToken: aws.String(nextSequenceToken), 447 }, 448 } 449 ticks := make(chan time.Time) 450 newTicker = func(_ time.Duration) *time.Ticker { 451 return &time.Ticker{ 452 C: ticks, 453 } 454 } 455 456 go stream.collectBatch() 457 458 stream.Log(&logger.Message{ 459 Line: []byte(logline + " 1"), 460 Timestamp: time.Time{}, 461 }) 462 stream.Log(&logger.Message{ 463 Line: []byte(logline + " 2"), 464 Timestamp: time.Time{}, 465 }) 466 467 ticks <- time.Time{} 468 469 // Verify first batch 470 argument := <-mockClient.putLogEventsArgument 471 if argument == nil { 472 t.Fatal("Expected non-nil PutLogEventsInput") 473 } 474 if len(argument.LogEvents) != 2 { 475 t.Errorf("Expected LogEvents to contain 2 elements, but contains %d", len(argument.LogEvents)) 476 } 477 if *argument.LogEvents[0].Message != logline+" 1" { 478 t.Errorf("Expected message to be %s but was %s", logline+" 1", *argument.LogEvents[0].Message) 479 } 480 if *argument.LogEvents[1].Message != logline+" 2" { 481 t.Errorf("Expected message to be %s but was %s", logline+" 2", *argument.LogEvents[0].Message) 482 } 483 484 stream.Log(&logger.Message{ 485 Line: []byte(logline + " 3"), 486 Timestamp: time.Time{}, 487 }) 488 489 ticks <- time.Time{} 490 argument = <-mockClient.putLogEventsArgument 491 if argument == nil { 492 t.Fatal("Expected non-nil PutLogEventsInput") 493 } 494 if len(argument.LogEvents) != 1 { 495 t.Errorf("Expected LogEvents to contain 1 elements, but contains %d", len(argument.LogEvents)) 496 } 497 if *argument.LogEvents[0].Message != logline+" 3" { 498 t.Errorf("Expected message to be %s but was %s", logline+" 3", *argument.LogEvents[0].Message) 499 } 500 501 stream.Close() 502 503 } 504 505 func TestCollectBatchMultilinePattern(t *testing.T) { 506 mockClient := newMockClient() 507 multilinePattern := regexp.MustCompile("xxxx") 508 stream := &logStream{ 509 client: mockClient, 510 logGroupName: groupName, 511 logStreamName: streamName, 512 multilinePattern: multilinePattern, 513 sequenceToken: aws.String(sequenceToken), 514 messages: make(chan *logger.Message), 515 } 516 mockClient.putLogEventsResult <- &putLogEventsResult{ 517 successResult: &cloudwatchlogs.PutLogEventsOutput{ 518 NextSequenceToken: aws.String(nextSequenceToken), 519 }, 520 } 521 ticks := make(chan time.Time) 522 newTicker = func(_ time.Duration) *time.Ticker { 523 return &time.Ticker{ 524 C: ticks, 525 } 526 } 527 528 go stream.collectBatch() 529 530 stream.Log(&logger.Message{ 531 Line: []byte(logline), 532 Timestamp: time.Now(), 533 }) 534 stream.Log(&logger.Message{ 535 Line: []byte(logline), 536 Timestamp: time.Now(), 537 }) 538 stream.Log(&logger.Message{ 539 Line: []byte("xxxx " + logline), 540 Timestamp: time.Now(), 541 }) 542 543 ticks <- time.Now() 544 545 // Verify single multiline event 546 argument := <-mockClient.putLogEventsArgument 547 assert.NotNil(t, argument, "Expected non-nil PutLogEventsInput") 548 assert.Equal(t, 1, len(argument.LogEvents), "Expected single multiline event") 549 assert.Equal(t, logline+"\n"+logline+"\n", *argument.LogEvents[0].Message, "Received incorrect multiline message") 550 551 stream.Close() 552 553 // Verify single event 554 argument = <-mockClient.putLogEventsArgument 555 assert.NotNil(t, argument, "Expected non-nil PutLogEventsInput") 556 assert.Equal(t, 1, len(argument.LogEvents), "Expected single multiline event") 557 assert.Equal(t, "xxxx "+logline+"\n", *argument.LogEvents[0].Message, "Received incorrect multiline message") 558 } 559 560 func BenchmarkCollectBatch(b *testing.B) { 561 for i := 0; i < b.N; i++ { 562 mockClient := newMockClient() 563 stream := &logStream{ 564 client: mockClient, 565 logGroupName: groupName, 566 logStreamName: streamName, 567 sequenceToken: aws.String(sequenceToken), 568 messages: make(chan *logger.Message), 569 } 570 mockClient.putLogEventsResult <- &putLogEventsResult{ 571 successResult: &cloudwatchlogs.PutLogEventsOutput{ 572 NextSequenceToken: aws.String(nextSequenceToken), 573 }, 574 } 575 ticks := make(chan time.Time) 576 newTicker = func(_ time.Duration) *time.Ticker { 577 return &time.Ticker{ 578 C: ticks, 579 } 580 } 581 582 go stream.collectBatch() 583 stream.logGenerator(10, 100) 584 ticks <- time.Time{} 585 stream.Close() 586 } 587 } 588 589 func BenchmarkCollectBatchMultilinePattern(b *testing.B) { 590 for i := 0; i < b.N; i++ { 591 mockClient := newMockClient() 592 multilinePattern := regexp.MustCompile(`\d{4}-(?:0[1-9]|1[0-2])-(?:0[1-9]|[1,2][0-9]|3[0,1]) (?:[0,1][0-9]|2[0-3]):[0-5][0-9]:[0-5][0-9]`) 593 stream := &logStream{ 594 client: mockClient, 595 logGroupName: groupName, 596 logStreamName: streamName, 597 multilinePattern: multilinePattern, 598 sequenceToken: aws.String(sequenceToken), 599 messages: make(chan *logger.Message), 600 } 601 mockClient.putLogEventsResult <- &putLogEventsResult{ 602 successResult: &cloudwatchlogs.PutLogEventsOutput{ 603 NextSequenceToken: aws.String(nextSequenceToken), 604 }, 605 } 606 ticks := make(chan time.Time) 607 newTicker = func(_ time.Duration) *time.Ticker { 608 return &time.Ticker{ 609 C: ticks, 610 } 611 } 612 go stream.collectBatch() 613 stream.logGenerator(10, 100) 614 ticks <- time.Time{} 615 stream.Close() 616 } 617 } 618 619 func TestCollectBatchMultilinePatternMaxEventAge(t *testing.T) { 620 mockClient := newMockClient() 621 multilinePattern := regexp.MustCompile("xxxx") 622 stream := &logStream{ 623 client: mockClient, 624 logGroupName: groupName, 625 logStreamName: streamName, 626 multilinePattern: multilinePattern, 627 sequenceToken: aws.String(sequenceToken), 628 messages: make(chan *logger.Message), 629 } 630 mockClient.putLogEventsResult <- &putLogEventsResult{ 631 successResult: &cloudwatchlogs.PutLogEventsOutput{ 632 NextSequenceToken: aws.String(nextSequenceToken), 633 }, 634 } 635 ticks := make(chan time.Time) 636 newTicker = func(_ time.Duration) *time.Ticker { 637 return &time.Ticker{ 638 C: ticks, 639 } 640 } 641 642 go stream.collectBatch() 643 644 stream.Log(&logger.Message{ 645 Line: []byte(logline), 646 Timestamp: time.Now(), 647 }) 648 649 // Log an event 1 second later 650 stream.Log(&logger.Message{ 651 Line: []byte(logline), 652 Timestamp: time.Now().Add(time.Second), 653 }) 654 655 // Fire ticker batchPublishFrequency seconds later 656 ticks <- time.Now().Add(batchPublishFrequency + time.Second) 657 658 // Verify single multiline event is flushed after maximum event buffer age (batchPublishFrequency) 659 argument := <-mockClient.putLogEventsArgument 660 assert.NotNil(t, argument, "Expected non-nil PutLogEventsInput") 661 assert.Equal(t, 1, len(argument.LogEvents), "Expected single multiline event") 662 assert.Equal(t, logline+"\n"+logline+"\n", *argument.LogEvents[0].Message, "Received incorrect multiline message") 663 664 // Log an event 1 second later 665 stream.Log(&logger.Message{ 666 Line: []byte(logline), 667 Timestamp: time.Now().Add(time.Second), 668 }) 669 670 // Fire ticker another batchPublishFrequency seconds later 671 ticks <- time.Now().Add(2*batchPublishFrequency + time.Second) 672 673 // Verify the event buffer is truly flushed - we should only receive a single event 674 argument = <-mockClient.putLogEventsArgument 675 assert.NotNil(t, argument, "Expected non-nil PutLogEventsInput") 676 assert.Equal(t, 1, len(argument.LogEvents), "Expected single multiline event") 677 assert.Equal(t, logline+"\n", *argument.LogEvents[0].Message, "Received incorrect multiline message") 678 stream.Close() 679 } 680 681 func TestCollectBatchMultilinePatternNegativeEventAge(t *testing.T) { 682 mockClient := newMockClient() 683 multilinePattern := regexp.MustCompile("xxxx") 684 stream := &logStream{ 685 client: mockClient, 686 logGroupName: groupName, 687 logStreamName: streamName, 688 multilinePattern: multilinePattern, 689 sequenceToken: aws.String(sequenceToken), 690 messages: make(chan *logger.Message), 691 } 692 mockClient.putLogEventsResult <- &putLogEventsResult{ 693 successResult: &cloudwatchlogs.PutLogEventsOutput{ 694 NextSequenceToken: aws.String(nextSequenceToken), 695 }, 696 } 697 ticks := make(chan time.Time) 698 newTicker = func(_ time.Duration) *time.Ticker { 699 return &time.Ticker{ 700 C: ticks, 701 } 702 } 703 704 go stream.collectBatch() 705 706 stream.Log(&logger.Message{ 707 Line: []byte(logline), 708 Timestamp: time.Now(), 709 }) 710 711 // Log an event 1 second later 712 stream.Log(&logger.Message{ 713 Line: []byte(logline), 714 Timestamp: time.Now().Add(time.Second), 715 }) 716 717 // Fire ticker in past to simulate negative event buffer age 718 ticks <- time.Now().Add(-time.Second) 719 720 // Verify single multiline event is flushed with a negative event buffer age 721 argument := <-mockClient.putLogEventsArgument 722 assert.NotNil(t, argument, "Expected non-nil PutLogEventsInput") 723 assert.Equal(t, 1, len(argument.LogEvents), "Expected single multiline event") 724 assert.Equal(t, logline+"\n"+logline+"\n", *argument.LogEvents[0].Message, "Received incorrect multiline message") 725 726 stream.Close() 727 } 728 729 func TestCollectBatchClose(t *testing.T) { 730 mockClient := newMockClient() 731 stream := &logStream{ 732 client: mockClient, 733 logGroupName: groupName, 734 logStreamName: streamName, 735 sequenceToken: aws.String(sequenceToken), 736 messages: make(chan *logger.Message), 737 } 738 mockClient.putLogEventsResult <- &putLogEventsResult{ 739 successResult: &cloudwatchlogs.PutLogEventsOutput{ 740 NextSequenceToken: aws.String(nextSequenceToken), 741 }, 742 } 743 var ticks = make(chan time.Time) 744 newTicker = func(_ time.Duration) *time.Ticker { 745 return &time.Ticker{ 746 C: ticks, 747 } 748 } 749 750 go stream.collectBatch() 751 752 stream.Log(&logger.Message{ 753 Line: []byte(logline), 754 Timestamp: time.Time{}, 755 }) 756 757 // no ticks 758 stream.Close() 759 760 argument := <-mockClient.putLogEventsArgument 761 if argument == nil { 762 t.Fatal("Expected non-nil PutLogEventsInput") 763 } 764 if len(argument.LogEvents) != 1 { 765 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 766 } 767 if *argument.LogEvents[0].Message != logline { 768 t.Errorf("Expected message to be %s but was %s", logline, *argument.LogEvents[0].Message) 769 } 770 } 771 772 func TestCollectBatchLineSplit(t *testing.T) { 773 mockClient := newMockClient() 774 stream := &logStream{ 775 client: mockClient, 776 logGroupName: groupName, 777 logStreamName: streamName, 778 sequenceToken: aws.String(sequenceToken), 779 messages: make(chan *logger.Message), 780 } 781 mockClient.putLogEventsResult <- &putLogEventsResult{ 782 successResult: &cloudwatchlogs.PutLogEventsOutput{ 783 NextSequenceToken: aws.String(nextSequenceToken), 784 }, 785 } 786 var ticks = make(chan time.Time) 787 newTicker = func(_ time.Duration) *time.Ticker { 788 return &time.Ticker{ 789 C: ticks, 790 } 791 } 792 793 go stream.collectBatch() 794 795 longline := strings.Repeat("A", maximumBytesPerEvent) 796 stream.Log(&logger.Message{ 797 Line: []byte(longline + "B"), 798 Timestamp: time.Time{}, 799 }) 800 801 // no ticks 802 stream.Close() 803 804 argument := <-mockClient.putLogEventsArgument 805 if argument == nil { 806 t.Fatal("Expected non-nil PutLogEventsInput") 807 } 808 if len(argument.LogEvents) != 2 { 809 t.Errorf("Expected LogEvents to contain 2 elements, but contains %d", len(argument.LogEvents)) 810 } 811 if *argument.LogEvents[0].Message != longline { 812 t.Errorf("Expected message to be %s but was %s", longline, *argument.LogEvents[0].Message) 813 } 814 if *argument.LogEvents[1].Message != "B" { 815 t.Errorf("Expected message to be %s but was %s", "B", *argument.LogEvents[1].Message) 816 } 817 } 818 819 func TestCollectBatchMaxEvents(t *testing.T) { 820 mockClient := newMockClientBuffered(1) 821 stream := &logStream{ 822 client: mockClient, 823 logGroupName: groupName, 824 logStreamName: streamName, 825 sequenceToken: aws.String(sequenceToken), 826 messages: make(chan *logger.Message), 827 } 828 mockClient.putLogEventsResult <- &putLogEventsResult{ 829 successResult: &cloudwatchlogs.PutLogEventsOutput{ 830 NextSequenceToken: aws.String(nextSequenceToken), 831 }, 832 } 833 var ticks = make(chan time.Time) 834 newTicker = func(_ time.Duration) *time.Ticker { 835 return &time.Ticker{ 836 C: ticks, 837 } 838 } 839 840 go stream.collectBatch() 841 842 line := "A" 843 for i := 0; i <= maximumLogEventsPerPut; i++ { 844 stream.Log(&logger.Message{ 845 Line: []byte(line), 846 Timestamp: time.Time{}, 847 }) 848 } 849 850 // no ticks 851 stream.Close() 852 853 argument := <-mockClient.putLogEventsArgument 854 if argument == nil { 855 t.Fatal("Expected non-nil PutLogEventsInput") 856 } 857 if len(argument.LogEvents) != maximumLogEventsPerPut { 858 t.Errorf("Expected LogEvents to contain %d elements, but contains %d", maximumLogEventsPerPut, len(argument.LogEvents)) 859 } 860 861 argument = <-mockClient.putLogEventsArgument 862 if argument == nil { 863 t.Fatal("Expected non-nil PutLogEventsInput") 864 } 865 if len(argument.LogEvents) != 1 { 866 t.Errorf("Expected LogEvents to contain %d elements, but contains %d", 1, len(argument.LogEvents)) 867 } 868 } 869 870 func TestCollectBatchMaxTotalBytes(t *testing.T) { 871 expectedPuts := 2 872 mockClient := newMockClientBuffered(expectedPuts) 873 stream := &logStream{ 874 client: mockClient, 875 logGroupName: groupName, 876 logStreamName: streamName, 877 sequenceToken: aws.String(sequenceToken), 878 messages: make(chan *logger.Message), 879 } 880 for i := 0; i < expectedPuts; i++ { 881 mockClient.putLogEventsResult <- &putLogEventsResult{ 882 successResult: &cloudwatchlogs.PutLogEventsOutput{ 883 NextSequenceToken: aws.String(nextSequenceToken), 884 }, 885 } 886 } 887 888 var ticks = make(chan time.Time) 889 newTicker = func(_ time.Duration) *time.Ticker { 890 return &time.Ticker{ 891 C: ticks, 892 } 893 } 894 895 go stream.collectBatch() 896 897 numPayloads := maximumBytesPerPut / (maximumBytesPerEvent + perEventBytes) 898 // maxline is the maximum line that could be submitted after 899 // accounting for its overhead. 900 maxline := strings.Repeat("A", maximumBytesPerPut-(perEventBytes*numPayloads)) 901 // This will be split and batched up to the `maximumBytesPerPut' 902 // (+/- `maximumBytesPerEvent'). This /should/ be aligned, but 903 // should also tolerate an offset within that range. 904 stream.Log(&logger.Message{ 905 Line: []byte(maxline[:len(maxline)/2]), 906 Timestamp: time.Time{}, 907 }) 908 stream.Log(&logger.Message{ 909 Line: []byte(maxline[len(maxline)/2:]), 910 Timestamp: time.Time{}, 911 }) 912 stream.Log(&logger.Message{ 913 Line: []byte("B"), 914 Timestamp: time.Time{}, 915 }) 916 917 // no ticks, guarantee batch by size (and chan close) 918 stream.Close() 919 920 argument := <-mockClient.putLogEventsArgument 921 if argument == nil { 922 t.Fatal("Expected non-nil PutLogEventsInput") 923 } 924 925 // Should total to the maximum allowed bytes. 926 eventBytes := 0 927 for _, event := range argument.LogEvents { 928 eventBytes += len(*event.Message) 929 } 930 eventsOverhead := len(argument.LogEvents) * perEventBytes 931 payloadTotal := eventBytes + eventsOverhead 932 // lowestMaxBatch allows the payload to be offset if the messages 933 // don't lend themselves to align with the maximum event size. 934 lowestMaxBatch := maximumBytesPerPut - maximumBytesPerEvent 935 936 if payloadTotal > maximumBytesPerPut { 937 t.Errorf("Expected <= %d bytes but was %d", maximumBytesPerPut, payloadTotal) 938 } 939 if payloadTotal < lowestMaxBatch { 940 t.Errorf("Batch to be no less than %d but was %d", lowestMaxBatch, payloadTotal) 941 } 942 943 argument = <-mockClient.putLogEventsArgument 944 if len(argument.LogEvents) != 1 { 945 t.Errorf("Expected LogEvents to contain 1 elements, but contains %d", len(argument.LogEvents)) 946 } 947 message := *argument.LogEvents[len(argument.LogEvents)-1].Message 948 if message[len(message)-1:] != "B" { 949 t.Errorf("Expected message to be %s but was %s", "B", message[len(message)-1:]) 950 } 951 } 952 953 func TestCollectBatchWithDuplicateTimestamps(t *testing.T) { 954 mockClient := newMockClient() 955 stream := &logStream{ 956 client: mockClient, 957 logGroupName: groupName, 958 logStreamName: streamName, 959 sequenceToken: aws.String(sequenceToken), 960 messages: make(chan *logger.Message), 961 } 962 mockClient.putLogEventsResult <- &putLogEventsResult{ 963 successResult: &cloudwatchlogs.PutLogEventsOutput{ 964 NextSequenceToken: aws.String(nextSequenceToken), 965 }, 966 } 967 ticks := make(chan time.Time) 968 newTicker = func(_ time.Duration) *time.Ticker { 969 return &time.Ticker{ 970 C: ticks, 971 } 972 } 973 974 go stream.collectBatch() 975 976 times := maximumLogEventsPerPut 977 expectedEvents := []*cloudwatchlogs.InputLogEvent{} 978 timestamp := time.Now() 979 for i := 0; i < times; i++ { 980 line := fmt.Sprintf("%d", i) 981 if i%2 == 0 { 982 timestamp.Add(1 * time.Nanosecond) 983 } 984 stream.Log(&logger.Message{ 985 Line: []byte(line), 986 Timestamp: timestamp, 987 }) 988 expectedEvents = append(expectedEvents, &cloudwatchlogs.InputLogEvent{ 989 Message: aws.String(line), 990 Timestamp: aws.Int64(timestamp.UnixNano() / int64(time.Millisecond)), 991 }) 992 } 993 994 ticks <- time.Time{} 995 stream.Close() 996 997 argument := <-mockClient.putLogEventsArgument 998 if argument == nil { 999 t.Fatal("Expected non-nil PutLogEventsInput") 1000 } 1001 if len(argument.LogEvents) != times { 1002 t.Errorf("Expected LogEvents to contain %d elements, but contains %d", times, len(argument.LogEvents)) 1003 } 1004 for i := 0; i < times; i++ { 1005 if !reflect.DeepEqual(*argument.LogEvents[i], *expectedEvents[i]) { 1006 t.Errorf("Expected event to be %v but was %v", *expectedEvents[i], *argument.LogEvents[i]) 1007 } 1008 } 1009 } 1010 1011 func TestParseLogOptionsMultilinePattern(t *testing.T) { 1012 info := logger.Info{ 1013 Config: map[string]string{ 1014 multilinePatternKey: "^xxxx", 1015 }, 1016 } 1017 1018 multilinePattern, err := parseMultilineOptions(info) 1019 assert.Nil(t, err, "Received unexpected error") 1020 assert.True(t, multilinePattern.MatchString("xxxx"), "No multiline pattern match found") 1021 } 1022 1023 func TestParseLogOptionsDatetimeFormat(t *testing.T) { 1024 datetimeFormatTests := []struct { 1025 format string 1026 match string 1027 }{ 1028 {"%d/%m/%y %a %H:%M:%S%L %Z", "31/12/10 Mon 08:42:44.345 NZDT"}, 1029 {"%Y-%m-%d %A %I:%M:%S.%f%p%z", "2007-12-04 Monday 08:42:44.123456AM+1200"}, 1030 {"%b|%b|%b|%b|%b|%b|%b|%b|%b|%b|%b|%b", "Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec"}, 1031 {"%B|%B|%B|%B|%B|%B|%B|%B|%B|%B|%B|%B", "January|February|March|April|May|June|July|August|September|October|November|December"}, 1032 {"%A|%A|%A|%A|%A|%A|%A", "Monday|Tuesday|Wednesday|Thursday|Friday|Saturday|Sunday"}, 1033 {"%a|%a|%a|%a|%a|%a|%a", "Mon|Tue|Wed|Thu|Fri|Sat|Sun"}, 1034 {"Day of the week: %w, Day of the year: %j", "Day of the week: 4, Day of the year: 091"}, 1035 } 1036 for _, dt := range datetimeFormatTests { 1037 t.Run(dt.match, func(t *testing.T) { 1038 info := logger.Info{ 1039 Config: map[string]string{ 1040 datetimeFormatKey: dt.format, 1041 }, 1042 } 1043 multilinePattern, err := parseMultilineOptions(info) 1044 assert.Nil(t, err, "Received unexpected error") 1045 assert.True(t, multilinePattern.MatchString(dt.match), "No multiline pattern match found") 1046 }) 1047 } 1048 } 1049 1050 func TestValidateLogOptionsDatetimeFormatAndMultilinePattern(t *testing.T) { 1051 cfg := map[string]string{ 1052 multilinePatternKey: "^xxxx", 1053 datetimeFormatKey: "%Y-%m-%d", 1054 logGroupKey: groupName, 1055 } 1056 conflictingLogOptionsError := "you cannot configure log opt 'awslogs-datetime-format' and 'awslogs-multiline-pattern' at the same time" 1057 1058 err := ValidateLogOpt(cfg) 1059 assert.NotNil(t, err, "Expected an error") 1060 assert.Equal(t, err.Error(), conflictingLogOptionsError, "Received invalid error") 1061 } 1062 1063 func TestCreateTagSuccess(t *testing.T) { 1064 mockClient := newMockClient() 1065 info := logger.Info{ 1066 ContainerName: "/test-container", 1067 ContainerID: "container-abcdefghijklmnopqrstuvwxyz01234567890", 1068 Config: map[string]string{"tag": "{{.Name}}/{{.FullID}}"}, 1069 } 1070 logStreamName, e := loggerutils.ParseLogTag(info, loggerutils.DefaultTemplate) 1071 if e != nil { 1072 t.Errorf("Error generating tag: %q", e) 1073 } 1074 stream := &logStream{ 1075 client: mockClient, 1076 logGroupName: groupName, 1077 logStreamName: logStreamName, 1078 } 1079 mockClient.createLogStreamResult <- &createLogStreamResult{} 1080 1081 err := stream.create() 1082 1083 if err != nil { 1084 t.Errorf("Received unexpected err: %v\n", err) 1085 } 1086 argument := <-mockClient.createLogStreamArgument 1087 1088 if *argument.LogStreamName != "test-container/container-abcdefghijklmnopqrstuvwxyz01234567890" { 1089 t.Errorf("Expected LogStreamName to be %s", "test-container/container-abcdefghijklmnopqrstuvwxyz01234567890") 1090 } 1091 } 1092 1093 func TestIsSizedLogger(t *testing.T) { 1094 awslogs := &logStream{} 1095 assert.Implements(t, (*logger.SizedLogger)(nil), awslogs, "awslogs should implement SizedLogger") 1096 } 1097 1098 func BenchmarkUnwrapEvents(b *testing.B) { 1099 events := make([]wrappedEvent, maximumLogEventsPerPut) 1100 for i := 0; i < maximumLogEventsPerPut; i++ { 1101 mes := strings.Repeat("0", maximumBytesPerEvent) 1102 events[i].inputLogEvent = &cloudwatchlogs.InputLogEvent{ 1103 Message: &mes, 1104 } 1105 } 1106 1107 as := assert.New(b) 1108 b.ResetTimer() 1109 for i := 0; i < b.N; i++ { 1110 res := unwrapEvents(events) 1111 as.Len(res, maximumLogEventsPerPut) 1112 } 1113 } 1114 1115 func TestNewAWSLogsClientCredentialEndpointDetect(t *testing.T) { 1116 // required for the cloudwatchlogs client 1117 os.Setenv("AWS_REGION", "us-west-2") 1118 defer os.Unsetenv("AWS_REGION") 1119 1120 credsResp := `{ 1121 "AccessKeyId" : "test-access-key-id", 1122 "SecretAccessKey": "test-secret-access-key" 1123 }` 1124 1125 expectedAccessKeyID := "test-access-key-id" 1126 expectedSecretAccessKey := "test-secret-access-key" 1127 1128 testServer := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { 1129 w.Header().Set("Content-Type", "application/json") 1130 fmt.Fprintln(w, credsResp) 1131 })) 1132 defer testServer.Close() 1133 1134 // set the SDKEndpoint in the driver 1135 newSDKEndpoint = testServer.URL 1136 1137 info := logger.Info{ 1138 Config: map[string]string{}, 1139 } 1140 1141 info.Config["awslogs-credentials-endpoint"] = "/creds" 1142 1143 c, err := newAWSLogsClient(info) 1144 assert.NoError(t, err) 1145 1146 client := c.(*cloudwatchlogs.CloudWatchLogs) 1147 1148 creds, err := client.Config.Credentials.Get() 1149 assert.NoError(t, err) 1150 1151 assert.Equal(t, expectedAccessKeyID, creds.AccessKeyID) 1152 assert.Equal(t, expectedSecretAccessKey, creds.SecretAccessKey) 1153 } 1154 1155 func TestNewAWSLogsClientCredentialEnvironmentVariable(t *testing.T) { 1156 // required for the cloudwatchlogs client 1157 os.Setenv("AWS_REGION", "us-west-2") 1158 defer os.Unsetenv("AWS_REGION") 1159 1160 expectedAccessKeyID := "test-access-key-id" 1161 expectedSecretAccessKey := "test-secret-access-key" 1162 1163 os.Setenv("AWS_ACCESS_KEY_ID", expectedAccessKeyID) 1164 defer os.Unsetenv("AWS_ACCESS_KEY_ID") 1165 1166 os.Setenv("AWS_SECRET_ACCESS_KEY", expectedSecretAccessKey) 1167 defer os.Unsetenv("AWS_SECRET_ACCESS_KEY") 1168 1169 info := logger.Info{ 1170 Config: map[string]string{}, 1171 } 1172 1173 c, err := newAWSLogsClient(info) 1174 assert.NoError(t, err) 1175 1176 client := c.(*cloudwatchlogs.CloudWatchLogs) 1177 1178 creds, err := client.Config.Credentials.Get() 1179 assert.NoError(t, err) 1180 1181 assert.Equal(t, expectedAccessKeyID, creds.AccessKeyID) 1182 assert.Equal(t, expectedSecretAccessKey, creds.SecretAccessKey) 1183 1184 } 1185 1186 func TestNewAWSLogsClientCredentialSharedFile(t *testing.T) { 1187 // required for the cloudwatchlogs client 1188 os.Setenv("AWS_REGION", "us-west-2") 1189 defer os.Unsetenv("AWS_REGION") 1190 1191 expectedAccessKeyID := "test-access-key-id" 1192 expectedSecretAccessKey := "test-secret-access-key" 1193 1194 contentStr := ` 1195 [default] 1196 aws_access_key_id = "test-access-key-id" 1197 aws_secret_access_key = "test-secret-access-key" 1198 ` 1199 content := []byte(contentStr) 1200 1201 tmpfile, err := ioutil.TempFile("", "example") 1202 defer os.Remove(tmpfile.Name()) // clean up 1203 assert.NoError(t, err) 1204 1205 _, err = tmpfile.Write(content) 1206 assert.NoError(t, err) 1207 1208 err = tmpfile.Close() 1209 assert.NoError(t, err) 1210 1211 os.Unsetenv("AWS_ACCESS_KEY_ID") 1212 os.Unsetenv("AWS_SECRET_ACCESS_KEY") 1213 1214 os.Setenv("AWS_SHARED_CREDENTIALS_FILE", tmpfile.Name()) 1215 defer os.Unsetenv("AWS_SHARED_CREDENTIALS_FILE") 1216 1217 info := logger.Info{ 1218 Config: map[string]string{}, 1219 } 1220 1221 c, err := newAWSLogsClient(info) 1222 assert.NoError(t, err) 1223 1224 client := c.(*cloudwatchlogs.CloudWatchLogs) 1225 1226 creds, err := client.Config.Credentials.Get() 1227 assert.NoError(t, err) 1228 1229 assert.Equal(t, expectedAccessKeyID, creds.AccessKeyID) 1230 assert.Equal(t, expectedSecretAccessKey, creds.SecretAccessKey) 1231 }