diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 77d98af..265ac3f 100644 --- a/.pre-commit-config.yaml +++ b/.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: [ diff --git a/gambaterm/audio.py b/gambaterm/audio.py index 6e14e2d..4c04218 100644 --- a/gambaterm/audio.py +++ b/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() diff --git a/gambaterm/main.py b/gambaterm/main.py index 75d1f7d..894d98e 100644 --- a/gambaterm/main.py +++ b/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) diff --git a/gambaterm/run.py b/gambaterm/run.py index b7d0e69..51265c3 100644 --- a/gambaterm/run.py +++ b/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 diff --git a/gambaterm/ssh.py b/gambaterm/ssh.py index 036a1ab..b819b99 100644 --- a/gambaterm/ssh.py +++ b/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") diff --git a/gambaterm/telnet.py b/gambaterm/telnet.py index b06ea5b..893a3be 100644 --- a/gambaterm/telnet.py +++ b/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")