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

[Anuj-Gupta4]

• 🧑‍💻 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]

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]

@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 │ └ <uvloop.Loop running=True closed=False debug=False>\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"