Signed-off-by: JCW <a1q123456@users.noreply.github.com>
This commit is contained in:
JCW
2025-09-04 16:31:39 +01:00
parent e898d98e0a
commit 2491b28fcd
8 changed files with 109 additions and 123 deletions

View File

@@ -39,7 +39,8 @@
namespace ripple {
namespace {
constexpr auto FLUSH_INTERVAL = std::chrono::milliseconds(10); // Max delay before flush
constexpr auto FLUSH_INTERVAL =
std::chrono::milliseconds(10); // Max delay before flush
}
Logs::Sink::Sink(
@@ -128,7 +129,8 @@ Logs::File::write(std::string_view text)
Logs::Logs(beast::severities::Severity thresh)
: thresh_(thresh) // default severity
, writeBuffer_(batchBuffer_) // Initially, entire buffer is available for writing
, writeBuffer_(
batchBuffer_) // Initially, entire buffer is available for writing
, readBuffer_(batchBuffer_.data(), 0) // No data ready to flush initially
{
}
@@ -193,41 +195,43 @@ Logs::write(
{
std::string s;
format(s, text, level, partition);
// Console output still immediate for responsiveness
if (!silent_)
std::cerr << s << '\n';
// Add to batch buffer for file output
{
std::lock_guard lock(batchMutex_);
size_t logSize = s.size() + 1; // +1 for newline
// If log won't fit in current write buffer, flush first
if (logSize > writeBuffer_.size()) {
if (logSize > writeBuffer_.size())
{
flushBatchUnsafe();
}
// Copy log into write buffer
std::copy(s.begin(), s.end(), writeBuffer_.begin());
writeBuffer_[s.size()] = '\n';
// Update spans: expand read buffer, shrink write buffer
size_t totalUsed = readBuffer_.size() + logSize;
readBuffer_ = std::span<char>(batchBuffer_.data(), totalUsed);
writeBuffer_ = std::span<char>(batchBuffer_.data() + totalUsed,
batchBuffer_.size() - totalUsed);
writeBuffer_ = std::span<char>(
batchBuffer_.data() + totalUsed, batchBuffer_.size() - totalUsed);
auto now = std::chrono::steady_clock::now();
bool shouldFlush = (now - lastFlush_) >= FLUSH_INTERVAL;
if (shouldFlush) {
if (shouldFlush)
{
flushBatchUnsafe();
lastFlush_ = now;
}
}
// VFALCO TODO Fix console output
// if (console)
// out_.write_console(s);
@@ -245,10 +249,10 @@ Logs::flushBatchUnsafe()
{
if (readBuffer_.empty())
return;
// Write the read buffer contents to file in one system call
file_.write(std::string_view{readBuffer_.data(), readBuffer_.size()});
// Reset spans: entire buffer available for writing, nothing to read
writeBuffer_ = std::span<char>(batchBuffer_);
readBuffer_ = std::span<char>(batchBuffer_.data(), 0);

View File

@@ -19,12 +19,12 @@
#include <xrpl/beast/utility/Journal.h>
#include <chrono>
#include <ios>
#include <ostream>
#include <ranges>
#include <string>
#include <thread>
#include <chrono>
namespace beast {
@@ -35,45 +35,50 @@ namespace {
std::string_view
fastTimestampToString(std::int64_t milliseconds_since_epoch)
{
thread_local char buffer[64]; // "2024-01-15T10:30:45.123Z"
thread_local char buffer[64]; // "2024-01-15T10:30:45.123Z"
// Precomputed lookup table for 2-digit numbers 00-99
static constexpr char digits[200] = {
'0','0','0','1','0','2','0','3','0','4','0','5','0','6','0','7','0','8','0','9',
'1','0','1','1','1','2','1','3','1','4','1','5','1','6','1','7','1','8','1','9',
'2','0','2','1','2','2','2','3','2','4','2','5','2','6','2','7','2','8','2','9',
'3','0','3','1','3','2','3','3','3','4','3','5','3','6','3','7','3','8','3','9',
'4','0','4','1','4','2','4','3','4','4','4','5','4','6','4','7','4','8','4','9',
'5','0','5','1','5','2','5','3','5','4','5','5','5','6','5','7','5','8','5','9',
'6','0','6','1','6','2','6','3','6','4','6','5','6','6','6','7','6','8','6','9',
'7','0','7','1','7','2','7','3','7','4','7','5','7','6','7','7','7','8','7','9',
'8','0','8','1','8','2','8','3','8','4','8','5','8','6','8','7','8','8','8','9',
'9','0','9','1','9','2','9','3','9','4','9','5','9','6','9','7','9','8','9','9'
};
constexpr std::int64_t UNIX_EPOCH_DAYS = 719468; // Days from year 0 to 1970-01-01
'0', '0', '0', '1', '0', '2', '0', '3', '0', '4', '0', '5', '0', '6',
'0', '7', '0', '8', '0', '9', '1', '0', '1', '1', '1', '2', '1', '3',
'1', '4', '1', '5', '1', '6', '1', '7', '1', '8', '1', '9', '2', '0',
'2', '1', '2', '2', '2', '3', '2', '4', '2', '5', '2', '6', '2', '7',
'2', '8', '2', '9', '3', '0', '3', '1', '3', '2', '3', '3', '3', '4',
'3', '5', '3', '6', '3', '7', '3', '8', '3', '9', '4', '0', '4', '1',
'4', '2', '4', '3', '4', '4', '4', '5', '4', '6', '4', '7', '4', '8',
'4', '9', '5', '0', '5', '1', '5', '2', '5', '3', '5', '4', '5', '5',
'5', '6', '5', '7', '5', '8', '5', '9', '6', '0', '6', '1', '6', '2',
'6', '3', '6', '4', '6', '5', '6', '6', '6', '7', '6', '8', '6', '9',
'7', '0', '7', '1', '7', '2', '7', '3', '7', '4', '7', '5', '7', '6',
'7', '7', '7', '8', '7', '9', '8', '0', '8', '1', '8', '2', '8', '3',
'8', '4', '8', '5', '8', '6', '8', '7', '8', '8', '8', '9', '9', '0',
'9', '1', '9', '2', '9', '3', '9', '4', '9', '5', '9', '6', '9', '7',
'9', '8', '9', '9'};
constexpr std::int64_t UNIX_EPOCH_DAYS =
719468; // Days from year 0 to 1970-01-01
std::int64_t seconds = milliseconds_since_epoch / 1000;
int ms = milliseconds_since_epoch % 1000;
std::int64_t days = seconds / 86400 + UNIX_EPOCH_DAYS;
int sec_of_day = seconds % 86400;
// Calculate year, month, day from days using Gregorian calendar algorithm
int era = (days >= 0 ? days : days - 146096) / 146097;
int doe = days - era * 146097;
int yoe = (doe - doe/1460 + doe/36524 - doe/146096) / 365;
int yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365;
int year = yoe + era * 400;
int doy = doe - (365*yoe + yoe/4 - yoe/100);
int mp = (5*doy + 2)/153;
int day = doy - (153*mp+2)/5 + 1;
int doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
int mp = (5 * doy + 2) / 153;
int day = doy - (153 * mp + 2) / 5 + 1;
int month = mp + (mp < 10 ? 3 : -9);
year += (month <= 2);
// Calculate hour, minute, second
int hour = sec_of_day / 3600;
int min = (sec_of_day % 3600) / 60;
int sec = sec_of_day % 60;
// Format: "2024-01-15T10:30:45.123Z"
buffer[0] = '0' + year / 1000;
buffer[1] = '0' + (year / 100) % 10;
@@ -99,14 +104,14 @@ fastTimestampToString(std::int64_t milliseconds_since_epoch)
buffer[21] = '0' + (ms / 10) % 10;
buffer[22] = '0' + ms % 10;
buffer[23] = 'Z';
return {buffer, 24};
}
} // anonymous namespace
std::atomic<std::shared_ptr<const std::string>> Journal::globalLogAttributesJson_;
std::size_t Journal::m_filePathOffset_ = 0;
std::string Journal::globalLogAttributesJson_;
std::shared_mutex Journal::globalLogAttributesMutex_;
bool Journal::m_jsonLogsEnabled = false;
thread_local Journal::JsonLogContext Journal::currentJsonLogContext_{};
@@ -230,11 +235,11 @@ Journal::JsonLogContext::reset(
}
{
auto globalAttrs = globalLogAttributesJson_.load();
if (globalAttrs && !globalAttrs->empty())
std::shared_lock lock(globalLogAttributesMutex_);
if (!globalLogAttributesJson_.empty())
{
writer().writeKey("GlobalParams");
writer().writeRaw(*globalAttrs);
writer().writeRaw(globalLogAttributesJson_);
writer().endObject();
}
}
@@ -249,8 +254,9 @@ Journal::JsonLogContext::reset(
writer().writeKey("File");
std::string_view fileName = location.file_name();
std::string_view trimmedFileName = (m_filePathOffset_ < fileName.size())
? fileName.substr(m_filePathOffset_)
constexpr size_t KEEP_CHARS = 10;
std::string_view trimmedFileName = (fileName.size() > KEEP_CHARS)
? fileName.substr(fileName.size() - KEEP_CHARS)
: fileName;
writer().writeString(trimmedFileName);
@@ -265,7 +271,8 @@ Journal::JsonLogContext::reset(
writer().writeString(severityStr);
auto nowMs = std::chrono::duration_cast<std::chrono::milliseconds>(
std::chrono::system_clock::now().time_since_epoch()).count();
std::chrono::system_clock::now().time_since_epoch())
.count();
writer().writeKey("Timestamp");
writer().writeInt(nowMs);
writer().writeKey("Time");
@@ -304,19 +311,6 @@ Journal::formatLog(std::string&& message)
return writer.finish();
}
void
Journal::setRootPath(std::string_view fullPath, std::string_view relativePath)
{
if (relativePath.size() <= fullPath.size() &&
fullPath.ends_with(relativePath))
{
m_filePathOffset_ = fullPath.size() - relativePath.size();
}
else
{
m_filePathOffset_ = 0;
}
}
void
Journal::enableStructuredJournal()

View File

@@ -308,10 +308,12 @@ TEST_CASE("Test setJsonValue")
writer.startObject();
log::detail::setJsonValue<bool>(writer, "testBool", true, &stringBuf);
log::detail::setJsonValue<std::int32_t>(writer, "testInt32", -1, &stringBuf);
log::detail::setJsonValue<std::int32_t>(
writer, "testInt32", -1, &stringBuf);
log::detail::setJsonValue<std::uint32_t>(
writer, "testUInt32", 1, &stringBuf);
log::detail::setJsonValue<std::int64_t>(writer, "testInt64", -1, &stringBuf);
log::detail::setJsonValue<std::int64_t>(
writer, "testInt64", -1, &stringBuf);
log::detail::setJsonValue<std::uint64_t>(
writer, "testUInt64", 1, &stringBuf);
log::detail::setJsonValue<double>(writer, "testDouble", 1.1, &stringBuf);
@@ -327,7 +329,9 @@ TEST_CASE("Test setJsonValue")
writer, "testStream", {}, &stringBuf);
writer.endObject();
CHECK(writer.finish() == R"AAA({"testBool":true,"testInt32":-1,"testUInt32":1,"testInt64":-1,"testUInt64":1,"testDouble":1.1,"testCharStar":"Char*","testStdString":"StdString","testStdStringView":"StdStringView","testToChars":"0","testStream":"0"})AAA");
CHECK(
writer.finish() ==
R"AAA({"testBool":true,"testInt32":-1,"testUInt32":1,"testInt64":-1,"testUInt64":1,"testDouble":1.1,"testCharStar":"Char*","testStdString":"StdString","testStdStringView":"StdStringView","testToChars":"0","testStream":"0"})AAA");
}
TEST_CASE("Test json logging not enabled")
@@ -421,30 +425,24 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log fields")
CHECK(logValue.is_object());
CHECK(logValue.as_object().contains("GlobalParams"));
CHECK(logValue.as_object().contains("JournalParams"));
CHECK(logValue.as_object().contains("MessageParams"));
CHECK(logValue.as_object().contains("Metadata"));
CHECK(logValue.as_object().contains("Message"));
CHECK(logValue.as_object()["GlobalParams"].is_object());
CHECK(logValue.as_object()["JournalParams"].is_object());
CHECK(logValue.as_object()["MessageParams"].is_object());
CHECK(logValue.as_object()["Metadata"].is_object());
CHECK(logValue.as_object()["Message"].is_string());
CHECK(
logValue.as_object()["MessageParams"].as_object().contains("Function"));
CHECK(logValue.as_object()["MessageParams"].as_object().contains("File"));
CHECK(logValue.as_object()["MessageParams"].as_object().contains("Line"));
CHECK(
logValue.as_object()["MessageParams"].as_object().contains("ThreadId"));
CHECK(logValue.as_object()["MessageParams"].as_object().contains("Level"));
CHECK(logValue.as_object()["MessageParams"].as_object().contains("Time"));
CHECK(logValue.as_object()["Metadata"].as_object().contains("Function"));
CHECK(logValue.as_object()["Metadata"].as_object().contains("File"));
CHECK(logValue.as_object()["Metadata"].as_object().contains("Line"));
CHECK(logValue.as_object()["Metadata"].as_object().contains("ThreadId"));
CHECK(logValue.as_object()["Metadata"].as_object().contains("Level"));
CHECK(logValue.as_object()["Metadata"].as_object().contains("Time"));
CHECK(logValue.as_object()["MessageParams"]
.as_object()["Function"]
.is_string());
CHECK(
logValue.as_object()["MessageParams"].as_object()["File"].is_string());
CHECK(
logValue.as_object()["MessageParams"].as_object()["Line"].is_number());
CHECK(logValue.as_object()["Metadata"].as_object()["Function"].is_string());
CHECK(logValue.as_object()["Metadata"].as_object()["File"].is_string());
CHECK(logValue.as_object()["Metadata"].as_object()["Line"].is_number());
CHECK(
logValue.as_object()["Message"].get_string() ==
@@ -462,7 +460,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels")
CHECK(ec == boost::system::errc::success);
CHECK(
logValue.as_object()["MessageParams"]
logValue.as_object()["Metadata"]
.as_object()["Level"]
.get_string() ==
beast::severities::to_string(beast::severities::kTrace));
@@ -477,7 +475,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels")
CHECK(ec == boost::system::errc::success);
CHECK(
logValue.as_object()["MessageParams"]
logValue.as_object()["Metadata"]
.as_object()["Level"]
.get_string() ==
beast::severities::to_string(beast::severities::kDebug));
@@ -492,7 +490,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels")
CHECK(ec == boost::system::errc::success);
CHECK(
logValue.as_object()["MessageParams"]
logValue.as_object()["Metadata"]
.as_object()["Level"]
.get_string() ==
beast::severities::to_string(beast::severities::kInfo));
@@ -507,7 +505,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels")
CHECK(ec == boost::system::errc::success);
CHECK(
logValue.as_object()["MessageParams"]
logValue.as_object()["Metadata"]
.as_object()["Level"]
.get_string() ==
beast::severities::to_string(beast::severities::kWarning));
@@ -522,7 +520,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels")
CHECK(ec == boost::system::errc::success);
CHECK(
logValue.as_object()["MessageParams"]
logValue.as_object()["Metadata"]
.as_object()["Level"]
.get_string() ==
beast::severities::to_string(beast::severities::kError));
@@ -537,7 +535,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels")
CHECK(ec == boost::system::errc::success);
CHECK(
logValue.as_object()["MessageParams"]
logValue.as_object()["Metadata"]
.as_object()["Level"]
.get_string() ==
beast::severities::to_string(beast::severities::kFatal));
@@ -553,9 +551,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log stream")
CHECK(ec == boost::system::errc::success);
CHECK(
logValue.as_object()["MessageParams"]
.as_object()["Level"]
.get_string() ==
logValue.as_object()["Metadata"].as_object()["Level"].get_string() ==
beast::severities::to_string(beast::severities::kError));
}

View File

@@ -1215,10 +1215,6 @@ ApplicationImp::setup(boost::program_options::variables_map const& cmdline)
<< ", Instance Cookie: "
<< log::param("InstanceCookie", instanceCookie_);
beast::Journal::addGlobalAttributes(log::attributes(
log::attr("RippledVersion", BuildInfo::getFullVersionString()),
log::attr("InstanceCookie", to_string(instanceCookie_))));
if (numberOfThreads(*config_) < 2)
{
JLOG(m_journal.warn()) << "Limited to a single I/O service thread by "

View File

@@ -790,11 +790,7 @@ run(int argc, char** argv)
if (config->LOG_STYLE == LogStyle::Json)
{
beast::Journal::setRootPath(std::source_location::current().file_name(), "src/xrpld/app/main/Main.cpp");
beast::Journal::enableStructuredJournal();
beast::Journal::addGlobalAttributes(log::attributes(
log::attr("Application", "rippled"),
log::attr("NetworkID", config->NETWORK_ID)));
}
auto logs = std::make_unique<Logs>(thresh);

View File

@@ -680,7 +680,8 @@ PeerImp::setTimer()
if (ec)
{
JLOG(journal_.error()) << "setTimer: " << log::param("ErrorCode", ec.message());
JLOG(journal_.error())
<< "setTimer: " << log::param("ErrorCode", ec.message());
return;
}
timer_.async_wait(bind_executor(