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