diff options
Diffstat (limited to 'buildscripts/resmokelib/testing')
11 files changed, 209 insertions, 570 deletions
diff --git a/buildscripts/resmokelib/testing/fixtures/standalone.py b/buildscripts/resmokelib/testing/fixtures/standalone.py index 55c23923ecc..394c025d510 100644 --- a/buildscripts/resmokelib/testing/fixtures/standalone.py +++ b/buildscripts/resmokelib/testing/fixtures/standalone.py @@ -4,8 +4,6 @@ import os import os.path import time import shutil -import uuid - import yaml import pymongo @@ -25,9 +23,6 @@ class MongoDFixture(interface.Fixture): self.mongod_options = self.fixturelib.make_historic( self.fixturelib.default_if_none(mongod_options, {})) - if "set_parameters" not in self.mongod_options: - self.mongod_options["set_parameters"] = {} - if add_feature_flags: for ff in self.config.ENABLED_FEATURE_FLAGS: self.mongod_options["set_parameters"][ff] = "true" @@ -57,11 +52,6 @@ class MongoDFixture(interface.Fixture): self.port = port or fixturelib.get_next_port(job_num) self.mongod_options["port"] = self.port - # Always log backtraces to a file in the dbpath in our testing. - backtrace_log_file_name = os.path.join(self.get_dbpath_prefix(), - uuid.uuid4().hex + ".stacktrace") - self.mongod_options["set_parameters"]["backtraceLogFile"] = backtrace_log_file_name - def setup(self): """Set up the mongod.""" if not self.preserve_dbpath and os.path.lexists(self._dbpath): @@ -71,8 +61,7 @@ class MongoDFixture(interface.Fixture): launcher = MongodLauncher(self.fixturelib) # Second return val is the port, which we ignore because we explicitly created the port above. - # The port is used to set other mongod_option's here: - # https://github.com/mongodb/mongo/blob/532a6a8ae7b8e7ab5939e900759c00794862963d/buildscripts/resmokelib/testing/fixtures/replicaset.py#L136 + # The port is used to set other mongod_option's here: https://github.com/mongodb/mongo/blob/532a6a8ae7b8e7ab5939e900759c00794862963d/buildscripts/resmokelib/testing/fixtures/replicaset.py#L136 mongod, _ = launcher.launch_mongod_program(self.logger, self.job_num, executable=self.mongod_executable, mongod_options=self.mongod_options) @@ -179,7 +168,7 @@ class MongoDFixture(interface.Fixture): def get_driver_connection_url(self): """Return the driver connection URL.""" - return "mongodb://" + self.get_internal_connection_string() + "/?directConnection=true" + return "mongodb://" + self.get_internal_connection_string() # The below parameters define the default 'logComponentVerbosity' object passed to mongod processes @@ -191,16 +180,15 @@ class MongoDFixture(interface.Fixture): # The default verbosity setting for any tests that are not started with an Evergreen task id. This # will apply to any tests run locally. DEFAULT_MONGOD_LOG_COMPONENT_VERBOSITY = { - "replication": {"rollback": 2}, "sharding": {"migration": 2, "rangeDeleter": 2}, - "transaction": 4, "tenantMigration": 4 + "replication": {"rollback": 2}, "sharding": {"migration": 2}, "transaction": 4, + "tenantMigration": 4 } # The default verbosity setting for any mongod processes running in Evergreen i.e. started with an # Evergreen task id. DEFAULT_EVERGREEN_MONGOD_LOG_COMPONENT_VERBOSITY = { - "replication": {"election": 4, "heartbeats": 2, "initialSync": 2, - "rollback": 2}, "sharding": {"migration": 2, "rangeDeleter": 2}, - "storage": {"recovery": 2}, "transaction": 4, "tenantMigration": 4 + "replication": {"election": 4, "heartbeats": 2, "initialSync": 2, "rollback": 2}, + "sharding": {"migration": 2}, "storage": {"recovery": 2}, "transaction": 4, "tenantMigration": 4 } @@ -254,15 +242,6 @@ class MongodLauncher(object): if "shardsvr" in mongod_options and "orphanCleanupDelaySecs" not in suite_set_parameters: suite_set_parameters["orphanCleanupDelaySecs"] = 1 - # receiveChunkWaitForRangeDeleterTimeoutMS controls the amount of time an incoming migration - # will wait for an intersecting range with data in it to be cleared up before failing. The - # default is 10 seconds, but in some slower variants this is not enough time for the range - # deleter to finish so we increase it here to 90 seconds. Setting a value for this parameter - # in the .yml file overrides this. - if (("shardsvr" in mongod_options or "configsvr" in mongod_options) - and "receiveChunkWaitForRangeDeleterTimeoutMS" not in suite_set_parameters): - suite_set_parameters["receiveChunkWaitForRangeDeleterTimeoutMS"] = 90000 - # The LogicalSessionCache does automatic background refreshes in the server. This is # race-y for tests, since tests trigger their own immediate refreshes instead. Turn off # background refreshing for tests. Set in the .yml file to override this. @@ -313,13 +292,6 @@ class MongodLauncher(object): "mode": "alwaysOn", "data": {"numTickets": self.config.FLOW_CONTROL_TICKETS} } - # The internalQueryForceClassicEngine parameter was renamed to - # internalQueryFrameworkControl starting in version 6.1. - if "internalQueryFrameworkControl" in suite_set_parameters and suite_set_parameters[ - "internalQueryFrameworkControl"] == "forceClassicEngine": - del suite_set_parameters["internalQueryFrameworkControl"] - suite_set_parameters["internalQueryForceClassicEngine"] = True - _add_testing_set_parameters(suite_set_parameters) shortcut_opts = { @@ -396,7 +368,3 @@ def _add_testing_set_parameters(suite_set_parameters): """ suite_set_parameters.setdefault("testingDiagnosticsEnabled", True) suite_set_parameters.setdefault("enableTestCommands", True) - # The exact file location is on a per-process basis, so it'll have to be determined when the process gets spun up. - # Set it to true for now as a placeholder that will error if no further processing is done. - # The placeholder is needed so older versions don't have this option won't have this value set. - suite_set_parameters.setdefault("backtraceLogFile", True) diff --git a/buildscripts/resmokelib/testing/hook_test_archival.py b/buildscripts/resmokelib/testing/hook_test_archival.py index 23ebfda8de3..38909056ce3 100644 --- a/buildscripts/resmokelib/testing/hook_test_archival.py +++ b/buildscripts/resmokelib/testing/hook_test_archival.py @@ -6,7 +6,6 @@ import threading from buildscripts.resmokelib import config from buildscripts.resmokelib import errors from buildscripts.resmokelib import utils -from buildscripts.resmokelib.flags import HANG_ANALYZER_CALLED from buildscripts.resmokelib.utils import globstar @@ -106,9 +105,5 @@ class HookTestArchival(object): else: logger.info("Archive succeeded for %s: %s", test_name, message) - if HANG_ANALYZER_CALLED.is_set(): - logger.info("Hang Analyzer has been called. Fixtures will not be restarted.") - raise errors.StopExecution( - "Hang analyzer has been called. Stopping further execution of tests.") - elif not manager.setup_fixture(logger): + if not manager.setup_fixture(logger): raise errors.StopExecution("Error while restarting test fixtures after archiving.") diff --git a/buildscripts/resmokelib/testing/hooks/aggregate_metrics_background.py b/buildscripts/resmokelib/testing/hooks/aggregate_metrics_background.py index c45f93192eb..d392c6ae0b8 100644 --- a/buildscripts/resmokelib/testing/hooks/aggregate_metrics_background.py +++ b/buildscripts/resmokelib/testing/hooks/aggregate_metrics_background.py @@ -4,70 +4,70 @@ This hook runs continuously, but the run_aggregate_metrics_background.js file it internally sleep for 1 second between runs. """ -import random -import pymongo +import os.path -from buildscripts.resmokelib.testing.hooks.bghook import BGHook +from buildscripts.resmokelib import errors +from buildscripts.resmokelib.testing.hooks import jsfile +from buildscripts.resmokelib.testing.hooks.background_job import _BackgroundJob, _ContinuousDynamicJSTestCase -def verify_metrics(doc): - """Checks whether the output from $operatiomMetrics has the schema we expect.""" +class AggregateResourceConsumptionMetricsInBackground(jsfile.JSHook): + """A hook to run $operationMetrics stage in the background.""" - top_level_fields = [ - "docBytesWritten", "docUnitsWritten", "idxEntryBytesWritten", "idxEntryUnitsWritten", - "totalUnitsWritten", "cpuNanos", "db", "primaryMetrics", "secondaryMetrics" - ] - read_fields = [ - "docBytesRead", "docUnitsRead", "idxEntryBytesRead", "idxEntryUnitsRead", "keysSorted", - "docUnitsReturned" - ] + IS_BACKGROUND = True - for key in top_level_fields: - assert key in doc, ("The metrics output is missing the property: " + key) + def __init__(self, hook_logger, fixture, shell_options=None): + """Initialize AggregateResourceConsumptionMetricsInBackground.""" + description = "Run background $operationMetrics on all mongods while a test is running" + js_filename = os.path.join("jstests", "hooks", "run_aggregate_metrics_background.js") + jsfile.JSHook.__init__(self, hook_logger, fixture, js_filename, description, + shell_options=shell_options) + self._background_job = None - primary_metrics = doc["primaryMetrics"] - for key in read_fields: - assert key in primary_metrics, ( - "The metrics output is missing the property: primaryMetrics." + key) + def before_suite(self, test_report): + """Start the background thread.""" + self._background_job = _BackgroundJob("AggregateResourceConsumptionMetricsInBackground") + self.logger.info("Starting the background aggregate metrics thread.") + self._background_job.start() - secondary_metrics = doc["secondaryMetrics"] - for key in read_fields: - assert key in secondary_metrics, ( - "The metrics output is missing the property: secondaryMetrics." + key) + def after_suite(self, test_report, teardown_flag=None): + """Signal the background aggregate metrics thread to exit, and wait until it does.""" + if self._background_job is None: + return + self.logger.info("Stopping the background aggregate metrics thread.") + self._background_job.stop() -class AggregateResourceConsumptionMetricsInBackground(BGHook): - """A hook to run $operationMetrics stage in the background.""" + def before_test(self, test, test_report): + """Instruct the background aggregate metrics thread to run while 'test' is also running.""" + if self._background_job is None: + return - def __init__(self, hook_logger, fixture): - """Initialize AggregateResourceConsumptionMetricsInBackground.""" + hook_test_case = _ContinuousDynamicJSTestCase.create_before_test( + test.logger, test, self, self._js_filename, self._shell_options) + hook_test_case.configure(self.fixture) - description = "Run background $operationMetrics on all mongods while a test is running" - super().__init__(hook_logger, fixture, description, tests_per_cycle=None, - loop_delay_ms=1000) - - def run_action(self): - """Collects $operationMetrics on all non-arbiter nodes in the fixture.""" - for node_info in self.fixture.get_node_info(): - conn = pymongo.MongoClient(port=node_info.port) - # Filter out arbiters. - if "arbiterOnly" in conn.admin.command({"isMaster": 1}): - self.logger.info( - "Skipping background aggregation against test node: %s because it is an " + - "arbiter and has no data.", node_info.full_name) - return - - # Clear the metrics about 10% of the time. - clear_metrics = random.random() < 0.1 - self.logger.info("Running $operationMetrics with {clearMetrics: %s} on host: %s", - clear_metrics, node_info.full_name) - with conn.admin.aggregate( - [{"$operationMetrics": {"clearMetrics": clear_metrics}}]) as cursor: - for doc in cursor: - try: - verify_metrics(doc) - except: - self.logger.info( - "caught exception while verifying that all expected fields are in the" + - " metrics output: ", doc) - raise + self.logger.info("Resuming the background aggregate metrics thread.") + self._background_job.resume(hook_test_case, test_report) + + def after_test(self, test, test_report): # noqa: D205,D400 + """Instruct the background aggregate metrics thread to stop running now that 'test' has + finished running. + """ + if self._background_job is None: + return + + self.logger.info("Pausing the background aggregate metrics thread.") + self._background_job.pause() + + if self._background_job.exc_info is not None: + if isinstance(self._background_job.exc_info[1], errors.TestFailure): + # If the mongo shell process running the JavaScript file exited with a non-zero + # return code, then we raise an errors.ServerFailure exception to cause resmoke.py's + # test execution to stop. + raise errors.ServerFailure(self._background_job.exc_info[1].args[0]) + else: + self.logger.error( + "Encountered an error inside the background aggregate metrics thread.", + exc_info=self._background_job.exc_info) + raise self._background_job.exc_info[1] diff --git a/buildscripts/resmokelib/testing/hooks/background_job.py b/buildscripts/resmokelib/testing/hooks/background_job.py index cd775aabd4a..92dbb5437a4 100644 --- a/buildscripts/resmokelib/testing/hooks/background_job.py +++ b/buildscripts/resmokelib/testing/hooks/background_job.py @@ -3,7 +3,6 @@ import sys import threading -from buildscripts.resmokelib import errors from buildscripts.resmokelib.testing.hooks import jsfile diff --git a/buildscripts/resmokelib/testing/hooks/bghook.py b/buildscripts/resmokelib/testing/hooks/bghook.py index 1b3fed3b104..b61f37b4e2d 100644 --- a/buildscripts/resmokelib/testing/hooks/bghook.py +++ b/buildscripts/resmokelib/testing/hooks/bghook.py @@ -13,13 +13,11 @@ class BGJob(threading.Thread): BGJob will call 'run_action' without any delay and expects the 'run_action' function to add some form of delay. """ - def __init__(self, hook, loop_delay_ms=None): + def __init__(self, hook): """Initialize the background job.""" threading.Thread.__init__(self, name=f"BGJob-{hook.__class__.__name__}") - self._loop_delay_ms = loop_delay_ms self.daemon = True self._hook = hook - self._interrupt_event = threading.Event() self.__is_alive = True self.err = None @@ -31,14 +29,6 @@ class BGJob(threading.Thread): try: self._hook.run_action() - if self._loop_delay_ms is not None: - # The configured loop delay asked us to wait before running the action again. Do - # that wait, but listen to see if we finish running the test or are killed in - # the meantime. - interrupted = self._interrupt_event.wait(self._loop_delay_ms / 1000.0) - if interrupted: - self._hook.logger.info("interrupted") - break except Exception as err: # pylint: disable=broad-except self._hook.logger.error("Background thread caught exception: %s.", err) self.err = err @@ -47,7 +37,6 @@ class BGJob(threading.Thread): def kill(self): """Kill the background job.""" self.__is_alive = False - self._interrupt_event.set() class BGHook(interface.Hook): @@ -57,13 +46,8 @@ class BGHook(interface.Hook): # By default, we continuously run the background hook for the duration of the suite. DEFAULT_TESTS_PER_CYCLE = math.inf - def __init__(self, hook_logger, fixture, desc, tests_per_cycle=None, loop_delay_ms=None): - """ - Initialize the background hook. - - 'tests_per_cycle' or 'loop_delay_ms' can be used to configure how often the background job - is restarted, and how often run_action() is called, respectively. - """ + def __init__(self, hook_logger, fixture, desc, tests_per_cycle=None): + """Initialize the background hook.""" interface.Hook.__init__(self, hook_logger, fixture, desc) self.logger = hook_logger @@ -73,21 +57,15 @@ class BGHook(interface.Hook): self._test_num = 0 # The number of tests we execute before restarting the background hook. self._tests_per_cycle = self.DEFAULT_TESTS_PER_CYCLE if tests_per_cycle is None else tests_per_cycle - self._loop_delay_ms = loop_delay_ms def run_action(self): - """ - Perform an action. This function will be called continuously in the BgJob. - - If a sleep_delay_ms was given, that many milliseconds of sleep will happen between each - invocation. - """ + """Perform an action. This function will be called continuously in the BgJob.""" raise NotImplementedError def before_suite(self, test_report): """Start the background thread.""" self.logger.info("Starting the background thread.") - self._background_job = BGJob(self, self._loop_delay_ms) + self._background_job = BGJob(self) self._background_job.start() def after_suite(self, test_report, teardown_flag=None): @@ -108,7 +86,7 @@ class BGHook(interface.Hook): return self.logger.info("Restarting the background thread.") - self._background_job = BGJob(self, self._loop_delay_ms) + self._background_job = BGJob(self) self._background_job.start() def after_test(self, test, test_report): diff --git a/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py b/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py index 5278819da8f..b0ff858c5dc 100644 --- a/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py +++ b/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py @@ -276,15 +276,16 @@ class PeriodicKillSecondariesTestCase(interface.DynamicTestCase): secondary.await_ready() client = secondary.mongo_client() + minvalid_doc = client.local["replset.minvalid"].find_one() oplog_truncate_after_doc = client.local["replset.oplogTruncateAfterPoint"].find_one() recovery_timestamp_res = client.admin.command("replSetTest", getLastStableRecoveryTimestamp=True) latest_oplog_doc = client.local["oplog.rs"].find_one(sort=[("$natural", pymongo.DESCENDING)]) - self.logger.info("Checking replication invariants. oplogTruncateAfterPoint: {}," + self.logger.info("Checking invariants: minValid: {}, oplogTruncateAfterPoint: {}," " stable recovery timestamp: {}, latest oplog doc: {}".format( - oplog_truncate_after_doc, recovery_timestamp_res, + minvalid_doc, oplog_truncate_after_doc, recovery_timestamp_res, latest_oplog_doc)) null_ts = bson.Timestamp(0, 0) @@ -298,6 +299,13 @@ class PeriodicKillSecondariesTestCase(interface.DynamicTestCase): raise errors.ServerFailure( "Latest oplog entry had no 'ts' field: {}".format(latest_oplog_doc)) + # The "oplogTruncateAfterPoint" document may not exist at startup. If so, we default + # it to null. + oplog_truncate_after_ts = null_ts + if oplog_truncate_after_doc is not None: + oplog_truncate_after_ts = oplog_truncate_after_doc.get( + "oplogTruncateAfterPoint", null_ts) + # The "lastStableRecoveryTimestamp" field is present if the storage engine supports # "recover to a timestamp". If it's a null timestamp on a durable storage engine, that # means we do not yet have a stable checkpoint timestamp and must be restarting at the @@ -320,6 +328,94 @@ class PeriodicKillSecondariesTestCase(interface.DynamicTestCase): recovery_timestamp, latest_oplog_entry_ts, recovery_timestamp_res, latest_oplog_doc)) + if minvalid_doc is not None: + applied_through_ts = minvalid_doc.get("begin", {}).get("ts", null_ts) + minvalid_ts = minvalid_doc.get("ts", null_ts) + + # The "appliedThrough" value should always equal the "last stable recovery + # timestamp", AKA the stable checkpoint for durable engines, on server restart. + # + # The written "appliedThrough" time is updated with the latest timestamp at the end + # of each batch application, and batch boundaries are the only valid stable + # timestamps on secondaries. Therefore, a non-null appliedThrough timestamp must + # equal the checkpoint timestamp, because any stable timestamp that the checkpoint + # could use includes an equal persisted appliedThrough timestamp. + if (recovery_timestamp != null_ts and applied_through_ts != null_ts + and (not recovery_timestamp == applied_through_ts)): + raise errors.ServerFailure( + "The condition last stable recovery timestamp ({}) == appliedThrough ({})" + " doesn't hold: minValid document={}," + " getLastStableRecoveryTimestamp result={}, last oplog entry={}".format( + recovery_timestamp, applied_through_ts, minvalid_doc, + recovery_timestamp_res, latest_oplog_doc)) + + if applied_through_ts == null_ts: + # We clear "appliedThrough" to represent having applied through the top of the + # oplog in PRIMARY state or immediately after "rollback via refetch". + # If we are using a storage engine that supports "recover to a timestamp," + # then we will have a "last stable recovery timestamp" and we should use that + # as our "appliedThrough" (similarly to why we assert their equality above). + # If both are null, then we are in PRIMARY state on a storage engine that does + # not support "recover to a timestamp" or in RECOVERING immediately after + # "rollback via refetch". Since we do not update "minValid" in PRIMARY state, + # we leave "appliedThrough" as null so that the invariants below hold, rather + # than substituting the latest oplog entry for the "appliedThrough" value. + applied_through_ts = recovery_timestamp + + if minvalid_ts == null_ts: + # The server treats the "ts" field in the minValid document as missing when its + # value is the null timestamp. + minvalid_ts = applied_through_ts + + if latest_oplog_entry_ts == null_ts: + # If the oplog is empty, we treat the "minValid" as the latest oplog entry. + latest_oplog_entry_ts = minvalid_ts + + if oplog_truncate_after_ts == null_ts: + # The server treats the "oplogTruncateAfterPoint" field as missing when its + # value is the null timestamp. When it is null, the oplog is complete and + # should not be truncated, so it is effectively the top of the oplog. + oplog_truncate_after_ts = latest_oplog_entry_ts + + # Check the ordering invariants before the secondary has reconciled the end of + # its oplog. + # The "oplogTruncateAfterPoint" is set to the first timestamp of each batch of + # oplog entries before they are written to the oplog. Thus, it can be ahead + # of the top of the oplog before any oplog entries are written, and behind it + # after some are written. Thus, we cannot compare it to the top of the oplog. + + # appliedThrough <= minValid + # appliedThrough represents the end of the previous batch, so it is always the + # earliest. + if applied_through_ts > minvalid_ts: + raise errors.ServerFailure( + "The condition appliedThrough <= minValid ({} <= {}) doesn't hold: minValid" + " document={}, latest oplog entry={}".format( + applied_through_ts, minvalid_ts, minvalid_doc, latest_oplog_doc)) + + # minValid <= oplogTruncateAfterPoint + # This is true because this hook is never run after a rollback. Thus, we only + # move "minValid" to the end of each batch after the batch is written to the oplog. + # We reset the "oplogTruncateAfterPoint" to null before we move "minValid" from + # the end of the previous batch to the end of the current batch. Thus "minValid" + # must be less than or equal to the "oplogTruncateAfterPoint". + if minvalid_ts > oplog_truncate_after_ts: + raise errors.ServerFailure( + "The condition minValid <= oplogTruncateAfterPoint ({} <= {}) doesn't" + " hold: minValid document={}, oplogTruncateAfterPoint document={}," + " latest oplog entry={}".format(minvalid_ts, oplog_truncate_after_ts, + minvalid_doc, oplog_truncate_after_doc, + latest_oplog_doc)) + + # minvalid <= latest oplog entry + # "minValid" is set to the end of a batch after the batch is written to the oplog. + # Thus it is always less than or equal to the top of the oplog. + if minvalid_ts > latest_oplog_entry_ts: + raise errors.ServerFailure( + "The condition minValid <= top of oplog ({} <= {}) doesn't" + " hold: minValid document={}, latest oplog entry={}".format( + minvalid_ts, latest_oplog_entry_ts, minvalid_doc, latest_oplog_doc)) + try: secondary.teardown() except errors.ServerFailure: diff --git a/buildscripts/resmokelib/testing/hooks/run_query_stats.py b/buildscripts/resmokelib/testing/hooks/run_query_stats.py deleted file mode 100644 index 736c5e261c7..00000000000 --- a/buildscripts/resmokelib/testing/hooks/run_query_stats.py +++ /dev/null @@ -1,83 +0,0 @@ -""" -Test hook for verifying $queryStats collects expected metrics and can redact query shapes. - -This runs in the background as other tests are ongoing. -""" - -from bson import binary -import pymongo.errors -from buildscripts.resmokelib.testing.hooks.interface import Hook - -QUERY_STATS_NOT_ENABLED_CODES = [224, 7373500, 6579000] - - -class RunQueryStats(Hook): - """Runs $queryStats after every test, and clears the query stats store before every test.""" - - IS_BACKGROUND = False - - def __init__(self, hook_logger, fixture, allow_feature_not_supported=False): - """Initialize the RunQueryStats hook. - - Args: - hook_logger: the logger instance for this hook. - fixture: the target fixture (replica sets or a sharded cluster). - allow_feature_not_supported: absorb 'QueryFeatureNotAllowed' errors when calling - $queryStats. This is to support fuzzer suites that may manipulate the FCV. - """ - description = "Read query stats data after each test." - super().__init__(hook_logger, fixture, description) - self.client = self.fixture.mongo_client() - self.hmac_key = binary.Binary(("0" * 32).encode('utf-8'), 8) - self.allow_feature_not_supported = allow_feature_not_supported - - def verify_query_stats(self, querystats_spec): - """Verify a $queryStats call has all the right properties.""" - query_stats_pipeline = [ - {"$queryStats": querystats_spec}, - # SERVER-90921: The pymongo version we use on this branch has trouble parsing invalid - # DBRefs, which can be produced by the 'key' field. We'll overwrite that field with a - # dummy one, since the contents aren't important for this test/check. - {"$set": {"key": "Redacted due to issues with DBRefs"}} - ] - try: - with self.client.admin.aggregate(query_stats_pipeline) as cursor: - nreturned = 0 - for operation in cursor: - assert "key" in operation - assert "metrics" in operation - assert "asOf" in operation - nreturned += 1 - self.logger.info("Found %d query stats entries.", nreturned) - except pymongo.errors.OperationFailure as err: - if self.allow_feature_not_supported and err.code in QUERY_STATS_NOT_ENABLED_CODES: - self.logger.info("Encountered an error while running $queryStats. " - "$queryStats will not be run for this test.") - else: - raise err - - def after_test(self, test, test_report): - """After the test, make sure we can ingest the query stats, with and without hmac.""" - self.verify_query_stats({}) - self.verify_query_stats( - {"transformIdentifiers": {"algorithm": "hmac-sha-256", "hmacKey": self.hmac_key}}) - - # Log the number of evictions we encountered. - server_status = self.client.admin.command({"serverStatus": 1}) - num_evicted_entries = server_status["metrics"]["queryStats"]["numEvicted"] - if num_evicted_entries > 0: - self.logger.info("Evicted %d query stats entries during test execution.", - num_evicted_entries) - - def before_test(self, test, test_report): - """Before the test, reset the contents of the query stats store.""" - try: - # Clear out all existing entries, then reset the size cap. - self.client.admin.command("setParameter", 1, internalQueryStatsCacheSize="0%") - self.client.admin.command("setParameter", 1, internalQueryStatsCacheSize="1%") - except pymongo.errors.OperationFailure as err: - if self.allow_feature_not_supported and err.code in QUERY_STATS_NOT_ENABLED_CODES: - self.logger.info("Encountered an error while configuring the query stats store. " - "Query stats will not be collected for this test.") - else: - raise err diff --git a/buildscripts/resmokelib/testing/hooks/simulate_crash.py b/buildscripts/resmokelib/testing/hooks/simulate_crash.py index 68407a66192..c7f8bc4026c 100644 --- a/buildscripts/resmokelib/testing/hooks/simulate_crash.py +++ b/buildscripts/resmokelib/testing/hooks/simulate_crash.py @@ -94,14 +94,7 @@ class SimulateCrash(bghook.BGHook): rel = fqfn[len(root):] os.makedirs(new_root + "/journal", exist_ok=True) out_fd = os.open(new_root + rel, os.O_WRONLY | os.O_CREAT) - - total_bytes_sent = 0 - while total_bytes_sent < in_bytes: - bytes_sent = os.sendfile(out_fd, in_fd, total_bytes_sent, in_bytes - total_bytes_sent) - if bytes_sent == 0: - raise ValueError("Unexpectedly reached EOF copying file") - total_bytes_sent += bytes_sent - + os.sendfile(out_fd, in_fd, 0, in_bytes) os.close(out_fd) os.close(in_fd) diff --git a/buildscripts/resmokelib/testing/hooks/stepdown.py b/buildscripts/resmokelib/testing/hooks/stepdown.py index 8fb565cd1d8..c09602baee8 100644 --- a/buildscripts/resmokelib/testing/hooks/stepdown.py +++ b/buildscripts/resmokelib/testing/hooks/stepdown.py @@ -363,7 +363,7 @@ class FileBasedStepdownLifecycle(object): # We remove the "permitted" file to revoke permission for the stepdown thread to continue # performing stepdowns. - fs.remove_if_exists(self.__stepdown_files.permitted) + os.remove(self.__stepdown_files.permitted) class _StepdownThread(threading.Thread): # pylint: disable=too-many-instance-attributes @@ -627,10 +627,6 @@ class _StepdownThread(threading.Thread): # pylint: disable=too-many-instance-at break except pymongo.errors.NotMasterError: pass - except pymongo.errors.OperationFailure as ex: - if ex.code == 166: # CommandNotSupportedOnView - # listCollections return also views and collStats is not supported on views - break retarget_time = time.time() - start_time if retarget_time >= 60: raise RuntimeError( diff --git a/buildscripts/resmokelib/testing/report.py b/buildscripts/resmokelib/testing/report.py index e2655e8bf81..38fe409b656 100644 --- a/buildscripts/resmokelib/testing/report.py +++ b/buildscripts/resmokelib/testing/report.py @@ -4,14 +4,12 @@ This is used to support additional test status and timing information for the re """ import copy -import os import threading import time import unittest from buildscripts.resmokelib import config as _config from buildscripts.resmokelib import logging -from buildscripts.resmokelib.testing.symbolizer_service import ResmokeSymbolizer # pylint: disable=attribute-defined-outside-init @@ -56,9 +54,7 @@ class TestReport(unittest.TestResult): # pylint: disable=too-many-instance-attr for report in reports: if not isinstance(report, TestReport): - raise TypeError( - f"reports must be a list of TestReport instances, current report is {type(report)}" - ) + raise TypeError("reports must be a list of TestReport instances") with report._lock: # pylint: disable=protected-access for test_info in report.test_infos: @@ -110,7 +106,6 @@ class TestReport(unittest.TestResult): # pylint: disable=too-many-instance-attr unittest.TestResult.startTest(self, test) test_info = TestInfo(test.id(), test.test_name, test.dynamic) - test_info.group_id = f"job{self.job_num}" basename = test.basename() command = test.as_command() @@ -129,53 +124,40 @@ class TestReport(unittest.TestResult): # pylint: disable=too-many-instance-attr test.basename(), command, test.logger, self.job_num, test.id(), self.job_logger) - test_info.log_info = { - "log_name": logging.loggers.get_evergreen_log_name(self.job_num, test.id()), - "logs_to_merge": [logging.loggers.get_evergreen_log_name(self.job_num)], - "rendering_type": "resmoke", "version": 0 - } test_info.url_endpoint = url_endpoint if self.logging_prefix is not None: test_logger.info(self.logging_prefix) # Set job_num in test. test.job_num = self.job_num + test.override_logger(test_logger) test_info.start_time = time.time() def stopTest(self, test): # pylint: disable=invalid-name """Call after 'test' has run.""" - try: - # check if there are stacktrace files, if so, invoke the symbolizer here. - # log symbolized output to test.logger.info() - symbolizer = ResmokeSymbolizer() - symbolizer.symbolize_test_logs(test) - - unittest.TestResult.stopTest(self, test) - - with self._lock: - test_info = self.find_test_info(test) - test_info.end_time = time.time() - test_status = "no failures detected" if test_info.status == "pass" else "failed" - - time_taken = test_info.end_time - test_info.start_time - self.job_logger.info("%s ran in %0.2f seconds: %s.", test.basename(), time_taken, - test_status) - - finally: - # This is a failsafe. In the event that 'stopTest' fails, - # any rogue logger handlers will be removed from this test. - # If not cleaned up, these will trigger 'setup failures' -- - # indicated by exiting with LoggerRuntimeConfigError.EXIT_CODE. - for handler in test.logger.handlers: - # We ignore the cancellation token returned by close_later() since we always want the - # logs to eventually get flushed. - logging.flush.close_later(handler) - - # Restore the original logger for the test. - test.reset_logger() - - def addError(self, test, err): + unittest.TestResult.stopTest(self, test) + + with self._lock: + test_info = self.find_test_info(test) + test_info.end_time = time.time() + test_status = "no failures detected" if test_info.status == "pass" else "failed" + + time_taken = test_info.end_time - test_info.start_time + self.job_logger.info("%s ran in %0.2f seconds: %s.", test.basename(), time_taken, + test_status) + + # Asynchronously closes the buildlogger test handler to avoid having too many threads open + # on 32-bit systems. + for handler in test.logger.handlers: + # We ignore the cancellation token returned by close_later() since we always want the + # logs to eventually get flushed. + logging.flush.close_later(handler) + + # Restore the original logger for the test. + test.reset_logger() + + def addError(self, test, err): # pylint: disable=invalid-name """Call when a non-failureException was raised during the execution of 'test'.""" unittest.TestResult.addError(self, test, err) @@ -219,7 +201,12 @@ class TestReport(unittest.TestResult): # pylint: disable=too-many-instance-attr test_info = self.find_test_info(test) test_info.status = "fail" - test_info.evergreen_status = "fail" + if test_info.dynamic: + # Dynamic tests are used for data consistency checks, so the failures are never + # silenced. + test_info.evergreen_status = "fail" + else: + test_info.evergreen_status = self.suite_options.report_failure_status test_info.return_code = test.return_code def setFailure(self, test, return_code=1): # pylint: disable=invalid-name @@ -231,7 +218,12 @@ class TestReport(unittest.TestResult): # pylint: disable=too-many-instance-attr raise ValueError("stopTest was not called on %s" % (test.basename())) test_info.status = "fail" - test_info.evergreen_status = "fail" + if test_info.dynamic: + # Dynamic tests are used for data consistency checks, so the failures are never + # silenced. + test_info.evergreen_status = "fail" + else: + test_info.evergreen_status = self.suite_options.report_failure_status test_info.return_code = return_code # Recompute number of success, failures, and errors. @@ -294,18 +286,19 @@ class TestReport(unittest.TestResult): # pylint: disable=too-many-instance-attr for test_info in self.test_infos: result = { "test_file": test_info.test_file, - "group_id": test_info.group_id, "status": test_info.evergreen_status, "exit_code": test_info.return_code, "start": test_info.start_time, "end": test_info.end_time, "elapsed": test_info.end_time - test_info.start_time, - "log_info": test_info.log_info, } if test_info.display_test_name is not None: result["display_test_name"] = test_info.display_test_name + if test_info.group_id is not None: + result["group_id"] = test_info.group_id + if test_info.url_endpoint is not None: result["url"] = test_info.url_endpoint result["url_raw"] = test_info.url_endpoint + "?raw=1" @@ -335,7 +328,6 @@ class TestReport(unittest.TestResult): # pylint: disable=too-many-instance-attr test_info = TestInfo(test_file, test_file, is_dynamic) test_info.display_test_name = result.get("display_test_name") test_info.group_id = result.get("group_id") - test_info.log_info = result.get("log_info") test_info.url_endpoint = result.get("url") test_info.status = result["status"] test_info.evergreen_status = test_info.status @@ -389,16 +381,15 @@ class TestInfo(object): # pylint: disable=too-many-instance-attributes self.test_id = test_id self.test_file = test_file - self.group_id = None self.display_test_name = None self.dynamic = dynamic + self.group_id = None self.start_time = None self.end_time = None self.status = None self.evergreen_status = None self.return_code = None - self.log_info = None self.url_endpoint = None diff --git a/buildscripts/resmokelib/testing/symbolizer_service.py b/buildscripts/resmokelib/testing/symbolizer_service.py deleted file mode 100644 index 9e78b0dd6b7..00000000000 --- a/buildscripts/resmokelib/testing/symbolizer_service.py +++ /dev/null @@ -1,294 +0,0 @@ -"""Symbolize stacktraces inside test logs.""" -from __future__ import annotations - -import os -import subprocess -import sys -import time -from datetime import timedelta -from threading import Lock - -from typing import List, Optional, NamedTuple - -from buildscripts.resmokelib import config as _config -from buildscripts.resmokelib.flags import HANG_ANALYZER_CALLED -from buildscripts.resmokelib.testing.testcases.interface import TestCase - -# This lock prevents different resmoke jobs from symbolizing stacktraces concurrently, -# which includes downloading the debug symbols, that can be reused by other resmoke jobs -_lock = Lock() - -STACKTRACE_FILE_EXTENSION = ".stacktrace" -SYMBOLIZE_RETRY_TIMEOUT_SECS = timedelta(minutes=4).total_seconds() - - -class ResmokeSymbolizerConfig(NamedTuple): - """ - Resmoke symbolizer config. - - * evg_task_id: evergreen task ID resmoke runs on - * client_id: symbolizer client ID - * client_secret: symbolizer client secret - """ - - evg_task_id: Optional[str] - client_id: Optional[str] - client_secret: Optional[str] - - @classmethod - def from_resmoke_config(cls) -> ResmokeSymbolizerConfig: - """ - Make resmoke symbolizer config from a global resmoke config. - - :return: resmoke symbolizer config - """ - return cls( - evg_task_id=_config.EVERGREEN_TASK_ID, - client_id=_config.SYMBOLIZER_CLIENT_ID, - client_secret=_config.SYMBOLIZER_CLIENT_SECRET, - ) - - @staticmethod - def is_windows() -> bool: - """ - Whether we are on Windows. - - :return: True if on Windows - """ - return sys.platform == "win32" or sys.platform == "cygwin" - - @staticmethod - def is_macos() -> bool: - """ - Whether we are on MacOS. - - :return: True if on MacOS. - """ - return sys.platform == "darwin" - - -class ResmokeSymbolizer: - """Symbolize stacktraces inside test logs.""" - - def __init__(self, config: Optional[ResmokeSymbolizerConfig] = None, - symbolizer_service: Optional[SymbolizerService] = None, - file_service: Optional[FileService] = None): - """Initialize instance.""" - - self.config = config if config is not None else ResmokeSymbolizerConfig.from_resmoke_config( - ) - self.symbolizer_service = symbolizer_service if symbolizer_service is not None else SymbolizerService( - ) - self.file_service = file_service if file_service is not None else FileService() - - def symbolize_test_logs(self, test: TestCase, - symbolize_retry_timeout: float = SYMBOLIZE_RETRY_TIMEOUT_SECS) -> None: - """ - Perform all necessary actions to symbolize and write output to test logs. - - :param test: resmoke test case - :param symbolize_retry_timeout: the timeout for symbolizer retries - """ - if not self.should_symbolize(test): - return - - dbpath = self.get_stacktrace_dir(test) - if dbpath is None: - return - - test.logger.info("Looking for stacktrace files in '%s'", dbpath) - files = self.collect_stacktrace_files(dbpath) - if not files: - test.logger.info("No failure logs/stacktrace files found, skipping symbolization") - return - - with _lock: - test.logger.info("Found stacktrace files. \nBEGIN Symbolization") - test.logger.info("Stacktrace files: %s", files) - - start_time = time.perf_counter() - for file_path in files: - test.logger.info("Working on: %s", file_path) - symbolizer_script_timeout = int(symbolize_retry_timeout - - (time.perf_counter() - start_time)) - symbolized_out = self.symbolizer_service.run_symbolizer_script( - file_path, symbolizer_script_timeout) - test.logger.info(symbolized_out) - if time.perf_counter() - start_time > symbolize_retry_timeout: - break - - # To avoid performing the same actions on these files again, we remove them - self.file_service.remove_all(files) - - test.logger.info("\nEND Symbolization \nSymbolization process completed. ") - - def should_symbolize(self, test: TestCase) -> bool: - """ - Check whether we should perform symbolization process. - - :param test: resmoke test case - :return: whether we should symbolize - """ - if self.config.evg_task_id is None: - test.logger.info("Not running in Evergreen, skipping symbolization") - return False - - if self.config.client_id is None or self.config.client_secret is None: - test.logger.info("Symbolizer client secret and/or client ID are absent," - " skipping symbolization") - return False - - if self.config.is_windows(): - test.logger.info("Running on Windows, skipping symbolization") - return False - - if self.config.is_macos(): - test.logger.info("Running on MacOS, skipping symbolization") - return False - - if HANG_ANALYZER_CALLED.is_set(): - test.logger.info( - "Hang analyzer has been called, skipping symbolization to meet timeout constraints." - ) - return False - - return True - - def get_stacktrace_dir(self, test: TestCase) -> Optional[str]: - """ - Get dbpath from test case. - - :param test: resmoke test case - :return: dbpath or None - """ - if not hasattr(test, "fixture") or test.fixture is None: - test.logger.info("Test fixture is not available, could not get dbpath") - return None - - dbpath = test.fixture.get_dbpath_prefix() - if not self.file_service.check_path_exists(dbpath): - test.logger.info("dbpath '%s' directory not found", dbpath) - return None - - return dbpath - - def collect_stacktrace_files(self, dir_path: str) -> List[str]: - """ - Collect all stacktrace files which are not empty and return their full paths. - - :param dir_path: directory to look into - :return: list of stacktrace files paths - """ - - files = self.file_service.find_all_children_recursively(dir_path) - files = self.file_service.filter_by_extension(files, STACKTRACE_FILE_EXTENSION) - self.file_service.remove_empty(files) - files = self.file_service.filter_out_non_files(files) - - return files - - -class FileService: - """A service for working with files.""" - - @staticmethod - def find_all_children_recursively(dir_path: str) -> List[str]: - """ - Find all children files in directory recursively. - - :param dir_path: directory path - :return: list of all children files - """ - children_in_dir = [] - for parent, _, children in os.walk(dir_path): - children_in_dir.extend(os.path.join(parent, child) for child in children) - return children_in_dir - - @staticmethod - def filter_by_extension(files: List[str], extension: str) -> List[str]: - """ - Filter files by extension. - - :param files: list of file paths - :param extension: file extension - :return: filtered list of file paths - """ - return [f for f in files if f.endswith(extension)] - - @staticmethod - def filter_out_non_files(files: List[str]) -> List[str]: - """ - Filter out non files. - - :param files: list of paths - :return: filtered list of file paths - """ - return [f for f in files if os.path.isfile(f)] - - @staticmethod - def remove_empty(files: List[str]) -> None: - """ - Delete files that are empty. - - :param files: list of paths - """ - for file in [f for f in files if os.stat(f).st_size == 0]: - os.remove(file) - - @staticmethod - def remove_all(files: List[str]) -> None: - """ - Delete all files. - - :param files: list of paths - """ - for file in files: - os.remove(file) - - @staticmethod - def check_path_exists(path: str) -> bool: - """ - Check that file or directory exists. - - :param path: file or directory path - :return: whether path exists - """ - return os.path.exists(path) - - -class SymbolizerService: - """Wrapper around symbolizer script.""" - - @staticmethod - def run_symbolizer_script(full_file_path: str, retry_timeout_secs: int) -> str: - """ - Symbolize given file and return symbolized output as string. - - :param full_file_path: stacktrace file path - :param retry_timeout_secs: the timeout for symbolizer to retry - :return: symbolized output as string - """ - - symbolizer_args = [ - "db-contrib-tool", - "symbolize", - "--client-secret", - _config.SYMBOLIZER_CLIENT_SECRET, - "--client-id", - _config.SYMBOLIZER_CLIENT_ID, - "--total-seconds-for-retries", - str(retry_timeout_secs), - ] - - with open(full_file_path) as file_obj: - symbolizer_process = subprocess.Popen(args=symbolizer_args, close_fds=True, - stdin=file_obj, stdout=subprocess.PIPE, - stderr=subprocess.STDOUT) - - try: - output, _ = symbolizer_process.communicate(timeout=retry_timeout_secs) - except subprocess.TimeoutExpired: - symbolizer_process.kill() - output, _ = symbolizer_process.communicate() - - return output.strip().decode() |