file_net_log_observer_unittest.cc 37 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910911912913914915916917918919920921922923924925926927928929930931932933934935936937938939940941942943944945946947948949950951952953954955956957958959960961962963964965966967968969970971972973974975976977978979980981982983984985986987988989990991992993994995996997998999100010011002100310041005100610071008100910101011101210131014101510161017101810191020102110221023102410251026102710281029103010311032103310341035103610371038103910401041104210431044104510461047104810491050105110521053105410551056105710581059106010611062106310641065106610671068106910701071107210731074107510761077107810791080108110821083108410851086108710881089109010911092
  1. // Copyright 2016 The Chromium Authors. All rights reserved.
  2. // Use of this source code is governed by a BSD-style license that can be
  3. // found in the LICENSE file.
  4. #include "net/log/file_net_log_observer.h"
  5. #include <string>
  6. #include <vector>
  7. #include "base/bind.h"
  8. #include "base/callback.h"
  9. #include "base/files/file.h"
  10. #include "base/files/file_path.h"
  11. #include "base/files/file_util.h"
  12. #include "base/files/scoped_file.h"
  13. #include "base/files/scoped_temp_dir.h"
  14. #include "base/json/json_reader.h"
  15. #include "base/json/json_writer.h"
  16. #include "base/memory/raw_ptr.h"
  17. #include "base/strings/string_number_conversions.h"
  18. #include "base/strings/string_util.h"
  19. #include "base/strings/stringprintf.h"
  20. #include "base/task/thread_pool/thread_pool_instance.h"
  21. #include "base/threading/thread.h"
  22. #include "base/values.h"
  23. #include "build/build_config.h"
  24. #include "net/base/test_completion_callback.h"
  25. #include "net/log/net_log.h"
  26. #include "net/log/net_log_entry.h"
  27. #include "net/log/net_log_event_type.h"
  28. #include "net/log/net_log_source.h"
  29. #include "net/log/net_log_source_type.h"
  30. #include "net/log/net_log_util.h"
  31. #include "net/log/net_log_values.h"
  32. #include "net/test/test_with_task_environment.h"
  33. #include "net/url_request/url_request.h"
  34. #include "net/url_request/url_request_context.h"
  35. #include "net/url_request/url_request_test_util.h"
  36. #include "testing/gtest/include/gtest/gtest.h"
  37. namespace net {
  38. namespace {
  39. // Indicates the number of event files used in test cases.
  40. const int kTotalNumFiles = 10;
  41. // Used to set the total file size maximum in test cases where the file size
  42. // doesn't matter.
  43. const int kLargeFileSize = 100000000;
  44. // Used to set the size of events to be sent to the observer in test cases
  45. // where event size doesn't matter.
  46. const size_t kDummyEventSize = 150;
  47. // Adds |num_entries| to |logger|. The "inverse" of this is VerifyEventsInLog().
  48. void AddEntries(FileNetLogObserver* logger,
  49. int num_entries,
  50. size_t entry_size) {
  51. // Get base size of event.
  52. const int kDummyId = 0;
  53. NetLogSource source(NetLogSourceType::HTTP2_SESSION, kDummyId);
  54. NetLogEntry base_entry(NetLogEventType::PAC_JAVASCRIPT_ERROR, source,
  55. NetLogEventPhase::BEGIN, base::TimeTicks::Now(),
  56. NetLogParamsWithString("message", ""));
  57. base::Value value = base_entry.ToValue();
  58. std::string json;
  59. base::JSONWriter::Write(value, &json);
  60. size_t base_entry_size = json.size();
  61. // The maximum value of base::TimeTicks::Now() will be the maximum value of
  62. // int64_t, and if the maximum number of digits are included, the
  63. // |base_entry_size| could be up to 136 characters. Check that the event
  64. // format does not include additional padding.
  65. DCHECK_LE(base_entry_size, 136u);
  66. // |entry_size| should be at least as big as the largest possible base
  67. // entry.
  68. EXPECT_GE(entry_size, 136u);
  69. // |entry_size| cannot be smaller than the minimum event size.
  70. EXPECT_GE(entry_size, base_entry_size);
  71. for (int i = 0; i < num_entries; i++) {
  72. source = NetLogSource(NetLogSourceType::HTTP2_SESSION, i);
  73. std::string id = base::NumberToString(i);
  74. // String size accounts for the number of digits in id so that all events
  75. // are the same size.
  76. std::string message =
  77. std::string(entry_size - base_entry_size - id.size() + 1, 'x');
  78. NetLogEntry entry(NetLogEventType::PAC_JAVASCRIPT_ERROR, source,
  79. NetLogEventPhase::BEGIN, base::TimeTicks::Now(),
  80. NetLogParamsWithString("message", message));
  81. logger->OnAddEntry(entry);
  82. }
  83. }
  84. // ParsedNetLog holds the parsed contents of a NetLog file (constants, events,
  85. // and polled data).
  86. struct ParsedNetLog {
  87. ::testing::AssertionResult InitFromFileContents(const std::string& input);
  88. const base::Value::Dict* GetEvent(size_t i) const;
  89. // Initializes the ParsedNetLog by parsing a JSON file.
  90. // Owner for the Value tree and a dictionary for the entire netlog.
  91. base::Value root;
  92. // The constants dictionary.
  93. raw_ptr<const base::Value::Dict> constants = nullptr;
  94. // The events list.
  95. raw_ptr<const base::Value::List> events = nullptr;
  96. // The optional polled data (may be nullptr).
  97. raw_ptr<const base::Value::Dict> polled_data = nullptr;
  98. };
  99. ::testing::AssertionResult ParsedNetLog::InitFromFileContents(
  100. const std::string& input) {
  101. if (input.empty()) {
  102. return ::testing::AssertionFailure() << "input is empty";
  103. }
  104. auto parsed_json = base::JSONReader::ReadAndReturnValueWithError(input);
  105. if (!parsed_json.has_value()) {
  106. return ::testing::AssertionFailure() << parsed_json.error().message;
  107. }
  108. root = std::move(*parsed_json);
  109. const base::Value::Dict* dict = root.GetIfDict();
  110. if (!dict) {
  111. return ::testing::AssertionFailure() << "Not a dictionary";
  112. }
  113. events = dict->FindListByDottedPath("events");
  114. if (!events) {
  115. return ::testing::AssertionFailure() << "No events list";
  116. }
  117. constants = dict->FindDictByDottedPath("constants");
  118. if (!constants) {
  119. return ::testing::AssertionFailure() << "No constants dictionary";
  120. }
  121. // Polled data is optional (ignore success).
  122. polled_data = dict->FindDictByDottedPath("polledData");
  123. return ::testing::AssertionSuccess();
  124. }
  125. // Returns the event at index |i|, or nullptr if there is none.
  126. const base::Value::Dict* ParsedNetLog::GetEvent(size_t i) const {
  127. if (!events || i >= events->size())
  128. return nullptr;
  129. return (*events)[i].GetIfDict();
  130. }
  131. // Creates a ParsedNetLog by reading a NetLog from a file. Returns nullptr on
  132. // failure.
  133. std::unique_ptr<ParsedNetLog> ReadNetLogFromDisk(
  134. const base::FilePath& log_path) {
  135. std::string input;
  136. if (!base::ReadFileToString(log_path, &input)) {
  137. ADD_FAILURE() << "Failed reading file: " << log_path.value();
  138. return nullptr;
  139. }
  140. std::unique_ptr<ParsedNetLog> result = std::make_unique<ParsedNetLog>();
  141. ::testing::AssertionResult init_result = result->InitFromFileContents(input);
  142. EXPECT_TRUE(init_result);
  143. if (!init_result)
  144. return nullptr;
  145. return result;
  146. }
  147. // Checks that |log| contains events as emitted by AddEntries() above.
  148. // |num_events_emitted| corresponds to |num_entries| of AddEntries(). Whereas
  149. // |num_events_saved| is the expected number of events that have actually been
  150. // written to the log (post-truncation).
  151. void VerifyEventsInLog(const ParsedNetLog* log,
  152. size_t num_events_emitted,
  153. size_t num_events_saved) {
  154. ASSERT_TRUE(log);
  155. ASSERT_LE(num_events_saved, num_events_emitted);
  156. ASSERT_EQ(num_events_saved, log->events->size());
  157. // The last |num_events_saved| should all be sequential, with the last one
  158. // being numbered |num_events_emitted - 1|.
  159. for (size_t i = 0; i < num_events_saved; ++i) {
  160. const base::Value::Dict* event = log->GetEvent(i);
  161. ASSERT_TRUE(event);
  162. size_t expected_source_id = num_events_emitted - num_events_saved + i;
  163. absl::optional<int> id_value = event->FindIntByDottedPath("source.id");
  164. ASSERT_EQ(static_cast<int>(expected_source_id), id_value);
  165. }
  166. }
  167. // Helper that checks whether |dict| has a string property at |key| having
  168. // |value|.
  169. void ExpectDictionaryContainsProperty(const base::Value::Dict& dict,
  170. const std::string& key,
  171. const std::string& value) {
  172. const std::string* actual_value = dict.FindStringByDottedPath(key);
  173. ASSERT_EQ(value, *actual_value);
  174. }
  175. // Used for tests that are common to both bounded and unbounded modes of the
  176. // the FileNetLogObserver. The param is true if bounded mode is used.
  177. class FileNetLogObserverTest : public ::testing::TestWithParam<bool>,
  178. public WithTaskEnvironment {
  179. public:
  180. void SetUp() override {
  181. ASSERT_TRUE(temp_dir_.CreateUniqueTempDir());
  182. log_path_ = temp_dir_.GetPath().AppendASCII("net-log.json");
  183. }
  184. void TearDown() override {
  185. logger_.reset();
  186. // FileNetLogObserver destructor might post to message loop.
  187. RunUntilIdle();
  188. }
  189. bool IsBounded() const { return GetParam(); }
  190. void CreateAndStartObserving(
  191. std::unique_ptr<base::Value> constants,
  192. NetLogCaptureMode capture_mode = NetLogCaptureMode::kDefault) {
  193. if (IsBounded()) {
  194. logger_ = FileNetLogObserver::CreateBoundedForTests(
  195. log_path_, kLargeFileSize, kTotalNumFiles, capture_mode,
  196. std::move(constants));
  197. } else {
  198. logger_ = FileNetLogObserver::CreateUnbounded(log_path_, capture_mode,
  199. std::move(constants));
  200. }
  201. logger_->StartObserving(NetLog::Get());
  202. }
  203. void CreateAndStartObservingPreExisting(
  204. std::unique_ptr<base::Value> constants) {
  205. ASSERT_TRUE(scratch_dir_.CreateUniqueTempDir());
  206. base::File file(log_path_,
  207. base::File::FLAG_CREATE | base::File::FLAG_WRITE);
  208. EXPECT_TRUE(file.IsValid());
  209. // Stick in some nonsense to make sure the file gets cleared properly
  210. file.Write(0, "not json", 8);
  211. if (IsBounded()) {
  212. logger_ = FileNetLogObserver::CreateBoundedPreExisting(
  213. scratch_dir_.GetPath(), std::move(file), kLargeFileSize,
  214. NetLogCaptureMode::kDefault, std::move(constants));
  215. } else {
  216. logger_ = FileNetLogObserver::CreateUnboundedPreExisting(
  217. std::move(file), NetLogCaptureMode::kDefault, std::move(constants));
  218. }
  219. logger_->StartObserving(NetLog::Get());
  220. }
  221. bool LogFileExists() {
  222. // The log files are written by a sequenced task runner. Drain all the
  223. // scheduled tasks to ensure that the file writing ones have run before
  224. // checking if they exist.
  225. base::ThreadPoolInstance::Get()->FlushForTesting();
  226. return base::PathExists(log_path_);
  227. }
  228. protected:
  229. std::unique_ptr<FileNetLogObserver> logger_;
  230. base::ScopedTempDir temp_dir_;
  231. base::ScopedTempDir scratch_dir_; // used for bounded + preexisting
  232. base::FilePath log_path_;
  233. };
  234. // Used for tests that are exclusive to the bounded mode of FileNetLogObserver.
  235. class FileNetLogObserverBoundedTest : public ::testing::Test,
  236. public WithTaskEnvironment {
  237. public:
  238. void SetUp() override {
  239. ASSERT_TRUE(temp_dir_.CreateUniqueTempDir());
  240. log_path_ = temp_dir_.GetPath().AppendASCII("net-log.json");
  241. }
  242. void TearDown() override {
  243. logger_.reset();
  244. // FileNetLogObserver destructor might post to message loop.
  245. RunUntilIdle();
  246. }
  247. void CreateAndStartObserving(std::unique_ptr<base::Value> constants,
  248. uint64_t total_file_size,
  249. int num_files) {
  250. logger_ = FileNetLogObserver::CreateBoundedForTests(
  251. log_path_, total_file_size, num_files, NetLogCaptureMode::kDefault,
  252. std::move(constants));
  253. logger_->StartObserving(NetLog::Get());
  254. }
  255. // Returns the path for an internally directory created for bounded logs (this
  256. // needs to be kept in sync with the implementation).
  257. base::FilePath GetInprogressDirectory() const {
  258. return log_path_.AddExtension(FILE_PATH_LITERAL(".inprogress"));
  259. }
  260. base::FilePath GetEventFilePath(int index) const {
  261. return GetInprogressDirectory().AppendASCII(
  262. "event_file_" + base::NumberToString(index) + ".json");
  263. }
  264. base::FilePath GetEndNetlogPath() const {
  265. return GetInprogressDirectory().AppendASCII("end_netlog.json");
  266. }
  267. base::FilePath GetConstantsPath() const {
  268. return GetInprogressDirectory().AppendASCII("constants.json");
  269. }
  270. protected:
  271. std::unique_ptr<FileNetLogObserver> logger_;
  272. base::FilePath log_path_;
  273. private:
  274. base::ScopedTempDir temp_dir_;
  275. };
  276. // Instantiates each FileNetLogObserverTest to use bounded and unbounded modes.
  277. INSTANTIATE_TEST_SUITE_P(All,
  278. FileNetLogObserverTest,
  279. ::testing::Values(true, false));
  280. // Tests deleting a FileNetLogObserver without first calling StopObserving().
  281. TEST_P(FileNetLogObserverTest, ObserverDestroyedWithoutStopObserving) {
  282. CreateAndStartObserving(nullptr);
  283. // Send dummy event
  284. AddEntries(logger_.get(), 1, kDummyEventSize);
  285. // The log files should have been started.
  286. ASSERT_TRUE(LogFileExists());
  287. logger_.reset();
  288. // When the logger is re-set without having called StopObserving(), the
  289. // partially written log files are deleted.
  290. ASSERT_FALSE(LogFileExists());
  291. }
  292. // Same but with pre-existing file.
  293. TEST_P(FileNetLogObserverTest,
  294. ObserverDestroyedWithoutStopObservingPreExisting) {
  295. CreateAndStartObservingPreExisting(nullptr);
  296. // Send dummy event
  297. AddEntries(logger_.get(), 1, kDummyEventSize);
  298. // The log files should have been started.
  299. ASSERT_TRUE(LogFileExists());
  300. // Should also have the scratch dir, if bounded. (Can be checked since
  301. // LogFileExists flushed the thread pool).
  302. if (IsBounded()) {
  303. ASSERT_TRUE(base::PathExists(scratch_dir_.GetPath()));
  304. }
  305. logger_.reset();
  306. // Unlike in the non-preexisting case, the output file isn't deleted here,
  307. // since the process running the observer likely won't have the sandbox
  308. // permission to do so.
  309. ASSERT_TRUE(LogFileExists());
  310. if (IsBounded()) {
  311. ASSERT_FALSE(base::PathExists(scratch_dir_.GetPath()));
  312. }
  313. }
  314. // Tests calling StopObserving() with a null closure.
  315. TEST_P(FileNetLogObserverTest, StopObservingNullClosure) {
  316. CreateAndStartObserving(nullptr);
  317. // Send dummy event
  318. AddEntries(logger_.get(), 1, kDummyEventSize);
  319. // The log files should have been started.
  320. ASSERT_TRUE(LogFileExists());
  321. logger_->StopObserving(nullptr, base::OnceClosure());
  322. logger_.reset();
  323. // Since the logger was explicitly stopped, its files should still exist.
  324. ASSERT_TRUE(LogFileExists());
  325. }
  326. // Tests creating a FileNetLogObserver using an invalid (can't be written to)
  327. // path.
  328. TEST_P(FileNetLogObserverTest, InitLogWithInvalidPath) {
  329. // Use a path to a non-existent directory.
  330. log_path_ = temp_dir_.GetPath().AppendASCII("bogus").AppendASCII("path");
  331. CreateAndStartObserving(nullptr);
  332. // Send dummy event
  333. AddEntries(logger_.get(), 1, kDummyEventSize);
  334. // No log files should have been written, as the log writer will not create
  335. // missing directories.
  336. ASSERT_FALSE(LogFileExists());
  337. logger_->StopObserving(nullptr, base::OnceClosure());
  338. logger_.reset();
  339. // There should still be no files.
  340. ASSERT_FALSE(LogFileExists());
  341. }
  342. TEST_P(FileNetLogObserverTest, GeneratesValidJSONWithNoEvents) {
  343. TestClosure closure;
  344. CreateAndStartObserving(nullptr);
  345. logger_->StopObserving(nullptr, closure.closure());
  346. closure.WaitForResult();
  347. // Verify the written log.
  348. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  349. ASSERT_TRUE(log);
  350. ASSERT_EQ(0u, log->events->size());
  351. }
  352. TEST_P(FileNetLogObserverTest, GeneratesValidJSONWithOneEvent) {
  353. TestClosure closure;
  354. CreateAndStartObserving(nullptr);
  355. // Send dummy event.
  356. AddEntries(logger_.get(), 1, kDummyEventSize);
  357. logger_->StopObserving(nullptr, closure.closure());
  358. closure.WaitForResult();
  359. // Verify the written log.
  360. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  361. ASSERT_TRUE(log);
  362. ASSERT_EQ(1u, log->events->size());
  363. }
  364. TEST_P(FileNetLogObserverTest, GeneratesValidJSONWithOneEventPreExisting) {
  365. TestClosure closure;
  366. CreateAndStartObservingPreExisting(nullptr);
  367. // Send dummy event.
  368. AddEntries(logger_.get(), 1, kDummyEventSize);
  369. logger_->StopObserving(nullptr, closure.closure());
  370. closure.WaitForResult();
  371. // Verify the written log.
  372. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  373. ASSERT_TRUE(log);
  374. ASSERT_EQ(1u, log->events->size());
  375. }
  376. TEST_P(FileNetLogObserverTest, PreExistingFileBroken) {
  377. // Test that pre-existing output file not being successfully open is
  378. // tolerated.
  379. ASSERT_TRUE(scratch_dir_.CreateUniqueTempDir());
  380. base::File file;
  381. EXPECT_FALSE(file.IsValid());
  382. if (IsBounded())
  383. logger_ = FileNetLogObserver::CreateBoundedPreExisting(
  384. scratch_dir_.GetPath(), std::move(file), kLargeFileSize,
  385. NetLogCaptureMode::kDefault, nullptr);
  386. else
  387. logger_ = FileNetLogObserver::CreateUnboundedPreExisting(
  388. std::move(file), NetLogCaptureMode::kDefault, nullptr);
  389. logger_->StartObserving(NetLog::Get());
  390. // Send dummy event.
  391. AddEntries(logger_.get(), 1, kDummyEventSize);
  392. TestClosure closure;
  393. logger_->StopObserving(nullptr, closure.closure());
  394. closure.WaitForResult();
  395. }
  396. TEST_P(FileNetLogObserverTest, CustomConstants) {
  397. TestClosure closure;
  398. const char kConstantKey[] = "magic";
  399. const char kConstantString[] = "poney";
  400. base::Value::Dict constants;
  401. constants.SetByDottedPath(kConstantKey, kConstantString);
  402. CreateAndStartObserving(std::make_unique<base::Value>(std::move(constants)));
  403. logger_->StopObserving(nullptr, closure.closure());
  404. closure.WaitForResult();
  405. // Verify the written log.
  406. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  407. ASSERT_TRUE(log);
  408. // Check that custom constant was correctly printed.
  409. ExpectDictionaryContainsProperty(*log->constants, kConstantKey,
  410. kConstantString);
  411. }
  412. TEST_P(FileNetLogObserverTest, GeneratesValidJSONWithPolledData) {
  413. TestClosure closure;
  414. CreateAndStartObserving(nullptr);
  415. // Create dummy polled data
  416. const char kDummyPolledDataPath[] = "dummy_path";
  417. const char kDummyPolledDataString[] = "dummy_info";
  418. base::Value::Dict dummy_polled_data;
  419. dummy_polled_data.SetByDottedPath(kDummyPolledDataPath,
  420. kDummyPolledDataString);
  421. logger_->StopObserving(
  422. std::make_unique<base::Value>(std::move(dummy_polled_data)),
  423. closure.closure());
  424. closure.WaitForResult();
  425. // Verify the written log.
  426. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  427. ASSERT_TRUE(log);
  428. ASSERT_EQ(0u, log->events->size());
  429. // Make sure additional information is present and validate it.
  430. ASSERT_TRUE(log->polled_data);
  431. ExpectDictionaryContainsProperty(*log->polled_data, kDummyPolledDataPath,
  432. kDummyPolledDataString);
  433. }
  434. // Ensure that the Capture Mode is recorded as a constant in the NetLog.
  435. TEST_P(FileNetLogObserverTest, LogModeRecorded) {
  436. struct TestCase {
  437. NetLogCaptureMode capture_mode;
  438. const char* expected_value;
  439. } test_cases[] = {// Challenges that result in success results.
  440. {NetLogCaptureMode::kEverything, "Everything"},
  441. {NetLogCaptureMode::kIncludeSensitive, "IncludeSensitive"},
  442. {NetLogCaptureMode::kDefault, "Default"}};
  443. TestClosure closure;
  444. for (const auto& test_case : test_cases) {
  445. CreateAndStartObserving(nullptr, test_case.capture_mode);
  446. logger_->StopObserving(nullptr, closure.closure());
  447. closure.WaitForResult();
  448. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  449. ASSERT_TRUE(log);
  450. ExpectDictionaryContainsProperty(*log->constants, "logCaptureMode",
  451. test_case.expected_value);
  452. }
  453. }
  454. // Adds events concurrently from several different threads. The exact order of
  455. // events seen by this test is non-deterministic.
  456. TEST_P(FileNetLogObserverTest, AddEventsFromMultipleThreads) {
  457. const size_t kNumThreads = 10;
  458. std::vector<std::unique_ptr<base::Thread>> threads(kNumThreads);
  459. #if BUILDFLAG(IS_FUCHSIA)
  460. // TODO(https://crbug.com/959245): Diagnosting logging to determine where
  461. // this test sometimes hangs.
  462. LOG(ERROR) << "Create and start threads.";
  463. #endif
  464. // Start all the threads. Waiting for them to start is to hopefuly improve
  465. // the odds of hitting interesting races once events start being added.
  466. for (size_t i = 0; i < threads.size(); ++i) {
  467. threads[i] = std::make_unique<base::Thread>(
  468. base::StringPrintf("WorkerThread%i", static_cast<int>(i)));
  469. threads[i]->Start();
  470. threads[i]->WaitUntilThreadStarted();
  471. }
  472. #if BUILDFLAG(IS_FUCHSIA)
  473. LOG(ERROR) << "Create and start observing.";
  474. #endif
  475. CreateAndStartObserving(nullptr);
  476. const size_t kNumEventsAddedPerThread = 200;
  477. #if BUILDFLAG(IS_FUCHSIA)
  478. LOG(ERROR) << "Posting tasks.";
  479. #endif
  480. // Add events in parallel from all the threads.
  481. for (size_t i = 0; i < kNumThreads; ++i) {
  482. threads[i]->task_runner()->PostTask(
  483. FROM_HERE, base::BindOnce(&AddEntries, base::Unretained(logger_.get()),
  484. kNumEventsAddedPerThread, kDummyEventSize));
  485. }
  486. #if BUILDFLAG(IS_FUCHSIA)
  487. LOG(ERROR) << "Joining all threads.";
  488. #endif
  489. // Join all the threads.
  490. threads.clear();
  491. #if BUILDFLAG(IS_FUCHSIA)
  492. LOG(ERROR) << "Stop observing.";
  493. #endif
  494. // Stop observing.
  495. TestClosure closure;
  496. logger_->StopObserving(nullptr, closure.closure());
  497. closure.WaitForResult();
  498. #if BUILDFLAG(IS_FUCHSIA)
  499. LOG(ERROR) << "Read log from disk and verify.";
  500. #endif
  501. // Verify the written log.
  502. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  503. ASSERT_TRUE(log);
  504. // Check that the expected number of events were written to disk.
  505. EXPECT_EQ(kNumEventsAddedPerThread * kNumThreads, log->events->size());
  506. #if BUILDFLAG(IS_FUCHSIA)
  507. LOG(ERROR) << "Teardown.";
  508. #endif
  509. }
  510. // Sends enough events to the observer to completely fill one file, but not
  511. // write any events to an additional file. Checks the file bounds.
  512. TEST_F(FileNetLogObserverBoundedTest, EqualToOneFile) {
  513. // The total size of the events is equal to the size of one file.
  514. // |kNumEvents| * |kEventSize| = |kTotalFileSize| / |kTotalNumEvents|
  515. const int kTotalFileSize = 5000;
  516. const int kNumEvents = 2;
  517. const int kEventSize = 250;
  518. TestClosure closure;
  519. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  520. AddEntries(logger_.get(), kNumEvents, kEventSize);
  521. logger_->StopObserving(nullptr, closure.closure());
  522. closure.WaitForResult();
  523. // Verify the written log.
  524. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  525. ASSERT_TRUE(log);
  526. VerifyEventsInLog(log.get(), kNumEvents, kNumEvents);
  527. }
  528. // Sends enough events to fill one file, and partially fill a second file.
  529. // Checks the file bounds and writing to a new file.
  530. TEST_F(FileNetLogObserverBoundedTest, OneEventOverOneFile) {
  531. // The total size of the events is greater than the size of one file, and
  532. // less than the size of two files. The total size of all events except one
  533. // is equal to the size of one file, so the last event will be the only event
  534. // in the second file.
  535. // (|kNumEvents| - 1) * kEventSize = |kTotalFileSize| / |kTotalNumEvents|
  536. const int kTotalFileSize = 6000;
  537. const int kNumEvents = 4;
  538. const int kEventSize = 200;
  539. TestClosure closure;
  540. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  541. AddEntries(logger_.get(), kNumEvents, kEventSize);
  542. logger_->StopObserving(nullptr, closure.closure());
  543. closure.WaitForResult();
  544. // Verify the written log.
  545. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  546. ASSERT_TRUE(log);
  547. VerifyEventsInLog(log.get(), kNumEvents, kNumEvents);
  548. }
  549. // Sends enough events to the observer to completely fill two files.
  550. TEST_F(FileNetLogObserverBoundedTest, EqualToTwoFiles) {
  551. // The total size of the events is equal to the total size of two files.
  552. // |kNumEvents| * |kEventSize| = 2 * |kTotalFileSize| / |kTotalNumEvents|
  553. const int kTotalFileSize = 6000;
  554. const int kNumEvents = 6;
  555. const int kEventSize = 200;
  556. TestClosure closure;
  557. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  558. AddEntries(logger_.get(), kNumEvents, kEventSize);
  559. logger_->StopObserving(nullptr, closure.closure());
  560. closure.WaitForResult();
  561. // Verify the written log.
  562. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  563. ASSERT_TRUE(log);
  564. VerifyEventsInLog(log.get(), kNumEvents, kNumEvents);
  565. }
  566. // Sends exactly enough events to the observer to completely fill all files,
  567. // so that all events fit into the event files and no files need to be
  568. // overwritten.
  569. TEST_F(FileNetLogObserverBoundedTest, FillAllFilesNoOverwriting) {
  570. // The total size of events is equal to the total size of all files.
  571. // |kEventSize| * |kNumEvents| = |kTotalFileSize|
  572. const int kTotalFileSize = 10000;
  573. const int kEventSize = 200;
  574. const int kFileSize = kTotalFileSize / kTotalNumFiles;
  575. const int kNumEvents = kTotalNumFiles * ((kFileSize - 1) / kEventSize + 1);
  576. TestClosure closure;
  577. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  578. AddEntries(logger_.get(), kNumEvents, kEventSize);
  579. logger_->StopObserving(nullptr, closure.closure());
  580. closure.WaitForResult();
  581. // Verify the written log.
  582. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  583. ASSERT_TRUE(log);
  584. VerifyEventsInLog(log.get(), kNumEvents, kNumEvents);
  585. }
  586. // Sends more events to the observer than will fill the WriteQueue, forcing the
  587. // queue to drop an event. Checks that the queue drops the oldest event.
  588. TEST_F(FileNetLogObserverBoundedTest, DropOldEventsFromWriteQueue) {
  589. // The total size of events is greater than the WriteQueue's memory limit, so
  590. // the oldest event must be dropped from the queue and not written to any
  591. // file.
  592. // |kNumEvents| * |kEventSize| > |kTotalFileSize| * 2
  593. const int kTotalFileSize = 1000;
  594. const int kNumEvents = 11;
  595. const int kEventSize = 200;
  596. const int kFileSize = kTotalFileSize / kTotalNumFiles;
  597. TestClosure closure;
  598. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  599. AddEntries(logger_.get(), kNumEvents, kEventSize);
  600. logger_->StopObserving(nullptr, closure.closure());
  601. closure.WaitForResult();
  602. // Verify the written log.
  603. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  604. ASSERT_TRUE(log);
  605. VerifyEventsInLog(
  606. log.get(), kNumEvents,
  607. static_cast<size_t>(kTotalNumFiles * ((kFileSize - 1) / kEventSize + 1)));
  608. }
  609. // Sends twice as many events as will fill all files to the observer, so that
  610. // all of the event files will be filled twice, and every file will be
  611. // overwritten.
  612. TEST_F(FileNetLogObserverBoundedTest, OverwriteAllFiles) {
  613. // The total size of the events is much greater than twice the number of
  614. // events that can fit in the event files, to make sure that the extra events
  615. // are written to a file, not just dropped from the queue.
  616. // |kNumEvents| * |kEventSize| >= 2 * |kTotalFileSize|
  617. const int kTotalFileSize = 6000;
  618. const int kNumEvents = 60;
  619. const int kEventSize = 200;
  620. const int kFileSize = kTotalFileSize / kTotalNumFiles;
  621. TestClosure closure;
  622. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  623. AddEntries(logger_.get(), kNumEvents, kEventSize);
  624. logger_->StopObserving(nullptr, closure.closure());
  625. closure.WaitForResult();
  626. // Check that the minimum number of events that should fit in event files
  627. // have been written to all files.
  628. int events_per_file = (kFileSize - 1) / kEventSize + 1;
  629. int events_in_last_file = (kNumEvents - 1) % events_per_file + 1;
  630. // Indicates the total number of events that should be written to all files.
  631. int num_events_in_files =
  632. (kTotalNumFiles - 1) * events_per_file + events_in_last_file;
  633. // Verify the written log.
  634. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  635. ASSERT_TRUE(log);
  636. VerifyEventsInLog(log.get(), kNumEvents,
  637. static_cast<size_t>(num_events_in_files));
  638. }
  639. // Sends enough events to the observer to fill all event files, plus overwrite
  640. // some files, without overwriting all of them. Checks that the FileWriter
  641. // overwrites the file with the oldest events.
  642. TEST_F(FileNetLogObserverBoundedTest, PartiallyOverwriteFiles) {
  643. // The number of events sent to the observer is greater than the number of
  644. // events that can fit into the event files, but the events can fit in less
  645. // than twice the number of event files, so not every file will need to be
  646. // overwritten.
  647. // |kTotalFileSize| < |kNumEvents| * |kEventSize|
  648. // |kNumEvents| * |kEventSize| <= (2 * |kTotalNumFiles| - 1) * |kFileSize|
  649. const int kTotalFileSize = 6000;
  650. const int kNumEvents = 50;
  651. const int kEventSize = 200;
  652. const int kFileSize = kTotalFileSize / kTotalNumFiles;
  653. TestClosure closure;
  654. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  655. AddEntries(logger_.get(), kNumEvents, kEventSize);
  656. logger_->StopObserving(nullptr, closure.closure());
  657. closure.WaitForResult();
  658. // Check that the minimum number of events that should fit in event files
  659. // have been written to a file.
  660. int events_per_file = (kFileSize - 1) / kEventSize + 1;
  661. int events_in_last_file = kNumEvents % events_per_file;
  662. if (!events_in_last_file)
  663. events_in_last_file = events_per_file;
  664. int num_events_in_files =
  665. (kTotalNumFiles - 1) * events_per_file + events_in_last_file;
  666. // Verify the written log.
  667. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  668. ASSERT_TRUE(log);
  669. VerifyEventsInLog(log.get(), kNumEvents,
  670. static_cast<size_t>(num_events_in_files));
  671. }
  672. // Start logging in bounded mode. Create directories in places where the logger
  673. // expects to create files, in order to cause that file creation to fail.
  674. //
  675. // constants.json -- succeess
  676. // event_file_0.json -- fails to open
  677. // end_netlog.json -- fails to open
  678. TEST_F(FileNetLogObserverBoundedTest, SomeFilesFailToOpen) {
  679. // The total size of events is equal to the total size of all files.
  680. // |kEventSize| * |kNumEvents| = |kTotalFileSize|
  681. const int kTotalFileSize = 10000;
  682. const int kEventSize = 200;
  683. const int kFileSize = kTotalFileSize / kTotalNumFiles;
  684. const int kNumEvents = kTotalNumFiles * ((kFileSize - 1) / kEventSize + 1);
  685. TestClosure closure;
  686. // Create directories as a means to block files from being created by logger.
  687. EXPECT_TRUE(base::CreateDirectory(GetEventFilePath(0)));
  688. EXPECT_TRUE(base::CreateDirectory(GetEndNetlogPath()));
  689. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  690. AddEntries(logger_.get(), kNumEvents, kEventSize);
  691. logger_->StopObserving(nullptr, closure.closure());
  692. closure.WaitForResult();
  693. // The written log is invalid (and hence can't be parsed). It is just the
  694. // constants.
  695. std::string log_contents;
  696. ASSERT_TRUE(base::ReadFileToString(log_path_, &log_contents));
  697. // TODO(eroman): Verify the partially written log file?
  698. // Even though FileNetLogObserver didn't create the directory itself, it will
  699. // unconditionally delete it. The name should be uncommon enough for this be
  700. // to reasonable.
  701. EXPECT_FALSE(base::PathExists(GetInprogressDirectory()));
  702. }
  703. // Start logging in bounded mode. Create a file at the path where the logger
  704. // expects to create its inprogress directory to store event files. This will
  705. // cause logging to completely break. open it.
  706. TEST_F(FileNetLogObserverBoundedTest, InprogressDirectoryBlocked) {
  707. // The total size of events is equal to the total size of all files.
  708. // |kEventSize| * |kNumEvents| = |kTotalFileSize|
  709. const int kTotalFileSize = 10000;
  710. const int kEventSize = 200;
  711. const int kFileSize = kTotalFileSize / kTotalNumFiles;
  712. const int kNumEvents = kTotalNumFiles * ((kFileSize - 1) / kEventSize + 1);
  713. TestClosure closure;
  714. // By creating a file where a directory should be, it will not be possible to
  715. // write any event files.
  716. EXPECT_TRUE(base::WriteFile(GetInprogressDirectory(), "x", 1));
  717. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  718. AddEntries(logger_.get(), kNumEvents, kEventSize);
  719. logger_->StopObserving(nullptr, closure.closure());
  720. closure.WaitForResult();
  721. // There will be a log file at the final output, however it will be empty
  722. // since nothing was written to the .inprogress directory.
  723. std::string log_contents;
  724. ASSERT_TRUE(base::ReadFileToString(log_path_, &log_contents));
  725. EXPECT_EQ("", log_contents);
  726. // FileNetLogObserver unconditionally deletes the inprogress path (even though
  727. // it didn't actually create this file and it was a file instead of a
  728. // directory).
  729. // TODO(eroman): Should it only delete if it is a file?
  730. EXPECT_FALSE(base::PathExists(GetInprogressDirectory()));
  731. }
  732. // Start logging in bounded mode. Create a file with the same name as the 0th
  733. // events file. This will prevent any events from being written.
  734. TEST_F(FileNetLogObserverBoundedTest, BlockEventsFile0) {
  735. // The total size of events is equal to the total size of all files.
  736. // |kEventSize| * |kNumEvents| = |kTotalFileSize|
  737. const int kTotalFileSize = 10000;
  738. const int kEventSize = 200;
  739. const int kFileSize = kTotalFileSize / kTotalNumFiles;
  740. const int kNumEvents = kTotalNumFiles * ((kFileSize - 1) / kEventSize + 1);
  741. TestClosure closure;
  742. // Block the 0th events file.
  743. EXPECT_TRUE(base::CreateDirectory(GetEventFilePath(0)));
  744. CreateAndStartObserving(nullptr, kTotalFileSize, kTotalNumFiles);
  745. AddEntries(logger_.get(), kNumEvents, kEventSize);
  746. logger_->StopObserving(nullptr, closure.closure());
  747. closure.WaitForResult();
  748. // Verify the written log.
  749. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  750. ASSERT_TRUE(log);
  751. ASSERT_EQ(0u, log->events->size());
  752. }
  753. // Make sure that when using bounded mode with a pre-existing output file,
  754. // a separate in-progress directory can be specified.
  755. TEST_F(FileNetLogObserverBoundedTest, PreExistingUsesSpecifiedDir) {
  756. base::ScopedTempDir scratch_dir;
  757. ASSERT_TRUE(scratch_dir.CreateUniqueTempDir());
  758. base::File file(log_path_, base::File::FLAG_CREATE | base::File::FLAG_WRITE);
  759. ASSERT_TRUE(file.IsValid());
  760. // Stick in some nonsense to make sure the file gets cleared properly
  761. file.Write(0, "not json", 8);
  762. logger_ = FileNetLogObserver::CreateBoundedPreExisting(
  763. scratch_dir.GetPath(), std::move(file), kLargeFileSize,
  764. NetLogCaptureMode::kDefault, nullptr);
  765. logger_->StartObserving(NetLog::Get());
  766. base::ThreadPoolInstance::Get()->FlushForTesting();
  767. EXPECT_TRUE(base::PathExists(log_path_));
  768. EXPECT_TRUE(
  769. base::PathExists(scratch_dir.GetPath().AppendASCII("constants.json")));
  770. EXPECT_FALSE(base::PathExists(GetInprogressDirectory()));
  771. TestClosure closure;
  772. logger_->StopObserving(nullptr, closure.closure());
  773. closure.WaitForResult();
  774. // Now the scratch dir should be gone, too.
  775. EXPECT_FALSE(base::PathExists(scratch_dir.GetPath()));
  776. EXPECT_FALSE(base::PathExists(GetInprogressDirectory()));
  777. }
  778. // Creates a bounded log with a very large total size and verifies that events
  779. // are not dropped. This is a regression test for https://crbug.com/959929 in
  780. // which the WriteQueue size was calculated by the possibly overflowed
  781. // expression |total_file_size * 2|.
  782. TEST_F(FileNetLogObserverBoundedTest, LargeWriteQueueSize) {
  783. TestClosure closure;
  784. // This is a large value such that multiplying it by 2 will overflow to a much
  785. // smaller value (5).
  786. uint64_t total_file_size = 0x8000000000000005;
  787. CreateAndStartObserving(nullptr, total_file_size, kTotalNumFiles);
  788. // Send 3 dummy events. This isn't a lot of data, however if WriteQueue was
  789. // initialized using the overflowed value of |total_file_size * 2| (which is
  790. // 5), then the effective limit would prevent any events from being written.
  791. AddEntries(logger_.get(), 3, kDummyEventSize);
  792. logger_->StopObserving(nullptr, closure.closure());
  793. closure.WaitForResult();
  794. // Verify the written log.
  795. std::unique_ptr<ParsedNetLog> log = ReadNetLogFromDisk(log_path_);
  796. ASSERT_TRUE(log);
  797. ASSERT_EQ(3u, log->events->size());
  798. }
  799. void AddEntriesViaNetLog(NetLog* net_log, int num_entries) {
  800. for (int i = 0; i < num_entries; i++) {
  801. net_log->AddGlobalEntry(NetLogEventType::PAC_JAVASCRIPT_ERROR);
  802. }
  803. }
  804. TEST_P(FileNetLogObserverTest, AddEventsFromMultipleThreadsWithStopObserving) {
  805. const size_t kNumThreads = 10;
  806. std::vector<std::unique_ptr<base::Thread>> threads(kNumThreads);
  807. // Start all the threads. Waiting for them to start is to hopefully improve
  808. // the odds of hitting interesting races once events start being added.
  809. for (size_t i = 0; i < threads.size(); ++i) {
  810. threads[i] = std::make_unique<base::Thread>(
  811. base::StringPrintf("WorkerThread%i", static_cast<int>(i)));
  812. threads[i]->Start();
  813. threads[i]->WaitUntilThreadStarted();
  814. }
  815. CreateAndStartObserving(nullptr);
  816. const size_t kNumEventsAddedPerThread = 200;
  817. // Add events in parallel from all the threads.
  818. for (size_t i = 0; i < kNumThreads; ++i) {
  819. threads[i]->task_runner()->PostTask(
  820. FROM_HERE,
  821. base::BindOnce(&AddEntriesViaNetLog, base::Unretained(NetLog::Get()),
  822. kNumEventsAddedPerThread));
  823. }
  824. // Stop observing.
  825. TestClosure closure;
  826. logger_->StopObserving(nullptr, closure.closure());
  827. closure.WaitForResult();
  828. // Join all the threads.
  829. threads.clear();
  830. ASSERT_TRUE(LogFileExists());
  831. }
  832. TEST_P(FileNetLogObserverTest,
  833. AddEventsFromMultipleThreadsWithoutStopObserving) {
  834. const size_t kNumThreads = 10;
  835. std::vector<std::unique_ptr<base::Thread>> threads(kNumThreads);
  836. // Start all the threads. Waiting for them to start is to hopefully improve
  837. // the odds of hitting interesting races once events start being added.
  838. for (size_t i = 0; i < threads.size(); ++i) {
  839. threads[i] = std::make_unique<base::Thread>(
  840. base::StringPrintf("WorkerThread%i", static_cast<int>(i)));
  841. threads[i]->Start();
  842. threads[i]->WaitUntilThreadStarted();
  843. }
  844. CreateAndStartObserving(nullptr);
  845. const size_t kNumEventsAddedPerThread = 200;
  846. // Add events in parallel from all the threads.
  847. for (size_t i = 0; i < kNumThreads; ++i) {
  848. threads[i]->task_runner()->PostTask(
  849. FROM_HERE,
  850. base::BindOnce(&AddEntriesViaNetLog, base::Unretained(NetLog::Get()),
  851. kNumEventsAddedPerThread));
  852. }
  853. // Destroy logger.
  854. logger_.reset();
  855. // Join all the threads.
  856. threads.clear();
  857. // The log file doesn't exist since StopObserving() was not called.
  858. ASSERT_FALSE(LogFileExists());
  859. }
  860. } // namespace
  861. } // namespace net