diff --git a/services/network/sct_auditing/sct_auditing_reporter.cc b/services/network/sct_auditing/sct_auditing_reporter.cc index 208259c979e2ba..900a05dc81b0b8 100644 --- a/services/network/sct_auditing/sct_auditing_reporter.cc +++ b/services/network/sct_auditing/sct_auditing_reporter.cc @@ -60,6 +60,11 @@ constexpr char kStatusOK[] = "OK"; // not nullopt. absl::optional g_retry_delay_for_testing = absl::nullopt; +void RecordLookupQueryResult(SCTAuditingReporter::LookupQueryResult result) { + base::UmaHistogramEnumeration("Security.SCTAuditing.OptOut.LookupQueryResult", + result); +} + // Records whether sending the report to the reporting server succeeded for each // report sent. void RecordSCTAuditingReportSucceededMetrics(bool success) { @@ -364,18 +369,26 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( bool success = url_loader_->NetError() == net::OK && response_code == net::HTTP_OK && response_body; if (!success) { + RecordLookupQueryResult(LookupQueryResult::kHTTPError); MaybeRetryRequest(); return; } absl::optional result = base::JSONReader::Read(*response_body); if (!result) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); MaybeRetryRequest(); return; } const std::string* status = result->FindStringKey(kLookupStatusKey); - if (!status || *status != kStatusOK) { + if (!status) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); + MaybeRetryRequest(); + return; + } + if (*status != kStatusOK) { + RecordLookupQueryResult(LookupQueryResult::kStatusNotOk); MaybeRetryRequest(); return; } @@ -383,6 +396,7 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( const std::string* server_timestamp_string = result->FindStringKey(kLookupTimestampKey); if (!server_timestamp_string) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); MaybeRetryRequest(); return; } @@ -390,12 +404,14 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( base::Time server_timestamp; if (!base::Time::FromUTCString(server_timestamp_string->c_str(), &server_timestamp)) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); MaybeRetryRequest(); return; } if (sct_hashdance_metadata_->certificate_expiry < server_timestamp) { // The certificate has expired. Do not report. + RecordLookupQueryResult(LookupQueryResult::kCertificateExpired); std::move(done_callback_).Run(reporter_key_); return; } @@ -403,6 +419,7 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( // Find the corresponding log entry. const base::Value* logs = result->FindListKey(kLookupLogStatusKey); if (!logs) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); MaybeRetryRequest(); return; } @@ -412,6 +429,7 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( const std::string* encoded_log_id = log.FindStringKey(kLookupLogIdKey); std::string log_id; if (!encoded_log_id || !base::Base64Decode(*encoded_log_id, &log_id)) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); MaybeRetryRequest(); return; } @@ -423,6 +441,7 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( if (!found_log) { // We could not find the SCT's log. Maybe it's a new log that the server // doesn't know about yet, schedule a retry. + RecordLookupQueryResult(LookupQueryResult::kLogNotFound); MaybeRetryRequest(); return; } @@ -430,6 +449,7 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( const std::string* ingested_until_string = found_log->FindStringKey(kLookupIngestedUntilKey); if (!ingested_until_string) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); MaybeRetryRequest(); return; } @@ -437,18 +457,21 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( base::Time ingested_until; if (!base::Time::FromString(ingested_until_string->c_str(), &ingested_until)) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); MaybeRetryRequest(); return; } if (sct_hashdance_metadata_->issued > ingested_until) { // The log has not yet ingested this SCT. Schedule a retry. + RecordLookupQueryResult(LookupQueryResult::kLogNotYetIngested); MaybeRetryRequest(); return; } const base::Value* suffix_value = result->FindListKey(kLookupHashSuffixKey); if (!suffix_value) { + RecordLookupQueryResult(LookupQueryResult::kInvalidJson); MaybeRetryRequest(); return; } @@ -466,6 +489,7 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( if (std::find(suffixes.begin(), suffixes.end(), hash_suffix_value) != suffixes.end()) { // Found the SCT in the suffix list, all done. + RecordLookupQueryResult(LookupQueryResult::kSCTSuffixFound); std::move(done_callback_).Run(reporter_key_); return; } @@ -473,6 +497,7 @@ void SCTAuditingReporter::OnSendLookupQueryComplete( // The server does not know about this SCT, and it should. Notify the // embedder and start sending the full report. owner_network_context_->OnNewSCTAuditingReportSent(); + RecordLookupQueryResult(LookupQueryResult::kSCTSuffixNotFound); SendReport(); } diff --git a/services/network/sct_auditing/sct_auditing_reporter.h b/services/network/sct_auditing/sct_auditing_reporter.h index 34653bf0ac00d9..36dec761656e48 100644 --- a/services/network/sct_auditing/sct_auditing_reporter.h +++ b/services/network/sct_auditing/sct_auditing_reporter.h @@ -89,6 +89,48 @@ class COMPONENT_EXPORT(NETWORK_SERVICE) SCTAuditingReporter { base::Time certificate_expiry; }; + // These values are persisted to logs. Entries should not be renumbered and + // numeric values should never be reused. + enum class LookupQueryResult { + // Indicates a network status other than 200 OK. + kHTTPError = 0, + + // The content returned by the server either did not parse as valid JSON or + // was missing required fields. + kInvalidJson = 1, + + // The server returned a `responseStatus` field other than "OK". + kStatusNotOk = 2, + + // The certificate has expired according to the timestamp returned by the + // server. + kCertificateExpired = 3, + + // The server does not know about the log corresponding to the SCT. + kLogNotFound = 4, + + // The log has not yet ingested the SCT. + kLogNotYetIngested = 5, + + // The SCT suffix was found in the suffix list, so it should not be + // reported. + kSCTSuffixFound = 6, + + // The SCT suffix was NOT found in the suffix list, so it should be + // reported. + kSCTSuffixNotFound = 7, + kMaxValue = kSCTSuffixNotFound, + }; + + // These values are persisted to logs. Entries should not be renumbered and + // numeric values should never be reused. + enum class CompletionStatus { + kSuccessFirstTry = 0, + kSuccessAfterRetries = 1, + kRetriesExhausted = 2, + kMaxValue = kRetriesExhausted, + }; + SCTAuditingReporter( NetworkContext* owner_network_context_, net::HashValue reporter_key, @@ -122,15 +164,6 @@ class COMPONENT_EXPORT(NETWORK_SERVICE) SCTAuditingReporter { return sct_hashdance_metadata_; } - // These values are persisted to logs. Entries should not be renumbered and - // numeric values should never be reused. - enum class CompletionStatus { - kSuccessFirstTry = 0, - kSuccessAfterRetries = 1, - kRetriesExhausted = 2, - kMaxValue = kRetriesExhausted, - }; - static void SetRetryDelayForTesting(absl::optional delay); private: diff --git a/services/network/sct_auditing/sct_auditing_reporter_unittest.cc b/services/network/sct_auditing/sct_auditing_reporter_unittest.cc index c174e2b42a51d5..4090165933cdaa 100644 --- a/services/network/sct_auditing/sct_auditing_reporter_unittest.cc +++ b/services/network/sct_auditing/sct_auditing_reporter_unittest.cc @@ -8,6 +8,7 @@ #include "base/callback_helpers.h" #include "base/strings/string_number_conversions.h" #include "base/test/bind.h" +#include "base/test/metrics/histogram_tester.h" #include "base/test/scoped_feature_list.h" #include "base/test/task_environment.h" #include "base/time/clock.h" @@ -164,6 +165,7 @@ class SCTAuditingReporterTest : public testing::Test { std::unique_ptr network_context_; std::unique_ptr network_context_client_; TestURLLoaderFactory url_loader_factory_; + base::HistogramTester histograms; // Metadata used when creating a repoter. SCTAuditingReporter::SCTHashdanceMetadata reporter_metadata_; @@ -284,6 +286,9 @@ TEST_F(SCTAuditingReporterTest, HashdanceLookupNotFound) { EXPECT_EQ(url_loader_factory_.NumPending(), 1); pending_request = url_loader_factory_.GetPendingRequest(0); EXPECT_EQ(pending_request->request.url.spec(), kTestReportURL); + histograms.ExpectUniqueSample( + "Security.SCTAuditing.OptOut.LookupQueryResult", + SCTAuditingReporter::LookupQueryResult::kSCTSuffixNotFound, 1); } // Tests that a hashdance lookup that finds the SCT does not report it. @@ -304,6 +309,9 @@ TEST_F(SCTAuditingReporterTest, HashdanceLookupFound) { // SCT should not be reported. EXPECT_EQ(url_loader_factory_.NumPending(), 0); + histograms.ExpectUniqueSample( + "Security.SCTAuditing.OptOut.LookupQueryResult", + SCTAuditingReporter::LookupQueryResult::kSCTSuffixFound, 1); } // Tests that a hashdance lookup with a server error retries. @@ -319,6 +327,9 @@ TEST_F(SCTAuditingReporterTest, HashdanceLookupServerError) { // Respond to the lookup request with an error. response_.status = "ERROR"; SimulateResponse(); + histograms.ExpectUniqueSample( + "Security.SCTAuditing.OptOut.LookupQueryResult", + SCTAuditingReporter::LookupQueryResult::kStatusNotOk, 1); // A retry should be rescheduled. EXPECT_EQ(url_loader_factory_.NumPending(), 1); @@ -349,6 +360,9 @@ TEST_F(SCTAuditingReporterTest, HashdanceLookupHTTPError) { url_loader_factory_.SimulateResponseForPendingRequest( pending_request->request.url.spec(), /*content=*/"", net::HTTP_TOO_MANY_REQUESTS); + histograms.ExpectUniqueSample( + "Security.SCTAuditing.OptOut.LookupQueryResult", + SCTAuditingReporter::LookupQueryResult::kHTTPError, 1); // A retry should be rescheduled. EXPECT_EQ(url_loader_factory_.NumPending(), 1); @@ -381,6 +395,9 @@ TEST_F(SCTAuditingReporterTest, HashdanceLookupCertificateExpired) { // SCT should not be reported. EXPECT_EQ(url_loader_factory_.NumPending(), 0); + histograms.ExpectUniqueSample( + "Security.SCTAuditing.OptOut.LookupQueryResult", + SCTAuditingReporter::LookupQueryResult::kCertificateExpired, 1); } // Tests that a hashdance lookup that does not return the SCT Log ID gets @@ -397,6 +414,9 @@ TEST_F(SCTAuditingReporterTest, HashdanceLookupUnknownLog) { // Respond to the lookup request with a different log id. response_.log_id = "some_other_log"; SimulateResponse(); + histograms.ExpectUniqueSample( + "Security.SCTAuditing.OptOut.LookupQueryResult", + SCTAuditingReporter::LookupQueryResult::kLogNotFound, 1); // A retry should be rescheduled. EXPECT_EQ(url_loader_factory_.NumPending(), 1); @@ -427,6 +447,9 @@ TEST_F(SCTAuditingReporterTest, HashdanceLookupLogNotIngested) { // Respond to the lookup request with a too early `ingested_until`. response_.ingested_until = reporter_metadata_.issued - base::Seconds(1); SimulateResponse(); + histograms.ExpectUniqueSample( + "Security.SCTAuditing.OptOut.LookupQueryResult", + SCTAuditingReporter::LookupQueryResult::kLogNotYetIngested, 1); // A retry should be rescheduled. EXPECT_EQ(url_loader_factory_.NumPending(), 1); @@ -470,6 +493,9 @@ TEST_F(SCTAuditingReporterTest, HashdanceSCTSuspectedNotYetIngested) { EXPECT_EQ(url_loader_factory_.NumPending(), 1); pending_request = url_loader_factory_.GetPendingRequest(0); EXPECT_EQ(pending_request->request.url.spec(), kTestReportURL); + histograms.ExpectUniqueSample( + "Security.SCTAuditing.OptOut.LookupQueryResult", + SCTAuditingReporter::LookupQueryResult::kSCTSuffixNotFound, 1); } } // namespace network diff --git a/tools/metrics/histograms/enums.xml b/tools/metrics/histograms/enums.xml index 0064c0895e0cb8..0c1e635d813976 100644 --- a/tools/metrics/histograms/enums.xml +++ b/tools/metrics/histograms/enums.xml @@ -79765,6 +79765,17 @@ https://www.dmtf.org/sites/default/files/standards/documents/DSP0134_2.7.1.pdf + + + + + + + + + + + diff --git a/tools/metrics/histograms/metadata/security/histograms.xml b/tools/metrics/histograms/metadata/security/histograms.xml index bf2c5628868f1b..6aa93535d4771c 100644 --- a/tools/metrics/histograms/metadata/security/histograms.xml +++ b/tools/metrics/histograms/metadata/security/histograms.xml @@ -576,6 +576,17 @@ chromium-metrics-reviews@google.com. + + cthomp@chromium.org + nsatragno@chromium.org + trusty-transport@chromium.org + + Records the result of a hashdance lookup query. Recorded once per query + regardless of whether the query succeeded, failed, or is a retry. + + + cthomp@chromium.org