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,6 +1,9 @@
 from __future__ import annotations
 
-from typing import Generator, Iterator, TYPE_CHECKING
+import atexit
+import logging
+import os
+from typing import Any, Generator, Iterator, TYPE_CHECKING
 from contextlib import contextmanager
 from collections import deque
 
@@ -14,6 +17,8 @@
     import miniaudio
     import samplerate
 
+logger = logging.getLogger(__name__)
+
 
 class AudioOut:
     output_rate: float = 48000.0  # Hz
@@ -50,21 +55,38 @@ def __init__(
         self.ring_buffer = np.zeros((self.ring_size, 2), dtype=np.int16)
 
         # We implement a SPSC (Single Producer Single Consumer) ring buffer,
-        # so we do not need synchonization primitives. The contract is:
-        # - only the producer (the `send` method) can incremement the write counter
+        # so we do not need synchronization primitives. The contract is:
+        # - only the producer (the `send` method) can increment the write counter
         # - only the consumer (the `_audio_stream` generator) can increment the read counter
         # - the read counter can never surpass the write counter
         # - both the consumer and producer can read both counters to compute the fill level
-        # Since this this fill is not protected by a lock, it represents:
+        # Since this fill is not protected by a lock, it represents:
         # - a maximum fill level when it's read by the producer
         # - a minimum fill level when it's read by the consumer
         self.write_counter = 0
         self.read_counter = 0
 
+        # Diagnostics variables
+        self._underruns = 0
+        self._overruns = 0
+        self._frame_num = 0
+        self._csv_enabled = bool(os.environ.get("GAMBATERM_AUDIO_CSV"))
+        self._diag_fill_min = 1.0
+        self._diag_ratio_min = self.nominal_sampling_ratio
+        self._diag_ratio_max = self.nominal_sampling_ratio
+        if self._csv_enabled:
+            self._diag_frames: list[dict[str, Any]] = []
+            atexit.register(self._dump_csv)
+        atexit.register(self._log_summary)
+
         # Controller configuration
         self.correction_min = 1 - self.correction_clamp
         self.correction_max = 1 + self.correction_clamp
 
+        # Batch the variable-length emulator audio output, avoids starving the ring buffer, runFor()
+        # sometimes returns partial frames!
+        self._acc_buf: npt.NDArray[np.float32] = np.empty((0, 2), dtype=np.float32)
+
         # Controller state
         self.last_buffer_levels = deque[float](maxlen=self.ma_length)
         self.moving_average = 0.5
@@ -86,10 +108,39 @@ def start(self) -> miniaudio.PlaybackDevice:
         device.start(stream)
         return device
 
+    def _dump_csv(self) -> None:
+        if diag_csv := os.environ.get("GAMBATERM_AUDIO_CSV"):
+            with open(diag_csv, "w") as fout:
+                fout.write("frame,input,acc,proc,output,fill\n")
+                for _df in self._diag_frames:
+                    fout.write(
+                        f"{_df['frame']},{_df['input']},{_df['acc']},"
+                        f"{_df['proc']},{_df['output']},{_df['fill']:.4f}\n"
+                    )
+
+    def _log_summary(self) -> None:
+        logger.debug(
+            "Audio stats: underruns=%d overruns=%d "
+            "fill_min=%.4f ratio_min=%.8f ratio_max=%.8f "
+            "ratio_range=%.8f",
+            self._underruns,
+            self._overruns,
+            self._diag_fill_min,
+            self._diag_ratio_min,
+            self._diag_ratio_max,
+            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,13 +164,93 @@ def adapt_sample_rate(self) -> None:
 
         # Return the adjusted sample rate
         self.sampling_ratio = self.nominal_sampling_ratio * correction
+        self._diag_track_ratio()
+
+    def _diag_record_skip(self, input_len: int, acc_len: int) -> None:
+        fill = self.fill_fraction
+        self._diag_fill_min = min(self._diag_fill_min, fill)
+        frame = self._frame_num
+        self._frame_num += 1
+        logger.debug(
+            "skip frame=%d input=%d acc=%d fill=%.4f", frame, input_len, acc_len, fill
+        )
+        if self._csv_enabled:
+            self._diag_frames.append(
+                {
+                    "frame": frame,
+                    "input": input_len,
+                    "acc": acc_len,
+                    "proc": 0,
+                    "output": 0,
+                    "fill": fill,
+                }
+            )
+
+    def _diag_record_process(
+        self,
+        input_len: int,
+        acc_len: int,
+        output_len: int,
+    ) -> None:
+        fill = self.fill_fraction
+        self._diag_fill_min = min(self._diag_fill_min, fill)
+        frame = self._frame_num
+        self._frame_num += 1
+        logger.debug(
+            "process frame=%d input=%d acc=%d output=%d fill=%.4f",
+            frame,
+            input_len,
+            acc_len,
+            output_len,
+            fill,
+        )
+        if self._csv_enabled:
+            self._diag_frames.append(
+                {
+                    "frame": frame,
+                    "input": input_len,
+                    "acc": acc_len,
+                    "proc": 1,
+                    "output": output_len,
+                    "fill": fill,
+                }
+            )
+
+    def _diag_track_fill(self) -> None:
+        self._diag_fill_min = min(self._diag_fill_min, self.fill_fraction)
+
+    def _diag_track_ratio(self) -> None:
+        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,
-            self.sampling_ratio,
-        ).astype(np.int16)
+        # Scale and remove DC offset
+        scaled = (
+            audio.astype(np.float32) * self.audio_volume
+            - console.AUDIO_OFFSET * self.audio_volume
+        )
+
+        # Accumulate input to batch variable-length emulator frames into consistent chunks for the
+        # resampler.  The emulator's runFor() may produce anywhere from a few hundred to tens of
+        # thousands of samples per call; tiny batches could otherwise starve the ring buffer when
+        # under load.
+        self._acc_buf = np.concatenate([self._acc_buf, scaled])
+        input_len = len(scaled)
+        acc_len = len(self._acc_buf)
+
+        # Process when we have enough to produce ~5ms of output at 48 kHz,
+        # or when we have accumulated more than 3 video frames (safety valve).
+        min_output = 240
+        min_input = max(1, int(min_output / self.sampling_ratio))
+        max_input = console.TICKS_IN_FRAME * 3
+        if acc_len < min_input and acc_len < max_input:
+            self._diag_record_skip(input_len, acc_len)
+            return
+
+        chunk = self._acc_buf
+        self._acc_buf = np.empty((0, 2), dtype=np.float32)
+        resampled = self.resampler.process(chunk, self.sampling_ratio)
+        resampled = np.clip(resampled, -32768, 32767).astype(np.int16)
 
         # Get the ring buffer
         ring_buffer = self.ring_buffer
@@ -135,7 +266,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: dropping %d of %d frames (fill=%.2f)",
+                frames - space,
+                frames,
+                self.fill_fraction,
+            )
             resampled = resampled[:space]
             frames = space
 
@@ -157,6 +294,7 @@ def send(self, console: Console, audio: npt.NDArray[np.int16]) -> None:
 
         # Update the write counter
         self.write_counter += frames
+        self._diag_record_process(input_len, acc_len, frames)
 
     def _audio_stream(self) -> Generator[bytes, int, None]:
         # Get the ring buffer
@@ -201,11 +339,17 @@ def _audio_stream(self) -> Generator[bytes, int, None]:
 
             # Update the read counter
             self.read_counter += read_size
+            self._diag_track_fill()
 
             # Log if we're underrunning
             if read_size < required_frames:
-                # TODO: Implement logging
-                pass
+                self._underruns += 1
+                logger.warning(
+                    "Audio underrun: requested %d, got %d (fill=%.2f)",
+                    required_frames,
+                    read_size,
+                    self.fill_fraction,
+                )
 
             # Send audio to output and get next required frames
             required_frames = yield result.tobytes()

gambaterm/main.py

@@ -2,9 +2,10 @@
 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
 
@@ -23,6 +24,45 @@
 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 (following telnetlib3 pattern)."""
+    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)
+    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="warn",
+        help="Logging level: debug, info, warn, error (default: warn)",
+    )
+    parser.add_argument(
+        "--logfmt",
+        default=_DEFAULT_LOGFMT,
+        help="Log format string (default: LEVEL file:lineno message)",
+    )
+
 
 @dataclass
 class AppConfig:
@@ -151,11 +191,18 @@ def main(
     add_base_arguments(parser)
     add_input_file_arguments(parser)
     add_tuning_arguments(parser)
+    add_logging_arguments(parser)
     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", "warn"),
+        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", "warn"),
+        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")