This is an automated email from the ASF dual-hosted git repository. gancho pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/master by this push: new b81422a Options to roll empty logs and log trimming b81422a is described below commit b81422ac723daca585fbe24247832b33309b21a9 Author: Gancho Tenev <gan...@apache.org> AuthorDate: Fri Jul 5 17:09:15 2019 -0700 Options to roll empty logs and log trimming Added 2 options: - proxy.config.log.rolling_allow_empty - ability to roll empty logs (i.e. rolling logs without traffic) - proxy.config.log.rolling_max_count - trimming logs to a certain number of rolled files on each rolling More info in records.config.en.rst and rotation.en.rst. --- doc/admin-guide/files/records.config.en.rst | 25 ++++++++ doc/admin-guide/logging/rotation.en.rst | 24 ++++++++ mgmt/RecordsConfig.cc | 4 ++ proxy/logging/LogConfig.cc | 14 ++++- proxy/logging/LogConfig.h | 2 + proxy/logging/LogFile.cc | 89 ++++++++++++++++++++++++++++- proxy/logging/LogFile.h | 3 +- proxy/logging/LogObject.cc | 25 ++++++-- proxy/logging/LogObject.h | 16 +++--- proxy/logging/YamlLogConfig.cc | 19 ++++-- src/traffic_server/InkAPI.cc | 3 +- 11 files changed, 202 insertions(+), 22 deletions(-) diff --git a/doc/admin-guide/files/records.config.en.rst b/doc/admin-guide/files/records.config.en.rst index 11107d1..fd965b0 100644 --- a/doc/admin-guide/files/records.config.en.rst +++ b/doc/admin-guide/files/records.config.en.rst @@ -273,6 +273,31 @@ System Variables order of auto-deletion (if enabled). A default value of 0 means auto-deletion will try to keep output logs as much as possible. See :doc:`../logging/rotation.en` for guidance. +.. ts:cv:: CONFIG proxy.config.output.logfile.rolling_max_count INT 0 + :reloadable: + + Specifies the maximum count of rolled output logs to keep. This value will be used by the + auto-deletion (if enabled) to trim the number of rolled log files every time the log is rolled. + A default value of 0 means auto-deletion will not try to limit the number of output logs. + See :doc:`../logging/rotation.en` for an use-case for this option. + +.. ts:cv:: CONFIG proxy.config.output.logfile.rolling_allow_empty INT 0 + :reloadable: + + While rolling default behavior is to rename, close and re-open the log file *only* when/if there is + something to log to the log file. This option opens a new log file right after rolling even if there + is nothing to log (i.e. nothing to be logged due to lack of requests to the server) + which may lead to 0-sized log files while rollong. See :doc:`../logging/rotation.en` for an use-case + for this option. + + ===== ====================================================================== + Value Description + ===== ====================================================================== + ``0`` No empty log files created and rolloed if there was nothing to log + ``1`` Allow empty log files to be created and rolled even if there was nothing to log + ===== ====================================================================== + + Thread Variables ---------------- diff --git a/doc/admin-guide/logging/rotation.en.rst b/doc/admin-guide/logging/rotation.en.rst index eaed409..64ed337 100644 --- a/doc/admin-guide/logging/rotation.en.rst +++ b/doc/admin-guide/logging/rotation.en.rst @@ -245,3 +245,27 @@ To set log management options, follow the steps below: #. Run the command :option:`traffic_ctl config reload` to apply the configuration changes. + +Retaining Logs For No More Than a Specified Period +-------------------------------------------------- + +If for security reasons logs need to be purged to make sure no log entry remains on the box +for more then a specified period of time, we could achieve this by setting the rolling interval, +the maximum number of rolled log files, and forcing |TS| to roll even when there is no traffic. + +Let us say we wanted the oldest log entry to be kept on the box to be no older than 2-hour old. + +Set :ts:cv:`proxy.config.output.logfile.rolling_interval_sec` (yaml: `rolling_interval_sec`) to 3600 (1h) +which will lead to rolling every 1h. + +Set :ts:cv:`proxy.config.output.logfile.rolling_max_count` (yaml: `rolling_max_count`) to 1 +which will lead to keeping only one rolled log file at any moment (rolled will be trimmed on every roll). + +Set :ts:cv:`proxy.config.output.logfile.rolling_allow_empty` (yaml: `rolling_allow_empty`) to 1 (default: 0) +which will allow logs to be open and rolled even if there was nothing to be logged during the previous period +(i.e. no requests to |TS|). + +The above will ensure logs are rolled every 1h hour, only 1 rolled log file to be kept +(rest will be trimmed/removed) and logs will be rolling ("moving") even if nothing is logged +(i.e. no traffic to |TS|). + diff --git a/mgmt/RecordsConfig.cc b/mgmt/RecordsConfig.cc index 6ab20eb..f573985 100644 --- a/mgmt/RecordsConfig.cc +++ b/mgmt/RecordsConfig.cc @@ -1008,6 +1008,10 @@ static const RecordElement RecordsConfig[] = , {RECT_CONFIG, "proxy.config.log.rolling_min_count", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_STR, "^0*[1-9][0-9]*$", RECA_NULL} , + {RECT_CONFIG, "proxy.config.log.rolling_max_count", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL} + , + {RECT_CONFIG, "proxy.config.log.rolling_allow_empty", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_INT, "[0-1]", RECA_NULL} + , {RECT_CONFIG, "proxy.config.log.auto_delete_rolled_files", RECD_INT, "1", RECU_DYNAMIC, RR_NULL, RECC_INT, "[0-1]", RECA_NULL} , {RECT_CONFIG, "proxy.config.log.sampling_frequency", RECD_INT, "1", RECU_DYNAMIC, RR_NULL, RECC_NULL, nullptr, RECA_NULL} diff --git a/proxy/logging/LogConfig.cc b/proxy/logging/LogConfig.cc index e61f1e0..cb8522c 100644 --- a/proxy/logging/LogConfig.cc +++ b/proxy/logging/LogConfig.cc @@ -85,6 +85,8 @@ LogConfig::setup_default_values() rolling_interval_sec = 86400; // 24 hours rolling_offset_hr = 0; rolling_size_mb = 10; + rolling_max_count = 0; + rolling_allow_empty = false; auto_delete_rolled_files = true; roll_log_files_now = false; @@ -177,6 +179,9 @@ LogConfig::read_configuration_variables() val = (int)REC_ConfigReadInteger("proxy.config.log.auto_delete_rolled_files"); auto_delete_rolled_files = (val > 0); + val = (int)REC_ConfigReadInteger("proxy.config.log.rolling_allow_empty"); + rolling_allow_empty = (val > 0); + // Read in min_count control values for auto deletion if (auto_delete_rolled_files) { // For diagnostic logs @@ -193,6 +198,8 @@ LogConfig::read_configuration_variables() } else { deleting_info.insert(new LogDeletingInfo("traffic.out", val)); } + + rolling_max_count = (int)REC_ConfigReadInteger("proxy.config.log.rolling_max_count"); } // PERFORMANCE val = (int)REC_ConfigReadInteger("proxy.config.log.sampling_frequency"); @@ -329,6 +336,9 @@ LogConfig::display(FILE *fd) fprintf(fd, " rolling_interval_sec = %d\n", rolling_interval_sec); fprintf(fd, " rolling_offset_hr = %d\n", rolling_offset_hr); fprintf(fd, " rolling_size_mb = %d\n", rolling_size_mb); + fprintf(fd, " rolling_min_count = %d\n", rolling_min_count); + fprintf(fd, " rolling_max_count = %d\n", rolling_max_count); + fprintf(fd, " rolling_allow_empty = %d\n", rolling_allow_empty); fprintf(fd, " auto_delete_rolled_files = %d\n", auto_delete_rolled_files); fprintf(fd, " sampling_frequency = %d\n", sampling_frequency); fprintf(fd, " file_stat_frequency = %d\n", file_stat_frequency); @@ -406,8 +416,8 @@ LogConfig::register_config_callbacks() "proxy.config.log.max_space_mb_headroom", "proxy.config.log.logfile_perm", "proxy.config.log.hostname", "proxy.config.log.logfile_dir", "proxy.config.log.rolling_enabled", "proxy.config.log.rolling_interval_sec", "proxy.config.log.rolling_offset_hr", "proxy.config.log.rolling_size_mb", "proxy.config.log.auto_delete_rolled_files", - "proxy.config.log.config.filename", "proxy.config.log.sampling_frequency", "proxy.config.log.file_stat_frequency", - "proxy.config.log.space_used_frequency", + "proxy.config.log.rolling_max_count", "proxy.config.log.rolling_allow_empty", "proxy.config.log.config.filename", + "proxy.config.log.sampling_frequency", "proxy.config.log.file_stat_frequency", "proxy.config.log.space_used_frequency", }; for (unsigned i = 0; i < countof(names); ++i) { diff --git a/proxy/logging/LogConfig.h b/proxy/logging/LogConfig.h index b3372e3..6d69cdf 100644 --- a/proxy/logging/LogConfig.h +++ b/proxy/logging/LogConfig.h @@ -250,6 +250,8 @@ public: int rolling_offset_hr; int rolling_size_mb; int rolling_min_count; + int rolling_max_count; + bool rolling_allow_empty; bool auto_delete_rolled_files; IntrusiveHashMap<LogDeletingInfoDescriptor> deleting_info; diff --git a/proxy/logging/LogFile.cc b/proxy/logging/LogFile.cc index 53b0275..8c36d1a 100644 --- a/proxy/logging/LogFile.cc +++ b/proxy/logging/LogFile.cc @@ -27,6 +27,10 @@ ***************************************************************************/ +#include <vector> +#include <string> +#include <algorithm> + #include "tscore/ink_platform.h" #include "tscore/SimpleTokenizer.h" #include "tscore/ink_file.h" @@ -35,6 +39,7 @@ #include <sys/types.h> #include <sys/stat.h> #include <fcntl.h> +#include <libgen.h> #include "P_EventSystem.h" #include "I_Machine.h" @@ -235,6 +240,82 @@ LogFile::close_file() RecIncrRawStat(log_rsb, this_thread()->mutex->thread_holding, log_stat_log_files_open_stat, -1); } +struct RolledFile { + RolledFile(const std::string &name, time_t mtime) : _name(name), _mtime(mtime) {} + std::string _name; + time_t _mtime; +}; + +/** + * @brief trim rolled files to max number of rolled files, older first + * + * @param rolling_max_count - limit to which rolled files will be trimmed + * @return true if success, false if failure + */ +bool +LogFile::trim_rolled(size_t rolling_max_count) +{ + /* man: "dirname() may modify the contents of path, so it may be + * desirable to pass a copy when calling one of these functions." */ + char *name = ats_strdup(m_name); + std::string logfile_dir(::dirname((name))); + ats_free(name); + + /* Check logging directory access */ + int err; + do { + err = access(logfile_dir.c_str(), R_OK | W_OK | X_OK); + } while ((err < 0) && (errno == EINTR)); + + if (err < 0) { + Error("Error accessing logging directory %s: %s.", logfile_dir.c_str(), strerror(errno)); + return false; + } + + /* Open logging directory */ + DIR *ld = ::opendir(logfile_dir.c_str()); + if (ld == nullptr) { + Error("Error opening logging directory %s to collect trim candidates: %s.", logfile_dir.c_str(), strerror(errno)); + return false; + } + + /* Collect the rolled file names from the logging directory that match the specified log file name */ + std::vector<RolledFile> rolled; + char path[MAXPATHLEN]; + struct dirent *entry; + while ((entry = readdir(ld))) { + struct stat sbuf; + snprintf(path, MAXPATHLEN, "%s/%s", logfile_dir.c_str(), entry->d_name); + int sret = ::stat(path, &sbuf); + if (sret != -1 && S_ISREG(sbuf.st_mode)) { + int name_len = strlen(m_name); + int path_len = strlen(path); + if (path_len > name_len && 0 == ::strncmp(m_name, path, name_len) && LogFile::rolled_logfile(entry->d_name)) { + rolled.push_back(RolledFile(path, sbuf.st_mtime)); + } + } + } + + ::closedir(ld); + + bool result = true; + std::sort(rolled.begin(), rolled.end(), [](const RolledFile a, const RolledFile b) { return a._mtime > b._mtime; }); + if (rolling_max_count < rolled.size()) { + for (auto it = rolled.begin() + rolling_max_count; it != rolled.end(); it++) { + const RolledFile &file = *it; + if (unlink(file._name.c_str()) < 0) { + Error("unable to auto-delete rolled logfile %s: %s.", file._name.c_str(), strerror(errno)); + result = false; + } else { + Debug("log-file", "rolled logfile, %s, was auto-deleted", file._name.c_str()); + } + } + } + + rolled.clear(); + return result; +} + /*------------------------------------------------------------------------- * LogFile::roll * This function is called by a LogObject to roll its files. @@ -242,7 +323,7 @@ LogFile::close_file() * Return 1 if file rolled, 0 otherwise -------------------------------------------------------------------------*/ int -LogFile::roll(long interval_start, long interval_end) +LogFile::roll(long interval_start, long interval_end, bool reopen_after_rolling) { if (m_log) { // Due to commit 346b419 the BaseLogFile::close_file() is no longer called within BaseLogFile::roll(). @@ -257,6 +338,12 @@ LogFile::roll(long interval_start, long interval_end) // close file operation here within the containing LogFile object. if (m_log->roll(interval_start, interval_end)) { m_log->close_file(); + + if (reopen_after_rolling) { + /* If we re-open now log file will be created even if there is nothing being logged */ + m_log->open_file(); + } + return 1; } } diff --git a/proxy/logging/LogFile.h b/proxy/logging/LogFile.h index fe3b110..4f2fd65 100644 --- a/proxy/logging/LogFile.h +++ b/proxy/logging/LogFile.h @@ -58,7 +58,8 @@ public: int preproc_and_try_delete(LogBuffer *lb) override; - int roll(long interval_start, long interval_end); + bool trim_rolled(size_t rolling_max_count); + int roll(long interval_start, long interval_end, bool reopen_after_rolling = false); const char * get_name() const diff --git a/proxy/logging/LogObject.cc b/proxy/logging/LogObject.cc index 74b45dd..99838ea 100644 --- a/proxy/logging/LogObject.cc +++ b/proxy/logging/LogObject.cc @@ -90,7 +90,7 @@ LogBufferManager::preproc_buffers(LogBufferSink *sink) LogObject::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, - int rolling_offset_hr, int rolling_size_mb, bool auto_created) + int rolling_offset_hr, int rolling_size_mb, bool auto_created, int max_rolled, bool reopen_after_rolling) : m_alt_filename(nullptr), m_flags(0), m_signature(0), @@ -99,6 +99,8 @@ LogObject::LogObject(const LogFormat *format, const char *log_dir, const char *b m_rolling_offset_hr(rolling_offset_hr), m_rolling_size_mb(rolling_size_mb), m_last_roll_time(0), + m_max_rolled(max_rolled), + m_reopen_after_rolling(reopen_after_rolling), m_buffer_manager_idx(0) { ink_release_assert(format); @@ -118,6 +120,10 @@ LogObject::LogObject(const LogFormat *format, const char *log_dir, const char *b m_logFile = new LogFile(m_filename, header, file_format, m_signature, Log::config->ascii_buffer_size, Log::config->max_line_size); + if (m_reopen_after_rolling) { + m_logFile->open_file(); + } + LogBuffer *b = new LogBuffer(this, Log::config->log_buffer_size); ink_assert(b); SET_FREELIST_POINTER_VERSION(m_log_buffer, b, 0); @@ -140,14 +146,19 @@ LogObject::LogObject(LogObject &rhs) m_rolling_offset_hr(rhs.m_rolling_offset_hr), m_rolling_size_mb(rhs.m_rolling_size_mb), m_last_roll_time(rhs.m_last_roll_time), + m_max_rolled(rhs.m_max_rolled), + m_reopen_after_rolling(rhs.m_reopen_after_rolling), m_buffer_manager_idx(rhs.m_buffer_manager_idx) - { m_format = new LogFormat(*(rhs.m_format)); m_buffer_manager = new LogBufferManager[m_flush_threads]; if (rhs.m_logFile) { m_logFile = new LogFile(*(rhs.m_logFile)); + + if (m_reopen_after_rolling) { + m_logFile->open_file(); + } } else { m_logFile = nullptr; } @@ -746,7 +757,11 @@ LogObject::_roll_files(long last_roll_time, long time_now) if (m_logFile) { // no need to roll if object writes to a pipe if (!writes_to_pipe()) { - num_rolled += m_logFile->roll(last_roll_time, time_now); + num_rolled += m_logFile->roll(last_roll_time, time_now, m_reopen_after_rolling); + + if (Log::config->auto_delete_rolled_files && m_max_rolled > 0) { + m_logFile->trim_rolled(m_max_rolled); + } } } @@ -770,9 +785,9 @@ const LogFormat *TextLogObject::textfmt = MakeTextLogFormat(); TextLogObject::TextLogObject(const char *name, const char *log_dir, bool timestamps, const char *header, Log::RollingEnabledValues rolling_enabled, int flush_threads, int rolling_interval_sec, - int rolling_offset_hr, int rolling_size_mb) + int rolling_offset_hr, int rolling_size_mb, int max_rolled, 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) + rolling_offset_hr, rolling_size_mb, max_rolled, reopen_after_rolling) { if (timestamps) { this->set_fmt_timestamps(); diff --git a/proxy/logging/LogObject.h b/proxy/logging/LogObject.h index 73bc329..fcf6046 100644 --- a/proxy/logging/LogObject.h +++ b/proxy/logging/LogObject.h @@ -95,7 +95,7 @@ public: 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_size_mb = 0, bool auto_created = false, int rolling_max_count = 0, bool reopen_after_rolling = false); LogObject(LogObject &); ~LogObject() override; @@ -275,10 +275,11 @@ private: int m_flush_threads; // number of flush threads int m_rolling_interval_sec; // time interval between rolls // 0 means no rolling - int m_rolling_offset_hr; // - int m_rolling_size_mb; // size at which the log file rolls - long m_last_roll_time; // the last time this object rolled - // its files + int m_rolling_offset_hr; // + int m_rolling_size_mb; // size at which the log file rolls + long m_last_roll_time; // the last time this object rolled its files + int m_max_rolled; // maximum number of rolled logs to be kept, 0 no limit + bool m_reopen_after_rolling; // reopen log file after rolling (normally it is just renamed and closed) head_p m_log_buffer; // current work buffer unsigned m_buffer_manager_idx; @@ -309,7 +310,7 @@ class TextLogObject : public LogObject public: inkcoreapi TextLogObject(const char *name, const char *log_dir, bool timestamps, const char *header, Log::RollingEnabledValues rolling_enabled, int flush_threads, int rolling_interval_sec, - int rolling_offset_hr, int rolling_size_mb); + int rolling_offset_hr, int rolling_size_mb, int max_rolled, bool reopen_after_rolling); inkcoreapi int write(const char *format, ...) TS_PRINTFLIKE(2, 3); inkcoreapi int va_write(const char *format, va_list ap); @@ -409,7 +410,8 @@ LogObject::operator==(LogObject &old) return (get_signature() == old.get_signature() && m_logFile && old.m_logFile && strcmp(m_logFile->get_name(), old.m_logFile->get_name()) == 0 && (m_filter_list == old.m_filter_list) && (m_rolling_interval_sec == old.m_rolling_interval_sec && m_rolling_offset_hr == old.m_rolling_offset_hr && - m_rolling_size_mb == old.m_rolling_size_mb)); + m_rolling_size_mb == old.m_rolling_size_mb && m_reopen_after_rolling == old.m_reopen_after_rolling && + m_max_rolled == old.m_max_rolled)); } inline off_t diff --git a/proxy/logging/YamlLogConfig.cc b/proxy/logging/YamlLogConfig.cc index 2db694b..934a655 100644 --- a/proxy/logging/YamlLogConfig.cc +++ b/proxy/logging/YamlLogConfig.cc @@ -110,8 +110,8 @@ TsEnumDescriptor ROLLING_MODE_LUA = { {{"log.roll.none", 0}, {"log.roll.time", 1}, {"log.roll.size", 2}, {"log.roll.both", 3}, {"log.roll.any", 4}}}; std::set<std::string> valid_log_object_keys = { - "filename", "format", "mode", "header", "rolling_enabled", "rolling_interval_sec", - "rolling_offset_hr", "rolling_size_mb", "filters", "min_count"}; + "filename", "format", "mode", "header", "rolling_enabled", "rolling_interval_sec", + "rolling_offset_hr", "rolling_size_mb", "filters", "min_count", "rolling_max_count", "rolling_allow_empty"}; LogObject * YamlLogConfig::decodeLogObject(const YAML::Node &node) @@ -158,6 +158,8 @@ YamlLogConfig::decodeLogObject(const YAML::Node &node) int obj_rolling_offset_hr = cfg->rolling_offset_hr; int obj_rolling_size_mb = cfg->rolling_size_mb; int obj_min_count = cfg->rolling_min_count; + int obj_rolling_max_count = cfg->rolling_max_count; + int obj_rolling_allow_empty = cfg->rolling_allow_empty; if (node["rolling_enabled"]) { auto value = node["rolling_enabled"].as<std::string>(); @@ -184,13 +186,20 @@ YamlLogConfig::decodeLogObject(const YAML::Node &node) if (node["min_count"]) { obj_min_count = node["min_count"].as<int>(); } + if (node["rolling_max_count"]) { + obj_rolling_max_count = node["rolling_max_count"].as<int>(); + } + if (node["rolling_allow_empty"]) { + obj_rolling_allow_empty = node["rolling_allow_empty"].as<int>(); + } if (!LogRollingEnabledIsValid(obj_rolling_enabled)) { Warning("Invalid log rolling value '%d' in log object", obj_rolling_enabled); } - auto logObject = new LogObject(fmt, Log::config->logfile_dir, filename.c_str(), file_type, header.c_str(), - (Log::RollingEnabledValues)obj_rolling_enabled, Log::config->preproc_threads, - obj_rolling_interval_sec, obj_rolling_offset_hr, obj_rolling_size_mb); + auto logObject = new LogObject( + fmt, Log::config->logfile_dir, filename.c_str(), file_type, header.c_str(), (Log::RollingEnabledValues)obj_rolling_enabled, + Log::config->preproc_threads, obj_rolling_interval_sec, obj_rolling_offset_hr, obj_rolling_size_mb, /* auto_created */ false, + /* rolling_max_count */ obj_rolling_max_count, /* reopen_after_rolling */ obj_rolling_allow_empty > 0); // Generate LogDeletingInfo entry for later use std::string ext; diff --git a/src/traffic_server/InkAPI.cc b/src/traffic_server/InkAPI.cc index c103e0f..9414b1d 100644 --- a/src/traffic_server/InkAPI.cc +++ b/src/traffic_server/InkAPI.cc @@ -7320,7 +7320,8 @@ TSTextLogObjectCreate(const char *filename, int mode, TSTextLogObject *new_objec TextLogObject *tlog = new TextLogObject( filename, Log::config->logfile_dir, (bool)mode & TS_LOG_MODE_ADD_TIMESTAMP, nullptr, Log::config->rolling_enabled, - Log::config->preproc_threads, Log::config->rolling_interval_sec, Log::config->rolling_offset_hr, Log::config->rolling_size_mb); + Log::config->preproc_threads, Log::config->rolling_interval_sec, Log::config->rolling_offset_hr, Log::config->rolling_size_mb, + Log::config->rolling_max_count, Log::config->rolling_allow_empty); if (tlog == nullptr) { *new_object = nullptr; return TS_ERROR;