Skip to content

troubleshooting.md

Latest commit

 

History

History
159 lines (127 loc) · 16 KB

troubleshooting.md

File metadata and controls

159 lines (127 loc) · 16 KB

🛠️ Troubleshooting - Lab 21: Structured Logging and Correlation IDs

Logs not in JSON format

  • Verify python-json-logger is installed correctly
  • Check JsonFormatter configuration includes all required fields
  • Ensure logger level is set to INFO or DEBUG

Check installed package:

(venv) toor@ip-172-31-10-246:~/logging-lab$ python3 -m pip show python-json-logger
Name: python-json-logger
Version: 3.3.0
Summary: JSON Log Formatter for the Python Logging Package
Home-page: 
Author: 
Author-email: 
License: BSD-2-Clause License
Location: /home/toor/logging-lab/venv/lib/python3.12/site-packages
Requires: 
Required-by:

Correlation ID not propagating

  • Verify X-Correlation-ID header is being set in outgoing requests
  • Check that before_request middleware is extracting header correctly
  • Confirm g.correlation_id is accessible in request context

Check recent relevant logs:

(venv) toor@ip-172-31-10-246:~/logging-lab$ tail -20 app.log
{"timestamp": "2026-04-12T17:22:11.649593+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "verify-1744478531", "message": "Starting full order workflow", "method": "POST", "path": "/api/orders/full", "payload_keys": ["product_id", "user_id"]}
{"timestamp": "2026-04-12T17:22:11.704952+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "verify-1744478531", "message": "Inventory check completed in upstream service", "inventory_result": {"available": true, "product_id": "test-prod", "quantity": 50}}
{"timestamp": "2026-04-12T17:22:11.705207+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "verify-1744478531", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "f7e0d184-b30c-4830-b9cb-e8bebfdd734a", "product_id": "test-prod", "user_id": 1, "duration_ms": 55.65}
127.0.0.1 - - [12/Apr/2026 17:22:11] "POST /api/orders/full HTTP/1.1" 201 -
{"timestamp": "2026-04-12T17:23:29.119174+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Starting full order workflow", "method": "POST", "path": "/api/orders/full", "payload_keys": ["product_id", "user_id"]}
{"timestamp": "2026-04-12T17:23:29.174684+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Inventory check completed in upstream service", "inventory_result": {"available": true, "product_id": "prod-1", "quantity": 50}}
{"timestamp": "2026-04-12T17:23:29.174928+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "77db17d7-094c-4d16-8817-58ccd0c893bd", "product_id": "prod-1", "user_id": 1, "duration_ms": 55.78}
{"timestamp": "2026-04-12T17:23:30.186350+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Starting full order workflow", "method": "POST", "path": "/api/orders/full", "payload_keys": ["product_id", "user_id"]}
{"timestamp": "2026-04-12T17:23:30.241795+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Inventory check completed in upstream service", "inventory_result": {"available": true, "product_id": "prod-2", "quantity": 50}}
{"timestamp": "2026-04-12T17:23:30.242016+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "b80ce30b-486b-4714-b31a-06cd51e7ac85", "product_id": "prod-2", "user_id": 2, "duration_ms": 55.67}
{"timestamp": "2026-04-12T17:23:31.252961+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Starting full order workflow", "method": "POST", "path": "/api/orders/full", "payload_keys": ["product_id", "user_id"]}
{"timestamp": "2026-04-12T17:23:31.308363+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Inventory check completed in upstream service", "inventory_result": {"available": true, "product_id": "prod-3", "quantity": 50}}
{"timestamp": "2026-04-12T17:23:31.308595+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "43f492fc-f6ae-4ded-a6ca-ab9a613f3f38", "product_id": "prod-3", "user_id": 3, "duration_ms": 55.64}
(venv) toor@ip-172-31-10-246:~/logging-lab$ tail -20 service_b.log
{"timestamp": "2026-04-12T17:22:11.654040+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "verify-1744478531", "message": "Inventory check request received", "method": "POST", "path": "/api/inventory/check", "product_id": "test-prod"}
{"timestamp": "2026-04-12T17:22:11.704498+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "verify-1744478531", "message": "Inventory check completed", "status_code": 200, "product_id": "test-prod", "available": true, "quantity": 50, "duration_ms": 50.45}
127.0.0.1 - - [12/Apr/2026 17:22:11] "POST /api/inventory/check HTTP/1.1" 200 -
{"timestamp": "2026-04-12T17:23:29.123660+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Inventory check request received", "method": "POST", "path": "/api/inventory/check", "product_id": "prod-1"}
{"timestamp": "2026-04-12T17:23:29.174118+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Inventory check completed", "status_code": 200, "product_id": "prod-1", "available": true, "quantity": 50, "duration_ms": 50.42}
127.0.0.1 - - [12/Apr/2026 17:23:29] "POST /api/inventory/check HTTP/1.1" 200 -
{"timestamp": "2026-04-12T17:23:30.190916+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Inventory check request received", "method": "POST", "path": "/api/inventory/check", "product_id": "prod-2"}
{"timestamp": "2026-04-12T17:23:30.241279+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Inventory check completed", "status_code": 200, "product_id": "prod-2", "available": true, "quantity": 50, "duration_ms": 50.39}
127.0.0.1 - - [12/Apr/2026 17:23:30] "POST /api/inventory/check HTTP/1.1" 200 -
{"timestamp": "2026-04-12T17:23:31.257503+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Inventory check request received", "method": "POST", "path": "/api/inventory/check", "product_id": "prod-3"}
{"timestamp": "2026-04-12T17:23:31.307844+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Inventory check completed", "status_code": 200, "product_id": "prod-3", "available": true, "quantity": 50, "duration_ms": 50.37}
127.0.0.1 - - [12/Apr/2026 17:23:31] "POST /api/inventory/check HTTP/1.1" 200 -

Services not responding

Check if ports 5000 and 5001 are available:

(venv) toor@ip-172-31-10-246:~/logging-lab$ ss -tlnp | grep -E ':5000|:5001'
LISTEN 0      128          0.0.0.0:5000       0.0.0.0:*    users:(("python3",pid=8198,fd=3))
LISTEN 0      128          0.0.0.0:5001       0.0.0.0:*    users:(("python3",pid=8182,fd=3))

Verify services are running:

(venv) toor@ip-172-31-10-246:~/logging-lab$ ps aux | grep python3 | grep -E 'app.py|service_b.py' | grep -v grep
toor        8182  0.1  1.1 112320 45444 pts/0    S    17:15   0:00 python3 service_b.py
toor        8198  0.2  1.2 116748 47160 pts/0    S    17:16   0:00 python3 app.py

Check for errors in service output:

(venv) toor@ip-172-31-10-246:~/logging-lab$ tail -20 app.log
{"timestamp": "2026-04-12T17:22:11.649593+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "verify-1744478531", "message": "Starting full order workflow", "method": "POST", "path": "/api/orders/full", "payload_keys": ["product_id", "user_id"]}
{"timestamp": "2026-04-12T17:22:11.704952+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "verify-1744478531", "message": "Inventory check completed in upstream service", "inventory_result": {"available": true, "product_id": "test-prod", "quantity": 50}}
{"timestamp": "2026-04-12T17:22:11.705207+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "verify-1744478531", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "f7e0d184-b30c-4830-b9cb-e8bebfdd734a", "product_id": "test-prod", "user_id": 1, "duration_ms": 55.65}
127.0.0.1 - - [12/Apr/2026 17:22:11] "POST /api/orders/full HTTP/1.1" 201 -
{"timestamp": "2026-04-12T17:23:29.119174+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Starting full order workflow", "method": "POST", "path": "/api/orders/full", "payload_keys": ["product_id", "user_id"]}
{"timestamp": "2026-04-12T17:23:29.174684+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Inventory check completed in upstream service", "inventory_result": {"available": true, "product_id": "prod-1", "quantity": 50}}
{"timestamp": "2026-04-12T17:23:29.174928+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "77db17d7-094c-4d16-8817-58ccd0c893bd", "product_id": "prod-1", "user_id": 1, "duration_ms": 55.78}
{"timestamp": "2026-04-12T17:23:30.186350+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Starting full order workflow", "method": "POST", "path": "/api/orders/full", "payload_keys": ["product_id", "user_id"]}
{"timestamp": "2026-04-12T17:23:30.241795+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Inventory check completed in upstream service", "inventory_result": {"available": true, "product_id": "prod-2", "quantity": 50}}
{"timestamp": "2026-04-12T17:23:30.242016+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "b80ce30b-486b-4714-b31a-06cd51e7ac85", "product_id": "prod-2", "user_id": 2, "duration_ms": 55.67}
{"timestamp": "2026-04-12T17:23:31.252961+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Starting full order workflow", "method": "POST", "path": "/api/orders/full", "payload_keys": ["product_id", "user_id"]}
{"timestamp": "2026-04-12T17:23:31.308363+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Inventory check completed in upstream service", "inventory_result": {"available": true, "product_id": "prod-3", "quantity": 50}}
{"timestamp": "2026-04-12T17:23:31.308595+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "43f492fc-f6ae-4ded-a6ca-ab9a613f3f38", "product_id": "prod-3", "user_id": 3, "duration_ms": 55.64}
(venv) toor@ip-172-31-10-246:~/logging-lab$ tail -20 service_b.log
{"timestamp": "2026-04-12T17:22:11.654040+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "verify-1744478531", "message": "Inventory check request received", "method": "POST", "path": "/api/inventory/check", "product_id": "test-prod"}
{"timestamp": "2026-04-12T17:22:11.704498+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "verify-1744478531", "message": "Inventory check completed", "status_code": 200, "product_id": "test-prod", "available": true, "quantity": 50, "duration_ms": 50.45}
127.0.0.1 - - [12/Apr/2026 17:22:11] "POST /api/inventory/check HTTP/1.1" 200 -
{"timestamp": "2026-04-12T17:23:29.123660+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Inventory check request received", "method": "POST", "path": "/api/inventory/check", "product_id": "prod-1"}
{"timestamp": "2026-04-12T17:23:29.174118+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "094a1f57-5771-42c5-9c56-0fb558d928fa", "message": "Inventory check completed", "status_code": 200, "product_id": "prod-1", "available": true, "quantity": 50, "duration_ms": 50.42}
127.0.0.1 - - [12/Apr/2026 17:23:29] "POST /api/inventory/check HTTP/1.1" 200 -
{"timestamp": "2026-04-12T17:23:30.190916+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Inventory check request received", "method": "POST", "path": "/api/inventory/check", "product_id": "prod-2"}
{"timestamp": "2026-04-12T17:23:30.241279+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "a8e52f6f-44fe-4e1b-9883-833c3f58542f", "message": "Inventory check completed", "status_code": 200, "product_id": "prod-2", "available": true, "quantity": 50, "duration_ms": 50.39}
127.0.0.1 - - [12/Apr/2026 17:23:30] "POST /api/inventory/check HTTP/1.1" 200 -
{"timestamp": "2026-04-12T17:23:31.257503+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Inventory check request received", "method": "POST", "path": "/api/inventory/check", "product_id": "prod-3"}
{"timestamp": "2026-04-12T17:23:31.307844+00:00", "level": "INFO", "name": "service-b", "service": "service-b", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Inventory check completed", "status_code": 200, "product_id": "prod-3", "available": true, "quantity": 50, "duration_ms": 50.37}
127.0.0.1 - - [12/Apr/2026 17:23:31] "POST /api/inventory/check HTTP/1.1" 200 -

Missing log fields

  • Ensure extra fields are passed to logger methods
  • Verify JsonFormatter format string includes all desired fields
  • Check that log_with_context function adds required context

Inspect a single structured log line:

(venv) toor@ip-172-31-10-246:~/logging-lab$ grep '"correlation_id"' app.log | tail -1
{"timestamp": "2026-04-12T17:23:31.308595+00:00", "level": "INFO", "name": "service-a", "service": "service-a", "correlation_id": "64c5b11f-14db-4c1b-a980-c4ed5d46a548", "message": "Full order workflow completed successfully", "status_code": 201, "order_id": "43f492fc-f6ae-4ded-a6ca-ab9a613f3f38", "product_id": "prod-3", "user_id": 3, "duration_ms": 55.64}

Final Project Snapshot

(venv) toor@ip-172-31-10-246:~/logging-lab$ find . -maxdepth 1 -type f | sort
./analyze_logs.py
./app.log
./app.py
./combined.log
./service_b.log
./service_b.py

Background services summary:

(venv) toor@ip-172-31-10-246:~/logging-lab$ jobs -l
[1]-  8182 Running                 python3 service_b.py > service_b.log 2>&1 &
[2]+  8198 Running                 python3 app.py > app.log 2>&1 &