// // Copyright 2012,2014,2016 Ettus Research LLC // Copyright 2018 Ettus Research, a National Instruments Company // Copyright 2019 Ettus Research, a National Instruments Brand // // SPDX-License-Identifier: GPL-3.0-or-later // #include #include #include #include #include #include #include #include #include #include #include #include #include #include namespace pt = boost::posix_time; constexpr double READ_TIMEOUT = 0.5; // Waiting time to read from the queue // Don't make these static const std::string -- we need their lifetime guaranteed! #define PURPLE "\033[0;35m" // purple #define BLUE "\033[1;34m" // blue #define GREEN "\033[0;32m" // green #define YELLOW "\033[0;33m" // yellow #define BYELLOW "\033[1;33m" // yellow #define RED "\033[0;31m" // red #define BRED "\033[1;31m" // bright red #define RED_ON_YELLOW "\033[0;31;43m" // bright red #define RESET_COLORS "\033[0;39m" // reset colors /*********************************************************************** * Helpers **********************************************************************/ namespace { 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; } } 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 "-"; } } //! 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); } } // namespace /*********************************************************************** * 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: 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; ; } } ~file_logger_backend() { if (_file_stream.is_open()) { _file_stream.close(); } } private: std::ofstream _file_stream; }; /*********************************************************************** * 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; 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 && log_level_env[0] != '\0') { this->global_level = _get_log_level(log_level_env, this->global_level); } // Setup default loggers (console and file) _setup_console_logging(); _setup_file_logging(); // On boot, we print the current UHD version info: { std::ostringstream sys_info; sys_info << BOOST_PLATFORM << "; " << BOOST_COMPILER << "; " << "Boost_" << BOOST_VERSION << "; " << "UHD_" << uhd::get_version_string(); _publish_log_msg(sys_info.str(), uhd::log::info, "UHD"); } // Launch log message consumer _pop_task = std::make_shared(std::thread([this]() { this->pop_task(); })); // Fastpath message consumer #ifndef UHD_LOG_FASTPATH_DISABLE // allow override from environment variables const bool enable_fastpath = []() { const char* disable_fastpath_env = std::getenv("UHD_LOG_FASTPATH_DISABLE"); if (disable_fastpath_env != NULL && disable_fastpath_env[0] != '\0') { return false; } return true; }(); if (enable_fastpath) { _pop_fastpath_task = std::make_shared( std::thread([this]() { this->pop_fastpath_task(); })); } else { _pop_fastpath_task = std::make_shared( std::thread([this]() { this->pop_fastpath_dummy_task(); })); _publish_log_msg("Fastpath logging disabled at runtime."); } #else { _publish_log_msg("Fastpath logging disabled at compile time."); } #endif } ~log_resource(void) { _exit = true; #ifndef BOOST_MSVC // push a final message is required, since the pop_with_wait() function // will be used. // 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 = ""; push(final_message); # ifndef UHD_LOG_FASTPATH_DISABLE push_fastpath(""); # endif #endif // BOOST_MSVC _pop_task->join(); { std::lock_guard l(_logmap_mutex); _loggers.clear(); } _pop_task.reset(); #ifndef UHD_LOG_FASTPATH_DISABLE _pop_fastpath_task->join(); _pop_fastpath_task.reset(); #endif } 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); } #ifndef UHD_LOG_FASTPATH_DISABLE void push_fastpath(const std::string& message) { // Never wait. If the buffer is full, we just don't see the message. // Too bad. _fastpath_queue.push_with_haste(message); } #endif void _handle_log_info(const uhd::log::logging_info& log_info) { if (log_info.message.empty()) { return; } std::lock_guard l(_logmap_mutex); for (const auto& logger_pair : _loggers) { const auto& logger = logger_pair.second; if (log_info.verbosity < logger.first) { continue; } logger.second(log_info); } } void pop_task() { uhd::log::logging_info log_info; log_info.message = ""; // For the lifetime of this thread, we run the following loop: while (!_exit) { #ifdef BOOST_MSVC // Some versions of MSVC will hang if threads are being joined after main has // completed, so we need to guarantee a timeout here if (_log_queue.pop_with_timed_wait(log_info, READ_TIMEOUT)) { _handle_log_info(log_info); } #else _log_queue.pop_with_wait(log_info); // Blocking call _handle_log_info(log_info); #endif // BOOST_MSVC } // Exit procedure: Clear the queue while (_log_queue.pop_with_haste(log_info)) { _handle_log_info(log_info); } // Terminate this thread. } void pop_fastpath_task() { #ifndef UHD_LOG_FASTPATH_DISABLE std::string msg; while (!_exit) { # ifdef BOOST_MSVC // Some versions of MSVC will hang if threads are being joined after main has // completed, so we need to guarantee a timeout here if (_fastpath_queue.pop_with_timed_wait(msg, READ_TIMEOUT)) { std::cerr << msg << std::flush; } # else _fastpath_queue.pop_with_wait(msg); std::cerr << msg << std::flush; # endif // BOOST_MSVC } // Exit procedure: Clear the queue while (_fastpath_queue.pop_with_haste(msg)) { std::cerr << msg << std::flush; } #endif } void pop_fastpath_dummy_task() { #ifndef UHD_LOG_FASTPATH_DISABLE std::string msg; while (!_exit) { # ifdef BOOST_MSVC // Some versions of MSVC will hang if threads are being joined after main has // completed, so we need to guarantee a timeout here _fastpath_queue.pop_with_timed_wait(msg, READ_TIMEOUT); # else _fastpath_queue.pop_with_wait(msg); # endif // BOOST_MSVC } // Exit procedure: Clear the queue while (_fastpath_queue.pop_with_haste(msg)) ; #endif } void add_logger(const std::string& key, uhd::log::log_fn_t logger_fn) { std::lock_guard l(_logmap_mutex); _loggers[key] = level_logfn_pair{global_level, logger_fn}; } void set_log_level(const std::string& key, const uhd::log::severity_level level) { std::lock_guard l(_logmap_mutex); _loggers[key].first = level; } private: std::shared_ptr _pop_task; #ifndef UHD_LOG_FASTPATH_DISABLE std::shared_ptr _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_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; } void _setup_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); } _loggers[UHD_CONSOLE_LOGGER_KEY] = level_logfn_pair{console_level, &console_log}; #endif } void _setup_file_logging() { uhd::log::severity_level file_level = uhd::log::trace; std::string log_file_target; #if defined(UHD_LOG_FILE_LEVEL) file_level = _get_log_level(BOOST_STRINGIZE(UHD_LOG_FILE_LEVEL), file_level); #endif #if defined(UHD_LOG_FILE) 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()) { auto F = std::make_shared(log_file_target); _loggers[UHD_FILE_LOGGER_KEY] = level_logfn_pair{file_level, [F](const uhd::log::logging_info& log_info) { F->log(log_info); }}; } } void _publish_log_msg(const std::string& msg, const uhd::log::severity_level level = uhd::log::info, const std::string& component = "LOGGING") { auto log_msg = uhd::log::logging_info(pt::microsec_clock::local_time(), level, __FILE__, __LINE__, component, boost::this_thread::get_id()); log_msg.message = msg; _log_queue.push_with_timed_wait(log_msg, 0.25); } std::mutex _logmap_mutex; std::atomic _exit; using level_logfn_pair = std::pair; std::map _loggers; #ifndef UHD_LOG_FASTPATH_DISABLE uhd::transport::bounded_buffer _fastpath_queue; #endif uhd::transport::bounded_buffer _log_queue; }; UHD_SINGLETON_FCN(log_resource, log_rs); /*********************************************************************** * The logger object implementation **********************************************************************/ uhd::_log::log::log(const uhd::log::severity_level verbosity, const std::string& file, const unsigned int line, const std::string& component, const boost::thread::id thread_id) : _log_it(verbosity >= log_rs().global_level) { 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 (_log_it) { this->_log_info.message = _ss.str(); try { log_rs().push(this->_log_info); } catch (...) { } } } #ifndef UHD_LOG_FASTPATH_DISABLE void uhd::_log::log_fastpath(const std::string& msg) { log_rs().push_fastpath(msg); } #else void uhd::_log::log_fastpath(const std::string&) { // nop } #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().set_log_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); }