Replace spdlog with internal logging framework (9ab384e8) · Commits · hpc / gekkofs

CMakeLists.txt

+18 −1

Original line number	Diff line number	Diff line
		@@ -27,9 +27,13 @@ message(STATUS "Build type: ${CMAKE_BUILD_TYPE}")
		# Compiler flags for various cmake build types
		set(WARNINGS_FLAGS "-Wall -Wextra --pedantic -Wno-unused-parameter -Wno-missing-field-initializers")
		set(CMAKE_CXX_FLAGS_RELEASE "${CMAKE_CXX_FLAGS_RELEASE} -DNDEBUG -O3")
		set(CMAKE_CXX_FLAGS_DEBUG "${CMAKE_CXX_FLAGS_DEBUG} ${WARNINGS_FLAGS} -g -O0")
		set(CMAKE_CXX_FLAGS_DEBUG "${CMAKE_CXX_FLAGS_DEBUG} ${WARNINGS_FLAGS} -g -O0 -DGKFS_DEBUG_BUILD")
		set(CMAKE_CXX_FLAGS_MEMCHECK "${WARNINGS_FLAGS} -g -O0 -fsanitize=address -fno-omit-frame-pointer")
		set(CMAKE_CXX_FLAGS_MAINTAINER "${WARNINGS_FLAGS} -g -O0 -pg -no-pie")
		set(CMAKE_C_FLAGS_RELEASE "${CMAKE_C_FLAGS_RELEASE} -DNDEBUG -O3")
		set(CMAKE_C_FLAGS_DEBUG "${CMAKE_C_FLAGS_DEBUG} ${WARNINGS_FLAGS} -g -O0 -DGKFS_DEBUG_BUILD")
		set(CMAKE_C_FLAGS_MEMCHECK "${WARNINGS_FLAGS} -g -O0 -fsanitize=address -fno-omit-frame-pointer")
		set(CMAKE_C_FLAGS_MAINTAINER "${WARNINGS_FLAGS} -g -O0 -pg -no-pie")
		mark_as_advanced(CMAKE_CXX_FLAGS_MAINTAINER)

		# Project version
		@@ -94,6 +98,8 @@ find_package(Boost 1.53 REQUIRED

		find_package(Threads REQUIRED)

		find_package(Date REQUIRED)

		set(RPC_PROTOCOL "ofi+tcp" CACHE STRING "Communication plugin used for RPCs")
		set_property(CACHE RPC_PROTOCOL PROPERTY STRINGS
		"bmi+tcp"
		@@ -112,6 +118,10 @@ if(SYMLINK_SUPPORT)
		endif()
		message(STATUS "Symlink support: ${SYMLINK_SUPPORT}")

		set(MAX_INTERNAL_FDS 256 CACHE STRING "Number of file descriptors reserved for internal use")
		add_definitions(-DMAX_INTERNAL_FDS=${MAX_INTERNAL_FDS})
		message(STATUS "File descriptors reserved for internal use: ${MAX_INTERNAL_FDS}")

		option(USE_BITSET_FOR_INTERNAL_FDS "Use std::bitset to track internal fds" ON)
		if(USE_BITSET_FOR_INTERNAL_FDS)
		add_definitions(-DUSE_BITSET_FOR_INTERNAL_FDS)
		@@ -131,6 +141,13 @@ if(USE_BITSET_FOR_INTERNAL_FDS)
		message(STATUS "Max open files: ${GETCONF_MAX_FDS}")
		endif()


		option(ENABLE_LOGGING "Disable all logging messages" ON)
		if(NOT ENABLE_LOGGING)
		add_definitions(-DGKFS_DISABLE_LOGGING)
		endif()
		message(STATUS "Logging output: ${ENABLE_LOGGING}")

		configure_file(include/global/configure.hpp.in include/global/configure.hpp)

		# Imported target

include/client/env.hpp

0 → 100644

+37 −0

Original line number	Diff line number	Diff line
		/*
		Copyright 2018-2019, Barcelona Supercomputing Center (BSC), Spain
		Copyright 2015-2019, 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.

		SPDX-License-Identifier: MIT
		*/

		#ifndef GKFS_CLIENT_ENV
		#define GKFS_CLIENT_ENV

		#include <global/configure.hpp>

		#define ADD_PREFIX(str) CLIENT_ENV_PREFIX str

		/* Environment variables for the GekkoFS client */
		namespace gkfs {
		namespace env {

		static constexpr auto LOG = ADD_PREFIX("LOG");
		static constexpr auto LOG_OUTPUT = ADD_PREFIX("LOG_OUTPUT");
		static constexpr auto LOG_OUTPUT_TRUNC = ADD_PREFIX("LOG_OUTPUT_TRUNC");
		static constexpr auto CWD = ADD_PREFIX("CWD");
		static constexpr auto HOSTS_FILE = ADD_PREFIX("HOSTS_FILE");

		} // namespace env
		} // namespace gkfs

		#undef ADD_PREFIX

		#endif // GKFS_CLIENT_ENV

include/client/intercept.hpp

+7 −0

Original line number	Diff line number	Diff line
		@@ -14,12 +14,19 @@
		#ifndef IFS_INTERCEPT_HPP
		#define IFS_INTERCEPT_HPP

		int
		internal_hook_guard_wrapper(long syscall_number,
		long arg0, long arg1, long arg2,
		long arg3, long arg4, long arg5,
		long *syscall_return_value);

		int
		hook_guard_wrapper(long syscall_number,
		long arg0, long arg1, long arg2,
		long arg3, long arg4, long arg5,
		long *syscall_return_value);

		void start_self_interception();
		void start_interception();
		void stop_interception();

include/client/logging.hpp

0 → 100644

+495 −0

Original line number	Diff line number	Diff line
		/*
		Copyright 2018-2019, Barcelona Supercomputing Center (BSC), Spain
		Copyright 2015-2019, 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.

		SPDX-License-Identifier: MIT
		*/

		#ifndef LIBGKFS_LOGGING_HPP
		#define LIBGKFS_LOGGING_HPP

		#include <libsyscall_intercept_hook_point.h>

		#include <type_traits>
		#include <boost/optional.hpp>
		#include <client/make_array.hpp>
		#include <client/syscalls.hpp>
		#include <fmt/fmt.h>
		#include <fmt/ostr.h>
		#include <date/tz.h>

		namespace gkfs {
		namespace log {

		enum class log_level : short {
		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_mercury = 1 << 6,
		print_debug = 1 << 7,

		// for internal use
		print_none = 0,
		print_all = print_syscalls \| print_syscalls_entry \| print_info \|
		print_critical \| print_errors \| print_warnings \|
		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 mercury = log_level::print_mercury;
		static const auto constexpr debug = log_level::print_debug;
		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",
		"mercury",
		"debug"
		);

		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 {

		enum { inline_buffer_size = 0x1000 };

		using safe_buffer = fmt::basic_memory_buffer<char, inline_buffer_size>;

		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);
		}

		/**
		* format_timestamp_to - safely format a timestamp for logging messages
		*
		* This function produes a timestamp that can be used to prefix logging
		* messages. Since we are actively intercepting system calls, the formatting
		* MUST NOT rely on internal system calls, otherwise we risk recursively
		* calling ourselves for each syscall generated. Also, we cannot rely on
		* the C formatting functions asctime, ctime, gmtime, localtime, mktime,
		* asctime_r, ctime_r, gmtime_r, localtime_r, since they acquire a
		* non-reentrant lock to determine the caller's timezone (yes, the assumedly
		* reentrant *_r versions of the functions exhibit this problem as well,
		* see https://sourceware.org/bugzilla/show_bug.cgi?id=16145). To solve this
		* issue and still get readable timestamps, we determine and cache the
		* timezone when the logger is created so that the lock is only held once, by
		* one thread exactly, and we pass it as an argument whenever we need to
		* format a timestamp. If no timezone is provided, we just format the epoch.
		*
		* NOTE: we use the date C++ library to query the timezone database and
		* to format the timestamps.
		*/
		template <typename Buffer>
		static inline void
		format_timestamp_to(Buffer&& buffer,
		const date::time_zone * const timezone = nullptr) {

		struct ::timeval tv;

		int rv = ::syscall_no_intercept(SYS_gettimeofday, &tv, NULL);

		if(::syscall_error_code(rv) != 0) {
		return;
		}

		date::sys_time<std::chrono::microseconds> now{
		std::chrono::seconds{tv.tv_sec} +
		std::chrono::microseconds{tv.tv_usec}};

		if(!timezone) {
		fmt::format_to(buffer, "[{}] ", now.time_since_epoch().count());
		return;
		}

		fmt::format_to(buffer, "[{}] ",
		date::zoned_time<std::chrono::microseconds>{timezone, now});
		}

		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(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(buffer, fmt::string_view(tmp.data(), tmp.size()));
		}



		} // namespace detail

		struct logger {

		logger(const std::string& opts,
		const std::string& path,
		bool trunc);

		~logger();

		template <typename... Args>
		inline void
		log(log_level level,
		const char * const func,
		const int lineno,
		Args&&... args) {

		if(!(level & log_mask_)) {
		return;
		}

		detail::safe_buffer buffer;
		detail::format_timestamp_to(buffer, timezone_);
		fmt::format_to(buffer, "[{}] [{}] ",
		::syscall_no_intercept(SYS_gettid),
		lookup_level_name(level));

		if(!!(level & log::debug)) {
		fmt::format_to(buffer, "<{}():{}> ", func, lineno);
		}

		fmt::format_to(buffer, std::forward<Args>(args)...);
		fmt::format_to(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;
		};


		char buffer[detail::inline_buffer_size];

		detail::safe_buffer prefix;
		detail::format_timestamp_to(prefix);
		fmt::format_to(prefix, "[{}] [{}] ",
		::syscall_no_intercept(SYS_gettid),
		lookup_level_name(level));

		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");
		}

		detail::safe_buffer buffer;
		fmt::format_to(buffer, std::forward<Args>(args)...);
		fmt::format_to(buffer, "\n");
		detail::log_buffer(fd, buffer);
		}

		void
		log_syscall(syscall::info info,
		const long syscall_number,
		const long args[6],
		boost::optional<long> result = boost::none);

		static std::shared_ptr<logger>& global_logger() {
		static std::shared_ptr<logger> s_global_logger;
		return s_global_logger;
		}

		int log_fd_;
		log_level log_mask_;
		const date::time_zone * const timezone_;
		};


		// 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 log
		} // namespace gkfs

		#define LOG(XXX, ...) LOG_##XXX(__VA_ARGS__)

		#ifdef GKFS_DISABLE_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_SYSCALL(...) do {} while(0);
		#define LOG_DEBUG(...) do {} while(0);

		#else // !GKFS_DISABLE_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);

		#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_DISABLE_LOGGING

		#endif // LIBGKFS_LOGGING_HPP

include/client/make_array.hpp

0 → 100644

+35 −0

Original line number	Diff line number	Diff line
		/*
		Copyright 2018-2019, Barcelona Supercomputing Center (BSC), Spain
		Copyright 2015-2019, 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.

		SPDX-License-Identifier: MIT
		*/

		#ifndef LIBGKFS_UTILS_MAKE_ARRAY_HPP
		#define LIBGKFS_UTILS_MAKE_ARRAY_HPP

		namespace gkfs {
		namespace utils {

		template <typename... T>
		constexpr auto make_array(T&&... values) ->
		std::array<
		typename std::decay<
		typename std::common_type<T...>::type>::type,
		sizeof...(T)> {
		return std::array<
		typename std::decay<
		typename std::common_type<T...>::type>::type,
		sizeof...(T)>{std::forward<T>(values)...};
		}

		} // namespace utils
		} // namespace gkfs

		#endif // LIBGKFS_UTILS_MAKE_ARRAY_HPP