1 // Copyright 2019 The Chromium Authors
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "components/metrics/structured/structured_metrics_provider.h"
6
7 #include <sstream>
8 #include <utility>
9
10 #include "base/feature_list.h"
11 #include "base/logging.h"
12 #include "base/metrics/histogram_macros.h"
13 #include "base/metrics/metrics_hashes.h"
14 #include "base/strings/string_number_conversions.h"
15 #include "base/strings/string_split.h"
16 #include "base/task/current_thread.h"
17 #include "components/metrics/structured/enums.h"
18 #include "components/metrics/structured/external_metrics.h"
19 #include "components/metrics/structured/histogram_util.h"
20 #include "components/metrics/structured/project_validator.h"
21 #include "components/metrics/structured/storage.pb.h"
22 #include "components/metrics/structured/structured_metrics_features.h"
23 #include "components/metrics/structured/structured_metrics_validator.h"
24 #include "third_party/metrics_proto/chrome_user_metrics_extension.pb.h"
25
26 namespace metrics::structured {
27 namespace {
28
29 using ::metrics::ChromeUserMetricsExtension;
30 using ::metrics::SystemProfileProto;
31
32 // The delay period for the PersistentProto.
33 constexpr int kSaveDelayMs = 1000;
34
35 // The interval between chrome's collection of metrics logged from cros.
36 constexpr int kExternalMetricsIntervalMins = 10;
37
38 // This is set carefully: metrics logs are stored in a queue of limited size,
39 // and are uploaded roughly every 30 minutes.
40 constexpr base::TimeDelta kMinIndependentMetricsInterval = base::Minutes(45);
41
42 // Directory containing serialized event protos to read.
43 constexpr char kExternalMetricsDir[] = "/var/lib/metrics/structured/events";
44
45 } // namespace
46
47 int StructuredMetricsProvider::kMaxEventsPerUpload = 100;
48
49 char StructuredMetricsProvider::kProfileKeyDataPath[] =
50 "structured_metrics/keys";
51
52 char StructuredMetricsProvider::kDeviceKeyDataPath[] =
53 "/var/lib/metrics/structured/chromium/keys";
54
55 char StructuredMetricsProvider::kUnsentLogsPath[] = "structured_metrics/events";
56
StructuredMetricsProvider(metrics::MetricsProvider * system_profile_provider)57 StructuredMetricsProvider::StructuredMetricsProvider(
58 metrics::MetricsProvider* system_profile_provider)
59 : StructuredMetricsProvider(base::FilePath(kDeviceKeyDataPath),
60 base::Milliseconds(kSaveDelayMs),
61 kMinIndependentMetricsInterval,
62 system_profile_provider) {}
63
StructuredMetricsProvider(const base::FilePath & device_key_path,base::TimeDelta min_independent_metrics_interval,base::TimeDelta write_delay,metrics::MetricsProvider * system_profile_provider)64 StructuredMetricsProvider::StructuredMetricsProvider(
65 const base::FilePath& device_key_path,
66 base::TimeDelta min_independent_metrics_interval,
67 base::TimeDelta write_delay,
68 metrics::MetricsProvider* system_profile_provider)
69 : device_key_path_(device_key_path),
70 write_delay_(write_delay),
71 min_independent_metrics_interval_(min_independent_metrics_interval),
72 system_profile_provider_(system_profile_provider) {
73 DCHECK(system_profile_provider_);
74 Recorder::GetInstance()->AddObserver(this);
75 }
76
~StructuredMetricsProvider()77 StructuredMetricsProvider::~StructuredMetricsProvider() {
78 Recorder::GetInstance()->RemoveObserver(this);
79 DCHECK(!IsInObserverList());
80 }
81
OnKeyDataInitialized()82 void StructuredMetricsProvider::OnKeyDataInitialized() {
83 DCHECK(base::CurrentUIThread::IsSet());
84
85 ++init_count_;
86 if (init_count_ == kTargetInitCount) {
87 init_state_ = InitState::kInitialized;
88 HashUnhashedEventsAndPersist();
89 }
90 }
91
OnRead(const ReadStatus status)92 void StructuredMetricsProvider::OnRead(const ReadStatus status) {
93 DCHECK(base::CurrentUIThread::IsSet());
94
95 switch (status) {
96 case ReadStatus::kOk:
97 case ReadStatus::kMissing:
98 break;
99 case ReadStatus::kReadError:
100 LogInternalError(StructuredMetricsError::kEventReadError);
101 break;
102 case ReadStatus::kParseError:
103 LogInternalError(StructuredMetricsError::kEventParseError);
104 break;
105 }
106
107 ++init_count_;
108 if (init_count_ == kTargetInitCount) {
109 init_state_ = InitState::kInitialized;
110 HashUnhashedEventsAndPersist();
111 }
112 }
113
OnWrite(const WriteStatus status)114 void StructuredMetricsProvider::OnWrite(const WriteStatus status) {
115 DCHECK(base::CurrentUIThread::IsSet());
116
117 switch (status) {
118 case WriteStatus::kOk:
119 break;
120 case WriteStatus::kWriteError:
121 LogInternalError(StructuredMetricsError::kEventWriteError);
122 break;
123 case WriteStatus::kSerializationError:
124 LogInternalError(StructuredMetricsError::kEventSerializationError);
125 break;
126 }
127 }
128
OnExternalMetricsCollected(const EventsProto & events)129 void StructuredMetricsProvider::OnExternalMetricsCollected(
130 const EventsProto& events) {
131 DCHECK(base::CurrentUIThread::IsSet());
132 if (recording_enabled_) {
133 events_.get()->get()->mutable_uma_events()->MergeFrom(events.uma_events());
134 events_.get()->get()->mutable_non_uma_events()->MergeFrom(
135 events.non_uma_events());
136
137 // Only increment if new events were add.
138 if (events.uma_events_size() || events.non_uma_events_size()) {
139 external_metrics_scans_ += 1;
140 }
141 }
142 }
143
Purge()144 void StructuredMetricsProvider::Purge() {
145 DCHECK(events_ && profile_key_data_ && device_key_data_);
146 events_->Purge();
147 profile_key_data_->Purge();
148 device_key_data_->Purge();
149 }
150
OnProfileAdded(const base::FilePath & profile_path)151 void StructuredMetricsProvider::OnProfileAdded(
152 const base::FilePath& profile_path) {
153 DCHECK(base::CurrentUIThread::IsSet());
154
155 // We do not handle multiprofile, instead initializing with the state stored
156 // in the first logged-in user's cryptohome. So if a second profile is added
157 // we should ignore it. All init state beyond |InitState::kUninitialized| mean
158 // a profile has already been added.
159 if (init_state_ != InitState::kUninitialized) {
160 return;
161 }
162 init_state_ = InitState::kProfileAdded;
163
164 profile_key_data_ = std::make_unique<KeyData>(
165 profile_path.Append(kProfileKeyDataPath), write_delay_,
166 base::BindOnce(&StructuredMetricsProvider::OnKeyDataInitialized,
167 weak_factory_.GetWeakPtr()));
168
169 device_key_data_ = std::make_unique<KeyData>(
170 base::FilePath(device_key_path_), write_delay_,
171 base::BindOnce(&StructuredMetricsProvider::OnKeyDataInitialized,
172 weak_factory_.GetWeakPtr()));
173
174 events_ = std::make_unique<PersistentProto<EventsProto>>(
175 profile_path.Append(kUnsentLogsPath), write_delay_,
176 base::BindOnce(&StructuredMetricsProvider::OnRead,
177 weak_factory_.GetWeakPtr()),
178 base::BindRepeating(&StructuredMetricsProvider::OnWrite,
179 weak_factory_.GetWeakPtr()));
180
181 external_metrics_ = std::make_unique<ExternalMetrics>(
182 base::FilePath(kExternalMetricsDir),
183 base::Minutes(kExternalMetricsIntervalMins),
184 base::BindRepeating(
185 &StructuredMetricsProvider::OnExternalMetricsCollected,
186 weak_factory_.GetWeakPtr()));
187
188 // See OnRecordingDisabled for more information.
189 if (purge_state_on_init_) {
190 Purge();
191 purge_state_on_init_ = false;
192 }
193 }
194
OnEventRecord(const Event & event)195 void StructuredMetricsProvider::OnEventRecord(const Event& event) {
196 DCHECK(base::CurrentUIThread::IsSet());
197
198 // One more state for the EventRecordingState exists: kMetricsProviderMissing.
199 // This is recorded in Recorder::Record.
200 if (!recording_enabled_) {
201 // Events should be ignored if recording is disabled.
202 LogEventRecordingState(EventRecordingState::kRecordingDisabled);
203 return;
204 } else if (init_state_ != InitState::kInitialized) {
205 // If keys have not loaded yet, then hold the data in memory until the keys
206 // have been loaded.
207 LogEventRecordingState(EventRecordingState::kProviderUninitialized);
208 RecordEventBeforeInitialization(event);
209 return;
210 }
211
212 DCHECK(profile_key_data_->is_initialized());
213 DCHECK(device_key_data_->is_initialized());
214
215 RecordEvent(event);
216
217 events_->QueueWrite();
218 }
219
LastKeyRotation(const uint64_t project_name_hash)220 absl::optional<int> StructuredMetricsProvider::LastKeyRotation(
221 const uint64_t project_name_hash) {
222 DCHECK(base::CurrentUIThread::IsSet());
223 if (init_state_ != InitState::kInitialized) {
224 return absl::nullopt;
225 }
226 DCHECK(profile_key_data_->is_initialized());
227 DCHECK(device_key_data_->is_initialized());
228
229 // |project_name_hash| could store its keys in either the profile or device
230 // key data, so check both. As they cannot both contain the same name hash, at
231 // most one will return a non-nullopt value.
232 absl::optional<int> profile_day =
233 profile_key_data_->LastKeyRotation(project_name_hash);
234 absl::optional<int> device_day =
235 device_key_data_->LastKeyRotation(project_name_hash);
236 DCHECK(!(profile_day && device_day));
237 return profile_day ? profile_day : device_day;
238 }
239
OnRecordingEnabled()240 void StructuredMetricsProvider::OnRecordingEnabled() {
241 DCHECK(base::CurrentUIThread::IsSet());
242 // Enable recording only if structured metrics' feature flag is enabled.
243 recording_enabled_ = base::FeatureList::IsEnabled(kStructuredMetrics);
244 if (recording_enabled_) {
245 CacheDisallowedProjectsSet();
246 }
247 }
248
OnRecordingDisabled()249 void StructuredMetricsProvider::OnRecordingDisabled() {
250 DCHECK(base::CurrentUIThread::IsSet());
251 recording_enabled_ = false;
252 disallowed_projects_.clear();
253 }
254
OnReportingStateChanged(bool enabled)255 void StructuredMetricsProvider::OnReportingStateChanged(bool enabled) {
256 DCHECK(base::CurrentUIThread::IsSet());
257
258 // When reporting is enabled, OnRecordingEnabled is also called. Let that
259 // handle enabling.
260 if (enabled) {
261 return;
262 }
263
264 // When reporting is disabled, OnRecordingDisabled is also called. Disabling
265 // here is redundant but done for clarity.
266 recording_enabled_ = false;
267
268 // Delete keys and unsent logs. We need to handle two cases:
269 //
270 // 1. A profile hasn't been added yet and we can't delete the files
271 // immediately. In this case set |purge_state_on_init_| and let
272 // OnProfileAdded call Purge after initialization.
273 //
274 // 2. A profile has been added and so the backing PersistentProtos have been
275 // constructed. In this case just call Purge directly.
276 //
277 // Note that Purge will ensure the events are deleted from disk even if the
278 // PersistentProto hasn't itself finished being read.
279 if (init_state_ == InitState::kUninitialized) {
280 purge_state_on_init_ = true;
281 } else {
282 Purge();
283 }
284 }
285
OnSystemProfileInitialized()286 void StructuredMetricsProvider::OnSystemProfileInitialized() {
287 system_profile_initialized_ = true;
288 }
289
ProvideCurrentSessionData(ChromeUserMetricsExtension * uma_proto)290 void StructuredMetricsProvider::ProvideCurrentSessionData(
291 ChromeUserMetricsExtension* uma_proto) {
292 DCHECK(base::CurrentUIThread::IsSet());
293 if (!recording_enabled_ || init_state_ != InitState::kInitialized) {
294 return;
295 }
296
297 LogNumEventsInUpload(events_.get()->get()->uma_events_size());
298
299 auto* structured_data = uma_proto->mutable_structured_data();
300 structured_data->mutable_events()->Swap(
301 events_.get()->get()->mutable_uma_events());
302 events_.get()->get()->clear_uma_events();
303 events_->StartWrite();
304
305 LogUploadSizeBytes(structured_data->ByteSizeLong());
306 }
307
HasIndependentMetrics()308 bool StructuredMetricsProvider::HasIndependentMetrics() {
309 if (!IsIndependentMetricsUploadEnabled()) {
310 return false;
311 }
312
313 if (!recording_enabled_ || init_state_ != InitState::kInitialized) {
314 return false;
315 }
316
317 if (base::Time::Now() - last_provided_independent_metrics_ <
318 min_independent_metrics_interval_) {
319 return false;
320 }
321
322 return events_.get()->get()->non_uma_events_size() != 0;
323 }
324
ProvideIndependentMetrics(base::OnceCallback<void (bool)> done_callback,ChromeUserMetricsExtension * uma_proto,base::HistogramSnapshotManager *)325 void StructuredMetricsProvider::ProvideIndependentMetrics(
326 base::OnceCallback<void(bool)> done_callback,
327 ChromeUserMetricsExtension* uma_proto,
328 base::HistogramSnapshotManager*) {
329 DCHECK(base::CurrentUIThread::IsSet());
330 if (!recording_enabled_ || init_state_ != InitState::kInitialized) {
331 std::move(done_callback).Run(false);
332 return;
333 }
334
335 last_provided_independent_metrics_ = base::Time::Now();
336
337 LogNumEventsInUpload(events_.get()->get()->non_uma_events_size());
338
339 // Independent metrics need to manually populate Chrome OS fields such as
340 // full_hardware_class as ChromeOSMetricsProvider will not be called for
341 // IndependentMetrics.
342 ProvideSystemProfile(uma_proto->mutable_system_profile());
343
344 auto* structured_data = uma_proto->mutable_structured_data();
345 structured_data->mutable_events()->Swap(
346 events_.get()->get()->mutable_non_uma_events());
347 events_.get()->get()->clear_non_uma_events();
348 events_->StartWrite();
349
350 LogUploadSizeBytes(structured_data->ByteSizeLong());
351 LogExternalMetricsScanInUpload(external_metrics_scans_);
352 external_metrics_scans_ = 0;
353
354 // Independent events should not be associated with the client_id, so clear
355 // it.
356 uma_proto->clear_client_id();
357 // TODO(crbug/1052796): Remove the UMA timer code, which is currently used to
358 // determine if it is worth to finalize independent logs in the background
359 // by measuring the time it takes to execute the callback
360 // MetricsService::PrepareProviderMetricsLogDone().
361 SCOPED_UMA_HISTOGRAM_TIMER(
362 "UMA.IndependentLog.StructuredMetricsProvider.FinalizeTime");
363 std::move(done_callback).Run(true);
364 }
365
ProvideSystemProfile(SystemProfileProto * system_profile)366 void StructuredMetricsProvider::ProvideSystemProfile(
367 SystemProfileProto* system_profile) {
368 // Populate the proto if the system profile has been initialized and
369 // has a system profile provider. The field may be populated if
370 // ChromeOSMetricsProvider has already run.
371 if (system_profile_initialized_) {
372 system_profile_provider_->ProvideSystemProfileMetrics(system_profile);
373 }
374 }
375
WriteNowForTest()376 void StructuredMetricsProvider::WriteNowForTest() {
377 events_->StartWrite();
378 }
379
SetExternalMetricsDirForTest(const base::FilePath & dir)380 void StructuredMetricsProvider::SetExternalMetricsDirForTest(
381 const base::FilePath& dir) {
382 external_metrics_ = std::make_unique<ExternalMetrics>(
383 dir, base::Minutes(kExternalMetricsIntervalMins),
384 base::BindRepeating(
385 &StructuredMetricsProvider::OnExternalMetricsCollected,
386 weak_factory_.GetWeakPtr()));
387 }
388
RecordEventBeforeInitialization(const Event & event)389 void StructuredMetricsProvider::RecordEventBeforeInitialization(
390 const Event& event) {
391 DCHECK_NE(init_state_, InitState::kInitialized);
392 unhashed_events_.emplace_back(event.Clone());
393 }
394
RecordEvent(const Event & event)395 void StructuredMetricsProvider::RecordEvent(const Event& event) {
396 // Validates the event. If valid, retrieve the metadata associated
397 // with the event.
398 auto maybe_project_validator =
399 validator::GetProjectValidator(event.project_name());
400
401 DCHECK(maybe_project_validator.has_value());
402 if (!maybe_project_validator.has_value()) {
403 return;
404 }
405 const auto* project_validator = maybe_project_validator.value();
406 const auto maybe_event_validator =
407 project_validator->GetEventValidator(event.event_name());
408 DCHECK(maybe_event_validator.has_value());
409 if (!maybe_event_validator.has_value()) {
410 return;
411 }
412 const auto* event_validator = maybe_event_validator.value();
413
414 if (!CanUploadProject(project_validator->project_hash())) {
415 LogEventRecordingState(EventRecordingState::kProjectDisallowed);
416 return;
417 }
418
419 LogEventRecordingState(EventRecordingState::kRecorded);
420
421 // The |events_| persistent proto contains two repeated fields, uma_events
422 // and non_uma_events. uma_events is added to the ChromeUserMetricsExtension
423 // on a call to ProvideCurrentSessionData, which is the standard UMA upload
424 // and contains the UMA client_id. non_uma_events is added to the proto on
425 // a call to ProvideIndependentMetrics, which is a separate upload that does
426 // _not_ contain the UMA client_id.
427 //
428 // We decide which field to add this event to based on the event's IdType.
429 // kUmaId events should go in the UMA upload, and all others in the non-UMA
430 // upload.
431 StructuredEventProto* event_proto;
432 if (project_validator->id_type() == IdType::kUmaId ||
433 !IsIndependentMetricsUploadEnabled()) {
434 event_proto = events_.get()->get()->add_uma_events();
435 } else {
436 event_proto = events_.get()->get()->add_non_uma_events();
437 }
438
439 event_proto->set_project_name_hash(project_validator->project_hash());
440
441 // Sequence-related metadata.
442 if (project_validator->event_type() ==
443 StructuredEventProto_EventType_SEQUENCE &&
444 base::FeatureList::IsEnabled(kEventSequenceLogging)) {
445 auto* event_sequence_metadata =
446 event_proto->mutable_event_sequence_metadata();
447
448 event_sequence_metadata->set_reset_counter(
449 event.event_sequence_metadata().reset_counter);
450 event_sequence_metadata->set_system_uptime(
451 event.recorded_time_since_boot().InMilliseconds());
452 event_sequence_metadata->set_event_unique_id(
453 base::HashMetricName(event.event_sequence_metadata().event_unique_id));
454 event_proto->set_device_project_id(
455 device_key_data_.get()->Id(project_validator->project_hash(),
456 project_validator->key_rotation_period()));
457 event_proto->set_user_project_id(
458 profile_key_data_.get()->Id(project_validator->project_hash(),
459 project_validator->key_rotation_period()));
460 }
461
462 // Choose which KeyData to use for this event.
463 KeyData* key_data;
464 switch (project_validator->id_scope()) {
465 case IdScope::kPerProfile:
466 key_data = profile_key_data_.get();
467 break;
468 case IdScope::kPerDevice:
469 // For event sequence, use the profile key for now to hash strings.
470 //
471 // TODO(crbug/1399632): Event sequence is considered a structured metrics
472 // project. Once the client supports device/profile split of events like
473 // structured metrics, remove this.
474 if (project_validator->event_type() ==
475 StructuredEventProto_EventType_SEQUENCE) {
476 key_data = profile_key_data_.get();
477 } else {
478 key_data = device_key_data_.get();
479 }
480 break;
481 default:
482 // In case id_scope is uninitialized.
483 NOTREACHED();
484 }
485
486 // Set the ID for this event, if any.
487 switch (project_validator->id_type()) {
488 case IdType::kProjectId:
489 event_proto->set_profile_event_id(
490 key_data->Id(project_validator->project_hash(),
491 project_validator->key_rotation_period()));
492 break;
493 case IdType::kUmaId:
494 // TODO(crbug.com/1148168): Unimplemented.
495 break;
496 case IdType::kUnidentified:
497 // Do nothing.
498 break;
499 default:
500 // In case id_type is uninitialized.
501 NOTREACHED();
502 break;
503 }
504
505 // Set the event type. Do this with a switch statement to catch when the event
506 // type is UNKNOWN or uninitialized.
507 switch (project_validator->event_type()) {
508 case StructuredEventProto_EventType_REGULAR:
509 case StructuredEventProto_EventType_RAW_STRING:
510 case StructuredEventProto_EventType_SEQUENCE:
511 event_proto->set_event_type(project_validator->event_type());
512 break;
513 default:
514 NOTREACHED();
515 break;
516 }
517
518 event_proto->set_event_name_hash(event_validator->event_hash());
519
520 // Set each metric's name hash and value.
521 for (const auto& metric : event.metric_values()) {
522 const std::string& metric_name = metric.first;
523 const Event::MetricValue& metric_value = metric.second;
524
525 // Validate that both name and metric type are valid structured metrics. If
526 // a metric is invalid, then ignore the metric so that other valid metrics
527 // are added to the proto.
528 absl::optional<EventValidator::MetricMetadata> metadata =
529 event_validator->GetMetricMetadata(metric_name);
530
531 // Checks that the metrics defined are valid. If not valid, then the metric
532 // will be ignored.
533 bool is_valid =
534 metadata.has_value() && metadata->metric_type == metric_value.type;
535 DCHECK(is_valid);
536 if (!is_valid) {
537 continue;
538 }
539
540 StructuredEventProto::Metric* metric_proto = event_proto->add_metrics();
541 int64_t metric_name_hash = metadata->metric_name_hash;
542 metric_proto->set_name_hash(metric_name_hash);
543
544 const auto& value = metric_value.value;
545 switch (metadata->metric_type) {
546 case Event::MetricType::kHmac:
547 metric_proto->set_value_hmac(key_data->HmacMetric(
548 project_validator->project_hash(), metric_name_hash,
549 value.GetString(), project_validator->key_rotation_period()));
550 break;
551 case Event::MetricType::kLong:
552 int64_t long_value;
553 base::StringToInt64(value.GetString(), &long_value);
554 metric_proto->set_value_int64(long_value);
555 break;
556 case Event::MetricType::kRawString:
557 metric_proto->set_value_string(value.GetString());
558 break;
559 case Event::MetricType::kDouble:
560 metric_proto->set_value_double(value.GetDouble());
561 break;
562 // Not supported yet.
563 case Event::MetricType::kInt:
564 case Event::MetricType::kBoolean:
565 break;
566 }
567
568 // Log size information about the event.
569 LogEventSerializedSizeBytes(event_proto->ByteSizeLong());
570 }
571 }
572
HashUnhashedEventsAndPersist()573 void StructuredMetricsProvider::HashUnhashedEventsAndPersist() {
574 LogNumEventsRecordedBeforeInit(unhashed_events_.size());
575
576 while (!unhashed_events_.empty()) {
577 RecordEvent(unhashed_events_.front());
578 unhashed_events_.pop_front();
579 }
580 }
581
CanUploadProject(uint64_t project_name_hash) const582 bool StructuredMetricsProvider::CanUploadProject(
583 uint64_t project_name_hash) const {
584 return !disallowed_projects_.contains(project_name_hash);
585 }
586
CacheDisallowedProjectsSet()587 void StructuredMetricsProvider::CacheDisallowedProjectsSet() {
588 const std::string& disallowed_list = GetDisabledProjects();
589 if (disallowed_list.empty()) {
590 return;
591 }
592
593 for (const auto& value :
594 base::SplitString(disallowed_list, ",", base::TRIM_WHITESPACE,
595 base::SPLIT_WANT_NONEMPTY)) {
596 uint64_t project_name_hash;
597 // Parse the string and keep only perfect conversions.
598 if (base::StringToUint64(value, &project_name_hash)) {
599 disallowed_projects_.insert(project_name_hash);
600 }
601 }
602 }
603
AddDisallowedProjectForTest(uint64_t project_name_hash)604 void StructuredMetricsProvider::AddDisallowedProjectForTest(
605 uint64_t project_name_hash) {
606 disallowed_projects_.insert(project_name_hash);
607 }
608
609 } // namespace metrics::structured
610