diff options
Diffstat (limited to 'host/lib/utils/log.cpp')
| -rw-r--r-- | host/lib/utils/log.cpp | 511 |
1 files changed, 408 insertions, 103 deletions
diff --git a/host/lib/utils/log.cpp b/host/lib/utils/log.cpp index 4e58ce894..6a694ed8e 100644 --- a/host/lib/utils/log.cpp +++ b/host/lib/utils/log.cpp @@ -16,150 +16,455 @@ // #include <uhd/utils/log.hpp> -#include <uhd/utils/msg.hpp> +#include <uhd/utils/log_add.hpp> #include <uhd/utils/static.hpp> #include <uhd/utils/paths.hpp> -#include <boost/filesystem.hpp> -#include <boost/format.hpp> -#include <boost/thread/mutex.hpp> +#include <uhd/transport/bounded_buffer.hpp> +#include <uhd/version.hpp> #include <boost/date_time/posix_time/posix_time.hpp> -#include <boost/thread/locks.hpp> -#include <boost/interprocess/sync/file_lock.hpp> +#include <boost/make_shared.hpp> #include <fstream> #include <cctype> +#include <atomic> +#include <mutex> +#include <memory> +#include <thread> -namespace fs = boost::filesystem; namespace pt = boost::posix_time; -namespace ip = boost::interprocess; + +// Don't make these static const std::string -- we need their lifetime guaranteed! +#define PURPLE "\033[35;1m" // purple +#define BLUE "\033[34;1m" // blue +#define GREEN "\033[32;1m" // green +#define YELLOW "\033[33;1m" // yellow +#define RED "\033[31;0m" // red +#define BRED "\033[31;1m" // bright red +#define RESET_COLORS "\033[39;0m" // reset colors /*********************************************************************** - * Global resources for the logger + * Helpers **********************************************************************/ -class log_resource_type{ +static std::string verbosity_color(const uhd::log::severity_level &level){ + switch(level){ + case (uhd::log::trace): + return PURPLE; + case(uhd::log::debug): + return BLUE; + case(uhd::log::info): + return GREEN; + case(uhd::log::warning): + return YELLOW; + case(uhd::log::error): + return RED; + case(uhd::log::fatal): + return BRED; + default: + return RESET_COLORS; + } +} + +static std::string verbosity_name(const uhd::log::severity_level &level){ + switch(level){ + case (uhd::log::trace): + return "TRACE"; + case(uhd::log::debug): + return "DEBUG"; + case(uhd::log::info): + return "INFO"; + case(uhd::log::warning): + return "WARNING"; + case(uhd::log::error): + return "ERROR"; + case(uhd::log::fatal): + return "FATAL"; + default: + return "-"; + } + return ""; +} + +//! get the relative file path from the host directory +inline std::string path_to_filename(std::string path) +{ + return path.substr(path.find_last_of("/\\") + 1); +} + +/*********************************************************************** + * Logger backends + **********************************************************************/ +void console_log( + const uhd::log::logging_info &log_info +) { + + std::clog +#ifdef UHD_LOG_CONSOLE_COLOR + << verbosity_color(log_info.verbosity) +#endif +#ifdef UHD_LOG_CONSOLE_TIME + << "[" << pt::to_simple_string(log_info.time) << "] " +#endif +#ifdef UHD_LOG_CONSOLE_THREAD + << "[0x" << log_info.thread_id << "] " +#endif +#ifdef UHD_LOG_CONSOLE_SRC + << "[" << path_to_filename(log_info.file) << ":" << log_info.line << "] " +#endif + << "[" << verbosity_name(log_info.verbosity) << "] " + << "[" << log_info.component << "] " +#ifdef UHD_LOG_CONSOLE_COLOR + << RESET_COLORS +#endif + << log_info.message + << std::endl + ; +} + +/*! Helper class to implement file logging + * + * The class holds references to the file stream object, and handles closing + * and cleanup. + */ +class file_logger_backend +{ public: - uhd::_log::verbosity_t level; + file_logger_backend(const std::string &file_path) + { + _file_stream.exceptions(std::ofstream::failbit | std::ofstream::badbit); + if (!file_path.empty()){ + try { + _file_stream.open(file_path.c_str(), std::fstream::out | std::fstream::app); + } catch (const std::ofstream::failure& fail){ + std::cerr << "Error opening log file: " << fail.what() << std::endl; + } + } + } + + void log(const uhd::log::logging_info &log_info) + { + if (_file_stream.is_open()){ + _file_stream + << pt::to_simple_string(log_info.time) << "," + << "0x" << log_info.thread_id << "," + << path_to_filename(log_info.file) << ":" << log_info.line << "," + << log_info.verbosity << "," + << log_info.component << "," + << log_info.message + << std::endl; + ; + } + } - log_resource_type(void){ - //file lock pointer must be null - _file_lock = NULL; + ~file_logger_backend() + { + if (_file_stream.is_open()){ + _file_stream.close(); + } + } - //set the default log level - level = uhd::_log::never; +private: + std::ofstream _file_stream; +}; - //allow override from macro definition - #ifdef UHD_LOG_LEVEL - _set_log_level(BOOST_STRINGIZE(UHD_LOG_LEVEL)); - #endif +/*********************************************************************** + * Global resources for the logger + **********************************************************************/ + +#define UHD_CONSOLE_LOGGER_KEY "console" +#define UHD_FILE_LOGGER_KEY "file" + +class log_resource { +public: + uhd::log::severity_level global_level; + std::map<std::string, uhd::log::severity_level> logger_level; - //allow override from environment variable + log_resource(void): + global_level(uhd::log::off), + _exit(false), +#ifndef UHD_LOG_FASTPATH_DISABLE + _fastpath_queue(10), +#endif + _log_queue(10) + { + //allow override from macro definition +#ifdef UHD_LOG_MIN_LEVEL + this->global_level = _get_log_level(BOOST_STRINGIZE(UHD_LOG_MIN_LEVEL), this->global_level); +#endif + //allow override from environment variables const char * log_level_env = std::getenv("UHD_LOG_LEVEL"); - if (log_level_env != NULL) _set_log_level(log_level_env); + if (log_level_env != NULL && log_level_env[0] != '\0') { + this->global_level = + _get_log_level(log_level_env, this->global_level); + } + + + /***** Console logging ***********************************************/ +#ifndef UHD_LOG_CONSOLE_DISABLE + uhd::log::severity_level console_level = uhd::log::trace; +#ifdef UHD_LOG_CONSOLE_LEVEL + console_level = _get_log_level(BOOST_STRINGIZE(UHD_LOG_CONSOLE_LEVEL), console_level); +#endif + const char * log_console_level_env = std::getenv("UHD_LOG_CONSOLE_LEVEL"); + if (log_console_level_env != NULL && log_console_level_env[0] != '\0') { + console_level = + _get_log_level(log_console_level_env, console_level); + } + logger_level[UHD_CONSOLE_LOGGER_KEY] = console_level; + _loggers[UHD_CONSOLE_LOGGER_KEY] = &console_log; +#endif + + /***** File logging **************************************************/ + uhd::log::severity_level file_level = uhd::log::trace; + std::string log_file_target; +#if defined(UHD_LOG_FILE_LEVEL) && defined(UHD_LOG_FILE_PATH) + file_level = _get_log_level(BOOST_STRINGIZE(UHD_LOG_FILE_LEVEL), file_level); + log_file_target = BOOST_STRINGIZE(UHD_LOG_FILE); +#endif + const char * log_file_level_env = std::getenv("UHD_LOG_FILE_LEVEL"); + if (log_file_level_env != NULL && log_file_level_env[0] != '\0'){ + file_level = _get_log_level(log_file_level_env, file_level); + } + const char* log_file_env = std::getenv("UHD_LOG_FILE"); + if ((log_file_env != NULL) && (log_file_env[0] != '\0')) { + log_file_target = std::string(log_file_env); + } + if (!log_file_target.empty()){ + logger_level[UHD_FILE_LOGGER_KEY] = file_level; + auto F = boost::make_shared<file_logger_backend>(log_file_target); + _loggers[UHD_FILE_LOGGER_KEY] = [F](const uhd::log::logging_info& log_info){F->log(log_info);}; + } + std::ostringstream sys_info; + sys_info \ + << "UHD" \ + << BOOST_PLATFORM << "; " + << BOOST_COMPILER << "; " + << "Boost_" + << BOOST_VERSION << "; " + << "UHD_" << uhd::get_version_string(); + _log_queue.push_with_timed_wait( + uhd::log::logging_info( + pt::microsec_clock::local_time(), + uhd::log::info, + __FILE__, + __LINE__, + sys_info.str(), + boost::this_thread::get_id()), + 0.25); + + // Launch log message consumer + _pop_task = std::make_shared<std::thread>(std::thread([this](){this->pop_task();})); + _pop_fastpath_task = std::make_shared<std::thread>(std::thread([this](){this->pop_fastpath_task();})); } - ~log_resource_type(void){ - boost::lock_guard<boost::mutex> lock(_mutex); - _file_stream.close(); - if (_file_lock != NULL) delete _file_lock; + ~log_resource(void){ + _exit = true; + // We push a final message to kick the pop task out of it's wait state. + // This wouldn't be necessary if pop_with_wait() could fail. Should + // that ever get fixed, we can remove this. + auto final_message = uhd::log::logging_info( + pt::microsec_clock::local_time(), + uhd::log::trace, + __FILE__, + __LINE__, + "LOGGING", + boost::this_thread::get_id() + ); + final_message.message = "Terminating logger."; + push(final_message); +#ifndef UHD_LOG_FASTPATH_DISABLE + push_fastpath(""); +#endif + _pop_task->join(); + { + std::lock_guard<std::mutex> l(_logmap_mutex); + _loggers.clear(); + } + _pop_task.reset(); +#ifndef UHD_LOG_FASTPATH_DISABLE + _pop_fastpath_task->join(); + _pop_fastpath_task.reset(); +#endif } - void log_to_file(const std::string &log_msg){ - boost::lock_guard<boost::mutex> lock(_mutex); - if (_file_lock == NULL){ - const std::string log_path = (fs::path(uhd::get_tmp_path()) / "uhd.log").string(); - _file_stream.open(log_path.c_str(), std::fstream::out | std::fstream::app); - _file_lock = new ip::file_lock(log_path.c_str()); + void push(const uhd::log::logging_info& log_info) + { + static const double PUSH_TIMEOUT = 0.25; // seconds + _log_queue.push_with_timed_wait(log_info, PUSH_TIMEOUT); + } + + void push_fastpath(const std::string &message) + { + // Never wait. If the buffer is full, we just don't see the message. + // Too bad. +#ifndef UHD_LOG_FASTPATH_DISABLE + _fastpath_queue.push_with_haste(message); +#endif + } + + void pop_task() + { + uhd::log::logging_info log_info; + log_info.message = ""; + + while (!_exit) { + _log_queue.pop_with_wait(log_info); + { + std::lock_guard<std::mutex> l(_logmap_mutex); + for (const auto &logger : _loggers) { + auto level = logger_level.find(logger.first); + if(level != logger_level.end() && log_info.verbosity < level->second){ + continue; + } + logger.second(log_info); + } + } + } + + // Exit procedure: Clear the queue + while (_log_queue.pop_with_haste(log_info)) { + std::lock_guard<std::mutex> l(_logmap_mutex); + for (const auto &logger : _loggers) { + auto level = logger_level.find(logger.first); + if (level != logger_level.end() && log_info.verbosity < level->second){ + continue; + } + logger.second(log_info); + } } - _file_lock->lock(); - _file_stream << log_msg << std::flush; - _file_lock->unlock(); + } + + void pop_fastpath_task() + { +#ifndef UHD_LOG_FASTPATH_DISABLE + while (!_exit) { + std::string msg; + _fastpath_queue.pop_with_wait(msg); + { + std::cerr << msg << std::flush; + } + } + + // Exit procedure: Clear the queue + std::string msg; + while (_fastpath_queue.pop_with_haste(msg)) { + std::cerr << msg << std::flush; + } +#endif + } + + + void add_logger(const std::string &key, uhd::log::log_fn_t logger_fn) + { + std::lock_guard<std::mutex> l(_logmap_mutex); + _loggers[key] = logger_fn; } private: - //! set the log level from a string that is either a digit or an enum name - void _set_log_level(const std::string &log_level_str){ - const uhd::_log::verbosity_t log_level_num = uhd::_log::verbosity_t(log_level_str[0]-'0'); - if (std::isdigit(log_level_str[0]) and log_level_num >= uhd::_log::always and log_level_num <= uhd::_log::never){ - this->level = log_level_num; - return; + std::shared_ptr<std::thread> _pop_task; +#ifndef UHD_LOG_FASTPATH_DISABLE + std::shared_ptr<std::thread> _pop_fastpath_task; +#endif + uhd::log::severity_level _get_log_level(const std::string &log_level_str, + const uhd::log::severity_level &previous_level){ + if (std::isdigit(log_level_str[0])) { + const uhd::log::severity_level log_level_num = + uhd::log::severity_level(std::stoi(log_level_str)); + if (log_level_num >= uhd::log::trace and + log_level_num <= uhd::log::fatal) { + return log_level_num; + }else{ + UHD_LOGGER_ERROR("LOG") << "Failed to set log level to: " << log_level_str; + return previous_level; + } } - #define if_lls_equal(name) else if(log_level_str == #name) this->level = uhd::_log::name - if_lls_equal(always); - if_lls_equal(often); - if_lls_equal(regularly); - if_lls_equal(rarely); - if_lls_equal(very_rarely); - if_lls_equal(never); + +#define if_loglevel_equal(name) \ + else if (log_level_str == #name) return uhd::log::name + if_loglevel_equal(trace); + if_loglevel_equal(debug); + if_loglevel_equal(info); + if_loglevel_equal(warning); + if_loglevel_equal(error); + if_loglevel_equal(fatal); + if_loglevel_equal(off); + return previous_level; } - //file stream and lock: - std::ofstream _file_stream; - ip::file_lock *_file_lock; - boost::mutex _mutex; + std::mutex _logmap_mutex; + std::atomic<bool> _exit; + std::map<std::string, uhd::log::log_fn_t> _loggers; +#ifndef UHD_LOG_FASTPATH_DISABLE + uhd::transport::bounded_buffer<std::string> _fastpath_queue; +#endif + uhd::transport::bounded_buffer<uhd::log::logging_info> _log_queue; }; -UHD_SINGLETON_FCN(log_resource_type, log_rs); +UHD_SINGLETON_FCN(log_resource, log_rs); /*********************************************************************** * The logger object implementation **********************************************************************/ -//! get the relative file path from the host directory -static std::string get_rel_file_path(const fs::path &file){ - fs::path abs_path = file.parent_path(); - fs::path rel_path = file.leaf(); - while (not abs_path.empty() and abs_path.leaf() != "host"){ - rel_path = abs_path.leaf() / rel_path; - abs_path = abs_path.parent_path(); - } - return rel_path.string(); -} - - uhd::_log::log::log( - const verbosity_t verbosity, + const uhd::log::severity_level verbosity, const std::string &file, const unsigned int line, - const std::string &function - ) + const std::string &component, + const boost::thread::id thread_id + ) : + _log_it(verbosity >= log_rs().global_level) { - _log_it = (verbosity >= log_rs().level); - if (_log_it) - { - const std::string time = pt::to_simple_string(pt::microsec_clock::local_time()); - const std::string header1 = str(boost::format("-- %s - level %d") % time % int(verbosity)); - const std::string header2 = str(boost::format("-- %s") % function).substr(0, 80); - const std::string header3 = str(boost::format("-- %s:%u") % get_rel_file_path(file) % line); - const std::string border = std::string(std::max(std::max(header1.size(), header2.size()), header3.size()), '-'); - _ss << std::endl - << border << std::endl - << header1 << std::endl - << header2 << std::endl - << header3 << std::endl - << border << std::endl - ; - } + if (_log_it){ + this->_log_info = uhd::log::logging_info( + pt::microsec_clock::local_time(), + verbosity, + file, + line, + component, + thread_id); + } } uhd::_log::log::~log(void) { - if (not _log_it) - return; - - _ss << std::endl; - try{ - log_rs().log_to_file(_ss.str()); - } - catch(const std::exception &e){ - /*! - * Critical behavior below. - * The following steps must happen in order to avoid a lock-up condition. - * This is because the message facility will call into the logging facility. - * Therefore we must disable the logger (level = never) before messaging. - */ - log_rs().level = never; - UHD_MSG(error) - << "Logging failed: " << e.what() << std::endl - << "Logging has been disabled for this process" << std::endl - ; + if (_log_it) { + this->_log_info.message = _ss.str(); + log_rs().push(this->_log_info); } } + +void uhd::_log::log_fastpath(const std::string &msg) +{ +#ifndef UHD_LOG_FASTPATH_DISABLE + log_rs().push_fastpath(msg); +#endif +} + +/*********************************************************************** + * Public API calls + **********************************************************************/ +void +uhd::log::add_logger(const std::string &key, log_fn_t logger_fn) +{ + log_rs().add_logger(key, logger_fn); +} + +void +uhd::log::set_log_level(uhd::log::severity_level level){ + log_rs().global_level = level; +} + +void +uhd::log::set_logger_level(const std::string &key, uhd::log::severity_level level){ + log_rs().logger_level[key] = level; +} + +void +uhd::log::set_console_level(uhd::log::severity_level level){ + set_logger_level(UHD_CONSOLE_LOGGER_KEY, level); +} + +void +uhd::log::set_file_level(uhd::log::severity_level level){ + set_logger_level(UHD_FILE_LOGGER_KEY, level); +} + |