github.com/docker/engine@v22.0.0-20211208180946-d456264580cf+incompatible/daemon/logger/awslogs/cloudwatchlogs_test.go (about) 1 package awslogs // import "github.com/docker/docker/daemon/logger/awslogs" 2 3 import ( 4 "errors" 5 "fmt" 6 "net/http" 7 "net/http/httptest" 8 "os" 9 "reflect" 10 "regexp" 11 "runtime" 12 "strconv" 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 "gotest.tools/v3/assert" 25 is "gotest.tools/v3/assert/cmp" 26 ) 27 28 const ( 29 groupName = "groupName" 30 streamName = "streamName" 31 sequenceToken = "sequenceToken" 32 nextSequenceToken = "nextSequenceToken" 33 logline = "this is a log line\r" 34 multilineLogline = "2017-01-01 01:01:44 This is a multiline log entry\r" 35 ) 36 37 // Generates i multi-line events each with j lines 38 func (l *logStream) logGenerator(lineCount int, multilineCount int) { 39 for i := 0; i < multilineCount; i++ { 40 l.Log(&logger.Message{ 41 Line: []byte(multilineLogline), 42 Timestamp: time.Time{}, 43 }) 44 for j := 0; j < lineCount; j++ { 45 l.Log(&logger.Message{ 46 Line: []byte(logline), 47 Timestamp: time.Time{}, 48 }) 49 } 50 } 51 } 52 53 func testEventBatch(events []wrappedEvent) *eventBatch { 54 batch := newEventBatch() 55 for _, event := range events { 56 eventlen := len([]byte(*event.inputLogEvent.Message)) 57 batch.add(event, eventlen) 58 } 59 return batch 60 } 61 62 func TestNewStreamConfig(t *testing.T) { 63 tests := []struct { 64 logStreamName string 65 logGroupName string 66 logCreateGroup string 67 logCreateStream string 68 logNonBlocking string 69 forceFlushInterval string 70 maxBufferedEvents string 71 datetimeFormat string 72 multilinePattern string 73 shouldErr bool 74 testName string 75 }{ 76 {"", groupName, "", "", "", "", "", "", "", false, "defaults"}, 77 {"", groupName, "invalid create group", "", "", "", "", "", "", true, "invalid create group"}, 78 {"", groupName, "", "", "", "invalid flush interval", "", "", "", true, "invalid flush interval"}, 79 {"", groupName, "", "", "", "", "invalid max buffered events", "", "", true, "invalid max buffered events"}, 80 {"", groupName, "", "", "", "", "", "", "n{1001}", true, "invalid multiline pattern"}, 81 {"", groupName, "", "", "", "15", "", "", "", false, "flush interval at 15"}, 82 {"", groupName, "", "", "", "", "1024", "", "", false, "max buffered events at 1024"}, 83 } 84 85 for _, tc := range tests { 86 t.Run(tc.testName, func(t *testing.T) { 87 cfg := map[string]string{ 88 logGroupKey: tc.logGroupName, 89 logCreateGroupKey: tc.logCreateGroup, 90 "mode": tc.logNonBlocking, 91 forceFlushIntervalKey: tc.forceFlushInterval, 92 maxBufferedEventsKey: tc.maxBufferedEvents, 93 logStreamKey: tc.logStreamName, 94 logCreateStreamKey: tc.logCreateStream, 95 datetimeFormatKey: tc.datetimeFormat, 96 multilinePatternKey: tc.multilinePattern, 97 } 98 99 info := logger.Info{ 100 Config: cfg, 101 } 102 logStreamConfig, err := newStreamConfig(info) 103 if tc.shouldErr { 104 assert.Check(t, err != nil, "Expected an error") 105 } else { 106 assert.Check(t, err == nil, "Unexpected error") 107 assert.Check(t, logStreamConfig.logGroupName == tc.logGroupName, "Unexpected logGroupName") 108 if tc.forceFlushInterval != "" { 109 forceFlushIntervalAsInt, _ := strconv.Atoi(info.Config[forceFlushIntervalKey]) 110 assert.Check(t, logStreamConfig.forceFlushInterval == time.Duration(forceFlushIntervalAsInt)*time.Second, "Unexpected forceFlushInterval") 111 } 112 if tc.maxBufferedEvents != "" { 113 maxBufferedEvents, _ := strconv.Atoi(info.Config[maxBufferedEventsKey]) 114 assert.Check(t, logStreamConfig.maxBufferedEvents == maxBufferedEvents, "Unexpected maxBufferedEvents") 115 } 116 } 117 }) 118 } 119 } 120 121 func TestNewAWSLogsClientUserAgentHandler(t *testing.T) { 122 info := logger.Info{ 123 Config: map[string]string{ 124 regionKey: "us-east-1", 125 }, 126 } 127 128 client, err := newAWSLogsClient(info) 129 assert.NilError(t, err) 130 131 realClient, ok := client.(*cloudwatchlogs.CloudWatchLogs) 132 assert.Check(t, ok, "Could not cast client to cloudwatchlogs.CloudWatchLogs") 133 134 buildHandlerList := realClient.Handlers.Build 135 request := &request.Request{ 136 HTTPRequest: &http.Request{ 137 Header: http.Header{}, 138 }, 139 } 140 buildHandlerList.Run(request) 141 expectedUserAgentString := fmt.Sprintf("Docker %s (%s) %s/%s (%s; %s; %s)", 142 dockerversion.Version, runtime.GOOS, aws.SDKName, aws.SDKVersion, runtime.Version(), runtime.GOOS, runtime.GOARCH) 143 userAgent := request.HTTPRequest.Header.Get("User-Agent") 144 if userAgent != expectedUserAgentString { 145 t.Errorf("Wrong User-Agent string, expected \"%s\" but was \"%s\"", 146 expectedUserAgentString, userAgent) 147 } 148 } 149 150 func TestNewAWSLogsClientLogFormatHeaderHandler(t *testing.T) { 151 tests := []struct { 152 logFormat string 153 expectedHeaderValue string 154 }{ 155 { 156 logFormat: jsonEmfLogFormat, 157 expectedHeaderValue: "json/emf", 158 }, 159 { 160 logFormat: "", 161 expectedHeaderValue: "", 162 }, 163 } 164 for _, tc := range tests { 165 t.Run(tc.logFormat, func(t *testing.T) { 166 info := logger.Info{ 167 Config: map[string]string{ 168 regionKey: "us-east-1", 169 logFormatKey: tc.logFormat, 170 }, 171 } 172 173 client, err := newAWSLogsClient(info) 174 assert.NilError(t, err) 175 176 realClient, ok := client.(*cloudwatchlogs.CloudWatchLogs) 177 assert.Check(t, ok, "Could not cast client to cloudwatchlogs.CloudWatchLogs") 178 179 buildHandlerList := realClient.Handlers.Build 180 request := &request.Request{ 181 HTTPRequest: &http.Request{ 182 Header: http.Header{}, 183 }, 184 } 185 buildHandlerList.Run(request) 186 logFormatHeaderVal := request.HTTPRequest.Header.Get("x-amzn-logs-format") 187 assert.Equal(t, tc.expectedHeaderValue, logFormatHeaderVal) 188 }) 189 } 190 } 191 192 func TestNewAWSLogsClientAWSLogsEndpoint(t *testing.T) { 193 endpoint := "mock-endpoint" 194 info := logger.Info{ 195 Config: map[string]string{ 196 regionKey: "us-east-1", 197 endpointKey: endpoint, 198 }, 199 } 200 201 client, err := newAWSLogsClient(info) 202 assert.NilError(t, err) 203 204 realClient, ok := client.(*cloudwatchlogs.CloudWatchLogs) 205 assert.Check(t, ok, "Could not cast client to cloudwatchlogs.CloudWatchLogs") 206 207 endpointWithScheme := realClient.Endpoint 208 expectedEndpointWithScheme := "https://" + endpoint 209 assert.Equal(t, endpointWithScheme, expectedEndpointWithScheme, "Wrong endpoint") 210 } 211 212 func TestNewAWSLogsClientRegionDetect(t *testing.T) { 213 info := logger.Info{ 214 Config: map[string]string{}, 215 } 216 217 mockMetadata := newMockMetadataClient() 218 newRegionFinder = func() (regionFinder, error) { 219 return mockMetadata, nil 220 } 221 mockMetadata.regionResult <- ®ionResult{ 222 successResult: "us-east-1", 223 } 224 225 _, err := newAWSLogsClient(info) 226 assert.NilError(t, err) 227 } 228 229 func TestCreateSuccess(t *testing.T) { 230 mockClient := newMockClient() 231 stream := &logStream{ 232 client: mockClient, 233 logGroupName: groupName, 234 logStreamName: streamName, 235 logCreateStream: true, 236 } 237 mockClient.createLogStreamResult <- &createLogStreamResult{} 238 239 err := stream.create() 240 241 if err != nil { 242 t.Errorf("Received unexpected err: %v\n", err) 243 } 244 argument := <-mockClient.createLogStreamArgument 245 if argument.LogGroupName == nil { 246 t.Fatal("Expected non-nil LogGroupName") 247 } 248 if *argument.LogGroupName != groupName { 249 t.Errorf("Expected LogGroupName to be %s", groupName) 250 } 251 if argument.LogStreamName == nil { 252 t.Fatal("Expected non-nil LogStreamName") 253 } 254 if *argument.LogStreamName != streamName { 255 t.Errorf("Expected LogStreamName to be %s", streamName) 256 } 257 } 258 259 func TestCreateStreamSkipped(t *testing.T) { 260 stream := &logStream{ 261 logGroupName: groupName, 262 logStreamName: streamName, 263 logCreateStream: false, 264 } 265 266 err := stream.create() 267 268 if err != nil { 269 t.Errorf("Received unexpected err: %v\n", err) 270 } 271 } 272 273 func TestCreateLogGroupSuccess(t *testing.T) { 274 mockClient := newMockClient() 275 stream := &logStream{ 276 client: mockClient, 277 logGroupName: groupName, 278 logStreamName: streamName, 279 logCreateGroup: true, 280 logCreateStream: true, 281 } 282 mockClient.createLogGroupResult <- &createLogGroupResult{} 283 mockClient.createLogStreamResult <- &createLogStreamResult{} 284 285 err := stream.create() 286 287 if err != nil { 288 t.Errorf("Received unexpected err: %v\n", err) 289 } 290 argument := <-mockClient.createLogStreamArgument 291 if argument.LogGroupName == nil { 292 t.Fatal("Expected non-nil LogGroupName") 293 } 294 if *argument.LogGroupName != groupName { 295 t.Errorf("Expected LogGroupName to be %s", groupName) 296 } 297 if argument.LogStreamName == nil { 298 t.Fatal("Expected non-nil LogStreamName") 299 } 300 if *argument.LogStreamName != streamName { 301 t.Errorf("Expected LogStreamName to be %s", streamName) 302 } 303 } 304 305 func TestCreateError(t *testing.T) { 306 mockClient := newMockClient() 307 stream := &logStream{ 308 client: mockClient, 309 logCreateStream: true, 310 } 311 mockClient.createLogStreamResult <- &createLogStreamResult{ 312 errorResult: errors.New("Error"), 313 } 314 315 err := stream.create() 316 317 if err == nil { 318 t.Fatal("Expected non-nil err") 319 } 320 } 321 322 func TestCreateAlreadyExists(t *testing.T) { 323 mockClient := newMockClient() 324 stream := &logStream{ 325 client: mockClient, 326 logCreateStream: true, 327 } 328 mockClient.createLogStreamResult <- &createLogStreamResult{ 329 errorResult: awserr.New(resourceAlreadyExistsCode, "", nil), 330 } 331 332 err := stream.create() 333 334 assert.NilError(t, err) 335 } 336 337 func TestLogClosed(t *testing.T) { 338 mockClient := newMockClient() 339 stream := &logStream{ 340 client: mockClient, 341 closed: true, 342 } 343 err := stream.Log(&logger.Message{}) 344 if err == nil { 345 t.Fatal("Expected non-nil error") 346 } 347 } 348 349 // TestLogBlocking tests that the Log method blocks appropriately when 350 // non-blocking behavior is not enabled. Blocking is achieved through an 351 // internal channel that must be drained for Log to return. 352 func TestLogBlocking(t *testing.T) { 353 mockClient := newMockClient() 354 stream := &logStream{ 355 client: mockClient, 356 messages: make(chan *logger.Message), 357 } 358 359 errorCh := make(chan error, 1) 360 started := make(chan bool) 361 go func() { 362 started <- true 363 err := stream.Log(&logger.Message{}) 364 errorCh <- err 365 }() 366 // block until the goroutine above has started 367 <-started 368 select { 369 case err := <-errorCh: 370 t.Fatal("Expected stream.Log to block: ", err) 371 default: 372 } 373 // assuming it is blocked, we can now try to drain the internal channel and 374 // unblock it 375 select { 376 case <-time.After(10 * time.Millisecond): 377 // if we're unable to drain the channel within 10ms, something seems broken 378 t.Fatal("Expected to be able to read from stream.messages but was unable to") 379 case <-stream.messages: 380 } 381 select { 382 case err := <-errorCh: 383 assert.NilError(t, err) 384 385 case <-time.After(30 * time.Second): 386 t.Fatal("timed out waiting for read") 387 } 388 } 389 390 func TestLogNonBlockingBufferEmpty(t *testing.T) { 391 mockClient := newMockClient() 392 stream := &logStream{ 393 client: mockClient, 394 messages: make(chan *logger.Message, 1), 395 logNonBlocking: true, 396 } 397 err := stream.Log(&logger.Message{}) 398 assert.NilError(t, err) 399 } 400 401 func TestLogNonBlockingBufferFull(t *testing.T) { 402 mockClient := newMockClient() 403 stream := &logStream{ 404 client: mockClient, 405 messages: make(chan *logger.Message, 1), 406 logNonBlocking: true, 407 } 408 stream.messages <- &logger.Message{} 409 errorCh := make(chan error, 1) 410 started := make(chan bool) 411 go func() { 412 started <- true 413 err := stream.Log(&logger.Message{}) 414 errorCh <- err 415 }() 416 <-started 417 select { 418 case err := <-errorCh: 419 if err == nil { 420 t.Fatal("Expected non-nil error") 421 } 422 case <-time.After(30 * time.Second): 423 t.Fatal("Expected Log call to not block") 424 } 425 } 426 func TestPublishBatchSuccess(t *testing.T) { 427 mockClient := newMockClient() 428 stream := &logStream{ 429 client: mockClient, 430 logGroupName: groupName, 431 logStreamName: streamName, 432 sequenceToken: aws.String(sequenceToken), 433 } 434 mockClient.putLogEventsResult <- &putLogEventsResult{ 435 successResult: &cloudwatchlogs.PutLogEventsOutput{ 436 NextSequenceToken: aws.String(nextSequenceToken), 437 }, 438 } 439 events := []wrappedEvent{ 440 { 441 inputLogEvent: &cloudwatchlogs.InputLogEvent{ 442 Message: aws.String(logline), 443 }, 444 }, 445 } 446 447 stream.publishBatch(testEventBatch(events)) 448 if stream.sequenceToken == nil { 449 t.Fatal("Expected non-nil sequenceToken") 450 } 451 if *stream.sequenceToken != nextSequenceToken { 452 t.Errorf("Expected sequenceToken to be %s, but was %s", nextSequenceToken, *stream.sequenceToken) 453 } 454 argument := <-mockClient.putLogEventsArgument 455 if argument == nil { 456 t.Fatal("Expected non-nil PutLogEventsInput") 457 } 458 if argument.SequenceToken == nil { 459 t.Fatal("Expected non-nil PutLogEventsInput.SequenceToken") 460 } 461 if *argument.SequenceToken != sequenceToken { 462 t.Errorf("Expected PutLogEventsInput.SequenceToken to be %s, but was %s", sequenceToken, *argument.SequenceToken) 463 } 464 if len(argument.LogEvents) != 1 { 465 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 466 } 467 if argument.LogEvents[0] != events[0].inputLogEvent { 468 t.Error("Expected event to equal input") 469 } 470 } 471 472 func TestPublishBatchError(t *testing.T) { 473 mockClient := newMockClient() 474 stream := &logStream{ 475 client: mockClient, 476 logGroupName: groupName, 477 logStreamName: streamName, 478 sequenceToken: aws.String(sequenceToken), 479 } 480 mockClient.putLogEventsResult <- &putLogEventsResult{ 481 errorResult: errors.New("Error"), 482 } 483 484 events := []wrappedEvent{ 485 { 486 inputLogEvent: &cloudwatchlogs.InputLogEvent{ 487 Message: aws.String(logline), 488 }, 489 }, 490 } 491 492 stream.publishBatch(testEventBatch(events)) 493 if stream.sequenceToken == nil { 494 t.Fatal("Expected non-nil sequenceToken") 495 } 496 if *stream.sequenceToken != sequenceToken { 497 t.Errorf("Expected sequenceToken to be %s, but was %s", sequenceToken, *stream.sequenceToken) 498 } 499 } 500 501 func TestPublishBatchInvalidSeqSuccess(t *testing.T) { 502 mockClient := newMockClientBuffered(2) 503 stream := &logStream{ 504 client: mockClient, 505 logGroupName: groupName, 506 logStreamName: streamName, 507 sequenceToken: aws.String(sequenceToken), 508 } 509 mockClient.putLogEventsResult <- &putLogEventsResult{ 510 errorResult: awserr.New(invalidSequenceTokenCode, "use token token", nil), 511 } 512 mockClient.putLogEventsResult <- &putLogEventsResult{ 513 successResult: &cloudwatchlogs.PutLogEventsOutput{ 514 NextSequenceToken: aws.String(nextSequenceToken), 515 }, 516 } 517 518 events := []wrappedEvent{ 519 { 520 inputLogEvent: &cloudwatchlogs.InputLogEvent{ 521 Message: aws.String(logline), 522 }, 523 }, 524 } 525 526 stream.publishBatch(testEventBatch(events)) 527 if stream.sequenceToken == nil { 528 t.Fatal("Expected non-nil sequenceToken") 529 } 530 if *stream.sequenceToken != nextSequenceToken { 531 t.Errorf("Expected sequenceToken to be %s, but was %s", nextSequenceToken, *stream.sequenceToken) 532 } 533 534 argument := <-mockClient.putLogEventsArgument 535 if argument == nil { 536 t.Fatal("Expected non-nil PutLogEventsInput") 537 } 538 if argument.SequenceToken == nil { 539 t.Fatal("Expected non-nil PutLogEventsInput.SequenceToken") 540 } 541 if *argument.SequenceToken != sequenceToken { 542 t.Errorf("Expected PutLogEventsInput.SequenceToken to be %s, but was %s", sequenceToken, *argument.SequenceToken) 543 } 544 if len(argument.LogEvents) != 1 { 545 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 546 } 547 if argument.LogEvents[0] != events[0].inputLogEvent { 548 t.Error("Expected event to equal input") 549 } 550 551 argument = <-mockClient.putLogEventsArgument 552 if argument == nil { 553 t.Fatal("Expected non-nil PutLogEventsInput") 554 } 555 if argument.SequenceToken == nil { 556 t.Fatal("Expected non-nil PutLogEventsInput.SequenceToken") 557 } 558 if *argument.SequenceToken != "token" { 559 t.Errorf("Expected PutLogEventsInput.SequenceToken to be %s, but was %s", "token", *argument.SequenceToken) 560 } 561 if len(argument.LogEvents) != 1 { 562 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 563 } 564 if argument.LogEvents[0] != events[0].inputLogEvent { 565 t.Error("Expected event to equal input") 566 } 567 } 568 569 func TestPublishBatchAlreadyAccepted(t *testing.T) { 570 mockClient := newMockClient() 571 stream := &logStream{ 572 client: mockClient, 573 logGroupName: groupName, 574 logStreamName: streamName, 575 sequenceToken: aws.String(sequenceToken), 576 } 577 mockClient.putLogEventsResult <- &putLogEventsResult{ 578 errorResult: awserr.New(dataAlreadyAcceptedCode, "use token token", nil), 579 } 580 581 events := []wrappedEvent{ 582 { 583 inputLogEvent: &cloudwatchlogs.InputLogEvent{ 584 Message: aws.String(logline), 585 }, 586 }, 587 } 588 589 stream.publishBatch(testEventBatch(events)) 590 if stream.sequenceToken == nil { 591 t.Fatal("Expected non-nil sequenceToken") 592 } 593 if *stream.sequenceToken != "token" { 594 t.Errorf("Expected sequenceToken to be %s, but was %s", "token", *stream.sequenceToken) 595 } 596 597 argument := <-mockClient.putLogEventsArgument 598 if argument == nil { 599 t.Fatal("Expected non-nil PutLogEventsInput") 600 } 601 if argument.SequenceToken == nil { 602 t.Fatal("Expected non-nil PutLogEventsInput.SequenceToken") 603 } 604 if *argument.SequenceToken != sequenceToken { 605 t.Errorf("Expected PutLogEventsInput.SequenceToken to be %s, but was %s", sequenceToken, *argument.SequenceToken) 606 } 607 if len(argument.LogEvents) != 1 { 608 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 609 } 610 if argument.LogEvents[0] != events[0].inputLogEvent { 611 t.Error("Expected event to equal input") 612 } 613 } 614 615 func TestCollectBatchSimple(t *testing.T) { 616 mockClient := newMockClient() 617 stream := &logStream{ 618 client: mockClient, 619 logGroupName: groupName, 620 logStreamName: streamName, 621 sequenceToken: aws.String(sequenceToken), 622 messages: make(chan *logger.Message), 623 } 624 mockClient.putLogEventsResult <- &putLogEventsResult{ 625 successResult: &cloudwatchlogs.PutLogEventsOutput{ 626 NextSequenceToken: aws.String(nextSequenceToken), 627 }, 628 } 629 ticks := make(chan time.Time) 630 newTicker = func(_ time.Duration) *time.Ticker { 631 return &time.Ticker{ 632 C: ticks, 633 } 634 } 635 d := make(chan bool) 636 close(d) 637 go stream.collectBatch(d) 638 639 stream.Log(&logger.Message{ 640 Line: []byte(logline), 641 Timestamp: time.Time{}, 642 }) 643 644 ticks <- time.Time{} 645 stream.Close() 646 647 argument := <-mockClient.putLogEventsArgument 648 if argument == nil { 649 t.Fatal("Expected non-nil PutLogEventsInput") 650 } 651 if len(argument.LogEvents) != 1 { 652 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 653 } 654 if *argument.LogEvents[0].Message != logline { 655 t.Errorf("Expected message to be %s but was %s", logline, *argument.LogEvents[0].Message) 656 } 657 } 658 659 func TestCollectBatchTicker(t *testing.T) { 660 mockClient := newMockClient() 661 stream := &logStream{ 662 client: mockClient, 663 logGroupName: groupName, 664 logStreamName: streamName, 665 sequenceToken: aws.String(sequenceToken), 666 messages: make(chan *logger.Message), 667 } 668 mockClient.putLogEventsResult <- &putLogEventsResult{ 669 successResult: &cloudwatchlogs.PutLogEventsOutput{ 670 NextSequenceToken: aws.String(nextSequenceToken), 671 }, 672 } 673 ticks := make(chan time.Time) 674 newTicker = func(_ time.Duration) *time.Ticker { 675 return &time.Ticker{ 676 C: ticks, 677 } 678 } 679 680 d := make(chan bool) 681 close(d) 682 go stream.collectBatch(d) 683 684 stream.Log(&logger.Message{ 685 Line: []byte(logline + " 1"), 686 Timestamp: time.Time{}, 687 }) 688 stream.Log(&logger.Message{ 689 Line: []byte(logline + " 2"), 690 Timestamp: time.Time{}, 691 }) 692 693 ticks <- time.Time{} 694 695 // Verify first batch 696 argument := <-mockClient.putLogEventsArgument 697 if argument == nil { 698 t.Fatal("Expected non-nil PutLogEventsInput") 699 } 700 if len(argument.LogEvents) != 2 { 701 t.Errorf("Expected LogEvents to contain 2 elements, but contains %d", len(argument.LogEvents)) 702 } 703 if *argument.LogEvents[0].Message != logline+" 1" { 704 t.Errorf("Expected message to be %s but was %s", logline+" 1", *argument.LogEvents[0].Message) 705 } 706 if *argument.LogEvents[1].Message != logline+" 2" { 707 t.Errorf("Expected message to be %s but was %s", logline+" 2", *argument.LogEvents[0].Message) 708 } 709 710 stream.Log(&logger.Message{ 711 Line: []byte(logline + " 3"), 712 Timestamp: time.Time{}, 713 }) 714 715 ticks <- time.Time{} 716 argument = <-mockClient.putLogEventsArgument 717 if argument == nil { 718 t.Fatal("Expected non-nil PutLogEventsInput") 719 } 720 if len(argument.LogEvents) != 1 { 721 t.Errorf("Expected LogEvents to contain 1 elements, but contains %d", len(argument.LogEvents)) 722 } 723 if *argument.LogEvents[0].Message != logline+" 3" { 724 t.Errorf("Expected message to be %s but was %s", logline+" 3", *argument.LogEvents[0].Message) 725 } 726 727 stream.Close() 728 729 } 730 731 func TestCollectBatchMultilinePattern(t *testing.T) { 732 mockClient := newMockClient() 733 multilinePattern := regexp.MustCompile("xxxx") 734 stream := &logStream{ 735 client: mockClient, 736 logGroupName: groupName, 737 logStreamName: streamName, 738 multilinePattern: multilinePattern, 739 sequenceToken: aws.String(sequenceToken), 740 messages: make(chan *logger.Message), 741 } 742 mockClient.putLogEventsResult <- &putLogEventsResult{ 743 successResult: &cloudwatchlogs.PutLogEventsOutput{ 744 NextSequenceToken: aws.String(nextSequenceToken), 745 }, 746 } 747 ticks := make(chan time.Time) 748 newTicker = func(_ time.Duration) *time.Ticker { 749 return &time.Ticker{ 750 C: ticks, 751 } 752 } 753 754 d := make(chan bool) 755 close(d) 756 go stream.collectBatch(d) 757 758 stream.Log(&logger.Message{ 759 Line: []byte(logline), 760 Timestamp: time.Now(), 761 }) 762 stream.Log(&logger.Message{ 763 Line: []byte(logline), 764 Timestamp: time.Now(), 765 }) 766 stream.Log(&logger.Message{ 767 Line: []byte("xxxx " + logline), 768 Timestamp: time.Now(), 769 }) 770 771 ticks <- time.Now() 772 773 // Verify single multiline event 774 argument := <-mockClient.putLogEventsArgument 775 assert.Check(t, argument != nil, "Expected non-nil PutLogEventsInput") 776 assert.Check(t, is.Equal(1, len(argument.LogEvents)), "Expected single multiline event") 777 assert.Check(t, is.Equal(logline+"\n"+logline+"\n", *argument.LogEvents[0].Message), "Received incorrect multiline message") 778 779 stream.Close() 780 781 // Verify single event 782 argument = <-mockClient.putLogEventsArgument 783 assert.Check(t, argument != nil, "Expected non-nil PutLogEventsInput") 784 assert.Check(t, is.Equal(1, len(argument.LogEvents)), "Expected single multiline event") 785 assert.Check(t, is.Equal("xxxx "+logline+"\n", *argument.LogEvents[0].Message), "Received incorrect multiline message") 786 } 787 788 func BenchmarkCollectBatch(b *testing.B) { 789 for i := 0; i < b.N; i++ { 790 mockClient := newMockClient() 791 stream := &logStream{ 792 client: mockClient, 793 logGroupName: groupName, 794 logStreamName: streamName, 795 sequenceToken: aws.String(sequenceToken), 796 messages: make(chan *logger.Message), 797 } 798 mockClient.putLogEventsResult <- &putLogEventsResult{ 799 successResult: &cloudwatchlogs.PutLogEventsOutput{ 800 NextSequenceToken: aws.String(nextSequenceToken), 801 }, 802 } 803 ticks := make(chan time.Time) 804 newTicker = func(_ time.Duration) *time.Ticker { 805 return &time.Ticker{ 806 C: ticks, 807 } 808 } 809 810 d := make(chan bool) 811 close(d) 812 go stream.collectBatch(d) 813 stream.logGenerator(10, 100) 814 ticks <- time.Time{} 815 stream.Close() 816 } 817 } 818 819 func BenchmarkCollectBatchMultilinePattern(b *testing.B) { 820 for i := 0; i < b.N; i++ { 821 mockClient := newMockClient() 822 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]`) 823 stream := &logStream{ 824 client: mockClient, 825 logGroupName: groupName, 826 logStreamName: streamName, 827 multilinePattern: multilinePattern, 828 sequenceToken: aws.String(sequenceToken), 829 messages: make(chan *logger.Message), 830 } 831 mockClient.putLogEventsResult <- &putLogEventsResult{ 832 successResult: &cloudwatchlogs.PutLogEventsOutput{ 833 NextSequenceToken: aws.String(nextSequenceToken), 834 }, 835 } 836 ticks := make(chan time.Time) 837 newTicker = func(_ time.Duration) *time.Ticker { 838 return &time.Ticker{ 839 C: ticks, 840 } 841 } 842 d := make(chan bool) 843 close(d) 844 go stream.collectBatch(d) 845 stream.logGenerator(10, 100) 846 ticks <- time.Time{} 847 stream.Close() 848 } 849 } 850 851 func TestCollectBatchMultilinePatternMaxEventAge(t *testing.T) { 852 mockClient := newMockClient() 853 multilinePattern := regexp.MustCompile("xxxx") 854 stream := &logStream{ 855 client: mockClient, 856 logGroupName: groupName, 857 logStreamName: streamName, 858 multilinePattern: multilinePattern, 859 sequenceToken: aws.String(sequenceToken), 860 messages: make(chan *logger.Message), 861 } 862 mockClient.putLogEventsResult <- &putLogEventsResult{ 863 successResult: &cloudwatchlogs.PutLogEventsOutput{ 864 NextSequenceToken: aws.String(nextSequenceToken), 865 }, 866 } 867 ticks := make(chan time.Time) 868 newTicker = func(_ time.Duration) *time.Ticker { 869 return &time.Ticker{ 870 C: ticks, 871 } 872 } 873 874 d := make(chan bool) 875 close(d) 876 go stream.collectBatch(d) 877 878 stream.Log(&logger.Message{ 879 Line: []byte(logline), 880 Timestamp: time.Now(), 881 }) 882 883 // Log an event 1 second later 884 stream.Log(&logger.Message{ 885 Line: []byte(logline), 886 Timestamp: time.Now().Add(time.Second), 887 }) 888 889 // Fire ticker defaultForceFlushInterval seconds later 890 ticks <- time.Now().Add(defaultForceFlushInterval + time.Second) 891 892 // Verify single multiline event is flushed after maximum event buffer age (defaultForceFlushInterval) 893 argument := <-mockClient.putLogEventsArgument 894 assert.Check(t, argument != nil, "Expected non-nil PutLogEventsInput") 895 assert.Check(t, is.Equal(1, len(argument.LogEvents)), "Expected single multiline event") 896 assert.Check(t, is.Equal(logline+"\n"+logline+"\n", *argument.LogEvents[0].Message), "Received incorrect multiline message") 897 898 // Log an event 1 second later 899 stream.Log(&logger.Message{ 900 Line: []byte(logline), 901 Timestamp: time.Now().Add(time.Second), 902 }) 903 904 // Fire ticker another defaultForceFlushInterval seconds later 905 ticks <- time.Now().Add(2*defaultForceFlushInterval + time.Second) 906 907 // Verify the event buffer is truly flushed - we should only receive a single event 908 argument = <-mockClient.putLogEventsArgument 909 assert.Check(t, argument != nil, "Expected non-nil PutLogEventsInput") 910 assert.Check(t, is.Equal(1, len(argument.LogEvents)), "Expected single multiline event") 911 assert.Check(t, is.Equal(logline+"\n", *argument.LogEvents[0].Message), "Received incorrect multiline message") 912 stream.Close() 913 } 914 915 func TestCollectBatchMultilinePatternNegativeEventAge(t *testing.T) { 916 mockClient := newMockClient() 917 multilinePattern := regexp.MustCompile("xxxx") 918 stream := &logStream{ 919 client: mockClient, 920 logGroupName: groupName, 921 logStreamName: streamName, 922 multilinePattern: multilinePattern, 923 sequenceToken: aws.String(sequenceToken), 924 messages: make(chan *logger.Message), 925 } 926 mockClient.putLogEventsResult <- &putLogEventsResult{ 927 successResult: &cloudwatchlogs.PutLogEventsOutput{ 928 NextSequenceToken: aws.String(nextSequenceToken), 929 }, 930 } 931 ticks := make(chan time.Time) 932 newTicker = func(_ time.Duration) *time.Ticker { 933 return &time.Ticker{ 934 C: ticks, 935 } 936 } 937 938 d := make(chan bool) 939 close(d) 940 go stream.collectBatch(d) 941 942 stream.Log(&logger.Message{ 943 Line: []byte(logline), 944 Timestamp: time.Now(), 945 }) 946 947 // Log an event 1 second later 948 stream.Log(&logger.Message{ 949 Line: []byte(logline), 950 Timestamp: time.Now().Add(time.Second), 951 }) 952 953 // Fire ticker in past to simulate negative event buffer age 954 ticks <- time.Now().Add(-time.Second) 955 956 // Verify single multiline event is flushed with a negative event buffer age 957 argument := <-mockClient.putLogEventsArgument 958 assert.Check(t, argument != nil, "Expected non-nil PutLogEventsInput") 959 assert.Check(t, is.Equal(1, len(argument.LogEvents)), "Expected single multiline event") 960 assert.Check(t, is.Equal(logline+"\n"+logline+"\n", *argument.LogEvents[0].Message), "Received incorrect multiline message") 961 962 stream.Close() 963 } 964 965 func TestCollectBatchMultilinePatternMaxEventSize(t *testing.T) { 966 mockClient := newMockClient() 967 multilinePattern := regexp.MustCompile("xxxx") 968 stream := &logStream{ 969 client: mockClient, 970 logGroupName: groupName, 971 logStreamName: streamName, 972 multilinePattern: multilinePattern, 973 sequenceToken: aws.String(sequenceToken), 974 messages: make(chan *logger.Message), 975 } 976 mockClient.putLogEventsResult <- &putLogEventsResult{ 977 successResult: &cloudwatchlogs.PutLogEventsOutput{ 978 NextSequenceToken: aws.String(nextSequenceToken), 979 }, 980 } 981 ticks := make(chan time.Time) 982 newTicker = func(_ time.Duration) *time.Ticker { 983 return &time.Ticker{ 984 C: ticks, 985 } 986 } 987 988 d := make(chan bool) 989 close(d) 990 go stream.collectBatch(d) 991 992 // Log max event size 993 longline := strings.Repeat("A", maximumBytesPerEvent) 994 stream.Log(&logger.Message{ 995 Line: []byte(longline), 996 Timestamp: time.Now(), 997 }) 998 999 // Log short event 1000 shortline := strings.Repeat("B", 100) 1001 stream.Log(&logger.Message{ 1002 Line: []byte(shortline), 1003 Timestamp: time.Now(), 1004 }) 1005 1006 // Fire ticker 1007 ticks <- time.Now().Add(defaultForceFlushInterval) 1008 1009 // Verify multiline events 1010 // We expect a maximum sized event with no new line characters and a 1011 // second short event with a new line character at the end 1012 argument := <-mockClient.putLogEventsArgument 1013 assert.Check(t, argument != nil, "Expected non-nil PutLogEventsInput") 1014 assert.Check(t, is.Equal(2, len(argument.LogEvents)), "Expected two events") 1015 assert.Check(t, is.Equal(longline, *argument.LogEvents[0].Message), "Received incorrect multiline message") 1016 assert.Check(t, is.Equal(shortline+"\n", *argument.LogEvents[1].Message), "Received incorrect multiline message") 1017 stream.Close() 1018 } 1019 1020 func TestCollectBatchClose(t *testing.T) { 1021 mockClient := newMockClient() 1022 stream := &logStream{ 1023 client: mockClient, 1024 logGroupName: groupName, 1025 logStreamName: streamName, 1026 sequenceToken: aws.String(sequenceToken), 1027 messages: make(chan *logger.Message), 1028 } 1029 mockClient.putLogEventsResult <- &putLogEventsResult{ 1030 successResult: &cloudwatchlogs.PutLogEventsOutput{ 1031 NextSequenceToken: aws.String(nextSequenceToken), 1032 }, 1033 } 1034 var ticks = make(chan time.Time) 1035 newTicker = func(_ time.Duration) *time.Ticker { 1036 return &time.Ticker{ 1037 C: ticks, 1038 } 1039 } 1040 1041 d := make(chan bool) 1042 close(d) 1043 go stream.collectBatch(d) 1044 1045 stream.Log(&logger.Message{ 1046 Line: []byte(logline), 1047 Timestamp: time.Time{}, 1048 }) 1049 1050 // no ticks 1051 stream.Close() 1052 1053 argument := <-mockClient.putLogEventsArgument 1054 if argument == nil { 1055 t.Fatal("Expected non-nil PutLogEventsInput") 1056 } 1057 if len(argument.LogEvents) != 1 { 1058 t.Errorf("Expected LogEvents to contain 1 element, but contains %d", len(argument.LogEvents)) 1059 } 1060 if *argument.LogEvents[0].Message != logline { 1061 t.Errorf("Expected message to be %s but was %s", logline, *argument.LogEvents[0].Message) 1062 } 1063 } 1064 1065 func TestEffectiveLen(t *testing.T) { 1066 tests := []struct { 1067 str string 1068 effectiveBytes int 1069 }{ 1070 {"Hello", 5}, 1071 {string([]byte{1, 2, 3, 4}), 4}, 1072 {"🙃", 4}, 1073 {string([]byte{0xFF, 0xFF, 0xFF, 0xFF}), 12}, 1074 {"He\xff\xffo", 9}, 1075 {"", 0}, 1076 } 1077 for i, tc := range tests { 1078 t.Run(fmt.Sprintf("%d/%s", i, tc.str), func(t *testing.T) { 1079 assert.Equal(t, tc.effectiveBytes, effectiveLen(tc.str)) 1080 }) 1081 } 1082 } 1083 1084 func TestFindValidSplit(t *testing.T) { 1085 tests := []struct { 1086 str string 1087 maxEffectiveBytes int 1088 splitOffset int 1089 effectiveBytes int 1090 }{ 1091 {"", 10, 0, 0}, 1092 {"Hello", 6, 5, 5}, 1093 {"Hello", 2, 2, 2}, 1094 {"Hello", 0, 0, 0}, 1095 {"🙃", 3, 0, 0}, 1096 {"🙃", 4, 4, 4}, 1097 {string([]byte{'a', 0xFF}), 2, 1, 1}, 1098 {string([]byte{'a', 0xFF}), 4, 2, 4}, 1099 } 1100 for i, tc := range tests { 1101 t.Run(fmt.Sprintf("%d/%s", i, tc.str), func(t *testing.T) { 1102 splitOffset, effectiveBytes := findValidSplit(tc.str, tc.maxEffectiveBytes) 1103 assert.Equal(t, tc.splitOffset, splitOffset, "splitOffset") 1104 assert.Equal(t, tc.effectiveBytes, effectiveBytes, "effectiveBytes") 1105 t.Log(tc.str[:tc.splitOffset]) 1106 t.Log(tc.str[tc.splitOffset:]) 1107 }) 1108 } 1109 } 1110 1111 func TestProcessEventEmoji(t *testing.T) { 1112 stream := &logStream{} 1113 batch := &eventBatch{} 1114 bytes := []byte(strings.Repeat("🙃", maximumBytesPerEvent/4+1)) 1115 stream.processEvent(batch, bytes, 0) 1116 assert.Equal(t, 2, len(batch.batch), "should be two events in the batch") 1117 assert.Equal(t, strings.Repeat("🙃", maximumBytesPerEvent/4), aws.StringValue(batch.batch[0].inputLogEvent.Message)) 1118 assert.Equal(t, "🙃", aws.StringValue(batch.batch[1].inputLogEvent.Message)) 1119 } 1120 1121 func TestCollectBatchLineSplit(t *testing.T) { 1122 mockClient := newMockClient() 1123 stream := &logStream{ 1124 client: mockClient, 1125 logGroupName: groupName, 1126 logStreamName: streamName, 1127 sequenceToken: aws.String(sequenceToken), 1128 messages: make(chan *logger.Message), 1129 } 1130 mockClient.putLogEventsResult <- &putLogEventsResult{ 1131 successResult: &cloudwatchlogs.PutLogEventsOutput{ 1132 NextSequenceToken: aws.String(nextSequenceToken), 1133 }, 1134 } 1135 var ticks = make(chan time.Time) 1136 newTicker = func(_ time.Duration) *time.Ticker { 1137 return &time.Ticker{ 1138 C: ticks, 1139 } 1140 } 1141 1142 d := make(chan bool) 1143 close(d) 1144 go stream.collectBatch(d) 1145 1146 longline := strings.Repeat("A", maximumBytesPerEvent) 1147 stream.Log(&logger.Message{ 1148 Line: []byte(longline + "B"), 1149 Timestamp: time.Time{}, 1150 }) 1151 1152 // no ticks 1153 stream.Close() 1154 1155 argument := <-mockClient.putLogEventsArgument 1156 if argument == nil { 1157 t.Fatal("Expected non-nil PutLogEventsInput") 1158 } 1159 if len(argument.LogEvents) != 2 { 1160 t.Errorf("Expected LogEvents to contain 2 elements, but contains %d", len(argument.LogEvents)) 1161 } 1162 if *argument.LogEvents[0].Message != longline { 1163 t.Errorf("Expected message to be %s but was %s", longline, *argument.LogEvents[0].Message) 1164 } 1165 if *argument.LogEvents[1].Message != "B" { 1166 t.Errorf("Expected message to be %s but was %s", "B", *argument.LogEvents[1].Message) 1167 } 1168 } 1169 1170 func TestCollectBatchLineSplitWithBinary(t *testing.T) { 1171 mockClient := newMockClient() 1172 stream := &logStream{ 1173 client: mockClient, 1174 logGroupName: groupName, 1175 logStreamName: streamName, 1176 sequenceToken: aws.String(sequenceToken), 1177 messages: make(chan *logger.Message), 1178 } 1179 mockClient.putLogEventsResult <- &putLogEventsResult{ 1180 successResult: &cloudwatchlogs.PutLogEventsOutput{ 1181 NextSequenceToken: aws.String(nextSequenceToken), 1182 }, 1183 } 1184 var ticks = make(chan time.Time) 1185 newTicker = func(_ time.Duration) *time.Ticker { 1186 return &time.Ticker{ 1187 C: ticks, 1188 } 1189 } 1190 1191 d := make(chan bool) 1192 close(d) 1193 go stream.collectBatch(d) 1194 1195 longline := strings.Repeat("\xFF", maximumBytesPerEvent/3) // 0xFF is counted as the 3-byte utf8.RuneError 1196 stream.Log(&logger.Message{ 1197 Line: []byte(longline + "\xFD"), 1198 Timestamp: time.Time{}, 1199 }) 1200 1201 // no ticks 1202 stream.Close() 1203 1204 argument := <-mockClient.putLogEventsArgument 1205 if argument == nil { 1206 t.Fatal("Expected non-nil PutLogEventsInput") 1207 } 1208 if len(argument.LogEvents) != 2 { 1209 t.Errorf("Expected LogEvents to contain 2 elements, but contains %d", len(argument.LogEvents)) 1210 } 1211 if *argument.LogEvents[0].Message != longline { 1212 t.Errorf("Expected message to be %s but was %s", longline, *argument.LogEvents[0].Message) 1213 } 1214 if *argument.LogEvents[1].Message != "\xFD" { 1215 t.Errorf("Expected message to be %s but was %s", "\xFD", *argument.LogEvents[1].Message) 1216 } 1217 } 1218 1219 func TestCollectBatchMaxEvents(t *testing.T) { 1220 mockClient := newMockClientBuffered(1) 1221 stream := &logStream{ 1222 client: mockClient, 1223 logGroupName: groupName, 1224 logStreamName: streamName, 1225 sequenceToken: aws.String(sequenceToken), 1226 messages: make(chan *logger.Message), 1227 } 1228 mockClient.putLogEventsResult <- &putLogEventsResult{ 1229 successResult: &cloudwatchlogs.PutLogEventsOutput{ 1230 NextSequenceToken: aws.String(nextSequenceToken), 1231 }, 1232 } 1233 var ticks = make(chan time.Time) 1234 newTicker = func(_ time.Duration) *time.Ticker { 1235 return &time.Ticker{ 1236 C: ticks, 1237 } 1238 } 1239 1240 d := make(chan bool) 1241 close(d) 1242 go stream.collectBatch(d) 1243 1244 line := "A" 1245 for i := 0; i <= maximumLogEventsPerPut; i++ { 1246 stream.Log(&logger.Message{ 1247 Line: []byte(line), 1248 Timestamp: time.Time{}, 1249 }) 1250 } 1251 1252 // no ticks 1253 stream.Close() 1254 1255 argument := <-mockClient.putLogEventsArgument 1256 if argument == nil { 1257 t.Fatal("Expected non-nil PutLogEventsInput") 1258 } 1259 if len(argument.LogEvents) != maximumLogEventsPerPut { 1260 t.Errorf("Expected LogEvents to contain %d elements, but contains %d", maximumLogEventsPerPut, len(argument.LogEvents)) 1261 } 1262 1263 argument = <-mockClient.putLogEventsArgument 1264 if argument == nil { 1265 t.Fatal("Expected non-nil PutLogEventsInput") 1266 } 1267 if len(argument.LogEvents) != 1 { 1268 t.Errorf("Expected LogEvents to contain %d elements, but contains %d", 1, len(argument.LogEvents)) 1269 } 1270 } 1271 1272 func TestCollectBatchMaxTotalBytes(t *testing.T) { 1273 expectedPuts := 2 1274 mockClient := newMockClientBuffered(expectedPuts) 1275 stream := &logStream{ 1276 client: mockClient, 1277 logGroupName: groupName, 1278 logStreamName: streamName, 1279 sequenceToken: aws.String(sequenceToken), 1280 messages: make(chan *logger.Message), 1281 } 1282 for i := 0; i < expectedPuts; i++ { 1283 mockClient.putLogEventsResult <- &putLogEventsResult{ 1284 successResult: &cloudwatchlogs.PutLogEventsOutput{ 1285 NextSequenceToken: aws.String(nextSequenceToken), 1286 }, 1287 } 1288 } 1289 1290 var ticks = make(chan time.Time) 1291 newTicker = func(_ time.Duration) *time.Ticker { 1292 return &time.Ticker{ 1293 C: ticks, 1294 } 1295 } 1296 1297 d := make(chan bool) 1298 close(d) 1299 go stream.collectBatch(d) 1300 1301 numPayloads := maximumBytesPerPut / (maximumBytesPerEvent + perEventBytes) 1302 // maxline is the maximum line that could be submitted after 1303 // accounting for its overhead. 1304 maxline := strings.Repeat("A", maximumBytesPerPut-(perEventBytes*numPayloads)) 1305 // This will be split and batched up to the `maximumBytesPerPut' 1306 // (+/- `maximumBytesPerEvent'). This /should/ be aligned, but 1307 // should also tolerate an offset within that range. 1308 stream.Log(&logger.Message{ 1309 Line: []byte(maxline[:len(maxline)/2]), 1310 Timestamp: time.Time{}, 1311 }) 1312 stream.Log(&logger.Message{ 1313 Line: []byte(maxline[len(maxline)/2:]), 1314 Timestamp: time.Time{}, 1315 }) 1316 stream.Log(&logger.Message{ 1317 Line: []byte("B"), 1318 Timestamp: time.Time{}, 1319 }) 1320 1321 // no ticks, guarantee batch by size (and chan close) 1322 stream.Close() 1323 1324 argument := <-mockClient.putLogEventsArgument 1325 if argument == nil { 1326 t.Fatal("Expected non-nil PutLogEventsInput") 1327 } 1328 1329 // Should total to the maximum allowed bytes. 1330 eventBytes := 0 1331 for _, event := range argument.LogEvents { 1332 eventBytes += len(*event.Message) 1333 } 1334 eventsOverhead := len(argument.LogEvents) * perEventBytes 1335 payloadTotal := eventBytes + eventsOverhead 1336 // lowestMaxBatch allows the payload to be offset if the messages 1337 // don't lend themselves to align with the maximum event size. 1338 lowestMaxBatch := maximumBytesPerPut - maximumBytesPerEvent 1339 1340 if payloadTotal > maximumBytesPerPut { 1341 t.Errorf("Expected <= %d bytes but was %d", maximumBytesPerPut, payloadTotal) 1342 } 1343 if payloadTotal < lowestMaxBatch { 1344 t.Errorf("Batch to be no less than %d but was %d", lowestMaxBatch, payloadTotal) 1345 } 1346 1347 argument = <-mockClient.putLogEventsArgument 1348 if len(argument.LogEvents) != 1 { 1349 t.Errorf("Expected LogEvents to contain 1 elements, but contains %d", len(argument.LogEvents)) 1350 } 1351 message := *argument.LogEvents[len(argument.LogEvents)-1].Message 1352 if message[len(message)-1:] != "B" { 1353 t.Errorf("Expected message to be %s but was %s", "B", message[len(message)-1:]) 1354 } 1355 } 1356 1357 func TestCollectBatchMaxTotalBytesWithBinary(t *testing.T) { 1358 expectedPuts := 2 1359 mockClient := newMockClientBuffered(expectedPuts) 1360 stream := &logStream{ 1361 client: mockClient, 1362 logGroupName: groupName, 1363 logStreamName: streamName, 1364 sequenceToken: aws.String(sequenceToken), 1365 messages: make(chan *logger.Message), 1366 } 1367 for i := 0; i < expectedPuts; i++ { 1368 mockClient.putLogEventsResult <- &putLogEventsResult{ 1369 successResult: &cloudwatchlogs.PutLogEventsOutput{ 1370 NextSequenceToken: aws.String(nextSequenceToken), 1371 }, 1372 } 1373 } 1374 1375 var ticks = make(chan time.Time) 1376 newTicker = func(_ time.Duration) *time.Ticker { 1377 return &time.Ticker{ 1378 C: ticks, 1379 } 1380 } 1381 1382 d := make(chan bool) 1383 close(d) 1384 go stream.collectBatch(d) 1385 1386 // maxline is the maximum line that could be submitted after 1387 // accounting for its overhead. 1388 maxline := strings.Repeat("\xFF", (maximumBytesPerPut-perEventBytes)/3) // 0xFF is counted as the 3-byte utf8.RuneError 1389 // This will be split and batched up to the `maximumBytesPerPut' 1390 // (+/- `maximumBytesPerEvent'). This /should/ be aligned, but 1391 // should also tolerate an offset within that range. 1392 stream.Log(&logger.Message{ 1393 Line: []byte(maxline), 1394 Timestamp: time.Time{}, 1395 }) 1396 stream.Log(&logger.Message{ 1397 Line: []byte("B"), 1398 Timestamp: time.Time{}, 1399 }) 1400 1401 // no ticks, guarantee batch by size (and chan close) 1402 stream.Close() 1403 1404 argument := <-mockClient.putLogEventsArgument 1405 if argument == nil { 1406 t.Fatal("Expected non-nil PutLogEventsInput") 1407 } 1408 1409 // Should total to the maximum allowed bytes. 1410 eventBytes := 0 1411 for _, event := range argument.LogEvents { 1412 eventBytes += effectiveLen(*event.Message) 1413 } 1414 eventsOverhead := len(argument.LogEvents) * perEventBytes 1415 payloadTotal := eventBytes + eventsOverhead 1416 // lowestMaxBatch allows the payload to be offset if the messages 1417 // don't lend themselves to align with the maximum event size. 1418 lowestMaxBatch := maximumBytesPerPut - maximumBytesPerEvent 1419 1420 if payloadTotal > maximumBytesPerPut { 1421 t.Errorf("Expected <= %d bytes but was %d", maximumBytesPerPut, payloadTotal) 1422 } 1423 if payloadTotal < lowestMaxBatch { 1424 t.Errorf("Batch to be no less than %d but was %d", lowestMaxBatch, payloadTotal) 1425 } 1426 1427 argument = <-mockClient.putLogEventsArgument 1428 message := *argument.LogEvents[len(argument.LogEvents)-1].Message 1429 if message[len(message)-1:] != "B" { 1430 t.Errorf("Expected message to be %s but was %s", "B", message[len(message)-1:]) 1431 } 1432 } 1433 1434 func TestCollectBatchWithDuplicateTimestamps(t *testing.T) { 1435 mockClient := newMockClient() 1436 stream := &logStream{ 1437 client: mockClient, 1438 logGroupName: groupName, 1439 logStreamName: streamName, 1440 sequenceToken: aws.String(sequenceToken), 1441 messages: make(chan *logger.Message), 1442 } 1443 mockClient.putLogEventsResult <- &putLogEventsResult{ 1444 successResult: &cloudwatchlogs.PutLogEventsOutput{ 1445 NextSequenceToken: aws.String(nextSequenceToken), 1446 }, 1447 } 1448 ticks := make(chan time.Time) 1449 newTicker = func(_ time.Duration) *time.Ticker { 1450 return &time.Ticker{ 1451 C: ticks, 1452 } 1453 } 1454 1455 d := make(chan bool) 1456 close(d) 1457 go stream.collectBatch(d) 1458 1459 var expectedEvents []*cloudwatchlogs.InputLogEvent 1460 times := maximumLogEventsPerPut 1461 timestamp := time.Now() 1462 for i := 0; i < times; i++ { 1463 line := fmt.Sprintf("%d", i) 1464 if i%2 == 0 { 1465 timestamp.Add(1 * time.Nanosecond) 1466 } 1467 stream.Log(&logger.Message{ 1468 Line: []byte(line), 1469 Timestamp: timestamp, 1470 }) 1471 expectedEvents = append(expectedEvents, &cloudwatchlogs.InputLogEvent{ 1472 Message: aws.String(line), 1473 Timestamp: aws.Int64(timestamp.UnixNano() / int64(time.Millisecond)), 1474 }) 1475 } 1476 1477 ticks <- time.Time{} 1478 stream.Close() 1479 1480 argument := <-mockClient.putLogEventsArgument 1481 if argument == nil { 1482 t.Fatal("Expected non-nil PutLogEventsInput") 1483 } 1484 if len(argument.LogEvents) != times { 1485 t.Errorf("Expected LogEvents to contain %d elements, but contains %d", times, len(argument.LogEvents)) 1486 } 1487 for i := 0; i < times; i++ { 1488 if !reflect.DeepEqual(*argument.LogEvents[i], *expectedEvents[i]) { 1489 t.Errorf("Expected event to be %v but was %v", *expectedEvents[i], *argument.LogEvents[i]) 1490 } 1491 } 1492 } 1493 1494 func TestParseLogOptionsMultilinePattern(t *testing.T) { 1495 info := logger.Info{ 1496 Config: map[string]string{ 1497 multilinePatternKey: "^xxxx", 1498 }, 1499 } 1500 1501 multilinePattern, err := parseMultilineOptions(info) 1502 assert.Check(t, err, "Received unexpected error") 1503 assert.Check(t, multilinePattern.MatchString("xxxx"), "No multiline pattern match found") 1504 } 1505 1506 func TestParseLogOptionsDatetimeFormat(t *testing.T) { 1507 datetimeFormatTests := []struct { 1508 format string 1509 match string 1510 }{ 1511 {"%d/%m/%y %a %H:%M:%S%L %Z", "31/12/10 Mon 08:42:44.345 NZDT"}, 1512 {"%Y-%m-%d %A %I:%M:%S.%f%p%z", "2007-12-04 Monday 08:42:44.123456AM+1200"}, 1513 {"%b|%b|%b|%b|%b|%b|%b|%b|%b|%b|%b|%b", "Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec"}, 1514 {"%B|%B|%B|%B|%B|%B|%B|%B|%B|%B|%B|%B", "January|February|March|April|May|June|July|August|September|October|November|December"}, 1515 {"%A|%A|%A|%A|%A|%A|%A", "Monday|Tuesday|Wednesday|Thursday|Friday|Saturday|Sunday"}, 1516 {"%a|%a|%a|%a|%a|%a|%a", "Mon|Tue|Wed|Thu|Fri|Sat|Sun"}, 1517 {"Day of the week: %w, Day of the year: %j", "Day of the week: 4, Day of the year: 091"}, 1518 } 1519 for _, dt := range datetimeFormatTests { 1520 t.Run(dt.match, func(t *testing.T) { 1521 info := logger.Info{ 1522 Config: map[string]string{ 1523 datetimeFormatKey: dt.format, 1524 }, 1525 } 1526 multilinePattern, err := parseMultilineOptions(info) 1527 assert.Check(t, err, "Received unexpected error") 1528 assert.Check(t, multilinePattern.MatchString(dt.match), "No multiline pattern match found") 1529 }) 1530 } 1531 } 1532 1533 func TestValidateLogOptionsDatetimeFormatAndMultilinePattern(t *testing.T) { 1534 cfg := map[string]string{ 1535 multilinePatternKey: "^xxxx", 1536 datetimeFormatKey: "%Y-%m-%d", 1537 logGroupKey: groupName, 1538 } 1539 conflictingLogOptionsError := "you cannot configure log opt 'awslogs-datetime-format' and 'awslogs-multiline-pattern' at the same time" 1540 1541 err := ValidateLogOpt(cfg) 1542 assert.Check(t, err != nil, "Expected an error") 1543 assert.Check(t, is.Equal(err.Error(), conflictingLogOptionsError), "Received invalid error") 1544 } 1545 1546 func TestValidateLogOptionsForceFlushIntervalSeconds(t *testing.T) { 1547 tests := []struct { 1548 input string 1549 shouldErr bool 1550 }{ 1551 {"0", true}, 1552 {"-1", true}, 1553 {"a", true}, 1554 {"10", false}, 1555 } 1556 1557 for _, tc := range tests { 1558 t.Run(tc.input, func(t *testing.T) { 1559 cfg := map[string]string{ 1560 forceFlushIntervalKey: tc.input, 1561 logGroupKey: groupName, 1562 } 1563 1564 err := ValidateLogOpt(cfg) 1565 if tc.shouldErr { 1566 expectedErr := "must specify a positive integer for log opt 'awslogs-force-flush-interval-seconds': " + tc.input 1567 assert.Error(t, err, expectedErr) 1568 } else { 1569 assert.NilError(t, err) 1570 } 1571 }) 1572 } 1573 } 1574 1575 func TestValidateLogOptionsMaxBufferedEvents(t *testing.T) { 1576 tests := []struct { 1577 input string 1578 shouldErr bool 1579 }{ 1580 {"0", true}, 1581 {"-1", true}, 1582 {"a", true}, 1583 {"10", false}, 1584 } 1585 1586 for _, tc := range tests { 1587 t.Run(tc.input, func(t *testing.T) { 1588 cfg := map[string]string{ 1589 maxBufferedEventsKey: tc.input, 1590 logGroupKey: groupName, 1591 } 1592 1593 err := ValidateLogOpt(cfg) 1594 if tc.shouldErr { 1595 expectedErr := "must specify a positive integer for log opt 'awslogs-max-buffered-events': " + tc.input 1596 assert.Error(t, err, expectedErr) 1597 } else { 1598 assert.NilError(t, err) 1599 } 1600 }) 1601 } 1602 } 1603 1604 func TestValidateLogOptionsFormat(t *testing.T) { 1605 tests := []struct { 1606 format string 1607 multiLinePattern string 1608 datetimeFormat string 1609 expErrMsg string 1610 }{ 1611 {"json/emf", "", "", ""}, 1612 {"random", "", "", "unsupported log format 'random'"}, 1613 {"", "", "", ""}, 1614 {"json/emf", "---", "", "you cannot configure log opt 'awslogs-datetime-format' or 'awslogs-multiline-pattern' when log opt 'awslogs-format' is set to 'json/emf'"}, 1615 {"json/emf", "", "yyyy-dd-mm", "you cannot configure log opt 'awslogs-datetime-format' or 'awslogs-multiline-pattern' when log opt 'awslogs-format' is set to 'json/emf'"}, 1616 } 1617 1618 for i, tc := range tests { 1619 t.Run(fmt.Sprintf("%d/%s", i, tc.format), func(t *testing.T) { 1620 cfg := map[string]string{ 1621 logGroupKey: groupName, 1622 logFormatKey: tc.format, 1623 } 1624 if tc.multiLinePattern != "" { 1625 cfg[multilinePatternKey] = tc.multiLinePattern 1626 } 1627 if tc.datetimeFormat != "" { 1628 cfg[datetimeFormatKey] = tc.datetimeFormat 1629 } 1630 1631 err := ValidateLogOpt(cfg) 1632 if tc.expErrMsg != "" { 1633 assert.Error(t, err, tc.expErrMsg) 1634 } else { 1635 assert.NilError(t, err) 1636 } 1637 }) 1638 } 1639 } 1640 1641 func TestCreateTagSuccess(t *testing.T) { 1642 mockClient := newMockClient() 1643 info := logger.Info{ 1644 ContainerName: "/test-container", 1645 ContainerID: "container-abcdefghijklmnopqrstuvwxyz01234567890", 1646 Config: map[string]string{"tag": "{{.Name}}/{{.FullID}}"}, 1647 } 1648 logStreamName, e := loggerutils.ParseLogTag(info, loggerutils.DefaultTemplate) 1649 if e != nil { 1650 t.Errorf("Error generating tag: %q", e) 1651 } 1652 stream := &logStream{ 1653 client: mockClient, 1654 logGroupName: groupName, 1655 logStreamName: logStreamName, 1656 logCreateStream: true, 1657 } 1658 mockClient.createLogStreamResult <- &createLogStreamResult{} 1659 1660 err := stream.create() 1661 1662 assert.NilError(t, err) 1663 argument := <-mockClient.createLogStreamArgument 1664 1665 if *argument.LogStreamName != "test-container/container-abcdefghijklmnopqrstuvwxyz01234567890" { 1666 t.Errorf("Expected LogStreamName to be %s", "test-container/container-abcdefghijklmnopqrstuvwxyz01234567890") 1667 } 1668 } 1669 1670 func BenchmarkUnwrapEvents(b *testing.B) { 1671 events := make([]wrappedEvent, maximumLogEventsPerPut) 1672 for i := 0; i < maximumLogEventsPerPut; i++ { 1673 mes := strings.Repeat("0", maximumBytesPerEvent) 1674 events[i].inputLogEvent = &cloudwatchlogs.InputLogEvent{ 1675 Message: &mes, 1676 } 1677 } 1678 1679 b.ResetTimer() 1680 for i := 0; i < b.N; i++ { 1681 res := unwrapEvents(events) 1682 assert.Check(b, is.Len(res, maximumLogEventsPerPut)) 1683 } 1684 } 1685 1686 func TestNewAWSLogsClientCredentialEndpointDetect(t *testing.T) { 1687 // required for the cloudwatchlogs client 1688 os.Setenv("AWS_REGION", "us-west-2") 1689 defer os.Unsetenv("AWS_REGION") 1690 1691 credsResp := `{ 1692 "AccessKeyId" : "test-access-key-id", 1693 "SecretAccessKey": "test-secret-access-key" 1694 }` 1695 1696 expectedAccessKeyID := "test-access-key-id" 1697 expectedSecretAccessKey := "test-secret-access-key" 1698 1699 testServer := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { 1700 w.Header().Set("Content-Type", "application/json") 1701 fmt.Fprintln(w, credsResp) 1702 })) 1703 defer testServer.Close() 1704 1705 // set the SDKEndpoint in the driver 1706 newSDKEndpoint = testServer.URL 1707 1708 info := logger.Info{ 1709 Config: map[string]string{}, 1710 } 1711 1712 info.Config["awslogs-credentials-endpoint"] = "/creds" 1713 1714 c, err := newAWSLogsClient(info) 1715 assert.Check(t, err) 1716 1717 client := c.(*cloudwatchlogs.CloudWatchLogs) 1718 1719 creds, err := client.Config.Credentials.Get() 1720 assert.Check(t, err) 1721 1722 assert.Check(t, is.Equal(expectedAccessKeyID, creds.AccessKeyID)) 1723 assert.Check(t, is.Equal(expectedSecretAccessKey, creds.SecretAccessKey)) 1724 } 1725 1726 func TestNewAWSLogsClientCredentialEnvironmentVariable(t *testing.T) { 1727 // required for the cloudwatchlogs client 1728 os.Setenv("AWS_REGION", "us-west-2") 1729 defer os.Unsetenv("AWS_REGION") 1730 1731 expectedAccessKeyID := "test-access-key-id" 1732 expectedSecretAccessKey := "test-secret-access-key" 1733 1734 os.Setenv("AWS_ACCESS_KEY_ID", expectedAccessKeyID) 1735 defer os.Unsetenv("AWS_ACCESS_KEY_ID") 1736 1737 os.Setenv("AWS_SECRET_ACCESS_KEY", expectedSecretAccessKey) 1738 defer os.Unsetenv("AWS_SECRET_ACCESS_KEY") 1739 1740 info := logger.Info{ 1741 Config: map[string]string{}, 1742 } 1743 1744 c, err := newAWSLogsClient(info) 1745 assert.Check(t, err) 1746 1747 client := c.(*cloudwatchlogs.CloudWatchLogs) 1748 1749 creds, err := client.Config.Credentials.Get() 1750 assert.Check(t, err) 1751 1752 assert.Check(t, is.Equal(expectedAccessKeyID, creds.AccessKeyID)) 1753 assert.Check(t, is.Equal(expectedSecretAccessKey, creds.SecretAccessKey)) 1754 } 1755 1756 func TestNewAWSLogsClientCredentialSharedFile(t *testing.T) { 1757 // required for the cloudwatchlogs client 1758 os.Setenv("AWS_REGION", "us-west-2") 1759 defer os.Unsetenv("AWS_REGION") 1760 1761 expectedAccessKeyID := "test-access-key-id" 1762 expectedSecretAccessKey := "test-secret-access-key" 1763 1764 contentStr := ` 1765 [default] 1766 aws_access_key_id = "test-access-key-id" 1767 aws_secret_access_key = "test-secret-access-key" 1768 ` 1769 content := []byte(contentStr) 1770 1771 tmpfile, err := os.CreateTemp("", "example") 1772 defer os.Remove(tmpfile.Name()) // clean up 1773 assert.Check(t, err) 1774 1775 _, err = tmpfile.Write(content) 1776 assert.Check(t, err) 1777 1778 err = tmpfile.Close() 1779 assert.Check(t, err) 1780 1781 os.Unsetenv("AWS_ACCESS_KEY_ID") 1782 os.Unsetenv("AWS_SECRET_ACCESS_KEY") 1783 1784 os.Setenv("AWS_SHARED_CREDENTIALS_FILE", tmpfile.Name()) 1785 defer os.Unsetenv("AWS_SHARED_CREDENTIALS_FILE") 1786 1787 info := logger.Info{ 1788 Config: map[string]string{}, 1789 } 1790 1791 c, err := newAWSLogsClient(info) 1792 assert.Check(t, err) 1793 1794 client := c.(*cloudwatchlogs.CloudWatchLogs) 1795 1796 creds, err := client.Config.Credentials.Get() 1797 assert.Check(t, err) 1798 1799 assert.Check(t, is.Equal(expectedAccessKeyID, creds.AccessKeyID)) 1800 assert.Check(t, is.Equal(expectedSecretAccessKey, creds.SecretAccessKey)) 1801 }