[darwin][asan] add test for application specific information in crash logs

[aralisza]

Summary

Added a lit test that finds its corresponding crash log and checks to make sure it has asn output under Application Specific Information.

This required adding two python commands:

• get_pid_from_output: takes the output from the asan instrumentation and parses out the process ID
• print_crashreport_for_pid: takes in the pid of the process and the file name of the binary that was run and prints the contents of the corresponding crash log.

This test was added in preparation for changing the integration with crash reporter from the old api to the new api, which is implemented in a subsequent commit.

rdar://69767688

[delcypher]

compiler-rt/lib/sanitizer_common/sanitizer_mac.cpp

785 ↗

(On Diff #323843)

We should move this check and #include to near the top of the file. The problem with doing the #include here is that we're currently in the __sanitizer namespace. Many header files don't expect to be included inside a namespace and may misbehave. It's probably okay here because we're only using macros but to avoid potential problems in the future let's move the include to where all the others are near the top of the file outside of the __sanitizer namespace.

788 ↗

(On Diff #323843)

Both the #if ... and #else sides contain

extern "C" {

it's probably cleaner to hoist this out to make simpler code, i..e.:

extern "C" {
#if defined(HAVE_CRASHREPORTERCLIENT_H)
CRASH_REPORTER_CLIENT_HIDDEN
struct crashreporter_annotations_t gCRAnnotations
    __attribute__((section("__DATA," CRASHREPORTER_ANNOTATIONS_SECTION))) = {
        CRASHREPORTER_ANNOTATIONS_VERSION,
        0,
        0,
        0,
        0,
        0,
        0,
#if CRASHREPORTER_ANNOTATIONS_VERSION > 4
        0,
#endif
};
#else
// fall back to old crashreporter api
static const char *__crashreporter_info__ __attribute__((__used__)) =
    &__crashreporter_info_buff__[0];
asm(".desc ___crashreporter_info__, 0x10");

#endif
}

806 ↗

(On Diff #323843)

Have you tested that this old path compiles and works on macOS?

815 ↗

(On Diff #323843)

We should probably move the mutex declaration to be global and not a static variable.

1. In newer versions of C++/C where this is thread safe it apparently compiles down to some libc++ internals. I'd rather not pull in the dependency. See https://iamroman.org/blog/2017/04/cpp11-static-init/

2. (Minor reason as we con't compile with older C++ versions anymore). In older versions of the C++ language initializing static variables was racey (undefined behaviour). This is a little silly given that the goal of the mutex is to prevent races.

817 ↗

(On Diff #323843)

This "call" here is technically a race because it's not guarded by the mutex. It probably happens to work because all threads would write the same value if there were a race.

We should call CRSetCrashLogMessage after the mutex is held.

compiler-rt/lib/sanitizer_common/sanitizer_mac.h

68 ↗

(On Diff #323843)

I don't think we need the inline keyword here. I don't think it really adds that much because:

• Outside of sanitizer_mac.cpp we won't be able to inline unless we build with link-time-optimization (LTO) (I don't think we do that)
• Inside sanitizer_mac.cpp the benefits of inlining calls to CRAppendCrashLogMessage are a bit unknown at this point because I don't we've measure the perf impact, have we?

I suggest we drop the inline keyword and add it in a separate patch if we discover there's a perf problem.

compiler-rt/test/asan/TestCases/Darwin/asan_log_to_crashreporter.cpp

2

Is this a copy-paste error? This comment doesn't make sense to me because we are modifying ASAN_OPTIONS by the using the %env_asan_opts substitution.

2

We should mark this test with.

UNSUPPORTED: ios

until we've made it possible to run on iOS.

2

I think we should introduce the test as a separate patch first. Then as a second patch do the api change.

9

Could we do something like?

RUN: TEST_PID="$(%ios_command get_pid_from_output.py <%t.process_output.txt)" ; \
RUN: %ios_command print_crashreport_for_pid.py --filename=%basename_t.tmp --pid=$(TEST_PID) | FileCheck %s

This makes it much more obvious how the PID is getting passed?

18

Side note. If the crash reporter prefs are set to "Server", do the crash logs still show up?

compiler-rt/test/lit.common.cfg.py

599

As we discussed I'm not a huge fan of this.

1. %ios_command is a bit confusing because we aren't using this command on iOS (yet).
2. The current precedent it to use separate substitutions for each command introduced..
3. We shouldn't hardcode python here because the CMake build might have been configured to use a different python install. You can probably use config.python_executable here (see lit.common.configured.in). Take a look at how %asan_symbolize is set.

compiler-rt/test/sanitizer_common/ios_commands/get_pid_from_output.py

2

Maybe add a doc string explaining what this script does?

compiler-rt/test/sanitizer_common/ios_commands/print_crashreport_for_pid.py

2

Maybe add a doc string explaining what this script does?

7

Filename is a little misleading here. It's actually the filename prefix rather than the whole filename. Rather than exposing this implementation detail maybe this option should be called --binary-filename ?

15

I'd suggest removing this part. Parsing the pid on stdin is not very intuitive. maybe we should make passing the pid a mandatory argument?

20

The retry_count should probably be settable from the command line so we can conveniently change it from a test.

27

This variable back-off strategy probably deserves a comment.

[aralisza]

most of the code review comments

compiler-rt/lib/sanitizer_common/sanitizer_mac.cpp

806 ↗

(On Diff #323843)

Yes, the test I wrote passes on this path on my machine.

compiler-rt/test/asan/TestCases/Darwin/asan_log_to_crashreporter.cpp

18

Yup!

From reading the description of that setting, it should only change whether the popup dialog window shows up or not and does not affect whether the crashlog itself is created.

[aralisza]

actual change

[aralisza]

remove implementation changes

[aralisza]

Moved implementation changes to a stacked diff

[delcypher]

compiler-rt/test/lit.common.cfg.py

599

This will likely fail if any the paths have spaces in them. You probably want to wrap config.python_executable and get_ios_commands_dir() in a call to sh_quote() (defined in the asan lit config file right now).

compiler-rt/test/sanitizer_common/ios_commands/print_crashreport_for_pid.py

15

Is pid actually mandatory? I don't see anything in the script that enforces that. It just looks like we won't find any crash logs after searching through all the files. We should probably just error out earlier if the pid isn't provided.

32

I wonder if this approach will be reliable enough when the machine is under heavy load.

tries = 10
t = 2.0
acc = 0
for x in range(1, tries+1):
  acc += (t / x)
print("total: {}".format(acc))
...
total: 5.8579365079365076

So the maximum time we'll wait here is just under 6 seconds. I wonder if that's long enough. Of course scanning the disk and opening the log files might end up actually dominating execution time if there are a lot of crash logs on the machine.

[aralisza]

compiler-rt/test/sanitizer_common/ios_commands/print_crashreport_for_pid.py

32

I'll increase t=5 so the total time will be ~15 seconds. Hopefully that'll be enough

[aralisza]

make pid and binary filename required and increase time to wait between retries

[delcypher]

LGTM

[aralisza]

disable lit test and add radar number

[aralisza]

line length fix

[delcypher]

LGTM

compiler-rt/test/asan/TestCases/Darwin/asan_log_to_crashreporter.cpp

+// UNSUPPORTED: ios
+// Check that ASan reports on OS X actually crash the process (abort_on_error=1)
+// and that crash is logged via the crash reporter with ASan logs in the
+// Application Specific Information section of the log.
+
+// RUN: %clangxx_asan %s -o %t
+
+// crash hard so the crashlog is created.
+// RUN: %env_asan_opts=abort_on_error=1 not --crash %run %t > %t.process_output.txt 2>&1
+// RUN: %print_crashreport_for_pid --binary-filename=%basename_t.tmp --pid=$(%get_pid_from_output --infile=%t.process_output.txt) \
+// RUN: | FileCheck %s --check-prefixes CHECK-CRASHLOG
+
+#include <stdlib.h>
+int main() {
+  char *x = (char *)malloc(10 * sizeof(char));
+  free(x);
+  return x[5];
+  // needs to crash hard so the crashlog exists...
+  // CHECK-CRASHLOG: {{.*Application Specific Information:}}
+  // CHECK-CRASHLOG-NEXT: {{=====}}
+  // CHECK-CRASHLOG-NEXT: {{.*ERROR: AddressSanitizer: heap-use-after-free on address}}
+  // CHECK-CRASHLOG: {{abort()}}
+}

compiler-rt/test/lit.common.cfg.py

def get_lit_conf(name, default=None):
     if val is None:
         val = getattr(config, name, None)
         if val is None:
             val = default
     return val
 
 emulator = get_lit_conf('emulator', None)
 
+def get_ios_commands_dir():
+  return os.path.join(config.compiler_rt_src_root, "test", "sanitizer_common", "ios_commands")
+
 # Allow tests to be executed on a simulator or remotely.
 if emulator:
   config.substitutions.append( ('%run', emulator) )
   config.substitutions.append( ('%env ', "env ") )
   # TODO: Implement `%device_rm` to perform removal of files in the emulator.
   # For now just make it a no-op.
   lit_config.warning('%device_rm is not implemented')
   config.substitutions.append( ('%device_rm', 'echo ') )
if ios_or_iossim == "iossim":
     config.available_features.add('iossim')
     if device_id_env not in os.environ:
       lit_config.fatal(
         '{} must be set in the environment when running iossim tests'.format(
           device_id_env))
   if config.apple_platform != "ios" and config.apple_platform != "iossim":
     config.available_features.add(config.apple_platform)
 
-  ios_commands_dir = os.path.join(config.compiler_rt_src_root, "test", "sanitizer_common", "ios_commands")
+  ios_commands_dir = get_ios_commands_dir()
 
   run_wrapper = os.path.join(ios_commands_dir, ios_or_iossim + "_run.py")
   env_wrapper = os.path.join(ios_commands_dir, ios_or_iossim + "_env.py")
   compile_wrapper = os.path.join(ios_commands_dir, ios_or_iossim + "_compile.py")
   prepare_script = os.path.join(ios_commands_dir, ios_or_iossim + "_prepare.py")
 
   if device_id_env in os.environ:
     config.environment[device_id_env] = os.environ[device_id_env]

 # Append any extra flags passed in lit_config
 append_target_cflags = lit_config.params.get('append_target_cflags', None)
 if append_target_cflags:
   lit_config.note('Appending to extra_cflags: "{}"'.format(append_target_cflags))
   extra_cflags += [append_target_cflags]
 
 config.clang = " " + " ".join(run_wrapper + [config.compile_wrapper, config.clang]) + " "
 config.target_cflags = " " + " ".join(target_cflags + extra_cflags) + " "
+
+if config.host_os == 'Darwin':
+  config.substitutions.append(("%get_pid_from_output", "{} {}/get_pid_from_output.py".format(config.python_executable, get_ios_commands_dir())))
+  config.substitutions.append(("%print_crashreport_for_pid", "{} {}/print_crashreport_for_pid.py".format(config.python_executable, get_ios_commands_dir())))

compiler-rt/test/sanitizer_common/ios_commands/get_pid_from_output.py

+"""
+Parses the id of the process that ran with ASAN from the output logs.
+"""
+import sys, argparse, re
+
+def main():
+    parser = argparse.ArgumentParser()
+    parser.add_argument('--infile', nargs='?', type=argparse.FileType('r'), default=sys.stdin, help='The sanitizer output to get the pid from')
+    parser.add_argument('--outfile', nargs='?', type=argparse.FileType('r'), default=sys.stdout, help='Where to write the result')
+    args = parser.parse_args()
+
+    pid = process_file(args.infile)
+    args.outfile.write(pid)
+    args.infile.close()
+    args.outfile.close()
+
+
+
+def process_file(infile):
+    # check first line is just ==== divider
+    first_line_pattern = re.compile(r'=*')
+    assert first_line_pattern.match(infile.readline())
+
+    # parse out pid from 2nd line 
+    # `==PID==ERROR: SanitizerName: error-type on address...`
+    pid_pattern = re.compile(r'==([0-9]*)==ERROR:')
+    pid = pid_pattern.search(infile.readline()).group(1)
+
+    # ignore the rest
+
+    assert pid and pid.isdigit()
+
+    return pid
+
+if __name__ == '__main__':
+    main()

compiler-rt/test/sanitizer_common/ios_commands/print_crashreport_for_pid.py

+"""
+Finds and prints the crash report associated with a specific (binary filename, process id).
+Waits (max_wait_time/attempts_remaining) between retries.
+Errors if the report cannot be found after `retry_count` retries.
+"""
+import sys, os, argparse, re, glob, shutil, time
+
+def main():
+    parser = argparse.ArgumentParser()
+    parser.add_argument('--pid', type=str, help='The process id of the process that crashed')
+    parser.add_argument('--binary-filename', type=str, help='The name of the file that crashed')
+    parser.add_argument('--retry-count', type=int, nargs='?', default=10, help='The number of retries to make')
+    parser.add_argument('--max-wait-time', type=float, nargs='?', default=2.0, help='The max amount of seconds to wait between tries')
+
+    parser.add_argument('--dir', nargs='?', type=str, default="~/Library/Logs/DiagnosticReports", help='The directory to look for the crash report')
+    parser.add_argument('--outfile', nargs='?', type=argparse.FileType('r'), default=sys.stdout, help='Where to write the result')
+    args = parser.parse_args()
+
+    os.chdir(os.path.expanduser(args.dir))
+    output_report_with_retries(args.outfile, args.pid.strip(), args.binary_filename, args.retry_count, args.max_wait_time)
+
+def output_report_with_retries(outfile, pid, filename, attempts_remaining, max_wait_time):
+    report_name = find_report_in_cur_dir(pid, filename)
+    if report_name:
+        with open(report_name, "r") as f:
+            shutil.copyfileobj(f, outfile)
+        return
+    elif(attempts_remaining > 0):
+        # As the number of attempts remaining decreases, increase the number of seconds waited
+        # if the max wait time is 2s and there are 10 attempts remaining, wait .2 seconds.
+        # if the max wait time is 2s and there are 2 attempts remaining, wait 1 second. 
+        time.sleep(max_wait_time / attempts_remaining)
+        output_report_with_retries(outfile, pid, filename, attempts_remaining - 1, max_wait_time)
+    else:
+        raise RuntimeError("Report not found for ({}, {}).".format(filename, pid))
+
+def find_report_in_cur_dir(pid, filename):
+    for report_name in sorted(glob.glob("{}_*.crash".format(filename)), reverse=True):
+        # parse out pid from first line of report
+        # `Process:               filename [pid]``
+        with open(report_name) as cur_report:
+            pattern = re.compile(r'Process: *{} \[([0-9]*)\]'.format(filename))
+            cur_report_pid = pattern.search(cur_report.readline()).group(1)
+
+        assert cur_report_pid and cur_report_pid.isdigit()
+        if cur_report_pid == pid:
+            return report_name
+
+    # did not find the crash report
+    return None
+        
+
+if __name__ == '__main__':
+    main()