Unified logging behaviour
Build & Publish to GHCR / build (push) Successful in 43s

- Logger doesn't start with log level DEBUG by default, instead reads a environment variable
- Secret handler raises exceptions instead of using the module os to exit
- Added extensive debug logging
This commit is contained in:
florian committed 2025-10-17 08:59:27 +02:00
1 parent 4590386b3e
commit 101e208a8f
6 files changed
+66 -58

No files matched your search

+28 -7
View File
@@ -7,11 +7,10 @@ from pydantic import BaseModel
from validator import is_valid_platform,is_valid_token,verify_api_key
from secret_handler import encrypt_token
from db import get_db, create_connection_pool, close_connection_pool, start_healthcheck_thread
from logger_handler import setup_logger
from logger_handler import setup_logger, LOG_LEVEL
import uuid
from hashlib import sha256
import uvicorn
from uvicorn_logging_config import LOGGING_CONFIG
from contextlib import asynccontextmanager
from metrics_server import REQUEST_COUNTER
import asyncio
@@ -23,7 +22,10 @@ api_key_header = APIKeyHeader(name="X-API-Key")
def hash_token(token: str) -> str:
return sha256(token.encode()).hexdigest()
logger.debug(f"Hashing token: {token}")
result = sha256(token.encode()).hexdigest()
logger.debug(f"Hashed token result: {result}")
return result
class TokenRequest(BaseModel):
token : str
@@ -58,22 +60,28 @@ api = FastAPI(
@api.middleware("http")
async def prometheus_middleware(request: Request, call_next):
status = 500
logger.debug(f"Incoming request: {request.method} {request.url.path}")
try:
response = await call_next(request)
status = response.status_code
logger.debug(f"Request processed with status {status}")
except Exception:
logger.exception(f"Exception during request processing: {e}")
raise
finally:
REQUEST_COUNTER.labels(request.method, request.url.path, status).inc()
logger.debug(f"Prometheus counter incremented for {request.method} {request.url.path} {status}")
return response
@api.get("/health", tags=["Health"])
def return_health(db=Depends(get_db)):
logger.debug("Health check initiated")
try:
cursor = db.cursor()
cursor.execute("SELECT 1")
cursor.fetchone()
db_status = "ok"
logger.debug("Database health check passed")
except Exception as e:
logger.error(f"Health check DB failed: {e}")
db_status = "error"
@@ -85,15 +93,19 @@ def return_health(db=Depends(get_db)):
def verify_api_key_dependency(db=Depends(get_db), api_key: str = Depends(api_key_header)) -> int:
logger.debug(f"Verifying API key: {api_key}")
cursor = db.cursor()
cursor.execute("SELECT user_id, api_key FROM users WHERE status = 'active'")
for user_id, hashed_key in cursor.fetchall():
if verify_api_key(api_key=api_key, hashed=hashed_key):
logger.debug(f"API key verified for user_id={user_id}")
return user_id
logger.warning("API key verification failed")
raise HTTPException(status_code=403, detail="Unauthorized here")
@api.exception_handler(StarletteHTTPException)
async def custom_http_exception_handler(request,exc):
logger.debug(f"Handling HTTP exception: {exc}")
if exc.status_code == 404:
return JSONResponse(
status_code=401,
@@ -111,11 +123,14 @@ def register_token(
user_id: int = Depends(verify_api_key_dependency)
):
logger.info(f"Registering token for user_id={user_id}, platform={request_data.platform}")
logger.debug(f"Request data: {request_data}")
if not is_valid_platform(request_data.platform) or not is_valid_token(request_data.token):
logger.warning(f"Invalid platform or token for user_id={user_id}")
raise HTTPException(status_code=403,detail="Unathorized")
secure_token = encrypt_token(request_data.token)
hashed_token = hash_token(request_data.token)
logger.debug(f"Secure token: {secure_token}, Hashed token: {hashed_token}")
try:
cursor = db.cursor()
@@ -123,8 +138,10 @@ def register_token(
"SELECT * FROM device_tokens WHERE user_id=%s AND hashed_token=%s",
(user_id,hashed_token))
existing = cursor.fetchone()
logger.debug(f"Existing token fetched: {existing}")
if existing:
logger.debug(f"Updating existing token for user_id={user_id}")
cursor.execute("""
UPDATE device_tokens
SET platform=%s, app_ver=%s, locale=%s, topics=%s, last_seen_at=NOW()
@@ -138,7 +155,7 @@ def register_token(
))
else:
token_id = str(uuid.uuid4())
logger.info(f"Creating new entry user_id={user_id}, token_id={token_id}")
logger.debug(f"Creating new entry user_id={user_id}, token_id={token_id}")
cursor.execute("""
INSERT INTO device_tokens
(token_id, user_id, platform, token, hashed_token, status, app_ver, locale, topics, created_at)
@@ -157,6 +174,7 @@ def register_token(
db.commit()
logger.info(f"Success: Registering token for user_id={user_id}, platform={request_data.platform}")
except Exception as e:
logger.exception(f"Failed to register token for user_id={user_id}: {e}")
raise HTTPException(status_code=500, detail=str(e))
return {"status":"registered"}
@@ -170,6 +188,7 @@ def unregister_token(
):
logger.info(f"Unregistering token for user_id={user_id}, platform={request_data.platform}")
hashed_token = hash_token(request_data.token)
logger.debug(f"Hashed token for removal: {hashed_token}")
try:
cursor = db.cursor()
cursor.execute("""
@@ -177,20 +196,22 @@ def unregister_token(
SET status=%s, last_seen_at=NOW()
WHERE hashed_token=%s
""", ('expired', hashed_token))
except Exception as e:
logger.exception(f"Failed to unregister token for user_id={user_id}: {e}")
raise HTTPException(status_code=500, detail=str(e))
logger.info(f"Success: Unregistering token for user_id={user_id}, platform={request_data.platform}")
return {"status":"unregistered"}
async def start_servers():
config_main = uvicorn.Config("main:api", host="0.0.0.0", port=8100, log_config=LOGGING_CONFIG, log_level="info")
config_metrics = uvicorn.Config("metrics_server:metrics_api", host="0.0.0.0", port=9000, log_level="info")
logger.debug("Starting servers...")
config_main = uvicorn.Config("main:api", host="0.0.0.0", port=8100, log_level=LOG_LEVEL.lower())
config_metrics = uvicorn.Config("metrics_server:metrics_api", host="0.0.0.0", port=9000, log_level=LOG_LEVEL.lower())
server_main = uvicorn.Server(config_main)
server_metrics = uvicorn.Server(config_metrics)
await asyncio.gather(server_main.serve(), server_metrics.serve())
logger.debug("Servers started")
if __name__ == "__main__":
asyncio.run(start_servers())