diff --git a/common/BUILD b/common/BUILD index 99450c22..53e6d241 100644 --- a/common/BUILD +++ b/common/BUILD @@ -179,6 +179,7 @@ cc_library( ":snapshot_enums", ":snapshot_types", "@silifuzz//proto:snapshot_cc_proto", + "@silifuzz//proto:snapshot_execution_result_cc_proto", "@silifuzz//util:checks", "@silifuzz//util:misc_util", "@silifuzz//util:platform", diff --git a/common/snapshot_enums.h b/common/snapshot_enums.h index 4eb9f042..0249c2a1 100644 --- a/common/snapshot_enums.h +++ b/common/snapshot_enums.h @@ -98,7 +98,7 @@ class Endpoint final { using SigCause = snapshot_types::SigCause; using enum snapshot_types::SigCause; - // Enpoint that is the first occurrence of reaching the instruction_address. + // Endpoint that is the first occurrence of reaching the instruction_address. // I.e. type() == kInstruction. explicit Endpoint(Address instruction_address); @@ -254,6 +254,25 @@ enum class MakerStopReason { kSignal, }; +// Status codes for runner execution. +// Parallels RunnerOutput::ExecutionResult::StatusCode proto. +enum class RunnerExecutionStatusCode { + kInternalError = 0, + kOk = 1, + kUnhandledSignal = 2, + kMmapFailed = 3, + kOverlappingMappings = 4, + kInitialChecksumMismatch = 5, + kSnapshotFailed = 6, +}; + +// Parallels RunnerOutput::ExecutionResult::ChecksumStatus proto. +enum class RunnerPostfailureChecksumStatus { + kNotChecked = 0, + kMatch = 1, + kMismatch = 2, +}; + } // namespace snapshot_types template <> diff --git a/common/snapshot_proto.cc b/common/snapshot_proto.cc index 9883dc5a..1935a609 100644 --- a/common/snapshot_proto.cc +++ b/common/snapshot_proto.cc @@ -26,6 +26,7 @@ #include "./common/snapshot.h" #include "./common/snapshot_enums.h" #include "./proto/snapshot.pb.h" +#include "./proto/snapshot_execution_result.pb.h" #include "./util/checks.h" #include "./util/misc_util.h" #include "./util/platform.h" @@ -133,6 +134,41 @@ static_assert(ToInt(PlatformId::kAmdRyzenV3000) == static_assert(ToInt(PlatformId::kArmNeoverseV2) == ToInt(proto::PlatformId::ARM_NEOVERSE_V2)); +static_assert(ToInt(snapshot_types::RunnerExecutionStatusCode::kOk) == + ToInt(proto::RunnerOutput::ExecutionResult::OK)); +static_assert( + ToInt(snapshot_types::RunnerExecutionStatusCode::kInternalError) == + ToInt(proto::RunnerOutput::ExecutionResult::INTERNAL_ERROR)); +static_assert( + ToInt(snapshot_types::RunnerExecutionStatusCode::kUnhandledSignal) == + ToInt(proto::RunnerOutput::ExecutionResult::UNHANDLED_SIGNAL)); +static_assert(ToInt(snapshot_types::RunnerExecutionStatusCode::kMmapFailed) == + ToInt(proto::RunnerOutput::ExecutionResult::MMAP_FAILED)); +static_assert( + ToInt(snapshot_types::RunnerExecutionStatusCode::kOverlappingMappings) == + ToInt(proto::RunnerOutput::ExecutionResult::OVERLAPPING_MAPPINGS)); +static_assert( + ToInt( + snapshot_types::RunnerExecutionStatusCode::kInitialChecksumMismatch) == + ToInt(proto::RunnerOutput::ExecutionResult::INITIAL_CHECKSUM_MISMATCH)); +static_assert( + ToInt(snapshot_types::RunnerExecutionStatusCode::kSnapshotFailed) == + ToInt(proto::RunnerOutput::ExecutionResult::SNAPSHOT_FAILED)); + +static_assert( + ToInt(snapshot_types::RunnerPostfailureChecksumStatus::kNotChecked) == + ToInt(proto::RunnerOutput::ChecksumStatus:: + RunnerOutput_ChecksumStatus_NOT_CHECKED)); + +static_assert(ToInt(snapshot_types::RunnerPostfailureChecksumStatus::kMatch) == + ToInt(proto::RunnerOutput::ChecksumStatus:: + RunnerOutput_ChecksumStatus_MATCH)); + +static_assert( + ToInt(snapshot_types::RunnerPostfailureChecksumStatus::kMismatch) == + ToInt(proto::RunnerOutput::ChecksumStatus:: + RunnerOutput_ChecksumStatus_MISMATCH)); + static_assert(proto::PlatformId_MAX < 64, "PlatformId_MAX is too large to fit in EndState::platforms"); diff --git a/orchestrator/BUILD b/orchestrator/BUILD index 66fdafcc..4f5e3384 100644 --- a/orchestrator/BUILD +++ b/orchestrator/BUILD @@ -60,7 +60,6 @@ cc_library( "@com_google_absl//absl/base:core_headers", "@com_google_absl//absl/base:log_severity", "@com_google_absl//absl/log:check", - "@com_google_absl//absl/status", "@com_google_absl//absl/status:statusor", "@com_google_absl//absl/strings", "@com_google_absl//absl/synchronization", @@ -115,11 +114,11 @@ cc_test( deps = [ ":binary_log_channel", ":result_collector", - "@silifuzz//common:snapshot_enums", "@silifuzz//proto:binary_log_entry_cc_proto", "@silifuzz//proto:snapshot_execution_result_cc_proto", "@silifuzz//runner/driver:runner_driver", "@silifuzz//util/testing:status_macros", + "@com_google_absl//absl/strings:string_view", "@com_google_absl//absl/time", "@com_google_googletest//:gtest_main", ], diff --git a/orchestrator/orchestrator_test.py b/orchestrator/orchestrator_test.py index 29b99931..52dafc28 100644 --- a/orchestrator/orchestrator_test.py +++ b/orchestrator/orchestrator_test.py @@ -44,7 +44,8 @@ def setUpClass(cls): super(OrchestratorTest, cls).setUpClass() corpus_paths = [_ENDS_AS_EXPECTED_CORPUS_PATH, _RUNAWAY_CORPUS_PATH] for i, original_path in enumerate(corpus_paths): - contents = open(original_path, 'rb').read() + with open(original_path, 'rb') as f: + contents = f.read() # Compress one corpus only. The orchestrator can load # both corpora with and without compression. is_compressed = i > 0 @@ -217,7 +218,9 @@ def test_snap_failure(self): (err_log, returncode) = self.run_orchestrator( ['snap_fail'], extra_args=['--enable_v1_compat_logging'] ) - self.assertEqual(returncode, 1) + self.assertEqual( + returncode, 1, msg='Expected EXIT_FAILURE ' + '\n'.join(err_log) + ) latest_entry = self._parse_v1_log(err_log) self.assertGreater( int(latest_entry['issues_detected']), @@ -287,11 +290,50 @@ def test_duration(self): err_log, [ 'corpus: ends_as_expected_corpus', - 'error: Runner killed by signal 14', + 'Runner killed by signal 14', 'exit_status: internal_error', ], ) + def test_checksum_mismatch(self): + (err_log, returncode) = self.run_orchestrator(['checksum_mismatch']) + self.assertEqual( + returncode, 1, msg='Expected EXIT_FAILURE ' + '\n'.join(err_log) + ) + self.assertStrSeqContainsAll( + err_log, + [ + 'Snapshot checksum mismatch', + ], + ) + + def test_no_execution_result(self): + (err_log, returncode) = self.run_orchestrator(['no_execution_result']) + self.assertEqual(returncode, 0) + self.assertStrSeqContainsAll( + err_log, + [ + 'Missing required execution_result', + ], + ) + + def test_mmap_failed(self): + (err_log, returncode) = self.run_orchestrator(['mmap_failed']) + self.assertEqual( + returncode, + 0, + msg=( + 'Expected no failure from the orchestrator if the runner fails to' + ' map memory' + ), + ) + self.assertStrSeqContainsAll( + err_log, + [ + 'failed to map memory', + ], + ) + def test_watchdog(self): (err_log, returncode) = self.run_orchestrator( ['ignore_alarm', 'sleep100'], diff --git a/orchestrator/result_collector.cc b/orchestrator/result_collector.cc index 427d7f49..ac338dc0 100644 --- a/orchestrator/result_collector.cc +++ b/orchestrator/result_collector.cc @@ -90,9 +90,9 @@ absl::StatusOr RunResultToSnapshotExecutionResult( proto::BinaryLogEntry entry; proto::SnapshotExecutionResult *snapshot_execution_result = entry.mutable_snapshot_execution_result(); - snapshot_execution_result->set_snapshot_id(run_result.snapshot_id()); + snapshot_execution_result->set_snapshot_id(run_result.failed_snapshot_id()); RETURN_IF_NOT_OK(PlayerResultProto::ToProto( - run_result.player_result(), + run_result.failed_player_result(), *snapshot_execution_result->mutable_player_result())); snapshot_execution_result->set_hostname(std::string(ShortHostname())); @@ -123,8 +123,8 @@ void LogV1SingleSnapFailure(const RunnerDriver::RunResult &run_result) { absl::GetFlag(FLAGS_enable_v1_compat_logging); if (!enable_v1_compat_logging) return; std::cerr << "Silifuzz detected issue on CPU " - << run_result.player_result().cpu_id << " running snapshot " - << run_result.snapshot_id() << '\n'; + << run_result.failed_player_result().cpu_id << " running snapshot " + << run_result.failed_snapshot_id() << std::endl; } // Logs V1-style summary e.g. @@ -151,7 +151,7 @@ void LogV1CompatSummary(const Summary &summary, absl::Duration elapsed, << ", snapshot_execution_errors = 0" << ", runaway_count = " << summary.num_runaway_snapshots << ", max_rss_kb = " << max_rss_kb - << ", had_checker_misconfigurations = false}" << '\n'; + << ", had_checker_misconfigurations = false}" << std::endl; } } // namespace @@ -175,23 +175,33 @@ bool ResultCollector::operator()(const RunnerDriver::RunResult &result) { max_rss_kb_ = std::max(max_rss_kb_, MaxRunnerRssSizeBytes(getpid()) / 1024); bool should_stop = false; if (!result.success()) { - if (result.player_result().outcome == - snapshot_types::PlaybackOutcome::kExecutionRunaway) { - summary_.num_runaway_snapshots++; - if (!options_.report_runaways_as_errors) return false; + if (!result.execution_result().ok()) { + // TODO(ksteuck) Report the error to `binary_log_producer_`. + VLOG_INFO(1, result.execution_result().DebugString()); } - ++summary_.num_failed_snapshots; - LogV1SingleSnapFailure(result); - absl::StatusOr entry_or = - RunResultToSnapshotExecutionResult(result, absl::Now(), session_id_); - if (entry_or.ok()) { - if (binary_log_producer_) { - if (absl::Status s = binary_log_producer_->Send(*entry_or); !s.ok()) { - LOG_ERROR(s.message()); + if (result.has_failed_player_result()) { + // Currently, only explicitly failed snapshots count towards the overall + // failure status. + // TODO(ksteuck) Consider what non-successful execution_result codes + // should be considered as failures. + if (result.failed_player_result().outcome == + snapshot_types::PlaybackOutcome::kExecutionRunaway) { + summary_.num_runaway_snapshots++; + if (!options_.report_runaways_as_errors) return false; + } + ++summary_.num_failed_snapshots; + LogV1SingleSnapFailure(result); + absl::StatusOr entry = + RunResultToSnapshotExecutionResult(result, absl::Now(), session_id_); + if (entry.ok()) { + if (binary_log_producer_) { + if (absl::Status s = binary_log_producer_->Send(*entry); !s.ok()) { + LOG_ERROR(s.message()); + } } + } else { + LOG_ERROR(entry.status().message()); } - } else { - LOG_ERROR(entry_or.status().message()); } should_stop = (--options_.fail_after_n_errors <= 0); } diff --git a/orchestrator/result_collector_test.cc b/orchestrator/result_collector_test.cc index 397ac7b2..9cce66d7 100644 --- a/orchestrator/result_collector_test.cc +++ b/orchestrator/result_collector_test.cc @@ -17,8 +17,8 @@ #include #include "gtest/gtest.h" +#include "absl/strings/string_view.h" #include "absl/time/clock.h" -#include "./common/snapshot_enums.h" #include "./orchestrator/binary_log_channel.h" #include "./proto/binary_log_entry.pb.h" #include "./proto/snapshot_execution_result.pb.h" @@ -26,18 +26,25 @@ #include "./util/testing/status_macros.h" namespace silifuzz { -namespace { -using snapshot_types::PlaybackOutcome; +class RunResultPeer { + public: + static RunnerDriver::RunResult SnapshotFailed(absl::string_view snapshot_id) { + RunnerDriver::PlayerResult result = { + .outcome = PlaybackOutcome::kExecutionMisbehave}; + return RunnerDriver::RunResult( + RunnerDriver::ExecutionResult::SnapshotFailed(snapshot_id), result, {}, + snapshot_id); + } +}; +namespace { TEST(ResultCollector, Simple) { ResultCollector collector(-1, absl::Now(), {}); collector(RunnerDriver::RunResult::Successful({})); ASSERT_EQ(collector.summary().play_count, 1); ASSERT_EQ(collector.summary().num_failed_snapshots, 0); - RunnerDriver::PlayerResult result = { - .outcome = PlaybackOutcome::kExecutionMisbehave}; - collector(RunnerDriver::RunResult(result, {}, "snap_id")); + collector(RunResultPeer::SnapshotFailed("snap_id")); ASSERT_EQ(collector.summary().play_count, 2); ASSERT_EQ(collector.summary().num_failed_snapshots, 1); } @@ -48,9 +55,7 @@ TEST(ResultCollector, BinaryLogging) { { ResultCollector collector(pipefd[1], absl::Now(), {}); collector(RunnerDriver::RunResult::Successful({})); - RunnerDriver::PlayerResult result = { - .outcome = PlaybackOutcome::kExecutionMisbehave}; - collector(RunnerDriver::RunResult(result, {}, "snap_id")); + collector(RunResultPeer::SnapshotFailed("snap_id")); // Let collector go out of scope which closes the write end of the pipe. // This way the Receive() below does not block if logging misbehaves. } diff --git a/orchestrator/silifuzz_orchestrator.cc b/orchestrator/silifuzz_orchestrator.cc index 047bc0c5..007e5ee2 100644 --- a/orchestrator/silifuzz_orchestrator.cc +++ b/orchestrator/silifuzz_orchestrator.cc @@ -22,7 +22,6 @@ #include "absl/base/log_severity.h" #include "absl/log/check.h" -#include "absl/status/status.h" #include "absl/status/statusor.h" #include "absl/strings/str_cat.h" #include "absl/strings/string_view.h" @@ -38,16 +37,17 @@ namespace silifuzz { namespace { // Returns a string representation of StatusOr. -std::string RunResultToDebugString( - const absl::StatusOr &run_result_or) { - if (run_result_or.ok()) { - if (run_result_or->success()) { - return "ok"; - } else { +std::string RunResultToDebugString(const RunnerDriver::RunResult &run_result) { + if (run_result.success()) { + return "ok"; + } + switch (run_result.execution_result().code) { + case RunnerDriver::ExecutionResult::Code::kInternalError: + return "internal_error"; + case RunnerDriver::ExecutionResult::Code::kSnapshotFailed: return "snap_fail"; - } - } else { - return "internal_error"; + default: + return "unknown"; } } } // namespace @@ -173,22 +173,25 @@ void RunnerThread(ExecutionContext *ctx, const RunnerThreadArgs &args) { const InMemoryShard &shard = args.corpora->shards[shard_idx]; RunnerDriver driver = RunnerDriver::ReadingRunner(args.runner, shard.file_path, shard.name); - absl::StatusOr run_result_or = - driver.Run(runner_options); + RunnerDriver::RunResult run_result = driver.Run(runner_options); absl::Duration elapsed_time = absl::Now() - start_time; std::string log_msg = absl::StrCat( "T", args.thread_idx, " cpu: ", args.runner_options.cpu(), " corpus: ", shard.name, " time: ", absl::ToInt64Seconds(elapsed_time), - " exit_status: ", RunResultToDebugString(run_result_or)); - if (!run_result_or.ok()) { - LOG_ERROR(log_msg, " error: ", run_result_or.status().message()); + " exit_status: ", RunResultToDebugString(run_result)); + if (!run_result.execution_result().ok()) { + LOG_ERROR(log_msg, " ", run_result.execution_result().DebugString()); + if (run_result.postfailure_checksum_status() == + RunnerPostfailureChecksumStatus::kMismatch) { + LOG_ERROR("Snapshot checksum mismatch"); + } } else { VLOG_INFO(0, log_msg); } - if (!ctx->OfferRunResult(std::move(run_result_or))) { + if (!ctx->OfferRunResult(std::move(run_result))) { LOG_ERROR( "T", args.thread_idx, " Result processing queue is stuck, some results won't be logged"); diff --git a/orchestrator/test_runner.cc b/orchestrator/test_runner.cc index a7679cc5..829434d3 100644 --- a/orchestrator/test_runner.cc +++ b/orchestrator/test_runner.cc @@ -102,9 +102,20 @@ int main(int argc, char** argv) { } else if (cmd == "snap_fail") { LogHumanReadable("snap_fail: %s\n", "my_snap"); fprintf(stdout, - "snapshot_id:'my_snap' player_result:{ outcome:3 cpu_id:1 " - "actual_end_state:{ endpoint:{ instruction_address:0x6595e5c4025 " - "} registers: { gregs: '' fpregs: '' } } }"); + R"pb( + execution_result: { code: SNAPSHOT_FAILED } + failed_snapshot_execution: { + snapshot_id: 'my_snap' + player_result: { + outcome: REGISTER_STATE_MISMATCH + cpu_id: 1 + actual_end_state: { + endpoint: { instruction_address: 0x6595e5c4025 } + registers: { gregs: '' fpregs: '' } + } + } + } + )pb"); fflush(stdout); return 1; } else if (cmd == "print_first_snap_id") { @@ -117,6 +128,40 @@ int main(int argc, char** argv) { sigaction(SIGALRM, &sigact, nullptr); } else if (cmd == "sleep100") { sleep(100); + } else if (cmd == "checksum_mismatch") { + LogHumanReadable("checksum_mismatch"); + fprintf(stdout, + R"pb( + failed_snapshot_execution: { + snapshot_id: 'my_snap' + player_result: { + outcome: REGISTER_STATE_MISMATCH + cpu_id: 1 + actual_end_state: { + endpoint: { instruction_address: 0x6595e5c4025 } + registers: { gregs: '' fpregs: '' } + } + } + } + postfailure_checksum_status: MISMATCH + execution_result: { code: SNAPSHOT_FAILED } + )pb"); + fflush(stdout); + return 1; + } else if (cmd == "no_execution_result") { + LogHumanReadable("no_execution_result"); + fprintf(stdout, R"pb()pb"); + fflush(stdout); + return 1; + } else if (cmd == "mmap_failed") { + LogHumanReadable("mmap_failed"); + fprintf( + stdout, + R"pb( + execution_result: { code: MMAP_FAILED msg: 'failed to map memory' } + )pb"); + fflush(stdout); + return 1; } else { if (print_first_snap_id) { silifuzz::PrintFirstSnapId(argv[i]); diff --git a/proto/snapshot_execution_result.proto b/proto/snapshot_execution_result.proto index f9a41bc9..94cf8304 100644 --- a/proto/snapshot_execution_result.proto +++ b/proto/snapshot_execution_result.proto @@ -34,6 +34,10 @@ message SnapshotExecutionResult { optional PlayerResult player_result = 2; // Time when this result was recorded. + // NOTE that this field must be preserved for compatibility with older + // text-formatted results. + // TODO(ksteuck): Revisit once the old data has gone beyond the analysis + // horizon (Q2 2025-ish). optional google.protobuf.Timestamp time = 3 [deprecated = true]; } diff --git a/runner/BUILD b/runner/BUILD index 00e89664..af0db1bd 100644 --- a/runner/BUILD +++ b/runner/BUILD @@ -290,8 +290,6 @@ cc_test( "@silifuzz//util/testing:status_matchers", "@silifuzz//util/ucontext:serialize", "@silifuzz//util/ucontext:ucontext_types", - "@com_google_absl//absl/status", - "@com_google_absl//absl/status:statusor", "@com_google_absl//absl/strings", "@com_google_absl//absl/time", "@com_google_googletest//:gtest_main", diff --git a/runner/aarch64/disassembling_snap_tracer_test.cc b/runner/aarch64/disassembling_snap_tracer_test.cc index c2a8dddf..be87a62a 100644 --- a/runner/aarch64/disassembling_snap_tracer_test.cc +++ b/runner/aarch64/disassembling_snap_tracer_test.cc @@ -61,11 +61,8 @@ TEST(DisassemblingSnapTracer, TraceAsExpected) { auto snapshot = MakeSnapRunnerTestSnapshot(TestSnapshot::kEndsAsExpected); DisassemblingSnapTracer tracer(snapshot); - ASSERT_OK_AND_ASSIGN( - auto result, - driver.TraceOne( - snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer))); + auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer)); ASSERT_TRUE(result.success()); const auto& trace_result = tracer.trace_result(); EXPECT_EQ(trace_result.instructions_executed, 4); @@ -79,14 +76,12 @@ TEST(DisassemblingSnapTracer, TraceSigill) { RunnerDriver driver = HelperDriver(); auto snapshot = MakeSnapRunnerTestSnapshot(TestSnapshot::kSigIll); DisassemblingSnapTracer tracer(snapshot); - ASSERT_OK_AND_ASSIGN( - auto result, - driver.TraceOne( - snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer))); + auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer)); ASSERT_FALSE(result.success()); - ASSERT_TRUE(result.player_result().actual_end_state->endpoint().sig_num() == - SigNum::kSigIll); + ASSERT_TRUE( + result.failed_player_result().actual_end_state->endpoint().sig_num() == + SigNum::kSigIll); } TEST(DisassemblingSnapTracer, TraceMultipeTimes) { @@ -95,11 +90,9 @@ TEST(DisassemblingSnapTracer, TraceMultipeTimes) { MakeSnapRunnerTestSnapshot(TestSnapshot::kEndsAsExpected); DisassemblingSnapTracer tracer(snapshot); constexpr size_t kNumIterations = 3; - ASSERT_OK_AND_ASSIGN( - auto result, - driver.TraceOne(snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer), - kNumIterations)); + auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer), + kNumIterations); ASSERT_TRUE(result.success()); const auto& trace_result = tracer.trace_result(); EXPECT_EQ(trace_result.instructions_executed, 4 * kNumIterations); diff --git a/runner/driver/BUILD b/runner/driver/BUILD index 9f2c4915..c22977cc 100644 --- a/runner/driver/BUILD +++ b/runner/driver/BUILD @@ -80,10 +80,8 @@ cc_test( "@silifuzz//util:itoa", "@silifuzz//util:path_util", "@silifuzz//util/testing:status_macros", - "@silifuzz//util/testing:status_matchers", "@silifuzz//util/ucontext:serialize", "@silifuzz//util/ucontext:ucontext_types", - "@com_google_absl//absl/status", "@com_google_absl//absl/status:statusor", "@com_google_googletest//:gtest_main", ], diff --git a/runner/driver/runner_driver.cc b/runner/driver/runner_driver.cc index 8cc677fc..978884ec 100644 --- a/runner/driver/runner_driver.cc +++ b/runner/driver/runner_driver.cc @@ -51,45 +51,49 @@ namespace silifuzz { -absl::StatusOr RunnerDriver::PlayOne( - absl::string_view snap_id, int cpu) const { +RunnerDriver::RunResult RunnerDriver::PlayOne(absl::string_view snap_id, + int cpu) const { CHECK(!snap_id.empty()); return RunImpl(RunnerOptions::PlayOptions(snap_id, cpu), snap_id); } -absl::StatusOr RunnerDriver::MakeOne( - absl::string_view snap_id, size_t max_pages_to_add, int cpu) const { +RunnerDriver::RunResult RunnerDriver::MakeOne(absl::string_view snap_id, + size_t max_pages_to_add, + int cpu) const { CHECK(!snap_id.empty()); return RunImpl(RunnerOptions::MakeOptions(snap_id, max_pages_to_add, cpu), snap_id); } -absl::StatusOr RunnerDriver::TraceOne( - absl::string_view snap_id, HarnessTracer::Callback cb, - size_t num_iterations, int cpu) const { +RunnerDriver::RunResult RunnerDriver::TraceOne(absl::string_view snap_id, + HarnessTracer::Callback cb, + size_t num_iterations, + int cpu) const { CHECK(!snap_id.empty()); return RunImpl(RunnerOptions::TraceOptions(snap_id, num_iterations, cpu), snap_id, cb); } -absl::StatusOr RunnerDriver::VerifyOneRepeatedly( +RunnerDriver::RunResult RunnerDriver::VerifyOneRepeatedly( absl::string_view snap_id, int num_attempts, int cpu) const { CHECK(!snap_id.empty()); auto opts = RunnerOptions::VerifyOptions(snap_id, cpu); for (int i = 0; i < num_attempts - 1; ++i) { - RETURN_IF_NOT_OK(RunImpl(opts, snap_id).status()); + if (auto result = RunImpl(opts, snap_id); !result.success()) { + return result; + } } return RunImpl(opts, snap_id); } -absl::StatusOr RunnerDriver::Run( +RunnerDriver::RunResult RunnerDriver::Run( const RunnerOptions& runner_options) const { return RunImpl(runner_options); } // Generic entry point for all methods that need to execute the runner binary // and handle its output. -absl::StatusOr RunnerDriver::RunImpl( +RunnerDriver::RunResult RunnerDriver::RunImpl( const RunnerOptions& runner_options, absl::string_view snap_id, std::optional trace_cb) const { std::vector argv = {binary_path_}; @@ -135,7 +139,9 @@ absl::StatusOr RunnerDriver::RunImpl( } Subprocess runner_proc(options); - RETURN_IF_NOT_OK(runner_proc.Start(argv)); + if (auto s = runner_proc.Start(argv); !s.ok()) { + return RunResult::InternalError(s.message()); + } std::unique_ptr tracer = nullptr; if (trace_cb.has_value()) { @@ -158,11 +164,11 @@ absl::StatusOr RunnerDriver::RunImpl( return HandleRunnerOutput(runner_stdout, info, snap_id); } -absl::StatusOr RunnerDriver::HandleRunnerOutput( +RunnerDriver::RunResult RunnerDriver::HandleRunnerOutput( absl::string_view runner_stdout, const ProcessInfo& info, absl::string_view snapshot_id) const { VLOG_INFO(3, absl::StrCat("Snapshot [", snapshot_id, - "] runner exit status = ", HexStr(info.status))); + "] runner exit status = ", info.status)); if (WIFSIGNALED(info.status)) { int sig_num = WTERMSIG(info.status); if (sig_num == SIGINT) { @@ -172,9 +178,9 @@ absl::StatusOr RunnerDriver::HandleRunnerOutput( } if (sig_num == SIGSYS) { // The process died with SIGSYS because an unexpected syscall was made. - return absl::InternalError("Snapshot made a syscall"); + return RunResult::InternalError("Snapshot made a syscall"); } - return absl::InternalError( + return RunResult::InternalError( absl::StrCat("Runner killed by signal ", sig_num)); } if (WIFEXITED(info.status)) { @@ -196,32 +202,50 @@ absl::StatusOr RunnerDriver::HandleRunnerOutput( return RunResult::Successful(info.rusage); } google::protobuf::TextFormat::Parser parser; - proto::SnapshotExecutionResult exec_result_proto; - if (!parser.ParseFromString(runner_stdout, &exec_result_proto)) { - return absl::InternalError( - absl::StrCat("couldn't parse [", runner_stdout, - "] as proto::SnapshotExecutionResult. Exit status = ", - HexStr(info.status))); + proto::RunnerOutput runner_output_proto; + if (!parser.ParseFromString(runner_stdout, &runner_output_proto)) { + return RunResult::InternalError(absl::StrCat( + "couldn't parse [", runner_stdout, + "] as proto::RunnerOutput. Exit status = ", info.status)); + } + + if (!runner_output_proto.has_execution_result()) { + return RunResult::InternalError("Missing required execution_result"); } + ExecutionResult execution_result = ExecutionResult{ + .code = static_cast( + runner_output_proto.execution_result().code()), + .message = runner_output_proto.execution_result().msg(), + }; + + if (!runner_output_proto.has_failed_snapshot_execution()) { + return RunResult::FromExecutionResult(execution_result, info.rusage); + } + + const proto::SnapshotExecutionResult& exec_result_proto = + runner_output_proto.failed_snapshot_execution(); if (!snapshot_id.empty() && exec_result_proto.snapshot_id() != snapshot_id) { - // This catches all runner crashes due to mmap errors etc. - return absl::InternalError(absl::StrCat( + return RunResult::InternalError(absl::StrCat( "Runner misbehaved: got id [", exec_result_proto.snapshot_id(), "] expected ", snapshot_id, ". Exit status = ", info.status)); } - absl::StatusOr player_result_or = + absl::StatusOr player_result = PlayerResultProto::FromProto(exec_result_proto.player_result()); - RETURN_IF_NOT_OK_PLUS(player_result_or.status(), - "PlayerResultProto::FromProto: "); - if (!player_result_or->actual_end_state.has_value()) { - return absl::InternalError( + if (!player_result.status().ok()) { + return RunResult::InternalError(absl::StrCat( + "PlayerResultProto::FromProto: ", player_result.status().message())); + } + if (!player_result->actual_end_state.has_value()) { + return RunResult::InternalError( absl::StrCat(exec_result_proto, " has no actual_end_state")); } - return RunResult(*player_result_or, info.rusage, - exec_result_proto.snapshot_id()); + return RunResult(execution_result, *player_result, info.rusage, + exec_result_proto.snapshot_id(), + static_cast( + runner_output_proto.postfailure_checksum_status())); } - return absl::InternalError( + return RunResult::InternalError( absl::StrCat("Unknown runner exit status ", info.status)); } @@ -242,8 +266,8 @@ absl::StatusOr RunnerDriverFromSnapshot( memfd_name.resize(kMaxNameLength); } - // Allocate an anonymous memfile, copy the relocatable buffer contents there, - // then seal the file to prevent any future writes. + // Allocate an anonymous memfile, copy the relocatable buffer contents + // there, then seal the file to prevent any future writes. // TODO(ksteuck): [impl] We can also augment GenerateRelocatableSnaps() API // to take a buffer parameter and avoid the extra copy. int memfd = memfd_create(memfd_name.c_str(), @@ -272,8 +296,8 @@ absl::StatusOr RunnerDriverFromSnapshot( // memory. // Possible alternatives to this are: // * /proc/self/fd/$memfd (remove MDF_CLOEXEC above) -- the runner will - // access its own FD corresponding to the same in-mem file. This will leak - // details of RunnerDriver implementation. + // access its own FD corresponding to the same in-mem file. This will + // leak details of RunnerDriver implementation. // * pass an extra --fd=$memfd to the runner or implement fd:// schema in // the runner. This option requires runner changes and introduces added // complexity around determining the file size. diff --git a/runner/driver/runner_driver.h b/runner/driver/runner_driver.h index a084fe8a..7740050c 100644 --- a/runner/driver/runner_driver.h +++ b/runner/driver/runner_driver.h @@ -25,6 +25,7 @@ #include #include "absl/status/statusor.h" +#include "absl/strings/str_cat.h" #include "absl/strings/string_view.h" #include "./common/harness_tracer.h" #include "./common/snapshot.h" @@ -38,6 +39,9 @@ namespace silifuzz { using snapshot_types::PlaybackOutcome; using snapshot_types::PlaybackResult; +using snapshot_types::RunnerPostfailureChecksumStatus; + +class RunResultPeer; // RunnerDriver wraps a SiliFuzz runner (aka v2 player) binary and provides // helpers to Play()/Make()/Trace() individual snapshots contained in the @@ -46,12 +50,30 @@ using snapshot_types::PlaybackResult; // This class is thread-compatible. class RunnerDriver { public: + struct ExecutionResult { + using Code = snapshot_types::RunnerExecutionStatusCode; + Code code; + std::string message; + + bool ok() const { return code == Code::kOk; } + static ExecutionResult OkResult() { return ExecutionResult{Code::kOk, ""}; } + static ExecutionResult InternalError(absl::string_view message) { + return ExecutionResult{Code::kInternalError, std::string(message)}; + } + static ExecutionResult SnapshotFailed(absl::string_view message) { + return ExecutionResult{Code::kSnapshotFailed, std::string(message)}; + } + + std::string DebugString() const { + return absl::StrCat("ExecutionResult {code:", code, " error:", message, + "}"); + } + }; using PlayerResult = PlaybackResult; + // Represents result of the runner binary invocation. Contains a success bit // and an optional PlayerResult representing the result of Snap playback. // - // TODO(ksteuck): [as-needed] Finer-grained error codes needed to handle - // conditions like "unmappable memory page" or "memory page conflict". // TODO(ksteuck): [as-needed] While the runner provides a way to tell if // an unexpected syscall was made, this class does not model that state and // relies on higher-level StatusOr to capture the fact. If finer-grained @@ -59,19 +81,19 @@ class RunnerDriver { // side + some handling logic here. class RunResult { public: - // Constructs a new RunResult from the given `player_result`. The success() - // value is determined by player_result.outcome == kAsExpected. - explicit RunResult(const PlayerResult& player_result, - const struct rusage& rusage, - absl::string_view snapshot_id = "") - : success_(player_result.outcome == PlaybackOutcome::kAsExpected), - player_result_(player_result), - snapshot_id_(snapshot_id), - rusage_(rusage) {} - // Construct a success()-ful RunResult with no attached player_result. static RunResult Successful(const struct rusage& rusage) { - return RunResult(true, rusage); + return RunResult(ExecutionResult::OkResult(), std::nullopt, rusage); + } + + static RunResult FromExecutionResult( + const ExecutionResult& execution_result, const struct rusage& rusage) { + return RunResult(execution_result, std::nullopt, rusage); + } + + static RunResult InternalError(absl::string_view error_message) { + return RunResult(ExecutionResult::InternalError(error_message), + std::nullopt, {}); } // Tests if the execution was successful. @@ -80,27 +102,54 @@ class RunnerDriver { // Snapshot ID if there's any associated with the current Result. // REQUIRES: !success() // Only populated if the runner process reported the snapshot id. - const std::string& snapshot_id() const { + const std::string& failed_snapshot_id() const { CHECK(!success()); return snapshot_id_; } + bool has_failed_player_result() const { return player_result_.has_value(); } + // Returns the contained PlayerResult object. - // REQUIRES !success() + // REQUIRES has_failed_player_result() == true. // PROVIDES player_result.actual_end_state().has_value() == true - const PlayerResult& player_result() const { - CHECK(!success()); + const PlayerResult& failed_player_result() const { + CHECK(has_failed_player_result()); return *player_result_; } // Information about the resource usage of the run. const struct rusage& rusage() const { return rusage_; } + // Returns the contained ExecutionResult object. + const ExecutionResult& execution_result() const { + return execution_result_; + } + + // Returns the status of the post-failure checksum validation. + // REQUIRES !success() + RunnerPostfailureChecksumStatus postfailure_checksum_status() const { + CHECK(!success()); + return postfailure_checksum_status_; + } + private: - // Constructs a new RunResult with the given success status and no - // associated `player_result`. - explicit RunResult(bool success, const struct rusage& rusage) - : success_(success), player_result_(std::nullopt), rusage_(rusage) {} + RunResult(const ExecutionResult& execution_result, + const std::optional& player_result, + const struct rusage& rusage, absl::string_view snapshot_id = "", + RunnerPostfailureChecksumStatus postfailure_checksum_status = + RunnerPostfailureChecksumStatus::kNotChecked) + : success_(execution_result.ok()), + player_result_(player_result), + snapshot_id_(snapshot_id), + rusage_(rusage), + execution_result_(execution_result), + postfailure_checksum_status_(postfailure_checksum_status) { + // Cross check that overall execution result matches player outcome. + CHECK_EQ(execution_result.ok(), success_); + } + + friend class RunnerDriver; + friend class RunResultPeer; // Was the execution successful. bool success_; @@ -112,6 +161,10 @@ class RunnerDriver { std::string snapshot_id_; struct rusage rusage_; + + ExecutionResult execution_result_; + + RunnerPostfailureChecksumStatus postfailure_checksum_status_; }; // Creates a RunnerDriver for a binary with baked-in corpus. @@ -142,45 +195,38 @@ class RunnerDriver { // Runs `snap_id` in play mode. // REQUIRES snap_id is not empty. - absl::StatusOr PlayOne(absl::string_view snap_id, - int cpu = kAnyCPUId) const; + RunResult PlayOne(absl::string_view snap_id, int cpu = kAnyCPUId) const; // Runs `snap_id` in make mode (see comments in runner.cc). // During making, up to 'max_pages_to_add' pages are added to the snapshot. // Making fails if more pages are required. If 'max_pages_to_add' is 0, // the runner does not add any new page and the caller of the runner driver // need to add necessary pages in the making process. - absl::StatusOr MakeOne(absl::string_view snap_id, - size_t max_pages_to_add = 0, - int cpu = kAnyCPUId) const; + RunResult MakeOne(absl::string_view snap_id, size_t max_pages_to_add = 0, + int cpu = kAnyCPUId) const; // Traces `snap_id` in single-step mode and invokes the provided callback for // every instruction of the snapshot. This runs the snapshot `num_iterations` // times. - absl::StatusOr TraceOne(absl::string_view snap_id, - HarnessTracer::Callback cb, - size_t num_iterations = 1, - int cpu = kAnyCPUId) const; + RunResult TraceOne(absl::string_view snap_id, HarnessTracer::Callback cb, + size_t num_iterations = 1, int cpu = kAnyCPUId) const; // Ensures that `snap_id` replays deterministically. // REQUIRES snap_id is not empty. - absl::StatusOr VerifyOneRepeatedly(absl::string_view snap_id, - int num_attempts, - int cpu = kAnyCPUId) const; + RunResult VerifyOneRepeatedly(absl::string_view snap_id, int num_attempts, + int cpu = kAnyCPUId) const; // Runs the runner binary with the provided runner_options. // // Unlike the *One() family of methods above this is a more generic way of // calling the binary that is intended for screening. - absl::StatusOr Run(const RunnerOptions& runner_options) const; + RunResult Run(const RunnerOptions& runner_options) const; private: // Wraps the binary at `binary_path`. When `corpus_path` not empty, it will // be passed as the last argument to the binary. - explicit RunnerDriver(absl::string_view binary_path, - absl::string_view corpus_path, - absl::string_view corpus_name, - std::function cleanup) + RunnerDriver(absl::string_view binary_path, absl::string_view corpus_path, + absl::string_view corpus_name, std::function cleanup) : binary_path_(binary_path), corpus_path_(corpus_path), corpus_name_(corpus_name), @@ -207,13 +253,13 @@ class RunnerDriver { kFailure = 1, kTimeout = 2, }; - absl::StatusOr RunImpl( + RunResult RunImpl( const RunnerOptions& runner_options, absl::string_view snap_id = "", std::optional trace_cb = std::nullopt) const; - absl::StatusOr HandleRunnerOutput( - absl::string_view runner_stdout, const ProcessInfo& info, - absl::string_view snapshot_id = "") const; + RunResult HandleRunnerOutput(absl::string_view runner_stdout, + const ProcessInfo& info, + absl::string_view snapshot_id = "") const; // C-tor parameters. std::string binary_path_; diff --git a/runner/driver/runner_driver_test.cc b/runner/driver/runner_driver_test.cc index bbdf06d5..ff2e7a78 100644 --- a/runner/driver/runner_driver_test.cc +++ b/runner/driver/runner_driver_test.cc @@ -20,9 +20,7 @@ #include #include // NOLINT -#include "gmock/gmock.h" #include "gtest/gtest.h" -#include "absl/status/status.h" #include "absl/status/statusor.h" #include "./common/harness_tracer.h" #include "./common/proxy_config.h" @@ -36,15 +34,12 @@ #include "./util/itoa.h" #include "./util/path_util.h" #include "./util/testing/status_macros.h" -#include "./util/testing/status_matchers.h" #include "./util/ucontext/serialize.h" #include "./util/ucontext/ucontext_types.h" namespace silifuzz { namespace { -using silifuzz::testing::StatusIs; using snapshot_types::PlaybackOutcome; -using ::testing::HasSubstr; RunnerDriver HelperDriver() { return RunnerDriver::ReadingRunner( @@ -53,54 +48,46 @@ RunnerDriver HelperDriver() { TEST(RunnerDriver, BasicRun) { RunnerDriver driver = HelperDriver(); - auto run_result_or = driver.PlayOne(EnumStr(TestSnapshot::kEndsAsExpected)); - ASSERT_OK(run_result_or); - ASSERT_TRUE(run_result_or->success()); + auto run_result = driver.PlayOne(EnumStr(TestSnapshot::kEndsAsExpected)); + ASSERT_TRUE(run_result.success()); // Check the rusage looks somewhat reasonable. - EXPECT_GE(run_result_or->rusage().ru_maxrss, 4); - - run_result_or = driver.PlayOne(EnumStr(TestSnapshot::kSyscall)); - ASSERT_THAT(run_result_or, - StatusIs(absl::StatusCode::kInternal, HasSubstr("syscall"))); + EXPECT_GE(run_result.rusage().ru_maxrss, 4); } TEST(RunnerDriver, BasicMake) { RunnerDriver driver = HelperDriver(); - auto make_result_or = driver.MakeOne(EnumStr(TestSnapshot::kSigSegvRead)); - ASSERT_OK(make_result_or); - ASSERT_FALSE(make_result_or->success()); - ASSERT_EQ(make_result_or->player_result().outcome, + auto make_result = driver.MakeOne(EnumStr(TestSnapshot::kSigSegvRead)); + ASSERT_FALSE(make_result.success()); + ASSERT_EQ(make_result.failed_player_result().outcome, PlaybackOutcome::kExecutionMisbehave); - ASSERT_EQ(make_result_or->snapshot_id(), EnumStr(TestSnapshot::kSigSegvRead)); + ASSERT_EQ(make_result.failed_snapshot_id(), + EnumStr(TestSnapshot::kSigSegvRead)); } TEST(RunnerDriver, MaxPageToAddOption) { RunnerDriver driver = HelperDriver(); - auto make_result_or = - driver.MakeOne(EnumStr(TestSnapshot::kSigSegvReadFixable), - /*max_pages_to_add=*/0); - ASSERT_OK(make_result_or); - ASSERT_FALSE(make_result_or->success()); - ASSERT_EQ(make_result_or->player_result().outcome, + auto make_result = driver.MakeOne(EnumStr(TestSnapshot::kSigSegvReadFixable), + /*max_pages_to_add=*/0); + ASSERT_FALSE(make_result.success()); + ASSERT_EQ(make_result.failed_player_result().outcome, PlaybackOutcome::kExecutionMisbehave); - ASSERT_EQ(make_result_or->snapshot_id(), + ASSERT_EQ(make_result.failed_snapshot_id(), EnumStr(TestSnapshot::kSigSegvReadFixable)); // Make again with runner adding pages automatically. - make_result_or = driver.MakeOne(EnumStr(TestSnapshot::kSigSegvReadFixable), - /*max_pages_to_add=*/1); - ASSERT_OK(make_result_or); - ASSERT_FALSE(make_result_or->success()); + make_result = driver.MakeOne(EnumStr(TestSnapshot::kSigSegvReadFixable), + /*max_pages_to_add=*/1); + ASSERT_FALSE(make_result.success()); // The snapshot should complete with a register mismatch instead of // a SEGV fault. - ASSERT_EQ(make_result_or->player_result().outcome, + ASSERT_EQ(make_result.failed_player_result().outcome, PlaybackOutcome::kRegisterStateMismatch); - ASSERT_EQ(make_result_or->snapshot_id(), + ASSERT_EQ(make_result.failed_snapshot_id(), EnumStr(TestSnapshot::kSigSegvReadFixable)); - ASSERT_TRUE(make_result_or->player_result().actual_end_state.has_value()); + ASSERT_TRUE(make_result.failed_player_result().actual_end_state.has_value()); Snapshot::EndState end_state = - make_result_or->player_result().actual_end_state.value(); + make_result.failed_player_result().actual_end_state.value(); // We should find memory bytes not in the original memory mapping. Snapshot snapshot = @@ -138,11 +125,10 @@ TEST(RunnerDriver, BasicTrace) { }; auto trace_result_or = driver.TraceOne(EnumStr(TestSnapshot::kEndsAsExpected), cb); - ASSERT_OK(trace_result_or); - ASSERT_TRUE(trace_result_or->success()); + ASSERT_TRUE(trace_result_or.success()); ASSERT_TRUE(hit_initial_snap_rip); // Check the rusage looks somewhat reasonable. - EXPECT_GE(trace_result_or->rusage().ru_maxrss, 4); + EXPECT_GE(trace_result_or.rusage().ru_maxrss, 4); } TEST(RunnerDriver, Cleanup) { diff --git a/runner/runner.cc b/runner/runner.cc index 5bd45101..ad7df677 100644 --- a/runner/runner.cc +++ b/runner/runner.cc @@ -121,6 +121,8 @@ namespace { using snapshot_types::Endpoint; using snapshot_types::EndpointType; +using snapshot_types::RunnerExecutionStatusCode; +using snapshot_types::RunnerPostfailureChecksumStatus; // Number of data pages mapped by SIGSEGV handler during snap making. // This is incremented every time a new data page is discovered during making. @@ -135,6 +137,29 @@ constexpr size_t kMaxAddedPageAddresses = 20; uint64_t added_page_addresses[kMaxAddedPageAddresses]; +// Logs RunnerOutput::ExecutionResult-formatted message to stdout. Every code +// path that exits the runner (either via _exit() or LOG_FATAL) should call this +// function. +void LogExecutionResult(RunnerExecutionStatusCode status_code, + const char* message = nullptr) { + TextProtoPrinter runner_output; + { + auto runtime_failure_m = runner_output.Message("execution_result"); + runtime_failure_m->Int("code", static_cast(status_code)); + if (message != nullptr) { + runtime_failure_m->String("msg", message); + } + } + LogToStdout(runner_output.c_str()); +} + +void LogPostfailureChecksumStatus(RunnerPostfailureChecksumStatus status_code) { + TextProtoPrinter runner_output; + runner_output.Int("postfailure_checksum_status", + static_cast(status_code)); + LogToStdout(runner_output.c_str()); +} + constexpr int kInitialMappingProtection = PROT_READ | PROT_WRITE; // Attempts to recover from a SEGV fault due to missing mapping. @@ -228,6 +253,8 @@ void SigAction(int signal, siginfo_t* siginfo, void* uc) { } // A signal occurred while executing the runner code. Most likely indicates // a bug in the runner or a signal from the environment (keyboard, RLIMIT). + LogExecutionResult(RunnerExecutionStatusCode::kUnhandledSignal, + SignalNameStr(signal)); ASS_LOG_FATAL("Unhandled signal ", SignalNameStr(signal)); __builtin_unreachable(); } @@ -255,10 +282,12 @@ void SetupMemoryBytes(const SnapMemoryBytes& memory_bytes) { void CheckFixedMmapOK(void* mapped_address, void* target_address) { if (mapped_address == MAP_FAILED) { + LogExecutionResult(RunnerExecutionStatusCode::kMmapFailed); LOG_FATAL("mmap(", HexStr(AsInt(target_address)), ") failed: ", ErrnoStr(errno)); } if (mapped_address != target_address) { + LogExecutionResult(RunnerExecutionStatusCode::kMmapFailed); LOG_FATAL("mmap failed: got ", HexStr(AsInt(mapped_address)), " want ", HexStr(AsInt(target_address))); } @@ -471,6 +500,7 @@ void MapCorpus(const SnapCorpus& corpus, int corpus_fd, // conflicting snaps found here. if (SnapOverlapsWithProcMapsEntries(*snap, proc_maps_entries, num_proc_maps_entries)) { + LogExecutionResult(RunnerExecutionStatusCode::kOverlappingMappings); LOG_FATAL("Cannot handle overlapping mappings"); } // If any of these memory mappings overlap, the mapping earlier in this list @@ -555,6 +585,7 @@ void VerifyChecksums(const SnapCorpus& corpus) { ok &= VerifySnapChecksums(*snap); } if (!ok) { + LogExecutionResult(RunnerExecutionStatusCode::kInitialChecksumMismatch); LOG_FATAL("Checksum mismatch"); } } @@ -673,11 +704,14 @@ void LogSnapRunResult(const Snap& snap, const RunnerMainOptions& options, run_result.end_spot.Log(); } } - // The root message is proto.SnapshotExecutionResult - TextProtoPrinter snapshot_execution_result; + + // The root message is proto.RunnerOutput + TextProtoPrinter runner_output; { - snapshot_execution_result.String("snapshot_id", snap.id); - auto player_result = snapshot_execution_result.Message("player_result"); + auto failed_snapshot_execution_m = + runner_output.Message("failed_snapshot_execution"); + failed_snapshot_execution_m->String("snapshot_id", snap.id); + auto player_result = failed_snapshot_execution_m->Message("player_result"); // actual_end_state is a text representation of silifuzz.proto.EndState. // There is no in-memory format to represent EndState in the runner, the // the memory state is read directly from the corresponding live mappings. @@ -731,7 +765,7 @@ void LogSnapRunResult(const Snap& snap, const RunnerMainOptions& options, memory_bytes_m->Bytes("byte_values", start_address, kPageSize); } } - LogToStdout(snapshot_execution_result.c_str()); + LogToStdout(runner_output.c_str()); } const SnapCorpus* CommonMain(const RunnerMainOptions& options) { @@ -808,9 +842,11 @@ int MakerMain(const RunnerMainOptions& options) { LogSnapRunResult(snap, options, run_result); if (run_result.outcome != RunSnapOutcome::kAsExpected) { + LogExecutionResult(RunnerExecutionStatusCode::kSnapshotFailed); return EXIT_FAILURE; } + LogExecutionResult(RunnerExecutionStatusCode::kOk); return EXIT_SUCCESS; } @@ -860,14 +896,20 @@ int RunnerMain(const RunnerMainOptions& options) { // have gone seriously wrong. if (VerifySnapChecksums(snap)) { // Print a positive message so we know it completed. - LOG_ERROR("Snap checksums verified"); + LOG_INFO("Snap checksums verified"); + LogPostfailureChecksumStatus(RunnerPostfailureChecksumStatus::kMatch); + } else { + LogPostfailureChecksumStatus( + RunnerPostfailureChecksumStatus::kMismatch); } + LogExecutionResult(RunnerExecutionStatusCode::kSnapshotFailed); return EXIT_FAILURE; } previous_snap_id = snap.id; } } + LogExecutionResult(RunnerExecutionStatusCode::kOk); return EXIT_SUCCESS; } @@ -888,11 +930,12 @@ int RunnerMainSequential(const RunnerMainOptions& options) { RunSnap(snap, options, run_result); if (run_result.outcome != RunSnapOutcome::kAsExpected) { LogSnapRunResult(snap, options, run_result); + LogExecutionResult(RunnerExecutionStatusCode::kSnapshotFailed); LOG_ERROR("Id = ", snap.id, " Iteration #", IntStr(i)); return EXIT_FAILURE; } } - + LogExecutionResult(RunnerExecutionStatusCode::kOk); return EXIT_SUCCESS; } diff --git a/runner/runner_integration_test.cc b/runner/runner_integration_test.cc index b3bcc3c7..f8622f48 100644 --- a/runner/runner_integration_test.cc +++ b/runner/runner_integration_test.cc @@ -21,8 +21,6 @@ #include "gmock/gmock.h" #include "gtest/gtest.h" -#include "absl/status/status.h" -#include "absl/status/statusor.h" #include "absl/strings/string_view.h" #include "absl/time/time.h" #include "./common/proxy_config.h" @@ -49,7 +47,6 @@ namespace silifuzz { namespace { -using ::silifuzz::testing::StatusIs; using snapshot_types::PlaybackOutcome; using ::testing::HasSubstr; using ::testing::IsEmpty; @@ -58,7 +55,7 @@ using ::testing::Not; // Runs the given `snap` and returns the execution result. // // NOTE: Assumes that the snap is already built into the test helper binary. -absl::StatusOr RunOneSnap( +RunnerDriver::RunResult RunOneSnap( TestSnapshot test_snap_type, absl::Duration timeout = absl::InfiniteDuration()) { RunnerDriver driver = RunnerDriver::ReadingRunner( @@ -72,22 +69,23 @@ absl::StatusOr RunOneSnap( } TEST(RunnerTest, AsExpectedSnap) { - ASSERT_OK_AND_ASSIGN(auto result, RunOneSnap(TestSnapshot::kEndsAsExpected)); + auto result = RunOneSnap(TestSnapshot::kEndsAsExpected); ASSERT_TRUE(result.success()); } TEST(RunnerTest, RegisterMismatchSnap) { - ASSERT_OK_AND_ASSIGN(auto result, RunOneSnap(TestSnapshot::kRegsMismatch)); + auto result = RunOneSnap(TestSnapshot::kRegsMismatch); ASSERT_FALSE(result.success()); - EXPECT_EQ(result.player_result().outcome, + EXPECT_EQ(result.failed_player_result().outcome, PlaybackOutcome::kRegisterStateMismatch); } TEST(RunnerTest, MemoryMismatchSnap) { - ASSERT_OK_AND_ASSIGN(auto result, RunOneSnap(TestSnapshot::kMemoryMismatch)); + auto result = RunOneSnap(TestSnapshot::kMemoryMismatch); ASSERT_FALSE(result.success()); - EXPECT_EQ(result.player_result().outcome, PlaybackOutcome::kMemoryMismatch); - const auto& end_state = *result.player_result().actual_end_state; + EXPECT_EQ(result.failed_player_result().outcome, + PlaybackOutcome::kMemoryMismatch); + const auto& end_state = *result.failed_player_result().actual_end_state; EXPECT_THAT(end_state.memory_bytes(), Not(IsEmpty())); Snapshot memoryMismatchSnap = @@ -99,13 +97,12 @@ TEST(RunnerTest, MemoryMismatchSnap) { } TEST(RunnerTest, SigSegvSnap) { - ASSERT_OK_AND_ASSIGN(auto result, - RunOneSnap(TestSnapshot::kSigSegvReadFixable)); + auto result = RunOneSnap(TestSnapshot::kSigSegvReadFixable); ASSERT_FALSE(result.success()); - EXPECT_EQ(result.player_result().outcome, + EXPECT_EQ(result.failed_player_result().outcome, PlaybackOutcome::kExecutionMisbehave); const Snapshot::EndState& end_state = - *result.player_result().actual_end_state; + *result.failed_player_result().actual_end_state; EXPECT_THAT(end_state.memory_bytes(), Not(IsEmpty())); const snapshot_types::Endpoint& ep = end_state.endpoint(); // sig_address and sig_instruction_address addresses are snapshot-dependent @@ -126,17 +123,17 @@ TEST(RunnerTest, SigSegvSnap) { TEST(RunnerTest, SyscallSnap) { auto result = RunOneSnap(TestSnapshot::kSyscall); - ASSERT_THAT(result, - StatusIs(absl::StatusCode::kInternal, HasSubstr("syscall"))); + ASSERT_FALSE(result.success()); + ASSERT_THAT(result.execution_result().message, HasSubstr("syscall")); } TEST(RunnerTest, BreakpointSnap) { - ASSERT_OK_AND_ASSIGN(auto result, RunOneSnap(TestSnapshot::kBreakpoint)); + auto result = RunOneSnap(TestSnapshot::kBreakpoint); ASSERT_FALSE(result.success()); - EXPECT_EQ(result.player_result().outcome, + EXPECT_EQ(result.failed_player_result().outcome, PlaybackOutcome::kExecutionMisbehave); const snapshot_types::Endpoint& ep = - result.player_result().actual_end_state->endpoint(); + result.failed_player_result().actual_end_state->endpoint(); Snapshot breakpointSnap = MakeSnapRunnerTestSnapshot(TestSnapshot::kBreakpoint); GRegSet gregs; @@ -155,14 +152,14 @@ TEST(RunnerTest, BreakpointSnap) { } TEST(RunnerTest, RunawaySnap) { - ASSERT_OK_AND_ASSIGN(auto result, RunOneSnap(TestSnapshot::kRunaway)); + auto result = RunOneSnap(TestSnapshot::kRunaway); ASSERT_FALSE(result.success()); - EXPECT_EQ(result.player_result().outcome, PlaybackOutcome::kExecutionRunaway); + EXPECT_EQ(result.failed_player_result().outcome, + PlaybackOutcome::kExecutionRunaway); } TEST(RunnerTest, Deadline) { - ASSERT_OK_AND_ASSIGN(auto result, - RunOneSnap(TestSnapshot::kRunaway, absl::Seconds(2))); + auto result = RunOneSnap(TestSnapshot::kRunaway, absl::Seconds(2)); ASSERT_TRUE(result.success()); } @@ -180,9 +177,9 @@ TEST(RunnerTest, EmptyCorpus) { RunnerDriver driver = RunnerDriver::ReadingRunner( RunnerLocation(), path, "", [&path] { unlink(path.c_str()); }); auto opts = RunnerOptions::Default(); - ASSERT_OK(driver.Run(opts)); + ASSERT_TRUE(driver.Run(opts).success()); opts.set_sequential_mode(true); - ASSERT_OK(driver.Run(opts)); + ASSERT_TRUE(driver.Run(opts).success()); } TEST(RunnerTest, UnknownFlags) { @@ -200,8 +197,10 @@ TEST(RunnerTest, UnknownFlags) { RunnerLocation(), path, "", [&path] { unlink(path.c_str()); }); RunnerOptions opts = RunnerOptions::PlayOptions(""); opts.set_extra_argv({"--foobar=1"}); - absl::StatusOr result = driver.Run(opts); - ASSERT_THAT(result, StatusIs(absl::StatusCode::kInvalidArgument)); + RunnerDriver::RunResult result = driver.Run(opts); + ASSERT_FALSE(result.success()); + ASSERT_EQ(result.execution_result().code, + RunnerDriver::ExecutionResult::Code::kInternalError); } } // namespace diff --git a/runner/snap_maker.cc b/runner/snap_maker.cc index 4984d994..734c1eba 100644 --- a/runner/snap_maker.cc +++ b/runner/snap_maker.cc @@ -135,17 +135,17 @@ absl::StatusOr SnapMaker::RecordEndState(const Snapshot& snapshot) { ASSIGN_OR_RETURN_IF_NOT_OK( RunnerDriver recorder, RunnerDriverFromSnapshot(snapified, opts_.runner_path)); - ASSIGN_OR_RETURN_IF_NOT_OK(RunnerDriver::RunResult record_result, - recorder.MakeOne(snapified.id(), 0, opts_.cpu)); + RunnerDriver::RunResult record_result = + recorder.MakeOne(snapified.id(), 0, opts_.cpu); if (record_result.success()) { RETURN_IF_NOT_OK(snapified.IsComplete()); return snapified; } - if (!record_result.player_result().actual_end_state.has_value()) { + if (!record_result.failed_player_result().actual_end_state.has_value()) { return absl::InternalError("The runner didn't report actual_end_state"); } Snapshot::EndState actual_end_state = - *record_result.player_result().actual_end_state; + *record_result.failed_player_result().actual_end_state; actual_end_state.set_platforms({CurrentPlatformId()}); snapified.set_expected_end_states({}); // TODO(ksteuck): [as-needed] The runner machinery already supports signal @@ -205,16 +205,14 @@ absl::Status SnapMaker::VerifyPlaysDeterministically( // Current code plays the snapshot several times with ASLR enabled which // takes care of vDSO mappings and stack but the runner code itself is // always placed at the fixed address (--image-base linker arg). - ASSIGN_OR_RETURN_IF_NOT_OK( - RunnerDriver::RunResult verify_result, - driver.VerifyOneRepeatedly(snapified.id(), opts_.num_verify_attempts, - opts_.cpu)); + RunnerDriver::RunResult verify_result = driver.VerifyOneRepeatedly( + snapified.id(), opts_.num_verify_attempts, opts_.cpu); if (!verify_result.success()) { if (VLOG_IS_ON(1)) { LinePrinter lp(LinePrinter::StdErrPrinter); SnapshotPrinter printer(&lp); printer.PrintActualEndState( - snapified, *verify_result.player_result().actual_end_state); + snapified, *verify_result.failed_player_result().actual_end_state); } return absl::InternalError("Verify() failed, non-deterministic snapshot?"); } @@ -316,10 +314,9 @@ absl::StatusOr SnapMaker::MakeLoop(Snapshot* snapshot, // mappings. const int runner_max_pages_to_add = opts_.compatibility_mode ? 0 : opts_.max_pages_to_add; - ASSIGN_OR_RETURN_IF_NOT_OK( - RunnerDriver::RunResult make_result, - runner_driver.MakeOne(snapshot->id(), runner_max_pages_to_add, - opts_.cpu)); + + RunnerDriver::RunResult make_result = runner_driver.MakeOne( + snapshot->id(), runner_max_pages_to_add, opts_.cpu); if (make_result.success()) { // In practice this can happen if the snapshot hits just the right // sequence of instructions to call _exit(0) either by jumping into @@ -328,16 +325,21 @@ absl::StatusOr SnapMaker::MakeLoop(Snapshot* snapshot, absl::StrCat("Unlikely: snapshot ", snapshot->id(), " had an undefined end state yet ran successfully")); } + if (make_result.execution_result().code != + RunnerDriver::ExecutionResult::Code::kSnapshotFailed) { + return absl::InternalError(absl::StrCat( + "Runner failed: ", make_result.execution_result().DebugString())); + } if (!opts_.compatibility_mode) { ASSIGN_OR_RETURN_IF_NOT_OK( Snapshot::MemoryMappingList memory_mapping_list, - DataMappingDelta(*snapshot, - *make_result.player_result().actual_end_state)); + DataMappingDelta( + *snapshot, *make_result.failed_player_result().actual_end_state)); RETURN_IF_NOT_OK(AddMemoryMappings(snapshot, memory_mapping_list)); } const Snapshot::Endpoint& ep = - make_result.player_result().actual_end_state->endpoint(); - switch (make_result.player_result().outcome) { + make_result.failed_player_result().actual_end_state->endpoint(); + switch (make_result.failed_player_result().outcome) { case PlaybackOutcome::kAsExpected: return absl::InternalError( absl::StrCat("Impossible: snapshot ", snapshot->id(), @@ -393,7 +395,7 @@ absl::StatusOr SnapMaker::MakeLoop(Snapshot* snapshot, case PlaybackOutcome::kPlatformMismatch: return absl::InternalError( absl::StrCat("Unsupported outcome ", - EnumStr(make_result.player_result().outcome))); + EnumStr(make_result.failed_player_result().outcome))); } } } diff --git a/runner/x86_64/disassembling_snap_tracer_test.cc b/runner/x86_64/disassembling_snap_tracer_test.cc index 566defc0..47d1568d 100644 --- a/runner/x86_64/disassembling_snap_tracer_test.cc +++ b/runner/x86_64/disassembling_snap_tracer_test.cc @@ -22,7 +22,6 @@ #include "gmock/gmock.h" #include "gtest/gtest.h" #include "absl/functional/bind_front.h" -#include "absl/status/status.h" #include "absl/strings/str_cat.h" #include "absl/strings/string_view.h" #include "./common/snapshot_enums.h" @@ -33,13 +32,10 @@ #include "./snap/testing/snap_test_snapshots.h" #include "./util/arch.h" #include "./util/data_dependency.h" -#include "./util/testing/status_macros.h" -#include "./util/testing/status_matchers.h" namespace silifuzz { namespace { -using silifuzz::testing::StatusIs; using snapshot_types::SigNum; using ::testing::ElementsAre; using ::testing::IsEmpty; @@ -62,11 +58,8 @@ TEST(DisassemblingSnapTracer, TraceAsExpected) { auto snapshot = MakeSnapRunnerTestSnapshot(TestSnapshot::kEndsAsExpected); DisassemblingSnapTracer tracer(snapshot); - ASSERT_OK_AND_ASSIGN( - auto result, - driver.TraceOne( - snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer))); + auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer)); ASSERT_TRUE(result.success()); const auto& trace_result = tracer.trace_result(); EXPECT_EQ(trace_result.instructions_executed, 2); @@ -79,14 +72,12 @@ TEST(DisassemblingSnapTracer, TraceSigill) { RunnerDriver driver = HelperDriver(); auto snapshot = MakeSnapRunnerTestSnapshot(TestSnapshot::kSigIll); DisassemblingSnapTracer tracer(snapshot); - ASSERT_OK_AND_ASSIGN( - auto result, - driver.TraceOne( - snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer))); + auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer)); ASSERT_FALSE(result.success()); - ASSERT_TRUE(result.player_result().actual_end_state->endpoint().sig_num() == - SigNum::kSigIll); + ASSERT_TRUE( + result.failed_player_result().actual_end_state->endpoint().sig_num() == + SigNum::kSigIll); } TEST(DisassemblingSnapTracer, TraceNonDeterministic) { @@ -96,7 +87,7 @@ TEST(DisassemblingSnapTracer, TraceNonDeterministic) { DisassemblingSnapTracer tracer(snapshot); auto result = driver.TraceOne( snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer)); - ASSERT_THAT(result, StatusIs(absl::StatusCode::kInvalidArgument)); + EXPECT_FALSE(result.success()); const auto& trace_result = tracer.trace_result(); EXPECT_EQ(trace_result.early_termination_reason, "Non-deterministic insn CPUID"); @@ -109,11 +100,8 @@ TEST(DisassemblingSnapTracer, TraceSplitLock) { TraceOptions options = TraceOptions::Default(); options.x86_filter_split_lock = false; DisassemblingSnapTracer tracer(snapshot, options); - ASSERT_OK_AND_ASSIGN( - const auto result, - driver.TraceOne( - snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer))); + const auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer)); EXPECT_FALSE(result.success()); // We don't have the correct endstate. const auto& trace_result = tracer.trace_result(); EXPECT_EQ(trace_result.instructions_executed, 5); @@ -129,7 +117,7 @@ TEST(DisassemblingSnapTracer, TraceSplitLock) { const auto result2 = driver.TraceOne( snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &split_lock_tracer)); - EXPECT_THAT(result2, StatusIs(absl::StatusCode::kInvalidArgument)); + EXPECT_FALSE(result2.success()); const auto& trace_result2 = split_lock_tracer.trace_result(); EXPECT_EQ(trace_result2.early_termination_reason, "Split-lock insn INC_LOCK"); } @@ -142,11 +130,8 @@ TEST(DisassemblingSnapTracer, TraceVSyscallRegionAccess) { TraceOptions options = TraceOptions::Default(); options.x86_filter_vsyscall_region_access = false; DisassemblingSnapTracer tracer(snapshot, options); - ASSERT_OK_AND_ASSIGN( - const auto result, - driver.TraceOne( - snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer))); + const auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer)); EXPECT_FALSE(result.success()); // We don't have the correct endstate. const auto& trace_result = tracer.trace_result(); // We may execute either 1 or 3 instruction depending on whether kernel @@ -172,7 +157,7 @@ TEST(DisassemblingSnapTracer, TraceVSyscallRegionAccess) { const auto result2 = driver.TraceOne( snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &vsyscall_region_access_tracer)); - EXPECT_THAT(result2, StatusIs(absl::StatusCode::kInvalidArgument)); + EXPECT_FALSE(result2.success()); const auto& trace_result2 = vsyscall_region_access_tracer.trace_result(); EXPECT_EQ(trace_result2.instructions_executed, 2); EXPECT_THAT(trace_result2.disassembly, @@ -188,11 +173,9 @@ TEST(DisassemblingSnapTracer, TraceMultipeTimes) { MakeSnapRunnerTestSnapshot(TestSnapshot::kEndsAsExpected); DisassemblingSnapTracer tracer(snapshot); constexpr size_t kNumIterations = 3; - ASSERT_OK_AND_ASSIGN( - auto result, - driver.TraceOne(snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer), - kNumIterations)); + auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer), + kNumIterations); ASSERT_TRUE(result.success()); const auto& trace_result = tracer.trace_result(); EXPECT_EQ(trace_result.instructions_executed, 2 * kNumIterations); @@ -211,11 +194,8 @@ TEST(DisassemblingSnapTracer, TraceX86FilterMemoryAccess) { TraceOptions options = TraceOptions::Default(); options.filter_memory_access = false; DisassemblingSnapTracer tracer(snapshot, options); - ASSERT_OK_AND_ASSIGN( - const auto result, - driver.TraceOne( - snapshot.id(), - absl::bind_front(&DisassemblingSnapTracer::Step, &tracer))); + const auto result = driver.TraceOne( + snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer)); // The test snapshot does not have a matching memory state. EXPECT_FALSE(result.success()); const auto& trace_result = tracer.trace_result(); @@ -230,7 +210,7 @@ TEST(DisassemblingSnapTracer, TraceX86FilterMemoryAccess) { const auto result_with_filter = driver.TraceOne( snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, &tracer_with_filter)); - EXPECT_THAT(result_with_filter, StatusIs(absl::StatusCode::kInvalidArgument)); + EXPECT_FALSE(result_with_filter.success()); const auto& trace_result_with_filter = tracer_with_filter.trace_result(); EXPECT_EQ(trace_result_with_filter.instructions_executed, 1); EXPECT_THAT(trace_result_with_filter.disassembly, @@ -244,11 +224,10 @@ TEST(DisassemblingSnapTracer, TraceX86FilterMemoryAccess) { MakeSnapRunnerTestSnapshot(TestSnapshot::kEndsAsExpected); DisassemblingSnapTracer ends_as_expected_tracer(ends_as_expected_snapshot, options); - ASSERT_OK_AND_ASSIGN( - const auto ends_as_expected_result, + const auto ends_as_expected_result = driver.TraceOne(ends_as_expected_snapshot.id(), absl::bind_front(&DisassemblingSnapTracer::Step, - &ends_as_expected_tracer))); + &ends_as_expected_tracer)); EXPECT_TRUE(ends_as_expected_result.success()); const auto& ends_as_expected_trace_result = ends_as_expected_tracer.trace_result(); diff --git a/tools/snap_tool.cc b/tools/snap_tool.cc index ef5530a3..883529ec 100644 --- a/tools/snap_tool.cc +++ b/tools/snap_tool.cc @@ -428,23 +428,18 @@ bool SnapToolMain(std::vector& args) { line_printer.Line("Could not play snapshot: ", runner_or.status().ToString()); } - auto result_or = runner_or->PlayOne(snapshot.id()); - if (!result_or.ok()) { - line_printer.Line("Could not play snapshot: ", - result_or.status().ToString()); - return false; - } - if (result_or->success()) { + auto result = runner_or->PlayOne(snapshot.id()); + if (result.success()) { line_printer.Line("Snapshot played successfully."); return true; } else { - RunnerDriver::PlayerResult player_result = result_or->player_result(); + const RunnerDriver::PlayerResult& player_result = + result.failed_player_result(); line_printer.Line("Snapshot played with outcome = ", EnumStr(player_result.outcome)); line_printer.Line("Actual end state reached:"); SnapshotPrinter printer(&line_printer); - printer.PrintActualEndState(snapshot, - *result_or->player_result().actual_end_state); + printer.PrintActualEndState(snapshot, *player_result.actual_end_state); return false; } } else if (command == "make") {