diff --git a/src/deepseek_cursor_proxy/logging.py b/src/deepseek_cursor_proxy/logging.py new file mode 100644 index 0000000..13ccf0e --- /dev/null +++ b/src/deepseek_cursor_proxy/logging.py @@ -0,0 +1,96 @@ +from __future__ import annotations + +import logging as stdlib_logging +import sys +import threading +from typing import Any + + +LOG = stdlib_logging.getLogger("deepseek_cursor_proxy") + +DEFAULT_INFO_LOG_FORMAT = "%(message)s" +DEFAULT_WARNING_LOG_FORMAT = "%(levelname)s %(message)s" +VERBOSE_LOG_FORMAT = "%(asctime)s %(levelname)s %(message)s" + + +class ConsoleLogFormatter(stdlib_logging.Formatter): + def __init__(self, *, verbose: bool) -> None: + super().__init__() + self.verbose = verbose + self._verbose_formatter = stdlib_logging.Formatter(VERBOSE_LOG_FORMAT) + self._info_formatter = stdlib_logging.Formatter(DEFAULT_INFO_LOG_FORMAT) + self._warning_formatter = stdlib_logging.Formatter(DEFAULT_WARNING_LOG_FORMAT) + + def format(self, record: stdlib_logging.LogRecord) -> str: + if self.verbose: + return self._verbose_formatter.format(record) + if record.levelno <= stdlib_logging.INFO: + return self._info_formatter.format(record) + return self._warning_formatter.format(record) + + +def configure_logging(*, verbose: bool) -> None: + handler = stdlib_logging.StreamHandler() + handler.setFormatter(ConsoleLogFormatter(verbose=verbose)) + stdlib_logging.basicConfig( + level=stdlib_logging.INFO, + handlers=[handler], + force=True, + ) + + +class TerminalSpinner: + hide_cursor = "\x1b[?25l" + show_cursor = "\x1b[?25h" + frames = ("⠋", "⠙", "⠹", "⠸", "⠼", "⠴", "⠦", "⠧", "⠇", "⠏") + + def __init__( + self, + *, + enabled: bool, + text: str, + stream: Any | None = None, + interval: float = 0.12, + ) -> None: + self.stream = stream if stream is not None else sys.stderr + self.enabled = enabled and bool(getattr(self.stream, "isatty", lambda: False)()) + self.text = text + self.interval = interval + self._stop = threading.Event() + self._thread: threading.Thread | None = None + self._visible = False + + def start(self) -> "TerminalSpinner": + if not self.enabled or self._thread is not None: + return self + self.stream.write(self.hide_cursor) + self.stream.flush() + self._thread = threading.Thread(target=self._run, daemon=True) + self._thread.start() + return self + + def stop(self) -> None: + if not self.enabled: + return + self._stop.set() + if self._thread is not None: + self._thread.join(timeout=1) + self._thread = None + if self._visible: + self.stream.write("\r" + (" " * self._clear_width()) + "\r") + self.stream.flush() + self._visible = False + self.stream.write(self.show_cursor) + self.stream.flush() + + def _run(self) -> None: + index = 0 + while not self._stop.is_set(): + self.stream.write("\r" + self.text.format(frame=self.frames[index])) + self.stream.flush() + self._visible = True + index = (index + 1) % len(self.frames) + self._stop.wait(self.interval) + + def _clear_width(self) -> int: + return max(len(self.text.format(frame=frame)) for frame in self.frames) diff --git a/src/deepseek_cursor_proxy/server.py b/src/deepseek_cursor_proxy/server.py index ae4181e..2594689 100644 --- a/src/deepseek_cursor_proxy/server.py +++ b/src/deepseek_cursor_proxy/server.py @@ -5,7 +5,6 @@ import gzip from http.client import HTTPException import json -import logging from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer from pathlib import Path import sys @@ -21,21 +20,22 @@ default_config_path, default_reasoning_content_path, ) +from .logging import ( + LOG, + TerminalSpinner, + configure_logging, +) from .reasoning_store import ReasoningStore, conversation_scope from .streaming import CursorReasoningDisplayAdapter, StreamAccumulator from .trace import TraceRequest, TraceWriter from .tunnel import NgrokTunnel, local_tunnel_target from .transform import ( - PreparedRequest, RECOVERY_NOTICE_CONTENT, prepare_upstream_request, rewrite_response_body, ) -LOG = logging.getLogger("deepseek_cursor_proxy") - - class RequestBodyTooLarge(ValueError): pass @@ -237,13 +237,19 @@ def do_POST(self) -> None: headers=upstream_headers, ) - log_send_summary(prepared) + if self.config.verbose: + log_send_summary(prepared) + spinner = TerminalSpinner( + enabled=bool(prepared.payload.get("stream")) and not self.config.verbose, + text="└ {frame}", + ).start() try: if self.config.verbose: LOG.info("forwarding to %s", upstream_url) response = urlopen(request, timeout=self.config.request_timeout) except HTTPError as exc: + spinner.stop() LOG.warning( "request failed upstream_status=%s stream=%s elapsed_ms=%s", exc.code, @@ -259,6 +265,7 @@ def do_POST(self) -> None: ) return except URLError as exc: + spinner.stop() LOG.warning( "upstream request failed elapsed_ms=%s reason=%s", elapsed_ms(started), @@ -271,55 +278,63 @@ def do_POST(self) -> None: ) self._finish_trace(trace, "upstream_error", http_status=502) return + except Exception: + spinner.stop() + raise - with response: - upstream_status = getattr(response, "status", 200) - if self.config.verbose: - LOG.info( - "upstream response status=%s stream=%s elapsed_ms=%s", - upstream_status, - bool(prepared.payload.get("stream")), - elapsed_ms(started), - ) - if prepared.payload.get("stream"): - sent_response = self._proxy_streaming_response( - response, - prepared.original_model, - prepared.payload["messages"], - prepared.cache_namespace, - prepared.recovery_notice, - trace=trace, - record_response_scope=prepared.record_response_scope, - record_response_messages=prepared.record_response_messages, - record_response_contexts=prepared.record_response_contexts, - ) - else: - sent_response = self._proxy_regular_response( - response, - prepared.original_model, - prepared.payload["messages"], - prepared.cache_namespace, - prepared.recovery_notice, - trace=trace, - record_response_scope=prepared.record_response_scope, - record_response_messages=prepared.record_response_messages, - record_response_contexts=prepared.record_response_contexts, - ) - if not sent_response.sent: + try: + with response: + upstream_status = getattr(response, "status", 200) + if self.config.verbose: + LOG.info( + "upstream response status=%s stream=%s elapsed_ms=%s", + upstream_status, + bool(prepared.payload.get("stream")), + elapsed_ms(started), + ) + if prepared.payload.get("stream"): + sent_response = self._proxy_streaming_response( + response, + prepared.original_model, + prepared.payload["messages"], + prepared.cache_namespace, + prepared.recovery_notice, + trace=trace, + record_response_scope=prepared.record_response_scope, + record_response_messages=prepared.record_response_messages, + record_response_contexts=prepared.record_response_contexts, + ) + else: + sent_response = self._proxy_regular_response( + response, + prepared.original_model, + prepared.payload["messages"], + prepared.cache_namespace, + prepared.recovery_notice, + trace=trace, + record_response_scope=prepared.record_response_scope, + record_response_messages=prepared.record_response_messages, + record_response_contexts=prepared.record_response_contexts, + ) + if not sent_response.sent: + spinner.stop() + self._finish_trace( + trace, + "client_disconnected", + http_status=upstream_status, + stream=bool(prepared.payload.get("stream")), + ) + return + spinner.stop() + log_stats_summary(sent_response.usage) self._finish_trace( trace, - "client_disconnected", + "completed", http_status=upstream_status, stream=bool(prepared.payload.get("stream")), ) - return - log_stats_summary(sent_response.usage) - self._finish_trace( - trace, - "completed", - http_status=upstream_status, - stream=bool(prepared.payload.get("stream")), - ) + finally: + spinner.stop() def _start_trace(self, request_path: str) -> TraceRequest | None: writer = self.trace_writer @@ -997,26 +1012,31 @@ def log_cursor_request( ) -> None: model = str(payload.get("model") or config.upstream_model) LOG.info( - "┌ cursor model=%s effort=%s messages=%s tools=%s", + "┌ request model=%s effort=%s messages=%s", model, config.reasoning_effort, format_count(message_count(payload)), - format_count(tool_count(payload)), ) -def log_context_summary(prepared: PreparedRequest) -> None: +def log_context_summary(prepared: Any) -> None: + status = context_status(prepared) + if status == "ok": + LOG.info( + "├ context status=ok reasoning_context=%s", + format_count(prepared.patched_reasoning_messages), + ) + return LOG.info( - "├ context filled=%s missing=%s recovered=%s dropped=%s status=%s", - format_count(prepared.patched_reasoning_messages), + "├ context status=%s missing=%s recovered=%s dropped=%s", + status, format_count(prepared.missing_reasoning_messages), format_count(prepared.recovered_reasoning_messages), format_count(prepared.recovery_dropped_messages), - context_status(prepared), ) -def log_send_summary(prepared: PreparedRequest) -> None: +def log_send_summary(prepared: Any) -> None: LOG.info( "├ send user_msgs=%s messages=%s tools=%s reasoning_content=%s", format_count(user_message_count(prepared.payload)), @@ -1036,7 +1056,7 @@ def log_stats_summary(usage: dict[str, Any] | None) -> None: ) -def context_status(prepared: PreparedRequest) -> str: +def context_status(prepared: Any) -> str: if prepared.recovered_reasoning_messages: return "recovered" if prepared.missing_reasoning_messages: @@ -1216,13 +1236,11 @@ def warn_if_insecure_upstream(url: str) -> None: def main(argv: list[str] | None = None) -> int: - logging.basicConfig( - level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s" - ) args = build_arg_parser().parse_args(argv) try: config = ProxyConfig.from_file(config_path=args.config_path) except ValueError as exc: + configure_logging(verbose=bool(args.verbose)) LOG.error("%s", exc) return 2 updates: dict[str, Any] = {} @@ -1267,6 +1285,7 @@ def main(argv: list[str] | None = None) -> int: if updates: config = replace(config, **updates) + configure_logging(verbose=config.verbose) warn_if_insecure_upstream(config.upstream_base_url) store = ReasoningStore( config.reasoning_content_path, @@ -1291,37 +1310,8 @@ def main(argv: list[str] | None = None) -> int: server.reasoning_store = store server.trace_writer = trace_writer - LOG.info("listening on http://%s:%s/v1", config.host, config.port) - LOG.info( - "forwarding to %s/chat/completions default_model=%s", - config.upstream_base_url, - config.upstream_model, - ) - LOG.info( - ( - "thinking=%s reasoning_effort=%s display_reasoning=%s " - "collapsible_reasoning=%s missing_reasoning_strategy=%s " - "reasoning_content_path=%s" - ), - config.thinking, - config.reasoning_effort, - config.display_reasoning, - config.collapsible_reasoning, - config.missing_reasoning_strategy, - config.reasoning_content_path, - ) - if config.verbose: - LOG.info("logging mode=verbose metadata=detailed bodies=true") - LOG.warning( - "verbose logging enabled; prompts and code may be written to stdout" - ) - else: - LOG.info("logging mode=normal metadata=safe_summaries bodies=false") - if trace_writer is not None: - LOG.info("trace session directory: %s", trace_writer.session_dir) - LOG.warning("trace logging enabled; prompts and code will be written to disk") - tunnel: NgrokTunnel | None = None + public_url: str | None = None if config.ngrok: target_url = local_tunnel_target(config.host, config.port) tunnel = NgrokTunnel(target_url) @@ -1332,8 +1322,39 @@ def main(argv: list[str] | None = None) -> int: server.server_close() store.close() return 2 - LOG.info("ngrok tunnel forwarding %s -> %s", public_url, target_url) - LOG.info("api base url: %s/v1", public_url.rstrip("/")) + local_base_url = f"http://{config.host}:{config.port}/v1" + api_base_url = ( + f"{public_url.rstrip('/')}/v1" if public_url is not None else local_base_url + ) + + LOG.info( + "default_model: %s (%s, %s)", + config.upstream_model, + "thinking" if config.thinking == "enabled" else "no thinking", + config.reasoning_effort, + ) + + if config.verbose: + display_reasoning = "off" + if config.display_reasoning: + display_reasoning = ( + "on (collapsible)" if config.collapsible_reasoning else "on" + ) + LOG.info("display_reasoning: %s", display_reasoning) + LOG.info("missing_reasoning_strategy: %s", config.missing_reasoning_strategy) + LOG.info("reasoning_cache: %s", config.reasoning_content_path) + LOG.warning( + "verbose logging enabled; prompts and code may be written to stdout" + ) + if trace_writer is not None: + LOG.info("trace_dir: %s", trace_writer.session_dir) + LOG.warning("trace logging enabled; prompts and code will be written to disk") + if public_url is None and not config.ngrok: + LOG.info("public_tunnel: off") + if config.verbose: + LOG.info("upstream_url: %s/chat/completions", config.upstream_base_url) + LOG.info("local_base_url: %s", local_base_url) + LOG.info("api_base_url: %s", api_base_url) try: server.serve_forever() except KeyboardInterrupt: diff --git a/src/deepseek_cursor_proxy/transform.py b/src/deepseek_cursor_proxy/transform.py index 40d5cdc..0053d98 100644 --- a/src/deepseek_cursor_proxy/transform.py +++ b/src/deepseek_cursor_proxy/transform.py @@ -3,11 +3,11 @@ from dataclasses import dataclass, field import hashlib import json -import logging import re from typing import Any from .config import ProxyConfig +from .logging import LOG from .reasoning_store import ( ReasoningStore, conversation_scope, @@ -20,9 +20,6 @@ from .streaming import fold_reasoning_into_content -LOG = logging.getLogger("deepseek_cursor_proxy") - - SUPPORTED_REQUEST_FIELDS = { "model", "messages", diff --git a/src/deepseek_cursor_proxy/tunnel.py b/src/deepseek_cursor_proxy/tunnel.py index d2a09c5..005b134 100644 --- a/src/deepseek_cursor_proxy/tunnel.py +++ b/src/deepseek_cursor_proxy/tunnel.py @@ -2,7 +2,6 @@ from dataclasses import dataclass import json -import logging import shutil import subprocess import time @@ -10,8 +9,7 @@ from urllib.error import URLError from urllib.request import urlopen - -LOG = logging.getLogger("deepseek_cursor_proxy") +from .logging import LOG DEFAULT_NGROK_API_URL = "http://127.0.0.1:4040/api" diff --git a/tests/test_server.py b/tests/test_server.py index 7788229..b898aa8 100644 --- a/tests/test_server.py +++ b/tests/test_server.py @@ -14,7 +14,9 @@ from io import BytesIO import gzip import json +import logging from pathlib import Path +import re import threading import time from types import SimpleNamespace @@ -24,6 +26,10 @@ from urllib.request import Request, urlopen from deepseek_cursor_proxy.config import ProxyConfig +from deepseek_cursor_proxy.logging import ( + ConsoleLogFormatter, + TerminalSpinner, +) from deepseek_cursor_proxy.reasoning_store import ReasoningStore from deepseek_cursor_proxy.server import ( DeepSeekProxyHandler, @@ -80,6 +86,21 @@ def flush(self) -> None: raise BrokenPipeError("test disconnect") +class _FakeConsole: + def __init__(self, *, tty: bool) -> None: + self.tty = tty + self.writes: list[str] = [] + + def isatty(self) -> bool: + return self.tty + + def write(self, text: str) -> None: + self.writes.append(text) + + def flush(self) -> None: + return + + def _make_handler_stub(wfile: object, **config: object) -> DeepSeekProxyHandler: handler = object.__new__(DeepSeekProxyHandler) handler.server = SimpleNamespace( @@ -119,6 +140,76 @@ def test_cli_boolean_flags_have_on_and_off_forms(self) -> None: self.assertTrue(args.cors) self.assertEqual(args.trace_dir, Path("/tmp/dcp-traces")) + def test_default_console_logging_hides_info_prefix_and_timestamp(self) -> None: + formatter = ConsoleLogFormatter(verbose=False) + info_record = logging.LogRecord( + "deepseek_cursor_proxy", + logging.INFO, + __file__, + 1, + "listening on %s", + ("http://127.0.0.1:9000/v1",), + None, + ) + warning_record = logging.LogRecord( + "deepseek_cursor_proxy", + logging.WARNING, + __file__, + 1, + "trace logging enabled", + (), + None, + ) + + self.assertEqual( + formatter.format(info_record), + "listening on http://127.0.0.1:9000/v1", + ) + self.assertEqual( + formatter.format(warning_record), "WARNING trace logging enabled" + ) + + def test_verbose_console_logging_shows_timestamp_and_level(self) -> None: + formatter = ConsoleLogFormatter(verbose=True) + record = logging.LogRecord( + "deepseek_cursor_proxy", + logging.INFO, + __file__, + 1, + "listening on %s", + ("http://127.0.0.1:9000/v1",), + None, + ) + + self.assertRegex( + formatter.format(record), + re.compile( + r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} INFO listening on " + ), + ) + + def test_terminal_spinner_animates_only_for_tty(self) -> None: + tty = _FakeConsole(tty=True) + spinner = TerminalSpinner( + enabled=True, text="└ {frame}", stream=tty, interval=0.001 + ).start() + deadline = time.monotonic() + 0.2 + while time.monotonic() < deadline and not tty.writes: + time.sleep(0.001) + spinner.stop() + + output = "".join(tty.writes) + self.assertIn(TerminalSpinner.hide_cursor, output) + self.assertIn("└ ⠋", output) + self.assertIn(TerminalSpinner.show_cursor, output) + self.assertTrue(output.endswith(TerminalSpinner.show_cursor)) + + non_tty = _FakeConsole(tty=False) + TerminalSpinner( + enabled=True, text="└ {frame}", stream=non_tty, interval=0.001 + ).start().stop() + self.assertEqual(non_tty.writes, []) + def test_read_response_body_decodes_gzip_and_deflate(self) -> None: self.assertEqual( read_response_body(_FakeResponse(gzip.compress(b'{"ok":1}'), "gzip")), @@ -461,10 +552,12 @@ def test_normal_logging_summarizes_without_bodies_or_keys(self) -> None: time.sleep(0.01) output = "\n".join(captured.output) self.assertEqual(status, 200) - # Single-line stage records keep the log readable. - for marker in ("┌ cursor", "├ context", "├ send", "└ stats"): - self.assertIn(marker, output) - self.assertNotIn("hi", output.split("┌ cursor")[1].split("\n")[0]) + self.assertIn("┌ request model=deepseek-v4-pro effort=max messages=1", output) + self.assertIn("├ context status=ok reasoning_context=0", output) + self.assertIn("└ stats", output) + self.assertNotIn(" tools=", output) + self.assertNotIn("├ send", output) + self.assertNotIn("hi", output.split("┌ request")[1].split("\n")[0]) self.assertNotIn("sk-from-cursor", output) def test_verbose_logging_includes_bodies_but_redacts_api_key(self) -> None: