Support replay mode with garbage collection (microsoft#845)

This change enables a new 'replay' mode option that replays requests from the trace database.

Changes include:

1. Refactor driver to consume sequences from different sources (with trace database another supported source of specific
sequences, similar to the existing smoke test mode)

2. Generate 'replay blocks' as part of payload rendering.  Replay blocks contain dynamic objects, but do not support
custom payloads (this is future work).

3. Enables replay to be based on replay blocks

With this change, RESTler generates sequences from replay blocks if available,
or from raw request/responses (similar to the existing replay mode) when they are not available.

The current version of replay is based on the rendered data sent at the time of
original sequence rendering.  This has several limitations, such as not being able to
garbage-collect resources or plugging in custom payloads.

In particular, when a bug is reproduced in RESTler today, the same replay mechanism is used, which
means that GC does not collect resources created while reproducing the bug.  Moreover, re-running
the same sequence without GC will not work if the resource has not been deleted if a resource-generating
request has a unique ID parameter (e.g. PUT /resource/{resourceId}), causing false negative non-reproducible
bugs.

This change addresses this issue by implementing replay blocks-based replay, which is invoked when reproducing bugs.

Note: the existing replay based on .replay.txt files will also be able to use this new mechanism if a grammar is provided,
but this is not implemented as part of this change.

4. Added a setting to filter the origin during DB replay.

To only replay specific origins, add the following to the settings file:
  "replay": {
    "include_origins": ["main_driver", "InvalidValueChecker"]
  }

Testing:
- manual testing of demo_server replay as follows:

1) Run 'test' task and generate trace database
>restler.exe test --grammar_file .\Compile\grammar.py --dictionary_file .\Compile\dict.json --host localhost --target_port 8888  --settings .\compile\engine_settings.json --no_ssl

Engine settings:
{
  "use_trace_database": true,
  "trace_database": {
    "root_dir": "d:\\demo_server\\trace_databases",
  },
}

2) Run 'replay' task from above trace database

>restler.exe replay --replay_log ./trace_data.ndjson --grammar_file .\Compile\grammar.py --dictionary_file .\Compile\dict.json --host localhost --target_port 8888  --settings .\compile\engine_settings.json --no_ssl

- updated unit tests

Author: marina-p

.vscode/launch.json

@@ -17,7 +17,7 @@
             "request": "launch",
             "program": "${workspaceFolder}\\restler\\end_to_end_tests\\test_quick_start.py",
             "args": [
-                "d:\\restlerdrop\\main",
+                "d:\\restlerdrop\\tracedb2",
             ]
         },
         {
@@ -106,6 +106,48 @@
             ],
             "justMyCode": false
         },
+        {
+            "name": "Python: replay mode with grammar",
+            "type": "python",
+            "request": "launch",
+            "program": "${workspaceFolder}\\restler\\restler.py",
+            "args": [
+                "--replay_log",
+                "D:\\test\\demo_server\\replaytests3\\replay_trace_data.ndjson",
+                "--restler_grammar",
+                "d:\\test\\demo_server\\replaytests3\\Compile\\grammar.py",
+                "--custom_mutations",
+                "d:\\test\\demo_server\\replaytests3\\Compile\\dict.json",
+                "--settings",
+                "d:\\test\\demo_server\\replaytests3\\Compile\\engine_settings.json",
+                "--no_ssl",
+                "--host",
+                "localhost",
+                "--target_port",
+                "8888",
+                "--garbage_collection_interval",
+                "30"
+            ],
+            "justMyCode": false
+        },
+        {
+            "name": "Python: replay mode no grammar",
+            "type": "python",
+            "request": "launch",
+            "program": "${workspaceFolder}\\restler\\restler.py",
+            "args": [
+                "--replay_log",
+                "D:\\test\\demo_server\\replaytests\\replay_trace_data.ndjson",
+                "--no_ssl",
+                "--host",
+                "localhost",
+                "--target_port",
+                "8888",
+                "--garbage_collection_interval",
+                "30"
+            ],
+            "justMyCode": false
+        },
         {
             "name": "Python: examples checker",
             "type": "python",

docs/user-guide/Replay.md

@@ -28,7 +28,7 @@ Any resources that were created during the replay will NOT be automatically dele
 unless the replaying sequence itself deletes the resource.
 Any resources created should be removed manually.
 
-## Replay log format
+### Replay log format
 
 The replay log is created anytime a new bug bucket is reported.
 This replay log consists of the full sequence of requests that were sent to create the bug.
@@ -60,7 +60,7 @@ You may notice that content-length and user-agent are not included in the replay
 These fields are populated automatically by RESTler when the request is sent to the server,
 so they are not needed (and shouldn't exist) in the log.
 
-## Using replay logs to send custom sequences
+### Using replay logs to send custom sequences
 While the main purpose of replay logs are to re-test bugs previously found,
 it is also possible to use these files as a way to send custom sequences to RESTler, similar to how you may send a request through *curl* or *Postman*.
 
@@ -84,4 +84,25 @@ while max_async_wait_time will attempt to perform an asynchronous polling-wait b
 with a maximum resource-creation-wait-time of the max_async_wait_time setting.
 
 
-##
+## Using the Trace Database
+
+Previously executed RESTler sequences may be re-played by configuring a trace database to be written during `test` or `fuzz` tasks, then specifying it as the replay file for the `replay` task.
+
+For example:
+
+1. Generate the trace database by adding the following to the engine settings:
+    ```json
+    {
+        "use_trace_database": true,
+        "trace_database": {
+            "root_dir": "/path/to/trace_databases",
+        },
+    }
+    ```
+
+2. Replay the same sequences of requests (in the same order) from the replay log.  The below command specifies to run the RESTler `replay` task.  The grammar, dictionary, and engine settings files must be specified to enable generating unique dynamic object names and garbage collection as in the original run (note: custom payloads from the specified dictionary will not currently be used for replay).  If the grammar and dictionary are omitted, the replay will execute the same request text as sent
+in the original run, and GC will not be triggered.
+
+    >restler.exe replay --replay_log /path/to/trace_databases/trace_data.ndjson --grammar_file ./Compile/grammar.py --dictionary_file ./Compile/dict.json --host localhost --target_port 8888  --settings ./Compile/engine_settings.json
+
+Replaying sequences from checkers is enabled for experimental purposes, but is not fully supported at this time.

docs/user-guide/SettingsFile.md

@@ -385,6 +385,21 @@ Dictionary containing settings for the trace database.
 
 `cleanup_time` float (default 10): The maximum amount of time, in seconds, to wait for the data serialization to be complete before exiting.
 
+### replay: dict (default empty)
+
+Dictionary containing replay settings.
+
+`trace_database_file_path` str (default None):  The path to the trace database from which to replay requests.
+Overrides the value of `--replay_file` if specified on the command line.
+
+`include_origins` list (default empty list=No filtering):  When replaying requests from the trace database, specify a list of origin values to use.  For example:
+
+```json
+  "replay": {
+    "include_origins": ["main_driver", "InvalidValueChecker"]
+  }
+```
+
 ### request_throttle_ms: float (default None)
 The time, in milliseconds, to throttle each request being sent.
 This is here for special cases where the server will block requests from connections that arrive too quickly.

restler/checkers/checker_base.py

@@ -119,15 +119,17 @@ def _render_and_send_data(self, seq, request, check_async=True):
         @rtype : Tuple(HttpResponse, HttpResponse)
 
         """
-        rendered_data, parser, tracked_parameters, updated_writer_variables = request.render_current(self._req_collection.candidate_values_pool)
+        rendered_data, parser, tracked_parameters, updated_writer_variables, replay_blocks =\
+             request.render_current(self._req_collection.candidate_values_pool)
         rendered_data = seq.resolve_dependencies(rendered_data)
 
         # We need to record that the request originates from the checker, but
         # there is not a clear sequence origin.
         SequenceTracker.initialize_sequence_trace(combination_id=seq.combination_id,
                                             tags={'hex_definition': seq.hex_definition})
         SequenceTracker.initialize_request_trace(combination_id=seq.combination_id,
-                                            request_id=request.hex_definition)
+                                                 request_id=request.hex_definition,
+                                                 replay_blocks=replay_blocks)
 
         response = self._send_request(parser, rendered_data)
         if response.has_valid_code():
@@ -141,7 +143,10 @@ def _render_and_send_data(self, seq, request, check_async=True):
             responses_to_parse, _, _ = async_request_utilities.try_async_poll(
                 rendered_data, response, async_wait)
         request_utilities.call_response_parser(parser, None, responses=responses_to_parse)
-        seq.append_data_to_sent_list(rendered_data, parser, response, producer_timing_delay=0, max_async_wait_time=async_wait)
+        seq.append_data_to_sent_list(request.method_endpoint_hex_definition,
+                                     rendered_data, parser, response, producer_timing_delay=0,
+                                     max_async_wait_time=async_wait,
+                                     replay_blocks=replay_blocks)
         SequenceTracker.clear_sequence_trace()
         return response, response_to_parse
 

restler/checkers/demo_checker.py

@@ -71,10 +71,10 @@ def apply(self, rendered_sequence, lock):
         # Add the sent prefix requests for replay
         checked_seq.set_sent_requests_for_replay(new_seq.sent_request_data_list)
         # Create a placeholder sent data, so it can be replaced below when bugs are detected for replays
-        checked_seq.append_data_to_sent_list("GET /", None,  HttpResponse(), max_async_wait_time=req_async_wait)
+        checked_seq.append_data_to_sent_list("-", "GET /", None,  HttpResponse(), max_async_wait_time=req_async_wait)
 
         # Render the current request combination
-        rendered_data, parser, tracked_parameters, updated_writer_variables = \
+        rendered_data, parser, tracked_parameters, updated_writer_variables, replay_blocks = \
             next(last_request.render_iter(self._req_collection.candidate_values_pool,
                                           skip=last_request._current_combination_id - 1,
                                           preprocessing=False))
@@ -105,7 +105,9 @@ def apply(self, rendered_sequence, lock):
                                                                                    responses=responses_to_parse)
 
         if response and self._rule_violation(checked_seq, response, valid_response_is_violation=True):
-            checked_seq.replace_last_sent_request_data(rendered_data, parser, response, max_async_wait_time=req_async_wait)
+            checked_seq.replace_last_sent_request_data(request_hash,
+                                                       rendered_data, parser, response, max_async_wait_time=req_async_wait,
+                                                       replay_blocks=replay_blocks)
             self._print_suspect_sequence(checked_seq, response)
             BugBuckets.Instance().update_bug_buckets(checked_seq, response.status_code, origin=self.__class__.__name__)
             self.bugs_reported += 1

restler/checkers/invalid_dynamic_object_checker.py

@@ -58,7 +58,7 @@ def apply(self, rendered_sequence, lock):
         InvalidDynamicObjectChecker.generation_executed_requests[generation].add(last_request.hex_definition)
 
         # Get the current rendering of the sequence, which will be the valid rendering of the last request
-        last_rendering, last_request_parser, tracked_parameters, updated_writer_variables =\
+        last_rendering, last_request_parser, tracked_parameters, updated_writer_variables, replay_blocks =\
             last_request.render_current(self._req_collection.candidate_values_pool)
 
         # Execute the sequence up until the last request
@@ -77,12 +77,12 @@ def apply(self, rendered_sequence, lock):
             request_utilities.call_response_parser(last_request_parser, response)
             if response and self._rule_violation(new_seq, response):
                 # Append the data that we just sent to the sequence's sent list
-                new_seq.append_data_to_sent_list(data, last_request_parser, response)
+                new_seq.append_data_to_sent_list(last_request.method_endpoint_hex_definition,
+                                                 data, last_request_parser, response, replay_blocks=replay_blocks)
                 BugBuckets.Instance().update_bug_buckets(new_seq, response.status_code, origin=self.__class__.__name__)
                 self._print_suspect_sequence(new_seq, response)
 
 
-
     def _prepare_invalid_requests(self, data):
         """ Prepares requests with invalid dynamic objects.
         Each combination of valid/invalid for requests with multiple

restler/checkers/invalid_value_checker.py

@@ -245,11 +245,11 @@ def should_fuzz(req_block):
         # Add the sent prefix requests for replay
         checked_seq.set_sent_requests_for_replay(new_seq.sent_request_data_list)
         # Create a placeholder sent data, so it can be replaced below when bugs are detected for replays
-        checked_seq.append_data_to_sent_list("GET /", None,  HttpResponse(), max_async_wait_time=req_async_wait)
+        checked_seq.append_data_to_sent_list("-", "GET /", None,  HttpResponse(), max_async_wait_time=req_async_wait)
 
         # Render the current request combination, but get the list of primitive
         # values before they are concatenated.
-        rendered_values, parser, tracked_parameters, updated_writer_variables = \
+        rendered_values, parser, tracked_parameters, updated_writer_variables, replay_blocks = \
             next(last_request.render_iter(self._req_collection.candidate_values_pool,
                                            skip=last_request._current_combination_id - 1,
                                            preprocessing=False,
@@ -310,7 +310,8 @@ def should_fuzz(req_block):
                     if not isinstance(fuzzed_value, str):
                         print("not a string!")
                     rendered_data = "".join(rendered_values)
-
+                    # Get the replay blocks that contain the value currently being fuzzed
+                    fuzzed_replay_blocks = request_utilities.get_replay_blocks(last_request.definition, rendered_values)
                     # Check time budget
                     if Monitor().remaining_time_budget <= 0:
                         raise TimeOutException('Exceed Timeout')
@@ -339,7 +340,10 @@ def should_fuzz(req_block):
                     status_code = response.status_code
 
                     if response and self._rule_violation(checked_seq, response, valid_response_is_violation=False):
-                        checked_seq.replace_last_sent_request_data(rendered_data, parser, response, max_async_wait_time=req_async_wait)
+                        checked_seq.replace_last_sent_request_data(last_request.method_endpoint_hex_definition,
+                                                                   rendered_data, parser, response,
+                                                                   max_async_wait_time=req_async_wait,
+                                                                   replay_blocks=fuzzed_replay_blocks)
                         self._print_suspect_sequence(checked_seq, response)
                         BugBuckets.Instance().update_bug_buckets(checked_seq, response.status_code, origin=self.__class__.__name__)
 

restler/checkers/namespace_rule_checker.py

@@ -74,7 +74,7 @@ def _render_original_sequence_start(self, seq):
         self._checker_log.checker_print("\nRe-rendering start of original sequence")
 
         for request in seq.requests[:-1]:
-            rendered_data, parser, tracked_parameters, updated_writer_variables = request.render_current(
+            rendered_data, parser, tracked_parameters, updated_writer_variables, replay_blocks = request.render_current(
                 self._req_collection.candidate_values_pool
             )
             rendered_data = seq.resolve_dependencies(rendered_data)
@@ -106,7 +106,7 @@ def _namespace_rule(self):
         # Check if last request contains any trigger_object
 
         last_request = self._sequence.last_request
-        last_rendering, last_parser, _, _ = last_request.render_current(self._req_collection.candidate_values_pool)
+        last_rendering, last_parser, _, _,_ = last_request.render_current(self._req_collection.candidate_values_pool)
 
         last_request_contains_a_trigger_object = False
         for obj in self._trigger_objects:
@@ -182,7 +182,7 @@ def _render_attacker_subsequence(self, req):
 
         for i in range(stopping_length):
             request = self._sequence.requests[i]
-            rendered_data, parser, tracked_parameters = request.render_current(
+            rendered_data, parser, tracked_parameters, replay_blocks = request.render_current(
                 self._req_collection.candidate_values_pool
             )
             rendered_data = self._sequence.resolve_dependencies(rendered_data)
@@ -206,7 +206,7 @@ def _render_hijack_request(self, req):
 
         """
         self._checker_log.checker_print("Hijack request rendering")
-        rendered_data, parser, tracked_parameters, updated_writer_variables = req.render_current(
+        rendered_data, parser, tracked_parameters, updated_writer_variables, replay_blocks = req.render_current(
             self._req_collection.candidate_values_pool
         )
         rendered_data = self._sequence.resolve_dependencies(rendered_data)

restler/checkers/payload_body_checker.py

@@ -1122,7 +1122,7 @@ def _exec_request_with_new_body(
         cnt = 0
 
         # iterate through different value combinations
-        for rendered_data, parser,_,updated_writer_variables in new_request.render_iter(
+        for rendered_data, parser,_,updated_writer_variables, replay_blocks in new_request.render_iter(
             self._req_collection.candidate_values_pool
         ):
             # check time budget
@@ -1230,7 +1230,8 @@ def _exec_request_with_new_body(
             # analyze response -- error
             if self._rule_violation(seq, response, valid_is_violation):
                 # Append the new request to the sequence before filing the bug
-                seq.replace_last_sent_request_data(rendered_data, parser, response)
+                seq.replace_last_sent_request_data(request.method_endpoint_hex_definition,
+                                                   rendered_data, parser, response)
                 err_seq = sequences.Sequence(seq.requests[:-1] + [new_request])
                 err_seq.set_sent_requests_for_replay(seq.sent_request_data_list)
                 self._print_suspect_sequence(err_seq, response)

restler/checkers/use_after_free_checker.py

@@ -109,7 +109,7 @@ def _render_last_request(self, seq):
 
         """
         request = seq.last_request
-        for rendered_data, parser,_,updated_writer_variables in\
+        for rendered_data, parser,_,updated_writer_variables, replay_blocks in\
             request.render_iter(self._req_collection.candidate_values_pool,
                                 skip=request._current_combination_id):
             # Hold the lock (because other workers may be rendering the same
@@ -138,11 +138,10 @@ def _render_last_request(self, seq):
                 for name,v in updated_writer_variables.items():
                     dependencies.set_variable(name, v)
 
-
-
             # Append the rendered data to the sent list as we will not be rendering
             # with the sequence's render function
-            seq.append_data_to_sent_list(rendered_data, parser, response)
+            seq.append_data_to_sent_list(request.method_endpoint_hex_definition,
+                                         rendered_data, parser, response, replay_blocks=replay_blocks)
             if response and self._rule_violation(seq, response):
                 self._print_suspect_sequence(seq, response)
                 BugBuckets.Instance().update_bug_buckets(seq, response.status_code, origin=self.__class__.__name__)