refactor(logging): simplified prints and add spinner (#37)

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)

src/deepseek_cursor_proxy/server.py

@@ -5,7 +5,6 @@ from dataclasses import dataclass, replace
 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 @@ from .config import (
     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 @@ class DeepSeekProxyHandler(BaseHTTPRequestHandler):
             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 @@ class DeepSeekProxyHandler(BaseHTTPRequestHandler):
             )
             return
         except URLError as exc:
+            spinner.stop()
             LOG.warning(
                 "upstream request failed elapsed_ms=%s reason=%s",
                 elapsed_ms(started),
@@ -271,55 +278,63 @@ class DeepSeekProxyHandler(BaseHTTPRequestHandler):
             )
             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:

src/deepseek_cursor_proxy/transform.py

@@ -3,11 +3,11 @@ from __future__ import annotations
 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 .reasoning_store import (
 from .streaming import fold_reasoning_into_content
 
 
-LOG = logging.getLogger("deepseek_cursor_proxy")
-
-
 SUPPORTED_REQUEST_FIELDS = {
     "model",
     "messages",

src/deepseek_cursor_proxy/tunnel.py

@@ -2,7 +2,6 @@ from __future__ import annotations
 
 from dataclasses import dataclass
 import json
-import logging
 import shutil
 import subprocess
 import time
@@ -10,8 +9,7 @@ from typing import Any
 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"

tests/test_server.py

@@ -14,7 +14,9 @@ from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer
 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.error import HTTPError
 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 @@ class _BrokenPipeWfile:
         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 @@ class CliAndHelperTests(unittest.TestCase):
         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 @@ class HttpBoundaryTests(unittest.TestCase):
                 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: