diff --git a/nya/common/logging.py b/nya/common/logging.py new file mode 100644 index 0000000..033d442 --- /dev/null +++ b/nya/common/logging.py @@ -0,0 +1,136 @@ +""" +One logging configuration for the whole process. + +Everything logs through the standard library — NyaProxy, Uvicorn, Starlette, +watchfiles, httpx, and nacho — so a single root handler gives every line the +same shape without any bridging between logging frameworks. + +The format deliberately stops at the logger name: + + 2026-07-19 23:08:44.076 | INFO | nya.server.app - Setting up routes + 2026-07-19 23:08:50.770 | INFO | uvicorn.access - 127.0.0.1 - "GET /health" 200 + +The emitting module, function, and line are omitted: the name already says +which subsystem spoke, and anything worth locating precisely arrives with a +traceback that carries the exact position. +""" + +import logging +import logging.handlers +import os +import sys +from typing import Optional + +#: Shared line format. ``levelcolor`` is filled in by the formatter so the +#: level can be padded before any escape codes are added. +LOG_FORMAT = "%(asctime)s.%(msecs)03d | %(levelcolor)s | %(name)s - %(message)s" +DATE_FORMAT = "%Y-%m-%d %H:%M:%S" + +#: Size-based rotation, matching what the configuration documents. +_MAX_BYTES = 10 * 1024 * 1024 +_BACKUP_COUNT = 5 + +_RESET = "\033[0m" +_LEVEL_COLORS = { + "DEBUG": "\033[36m", # cyan + "INFO": "\033[32m", # green + "WARNING": "\033[33m", # yellow + "ERROR": "\033[31m", # red + "CRITICAL": "\033[1;31m", # bold red +} + +#: Third-party loggers that install handlers or pin levels of their own. +_MANAGED_LOGGERS = ( + "uvicorn", + "uvicorn.error", + "uvicorn.access", + "uvicorn.asgi", + "fastapi", + "starlette", + "watchfiles", + "watchfiles.main", + "httpx", + "httpcore", + "nacho", +) + + +class Formatter(logging.Formatter): + """Shared formatter, optionally colouring the level for a terminal.""" + + def __init__(self, *, color: bool = False) -> None: + super().__init__(LOG_FORMAT, datefmt=DATE_FORMAT) + self.color = color + + def format(self, record: logging.LogRecord) -> str: + # Pad first, then colour: escape codes count towards a %-width and + # would otherwise break the column alignment. + level = f"{record.levelname:<8}" + if self.color: + level = f"{_LEVEL_COLORS.get(record.levelname, '')}{level}{_RESET}" + record.levelcolor = level + return super().format(record) + + +def _supports_color(stream) -> bool: + if os.environ.get("NO_COLOR"): + return False + return bool(getattr(stream, "isatty", lambda: False)()) + + +def configure_logging( + level: str = "INFO", + log_file: Optional[str] = None, + enabled: bool = True, +) -> None: + """ + Install the shared configuration. Safe to call more than once. + + Called at import so Uvicorn's startup lines are covered, and again once + the configuration file has been read. + """ + normalized = (level or "INFO").upper() + root = logging.getLogger() + + for handler in root.handlers[:]: + root.removeHandler(handler) + handler.close() + + if not enabled: + root.addHandler(logging.NullHandler()) + root.setLevel(logging.CRITICAL + 1) + _reset_managed_loggers() + return + + stream = logging.StreamHandler(sys.stderr) + stream.setFormatter(Formatter(color=_supports_color(sys.stderr))) + root.addHandler(stream) + + if log_file: + file_handler = logging.handlers.RotatingFileHandler( + log_file, + maxBytes=_MAX_BYTES, + backupCount=_BACKUP_COUNT, + encoding="utf-8", + ) + file_handler.setFormatter(Formatter(color=False)) + root.addHandler(file_handler) + + root.setLevel(logging.getLevelName(normalized)) + _reset_managed_loggers() + + +def _reset_managed_loggers() -> None: + """ + Hand the managed loggers back to the root configuration. + + Uvicorn attaches its own handlers and pins an explicit level (that is what + --log-level does). An explicit level beats the root's, so leaving one in + place would silently override the level from the configuration file. + """ + for name in _MANAGED_LOGGERS: + std_logger = logging.getLogger(name) + for handler in std_logger.handlers[:]: + std_logger.removeHandler(handler) + std_logger.propagate = True + std_logger.setLevel(logging.NOTSET) diff --git a/nya/config/manager.py b/nya/config/manager.py index 38ef890..8e500cf 100644 --- a/nya/config/manager.py +++ b/nya/config/manager.py @@ -2,16 +2,18 @@ Configuration manager for NyaProxy using Nacho. """ +import logging import os import re from typing import Any, Callable, Dict, List, Optional, TypeVar, Union -from loguru import logger from nacho import FileStorageBackend, Nacho, NachoOrchestrator, RemoteStorageBackend from nya.common.constants import DEFAULT_HOST, DEFAULT_PORT from nya.common.exceptions import ConfigurationError +logger = logging.getLogger(__name__) + T = TypeVar("T") BUILTIN_API_DEFAULTS: Dict[str, Any] = { diff --git a/nya/core/handler.py b/nya/core/handler.py index 3052954..735bf25 100644 --- a/nya/core/handler.py +++ b/nya/core/handler.py @@ -2,12 +2,12 @@ Request handler for intercepting and forwarding HTTP requests with token rotation. """ +import logging import random from typing import TYPE_CHECKING, Any, Dict, List, Optional, Tuple from urllib.parse import urlparse import orjson -from loguru import logger from ..common.constants import API_PATH_PREFIX from ..common.exceptions import MissingAPIKeyError, VariablesConfigurationError @@ -15,6 +15,8 @@ from ..utils.header import HeaderUtils from ..utils.substitution import apply_body_substitutions +logger = logging.getLogger(__name__) + if TYPE_CHECKING: from ..config.manager import ConfigManager @@ -67,7 +69,20 @@ def prepare_request(self, request: ProxyRequest) -> None: ) if HeaderUtils.is_trusted_proxy(request.ip, trusted_proxies): proxy_ip = HeaderUtils.parse_source_ip_address(request.headers) - request.ip = proxy_ip if proxy_ip else request.ip + if proxy_ip: + # The access log only ever shows the socket peer, so without + # this there is no way to tell whether forwarding headers are + # being honoured or every client is sharing one quota. + logger.debug( + f"Resolved client IP {proxy_ip} from headers " + f"(trusted peer {request.ip})" + ) + request.ip = proxy_ip + elif trusted_proxies: + logger.debug( + f"Peer {request.ip} is not in trusted_proxies; " + "forwarding headers ignored and quotas apply to the peer" + ) request.user = self.get_proxy_api_key(request) diff --git a/nya/core/proxy.py b/nya/core/proxy.py index 258b8b2..31a09e3 100644 --- a/nya/core/proxy.py +++ b/nya/core/proxy.py @@ -3,13 +3,13 @@ """ import asyncio +import logging import math import random import traceback from typing import TYPE_CHECKING, Dict, Optional, Union import httpx -from loguru import logger from starlette.responses import JSONResponse, Response, StreamingResponse from ..common.exceptions import ( @@ -24,6 +24,8 @@ from .queue import RequestQueue from .request import RequestExecutor +logger = logging.getLogger(__name__) + if TYPE_CHECKING: from ..common.models import ProxyRequest from ..config.manager import ConfigManager diff --git a/nya/core/queue.py b/nya/core/queue.py index 3cfb214..0bd7a10 100644 --- a/nya/core/queue.py +++ b/nya/core/queue.py @@ -3,13 +3,12 @@ """ import asyncio +import logging import random import time import traceback from typing import TYPE_CHECKING, Any, Awaitable, Callable, Dict, List, Optional, Tuple -from loguru import logger - from ..common.exceptions import ( QueueFullError, ReachedMaxQuotaError, @@ -18,6 +17,8 @@ ) from ..utils.redaction import mask_secret +logger = logging.getLogger(__name__) + if TYPE_CHECKING: from starlette.responses import Response diff --git a/nya/core/request.py b/nya/core/request.py index 2e4c905..c595484 100644 --- a/nya/core/request.py +++ b/nya/core/request.py @@ -2,11 +2,11 @@ Simplified request executor focused on HTTP execution only. """ +import logging import time from typing import TYPE_CHECKING, Optional, Union import httpx -from loguru import logger from starlette.responses import JSONResponse, Response, StreamingResponse from ..utils.formatting import format_elapsed_time, json_safe_dumps @@ -18,6 +18,8 @@ handle_streaming_response, ) +logger = logging.getLogger(__name__) + if TYPE_CHECKING: from ..common.models import ProxyRequest from ..config.manager import ConfigManager @@ -84,7 +86,9 @@ async def execute( track = bool(self.metrics_collector) if track: - self.metrics_collector.record_request(api_name, request.api_key) + self.metrics_collector.record_request( + api_name, request.api_key, request.trail_path + ) logger.debug(f"[Request] Method: {request.method.upper()}, URL: {request.url}") @@ -100,6 +104,7 @@ async def execute( request.api_key, 0, time.time() - actual_start_time, + request.trail_path, ) raise @@ -128,6 +133,7 @@ async def execute( request.api_key, response.status_code, time.time() - actual_start_time, + request.trail_path, ) ) return streaming @@ -141,6 +147,7 @@ async def execute( request.api_key, 0, time.time() - actual_start_time, + request.trail_path, ) raise @@ -150,6 +157,7 @@ async def execute( request.api_key, response.status_code, time.time() - actual_start_time, + request.trail_path, ) return result diff --git a/nya/core/streaming.py b/nya/core/streaming.py index 7babfee..45eeca9 100644 --- a/nya/core/streaming.py +++ b/nya/core/streaming.py @@ -2,14 +2,16 @@ Streaming response handling utilities for NyaProxy. """ +import logging import traceback from collections.abc import Callable from typing import Awaitable, Optional import httpx -from loguru import logger from starlette.responses import StreamingResponse +logger = logging.getLogger(__name__) + __all__ = [ "handle_streaming_response", "detect_streaming_content", diff --git a/nya/dashboard/api.py b/nya/dashboard/api.py index f97b8b6..bf621aa 100644 --- a/nya/dashboard/api.py +++ b/nya/dashboard/api.py @@ -7,13 +7,13 @@ """ import importlib.resources +import logging import os from pathlib import Path from typing import TYPE_CHECKING, Optional from fastapi import FastAPI from fastapi.staticfiles import StaticFiles -from loguru import logger from .._version import __version__ from .routes import ( @@ -24,6 +24,8 @@ register_queue_routes, ) +logger = logging.getLogger(__name__) + if TYPE_CHECKING: from ..config.manager import ConfigManager from ..core.queue import RequestQueue diff --git a/nya/dashboard/routes/control.py b/nya/dashboard/routes/control.py index 936cab8..0027a34 100644 --- a/nya/dashboard/routes/control.py +++ b/nya/dashboard/routes/control.py @@ -5,11 +5,13 @@ ``enable_control=True``. """ +import logging from typing import TYPE_CHECKING from fastapi import FastAPI from fastapi.responses import JSONResponse -from loguru import logger + +logger = logging.getLogger(__name__) if TYPE_CHECKING: from ..api import DashboardAPI diff --git a/nya/dashboard/routes/history.py b/nya/dashboard/routes/history.py index fda9a1a..6db38a1 100644 --- a/nya/dashboard/routes/history.py +++ b/nya/dashboard/routes/history.py @@ -6,11 +6,13 @@ via the ``/metrics`` endpoint. """ +import logging from typing import TYPE_CHECKING, Any, Dict, Optional from fastapi import FastAPI, Query from fastapi.responses import JSONResponse -from loguru import logger + +logger = logging.getLogger(__name__) if TYPE_CHECKING: from ..api import DashboardAPI diff --git a/nya/dashboard/routes/metrics.py b/nya/dashboard/routes/metrics.py index 13e6a61..54df321 100644 --- a/nya/dashboard/routes/metrics.py +++ b/nya/dashboard/routes/metrics.py @@ -2,11 +2,13 @@ Metrics routes: aggregate metrics, per-API metrics, and key-usage stats. """ +import logging from typing import TYPE_CHECKING from fastapi import FastAPI from fastapi.responses import JSONResponse -from loguru import logger + +logger = logging.getLogger(__name__) if TYPE_CHECKING: from ..api import DashboardAPI diff --git a/nya/dashboard/routes/queue.py b/nya/dashboard/routes/queue.py index 091daf9..aa6cbc5 100644 --- a/nya/dashboard/routes/queue.py +++ b/nya/dashboard/routes/queue.py @@ -2,11 +2,13 @@ Read-only queue-status route. """ +import logging from typing import TYPE_CHECKING from fastapi import FastAPI from fastapi.responses import JSONResponse -from loguru import logger + +logger = logging.getLogger(__name__) if TYPE_CHECKING: from ..api import DashboardAPI diff --git a/nya/html/index.html b/nya/html/index.html index 576be6b..041f9bb 100644 --- a/nya/html/index.html +++ b/nya/html/index.html @@ -254,15 +254,16 @@

Recent requests Time API + Path Status Latency Key - - - + + + diff --git a/nya/html/static/css/styles.css b/nya/html/static/css/styles.css index b1b65bd..1d65c52 100644 --- a/nya/html/static/css/styles.css +++ b/nya/html/static/css/styles.css @@ -2210,6 +2210,55 @@ table.data tbody > tr:not(.detail-row):hover { color: var(--text-2); } +/* Paths are the widest, least predictable column: give it the slack and + truncate from the left so the distinguishing tail stays visible. */ +/* Constrain the button, not the cell: a max-width on a is advisory + under automatic table layout, so the column would still push its + neighbours out. */ +.cell-path .cell-link { + display: block; + max-width: 190px; + direction: rtl; + text-align: left; +} + +/* The masked key is short and fixed-width; never let it collapse. */ +.table-history td:last-child, +.table-history th:last-child { + white-space: nowrap; +} + +.cell-path .cell-link::before { + content: "\200E"; /* keep the leading slash on the left under rtl */ +} + +.path-table { + margin-top: var(--sp-4); +} + +.path-table th { + padding: 0 0 var(--sp-1); + color: var(--text-3); + font-size: 10.5px; + font-weight: 600; + letter-spacing: 0.08em; + text-transform: uppercase; + text-align: left; +} + +.path-table th.col-num { + text-align: right; +} + +.path-table .path-filter-btn { + max-width: 100%; + padding: 0; + overflow: hidden; + font-size: 13px; + text-overflow: ellipsis; + white-space: nowrap; +} + /* Latency reads against the slowest response currently on screen. */ .cell-latency { position: relative; @@ -2410,8 +2459,11 @@ table.data tbody > tr:not(.detail-row):hover { flex: none; } - .panel-history table th:nth-child(5), - .panel-history table td:nth-child(5) { + /* Drop the key, then the path: both are recoverable from the API detail. */ + .panel-history table th:nth-child(6), + .panel-history table td:nth-child(6), + .panel-history table th:nth-child(3), + .panel-history table td:nth-child(3) { display: none; } diff --git a/nya/html/static/js/dashboard.js b/nya/html/static/js/dashboard.js index 87ae5f4..ef77503 100644 --- a/nya/html/static/js/dashboard.js +++ b/nya/html/static/js/dashboard.js @@ -47,6 +47,7 @@ const state = { statusChip: "all", historyApi: null, // cross-filter: show only this API in the traffic log historyKey: null, // cross-filter: show only this credential + historyPath: null, // cross-filter: show only this upstream path sort: { key: "requests", dir: "desc" }, openApi: null, idleOpen: false, @@ -247,6 +248,7 @@ function deriveAnalytics(history, metrics) { total: 0, errors: 0, latencies: [], + paths: new Map(), }; perApi.set(e.api_name, a); } @@ -254,6 +256,17 @@ function deriveAnalytics(history, metrics) { a.total += 1; if (err) a.errors += 1; if (ms) a.latencies.push(ms); + + // Which endpoints an upstream is actually serving, and how well. + const route = e.path || "/"; + let p = a.paths.get(route); + if (!p) { + p = { total: 0, errors: 0, latencies: [] }; + a.paths.set(route, p); + } + p.total += 1; + if (err) p.errors += 1; + if (ms) p.latencies.push(ms); } if (e.key_id != null) { @@ -291,12 +304,25 @@ function deriveAnalytics(history, metrics) { const apis = {}; for (const [name, a] of perApi) { const sorted = a.latencies.slice().sort((x, y) => x - y); + const paths = [...a.paths.entries()] + .map(([route, p]) => ({ + path: route, + total: p.total, + errors: p.errors, + errorRate: p.total ? (p.errors / p.total) * 100 : 0, + p95: percentile( + p.latencies.slice().sort((x, y) => x - y), + 95 + ), + })) + .sort((x, y) => y.total - x.total || x.path.localeCompare(y.path)); apis[name] = { series: a.buckets, total: a.total, errors: a.errors, errorRate: a.total ? (a.errors / a.total) * 100 : 0, p95: percentile(sorted, 95), + paths, }; } @@ -905,6 +931,29 @@ function detailRowHtml(name, a) { ) .join(""); + // Which endpoints this upstream actually serves. Derived from the recent + // sample, so it is labelled as such rather than shown beside all-time counts. + const pathRows = ((trend && trend.paths) || []) + .slice(0, 8) + .map( + (p) => + ` + ${fmt.int(p.total)} + ${ + p.errorRate > 0 + ? `${p.errorRate.toFixed(1)}%` + : '—' + } + ${fmt.latency(p.p95)}` + ) + .join(""); + return `
@@ -941,6 +990,17 @@ function detailRowHtml(name, a) {
` : "" } + ${ + pathRows + ? `
+

Top paths recent

+ + + ${pathRows} +
PathRequestsErrp95
+
` + : "" + }
`; } @@ -1208,6 +1268,8 @@ function renderActiveFilters() { chips.push({ kind: "api", label: "API", value: state.historyApi }); if (state.historyKey) chips.push({ kind: "key", label: "Key", value: state.historyKey }); + if (state.historyPath) + chips.push({ kind: "path", label: "Path", value: state.historyPath }); if (!chips.length) { bar.hidden = true; @@ -1220,7 +1282,7 @@ function renderActiveFilters() { .map( (c) => `${c.label} - ${escapeHtml( + ${escapeHtml( c.value )} `; return 0; } @@ -1304,6 +1368,11 @@ function renderHistory() { )}" title="Filter the log by ${escapeHtml( e.api_name )}">${escapeHtml(e.api_name)} + ${escapeHtml( e.status_code )} @@ -1569,9 +1638,16 @@ function setHistoryKey(id) { announce(`${n ?? 0} requests shown`); } +function setHistoryPath(path) { + state.historyPath = state.historyPath === path ? null : path; + const n = renderHistory(); + announce(`${n ?? 0} requests shown`); +} + function clearHistoryFilters() { state.historyApi = null; state.historyKey = null; + state.historyPath = null; state.historyFilter = ""; state.statusChip = "all"; $("history-search").value = ""; @@ -1605,6 +1681,16 @@ function wireApiTable() { scrollToHistory(); return; } + const pathBtn = e.target.closest(".path-filter-btn"); + if (pathBtn) { + state.historyApi = pathBtn.closest("tr.detail-row") + ? state.openApi + : state.historyApi; + state.historyPath = pathBtn.dataset.path; + renderHistory(); + scrollToHistory(); + return; + } const row = e.target.closest("tr.api-row"); if (row) toggleApi(row.dataset.api); }); @@ -1707,6 +1793,7 @@ function wireHistory() { const x = e.target.closest(".filter-x"); if (!x) return; if (x.dataset.clear === "api") state.historyApi = null; + else if (x.dataset.clear === "path") state.historyPath = null; else state.historyKey = null; writeHash(); renderHistory(); @@ -1724,6 +1811,11 @@ function wireHistory() { setHistoryApi(apiBtn.dataset.filterApi); return; } + const pathBtn = e.target.closest("[data-filter-path]"); + if (pathBtn) { + setHistoryPath(pathBtn.dataset.filterPath); + return; + } const keyBtn = e.target.closest("[data-filter-key]"); if (keyBtn) setHistoryKey(keyBtn.dataset.filterKey); }); @@ -1746,7 +1838,7 @@ function wireShortcuts() { disarmAll(); return; } - if (state.historyApi || state.historyKey) { + if (state.historyApi || state.historyKey || state.historyPath) { clearHistoryFilters(); return; } diff --git a/nya/server/app.py b/nya/server/app.py index 0a6272a..325f747 100644 --- a/nya/server/app.py +++ b/nya/server/app.py @@ -5,14 +5,13 @@ import argparse import contextlib +import logging import os -import sys import time from pathlib import Path import uvicorn from fastapi import FastAPI, Request -from loguru import logger from starlette.middleware.cors import CORSMiddleware from starlette.responses import JSONResponse, Response @@ -25,6 +24,7 @@ RELOAD_DEBOUNCE_SECONDS, WATCH_FILE, ) +from ..common.logging import configure_logging from ..common.models import ProxyRequest from ..config.manager import ConfigManager from ..core.proxy import NyaProxyCore @@ -33,8 +33,11 @@ from ..services.state import load_state, resolve_state_path, save_state from .auth import AuthManager, AuthMiddleware -logger.remove() -logger.add(sys.stderr, level="INFO") +logger = logging.getLogger(__name__) + +# Applied at import so Uvicorn's startup lines share the format too; the +# configured level and file sink are applied again once config is loaded. +configure_logging() class NyaProxyApp: @@ -261,19 +264,10 @@ def init_logging(self) -> None: Initialize logging. """ log_config = self.config.get_logging_config() - logger.remove() # Remove default logger - if not log_config.get("enabled", True): - return - - logger.add( - sys.stderr, - level=log_config.get("level", "INFO").upper(), - ) - logger.add( - log_config.get("log_file", "app.log"), - level=log_config.get("level", "INFO").upper(), - rotation="10 MB", - retention=5, + configure_logging( + level=log_config.get("level", "INFO"), + log_file=log_config.get("log_file", "app.log"), + enabled=log_config.get("enabled", True), ) def init_metrics_collector(self) -> None: @@ -627,6 +621,9 @@ def main(): reload_includes=None if args.no_reload else [WATCH_FILE], timeout_keep_alive=30, server_header=False, + # Uvicorn's default config would replace the shared handlers with its + # own formatters; None leaves our interceptor in place. + log_config=None, # Forwarded client addresses are resolved by NyaProxy after checking # server.trusted_proxies. Letting Uvicorn do this first would allow a # direct client to influence request.client.host. diff --git a/nya/services/lb.py b/nya/services/lb.py index b2a588c..73d885b 100644 --- a/nya/services/lb.py +++ b/nya/services/lb.py @@ -2,10 +2,12 @@ Load balancer for selecting API keys based on various strategies. """ +import logging import random from typing import Callable, Dict, List, Optional, TypeVar -from loguru import logger +logger = logging.getLogger(__name__) + T = TypeVar("T") diff --git a/nya/services/metrics.py b/nya/services/metrics.py index 3b357fd..7a12aea 100644 --- a/nya/services/metrics.py +++ b/nya/services/metrics.py @@ -10,7 +10,7 @@ import time from collections import defaultdict, deque -from typing import Any, Deque, Dict, List +from typing import Any, Deque, Dict, List, Optional from prometheus_client import ( CONTENT_TYPE_LATEST, @@ -122,8 +122,16 @@ def __init__(self) -> None: # ----------------------------------------------------------------- write - def record_request(self, api_name: str, api_key: str) -> None: - """Record a request being sent to an upstream API.""" + def record_request( + self, api_name: str, api_key: str, path: Optional[str] = None + ) -> None: + """ + Record a request being sent to an upstream API. + + ``path`` is kept in the history buffer only, never as a Prometheus + label: paths are unbounded, and one label per distinct path would grow + the metric series without limit. + """ key_id = mask_secret(api_key) now = time.time() @@ -137,12 +145,18 @@ def record_request(self, api_name: str, api_key: str) -> None: "type": "request", "api_name": api_name, "key_id": key_id, + "path": path or "/", "timestamp": now, } ) def record_response( - self, api_name: str, api_key: str, status_code: int, elapsed: float + self, + api_name: str, + api_key: str, + status_code: int, + elapsed: float, + path: Optional[str] = None, ) -> None: """Record a response received from an upstream API.""" self._responses.labels(api=api_name, status=str(status_code)).inc() @@ -156,6 +170,7 @@ def record_response( "key_id": mask_secret(api_key), "status_code": status_code, "elapsed_ms": elapsed * 1000, + "path": path or "/", "timestamp": time.time(), } ) diff --git a/nya/services/state.py b/nya/services/state.py index 7067e60..40c2e04 100644 --- a/nya/services/state.py +++ b/nya/services/state.py @@ -14,12 +14,14 @@ import hashlib import json +import logging import os import tempfile from pathlib import Path from typing import Any, Dict, Optional, Union -from loguru import logger +logger = logging.getLogger(__name__) + STATE_VERSION = 1 diff --git a/nya/utils/header.py b/nya/utils/header.py index 124b683..dcfe8d0 100644 --- a/nya/utils/header.py +++ b/nya/utils/header.py @@ -3,14 +3,16 @@ """ import ipaddress +import logging import re from typing import Any, Dict, Iterable, Optional, Set, Union from httpx import Headers -from loguru import logger from ..common.constants import EXCLUDED_REQUEST_HEADERS +logger = logging.getLogger(__name__) + class HeaderUtils: """ diff --git a/nya/utils/substitution.py b/nya/utils/substitution.py index 1ea27c0..9dc84ea 100644 --- a/nya/utils/substitution.py +++ b/nya/utils/substitution.py @@ -7,13 +7,15 @@ """ import json +import logging import re from typing import Any, Dict, List, Union import jmespath import orjson from jmespath.exceptions import JMESPathError -from loguru import logger + +logger = logging.getLogger(__name__) __all__ = ["apply_body_substitutions"] diff --git a/pyproject.toml b/pyproject.toml index e68e2cd..d76c42a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -30,7 +30,6 @@ dependencies = [ "watchfiles>=1.0.0", "jmespath>=1.1.0", "orjson>=3.11,<4", - "loguru>=0.7.3", "prometheus-client>=0.25.0", "nacho-python[remote,schema,server]>=1.0.0", ] diff --git a/tests/e2e/conftest.py b/tests/e2e/conftest.py index e48f1ac..63e600b 100644 --- a/tests/e2e/conftest.py +++ b/tests/e2e/conftest.py @@ -191,6 +191,7 @@ def start_proxy( queue_max_size: int = 20, max_workers: int = 3, dashboard_enabled: bool = False, + trusted_proxies: tuple[str, ...] = (), extra_api_config: str = "", keys: tuple = UPSTREAM_KEYS, endpoint_override: str | None = None, @@ -210,6 +211,7 @@ def start_proxy( log_file: {log_path} dashboard: enabled: {str(dashboard_enabled).lower()} + trusted_proxies: [{", ".join(f'"{p}"' for p in trusted_proxies)}] cors: allow_origins: ["*"] allow_credentials: false diff --git a/tests/e2e/test_http_fidelity.py b/tests/e2e/test_http_fidelity.py index 155abc8..930b173 100644 --- a/tests/e2e/test_http_fidelity.py +++ b/tests/e2e/test_http_fidelity.py @@ -82,3 +82,68 @@ def test_untrusted_forwarded_for_cannot_evade_ip_quota(proxy_server): assert first.status_code == 200 assert second.status_code == 429 + + +def test_trusted_proxy_applies_quota_per_forwarded_client(proxy_server): + """ + Behind a trusted reverse proxy, quotas must apply to the real client. + + The socket peer is the proxy, so without this every user shares one + bucket. Note the uvicorn access log always shows the peer address — the + resolved client is only observable through behaviour like this. + """ + proxy_url = proxy_server( + ip_rate_limit="2/m", + queue_expiry_seconds=1, + trusted_proxies=("127.0.0.1/32", "::1/128"), + ) + + # Two requests from one client consume that client's quota. + for _ in range(2): + response = httpx.get( + f"{proxy_url}/api/mock/v1/quota", + headers=proxy_headers(**{"X-Forwarded-For": "203.0.113.10"}), + timeout=5, + ) + assert response.status_code == 200 + + exhausted = httpx.get( + f"{proxy_url}/api/mock/v1/quota", + headers=proxy_headers(**{"X-Forwarded-For": "203.0.113.10"}), + timeout=5, + ) + assert exhausted.status_code == 429, "the forwarded client was not rate limited" + + # A different client must still have its own quota. + other = httpx.get( + f"{proxy_url}/api/mock/v1/quota", + headers=proxy_headers(**{"X-Forwarded-For": "203.0.113.99"}), + timeout=5, + ) + assert other.status_code == 200, ( + "a second client shared the first client's quota, so the forwarded " + "address was ignored and everyone is bucketed as the proxy" + ) + + +def test_x_real_ip_is_honoured_from_a_trusted_proxy(proxy_server): + """nginx's X-Real-IP alone is enough; X-Forwarded-For is not required.""" + proxy_url = proxy_server( + ip_rate_limit="1/m", + queue_expiry_seconds=1, + trusted_proxies=("127.0.0.1/32", "::1/128"), + ) + + first = httpx.get( + f"{proxy_url}/api/mock/v1/quota", + headers=proxy_headers(**{"X-Real-IP": "198.51.100.7"}), + timeout=5, + ) + second = httpx.get( + f"{proxy_url}/api/mock/v1/quota", + headers=proxy_headers(**{"X-Real-IP": "198.51.100.8"}), + timeout=5, + ) + + assert first.status_code == 200 + assert second.status_code == 200, "X-Real-IP from a trusted proxy was ignored" diff --git a/tests/unit/test_core_request.py b/tests/unit/test_core_request.py index c3f589f..2d4d023 100644 --- a/tests/unit/test_core_request.py +++ b/tests/unit/test_core_request.py @@ -17,9 +17,11 @@ async def test_request_executor_normal_streaming_proxy_and_metrics_paths(monkeyp metrics = SimpleNamespace( requests=[], responses=[], - record_request=lambda api, key: metrics.requests.append((api, key)), - record_response=lambda api, key, status, elapsed: metrics.responses.append( - (api, key, status) + record_request=lambda api, key, path=None: metrics.requests.append( + (api, key, path) + ), + record_response=lambda api, key, status, elapsed, path=None: ( + metrics.responses.append((api, key, status, path)) ), ) executor = RequestExecutor(config, metrics) @@ -37,7 +39,9 @@ async def fake_execute_request(request, timeout): executor.execute_request = fake_execute_request response = await executor.execute(request) assert response.body == b"hello" - assert metrics.requests == [("mock", "key-a")] + # The path travels with the metric so the dashboard can group by it. + assert metrics.requests == [("mock", "key-a", request.trail_path)] + assert metrics.responses[0][3] == request.trail_path assert metrics.responses[0][:3] == ("mock", "key-a", 200) async def fake_stream(request, timeout): diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py new file mode 100644 index 0000000..51282b8 --- /dev/null +++ b/tests/unit/test_logging.py @@ -0,0 +1,185 @@ +""" +One log format for the whole process. + +Everything — NyaProxy, Uvicorn, Starlette, watchfiles — logs through the +standard library, so a single root handler covers all of it. These tests pin +the parts that are easy to regress: the shared format, the configured level +actually winning, and third-party loggers not smuggling in their own. +""" + +import logging +import logging.handlers + +import pytest + +from nya.common.logging import DATE_FORMAT, LOG_FORMAT, Formatter, configure_logging + + +@pytest.fixture(autouse=True) +def restore_logging(): + """Leave global logging state as it was found.""" + yield + configure_logging(level="INFO") + + +def capture() -> list: + """ + Attach a capturing handler and return the list it fills. + + Must be called *after* configure_logging: that replaces the root + handlers, which would otherwise drop this one. + """ + lines: list = [] + + class ListHandler(logging.Handler): + def emit(self, record): + lines.append(self.format(record)) + + handler = ListHandler() + handler.setFormatter(Formatter(color=False)) + logging.getLogger().addHandler(handler) + return lines + + +def test_third_party_records_share_the_format(): + configure_logging(level="DEBUG") + captured = capture() + + logging.getLogger("uvicorn.access").info('127.0.0.1 - "GET /health" 200') + + assert len(captured) == 1 + assert "| INFO | uvicorn.access - " in captured[0] + assert '"GET /health" 200' in captured[0] + + +def test_nyaproxy_records_share_the_same_format(): + configure_logging(level="DEBUG") + captured = capture() + + logging.getLogger("nya.server.app").info("Setting up generic proxy routes") + + assert ( + "| INFO | nya.server.app - Setting up generic proxy routes" in captured[0] + ) + + +def test_format_omits_function_and_line(): + """ + The logger name says which subsystem spoke; anything worth locating + precisely arrives with a traceback that carries the exact position. + """ + assert "%(name)s" in LOG_FORMAT + assert "funcName" not in LOG_FORMAT + assert "lineno" not in LOG_FORMAT + assert "%(asctime)s" in LOG_FORMAT and "msecs" in LOG_FORMAT + assert DATE_FORMAT == "%Y-%m-%d %H:%M:%S" + + +def test_levels_are_rendered_padded(): + configure_logging(level="DEBUG") + captured = capture() + std = logging.getLogger("uvicorn.error") + + std.warning("warned") + std.error("failed") + + assert "| WARNING |" in captured[0] + assert "| ERROR |" in captured[1] + + +def test_configured_level_also_quietens_third_party_loggers(): + configure_logging(level="WARNING") + captured = capture() + + logging.getLogger("uvicorn.access").info("chatty access line") + logging.getLogger("uvicorn.error").warning("real problem") + + assert len(captured) == 1 + assert "real problem" in captured[0] + + +def test_a_preset_level_on_a_third_party_logger_does_not_win(): + """ + Uvicorn sets an explicit level on its loggers (that is what --log-level + does), and an explicit level beats the root's. Left in place it would + silently override the level from the configuration file. + """ + noisy = logging.getLogger("uvicorn.access") + noisy.setLevel(logging.WARNING) + + configure_logging(level="DEBUG") + captured = capture() + noisy.info("access line that the preset WARNING would have swallowed") + + assert len(captured) == 1 + assert noisy.level == logging.NOTSET + + +def test_third_party_handlers_are_removed_so_records_are_not_doubled(): + noisy = logging.getLogger("uvicorn.access") + noisy.addHandler(logging.StreamHandler()) + + configure_logging(level="INFO") + + assert noisy.handlers == [] + assert noisy.propagate is True + + +def test_exception_info_is_rendered(): + configure_logging(level="DEBUG") + captured = capture() + + try: + raise ValueError("upstream exploded") + except ValueError: + logging.getLogger("nya.core.queue").exception("handler failed") + + assert "handler failed" in captured[0] + assert "ValueError: upstream exploded" in captured[0] + + +def test_file_sink_rotates_and_is_not_coloured(tmp_path): + log_file = tmp_path / "app.log" + configure_logging(level="INFO", log_file=str(log_file)) + + logging.getLogger("nya.server.app").info("written to file") + + handlers = [ + h + for h in logging.getLogger().handlers + if isinstance(h, logging.handlers.RotatingFileHandler) + ] + assert len(handlers) == 1 + assert handlers[0].maxBytes == 10 * 1024 * 1024 + assert handlers[0].backupCount == 5 + + contents = log_file.read_text() + assert "| INFO | nya.server.app - written to file" in contents + assert "\033[" not in contents # never colour a file + + +def test_repeated_configuration_does_not_duplicate_handlers(): + configure_logging(level="INFO") + configure_logging(level="INFO") + configure_logging(level="DEBUG") + + assert len(logging.getLogger().handlers) == 1 + + +def test_disabled_logging_emits_nothing(): + configure_logging(enabled=False) + captured = capture() + + logging.getLogger("uvicorn.access").info("should not appear") + logging.getLogger("nya.server.app").error("nor should this") + + assert captured == [] + + +def test_colour_is_applied_only_when_asked(): + record = logging.LogRecord( + "nya.test", logging.WARNING, __file__, 1, "careful", None, None + ) + + assert "\033[33m" in Formatter(color=True).format(record) + assert "\033[" not in Formatter(color=False).format(record) diff --git a/tests/unit/test_server_app.py b/tests/unit/test_server_app.py index 1719b4d..ee5a08c 100644 --- a/tests/unit/test_server_app.py +++ b/tests/unit/test_server_app.py @@ -1,5 +1,6 @@ import argparse import contextlib +import logging import os import time from types import SimpleNamespace @@ -265,10 +266,15 @@ async def test_init_services_calls_each_initializer_in_order(monkeypatch): def test_warn_if_unauthenticated_fires_only_on_public_bind(monkeypatch): - from loguru import logger - messages = [] - sink_id = logger.add(lambda m: messages.append(str(m)), level="WARNING") + + class _Capture(logging.Handler): + def emit(self, record): + messages.append(record.getMessage()) + + handler = _Capture(level=logging.WARNING) + root = logging.getLogger() + root.addHandler(handler) try: instance = make_app_instance() @@ -299,7 +305,7 @@ def test_warn_if_unauthenticated_fires_only_on_public_bind(monkeypatch): instance._warn_if_unauthenticated() assert any("no master key is configured" in m for m in messages) finally: - logger.remove(sink_id) + root.removeHandler(handler) @pytest.mark.asyncio diff --git a/uv.lock b/uv.lock index 93a1efd..c6701ed 100644 --- a/uv.lock +++ b/uv.lock @@ -481,19 +481,6 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/5f/5d/3dcec2884ba1b0806d1408612555c38dd5d68e90156b59f75f6e36435c3a/librt-0.13.0-cp314-cp314t-win_arm64.whl", hash = "sha256:2f281549a4c52ac7bb97997f14353f8bd0e53a34ca0dad1c905cfd0b4a58ae99", size = 110771, upload-time = "2026-07-08T12:26:12.303Z" }, ] -[[package]] -name = "loguru" -version = "0.7.3" -source = { registry = "https://pypi.org/simple" } -dependencies = [ - { name = "colorama", marker = "sys_platform == 'win32'" }, - { name = "win32-setctime", marker = "sys_platform == 'win32'" }, -] -sdist = { url = "https://files.pythonhosted.org/packages/3a/05/a1dae3dffd1116099471c643b8924f5aa6524411dc6c63fdae648c4f1aca/loguru-0.7.3.tar.gz", hash = "sha256:19480589e77d47b8d85b2c827ad95d49bf31b0dcde16593892eb51dd18706eb6", size = 63559, upload-time = "2024-12-06T11:20:56.608Z" } -wheels = [ - { url = "https://files.pythonhosted.org/packages/0c/29/0348de65b8cc732daa3e33e67806420b2ae89bdce2b04af740289c5c6c8c/loguru-0.7.3-py3-none-any.whl", hash = "sha256:31a33c10c8e1e10422bfd431aeb5d351c7cf7fa671e3c4df004162264b28220c", size = 61595, upload-time = "2024-12-06T11:20:54.538Z" }, -] - [[package]] name = "mypy" version = "2.3.0" @@ -592,7 +579,6 @@ dependencies = [ { name = "fastapi" }, { name = "httpx", extra = ["socks"] }, { name = "jmespath" }, - { name = "loguru" }, { name = "nacho-python", extra = ["remote", "schema", "server"] }, { name = "orjson" }, { name = "prometheus-client" }, @@ -618,7 +604,6 @@ requires-dist = [ { name = "fastapi", specifier = ">=0.139.0" }, { name = "httpx", extras = ["socks"], specifier = ">=0.28.0" }, { name = "jmespath", specifier = ">=1.1.0" }, - { name = "loguru", specifier = ">=0.7.3" }, { name = "mypy", marker = "extra == 'lint'", specifier = ">=1.14.0" }, { name = "nacho-python", extras = ["remote", "schema", "server"], specifier = ">=1.0.0" }, { name = "orjson", specifier = ">=3.11,<4" }, @@ -1494,12 +1479,3 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/2d/3f/73e511ecf2496ceac57dd4ed8388efe2bcf0769338a2dbf242c8366ae87e/websockets-16.1.1-pp311-pypy311_pp73-win_amd64.whl", hash = "sha256:56cd5fc4f10a9ea8aa0804bddb7b42506cf9e136046f3b4c27de8fec9e2ecba5", size = 180330, upload-time = "2026-07-17T22:51:02.603Z" }, { url = "https://files.pythonhosted.org/packages/be/4d/2d0d67834092e354d2b0498f014a41249a89556bc406cf86f3e1557bb463/websockets-16.1.1-py3-none-any.whl", hash = "sha256:6abbd3e82c731c8e531714466acd5d87b5e88ac3243465337ba71d68e23ae7e3", size = 173814, upload-time = "2026-07-17T22:51:04.184Z" }, ] - -[[package]] -name = "win32-setctime" -version = "1.2.0" -source = { registry = "https://pypi.org/simple" } -sdist = { url = "https://files.pythonhosted.org/packages/b3/8f/705086c9d734d3b663af0e9bb3d4de6578d08f46b1b101c2442fd9aecaa2/win32_setctime-1.2.0.tar.gz", hash = "sha256:ae1fdf948f5640aae05c511ade119313fb6a30d7eabe25fef9764dca5873c4c0", size = 4867, upload-time = "2024-12-07T15:28:28.314Z" } -wheels = [ - { url = "https://files.pythonhosted.org/packages/e1/07/c6fe3ad3e685340704d314d765b7912993bcb8dc198f0e7a89382d37974b/win32_setctime-1.2.0-py3-none-any.whl", hash = "sha256:95d644c4e708aba81dc3704a116d8cbc974d70b3bdb8be1d150e36be6e9d1390", size = 4083, upload-time = "2024-12-07T15:28:26.465Z" }, -]