From 17f0ce8245179782869ee47ce752b4f511d17325 Mon Sep 17 00:00:00 2001 From: Griatch Date: Sun, 13 Feb 2022 21:14:33 +0100 Subject: [PATCH] Update logger.py to use new Twisted log api. No change in evennia-side usage --- CHANGELOG.md | 2 + evennia/server/portal/portal.py | 9 +- evennia/server/server.py | 8 +- evennia/server/tests/testrunner.py | 25 +- evennia/utils/logger.py | 391 +++++++++++++++-------------- evennia/utils/test_resources.py | 5 +- 6 files changed, 230 insertions(+), 210 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 50319103bc..f92f1c6f18 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -153,6 +153,8 @@ Up requirements to Django 4.0+, Twisted 22+, Python 3.9 or 3.10 decouple structures from database without needing separate import. - Add `run_in_main_thread` as a helper for those wanting to code server code from a web view. +- Update `evennia.utils.logger` to use Twisted's new logging API. No change in Evennia API + except more standard aliases logger.error/info/exception/debug etc can now be used. ## Evennia 0.9.5 diff --git a/evennia/server/portal/portal.py b/evennia/server/portal/portal.py index 67b2b96c8d..b8048185e2 100644 --- a/evennia/server/portal/portal.py +++ b/evennia/server/portal/portal.py @@ -15,7 +15,7 @@ from os.path import dirname, abspath from twisted.application import internet, service from twisted.internet.task import LoopingCall from twisted.internet import protocol, reactor -from twisted.python.log import ILogObserver +from twisted.logger import globalLogPublisher import django @@ -245,16 +245,17 @@ class Portal(object): # what to execute from. application = service.Application("Portal") -# custom logging -if "--nodaemon" not in sys.argv: +if ("--nodaemon" not in sys.argv + and not hasattr(settings, "_TEST_ENVIRONMENT") and settings._TEST_ENVIRONMENT): + # custom logging logfile = logger.WeeklyLogFile( os.path.basename(settings.PORTAL_LOG_FILE), os.path.dirname(settings.PORTAL_LOG_FILE), day_rotation=settings.PORTAL_LOG_DAY_ROTATION, max_size=settings.PORTAL_LOG_MAX_SIZE, ) - application.setComponent(ILogObserver, logger.PortalLogObserver(logfile).emit) + globalLogPublisher.addObserver(logger.GetPortalLogObserver()(logfile)) # The main Portal server program. This sets up the database # and is where we store all the other services. diff --git a/evennia/server/server.py b/evennia/server/server.py index 771ded506a..b20549503e 100644 --- a/evennia/server/server.py +++ b/evennia/server/server.py @@ -16,7 +16,7 @@ from twisted.web import static from twisted.application import internet, service from twisted.internet import reactor, defer from twisted.internet.task import LoopingCall -from twisted.python.log import ILogObserver +from twisted.logger import globalLogPublisher import django @@ -647,7 +647,8 @@ except OperationalError: # what to execute from. application = service.Application("Evennia") -if "--nodaemon" not in sys.argv: +if ("--nodaemon" not in sys.argv + and not hasattr(settings, "_TEST_ENVIRONMENT") and settings._TEST_ENVIRONMENT): # custom logging, but only if we are not running in interactive mode logfile = logger.WeeklyLogFile( os.path.basename(settings.SERVER_LOG_FILE), @@ -655,7 +656,8 @@ if "--nodaemon" not in sys.argv: day_rotation=settings.SERVER_LOG_DAY_ROTATION, max_size=settings.SERVER_LOG_MAX_SIZE, ) - application.setComponent(ILogObserver, logger.ServerLogObserver(logfile).emit) + globalLogPublisher.addObserver(logger.GetServerLogObserver()(logfile)) + # The main evennia server program. This sets up the database # and is where we store all the other services. diff --git a/evennia/server/tests/testrunner.py b/evennia/server/tests/testrunner.py index 99148a6ea8..9199164c58 100644 --- a/evennia/server/tests/testrunner.py +++ b/evennia/server/tests/testrunner.py @@ -16,20 +16,27 @@ class EvenniaTestSuiteRunner(DiscoverRunner): avoid running the large number of tests defined by Django """ - - def build_suite(self, test_labels, extra_tests=None, **kwargs): - """ - Build a test suite for Evennia. test_labels is a list of apps to test. - If not given, a subset of settings.INSTALLED_APPS will be used. - """ + def setup_test_environment(self, **kwargs): # the portal looping call starts before the unit-test suite so we # can't mock it - instead we stop it before starting the test - otherwise # we'd get unclean reactor errors across test boundaries. from evennia.server.portal.portal import PORTAL - PORTAL.maintenance_task.stop() + # initialize evennia itself import evennia - evennia._init() - return super().build_suite(test_labels, extra_tests=extra_tests, **kwargs) + + from django.conf import settings + + # set testing flag while suite runs + settings._TEST_ENVIRONMENT = True + super().setup_test_environment(**kwargs) + + def teardown_test_environment(self, **kwargs): + + # remove testing flag after suite has run + from django.conf import settings + settings._TEST_ENVIRONMENT = False + + super().teardown_test_environment(**kwargs) diff --git a/evennia/utils/logger.py b/evennia/utils/logger.py index 5c40c33d5b..18d8d0047c 100644 --- a/evennia/utils/logger.py +++ b/evennia/utils/logger.py @@ -18,16 +18,213 @@ import os import time from datetime import datetime from traceback import format_exc -from twisted.python import log, logfile +from twisted import logger as twisted_logger +from twisted.python import logfile from twisted.python import util as twisted_util from twisted.internet.threads import deferToThread +log = twisted_logger.Logger() _LOGDIR = None _LOG_ROTATE_SIZE = None _TIMEZONE = None _CHANNEL_LOG_NUM_TAIL_LINES = None +_TIME_FORMAT = "%Y-%m-%d %H:%M:%S" + + +def _log(msg, logfunc, prefix="", **kwargs): + try: + msg = str(msg) + except Exception as err: + msg = str(e) + if kwargs: + logfunc(msg, **kwargs) + else: + try: + for line in msg.splitlines(): + logfunc("{line}", prefix=prefix, line=line) + except Exception as err: + log.error("Log failure: {err}", err=err) + + +# log call functions (each has legacy aliases) + +def log_info(msg, **kwargs): + """ + Logs any generic debugging/informative info that should appear in the log. + + Args: + msg: (string) The message to be logged. + **kwargs: If given, The `msg` is parsed as a format string with `{..}` + formatting markers that should match the keywords. + + """ + _log(msg, log.info, **kwargs) + +info = log_info +log_infomsg = log_info +log_msg = log_info + + +def log_warn(msg, **kwargs): + """ + Logs warnings that aren't critical but should be noted. + + Args: + msg (str): The message to be logged. + **kwargs: If given, The `msg` is parsed as a format string with `{..}` + formatting markers that should match the keywords. + + """ + _log(msg, log.warn, **kwargs) + +warn = log_warn +warning = log_warn +log_warnmsg = log_warn + + +def log_err(msg, **kwargs): + """ + Logs an error message to the server log. + + Args: + msg (str): The message to be logged. + **kwargs: If given, The `msg` is parsed as a format string with `{..}` + formatting markers that should match the keywords. + + """ + _log(msg, log.error, **kwargs) + + +error = log_err +err = log_err +log_errmsg = log_err + + +def log_trace(msg=None, **kwargs): + """ + Log a traceback to the log. This should be called from within an + exception. + + Args: + msg (str, optional): Adds an extra line with added info + at the end of the traceback in the log. + **kwargs: If given, The `msg` is parsed as a format string with `{..}` + formatting markers that should match the keywords. + + """ + tracestring = format_exc() + if tracestring: + _log(tracestring, log.error, prefix="!!", **kwargs) + if msg: + _log(msg, log.error, prefix="!!", **kwargs) + +log_tracemsg = log_trace +exception = log_trace +critical = log_trace +trace = log_trace + + +def log_dep(msg, **kwargs): + """ + Prints a deprecation message. + + Args: + msg (str): The deprecation message to log. + **kwargs: If given, The `msg` is parsed as a format string with `{..}` + formatting markers that should match the keywords. + + """ + _log(msg, log.warn, prefix="DP", **kwargs) + + +dep = log_dep +deprecated = log_dep +log_depmsg = log_dep + + +def log_sec(msg, **kwargs): + """ + Prints a security-related message. + + Args: + msg (str): The security message to log. + **kwargs: If given, The `msg` is parsed as a format string with `{..}` + formatting markers that should match the keywords. + + """ + _log(msg, log.info, prefix="SS", **kwargs) + +sec = log_sec +security = log_sec +log_secmsg = log_sec + + +def log_server(msg, **kwargs): + """ + This is for the Portal to log captured Server stdout messages (it's + usually only used during startup, before Server log is open) + + Args: + msg (str): The message to be logged. + **kwargs: If given, The `msg` is parsed as a format string with `{..}` + formatting markers that should match the keywords. + """ + _log(msg, log.info, prefix="Server", **kwargs) + + + +class GetLogObserver: + """ + Sets up how the system logs are formatted. + + """ + component_prefix = "" + event_levels = { + twisted_logger.LogLevel.debug: "??", + twisted_logger.LogLevel.info: "..", + twisted_logger.LogLevel.warn: "WW", + twisted_logger.LogLevel.error: "EE", + twisted_logger.LogLevel.critical: "!!", + } + + def format_log_event(self, event): + """ + By assigning log_system here, we skip the spammy display of namespace/level + in the default log output. + + [component_prefix] [date] [system/lvl] [msg] + + """ + # setting log_system fills the [..] block after the time stamp + prefix = event.get("prefix", "") + if prefix: + event["log_system"] = prefix + else: + lvl = event.get("log_level", twisted_logger.LogLevel.info) + event["log_system"] = self.event_levels.get(lvl, "-") + event["log_format"] = str(event.get("log_format", "")) + component_prefix = self.component_prefix or "" + + return component_prefix + twisted_logger.formatEventAsClassicLogText( + event, + formatTime=lambda e: twisted_logger.formatTime(e, _TIME_FORMAT) + ) + + def __call__(self, outfile): + return twisted_logger.FileLogObserver(outfile, self.format_log_event) + + +# Called by server/portal on startup + +class GetPortalLogObserver(GetLogObserver): + component_prefix = "|Portal| " + +class GetServerLogObserver(GetLogObserver): + component_prefix = "" + + # logging overrides @@ -37,7 +234,7 @@ def timeformat(when=None): This helper function will format the current time in the same way as the twisted logger does, including time zone info. Only difference from official logger is that we only use two digits - for the year and don't show timezone for CET times. + for the year and don't show timezone for GMT times. Args: when (int, optional): This is a time in POSIX seconds on the form @@ -155,196 +352,6 @@ class WeeklyLogFile(logfile.DailyLogFile): self.lastDate = max(self.lastDate, self.toDate()) self.size += len(data) - -class PortalLogObserver(log.FileLogObserver): - """ - Reformat logging - - """ - - timeFormat = None - prefix = " |Portal| " - - def emit(self, eventDict): - """ - Copied from Twisted parent, to change logging output - - """ - text = log.textFromEventDict(eventDict) - if text is None: - return - - # timeStr = self.formatTime(eventDict["time"]) - timeStr = timeformat(eventDict["time"]) - fmtDict = {"text": text.replace("\n", "\n\t")} - - msgStr = log._safeFormat("%(text)s\n", fmtDict) - - twisted_util.untilConcludes(self.write, timeStr + "%s" % self.prefix + msgStr) - twisted_util.untilConcludes(self.flush) - - -class ServerLogObserver(PortalLogObserver): - prefix = " " - - -def log_msg(msg): - """ - Wrapper around log.msg call to catch any exceptions that might - occur in logging. If an exception is raised, we'll print to - stdout instead. - - Args: - msg: The message that was passed to log.msg - - """ - try: - log.msg(msg) - except Exception: - print("Exception raised while writing message to log. Original message: %s" % msg) - - -def log_trace(errmsg=None): - """ - Log a traceback to the log. This should be called from within an - exception. - - Args: - errmsg (str, optional): Adds an extra line with added info - at the end of the traceback in the log. - - """ - tracestring = format_exc() - try: - if tracestring: - for line in tracestring.splitlines(): - log.msg("[::] %s" % line) - if errmsg: - try: - errmsg = str(errmsg) - except Exception as e: - errmsg = str(e) - for line in errmsg.splitlines(): - log_msg("[EE] %s" % line) - except Exception: - log_msg("[EE] %s" % errmsg) - - -log_tracemsg = log_trace - - -def log_err(errmsg): - """ - Prints/logs an error message to the server log. - - Args: - errmsg (str): The message to be logged. - - """ - try: - errmsg = str(errmsg) - except Exception as e: - errmsg = str(e) - for line in errmsg.splitlines(): - log_msg("[EE] %s" % line) - - # log.err('ERROR: %s' % (errmsg,)) - - -log_errmsg = log_err - - -def log_server(servermsg): - """ - This is for the Portal to log captured Server stdout messages (it's - usually only used during startup, before Server log is open) - - """ - try: - servermsg = str(servermsg) - except Exception as e: - servermsg = str(e) - for line in servermsg.splitlines(): - log_msg("[Server] %s" % line) - - -def log_warn(warnmsg): - """ - Prints/logs any warnings that aren't critical but should be noted. - - Args: - warnmsg (str): The message to be logged. - - """ - try: - warnmsg = str(warnmsg) - except Exception as e: - warnmsg = str(e) - for line in warnmsg.splitlines(): - log_msg("[WW] %s" % line) - - # log.msg('WARNING: %s' % (warnmsg,)) - - -log_warnmsg = log_warn - - -def log_info(infomsg): - """ - Prints any generic debugging/informative info that should appear in the log. - - infomsg: (string) The message to be logged. - - """ - try: - infomsg = str(infomsg) - except Exception as e: - infomsg = str(e) - for line in infomsg.splitlines(): - log_msg("[..] %s" % line) - - -log_infomsg = log_info - - -def log_dep(depmsg): - """ - Prints a deprecation message. - - Args: - depmsg (str): The deprecation message to log. - - """ - try: - depmsg = str(depmsg) - except Exception as e: - depmsg = str(e) - for line in depmsg.splitlines(): - log_msg("[DP] %s" % line) - - -log_depmsg = log_dep - - -def log_sec(secmsg): - """ - Prints a security-related message. - - Args: - secmsg (str): The security message to log. - - """ - try: - secmsg = str(secmsg) - except Exception as e: - secmsg = str(e) - for line in secmsg.splitlines(): - log_msg("[SS] %s" % line) - - -log_secmsg = log_sec - - # Arbitrary file logger diff --git a/evennia/utils/test_resources.py b/evennia/utils/test_resources.py index 58beb138c9..65b62ea633 100644 --- a/evennia/utils/test_resources.py +++ b/evennia/utils/test_resources.py @@ -96,8 +96,9 @@ DEFAULT_SETTING_RESETS = dict( "evennia.game_template.server.conf.prototypefuncs", ], BASE_GUEST_TYPECLASS="evennia.accounts.accounts.DefaultGuest", - # a special flag; test with settings._TEST_ENVIRONMENT to see if code runs in a test - _TEST_ENVIRONMENT=True, + + # a special setting boolean _TEST_ENVIRONMENT is set by the test runner + # while the test suite is running. ) DEFAULT_SETTINGS = {**all_from_module(settings_default), **DEFAULT_SETTING_RESETS}