Skip to content

Commit ed390df

Browse files
committed
fix(logging): format variadic arguments before forwarding to glog
GlogAdaptor::LogV passed its va_list directly to google::RawLog__, which is a printf-style variadic function with no va_list overload. Format conversions then read va_list itself as an argument, producing garbage output such as "0" for %s. Expand arguments with std::vsnprintf into a 2048-byte buffer first and pass result to RawLog__ through a fixed "%s" format. Buffer stays below glog's 3000-byte raw log limit, so long messages are truncated instead of being replaced by glog's "Message was too long" error. Apply same fix to GlogForwardingLogger in logging_test.cpp. Add regression tests for argument formatting and message truncation. Register custom logger creator in a separate death test process, so these tests always exercise default logger regardless of test order.
1 parent d21122e commit ed390df

2 files changed

Lines changed: 68 additions & 18 deletions

File tree

‎src/paimon/common/logging/logging.cpp‎

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121

2222
#include <cerrno>
2323
#include <cstdarg>
24+
#include <cstdio>
2425
#include <cstdlib>
2526
#include <mutex>
2627
#include <optional>
@@ -78,15 +79,23 @@ class GlogAdaptor : public Logger {
7879
public:
7980
void LogV(PaimonLogLevel level, const char* fname, int lineno, const char* function,
8081
const char* fmt, ...) override {
82+
// RawLog__ is variadic and cannot take a va_list, so format the message first.
83+
char message[kMessageBufferSize] = {};
8184
va_list args;
8285
va_start(args, fmt);
83-
google::RawLog__(ToGlogLevel(level), fname, lineno, fmt, args);
86+
std::vsnprintf(message, sizeof(message), fmt, args);
8487
va_end(args);
88+
google::RawLog__(ToGlogLevel(level), fname, lineno, "%s", message);
8589
}
8690

8791
bool IsLevelEnabled(PaimonLogLevel level) const override {
8892
return true;
8993
}
94+
95+
private:
96+
// Stays below glog's 3000-byte raw log buffer, so long messages are truncated
97+
// instead of being replaced by glog's "Message was too long" error.
98+
static constexpr size_t kMessageBufferSize = 2048;
9099
};
91100

92101
std::unique_ptr<Logger> Logger::GetLogger(const std::string& path) {

‎src/paimon/common/logging/logging_test.cpp‎

Lines changed: 58 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,9 @@
2020

2121
#include <atomic>
2222
#include <cstdarg>
23+
#include <cstdio>
24+
#include <cstdlib>
25+
#include <functional>
2326
#include <future>
2427
#include <iostream>
2528
#include <memory>
@@ -40,17 +43,17 @@ namespace {
4043

4144
std::atomic<int> g_creator_calls{0};
4245

43-
// A Logger that forwards to glog exactly like the built-in adaptor. It is used to
44-
// restore behavior-preserving logging after exercising the custom-creator path,
45-
// because the registry cannot be reset to "unset" through the public API.
46+
// A Logger that forwards to glog exactly like the built-in adaptor.
4647
class GlogForwardingLogger : public Logger {
4748
public:
4849
void LogV(PaimonLogLevel level, const char* fname, int lineno, const char* /*function*/,
4950
const char* fmt, ...) override {
51+
char message[2048] = {};
5052
va_list args;
5153
va_start(args, fmt);
52-
google::RawLog__(ToGlog(level), fname, lineno, fmt, args);
54+
std::vsnprintf(message, sizeof(message), fmt, args);
5355
va_end(args);
56+
google::RawLog__(ToGlog(level), fname, lineno, "%s", message);
5457
}
5558

5659
bool IsLevelEnabled(PaimonLogLevel /*level*/) const override {
@@ -70,6 +73,29 @@ class GlogForwardingLogger : public Logger {
7073
}
7174
};
7275

76+
std::string CaptureInfoLogs(const std::function<void()>& log) {
77+
const int32_t prev_stderrthreshold = FLAGS_stderrthreshold;
78+
FLAGS_stderrthreshold = google::GLOG_INFO;
79+
::testing::internal::CaptureStderr();
80+
log();
81+
std::string output = ::testing::internal::GetCapturedStderr();
82+
FLAGS_stderrthreshold = prev_stderrthreshold;
83+
return output;
84+
}
85+
86+
void RegisterCustomLoggerCreatorAndExit() {
87+
g_creator_calls.store(0);
88+
Logger::RegisterLogger([](const std::string& /*path*/) -> std::unique_ptr<Logger> {
89+
g_creator_calls.fetch_add(1);
90+
return std::make_unique<GlogForwardingLogger>();
91+
});
92+
93+
auto logger = Logger::GetLogger("custom_path");
94+
const bool used_creator =
95+
logger && g_creator_calls.load() == 1 && logger->IsLevelEnabled(PAIMON_LOG_LEVEL_INFO);
96+
std::_Exit(used_creator ? 0 : 1);
97+
}
98+
7399
} // namespace
74100
TEST(LoggerTest, TestMultiThreadGetLogger) {
75101
ASSERT_OK_AND_ASSIGN(auto executor, CreateDefaultExecutor(/*thread_count=*/4));
@@ -99,6 +125,30 @@ TEST(LoggerTest, TestLogAllSeverities) {
99125
logger->LogV(PAIMON_LOG_LEVEL_MAX, __FILE__, __LINE__, __FUNCTION__, "max severity");
100126
}
101127

128+
TEST(LoggerTest, TestLogFormatsArguments) {
129+
auto logger = Logger::GetLogger("format_test");
130+
ASSERT_TRUE(logger);
131+
132+
const std::string output = CaptureInfoLogs(
133+
[&]() { PAIMON_LOG_INFO(logger, "name=%s count=%d raw=%s", "paimon", 42, "100%d"); });
134+
ASSERT_NE(output.find("name=paimon count=42 raw=100%d"), std::string::npos) << output;
135+
}
136+
137+
TEST(LoggerTest, TestLogTruncatesLongMessage) {
138+
auto logger = Logger::GetLogger("truncate_test");
139+
ASSERT_TRUE(logger);
140+
constexpr size_t kMaxMessageLength = 2047;
141+
const std::string fitting_message = "[" + std::string(kMaxMessageLength - 2, 'a') + "]";
142+
const std::string long_message = "[" + std::string(4096, 'b');
143+
144+
const std::string output = CaptureInfoLogs([&]() {
145+
PAIMON_LOG_INFO(logger, "%s", fitting_message.c_str());
146+
PAIMON_LOG_INFO(logger, "%s", long_message.c_str());
147+
});
148+
ASSERT_NE(output.find(fitting_message + "\n"), std::string::npos);
149+
ASSERT_NE(output.find(long_message.substr(0, kMaxMessageLength) + "\n"), std::string::npos);
150+
}
151+
102152
// Demonstrates that glog's normal LOG() path actually writes a log file to disk.
103153
// Note: Paimon's Logger/GlogAdaptor uses google::RawLog__, which only goes to
104154
// stderr and never touches disk, so this test drives glog's file sink directly.
@@ -166,19 +216,10 @@ TEST(LoggerTest, TestGlogWritesLogFileToDisk) {
166216
FLAGS_minloglevel = prev_minloglevel;
167217
}
168218

169-
// Keep this test last: it installs a process-wide logger creator that cannot be
170-
// unset, so it must not run before tests that rely on the default logger.
219+
// A registered logger creator cannot be unset, so register it in a separate process
220+
// to keep the default logger for other tests regardless of test order.
171221
TEST(LoggerTest, TestRegisterCustomLoggerCreator) {
172-
g_creator_calls.store(0);
173-
Logger::RegisterLogger([](const std::string& /*path*/) -> std::unique_ptr<Logger> {
174-
g_creator_calls.fetch_add(1);
175-
return std::make_unique<GlogForwardingLogger>();
176-
});
177-
178-
auto logger = Logger::GetLogger("custom_path");
179-
ASSERT_TRUE(logger);
180-
// GetLogger must have gone through the registered creator branch.
181-
ASSERT_EQ(1, g_creator_calls.load());
182-
ASSERT_TRUE(logger->IsLevelEnabled(PAIMON_LOG_LEVEL_INFO));
222+
::testing::FLAGS_gtest_death_test_style = "threadsafe";
223+
ASSERT_EXIT(RegisterCustomLoggerCreatorAndExit(), ::testing::ExitedWithCode(0), "");
183224
}
184225
} // namespace paimon::test

0 commit comments

Comments
 (0)