Options to roll empty logs and log trimming (8.1.x)

doc/admin-guide/files/records.config.en.rst

@@ -277,6 +277,31 @@ System Variables
    Specifies at what size to roll the output log at.
 
 
+.. 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
 ----------------
 

doc/admin-guide/logging/rotation.en.rst

@@ -235,3 +235,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|).
+

mgmt/RecordsConfig.cc

@@ -1039,6 +1039,10 @@ static const RecordElement RecordsConfig[] =
   ,
   {RECT_CONFIG, "proxy.config.log.rolling_size_mb", RECD_INT, "10", 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}

proxy/logging/LogConfig.cc

@@ -96,6 +96,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;
 
@@ -233,6 +235,11 @@ 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);
+
+  rolling_max_count = (int)REC_ConfigReadInteger("proxy.config.log.rolling_max_count");
+
   // PERFORMANCE
   val = (int)REC_ConfigReadInteger("proxy.config.log.sampling_frequency");
   if (val > 0) {
@@ -466,6 +473,8 @@ 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_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);
@@ -559,6 +568,8 @@ LogConfig::register_config_callbacks()
     "proxy.config.log.rolling_offset_hr",
     "proxy.config.log.rolling_size_mb",
     "proxy.config.log.auto_delete_rolled_files",
+    "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/logging/LogConfig.h

@@ -188,6 +188,8 @@ class LogConfig : public ConfigInfo
   int rolling_interval_sec;
   int rolling_offset_hr;
   int rolling_size_mb;
+  int rolling_max_count;
+  bool rolling_allow_empty;
   bool auto_delete_rolled_files;
 
   int sampling_frequency;

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"
@@ -237,14 +242,90 @@ 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.
  *
  * 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().
@@ -259,6 +340,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;
     }
   }

proxy/logging/LogFile.h

@@ -59,7 +59,8 @@ class LogFile : public LogBufferSink, public RefCountObj
 
   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

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_auto_created(auto_created),
     m_alt_filename(nullptr),
     m_flags(0),
@@ -100,6 +100,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);
@@ -122,6 +124,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);
@@ -145,14 +151,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;
   }
@@ -774,7 +785,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);
+      }
     }
   } else {
     LogHost *host;
@@ -805,9 +820,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();

proxy/logging/LogObject.h

@@ -99,7 +99,7 @@ class LogObject : public RefCountObj
 
   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;
 
@@ -289,10 +289,11 @@ class LogObject : public RefCountObj
   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;
@@ -323,7 +324,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);
@@ -428,7 +429,8 @@ LogObject::operator==(LogObject &old)
                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));
   }
   return false;
 }