Windows: Add log file rotation support

An external log file rotation tool, such as `logrotate` will not work
with an operating system such as Windows. From the Python documentation
for `WatchedFileHandler` (which is used for log files in Salt):

"This handler is not appropriate for use under Windows, because under
Windows open log files cannot be moved or renamed - logging opens the
files with exclusive locks - and so there is no need for such a handler.
Furthermore, ST_INO is not supported under Windows; stat() always returns
zero for this value."

This also describes the problem with why an external utility such as
`logrotate` will not work for Windows, because files cannot be renamed
while in use, unlike on other operating systems, such as Linux.

Due to the above, the strategy for this change is to use the
`RotatingFileHandler` logger (when log file rotation is enabled) and to
allow only one process to do the file logging. Previously on Windows,
there was a file logger installed in the main process and another in the
logging listener process. This change changes the architecture in the
following way (on Windows only):

- Added two new configuration options, `log_rotate_max_bytes` and
`log_rotate_backup_count`. They both default to 0. When
`log_rotate_max_bytes` is non-zero, the `RotatingFileHandler` will be
used for file logging instead of the `WatchedFileHandler`.
- The only process that does file logging is the logging listener process
(if it exists)
- When the logging listener process does not exist, only the main process
does file logging.
- When the logging listener process exists, the main process will now set
up multiprocessing logging (which is the client to the logging listener).
- Since the logging listener does logging for extended logging, console,
and log file logging, do not use these types of logging in the main process
when there is a logging listener.

There is one observed caveat: when the log file is in use, and it is time
to rollover (rename the file), the rollover will fail. This has been
obversed when salt-call is running and has the `minion` log file open
for its own logging uses while the salt-minion is trying to rollover.
Luckily, it will recover and try to rollover again on the next log write,
and if the file is no longer in use, it will succeed this time. Hence,
having a log file open somewhere else will delay rollover until the file
is closed.

Signed-off-by: Sergey Kizunov <sergey.kizunov@ni.com>

salt/config/__init__.py

@@ -361,6 +361,18 @@ def _gather_buffer_space():
     # A dictionary of logging levels
     'log_granular_levels': dict,
 
+    # The maximum number of bytes a single log file may contain before
+    # it is rotated. A value of 0 disables this feature.
+    # Currently only supported on Windows. On other platforms, use an
+    # external tool such as 'logrotate' to manage log files.
+    'log_rotate_max_bytes': int,
+
+    # The number of backup files to keep when rotating log files. Only
+    # used if log_rotate_max_bytes is greater than 0.
+    # Currently only supported on Windows. On other platforms, use an
+    # external tool such as 'logrotate' to manage log files.
+    'log_rotate_backup_count': int,
+
     # If an event is above this size, it will be trimmed before putting it on the event bus
     'max_event_size': int,
 
@@ -1056,6 +1068,8 @@ def _gather_buffer_space():
     'log_fmt_console': _DFLT_LOG_FMT_CONSOLE,
     'log_fmt_logfile': _DFLT_LOG_FMT_LOGFILE,
     'log_granular_levels': {},
+    'log_rotate_max_bytes': 0,
+    'log_rotate_backup_count': 0,
     'max_event_size': 1048576,
     'test': False,
     'ext_job_cache': '',
@@ -1324,6 +1338,8 @@ def _gather_buffer_space():
     'log_fmt_console': _DFLT_LOG_FMT_CONSOLE,
     'log_fmt_logfile': _DFLT_LOG_FMT_LOGFILE,
     'log_granular_levels': {},
+    'log_rotate_max_bytes': 0,
+    'log_rotate_backup_count': 0,
     'pidfile': os.path.join(salt.syspaths.PIDFILE_DIR, 'salt-master.pid'),
     'publish_session': 86400,
     'range_server': 'range:80',
@@ -1472,6 +1488,8 @@ def _gather_buffer_space():
     'log_fmt_console': _DFLT_LOG_FMT_CONSOLE,
     'log_fmt_logfile': _DFLT_LOG_FMT_LOGFILE,
     'log_granular_levels': {},
+    'log_rotate_max_bytes': 0,
+    'log_rotate_backup_count': 0,
     'bootstrap_delay': None,
 }
 

salt/log/handlers/__init__.py

@@ -104,6 +104,40 @@ class SysLogHandler(ExcInfoOnLogLevelFormatMixIn, logging.handlers.SysLogHandler
     '''
 
 
+class RotatingFileHandler(ExcInfoOnLogLevelFormatMixIn, logging.handlers.RotatingFileHandler, NewStyleClassMixIn):
+    '''
+    Rotating file handler which properly handles exc_info on a per handler basis
+    '''
+    def handleError(self, record):
+        '''
+        Override the default error handling mechanism
+
+        Deal with log file rotation errors due to log file in use
+        more softly.
+        '''
+        handled = False
+
+        # Can't use "salt.utils.is_windows()" in this file
+        if (sys.platform.startswith('win') and
+                logging.raiseExceptions and
+                sys.stderr):  # see Python issue 13807
+            t, v, tb = sys.exc_info()
+            try:
+                # PermissionError is used since Python 3.3.
+                # OSError is used for previous versions of Python.
+                if t.__name__ in ('PermissionError', 'OSError') and v.winerror == 32:
+                    if self.level <= logging.WARNING:
+                        sys.stderr.write('[WARNING ] Unable to rotate the log file "{0}" '
+                                         'because it is in use\n'.format(self.baseFilename)
+                        )
+                    handled = True
+            finally:
+                del t, v, tb
+
+        if not handled:
+            super(RotatingFileHandler, self).handleError(record)
+
+
 if sys.version_info > (2, 6):
     class WatchedFileHandler(ExcInfoOnLogLevelFormatMixIn, logging.handlers.WatchedFileHandler, NewStyleClassMixIn):
         '''

salt/log/setup.py

@@ -44,6 +44,7 @@
                                SysLogHandler,
                                FileHandler,
                                WatchedFileHandler,
+                               RotatingFileHandler,
                                QueueHandler)
 from salt.log.mixins import LoggingMixInMeta, NewStyleClassMixIn
 
@@ -107,7 +108,9 @@
 MODNAME_PATTERN = re.compile(r'(?P<name>%%\(name\)(?:\-(?P<digits>[\d]+))?s)')
 
 __CONSOLE_CONFIGURED = False
+__LOGGING_CONSOLE_HANDLER = None
 __LOGFILE_CONFIGURED = False
+__LOGGING_LOGFILE_HANDLER = None
 __TEMP_LOGGING_CONFIGURED = False
 __EXTERNAL_LOGGERS_CONFIGURED = False
 __MP_LOGGING_LISTENER_CONFIGURED = False
@@ -501,11 +504,13 @@ def setup_console_logger(log_level='error', log_format=None, date_format=None):
     logging.root.addHandler(handler)
 
     global __CONSOLE_CONFIGURED
+    global __LOGGING_CONSOLE_HANDLER
     __CONSOLE_CONFIGURED = True
+    __LOGGING_CONSOLE_HANDLER = handler
 
 
 def setup_logfile_logger(log_path, log_level='error', log_format=None,
-                         date_format=None):
+                         date_format=None, max_bytes=0, backup_count=0):
     '''
     Setup the logfile logger
 
@@ -649,7 +654,15 @@ def setup_logfile_logger(log_path, log_level='error', log_format=None,
             # Since salt uses YAML and YAML uses either UTF-8 or UTF-16, if a
             # user is not using plain ASCII, their system should be ready to
             # handle UTF-8.
-            handler = WatchedFileHandler(log_path, mode='a', encoding='utf-8', delay=0)
+            if max_bytes > 0:
+                handler = RotatingFileHandler(log_path,
+                                              mode='a',
+                                              maxBytes=max_bytes,
+                                              backupCount=backup_count,
+                                              encoding='utf-8',
+                                              delay=0)
+            else:
+                handler = WatchedFileHandler(log_path, mode='a', encoding='utf-8', delay=0)
         except (IOError, OSError):
             logging.getLogger(__name__).warning(
                 'Failed to open log file, do you have permission to write to '
@@ -674,7 +687,9 @@ def setup_logfile_logger(log_path, log_level='error', log_format=None,
     root_logger.addHandler(handler)
 
     global __LOGFILE_CONFIGURED
+    global __LOGGING_LOGFILE_HANDLER
     __LOGFILE_CONFIGURED = True
+    __LOGGING_LOGFILE_HANDLER = handler
 
 
 def setup_extended_logging(opts):
@@ -807,11 +822,15 @@ def setup_multiprocessing_logging(queue=None):
     This code should be called from within a running multiprocessing
     process instance.
     '''
+    from salt.utils import is_windows
+
     global __MP_LOGGING_CONFIGURED
     global __MP_LOGGING_QUEUE_HANDLER
 
-    if __MP_IN_MAINPROCESS is True:
+    if __MP_IN_MAINPROCESS is True and not is_windows():
         # We're in the MainProcess, return! No multiprocessing logging setup shall happen
+        # Windows is the exception where we want to set up multiprocessing
+        # logging in the MainProcess.
         return
 
     try:
@@ -850,21 +869,55 @@ def setup_multiprocessing_logging(queue=None):
         logging._releaseLock()  # pylint: disable=protected-access
 
 
+def shutdown_console_logging():
+    global __CONSOLE_CONFIGURED
+    global __LOGGING_CONSOLE_HANDLER
+
+    if not __CONSOLE_CONFIGURED or not __LOGGING_CONSOLE_HANDLER:
+        return
+
+    try:
+        logging._acquireLock()
+        logging.root.removeHandler(__LOGGING_CONSOLE_HANDLER)
+        __LOGGING_CONSOLE_HANDLER = None
+        __CONSOLE_CONFIGURED = False
+    finally:
+        logging._releaseLock()
+
+
+def shutdown_logfile_logging():
+    global __LOGFILE_CONFIGURED
+    global __LOGGING_LOGFILE_HANDLER
+
+    if not __LOGFILE_CONFIGURED or not __LOGGING_LOGFILE_HANDLER:
+        return
+
+    try:
+        logging._acquireLock()
+        logging.root.removeHandler(__LOGGING_LOGFILE_HANDLER)
+        __LOGGING_LOGFILE_HANDLER = None
+        __LOGFILE_CONFIGURED = False
+    finally:
+        logging._releaseLock()
+
+
+def shutdown_temp_logging():
+    __remove_temp_logging_handler()
+
+
 def shutdown_multiprocessing_logging():
     global __MP_LOGGING_CONFIGURED
     global __MP_LOGGING_QUEUE_HANDLER
 
-    if __MP_IN_MAINPROCESS is True:
-        # We're in the MainProcess, return! No multiprocessing logging shutdown shall happen
+    if not __MP_LOGGING_CONFIGURED or not __MP_LOGGING_QUEUE_HANDLER:
         return
 
     try:
         logging._acquireLock()
-        if __MP_LOGGING_CONFIGURED is True:
-            # Let's remove the queue handler from the logging root handlers
-            logging.root.removeHandler(__MP_LOGGING_QUEUE_HANDLER)
-            __MP_LOGGING_QUEUE_HANDLER = None
-            __MP_LOGGING_CONFIGURED = False
+        # Let's remove the queue handler from the logging root handlers
+        logging.root.removeHandler(__MP_LOGGING_QUEUE_HANDLER)
+        __MP_LOGGING_QUEUE_HANDLER = None
+        __MP_LOGGING_CONFIGURED = False
     finally:
         logging._releaseLock()
 
@@ -923,6 +976,7 @@ def patch_python_logging_handlers():
     logging.FileHandler = FileHandler
     logging.handlers.SysLogHandler = SysLogHandler
     logging.handlers.WatchedFileHandler = WatchedFileHandler
+    logging.handlers.RotatingFileHandler = RotatingFileHandler
     if sys.version_info >= (3, 2):
         logging.handlers.QueueHandler = QueueHandler
 
@@ -951,7 +1005,9 @@ def __process_multiprocessing_logging_queue(opts, queue):
             opts.get('log_file'),
             log_level=opts.get('log_level_logfile'),
             log_format=opts.get('log_fmt_logfile'),
-            date_format=opts.get('log_datefmt_logfile')
+            date_format=opts.get('log_datefmt_logfile'),
+            max_bytes=opts.get('log_rotate_max_bytes', 0),
+            backup_count=opts.get('log_rotate_backup_count', 0)
         )
         setup_extended_logging(opts)
     while True:

salt/utils/parsers.py

@@ -603,6 +603,9 @@ def process_log_level(self):
         self._mixin_after_parsed_funcs.append(self.__setup_console_logger_config)
         # Setup the multiprocessing log queue listener if enabled
         self._mixin_after_parsed_funcs.append(self._setup_mp_logging_listener)
+        # Setup the multiprocessing log queue client if listener is enabled
+        # and using Windows
+        self._mixin_after_parsed_funcs.append(self._setup_mp_logging_client)
         # Setup the console as the last _mixin_after_parsed_func to run
         self._mixin_after_parsed_funcs.append(self.__setup_console_logger)
 
@@ -799,28 +802,56 @@ def __setup_logfile_logger_config(self, *args):  # pylint: disable=unused-argume
             # If we haven't changed the logfile path and it's not writeable,
             # salt will fail once we try to setup the logfile logging.
 
+        # Log rotate options
+        log_rotate_max_bytes = self.config.get('log_rotate_max_bytes', 0)
+        log_rotate_backup_count = self.config.get('log_rotate_backup_count', 0)
+        if not salt.utils.is_windows():
+            # Not supported on platforms other than Windows.
+            # Other platforms may use an external tool such as 'logrotate'
+            if log_rotate_max_bytes != 0:
+                logging.getLogger(__name__).warning('\'log_rotate_max_bytes\' is only supported on Windows')
+                log_rotate_max_bytes = 0
+            if log_rotate_backup_count != 0:
+                logging.getLogger(__name__).warning('\'log_rotate_backup_count\' is only supported on Windows')
+                log_rotate_backup_count = 0
+
         # Save the settings back to the configuration
         self.config[self._logfile_config_setting_name_] = logfile
         self.config[self._logfile_loglevel_config_setting_name_] = loglevel
         self.config['log_fmt_logfile'] = log_file_fmt
         self.config['log_datefmt_logfile'] = log_file_datefmt
+        self.config['log_rotate_max_bytes'] = log_rotate_max_bytes
+        self.config['log_rotate_backup_count'] = log_rotate_backup_count
 
     def setup_logfile_logger(self):
+        if salt.utils.is_windows() and self._setup_mp_logging_listener_:
+            # On Windows when using a logging listener, all log file logging
+            # will go through the logging listener.
+            return
+
         logfile = self.config[self._logfile_config_setting_name_]
         loglevel = self.config[self._logfile_loglevel_config_setting_name_]
         log_file_fmt = self.config['log_fmt_logfile']
         log_file_datefmt = self.config['log_datefmt_logfile']
+        log_rotate_max_bytes = self.config['log_rotate_max_bytes']
+        log_rotate_backup_count = self.config['log_rotate_backup_count']
 
         log.setup_logfile_logger(
             logfile,
             loglevel,
             log_format=log_file_fmt,
-            date_format=log_file_datefmt
+            date_format=log_file_datefmt,
+            max_bytes=log_rotate_max_bytes,
+            backup_count=log_rotate_backup_count
         )
         for name, level in six.iteritems(self.config['log_granular_levels']):
             log.set_logger_level(name, level)
 
     def __setup_extended_logging(self, *args):  # pylint: disable=unused-argument
+        if salt.utils.is_windows() and self._setup_mp_logging_listener_:
+            # On Windows when using a logging listener, all extended logging
+            # will go through the logging listener.
+            return
         log.setup_extended_logging(self.config)
 
     def _get_mp_logging_listener_queue(self):
@@ -833,6 +864,23 @@ def _setup_mp_logging_listener(self, *args):  # pylint: disable=unused-argument
                 self._get_mp_logging_listener_queue()
             )
 
+    def _setup_mp_logging_client(self, *args):  # pylint: disable=unused-argument
+        if salt.utils.is_windows() and self._setup_mp_logging_listener_:
+            # On Windows, all logging including console and
+            # log file logging will go through the multiprocessing
+            # logging listener if it exists.
+            # This will allow log file rotation on Windows
+            # since only one process can own the log file
+            # for log file rotation to work.
+            log.setup_multiprocessing_logging(
+                self._get_mp_logging_listener_queue()
+            )
+            # Remove the temp logger and any other configured loggers since all of
+            # our logging is going through the multiprocessing logging listener.
+            log.shutdown_temp_logging()
+            log.shutdown_console_logging()
+            log.shutdown_logfile_logging()
+
     def __setup_console_logger_config(self, *args):  # pylint: disable=unused-argument
         # Since we're not going to be a daemon, setup the console logger
         cli_log_fmt = 'cli_{0}_log_fmt'.format(
@@ -884,6 +932,11 @@ def __setup_console_logger(self, *args):  # pylint: disable=unused-argument
         if getattr(self.options, 'daemon', False) is True:
             return
 
+        if salt.utils.is_windows() and self._setup_mp_logging_listener_:
+            # On Windows when using a logging listener, all console logging
+            # will go through the logging listener.
+            return
+
         log.setup_console_logger(
             self.config['log_level'],
             log_format=self.config['log_fmt_console'],