diff --git a/src/python/WMCore/REST/Main.py b/src/python/WMCore/REST/Main.py index fd0ad49b9e..9120b3efec 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,6 +17,7 @@ from future import standard_library standard_library.install_aliases() +from datetime import date import errno import logging import os @@ -35,19 +40,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 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" @@ -89,7 +96,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) @@ -221,7 +229,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. @@ -311,7 +319,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. @@ -468,7 +477,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) @@ -568,18 +578,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: @@ -614,10 +621,10 @@ def main(): # 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 rotating log + 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 1ff66890e3..e56e127848 100644 --- a/src/python/WMCore/WMLogging.py +++ b/src/python/WMCore/WMLogging.py @@ -8,13 +8,15 @@ import codecs from datetime import date, timedelta from logging.handlers import HTTPHandler, RotatingFileHandler, TimedRotatingFileHandler +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): """ @@ -23,7 +25,8 @@ def sqldebug(msg): """ logging.log(logging.SQLDEBUG, msg) -def setupRotatingHandler(fileName, maxBytes = 200000000, backupCount = 3): + +def setupRotatingHandler(fileName, maxBytes=200000000, backupCount=3): """ _setupRotatingHandler_ @@ -31,17 +34,17 @@ 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 = MyTimedRotatingFileHandler(logFile, duration, backupCount=10) else: - handler = TimedRotatingFileHandler(logFile, duration, backupCount = 10) + handler = TimedRotatingFileHandler(logFile, duration, backupCount=10) formatter = logging.Formatter("%(asctime)s:%(levelname)s:%(module)s:%(message)s") handler.setFormatter(formatter) logger.addHandler(handler) @@ -62,7 +65,18 @@ class MyTimedRotatingFileHandler(TimedRotatingFileHandler): https://stackoverflow.com/questions/338450/timedrotatingfilehandler-changing-file-name """ def __init__(self, logName, interval, backupCount): - super(MyTimedRotatingFileHandler, self).__init__(logName, when=interval, + """ + Initializes MyTimedRotatingFileHandler + + If logName doesn't contain a date, the day of runtime will be added + """ + logPath = Path(logName) + todayStr = date.today().strftime("%Y%m%d") + + if todayStr not in logName: + logPath = logPath.parent.joinpath(f"{logPath.stem}-{todayStr}{logPath.suffix}") + + super(MyTimedRotatingFileHandler, self).__init__(logPath, when=interval, backupCount=backupCount) def doRollover(self): @@ -71,7 +85,7 @@ def doRollover(self): Rotate the log file and add the date between the log name and its extension, e.g.: - reqmgr2.log becomes reqmgr2-20170815.log + reqmgr2-20170814.log becomes reqmgr2-20170815.log """ self.stream.close() # replace yesterday's date by today diff --git a/test/python/WMCore_t/WMLogging_t.py b/test/python/WMCore_t/WMLogging_t.py index bd40f31ee6..08e9b67a0d 100644 --- a/test/python/WMCore_t/WMLogging_t.py +++ b/test/python/WMCore_t/WMLogging_t.py @@ -1,19 +1,28 @@ #!/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 WMCore.WMLogging import CouchHandler, MyTimedRotatingFileHandler 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 +34,37 @@ 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) + def testRotatingLogHandler(self): + """ + Test to make sure a date is in or will be added to the logName + """ + todayStr = date.today().strftime("%Y%m%d") + logName = "mylog.log" + handler = MyTimedRotatingFileHandler(logName, 'midnight', backupCount=10) + self.assertIn(todayStr, handler.baseFilename) + + logName = f"mylog-{todayStr}.log" + handler = MyTimedRotatingFileHandler(logName, 'midnight', backupCount=10) + self.assertIn(todayStr, handler.baseFilename) + 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)) + if __name__ == "__main__": unittest.main()