Skip to content

Commit 33ee6e3

Browse files
canepatcanepat
authored
rpcdaemon: fix and enable auto-flushing in InterfaceLog (#2870)
1 parent ebda815 commit 33ee6e3

File tree

4 files changed

+198
-2
lines changed

4 files changed

+198
-2
lines changed

‎silkworm/rpc/common/interface_log.cpp

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,9 @@ class InterfaceLogImpl final {
2828
template <typename... Args>
2929
void log(spdlog::format_string_t<Args...> fmt, Args&&... args) {
3030
rotating_logger_->info(fmt, std::forward<Args>(args)...);
31+
if (auto_flush_) {
32+
rotating_logger_->flush();
33+
}
3134
}
3235

3336
void log(std::string_view msg) {
@@ -70,6 +73,9 @@ InterfaceLogImpl::InterfaceLogImpl(InterfaceLogSettings settings)
7073
rotating_logger_->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
7174
}
7275

76+
//! Fixed-size header prepended to every log line: "[YYYY-MM-dd hh:mm:ss.mss] REQ|RSP -> "
77+
const size_t InterfaceLog::kLogLineHeaderSize{33};
78+
7379
InterfaceLog::InterfaceLog(InterfaceLogSettings settings)
7480
: p_impl_{std::make_unique<InterfaceLogImpl>(std::move(settings))} {
7581
}

‎silkworm/rpc/common/interface_log.hpp

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,12 +20,14 @@ struct InterfaceLogSettings {
2020
std::filesystem::path container_folder{"logs/"};
2121
size_t max_file_size_mb{1};
2222
size_t max_files{100};
23-
bool auto_flush{false};
23+
bool auto_flush{true};
2424
bool dump_response{false};
2525
};
2626

2727
class InterfaceLog final {
2828
public:
29+
static const size_t kLogLineHeaderSize;
30+
2931
explicit InterfaceLog(InterfaceLogSettings settings);
3032
~InterfaceLog();
3133

‎silkworm/rpc/common/interface_log_test.cpp

Lines changed: 189 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ TEST_CASE("InterfaceLog dump: full (req+rsp)", "[rpc][common][interface_log]") {
2020
.enabled = true,
2121
.ifc_name = "eth_rpc",
2222
.container_folder = tmp_dir,
23+
.auto_flush = false,
2324
.dump_response = true,
2425
};
2526
auto ifc_log{std::make_unique<InterfaceLog>(settings)};
@@ -62,6 +63,7 @@ TEST_CASE("InterfaceLog dump: default (only req)", "[rpc][common][interface_log]
6263
.enabled = true,
6364
.ifc_name = "eth_rpc",
6465
.container_folder = tmp_dir,
66+
.auto_flush = false,
6567
};
6668
auto ifc_log{std::make_unique<InterfaceLog>(settings)};
6769
REQUIRE(!ifc_log->path().empty());
@@ -94,4 +96,191 @@ TEST_CASE("InterfaceLog dump: default (only req)", "[rpc][common][interface_log]
9496
CHECK(log_ifstream.eof());
9597
}
9698

99+
TEST_CASE("InterfaceLog dump: two instances w/o auto-flush", "[rpc][common][interface_log]") {
100+
const auto tmp_dir{TemporaryDirectory::get_unique_temporary_path()};
101+
InterfaceLogSettings settings{
102+
.enabled = true,
103+
.ifc_name = "eth_rpc",
104+
.container_folder = tmp_dir,
105+
.auto_flush = false,
106+
};
107+
auto ifc_log1 = std::make_unique<InterfaceLog>(settings);
108+
auto ifc_log2 = std::make_unique<InterfaceLog>(settings);
109+
REQUIRE(ifc_log1->path() == ifc_log2->path());
110+
111+
std::ifstream log_ifstream{ifc_log1->path().string()};
112+
113+
static constexpr size_t kLogBufferSize{1024 * 4};
114+
static const size_t kLogLineHeaderSize{InterfaceLog::kLogLineHeaderSize};
115+
116+
std::string request1;
117+
std::string request2(100, 'B'); // always less than page size
118+
119+
SECTION("less than page size") {
120+
request1.assign(kLogBufferSize - kLogLineHeaderSize - 1 /*\n*/ - 1, 'A');
121+
122+
SECTION("same instance") {
123+
// Logging request1 is NOT sufficient to trigger page write w/o flush
124+
ifc_log1->log_req(request1);
125+
CHECK(std::filesystem::file_size(ifc_log1->path()) == 0);
126+
127+
// Logging request2 crosses the page size, so one page is written w/o flush
128+
ifc_log1->log_req(request2);
129+
CHECK(std::filesystem::file_size(ifc_log1->path()) == kLogBufferSize);
130+
131+
// Flushing writes the whole write buffer content
132+
ifc_log1->flush();
133+
134+
// Log file content is exactly log_line_header + request1 + log_line_header + request2
135+
std::string content;
136+
std::getline(log_ifstream, content);
137+
CHECK(content.substr(kLogLineHeaderSize) == request1);
138+
std::getline(log_ifstream, content);
139+
CHECK(content.substr(kLogLineHeaderSize) == request2);
140+
}
141+
SECTION("different instances") {
142+
// Logging request1 through ifc_log1 is NOT sufficient to trigger page write w/o flush
143+
ifc_log1->log_req(request1);
144+
CHECK(std::filesystem::file_size(ifc_log1->path()) == 0);
145+
146+
// Logging request2 through ifc_log2 DOES NOT trigger page write: write buffers are separate
147+
ifc_log2->log_req(request2);
148+
CHECK(std::filesystem::file_size(ifc_log2->path()) == 0);
149+
150+
// Flushing both instances dumps the separate write buffers in order
151+
ifc_log2->flush();
152+
ifc_log1->flush();
153+
154+
// Log file content is exactly log_line_header + request2 + log_line_header + request1
155+
std::string content;
156+
std::getline(log_ifstream, content);
157+
CHECK(content.substr(kLogLineHeaderSize) == request2);
158+
std::getline(log_ifstream, content);
159+
CHECK(content.substr(kLogLineHeaderSize) == request1);
160+
}
161+
// No other content is present
162+
CHECK(log_ifstream.get() == -1);
163+
CHECK(log_ifstream.eof());
164+
165+
CHECK(std::filesystem::file_size(ifc_log1->path()) ==
166+
(request1.size() + kLogLineHeaderSize + 1) +
167+
(request2.size() + kLogLineHeaderSize + 1));
168+
}
169+
170+
SECTION("greater than or equal to page size") {
171+
request1.assign(4096 - kLogLineHeaderSize + 1, 'A');
172+
173+
SECTION("same instance") {
174+
// Logging request1 is sufficient to trigger page write w/o flush
175+
ifc_log1->log_req(request1);
176+
CHECK(std::filesystem::file_size(ifc_log1->path()) == kLogBufferSize);
177+
178+
// Logging request2 DOES NOT trigger another page write
179+
ifc_log1->log_req(request2);
180+
CHECK(std::filesystem::file_size(ifc_log1->path()) == kLogBufferSize);
181+
182+
// Flushing writes the whole write buffer content
183+
ifc_log1->flush();
184+
185+
// Log file content is exactly log_line_header + request1 + log_line_header + request2
186+
std::string content;
187+
std::getline(log_ifstream, content);
188+
CHECK(content.substr(kLogLineHeaderSize) == request1);
189+
std::getline(log_ifstream, content);
190+
CHECK(content.substr(kLogLineHeaderSize) == request2);
191+
}
192+
SECTION("different instances w/o flush: possible truncation") {
193+
// Logging request1 through ifc_log1 is sufficient to trigger page write w/o flush
194+
ifc_log1->log_req(request1);
195+
CHECK(std::filesystem::file_size(ifc_log1->path()) == kLogBufferSize);
196+
197+
// Logging request2 through ifc_log2 DOES NOT trigger another page write
198+
ifc_log2->log_req(request2);
199+
CHECK(std::filesystem::file_size(ifc_log2->path()) == kLogBufferSize);
200+
201+
// Flushing ifc_log2 BEFORE ifc_log1 generates a mixed content: truncated request1 + request2
202+
ifc_log2->flush();
203+
204+
// Log file content is exactly log_line_header + request1 TRUNCATED AT 4k + log_line_header + request2
205+
std::string content;
206+
std::getline(log_ifstream, content);
207+
CHECK(content.substr(0, kLogLineHeaderSize).ends_with("REQ -> "));
208+
CHECK(content.substr(kLogLineHeaderSize, kLogBufferSize - kLogLineHeaderSize) == std::string(kLogBufferSize - kLogLineHeaderSize, 'A'));
209+
CHECK(content.substr(kLogBufferSize, kLogLineHeaderSize).ends_with("REQ -> "));
210+
CHECK(content.substr(kLogBufferSize + kLogLineHeaderSize) == request2);
211+
}
212+
SECTION("different instances w/ flush: no truncation") {
213+
// Logging request1 through ifc_log1 and flushing
214+
ifc_log1->log_req(request1);
215+
ifc_log1->flush();
216+
CHECK(std::filesystem::file_size(ifc_log1->path()) == request1.size() + kLogLineHeaderSize + 1);
217+
218+
// Logging request2 through ifc_log2 and flushing
219+
ifc_log2->log_req(request2);
220+
ifc_log2->flush();
221+
CHECK(std::filesystem::file_size(ifc_log2->path()) ==
222+
(request1.size() + kLogLineHeaderSize + 1) +
223+
(request2.size() + kLogLineHeaderSize + 1));
224+
225+
// Log file content is exactly log_line_header + request2 + log_line_header + request1
226+
std::string content;
227+
std::getline(log_ifstream, content);
228+
CHECK(content.substr(kLogLineHeaderSize) == request1);
229+
std::getline(log_ifstream, content);
230+
CHECK(content.substr(kLogLineHeaderSize) == request2);
231+
}
232+
// No other content is present
233+
CHECK(log_ifstream.get() == -1);
234+
CHECK(log_ifstream.eof());
235+
}
236+
}
237+
238+
TEST_CASE("InterfaceLog dump: two instances w/ auto-flush", "[rpc][common][interface_log]") {
239+
const auto tmp_dir{TemporaryDirectory::get_unique_temporary_path()};
240+
InterfaceLogSettings settings{
241+
.enabled = true,
242+
.ifc_name = "eth_rpc",
243+
.container_folder = tmp_dir,
244+
};
245+
auto ifc_log1 = std::make_unique<InterfaceLog>(settings);
246+
auto ifc_log2 = std::make_unique<InterfaceLog>(settings);
247+
REQUIRE(ifc_log1->path() == ifc_log2->path());
248+
249+
static constexpr size_t kLogBufferSize{1024 * 4};
250+
static const size_t kLogLineHeaderSize{InterfaceLog::kLogLineHeaderSize};
251+
252+
std::string request1;
253+
std::string request2(100, 'B'); // always less than page size
254+
255+
SECTION("less than page size") {
256+
request1.assign(kLogBufferSize - kLogLineHeaderSize - 1 /*\n*/ - 1, 'A');
257+
}
258+
259+
SECTION("greater than or equal to page size") {
260+
request1.assign(4096 - kLogLineHeaderSize + 1, 'A');
261+
}
262+
263+
// Logging request1 through ifc_log1 implicitly flushes
264+
ifc_log1->log_req(request1);
265+
CHECK(std::filesystem::file_size(ifc_log1->path()) == request1.size() + kLogLineHeaderSize + 1);
266+
267+
// Logging request2 through ifc_log2 implicitly flushes
268+
ifc_log2->log_req(request2);
269+
CHECK(std::filesystem::file_size(ifc_log2->path()) ==
270+
(request1.size() + kLogLineHeaderSize + 1) +
271+
(request2.size() + kLogLineHeaderSize + 1));
272+
273+
// Log file content is exactly log_line_header + request1 + log_line_header + request2
274+
std::ifstream log_ifstream{ifc_log1->path().string()};
275+
std::string content;
276+
std::getline(log_ifstream, content);
277+
CHECK(content.substr(kLogLineHeaderSize) == request1);
278+
std::getline(log_ifstream, content);
279+
CHECK(content.substr(kLogLineHeaderSize) == request2);
280+
281+
// No other content is present
282+
CHECK(log_ifstream.get() == -1);
283+
CHECK(log_ifstream.eof());
284+
}
285+
97286
} // namespace silkworm::rpc

‎silkworm/rpc/json_rpc/request_handler.cpp

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -73,7 +73,6 @@ Task<std::optional<std::string>> RequestHandler::handle(const std::string& reque
7373

7474
if (ifc_log_) {
7575
ifc_log_->log_rsp(response);
76-
ifc_log_->flush();
7776
}
7877
SILK_TRACE << "handle HTTP request t=" << clock_time::since(start) << "ns";
7978

0 commit comments

Comments
 (0)