From 101d1e70ccbe184efcbc2679b8f3bd76c062f9b2 Mon Sep 17 00:00:00 2001 From: Qingyang Hu <103950869+qingyang-hu@users.noreply.github.com> Date: Tue, 12 Sep 2023 09:48:12 -0400 Subject: [PATCH] GODRIVER-2904 Add environment log. (#1373) * GODRIVER-2904 Add environment log. * minor updates * fix typos * fix typos * log before SRV lookup * improve logic --- .../topology/polling_srv_records_test.go | 1 + x/mongo/driver/topology/topology.go | 78 ++++-- x/mongo/driver/topology/topology_test.go | 234 ++++++++++++++++++ 3 files changed, 291 insertions(+), 22 deletions(-) diff --git a/x/mongo/driver/topology/polling_srv_records_test.go b/x/mongo/driver/topology/polling_srv_records_test.go index 0ca5c7cbce..7484109d4e 100644 --- a/x/mongo/driver/topology/polling_srv_records_test.go +++ b/x/mongo/driver/topology/polling_srv_records_test.go @@ -105,6 +105,7 @@ func (ss serverSorter) Less(i, j int) bool { } func compareHosts(t *testing.T, received []description.Server, expected []string) { + t.Helper() if len(received) != len(expected) { t.Fatalf("Number of hosts in topology does not match expected value. Got %v; want %v.", len(received), len(expected)) } diff --git a/x/mongo/driver/topology/topology.go b/x/mongo/driver/topology/topology.go index b0683021ee..b79efed4ed 100644 --- a/x/mongo/driver/topology/topology.go +++ b/x/mongo/driver/topology/topology.go @@ -161,13 +161,13 @@ func New(cfg *Config) (*Topology, error) { return t, nil } -func mustLogTopologyMessage(topo *Topology) bool { +func mustLogTopologyMessage(topo *Topology, level logger.Level) bool { return topo.cfg.logger != nil && topo.cfg.logger.LevelComponentEnabled( - logger.LevelDebug, logger.ComponentTopology) + level, logger.ComponentTopology) } -func logTopologyMessage(topo *Topology, msg string, keysAndValues ...interface{}) { - topo.cfg.logger.Print(logger.LevelDebug, +func logTopologyMessage(topo *Topology, level logger.Level, msg string, keysAndValues ...interface{}) { + topo.cfg.logger.Print(level, logger.ComponentTopology, msg, logger.SerializeTopology(logger.Topology{ @@ -176,6 +176,36 @@ func logTopologyMessage(topo *Topology, msg string, keysAndValues ...interface{} }, keysAndValues...)...) } +func logTopologyThirdPartyUsage(topo *Topology, parsedHosts []string) { + thirdPartyMessages := [2]string{ + `You appear to be connected to a CosmosDB cluster. For more information regarding feature compatibility and support please visit https://www.mongodb.com/supportability/cosmosdb`, + `You appear to be connected to a DocumentDB cluster. For more information regarding feature compatibility and support please visit https://www.mongodb.com/supportability/documentdb`, + } + + thirdPartySuffixes := map[string]int{ + ".cosmos.azure.com": 0, + ".docdb.amazonaws.com": 1, + ".docdb-elastic.amazonaws.com": 1, + } + + hostSet := make([]bool, len(thirdPartyMessages)) + for _, host := range parsedHosts { + if h, _, err := net.SplitHostPort(host); err == nil { + host = h + } + for suffix, env := range thirdPartySuffixes { + if !strings.HasSuffix(host, suffix) { + continue + } + if hostSet[env] { + break + } + hostSet[env] = true + logTopologyMessage(topo, logger.LevelInfo, thirdPartyMessages[env]) + } + } +} + func mustLogServerSelection(topo *Topology, level logger.Level) bool { return topo.cfg.logger != nil && topo.cfg.logger.LevelComponentEnabled( level, logger.ComponentServerSelection) @@ -183,8 +213,8 @@ func mustLogServerSelection(topo *Topology, level logger.Level) bool { func logServerSelection( ctx context.Context, - level logger.Level, topo *Topology, + level logger.Level, msg string, srvSelector description.ServerSelector, keysAndValues ...interface{}, @@ -224,7 +254,7 @@ func logServerSelectionSucceeded( portInt64, _ := strconv.ParseInt(port, 10, 32) - logServerSelection(ctx, logger.LevelDebug, topo, logger.ServerSelectionSucceeded, srvSelector, + logServerSelection(ctx, topo, logger.LevelDebug, logger.ServerSelectionSucceeded, srvSelector, logger.KeyServerHost, host, logger.KeyServerPort, portInt64) } @@ -235,7 +265,7 @@ func logServerSelectionFailed( srvSelector description.ServerSelector, err error, ) { - logServerSelection(ctx, logger.LevelDebug, topo, logger.ServerSelectionFailed, srvSelector, + logServerSelection(ctx, topo, logger.LevelDebug, logger.ServerSelectionFailed, srvSelector, logger.KeyFailure, err.Error()) } @@ -321,13 +351,17 @@ func (t *Topology) Connect() error { } t.serversLock.Unlock() + uri, err := url.Parse(t.cfg.URI) + if err != nil { + return err + } + parsedHosts := strings.Split(uri.Host, ",") + if mustLogTopologyMessage(t, logger.LevelInfo) { + logTopologyThirdPartyUsage(t, parsedHosts) + } if t.pollingRequired { - uri, err := url.Parse(t.cfg.URI) - if err != nil { - return err - } // sanity check before passing the hostname to resolver - if parsedHosts := strings.Split(uri.Host, ","); len(parsedHosts) != 1 { + if len(parsedHosts) != 1 { return fmt.Errorf("URI with SRV must include one and only one hostname") } _, _, err = net.SplitHostPort(uri.Host) @@ -492,7 +526,7 @@ func (t *Topology) SelectServer(ctx context.Context, ss description.ServerSelect if !doneOnce { if mustLogServerSelection(t, logger.LevelDebug) { - logServerSelection(ctx, logger.LevelDebug, t, logger.ServerSelectionStarted, ss) + logServerSelection(ctx, t, logger.LevelDebug, logger.ServerSelectionStarted, ss) } // for the first pass, select a server from the current description. @@ -531,7 +565,7 @@ func (t *Topology) SelectServer(ctx context.Context, ss description.ServerSelect elapsed := time.Since(startTime) remainingTimeMS := t.cfg.ServerSelectionTimeout - elapsed - logServerSelection(ctx, logger.LevelInfo, t, logger.ServerSelectionWaiting, ss, + logServerSelection(ctx, t, logger.LevelInfo, logger.ServerSelectionWaiting, ss, logger.KeyRemainingTimeMS, remainingTimeMS.Milliseconds()) } @@ -970,7 +1004,7 @@ func (t *Topology) publishServerClosedEvent(addr address.Address) { t.cfg.ServerMonitor.ServerClosed(serverClosed) } - if mustLogTopologyMessage(t) { + if mustLogTopologyMessage(t, logger.LevelDebug) { serverHost, serverPort, err := net.SplitHostPort(addr.String()) if err != nil { serverHost = addr.String() @@ -979,7 +1013,7 @@ func (t *Topology) publishServerClosedEvent(addr address.Address) { portInt64, _ := strconv.ParseInt(serverPort, 10, 32) - logTopologyMessage(t, logger.TopologyServerClosed, + logTopologyMessage(t, logger.LevelDebug, logger.TopologyServerClosed, logger.KeyServerHost, serverHost, logger.KeyServerPort, portInt64) } @@ -997,8 +1031,8 @@ func (t *Topology) publishTopologyDescriptionChangedEvent(prev description.Topol t.cfg.ServerMonitor.TopologyDescriptionChanged(topologyDescriptionChanged) } - if mustLogTopologyMessage(t) { - logTopologyMessage(t, logger.TopologyDescriptionChanged, + if mustLogTopologyMessage(t, logger.LevelDebug) { + logTopologyMessage(t, logger.LevelDebug, logger.TopologyDescriptionChanged, logger.KeyPreviousDescription, prev.String(), logger.KeyNewDescription, current.String()) } @@ -1014,8 +1048,8 @@ func (t *Topology) publishTopologyOpeningEvent() { t.cfg.ServerMonitor.TopologyOpening(topologyOpening) } - if mustLogTopologyMessage(t) { - logTopologyMessage(t, logger.TopologyOpening) + if mustLogTopologyMessage(t, logger.LevelDebug) { + logTopologyMessage(t, logger.LevelDebug, logger.TopologyOpening) } } @@ -1029,7 +1063,7 @@ func (t *Topology) publishTopologyClosedEvent() { t.cfg.ServerMonitor.TopologyClosed(topologyClosed) } - if mustLogTopologyMessage(t) { - logTopologyMessage(t, logger.TopologyClosed) + if mustLogTopologyMessage(t, logger.LevelDebug) { + logTopologyMessage(t, logger.LevelDebug, logger.TopologyClosed) } } diff --git a/x/mongo/driver/topology/topology_test.go b/x/mongo/driver/topology/topology_test.go index 773a8b6475..6cf540a95e 100644 --- a/x/mongo/driver/topology/topology_test.go +++ b/x/mongo/driver/topology/topology_test.go @@ -693,6 +693,240 @@ func TestTopologyConstruction(t *testing.T) { }) } +type mockLogSink struct { + msgs []string +} + +func (s *mockLogSink) Info(_ int, msg string, _ ...interface{}) { + s.msgs = append(s.msgs, msg) +} +func (*mockLogSink) Error(error, string, ...interface{}) { + // Do nothing. +} + +// Note: SRV connection strings are intentionally untested, since initial +// lookup responses cannot be easily mocked. +func TestTopologyConstructionLogging(t *testing.T) { + const ( + cosmosDBMsg = `You appear to be connected to a CosmosDB cluster. For more information regarding feature compatibility and support please visit https://www.mongodb.com/supportability/cosmosdb` + documentDBMsg = `You appear to be connected to a DocumentDB cluster. For more information regarding feature compatibility and support please visit https://www.mongodb.com/supportability/documentdb` + ) + + newLoggerOptions := func(sink options.LogSink) *options.LoggerOptions { + return options. + Logger(). + SetSink(sink). + SetComponentLevel(options.LogComponentTopology, options.LogLevelInfo) + } + + t.Run("CosmosDB URIs", func(t *testing.T) { + t.Parallel() + + testCases := []struct { + name string + uri string + msgs []string + }{ + { + name: "normal", + uri: "mongodb://a.mongo.cosmos.azure.com:19555/", + msgs: []string{cosmosDBMsg}, + }, + { + name: "multiple hosts", + uri: "mongodb://a.mongo.cosmos.azure.com:1955,b.mongo.cosmos.azure.com:19555/", + msgs: []string{cosmosDBMsg}, + }, + { + name: "case-insensitive matching", + uri: "mongodb://a.MONGO.COSMOS.AZURE.COM:19555/", + msgs: []string{}, + }, + { + name: "Mixing genuine and nongenuine hosts (unlikely in practice)", + uri: "mongodb://a.example.com:27017,b.mongo.cosmos.azure.com:19555/", + msgs: []string{cosmosDBMsg}, + }, + } + for _, tc := range testCases { + tc := tc + + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + sink := &mockLogSink{} + cfg, err := NewConfig(options.Client().ApplyURI(tc.uri).SetLoggerOptions(newLoggerOptions(sink)), nil) + require.Nil(t, err, "error constructing topology config: %v", err) + + topo, err := New(cfg) + require.Nil(t, err, "topology.New error: %v", err) + + err = topo.Connect() + assert.Nil(t, err, "Connect error: %v", err) + + assert.ElementsMatch(t, tc.msgs, sink.msgs, "expected messages to be %v, got %v", tc.msgs, sink.msgs) + }) + } + }) + t.Run("DocumentDB URIs", func(t *testing.T) { + t.Parallel() + + testCases := []struct { + name string + uri string + msgs []string + }{ + { + name: "normal", + uri: "mongodb://a.docdb.amazonaws.com:27017/", + msgs: []string{documentDBMsg}, + }, + { + name: "normal", + uri: "mongodb://a.docdb-elastic.amazonaws.com:27017/", + msgs: []string{documentDBMsg}, + }, + { + name: "multiple hosts", + uri: "mongodb://a.docdb.amazonaws.com:27017,a.docdb-elastic.amazonaws.com:27017/", + msgs: []string{documentDBMsg}, + }, + { + name: "case-insensitive matching", + uri: "mongodb://a.DOCDB.AMAZONAWS.COM:27017/", + msgs: []string{}, + }, + { + name: "case-insensitive matching", + uri: "mongodb://a.DOCDB-ELASTIC.AMAZONAWS.COM:27017/", + msgs: []string{}, + }, + { + name: "Mixing genuine and nongenuine hosts (unlikely in practice)", + uri: "mongodb://a.example.com:27017,b.docdb.amazonaws.com:27017/", + msgs: []string{documentDBMsg}, + }, + { + name: "Mixing genuine and nongenuine hosts (unlikely in practice)", + uri: "mongodb://a.example.com:27017,b.docdb-elastic.amazonaws.com:27017/", + msgs: []string{documentDBMsg}, + }, + } + for _, tc := range testCases { + tc := tc + + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + sink := &mockLogSink{} + cfg, err := NewConfig(options.Client().ApplyURI(tc.uri).SetLoggerOptions(newLoggerOptions(sink)), nil) + require.Nil(t, err, "error constructing topology config: %v", err) + + topo, err := New(cfg) + require.Nil(t, err, "topology.New error: %v", err) + + err = topo.Connect() + assert.Nil(t, err, "Connect error: %v", err) + + assert.ElementsMatch(t, tc.msgs, sink.msgs, "expected messages to be %v, got %v", tc.msgs, sink.msgs) + }) + } + }) + t.Run("Mixing CosmosDB and DocumentDB URIs", func(t *testing.T) { + t.Parallel() + + testCases := []struct { + name string + uri string + msgs []string + }{ + { + name: "Mixing hosts", + uri: "mongodb://a.mongo.cosmos.azure.com:19555,a.docdb.amazonaws.com:27017/", + msgs: []string{cosmosDBMsg, documentDBMsg}, + }, + } + for _, tc := range testCases { + tc := tc + + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + sink := &mockLogSink{} + cfg, err := NewConfig(options.Client().ApplyURI(tc.uri).SetLoggerOptions(newLoggerOptions(sink)), nil) + require.Nil(t, err, "error constructing topology config: %v", err) + + topo, err := New(cfg) + require.Nil(t, err, "topology.New error: %v", err) + + err = topo.Connect() + assert.Nil(t, err, "Connect error: %v", err) + + assert.ElementsMatch(t, tc.msgs, sink.msgs, "expected messages to be %v, got %v", tc.msgs, sink.msgs) + }) + } + }) + t.Run("genuine URIs", func(t *testing.T) { + t.Parallel() + + testCases := []struct { + name string + uri string + msgs []string + }{ + { + name: "normal", + uri: "mongodb://a.example.com:27017/", + msgs: []string{}, + }, + { + name: "srv", + uri: "mongodb+srv://test22.test.build.10gen.cc/?srvServiceName=customname", + msgs: []string{}, + }, + { + name: "multiple hosts", + uri: "mongodb://a.example.com:27017,b.example.com:27017/", + msgs: []string{}, + }, + { + name: "unexpected suffix", + uri: "mongodb://a.mongo.cosmos.azure.com.tld:19555/", + msgs: []string{}, + }, + { + name: "unexpected suffix", + uri: "mongodb://a.docdb.amazonaws.com.tld:27017/", + msgs: []string{}, + }, + { + name: "unexpected suffix", + uri: "mongodb://a.docdb-elastic.amazonaws.com.tld:27017/", + msgs: []string{}, + }, + } + for _, tc := range testCases { + tc := tc + + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + sink := &mockLogSink{} + cfg, err := NewConfig(options.Client().ApplyURI(tc.uri).SetLoggerOptions(newLoggerOptions(sink)), nil) + require.Nil(t, err, "error constructing topology config: %v", err) + + topo, err := New(cfg) + require.Nil(t, err, "topology.New error: %v", err) + + err = topo.Connect() + assert.Nil(t, err, "Connect error: %v", err) + + assert.ElementsMatch(t, tc.msgs, sink.msgs, "expected messages to be %v, got %v", tc.msgs, sink.msgs) + }) + } + }) +} + type inWindowServer struct { Address string `json:"address"` Type string `json:"type"`