refactor(logging): enhance error logging with stack information across multiple modules

Anuj-Gupta4 commented 2 weeks ago

[x] 🧑‍💻 Refactor

Related Issue

Resolves #1756

Describe this PR

Replaced log.error with log.exception and included traceback information where exceptions are raised.

Checklist before requesting a review

📖 Read the FMTM Contributing Guide: https://github.com/hotosm/fmtm/blob/main/CONTRIBUTING.md
📖 Read the HOT Code of Conduct: https://docs.hotosm.org/code-of-conduct
👷‍♀️ Create small PRs. In most cases, this will be possible.
✅ Provide tests for your changes.
📝 Use descriptive commit messages.
📗 Update any related documentation and include any relevant screenshots.

spwoodcock commented 1 week ago

Looks good!

Could you purposefully raise some exceptions to test this out & see what the logging format is like?

Temporarily adding raise Exception in the try block should do it

Anuj-Gupta4 commented 1 week ago

@spwoodcock

{"text": "2024-11-18 07:45:47.942 | ERROR | app.auth.auth_routes:get_or_create_user:219 - Exception occurred: Self generated exception\nTraceback (most recent call last):\n\n File \"\", line 1, in \n File \"/usr/local/lib/python3.12/multiprocessing/spawn.py\", line 122, in spawn_main\n exitcode = _main(fd, parent_sentinel)\n │ │ └ 5\n │ └ 8\n └ <function _main at 0x7f249e1018a0>\n File \"/usr/local/lib/python3.12/multiprocessing/spawn.py\", line 135, in _main\n return self._bootstrap(parent_sentinel)\n │ │ └ 5\n │ └ <function BaseProcess._bootstrap at 0x7f249e140180>\n └ \n File \"/usr/local/lib/python3.12/multiprocessing/process.py\", line 314, in _bootstrap\n self.run()\n │ └ <function BaseProcess.run at 0x7f249e1936a0>\n └ \n File \"/usr/local/lib/python3.12/multiprocessing/process.py\", line 108, in run\n self._target(*self._args, **self._kwargs)\n │ │ │ │ │ └ {'config': <uvicorn.config.Config object at 0x7f249e6b1ca0>, 'target': <bound method Server.run of <uvicorn.server.Server obj...\n │ │ │ │ └ \n │ │ │ └ ()\n │ │ └ \n │ └ <function subprocess_started at 0x7f249c58c860>\n └ \n File \"/home/appuser/.local/lib/python3.12/site-packages/uvicorn/_subprocess.py\", line 80, in subprocess_started\n target(sockets=sockets)\n │ └ [<socket.socket fd=4, family=2, type=1, proto=0, laddr=('0.0.0.0', 8000)>]\n └ <bound method Server.run of <uvicorn.server.Server object at 0x7f249e0aaf00>>\n File \"/home/appuser/.local/lib/python3.12/site-packages/uvicorn/server.py\", line 65, in run\n return asyncio.run(self.serve(sockets=sockets))\n │ │ │ │ └ [<socket.socket fd=4, family=2, type=1, proto=0, laddr=('0.0.0.0', 8000)>]\n │ │ │ └ <function Server.serve at 0x7f249c69bc40>\n │ │ └ <uvicorn.server.Server object at 0x7f249e0aaf00>\n │ └ <function run at 0x7f249e102c00>\n └ <module 'asyncio' from '/usr/local/lib/python3.12/asyncio/init.py'>\n File \"/usr/local/lib/python3.12/asyncio/runners.py\", line 194, in run\n return runner.run(main)\n │ │ └ <coroutine object Server.serve at 0x7f249c5e9fc0>\n │ └ <function Runner.run at 0x7f249e08d300>\n └ <asyncio.runners.Runner object at 0x7f249eff1100>\n File \"/usr/local/lib/python3.12/asyncio/runners.py\", line 118, in run\n return self._loop.run_until_complete(task)\n │ │ │ └ <Task pending name='Task-1' coro=<Server.serve() running at /home/appuser/.local/lib/python3.12/site-packages/uvicorn/server....\n │ │ └ <cyfunction Loop.run_until_complete at 0x7f249c5b58a0>\n │ └ \n └ <asyncio.runners.Runner object at 0x7f249eff1100>\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/middleware/base.py\", line 149, in coro\n await self.app(scope, receive_or_disconnect, send_no_error)\n │ │ │ │ └ <function BaseHTTPMiddleware.call..call_next..send_no_error at 0x7f245c203240>\n │ │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n │ └ <starlette.middleware.cors.CORSMiddleware object at 0x7f245c197500>\n └ <starlette.middleware.base.BaseHTTPMiddleware object at 0x7f245c381760>\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/middleware/cors.py\", line 85, in call\n await self.app(scope, receive, send)\n │ │ │ │ └ <function BaseHTTPMiddleware.call..call_next..send_no_error at 0x7f245c203240>\n │ │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n │ └ <starlette.middleware.exceptions.ExceptionMiddleware object at 0x7f245f8f15b0>\n └ <starlette.middleware.cors.CORSMiddleware object at 0x7f245c197500>\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/middleware/exceptions.py\", line 62, in call\n await wrap_app_handling_exceptions(self.app, conn)(scope, receive, send)\n │ │ │ │ │ │ └ <function BaseHTTPMiddleware.call..call_next..send_no_error at 0x7f245c203240>\n │ │ │ │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ │ │ │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n │ │ │ └ <starlette.requests.Request object at 0x7f245c1e1160>\n │ │ └ <fastapi.routing.APIRouter object at 0x7f245ce26930>\n │ └ <starlette.middleware.exceptions.ExceptionMiddleware object at 0x7f245f8f15b0>\n └ <function wrap_app_handling_exceptions at 0x7f248ee05d00>\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/_exception_handler.py\", line 42, in wrapped_app\n await app(scope, receive, sender)\n │ │ │ └ <function wrap_app_handling_exceptions..wrapped_app..sender at 0x7f245c22d9e0>\n │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n └ <fastapi.routing.APIRouter object at 0x7f245ce26930>\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/routing.py\", line 715, in call\n await self.middleware_stack(scope, receive, send)\n │ │ │ │ └ <function wrap_app_handling_exceptions..wrapped_app..sender at 0x7f245c22d9e0>\n │ │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n │ └ <bound method Router.app of <fastapi.routing.APIRouter object at 0x7f245ce26930>>\n └ <fastapi.routing.APIRouter object at 0x7f245ce26930>\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/routing.py\", line 735, in app\n await route.handle(scope, receive, send)\n │ │ │ │ └ <function wrap_app_handling_exceptions..wrapped_app..sender at 0x7f245c22d9e0>\n │ │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n │ └ <function Route.handle at 0x7f248ee07240>\n └ APIRoute(path='/auth/me/', name='my_data', methods=['GET'])\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/routing.py\", line 288, in handle\n await self.app(scope, receive, send)\n │ │ │ │ └ <function wrap_app_handling_exceptions..wrapped_app..sender at 0x7f245c22d9e0>\n │ │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n │ └ <function request_response..app at 0x7f245c4265c0>\n └ APIRoute(path='/auth/me/', name='my_data', methods=['GET'])\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/routing.py\", line 76, in app\n await wrap_app_handling_exceptions(app, request)(scope, receive, send)\n │ │ │ │ │ └ <function wrap_app_handling_exceptions..wrapped_app..sender at 0x7f245c22d9e0>\n │ │ │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ │ │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n │ │ └ <starlette.requests.Request object at 0x7f245c1e1310>\n │ └ <function request_response..app..app at 0x7f245c22d3a0>\n └ <function wrap_app_handling_exceptions at 0x7f248ee05d00>\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/_exception_handler.py\", line 42, in wrapped_app\n await app(scope, receive, sender)\n │ │ │ └ <function wrap_app_handling_exceptions..wrapped_app..sender at 0x7f245c22d940>\n │ │ └ <function BaseHTTPMiddleware.call..call_next..receive_or_disconnect at 0x7f245c1cb7e0>\n │ └ {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.4'}, 'http_version': '1.0', 'server': ('172.22.0.8', 8000), 'c...\n └ <function request_response..app..app at 0x7f245c22d3a0>\n File \"/home/appuser/.local/lib/python3.12/site-packages/starlette/routing.py\", line 73, in app\n response = await f(request)\n │ └ <starlette.requests.Request object at 0x7f245c1e1310>\n └ <function get_request_handler..app at 0x7f245c426480>\n File \"/home/appuser/.local/lib/python3.12/site-packages/fastapi/routing.py\", line 301, in app\n raw_response = await run_endpoint_function(\n └ <function run_endpoint_function at 0x7f248ee05760>\n File \"/home/appuser/.local/lib/python3.12/site-packages/fastapi/routing.py\", line 212, in run_endpoint_function\n return await dependant.call(**values)\n │ │ └ {'db': <psycopg.AsyncConnection [IDLE] (host=fmtm-db user=fmtm database=fmtm_stage) at 0x7f245c195df0>, 'current_user': AuthU...\n │ └ <function my_data at 0x7f24605bb1a0>\n └ Dependant(path_params=[], query_params=[], header_params=[], cookie_params=[], body_params=[], dependencies=[Dependant(path_p...\n\n File \"/opt/app/auth/auth_routes.py\", line 247, in my_data\n return await get_or_create_user(db, current_user)\n │ │ └ AuthUser(username='localadmin', picture=None, role='ADMIN', id=1)\n │ └ <psycopg.AsyncConnection [IDLE] (host=fmtm-db user=fmtm database=fmtm_stage) at 0x7f245c195df0>\n └ <function get_or_create_user at 0x7f24605367a0>\n\n> File \"/opt/app/auth/auth_routes.py\", line 169, in get_or_create_user\n raise Exception(\"Self generated exception\")\n\nException: Self generated exception\n", "record": {"elapsed": {"repr": "0:00:11.706153", "seconds": 11.706153}, "exception": {"type": "Exception", "value": "Self generated exception", "traceback": true}, "extra": {"stack_info": true}, "file": {"name": "auth_routes.py", "path": "/opt/app/auth/auth_routes.py"}, "function": "get_or_create_user", "level": {"icon": "❌", "name": "ERROR", "no": 40}, "line": 219, "message": "Exception occurred: Self generated exception", "module": "auth_routes", "name": "app.auth.auth_routes", "process": {"id": 637, "name": "SpawnProcess-15"}, "thread": {"id": 139795273313152, "name": "MainThread"}, "time": {"repr": "2024-11-18 07:45:47.942560+00:00", "timestamp": 1731915947.94256}}}

This is a sample log that was generated locally using self generated exception in fmtm.json file. This portion of it is clear: File \"/opt/app/auth/auth_routes.py\", line 169, in get_or_create_user\n raise Exception(\"Self generated exception\")\n\nException: Self generated exception\n", "record": {"elapsed": {"repr": "0:00:11.706153", "seconds": 11.706153}, "exception": {"type": "Exception", "value": "Self generated exception", "traceback": true}, "extra": {"stack_info": true}, "file": {"name": "auth_routes.py", "path": "/opt/app/auth/auth_routes.py"}, "function": "get_or_create_user", "level": {"icon": "❌", "name": "ERROR", "no": 40}, "line": 219, "message": "Exception occurred: Self generated exception", "module": "auth_routes", "name": "app.auth.auth_routes"

hotosm / fmtm