From 552399839ff9d4bf073b3d4ae88831951e28336d Mon Sep 17 00:00:00 2001 From: Dennis Lee Date: Mon, 1 Apr 2024 16:29:50 -0500 Subject: [PATCH 1/2] Removed rotatelogs setup in RESTDaemon Use getTimeRotatingLogger for WMCore REST Added date to filename for MyTimedRotatingFileHandler if it doesn't have it Added usage for wmc-httpd LOG-FILE arg Renamed MyTimedRotatingFileHandler to WMTimedRotatingFileHandler Simplified WMTimedRotatingFileHandler to use namer function Remove unused code and docstrings Fixed service log rotation Add QueueHandler for cherrypy, remove redirecting logging QueueHandler for cherrypy logs Added a queue listener thread that aggregates all logs that are handled with the WMTimedRotatingLogger Removed redirecting logging to a subprocess or a file using file descriptors --- src/python/WMCore/REST/Main.py | 83 ++++++++++++------------ src/python/WMCore/WMLogging.py | 114 ++++++++++++++++++++++++--------- 2 files changed, 125 insertions(+), 72 deletions(-) diff --git a/src/python/WMCore/REST/Main.py b/src/python/WMCore/REST/Main.py index 82e4e89e7c..9a65845e30 100644 --- a/src/python/WMCore/REST/Main.py +++ b/src/python/WMCore/REST/Main.py @@ -5,7 +5,11 @@ Manages a web server application. Loads configuration and all views, starting up an appropriately configured CherryPy instance. Views are loaded dynamically -and can be turned on/off via configuration file.""" +and can be turned on/off via configuration file. + +If LOG-FILE does not contain a date in %Y%m%d format, +a date will be added before the file extension. +""" from __future__ import print_function from builtins import object @@ -13,8 +17,10 @@ from future import standard_library standard_library.install_aliases() +from datetime import date import errno import logging +from multiprocessing import Queue, Process import os import os.path import re @@ -35,19 +41,21 @@ from cherrypy._cplogging import LogManager from cherrypy.lib import profiler -### Tools is needed for CRABServer startup: it sets up the tools attributes +# Tools is needed for CRABServer startup: it sets up the tools attributes import WMCore.REST.Tools + from WMCore.Configuration import ConfigSection, loadConfigurationFile +from WMCore.WMLogging import getTimeRotatingLogger, log_listener from Utils.Utilities import lowerCmsHeaders from Utils.PythonVersion import PY2 -#: Terminal controls to switch to "OK" status message colour. +# Terminal controls to switch to "OK" status message colour. COLOR_OK = "\033[0;32m" -#: Terminal controls to switch to "warning" status message colour. +# Terminal controls to switch to "warning" status message colour. COLOR_WARN = "\033[0;31m" -#: Terminal controls to restore normal message colour. +# Terminal controls to restore normal message colour. COLOR_NORMAL = "\033[0;39m" @@ -101,7 +109,8 @@ def __init__(self, app, path): self.profiler = profiler.ProfileAggregator(path) def __call__(self, env, handler): - def gather(): return Application.__call__(self, env, handler) + def gather(): + return Application.__call__(self, env, handler) return self.profiler.run(gather) @@ -181,6 +190,7 @@ def __init__(self, config, statedir): self.silent = False self.extensions = {} self.views = {} + self.logQueue = None def validate_config(self): """Check the server configuration has the required sections.""" @@ -213,10 +223,15 @@ def setup_server(self): if local_base.find(':') == -1: local_base = '%s:%d' % (local_base, port) - # Set default server configuration. + # setup the cherrypy access logs to log to a queue cherrypy.log = Logger() + handler = logging.handlers.QueueHandler(self.logQueue) + cherrypy.log.access_file = "" + cherrypy.log.error_file = "" + cherrypy.log.access_log.addHandler(handler) + cherrypy.log.error_log.addHandler(handler) - cpconfig.update({'tools.add_content_length_if_missing.on': True}) + # Set default server configuration. cpconfig.update({'server.max_request_body_size': 0}) cpconfig.update({'server.environment': 'production'}) cpconfig.update({'server.socket_host': '0.0.0.0'}) @@ -234,7 +249,7 @@ def setup_server(self): # as we previously used sys.setcheckinterval interval = getattr(self.srvconfig, 'sys_check_interval', 10000) # set check interval in seconds for sys.setswitchinterval - sys.setswitchinterval(interval/1000) + sys.setswitchinterval(interval / 1000) self.silent = getattr(self.srvconfig, 'silent', False) # Apply any override options from app config file. @@ -324,7 +339,8 @@ def __init__(self, config, statedir): :arg str statedir: server state directory.""" RESTMain.__init__(self, config, statedir) self.pidfile = "%s/%s.pid" % (self.statedir, self.appname) - self.logfile = ["rotatelogs", "%s/%s-%%Y%%m%%d.log" % (self.statedir, self.appname), "86400"] + todayStr = date.today().strftime("%Y%m%d") + self.logfile = f"{self.statedir}/{self.appname}-{todayStr}.log" def daemon_pid(self): """Check if there is a daemon running, and if so return its pid. @@ -413,24 +429,6 @@ def start_daemon(self): os.chdir(self.statedir) if daemonize: - # Redirect all output to the logging daemon. - devnull = open(os.devnull, "w") - if isinstance(self.logfile, list): - subproc = Popen(self.logfile, stdin=PIPE, stdout=devnull, stderr=devnull, - bufsize=0, close_fds=True, shell=False) - logger = subproc.stdin - elif isinstance(self.logfile, str): - # if a unix pipe is set as the logfile, it must be opened to append to the end of the file - # if file/pipe does not exist, create it - logger = open(self.logfile, "a") - else: - raise TypeError("'logfile' must be a string or array") - os.dup2(logger.fileno(), sys.stdout.fileno()) - os.dup2(logger.fileno(), sys.stderr.fileno()) - os.dup2(devnull.fileno(), sys.stdin.fileno()) - logger.close() - devnull.close() - # First fork. Discard the parent. pid = os.fork() if pid > 0: @@ -481,7 +479,8 @@ def run(self): cherrypy.log("WATCHDOG: starting server daemon (pid %d)" % os.getpid()) while True: serverpid = os.fork() - if not serverpid: break + if not serverpid: + break signal.signal(signal.SIGINT, signal.SIG_IGN) signal.signal(signal.SIGTERM, signal.SIG_IGN) signal.signal(signal.SIGQUIT, signal.SIG_IGN) @@ -581,18 +580,15 @@ def main(): running, pid = server.daemon_pid() if running: if not opts.quiet: - print("%s is %sRUNNING%s, PID %d" \ - % (app, COLOR_OK, COLOR_NORMAL, pid)) + print(f"{app} is {COLOR_OK}RUNNING{COLOR_NORMAL}, PID {pid}") sys.exit(0) elif pid != None: if not opts.quiet: - print("%s is %sNOT RUNNING%s, stale PID %d" \ - % (app, COLOR_WARN, COLOR_NORMAL, pid)) + print(f"{app} is {COLOR_WARN}NOT RUNNING{COLOR_NORMAL}, PID {pid}") sys.exit(2) else: if not opts.quiet: - print("%s is %sNOT RUNNING%s" \ - % (app, COLOR_WARN, COLOR_NORMAL)) + print(f"{app} is {COLOR_WARN}NOT RUNNING{COLOR_NORMAL}") sys.exit(1) elif opts.kill: @@ -623,14 +619,17 @@ def main(): print("Refusing to start over an already running daemon, pid %d" % pid, file=sys.stderr) sys.exit(1) - # If we are (re)starting and were given a log file option, convert - # the logfile option to a list if it looks like a pipe request, i.e. - # starts with "|", such as "|rotatelogs foo/bar-%Y%m%d.log". if opts.logfile: - if opts.logfile.startswith("|"): - server.logfile = re.split(r"\s+", opts.logfile[1:]) - else: - server.logfile = opts.logfile + server.logfile = opts.logfile + + # setup the queue for the QueueHandler + logQueue = Queue() + server.logQueue = logQueue + + listener = Process(target=log_listener, + args=(logQueue, server.logfile)) + + logger = getTimeRotatingLogger(None, server.logfile) # Actually start the daemon now. server.start_daemon() diff --git a/src/python/WMCore/WMLogging.py b/src/python/WMCore/WMLogging.py index 55d713b4e4..3f26236238 100644 --- a/src/python/WMCore/WMLogging.py +++ b/src/python/WMCore/WMLogging.py @@ -4,16 +4,23 @@ Logging facilities used in WMCore. """ +from datetime import datetime, date import logging -from datetime import date, timedelta -from logging.handlers import HTTPHandler, RotatingFileHandler, TimedRotatingFileHandler +from logging.handlers import (HTTPHandler, + RotatingFileHandler, + TimedRotatingFileHandler, + QueueHandler, + QueueListener) +from pathlib import Path + # a new log level which is lower than debug # to prevent a tsunami of log messages in debug # mode but to have the possibility to see all # database queries if necessary. logging.SQLDEBUG = 5 -logging.addLevelName(logging.SQLDEBUG,"SQLDEBUG") +logging.addLevelName(logging.SQLDEBUG, "SQLDEBUG") + def sqldebug(msg): """ @@ -22,7 +29,34 @@ def sqldebug(msg): """ logging.log(logging.SQLDEBUG, msg) -def setupRotatingHandler(fileName, maxBytes = 200000000, backupCount = 3): + +def log_listener(queue, name, logFile): + """ + Listener process for process to fetch logs from a queue and log to the + root logger. The root logger is set to a TimeRotatingLogger + + From + https://docs.python.org/3/howto/logging-cookbook.html#logging-to-a-single-file-from-multiple-processes + + :param queue: The queue to listen to + :param name: The logger name + :param logFile: The TimeRotatingLogger filename + """ + getTimeRotatingLogger(name, logFile) + while True: + try: + record = queue.get() + if record is None: + break + logger = logger.getLogger(record.name) + logger.handle(record) + except Exception: + import sys, traceback + print('Problem with log listener:', file=sys.stderr) + traceback.print_exc(file=sys.stderr) + + +def setupRotatingHandler(fileName, maxBytes=200000000, backupCount=3): """ _setupRotatingHandler_ @@ -30,55 +64,75 @@ def setupRotatingHandler(fileName, maxBytes = 200000000, backupCount = 3): """ handler = RotatingFileHandler(fileName, "a", maxBytes, backupCount) logging.getLogger().addHandler(handler) - return -def getTimeRotatingLogger(name, logFile, duration = 'midnight'): - """ Set the logger for time based lotaing. +def getTimeRotatingLogger(name, logFile, duration='midnight'): + """ + Set the logger for time based rotating. """ logger = logging.getLogger(name) if duration == 'midnight': - handler = MyTimedRotatingFileHandler(logFile, duration, backupCount = 10) + handler = WMTimedRotatingFileHandler(logFile, when=duration, backupCount=10) else: - handler = TimedRotatingFileHandler(logFile, duration, backupCount = 10) + handler = TimedRotatingFileHandler(logFile, when=duration, backupCount=10) formatter = logging.Formatter("%(asctime)s:%(levelname)s:%(module)s:%(message)s") handler.setFormatter(formatter) logger.addHandler(handler) - logger.setLevel(logging.INFO) + # logger.setLevel(logging.INFO) return logger -class MyTimedRotatingFileHandler(TimedRotatingFileHandler): +class WMTimedRotatingFileHandler(TimedRotatingFileHandler): """ - _MyTimedRotatingFileHandler_ + _WMTimedRotatingFileHandler_ Overwrite the standard filename functionality from - logging.handlers.MyTimedRotatingFileHandler + logging.handlers.TimedRotatingFileHandler such that it mimics the same behaviour as rotatelogs tool. - Source code from: - https://stackoverflow.com/questions/338450/timedrotatingfilehandler-changing-file-name + More information here: + https://docs.python.org/3/library/logging.handlers.html#baserotatinghandler """ - def __init__(self, logName, interval, backupCount): - super(MyTimedRotatingFileHandler, self).__init__(logName, when=interval, - backupCount=backupCount) + def __init__(self, filename, when='midnight', backupCount=10, **kwargs): + """ + Initializes WMTimedRotatingFileHandler + """ + super().__init__(filename, when=when, backupCount=backupCount, + delay=True, **kwargs) + + today = datetime.now().strftime(self.suffix).replace('-', '') + # store our filename and set the filename to be used + self.loggerBaseName = self.baseFilename + filepath = Path(self.baseFilename) + self.baseFilename = f"{filepath.parent}/{filepath.stem}-{today}{filepath.suffix}" + + self.stream = self._open() - def doRollover(self): + def namer(self, default_name): + """ + namer called by rotation_filename in TimedRotatingFileHandler.doRollover + + For us to replicate rotatelogs, we need to add the time_str to the + filename before the .log suffix + """ + # get the time from default_name + today = datetime.now().strftime(self.suffix).replace('-', '') + time_str = today.replace('-', '') + log_path = Path(self.loggerBaseName) + logPath = f"{log_path.parent}/{log_path.stem}-{time_str}{log_path.suffix}" + return logPath + + def rotator(self, src, dest): """ - _doRollover_ + rotator is called by the self.rotate - Rotate the log file and add the date between the log name - and its extension, e.g.: - reqmgr2.log becomes reqmgr2-20170815.log + Gets the new date, then sets the proper self.baseFilename + We don't use the default behavior of the current file being renamed """ - self.stream.close() - # replace yesterday's date by today - yesterdayStr = (date.today() - timedelta(1)).strftime("%Y%m%d") - todayStr = date.today().strftime("%Y%m%d") - self.baseFilename = self.baseFilename.replace(yesterdayStr, todayStr) - self.stream = open(self.baseFilename, 'w', encoding='utf-8') - self.rolloverAt = self.rolloverAt + self.interval + today = datetime.now().strftime(self.suffix).replace('-', '') + filepath = Path(self.loggerBaseName) + self.baseFilename = f"{filepath.parent}/{filepath.stem}-{today}{filepath.suffix}" class CouchHandler(logging.handlers.HTTPHandler): From 6647c4e42300a090d5952c08472d5305fb837525 Mon Sep 17 00:00:00 2001 From: Dennis Lee Date: Tue, 9 Apr 2024 15:52:44 -0500 Subject: [PATCH 2/2] Added test for WMCore.WMLogging.MyTimedRotatingFileHandler Updated WMLogging test to test a quick log rotation Fix some pylint errors in WMLogging_t.py Replace existing log rotation test --- test/python/WMCore_t/WMLogging_t.py | 92 ++++++++++++++++++++++++++--- 1 file changed, 83 insertions(+), 9 deletions(-) diff --git a/test/python/WMCore_t/WMLogging_t.py b/test/python/WMCore_t/WMLogging_t.py index bd40f31ee6..d07538bf1e 100644 --- a/test/python/WMCore_t/WMLogging_t.py +++ b/test/python/WMCore_t/WMLogging_t.py @@ -1,19 +1,30 @@ #!/usr/bin/env python # encoding: utf-8 +""" +Test case for WMLogging module +""" from builtins import range +from datetime import date import logging -import unittest import os -from WMCore.WMLogging import CouchHandler +from pathlib import Path +import unittest +import time + +from WMCore.WMLogging import CouchHandler, WMTimedRotatingFileHandler from WMCore.Database.CMSCouch import CouchServer + class WMLoggingTest(unittest.TestCase): + """ + Unit tests for WMLogging module. + """ def setUp(self): # Make an instance of the server self.server = CouchServer(os.getenv("COUCHURL", 'http://admin:password@localhost:5984')) testname = self.id().split('.')[-1] # Create a database, drop an existing one first - self.dbname = 'cmscouch_unittest_%s' % testname.lower() + self.dbname = f'cmscouch_unittest_{testname.lower()}' if self.dbname in self.server.listDatabases(): self.server.deleteDatabase(self.dbname) @@ -25,23 +36,86 @@ def tearDown(self): # This used to test self._exc_info to only run on success. Broke in 2.7. Removed. self.server.deleteDatabase(self.dbname) + # delete testRotate directory + logPath = Path('testRotate') + for _, _, filenames in os.walk(logPath): + for filename in filenames: + os.remove(logPath.joinpath(filename)) + pass + def testLog(self): """ Write ten log messages to the database at three different levels """ - my_logger = logging.getLogger('MyLogger') - my_logger.setLevel(logging.DEBUG) + myLogger = logging.getLogger('MyLogger') + myLogger.setLevel(logging.DEBUG) handler = CouchHandler(self.server.url, self.dbname) formatter = logging.Formatter('%(message)s') handler.setFormatter(formatter) - my_logger.addHandler(handler) + myLogger.addHandler(handler) for _ in range(10): - my_logger.debug('This is probably all noise.') - my_logger.info('Jackdaws love my big sphinx of quartz.') - my_logger.error('HOLLY CRAP!') + myLogger.debug('This is probably all noise.') + myLogger.info('Jackdaws love my big sphinx of quartz.') + myLogger.error('HOLLY CRAP!') logs = self.db.allDocs()['rows'] self.assertEqual(30, len(logs)) + def testWMRotateLogs(self): + """ + Test to make sure a date is in or will be added to the logName + """ + todayStr = date.today().strftime("%Y%m%d") + defaultToday = date.today().strftime("%Y-%m-%d") + + myLogger = logging.getLogger('MyLogger2') + myLogger.setLevel(logging.DEBUG) + logPath = Path('testRotate') + logPath.mkdir(parents=True, exist_ok=True) + logName = logPath.joinpath("mylog.log") + formatter = logging.Formatter('%(message)s') + handler = WMTimedRotatingFileHandler(logName, + when='S', + interval=1, + backupCount=10) + handler.setFormatter(formatter) + myLogger.addHandler(handler) + myLogger.info('log 1') + time.sleep(2) + myLogger.info('log 2') + + p = Path('testRotate') + files = list(p.iterdir()) + self.assertEqual(len(files), 2) + for idx, log in enumerate(sorted(files)): + with open(log, 'r', encoding='utf-8') as f: + lines = f.readlines() + if idx == 0: + self.assertEqual(lines[0].strip(), "log 1") + else: + self.assertEqual(lines[0].strip(), "log 2") + self.assertNotIn(defaultToday, log.name) + self.assertIn(todayStr, log.name) + + # test backupCount + time.sleep(2) + for i in range(3, 11): + myLogger.info('log %s', i) + time.sleep(2) + files = list(p.iterdir()) + self.assertEqual(len(files), 10) + + myLogger.info('log %s', 11) + files = list(p.iterdir()) + self.assertEqual(len(files), 11) + + time.sleep(2) + myLogger.info('log %s', 12) + time.sleep(2) + files = list(p.iterdir()) + self.assertEqual(len(files), 11) + + + if __name__ == "__main__": unittest.main()