LCOV - code coverage report
Current view: top level - include/client - logging.hpp (source / functions) Hit Total Coverage
Test: coverage.info Lines: 67 90 74.4 %
Date: 2024-04-30 13:21:35 Functions: 119 206 57.8 %
Legend: Lines: hit not hit

          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

Generated by: LCOV version 1.16