Skip to content

Commit

Permalink
[CT] Add metrics for hashdance lookup query result
Browse files Browse the repository at this point in the history 
This CL adds a histogram recording the result of a hashdance lookup
query.

Design doc:
https://docs.google.com/document/d/16G-Q7iN3kB46GSW5b-sfH5MO3nKSYyEb77YsM7TMZGE

(cherry picked from commit 53fda1c)

Bug: 1249925
Change-Id: I42c8d08b95e6fc5f689dce44a8f8acbbadab38ae
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3490373
Commit-Queue: Nina Satragno <nsatragno@chromium.org>
Auto-Submit: Nina Satragno <nsatragno@chromium.org>
Reviewed-by: Chris Thompson <cthomp@chromium.org>
Commit-Queue: Chris Thompson <cthomp@chromium.org>
Cr-Original-Commit-Position: refs/heads/main@{#975365}
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3510289
Cr-Commit-Position: refs/branch-heads/4896@{#385}
Cr-Branched-From: 1f63ff4-refs/heads/main@{#972766}
  • Loading branch information
@nsatragno
nsatragno authored and Chromium LUCI CQ committed Mar 8, 2022
1 parent 96998be commit 93806c7
Show file tree
Hide file tree
Showing 5 changed files with 116 additions and 10 deletions.
27 changes: 26 additions & 1 deletion services/network/sct_auditing/sct_auditing_reporter.cc
View file
Expand Up @@ -60,6 +60,11 @@ constexpr char kStatusOK[] = "OK";
// not nullopt.
absl::optional<base::TimeDelta> 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) {
Expand Down Expand Up @@ -364,45 +369,57 @@ 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<base::Value> 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;
}

const std::string* server_timestamp_string =
result->FindStringKey(kLookupTimestampKey);
if (!server_timestamp_string) {
RecordLookupQueryResult(LookupQueryResult::kInvalidJson);
MaybeRetryRequest();
return;
}

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;
}

// Find the corresponding log entry.
const base::Value* logs = result->FindListKey(kLookupLogStatusKey);
if (!logs) {
RecordLookupQueryResult(LookupQueryResult::kInvalidJson);
MaybeRetryRequest();
return;
}
Expand All @@ -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;
}
Expand All @@ -423,32 +441,37 @@ 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;
}

const std::string* ingested_until_string =
found_log->FindStringKey(kLookupIngestedUntilKey);
if (!ingested_until_string) {
RecordLookupQueryResult(LookupQueryResult::kInvalidJson);
MaybeRetryRequest();
return;
}

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;
}
Expand All @@ -466,13 +489,15 @@ 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;
}

// 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();
}

Expand Down
51 changes: 42 additions & 9 deletions services/network/sct_auditing/sct_auditing_reporter.h
View file
Expand Up @@ -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,
Expand Down Expand Up @@ -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<base::TimeDelta> delay);

private:
Expand Down
26 changes: 26 additions & 0 deletions services/network/sct_auditing/sct_auditing_reporter_unittest.cc
View file
Expand Up @@ -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"
Expand Down Expand Up @@ -164,6 +165,7 @@ class SCTAuditingReporterTest : public testing::Test {
std::unique_ptr<NetworkContext> network_context_;
std::unique_ptr<TestNetworkContextClient> network_context_client_;
TestURLLoaderFactory url_loader_factory_;
base::HistogramTester histograms;

// Metadata used when creating a repoter.
SCTAuditingReporter::SCTHashdanceMetadata reporter_metadata_;
Expand Down Expand Up @@ -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.
Expand All @@ -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.
Expand All @@ -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);
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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
Expand All @@ -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);
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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
11 changes: 11 additions & 0 deletions tools/metrics/histograms/enums.xml
View file
Expand Up @@ -79765,6 +79765,17 @@ https://www.dmtf.org/sites/default/files/standards/documents/DSP0134_2.7.1.pdf
<int value="7" label="Unable to determine leaf hash"/>
</enum>

<enum name="SCTLookupQueryResult">
<int value="0" label="HTTP error"/>
<int value="1" label="Invalid JSON"/>
<int value="2" label="Status not OK"/>
<int value="3" label="Certificate expired"/>
<int value="4" label="Log not found"/>
<int value="5" label="Log not yet ingested"/>
<int value="6" label="SCT suffix found"/>
<int value="7" label="SCT suffix not found"/>
</enum>

<enum name="SCTOrigin">
<int value="0" label="SCT_EMBEDDED"/>
<int value="1" label="SCT_FROM_TLS_EXTENSION"/>
Expand Down
11 changes: 11 additions & 0 deletions tools/metrics/histograms/metadata/security/histograms.xml
View file
Expand Up @@ -576,6 +576,17 @@ chromium-metrics-reviews@google.com.
</summary>
</histogram>

<histogram name="Security.SCTAuditing.OptOut.LookupQueryResult"
enum="SCTLookupQueryResult" expires_after="M104">
<owner>cthomp@chromium.org</owner>
<owner>nsatragno@chromium.org</owner>
<owner>trusty-transport@chromium.org</owner>
<summary>
Records the result of a hashdance lookup query. Recorded once per query
regardless of whether the query succeeded, failed, or is a retry.
</summary>
</histogram>

<histogram name="Security.SCTAuditing.OptOut.PopularSCTSkipped" enum="Boolean"
expires_after="M104">
<owner>cthomp@chromium.org</owner>
Expand Down

0 comments on commit 93806c7

Please sign in to comment.