Skip to content

fix: Handle first timestamp in deployment logs more carefully #1914

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
vpodzime wants to merge 1 commit into
base: master
Choose a base branch
from
Open

fix: Handle first timestamp in deployment logs more carefully #1914

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 23 additions & 0 deletions src/mender-update/deployments/deployments.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -534,7 +534,30 @@ error::Error JsonLogMessagesReader::SanitizeLogs() {
if (!clean_logs_) {
auto bad_data_msg_tstamp_start =
bad_data_msg_.begin() + 15; // len(R"({"timestamp": ")")

// The actual timestamp from logs can potential have a different
// (likely lower) time resolution and thus length than our default.
const auto first_tstamp_size = first_tstamp.size();
if (first_tstamp_size > default_tstamp_.size()) {
// In case the time resolution is higher and the timestamp
// longer (unlikely to happen)
if (first_tstamp[first_tstamp_size - 1] == 'Z') {
first_tstamp[default_tstamp_.size() - 1] = 'Z';
}
first_tstamp.resize(default_tstamp_.size());
}
copy_n(first_tstamp.cbegin(), first_tstamp.size(), bad_data_msg_tstamp_start);
if (first_tstamp.size() < default_tstamp_.size()) {
// Add a closing '"' right after the timestamp and fill in the
// rest of the space in the template with spaces that have no
// effect in JSON.
bad_data_msg_tstamp_start[first_tstamp.size()] = '"';
for (auto it = bad_data_msg_tstamp_start + first_tstamp.size() + 1;
it < bad_data_msg_tstamp_start + default_tstamp_.size() + 1;
it++) {
*it = ' ';
}
}
}
}
return err;
Expand Down
77 changes: 77 additions & 0 deletions tests/src/mender-update/deployments_test.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1153,6 +1153,83 @@ ed"}
EXPECT_EQ(ss.str(), expected_data);
}

TEST_F(DeploymentsTests, JsonLogMessageReaderMalformedJsonShortFirstTstampTest) {
const string messages =
R"({"timestamp": "2016-03-11T13:03:17.063493Z", "level": "INFO", "message": "OK"}
{"timestamp": "2020-03-11T13:03:17.063493443Z", "level": "WARNING", "message": "Warnings appear
ed"}
{"timestamp": "2021-03-11T13:03:17.063493443Z", "level": "DEBUG", "message": "Just some noise"}
)";
const string test_log_file_path = test_state_dir.Path() + "/test.log";
ofstream os {test_log_file_path};
auto err = io::WriteStringIntoOfstream(os, messages);
ASSERT_EQ(err, error::NoError);
os.close();

// Corrupted line should be replaced with timestamp from previous valid line
// (2016-03-11...), the first extra message should use the first timestamp
// in a valid format, even when the timestamp is shorter than expected due
// to lower time resolution.
string expected_data =
R"delim({"messages":[{"timestamp": "2016-03-11T13:03:17.063493Z" , "level": "ERROR", "message": "(THE ORIGINAL LOGS CONTAINED INVALID ENTRIES)"},{"timestamp": "2016-03-11T13:03:17.063493Z", "level": "INFO", "message": "OK"},{"timestamp": "2016-03-11T13:03:17.063493Z", "level": "ERROR", "message": "(CORRUPTED LOG DATA)"},{"timestamp": "2016-03-11T13:03:17.063493Z", "level": "ERROR", "message": "(CORRUPTED LOG DATA)"},{"timestamp": "2021-03-11T13:03:17.063493443Z", "level": "DEBUG", "message": "Just some noise"}]})delim";

deps::JsonLogMessagesReader logs_reader {test_log_file_path};
EXPECT_EQ(logs_reader.SanitizeLogs(), error::NoError);
EXPECT_EQ(logs_reader.TotalDataSize(), expected_data.length());

stringstream ss;
vector<uint8_t> buf(1024);
size_t n_read = 0;
do {
auto ex_n_read = logs_reader.Read(buf.begin(), buf.end());
ASSERT_TRUE(ex_n_read);
n_read = ex_n_read.value();
for (auto it = buf.begin(); it < buf.begin() + n_read; it++) {
ss << static_cast<char>(*it);
}
} while (n_read > 0);
EXPECT_EQ(ss.str(), expected_data);
}

TEST_F(DeploymentsTests, JsonLogMessageReaderMalformedJsonLongFirstTstampTest) {
const string messages =
R"({"timestamp": "2016-03-11T13:03:17.06349344355Z", "level": "INFO", "message": "OK"}
{"timestamp": "2020-03-11T13:03:17.063493443Z", "level": "WARNING", "message": "Warnings appear
ed"}
{"timestamp": "2021-03-11T13:03:17.063493443Z", "level": "DEBUG", "message": "Just some noise"}
)";
const string test_log_file_path = test_state_dir.Path() + "/test.log";
ofstream os {test_log_file_path};
auto err = io::WriteStringIntoOfstream(os, messages);
ASSERT_EQ(err, error::NoError);
os.close();

// Corrupted line should be replaced with timestamp from previous valid line
// (2016-03-11...), the first extra message should use the first timestamp
// in a valid format, even when the timestamp is longer than expected due to
// lower time resolution (the other lines can use the full timestamps, they
// don't rely on a template that needs to be filled-in).
string expected_data =
R"delim({"messages":[{"timestamp": "2016-03-11T13:03:17.063493443Z", "level": "ERROR", "message": "(THE ORIGINAL LOGS CONTAINED INVALID ENTRIES)"},{"timestamp": "2016-03-11T13:03:17.06349344355Z", "level": "INFO", "message": "OK"},{"timestamp": "2016-03-11T13:03:17.06349344355Z", "level": "ERROR", "message": "(CORRUPTED LOG DATA)"},{"timestamp": "2016-03-11T13:03:17.06349344355Z", "level": "ERROR", "message": "(CORRUPTED LOG DATA)"},{"timestamp": "2021-03-11T13:03:17.063493443Z", "level": "DEBUG", "message": "Just some noise"}]})delim";

deps::JsonLogMessagesReader logs_reader {test_log_file_path};
EXPECT_EQ(logs_reader.SanitizeLogs(), error::NoError);
EXPECT_EQ(logs_reader.TotalDataSize(), expected_data.length());

stringstream ss;
vector<uint8_t> buf(1024);
size_t n_read = 0;
do {
auto ex_n_read = logs_reader.Read(buf.begin(), buf.end());
ASSERT_TRUE(ex_n_read);
n_read = ex_n_read.value();
for (auto it = buf.begin(); it < buf.begin() + n_read; it++) {
ss << static_cast<char>(*it);
}
} while (n_read > 0);
EXPECT_EQ(ss.str(), expected_data);
}

TEST_F(DeploymentsTests, JsonLogMessageReaderBinaryDataTest) {
// Create file with binary data directly
const string test_log_file_path = test_state_dir.Path() + "/test.log";
Expand Down