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