audio logging and diagnostics with structlog

.pre-commit-config.yaml

@@ -15,7 +15,7 @@ repos:
     - id: trailing-whitespace
       exclude: \.patch$
 -   repo: https://github.com/pre-commit/mirrors-mypy
-    rev: "v1.7.0"
+    rev: "v2.3.0"
     hooks:
     - id: mypy
       additional_dependencies: [

gambaterm/audio.py

@@ -1,11 +1,13 @@
 from __future__ import annotations
 
+import atexit
 from typing import Generator, Iterator, TYPE_CHECKING
 from contextlib import contextmanager
 from collections import deque
 
 import numpy as np
 import numpy.typing as npt
+import structlog
 
 from .console import Console
 
@@ -14,6 +16,8 @@
     import miniaudio
     import samplerate
 
+logger = structlog.get_logger()
+
 
 class AudioOut:
     output_rate: float = 48000.0  # Hz
@@ -61,6 +65,14 @@ def __init__(
         self.write_counter = 0
         self.read_counter = 0
 
+        # Diagnostics variables
+        self._underruns = 0
+        self._overruns = 0
+        self._diag_fill_min = 1.0
+        self._diag_ratio_min = self.nominal_sampling_ratio
+        self._diag_ratio_max = self.nominal_sampling_ratio
+        atexit.register(self._log_summary)
+
         # Controller configuration
         self.correction_min = 1 - self.correction_clamp
         self.correction_max = 1 + self.correction_clamp
@@ -86,10 +98,27 @@ def start(self) -> miniaudio.PlaybackDevice:
         device.start(stream)
         return device
 
+    def _log_summary(self) -> None:
+        logger.debug(
+            "audio_summary",
+            underruns=self._underruns,
+            overruns=self._overruns,
+            fill_min=self._diag_fill_min,
+            ratio_min=self._diag_ratio_min,
+            ratio_max=self._diag_ratio_max,
+            ratio_range=self._diag_ratio_max - self._diag_ratio_min,
+        )
+
+    @property
+    def fill_fraction(self) -> float:
+        # Ring buffer fill ratio (0-1.0)
+        if self.ring_size == 0:
+            return 0.0
+        return max(0.0, (self.write_counter - self.read_counter) / self.ring_size)
+
     def adapt_sample_rate(self) -> None:
         # First perform a short moving average of the last 5 measurements
-        ring_fill = self.write_counter - self.read_counter
-        self.last_buffer_levels.append(ring_fill / self.ring_size)
+        self.last_buffer_levels.append(self.fill_fraction)
         buffer_level = sum(self.last_buffer_levels) / len(self.last_buffer_levels)
 
         # Then perform a longer exponential moving average
@@ -113,11 +142,14 @@ def adapt_sample_rate(self) -> None:
 
         # Return the adjusted sample rate
         self.sampling_ratio = self.nominal_sampling_ratio * correction
+        self._diag_ratio_min = min(self._diag_ratio_min, self.sampling_ratio)
+        self._diag_ratio_max = max(self._diag_ratio_max, self.sampling_ratio)
 
     def send(self, console: Console, audio: npt.NDArray[np.int16]) -> None:
         # Resample input audio to output rate with speed adjustment
         resampled = self.resampler.process(
-            audio * self.audio_volume - console.AUDIO_OFFSET * self.audio_volume,
+            audio.astype(np.float32) * self.audio_volume
+            - console.AUDIO_OFFSET * self.audio_volume,
             self.sampling_ratio,
         ).astype(np.int16)
 
@@ -135,7 +167,13 @@ def send(self, console: Console, audio: npt.NDArray[np.int16]) -> None:
 
         # Drop excess frames if we're overrun
         if frames > space:
-            # TODO: Implement logging
+            self._overruns += 1
+            logger.warning(
+                "audio_overrun",
+                dropped=frames - space,
+                frames=frames,
+                fill=self.fill_fraction,
+            )
             resampled = resampled[:space]
             frames = space
 
@@ -157,6 +195,13 @@ def send(self, console: Console, audio: npt.NDArray[np.int16]) -> None:
 
         # Update the write counter
         self.write_counter += frames
+        self._diag_fill_min = min(self._diag_fill_min, self.fill_fraction)
+        logger.debug(
+            "audio_frame",
+            input=len(audio),
+            output=frames,
+            fill=self.fill_fraction,
+        )
 
     def _audio_stream(self) -> Generator[bytes, int, None]:
         # Get the ring buffer
@@ -201,11 +246,17 @@ def _audio_stream(self) -> Generator[bytes, int, None]:
 
             # Update the read counter
             self.read_counter += read_size
+            self._diag_fill_min = min(self._diag_fill_min, self.fill_fraction)
 
             # Log if we're underrunning
             if read_size < required_frames:
-                # TODO: Implement logging
-                pass
+                self._underruns += 1
+                logger.warning(
+                    "audio_underrun",
+                    required=required_frames,
+                    got=read_size,
+                    fill=self.fill_fraction,
+                )
 
             # Send audio to output and get next required frames
             required_frames = yield result.tobytes()

gambaterm/main.py

@@ -2,12 +2,14 @@
 from __future__ import annotations
 
 import time
+import logging
 import argparse
 from pathlib import Path
-from typing import ContextManager, TYPE_CHECKING
+from typing import Any, ContextManager, Optional, TYPE_CHECKING
 import dataclasses
 from dataclasses import dataclass, field
 
+import structlog
 from blessed import Terminal
 
 from .run import run
@@ -23,6 +25,66 @@
 if TYPE_CHECKING:
     from typing import Self
 
+_DEFAULT_LOGFMT = " ".join(("%(levelname)s", "%(filename)s:%(lineno)d", "%(message)s"))
+
+
+def make_logger(
+    name: str,
+    loglevel: str = "info",
+    logfile: Optional[str] = None,
+    logfmt: str = _DEFAULT_LOGFMT,
+    filemode: str = "a",
+) -> logging.Logger:
+    """Create and return a configured logger."""
+    lvl = getattr(logging, loglevel.upper(), None)
+    if lvl is None:
+        lvl = logging.getLevelName(loglevel.upper())
+    _cfg: dict[str, Any] = {"format": logfmt}
+    if logfile:
+        _cfg["filename"] = logfile
+        _cfg["filemode"] = filemode
+    logging.basicConfig(**_cfg)
+    logging.getLogger().setLevel(lvl)
+    logging.getLogger(name).setLevel(lvl)
+
+    # Route structlog through standard logging so --logfile can be used
+    # to capture debug output when running locally without muddying up
+    # the screen's display
+    structlog.configure(
+        processors=[
+            structlog.stdlib.filter_by_level,
+            structlog.stdlib.add_log_level,
+            structlog.stdlib.PositionalArgumentsFormatter(),
+            structlog.processors.TimeStamper(fmt="iso"),
+            structlog.processors.StackInfoRenderer(),
+            structlog.processors.format_exc_info,
+            structlog.processors.UnicodeDecoder(),
+            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+        ],
+        context_class=dict,
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        wrapper_class=structlog.stdlib.BoundLogger,
+        cache_logger_on_first_use=True,
+    )
+
+    return logging.getLogger(name)
+
+
+def add_logging_arguments(parser: argparse.ArgumentParser) -> None:
+    parser.add_argument(
+        "--logfile", default=None, help="File path for log output (default: stderr)"
+    )
+    parser.add_argument(
+        "--loglevel",
+        default="info",
+        help="Logging level: debug, info, warn, error, critical (default: critical for local, info for ssh/telnet)",
+    )
+    parser.add_argument(
+        "--logfmt",
+        default=_DEFAULT_LOGFMT,
+        help="Log format string (default: LEVEL file:lineno message)",
+    )
+
 
 @dataclass
 class AppConfig:
@@ -151,11 +213,19 @@ def main(
     add_base_arguments(parser)
     add_input_file_arguments(parser)
     add_tuning_arguments(parser)
+    add_logging_arguments(parser)
+    parser.set_defaults(loglevel="critical")
     add_local_only_arguments(parser)
     console_cls.add_console_arguments(parser)
 
     # Parse arguments
     namespace = parser.parse_args(parser_args)
+    make_logger(
+        __name__,
+        loglevel=getattr(namespace, "loglevel", "critical"),
+        logfile=getattr(namespace, "logfile", None),
+        logfmt=getattr(namespace, "logfmt", _DEFAULT_LOGFMT),
+    )
     disable_audio = getattr(namespace, "disable_audio", False)
     args = LocalAppConfig.from_namespace(namespace)
 

gambaterm/run.py

@@ -36,7 +36,7 @@ def get_ref(width: int, height: int, console: Console) -> tuple[int, int]:
     return refx, refy
 
 
-def write_frame(term: Terminal, frame_data: bytes) -> None:
+def write_frame(term: Terminal, frame_data: bytes | bytearray) -> None:
     # Fix code page issue on windows:
     # `sys.stdout.buffer.raw` is a `WindowsConsoleIO` that always support UTF-8
     # regardless of the configured codepage

gambaterm/ssh.py

@@ -38,6 +38,9 @@
     add_base_arguments,
     add_input_file_arguments,
     add_tuning_arguments,
+    add_logging_arguments,
+    make_logger,
+    _DEFAULT_LOGFMT,
     AppConfig,
 )
 from .console import Console, GameboyColor
@@ -533,6 +536,7 @@ def main(
     add_base_arguments(parser)
     add_input_file_arguments(parser)
     add_tuning_arguments(parser)
+    add_logging_arguments(parser)
     console_cls.add_console_arguments(parser)
     parser.add_argument(
         "--bind",
@@ -570,6 +574,12 @@ def main(
 
     # Parse arguments
     namespace = parser.parse_args(parser_args)
+    make_logger(
+        __name__,
+        loglevel=getattr(namespace, "loglevel", "info"),
+        logfile=getattr(namespace, "logfile", None),
+        logfmt=getattr(namespace, "logfmt", _DEFAULT_LOGFMT),
+    )
     bind: str = namespace.__dict__.pop("bind")
     port: int = namespace.__dict__.pop("port")
     password: str = namespace.__dict__.pop("password")

gambaterm/telnet.py

@@ -32,6 +32,9 @@
     add_base_arguments,
     add_input_file_arguments,
     add_tuning_arguments,
+    add_logging_arguments,
+    make_logger,
+    _DEFAULT_LOGFMT,
     AppConfig,
 )
 from .console import Console, GameboyColor
@@ -444,6 +447,7 @@ def main(
     add_base_arguments(parser)
     add_input_file_arguments(parser)
     add_tuning_arguments(parser)
+    add_logging_arguments(parser)
     console_cls.add_console_arguments(parser)
     parser.add_argument(
         "--bind",
@@ -464,8 +468,7 @@ def main(
         "--robot-check",
         action="store_true",
         default=False,
-        help="reject bots by checking if client responds to "
-        "cursor position requests",
+        help="reject bots by checking if client responds to cursor position requests",
     )
     parser.add_argument(
         "--port",
@@ -488,6 +491,12 @@ def main(
     )
 
     namespace = parser.parse_args(parser_args)
+    make_logger(
+        __name__,
+        loglevel=getattr(namespace, "loglevel", "info"),
+        logfile=getattr(namespace, "logfile", None),
+        logfmt=getattr(namespace, "logfmt", _DEFAULT_LOGFMT),
+    )
     bind: str = namespace.__dict__.pop("bind")
     port: int = namespace.__dict__.pop("port")
     robot_check: bool = namespace.__dict__.pop("robot_check")