clam_prose_test.go

Documentation: go.mongodb.org/mongo-driver/mongo/integration

     1  // Copyright (C) MongoDB, Inc. 2023-present.
     2  //
     3  // Licensed under the Apache License, Version 2.0 (the "License"); you may
     4  // not use this file except in compliance with the License. You may obtain
     5  // a copy of the License at http://www.apache.org/licenses/LICENSE-2.0
     6  
     7  package integration
     8  
     9  import (
    10  	"context"
    11  	"fmt"
    12  	"testing"
    13  	"time"
    14  
    15  	"go.mongodb.org/mongo-driver/bson"
    16  	"go.mongodb.org/mongo-driver/internal/assert"
    17  	"go.mongodb.org/mongo-driver/internal/integtest"
    18  	"go.mongodb.org/mongo-driver/internal/logger"
    19  	"go.mongodb.org/mongo-driver/mongo"
    20  	"go.mongodb.org/mongo-driver/mongo/integration/mtest"
    21  	"go.mongodb.org/mongo-driver/mongo/options"
    22  )
    23  
    24  var ErrInvalidTruncation = fmt.Errorf("invalid truncation")
    25  
    26  func clamTruncErr(mt *mtest.T, op string, want, got int) error {
    27  	mt.Helper()
    28  
    29  	return fmt.Errorf("%w: expected length %s %d, got %d", ErrInvalidTruncation, op, want, got)
    30  }
    31  
    32  func clamDefaultTruncLimitOp(ctx context.Context, mt *mtest.T, coll *mongo.Collection) {
    33  	mt.Helper()
    34  
    35  	const documentsSize = 100
    36  
    37  	// Construct an array of docs containing the document {"x" : "y"}
    38  	// repeated "documentSize" times.
    39  	docs := []interface{}{}
    40  	for i := 0; i < documentsSize; i++ {
    41  		docs = append(docs, bson.D{{"x", "y"}})
    42  	}
    43  
    44  	// Insert docs to a the collection.
    45  	_, err := coll.InsertMany(ctx, docs)
    46  	assert.Nil(mt, err, "InsertMany error: %v", err)
    47  
    48  	// Run find() on the collection.
    49  	_, err = coll.Find(ctx, bson.D{})
    50  	assert.Nil(mt, err, "Find error: %v", err)
    51  }
    52  
    53  func clamDefaultTruncLimitLogs(mt *mtest.T) []truncValidator {
    54  	mt.Helper()
    55  
    56  	const cmd = "command"
    57  	const rpl = "reply"
    58  
    59  	expTruncLen := len(logger.TruncationSuffix) + logger.DefaultMaxDocumentLength
    60  	validators := make([]truncValidator, 4)
    61  
    62  	// Insert started.
    63  	validators[0] = newTruncValidator(mt, cmd, func(cmd string) error {
    64  		if len(cmd) != expTruncLen {
    65  			return clamTruncErr(mt, "=", expTruncLen, len(cmd))
    66  		}
    67  
    68  		return nil
    69  	})
    70  
    71  	// Insert succeeded.
    72  	validators[1] = newTruncValidator(mt, rpl, func(cmd string) error {
    73  		if len(cmd) > expTruncLen {
    74  			return clamTruncErr(mt, "<=", expTruncLen, len(cmd))
    75  		}
    76  
    77  		return nil
    78  	})
    79  
    80  	// Find started, nothing to validate.
    81  	validators[2] = nil
    82  
    83  	// Find succeeded.
    84  	validators[3] = newTruncValidator(mt, rpl, func(cmd string) error {
    85  		if len(cmd) != expTruncLen {
    86  			return clamTruncErr(mt, "=", expTruncLen, len(cmd))
    87  		}
    88  
    89  		return nil
    90  	})
    91  
    92  	return validators
    93  }
    94  
    95  func clamExplicitTruncLimitOp(ctx context.Context, mt *mtest.T, coll *mongo.Collection) {
    96  	mt.Helper()
    97  
    98  	result := coll.Database().RunCommand(ctx, bson.D{{"hello", true}})
    99  	assert.Nil(mt, result.Err(), "RunCommand error: %v", result.Err())
   100  }
   101  
   102  func clamExplicitTruncLimitLogs(mt *mtest.T) []truncValidator {
   103  	mt.Helper()
   104  
   105  	const cmd = "command"
   106  	const rpl = "reply"
   107  
   108  	expTruncLen := len(logger.TruncationSuffix) + 5
   109  	validators := make([]truncValidator, 2)
   110  
   111  	// Hello started.
   112  	validators[0] = newTruncValidator(mt, cmd, func(cmd string) error {
   113  		if len(cmd) != expTruncLen {
   114  			return clamTruncErr(mt, "=", expTruncLen, len(cmd))
   115  		}
   116  
   117  		return nil
   118  	})
   119  
   120  	// Hello succeeded.
   121  	validators[1] = newTruncValidator(mt, rpl, func(cmd string) error {
   122  		if len(cmd) != expTruncLen {
   123  			return clamTruncErr(mt, "=", expTruncLen, len(cmd))
   124  		}
   125  
   126  		return nil
   127  	})
   128  
   129  	return validators
   130  }
   131  
   132  func clamExplicitTruncLimitFailOp(ctx context.Context, mt *mtest.T, coll *mongo.Collection) {
   133  	mt.Helper()
   134  
   135  	result := coll.Database().RunCommand(ctx, bson.D{{"notARealCommand", true}})
   136  	assert.NotNil(mt, result.Err(), "expected RunCommand error, got: %v", result.Err())
   137  }
   138  
   139  func clamExplicitTruncLimitFailLogs(mt *mtest.T) []truncValidator {
   140  	mt.Helper()
   141  
   142  	const fail = "failure"
   143  
   144  	expTruncLen := len(logger.TruncationSuffix) + 5
   145  	validators := make([]truncValidator, 2)
   146  
   147  	// Hello started, nothing to validate.
   148  	validators[0] = nil
   149  
   150  	// Hello failed.
   151  	validators[1] = newTruncValidator(mt, fail, func(cmd string) error {
   152  		if len(cmd) != expTruncLen {
   153  			return clamTruncErr(mt, "=", expTruncLen, len(cmd))
   154  		}
   155  
   156  		return nil
   157  	})
   158  
   159  	return validators
   160  }
   161  
   162  // clamMultiByteTrunc runs an operation to insert a very large document with the
   163  // multi-byte character "界" repeated a large number of times. This repetition
   164  // is done to categorically ensure that the truncation point is made somewhere
   165  // within the multi-byte character. For example a typical insertion reply may
   166  // look something like this:
   167  //
   168  // {"insert": "setuptest","ordered": true,"lsid": {"id": ...
   169  //
   170  // We have no control over how the "header" portion of this reply is formatted.
   171  // Over time the server might support newer fields or change the formatting of
   172  // existing fields. This means that the truncation point could be anywhere in
   173  // the "header" portion of the reply. A large document lowers the likelihood of
   174  // the truncation point being in the "header" portion of the reply.
   175  func clamMultiByteTrunc(ctx context.Context, mt *mtest.T, coll *mongo.Collection) {
   176  	mt.Helper()
   177  
   178  	const multiByteCharStrLen = 50_000
   179  	const strToRepeat = "界"
   180  
   181  	// Repeat the string "strToRepeat" "multiByteCharStrLen" times.
   182  	multiByteCharStr := ""
   183  	for i := 0; i < multiByteCharStrLen; i++ {
   184  		multiByteCharStr += strToRepeat
   185  	}
   186  
   187  	_, err := coll.InsertOne(ctx, bson.D{{"x", multiByteCharStr}})
   188  	assert.Nil(mt, err, "InsertOne error: %v", err)
   189  }
   190  
   191  func clamMultiByteTruncLogs(mt *mtest.T) []truncValidator {
   192  	mt.Helper()
   193  
   194  	const cmd = "command"
   195  	const strToRepeat = "界"
   196  
   197  	validators := make([]truncValidator, 2)
   198  
   199  	// Insert started.
   200  	validators[0] = newTruncValidator(mt, cmd, func(cmd string) error {
   201  
   202  		// Remove the suffix from the command string.
   203  		cmd = cmd[:len(cmd)-len(logger.TruncationSuffix)]
   204  
   205  		// Get the last 3 bytes of the command string.
   206  		last3Bytes := cmd[len(cmd)-3:]
   207  
   208  		// Make sure the last 3 bytes are the multi-byte character.
   209  		if last3Bytes != strToRepeat {
   210  			return fmt.Errorf("expected last 3 bytes to be %q, got %q", strToRepeat, last3Bytes)
   211  		}
   212  
   213  		return nil
   214  	})
   215  
   216  	return validators
   217  }
   218  
   219  func TestCommandLoggingAndMonitoringProse(t *testing.T) {
   220  	t.Parallel()
   221  
   222  	mt := mtest.New(t, mtest.NewOptions().CreateClient(false))
   223  
   224  	for _, tcase := range []struct {
   225  		// name is the name of the test case
   226  		name string
   227  
   228  		// collectionName is the name to assign the collection for
   229  		// processing the operations. This should be unique across test
   230  		// cases.
   231  		collectionName string
   232  
   233  		// maxDocumentLength is the maximum document length for a
   234  		// command message.
   235  		maxDocumentLength uint
   236  
   237  		// orderedLogValidators is a slice of log validators that should
   238  		// be 1-1 with the actual logs that are propagated by the
   239  		// LogSink. The order here matters, the first log will be
   240  		// validated by the 0th validator, the second log will be
   241  		// validated by the 1st validator, etc.
   242  		orderedLogValidators []truncValidator
   243  
   244  		// operation is the operation to perform on the collection that
   245  		// will result in log propagation. The logs created by
   246  		// "operation" will be validated against the
   247  		// "orderedLogValidators."
   248  		operation func(context.Context, *mtest.T, *mongo.Collection)
   249  
   250  		// Setup is a function that will be run before the test case.
   251  		// Operations performed in this function will not be logged.
   252  		setup func(context.Context, *mtest.T, *mongo.Collection)
   253  	}{
   254  		{
   255  			name:                 "1 Default truncation limit",
   256  			collectionName:       "46a624c57c72463d90f88a733e7b28b4",
   257  			operation:            clamDefaultTruncLimitOp,
   258  			orderedLogValidators: clamDefaultTruncLimitLogs(mt),
   259  		},
   260  		{
   261  			name:                 "2 Explicitly configured truncation limit",
   262  			collectionName:       "540baa64dc854ca2a639627e2f0918df",
   263  			maxDocumentLength:    5,
   264  			operation:            clamExplicitTruncLimitOp,
   265  			orderedLogValidators: clamExplicitTruncLimitLogs(mt),
   266  		},
   267  		{
   268  			name:                 "2 Explicitly configured truncation limit for failures",
   269  			collectionName:       "aff43dfcaa1a4014b58aaa9606f5bd44",
   270  			maxDocumentLength:    5,
   271  			operation:            clamExplicitTruncLimitFailOp,
   272  			orderedLogValidators: clamExplicitTruncLimitFailLogs(mt),
   273  		},
   274  
   275  		// The third test case is to ensure that a truncation point made
   276  		// within a multi-byte character is handled correctly. The
   277  		// chosen multi-byte character for this test is "界" (U+754C).
   278  		// This character is repeated a large number of times (50,000).
   279  		// We need to run this test 3 times to ensure that the
   280  		// truncation occurs at a middle point within the multi-byte
   281  		// character at least once (at most twice).
   282  		{
   283  			name:                 "3.1 Truncation with multi-byte codepoints",
   284  			collectionName:       "5ed6d1b7-e358-438a-b067-e1d1dd10fee1",
   285  			maxDocumentLength:    20_000,
   286  			operation:            clamMultiByteTrunc,
   287  			orderedLogValidators: clamMultiByteTruncLogs(mt),
   288  		},
   289  		{
   290  			name:                 "3.2 Truncation with multi-byte codepoints",
   291  			collectionName:       "5ed6d1b7-e358-438a-b067-e1d1dd10fee1",
   292  			maxDocumentLength:    20_001,
   293  			operation:            clamMultiByteTrunc,
   294  			orderedLogValidators: clamMultiByteTruncLogs(mt),
   295  		},
   296  		{
   297  			name:                 "3.3 Truncation with multi-byte codepoints",
   298  			collectionName:       "5ed6d1b7-e358-438a-b067-e1d1dd10fee1",
   299  			maxDocumentLength:    20_002,
   300  			operation:            clamMultiByteTrunc,
   301  			orderedLogValidators: clamMultiByteTruncLogs(mt),
   302  		},
   303  	} {
   304  		tcase := tcase
   305  
   306  		mt.Run(tcase.name, func(mt *mtest.T) {
   307  			mt.Parallel()
   308  
   309  			const deadline = 10 * time.Second
   310  			ctx := context.Background()
   311  
   312  			// Before the test case, we need to see if there is a
   313  			// setup function to run.
   314  			if tcase.setup != nil {
   315  				clientOpts := options.Client().ApplyURI(mtest.ClusterURI())
   316  
   317  				// Create a context with a deadline so that the
   318  				// test setup doesn't hang forever.
   319  				ctx, cancel := context.WithTimeout(ctx, deadline)
   320  				defer cancel()
   321  
   322  				integtest.AddTestServerAPIVersion(clientOpts)
   323  
   324  				client, err := mongo.Connect(ctx, clientOpts)
   325  				assert.Nil(mt, err, "Connect error in setup: %v", err)
   326  
   327  				coll := mt.CreateCollection(mtest.Collection{
   328  					Name:   tcase.collectionName,
   329  					Client: client,
   330  				}, false)
   331  
   332  				tcase.setup(ctx, mt, coll)
   333  			}
   334  
   335  			// If there is no operation, then we don't need to run
   336  			// the test case.
   337  			if tcase.operation == nil {
   338  				return
   339  			}
   340  
   341  			// If there are no log validators, then we should error.
   342  			if len(tcase.orderedLogValidators) == 0 {
   343  				mt.Fatalf("no log validators provided")
   344  			}
   345  
   346  			sinkCtx, sinkCancel := context.WithDeadline(ctx, time.Now().Add(deadline))
   347  			defer sinkCancel()
   348  
   349  			validator := func(order int, level int, msg string, keysAndValues ...interface{}) error {
   350  				// If the order exceeds the length of the
   351  				// "orderedCaseValidators," then throw an error.
   352  				if order >= len(tcase.orderedLogValidators) {
   353  					return fmt.Errorf("not enough expected cases to validate")
   354  				}
   355  
   356  				caseValidator := tcase.orderedLogValidators[order]
   357  				if caseValidator == nil {
   358  					return nil
   359  				}
   360  
   361  				return tcase.orderedLogValidators[order](keysAndValues...)
   362  			}
   363  
   364  			sink := newTestLogSink(sinkCtx, mt, len(tcase.orderedLogValidators), validator)
   365  
   366  			// Configure logging with a minimum severity level of
   367  			// "debug" for the "command" component without
   368  			// explicitly configuring the max document length.
   369  			loggerOpts := options.Logger().SetSink(sink).
   370  				SetComponentLevel(options.LogComponentCommand, options.LogLevelDebug)
   371  
   372  			// If the test case requires a maximum document length,
   373  			// then configure it.
   374  			if mdl := tcase.maxDocumentLength; mdl != 0 {
   375  				loggerOpts.SetMaxDocumentLength(mdl)
   376  			}
   377  
   378  			clientOpts := options.Client().SetLoggerOptions(loggerOpts).ApplyURI(mtest.ClusterURI())
   379  
   380  			integtest.AddTestServerAPIVersion(clientOpts)
   381  
   382  			client, err := mongo.Connect(context.Background(), clientOpts)
   383  			assert.Nil(mt, err, "Connect error: %v", err)
   384  
   385  			coll := mt.CreateCollection(mtest.Collection{
   386  				Name:   tcase.collectionName,
   387  				Client: client,
   388  			}, false)
   389  
   390  			tcase.operation(ctx, mt, coll)
   391  
   392  			// Verify the logs.
   393  			if err := <-sink.errs(); err != nil {
   394  				mt.Fatalf("unexpected error: %v", err)
   395  			}
   396  		})
   397  	}
   398  }
   399
View as plain text