Low-lift solution to move to stdlib logging (#611)

* low-lift solution move to stdlib

* reverts

* more directly match old behaviour

* change err to warn

* one msg log for root warning

* remove unnecessary logging code

* green log for all non-err handled reqs

* logout is not a warning

* Support stdlib logging `extra` parameter data forwarding

* spacing

* accurate comment

* remove legacy chatlog logging to file

* simplify

* file logging without colors (for the sanity of humanity)

* move debug query logging

* sql query useful logs in stdout

* backwards compat for .data/logs/chat.log

* le fix

* prefer const

* Use `logging.yaml.example`

* update docs for logging.yaml.example

* Bump minor version to 5.2.0

Author: cmyui

Diff for: .env.example

@@ -63,6 +63,8 @@ DISCORD_AUDIT_LOG_WEBHOOK=
 # for debugging & development purposes.
 AUTOMATICALLY_REPORT_PROBLEMS=False
 
+LOG_WITH_COLORS=False
+
 # XXX: Uncomment this if you have downloaded the database from maxmind.
 # Change the path to the .mmdb file you downloaded, uncomment here and in docker-compose.yml
 # You can download the database here: https://dev.maxmind.com/geoip/geolite2-free-geolocation-data

Diff for: .github/docs/wiki/Setting-up.md

@@ -17,15 +17,23 @@ sudo apt install -y docker docker-compose
 ## configuring bancho.py
 
 all configuration for the osu! server (bancho.py) itself can be done from the
-`.env` file. we provide an example `.env.example` file which you can use as a base.
+`.env` and `logging.yaml` files. we will provide example files for each, which
+you can use as a base and modify as you'd like.
 
 ```sh
 # create a configuration file from the sample provided
 cp .env.example .env
 
+# create a logging configuration file from the sample provided
+cp logging.yaml.example logging.yaml
+
 # configure the application to your needs
 # this is required to move onto the next steps
 nano .env
+
+# you can additionally configure the logging if you'd like,
+# but the default should work fine for most users.
+nano logging.yaml
 ```
 
 ## configuring a reverse proxy (we'll use nginx)

Diff for: .github/docs/wiki/locale/de-DE/Setting-up-de-DE.md

@@ -17,15 +17,23 @@ sudo apt install -y docker docker-compose
 ## configuring bancho.py
 
 all configuration for the osu! server (bancho.py) itself can be done from the
-`.env` file. we provide an example `.env.example` file which you can use as a base.
+`.env` and `logging.yaml` files. we will provide example files for each, which
+you can use as a base and modify as you'd like.
 
 ```sh
 # create a configuration file from the sample provided
 cp .env.example .env
 
+# create a logging configuration file from the sample provided
+cp logging.yaml.example logging.yaml
+
 # configure the application to your needs
 # this is required to move onto the next steps
 nano .env
+
+# you can additionally configure the logging if you'd like,
+# but the default should work fine for most users.
+nano logging.yaml
 ```
 
 ## configuring a reverse proxy (we'll use nginx)

Diff for: .github/docs/wiki/locale/zh-CN/Setting-up-zh-CN.md

@@ -17,15 +17,23 @@ sudo apt install -y docker docker-compose
 ## configuring bancho.py
 
 all configuration for the osu! server (bancho.py) itself can be done from the
-`.env` file. we provide an example `.env.example` file which you can use as a base.
+`.env` and `logging.yaml` files. we will provide example files for each, which
+you can use as a base and modify as you'd like.
 
 ```sh
 # create a configuration file from the sample provided
 cp .env.example .env
 
+# create a logging configuration file from the sample provided
+cp logging.yaml.example logging.yaml
+
 # configure the application to your needs
 # this is required to move onto the next steps
 nano .env
+
+# you can additionally configure the logging if you'd like,
+# but the default should work fine for most users.
+nano logging.yaml
 ```
 
 ## configuring a reverse proxy (we'll use nginx)

Diff for: .github/workflows/test.yaml

@@ -18,6 +18,7 @@ env:
   APP_HOST: "0.0.0.0"
   APP_PORT: "10000"
   AUTOMATICALLY_REPORT_PROBLEMS: "False"
+  LOG_WITH_COLORS: "False"
   COMMAND_PREFIX: "!"
   DATA_DIRECTORY: "not relevant"
   DB_HOST: "mysql"

Diff for: .gitignore

@@ -17,3 +17,5 @@ tools/cf_records.txt
 /.redis-data/
 poetry.toml
 .coverage
+logging.yaml
+logs.log

Diff for: app/adapters/database.py

@@ -10,6 +10,7 @@
 from sqlalchemy.sql.expression import ClauseElement
 
 from app import settings
+from app.logging import log
 
 
 class MySQLDialect(MySQLDialect_mysqldb):
@@ -38,8 +39,6 @@ def _compile(self, clause_element: ClauseElement) -> tuple[str, MySQLParams]:
             dialect=DIALECT,
             compile_kwargs={"render_postcompile": True},
         )
-        if settings.DEBUG:
-            print(str(compiled), compiled.params)
         return str(compiled), compiled.params
 
     async def fetch_one(
@@ -51,6 +50,12 @@ async def fetch_one(
             query, params = self._compile(query)
 
         row = await self._database.fetch_one(query, params)
+        if settings.DEBUG:
+            log(
+                f"Executed SQL query: {query} {params}",
+                extra={"query": query, "params": params},
+            )
+
         return dict(row._mapping) if row is not None else None
 
     async def fetch_all(

Diff for: app/api/domains/cho.py

@@ -3,6 +3,7 @@
 from __future__ import annotations
 
 import asyncio
+import logging
 import re
 import struct
 import time
@@ -13,6 +14,7 @@
 from pathlib import Path
 from typing import Literal
 from typing import TypedDict
+from zoneinfo import ZoneInfo
 
 import bcrypt
 import databases.core
@@ -37,6 +39,7 @@
 from app.constants.privileges import ClientPrivileges
 from app.constants.privileges import Privileges
 from app.logging import Ansi
+from app.logging import get_timestamp
 from app.logging import log
 from app.logging import magnitude_fmt_time
 from app.objects.beatmap import Beatmap
@@ -69,6 +72,7 @@
 OSU_API_V2_CHANGELOG_URL = "https://osu.ppy.sh/api/v2/changelog"
 
 BEATMAPS_PATH = Path.cwd() / ".data/osu"
+DISK_CHAT_LOG_FILE = ".data/logs/chat.log"
 
 BASE_DOMAIN = app.settings.DOMAIN
 
@@ -424,7 +428,13 @@ async def handle(self, player: Player) -> None:
             t_chan.send(msg, sender=player)
 
         player.update_latest_activity_soon()
-        log(f"{player} @ {t_chan}: {msg}", Ansi.LCYAN, file=".data/logs/chat.log")
+
+        log(f"{player} @ {t_chan}: {msg}", Ansi.LCYAN)
+
+        with open(DISK_CHAT_LOG_FILE, "a+") as f:
+            f.write(
+                f"[{get_timestamp(full=True, tz=ZoneInfo('GMT'))}] {player} @ {t_chan}: {msg}\n",
+            )
 
 
 @register(ClientPackets.LOGOUT, restricted=True)
@@ -1298,7 +1308,12 @@ async def handle(self, player: Player) -> None:
                     player.send(resp_msg, sender=target)
 
         player.update_latest_activity_soon()
-        log(f"{player} @ {target}: {msg}", Ansi.LCYAN, file=".data/logs/chat.log")
+
+        log(f"{player} @ {target}: {msg}", Ansi.LCYAN)
+        with open(DISK_CHAT_LOG_FILE, "a+") as f:
+            f.write(
+                f"[{get_timestamp(full=True, tz=ZoneInfo('GMT'))}] {player} @ {target}: {msg}\n",
+            )
 
 
 @register(ClientPackets.PART_LOBBY)

Diff for: app/api/domains/osu.py

@@ -51,7 +51,6 @@
 from app.constants.privileges import Privileges
 from app.logging import Ansi
 from app.logging import log
-from app.logging import printc
 from app.objects import models
 from app.objects.beatmap import Beatmap
 from app.objects.beatmap import RankedStatus

Diff for: app/api/init_api.py

@@ -79,7 +79,7 @@ async def lifespan(asgi_app: BanchoAPI) -> AsyncIterator[None]:
     if app.utils.is_running_as_admin():
         log(
             "Running the server with root privileges is not recommended.",
-            Ansi.LRED,
+            Ansi.LYELLOW,
         )
 
     await app.state.services.database.connect()

Diff for: app/api/middlewares.py

@@ -10,7 +10,6 @@
 from app.logging import Ansi
 from app.logging import log
 from app.logging import magnitude_fmt_time
-from app.logging import printc
 
 
 class MetricsMiddleware(BaseHTTPMiddleware):
@@ -25,16 +24,14 @@ async def dispatch(
 
         time_elapsed = end_time - start_time
 
-        col = (
-            Ansi.LGREEN
-            if 200 <= response.status_code < 300
-            else Ansi.LYELLOW if 300 <= response.status_code < 400 else Ansi.LRED
-        )
+        col = Ansi.LGREEN if response.status_code < 400 else Ansi.LRED
 
         url = f"{request.headers['host']}{request['path']}"
 
-        log(f"[{request.method}] {response.status_code} {url}", col, end=" | ")
-        printc(f"Request took: {magnitude_fmt_time(time_elapsed)}", Ansi.LBLUE)
+        log(
+            f"[{request.method}] {response.status_code} {url}{Ansi.RESET!r} | {Ansi.LBLUE!r}Request took: {magnitude_fmt_time(time_elapsed)}",
+            col,
+        )
 
         response.headers["process-time"] = str(round(time_elapsed) / 1e6)
         return response

Diff for: app/logging.py

@@ -1,10 +1,22 @@
 from __future__ import annotations
 
-import colorsys
 import datetime
+import logging.config
+import re
+from collections.abc import Mapping
 from enum import IntEnum
 from zoneinfo import ZoneInfo
 
+import yaml
+
+from app import settings
+
+
+def configure_logging() -> None:
+    with open("logging.yaml") as f:
+        config = yaml.safe_load(f.read())
+        logging.config.dictConfig(config)
+
 
 class Ansi(IntEnum):
     # Default colours
@@ -33,105 +45,49 @@ def __repr__(self) -> str:
         return f"\x1b[{self.value}m"
 
 
-class RGB:
-    def __init__(self, *args: int) -> None:
-        largs = len(args)
-
-        if largs == 3:
-            # r, g, b passed.
-            self.r, self.g, self.b = args
-        elif largs == 1:
-            # passed as single argument
-            rgb = args[0]
-            self.b = rgb & 0xFF
-            self.g = (rgb >> 8) & 0xFF
-            self.r = (rgb >> 16) & 0xFF
-        else:
-            raise ValueError("Incorrect params for RGB.")
-
-    def __repr__(self) -> str:
-        return f"\x1b[38;2;{self.r};{self.g};{self.b}m"
-
-
-class _Rainbow: ...
-
-
-Rainbow = _Rainbow()
-
-Colour_Types = Ansi | RGB | _Rainbow
-
-
 def get_timestamp(full: bool = False, tz: ZoneInfo | None = None) -> str:
     fmt = "%d/%m/%Y %I:%M:%S%p" if full else "%I:%M:%S%p"
     return f"{datetime.datetime.now(tz=tz):{fmt}}"
 
 
-# TODO: better solution than this; this at least requires the
-# iana/tzinfo database to be installed, meaning it's limited.
-_log_tz = ZoneInfo("GMT")  # default
+ANSI_ESCAPE_REGEX = re.compile(r"(\x9B|\x1B\[)[0-?]*[ -\/]*[@-~]")
 
 
-def set_timezone(tz: ZoneInfo) -> None:
-    global _log_tz
-    _log_tz = tz
+def escape_ansi(line: str) -> str:
+    return ANSI_ESCAPE_REGEX.sub("", line)
 
 
-def printc(msg: str, col: Colour_Types, end: str = "\n") -> None:
-    """Print a string, in a specified ansi colour."""
-    print(f"{col!r}{msg}{Ansi.RESET!r}", end=end)
+ROOT_LOGGER = logging.getLogger()
 
 
 def log(
     msg: str,
-    col: Colour_Types | None = None,
-    file: str | None = None,
-    end: str = "\n",
+    start_color: Ansi | None = None,
+    extra: Mapping[str, object] | None = None,
 ) -> None:
     """\
-    Print a string, in a specified ansi colour with timestamp.
-
-    Allows for the functionality to write to a file as
-    well by passing the filepath with the `file` parameter.
+    A thin wrapper around the stdlib logging module to handle mostly
+    backwards-compatibility for colours during our migration to the
+    standard library logging module.
     """
 
-    ts_short = get_timestamp(full=False, tz=_log_tz)
-
-    if col:
-        if col is Rainbow:
-            print(f"{Ansi.GRAY!r}[{ts_short}] {_fmt_rainbow(msg, 2/3)}", end=end)
-            print(f"{Ansi.GRAY!r}[{ts_short}] {_fmt_rainbow(msg, 2/3)}", end=end)
-        else:
-            # normal colour
-            print(f"{Ansi.GRAY!r}[{ts_short}] {col!r}{msg}{Ansi.RESET!r}", end=end)
+    # TODO: decouple colors from the base logging function; move it to
+    # be a formatter-specific concern such that we can log without color.
+    if start_color is Ansi.LYELLOW:
+        log_level = logging.WARNING
+    elif start_color is Ansi.LRED:
+        log_level = logging.ERROR
     else:
-        print(f"{Ansi.GRAY!r}[{ts_short}]{Ansi.RESET!r} {msg}", end=end)
-
-    if file:
-        # log simple ascii output to file.
-        with open(file, "a+") as f:
-            f.write(f"[{get_timestamp(full=True, tz=_log_tz)}] {msg}\n")
-
-
-def rainbow_color_stops(
-    n: int = 10,
-    lum: float = 0.5,
-    end: float = 2 / 3,
-) -> list[tuple[float, float, float]]:
-    return [
-        (r * 255, g * 255, b * 255)
-        for r, g, b in [
-            colorsys.hls_to_rgb(end * i / (n - 1), lum, 1) for i in range(n)
-        ]
-    ]
-
-
-def _fmt_rainbow(msg: str, end: float = 2 / 3) -> str:
-    cols = [RGB(*map(int, rgb)) for rgb in rainbow_color_stops(n=len(msg), end=end)]
-    return "".join([f"{cols[i]!r}{c}" for i, c in enumerate(msg)]) + repr(Ansi.RESET)
+        log_level = logging.INFO
 
+    if settings.LOG_WITH_COLORS:
+        color_prefix = f"{start_color!r}" if start_color is not None else ""
+        color_suffix = f"{Ansi.RESET!r}" if start_color is not None else ""
+    else:
+        msg = escape_ansi(msg)
+        color_prefix = color_suffix = ""
 
-def print_rainbow(msg: str, rainbow_end: float = 2 / 3, end: str = "\n") -> None:
-    print(_fmt_rainbow(msg, rainbow_end), end=end)
+    ROOT_LOGGER.log(log_level, f"{color_prefix}{msg}{color_suffix}", extra=extra)
 
 
 TIME_ORDER_SUFFIXES = ["nsec", "μsec", "msec", "sec"]

Diff for: app/objects/player.py

@@ -403,7 +403,7 @@ def logout(self) -> None:
 
             app.state.sessions.players.enqueue(app.packets.logout(self.id))
 
-        log(f"{self} logged out.", Ansi.LYELLOW)
+        log(f"{self} logged out.")
 
     async def update_privs(self, new: Privileges) -> None:
         """Update `self`'s privileges to `new`."""