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): 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()