Add ongoing events to net-export log when logging starts

components/net_log/net_log_file_writer_unittest.cc

 // Copyright (c) 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "components/net_log/net_log_file_writer.h"
 
 #include <stdint.h>
 
 #include <memory>
 
@@ skipping 28 matching lines @@
 base::FilePath::CharType kLogRelativePath[] =
     FILE_PATH_LITERAL("net-export/chrome-net-export-log.json");
 
 const char kCaptureModeDefaultString[] = "STRIP_PRIVATE_DATA";
 const char kCaptureModeIncludeCookiesAndCredentialsString[] = "NORMAL";
 const char kCaptureModeIncludeSocketBytesString[] = "LOG_BYTES";
 
 const char kStateUninitializedString[] = "UNINITIALIZED";
 const char kStateInitializingString[] = "INITIALIZING";
 const char kStateNotLoggingString[] = "NOT_LOGGING";
+const char kStateStartingLogString[] = "STARTING_LOG";
 const char kStateLoggingString[] = "LOGGING";
 const char kStateStoppingLogString[] = "STOPPING_LOG";
 }  // namespace
 
 namespace net_log {
 
 // Sets |path| to |path_to_return| and always returns true. This function is
 // used to override NetLogFileWriter's usual getter for the default log base
 // directory.
 bool SetPathToGivenAndReturnTrue(const base::FilePath& path_to_return,
@@ skipping 114 matching lines @@
   params->quic_idle_connection_timeout_seconds =
       quic_idle_connection_timeout_seconds;
 
   context->set_http_network_session_params(std::move(params));
   context->Init();
 
   *context_getter = new net::TestURLRequestContextGetter(
       base::ThreadTaskRunnerHandle::Get(), std::move(context));
 }
 
+void SetUpTestContextGetterWithRequest(
+    net::NetLog* net_log,
+    base::StringPiece request_url,
+    net::URLRequest::Delegate* delegate,
+    scoped_refptr<net::TestURLRequestContextGetter>* context_getter,
+    std::unique_ptr<net::URLRequest>* request) {
+  std::unique_ptr<net::TestURLRequestContext> context =

[eroman, 2017/02/24 00:17:38]

[optional] My preference is to use "auto" with MakeUnique

[wangyix1, 2017/02/24 00:58:07]

Done.

+      base::MakeUnique<net::TestURLRequestContext>(true);
+  context->set_net_log(net_log);
+  context->Init();
+
+  *request = context->CreateRequest(GURL(request_url), net::IDLE, delegate);

[eroman, 2017/02/24 00:17:38]

[optional] I would suggest making |request_url| be of type |const GURL&| instead
of StringPiece, especially given that it is used with base::Bind().

(It is possible with StringPiece to end up with invalid pointers by the time the
task runs, since it doesn't own the memory).

[wangyix1, 2017/02/24 00:58:08]

Done.

+  (*request)->Start();
+
+  *context_getter = new net::TestURLRequestContextGetter(
+      base::ThreadTaskRunnerHandle::Get(), std::move(context));
+}
+
 // An implementation of NetLogFileWriter::StateObserver that allows waiting
 // until it's notified of a new state.
 class TestStateObserver : public NetLogFileWriter::StateObserver {
  public:
   // NetLogFileWriter::StateObserver implementation
   void OnNewState(const base::DictionaryValue& state) override {
     test_closure_.closure().Run();
     result_state_ = state.CreateDeepCopy();
   }
 
@@ skipping 31 matching lines @@
     test_closure_.closure().Run();
   }
 
   net::TestClosure test_closure_;
   base::FilePath result_;
   base::Callback<void(const base::FilePath&)> callback_;
 };
 
 class NetLogFileWriterTest : public ::testing::Test {
  public:
+  using URLRequestContextGetterList =
+      std::vector<scoped_refptr<net::URLRequestContextGetter>>;
+
   NetLogFileWriterTest()
       : net_log_(base::FilePath(),
                  net::NetLogCaptureMode::Default(),
                  base::CommandLine::ForCurrentProcess()->GetCommandLineString(),
                  kChannelString),
         net_log_file_writer_(
             &net_log_,
             base::CommandLine::ForCurrentProcess()->GetCommandLineString(),
             kChannelString),
         file_thread_("NetLogFileWriter file thread"),
@@ skipping 57 matching lines @@
              << "Second state after Initialize() does not match expected:"
              << std::endl
              << result.message();
     }
 
     return ::testing::AssertionSuccess();
   }
 
   // If |custom_log_path| is empty path, |net_log_file_writer_| will use its
   // default log path, which is cached in |default_log_path_|.
-  WARN_UNUSED_RESULT ::testing::AssertionResult StartThenVerifyNewState(
+  WARN_UNUSED_RESULT::testing::AssertionResult StartThenVerifyNewState(
       const base::FilePath& custom_log_path,
       net::NetLogCaptureMode capture_mode,
-      const std::string& expected_capture_mode_string) {
-    net_log_file_writer_.StartNetLog(custom_log_path, capture_mode);
+      const std::string& expected_capture_mode_string,
+      const URLRequestContextGetterList& context_getters) {
+    net_log_file_writer_.StartNetLog(custom_log_path, capture_mode,
+                                     context_getters);
     std::unique_ptr<base::DictionaryValue> state =
         test_state_observer_.WaitForNewState();
     ::testing::AssertionResult result =
-        VerifyState(std::move(state), kStateLoggingString, true, true,
-                    expected_capture_mode_string);
+        VerifyState(std::move(state), kStateStartingLogString);
     if (!result) {
       return ::testing::AssertionFailure()
              << "First state after StartNetLog() does not match expected:"
              << std::endl
              << result.message();
     }
 
+    state = test_state_observer_.WaitForNewState();
+    result = VerifyState(std::move(state), kStateLoggingString, true, true,
+                         expected_capture_mode_string);
+    if (!result) {
+      return ::testing::AssertionFailure()
+             << "Second state after StartNetLog() does not match expected:"
+             << std::endl
+             << result.message();
+    }
+
     // Make sure GetFilePath() returns empty path when logging.
     base::FilePath actual_log_path = FileWriterGetFilePathToCompletedLog();
     if (!actual_log_path.empty()) {
       return ::testing::AssertionFailure()
              << "GetFilePath() should return empty path after logging starts."
              << " Actual: " << ::testing::PrintToString(actual_log_path);
     }
 
     return ::testing::AssertionSuccess();
   }
@@ skipping 118 matching lines @@
   const std::string capture_mode_strings[3] = {
       kCaptureModeDefaultString, kCaptureModeIncludeCookiesAndCredentialsString,
       kCaptureModeIncludeSocketBytesString};
 
   ASSERT_TRUE(InitializeThenVerifyNewState(true, false));
 
   // For each capture mode, start and stop |net_log_file_writer_| in that mode.
   for (int i = 0; i < 3; ++i) {
     // StartNetLog(), should result in state change.
     ASSERT_TRUE(StartThenVerifyNewState(base::FilePath(), capture_modes[i],
-                                        capture_mode_strings[i]));
+                                        capture_mode_strings[i], {}));
 
     // Calling StartNetLog() again should be a no-op. Try doing StartNetLog()
     // with various capture modes; they should all be ignored and result in no
     // state change.
-    net_log_file_writer_.StartNetLog(base::FilePath(), capture_modes[i]);
+    net_log_file_writer_.StartNetLog(base::FilePath(), capture_modes[i], {});
     net_log_file_writer_.StartNetLog(base::FilePath(),
-                                     capture_modes[(i + 1) % 3]);
+                                     capture_modes[(i + 1) % 3], {});
     net_log_file_writer_.StartNetLog(base::FilePath(),
-                                     capture_modes[(i + 2) % 3]);
+                                     capture_modes[(i + 2) % 3], {});
 
     // StopNetLog(), should result in state change. The capture mode should
     // match that of the first StartNetLog() call (called by
     // StartThenVerifyNewState()).
     ASSERT_TRUE(StopThenVerifyNewStateAndFile(
         base::FilePath(), nullptr, nullptr, capture_mode_strings[i]));
 
     // Stopping a second time should be a no-op.
     net_log_file_writer_.StopNetLog(nullptr, nullptr);
   }
 
   // Start and stop one more time just to make sure the last StopNetLog() call
   // was properly ignored and left |net_log_file_writer_| in a valid state.
   ASSERT_TRUE(StartThenVerifyNewState(base::FilePath(), capture_modes[0],
-                                      capture_mode_strings[0]));
+                                      capture_mode_strings[0], {}));
 
   ASSERT_TRUE(StopThenVerifyNewStateAndFile(base::FilePath(), nullptr, nullptr,
                                             capture_mode_strings[0]));
 }
 
 // Verify the file sizes after two consecutive starts/stops are the same (even
 // if some junk data is added in between).
 TEST_F(NetLogFileWriterTest, StartClearsFile) {
   ASSERT_TRUE(InitializeThenVerifyNewState(true, false));
 
   ASSERT_TRUE(StartThenVerifyNewState(base::FilePath(),
                                       net::NetLogCaptureMode::Default(),
-                                      kCaptureModeDefaultString));
+                                      kCaptureModeDefaultString, {}));
 
   ASSERT_TRUE(StopThenVerifyNewStateAndFile(base::FilePath(), nullptr, nullptr,
                                             kCaptureModeDefaultString));
 
   int64_t stop_file_size;
   EXPECT_TRUE(base::GetFileSize(default_log_path_, &stop_file_size));
 
   // Add some junk at the end of the file.
   std::string junk_data("Hello");
   EXPECT_TRUE(base::AppendToFile(default_log_path_, junk_data.c_str(),
                                  junk_data.size()));
 
   int64_t junk_file_size;
   EXPECT_TRUE(base::GetFileSize(default_log_path_, &junk_file_size));
   EXPECT_GT(junk_file_size, stop_file_size);
 
   // Start and stop again and make sure the file is back to the size it was
   // before adding the junk data.
   ASSERT_TRUE(StartThenVerifyNewState(base::FilePath(),
                                       net::NetLogCaptureMode::Default(),
-                                      kCaptureModeDefaultString));
+                                      kCaptureModeDefaultString, {}));
 
   ASSERT_TRUE(StopThenVerifyNewStateAndFile(base::FilePath(), nullptr, nullptr,
                                             kCaptureModeDefaultString));
 
   int64_t new_stop_file_size;
   EXPECT_TRUE(base::GetFileSize(default_log_path_, &new_stop_file_size));
 
   EXPECT_EQ(stop_file_size, new_stop_file_size);
 }
 
 // Adds an event to the log file, then checks that the file is larger than
 // the file created without that event.
 TEST_F(NetLogFileWriterTest, AddEvent) {
   ASSERT_TRUE(InitializeThenVerifyNewState(true, false));
 
   ASSERT_TRUE(StartThenVerifyNewState(base::FilePath(),
                                       net::NetLogCaptureMode::Default(),
-                                      kCaptureModeDefaultString));
+                                      kCaptureModeDefaultString, {}));
 
   ASSERT_TRUE(StopThenVerifyNewStateAndFile(base::FilePath(), nullptr, nullptr,
                                             kCaptureModeDefaultString));
 
   // Get file size without the event.
   int64_t stop_file_size;
   EXPECT_TRUE(base::GetFileSize(default_log_path_, &stop_file_size));
 
   ASSERT_TRUE(StartThenVerifyNewState(base::FilePath(),
                                       net::NetLogCaptureMode::Default(),
-                                      kCaptureModeDefaultString));
+                                      kCaptureModeDefaultString, {}));
 
   net_log_.AddGlobalEntry(net::NetLogEventType::CANCELLED);
 
   ASSERT_TRUE(StopThenVerifyNewStateAndFile(base::FilePath(), nullptr, nullptr,
                                             kCaptureModeDefaultString));
 
   // Get file size after adding the event and make sure it's larger than before.
   int64_t new_stop_file_size;
   EXPECT_TRUE(base::GetFileSize(default_log_path_, &new_stop_file_size));
   EXPECT_GE(new_stop_file_size, stop_file_size);
 }
 
 // Using a custom path to make sure logging can still occur when the path has
 // changed.
 TEST_F(NetLogFileWriterTest, AddEventCustomPath) {
   ASSERT_TRUE(InitializeThenVerifyNewState(true, false));
 
   base::FilePath::CharType kCustomRelativePath[] =
       FILE_PATH_LITERAL("custom/custom/chrome-net-export-log.json");
   base::FilePath custom_log_path =
       log_temp_dir_.GetPath().Append(kCustomRelativePath);
   EXPECT_TRUE(
       base::CreateDirectoryAndGetError(custom_log_path.DirName(), nullptr));
 
   ASSERT_TRUE(StartThenVerifyNewState(custom_log_path,
                                       net::NetLogCaptureMode::Default(),
-                                      kCaptureModeDefaultString));
+                                      kCaptureModeDefaultString, {}));
 
   ASSERT_TRUE(StopThenVerifyNewStateAndFile(custom_log_path, nullptr, nullptr,
                                             kCaptureModeDefaultString));
 
   // Get file size without the event.
   int64_t stop_file_size;
   EXPECT_TRUE(base::GetFileSize(custom_log_path, &stop_file_size));
 
   ASSERT_TRUE(StartThenVerifyNewState(custom_log_path,
                                       net::NetLogCaptureMode::Default(),
-                                      kCaptureModeDefaultString));
+                                      kCaptureModeDefaultString, {}));
 
   net_log_.AddGlobalEntry(net::NetLogEventType::CANCELLED);
 
   ASSERT_TRUE(StopThenVerifyNewStateAndFile(custom_log_path, nullptr, nullptr,
                                             kCaptureModeDefaultString));
 
   // Get file size after adding the event and make sure it's larger than before.
   int64_t new_stop_file_size;
   EXPECT_TRUE(base::GetFileSize(custom_log_path, &new_stop_file_size));
   EXPECT_GE(new_stop_file_size, stop_file_size);
@@ skipping 14 matching lines @@
   const int kDummyQuicParam = 75;
   net::TestClosure init_done;
   net_thread_.task_runner()->PostTaskAndReply(
       FROM_HERE, base::Bind(&SetUpTestContextGetterWithQuicTimeoutInfo,
                             &net_log_, kDummyQuicParam, &context_getter),
       init_done.closure());
   init_done.WaitForResult();
 
   ASSERT_TRUE(StartThenVerifyNewState(base::FilePath(),
                                       net::NetLogCaptureMode::Default(),
-                                      kCaptureModeDefaultString));
+                                      kCaptureModeDefaultString, {}));
 
   ASSERT_TRUE(StopThenVerifyNewStateAndFile(
       base::FilePath(), std::move(dummy_polled_data), context_getter,
       kCaptureModeDefaultString));
 
   // Read polledData from log file.
   std::unique_ptr<base::DictionaryValue> root;
   ASSERT_TRUE(ReadCompleteLogFile(default_log_path_, &root));
   base::DictionaryValue* polled_data;
   ASSERT_TRUE(root->GetDictionary("polledData", &polled_data));
 
   // Check that it contains the field from the polled data that was passed in.
   std::string dummy_string;
   ASSERT_TRUE(polled_data->GetString(kDummyPolledDataPath, &dummy_string));
   EXPECT_EQ(kDummyPolledDataString, dummy_string);
 
   // Check that it also contains the field from the URLRequestContext that was
   // passed in.
   base::DictionaryValue* quic_info;
   ASSERT_TRUE(polled_data->GetDictionary("quicInfo", &quic_info));
   base::Value* timeout_value = nullptr;
   int timeout;
   ASSERT_TRUE(
       quic_info->Get("idle_connection_timeout_seconds", &timeout_value));
   ASSERT_TRUE(timeout_value->GetAsInteger(&timeout));
   EXPECT_EQ(kDummyQuicParam, timeout);
 }
 
+TEST_F(NetLogFileWriterTest, StartWithContextGetters) {

[eroman, 2017/02/24 00:17:38]

Thanks for adding the test!

[wangyix1, 2017/02/24 00:58:08]

Acknowledged.

+  ASSERT_TRUE(InitializeThenVerifyNewState(true, false));
+
+  // Create test context getter and request on |net_thread_| and wait for it to
+  // finish.
+  const std::string kDummyUrl = "blah:blah";
+  scoped_refptr<net::TestURLRequestContextGetter> context_getter;
+  std::unique_ptr<net::URLRequest> request;
+  net::TestDelegate delegate;
+  delegate.set_quit_on_complete(false);
+
+  net::TestClosure init_done;
+  net_thread_.task_runner()->PostTaskAndReply(
+      FROM_HERE, base::Bind(&SetUpTestContextGetterWithRequest, &net_log_,
+                            kDummyUrl, &delegate, &context_getter, &request),
+      init_done.closure());
+  init_done.WaitForResult();
+
+  ASSERT_TRUE(StartThenVerifyNewState(
+      base::FilePath(), net::NetLogCaptureMode::Default(),
+      kCaptureModeDefaultString, {context_getter}));
+
+  ASSERT_TRUE(StopThenVerifyNewStateAndFile(base::FilePath(), nullptr, nullptr,
+                                            kCaptureModeDefaultString));
+
+  // Read events from log file.
+  std::unique_ptr<base::DictionaryValue> root;
+  ASSERT_TRUE(ReadCompleteLogFile(default_log_path_, &root));
+  base::ListValue* events;
+  ASSERT_TRUE(root->GetList("events", &events));
+
+  // Check there is at least one event as a result of the ongoing request.
+  EXPECT_GE(events->GetSize(), 1u);
+
+  // Check the URL in the params of the first event.
+  base::DictionaryValue* event;
+  EXPECT_TRUE(events->GetDictionary(0, &event));
+  base::DictionaryValue* event_params;
+  EXPECT_TRUE(event->GetDictionary("params", &event_params));
+  std::string event_url;
+  EXPECT_TRUE(event_params->GetString("url", &event_url));
+  EXPECT_EQ(kDummyUrl, event_url);
+
+  net_thread_.task_runner()->DeleteSoon(FROM_HERE, request.release());
+}
+
 TEST_F(NetLogFileWriterTest, ReceiveStartWhileInitializing) {
   // Trigger initialization of |net_log_file_writer_|.
   net_log_file_writer_.Initialize(file_thread_.task_runner(),
                                   net_thread_.task_runner());
 
   // Before running the main message loop, tell |net_log_file_writer_| to start
   // logging. Not running the main message loop prevents the initialization
   // process from completing, so this ensures that StartNetLog() is received
   // before |net_log_file_writer_| finishes initialization, which means this
   // should be a no-op.
   net_log_file_writer_.StartNetLog(base::FilePath(),
-                                   net::NetLogCaptureMode::Default());
+                                   net::NetLogCaptureMode::Default(), {});
 
   // Now run the main message loop. Make sure StartNetLog() was ignored by
   // checking that the next two states are "initializing" followed by
   // "not-logging".
   std::unique_ptr<base::DictionaryValue> state =
       test_state_observer_.WaitForNewState();
   ASSERT_TRUE(VerifyState(std::move(state), kStateInitializingString));
   state = test_state_observer_.WaitForNewState();
   ASSERT_TRUE(
       VerifyState(std::move(state), kStateNotLoggingString, false, false, ""));
 }
 
 TEST_F(NetLogFileWriterTest, ReceiveStartWhileStoppingLog) {
   ASSERT_TRUE(InitializeThenVerifyNewState(true, false));
 
   // Call StartNetLog() on |net_log_file_writer_| and wait for the state change.
   ASSERT_TRUE(StartThenVerifyNewState(
       base::FilePath(), net::NetLogCaptureMode::IncludeSocketBytes(),
-      kCaptureModeIncludeSocketBytesString));
+      kCaptureModeIncludeSocketBytesString, {}));
 
   // Tell |net_log_file_writer_| to stop logging.
   net_log_file_writer_.StopNetLog(nullptr, nullptr);
 
   // Before running the main message loop, tell |net_log_file_writer_| to start
   // logging. Not running the main message loop prevents the stopping process
   // from completing, so this ensures StartNetLog() is received before
   // |net_log_file_writer_| finishes stopping, which means this should be a
   // no-op.
   net_log_file_writer_.StartNetLog(base::FilePath(),
-                                   net::NetLogCaptureMode::Default());
+                                   net::NetLogCaptureMode::Default(), {});
 
   // Now run the main message loop. Make sure the last StartNetLog() was
   // ignored by checking that the next two states are "stopping-log" followed by
   // "not-logging". Also make sure the capture mode matches that of the first
   // StartNetLog() call (called by StartThenVerifyState()).
   std::unique_ptr<base::DictionaryValue> state =
       test_state_observer_.WaitForNewState();
   ASSERT_TRUE(VerifyState(std::move(state), kStateStoppingLogString));
   state = test_state_observer_.WaitForNewState();
   ASSERT_TRUE(VerifyState(std::move(state), kStateNotLoggingString, true, true,
                           kCaptureModeIncludeSocketBytesString));
 }
 
 }  // namespace net_log