gitea-admin/gh-christianlouis-docuelevate
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge pull request #707 from christianlouis/copilot/fix-debug-logging-issue

Browse Source 
feat: fix DEBUG logging and add LOG_LEVEL/LOG_FORMAT/LOG_SYSLOG for standard log management
This commit is contained in:
Christian Krakau-Louis
2026-03-16 11:00:41 +01:00
committed by GitHub
parent 5e986cb6d6 df1fa51800
commit 740d18555b
7 changed files with 656 additions and 2 deletions
Download Patch File Download Diff File Expand all files Collapse all files
app/auth.py
+81 -2
View File
@@ -125,8 +125,17 @@ def get_current_user(request: Request):
# Check for Bearer token auth first (API tokens)
api_user = getattr(request.state, "api_token_user", None)
if isinstance(api_user, dict):
logger.debug("[AUTH] get_current_user: resolved from API token (user_id=%s)", api_user.get("id"))
return api_user
return request.session.get("user")
session_user = request.session.get("user")
if session_user:
logger.debug(
"[AUTH] get_current_user: resolved from session (user=%s)",
session_user.get("preferred_username") or session_user.get("email") or session_user.get("id"),
)
else:
logger.debug("[AUTH] get_current_user: no user in session or API token")
return session_user
def _resolve_bearer_user(request: Request, db: Session) -> dict | None:
@@ -141,10 +150,12 @@ def _resolve_bearer_user(request: Request, db: Session) -> dict | None:
"""
auth_header = request.headers.get("authorization", "")
if not isinstance(auth_header, str) or not auth_header.startswith("Bearer "):
logger.debug("[AUTH] _resolve_bearer_user: no Bearer token in Authorization header")
return None
raw_token = auth_header[7:]
if not raw_token or not isinstance(raw_token, str):
logger.debug("[AUTH] _resolve_bearer_user: empty or invalid token after 'Bearer ' prefix")
return None
from app.api.api_tokens import hash_token
@@ -153,8 +164,15 @@ def _resolve_bearer_user(request: Request, db: Session) -> dict | None:
token_hash = hash_token(raw_token)
db_token = db.query(ApiToken).filter(ApiToken.token_hash == token_hash, ApiToken.is_active.is_(True)).first()
if db_token is None:
logger.debug("[AUTH] _resolve_bearer_user: no active API token matched the provided hash")
return None
logger.debug(
"[AUTH] _resolve_bearer_user: matched API token id=%s owner=%s",
db_token.id,
db_token.owner_id,
)
# Update usage tracking
try:
db_token.last_used_at = datetime.now(timezone.utc)
@@ -205,16 +223,18 @@ def require_login(func):
@wraps(func)
async def wrapper(request: Request, *args, **kwargs):
url_path = urlparse(str(request.url)).path
# Check session auth first
if request.session.get("user"):
logger.debug("[AUTH] require_login: session auth OK for %s", url_path)
if inspect.iscoroutinefunction(func):
return await func(*args, request=request, **kwargs)
else:
return func(*args, request=request, **kwargs)
# Fall back to Bearer token auth for API endpoints
url_path = urlparse(str(request.url)).path
if url_path.startswith("/api/"):
logger.debug("[AUTH] require_login: no session, trying Bearer token for %s", url_path)
try:
from app.database import SessionLocal
@@ -228,17 +248,22 @@ def require_login(func):
if api_user:
request.state.api_token_user = api_user
logger.debug(
"[AUTH] require_login: Bearer token auth OK for %s (user=%s)", url_path, api_user.get("id")
)
if inspect.iscoroutinefunction(func):
return await func(*args, request=request, **kwargs)
else:
return func(*args, request=request, **kwargs)
logger.debug("[AUTH] require_login: no valid auth for API endpoint %s — returning 401", url_path)
return JSONResponse(
status_code=status.HTTP_401_UNAUTHORIZED,
content={"error": "Not authenticated"},
)
# Non-API endpoint with no session — redirect to login
logger.debug("[AUTH] require_login: no session for %s — redirecting to /login", url_path)
request.session["redirect_after_login"] = str(request.url)
return RedirectResponse(url="/login", status_code=status.HTTP_302_FOUND)
@@ -307,9 +332,15 @@ async def login(request: Request):
async def oauth_login(request: Request):
"""Handle OAuth login flow"""
if not OAUTH_CONFIGURED:
logger.debug("[AUTH] oauth_login: OAuth not configured — redirecting to /login")
return RedirectResponse(url="/login?error=OAuth+not+configured", status_code=status.HTTP_302_FOUND)
redirect_uri = request.url_for("oauth_callback")
logger.debug(
"[AUTH] oauth_login: initiating Authentik OAuth redirect_uri=%s session_keys=%s",
redirect_uri,
list(request.session.keys()),
)
return await oauth.authentik.authorize_redirect(request, redirect_uri)
@@ -324,13 +355,23 @@ async def social_login(request: Request, provider: str):
A redirect to the provider's authorization page, or back to /login on error.
"""
if provider not in SOCIAL_PROVIDERS:
logger.debug(
"[AUTH] social_login: unknown provider=%r (registered=%s)", provider, list(SOCIAL_PROVIDERS.keys())
)
return RedirectResponse(url="/login?error=Unknown+social+provider", status_code=status.HTTP_302_FOUND)
redirect_uri = request.url_for("social_callback", provider=provider)
oauth_client = getattr(oauth, provider, None)
if oauth_client is None:
logger.debug("[AUTH] social_login: provider=%r registered but OAuth client not configured", provider)
return RedirectResponse(url="/login?error=Provider+not+configured", status_code=status.HTTP_302_FOUND)
logger.debug(
"[AUTH] social_login: initiating %s OAuth, redirect_uri=%s session_keys=%s",
provider,
redirect_uri,
list(request.session.keys()),
)
return await oauth_client.authorize_redirect(request, redirect_uri)
@@ -389,27 +430,39 @@ async def social_callback(request: Request, provider: str, db: Session = Depends
A redirect to the user's original destination or the upload page.
"""
if provider not in SOCIAL_PROVIDERS:
logger.debug("[AUTH] social_callback: unknown provider=%r", provider)
return RedirectResponse(url="/login?error=Unknown+social+provider", status_code=status.HTTP_302_FOUND)
oauth_client = getattr(oauth, provider, None)
if oauth_client is None:
logger.debug("[AUTH] social_callback: provider=%r not configured", provider)
return RedirectResponse(url="/login?error=Provider+not+configured", status_code=status.HTTP_302_FOUND)
try:
logger.debug("[AUTH] social_callback: exchanging auth code for provider=%s", provider)
token = await oauth_client.authorize_access_token(request)
# Try standard OIDC userinfo first, fall back to token-embedded userinfo
raw_userinfo = token.get("userinfo")
if not raw_userinfo:
logger.debug("[AUTH] social_callback: no userinfo in token, fetching from userinfo endpoint")
try:
resp = await oauth_client.userinfo(token=token)
raw_userinfo = resp if isinstance(resp, dict) else resp.json() if hasattr(resp, "json") else {}
except Exception:
logger.debug("[AUTH] social_callback: userinfo endpoint failed, using empty dict", exc_info=True)
raw_userinfo = {}
user_data = _normalize_social_userinfo(provider, token, raw_userinfo)
logger.debug(
"[AUTH] social_callback: normalized user_data email=%s sub=%s provider=%s",
user_data.get("email"),
user_data.get("sub"),
provider,
)
if not user_data.get("email"):
logger.debug("[AUTH] social_callback: no email in user_data — aborting")
return RedirectResponse(
url="/login?error=Could+not+retrieve+email+from+provider",
status_code=status.HTTP_302_FOUND,
@@ -442,21 +495,29 @@ async def social_callback(request: Request, provider: str, db: Session = Depends
)
# Mobile app flow: issue an inline API token and redirect back to the app.
logger.debug(
"[MOBILE] social_callback: checking for mobile redirect (session has mobile_redirect_uri=%s)",
"mobile_redirect_uri" in request.session,
)
mobile_resp = _create_mobile_redirect(request, db)
if mobile_resp:
logger.info("[MOBILE] social_callback: returning mobile redirect response for provider=%s", provider)
return mobile_resp
if user_id:
profile = db.query(_UserProfile).filter(_UserProfile.user_id == user_id).first()
if profile and not profile.onboarding_completed:
logger.debug("[AUTH] social_callback: user=%s needs onboarding, redirecting", user_id)
post_onboarding = request.session.pop("redirect_after_login", "/upload")
request.session["post_onboarding_redirect"] = post_onboarding
return RedirectResponse(url="/onboarding", status_code=status.HTTP_302_FOUND)
redirect_url = request.session.pop("redirect_after_login", "/upload")
logger.debug("[AUTH] social_callback: login complete, redirecting to %s", redirect_url)
return RedirectResponse(url=redirect_url, status_code=status.HTTP_302_FOUND)
except Exception as e:
logger.warning("[SECURITY] SOCIAL_LOGIN_FAILURE provider=%s error=%s", provider, type(e).__name__)
logger.debug("[AUTH] social_callback: full exception for provider=%s", provider, exc_info=True)
return RedirectResponse(
url="/login?error=Social+login+failed.+Please+try+again.", status_code=status.HTTP_302_FOUND
)
@@ -561,15 +622,23 @@ def _ensure_user_profile(db: Session, user_data: dict, is_admin: bool = False) -
async def oauth_callback(request: Request, db: Session = Depends(get_db)):
"""Handle OAuth callback from provider"""
try:
logger.debug("[AUTH] oauth_callback: exchanging authorization code for token")
token = await oauth.authentik.authorize_access_token(request)
userinfo = token.get("userinfo")
if not userinfo:
logger.debug("[AUTH] oauth_callback: no userinfo in token response — aborting")
return RedirectResponse(
url="/login?error=Failed+to+retrieve+user+information", status_code=status.HTTP_302_FOUND
)
# Store user info in session
user_data = dict(userinfo)
logger.debug(
"[AUTH] oauth_callback: received userinfo email=%s sub=%s groups=%s",
user_data.get("email"),
user_data.get("sub"),
user_data.get("groups", []),
)
# Add Gravatar picture if no picture is provided
if not user_data.get("picture") and user_data.get("email"):
@@ -584,6 +653,12 @@ async def oauth_callback(request: Request, db: Session = Depends(get_db)):
groups = user_data.get("groups", [])
admin_group = (settings.admin_group_name or "admin").strip().lower()
is_admin = admin_group in [group.lower() for group in groups]
logger.debug(
"[AUTH] oauth_callback: admin group check — looking for %r in %s → is_admin=%s",
admin_group,
[g.lower() for g in groups],
is_admin,
)
# Set is_admin flag (defaults to False for OAuth users unless they're in admin group)
user_data["is_admin"] = is_admin
@@ -623,15 +698,18 @@ async def oauth_callback(request: Request, db: Session = Depends(get_db)):
if user_id:
profile = db.query(_UserProfile).filter(_UserProfile.user_id == user_id).first()
if profile and not profile.onboarding_completed:
logger.debug("[AUTH] oauth_callback: user=%s needs onboarding, redirecting", user_id)
post_onboarding = request.session.pop("redirect_after_login", "/upload")
request.session["post_onboarding_redirect"] = post_onboarding
return RedirectResponse(url="/onboarding", status_code=status.HTTP_302_FOUND)
# Redirect to original destination or default
redirect_url = request.session.pop("redirect_after_login", "/upload")
logger.debug("[AUTH] oauth_callback: login complete, redirecting to %s", redirect_url)
return RedirectResponse(url=redirect_url, status_code=status.HTTP_302_FOUND)
except Exception as e:
logger.warning(f"[SECURITY] OAUTH_LOGIN_FAILURE error={type(e).__name__}")
logger.debug("[AUTH] oauth_callback: full exception details", exc_info=True)
return RedirectResponse(url=f"/login?error=Authentication+failed:+{str(e)}", status_code=status.HTTP_302_FOUND)
@@ -931,6 +1009,7 @@ async def logout(request: Request, db: Session = Depends(get_db)):
username = "unknown"
if isinstance(user, dict):
username = user.get("preferred_username") or user.get("email") or "unknown"
logger.debug("[AUTH] logout: clearing session for user=%s client_ip=%s", username, get_client_ip(request))
logger.info(f"[SECURITY] LOGOUT user={username}")
try:
from app.utils.audit_service import record_event
app/config.py
+45
View File
@@ -48,6 +48,51 @@ class Settings(BaseSettings):
workdir: str
debug: bool = False # Default to False
# Logging level for the application. Accepts standard Python level names:
# DEBUG, INFO, WARNING, ERROR, CRITICAL. When *debug* is True and
# *log_level* has not been explicitly set, the effective level is forced to
# DEBUG so that all ``logger.debug()`` calls produce output.
log_level: str = Field(
default="INFO",
description=(
"Python logging level for the application root logger. "
"Accepts: DEBUG, INFO, WARNING, ERROR, CRITICAL. "
"When DEBUG=True and LOG_LEVEL is not explicitly set, "
"the effective level is automatically lowered to DEBUG."
),
)
# Log output format. ``text`` is the human-readable default.
# ``json`` emits one JSON object per line, ideal for log collectors
# (Promtail, Fluentd, Filebeat, Datadog agent) and SIEM ingestion.
log_format: str = Field(
default="text",
description=(
"Log output format: 'text' (human-readable, default) or "
"'json' (structured JSON lines for SIEM / log aggregation)."
),
)
# Optional syslog forwarding for application logs (not just audit events).
# When enabled, a Python SysLogHandler is added to the root logger so that
# every log message is also sent to the configured syslog receiver.
log_syslog_enabled: bool = Field(
default=False,
description="Forward application logs to a syslog receiver in addition to stdout.",
)
log_syslog_host: str = Field(
default="localhost",
description="Hostname or IP of the syslog receiver for application logs.",
)
log_syslog_port: int = Field(
default=514,
description="Port of the syslog receiver for application logs.",
)
log_syslog_protocol: str = Field(
default="udp",
description="Protocol for syslog transport: 'udp' or 'tcp'.",
)
# Making Dropbox optional
dropbox_enabled: bool = Field(
default=True,
app/main.py
+111
View File
@@ -1,8 +1,11 @@
#!/usr/bin/env python3
import json as _json_mod
import logging
import os
import pathlib
from contextlib import asynccontextmanager
from datetime import datetime as _dt
from datetime import timezone as _tz
from fastapi import FastAPI, HTTPException, Request, status
from fastapi.middleware.cors import CORSMiddleware
@@ -36,6 +39,114 @@ from app.views import router as frontend_router
# Explicitly include the files router
from app.views.files import router as files_router
# ---------------------------------------------------------------------------
# Configure Python root logging level early so that *all* loggers (including
# those already created via ``logging.getLogger(__name__)`` in other modules)
# respect the configured level.
#
# Standard behaviour (matches Django, Flask, 12-factor conventions):
# • ``LOG_LEVEL`` env var takes precedence when explicitly set.
# • When ``DEBUG=True`` and ``LOG_LEVEL`` is **not** set, the effective
# level is automatically lowered to ``DEBUG``.
# • Default (neither flag set): ``INFO``.
#
# ``LOG_FORMAT=json`` enables structured JSON lines on stdout, suitable for
# Promtail, Fluentd, Filebeat, Datadog, Splunk UF, or any log collector.
#
# ``LOG_SYSLOG_ENABLED=true`` adds a Python SysLogHandler so that every log
# message is also forwarded to the configured syslog receiver — useful for
# traditional (non-container) deployments and centralised SIEM ingestion.
#
# Noisy third-party loggers (httpx, httpcore, authlib, etc.) are pinned to
# WARNING when the app-level is DEBUG to keep output useful.
# ---------------------------------------------------------------------------
_explicit_log_level = os.environ.get("LOG_LEVEL")
if settings.debug and _explicit_log_level is None:
_effective_level = "DEBUG"
else:
_effective_level = settings.log_level.upper()
_effective_level_int = getattr(logging, _effective_level, logging.INFO)
class _JsonFormatter(logging.Formatter):
"""Emit one JSON object per log line for machine consumption.
Fields emitted: ``timestamp``, ``level``, ``logger``, ``message``,
``module``, ``funcName``, ``lineno``, and — when present — ``exc_info``.
Compatible with Grafana Loki, Splunk, ELK, Datadog, and most SIEM tools.
"""
def format(self, record: logging.LogRecord) -> str:
log_entry: dict = {
"timestamp": _dt.fromtimestamp(record.created, tz=_tz.utc).isoformat(),
"level": record.levelname,
"logger": record.name,
"message": record.getMessage(),
"module": record.module,
"funcName": record.funcName,
"lineno": record.lineno,
}
if record.exc_info and record.exc_info[1] is not None:
log_entry["exc_info"] = self.formatException(record.exc_info)
return _json_mod.dumps(log_entry, default=str)
# Choose formatter based on LOG_FORMAT setting
if settings.log_format.lower() == "json":
_handler = logging.StreamHandler()
_handler.setFormatter(_JsonFormatter())
logging.root.handlers = [_handler]
logging.root.setLevel(_effective_level_int)
else:
logging.basicConfig(
level=_effective_level_int,
format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
datefmt="%Y-%m-%d %H:%M:%S",
force=True,
)
# Optional: forward application logs to a syslog receiver
if settings.log_syslog_enabled:
import logging.handlers as _lh
import socket as _socket
_proto = settings.log_syslog_protocol.lower()
_socktype = _socket.SOCK_STREAM if _proto == "tcp" else _socket.SOCK_DGRAM
_syslog_handler = _lh.SysLogHandler(
address=(settings.log_syslog_host, settings.log_syslog_port),
socktype=_socktype,
)
_syslog_handler.setLevel(_effective_level_int)
# Use the same formatter as stdout (text or JSON)
if settings.log_format.lower() == "json":
_syslog_handler.setFormatter(_JsonFormatter())
else:
_syslog_handler.setFormatter(logging.Formatter("%(name)s - %(levelname)s - %(message)s"))
logging.root.addHandler(_syslog_handler)
# Keep noisy third-party loggers quiet at DEBUG level
if _effective_level_int <= logging.DEBUG:
for _noisy in (
"httpx",
"httpcore",
"authlib",
"urllib3",
"hpack",
"multipart",
"watchfiles",
):
logging.getLogger(_noisy).setLevel(logging.WARNING)
_startup_logger = logging.getLogger(__name__)
_startup_logger.info(
"Root logging level set to %s (debug=%s, format=%s, syslog=%s)",
_effective_level,
settings.debug,
settings.log_format,
settings.log_syslog_enabled,
)
# Load configuration from .env for the session key
config = Config(".env")
# Use settings.session_secret which has proper validation