diff options
Diffstat (limited to 'buildscripts/resmokelib/testing/hooks')
7 files changed, 162 insertions, 183 deletions
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( |