github.com/docker/docker@v299999999.0.0-20200612211812-aaf470eca7b5+incompatible/daemon/logger/awslogs/cloudwatchlogs_test.go (about)

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