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