Chapter 15: Structured Logging#

1. Stop Using print()#

print("user logged in") gets the job done in development. In production, it produces an undated, unlabelled stream of text with no severity, no context, and no way to filter. A crash at 3am gives you nothing useful.

Structured logging adds timestamps, levels, and machine-readable output to every message. Set the level in .env. Rotate logs by size. Write to a file. Filter by severity. Tina4's Log class does all of this without configuration beyond a single environment variable.

2. Basic Usage#

from tina4_python.debug import Log​Log.info("Application started")Log.debug("Request received", path="/api/users", method="GET")Log.warning("Rate limit approaching", remaining=10)Log.error("Database connection failed", host="db.internal", port=5432)

Output:

2026-04-02 09:14:01 [INFO]    Application started2026-04-02 09:14:01 [DEBUG]   Request received path=/api/users method=GET2026-04-02 09:14:01 [WARNING] Rate limit approaching remaining=102026-04-02 09:14:01 [ERROR]   Database connection failed host=db.internal port=5432

Every message includes a UTC timestamp and level. Keyword arguments become structured key-value pairs appended to the message.

3. Log Levels#

There are five severity levels, in ascending order (plus ALL, a filter-only setting):

Setting TINA4_LOG_LEVEL=WARNING hides DEBUG and INFO on the console; WARNING, ERROR, and CRITICAL stay visible. (The log file always records every level regardless; the level gates console output only.)

4. The TINA4LOGLEVEL Environment Variable#

# Development: see everythingTINA4_LOG_LEVEL=ALL​# Staging: see info and aboveTINA4_LOG_LEVEL=INFO​# Production: warnings and errors onlyTINA4_LOG_LEVEL=WARNING

The level is read at startup. Changing it requires a server restart (or, if you implement a reload endpoint, a signal to the process).

The default level is INFO: drop to debug to see everything#

When TINA4_LOG_LEVEL is unset, the console level defaults to INFO (since v3.13.14). On a fresh project Log.info(), Log.warning(), and Log.error() all print to the console; only Log.debug() is filtered out until you lower the level. If your Log.debug() calls seem to do nothing, that's why: raise the verbosity to see them.

For local development, drop the level to debug so every call appears:

# .env - see everything while developingTINA4_LOG_LEVEL=debugTINA4_LOG_OUTPUT=both     # console AND logs/tina4.log

Two more things worth knowing:

• Production keeps console output; it just changes shape. When TINA4_ENV=production, stdout stays on (containers and Kubernetes read PID 1's stdout) but logs switch to uncolored JSON lines instead of human-readable text. Console output is controlled by TINA4_LOG_OUTPUT (stdout / file / both), not by TINA4_ENV; set TINA4_LOG_OUTPUT=file if you want file-only.
• The file always receives every level. logs/tina4.log is written with all levels (and logs/error.log with warnings and errors), independent of the console level. If the console is quiet, tail -f logs/tina4.log still shows the full stream.

Checking whether a level is enabled#

Use Log.is_enabled(level) to skip building an expensive log payload that the current level would hide:

from tina4_python.debug import Log​if Log.is_enabled("debug"):    Log.debug("Query plan", plan=db.explain(query))   # only built when debug is visible

is_enabled returns True when level meets the configured minimum console level (level is case-insensitive). It reflects console (stdout) visibility: the log file still records every level regardless, so this guards what you'd see on the console, not whether anything is written at all.

5. Logging in Route Handlers#

from tina4_python.core.router import get, postfrom tina4_python.debug import Log​@post("/api/orders")async def create_order(request, response):    body = request.body​    Log.info("Order creation started", customer_id=body.get("customer_id"))​    if not body.get("items"):        Log.warning("Order rejected: no items", customer_id=body.get("customer_id"))        return response({"error": "At least one item is required"}, 400)​    try:        # Simulate order processing        order_id = 1001        total = sum(item.get("price", 0) for item in body["items"])​        Log.info("Order created", order_id=order_id, total=total, item_count=len(body["items"]))​        return response({"order_id": order_id, "total": total}, 201)​    except Exception as exc:        Log.error("Order creation failed", error=str(exc), customer_id=body.get("customer_id"))        return response({"error": "Internal server error"}, 500)

Log structured data alongside the message. When something goes wrong you can grep or filter by order_id, customer_id, or error without parsing free-form text.

6. File Output and Log Rotation#

Write logs to a file:

TINA4_LOG_FILE=logs/app.log

Tina4 creates the file (and the logs/ directory) if it does not exist. With an explicit TINA4_LOG_FILE, logs are written to both the file and stdout.

Without an explicit TINA4_LOG_FILE (or TINA4_LOG_OUTPUT), the log file is written only in development (TINA4_DEBUG=true). In production and containers the logger is stdout-only: a logs/tina4.log inside a container just bloats the writable layer and disk, and 12-factor wants logs on stdout for the platform to capture. Setting TINA4_LOG_FILE, or TINA4_LOG_OUTPUT=file/both, always writes a file in any environment.

Enable rotation by size:

TINA4_LOG_FILE=logs/app.logTINA4_LOG_MAX_SIZE=10485760TINA4_LOG_KEEP=5

TINA4_LOG_MAX_SIZE=10485760 rotates the log file when it reaches 10 MB. TINA4_LOG_KEEP=5 keeps the five most recent rotated files before deleting the oldest. These settings cap total log storage at roughly 50 MB.

Rotated files are named app.log.1, app.log.2, and so on.

7. Logging Exceptions#

Log a full exception with stack trace using Log.error and Python's traceback module:

import tracebackfrom tina4_python.debug import Log​try:    result = 1 / 0except Exception as exc:    Log.error(        "Unhandled exception",        error=str(exc),        traceback=traceback.format_exc()    )

Output:

2026-04-02 09:14:01 [ERROR] Unhandled exception error=division by zero traceback=Traceback (most recent call last):  File "src/routes/orders.py", line 34, in create_order    result = 1 / 0ZeroDivisionError: division by zero

The full stack trace is attached as a structured field. Log aggregators can extract, index, and alert on it.

8. Request Logging Middleware#

Log every incoming request automatically:

from tina4_python.debug import Log​async def request_logger(request, response, next_handler):    import time    start = time.monotonic()    result = await next_handler(request, response)    elapsed = round((time.monotonic() - start) * 1000, 2)​    Log.info(        "Request completed",        method=request.method,        path=request.url,        status=getattr(result, "status_code", 200),        duration_ms=elapsed    )​    return result

Register it globally in your app:

from tina4_python.core.router import useuse(request_logger)

Every request now produces a structured log line:

2026-04-02 09:14:01 [INFO] Request completed method=POST path=/api/orders status=201 duration_ms=14.32026-04-02 09:14:02 [INFO] Request completed method=GET path=/api/users status=200 duration_ms=2.1

Filter by path, method, or status code in any log aggregation tool.

9. Log Levels by Environment#

A typical multi-environment setup:

# .env.developmentTINA4_LOG_LEVEL=ALLTINA4_LOG_FILE=​# .env.stagingTINA4_LOG_LEVEL=INFOTINA4_LOG_FILE=logs/staging.logTINA4_LOG_MAX_SIZE=10485760TINA4_LOG_KEEP=3​# .env.productionTINA4_LOG_LEVEL=WARNINGTINA4_LOG_FILE=logs/app.logTINA4_LOG_MAX_SIZE=52428800TINA4_LOG_KEEP=10

Development logs everything to stdout. Staging logs info and above to a rotating file. Production only logs warnings and errors to a large rotating file kept for 10 rotations.

10. Exercise: Add Logging to an Order API#

Add structured logging to an order management API.

Requirements#

1. Create POST /api/shop/orders that:
   • Logs the start of each request with customer_id
   • Logs validation failures at WARNING level
   • Logs successful orders at INFO level with order_id, total, item_count
   • Logs any exceptions at ERROR level with full error context
2. Create GET /api/shop/orders/{order_id} that:
   • Logs cache hits and misses at DEBUG level
   • Logs 404s at WARNING level
3. Set up the request logging middleware globally

Test with:#

# Valid ordercurl -X POST http://localhost:7146/api/shop/orders \  -H "Content-Type: application/json" \  -d '{"customer_id": 1, "items": [{"name": "Keyboard", "price": 79.99}]}'​# Invalid order (no items)curl -X POST http://localhost:7146/api/shop/orders \  -H "Content-Type: application/json" \  -d '{"customer_id": 1}'​# Get ordercurl http://localhost:7146/api/shop/orders/1001

11. Solution#

Create src/routes/shop_orders.py:

import tracebackfrom tina4_python.core.router import get, postfrom tina4_python.debug import Logfrom tina4_python.cache import cache_get, cache_set​ORDER_STORE = {}NEXT_ORDER_ID = 1001​​@post("/api/shop/orders")async def create_shop_order(request, response):    body = request.body    customer_id = body.get("customer_id")​    Log.info("Order creation started", customer_id=customer_id)​    if not body.get("items"):        Log.warning("Order rejected: missing items", customer_id=customer_id)        return response({"error": "At least one item is required"}, 400)​    if not customer_id:        Log.warning("Order rejected: missing customer_id")        return response({"error": "customer_id is required"}, 400)​    try:        global NEXT_ORDER_ID        order_id = NEXT_ORDER_ID        NEXT_ORDER_ID += 1​        items = body["items"]        total = round(sum(item.get("price", 0) for item in items), 2)​        order = {            "order_id": order_id,            "customer_id": customer_id,            "items": items,            "total": total,            "status": "placed"        }        ORDER_STORE[order_id] = order        cache_set(f"order:{order_id}", order, ttl=300)​        Log.info(            "Order created",            order_id=order_id,            customer_id=customer_id,            total=total,            item_count=len(items)        )​        return response(order, 201)​    except Exception as exc:        Log.error(            "Order creation failed",            customer_id=customer_id,            error=str(exc),            traceback=traceback.format_exc()        )        return response({"error": "Internal server error"}, 500)​​@get("/api/shop/orders/{order_id}")async def get_shop_order(request, response):    order_id = int(request.params["order_id"])​    cached = cache_get(f"order:{order_id}")    if cached:        Log.debug("Order cache hit", order_id=order_id)        return response(cached)​    Log.debug("Order cache miss", order_id=order_id)​    order = ORDER_STORE.get(order_id)    if order is None:        Log.warning("Order not found", order_id=order_id)        return response({"error": "Order not found"}, 404)​    cache_set(f"order:{order_id}", order, ttl=300)    return response(order)

12. Gotchas#

1. DEBUG logs flooding production#

Problem: Hundreds of debug messages per second fill the log file and slow the server.

Fix: Set TINA4_LOG_LEVEL=WARNING in production. Debug calls are no-ops when the level is above DEBUG.

2. Logging sensitive data#

Problem: Log.info("User logged in", password=request.body["password"]) writes passwords to the log file.

Fix: Never log passwords, tokens, card numbers, or PII. Log identifiers and metadata only: Log.info("User logged in", user_id=user["id"]).

3. Log file grows without rotation#

Problem: TINA4_LOG_FILE is set but TINA4_LOG_MAX_SIZE is not. The log file grows until the disk is full.

Fix: Always set TINA4_LOG_MAX_SIZE and TINA4_LOG_KEEP alongside TINA4_LOG_FILE in production.

4. Forgetting to log exceptions#

Problem: A route returns 500 but there is no log entry explaining why.

Fix: Wrap the handler body in try/except. Log the exception with Log.error(..., error=str(exc), traceback=traceback.format_exc()) before returning the 500 response.