Skip to content

Commit

Permalink
Clean up SingleLogFileLogSource::ContinueReadFile
Browse files Browse the repository at this point in the history 
SingleLogFileLogSource::ContinueReadFile is a mess.

In particular, it has a lot of complex code to handle file rotation, but
the code is unreliable. It's unreliable because it only picks up
information in the before-rotation file if the class is created before
the rotation, and because it can only handle a single rotation -- if the
log file rotates twice between feedbacks, we'll get a very confusing
snippet of super-old log entries.

Given that, file_ should just be a local variable not a member variable.
This would also improve thread safety (there's no promise that two calls
to ReadFile couldn't happen at the same time).

This should make the code much simpler and remove excess if statements.

Bug: b/186687538
Change-Id: Ie9ede634ba2941c12e4e475255021ea5563c523c
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2817963
Commit-Queue: Ian Barkley-Yeung <iby@chromium.org>
Reviewed-by: Ian Barkley-Yeung <iby@chromium.org>
Cr-Commit-Position: refs/heads/master@{#880492}
  • Loading branch information
@gorogoroumaru
gorogoroumaru authored and Chromium LUCI CQ committed May 7, 2021
1 parent 81abe66 commit c31021a
Show file tree
Hide file tree
Showing 3 changed files with 35 additions and 231 deletions.
56 changes: 25 additions & 31 deletions chrome/browser/ash/system_logs/single_log_file_log_source.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -89,9 +89,7 @@ SingleLogFileLogSource::SingleLogFileLogSource(SupportedSource source_type)
: SystemLogsSource(GetLogFileSourceRelativeFilePathValue(source_type)),
source_type_(source_type),
log_file_dir_path_(kDefaultSystemLogDirPath),
max_read_size_(kMaxReadSize),
file_cursor_position_(0),
file_inode_(0) {}
max_read_size_(kMaxReadSize) {}

SingleLogFileLogSource::~SingleLogFileLogSource() {}

Expand Down Expand Up @@ -139,35 +137,36 @@ void SingleLogFileLogSource::ContinueReadFile(
bool bytes_skipped,
size_t num_rotations_allowed,
SystemLogsResponse* response) {
// Handle for reading the log file that is source of logging data.
base::File file;

// Attempt to open the file if it was not previously opened.
if (!file_.IsValid()) {
file_.Initialize(GetLogFilePath(),
base::File::FLAG_OPEN | base::File::FLAG_READ);
if (!file_.IsValid())
return;

file_cursor_position_ = 0;
file_inode_ = GetInodeValue(GetLogFilePath());
}
file.Initialize(GetLogFilePath(),
base::File::FLAG_OPEN | base::File::FLAG_READ);
if (!file.IsValid())
return;

// Keeps track of how much data has been read or skipped from |file|.
size_t file_cursor_position = 0;

// File system inode value that was associated with |log_file_path_| when it
// was originally opened for reading.
ino_t file_inode = GetInodeValue(GetLogFilePath());

// Check for file size reset.
const size_t length = file_.GetLength();
if (length < file_cursor_position_) {
file_cursor_position_ = 0;
file_.Seek(base::File::FROM_BEGIN, 0);
}
const size_t length = file.GetLength();

// Check for large read and skip forward to avoid out-of-memory conditions.
if (length - file_cursor_position_ > max_read_size_) {
if (length > max_read_size_) {
bytes_skipped = true;
file_.Seek(base::File::FROM_END, -max_read_size_);
// Update |file_cursor_position_| to support the file size reset check.
file_cursor_position_ = length - max_read_size_;
file.Seek(base::File::FROM_END, -max_read_size_);
// Update |file_cursor_position| to support the file size reset check.
file_cursor_position = length - max_read_size_;
}

// The calculated amount of data to read, after adjusting for
// |max_read_size_|.
const size_t size_to_read = length - file_cursor_position_;
const size_t size_to_read = length - file_cursor_position;

// Trim down the previously read data before starting a new read.
const size_t available_previous_read_size = max_read_size_ - size_to_read;
Expand All @@ -179,11 +178,10 @@ void SingleLogFileLogSource::ContinueReadFile(
// Read from file until end.
std::string new_result_string;
new_result_string.resize(size_to_read);
size_t size_read =
file_.ReadAtCurrentPos(&new_result_string[0], size_to_read);
size_t size_read = file.ReadAtCurrentPos(&new_result_string[0], size_to_read);
new_result_string.resize(size_read);

const bool file_was_rotated = file_inode_ != GetInodeValue(GetLogFilePath());
const bool file_was_rotated = file_inode != GetInodeValue(GetLogFilePath());
const bool should_handle_file_rotation =
file_was_rotated && num_rotations_allowed > 0;

Expand All @@ -200,24 +198,20 @@ void SingleLogFileLogSource::ContinueReadFile(
// itself.
size_t adjusted_size_read =
last_newline_pos == std::string::npos ? 0 : last_newline_pos + 1;
file_.Seek(base::File::FROM_CURRENT, -size_read + adjusted_size_read);
file.Seek(base::File::FROM_CURRENT, -size_read + adjusted_size_read);
new_result_string.resize(adjusted_size_read);

// Update |size_read| to reflect that the read was only up to the last
// newline.
size_read = adjusted_size_read;
}

file_cursor_position_ += size_read;

result_string->append(new_result_string);

// If the file was rotated, close the file handle and call this function
// again, to read from the new file.
if (should_handle_file_rotation) {
file_.Close();
file_cursor_position_ = 0;
file_inode_ = 0;
file.Close();
ContinueReadFile(std::move(result_string), bytes_skipped,
num_rotations_allowed - 1, response);
} else {
Expand Down
14 changes: 2 additions & 12 deletions chrome/browser/ash/system_logs/single_log_file_log_source.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ class Time;

namespace system_logs {

// Gathers log data from a single source, possibly incrementally.
// Gathers log data from a single source.
class SingleLogFileLogSource : public SystemLogsSource {
public:
enum class SupportedSource {
Expand Down Expand Up @@ -103,19 +103,9 @@ class SingleLogFileLogSource : public SystemLogsSource {
// Path to system log file directory.
base::FilePath log_file_dir_path_;

// The maximum size of a read from |file_|.
// The maximum size of a read from the system log file.
size_t max_read_size_;

// Keeps track of how much data has been read or skipped from |file_|.
size_t file_cursor_position_;

// Handle for reading the log file that is source of logging data.
base::File file_;

// File system inode value that was associated with |log_file_path_| when it
// was originally opened for reading.
ino_t file_inode_;

base::WeakPtrFactory<SingleLogFileLogSource> weak_ptr_factory_{this};

DISALLOW_COPY_AND_ASSIGN(SingleLogFileLogSource);
Expand Down
196 changes: 8 additions & 188 deletions chrome/browser/ash/system_logs/single_log_file_log_source_unittest.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -169,62 +169,18 @@ TEST_F(SingleLogFileLogSourceTest, IncrementalReads) {
FetchFromSource();

EXPECT_EQ(2, num_callback_calls());
EXPECT_EQ("The quick brown fox jumps over the lazy dog\n", latest_response());
EXPECT_EQ("Hello world!\nThe quick brown fox jumps over the lazy dog\n",
latest_response());

EXPECT_TRUE(AppendToFile(base::FilePath("messages"),
"Some like it hot.\nSome like it cold\n"));
FetchFromSource();

EXPECT_EQ(3, num_callback_calls());
EXPECT_EQ("Some like it hot.\nSome like it cold\n", latest_response());

// As a sanity check, read entire contents of file separately to make sure it
// was written incrementally, and hence read incrementally.
std::string file_contents;
EXPECT_TRUE(base::ReadFileToString(log_file_path(), &file_contents));
EXPECT_EQ(
"Hello world!\nThe quick brown fox jumps over the lazy dog\n"
"Some like it hot.\nSome like it cold\n",
file_contents);
}

// The log files read by SingleLogFileLogSource are not expected to be
// overwritten. This test is just to ensure that the SingleLogFileLogSource
// class is robust enough not to break in the event of an overwrite.
TEST_F(SingleLogFileLogSourceTest, FileOverwrite) {
InitializeSource(SingleLogFileLogSource::SupportedSource::kUiLatest);

EXPECT_TRUE(AppendToFile(base::FilePath("ui/ui.LATEST"), "0123456789\n"));
FetchFromSource();

EXPECT_EQ(1, num_callback_calls());
EXPECT_EQ("0123456789\n", latest_response());

// Overwrite the file.
EXPECT_TRUE(WriteFile(base::FilePath("ui/ui.LATEST"), "abcdefg\n"));
FetchFromSource();

// Should re-read from the beginning.
EXPECT_EQ(2, num_callback_calls());
EXPECT_EQ("abcdefg\n", latest_response());

// Append to the file to make sure incremental read still works.
EXPECT_TRUE(AppendToFile(base::FilePath("ui/ui.LATEST"), "hijk\n"));
FetchFromSource();

EXPECT_EQ(3, num_callback_calls());
EXPECT_EQ("hijk\n", latest_response());

// Overwrite again, this time with a longer length than the existing file.
// Previous contents:
// abcdefg~hijk~ <-- "~" is a single-char representation of newline.
// New contents:
// lmnopqrstuvwxyz~ <-- excess text beyond end of prev contents: "yz~"
EXPECT_TRUE(WriteFile(base::FilePath("ui/ui.LATEST"), "lmnopqrstuvwxyz\n"));
FetchFromSource();

EXPECT_EQ(4, num_callback_calls());
EXPECT_EQ("yz\n", latest_response());
"Hello world!\nThe quick brown fox jumps over the lazy dog\nSome like it "
"hot.\nSome like it cold\n",
latest_response());
}

TEST_F(SingleLogFileLogSourceTest, IncompleteLines) {
Expand Down Expand Up @@ -255,52 +211,14 @@ TEST_F(SingleLogFileLogSourceTest, IncompleteLines) {
FetchFromSource();

EXPECT_EQ(4, num_callback_calls());
EXPECT_EQ("Hello world\n", latest_response());
EXPECT_EQ("0123456789abcdefghijk\nHello world\n", latest_response());

EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "\n"));
FetchFromSource();

EXPECT_EQ(5, num_callback_calls());
EXPECT_EQ("Goodbye world\n", latest_response());
}

TEST_F(SingleLogFileLogSourceTest, HandleLogFileRotation) {
InitializeSource(SingleLogFileLogSource::SupportedSource::kMessages);

EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "1st log file\n"));
FetchFromSource();
EXPECT_EQ(1, num_callback_calls());
EXPECT_EQ("1st log file\n", latest_response());

// Rotate file. Make sure the rest of the old file and the contents of the new
// file are both read.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "More 1st log file\n"));
EXPECT_TRUE(
RotateFile(base::FilePath("messages"), base::FilePath("messages.1")));
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "2nd log file\n"));

FetchFromSource();
EXPECT_EQ(2, num_callback_calls());
EXPECT_EQ("More 1st log file\n2nd log file\n", latest_response());

// Rotate again, but this time omit the newline before rotating.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "No newline here..."));
EXPECT_TRUE(
RotateFile(base::FilePath("messages"), base::FilePath("messages.1")));
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "3rd log file\n"));
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "Also no newline here"));

FetchFromSource();
EXPECT_EQ(3, num_callback_calls());
// Make sure the rotation didn't break anything: the last part of the new file
// does not end with a newline; thus the new file should not be read.
EXPECT_EQ("No newline here...3rd log file\n", latest_response());

// Finish the previous read attempt by adding the missing newline.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "...yet\n"));
FetchFromSource();
EXPECT_EQ(4, num_callback_calls());
EXPECT_EQ("Also no newline here...yet\n", latest_response());
EXPECT_EQ("0123456789abcdefghijk\nHello world\nGoodbye world\n",
latest_response());
}

TEST_F(SingleLogFileLogSourceTest, ReadAtMaxReadSizeNotLimited) {
Expand Down Expand Up @@ -334,104 +252,6 @@ TEST_F(SingleLogFileLogSourceTest, ReadOverMaxReadSizeLimitedToTail) {
latest_response());
}

TEST_F(SingleLogFileLogSourceTest, ReadOverMaxReadSizeBeforeRotate) {
InitializeSource(SingleLogFileLogSource::SupportedSource::kMessages);
SetMaxReadSize(14);

EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "1st log file\n"));
EXPECT_TRUE(
AppendToFile(base::FilePath("messages"), "Exceeds max read size\n"));
FetchFromSource();
EXPECT_EQ(1, num_callback_calls());
EXPECT_EQ("<earlier logs truncated>\n<partial line>max read size\n",
latest_response());

// Rotate file. Make sure the rest of the old file and the contents of the new
// file are both read.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "More\n"));
EXPECT_TRUE(
RotateFile(base::FilePath("messages"), base::FilePath("messages.1")));
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "2nd file\n"));

FetchFromSource();
EXPECT_EQ(2, num_callback_calls());
EXPECT_EQ("More\n2nd file\n", latest_response());

// Rotate again, but this time omit the newline before rotating.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"),
"Long line without a newline ... "));
EXPECT_TRUE(
RotateFile(base::FilePath("messages"), base::FilePath("messages.1")));
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "ended\n"));
// Partial line counted against max read size.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "partial"));

FetchFromSource();
EXPECT_EQ(3, num_callback_calls());
EXPECT_EQ("<earlier logs truncated>\n<partial line> ended\n",
latest_response());
}

TEST_F(SingleLogFileLogSourceTest, ReadOverMaxReadSizeAfterRotate) {
InitializeSource(SingleLogFileLogSource::SupportedSource::kMessages);
SetMaxReadSize(14);

EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "1st\n"));
FetchFromSource();
EXPECT_EQ(1, num_callback_calls());
EXPECT_EQ("1st\n", latest_response());

// Rotate file. Make sure the rest of the old file and the contents of the new
// file are both read.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "More\n"));
EXPECT_TRUE(
RotateFile(base::FilePath("messages"), base::FilePath("messages.1")));
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "2nd file\n"));
EXPECT_TRUE(
AppendToFile(base::FilePath("messages"), "More data in 2nd file\n"));

FetchFromSource();
EXPECT_EQ(2, num_callback_calls());
EXPECT_EQ("<earlier logs truncated>\n<partial line>a in 2nd file\n",
latest_response());

// Rotate again, but this time omit the newline before rotating.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "Start ... "));
EXPECT_TRUE(
RotateFile(base::FilePath("messages"), base::FilePath("messages.1")));
EXPECT_TRUE(AppendToFile(base::FilePath("messages"),
"ended here but is a long line\n"));
// Partial line counted against max read size.
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "partial"));

FetchFromSource();
EXPECT_EQ(3, num_callback_calls());
EXPECT_EQ("<earlier logs truncated>\n<partial line>g line\n",
latest_response());
}

TEST_F(SingleLogFileLogSourceTest, ReadOverMaxReadSizeBeforeAndAfterRotate) {
InitializeSource(SingleLogFileLogSource::SupportedSource::kMessages);
SetMaxReadSize(14);

EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "1st log file\n"));
FetchFromSource();
EXPECT_EQ(1, num_callback_calls());
EXPECT_EQ("1st log file\n", latest_response());

EXPECT_TRUE(
AppendToFile(base::FilePath("messages"), "Exceeds max read size 1\n"));
EXPECT_TRUE(
RotateFile(base::FilePath("messages"), base::FilePath("messages.1")));
EXPECT_TRUE(AppendToFile(base::FilePath("messages"), "2nd file\n"));
EXPECT_TRUE(
AppendToFile(base::FilePath("messages"), "Exceeds max read size 2\n"));
FetchFromSource();
EXPECT_EQ(2, num_callback_calls());
EXPECT_EQ("<earlier logs truncated>\n<partial line>x read size 2\n",
latest_response());
}

TEST_F(SingleLogFileLogSourceTest, LongPartialLineEventuallySkipped) {
InitializeSource(SingleLogFileLogSource::SupportedSource::kMessages);
SetMaxReadSize(14);
Expand Down

0 comments on commit c31021a

Please sign in to comment.