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