// Matrix Construct // // Copyright (C) Matrix Construct Developers, Authors & Contributors // Copyright (C) 2016-2018 Jason Volk // // Permission to use, copy, modify, and/or distribute this software for any // purpose with or without fee is hereby granted, provided that the above // copyright notice and this permission notice is present in all copies. The // full license for this software is available in the LICENSE file. #include inclusion here runs std::ios_base::Init() statically as this unit // is initialized (GNU initialization order given in Makefile). namespace ircd::log { struct confs; static bool is_conf_mask_file(const string_view &name); static bool is_conf_mask_console(const string_view &name); static void slog(const log &, const level &, const window_buffer::closure &) noexcept; static void vlog_threadsafe(const log &, const level &, const string_view &fmt, const va_rtti &ap); static std::string file_path(const level &); static void open(const level &); static void mkdir(); extern const size_t CTX_NAME_TRUNC; extern const size_t LOG_NAME_TRUNC; extern const size_t LOG_BUFSIZE; extern const std::array()> console_ansi; extern std::array()> confs; extern conf::item unmask_file; extern conf::item unmask_console; extern conf::item mask_file; extern conf::item mask_console; extern std::array()> file; extern std::array()> console_quiet_stdout; extern std::array()> console_quiet_stderr; std::ostream &out_console{std::cout}; std::ostream &err_console{std::cerr}; } struct ircd::log::confs { conf::item file_enable; conf::item file_flush; conf::item console_stdout; conf::item console_stderr; conf::item console_flush; }; /// Linkage for list of named loggers. template<> decltype(ircd::instance_list::allocator) ircd::instance_list::allocator {}; template<> decltype(ircd::instance_list::list) ircd::instance_list::list { allocator }; decltype(ircd::log::file) ircd::log::file; decltype(ircd::log::console_quiet_stdout) ircd::log::console_quiet_stdout; decltype(ircd::log::console_quiet_stderr) ircd::log::console_quiet_stderr; decltype(ircd::log::LOG_BUFSIZE) ircd::log::LOG_BUFSIZE { 1024 }; decltype(ircd::log::LOG_NAME_TRUNC) ircd::log::LOG_NAME_TRUNC { 12 }; decltype(ircd::log::CTX_NAME_TRUNC) ircd::log::CTX_NAME_TRUNC { 10 }; /// The '*' logger is for log::mark()'s which do not target any specific named /// logger because such mark()'s are not repeated to all named loggers. The '*' /// logger should not otherwise be the target of log messages. decltype(ircd::log::star) ircd::log::star { "*", '*' }; /// The general logger is for all core and miscellaneous log messages. This /// is the default logger target for log:: calls which do not pass a specific /// logger. decltype(ircd::log::general) ircd::log::general { "ircd", 'G' }; decltype(ircd::log::hook) ircd::log::hook; // // init // void ircd::log::init() { // DEBUG is very noisy so it always starts off by default unless -debug if(!ircd::debugmode) console_disable(level::DEBUG); // In non-debug-mode compilation we don't want DWARNING and DERROR // messages which weren't DCE'ed to be displayed by default. if(!RB_DEBUG_LEVEL && !ircd::debugmode) { console_disable(level::DERROR); console_disable(level::DWARNING); } if(ircd::write_avoid) return; mkdir(); } void ircd::log::fini() { flush(); close(); } void ircd::log::mkdir() { if(fs::exists(fs::base::log)) return; fs::mkdir(fs::base::log); } // // interface // void ircd::log::open() { for_each([](const level &lev) { if(lev > RB_LOG_LEVEL) return; const auto &conf(confs.at(lev)); if(!bool(conf.file_enable)) return; if(file[lev].is_open()) file[lev].close(); file[lev].clear(); file[lev].exceptions(std::ios::badbit | std::ios::failbit); open(lev); }); } void ircd::log::close() { for_each([](const level &lev) { if(lev > RB_LOG_LEVEL) return; if(file[lev].is_open()) file[lev].close(); }); } void ircd::log::flush() { for_each([](const level &lev) { if(lev > RB_LOG_LEVEL) return; file[lev].flush(); }); std::flush(out_console); std::flush(err_console); } void ircd::log::open(const level &lev) try { const auto &mode(std::ios::app); const auto &path(file_path(lev)); file[lev].open(path.c_str(), mode); } catch(const std::exception &e) { fprintf(stderr, "!!! Opening log file [%s] failed: %s", file_path(lev).c_str(), e.what()); throw; } std::string ircd::log::file_path(const level &lev) { return fs::path_string(fs::path_views { fs::base::log, reflect(lev) }); } void ircd::log::console_enable() { for_each([](const level &lev) { console_enable(lev); }); } void ircd::log::console_disable() { for_each([](const level &lev) { console_disable(lev); }); } void ircd::log::console_enable(const level &lev) { if(console_quiet_stdout[lev]) console_quiet_stdout[lev]--; if(console_quiet_stderr[lev]) console_quiet_stderr[lev]--; } void ircd::log::console_disable(const level &lev) { console_quiet_stdout[lev]++; console_quiet_stderr[lev]++; } bool ircd::log::console_enabled(const level &lev) { return !console_quiet_stdout[lev] || !console_quiet_stderr[lev]; } void ircd::log::file_mask(const vector_view &list) { for(auto *const &log : log::list) log->fmasked = std::find(begin(list), end(list), log->name) != end(list); } void ircd::log::file_unmask(const vector_view &list) { for(auto *const &log : log::list) log->fmasked = std::find(begin(list), end(list), log->name) == end(list); } void ircd::log::console_mask(const vector_view &list) { for(auto *const &log : log::list) log->cmasked = std::find(begin(list), end(list), log->name) != end(list); } void ircd::log::console_unmask(const vector_view &list) { for(auto *const &log : log::list) log->cmasked = std::find(begin(list), end(list), log->name) == end(list); } // // console quiet // ircd::log::console_quiet::console_quiet(const bool &showmsg) { if(showmsg) notice("Log messages are now quieted at the console"); console_disable(); } ircd::log::console_quiet::~console_quiet() { console_enable(); } // // mark // ircd::log::mark::mark(const string_view &msg) { for_each([&msg] (const auto &lev) { if(lev > RB_LOG_LEVEL) return; mark(lev, msg); }); } ircd::log::mark::mark(const level &lev, const string_view &msg) { vlog(star, lev, "%s", msg); } // // log // ircd::log::log * ircd::log::log::find(const string_view &name) { const auto it { std::find_if(begin(list), end(list), [&name] (const auto *const &log) { return log->name == name; }) }; return *it; } ircd::log::log * ircd::log::log::find(const char &snote) { const auto it { std::find_if(begin(list), end(list), [&snote] (const auto *const &log) { return log->snote == snote; }) }; return *it; } /// This function is related to cross-thread logging; its purpose /// is to check if a given named logger still exists after the pointer /// is conveyed to the main thread from some other thread. bool ircd::log::log::exists(const log *const &ptr) { const auto it { std::find_if(begin(list), end(list), [&ptr] (const auto *const &log) { return log == ptr; }) }; return it != end(list); } // // log::log // ircd::log::log::log(const string_view &name, const char &snote) :name{name} ,snote{snote} ,cmasked { is_conf_mask_console(name) } ,fmasked { is_conf_mask_file(name) } { for(const auto *const &other : list) { if(other == this) continue; if(other->name == name) throw ircd::error { "Logger with name '%s' already exists at %p", name, other }; if(snote != '\0' && other->snote == snote) throw ircd::error { "Logger with snote '%c' is '%s' and already exists at %p", snote, other->name, other }; } } // required for instance_list template instantiation. ircd::log::log::~log() noexcept { } // // vlog // /// ircd::log is not thread-safe. This internal function is called when the /// normal vlog() detects it's not on the main IRCd thread. It then generates /// the formatted log message on this thread, and posts the message to the /// main IRCd event loop which is running on the main thread. void ircd::log::vlog_threadsafe(const log &log, const level &lev, const string_view &fmt, const va_rtti &ap) { static ios::descriptor descriptor { "ircd::log::vlog_threadsafe" }; // Generate the formatted message on this thread first std::string str { fmt::vsnstringf(1024, fmt, ap) }; // The pointer to the logger is copied to the main thread. auto *const logp{&log}; ircd::post(descriptor, [lev, str(std::move(str)), logp] { // If that named logger was destroyed while this closure was // travelling to the main thread then we just discard this message. if(!log::exists(logp)) return; slog(*logp, lev, [&str](const mutable_buffer &out) -> size_t { return copy(out, string_view{str}); }); }); } ircd::log::vlog::vlog(const log &log, const level &lev, const string_view &fmt, const va_rtti &ap) { if(!is_main_thread() && likely(ios::available())) { vlog_threadsafe(log, lev, fmt, ap); return; } slog(log, lev, [&fmt, &ap](const mutable_buffer &out) -> size_t { return fmt::vsprintf(out, fmt, ap); }); } namespace ircd::log { bool entered; static bool can_skip(const log &, const level &); } void __attribute__((optimize("3"))) ircd::log::slog(const log &log, const level &lev, const window_buffer::closure &closure) noexcept { if(can_skip(log, lev)) return; // Have to be on the main thread to call slog(). assert_main_thread(); // During the composition of this log message, if another log message // is created from calls for normal reasons or from errors, it's a // problem too. We can only have one log slog() at a time for now... const reentrance_assertion ra; // If slog() yields for some reason that's not good either... const ctx::critical_assertion ca; // The principal buffer doesn't have to be static but courtesy of all the // above effort we might as well take advantage... static char buf[LOG_BUFSIZE], date[64]; // Maximum size of log line leaving 2 characters for \r\n const size_t max(sizeof(buf) - 2); // Get the ANSI color for the level. const string_view &console_ansi { ircd::log::console_ansi.at(lev) }; // Get one of the two primary slice epoch counters. If this is being // invoked on an ircd::ctx, we grab the ctx slice counter; otherwise we // grab the ios slice counter. const auto &epoch { ctx::current? ctx::epoch() : ios::epoch() }; // With two possible slice epoch counters, the number of characters // required for the epoch column might be different between two adjacent // log messages. To maintain alignment we use this monotonic counter which // gets bumped the first time either epoch value requires more columns. To // minimize overhead here we simply settle for 3 different widths. static size_t epoch_width{6}; epoch_width = epoch < 1'000'000UL? std::max(epoch_width, 6UL): epoch < 100'000'000UL? std::max(epoch_width, 8UL): std::max(epoch_width, 12UL); // Compose the prefix sequence into the buffer through stringstream std::stringstream s; pubsetbuf(s, buf); s << microdate(date) << ' ' << std::setw(epoch_width) << std::right << epoch << ' ' << console_ansi << std::setw(8) << std::right << reflect(lev) << (console_ansi? "\033[0m " : " ") // << (log.snote? log.snote : '-') << std::setw(LOG_NAME_TRUNC) << std::left << trunc(log.name, LOG_NAME_TRUNC) << ' ' << std::setw(5) << std::right << ctx::id() << ' ' << std::setw(CTX_NAME_TRUNC) << std::left << trunc(ctx::name(), CTX_NAME_TRUNC) << " :"; // Compose the user message after prefix const size_t pos(s.tellp()); const mutable_buffer userspace{buf + pos, max - pos}; window_buffer sb{userspace}; sb(closure); // Compose the newline after user message. size_t len{pos + sb.consumed()}; assert(len + 2 <= sizeof(buf)); buf[len++] = '\r'; buf[len++] = '\n'; // The final message assert(len <= sizeof(buf)); const string_view msg{buf, len}; // Call the hooks listening for log messages. The return value in // `used` indicates at least one function was called, which we expect // after calling can_skip() above. bool used {false}; hook(used, log, lev, msg); assert(used); } bool __attribute__((optimize("3"))) ircd::log::can_skip(const log &log, const level &lev) { // Nobody is listening. if(hook.empty()) return true; // If used remains false, we can skip generating this log message; none // of the listeners will be making use of it. bool used {false}; hook(used, log, lev, string_view{}); return !used; } // // Primary internal log hooks. This will likely be moved out to // `$(topdir)/construct` at some point. // namespace ircd::log { static void check(std::ostream &) noexcept; static void handle_to_stdout(bool &, const log &, const level &, const string_view &) noexcept; static void handle_to_file(bool &, const log &, const level &, const string_view &) noexcept; extern hook::callback log_to_stdout; extern hook::callback log_to_file; } decltype(ircd::log::log_to_file) ircd::log::log_to_file { hook, handle_to_file }; void ircd::log::handle_to_file(bool &ret, const log &log, const level &lev, const string_view &msg) noexcept { const auto &conf { confs.at(lev) }; const bool copy_to_file { file[lev].is_open() && (log.fmasked || lev == level::CRITICAL) }; ret |= copy_to_file; if(!copy_to_file || !msg) return; file[lev].clear(); check(file[lev]); file[lev].write(data(msg), size(msg)); if(conf.file_flush) std::flush(file[lev]); } decltype(ircd::log::log_to_stdout) ircd::log::log_to_stdout { hook, handle_to_stdout }; void ircd::log::handle_to_stdout(bool &ret, const log &log, const level &lev, const string_view &msg) noexcept { const auto &conf { confs.at(lev) }; const bool copy_to_stderr { bool(conf.console_stderr) && ((!console_quiet_stderr[lev] && log.cmasked) || lev == level::CRITICAL) }; const bool copy_to_stdout { bool(conf.console_stdout) && ((!console_quiet_stdout[lev] && log.cmasked) || log.snote == '*') }; ret |= copy_to_stdout | copy_to_stderr; if((!copy_to_stdout && !copy_to_stderr) || !msg) return; if(unlikely(copy_to_stderr)) { err_console.clear(); check(err_console); err_console.write(data(msg), size(msg)); } if(likely(copy_to_stdout)) { out_console.clear(); check(out_console); out_console.write(data(msg), size(msg)); if(conf.console_flush) std::flush(out_console); } } // // ircd::log util // void ircd::log::check(std::ostream &s) noexcept try { if(likely(s.good())) return; thread_local char buf[128]; snprintf(buf, sizeof(buf), "fatal: log stream good[%d] bad[%d] fail[%d] eof[%d]", s.good(), s.bad(), s.fail(), s.eof()); fprintf(stderr, "log stream(%p) fatal: %s\n", (const void *)&s, buf); fprintf(stdout, "log stream(%p) fatal: %s\n", (const void *)&s, buf); fflush(stderr); fflush(stdout); s.exceptions(s.eofbit | s.failbit | s.badbit); throw std::runtime_error(buf); } catch(const std::exception &e) { fprintf(stderr, "%s\n", e.what()); fprintf(stdout, "%s\n", e.what()); fflush(stderr); fflush(stdout); ircd::terminate(); } ircd::log::level ircd::log::reflect(const string_view &f) { if(f == "CRITICAL") return level::CRITICAL; if(f == "ERROR") return level::ERROR; if(f == "DERROR") return level::DERROR; if(f == "DWARNING") return level::DWARNING; if(f == "WARNING") return level::WARNING; if(f == "NOTICE") return level::NOTICE; if(f == "INFO") return level::INFO; if(f == "DEBUG") return level::DEBUG; throw ircd::error { "'%s' is not a recognized log level", f }; } ircd::string_view ircd::log::reflect(const level &f) { switch(f) { case level::CRITICAL: return "CRITICAL"; case level::ERROR: return "ERROR"; case level::DERROR: return "ERROR"; case level::WARNING: return "WARNING"; case level::DWARNING: return "WARNING"; case level::INFO: return "INFO"; case level::NOTICE: return "NOTICE"; case level::DEBUG: return "DEBUG"; case level::_NUM_: break; // Allows -Wswitch to remind developer to add reflection here }; throw panic { "'%d' is not a recognized log level", int(f) }; } decltype(ircd::log::console_ansi) ircd::log::console_ansi {{ "\033[1;5;37;45m"_sv, // CRITICAL "\033[1;37;41m"_sv, // ERROR "\033[0;30;43m"_sv, // WARNING "\033[1;37;46m"_sv, // NOTICE "\033[1;37;42m"_sv, // INFO "\033[0;31;47m"_sv, // DERROR "\033[0;30;47m"_sv, // DWARNING "\033[1;30;47m"_sv, // DEBUG }}; bool ircd::log::is_conf_mask_console(const string_view &name) { if(token_exists(string_view(mask_console), ' ', name)) return true; if(token_exists(string_view(unmask_console), ' ', name)) return false; // When nothing is in the list then we consider this item masked. return empty(string_view(mask_console)); } bool ircd::log::is_conf_mask_file(const string_view &name) { if(token_exists(string_view(mask_file), ' ', name)) return true; if(token_exists(string_view(unmask_file), ' ', name)) return false; // When nothing is in the list then we consider this item masked. return empty(string_view(mask_file)); } decltype(ircd::log::unmask_file) ircd::log::unmask_file { { { "name", "ircd.log.unmask.file" }, { "default", string_view{} }, }, [] { if(!empty(string_view(unmask_file))) file_unmask(tokens(unmask_file, ' ')); } }; decltype(ircd::log::unmask_console) ircd::log::unmask_console { { { "name", "ircd.log.unmask.console" }, { "default", string_view{} }, }, [] { if(!empty(string_view(unmask_console))) console_unmask(tokens(unmask_console, ' ')); } }; decltype(ircd::log::mask_file) ircd::log::mask_file { { { "name", "ircd.log.mask.file" }, { "default", string_view{} }, }, [] { if(!empty(string_view(mask_file))) file_mask(tokens(mask_file, ' ')); } }; decltype(ircd::log::mask_console) ircd::log::mask_console { { { "name", "ircd.log.mask.console" }, { "default", string_view{} }, }, [] { if(!empty(string_view(mask_console))) console_mask(tokens(mask_console, ' ')); } }; decltype(ircd::log::confs) ircd::log::confs {{ // CRITICAL { // file enable { { "name", "ircd.log.critical.file.enable" }, { "default", false }, }, // file flush { { "name", "ircd.log.critical.file.flush" }, { "default", false }, }, // console enable on stdout { { "name", "ircd.log.critical.console.stdout" }, { "default", true }, }, // console enable on stderr { { "name", "ircd.log.critical.console.stderr" }, { "default", false }, }, // console flush { { "name", "ircd.log.critical.console.flush" }, { "default", true }, }, }, // ERROR { // file enable { { "name", "ircd.log.error.file.enable" }, { "default", false }, }, // file flush { { "name", "ircd.log.error.file.flush" }, { "default", false }, }, // console enable on stdout { { "name", "ircd.log.error.console.stdout" }, { "default", true }, }, // console enable on stderr { { "name", "ircd.log.error.console.stderr" }, { "default", false }, }, // console flush { { "name", "ircd.log.error.console.flush" }, { "default", true }, }, }, // WARNING { // file enable { { "name", "ircd.log.warning.file.enable" }, { "default", false }, }, // file flush { { "name", "ircd.log.warning.file.flush" }, { "default", false }, }, // console enable on stdout { { "name", "ircd.log.warning.console.stdout" }, { "default", true }, }, // console enable on stderr { { "name", "ircd.log.warning.console.stderr" }, { "default", false }, }, // console flush { { "name", "ircd.log.warning.console.flush" }, { "default", true }, }, }, // NOTICE { // file enable { { "name", "ircd.log.notice.file.enable" }, { "default", false }, }, // file flush { { "name", "ircd.log.notice.file.flush" }, { "default", false }, }, // console enable on stdout { { "name", "ircd.log.notice.console.stdout" }, { "default", true }, }, // console enable on stderr { { "name", "ircd.log.notice.console.stderr" }, { "default", false }, }, // console flush { { "name", "ircd.log.notice.console.flush" }, { "default", true }, }, }, // INFO { // file enable { { "name", "ircd.log.info.file.enable" }, { "default", false }, }, // file flush { { "name", "ircd.log.info.file.flush" }, { "default", false }, }, // console enable on stdout { { "name", "ircd.log.info.console.stdout" }, { "default", true }, }, // console enable on stderr { { "name", "ircd.log.info.console.stderr" }, { "default", false }, }, // console flush { { "name", "ircd.log.info.console.flush" }, { "default", true }, }, }, // DERROR { // file enable { { "name", "ircd.log.derror.file.enable" }, { "default", false }, }, // file flush { { "name", "ircd.log.derror.file.flush" }, { "default", false }, }, // console enable on stdout { { "name", "ircd.log.derror.console.stdout" }, { "default", true }, }, // console enable on stderr { { "name", "ircd.log.derror.console.stderr" }, { "default", false }, }, // console flush { { "name", "ircd.log.derror.console.flush" }, { "default", true }, }, }, // DWARNING { // file enable { { "name", "ircd.log.dwarning.file.enable" }, { "default", false }, }, // file flush { { "name", "ircd.log.dwarning.file.flush" }, { "default", false }, }, // console enable on stdout { { "name", "ircd.log.dwarning.console.stdout" }, { "default", true }, }, // console enable on stderr { { "name", "ircd.log.dwarning.console.stderr" }, { "default", false }, }, // console flush { { "name", "ircd.log.dwarning.console.flush" }, { "default", false }, }, }, // DEBUG { // file enable { { "name", "ircd.log.debug.file.enable" }, { "default", false }, }, // file flush { { "name", "ircd.log.debug.file.flush" }, { "default", false }, }, // console enable on stdout { { "name", "ircd.log.debug.console.stdout" }, { "default", true }, }, // console enable on stderr { { "name", "ircd.log.debug.console.stderr" }, { "default", false }, }, // console flush { { "name", "ircd.log.debug.console.flush" }, { "default", false }, }, } }};