Line data Source code
1 : /*
2 : Copyright 2018-2024, Barcelona Supercomputing Center (BSC), Spain
3 : Copyright 2015-2024, Johannes Gutenberg Universitaet Mainz, Germany
4 :
5 : This software was partially supported by the
6 : EC H2020 funded project NEXTGenIO (Project ID: 671951, www.nextgenio.eu).
7 :
8 : This software was partially supported by the
9 : ADA-FS project under the SPPEXA project funded by the DFG.
10 :
11 : This file is part of GekkoFS' POSIX interface.
12 :
13 : GekkoFS' POSIX interface is free software: you can redistribute it and/or
14 : modify it under the terms of the GNU Lesser General Public License as
15 : published by the Free Software Foundation, either version 3 of the License,
16 : or (at your option) any later version.
17 :
18 : GekkoFS' POSIX interface is distributed in the hope that it will be useful,
19 : but WITHOUT ANY WARRANTY; without even the implied warranty of
20 : MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
21 : GNU Lesser General Public License for more details.
22 :
23 : You should have received a copy of the GNU Lesser General Public License
24 : along with GekkoFS' POSIX interface. If not, see
25 : <https://www.gnu.org/licenses/>.
26 :
27 : SPDX-License-Identifier: LGPL-3.0-or-later
28 : */
29 :
30 : #ifndef LIBGKFS_LOGGING_HPP
31 : #define LIBGKFS_LOGGING_HPP
32 :
33 : #include <libsyscall_intercept_hook_point.h>
34 :
35 : #include <type_traits>
36 : #include <client/make_array.hpp>
37 : #include <client/syscalls.hpp>
38 : #include <optional>
39 : #include <fmt/format.h>
40 : #include <fmt/ostream.h>
41 : #include <date/tz.h>
42 : #include <hermes.hpp>
43 :
44 : #ifdef GKFS_DEBUG_BUILD
45 : #include <bitset>
46 : #endif
47 :
48 : namespace gkfs::log {
49 :
50 : enum class log_level : unsigned int {
51 : print_syscalls = 1 << 0,
52 : print_syscalls_entry = 1 << 1,
53 : print_info = 1 << 2,
54 : print_critical = 1 << 3,
55 : print_errors = 1 << 4,
56 : print_warnings = 1 << 5,
57 : print_hermes = 1 << 6,
58 : print_mercury = 1 << 7,
59 : print_debug = 1 << 8,
60 : print_trace_reads = 1 << 9,
61 :
62 : // for internal use
63 : print_none = 0,
64 : print_all = print_syscalls | print_syscalls_entry | print_info |
65 : print_critical | print_errors | print_warnings | print_hermes |
66 : print_mercury | print_debug,
67 : print_most = print_all & ~print_syscalls_entry,
68 : print_help = 1 << 10
69 : };
70 :
71 : inline constexpr log_level
72 23229493 : operator&(log_level l1, log_level l2) {
73 23229493 : return log_level(static_cast<short>(l1) & static_cast<short>(l2));
74 : }
75 :
76 : inline constexpr log_level
77 248 : operator|(log_level l1, log_level l2) {
78 248 : return log_level(static_cast<short>(l1) | static_cast<short>(l2));
79 : }
80 :
81 : inline constexpr log_level
82 : operator^(log_level l1, log_level l2) {
83 : return log_level(static_cast<short>(l1) ^ static_cast<short>(l2));
84 : }
85 :
86 : inline constexpr log_level
87 : operator~(log_level l1) {
88 : return log_level(~static_cast<short>(l1));
89 : }
90 :
91 : inline constexpr bool
92 23229493 : operator!(log_level dm) {
93 23192531 : return static_cast<short>(dm) == 0;
94 : }
95 :
96 : inline const log_level&
97 248 : operator|=(log_level& l1, log_level l2) {
98 248 : return l1 = l1 | l2;
99 : }
100 :
101 : inline const log_level&
102 0 : operator&=(log_level& l1, log_level l2) {
103 0 : return l1 = l1 & l2;
104 : }
105 :
106 : inline const log_level&
107 : operator^=(log_level& l1, log_level l2) {
108 : return l1 = l1 ^ l2;
109 : }
110 :
111 :
112 : static const auto constexpr syscall = log_level::print_syscalls;
113 : static const auto constexpr syscall_at_entry = log_level::print_syscalls_entry;
114 : static const auto constexpr info = log_level::print_info;
115 : static const auto constexpr critical = log_level::print_critical;
116 : static const auto constexpr error = log_level::print_errors;
117 : static const auto constexpr warning = log_level::print_warnings;
118 : static const auto constexpr hermes = log_level::print_hermes;
119 : static const auto constexpr mercury = log_level::print_mercury;
120 : static const auto constexpr debug = log_level::print_debug;
121 : static const auto constexpr trace_reads = log_level::print_trace_reads;
122 : static const auto constexpr none = log_level::print_none;
123 : static const auto constexpr most = log_level::print_most;
124 : static const auto constexpr all = log_level::print_all;
125 : static const auto constexpr help = log_level::print_help;
126 :
127 : static const auto constexpr level_names = utils::make_array(
128 : "syscall",
129 : "syscall", // sycall_entry uses the same name as syscall
130 : "info", "critical", "error", "warning", "hermes", "mercury", "debug",
131 : "trace_reads");
132 :
133 : inline constexpr auto
134 441702 : lookup_level_name(log_level l) {
135 :
136 441702 : assert(l != log::none && l != log::help);
137 :
138 : // since all log levels are powers of 2, we can find a name
139 : // very efficiently by counting the number of trailing 0-bits in l
140 441702 : const auto i = __builtin_ctz(static_cast<short>(l));
141 441702 : assert(i >= 0 && static_cast<std::size_t>(i) < level_names.size());
142 :
143 441702 : return level_names.at(i);
144 : }
145 :
146 :
147 : // forward declaration
148 : struct logger;
149 :
150 : namespace detail {
151 :
152 : template <typename Buffer>
153 : static inline void
154 : log_buffer(std::FILE* fp, Buffer&& buffer) {
155 : log_buffer(::fileno(fp), std::forward<Buffer>(buffer));
156 : }
157 :
158 : template <typename Buffer>
159 : static inline void
160 441703 : log_buffer(int fd, Buffer&& buffer) {
161 :
162 441703 : if(fd < 0) {
163 0 : throw std::runtime_error("Invalid file descriptor");
164 : }
165 :
166 441703 : ::syscall_no_intercept(SYS_write, fd, buffer.data(), buffer.size());
167 441703 : }
168 :
169 : static inline void
170 : log_buffer(int fd, const void* buffer, std::size_t length) {
171 : if(fd < 0) {
172 : throw std::runtime_error("Invalid file descriptor");
173 : }
174 :
175 : ::syscall_no_intercept(SYS_write, fd, buffer, length);
176 : }
177 :
178 : /**
179 : * format_timestamp_to - safely format a timestamp for logging messages
180 : *
181 : * This function produes a timestamp that can be used to prefix logging
182 : * messages. Since we are actively intercepting system calls, the formatting
183 : * MUST NOT rely on internal system calls, otherwise we risk recursively
184 : * calling ourselves for each syscall generated. Also, we cannot rely on
185 : * the C formatting functions asctime, ctime, gmtime, localtime, mktime,
186 : * asctime_r, ctime_r, gmtime_r, localtime_r, since they acquire a
187 : * non-reentrant lock to determine the caller's timezone (yes, the assumedly
188 : * reentrant *_r versions of the functions exhibit this problem as well,
189 : * see https://sourceware.org/bugzilla/show_bug.cgi?id=16145). To solve this
190 : * issue and still get readable timestamps, we determine and cache the
191 : * timezone when the logger is created so that the lock is only held once, by
192 : * one thread exactly, and we pass it as an argument whenever we need to
193 : * format a timestamp. If no timezone is provided, we just format the epoch.
194 : *
195 : * NOTE: we use the date C++ library to query the timezone database and
196 : * to format the timestamps.
197 : */
198 : template <typename Buffer>
199 : static inline void
200 1613730 : format_timestamp_to(Buffer&& buffer,
201 : const date::time_zone* const timezone = nullptr) {
202 :
203 : struct ::timeval tv;
204 :
205 1613730 : int rv = ::syscall_no_intercept(SYS_gettimeofday, &tv, NULL);
206 :
207 1613800 : if(::syscall_error_code(rv) != 0) {
208 0 : return;
209 : }
210 :
211 1613787 : date::sys_time<std::chrono::microseconds> now{
212 1613800 : std::chrono::seconds{tv.tv_sec} +
213 : std::chrono::microseconds{tv.tv_usec}};
214 :
215 1613787 : if(!timezone) {
216 0 : fmt::format_to(buffer, "[{}] ", now.time_since_epoch().count());
217 0 : return;
218 : }
219 :
220 1613787 : fmt::format_to(buffer, "[{}] ",
221 1613787 : date::zoned_time<std::chrono::microseconds>{timezone, now});
222 : }
223 :
224 : template <typename Buffer>
225 : static inline void
226 1172012 : format_syscall_info_to(Buffer&& buffer, gkfs::syscall::info info) {
227 :
228 1172012 : const auto ttid = syscall_no_intercept(SYS_gettid);
229 1172114 : fmt::format_to(buffer, "[{}] [syscall] ", ttid);
230 :
231 : char o;
232 : char t;
233 :
234 1172097 : switch(gkfs::syscall::origin(info)) {
235 : case gkfs::syscall::from_internal_code:
236 : o = 'i';
237 : break;
238 830204 : case gkfs::syscall::from_external_code:
239 830204 : o = 'a';
240 830204 : break;
241 991 : default:
242 991 : o = '?';
243 991 : break;
244 : }
245 :
246 1172097 : switch(gkfs::syscall::target(info)) {
247 : case gkfs::syscall::to_hook:
248 : t = 'h';
249 : break;
250 188646 : case gkfs::syscall::to_kernel:
251 188646 : t = 'k';
252 188646 : break;
253 991 : default:
254 991 : t = '?';
255 991 : break;
256 : }
257 :
258 1172097 : const std::array<char, 5> tmp = {'[', o, t, ']', ' '};
259 1172097 : fmt::format_to(buffer, fmt::string_view(tmp.data(), tmp.size()));
260 1172078 : }
261 :
262 : } // namespace detail
263 :
264 : enum { max_buffer_size = LIBGKFS_LOG_MESSAGE_SIZE };
265 :
266 3227614 : struct static_buffer : public fmt::basic_memory_buffer<char, max_buffer_size> {
267 :
268 : protected:
269 : void
270 : grow(std::size_t size) override final;
271 : };
272 :
273 :
274 : struct logger {
275 :
276 : logger(const std::string& opts, const std::string& path,
277 : bool log_per_process, bool trunc
278 : #ifdef GKFS_DEBUG_BUILD
279 : ,
280 : const std::string& filter, int verbosity
281 : #endif
282 : );
283 :
284 : ~logger();
285 :
286 : template <typename... Args>
287 : inline void
288 441731 : log(log_level level, const char* const func, const int lineno,
289 : Args&&... args) {
290 :
291 441731 : if(!(level & log_mask_)) {
292 28 : return;
293 : }
294 :
295 441703 : static_buffer buffer;
296 441703 : detail::format_timestamp_to(buffer, timezone_);
297 441703 : fmt::format_to(buffer, "[{}] [{}] ", log_process_id_,
298 441702 : lookup_level_name(level));
299 :
300 441703 : if(!!(level & log::debug)) {
301 420970 : fmt::format_to(buffer, "<{}():{}> ", func, lineno);
302 : }
303 :
304 441703 : fmt::format_to(buffer, std::forward<Args>(args)...);
305 441703 : fmt::format_to(buffer, "\n");
306 441703 : detail::log_buffer(log_fd_, buffer);
307 : }
308 :
309 : inline int
310 : log(log_level level, const char* fmt, va_list ap) {
311 :
312 : if(!(level & log_mask_)) {
313 : return 0;
314 : }
315 :
316 : // we use buffer views to compose the logging messages to
317 : // avoid copying buffers as much as possible
318 : struct buffer_view {
319 : const void* addr;
320 : std::size_t size;
321 : };
322 :
323 : // helper lambda to print an iterable of buffer_views
324 : const auto log_buffer_views = [this](const auto& buffers) {
325 : std::size_t n = 0;
326 :
327 : for(const auto& bv : buffers) {
328 : if(bv.addr != nullptr) {
329 : detail::log_buffer(log_fd_, bv.addr, bv.size);
330 : n += bv.size;
331 : }
332 : }
333 :
334 : return n;
335 : };
336 :
337 :
338 : static_buffer prefix;
339 : detail::format_timestamp_to(prefix);
340 : fmt::format_to(prefix, "[{}] [{}] ", log_process_id_,
341 : lookup_level_name(level));
342 :
343 : char buffer[max_buffer_size];
344 : const int n = vsnprintf(buffer, sizeof(buffer), fmt, ap);
345 :
346 : std::array<buffer_view, 3> buffers{};
347 :
348 : int i = 0;
349 : int m = 0;
350 : const char* addr = buffer;
351 : const char* p = nullptr;
352 : while((p = std::strstr(addr, "\n")) != nullptr) {
353 : buffers[0] = buffer_view{prefix.data(), prefix.size()};
354 : buffers[1] =
355 : buffer_view{addr, static_cast<std::size_t>(p - addr) + 1};
356 :
357 : m += log_buffer_views(buffers);
358 : addr = p + 1;
359 : ++i;
360 : }
361 :
362 : // original line might not end with (or include) '\n'
363 : if(buffer[n - 1] != '\n') {
364 : buffers[0] = buffer_view{prefix.data(), prefix.size()};
365 : buffers[1] = buffer_view{
366 : addr, static_cast<std::size_t>(&buffer[n] - addr)};
367 : buffers[2] = buffer_view{"\n", 1};
368 :
369 : m += log_buffer_views(buffers);
370 : }
371 :
372 : return m;
373 : }
374 :
375 : template <typename... Args>
376 : static inline void
377 0 : log_message(std::FILE* fp, Args&&... args) {
378 0 : log_message(::fileno(fp), std::forward<Args>(args)...);
379 0 : }
380 :
381 : template <typename... Args>
382 : static inline void
383 0 : log_message(int fd, Args&&... args) {
384 :
385 0 : if(fd < 0) {
386 0 : throw std::runtime_error("Invalid file descriptor");
387 : }
388 :
389 0 : static_buffer buffer;
390 0 : fmt::format_to(buffer, std::forward<Args>(args)...);
391 0 : fmt::format_to(buffer, "\n");
392 0 : detail::log_buffer(fd, buffer);
393 0 : }
394 :
395 : void
396 : log_syscall(syscall::info info, const long syscall_number,
397 : const long args[6], std::optional<long> result = {});
398 :
399 : static std::shared_ptr<logger>&
400 45950352 : global_logger() {
401 45950352 : static std::shared_ptr<logger> s_global_logger;
402 45950352 : return s_global_logger;
403 : }
404 :
405 : int log_fd_;
406 : int log_process_id_;
407 : log_level log_mask_;
408 :
409 : #ifdef GKFS_DEBUG_BUILD
410 : std::bitset<512> filtered_syscalls_;
411 : int debug_verbosity_;
412 : #endif
413 :
414 : const date::time_zone* timezone_;
415 : };
416 :
417 : // the following static functions can be used to interact
418 : // with a globally registered logger instance
419 :
420 : template <typename... Args>
421 : static inline void
422 248 : create_global_logger(Args&&... args) {
423 :
424 248 : auto foo = std::make_shared<logger>(std::forward<Args>(args)...);
425 248 : logger::global_logger() = foo;
426 248 : }
427 :
428 : static inline void
429 : register_global_logger(logger&& lg) {
430 : logger::global_logger() = std::make_shared<logger>(std::move(lg));
431 : }
432 :
433 : static inline std::shared_ptr<logger>&
434 45967225 : get_global_logger() {
435 45967225 : return logger::global_logger();
436 : }
437 :
438 : static inline void
439 : destroy_global_logger() {
440 : logger::global_logger().reset();
441 : }
442 :
443 : inline void
444 0 : static_buffer::grow(std::size_t size) {
445 :
446 0 : const auto logger = get_global_logger();
447 :
448 0 : if(logger) {
449 0 : logger->log_mask_ &= ~(syscall | syscall_at_entry);
450 : }
451 :
452 0 : std::fprintf(
453 : stderr,
454 : "FATAL: message too long for gkfs::log::static_buffer, increase the size of\n"
455 : "LIBGKFS_LOG_MESSAGE_SIZE in CMake or reduce the length of the offending "
456 : "message.\n");
457 0 : abort();
458 : }
459 :
460 : } // namespace gkfs::log
461 :
462 : #define LOG(XXX, ...) LOG_##XXX(__VA_ARGS__)
463 :
464 : #ifndef GKFS_ENABLE_LOGGING
465 :
466 : #define LOG_INFO(...) \
467 : do { \
468 : } while(0);
469 : #define LOG_WARNING(...) \
470 : do { \
471 : } while(0);
472 : #define LOG_ERROR(...) \
473 : do { \
474 : } while(0);
475 : #define LOG_CRITICAL(...) \
476 : do { \
477 : } while(0);
478 : #define LOG_HERMES(...) \
479 : do { \
480 : } while(0);
481 : #define LOG_MERCURY(...) \
482 : do { \
483 : } while(0);
484 : #define LOG_SYSCALL(...) \
485 : do { \
486 : } while(0);
487 : #define LOG_DEBUG(...) \
488 : do { \
489 : } while(0);
490 : #define LOG_TRACE_READS(...) \
491 : do { \
492 : } while(0);
493 :
494 : #else // !GKFS_ENABLE_LOGGING
495 :
496 : #define LOG_INFO(...) \
497 : do { \
498 : if(gkfs::log::get_global_logger()) { \
499 : gkfs::log::get_global_logger()->log(gkfs::log::info, __func__, \
500 : __LINE__, __VA_ARGS__); \
501 : } \
502 : } while(0);
503 :
504 : #define LOG_WARNING(...) \
505 : do { \
506 : if(gkfs::log::get_global_logger()) { \
507 : gkfs::log::get_global_logger()->log(gkfs::log::warning, __func__, \
508 : __LINE__, __VA_ARGS__); \
509 : } \
510 : } while(0);
511 :
512 : #define LOG_ERROR(...) \
513 : do { \
514 : if(gkfs::log::get_global_logger()) { \
515 : gkfs::log::get_global_logger()->log(gkfs::log::error, __func__, \
516 : __LINE__, __VA_ARGS__); \
517 : } \
518 : } while(0);
519 :
520 : #define LOG_CRITICAL(...) \
521 : do { \
522 : if(gkfs::log::get_global_logger()) { \
523 : gkfs::log::get_global_logger()->log(gkfs::log::critical, __func__, \
524 : __LINE__, __VA_ARGS__); \
525 : } \
526 : } while(0);
527 :
528 : #define LOG_HERMES(...) \
529 : do { \
530 : if(gkfs::log::get_global_logger()) { \
531 : gkfs::log::get_global_logger()->log(gkfs::log::hermes, __func__, \
532 : __LINE__, __VA_ARGS__); \
533 : } \
534 : } while(0);
535 :
536 : #define LOG_MERCURY(...) \
537 : do { \
538 : if(gkfs::log::get_global_logger()) { \
539 : gkfs::log::get_global_logger()->log(gkfs::log::mercury, __func__, \
540 : __LINE__, __VA_ARGS__); \
541 : } \
542 : } while(0);
543 :
544 : #define LOG_TRACE_READS(...) \
545 : do { \
546 : if(gkfs::log::get_global_logger()) { \
547 : gkfs::log::get_global_logger()->log( \
548 : gkfs::log::trace_reads, __func__, __LINE__, __VA_ARGS__); \
549 : } \
550 : } while(0);
551 :
552 : #ifdef GKFS_DEBUG_BUILD
553 :
554 : #define LOG_SYSCALL(...) \
555 : do { \
556 : if(gkfs::log::get_global_logger()) { \
557 : gkfs::log::get_global_logger()->log_syscall(__VA_ARGS__); \
558 : } \
559 : } while(0);
560 :
561 : #define LOG_DEBUG(...) \
562 : do { \
563 : if(gkfs::log::get_global_logger()) { \
564 : gkfs::log::get_global_logger()->log(gkfs::log::debug, __func__, \
565 : __LINE__, __VA_ARGS__); \
566 : } \
567 : } while(0);
568 :
569 : #else // ! GKFS_DEBUG_BUILD
570 :
571 : #define LOG_SYSCALL(...) \
572 : do { \
573 : } while(0);
574 : #define LOG_DEBUG(...) \
575 : do { \
576 : } while(0);
577 :
578 : #endif // ! GKFS_DEBUG_BUILD
579 : #endif // !GKFS_ENABLE_LOGGING
580 :
581 : #endif // LIBGKFS_LOGGING_HPP
|