From 499d15f50b4005aaded5273520c69b421a1ec4cd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tin=20=C5=A0vagelj?= Date: Sat, 4 May 2024 01:51:20 +0200 Subject: [PATCH] Improve logging facilities MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Tin Švagelj --- cmake/ConkyPlatformChecks.cmake | 8 +- cmake/config.h.in | 2 - src/CMakeLists.txt | 1 + src/ccurl_thread.cc | 4 +- src/common.cc | 4 +- src/conky.cc | 12 +- src/core.cc | 2 +- src/darwin.mm | 9 +- src/display-output.cc | 6 +- src/freebsd.cc | 4 - src/logging.cc | 54 ++++++ src/logging.h | 293 +++++++++++++++++++++++++++----- src/main.cc | 9 +- 13 files changed, 333 insertions(+), 75 deletions(-) create mode 100644 src/logging.cc diff --git a/cmake/ConkyPlatformChecks.cmake b/cmake/ConkyPlatformChecks.cmake index 3305e4df1f..5276107e0f 100644 --- a/cmake/ConkyPlatformChecks.cmake +++ b/cmake/ConkyPlatformChecks.cmake @@ -679,13 +679,9 @@ if(BUILD_COLOUR_NAME_MAP) mark_as_advanced(APP_GPERF) endif(BUILD_COLOUR_NAME_MAP) -if(CMAKE_BUILD_TYPE MATCHES "Debug") - set(DEBUG true) -endif(CMAKE_BUILD_TYPE MATCHES "Debug") - # The version numbers are simply derived from the date and number of commits # since start of month -if(DEBUG) +if(CMAKE_BUILD_TYPE MATCHES "Debug") execute_process(COMMAND ${APP_GIT} --git-dir=${CMAKE_CURRENT_SOURCE_DIR}/.git log --since=${VERSION_MAJOR}-${VERSION_MINOR}-01 --pretty=oneline @@ -694,4 +690,4 @@ if(DEBUG) RESULT_VARIABLE RETVAL OUTPUT_VARIABLE COMMIT_COUNT OUTPUT_STRIP_TRAILING_WHITESPACE) -endif(DEBUG) +endif() diff --git a/cmake/config.h.in b/cmake/config.h.in index 5eeff2076a..19044b3ee7 100644 --- a/cmake/config.h.in +++ b/cmake/config.h.in @@ -6,8 +6,6 @@ #ifndef _conky_config_h_ #define _conky_config_h_ -#cmakedefine DEBUG - #define SYSTEM_NAME "@CMAKE_SYSTEM_NAME@" #define PACKAGE_NAME "@PROJECT_NAME@" #define VERSION "@VERSION@" diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index d36f4dbc2a..cd1b68f0a6 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -64,6 +64,7 @@ execute_process( set(conky_sources ${conky_sources} + logging.cc c++wrap.cc c++wrap.hh colour-settings.cc diff --git a/src/ccurl_thread.cc b/src/ccurl_thread.cc index fc4caa63ac..22e454828b 100644 --- a/src/ccurl_thread.cc +++ b/src/ccurl_thread.cc @@ -29,9 +29,9 @@ #include "logging.h" #include "text_object.h" -#ifdef DEBUG +#ifndef NDEBUG #include -#endif /* DEBUG */ +#endif /* NDEBUG */ #include diff --git a/src/common.cc b/src/common.cc index bcbaeebead..d48692671c 100644 --- a/src/common.cc +++ b/src/common.cc @@ -365,7 +365,7 @@ double loadgraphval(struct text_object *obj) { uint8_t cpu_percentage(struct text_object *obj) { if (static_cast(obj->data.i) > info.cpu_count) { NORM_ERR("obj->data.i %i info.cpu_count %i", obj->data.i, info.cpu_count); - CRIT_ERR("attempting to use more CPUs than you have!"); + USER_ERR("attempting to use more CPUs than you have!"); } if (info.cpu_usage != nullptr) { return round_to_positive_int(info.cpu_usage[obj->data.i] * 100.0); @@ -376,7 +376,7 @@ uint8_t cpu_percentage(struct text_object *obj) { double cpu_barval(struct text_object *obj) { if (static_cast(obj->data.i) > info.cpu_count) { NORM_ERR("obj->data.i %i info.cpu_count %i", obj->data.i, info.cpu_count); - CRIT_ERR("attempting to use more CPUs than you have!"); + USER_ERR("attempting to use more CPUs than you have!"); } if (info.cpu_usage != nullptr) { return info.cpu_usage[obj->data.i]; } return 0.; diff --git a/src/conky.cc b/src/conky.cc index 3d731c8a1e..6d3620d73c 100644 --- a/src/conky.cc +++ b/src/conky.cc @@ -171,9 +171,6 @@ const char builtin_config_magic[] = "==builtin=="; // #define SIGNAL_BLOCKING #undef SIGNAL_BLOCKING -/* debugging level, used by logging.h */ -int global_debug_level = 0; - /* disable inotify auto reload feature if desired */ static conky::simple_config_setting disable_auto_reload( "disable_auto_reload", false, false); @@ -1915,6 +1912,7 @@ void clean_up(void) { conky::cleanup_config_settings(*state); state.reset(); + conky::log::terminate_logging(); } void handle_terminate() { @@ -2216,7 +2214,7 @@ void initialisation(int argc, char **argv) { case 'u': state->pushnumber(strtod(optarg, &conv_end)); if (*conv_end != 0) { - CRIT_ERR("'%s' is an invalid update interval", optarg); + USER_ERR("'%s' is an invalid update interval", optarg); } update_interval.lua_set(*state); break; @@ -2224,7 +2222,7 @@ void initialisation(int argc, char **argv) { case 'i': state->pushinteger(strtol(optarg, &conv_end, 10)); if (*conv_end != 0) { - CRIT_ERR("'%s' is an invalid number of update times", optarg); + USER_ERR("'%s' is an invalid number of update times", optarg); } total_run_times.lua_set(*state); break; @@ -2232,7 +2230,7 @@ void initialisation(int argc, char **argv) { case 'x': state->pushinteger(strtol(optarg, &conv_end, 10)); if (*conv_end != 0) { - CRIT_ERR("'%s' is an invalid value for the X-position", optarg); + USER_ERR("'%s' is an invalid value for the X-position", optarg); } gap_x.lua_set(*state); break; @@ -2240,7 +2238,7 @@ void initialisation(int argc, char **argv) { case 'y': state->pushinteger(strtol(optarg, &conv_end, 10)); if (*conv_end != 0) { - CRIT_ERR("'%s' is a wrong value for the Y-position", optarg); + USER_ERR("'%s' is a wrong value for the Y-position", optarg); } gap_y.lua_set(*state); break; diff --git a/src/core.cc b/src/core.cc index 0ce2cbdcbd..a4753c30df 100644 --- a/src/core.cc +++ b/src/core.cc @@ -2034,7 +2034,7 @@ struct text_object *construct_text_object(char *s, const char *arg, long line, END { auto *buf = static_cast(malloc(text_buffer_size.get(*state))); - NORM_ERR("unknown variable '$%s'", s); + LOG_WARNING("unknown variable '$%s'", s); snprintf(buf, text_buffer_size.get(*state), "${%s}", s); obj_be_plain_text(obj, buf); free(buf); diff --git a/src/darwin.mm b/src/darwin.mm index ebdc182fb2..448816ca2c 100644 --- a/src/darwin.mm +++ b/src/darwin.mm @@ -88,10 +88,10 @@ #endif /* debugging defines */ -#define DEBUG_MODE +#undef NDEBUG /* (E)nhanced printf */ -#ifdef DEBUG_MODE +#ifndef NDEBUG #include void eprintf(const char *fmt, ...) { va_list args; @@ -928,9 +928,8 @@ void get_cpu_count() { /* * Allocate ncpus+1 slots because cpu_usage[0] is overall usage. */ - info.cpu_usage = - static_cast(malloc((info.cpu_count + 1) * sizeof(float))); - if (info.cpu_usage == nullptr) { CRIT_ERR("malloc"); } + info.cpu_usage = new float[info.cpu_count + 1]; + if (info.cpu_usage == nullptr) { CRIT_ERR("unable to allocate cpu_usage for %d cores", info.cpu_count + 1); } } } diff --git a/src/display-output.cc b/src/display-output.cc index fafcf8c45e..eb59a70980 100644 --- a/src/display-output.cc +++ b/src/display-output.cc @@ -36,7 +36,7 @@ namespace conky { inline void log_missing(const char *name, const char *flag) { - DBGP( + LOG_INFO( "%s display output disabled. Enable by recompiling with '%s' " "flag enabled.", name, flag); @@ -87,7 +87,9 @@ bool initialize_display_outputs() { register_output(outputs); register_output(outputs); - for (auto out : outputs) { NORM_ERR("FOUND: %s", out->name.c_str()); } + for (auto out : outputs) { + LOG_TRACE("%s output display found.", out->name.c_str()); + } // Sort display outputs by descending priority, to try graphical ones first. sort(outputs.begin(), outputs.end(), &display_output_base::priority_compare); diff --git a/src/freebsd.cc b/src/freebsd.cc index 2caab79893..9a39884ad2 100644 --- a/src/freebsd.cc +++ b/src/freebsd.cc @@ -67,10 +67,6 @@ #define KELVTOC(x) ((x - 2732) / 10.0) #define MAXSHOWDEVS 16 -#if 0 -#define FREEBSD_DEBUG -#endif - kvm_t *kd; std::mutex kvm_proc_mutex; diff --git a/src/logging.cc b/src/logging.cc new file mode 100644 index 0000000000..378c94c7ac --- /dev/null +++ b/src/logging.cc @@ -0,0 +1,54 @@ +#include "logging.h" + +#include + +namespace conky::log { +static const char *DEFAULT_LOG_PATH = "/tmp/conky.log"; + +static level current_log_level = level::DEBUG; + +bool is_enabled(level log_level) { + return static_cast(current_log_level) >= static_cast(log_level); +} +void set_log_level(level log_level) { current_log_level = log_level; } +void log_more() { + current_log_level = static_cast(std::min( + static_cast(current_log_level) + 1, static_cast(level::TRACE))); +} +void log_less() { + current_log_level = static_cast(std::max( + static_cast(current_log_level) - 1, static_cast(level::OFF))); +} + +static std::array LOG_STREAMS{stderr, nullptr}; +void use_log_file(const char *path) { + if (LOG_STREAMS[1] != nullptr) { fclose(LOG_STREAMS[1]); } + + if (path != nullptr) { + LOG_STREAMS[1] = fopen(path, "a+"); + } else { + LOG_STREAMS[1] = fopen(DEFAULT_LOG_PATH, "a+"); + } +} + +void init_system_logging() { +#ifdef HAS_SYSLOG + openlog(PACKAGE_NAME, LOG_PID, LOG_USER); +#else + use_log_file(); +#endif +} + +FILE **_log_streams() { return LOG_STREAMS.data(); }; + +void terminate_logging() { + if (LOG_STREAMS[1] != nullptr) { + fclose(LOG_STREAMS[1]); + LOG_STREAMS[1] = nullptr; + } +#ifdef HAS_SYSLOG + closelog(); +#endif +} + +} // namespace conky::log \ No newline at end of file diff --git a/src/logging.h b/src/logging.h index 91801157c0..a47271884e 100644 --- a/src/logging.h +++ b/src/logging.h @@ -30,11 +30,39 @@ #ifndef _LOGGING_H #define _LOGGING_H +#include "config.h" + +#include "i18n.h" + +#include +#include #include // correct formatting for int types #include +#include +#include +#include +#include #include -#include "config.h" -#include "i18n.h" +#include + +#if __has_include() +#define HAS_SYSLOG +#endif + +#ifdef HAS_SYSLOG +extern "C" { +#include +// hide syslog level definitions +#undef LOG_EMERG +#undef LOG_ALERT +#undef LOG_CRIT +#undef LOG_ERR +#undef LOG_WARNING +#undef LOG_NOTICE +#undef LOG_INFO +#undef LOG_DEBUG +} +#endif /* HAS_SYSLOG */ class fork_throw : public std::runtime_error { public: @@ -62,41 +90,242 @@ class obj_create_error : public std::runtime_error { obj_create_error(const std::string &msg) : std::runtime_error(msg) {} }; -template -inline void gettextize_format(const char *format, Args &&...args) { - fprintf(stderr, _(format), args...); +namespace conky::log { +/// @brief Logging levels. +/// +/// Values match syslog ones, with addition of `TRACE` which is local. +/// `Emergency` (0) and `Alert` (1) are not used as they're not warranted from a +/// userspace application. +enum class level { + OFF = 1, + CRITICAL = 2, + ERROR = 3, + WARNING = 4, + NOTICE = 5, + INFO = 6, + /// @brief Debug information. + /// + /// Previously DBGP. + DEBUG = 7, + /// @brief Very detailed information useful for debugging purposes. + /// + /// Previously DBGP2. + TRACE = 8, +}; + +const auto level_names = std::array{ + "CRITICAL", "ERROR", "WARNING", "NOTICE", "INFO", "DEBUG", "TRACE", +}; +const size_t MAX_LEVEL_NAME_LEN = 8; + +constexpr inline const char *log_level_to_cstr(level log_level) { + return level_names[static_cast(log_level) - 2]; +} + +bool is_enabled(level log_level); +void set_log_level(level log_level); +void log_more(); +void log_less(); + +/// Implementation detail: +/// 0 - console output +/// 1 - file output +FILE **_log_streams(); +void use_log_file(const char *path = nullptr); +void init_system_logging(); +void terminate_logging(); + +using clock = std::chrono::system_clock; +using instant = clock::time_point; + +struct source_details { + const char *file = nullptr; + size_t line; +}; + +struct log_details { + level log_level = level::NOTICE; + std::optional source; + std::optional time; +}; + +static const size_t TIME_LEN = 24; + +namespace _priv { +inline size_t format_log_time(char *out, size_t max_len, instant time) { + std::time_t current_time = std::chrono::system_clock::to_time_t(time); + auto millis = std::chrono::duration_cast( + time.time_since_epoch()); + struct tm local_time; + localtime_r(¤t_time, &local_time); + size_t time_len = 0; + time_len += std::strftime(out, max_len, "%F %T", &local_time); + time_len += snprintf(&out[time_len], max_len - time_len, ".%03d", + static_cast(millis.count() % 1000)); + + return time_len; } -// explicit specialization for no arguments to avoid the -// "format not a string literal and no format arguments" warning -inline void gettextize_format(const char *format) { fputs(_(format), stderr); } +inline size_t format_log_time(FILE *out, size_t max_len, instant time) { + char buffer[TIME_LEN]; + size_t result = format_log_time(&buffer[0], max_len, time); + fprintf(out, "%s", buffer); + return result; +} + +constexpr const char *relative_source_path(const std::string_view &base) { + assert(base.end()[1] == 0); // expected a null terminated string + // leave space to lookup previous "/src/" characters + auto last = base.begin() + 5; + for (auto it = base.end(); it != last; it--) { + if (*it == '/' && *(it - 1) == 'c' && *(it - 2) == 'r' && + *(it - 3) == 's' && *(it - 4) == '/') { + return it - 3; + } + } + return base.begin(); +} template -void NORM_ERR(const char *format, Args &&...args) { - fprintf(stderr, PACKAGE_NAME ": "); - gettextize_format(format, args...); - fputs("\n", stderr); +inline void _impl_syslog(level log_level, const char *format, Args &&...args) { + syslog(static_cast(log_level), format, args...); +} +inline void _impl_syslog(level log_level, const char *format) { + syslog(static_cast(log_level), "%s", format); +} +template +inline void _impl_fprintf(FILE *out, const char *format, Args &&...args) { + fprintf(out, format, args...); +} +inline void _impl_fprintf(FILE *out, const char *format) { + fprintf(out, "%s", format); } +} // namespace _priv -/* critical error */ template -__attribute__((noreturn)) inline void CRIT_ERR(const char *format, - Args &&...args) { - NORM_ERR(format, args...); - std::terminate(); +inline void log_print_fmt(log_details &&details, const char *format, + Args &&...args) { +#ifdef HAS_SYSLOG + int lvl = static_cast(details.log_level); + if (lvl >= static_cast(level::CRITICAL) && + lvl < static_cast(level::TRACE)) { + _priv::_impl_syslog(details.log_level, format, args...); + } +#endif + + auto streams = _log_streams(); + if (!is_enabled(details.log_level) && streams[1] != nullptr) return; + + static const size_t MAX_FILE_LEN = 32; + static const size_t MAX_LOCATION_LEN = MAX_FILE_LEN + 1 + 5; // name:line + static const size_t PREAMBLE_LENGTH = + 2 + TIME_LEN + 2 + MAX_LEVEL_NAME_LEN + 2 + MAX_LOCATION_LEN; + char preamble[PREAMBLE_LENGTH + 1] = "["; + size_t offset = 1; + offset += _priv::format_log_time(&preamble[offset], TIME_LEN, + details.time.value_or(clock::now())); + offset += snprintf(&preamble[offset], PREAMBLE_LENGTH - offset, "][%s]", + log_level_to_cstr(details.log_level)); + if (details.source.has_value()) { + auto source = details.source.value(); + offset += snprintf(&preamble[offset], PREAMBLE_LENGTH - offset, "[%s:%ld]", + source.file, source.line); + } + + // localized output to console + if (is_enabled(details.log_level)) { + fprintf(streams[0], "%s: ", preamble); + _priv::_impl_fprintf(streams[0], _(format), args...); + fputs("\n", streams[0]); + } + // unlocalized output to file + if (streams[1] != nullptr) { + fprintf(streams[1], "%s: ", preamble); + _priv::_impl_fprintf(streams[1], format, args...); + fputs("\n", streams[1]); + } } -/* critical error with additional cleanup */ template -__attribute__((noreturn)) inline void CRIT_ERR_FREE(void *memtofree1, - void *memtofree2, - const char *format, - Args &&...args) { - free(memtofree1); - free(memtofree2); - CRIT_ERR(format, args...); +void log_location(level log_level, const char *file, size_t line, + const char *format, Args &&...args) { + log_print_fmt( + log_details{ + log_level, + source_details{file, line}, + }, + format, args...); } +template +void log(level log_level, const char *format, Args &&...args) { + log_print_fmt( + log_details{ + log_level, + }, + format, args...); +} + +#define LOG(Level, ...) \ + ::conky::log::log_location( \ + ::conky::log::level::Level, \ + ::conky::log::_priv::relative_source_path(__FILE__), __LINE__, \ + __VA_ARGS__) + +#define LOG_CRITICAL(...) LOG(CRITICAL, __VA_ARGS__) +#define LOG_ERROR(...) LOG(ERROR, __VA_ARGS__) +#define LOG_WARNING(...) LOG(WARNING, __VA_ARGS__) +#define LOG_NOTICE(...) LOG(NOTICE, __VA_ARGS__) +#define LOG_INFO(...) LOG(INFO, __VA_ARGS__) +#define LOG_DEBUG(...) LOG(DEBUG, __VA_ARGS__) +#define LOG_TRACE(...) LOG(TRACE, __VA_ARGS__) + +} // namespace conky::log + +// backwards compatibility aliases +#define NORM_ERR(...) LOG_INFO(__VA_ARGS__) +#define DBGP(...) LOG_DEBUG(__VA_ARGS__) +#define DBGP2(...) LOG_TRACE(__VA_ARGS__) + +/// @brief Error that warrants termination of the program, and is caused by +/// developer so it should produce a core dump for reporting. +/// +/// @param Format printf style format string. +/// @param Args printf style arguments. +#define CRIT_ERR(...) \ + LOG_CRITICAL(__VA_ARGS__); \ + std::terminate() + +extern void clean_up(); + +/// @brief Error that warrants termination of the program, but is caused by user +/// error (e.g. bad input) and as such a core dump isn't useful. +/// +/// @param Format printf style format string. +/// @param Args printf style arguments. +#define USER_ERR(...) \ + LOG_ERROR(__VA_ARGS__); \ + clean_up(); \ + std::exit(EXIT_FAILURE) + +/// @brief Error caused by system not supporting some required conky feature. +/// +/// We assume the fault is with user for not properly configuring conky so we +/// don't produce a core dump. +/// +/// @param Format printf style format string. +/// @param Args printf style arguments. +#define SYSTEM_ERR(...) \ + LOG_ERROR(__VA_ARGS__); \ + clean_up(); \ + std::exit(EXIT_FAILURE) + +/* critical error with additional cleanup */ +#define CRIT_ERR_FREE(memtofree1, memtofree2, ...) \ + free(memtofree1); \ + free(memtofree2); \ + SYSTEM_ERR(__VA_ARGS__); + namespace conky { class error : public std::runtime_error { public: @@ -104,18 +333,4 @@ class error : public std::runtime_error { }; } // namespace conky -/* debugging output */ -extern int global_debug_level; - -#define __DBGP(level, ...) \ - do { \ - if (global_debug_level > level) { \ - fprintf(stderr, "DEBUG(%d) [" __FILE__ ":%d]: ", level, __LINE__); \ - gettextize_format(__VA_ARGS__); \ - fputs("\n", stderr); \ - } \ - } while (0) -#define DBGP(...) __DBGP(0, __VA_ARGS__) -#define DBGP2(...) __DBGP(1, __VA_ARGS__) - #endif /* _LOGGING_H */ diff --git a/src/main.cc b/src/main.cc index ffa5b2904a..57eb6dc040 100644 --- a/src/main.cc +++ b/src/main.cc @@ -141,7 +141,7 @@ static void print_version() { #ifdef BUILD_PULSEAUDIO << _(" * PulseAudio\n") #endif /* BUIL_PULSEAUDIO */ -#ifdef DEBUG +#ifndef NDEBUG << _(" * Debugging extensions\n") #endif #if defined BUILD_LUA_CAIRO || defined BUILD_LUA_IMLIB2 || BUILD_LUA_RSVG @@ -283,6 +283,7 @@ inline void reset_optind() { int main(int argc, char **argv) { std::set_terminate(&handle_terminate); + conky::log::init_system_logging(); #ifdef BUILD_I18N setlocale(LC_ALL, ""); @@ -322,7 +323,7 @@ int main(int argc, char **argv) { switch (c) { case 'D': - global_debug_level++; + conky::log::log_more(); break; case 'v': print_version(); @@ -334,9 +335,7 @@ int main(int argc, char **argv) { current_config = optarg; break; case 'q': - if (freopen("/dev/null", "w", stderr) == nullptr) { - CRIT_ERR("could not open /dev/null as stderr!"); - } + conky::log::set_log_level(conky::log::level::OFF); break; case 'h': print_help(argv[0]);