1 /*
2 * Copyright 2022 Google LLC
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16 #include "fcp/client/phase_logger_impl.h"
17
18 #include <string>
19 #include <tuple>
20
21 #include "google/protobuf/util/time_util.h"
22 #include "gmock/gmock.h"
23 #include "gtest/gtest.h"
24 #include "absl/status/status.h"
25 #include "absl/time/clock.h"
26 #include "absl/time/time.h"
27 #include "fcp/client/test_helpers.h"
28 #include "fcp/testing/testing.h"
29
30 namespace fcp {
31 namespace client {
32 namespace {
33
34 using ::fcp::client::opstats::OperationalStats;
35 using ::google::internal::federatedml::v2::RetryWindow;
36 using ::google::protobuf::util::TimeUtil;
37 using ::testing::_;
38 using ::testing::AllOf;
39 using ::testing::Ge;
40 using ::testing::InSequence;
41 using ::testing::Lt;
42 using ::testing::Return;
43 using ::testing::StrictMock;
44
45 const int64_t kChunkingLayerBytesReceived = 100;
46 const int64_t kChunkingLayerBytesSent = 50;
47 const int kTotalExampleCount = 10;
48 const int64_t kTotalExampleSizeBytes = 1000;
49
50 // Parameterize tests with
51 // 1) whether log tf error message;
52 // 2) whether separate "plan URI received" events should be logged.
53 class PhaseLoggerImplTest : public testing::TestWithParam<bool> {
54 protected:
SetUp()55 void SetUp() override {
56 log_tensorflow_error_messages_ = GetParam();
57 EXPECT_CALL(mock_flags_, log_tensorflow_error_messages())
58 .WillRepeatedly(Return(log_tensorflow_error_messages_));
59
60 phase_logger_ = std::make_unique<PhaseLoggerImpl>(
61 &mock_event_publisher_, &mock_opstats_logger_, &mock_log_manager_,
62 &mock_flags_);
63 }
64
VerifyCounterLogged(HistogramCounters counter,const testing::Matcher<int64_t> & matcher)65 void VerifyCounterLogged(HistogramCounters counter,
66 const testing::Matcher<int64_t>& matcher) {
67 EXPECT_CALL(mock_log_manager_,
68 LogToLongHistogram(counter, /*execution_index=*/0,
69 /*epoch_index=*/0,
70 engine::DataSourceType::DATASET, matcher));
71 }
72
73 StrictMock<MockLogManager> mock_log_manager_;
74 StrictMock<MockEventPublisher> mock_event_publisher_;
75 StrictMock<MockOpStatsLogger> mock_opstats_logger_;
76 MockFlags mock_flags_;
77 bool log_tensorflow_error_messages_ = false;
78 std::unique_ptr<PhaseLoggerImpl> phase_logger_;
79 NetworkStats network_stats_ = {
80 .bytes_downloaded = kChunkingLayerBytesReceived,
81 .bytes_uploaded = kChunkingLayerBytesSent};
82 ExampleStats example_stats_ = {.example_count = kTotalExampleCount,
83 .example_size_bytes = kTotalExampleSizeBytes};
84 };
85
GenerateTestName(const testing::TestParamInfo<PhaseLoggerImplTest::ParamType> & info)86 std::string GenerateTestName(
87 const testing::TestParamInfo<PhaseLoggerImplTest::ParamType>& info) {
88 std::string name =
89 absl::StrCat(info.param ? "Log_tf_error" : "No_tf_error", "__");
90 return name;
91 }
92
93 INSTANTIATE_TEST_SUITE_P(OldVsNewBehavior, PhaseLoggerImplTest, testing::Bool(),
94 GenerateTestName);
95
TEST_P(PhaseLoggerImplTest,UpdateRetryWindowAndNetworkStats)96 TEST_P(PhaseLoggerImplTest, UpdateRetryWindowAndNetworkStats) {
97 RetryWindow retry_window;
98 *retry_window.mutable_retry_token() = "retry_token";
99 *retry_window.mutable_delay_max() = TimeUtil::HoursToDuration(48);
100 *retry_window.mutable_delay_min() = TimeUtil::HoursToDuration(4);
101
102 InSequence seq;
103 EXPECT_CALL(mock_opstats_logger_, SetRetryWindow(EqualsProto(retry_window)));
104 EXPECT_CALL(mock_opstats_logger_,
105 SetNetworkStats(testing::Eq(network_stats_)));
106
107 phase_logger_->UpdateRetryWindowAndNetworkStats(retry_window, network_stats_);
108 }
109
TEST_P(PhaseLoggerImplTest,SetModelIdentifier)110 TEST_P(PhaseLoggerImplTest, SetModelIdentifier) {
111 std::string model_identifier = "model_identifier";
112 InSequence seq;
113 EXPECT_CALL(mock_event_publisher_, SetModelIdentifier(model_identifier));
114 EXPECT_CALL(mock_log_manager_, SetModelIdentifier(model_identifier));
115
116 phase_logger_->SetModelIdentifier(model_identifier);
117 }
118
TEST_P(PhaseLoggerImplTest,LogTaskNotStarted)119 TEST_P(PhaseLoggerImplTest, LogTaskNotStarted) {
120 std::string error_message = "Client is not ready for training.";
121 EXPECT_CALL(mock_event_publisher_, PublishTaskNotStarted(error_message));
122 EXPECT_CALL(mock_opstats_logger_,
123 AddEventWithErrorMessage(
124 OperationalStats::Event::EVENT_KIND_TRAIN_NOT_STARTED,
125 error_message));
126 phase_logger_->LogTaskNotStarted(error_message);
127 }
128
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalCheckinStarted)129 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalCheckinStarted) {
130 InSequence seq;
131 EXPECT_CALL(mock_event_publisher_, PublishEligibilityEvalCheckin());
132 EXPECT_CALL(
133 mock_opstats_logger_,
134 AddEvent(
135 OperationalStats::Event::EVENT_KIND_ELIGIBILITY_CHECKIN_STARTED));
136 phase_logger_->LogEligibilityEvalCheckinStarted();
137 }
138
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalCheckinIOError)139 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalCheckinIOError) {
140 std::string error_message = "Network error";
141 std::string expected_error_message = absl::StrCat(
142 "Error during eligibility check-in: code: 3, error: ", error_message);
143 InSequence seq;
144 EXPECT_CALL(mock_event_publisher_,
145 PublishEligibilityEvalCheckinIoError(expected_error_message,
146 network_stats_, _));
147 EXPECT_CALL(
148 mock_opstats_logger_,
149 AddEventWithErrorMessage(
150 OperationalStats::Event::EVENT_KIND_ELIGIBILITY_CHECKIN_ERROR_IO,
151 expected_error_message));
152
153 VerifyCounterLogged(
154 HistogramCounters::TRAINING_FL_ELIGIBILITY_EVAL_CHECKIN_LATENCY, Ge(0));
155 phase_logger_->LogEligibilityEvalCheckinIOError(
156 absl::InvalidArgumentError(error_message), network_stats_, absl::Now());
157 }
158
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalCheckinClientInterrupted)159 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalCheckinClientInterrupted) {
160 std::string error_message = "Client is not idle";
161 std::string expected_error_message = absl::StrCat(
162 "Error during eligibility check-in: code: 1, error: ", error_message);
163 InSequence seq;
164 EXPECT_CALL(mock_event_publisher_,
165 PublishEligibilityEvalCheckinClientInterrupted(
166 expected_error_message, network_stats_, _));
167 EXPECT_CALL(mock_opstats_logger_,
168 AddEventWithErrorMessage(
169 OperationalStats::Event::
170 EVENT_KIND_ELIGIBILITY_CHECKIN_CLIENT_INTERRUPTED,
171 expected_error_message));
172 VerifyCounterLogged(
173 HistogramCounters::TRAINING_FL_ELIGIBILITY_EVAL_CHECKIN_LATENCY, Ge(0));
174
175 phase_logger_->LogEligibilityEvalCheckinClientInterrupted(
176 absl::CancelledError(error_message), network_stats_, absl::Now());
177 }
178
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalCheckinServerAborted)179 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalCheckinServerAborted) {
180 std::string error_message = "Connection aborted by the server";
181 std::string expected_error_message = absl::StrCat(
182 "Error during eligibility check-in: code: 10, error: ", error_message);
183 InSequence seq;
184 EXPECT_CALL(mock_event_publisher_,
185 PublishEligibilityEvalCheckinServerAborted(expected_error_message,
186 network_stats_, _));
187 EXPECT_CALL(mock_opstats_logger_,
188 AddEventWithErrorMessage(
189 OperationalStats::Event::
190 EVENT_KIND_ELIGIBILITY_CHECKIN_SERVER_ABORTED,
191 expected_error_message));
192 VerifyCounterLogged(
193 HistogramCounters::TRAINING_FL_ELIGIBILITY_EVAL_CHECKIN_LATENCY, Ge(0));
194
195 phase_logger_->LogEligibilityEvalCheckinServerAborted(
196 absl::AbortedError(error_message), network_stats_, absl::Now());
197 }
198
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalNotConfigured)199 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalNotConfigured) {
200 InSequence seq;
201 EXPECT_CALL(mock_event_publisher_,
202 PublishEligibilityEvalNotConfigured(network_stats_, _));
203 EXPECT_CALL(
204 mock_opstats_logger_,
205 AddEvent(OperationalStats::Event::EVENT_KIND_ELIGIBILITY_DISABLED));
206 VerifyCounterLogged(
207 HistogramCounters::TRAINING_FL_ELIGIBILITY_EVAL_CHECKIN_LATENCY, Ge(0));
208
209 phase_logger_->LogEligibilityEvalNotConfigured(network_stats_, absl::Now());
210 }
211
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalCheckinTurnedAway)212 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalCheckinTurnedAway) {
213 InSequence seq;
214 EXPECT_CALL(mock_event_publisher_,
215 PublishEligibilityEvalRejected(network_stats_, _));
216 EXPECT_CALL(
217 mock_opstats_logger_,
218 AddEvent(OperationalStats::Event::EVENT_KIND_ELIGIBILITY_REJECTED));
219 VerifyCounterLogged(
220 HistogramCounters::TRAINING_FL_ELIGIBILITY_EVAL_CHECKIN_LATENCY, Ge(0));
221
222 phase_logger_->LogEligibilityEvalCheckinTurnedAway(network_stats_,
223 absl::Now());
224 }
225
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalCheckinInvalidPayloadError)226 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalCheckinInvalidPayloadError) {
227 std::string error_message = "Cannot parse eligibility eval plan";
228 InSequence seq;
229 EXPECT_CALL(
230 mock_log_manager_,
231 LogDiag(
232 ProdDiagCode::
233 BACKGROUND_TRAINING_ELIGIBILITY_EVAL_FAILED_CANNOT_PARSE_PLAN));
234 EXPECT_CALL(mock_event_publisher_,
235 PublishEligibilityEvalCheckinErrorInvalidPayload(
236 error_message, network_stats_, _));
237 EXPECT_CALL(mock_opstats_logger_,
238 AddEventWithErrorMessage(
239 OperationalStats::Event::
240 EVENT_KIND_ELIGIBILITY_CHECKIN_ERROR_INVALID_PAYLOAD,
241 error_message));
242 VerifyCounterLogged(
243 HistogramCounters::TRAINING_FL_ELIGIBILITY_EVAL_CHECKIN_LATENCY, Ge(0));
244
245 phase_logger_->LogEligibilityEvalCheckinInvalidPayloadError(
246 error_message, network_stats_, absl::Now());
247 }
248
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalCheckinPlanUriReceived)249 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalCheckinPlanUriReceived) {
250 EXPECT_CALL(
251 mock_opstats_logger_,
252 AddEvent(
253 OperationalStats::Event::EVENT_KIND_ELIGIBILITY_PLAN_URI_RECEIVED));
254 EXPECT_CALL(mock_event_publisher_,
255 PublishEligibilityEvalPlanUriReceived(
256 network_stats_,
257 AllOf(Ge(absl::Minutes(1)),
258 Lt(absl::Minutes(1) + absl::Milliseconds(10)))));
259
260 phase_logger_->LogEligibilityEvalCheckinPlanUriReceived(
261 network_stats_, absl::Now() - absl::Minutes(1));
262 }
263
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalCheckinCompleted)264 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalCheckinCompleted) {
265 NetworkStats network_stats{.bytes_downloaded = 100,
266 .bytes_uploaded = 200,
267 .network_duration = absl::Seconds(40)};
268
269 absl::Duration expected_duration = absl::Minutes(1);
270
271 InSequence seq;
272 EXPECT_CALL(
273 mock_opstats_logger_,
274 AddEvent(OperationalStats::Event::EVENT_KIND_ELIGIBILITY_ENABLED));
275 EXPECT_CALL(mock_event_publisher_,
276 PublishEligibilityEvalPlanReceived(
277 network_stats,
278 AllOf(Ge(expected_duration),
279 Lt(expected_duration + absl::Milliseconds(10)))));
280 // The counter should always log the full duration, from before the start of
281 // the checkin (regardless of the enable_plan_uri_received_logs_ flag).
282 VerifyCounterLogged(
283 HistogramCounters::TRAINING_FL_ELIGIBILITY_EVAL_CHECKIN_LATENCY,
284 absl::ToInt64Milliseconds(absl::Minutes(2)));
285
286 phase_logger_->LogEligibilityEvalCheckinCompleted(
287 network_stats,
288 /*time_before_checkin=*/absl::Now() - absl::Minutes(2),
289 /*time_before_plan_downloaded=*/absl::Now() - absl::Minutes(1));
290 }
291
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalComputationStarted)292 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalComputationStarted) {
293 InSequence seq;
294 EXPECT_CALL(mock_event_publisher_,
295 PublishEligibilityEvalComputationStarted());
296 EXPECT_CALL(
297 mock_opstats_logger_,
298 AddEvent(
299 OperationalStats::Event::EVENT_KIND_ELIGIBILITY_COMPUTATION_STARTED));
300
301 phase_logger_->LogEligibilityEvalComputationStarted();
302 }
303
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalComputationInvalidArgument)304 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalComputationInvalidArgument) {
305 std::string error_message = "Invalid plan.";
306 std::string expected_error_message = absl::StrCat(
307 "Error during eligibility eval computation: code: 3, error: ",
308 error_message);
309 InSequence seq;
310 EXPECT_CALL(
311 mock_log_manager_,
312 LogDiag(
313 ProdDiagCode::BACKGROUND_TRAINING_FAILED_PLAN_FAILS_SANITY_CHECK));
314 EXPECT_CALL(mock_event_publisher_,
315 PublishEligibilityEvalComputationInvalidArgument(
316 expected_error_message, example_stats_, _));
317 EXPECT_CALL(mock_opstats_logger_,
318 AddEventWithErrorMessage(
319 OperationalStats::Event::
320 EVENT_KIND_ELIGIBILITY_COMPUTATION_ERROR_INVALID_ARGUMENT,
321 expected_error_message));
322 phase_logger_->LogEligibilityEvalComputationInvalidArgument(
323 absl::InvalidArgumentError(error_message), example_stats_, absl::Now());
324 }
325
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalComputationExampleIteratorError)326 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalComputationExampleIteratorError) {
327 std::string original_message = "Failed to create example iterator";
328 absl::Status error_status = absl::InvalidArgumentError(original_message);
329 std::string expected_error_message = absl::StrCat(
330 "Error during eligibility eval computation: code: 3, error: ",
331 original_message);
332 InSequence seq;
333 EXPECT_CALL(mock_event_publisher_,
334 PublishEligibilityEvalComputationExampleIteratorError(
335 expected_error_message, example_stats_, _));
336 EXPECT_CALL(mock_opstats_logger_,
337 AddEventWithErrorMessage(
338 OperationalStats::Event::
339 EVENT_KIND_ELIGIBILITY_COMPUTATION_ERROR_EXAMPLE_ITERATOR,
340 expected_error_message));
341
342 phase_logger_->LogEligibilityEvalComputationExampleIteratorError(
343 error_status, example_stats_, absl::Now());
344 }
345
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalComputationTensorflowError)346 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalComputationTensorflowError) {
347 std::string original_message = "Missing kernel for op NotExist";
348 absl::Status error_status = absl::InvalidArgumentError(original_message);
349 std::string expected_error_message = absl::StrCat(
350 "Error during eligibility eval computation: code: 3, error: ");
351 if (log_tensorflow_error_messages_) {
352 absl::StrAppend(&expected_error_message, original_message);
353 }
354 InSequence seq;
355 EXPECT_CALL(mock_event_publisher_,
356 PublishEligibilityEvalComputationTensorflowError(
357 expected_error_message, example_stats_, _));
358 EXPECT_CALL(mock_opstats_logger_,
359 AddEventWithErrorMessage(
360 OperationalStats::Event::
361 EVENT_KIND_ELIGIBILITY_COMPUTATION_ERROR_TENSORFLOW,
362 expected_error_message));
363 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_LATENCY, Ge(0));
364 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_END_TIME, Ge(0));
365 phase_logger_->LogEligibilityEvalComputationTensorflowError(
366 error_status, example_stats_, absl::Now() - absl::Minutes(2),
367 absl::Now() - absl::Minutes(5));
368 }
369
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalComputationInterrupted)370 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalComputationInterrupted) {
371 std::string error_message = "Client is no longer idle";
372 std::string expected_error_message = absl::StrCat(
373 "Error during eligibility eval computation: code: 1, error: ",
374 error_message);
375 InSequence seq;
376 EXPECT_CALL(mock_event_publisher_,
377 PublishEligibilityEvalComputationInterrupted(
378 expected_error_message, example_stats_, _));
379 EXPECT_CALL(mock_opstats_logger_,
380 AddEventWithErrorMessage(
381 OperationalStats::Event::
382 EVENT_KIND_ELIGIBILITY_COMPUTATION_CLIENT_INTERRUPTED,
383 expected_error_message));
384 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_LATENCY, Ge(0));
385 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_END_TIME, Ge(0));
386
387 phase_logger_->LogEligibilityEvalComputationInterrupted(
388 absl::CancelledError(error_message), example_stats_,
389 absl::Now() - absl::Minutes(2), absl::Now() - absl::Minutes(5));
390 }
391
TEST_P(PhaseLoggerImplTest,LogEligibilityEvalComputationCompleted)392 TEST_P(PhaseLoggerImplTest, LogEligibilityEvalComputationCompleted) {
393 absl::Time run_plan_start_time = absl::Now() - absl::Minutes(8);
394 absl::Time reference_time = absl::Now() - absl::Minutes(9);
395 InSequence seq;
396 EXPECT_CALL(mock_event_publisher_,
397 PublishEligibilityEvalComputationCompleted(example_stats_, _));
398 EXPECT_CALL(mock_opstats_logger_,
399 AddEvent(OperationalStats::Event::
400 EVENT_KIND_ELIGIBILITY_COMPUTATION_FINISHED));
401 VerifyCounterLogged(HistogramCounters::TRAINING_OVERALL_EXAMPLE_SIZE,
402 kTotalExampleSizeBytes);
403 VerifyCounterLogged(HistogramCounters::TRAINING_OVERALL_EXAMPLE_COUNT,
404 kTotalExampleCount);
405 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_LATENCY, Ge(0));
406 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_END_TIME, Ge(0));
407
408 phase_logger_->LogEligibilityEvalComputationCompleted(
409 example_stats_, run_plan_start_time, reference_time);
410 }
411
TEST_P(PhaseLoggerImplTest,LogCheckinStarted)412 TEST_P(PhaseLoggerImplTest, LogCheckinStarted) {
413 InSequence seq;
414 EXPECT_CALL(mock_event_publisher_, PublishCheckin());
415 EXPECT_CALL(mock_opstats_logger_,
416 AddEvent(OperationalStats::Event::EVENT_KIND_CHECKIN_STARTED));
417 phase_logger_->LogCheckinStarted();
418 }
419
TEST_P(PhaseLoggerImplTest,LogCheckinIOError)420 TEST_P(PhaseLoggerImplTest, LogCheckinIOError) {
421 std::string error_message = "IO error";
422 std::string expected_error_message =
423 absl::StrCat("Error during check-in: code: 14, error: ", error_message);
424 InSequence seq;
425 EXPECT_CALL(mock_event_publisher_,
426 PublishCheckinIoError(expected_error_message, network_stats_, _));
427 EXPECT_CALL(mock_opstats_logger_,
428 AddEventWithErrorMessage(
429 OperationalStats::Event::EVENT_KIND_CHECKIN_ERROR_IO,
430 expected_error_message));
431 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_LATENCY, Ge(0));
432 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_END_TIME, Ge(0));
433
434 phase_logger_->LogCheckinIOError(
435 absl::UnavailableError(error_message), network_stats_,
436 absl::Now() - absl::Minutes(2), absl::Now() - absl::Minutes(8));
437 }
438
TEST_P(PhaseLoggerImplTest,LogCheckinClientInterrupted)439 TEST_P(PhaseLoggerImplTest, LogCheckinClientInterrupted) {
440 std::string error_message = "The client is no longer idle";
441 std::string expected_error_message =
442 absl::StrCat("Error during check-in: code: 1, error: ", error_message);
443 InSequence seq;
444 EXPECT_CALL(mock_event_publisher_,
445 PublishCheckinClientInterrupted(expected_error_message,
446 network_stats_, _));
447 EXPECT_CALL(
448 mock_opstats_logger_,
449 AddEventWithErrorMessage(
450 OperationalStats::Event::EVENT_KIND_CHECKIN_CLIENT_INTERRUPTED,
451 expected_error_message));
452 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_LATENCY, Ge(0));
453 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_END_TIME, Ge(0));
454
455 phase_logger_->LogCheckinClientInterrupted(
456 absl::CancelledError(error_message), network_stats_,
457 absl::Now() - absl::Minutes(2), absl::Now() - absl::Minutes(8));
458 }
459
TEST_P(PhaseLoggerImplTest,LogCheckinServerAborted)460 TEST_P(PhaseLoggerImplTest, LogCheckinServerAborted) {
461 std::string error_message = "The request is aborted by the server";
462 std::string expected_error_message =
463 absl::StrCat("Error during check-in: code: 10, error: ", error_message);
464 InSequence seq;
465 EXPECT_CALL(
466 mock_event_publisher_,
467 PublishCheckinServerAborted(expected_error_message, network_stats_, _));
468 EXPECT_CALL(mock_opstats_logger_,
469 AddEventWithErrorMessage(
470 OperationalStats::Event::EVENT_KIND_CHECKIN_SERVER_ABORTED,
471 expected_error_message));
472
473 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_LATENCY, Ge(0));
474 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_END_TIME, Ge(0));
475
476 phase_logger_->LogCheckinServerAborted(
477 absl::AbortedError(error_message), network_stats_,
478 absl::Now() - absl::Minutes(2), absl::Now() - absl::Minutes(8));
479 }
480
TEST_P(PhaseLoggerImplTest,LogCheckinTurnedAway)481 TEST_P(PhaseLoggerImplTest, LogCheckinTurnedAway) {
482 InSequence seq;
483 EXPECT_CALL(mock_event_publisher_, PublishRejected(network_stats_, _));
484 EXPECT_CALL(mock_opstats_logger_,
485 AddEvent(OperationalStats::Event::EVENT_KIND_CHECKIN_REJECTED));
486 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_LATENCY, Ge(0));
487 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_END_TIME, Ge(0));
488
489 phase_logger_->LogCheckinTurnedAway(network_stats_,
490 absl::Now() - absl::Minutes(2),
491 absl::Now() - absl::Minutes(8));
492 }
493
TEST_P(PhaseLoggerImplTest,LogCheckinInvalidPayload)494 TEST_P(PhaseLoggerImplTest, LogCheckinInvalidPayload) {
495 std::string error_message = "Cannot parse plan";
496 InSequence seq;
497 EXPECT_CALL(
498 mock_log_manager_,
499 LogDiag(ProdDiagCode::BACKGROUND_TRAINING_FAILED_CANNOT_PARSE_PLAN));
500 EXPECT_CALL(mock_event_publisher_,
501 PublishCheckinInvalidPayload(error_message, network_stats_, _));
502 EXPECT_CALL(
503 mock_opstats_logger_,
504 AddEventWithErrorMessage(
505 OperationalStats::Event::EVENT_KIND_CHECKIN_ERROR_INVALID_PAYLOAD,
506 error_message));
507 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_LATENCY, Ge(0));
508 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_END_TIME, Ge(0));
509
510 phase_logger_->LogCheckinInvalidPayload(error_message, network_stats_,
511 absl::Now() - absl::Minutes(2),
512 absl::Now() - absl::Minutes(8));
513 }
514
TEST_P(PhaseLoggerImplTest,LogCheckinPlanUriReceived)515 TEST_P(PhaseLoggerImplTest, LogCheckinPlanUriReceived) {
516 std::string task_name = "my_task";
517 EXPECT_CALL(mock_event_publisher_,
518 PublishCheckinPlanUriReceived(
519 network_stats_,
520 AllOf(Ge(absl::Minutes(1)),
521 Lt(absl::Minutes(1) + absl::Milliseconds(10)))));
522 EXPECT_CALL(
523 mock_opstats_logger_,
524 AddEventAndSetTaskName(
525 task_name,
526 OperationalStats::Event::EVENT_KIND_CHECKIN_PLAN_URI_RECEIVED));
527
528 phase_logger_->LogCheckinPlanUriReceived(task_name, network_stats_,
529 absl::Now() - absl::Minutes(1));
530 }
531
TEST_P(PhaseLoggerImplTest,LogCheckinCompleted)532 TEST_P(PhaseLoggerImplTest, LogCheckinCompleted) {
533 NetworkStats network_stats{.bytes_downloaded = 100,
534 .bytes_uploaded = 200,
535 .network_duration = absl::Seconds(40)};
536
537 absl::Duration expected_duration = absl::Minutes(1);
538
539 std::string task_name = "my_task";
540 InSequence seq;
541 EXPECT_CALL(mock_event_publisher_,
542 PublishCheckinFinishedV2(
543 network_stats,
544 AllOf(Ge(expected_duration),
545 Lt(expected_duration + absl::Milliseconds(10)))));
546 EXPECT_CALL(mock_opstats_logger_,
547 AddEvent(OperationalStats::Event::EVENT_KIND_CHECKIN_ACCEPTED));
548 // The counter should always log the full duration, from before the start of
549 // the checkin.
550 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_LATENCY,
551 AllOf(Ge(absl::ToInt64Milliseconds(absl::Minutes(2))),
552 Lt(absl::ToInt64Milliseconds(
553 absl::Minutes(2) + absl::Milliseconds(100)))));
554 VerifyCounterLogged(HistogramCounters::TRAINING_FL_CHECKIN_END_TIME,
555 AllOf(Ge(absl::ToInt64Milliseconds(absl::Minutes(8))),
556 Lt(absl::ToInt64Milliseconds(
557 absl::Minutes(8) + absl::Milliseconds(100)))));
558
559 phase_logger_->LogCheckinCompleted(
560 task_name, network_stats,
561 /*time_before_checkin=*/absl::Now() - absl::Minutes(2),
562 /*time_before_plan_download=*/absl::Now() - absl::Minutes(1),
563 /*reference_time=*/absl::Now() - absl::Minutes(8));
564 }
565
TEST_P(PhaseLoggerImplTest,LogComputationStarted)566 TEST_P(PhaseLoggerImplTest, LogComputationStarted) {
567 InSequence seq;
568 EXPECT_CALL(mock_event_publisher_, PublishComputationStarted());
569 EXPECT_CALL(
570 mock_opstats_logger_,
571 AddEvent(OperationalStats::Event::EVENT_KIND_COMPUTATION_STARTED));
572 phase_logger_->LogComputationStarted();
573 }
574
TEST_P(PhaseLoggerImplTest,LogComputationInvalidArgument)575 TEST_P(PhaseLoggerImplTest, LogComputationInvalidArgument) {
576 std::string error_message = "Unexpected input tensor";
577 std::string expected_error_message =
578 absl::StrCat("Error during computation: code: 3, error: ", error_message);
579 InSequence seq;
580 EXPECT_CALL(
581 mock_log_manager_,
582 LogDiag(
583 ProdDiagCode::BACKGROUND_TRAINING_FAILED_PLAN_FAILS_SANITY_CHECK));
584 EXPECT_CALL(mock_event_publisher_,
585 PublishComputationInvalidArgument(
586 expected_error_message, example_stats_, network_stats_, _));
587 EXPECT_CALL(mock_opstats_logger_,
588 AddEventWithErrorMessage(
589 OperationalStats::Event::
590 EVENT_KIND_COMPUTATION_ERROR_INVALID_ARGUMENT,
591 expected_error_message));
592 phase_logger_->LogComputationInvalidArgument(
593 absl::InvalidArgumentError(error_message), example_stats_, network_stats_,
594 absl::Now());
595 }
596
TEST_P(PhaseLoggerImplTest,LogComputationIOError)597 TEST_P(PhaseLoggerImplTest, LogComputationIOError) {
598 std::string error_message = "IO error";
599 std::string expected_error_message =
600 absl::StrCat("Error during computation: code: 3, error: ", error_message);
601 InSequence seq;
602 EXPECT_CALL(mock_event_publisher_,
603 PublishComputationIOError(expected_error_message, example_stats_,
604 network_stats_, _));
605 EXPECT_CALL(mock_opstats_logger_,
606 AddEventWithErrorMessage(
607 OperationalStats::Event::EVENT_KIND_COMPUTATION_ERROR_IO,
608 expected_error_message));
609 phase_logger_->LogComputationIOError(
610 absl::InvalidArgumentError(error_message), example_stats_, network_stats_,
611 absl::Now());
612 }
613
TEST_P(PhaseLoggerImplTest,LogComputationExampleIteratorError)614 TEST_P(PhaseLoggerImplTest, LogComputationExampleIteratorError) {
615 std::string original_message = "Cannot create example iterator";
616 absl::Status error_status = absl::InvalidArgumentError(original_message);
617 std::string expected_error_message = absl::StrCat(
618 "Error during computation: code: 3, error: ", original_message);
619 InSequence seq;
620 EXPECT_CALL(mock_event_publisher_,
621 PublishComputationExampleIteratorError(
622 expected_error_message, example_stats_, network_stats_, _));
623 EXPECT_CALL(mock_opstats_logger_,
624 AddEventWithErrorMessage(
625 OperationalStats::Event::
626 EVENT_KIND_COMPUTATION_ERROR_EXAMPLE_ITERATOR,
627 expected_error_message));
628 phase_logger_->LogComputationExampleIteratorError(
629 error_status, example_stats_, network_stats_, absl::Now());
630 }
631
TEST_P(PhaseLoggerImplTest,LogComputationTensorflowError)632 TEST_P(PhaseLoggerImplTest, LogComputationTensorflowError) {
633 std::string original_message = "Missing op kernel NotExist";
634 absl::Status error_status = absl::InvalidArgumentError(original_message);
635 std::string expected_error_message =
636 absl::StrCat("Error during computation: code: 3, error: ");
637 if (log_tensorflow_error_messages_) {
638 absl::StrAppend(&expected_error_message, original_message);
639 }
640 InSequence seq;
641 EXPECT_CALL(mock_event_publisher_,
642 PublishComputationTensorflowError(
643 expected_error_message, example_stats_, network_stats_, _));
644 EXPECT_CALL(
645 mock_opstats_logger_,
646 AddEventWithErrorMessage(
647 OperationalStats::Event::EVENT_KIND_COMPUTATION_ERROR_TENSORFLOW,
648 expected_error_message));
649 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_LATENCY, Ge(0));
650 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_END_TIME, Ge(0));
651 phase_logger_->LogComputationTensorflowError(
652 error_status, example_stats_, network_stats_,
653 absl::Now() - absl::Minutes(6), absl::Now() - absl::Minutes(8));
654 }
655
TEST_P(PhaseLoggerImplTest,LogComputationInterrupted)656 TEST_P(PhaseLoggerImplTest, LogComputationInterrupted) {
657 absl::Time run_plan_start_time = absl::Now() - absl::Minutes(6);
658 absl::Time reference_time = absl::Now() - absl::Minutes(8);
659 std::string error_message = "Client is no longer idle.";
660 std::string expected_error_message =
661 absl::StrCat("Error during computation: code: 1, error: ", error_message);
662 InSequence seq;
663 EXPECT_CALL(mock_event_publisher_,
664 PublishComputationInterrupted(expected_error_message,
665 example_stats_, network_stats_, _));
666 EXPECT_CALL(
667 mock_opstats_logger_,
668 AddEventWithErrorMessage(
669 OperationalStats::Event::EVENT_KIND_COMPUTATION_CLIENT_INTERRUPTED,
670 expected_error_message));
671
672 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_LATENCY, Ge(0));
673 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_END_TIME, Ge(0));
674
675 phase_logger_->LogComputationInterrupted(absl::CancelledError(error_message),
676 example_stats_, network_stats_,
677 run_plan_start_time, reference_time);
678 }
679
TEST_P(PhaseLoggerImplTest,LogComputationCompleted)680 TEST_P(PhaseLoggerImplTest, LogComputationCompleted) {
681 absl::Time run_plan_start_time = absl::Now() - absl::Minutes(6);
682 absl::Time reference_time = absl::Now() - absl::Minutes(8);
683 InSequence seq;
684 EXPECT_CALL(mock_event_publisher_,
685 PublishComputationCompleted(example_stats_, network_stats_,
686 Ge(absl::Minutes(6))));
687 EXPECT_CALL(
688 mock_opstats_logger_,
689 AddEvent(OperationalStats::Event::EVENT_KIND_COMPUTATION_FINISHED));
690 VerifyCounterLogged(HistogramCounters::TRAINING_OVERALL_EXAMPLE_SIZE,
691 kTotalExampleSizeBytes);
692 VerifyCounterLogged(HistogramCounters::TRAINING_OVERALL_EXAMPLE_COUNT,
693 kTotalExampleCount);
694 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_LATENCY,
695 Ge(absl::ToInt64Milliseconds(absl::Minutes(6))));
696 VerifyCounterLogged(HistogramCounters::TRAINING_RUN_PHASE_END_TIME,
697 Ge(absl::ToInt64Milliseconds(absl::Minutes(8))));
698
699 phase_logger_->LogComputationCompleted(example_stats_, network_stats_,
700 run_plan_start_time, reference_time);
701 }
702
TEST_P(PhaseLoggerImplTest,LogResultUploadStartedOpStatsDbCommitSucceeds)703 TEST_P(PhaseLoggerImplTest, LogResultUploadStartedOpStatsDbCommitSucceeds) {
704 InSequence seq;
705 EXPECT_CALL(
706 mock_opstats_logger_,
707 AddEvent(OperationalStats::Event::EVENT_KIND_RESULT_UPLOAD_STARTED));
708 EXPECT_CALL(mock_opstats_logger_, CommitToStorage)
709 .WillOnce(Return(absl::OkStatus()));
710 EXPECT_CALL(mock_event_publisher_, PublishResultUploadStarted());
711
712 ASSERT_OK(phase_logger_->LogResultUploadStarted());
713 }
714
TEST_P(PhaseLoggerImplTest,LogResultUploadStartedOpStatsDbCommitFails)715 TEST_P(PhaseLoggerImplTest, LogResultUploadStartedOpStatsDbCommitFails) {
716 InSequence seq;
717 EXPECT_CALL(
718 mock_opstats_logger_,
719 AddEvent(OperationalStats::Event::EVENT_KIND_RESULT_UPLOAD_STARTED));
720 EXPECT_CALL(mock_opstats_logger_, CommitToStorage)
721 .WillOnce(Return(absl::InternalError("")));
722
723 ASSERT_THAT(phase_logger_->LogResultUploadStarted(),
724 IsCode(absl::StatusCode::kInternal));
725 }
726
TEST_P(PhaseLoggerImplTest,LogResultUploadIOError)727 TEST_P(PhaseLoggerImplTest, LogResultUploadIOError) {
728 std::string error_message = "Network IO";
729 std::string expected_error_message =
730 absl::StrCat("Error reporting results: code: 14, error: ", error_message);
731 InSequence seq;
732 EXPECT_CALL(
733 mock_event_publisher_,
734 PublishResultUploadIOError(expected_error_message, network_stats_, _));
735 EXPECT_CALL(mock_opstats_logger_,
736 AddEventWithErrorMessage(
737 OperationalStats::Event::EVENT_KIND_RESULT_UPLOAD_ERROR_IO,
738 expected_error_message));
739 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_LATENCY,
740 Ge(0));
741 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_END_TIME,
742 Ge(0));
743 phase_logger_->LogResultUploadIOError(
744 absl::UnavailableError(error_message), network_stats_,
745 absl::Now() - absl::Minutes(1), absl::Now() - absl::Minutes(8));
746 }
747
TEST_P(PhaseLoggerImplTest,LogResultUploadClientInterrupted)748 TEST_P(PhaseLoggerImplTest, LogResultUploadClientInterrupted) {
749 std::string error_message = "Client is no longer idle";
750 std::string expected_error_message =
751 absl::StrCat("Error reporting results: code: 1, error: ", error_message);
752 InSequence seq;
753 EXPECT_CALL(mock_event_publisher_,
754 PublishResultUploadClientInterrupted(expected_error_message,
755 network_stats_, _));
756 EXPECT_CALL(
757 mock_opstats_logger_,
758 AddEventWithErrorMessage(
759 OperationalStats::Event::EVENT_KIND_RESULT_UPLOAD_CLIENT_INTERRUPTED,
760 expected_error_message));
761 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_LATENCY,
762 Ge(0));
763 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_END_TIME,
764 Ge(0));
765
766 phase_logger_->LogResultUploadClientInterrupted(
767 absl::CancelledError(error_message), network_stats_,
768 absl::Now() - absl::Minutes(1), absl::Now() - absl::Minutes(8));
769 }
770
TEST_P(PhaseLoggerImplTest,LogResultUploadServerAborted)771 TEST_P(PhaseLoggerImplTest, LogResultUploadServerAborted) {
772 std::string error_message = "Request is aborted by the server";
773 std::string expected_error_message =
774 absl::StrCat("Error reporting results: code: 10, error: ", error_message);
775 InSequence seq;
776 EXPECT_CALL(mock_event_publisher_,
777 PublishResultUploadServerAborted(expected_error_message,
778 network_stats_, _));
779 EXPECT_CALL(
780 mock_opstats_logger_,
781 AddEventWithErrorMessage(
782 OperationalStats::Event::EVENT_KIND_RESULT_UPLOAD_SERVER_ABORTED,
783 expected_error_message));
784 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_LATENCY,
785 Ge(0));
786 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_END_TIME,
787 Ge(0));
788
789 phase_logger_->LogResultUploadServerAborted(
790 absl::AbortedError(error_message), network_stats_,
791 absl::Now() - absl::Minutes(1), absl::Now() - absl::Minutes(8));
792 }
793
TEST_P(PhaseLoggerImplTest,LogResultUploadCompleted)794 TEST_P(PhaseLoggerImplTest, LogResultUploadCompleted) {
795 InSequence seq;
796 EXPECT_CALL(mock_event_publisher_,
797 PublishResultUploadCompleted(network_stats_, _));
798 EXPECT_CALL(
799 mock_opstats_logger_,
800 AddEvent(OperationalStats::Event::EVENT_KIND_RESULT_UPLOAD_FINISHED));
801 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_LATENCY,
802 Ge(0));
803 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_END_TIME,
804 Ge(0));
805
806 phase_logger_->LogResultUploadCompleted(network_stats_,
807 absl::Now() - absl::Minutes(1),
808 absl::Now() - absl::Minutes(8));
809 }
810
TEST_P(PhaseLoggerImplTest,LogFailureUploadStartedOpstatsDbCommitSucceeds)811 TEST_P(PhaseLoggerImplTest, LogFailureUploadStartedOpstatsDbCommitSucceeds) {
812 InSequence seq;
813 EXPECT_CALL(
814 mock_opstats_logger_,
815 AddEvent(OperationalStats::Event::EVENT_KIND_FAILURE_UPLOAD_STARTED));
816 EXPECT_CALL(mock_opstats_logger_, CommitToStorage())
817 .WillOnce(Return(absl::OkStatus()));
818 EXPECT_CALL(mock_event_publisher_, PublishFailureUploadStarted());
819 ASSERT_OK(phase_logger_->LogFailureUploadStarted());
820 }
821
TEST_P(PhaseLoggerImplTest,LogFailureUploadStartedOpstatsDbCommitFails)822 TEST_P(PhaseLoggerImplTest, LogFailureUploadStartedOpstatsDbCommitFails) {
823 InSequence seq;
824 EXPECT_CALL(
825 mock_opstats_logger_,
826 AddEvent(OperationalStats::Event::EVENT_KIND_FAILURE_UPLOAD_STARTED));
827 EXPECT_CALL(mock_opstats_logger_, CommitToStorage())
828 .WillOnce(Return(absl::InternalError("")));
829 ASSERT_THAT(phase_logger_->LogFailureUploadStarted(),
830 IsCode(absl::StatusCode::kInternal));
831 }
832
TEST_P(PhaseLoggerImplTest,LogFailureUploadIOError)833 TEST_P(PhaseLoggerImplTest, LogFailureUploadIOError) {
834 std::string error_message = "Network error.";
835 std::string expected_error_message = absl::StrCat(
836 "Error reporting computation failure: code: 14, error: ", error_message);
837 InSequence seq;
838 EXPECT_CALL(
839 mock_event_publisher_,
840 PublishFailureUploadIOError(expected_error_message, network_stats_, _));
841 EXPECT_CALL(mock_opstats_logger_,
842 AddEventWithErrorMessage(
843 OperationalStats::Event::EVENT_KIND_FAILURE_UPLOAD_ERROR_IO,
844 expected_error_message));
845 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_LATENCY,
846 Ge(0));
847 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_END_TIME,
848 Ge(0));
849 phase_logger_->LogFailureUploadIOError(
850 absl::UnavailableError(error_message), network_stats_,
851 absl::Now() - absl::Minutes(1), absl::Now() - absl::Minutes(8));
852 }
853
TEST_P(PhaseLoggerImplTest,LogFailureUploadClientInterrupted)854 TEST_P(PhaseLoggerImplTest, LogFailureUploadClientInterrupted) {
855 std::string error_message = "The client is no longer idle";
856 std::string expected_error_message = absl::StrCat(
857 "Error reporting computation failure: code: 1, error: ", error_message);
858 InSequence seq;
859 EXPECT_CALL(mock_event_publisher_,
860 PublishFailureUploadClientInterrupted(expected_error_message,
861 network_stats_, _));
862 EXPECT_CALL(
863 mock_opstats_logger_,
864 AddEventWithErrorMessage(
865 OperationalStats::Event::EVENT_KIND_FAILURE_UPLOAD_CLIENT_INTERRUPTED,
866 expected_error_message));
867 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_LATENCY,
868 Ge(0));
869 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_END_TIME,
870 Ge(0));
871 phase_logger_->LogFailureUploadClientInterrupted(
872 absl::CancelledError(error_message), network_stats_,
873 absl::Now() - absl::Minutes(1), absl::Now() - absl::Minutes(8));
874 }
875
TEST_P(PhaseLoggerImplTest,LogFailureUploadServerAborted)876 TEST_P(PhaseLoggerImplTest, LogFailureUploadServerAborted) {
877 std::string error_message = "Request is aborted by the server.";
878 std::string expected_error_message = absl::StrCat(
879 "Error reporting computation failure: code: 10, error: ", error_message);
880 InSequence seq;
881 EXPECT_CALL(mock_event_publisher_,
882 PublishFailureUploadServerAborted(expected_error_message,
883 network_stats_, _));
884 EXPECT_CALL(
885 mock_opstats_logger_,
886 AddEventWithErrorMessage(
887 OperationalStats::Event::EVENT_KIND_FAILURE_UPLOAD_SERVER_ABORTED,
888 expected_error_message));
889 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_LATENCY,
890 Ge(0));
891 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_END_TIME,
892 Ge(0));
893 phase_logger_->LogFailureUploadServerAborted(
894 absl::AbortedError(error_message), network_stats_,
895 absl::Now() - absl::Minutes(1), absl::Now() - absl::Minutes(8));
896 }
897
TEST_P(PhaseLoggerImplTest,LogFailureUploadCompleted)898 TEST_P(PhaseLoggerImplTest, LogFailureUploadCompleted) {
899 InSequence seq;
900 EXPECT_CALL(mock_event_publisher_,
901 PublishFailureUploadCompleted(network_stats_, _));
902 EXPECT_CALL(
903 mock_opstats_logger_,
904 AddEvent(OperationalStats::Event::EVENT_KIND_FAILURE_UPLOAD_FINISHED));
905 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_LATENCY,
906 Ge(0));
907 VerifyCounterLogged(HistogramCounters::TRAINING_FL_REPORT_RESULTS_END_TIME,
908 Ge(0));
909 phase_logger_->LogFailureUploadCompleted(network_stats_,
910 absl::Now() - absl::Minutes(1),
911 absl::Now() - absl::Minutes(8));
912 }
913
914 } // namespace
915 } // namespace client
916 } // namespace fcp
917