LCOV - code coverage report
Current view: top level - src/client - logging.cpp (source / functions) Hit Total Coverage
Test: coverage.info Lines: 98 139 70.5 %
Date: 2024-04-23 00:09:24 Functions: 9 10 90.0 %
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             : #include <client/logging.hpp>
      31             : #include <client/env.hpp>
      32             : #include <client/make_array.hpp>
      33             : #include <regex>
      34             : #include <filesystem>
      35             : #include <ctime>
      36             : 
      37             : #ifdef GKFS_ENABLE_LOGGING
      38             : 
      39             : #include <hermes/logging.hpp>
      40             : 
      41             : #endif
      42             : 
      43             : namespace fs = std::filesystem;
      44             : 
      45             : namespace {
      46             : enum class split_str_mode {
      47             :     is_any_of,
      48             :     is_exactly_of // not used at the moment
      49             : };                ///> Mode for string splitter
      50             : 
      51             : /**
      52             :  * @brief Splits a string by a given delimiter for a given split_mode
      53             :  * @param input String to be splitted
      54             :  * @param delimiter split token
      55             :  * @param split_mode <split_str_node> how the string is split
      56             :  * @return vector<string> entries for splitted string
      57             :  */
      58             : std::vector<std::string>
      59         538 : split_str(const std::string& input, const std::string_view delimiter,
      60             :           const split_str_mode split_mode) {
      61         538 :     std::vector<std::string> out{};
      62         538 :     std::string regex_builder{};
      63         538 :     if(split_mode == split_str_mode::is_any_of) {
      64         538 :         regex_builder = fmt::format("[{}]+", delimiter);
      65             :     } else {
      66           0 :         regex_builder = delimiter;
      67             :     }
      68         538 :     const std::regex line_re(regex_builder,
      69         538 :                              std::regex::ECMAScript | std::regex::optimize);
      70         538 :     std::copy(
      71        1076 :             std::sregex_token_iterator(input.begin(), input.end(), line_re, -1),
      72         538 :             std::sregex_token_iterator(), std::back_inserter(out));
      73        1076 :     return out;
      74             : }
      75             : } // namespace
      76             : 
      77             : namespace gkfs::log {
      78             : 
      79             : struct opt_info {
      80             :     const char name_[32];
      81             :     const std::size_t length_;
      82             :     const char help_text_[8][64];
      83             :     const log_level mask_;
      84             : };
      85             : 
      86             : #define STR_AND_LEN(strbuf) strbuf, sizeof(strbuf) - 1
      87             : 
      88             : static const auto constexpr debug_opts = utils::make_array(
      89             : 
      90             :         opt_info{STR_AND_LEN("none"), {"don't print any messages"}, log::none},
      91             : 
      92             : #ifdef GKFS_DEBUG_BUILD
      93             : 
      94             :         opt_info{STR_AND_LEN("syscalls"),
      95             :                  {"Trace system calls: print the name of each system call,",
      96             :                   "its arguments, and its return value. All system calls are",
      97             :                   "printed after being executed save for those that may not",
      98             :                   "return, such as execve() and execve_at()",
      99             :                   "[ default: off ]"},
     100             :                  log::syscall},
     101             : 
     102             :         opt_info{STR_AND_LEN("syscalls_at_entry"),
     103             :                  {"Trace system calls: print the name of each system call",
     104             :                   "and its arguments. All system calls are printed before ",
     105             :                   "being executed and therefore their return values are not",
     106             :                   "available in the log", "[ default: off ]"},
     107             :                  log::syscall_at_entry},
     108             : 
     109             : #endif // !GKFS_DEBUG_BUILD
     110             : 
     111             :         opt_info{STR_AND_LEN("info"),
     112             :                  {"Print information messages", "[ default: on  ]"},
     113             :                  log::info},
     114             : 
     115             :         opt_info{STR_AND_LEN("critical"),
     116             :                  {"Print critical errors", "[ default: on  ]"},
     117             :                  log::critical},
     118             : 
     119             :         opt_info{STR_AND_LEN("errors"),
     120             :                  {"Print errors", "[ default: on  ]"},
     121             :                  log::error},
     122             : 
     123             :         opt_info{STR_AND_LEN("warnings"),
     124             :                  {"Print warnings", "[ default: on  ]"},
     125             :                  log::warning},
     126             : 
     127             :         opt_info{STR_AND_LEN("hermes"),
     128             :                  {"Print messages from Hermes (GekkoFS high-level RPC library)",
     129             :                   "[ default: on ]"},
     130             :                  log::hermes},
     131             : 
     132             :         opt_info{STR_AND_LEN("mercury"),
     133             :                  {"Print messages from Mercury (GekkoFS low-level RPC library)",
     134             :                   "[ default: on ]"},
     135             :                  log::mercury},
     136             : 
     137             :         opt_info{STR_AND_LEN("trace_reads"),
     138             :                  {"Print extended read information", "[ default: off  ]"},
     139             :                  log::trace_reads},
     140             : 
     141             : #ifdef GKFS_DEBUG_BUILD
     142             : 
     143             :         opt_info{STR_AND_LEN("debug"),
     144             :                  {"Print debug messages", "[ default: off ]"},
     145             :                  log::debug},
     146             : 
     147             :         opt_info{STR_AND_LEN("most"),
     148             :                  {"All previous options except 'syscalls_at_entry' combined."},
     149             :                  log::most},
     150             : 
     151             : #endif // !GKFS_DEBUG_BUILD
     152             : 
     153             :         opt_info{STR_AND_LEN("all"),
     154             :                  {"All previous options combined."},
     155             :                  log::all},
     156             : 
     157             :         opt_info{STR_AND_LEN("help"),
     158             :                  {"Print this help message and exit."},
     159             :                  log::help});
     160             : 
     161             : static const auto constexpr max_debug_opt_length =
     162             :         sizeof("syscalls_at_entry") - 1;
     163             : 
     164             : static const auto constexpr max_help_text_rows =
     165             :         sizeof(debug_opts[0].help_text_) / sizeof(debug_opts[0].help_text_[0]);
     166             : 
     167             : /**
     168             :  * process_log_options -- process the string given as parameter to determine
     169             :  *                        which debugging options are enabled and return a
     170             :  *                        log_level describing them
     171             :  */
     172             : log_level
     173         269 : process_log_options(const std::string gkfs_debug) {
     174             : 
     175             : #ifndef GKFS_ENABLE_LOGGING
     176             : 
     177             :     (void) gkfs_debug;
     178             :     logger::log_message(stdout, "warning: logging options ignored: "
     179             :                                 "logging support was disabled in this build");
     180             :     return log::none;
     181             : 
     182             : #endif // ! GKFS_ENABLE_LOGGING
     183         269 :     log_level dm = log::none;
     184             : 
     185             :     // skip separating white spaces and commas
     186         538 :     auto tokens = ::split_str(gkfs_debug, " ,", ::split_str_mode::is_any_of);
     187             : 
     188         538 :     for(const auto& t : tokens) {
     189             : 
     190        3497 :         bool is_known = false;
     191             : 
     192        3497 :         for(const auto& opt : debug_opts) {
     193             :             // none disables any future and previous flags observed
     194        3497 :             if(t == "none") {
     195           0 :                 return log::none;
     196             :             }
     197             : 
     198        3497 :             if(t == opt.name_) {
     199         269 :                 dm |= opt.mask_;
     200         269 :                 is_known = true;
     201         269 :                 break;
     202             :             }
     203             :         }
     204             : 
     205         269 :         if(!is_known) {
     206           0 :             logger::log_message(stdout,
     207             :                                 "warning: logging option '{}' unknown; "
     208             :                                 "try {}=help",
     209             :                                 t, gkfs::env::LOG);
     210             :         }
     211             :     }
     212             : 
     213         269 :     if(!!(dm & log::help)) {
     214           0 :         logger::log_message(stdout,
     215             :                             "Valid options for the {} "
     216             :                             "environment variable are:\n",
     217             :                             gkfs::env::LOG);
     218             : 
     219             : 
     220           0 :         for(const auto& opt : debug_opts) {
     221           0 :             const auto padding = max_debug_opt_length - opt.length_ + 2;
     222             : 
     223           0 :             logger::log_message(stdout, "  {}{:>{}}{}", opt.name_, "", padding,
     224           0 :                                 opt.help_text_[0]);
     225             : 
     226           0 :             for(auto i = 1lu; i < max_help_text_rows; ++i) {
     227           0 :                 if(opt.help_text_[i][0] != 0) {
     228           0 :                     logger::log_message(stdout, "  {:>{}}{}", "",
     229           0 :                                         max_debug_opt_length + 2,
     230           0 :                                         opt.help_text_[i]);
     231             :                 }
     232             :             }
     233             : 
     234           0 :             logger::log_message(stdout, "");
     235             :         }
     236             : 
     237           0 :         logger::log_message(stdout,
     238             :                             "\n"
     239             :                             "To direct the logging output into a file "
     240             :                             "instead of standard output\n"
     241             :                             "a filename can be specified using the "
     242             :                             "{} environment variable.",
     243             :                             gkfs::env::LOG_OUTPUT);
     244           0 :         ::_exit(0);
     245             :     }
     246             : 
     247             :     return dm;
     248             : }
     249             : 
     250             : #ifdef GKFS_DEBUG_BUILD
     251             : 
     252             : std::bitset<512>
     253         269 : process_log_filter(const std::string& log_filter) {
     254         269 :     std::bitset<512> filtered_syscalls;
     255             : 
     256         269 :     if(log_filter.empty()) {
     257             :         return filtered_syscalls;
     258             :     }
     259             : 
     260             :     // skip separating white spaces and commas
     261         269 :     auto tokens = ::split_str(log_filter, " ,", ::split_str_mode::is_any_of);
     262             : 
     263         807 :     for(const auto& t : tokens) {
     264         538 :         const auto sc = syscall::lookup_by_name(t);
     265             : 
     266         538 :         if(std::strcmp(sc.name(), "unknown_syscall") == 0) {
     267           0 :             logger::log_message(stdout,
     268             :                                 "warning: system call '{}' unknown; "
     269             :                                 "will not filter",
     270             :                                 t);
     271           0 :             continue;
     272             :         }
     273             : 
     274         538 :         filtered_syscalls.set(sc.number());
     275             :     }
     276             : 
     277         269 :     return filtered_syscalls;
     278             : }
     279             : 
     280             : #endif // GKFS_DEBUG_BUILD
     281             : 
     282         269 : logger::logger(const std::string& opts, const std::string& path,
     283             :                bool log_per_process, bool trunc
     284             : #ifdef GKFS_DEBUG_BUILD
     285             :                ,
     286             :                const std::string& filter, int verbosity
     287             : #endif
     288         269 : ) {
     289             : 
     290             :     /* use stderr by default */
     291         269 :     log_fd_ = 2;
     292         269 :     log_process_id_ = ::syscall_no_intercept(SYS_gettid);
     293         269 :     log_mask_ = process_log_options(opts);
     294             : 
     295             : #ifdef GKFS_DEBUG_BUILD
     296         269 :     filtered_syscalls_ = process_log_filter(filter);
     297         269 :     debug_verbosity_ = verbosity;
     298             : #endif
     299             : 
     300         269 :     if(!path.empty()) {
     301         269 :         int flags = O_CREAT | O_RDWR | O_APPEND | O_TRUNC;
     302             : 
     303         269 :         if(!trunc) {
     304         269 :             flags &= ~O_TRUNC;
     305             :         }
     306             : 
     307         538 :         std::string file_path = path;
     308         269 :         if(log_per_process) {
     309           0 :             if(fs::is_regular_file(file_path) && fs::exists(file_path)) {
     310           0 :                 fs::remove(file_path);
     311             :             }
     312           0 :             fs::create_directories(path);
     313           0 :             file_path = fmt::format("{}/{}", path, log_process_id_);
     314             :         }
     315             : 
     316             :         // we use ::open() here rather than ::syscall_no_intercept(SYS_open)
     317             :         // because we want the call to be intercepted by our hooks, which
     318             :         // allows us to categorize the resulting fd as 'internal' and
     319             :         // relocate it to our private range
     320         269 :         int fd = ::open(file_path.c_str(), flags, 0600);
     321             : 
     322         269 :         if(fd == -1) {
     323           0 :             log(gkfs::log::error, __func__, __LINE__,
     324             :                 "Failed to open log "
     325             :                 "file '{}'. Logging will fall back to stderr",
     326             :                 path);
     327           0 :             return;
     328             :         }
     329             : 
     330         269 :         log_fd_ = fd;
     331             :     }
     332             : 
     333             : #ifdef GKFS_ENABLE_LOGGING
     334         269 :     const auto log_hermes_message =
     335          85 :             [](const std::string& msg, hermes::log::level l, int severity,
     336             :                const std::string& file, const std::string& func, int lineno) {
     337         170 :                 const auto name = [](hermes::log::level l, int severity) {
     338          85 :                     using namespace std::string_literals;
     339             : 
     340          85 :                     switch(l) {
     341           0 :                         case hermes::log::info:
     342           0 :                             return "info"s;
     343           0 :                         case hermes::log::warning:
     344           0 :                             return "warning"s;
     345          85 :                         case hermes::log::error:
     346          85 :                             return "error"s;
     347           0 :                         case hermes::log::fatal:
     348           0 :                             return "fatal"s;
     349           0 :                         case hermes::log::mercury:
     350           0 :                             return "mercury"s;
     351           0 :                         default:
     352           0 :                             return "unknown"s;
     353             :                     }
     354             :                 };
     355             : 
     356         170 :                 LOG(HERMES, "[{}] {}", name(l, severity), msg);
     357          85 :             };
     358             : 
     359             : #ifdef GKFS_DEBUG_BUILD
     360         269 :     const auto log_hermes_debug_message =
     361       72676 :             [this](const std::string& msg, hermes::log::level l, int severity,
     362             :                    const std::string& file, const std::string& func,
     363       72676 :                    int lineno) {
     364       72676 :                 if(severity > debug_verbosity_) {
     365             :                     return;
     366             :                 }
     367             : 
     368       38718 :                 LOG(HERMES, "[debug{}] <{}():{}> {}",
     369             :                     (severity == 0 ? "" : std::to_string(severity + 1)), func,
     370       72676 :                     lineno, msg);
     371         269 :             };
     372             : #endif // GKFS_DEBUG_BUILD
     373             : 
     374         269 :     const auto log_hg_message = [](const std::string& msg, hermes::log::level l,
     375             :                                    int severity, const std::string& file,
     376             :                                    const std::string& func, int lineno) {
     377           0 :         (void) l;
     378             : 
     379             :         // mercury message might contain one or more sub-messages
     380             :         // separated by '\n'
     381           0 :         auto sub_msgs = ::split_str(msg, "\n", ::split_str_mode::is_any_of);
     382             : 
     383           0 :         for(const auto& m : sub_msgs) {
     384           0 :             if(!m.empty()) {
     385           0 :                 LOG(MERCURY, "{}", m);
     386             :             }
     387             :         }
     388           0 :     };
     389             : 
     390             :     // register log callbacks into hermes so that we can manage
     391             :     // both its and mercury's log messages
     392         269 :     hermes::log::logger::register_callback(hermes::log::info,
     393             :                                            log_hermes_message);
     394         269 :     hermes::log::logger::register_callback(hermes::log::warning,
     395             :                                            log_hermes_message);
     396         269 :     hermes::log::logger::register_callback(hermes::log::error,
     397             :                                            log_hermes_message);
     398         269 :     hermes::log::logger::register_callback(hermes::log::fatal,
     399             :                                            log_hermes_message);
     400             : #ifdef GKFS_DEBUG_BUILD
     401         269 :     hermes::log::logger::register_callback(hermes::log::debug,
     402             :                                            log_hermes_debug_message);
     403             : #endif
     404         538 :     hermes::log::logger::register_callback(hermes::log::mercury,
     405             :                                            log_hg_message);
     406             : 
     407             : #endif // GKFS_ENABLE_LOGGING
     408             : }
     409             : 
     410         538 : logger::~logger() {
     411         269 :     log_fd_ = ::syscall_no_intercept(SYS_close, log_fd_);
     412         269 : }
     413             : 
     414             : void
     415    29083781 : logger::log_syscall(syscall::info info, const long syscall_number,
     416             :                     const long args[6], std::optional<long> result) {
     417             : 
     418             : 
     419    29083781 :     const bool log_syscall_entry = !!(log::syscall_at_entry & log_mask_);
     420    29083781 :     const bool log_syscall_result = !!(log::syscall & log_mask_);
     421             : 
     422             :     // log the syscall if and only if logging for syscalls is enabled
     423    29083781 :     if(!log_syscall_entry && !log_syscall_result) {
     424    27812633 :         return;
     425             :     }
     426             : 
     427             : #ifdef GKFS_DEBUG_BUILD
     428    29083778 :     if(filtered_syscalls_[syscall_number]) {
     429             :         return;
     430             :     }
     431             : #endif
     432             : 
     433             :     // log the syscall even if we don't have information on it, since it may
     434             :     // be important to the user (we assume that the syscall has completed
     435             :     // though)
     436     1271148 :     if(info == syscall::no_info) {
     437           0 :         goto print_syscall;
     438             :     }
     439             : 
     440             :     // log the syscall entry if the syscall may not return (e.g. execve) or
     441             :     // if we are sure that it won't ever return (e.g. exit), even if
     442             :     // log::syscall_at_entry is disabled
     443     2542289 :     if(syscall::may_not_return(syscall_number) ||
     444     1271148 :        syscall::never_returns(syscall_number)) {
     445         842 :         goto print_syscall;
     446             :     }
     447             : 
     448     1270299 :     if(log_syscall_entry && syscall::execution_is_pending(info)) {
     449      634560 :         goto print_syscall;
     450             :     }
     451             : 
     452      635739 :     if(log_syscall_result && !syscall::execution_is_pending(info)) {
     453      635739 :         goto print_syscall;
     454             :     }
     455             : 
     456             :     return;
     457             : 
     458     1271141 : print_syscall:
     459             : 
     460     2542380 :     fmt::basic_memory_buffer<char, max_buffer_size> buffer;
     461             : 
     462     1271141 :     detail::format_timestamp_to(buffer);
     463     1271136 :     detail::format_syscall_info_to(buffer, info);
     464             : 
     465     1271164 :     if(result) {
     466      635730 :         syscall::decode(buffer, syscall_number, args, *result);
     467             :     } else {
     468      635434 :         syscall::decode(buffer, syscall_number, args);
     469             :     }
     470             : 
     471     1271175 :     fmt::format_to(std::back_inserter(buffer), "\n");
     472             : 
     473     1270386 :     ::syscall_no_intercept(SYS_write, log_fd_, buffer.data(), buffer.size());
     474             : }
     475             : 
     476             : } // namespace gkfs::log

Generated by: LCOV version 1.16