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