Refactor logging: three-tier levels (INFO/DEBUG/TRACE), ECS-aware format, and per-request USAGE logging

[dcox761]

The current logging approach uses a binary DEBUG flag with if DEBUG: logger.info(...) throughout the codebase. This has several issues:

1. No granularity — it's either all debug output or nothing. Per-chunk streaming logs (very verbose) are at the same level as request summaries.
2. Incorrect log levels — debug information is logged at INFO level, so DEBUG=true floods INFO-level log aggregators.
3. Duplicate timestamps in CloudWatch — when running in ECS/Fargate, the log format string adds timestamps that duplicate what CloudWatch already provides.
4. No request attribution — there's no way to correlate requests with users or track usage patterns without external tooling.
5. TRACE_LEVEL defined in multiple files — the custom level was duplicated across three source files.

Proposed solution

1. Centralise TRACE_LEVEL in setting.py

Register the custom TRACE level (5, below DEBUG at 10) once in setting.py and import it everywhere:

# setting.py
TRACE_LEVEL = 5
logging.addLevelName(TRACE_LEVEL, "TRACE")

2. Three-tier logging

• INFO (default) — startup, errors, CORS warnings, and USAGE summary per request
• DEBUG (DEBUG=true) — request/response details, model resolution, tool calls, cache points
• TRACE (TRACE=true) — per-chunk streaming data, raw request/response bodies, request headers

Only the api logger hierarchy is affected — boto3/botocore/urllib3 stay at INFO:

if TRACE or DEBUG:
    logging.getLogger("api").setLevel(TRACE_LEVEL if TRACE else logging.DEBUG)

3. ECS-aware log format

Detect ECS/Fargate via ECS_CONTAINER_METADATA_URI and skip log formatting (CloudWatch adds its own timestamps and metadata). Outside ECS, use human-readable format:

_log_kwargs = {"level": logging.INFO}
if not os.environ.get("ECS_CONTAINER_METADATA_URI"):
    _log_kwargs["format"] = "%(asctime)s [%(levelname)s] %(message)s"
logging.basicConfig(**_log_kwargs)

4. Lazy %s formatting and isEnabledFor guards

All logger.debug() calls use %s lazy formatting instead of f-strings. Expensive debug operations (JSON serialisation, dict formatting) are guarded with isEnabledFor:

# Before (eager f-string evaluation even when debug is off):
logger.debug(f"Resolved {model_id} → {result}")

# After (lazy — no string formatting unless DEBUG is enabled):
logger.debug("Resolved %s -> %s", model_id, result)

# Expensive operations guarded:
if logger.isEnabledFor(TRACE_LEVEL):
    logger.log(TRACE_LEVEL, "Request body: %s",
               json.dumps(chat_request.model_dump(), indent=2, default=str))

5. Per-request USAGE logging (INFO level)

A structured one-line summary logged after every request completes:

USAGE | user=admin@example.com | chat=abc-123 | model=claude-sonnet-4 | max_tokens=4096 | in=1523 | out=847 | cache_write=0 | cache_read=1200 | ua=OpenAI/Python

User and chat ID are extracted from configurable HTTP headers (empty defaults — only active when configured):

# Optional: configure headers from your upstream proxy
export USAGE_USER_HEADER=x-openwebui-user-email
export USAGE_CHAT_ID_HEADER=x-openwebui-chat-id

6. Improved validation error handler

The validation exception handler now logs error count at WARNING level and optionally logs the rejected request body at TRACE level:

@app.exception_handler(RequestValidationError)
async def validation_exception_handler(request, exc):
    error_count = len(exc.errors()) if hasattr(exc, 'errors') else 'unknown'
    logger.warning("Request validation failed: %s %s - %s error(s)",
                   request.method, request.url.path, error_count)
    if logger.isEnabledFor(TRACE_LEVEL):
        body = (await request.body()).decode("utf-8", errors="replace")[:2000]
        logger.log(TRACE_LEVEL, "Rejected request body: %s", body)
    return PlainTextResponse(str(exc), status_code=400)

New environment variables

Variable	Default	Description
TRACE	false	Enable TRACE-level logging (very verbose)
USAGE_USER_HEADER	""	HTTP header for user identity in USAGE lines
USAGE_CHAT_ID_HEADER	""	HTTP header for chat/session ID in USAGE lines

Files: src/api/setting.py, src/api/app.py, src/api/routers/chat.py, src/api/models/bedrock.py