Replay log fixes and add test coverage. (#503)

1. Fixed replay logic, which was broken after shared connection perf improvements.
2. Added end to end test for FuzzLean and Replay that caught the original regression.
3. After adding the two new tests, 2 other issues were found and fixed.

   a) The demo_server did not consume all the bytes of the request on all failure
   paths.  This was only caught during FuzzLean when invalid payloads were specified
   in the path and body.  The fix was to provide a teardown function that consumed
   the entire request.  The following issue has more details:
   pallets/flask#2188.

   b) test-quick-start hung in CI because the process output from demo_server was not consumed.
   This was not caught previously because there is more output in Fuzz modes.

Author: marina-p

demo_server/demo_server/app.py

@@ -52,6 +52,20 @@ def initialize_app(flask_app):
 
     db.init_app(flask_app)
 
+@app.teardown_request
+def teardown(stream):
+    if not stream:
+        return
+    exhaust = getattr(stream, "exhaust", None)
+
+    if exhaust is not None:
+        exhaust()
+    else:
+        while True:
+            chunk = stream.read(1024 * 64)
+
+            if not chunk:
+                break
 
 def main():
     initialize_app(app)

docs/user-guide/SettingsFile.md

@@ -162,7 +162,7 @@ the examples instead of just the first one.
 
 ```json
 "test_combinations_settings": {
-      "example_payloadds" : {
+      "example_payloads" : {
           "payload_kind": "all"
       }
 }

restler-quick-start.py

@@ -39,10 +39,45 @@ def compile_spec(api_spec_path, restler_dll_path):
 
     with usedir(RESTLER_TEMP_DIR):
         command=f"dotnet \"{restler_dll_path}\" compile --api_spec \"{api_spec_path}\""
-        print(command)
+        print(f"command: {command}")
         subprocess.run(command, shell=True)
 
-def test_spec(ip, port, host, use_ssl, restler_dll_path):
+def add_common_settings(ip, port, host, use_ssl, command):
+    if not use_ssl:
+        command = f"{command} --no_ssl"
+    if ip is not None:
+        command = f"{command} --target_ip {ip}"
+    if port is not None:
+        command = f"{command} --target_port {port}"
+    if host is not None:
+        command = f"{command} --host {host}"
+    return command
+
+def replay_bug(ip, port, host, use_ssl, restler_dll_path, replay_log):
+    """ Runs RESTler's replay mode on the specified replay file
+    """
+    with usedir(RESTLER_TEMP_DIR):
+        command = (
+            f"dotnet \"{restler_dll_path}\" replay --replay_log \"{replay_log}\""
+        )
+        command = add_common_settings(ip, port, host, use_ssl, command)
+        print(f"command: {command}\n")
+        subprocess.run(command, shell=True)
+
+def replay_from_dir(ip, port, host, use_ssl, restler_dll_path, replay_dir):
+    import glob
+    from pathlib import Path
+    # get all the 500 replay files in the bug buckets directory
+    bug_buckets = glob.glob(os.path.join(replay_dir, 'RestlerResults', '**/bug_buckets/*500*'))
+    print(f"buckets: {bug_buckets}")
+    for file_path in bug_buckets:
+        if "bug_buckets" in os.path.basename(file_path):
+            continue
+        print(f"Testing replay file: {file_path}")
+        replay_bug(ip, port, host, use_ssl, restler_dll_path, Path(file_path).absolute())
+    pass
+
+def test_spec(ip, port, host, use_ssl, restler_dll_path, task):
     """ Runs RESTler's test mode on a specified Compile directory
 
     @param ip: The IP of the service to test
@@ -60,33 +95,28 @@ def test_spec(ip, port, host, use_ssl, restler_dll_path):
     @rtype : None
 
     """
+    import json
     with usedir(RESTLER_TEMP_DIR):
         compile_dir = Path(f'Compile')
         grammar_file_path = compile_dir.joinpath('grammar.py')
         dictionary_file_path = compile_dir.joinpath('dict.json')
         settings_file_path = compile_dir.joinpath('engine_settings.json')
+
         command = (
-            f"dotnet \"{restler_dll_path}\" test --grammar_file \"{grammar_file_path}\" --dictionary_file \"{dictionary_file_path}\""
+            f"dotnet \"{restler_dll_path}\" {task} --grammar_file \"{grammar_file_path}\" --dictionary_file \"{dictionary_file_path}\""
             f" --settings \"{settings_file_path}\""
         )
-        if not use_ssl:
-            command = f"{command} --no_ssl"
-        if ip is not None:
-            command = f"{command} --target_ip {ip}"
-        if port is not None:
-            command = f"{command} --target_port {port}"
-        if host is not None:
-            command = f"{command} --host {host}"
-
-        print(command)
+        print(f"command: {command}\n")
+        command = add_common_settings(ip, port, host, use_ssl, command)
+
         subprocess.run(command, shell=True)
 
 if __name__ == '__main__':
 
     parser = argparse.ArgumentParser()
     parser.add_argument('--api_spec_path',
                         help='The API Swagger specification to compile and test',
-                        type=str, required=True)
+                        type=str, required=False, default=None)
     parser.add_argument('--ip',
                         help='The IP of the service to test',
                         type=str, required=False, default=None)
@@ -102,12 +132,27 @@ def test_spec(ip, port, host, use_ssl, restler_dll_path):
     parser.add_argument('--host',
                         help='The hostname of the service to test',
                         type=str, required=False, default=None)
+    parser.add_argument('--task',
+                        help='The task to run (test, fuzz-lean, fuzz, or replay)'
+                             'For test, fuzz-lean, and fuzz, the spec is compiled first.'
+                             'For replay, bug buckets from the specified task directory are re-played.',
+                        type=str, required=False, default='test')
+    parser.add_argument('--replay_bug_buckets_dir',
+                        help='For the replay task, specifies the directory in which to search for bug buckets.',
+                        type=str, required=False, default=None)
 
     args = parser.parse_args()
-
-    api_spec_path = os.path.abspath(args.api_spec_path)
     restler_dll_path = Path(os.path.abspath(args.restler_drop_dir)).joinpath('restler', 'Restler.dll')
-    compile_spec(api_spec_path, restler_dll_path.absolute())
-    test_spec(args.ip, args.port, args.host, args.use_ssl, restler_dll_path.absolute())
+    print(f"\nrestler_dll_path: {restler_dll_path}\n")
+
+    if args.task == "replay":
+        replay_from_dir(args.ip, args.port, args.host, args.use_ssl, restler_dll_path.absolute(), args.replay_bug_buckets_dir)
+    else:
+        if args.api_spec_path is None:
+            print("api_spec_path is required for all tasks except the replay task.")
+            exit(-1)
+        api_spec_path = os.path.abspath(args.api_spec_path)
+        compile_spec(api_spec_path, restler_dll_path.absolute())
+        test_spec(args.ip, args.port, args.host, args.use_ssl, restler_dll_path.absolute(), args.task)
 
     print(f"Test complete.\nSee {os.path.abspath(RESTLER_TEMP_DIR)} for results.")

restler/end_to_end_tests/test_quick_start.py

@@ -14,66 +14,188 @@
 import shutil
 import glob
 from pathlib import Path
+from threading import Thread
 
 RESTLER_WORKING_DIR = 'restler_working_dir'
 
 class QuickStartFailedException(Exception):
     pass
 
+def check_output_errors(output):
+    if output.stderr:
+        raise QuickStartFailedException(f"Failing because stderr was detected after running restler-quick-start:\n{output.stderr!s}")
+    try:
+        output.check_returncode()
+    except subprocess.CalledProcessError:
+        raise QuickStartFailedException(f"Failing because restler-quick-start exited with a non-zero return code: {output.returncode!s}")
+
+def check_expected_output(restler_working_dir, expected_strings, output, task_dir_name):
+    stdout = str(output.stdout)
+
+    for expected_str in expected_strings:
+        if expected_str not in stdout:
+            stdout = stdout.replace('\\r\\n', '\r\n')
+
+            # Print the engine logs to the console
+            out_file_path = os.path.join(restler_working_dir, task_dir_name, 'EngineStdOut.txt')
+            err_file_path = os.path.join(restler_working_dir, task_dir_name, 'EngineStdErr.txt')
+            results_dir = os.path.join(restler_working_dir, task_dir_name, 'RestlerResults')
+            # Return the newest experiments directory in RestlerResults
+            net_log_dir = max(glob.glob(os.path.join(results_dir, 'experiment*/')), key=os.path.getmtime)
+            net_log_path = glob.glob(os.path.join(net_log_dir, 'logs', f'network.testing.*.1.txt'))[0]
+            with open(out_file_path) as of, open(err_file_path) as ef, open(net_log_path) as nf:
+                out = of.read()
+                err = ef.read()
+                net_log = nf.read()
+            raise QuickStartFailedException(f"Failing because expected output '{expected_str}' was not found:\n{stdout}{out}{err}{net_log}")
+
+def test_test_task(restler_working_dir, swagger_path, restler_drop_dir):
+    # Run the quick start script
+    output = subprocess.run(
+        f'python ./restler-quick-start.py --api_spec_path {swagger_path} --restler_drop_dir {restler_drop_dir} --task test',
+        shell=True, capture_output=True
+    )
+    expected_strings = [
+        'Request coverage (successful / total): 6 / 6',
+        'No bugs were found.' ,
+        'Task Test succeeded.'
+    ]
+    check_output_errors(output)
+    check_expected_output(restler_working_dir, expected_strings, output, "Test")
+
+def test_fuzzlean_task(restler_working_dir, swagger_path, restler_drop_dir):
+    # Run the quick start script
+    output = subprocess.run(
+        f'python ./restler-quick-start.py --api_spec_path {swagger_path} --restler_drop_dir {restler_drop_dir} --task fuzz-lean',
+        shell=True, capture_output=True
+    )
+    expected_strings = [
+        'Request coverage (successful / total): 6 / 6',
+        'Bugs were found!' ,
+        'InvalidDynamicObjectChecker_20x: 2',
+        'InvalidDynamicObjectChecker_500: 1',
+        'PayloadBodyChecker_500: 1',
+        'Task FuzzLean succeeded.'
+    ]
+    check_output_errors(output)
+    check_expected_output(restler_working_dir, expected_strings, output, "FuzzLean")
+
+def test_fuzz_task(restler_working_dir, swagger_path, restler_drop_dir):
+    import json
+    compile_dir = Path(restler_working_dir, f'Compile')
+    settings_file_path = compile_dir.joinpath('engine_settings.json')
+    # Set the maximum number of generations (i.e. sequence length) to limit fuzzing
+    settings_json=json.load(open(settings_file_path))
+    settings_json["max_sequence_length"] = 5
+    json.dump(settings_json, open(settings_file_path, "w", encoding='utf-8'))
+
+    expected_strings = [
+        'Request coverage (successful / total): 6 / 6',
+        'Bugs were found!' ,
+        'InvalidDynamicObjectChecker_20x: 2',
+        'InvalidDynamicObjectChecker_500: 1',
+        'PayloadBodyChecker_500: 1',
+        'Task Fuzz succeeded.'
+    ]
+    output = subprocess.run(
+        f'python ./restler-quick-start.py --api_spec_path {swagger_path} --restler_drop_dir {restler_drop_dir} --task fuzz',
+        shell=True, capture_output=True
+    )
+    check_output_errors(output)
+    # check_expected_output(restler_working_dir, expected_strings, output)
+
+def test_replay_task(restler_working_dir, task_output_dir, restler_drop_dir):
+    # Run the quick start script
+    print(f"Testing replay for bugs found in task output dir: {task_output_dir}")
+    output = subprocess.run(
+        f'python ./restler-quick-start.py --replay_bug_buckets_dir {task_output_dir} --restler_drop_dir {restler_drop_dir} --task replay',
+        shell=True, capture_output=True
+    )
+    check_output_errors(output)
+    # Check that the Replay directory is present and that it contains a bug bucket with the
+    # same bug.
+    original_bug_buckets_file_path = glob.glob(os.path.join(task_output_dir, 'RestlerResults/*/bug_buckets/bug_buckets.txt'))[0]
+
+    # TODO: it would be better if the replay command also produced a bug bucket, so they could be
+    # diff'ed with the original bug buckets.
+    # Until this is implemented, check that a 500 is found in the log.
+    # replay_buckets = glob.glob(os.path.join(restler_working_dir, 'Replay/RestlerResults/*/bug_buckets/bug_buckets.txt'))
+    network_log = glob.glob(os.path.join(restler_working_dir, 'Replay/RestlerResults/**/logs/network.*.txt'))
+    if network_log:
+        network_log = network_log[0]
+    else:
+        output = str(output.stdout)
+        raise QuickStartFailedException(f"No bug buckets were found after replay.  Output: {output}")
+
+    with open(network_log) as rf, open(original_bug_buckets_file_path) as of:
+        orig_buckets = of.read()
+        log_contents = rf.read()
+        if 'HTTP/1.1 500 INTERNAL SERVER ERROR' not in log_contents:
+            raise QuickStartFailedException(f"Failing because bug buckets {orig_buckets} were not reproduced.  Replay log: {log_contents}.")
+        else:
+            print("500 error was reproduced.")
+
+demo_server_output=[]
+
+def get_demo_server_output(demo_server_process):
+    demo_server_output.clear()
+    while True:
+        output = demo_server_process.stdout.readline()
+        if output:
+            demo_server_output.append(output)
+        else:
+            result = demo_server_process.poll()
+            if result is not None:
+                break
+
+    return result
+
 if __name__ == '__main__':
     curr = os.getcwd()
+
     # Run demo server in background
+    # Note: demo_server must be started in its directory
     os.chdir('demo_server')
     demo_server_path = Path('demo_server', 'app.py')
     demo_server_process = subprocess.Popen([sys.executable, demo_server_path],
                                     stdout=subprocess.PIPE,
                                     stderr=subprocess.STDOUT)
 
+    thread = Thread(target = get_demo_server_output, args = (demo_server_process, ))
+    thread.start()
+
     os.chdir(curr)
 
     swagger_path = Path('demo_server', 'swagger.json')
     # argv 1 = path to RESTler drop
     restler_drop_dir = sys.argv[1]
-
+    restler_working_dir = os.path.join(curr, RESTLER_WORKING_DIR)
+    test_failed = False
     try:
-        # Run the quick start script
-        output = subprocess.run(
-            f'python ./restler-quick-start.py --api_spec_path {swagger_path} --restler_drop_dir {restler_drop_dir}',
-            shell=True, capture_output=True
-        )
-        # Kill demo server
-        demo_server_process.terminate()
-        demo_server_out, _ = demo_server_process.communicate()
-        # Check if restler-quick-start succeeded
-        if output.stderr:
-            raise QuickStartFailedException(f"Failing because stderr was detected after running restler-quick-start:\n{output.stderr!s}")
-        try:
-            output.check_returncode()
-        except subprocess.CalledProcessError:
-            raise QuickStartFailedException(f"Failing because restler-quick-start exited with a non-zero return code: {output.returncode!s}")
+        print("+++++++++++++++++++++++++++++test...")
+        test_test_task(restler_working_dir, swagger_path, restler_drop_dir)
 
-        stdout = str(output.stdout)
+        print("+++++++++++++++++++++++++++++fuzzlean...")
+        test_fuzzlean_task(restler_working_dir, swagger_path, restler_drop_dir)
 
-        if 'Request coverage (successful / total): 6 / 6' not in stdout or\
-        'No bugs were found.' not in stdout or\
-        'Task Test succeeded.' not in stdout:
-            print(f"Demo server output: {demo_server_out}")
+        print("+++++++++++++++++++++++++++++replay...")
+        fuzzlean_task_dir = os.path.join(curr, RESTLER_WORKING_DIR, 'FuzzLean')
+        test_replay_task(restler_working_dir, fuzzlean_task_dir, restler_drop_dir)
 
-            stdout = stdout.replace('\\r\\n', '\r\n')
-            # Print the engine logs to the console
-            out_file_path = os.path.join(curr, RESTLER_WORKING_DIR, 'Test', 'EngineStdOut.txt')
-            err_file_path = os.path.join(curr, RESTLER_WORKING_DIR, 'Test', 'EngineStdErr.txt')
-            results_dir = os.path.join(curr, RESTLER_WORKING_DIR, 'Test', 'RestlerResults')
-            # Return the newest experiments directory in RestlerResults
-            net_log_dir = max(glob.glob(os.path.join(results_dir, 'experiment*/')), key=os.path.getmtime)
-            net_log_path = glob.glob(os.path.join(net_log_dir, 'logs', f'network.testing.*.1.txt'))[0]
-            with open(out_file_path) as of, open(err_file_path) as ef, open(net_log_path) as nf:
-                out = of.read()
-                err = ef.read()
-                net_log = nf.read()
+        #print("+++++++++++++++++++++++++++++fuzz...")
+        #test_fuzz_task(restler_working_dir, swagger_path, restler_drop_dir)
 
-            raise QuickStartFailedException(f"Failing because expected output was not found:\n{stdout}{out}{err}{net_log}")
+    except Exception:
+        test_failed = True
+        raise
     finally:
+        # Kill demo server
+        demo_server_process.terminate()
+        thread.join()
+        demo_server_out, _ = demo_server_process.communicate()
+        if test_failed:
+            print(f"Demo server output: {demo_server_output} {demo_server_out}")
+
         # Delete the working directory that was created during restler quick start
         shutil.rmtree(RESTLER_WORKING_DIR)
 

restler/engine/core/driver.py

@@ -758,6 +758,14 @@ def generate_sequences(fuzzing_requests, checkers, fuzzing_jobs=1):
 
     return num_total_sequences
 
+def get_host_and_port(hostname):
+    if ':' in hostname:
+        # If hostname includes port, split it out
+        host_split = hostname.split(':')
+        return host_split[0], host_split[1]
+    else:
+        return hostname, None
+
 def replay_sequence_from_log(replay_log_filename, token_refresh_cmd):
     """ Replays a sequence of requests from a properly formed log file
 
@@ -790,6 +798,9 @@ def replay_sequence_from_log(replay_log_filename, token_refresh_cmd):
                     hostname = get_hostname_from_line(line)
                     if hostname is None:
                         raise Exception("Host not found in request. The replay log may be corrupted.")
+                    hostname, port = get_host_and_port(hostname)
+                    if Settings().connection_settings.target_port is None and port is not None:
+                        Settings().set_port(port)
                     Settings().set_hostname(hostname)
 
                 # Append the request data to the list