From 151a6038b63e8739bfed9d62c63165c17426a403 Mon Sep 17 00:00:00 2001 From: vkalintiris Date: Thu, 7 Jul 2022 15:56:01 +0300 Subject: [PATCH] Protect shared variables with log lock. (#13306) Fixes reports by helgrind: ``` ==00:00:00:01.769 44512== Possible data race during read of size 8 at 0x9767B0 by thread #4 ==00:00:00:01.769 44512== Locks held: none ==00:00:00:01.769 44512== at 0x17CB56: error_log_limit (log.c:627) ==00:00:00:01.769 44512== by 0x17CEC0: info_int (log.c:716) ==00:00:00:01.769 44512== by 0x18949F: thread_start (threads.c:173) ==00:00:00:01.769 44512== by 0x484A486: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so) ==00:00:00:01.769 44512== by 0x4E9CD7F: start_thread (pthread_create.c:481) ==00:00:00:01.769 44512== by 0x532F76E: clone (clone.S:95) ==00:00:00:01.769 44512== ==00:00:00:01.769 44512== This conflicts with a previous write of size 8 by thread #3 ==00:00:00:01.769 44512== Locks held: none ==00:00:00:01.769 44512== at 0x17CB61: error_log_limit (log.c:627) ==00:00:00:01.769 44512== by 0x17CEC0: info_int (log.c:716) ==00:00:00:01.769 44512== by 0x18949F: thread_start (threads.c:173) ==00:00:00:01.769 44512== by 0x484A486: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so) ==00:00:00:01.769 44512== by 0x4E9CD7F: start_thread (pthread_create.c:481) ==00:00:00:01.769 44512== by 0x532F76E: clone (clone.S:95) ==00:00:00:01.769 44512== Address 0x9767b0 is 0 bytes inside data symbol "counter.1" ``` ``` ==00:00:00:44.536 47685== Lock at 0x976720 was first observed ==00:00:00:44.536 47685== at 0x48477EF: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so) ==00:00:00:44.536 47685== by 0x17BBF4: __netdata_mutex_lock (locks.c:86) ==00:00:00:44.536 47685== by 0x17C514: log_lock (log.c:471) ==00:00:00:44.536 47685== by 0x17CEC0: info_int (log.c:715) ==00:00:00:44.536 47685== by 0x458C9E: compute_multidb_diskspace (rrdenginelib.c:279) ==00:00:00:44.536 47685== by 0x15B170: get_netdata_configured_variables (main.c:671) ==00:00:00:44.536 47685== by 0x15CE6C: main (main.c:1263) ==00:00:00:44.536 47685== Address 0x976720 is 0 bytes inside data symbol "log_mutex" ==00:00:00:44.536 47685== ==00:00:00:44.536 47685== Possible data race during write of size 8 at 0x9767A0 by thread #1 ==00:00:00:44.536 47685== Locks held: none ==00:00:00:44.536 47685== at 0x17CB39: error_log_limit (log.c:621) ==00:00:00:44.536 47685== by 0x15E234: signals_handle (signals.c:258) ==00:00:00:44.536 47685== by 0x15D880: main (main.c:1534) ==00:00:00:44.536 47685== ==00:00:00:44.536 47685== This conflicts with a previous read of size 8 by thread #9 ==00:00:00:44.536 47685== Locks held: 1, at address 0x976720 ==00:00:00:44.536 47685== at 0x17CAA3: error_log_limit (log.c:604) ==00:00:00:44.536 47685== by 0x17CECA: info_int (log.c:718) ==00:00:00:44.536 47685== by 0x4624D2: rrdset_done_push (rrdpush.c:344) ==00:00:00:44.536 47685== by 0x36190C: rrdset_done (rrdset.c:1351) ==00:00:00:44.536 47685== by 0x1B07E7: Chart::update(unsigned long) (plugin_profile.cc:82) ==00:00:00:44.536 47685== by 0x1B01D4: updateCharts(std::vector >, unsigned long) (plugin_profile.cc:126) ==00:00:00:44.536 47685== by 0x1B02AC: profile_main (plugin_profile.cc:144) ==00:00:00:44.536 47685== by 0x1895D4: thread_start (threads.c:185) ==00:00:00:44.536 47685== Address 0x9767a0 is 0 bytes inside data symbol "start.3" ``` --- libnetdata/log/log.c | 38 ++++++++++++++++++++++++++++++++------ libnetdata/log/log.h | 7 ++----- 2 files changed, 34 insertions(+), 11 deletions(-) diff --git a/libnetdata/log/log.c b/libnetdata/log/log.c index 3eed70c4f1e39c..6f4652e87e8652 100644 --- a/libnetdata/log/log.c +++ b/libnetdata/log/log.c @@ -681,6 +681,26 @@ int error_log_limit(int reset) { return 0; } +void error_log_limit_reset(void) { + log_lock(); + + error_log_errors_per_period = error_log_errors_per_period_backup; + error_log_limit(1); + + log_unlock(); +} + +void error_log_limit_unlimited(void) { + log_lock(); + + error_log_errors_per_period = error_log_errors_per_period_backup; + error_log_limit(1); + + error_log_errors_per_period = ((error_log_errors_per_period_backup * 10) < 10000) ? 10000 : (error_log_errors_per_period_backup * 10); + + log_unlock(); +} + // ---------------------------------------------------------------------------- // debug log @@ -712,8 +732,13 @@ void info_int( const char *file, const char *function, const unsigned long line, { va_list args; + log_lock(); + // prevent logging too much - if(error_log_limit(0)) return; + if (error_log_limit(0)) { + log_unlock(); + return; + } if(error_log_syslog) { va_start( args, fmt ); @@ -724,8 +749,6 @@ void info_int( const char *file, const char *function, const unsigned long line, char date[LOG_DATE_LENGTH]; log_date(date, LOG_DATE_LENGTH); - log_lock(); - va_start( args, fmt ); #ifdef NETDATA_INTERNAL_CHECKS fprintf(stderr, "%s: %s INFO : %s : (%04lu@%-20.20s:%-15.15s): ", date, program_name, netdata_thread_tag(), line, file, function); @@ -771,8 +794,13 @@ void error_int( const char *prefix, const char *file, const char *function, cons va_list args; + log_lock(); + // prevent logging too much - if(error_log_limit(0)) return; + if (error_log_limit(0)) { + log_unlock(); + return; + } if(error_log_syslog) { va_start( args, fmt ); @@ -783,8 +811,6 @@ void error_int( const char *prefix, const char *file, const char *function, cons char date[LOG_DATE_LENGTH]; log_date(date, LOG_DATE_LENGTH); - log_lock(); - va_start( args, fmt ); #ifdef NETDATA_INTERNAL_CHECKS fprintf(stderr, "%s: %s %-5.5s : %s : (%04lu@%-20.20s:%-15.15s): ", date, program_name, prefix, netdata_thread_tag(), line, file, function); diff --git a/libnetdata/log/log.h b/libnetdata/log/log.h index ea2be277c17d23..293901d442a2ea 100644 --- a/libnetdata/log/log.h +++ b/libnetdata/log/log.h @@ -74,11 +74,8 @@ extern void reopen_all_log_files(); static inline void debug_dummy(void) {} -#define error_log_limit_reset() do { error_log_errors_per_period = error_log_errors_per_period_backup; error_log_limit(1); } while(0) -#define error_log_limit_unlimited() do { \ - error_log_limit_reset(); \ - error_log_errors_per_period = ((error_log_errors_per_period_backup * 10) < 10000) ? 10000 : (error_log_errors_per_period_backup * 10); \ - } while(0) +void error_log_limit_reset(void); +void error_log_limit_unlimited(void); #ifdef NETDATA_INTERNAL_CHECKS #define debug(type, args...) do { if(unlikely(debug_flags & type)) debug_int(__FILE__, __FUNCTION__, __LINE__, ##args); } while(0)