Skip to content

feat(server): add per-request table log for chat completions - #8

Open
cdryzun wants to merge 1 commit into
Sliverkiss:masterfrom
cdryzun:feat/table-request-logging
Open

feat(server): add per-request table log for chat completions#8
cdryzun wants to merge 1 commit into
Sliverkiss:masterfrom
cdryzun:feat/table-request-logging

Conversation

@cdryzun

@cdryzun cdryzun commented Aug 25, 2026

Copy link
Copy Markdown

Summary

Adds a table-formatted request log for /v1/chat/completions. Each call prints one row to stdout with sequence number, time, model, mode (stream/sync), status, time-to-first-token, output token count, tokens/sec and total duration. This makes slow or throttled requests visible without digging through raw nginx access logs.

Why

The service currently logs only its startup line and any upstream transport errors. There is no per-request visibility into latency or token usage, which makes it hard to tell when a specific model or account is underperforming. The table gives an operator a quick per-request picture.

What changed

  • internal/server/logging.go (new): a chatStatsReader that wraps the upstream SSE stream. It counts streamed output tokens (by UTF-8 runes) and records the time to the first content frame. A logChatRow helper prints the aligned table row.
  • internal/server/handler.go: wires the logger into the stream and non-stream paths. Error paths (bad request, upstream parse failure, all accounts unavailable) now also emit a row with the real HTTP status instead of being silent. /healthz is excluded, and chat completions no longer duplicate the plain one-line log.
  • internal/server/logging_test.go (new): unit tests for SSE token counting (including reasoning_content), usage-field precedence, TTFB baseline, and model parsing.
  • Dockerfile: sets GOPROXY to goproxy.cn so the container build can fetch modules behind the GFW. Unrelated to logging, included separately for completeness.

Notes

  • Streamed token counts are estimates based on character count; non-streamed calls use the exact completion_tokens from the upstream usage field. The two are not directly comparable.
  • Time-to-first-token is measured from when the request enters the handler, not from when the upstream connection is established.

Print one aligned table row per /v1/chat/completions call to stdout,
covering sequence, time, model, mode, status, TTFB, output tokens,
tokens-per-second and total duration, so operators can spot slow or
throttled requests at a glance.

- measure real time-to-first-token from request entry via content-aware
  SSE parsing; count streamed output tokens by UTF-8 runes and use the
  upstream usage field when present
- emit a table row on error paths (bad request, upstream parse error,
  all-accounts-unavailable) with the real HTTP status code
- keep the SSE stream passthrough unchanged for the client
- silence /healthz and avoid duplicate logging of chat completions
- add unit tests for SSE token counting, TTFB baseline and model parsing
- Dockerfile: point GOPROXY at goproxy.cn to fix module downloads
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant