From 9096690f393bbd823297832511ac8d6ad44d0420 Mon Sep 17 00:00:00 2001 From: bneradt Date: Wed, 23 Sep 2020 23:15:37 +0000 Subject: [PATCH] Log config reload: use new config for initialization Before this patch, a logging config reload would use the prior logging configuration for all queries and log rotation auto deletion registration. This updates the mechanism to use the new configuration during this initialization phase. --- proxy/logging/Log.cc | 21 +++---- proxy/logging/Log.h | 5 ++ proxy/logging/LogBuffer.cc | 16 ++--- proxy/logging/LogBuffer.h | 6 +- proxy/logging/LogConfig.cc | 2 +- proxy/logging/LogObject.cc | 28 ++++----- proxy/logging/LogObject.h | 18 +++--- proxy/logging/RolledLogDeleter.cc | 4 ++ proxy/logging/YamlLogConfig.cc | 4 +- .../unit-tests/test_RolledLogDeleter.cc | 4 +- .../gold_tests/logging/log_retention.test.py | 60 +++++++++++++++++++ 11 files changed, 120 insertions(+), 48 deletions(-) diff --git a/proxy/logging/Log.cc b/proxy/logging/Log.cc index 10bf1132682..87e19e2a998 100644 --- a/proxy/logging/Log.cc +++ b/proxy/logging/Log.cc @@ -99,8 +99,8 @@ make_alias_map(Ptr &table) void Log::change_configuration() { - LogConfig *prev = Log::config; - LogConfig *new_config = nullptr; + LogConfig *prev_config = Log::config; + LogConfig *new_config = nullptr; Debug("log-config", "Changing configuration ..."); @@ -111,10 +111,10 @@ Log::change_configuration() // grab the _APImutex so we can transfer the api objects to // the new config // - ink_mutex_acquire(prev->log_object_manager._APImutex); + ink_mutex_acquire(prev_config->log_object_manager._APImutex); Debug("log-api-mutex", "Log::change_configuration acquired api mutex"); - new_config->init(Log::config); + new_config->init(prev_config); // Make the new LogConfig active. ink_atomic_swap(&Log::config, new_config); @@ -125,7 +125,7 @@ Log::change_configuration() // this happens, then the new TextLogObject will be immediately lost. Traffic // Server would crash the next time the plugin referenced the freed object. - ink_mutex_release(prev->log_object_manager._APImutex); + ink_mutex_release(prev_config->log_object_manager._APImutex); Debug("log-api-mutex", "Log::change_configuration released api mutex"); // Register the new config in the config processor; the old one will now be scheduled for a @@ -135,7 +135,7 @@ Log::change_configuration() // If we replaced the logging configuration, flush any log // objects that weren't transferred to the new config ... - prev->log_object_manager.flush_all_objects(); + prev_config->log_object_manager.flush_all_objects(); Debug("log-config", "... new configuration in place"); } @@ -1071,10 +1071,11 @@ Log::init_when_enabled() // setup global scrap object // global_scrap_format = MakeTextLogFormat(); - global_scrap_object = new LogObject( - global_scrap_format, Log::config->logfile_dir, "scrapfile.log", LOG_FILE_BINARY, nullptr, Log::config->rolling_enabled, - Log::config->preproc_threads, Log::config->rolling_interval_sec, Log::config->rolling_offset_hr, Log::config->rolling_size_mb, - /* auto create */ false, Log::config->rolling_max_count, Log::config->rolling_min_count); + global_scrap_object = + new LogObject(Log::config, global_scrap_format, Log::config->logfile_dir, "scrapfile.log", LOG_FILE_BINARY, nullptr, + Log::config->rolling_enabled, Log::config->preproc_threads, Log::config->rolling_interval_sec, + Log::config->rolling_offset_hr, Log::config->rolling_size_mb, + /* auto create */ false, Log::config->rolling_max_count, Log::config->rolling_min_count); // create the flush thread create_threads(); diff --git a/proxy/logging/Log.h b/proxy/logging/Log.h index 6b3c542e2b8..eff338aca7f 100644 --- a/proxy/logging/Log.h +++ b/proxy/logging/Log.h @@ -182,6 +182,11 @@ class Log // public data members static LogObject *error_log; + /** The latest fully initialized LogConfig. + * + * This is the safe, fully initialed LogConfig object to query against when + * performing logging operations. + */ static LogConfig *config; static LogFieldList global_field_list; static std::unordered_map field_symbol_hash; diff --git a/proxy/logging/LogBuffer.cc b/proxy/logging/LogBuffer.cc index 5dc19f40533..466e34f2c87 100644 --- a/proxy/logging/LogBuffer.cc +++ b/proxy/logging/LogBuffer.cc @@ -102,7 +102,7 @@ LogBufferHeader::log_filename() return addr; } -LogBuffer::LogBuffer(LogObject *owner, size_t size, size_t buf_align, size_t write_align) +LogBuffer::LogBuffer(const LogConfig *cfg, LogObject *owner, size_t size, size_t buf_align, size_t write_align) : m_size(size), m_buf_align(buf_align), m_write_align(write_align), m_owner(owner), m_references(0) { size_t hdr_size; @@ -111,8 +111,8 @@ LogBuffer::LogBuffer(LogObject *owner, size_t size, size_t buf_align, size_t wri // int64_t alloc_size = size + buf_align; - if (alloc_size <= BUFFER_SIZE_FOR_INDEX(Log::config->logbuffer_max_iobuf_index)) { - m_buffer_fast_allocator_size = buffer_size_to_index(alloc_size, Log::config->logbuffer_max_iobuf_index); + if (alloc_size <= BUFFER_SIZE_FOR_INDEX(cfg->logbuffer_max_iobuf_index)) { + m_buffer_fast_allocator_size = buffer_size_to_index(alloc_size, cfg->logbuffer_max_iobuf_index); m_unaligned_buffer = static_cast(ioBufAllocator[m_buffer_fast_allocator_size].alloc_void()); } else { m_buffer_fast_allocator_size = -1; @@ -121,7 +121,7 @@ LogBuffer::LogBuffer(LogObject *owner, size_t size, size_t buf_align, size_t wri m_buffer = static_cast(align_pointer_forward(m_unaligned_buffer, buf_align)); // add the header - hdr_size = _add_buffer_header(); + hdr_size = _add_buffer_header(cfg); // initialize buffer state m_state.s.offset = hdr_size; @@ -129,7 +129,7 @@ LogBuffer::LogBuffer(LogObject *owner, size_t size, size_t buf_align, size_t wri // update the buffer id (m_id gets the old value) m_id = static_cast(ink_atomic_increment(&M_ID, 1)); - m_expiration_time = LogUtils::timestamp() + Log::config->max_secs_per_buffer; + m_expiration_time = LogUtils::timestamp() + cfg->max_secs_per_buffer; Debug("log-logbuffer", "[%p] Created buffer %u for %s at address %p, size %d", this_ethread(), m_id, m_owner->get_base_filename(), m_buffer, (int)size); @@ -345,7 +345,7 @@ LogBuffer::add_header_str(const char *str, char *buf_ptr, unsigned buf_len) } size_t -LogBuffer::_add_buffer_header() +LogBuffer::_add_buffer_header(const LogConfig *cfg) { size_t header_len; @@ -392,9 +392,9 @@ LogBuffer::_add_buffer_header() m_header->fmt_printf_offset = header_len; header_len += add_header_str(fmt->printf_str(), &m_buffer[header_len], m_size - header_len); } - if (Log::config->hostname) { + if (cfg->hostname) { m_header->src_hostname_offset = header_len; - header_len += add_header_str(Log::config->hostname, &m_buffer[header_len], m_size - header_len); + header_len += add_header_str(cfg->hostname, &m_buffer[header_len], m_size - header_len); } if (m_owner->get_base_filename()) { m_header->log_filename_offset = header_len; diff --git a/proxy/logging/LogBuffer.h b/proxy/logging/LogBuffer.h index 581d99cd1a9..f732aae6e63 100644 --- a/proxy/logging/LogBuffer.h +++ b/proxy/logging/LogBuffer.h @@ -30,6 +30,7 @@ #include "LogAccess.h" class LogObject; +class LogConfig; class LogBufferIterator; #define LOG_SEGMENT_COOKIE 0xaceface @@ -129,7 +130,8 @@ class LogBuffer LB_BUFFER_TOO_SMALL }; - LogBuffer(LogObject *owner, size_t size, size_t buf_align = LB_DEFAULT_ALIGN, size_t write_align = INK_MIN_ALIGN); + LogBuffer(const LogConfig *cfg, LogObject *owner, size_t size, size_t buf_align = LB_DEFAULT_ALIGN, + size_t write_align = INK_MIN_ALIGN); LogBuffer(LogObject *owner, LogBufferHeader *header); ~LogBuffer(); @@ -232,7 +234,7 @@ class LogBuffer private: // private functions - size_t _add_buffer_header(); + size_t _add_buffer_header(const LogConfig *cfg); unsigned add_header_str(const char *str, char *buf_ptr, unsigned buf_len); void freeLogBuffer(); diff --git a/proxy/logging/LogConfig.cc b/proxy/logging/LogConfig.cc index d35eed14201..1a77f0daa6c 100644 --- a/proxy/logging/LogConfig.cc +++ b/proxy/logging/LogConfig.cc @@ -306,7 +306,7 @@ LogConfig::init(LogConfig *prev_config) Debug("log", "creating predefined error log object"); - errlog = new LogObject(fmt.get(), logfile_dir, "error.log", LOG_FILE_ASCII, nullptr, rolling_enabled, preproc_threads, + errlog = new LogObject(this, fmt.get(), logfile_dir, "error.log", LOG_FILE_ASCII, nullptr, rolling_enabled, preproc_threads, rolling_interval_sec, rolling_offset_hr, rolling_size_mb, /* auto_created */ false, rolling_max_count, rolling_min_count); diff --git a/proxy/logging/LogObject.cc b/proxy/logging/LogObject.cc index 1df7c81ea2f..55b5b769fa7 100644 --- a/proxy/logging/LogObject.cc +++ b/proxy/logging/LogObject.cc @@ -88,7 +88,7 @@ LogBufferManager::preproc_buffers(LogBufferSink *sink) LogObject -------------------------------------------------------------------------*/ -LogObject::LogObject(const LogFormat *format, const char *log_dir, const char *basename, LogFileFormat file_format, +LogObject::LogObject(LogConfig *cfg, const LogFormat *format, const char *log_dir, const char *basename, LogFileFormat file_format, const char *header, Log::RollingEnabledValues rolling_enabled, int flush_threads, int rolling_interval_sec, int rolling_offset_hr, int rolling_size_mb, bool auto_created, int rolling_max_count, int rolling_min_count, bool reopen_after_rolling, int pipe_buffer_size) @@ -121,18 +121,18 @@ LogObject::LogObject(const LogFormat *format, const char *log_dir, const char *b // compute_signature is a static function m_signature = compute_signature(m_format, m_basename, m_flags); - m_logFile = new LogFile(m_filename, header, file_format, m_signature, Log::config->ascii_buffer_size, Log::config->max_line_size, - m_pipe_buffer_size); + m_logFile = + new LogFile(m_filename, header, file_format, m_signature, cfg->ascii_buffer_size, cfg->max_line_size, m_pipe_buffer_size); if (m_reopen_after_rolling) { m_logFile->open_file(); } - LogBuffer *b = new LogBuffer(this, Log::config->log_buffer_size); + LogBuffer *b = new LogBuffer(cfg, this, cfg->log_buffer_size); ink_assert(b); SET_FREELIST_POINTER_VERSION(m_log_buffer, b, 0); - _setup_rolling(rolling_enabled, rolling_interval_sec, rolling_offset_hr, rolling_size_mb); + _setup_rolling(cfg, rolling_enabled, rolling_interval_sec, rolling_offset_hr, rolling_size_mb); Debug("log-config", "exiting LogObject constructor, filename=%s this=%p", m_filename, this); } @@ -176,7 +176,7 @@ LogObject::LogObject(LogObject &rhs) // copy gets a fresh log buffer // - LogBuffer *b = new LogBuffer(this, Log::config->log_buffer_size); + LogBuffer *b = new LogBuffer(Log::config, this, Log::config->log_buffer_size); ink_assert(b); SET_FREELIST_POINTER_VERSION(m_log_buffer, b, 0); @@ -396,7 +396,7 @@ LogObject::_checkout_write(size_t *write_offset, size_t bytes_needed) case LogBuffer::LB_FULL_ACTIVE_WRITERS: case LogBuffer::LB_FULL_NO_WRITERS: // no more room in current buffer, create a new one - new_buffer = new LogBuffer(this, Log::config->log_buffer_size); + new_buffer = new LogBuffer(Log::config, this, Log::config->log_buffer_size); // swap the new buffer for the old one INK_WRITE_MEMORY_BARRIER; @@ -629,8 +629,8 @@ LogObject::log(LogAccess *lad, std::string_view text_entry) } void -LogObject::_setup_rolling(Log::RollingEnabledValues rolling_enabled, int rolling_interval_sec, int rolling_offset_hr, - int rolling_size_mb) +LogObject::_setup_rolling(LogConfig *cfg, Log::RollingEnabledValues rolling_enabled, int rolling_interval_sec, + int rolling_offset_hr, int rolling_size_mb) { if (!LogRollingEnabledIsValid(static_cast(rolling_enabled))) { m_rolling_enabled = Log::NO_ROLLING; @@ -689,7 +689,7 @@ LogObject::_setup_rolling(Log::RollingEnabledValues rolling_enabled, int rolling m_rolling_size_mb = rolling_size_mb; } } - Log::config->register_rolled_log_auto_delete(m_basename, m_min_rolled); + cfg->register_rolled_log_auto_delete(m_basename, m_min_rolled); m_rolling_enabled = rolling_enabled; } } @@ -793,9 +793,9 @@ TextLogObject::TextLogObject(const char *name, const char *log_dir, bool timesta Log::RollingEnabledValues rolling_enabled, int flush_threads, int rolling_interval_sec, int rolling_offset_hr, int rolling_size_mb, int rolling_max_count, int rolling_min_count, bool reopen_after_rolling) - : LogObject(TextLogObject::textfmt, log_dir, name, LOG_FILE_ASCII, header, rolling_enabled, flush_threads, rolling_interval_sec, - rolling_offset_hr, rolling_size_mb, /* auto_created */ false, rolling_max_count, rolling_min_count, - reopen_after_rolling) + : LogObject(Log::config, TextLogObject::textfmt, log_dir, name, LOG_FILE_ASCII, header, rolling_enabled, flush_threads, + rolling_interval_sec, rolling_offset_hr, rolling_size_mb, /* auto_created */ false, rolling_max_count, + rolling_min_count, reopen_after_rolling) { if (timestamps) { this->set_fmt_timestamps(); @@ -1342,7 +1342,7 @@ MakeTestLogObject(const char *name) tmpdir = "/tmp"; } - return new LogObject(&format, tmpdir, name, LOG_FILE_ASCII /* file_format */, name /* header */, + return new LogObject(Log::config, &format, tmpdir, name, LOG_FILE_ASCII /* file_format */, name /* header */, Log::ROLL_ON_TIME_ONLY /* rolling_enabled */, 1 /* flush_threads */); } diff --git a/proxy/logging/LogObject.h b/proxy/logging/LogObject.h index fa16f0fa7c6..7a6b81782b6 100644 --- a/proxy/logging/LogObject.h +++ b/proxy/logging/LogObject.h @@ -93,10 +93,10 @@ class LogObject : public RefCountObj // BINARY: log is written in binary format (rather than ascii) // WRITES_TO_PIPE: object writes to a named pipe rather than to a file - LogObject(const LogFormat *format, const char *log_dir, const char *basename, LogFileFormat file_format, const char *header, - Log::RollingEnabledValues rolling_enabled, int flush_threads, int rolling_interval_sec = 0, int rolling_offset_hr = 0, - int rolling_size_mb = 0, bool auto_created = false, int rolling_max_count = 0, int rolling_min_count = 0, - bool reopen_after_rolling = false, int pipe_buffer_size = 0); + LogObject(LogConfig *cfg, const LogFormat *format, const char *log_dir, const char *basename, LogFileFormat file_format, + const char *header, Log::RollingEnabledValues rolling_enabled, int flush_threads, int rolling_interval_sec = 0, + int rolling_offset_hr = 0, int rolling_size_mb = 0, bool auto_created = false, int rolling_max_count = 0, + int rolling_min_count = 0, bool reopen_after_rolling = false, int pipe_buffer_size = 0); LogObject(LogObject &); ~LogObject() override; @@ -193,25 +193,25 @@ class LogObject : public RefCountObj inline void set_rolling_enabled(Log::RollingEnabledValues rolling_enabled) { - _setup_rolling(rolling_enabled, m_rolling_interval_sec, m_rolling_offset_hr, m_rolling_size_mb); + _setup_rolling(Log::config, rolling_enabled, m_rolling_interval_sec, m_rolling_offset_hr, m_rolling_size_mb); } inline void set_rolling_interval_sec(int rolling_interval_sec) { - _setup_rolling(m_rolling_enabled, rolling_interval_sec, m_rolling_offset_hr, m_rolling_size_mb); + _setup_rolling(Log::config, m_rolling_enabled, rolling_interval_sec, m_rolling_offset_hr, m_rolling_size_mb); } inline void set_rolling_offset_hr(int rolling_offset_hr) { - _setup_rolling(m_rolling_enabled, m_rolling_interval_sec, rolling_offset_hr, m_rolling_size_mb); + _setup_rolling(Log::config, m_rolling_enabled, m_rolling_interval_sec, rolling_offset_hr, m_rolling_size_mb); } inline void set_rolling_size_mb(int rolling_size_mb) { - _setup_rolling(m_rolling_enabled, m_rolling_interval_sec, m_rolling_offset_hr, rolling_size_mb); + _setup_rolling(Log::config, m_rolling_enabled, m_rolling_interval_sec, m_rolling_offset_hr, rolling_size_mb); } inline bool @@ -290,7 +290,7 @@ class LogObject : public RefCountObj int m_pipe_buffer_size; void generate_filenames(const char *log_dir, const char *basename, LogFileFormat file_format); - void _setup_rolling(Log::RollingEnabledValues rolling_enabled, int rolling_interval_sec, int rolling_offset_hr, + void _setup_rolling(LogConfig *cfg, Log::RollingEnabledValues rolling_enabled, int rolling_interval_sec, int rolling_offset_hr, int rolling_size_mb); unsigned _roll_files(long interval_start, long interval_end); diff --git a/proxy/logging/RolledLogDeleter.cc b/proxy/logging/RolledLogDeleter.cc index 2d5173888cc..1547b50fb25 100644 --- a/proxy/logging/RolledLogDeleter.cc +++ b/proxy/logging/RolledLogDeleter.cc @@ -64,6 +64,10 @@ LogDeletingInfo::LogDeletingInfo(std::string_view _logname, int _min_count) void RolledLogDeleter::register_log_type_for_deletion(std::string_view log_type, int rolling_min_count) { + if (deleting_info.find(log_type) != deleting_info.end()) { + // Already registered. + return; + } auto deletingInfo = std::make_unique(log_type, rolling_min_count); auto *deletingInfoPtr = deletingInfo.get(); diff --git a/proxy/logging/YamlLogConfig.cc b/proxy/logging/YamlLogConfig.cc index 5780aa6b030..b553a18518f 100644 --- a/proxy/logging/YamlLogConfig.cc +++ b/proxy/logging/YamlLogConfig.cc @@ -216,8 +216,8 @@ YamlLogConfig::decodeLogObject(const YAML::Node &node) } } - auto logObject = new LogObject(fmt, Log::config->logfile_dir, filename.c_str(), file_type, header.c_str(), - static_cast(obj_rolling_enabled), Log::config->preproc_threads, + auto logObject = new LogObject(cfg, fmt, cfg->logfile_dir, filename.c_str(), file_type, header.c_str(), + static_cast(obj_rolling_enabled), cfg->preproc_threads, obj_rolling_interval_sec, obj_rolling_offset_hr, obj_rolling_size_mb, /* auto_created */ false, /* rolling_max_count */ obj_rolling_max_count, /* rolling_min_count */ obj_rolling_min_count, /* reopen_after_rolling */ obj_rolling_allow_empty > 0, pipe_buffer_size); diff --git a/proxy/logging/unit-tests/test_RolledLogDeleter.cc b/proxy/logging/unit-tests/test_RolledLogDeleter.cc index 884030d0266..d0e51cd73c1 100644 --- a/proxy/logging/unit-tests/test_RolledLogDeleter.cc +++ b/proxy/logging/unit-tests/test_RolledLogDeleter.cc @@ -42,7 +42,7 @@ verify_there_are_no_candidates(RolledLogDeleter &deleter) void verify_rolled_log_behavior(RolledLogDeleter &deleter, fs::path rolled_log1, fs::path rolled_log2, fs::path rolled_log3) { - SECTION("Verify we can add a single rolled files") + SECTION("Verify we can add a single rolled file") { constexpr int64_t file_size = 100; constexpr time_t last_modified = 30; @@ -65,7 +65,7 @@ verify_rolled_log_behavior(RolledLogDeleter &deleter, fs::path rolled_log1, fs:: constexpr time_t oldest_timestamp = 30; constexpr time_t youngest_timestamp = 60; - // Intentionally insert them out of order (that is the first one to delete + // Intentionally insert them out of order (that is, the first one to delete // is the second added). REQUIRE(deleter.consider_for_candidacy(rolled_log2.string(), file_size, youngest_timestamp)); REQUIRE(deleter.consider_for_candidacy(rolled_log1.string(), file_size, oldest_timestamp)); diff --git a/tests/gold_tests/logging/log_retention.test.py b/tests/gold_tests/logging/log_retention.test.py index e678b619f3f..d90eaddf71a 100644 --- a/tests/gold_tests/logging/log_retention.test.py +++ b/tests/gold_tests/logging/log_retention.test.py @@ -470,3 +470,63 @@ def get_command_to_rotate_thrice(self): test.tr.Processes.Default.ReturnCode = 0 test.tr.StillRunningAfter = test.ts test.tr.StillRunningAfter = test.server + +# +# Test 8: Verify log deletion happens after a config reload. +# +test = TestLogRetention(twelve_meg_log_space, + "Verify log rotation and deletion after a config reload.") + +test.ts.Disk.logging_yaml.AddLines( + ''' +logging: + formats: + - name: long + format: "{prefix}: %" + logs: + - filename: test_deletion + format: long +'''.format(prefix="0123456789" * 500).split("\n") +) + +# Verify that the plugin's logs and other core logs were registered for deletion. +test.ts.Streams.stderr = Testers.ContainsExpression( + "Registering rotated log deletion for test_deletion.log with min roll count 0", + "Verify test_deletion.log auto-delete configuration") +test.ts.Streams.stderr += Testers.ContainsExpression( + "Registering rotated log deletion for error.log with min roll count 0", + "Verify error.log auto-delete configuration") +test.ts.Streams.stderr += Testers.ContainsExpression( + "Registering rotated log deletion for traffic.out with min roll count 0", + "Verify traffic.out auto-delete configuration") +test.ts.Streams.stderr += Testers.ContainsExpression( + "Registering rotated log deletion for diags.log with min roll count 0", + "Verify diags.log auto-delete configuration") +test.ts.Streams.stderr += Testers.ContainsExpression( + "Registering rotated log deletion for manager.log with min roll count 0", + "Verify manager.log auto-delete configuration") +# Verify test_deletion was rotated and deleted. +test.ts.Streams.stderr += Testers.ContainsExpression( + "The rolled logfile.*test_deletion.log_.*was auto-deleted.*bytes were reclaimed", + "Verify that space was reclaimed") + +# Touch logging.yaml so the config reload applies to logging objects. +test.tr.Processes.Default.Command = "touch " + test.ts.Disk.logging_yaml.AbsRunTimePath +test.tr.Processes.Default.ReturnCode = 0 +test.tr.StillRunningAfter = test.ts +test.tr.StillRunningAfter = test.server + +tr = Test.AddTestRun("Perform a config reload") +tr.Processes.Default.Command = "traffic_ctl config reload" +tr.Processes.Default.Env = test.ts.Env +tr.Processes.Default.ReturnCode = 0 +tr.Processes.Default.TimeOut = 5 +tr.TimeOut = 5 +tr.StillRunningAfter = test.ts +tr.StillRunningAfter = test.server + +tr = Test.AddTestRun("Get the log to rotate.") +tr.Processes.Default.Command = test.get_command_to_rotate_once() +tr.Processes.Default.ReturnCode = 0 +tr.StillRunningAfter = test.ts +tr.StillRunningAfter = test.server