SERVER-50085 Make it easier to correlate mongo process names, ports, PIDs in logs of fixtures started by resmoke

10 files changed, 100 insertions, 2 deletions

diff --git a/buildscripts/resmokelib/testing/fixtures/interface.py b/buildscripts/resmokelib/testing/fixtures/interface.py
index b0daebfd415..ad6be804cd6 100644
--- a/buildscripts/resmokelib/testing/fixtures/interface.py
+++ b/buildscripts/resmokelib/testing/fixtures/interface.py
@@ -3,6 +3,8 @@
 import os.path
 import time
 from enum import Enum
+from collections import namedtuple
+from typing import List
 
 import pymongo
 import pymongo.errors
@@ -112,6 +114,10 @@ class Fixture(object, metaclass=registry.make_registry_metaclass(_FIXTURES)):
         """Return true if the fixture is still operating and more tests and can be run."""
         return True
 
+    def get_node_info(self):  # pylint: disable=no-self-use
+        """Return a list of NodeInfo objects."""
+        return []
+
     def get_dbpath_prefix(self):
         """Return dbpath prefix."""
         return self._dbpath_prefix
@@ -283,3 +289,55 @@ class FixtureTeardownHandler(object):
             self._message = message
         else:
             self._message = "{} - {}".format(self._message, message)
+
+
+def create_fixture_table(fixture):
+    """Get fixture node info, make it a pretty table. Return it or None if fixture is invalid target."""
+    info: List[NodeInfo] = fixture.get_node_info()
+    if not info:
+        return None
+
+    columns = {}
+    longest = {}
+    for key in NodeInfo._fields:
+        longest[key] = len(key)
+        columns[key] = []
+        for node in info:
+            value = str(getattr(node, key))
+            columns[key].append(value)
+            longest[key] = max(longest[key], len(value))
+
+    def horizontal_separator():
+        row = ""
+        for key in columns:
+            row += "+" + "-" * (longest[key])
+        row += "+"
+        return row
+
+    def title_row():
+        row = ""
+        for key in columns:
+            row += "|" + key + " " * (longest[key] - len(key))
+        row += "|"
+        return row
+
+    def data_row(i):
+        row = ""
+        for key in columns:
+            row += "|" + columns[key][i] + " " * (longest[key] - len(columns[key][i]))
+        row += "|"
+        return row
+
+    table = ""
+    table += horizontal_separator() + "\n"
+    table += title_row() + "\n"
+    table += horizontal_separator() + "\n"
+    for i in range(len(info)):
+        table += data_row(i) + "\n"
+    table += horizontal_separator()
+
+    return "Fixture status:\n" + table
+
+
+# Represents a row in a node info table.
+NodeInfo = namedtuple('NodeInfo', ['name', 'port', 'pid'])
diff --git a/buildscripts/resmokelib/testing/fixtures/replicaset.py b/buildscripts/resmokelib/testing/fixtures/replicaset.py
index 0dc25d9c0cd..85c4366fe4b 100644
--- a/buildscripts/resmokelib/testing/fixtures/replicaset.py
+++ b/buildscripts/resmokelib/testing/fixtures/replicaset.py
@@ -636,6 +636,13 @@ class ReplicaSetFixture(interface.ReplFixture):  # pylint: disable=too-many-inst
             conn_strs.append(self.initial_sync_node.get_internal_connection_string())
         return self.replset_name + "/" + ",".join(conn_strs)
 
+    def get_node_info(self):
+        """Return a list of dicts of NodeInfo objects."""
+        output = []
+        for node in self.nodes:
+            output += node.get_node_info()
+        return output
+
     def get_driver_connection_url(self):
         """Return the driver connection URL."""
         if self.replset_name is None:
diff --git a/buildscripts/resmokelib/testing/fixtures/shardedcluster.py b/buildscripts/resmokelib/testing/fixtures/shardedcluster.py
index 4957f462b6b..839780f2614 100644
--- a/buildscripts/resmokelib/testing/fixtures/shardedcluster.py
+++ b/buildscripts/resmokelib/testing/fixtures/shardedcluster.py
@@ -242,6 +242,15 @@ class ShardedClusterFixture(interface.Fixture):  # pylint: disable=too-many-inst
         """Return the driver connection URL."""
         return "mongodb://" + self.get_internal_connection_string()
 
+    def get_node_info(self):
+        """Return a list of dicts of NodeInfo objects."""
+        output = []
+        for shard in self.shards:
+            output += shard.get_node_info()
+        for mongos in self.mongos:
+            output += mongos.get_node_info()
+        return output + self.configsvr.get_node_info()
+
     def _new_configsvr(self):
         """Return a replicaset.ReplicaSetFixture configured as the config server."""
 
@@ -493,3 +502,8 @@ class _MongoSFixture(interface.Fixture):
     def get_driver_connection_url(self):
         """Return the driver connection URL."""
         return "mongodb://" + self.get_internal_connection_string()
+
+    def get_node_info(self):
+        """Return a list of NodeInfo objects."""
+        info = interface.NodeInfo(name=self.logger.name, port=self.port, pid=self.mongos.pid)
+        return [info]
diff --git a/buildscripts/resmokelib/testing/fixtures/standalone.py b/buildscripts/resmokelib/testing/fixtures/standalone.py
index b820a60241d..56f4ca960a1 100644
--- a/buildscripts/resmokelib/testing/fixtures/standalone.py
+++ b/buildscripts/resmokelib/testing/fixtures/standalone.py
@@ -159,6 +159,11 @@ class MongoDFixture(interface.Fixture):
         """Return the _dbpath, as this is the root of the data directory."""
         return self._dbpath
 
+    def get_node_info(self):
+        """Return a list of NodeInfo objects."""
+        info = interface.NodeInfo(name=self.logger.name, port=self.port, pid=self.mongod.pid)
+        return [info]
+
     def get_internal_connection_string(self):
         """Return the internal connection string."""
         if self.mongod is None:
diff --git a/buildscripts/resmokelib/testing/hooks/initialsync.py b/buildscripts/resmokelib/testing/hooks/initialsync.py
index 003d988bb84..096a7ab005b 100644
--- a/buildscripts/resmokelib/testing/hooks/initialsync.py
+++ b/buildscripts/resmokelib/testing/hooks/initialsync.py
@@ -130,6 +130,7 @@ class BackgroundInitialSyncTestCase(jsfile.DynamicJSTestCase):
 
         self.logger.info("Starting the initial sync node back up again...")
         sync_node.setup()
+        self.logger.info(fixture_interface.create_fixture_table(self.fixture))
         sync_node.await_ready()
 
 
diff --git a/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py b/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py
index 5e516156e44..dfb4f707fce 100644
--- a/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py
+++ b/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py
@@ -193,6 +193,7 @@ class PeriodicKillSecondariesTestCase(interface.DynamicTestCase):
             # Start the 'secondary' mongod back up as part of the replica set and wait for it to
             # reach state SECONDARY.
             secondary.setup()
+            self.logger.info(fixture.create_fixture_table(self.fixture))
             secondary.await_ready()
             self._await_secondary_state(secondary)
 
@@ -208,6 +209,7 @@ class PeriodicKillSecondariesTestCase(interface.DynamicTestCase):
 
         try:
             self.fixture.setup()
+            self.logger.info(fixture.create_fixture_table(self.fixture))
             self.fixture.await_ready()
         finally:
             for (i, node) in enumerate(self.fixture.nodes):
@@ -250,6 +252,7 @@ class PeriodicKillSecondariesTestCase(interface.DynamicTestCase):
 
         self.logger.info("Starting the fixture back up again with no data...")
         self.fixture.setup()
+        self.logger.info(fixture.create_fixture_table(self.fixture))
         self.fixture.await_ready()
 
     def _check_invariants_as_standalone(self, secondary):  # pylint: disable=too-many-locals
@@ -262,6 +265,7 @@ class PeriodicKillSecondariesTestCase(interface.DynamicTestCase):
 
         try:
             secondary.setup()
+            self.logger.info(fixture.create_fixture_table(self.fixture))
             secondary.await_ready()
 
             client = secondary.mongo_client()
diff --git a/buildscripts/resmokelib/testing/hooks/stepdown.py b/buildscripts/resmokelib/testing/hooks/stepdown.py
index 849091af00d..ea0bffab88b 100644
--- a/buildscripts/resmokelib/testing/hooks/stepdown.py
+++ b/buildscripts/resmokelib/testing/hooks/stepdown.py
@@ -89,7 +89,7 @@ class ContinuousStepdown(interface.Hook):  # pylint: disable=too-many-instance-a
         self._stepdown_thread = _StepdownThread(
             self.logger, self._mongos_fixtures, self._rs_fixtures, self._stepdown_interval_secs,
             self._terminate, self._kill, lifecycle, self._wait_for_mongos_retarget,
-            self._stepdown_via_heartbeats, self._background_reconfig)
+            self._stepdown_via_heartbeats, self._background_reconfig, self._fixture)
         self.logger.info("Starting the stepdown thread.")
         self._stepdown_thread.start()
 
@@ -343,7 +343,7 @@ class _StepdownThread(threading.Thread):  # pylint: disable=too-many-instance-at
     def __init__(  # pylint: disable=too-many-arguments
             self, logger, mongos_fixtures, rs_fixtures, stepdown_interval_secs, terminate, kill,
             stepdown_lifecycle, wait_for_mongos_retarget, stepdown_via_heartbeats,
-            background_reconfig):
+            background_reconfig, fixture):
         """Initialize _StepdownThread."""
         threading.Thread.__init__(self, name="StepdownThread")
         self.daemon = True
@@ -361,6 +361,7 @@ class _StepdownThread(threading.Thread):  # pylint: disable=too-many-instance-at
         self._should_wait_for_mongos_retarget = wait_for_mongos_retarget
         self._stepdown_via_heartbeats = stepdown_via_heartbeats
         self._background_reconfig = background_reconfig
+        self._fixture = fixture
 
         self._last_exec = time.time()
         # Event set when the thread has been stopped using the 'stop()' method.
@@ -585,6 +586,7 @@ class _StepdownThread(threading.Thread):  # pylint: disable=too-many-instance-at
             primary.preserve_dbpath = True
             try:
                 primary.setup()
+                self.logger.info(fixture_interface.create_fixture_table(self._fixture))
                 primary.await_ready()
             finally:
                 primary.preserve_dbpath = original_preserve_dbpath
diff --git a/buildscripts/resmokelib/testing/job.py b/buildscripts/resmokelib/testing/job.py
index ead33dd7c8b..ecf37d18700 100644
--- a/buildscripts/resmokelib/testing/job.py
+++ b/buildscripts/resmokelib/testing/job.py
@@ -3,12 +3,14 @@
 import sys
 import time
 from collections import namedtuple
+from collections import defaultdict
 
 from buildscripts.resmokelib import config
 from buildscripts.resmokelib import errors
 from buildscripts.resmokelib.testing import testcases
 from buildscripts.resmokelib.testing.hooks import stepdown
 from buildscripts.resmokelib.testing.testcases import fixture as _fixture
+from buildscripts.resmokelib.testing.fixtures.interface import create_fixture_table
 from buildscripts.resmokelib.utils import queue as _queue
 
 
@@ -164,6 +166,7 @@ class Job(object):  # pylint: disable=too-many-instance-attributes
 
         test.configure(self.fixture, config.NUM_CLIENTS_PER_FIXTURE)
         self._run_hooks_before_tests(test)
+        self.report.logging_prefix = create_fixture_table(self.fixture)
 
         test(self.report)
         try:
diff --git a/buildscripts/resmokelib/testing/report.py b/buildscripts/resmokelib/testing/report.py
index a8d51473938..46e3df33e9d 100644
--- a/buildscripts/resmokelib/testing/report.py
+++ b/buildscripts/resmokelib/testing/report.py
@@ -30,6 +30,7 @@ class TestReport(unittest.TestResult):  # pylint: disable=too-many-instance-attr
         self.job_logger = job_logger
         self.job_num = job_num
         self.suite_options = suite_options
+        self.logging_prefix = None
 
         self._lock = threading.Lock()
 
@@ -117,6 +118,8 @@ class TestReport(unittest.TestResult):  # pylint: disable=too-many-instance-attr
         (test_logger, url_endpoint) = logging.loggers.new_test_logger(
             test.short_name(), test.basename(), command, test.logger, self.job_num, self.job_logger)
         test_info.url_endpoint = url_endpoint
+        if self.logging_prefix is not None:
+            test_logger.info(self.logging_prefix)
 
         test.override_logger(test_logger)
         test_info.start_time = time.time()
diff --git a/buildscripts/tests/resmokelib/testing/hooks/test_stepdown.py b/buildscripts/tests/resmokelib/testing/hooks/test_stepdown.py
index 32436a4e346..cbc1a9f95ae 100644
--- a/buildscripts/tests/resmokelib/testing/hooks/test_stepdown.py
+++ b/buildscripts/tests/resmokelib/testing/hooks/test_stepdown.py
@@ -38,6 +38,7 @@ class TestStepdownThread(unittest.TestCase):
             wait_for_mongos_retarget=False,
             stepdown_via_heartbeats=True,
             background_reconfig=False,
+            fixture=shardcluster_fixture,
         )
 
         # doesn't throw error when fixtures are running