Update logger.py to use new Twisted log api. No change in evennia-side usage

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

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.

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.

evennia/server/tests/testrunner.py

@@ -16,20 +16,27 @@ class EvenniaTestSuiteRunner(DiscoverRunner):
      avoid running the large number of tests defined by Django
 
     """
-
+    def setup_test_environment(self, **kwargs):
-    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.
-        """
         # 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)

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
 
 

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}