diff --git a/centipede/BUILD b/centipede/BUILD index 108e5e032..036f7e2d5 100644 --- a/centipede/BUILD +++ b/centipede/BUILD @@ -1944,7 +1944,11 @@ cc_test( ":util", ":workdir", "@abseil-cpp//absl/container:flat_hash_map", + "@abseil-cpp//absl/log:log_entry", + "@abseil-cpp//absl/log:log_sink", + "@abseil-cpp//absl/log:log_sink_registry", "@abseil-cpp//absl/status", + "@abseil-cpp//absl/strings", "@abseil-cpp//absl/strings:str_format", "@abseil-cpp//absl/time", "@abseil-cpp//absl/time:clock_interface", diff --git a/centipede/crash_deduplication.cc b/centipede/crash_deduplication.cc index b5ae094f4..0aaddbb0a 100644 --- a/centipede/crash_deduplication.cc +++ b/centipede/crash_deduplication.cc @@ -73,6 +73,22 @@ enum class ActionType { kDelete }; +std::string_view ActionTypeToString(ActionType action_type) { + switch (action_type) { + case ActionType::kTouch: + return "Touch"; + case ActionType::kKeep: + return "Keep"; + case ActionType::kReplaceInput: + return "ReplaceInput"; + case ActionType::kIncubateAndReplaceInput: + return "IncubateAndReplaceInput"; + case ActionType::kDelete: + return "Delete"; + } + return "Unknown"; +} + struct ExistingCrash { CrashReport crash_report; std::string new_signature; @@ -87,6 +103,7 @@ struct ExistingCrashAction { const ExistingCrash& existing_crash; ActionType action_type; std::optional new_details; + std::string reason; }; absl::StatusOr> ReadExistingCrashes( @@ -218,11 +235,13 @@ ExistingCrashAction ComputeExistingCrashAction( // If the crash was malformed (no signature), we delete it immediately. if (sig.empty()) { - return {existing, ActionType::kDelete, std::nullopt}; + return {existing, ActionType::kDelete, std::nullopt, + "Crash was malformed (empty signature)"}; } if (sig == sig_new) { - return {existing, ActionType::kTouch, std::nullopt}; + return {existing, ActionType::kTouch, std::nullopt, + absl::StrCat("Crash reproduced with the same signature: ", sig)}; } // The signature changed or it no longer reproduces. @@ -230,7 +249,17 @@ ExistingCrashAction ComputeExistingCrashAction( if (it == new_crashes.end()) { // No input reproduces this signature anymore. Keep it on disk (subject to // TTL). - return {existing, ActionType::kKeep, std::nullopt}; + std::string reason = + sig_new.empty() + ? absl::StrCat( + "Crash did not reproduce during replay, and no " + "active input reproduces signature '", + sig, "'; keeping on disk subject to TTL") + : absl::StrCat("Crash reproduced with a different signature ('", + sig_new, "' != '", sig, + "'), and no active input reproduces signature '", + sig, "'; keeping on disk subject to TTL"); + return {existing, ActionType::kKeep, std::nullopt, std::move(reason)}; } // We have an input for this crash signature. @@ -239,15 +268,33 @@ ExistingCrashAction ComputeExistingCrashAction( existing.crash_report.details.input_signature) { // The crashing input is the same which means that this input is flakey. // Just touch it. - return {existing, ActionType::kTouch, it->second}; + return {existing, ActionType::kTouch, it->second, + absl::StrCat("Crash did not reproduce during replay, but active " + "input for signature '", + sig, "' is identical, indicating a flaky crash")}; } // The old crash did not reproduce at all. Move it to incubating and // replace. - return {existing, ActionType::kIncubateAndReplaceInput, it->second}; + return {existing, ActionType::kIncubateAndReplaceInput, it->second, + absl::StrCat("Crash did not reproduce during replay; moving old " + "input to incubating and replacing with new input for " + "signature '", + sig, "'")}; } // The old crash reproduced with a different signature. Replace it. - return {existing, ActionType::kReplaceInput, it->second}; + return { + existing, ActionType::kReplaceInput, it->second, + absl::StrCat("Crash reproduced with a different signature ('", sig_new, + "' != '", sig, + "'); replacing with new input for signature '", sig, "'")}; +} + +void LogExistingCrashAction(const ExistingCrashAction& action) { + FUZZTEST_LOG(INFO) << "Action: " << ActionTypeToString(action.action_type) + << " for existing crash '" + << action.existing_crash.crash_report.details.input_path + << "'. Reason: " << action.reason << "."; } std::vector ComputeExistingCrashActions( @@ -257,6 +304,7 @@ std::vector ComputeExistingCrashActions( actions.reserve(existing_crashes.size()); for (const auto& existing : existing_crashes) { actions.push_back(ComputeExistingCrashAction(existing, new_crashes)); + LogExistingCrashAction(actions.back()); } return actions; } @@ -394,6 +442,11 @@ absl::Status WriteNewCrashes( size_t new_signatures_written = 0; for (const auto& [signature, report] : new_crash_reports) { if (new_signatures_written < num_new_allowed) { + FUZZTEST_LOG(INFO) << "Action: StoreNewCrash for signature '" << signature + << "' (input: " << report.details.input_signature + << ", bug_id: " << report.bug_id << ") to '" + << crashing_dir.c_str() + << "'. Reason: New crash signature discovered."; RETURN_IF_NOT_OK(WriteCrashToFile(crashing_dir, report.bug_id, report.signature, report.details, crash_summary)); @@ -413,6 +466,11 @@ absl::Status CleanUpIncubating( absl::Span incubating_crashes) { for (const auto& incubating : incubating_crashes) { if (!incubating.new_signature.empty()) { + FUZZTEST_LOG(INFO) << "Action: CleanUpIncubating for '" + << incubating.details.input_path + << "'. Reason: Input reproduced with signature '" + << incubating.new_signature + << "' and graduated from incubation."; RETURN_IF_NOT_OK(RemotePathDelete(incubating.details.input_path, /*recursively=*/false)); } @@ -446,6 +504,10 @@ absl::Status MoveExpiredCrashesToRegression( } std::filesystem::path dest_path = regression_dir / dest_filename; + FUZZTEST_LOG(INFO) << "Action: MoveToRegression for '" << file_path + << "' -> '" << dest_path.c_str() + << "'. Reason: Crash expired (not reproduced for " + << (now - mtime) << " > TTL " << ttl << ")."; RETURN_IF_NOT_OK(RemoteFileRename(file_path, dest_path.c_str())); } } diff --git a/centipede/crash_deduplication_test.cc b/centipede/crash_deduplication_test.cc index 12dd2f5e1..6fc02bfa1 100644 --- a/centipede/crash_deduplication_test.cc +++ b/centipede/crash_deduplication_test.cc @@ -23,8 +23,12 @@ #include "gmock/gmock.h" #include "gtest/gtest.h" #include "absl/container/flat_hash_map.h" +#include "absl/log/log_entry.h" +#include "absl/log/log_sink.h" +#include "absl/log/log_sink_registry.h" #include "absl/status/status.h" #include "absl/strings/str_format.h" +#include "absl/strings/str_join.h" #include "absl/time/clock.h" #include "absl/time/clock_interface.h" #include "absl/time/simulated_clock.h" @@ -52,6 +56,21 @@ using ::testing::MatchesRegex; using ::testing::Pair; using ::testing::UnorderedElementsAre; +class LogCapture : public absl::LogSink { + public: + LogCapture() { absl::AddLogSink(this); } + ~LogCapture() override { absl::RemoveLogSink(this); } + + void Send(const absl::LogEntry& entry) override { + captured_log_.emplace_back(entry.text_message()); + } + + std::string FullLog() const { return absl::StrJoin(captured_log_, "\n"); } + + private: + std::vector captured_log_; +}; + std::string SetContentsAndGetPath(const std::filesystem::path& dir, std::string_view file_name, std::string_view contents) { @@ -904,5 +923,198 @@ TEST_F(OrganizeCrashingInputsTest, ReplacesInputWithWinnerAlreadyOnDisk) { UnorderedElementsAre(FieldsAre("isig2", "input2"))); } +TEST_F(OrganizeCrashingInputsTest, LogsActionDeleteForMalformedCrash) { + LogCapture log_capture; + SetContentsAndGetPath(crashing_dir(), "isig", "input"); + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{ + {"input", {"csig", "desc"}}, + }); + NonOwningCallbacksFactory factory(callbacks); + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, /*new_crashes_by_signature=*/{}, + crash_summary()) + .ok()); + + EXPECT_THAT( + log_capture.FullLog(), + AllOf(HasSubstr("Action: Delete for existing crash"), + HasSubstr("Reason: Crash was malformed (empty signature)"))); +} + +TEST_F(OrganizeCrashingInputsTest, LogsActionTouchForReproducingCrash) { + LogCapture log_capture; + SetContentsAndGetPath(crashing_dir(), "bug-csig-isig", "input"); + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{ + {"input", {"csig", "desc"}}, + }); + NonOwningCallbacksFactory factory(callbacks); + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, /*new_crashes_by_signature=*/{}, + crash_summary()) + .ok()); + + EXPECT_THAT( + log_capture.FullLog(), + AllOf( + HasSubstr("Action: Touch for existing crash"), + HasSubstr("Reason: Crash reproduced with the same signature: csig"))); +} + +TEST_F(OrganizeCrashingInputsTest, LogsActionKeepForIrreproducibleCrash) { + LogCapture log_capture; + SetContentsAndGetPath(crashing_dir(), "bug-csig-isig", "input"); + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{}); + NonOwningCallbacksFactory factory(callbacks); + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, /*new_crashes_by_signature=*/{}, + crash_summary()) + .ok()); + + EXPECT_THAT( + log_capture.FullLog(), + AllOf(HasSubstr("Action: Keep for existing crash"), + HasSubstr("Reason: Crash did not reproduce during replay, and no " + "active input reproduces signature 'csig'; keeping on " + "disk subject to TTL"))); +} + +TEST_F(OrganizeCrashingInputsTest, LogsActionTouchForFlakyCrash) { + LogCapture log_capture; + SetContentsAndGetPath(crashing_dir(), "bug-csig-isig", "input"); + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{}); + NonOwningCallbacksFactory factory(callbacks); + + absl::flat_hash_map new_crashes_by_signature; + const auto new_input_path = + SetContentsAndGetPath(new_crashes_dir(), "isig", "input"); + new_crashes_by_signature["csig"] = {"isig", "desc", new_input_path}; + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, new_crashes_by_signature, + crash_summary()) + .ok()); + + EXPECT_THAT( + log_capture.FullLog(), + AllOf(HasSubstr("Action: Touch for existing crash"), + HasSubstr("Reason: Crash did not reproduce during replay, but " + "active input for signature 'csig' is identical, " + "indicating a flaky crash"))); +} + +TEST_F(OrganizeCrashingInputsTest, LogsActionIncubateAndReplaceInput) { + LogCapture log_capture; + SetContentsAndGetPath(crashing_dir(), "bug-csig-isig1", "input1"); + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{}); + NonOwningCallbacksFactory factory(callbacks); + + absl::flat_hash_map new_crashes_by_signature; + const auto new_input_path = + SetContentsAndGetPath(new_crashes_dir(), "isig2", "input2"); + new_crashes_by_signature["csig"] = {"isig2", "desc", new_input_path}; + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, new_crashes_by_signature, + crash_summary()) + .ok()); + + EXPECT_THAT( + log_capture.FullLog(), + AllOf(HasSubstr("Action: IncubateAndReplaceInput for existing crash"), + HasSubstr("Reason: Crash did not reproduce during replay; moving " + "old input to incubating and replacing with new input " + "for signature 'csig'"))); +} + +TEST_F(OrganizeCrashingInputsTest, LogsActionReplaceInput) { + LogCapture log_capture; + SetContentsAndGetPath(crashing_dir(), "bug-csig-isig1", "input1"); + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{ + {"input1", {"csig_diff", "desc"}}, + }); + NonOwningCallbacksFactory factory(callbacks); + + absl::flat_hash_map new_crashes_by_signature; + const auto new_input_path = + SetContentsAndGetPath(new_crashes_dir(), "isig2", "input2"); + new_crashes_by_signature["csig"] = {"isig2", "desc", new_input_path}; + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, new_crashes_by_signature, + crash_summary()) + .ok()); + + EXPECT_THAT( + log_capture.FullLog(), + AllOf(HasSubstr("Action: ReplaceInput for existing crash"), + HasSubstr("Reason: Crash reproduced with a different signature " + "('csig_diff' != 'csig'); replacing with new input for " + "signature 'csig'"))); +} + +TEST_F(OrganizeCrashingInputsTest, LogsActionStoreNewCrash) { + LogCapture log_capture; + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{}); + NonOwningCallbacksFactory factory(callbacks); + + absl::flat_hash_map new_crashes_by_signature; + const auto new_input_path = + SetContentsAndGetPath(new_crashes_dir(), "isig", "input"); + new_crashes_by_signature["csig"] = {"isig", "desc", new_input_path}; + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, new_crashes_by_signature, + crash_summary()) + .ok()); + + EXPECT_THAT(log_capture.FullLog(), + AllOf(HasSubstr("Action: StoreNewCrash for signature 'csig'"), + HasSubstr("Reason: New crash signature discovered"))); +} + +TEST_F(OrganizeCrashingInputsTest, LogsActionCleanUpIncubating) { + LogCapture log_capture; + SetContentsAndGetPath(incubating_dir(), "isig1", "input1"); + + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{ + {"input1", {"csig", "desc"}}, + }); + NonOwningCallbacksFactory factory(callbacks); + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, /*new_crashes_by_signature=*/{}, + crash_summary()) + .ok()); + + EXPECT_THAT( + log_capture.FullLog(), + AllOf(HasSubstr("Action: CleanUpIncubating for"), + HasSubstr("Reason: Input reproduced with signature 'csig' and " + "graduated from incubation"))); +} + +TEST_F(OrganizeCrashingInputsTest, LogsActionMoveToRegression) { + LogCapture log_capture; + absl::SimulatedClock clock(absl::Now()); + SetContentsAndGetPath(crashing_dir(), "bug-csig-isig", "input"); + clock.AdvanceTime(absl::Hours(25)); + + FakeCentipedeCallbacks callbacks(env(), /*crashing_inputs=*/{}); + NonOwningCallbacksFactory factory(callbacks); + + ASSERT_TRUE(OrganizeCrashingInputs(regression_dir(), crashing_dir(), env(), + factory, /*new_crashes_by_signature=*/{}, + crash_summary(), + /*regression_ttl=*/absl::Hours(24), clock) + .ok()); + + EXPECT_THAT(log_capture.FullLog(), + AllOf(HasSubstr("Action: MoveToRegression for"), + HasSubstr("Reason: Crash expired (not reproduced for"))); +} + } // namespace } // namespace fuzztest::internal