Skip to content
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

CBL-5425: Binary Encoder to encode the (Logging) object path #1986

Merged
merged 1 commit into from
Mar 27, 2024
Merged

CBL-5425: Binary Encoder to encode the (Logging) object path #1986

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
10 changes: 6 additions & 4 deletions LiteCore/Support/LogEncoder.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -87,23 +87,25 @@ namespace litecore {
_lastElapsed = elapsed;
_writeUVarInt(delta);

// Write level, domain, format string:
// Write level, domain
_writer.write(&_level, sizeof(_level));
_writeStringToken(domain ? domain : "");

// Write object path
const auto objRef = (unsigned)object;
_writeUVarInt(objRef);
if ( object != ObjectRef::None && _seenObjects.find(objRef) == _seenObjects.end() ) {
_seenObjects.insert(objRef);
const auto i = objectMap.find(objRef);
if ( i == objectMap.end() ) {
auto objPath = LogDomain::getObjectPath(objRef, objectMap);
if ( objPath.empty() ) {
_writer.write({"?\0", 2});
} else {
_writer.write(slice(i->second.first.c_str()));
_writer.write(slice(objPath.c_str()));
_writer.write("\0", 1);
}
}

// Write format string:
_writeStringToken(format);

// Parse the format string looking for substitutions:
Expand Down
8 changes: 4 additions & 4 deletions LiteCore/Support/Logging.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -538,11 +538,11 @@ namespace litecore {
ss << "/" << iter->second.first << "#" << iter->first;
}

std::string LogDomain::getObjectPath(unsigned obj) {
auto iter = sObjectMap.find(obj);
if ( iter == sObjectMap.end() ) { return ""; }
std::string LogDomain::getObjectPath(unsigned obj, const ObjectMap& objMap) {
auto iter = objMap.find(obj);
if ( iter == objMap.end() ) { return ""; }
std::stringstream ss;
getObjectPathRecur(sObjectMap, iter, ss);
getObjectPathRecur(objMap, iter, ss);
return ss.str() + "/";
}

Expand Down
16 changes: 10 additions & 6 deletions LiteCore/Support/Logging.hh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -120,14 +120,18 @@ namespace litecore {
static unsigned warningCount(); ///< Number of warnings logged since launch
static unsigned errorCount(); ///< Number of errors logged since launch

static std::string getObjectPath(unsigned obj, const ObjectMap& objMap);

private:
friend class Logging;
static std::string getObject(unsigned);
unsigned registerObject(const void* object, const unsigned* val, const std::string& description,
const std::string& nickname, LogLevel level);
static bool registerParentObject(unsigned object, unsigned parentObject);
static void unregisterObject(unsigned obj);
static std::string getObjectPath(unsigned obj);
static std::string getObject(unsigned);
unsigned registerObject(const void* object, const unsigned* val, const std::string& description,
const std::string& nickname, LogLevel level);
static bool registerParentObject(unsigned object, unsigned parentObject);
static void unregisterObject(unsigned obj);

static std::string getObjectPath(unsigned obj) { return getObjectPath(obj, sObjectMap); }

static inline size_t addObjectPath(char* destBuf, size_t bufSize, unsigned obj);
void vlog(LogLevel level, unsigned obj, bool callback, const char* fmt, va_list) __printflike(5, 0);

Expand Down
49 changes: 25 additions & 24 deletions LiteCore/tests/LogEncoderTest.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,8 +24,9 @@
using namespace std;

// These formats are used in the decoded log files. They are UTC times.
#define DATESTAMP "\\w+ \\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}Z"
#define TIMESTAMP "\\d{2}:\\d{2}:\\d{2}\\.\\d{6}Z\\| "
#define DATESTAMP "\\w+ \\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}Z"
#define TIMESTAMP "\\d{2}:\\d{2}:\\d{2}\\.\\d{6}Z\\| "
#define TIMESTAMP_NEW "\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}\\.\\d{6}Z"

constexpr size_t kFolderBufSize = 64;

Expand Down Expand Up @@ -56,7 +57,7 @@ static string dumpLog(const string& encoded, const vector<string>& levelNames) {
return result;
}

TEST_CASE("LogEncoder formatting", "[.loggingDisabled][Log]") {
TEST_CASE("LogEncoder formatting", "[Log]") {
// For checking the timestamp in the path to the binary log file.
#ifdef LITECORE_CPPTEST
string logPath = litecore::createLogPath_forUnitTest(LogLevel::Info);
Expand All @@ -82,21 +83,21 @@ TEST_CASE("LogEncoder formatting", "[.loggingDisabled][Log]") {
string result = dumpLog(encoded, {});

regex expected(
TIMESTAMP
"---- Logging begins on " DATESTAMP " ----\\n" TIMESTAMP
"Unsigned 1234567890, Long 2345678901, LongLong 123456789123456789, Size abcdabcd, Pointer "
"0x7fff5fbc\\n" TIMESTAMP
"Int -1234567890, Long -234567890, LongLong -123456789123456789, Size -1234567890, Char @\\n" TIMESTAMP
"Int 1234567890, Long 234567890, LongLong 123456789123456789, Size 1234567890, Char @\\n" TIMESTAMP
"String is 'C string', slice is 'hello' \\(hex 68656c6c6f\\)\\n");
TIMESTAMP_NEW
" ---- Logging begins on " DATESTAMP " ----\\n" TIMESTAMP_NEW
" Unsigned 1234567890, Long 2345678901, LongLong 123456789123456789, Size abcdabcd, Pointer "
"0x7fff5fbc\\n" TIMESTAMP_NEW " Int -1234567890, Long -234567890, LongLong -123456789123456789, Size "
"-1234567890, Char @\\n" TIMESTAMP_NEW
" Int 1234567890, Long 234567890, LongLong 123456789123456789, Size 1234567890, Char @\\n" TIMESTAMP_NEW
" String is 'C string', slice is 'hello' \\(hex 68656c6c6f\\)\\n");
CHECK(regex_match(result, expected));

#ifdef LITECORE_CPPTEST
// We insert timestamp in milliseconds (w.r.t. UTC) in the path to the binary log files.
// We also add the timestamp inside the log. When decoded to string, it is
// represented as UTC time, like, "Monday 2023-07-03T19:25:01Z"
// We want to ensure they are consistent.
regex catchUTCTimeTag{"^" TIMESTAMP "---- Logging begins on (" DATESTAMP ")"};
regex catchUTCTimeTag{"^" TIMESTAMP_NEW " ---- Logging begins on (" DATESTAMP ")"};
smatch m;
REQUIRE(regex_search(result, m, catchUTCTimeTag));
CHECK(m.size() == 2);
Expand Down Expand Up @@ -158,11 +159,11 @@ TEST_CASE("LogEncoder levels/domains", "[Log]") {
}
}

TEST_CASE("LogEncoder tokens", "[.loggingDisabled][Log]") {
TEST_CASE("LogEncoder tokens", "[Log]") {
LogDomain::ObjectMap objects;
objects.emplace(1, make_pair("Tweedledum", 0));
objects.emplace(2, make_pair("rattle", 0));
objects.emplace(3, make_pair("Tweedledee", 0));
objects.emplace(2, make_pair("rattle", 1));
objects.emplace(3, make_pair("Tweedledee", 2));

stringstream out;
stringstream out2;
Expand All @@ -176,18 +177,18 @@ TEST_CASE("LogEncoder tokens", "[.loggingDisabled][Log]") {
}
string encoded = out.str();
string result = dumpLog(encoded, {});
regex expected(TIMESTAMP "---- Logging begins on " DATESTAMP " ----\\n" TIMESTAMP
"\\{1\\|Tweedledum\\} I'm Tweedledum\\n" TIMESTAMP
"\\{3\\|Tweedledee\\} I'm Tweedledee\\n" TIMESTAMP
"\\{2\\|rattle\\} and I'm the rattle\\n");
regex expected(TIMESTAMP_NEW " ---- Logging begins on " DATESTAMP " ----\\n" TIMESTAMP_NEW
" \\{1\\|/Tweedledum#1/\\} I'm Tweedledum\\n" TIMESTAMP_NEW
" \\{3\\|/Tweedledum#1/rattle#2/Tweedledee#3/\\} I'm Tweedledee\\n" TIMESTAMP_NEW
" \\{2\\|/Tweedledum#1/rattle#2/\\} and I'm the rattle\\n");
CHECK(regex_match(result, expected));

encoded = out2.str();
result = dumpLog(encoded, {});

// Confirm other encoders have the same ref for "rattle"
expected = regex(TIMESTAMP "---- Logging begins on " DATESTAMP " ----\\n" TIMESTAMP
"\\{2\\|rattle\\} Am I the rattle too\\?\\n");
expected = regex(TIMESTAMP_NEW " ---- Logging begins on " DATESTAMP " ----\\n" TIMESTAMP_NEW
" \\{2\\|/Tweedledum#1/rattle#2/\\} Am I the rattle too\\?\\n");
CHECK(regex_match(result, expected));
}

Expand Down Expand Up @@ -441,7 +442,7 @@ TEST_CASE("Logging throw in c4", "[Log]") {
LogDomain::writeEncodedLogsTo(prevOptions);
}

TEST_CASE("Logging plaintext", "[.loggingDisabled][Log]") {
TEST_CASE("Logging plaintext", "[Log]") {
char folderName[kFolderBufSize];
snprintf(folderName, kFolderBufSize, "Log_Plaintext_%" PRIms "/", chrono::milliseconds(time(nullptr)).count());
FilePath tmpLogDir = TestFixture::sTempDir[folderName];
Expand Down Expand Up @@ -480,10 +481,10 @@ TEST_CASE("Logging plaintext", "[.loggingDisabled][Log]") {
n++;
#endif
CHECK(lines[n++] == "---- Hello ----");
regex utctimeRe{"^" TIMESTAMP};
regex utctimeRe{"^" TIMESTAMP_NEW};
CHECK(regex_search(lines[n], utctimeRe));
CHECK(lines[n].find("[DB]") != string::npos);
CHECK(lines[n].find("{dummy#") != string::npos);
CHECK(lines[n].find(" DB ") != string::npos);
CHECK(lines[n].find("/dummy#") != string::npos);
CHECK(lines[n].find("This will be in plaintext") != string::npos);

LogDomain::writeEncodedLogsTo(prevOptions); // undo writeEncodedLogsTo() call above
Expand Down
Loading