Program Listing for File logging.hpp
↰ Return to documentation for file (include/client/logging.hpp)
/*
Copyright 2018-2025, Barcelona Supercomputing Center (BSC), Spain
Copyright 2015-2025, Johannes Gutenberg Universitaet Mainz, Germany
This software was partially supported by the
EC H2020 funded project NEXTGenIO (Project ID: 671951, www.nextgenio.eu).
This software was partially supported by the
ADA-FS project under the SPPEXA project funded by the DFG.
This software was partially supported by the
the European Union’s Horizon 2020 JTI-EuroHPC research and
innovation programme, by the project ADMIRE (Project ID: 956748,
admire-eurohpc.eu)
This project was partially promoted by the Ministry for Digital Transformation
and the Civil Service, within the framework of the Recovery,
Transformation and Resilience Plan - Funded by the European Union
-NextGenerationEU.
This file is part of GekkoFS' POSIX interface.
GekkoFS' POSIX interface is free software: you can redistribute it and/or
modify it under the terms of the GNU Lesser General Public License as
published by the Free Software Foundation, either version 3 of the License,
or (at your option) any later version.
GekkoFS' POSIX interface is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU Lesser General Public License for more details.
You should have received a copy of the GNU Lesser General Public License
along with GekkoFS' POSIX interface. If not, see
<https://www.gnu.org/licenses/>.
SPDX-License-Identifier: LGPL-3.0-or-later
*/
#ifndef LIBGKFS_LOGGING_HPP
#define LIBGKFS_LOGGING_HPP
#ifndef BYPASS_SYSCALL
#include <libsyscall_intercept_hook_point.h>
#else
#include <client/void_syscall_intercept.hpp>
#endif
#include <type_traits>
#include <client/make_array.hpp>
#include <client/syscalls.hpp>
#include <optional>
#include <fmt/format.h>
#include <fmt/ostream.h>
#include <hermes.hpp>
#ifdef GKFS_DEBUG_BUILD
#include <bitset>
#endif
namespace gkfs::log {
enum class log_level : unsigned int {
print_syscalls = 1 << 0,
print_syscalls_entry = 1 << 1,
print_info = 1 << 2,
print_critical = 1 << 3,
print_errors = 1 << 4,
print_warnings = 1 << 5,
print_hermes = 1 << 6,
print_mercury = 1 << 7,
print_debug = 1 << 8,
print_trace_reads = 1 << 9,
// for internal use
print_none = 0,
print_all = print_syscalls | print_syscalls_entry | print_info |
print_critical | print_errors | print_warnings | print_hermes |
print_mercury | print_debug,
print_most = print_all & ~print_syscalls_entry,
print_help = 1 << 10
};
inline constexpr log_level
operator&(log_level l1, log_level l2) {
return log_level(static_cast<short>(l1) & static_cast<short>(l2));
}
inline constexpr log_level
operator|(log_level l1, log_level l2) {
return log_level(static_cast<short>(l1) | static_cast<short>(l2));
}
inline constexpr log_level
operator^(log_level l1, log_level l2) {
return log_level(static_cast<short>(l1) ^ static_cast<short>(l2));
}
inline constexpr log_level
operator~(log_level l1) {
return log_level(~static_cast<short>(l1));
}
inline constexpr bool
operator!(log_level dm) {
return static_cast<short>(dm) == 0;
}
inline const log_level&
operator|=(log_level& l1, log_level l2) {
return l1 = l1 | l2;
}
inline const log_level&
operator&=(log_level& l1, log_level l2) {
return l1 = l1 & l2;
}
inline const log_level&
operator^=(log_level& l1, log_level l2) {
return l1 = l1 ^ l2;
}
static const auto constexpr syscall = log_level::print_syscalls;
static const auto constexpr syscall_at_entry = log_level::print_syscalls_entry;
static const auto constexpr info = log_level::print_info;
static const auto constexpr critical = log_level::print_critical;
static const auto constexpr error = log_level::print_errors;
static const auto constexpr warning = log_level::print_warnings;
static const auto constexpr hermes = log_level::print_hermes;
static const auto constexpr mercury = log_level::print_mercury;
static const auto constexpr debug = log_level::print_debug;
static const auto constexpr trace_reads = log_level::print_trace_reads;
static const auto constexpr none = log_level::print_none;
static const auto constexpr most = log_level::print_most;
static const auto constexpr all = log_level::print_all;
static const auto constexpr help = log_level::print_help;
static const auto constexpr level_names = utils::make_array(
"syscall",
"syscall", // sycall_entry uses the same name as syscall
"info", "critical", "error", "warning", "hermes", "mercury", "debug",
"trace_reads");
inline constexpr auto
lookup_level_name(log_level l) {
assert(l != log::none && l != log::help);
// since all log levels are powers of 2, we can find a name
// very efficiently by counting the number of trailing 0-bits in l
const auto i = __builtin_ctz(static_cast<short>(l));
assert(i >= 0 && static_cast<std::size_t>(i) < level_names.size());
return level_names.at(i);
}
// forward declaration
struct logger;
namespace detail {
template <typename Buffer>
static inline void
log_buffer(std::FILE* fp, Buffer&& buffer) {
log_buffer(::fileno(fp), std::forward<Buffer>(buffer));
}
template <typename Buffer>
static inline void
log_buffer(int fd, Buffer&& buffer) {
if(fd < 0) {
throw std::runtime_error("Invalid file descriptor");
}
::syscall_no_intercept(SYS_write, fd, buffer.data(), buffer.size());
}
static inline void
log_buffer(int fd, const void* buffer, std::size_t length) {
if(fd < 0) {
throw std::runtime_error("Invalid file descriptor");
}
::syscall_no_intercept(SYS_write, fd, buffer, length);
}
static inline struct tm*
mini_gmtime_r(const time_t* timep, struct tm* tm) {
const time_t ts = *timep;
time_t t = ts / 86400;
unsigned hms =
ts %
86400; /* -86399 <= hms <= 86399. This needs sizeof(int) >= 4. */
time_t c, f;
unsigned yday; /* 0 <= yday <= 426. Also fits to an `unsigned short', but
`int' is faster. */
unsigned a; /* 0 <= a <= 2133. Also fits to an `unsigned short', but `int'
is faster. */
if((int) hms < 0) {
--t;
hms += 86400;
} /* Fix quotient and negative remainder if ts was negative (i.e. before
year 1970 CE). */
/* Now: -24856 <= t <= 24855. */
tm->tm_sec = hms % 60;
hms /= 60;
tm->tm_min = hms % 60;
tm->tm_hour = hms / 60;
if(sizeof(time_t) >
4) { /* Optimization. For int32_t, this would keep t intact, so we won't
have to do it. This produces unreachable code. */
f = (t + 4) % 7;
if(f < 0)
f += 7; /* Fix negative remainder if (t + 4) was negative. */
/* Now 0 <= f <= 6. */
tm->tm_wday = f;
c = (t << 2) + 102032;
f = c / 146097;
if(c % 146097 < 0)
--f; /* Fix negative remainder if c was negative. */
--f;
t += f;
f >>= 2;
t -= f;
f = (t << 2) + 102035;
c = f / 1461;
if(f % 1461 < 0)
--c; /* Fix negative remainder if f was negative. */
} else {
tm->tm_wday = (t + 24861) % 7; /* t + 24861 >= 0. */
/* Now: -24856 <= t <= 24855. */
c = ((t << 2) + 102035) / 1461;
}
yday = t - 365 * c - (c >> 2) + 25568;
/* Now: 0 <= yday <= 425. */
a = yday * 5 + 8;
/* Now: 8 <= a <= 2133. */
tm->tm_mon = a / 153;
a %= 153; /* No need to fix if a < 0, because a cannot be negative here. */
/* Now: 2 <= tm->tm_mon <= 13. */
/* Now: 0 <= a <= 152. */
tm->tm_mday = 1 + a / 5; /* No need to fix if a < 0, because a cannot be
negative here. */
/* Now: 1 <= tm->tm_mday <= 31. */
if(tm->tm_mon >= 12) {
tm->tm_mon -= 12;
/* Now: 0 <= tm->tm_mon <= 1. */
++c;
yday -= 366;
} else { /* Check for leap year (in c). */
/* Now: 2 <= tm->tm_mon <= 11. */
/* 1903: not leap; 1904: leap, 1900: not leap; 2000: leap */
/* With sizeof(time_t) == 4, we have 1901 <= year <= 2038; of these
* years only 2000 is divisble by 100, and that's a leap year, no we
* optimize the check to `(c & 3) == 0' only.
*/
if(!((c & 3) == 0 &&
(sizeof(time_t) <= 4 || c % 100 != 0 || (c + 300) % 400 == 0)))
--yday; /* These `== 0' comparisons work even if c < 0. */
}
tm->tm_year =
c; /* This assignment may overflow or underflow, we don't check it.
Example: time_t is a huge int64_t, tm->tm_year is int32_t. */
/* Now: 0 <= tm->tm_mon <= 11. */
/* Now: 0 <= yday <= 365. */
tm->tm_yday = yday;
tm->tm_isdst = 0;
return tm;
}
static inline struct tm*
mini_gmtime(const time_t* timep) {
static struct tm tm;
return mini_gmtime_r(timep, &tm);
}
static inline ssize_t
format_timeval(struct timeval* tv, char* buf, size_t sz) {
ssize_t written = -1;
struct tm* gm = mini_gmtime(&tv->tv_sec);
written = (ssize_t) strftime(buf, sz, "%Y-%m-%d %H:%M:%S", gm);
if((written > 0) && ((size_t) written < sz)) {
int w = snprintf(buf + written, sz - (size_t) written, ".%06ld",
tv->tv_usec);
written = (w > 0) ? written + w : -1;
}
return written;
}
template <typename Buffer>
static inline void
format_timestamp_to(Buffer&& buffer) {
struct ::timeval tv;
int rv = ::syscall_no_intercept(SYS_gettimeofday, &tv, NULL);
if(::syscall_error_code(rv) != 0) {
return;
}
char buf[28];
if(format_timeval(&tv, buf, sizeof(buf)) > 0) {
fmt::format_to(std::back_inserter(buffer), "[{}] ", buf);
}
}
template <typename Buffer>
static inline void
format_syscall_info_to(Buffer&& buffer, gkfs::syscall::info info) {
const auto ttid = syscall_no_intercept(SYS_gettid);
fmt::format_to(std::back_inserter(buffer), "[{}] [syscall] ", ttid);
char o;
char t;
switch(gkfs::syscall::origin(info)) {
case gkfs::syscall::from_internal_code:
o = 'i';
break;
case gkfs::syscall::from_external_code:
o = 'a';
break;
default:
o = '?';
break;
}
switch(gkfs::syscall::target(info)) {
case gkfs::syscall::to_hook:
t = 'h';
break;
case gkfs::syscall::to_kernel:
t = 'k';
break;
default:
t = '?';
break;
}
const std::array<char, 5> tmp = {'[', o, t, ']', ' '};
fmt::format_to(std::back_inserter(buffer),
fmt::string_view(tmp.data(), tmp.size()));
}
} // namespace detail
enum { max_buffer_size = LIBGKFS_LOG_MESSAGE_SIZE };
using static_buffer = fmt::basic_memory_buffer<char, max_buffer_size>;
struct logger {
logger(const std::string& opts, const std::string& path,
bool log_per_process, bool trunc
#ifdef GKFS_DEBUG_BUILD
,
const std::string& filter, int verbosity
#endif
);
~logger();
template <typename... Args>
inline void
log(log_level level, const char* const func, const int lineno,
Args&&... args) {
if(!(level & log_mask_)) {
return;
}
static_buffer buffer;
detail::format_timestamp_to(buffer);
fmt::format_to(std::back_inserter(buffer), "[{}] [{}] ",
log_process_id_, lookup_level_name(level));
if(!!(level & log::debug)) {
fmt::format_to(std::back_inserter(buffer), "<{}():{}> ", func,
lineno);
}
fmt::format_to(std::back_inserter(buffer), std::forward<Args>(args)...);
fmt::format_to(std::back_inserter(buffer), "\n");
detail::log_buffer(log_fd_, buffer);
}
inline int
log(log_level level, const char* fmt, va_list ap) {
if(!(level & log_mask_)) {
return 0;
}
// we use buffer views to compose the logging messages to
// avoid copying buffers as much as possible
struct buffer_view {
const void* addr;
std::size_t size;
};
// helper lambda to print an iterable of buffer_views
const auto log_buffer_views = [this](const auto& buffers) {
std::size_t n = 0;
for(const auto& bv : buffers) {
if(bv.addr != nullptr) {
detail::log_buffer(log_fd_, bv.addr, bv.size);
n += bv.size;
}
}
return n;
};
static_buffer prefix;
detail::format_timestamp_to(prefix);
fmt::format_to(std::back_inserter(prefix), "[{}] [{}] ",
log_process_id_, lookup_level_name(level));
char buffer[max_buffer_size];
const int n = vsnprintf(buffer, sizeof(buffer), fmt, ap);
std::array<buffer_view, 3> buffers{};
int i = 0;
int m = 0;
const char* addr = buffer;
const char* p = nullptr;
while((p = std::strstr(addr, "\n")) != nullptr) {
buffers[0] = buffer_view{prefix.data(), prefix.size()};
buffers[1] =
buffer_view{addr, static_cast<std::size_t>(p - addr) + 1};
m += log_buffer_views(buffers);
addr = p + 1;
++i;
}
// original line might not end with (or include) '\n'
if(buffer[n - 1] != '\n') {
buffers[0] = buffer_view{prefix.data(), prefix.size()};
buffers[1] = buffer_view{
addr, static_cast<std::size_t>(&buffer[n] - addr)};
buffers[2] = buffer_view{"\n", 1};
m += log_buffer_views(buffers);
}
return m;
}
template <typename... Args>
static inline void
log_message(std::FILE* fp, Args&&... args) {
log_message(::fileno(fp), std::forward<Args>(args)...);
}
template <typename... Args>
static inline void
log_message(int fd, Args&&... args) {
if(fd < 0) {
throw std::runtime_error("Invalid file descriptor");
}
static_buffer buffer;
fmt::format_to(std::back_inserter(buffer), std::forward<Args>(args)...);
fmt::format_to(std::back_inserter(buffer), "\n");
detail::log_buffer(fd, buffer);
}
void
log_syscall(syscall::info info, const long syscall_number,
const long args[6], std::optional<long> result = {});
static std::shared_ptr<logger>&
global_logger() {
static std::shared_ptr<logger> s_global_logger;
return s_global_logger;
}
int log_fd_;
int log_process_id_;
log_level log_mask_;
#ifdef GKFS_DEBUG_BUILD
std::bitset<512> filtered_syscalls_;
int debug_verbosity_;
#endif
};
// the following static functions can be used to interact
// with a globally registered logger instance
template <typename... Args>
static inline void
create_global_logger(Args&&... args) {
auto foo = std::make_shared<logger>(std::forward<Args>(args)...);
logger::global_logger() = foo;
}
static inline void
register_global_logger(logger&& lg) {
logger::global_logger() = std::make_shared<logger>(std::move(lg));
}
static inline std::shared_ptr<logger>&
get_global_logger() {
return logger::global_logger();
}
static inline void
destroy_global_logger() {
logger::global_logger().reset();
}
} // namespace gkfs::log
#define LOG(XXX, ...) LOG_##XXX(__VA_ARGS__)
#ifndef GKFS_ENABLE_LOGGING
#define LOG_INFO(...) \
do { \
} while(0);
#define LOG_WARNING(...) \
do { \
} while(0);
#define LOG_ERROR(...) \
do { \
} while(0);
#define LOG_CRITICAL(...) \
do { \
} while(0);
#define LOG_HERMES(...) \
do { \
} while(0);
#define LOG_MERCURY(...) \
do { \
} while(0);
#define LOG_SYSCALL(...) \
do { \
} while(0);
#define LOG_DEBUG(...) \
do { \
} while(0);
#define LOG_TRACE_READS(...) \
do { \
} while(0);
#else // !GKFS_ENABLE_LOGGING
#define LOG_INFO(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log(gkfs::log::info, __func__, \
__LINE__, __VA_ARGS__); \
} \
} while(0);
#define LOG_WARNING(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log(gkfs::log::warning, __func__, \
__LINE__, __VA_ARGS__); \
} \
} while(0);
#define LOG_ERROR(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log(gkfs::log::error, __func__, \
__LINE__, __VA_ARGS__); \
} \
} while(0);
#define LOG_CRITICAL(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log(gkfs::log::critical, __func__, \
__LINE__, __VA_ARGS__); \
} \
} while(0);
#define LOG_HERMES(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log(gkfs::log::hermes, __func__, \
__LINE__, __VA_ARGS__); \
} \
} while(0);
#define LOG_MERCURY(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log(gkfs::log::mercury, __func__, \
__LINE__, __VA_ARGS__); \
} \
} while(0);
#define LOG_TRACE_READS(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log( \
gkfs::log::trace_reads, __func__, __LINE__, __VA_ARGS__); \
} \
} while(0);
#ifdef GKFS_DEBUG_BUILD
#define LOG_SYSCALL(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log_syscall(__VA_ARGS__); \
} \
} while(0);
#define LOG_DEBUG(...) \
do { \
if(gkfs::log::get_global_logger()) { \
gkfs::log::get_global_logger()->log(gkfs::log::debug, __func__, \
__LINE__, __VA_ARGS__); \
} \
} while(0);
#else // ! GKFS_DEBUG_BUILD
#define LOG_SYSCALL(...) \
do { \
} while(0);
#define LOG_DEBUG(...) \
do { \
} while(0);
#endif // ! GKFS_DEBUG_BUILD
#endif // !GKFS_ENABLE_LOGGING
#endif // LIBGKFS_LOGGING_HPP