Skip to content

Commit bb63ff1

Browse files
ff137jamshale
ff137
and
jamshale
authored
✨ Handle NotFound and UnprocessableEntity errors in middleware (openwallet-foundation#3327)
* ✨ Handle NotFound and UnprocessableEntity exceptions at info log level Signed-off-by: ff137 <[email protected]> * 🎨 replace traceback print with exception log Signed-off-by: ff137 <[email protected]> * 🎨 replace deprecated .warn with .warning Signed-off-by: ff137 <[email protected]> * 🎨 setting ledger to read-only should not print error log Signed-off-by: ff137 <[email protected]> * ✨ extract the marshmallow validation error message from the nested exception Signed-off-by: ff137 <[email protected]> * 🎨 modify import for consistency Signed-off-by: ff137 <[email protected]> * ✅ test coverage for new method Signed-off-by: ff137 <[email protected]> * ✅ test coverage for exception handling changes Signed-off-by: ff137 <[email protected]> * 🎨 refactor for reduced complexity Signed-off-by: ff137 <[email protected]> * 🎨 reorder exceptions by severity Signed-off-by: ff137 <[email protected]> * 🎨 update log level Signed-off-by: ff137 <[email protected]> * 🎨 Signed-off-by: ff137 <[email protected]> --------- Signed-off-by: ff137 <[email protected]> Co-authored-by: jamshale <[email protected]>
1 parent 874f4db commit bb63ff1

File tree

7 files changed

+308
-43
lines changed

7 files changed

+308
-43
lines changed

‎acapy_agent/admin/server.py‎

Lines changed: 54 additions & 40 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,6 @@
1313
from aiohttp_apispec import setup_aiohttp_apispec, validation_middleware
1414
from uuid_utils import uuid4
1515

16-
from acapy_agent.wallet import singletons
17-
1816
from ..config.injection_context import InjectionContext
1917
from ..config.logging import context_wallet_id
2018
from ..core.event_bus import Event, EventBus
@@ -31,9 +29,11 @@
3129
from ..transport.outbound.status import OutboundSendStatus
3230
from ..transport.queue.basic import BasicMessageQueue
3331
from ..utils import general as general_utils
32+
from ..utils.extract_validation_error import extract_validation_error_message
3433
from ..utils.stats import Collector
3534
from ..utils.task_queue import TaskQueue
3635
from ..version import __version__
36+
from ..wallet import singletons
3737
from ..wallet.anoncreds_upgrade import check_upgrade_completion_loop
3838
from .base_server import BaseAdminServer
3939
from .error import AdminSetupError
@@ -68,6 +68,8 @@
6868
anoncreds_wallets = singletons.IsAnoncredsSingleton().wallets
6969
in_progress_upgrades = singletons.UpgradeInProgressSingleton()
7070

71+
status_paths = ("/status/live", "/status/ready")
72+
7173

7274
class AdminResponder(BaseResponder):
7375
"""Handle outgoing messages from message handlers."""
@@ -134,44 +136,56 @@ def send_fn(self) -> Coroutine:
134136
async def ready_middleware(request: web.BaseRequest, handler: Coroutine):
135137
"""Only continue if application is ready to take work."""
136138

137-
if str(request.rel_url).rstrip("/") in (
138-
"/status/live",
139-
"/status/ready",
140-
) or request.app._state.get("ready"):
141-
try:
142-
return await handler(request)
143-
except (LedgerConfigError, LedgerTransactionError) as e:
144-
# fatal, signal server shutdown
145-
LOGGER.error("Shutdown with %s", str(e))
146-
request.app._state["ready"] = False
147-
request.app._state["alive"] = False
148-
raise
149-
except web.HTTPFound as e:
150-
# redirect, typically / -> /api/doc
151-
LOGGER.info("Handler redirect to: %s", e.location)
152-
raise
153-
except (web.HTTPUnauthorized, jwt.InvalidTokenError, InvalidTokenError) as e:
154-
LOGGER.info(
155-
"Unauthorized access during %s %s: %s", request.method, request.path, e
156-
)
157-
raise web.HTTPUnauthorized(reason=str(e)) from e
158-
except (web.HTTPBadRequest, MultitenantManagerError) as e:
159-
LOGGER.info("Bad request during %s %s: %s", request.method, request.path, e)
160-
raise web.HTTPBadRequest(reason=str(e)) from e
161-
except asyncio.CancelledError:
162-
# redirection spawns new task and cancels old
163-
LOGGER.debug("Task cancelled")
164-
raise
165-
except Exception as e:
166-
# some other error?
167-
LOGGER.error("Handler error with exception: %s", str(e))
168-
import traceback
169-
170-
print("\n=================")
171-
traceback.print_exc()
172-
raise
173-
174-
raise web.HTTPServiceUnavailable(reason="Shutdown in progress")
139+
is_status_check = str(request.rel_url).rstrip("/") in status_paths
140+
is_app_ready = request.app._state.get("ready")
141+
142+
if not (is_status_check or is_app_ready):
143+
raise web.HTTPServiceUnavailable(reason="Shutdown in progress")
144+
145+
try:
146+
return await handler(request)
147+
except web.HTTPFound as e:
148+
# redirect, typically / -> /api/doc
149+
LOGGER.info("Handler redirect to: %s", e.location)
150+
raise
151+
except asyncio.CancelledError:
152+
# redirection spawns new task and cancels old
153+
LOGGER.debug("Task cancelled")
154+
raise
155+
except (web.HTTPUnauthorized, jwt.InvalidTokenError, InvalidTokenError) as e:
156+
LOGGER.info(
157+
"Unauthorized access during %s %s: %s", request.method, request.path, e
158+
)
159+
raise web.HTTPUnauthorized(reason=str(e)) from e
160+
except (web.HTTPBadRequest, MultitenantManagerError) as e:
161+
LOGGER.info("Bad request during %s %s: %s", request.method, request.path, e)
162+
raise web.HTTPBadRequest(reason=str(e)) from e
163+
except (web.HTTPNotFound, StorageNotFoundError) as e:
164+
LOGGER.info(
165+
"Not Found error occurred during %s %s: %s",
166+
request.method,
167+
request.path,
168+
e,
169+
)
170+
raise web.HTTPNotFound(reason=str(e)) from e
171+
except web.HTTPUnprocessableEntity as e:
172+
validation_error_message = extract_validation_error_message(e)
173+
LOGGER.info(
174+
"Unprocessable Entity occurred during %s %s: %s",
175+
request.method,
176+
request.path,
177+
validation_error_message,
178+
)
179+
raise
180+
except (LedgerConfigError, LedgerTransactionError) as e:
181+
# fatal, signal server shutdown
182+
LOGGER.critical("Shutdown with %s", str(e))
183+
request.app._state["ready"] = False
184+
request.app._state["alive"] = False
185+
raise
186+
except Exception as e:
187+
LOGGER.exception("Handler error with exception:", exc_info=e)
188+
raise
175189

176190

177191
@web.middleware

‎acapy_agent/admin/tests/test_admin_server.py‎

Lines changed: 158 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,9 +3,11 @@
33
from typing import Optional
44
from unittest import IsolatedAsyncioTestCase
55

6+
import jwt
67
import pytest
78
from aiohttp import ClientSession, DummyCookieJar, TCPConnector, web
89
from aiohttp.test_utils import unused_port
10+
from marshmallow import ValidationError
911

1012
from acapy_agent.tests import mock
1113
from acapy_agent.wallet import singletons
@@ -16,7 +18,9 @@
1618
from ...core.goal_code_registry import GoalCodeRegistry
1719
from ...core.in_memory import InMemoryProfile
1820
from ...core.protocol_registry import ProtocolRegistry
21+
from ...multitenant.error import MultitenantManagerError
1922
from ...storage.base import BaseStorage
23+
from ...storage.error import StorageNotFoundError
2024
from ...storage.record import StorageRecord
2125
from ...storage.type import RECORD_TYPE_ACAPY_UPGRADING
2226
from ...utils.stats import Collector
@@ -108,6 +112,160 @@ async def test_ready_middleware(self):
108112
with self.assertRaises(KeyError):
109113
await test_module.ready_middleware(request, handler)
110114

115+
async def test_ready_middleware_http_unauthorized(self):
116+
"""Test handling of web.HTTPUnauthorized and related exceptions."""
117+
with mock.patch.object(test_module, "LOGGER", mock.MagicMock()) as mock_logger:
118+
mock_logger.info = mock.MagicMock()
119+
120+
request = mock.MagicMock(
121+
method="GET",
122+
path="/unauthorized",
123+
app=mock.MagicMock(_state={"ready": True}),
124+
)
125+
126+
# Test web.HTTPUnauthorized
127+
handler = mock.CoroutineMock(
128+
side_effect=web.HTTPUnauthorized(reason="Unauthorized")
129+
)
130+
with self.assertRaises(web.HTTPUnauthorized):
131+
await test_module.ready_middleware(request, handler)
132+
mock_logger.info.assert_called_with(
133+
"Unauthorized access during %s %s: %s",
134+
request.method,
135+
request.path,
136+
handler.side_effect,
137+
)
138+
139+
# Test jwt.InvalidTokenError
140+
handler = mock.CoroutineMock(
141+
side_effect=jwt.InvalidTokenError("Invalid token")
142+
)
143+
with self.assertRaises(web.HTTPUnauthorized):
144+
await test_module.ready_middleware(request, handler)
145+
mock_logger.info.assert_called_with(
146+
"Unauthorized access during %s %s: %s",
147+
request.method,
148+
request.path,
149+
handler.side_effect,
150+
)
151+
152+
# Test InvalidTokenError
153+
handler = mock.CoroutineMock(
154+
side_effect=test_module.InvalidTokenError("Token error")
155+
)
156+
with self.assertRaises(web.HTTPUnauthorized):
157+
await test_module.ready_middleware(request, handler)
158+
mock_logger.info.assert_called_with(
159+
"Unauthorized access during %s %s: %s",
160+
request.method,
161+
request.path,
162+
handler.side_effect,
163+
)
164+
165+
async def test_ready_middleware_http_bad_request(self):
166+
"""Test handling of web.HTTPBadRequest and MultitenantManagerError."""
167+
with mock.patch.object(test_module, "LOGGER", mock.MagicMock()) as mock_logger:
168+
mock_logger.info = mock.MagicMock()
169+
170+
request = mock.MagicMock(
171+
method="POST",
172+
path="/bad-request",
173+
app=mock.MagicMock(_state={"ready": True}),
174+
)
175+
176+
# Test web.HTTPBadRequest
177+
handler = mock.CoroutineMock(
178+
side_effect=web.HTTPBadRequest(reason="Bad request")
179+
)
180+
with self.assertRaises(web.HTTPBadRequest):
181+
await test_module.ready_middleware(request, handler)
182+
mock_logger.info.assert_called_with(
183+
"Bad request during %s %s: %s",
184+
request.method,
185+
request.path,
186+
handler.side_effect,
187+
)
188+
189+
# Test MultitenantManagerError
190+
handler = mock.CoroutineMock(
191+
side_effect=MultitenantManagerError("Multitenant error")
192+
)
193+
with self.assertRaises(web.HTTPBadRequest):
194+
await test_module.ready_middleware(request, handler)
195+
mock_logger.info.assert_called_with(
196+
"Bad request during %s %s: %s",
197+
request.method,
198+
request.path,
199+
handler.side_effect,
200+
)
201+
202+
async def test_ready_middleware_http_not_found(self):
203+
"""Test handling of web.HTTPNotFound and StorageNotFoundError."""
204+
with mock.patch.object(test_module, "LOGGER", mock.MagicMock()) as mock_logger:
205+
mock_logger.info = mock.MagicMock()
206+
207+
request = mock.MagicMock(
208+
method="GET",
209+
path="/not-found",
210+
app=mock.MagicMock(_state={"ready": True}),
211+
)
212+
213+
# Test web.HTTPNotFound
214+
handler = mock.CoroutineMock(side_effect=web.HTTPNotFound(reason="Not found"))
215+
with self.assertRaises(web.HTTPNotFound):
216+
await test_module.ready_middleware(request, handler)
217+
mock_logger.info.assert_called_with(
218+
"Not Found error occurred during %s %s: %s",
219+
request.method,
220+
request.path,
221+
handler.side_effect,
222+
)
223+
224+
# Test StorageNotFoundError
225+
handler = mock.CoroutineMock(
226+
side_effect=StorageNotFoundError("Item not found")
227+
)
228+
with self.assertRaises(web.HTTPNotFound):
229+
await test_module.ready_middleware(request, handler)
230+
mock_logger.info.assert_called_with(
231+
"Not Found error occurred during %s %s: %s",
232+
request.method,
233+
request.path,
234+
handler.side_effect,
235+
)
236+
237+
async def test_ready_middleware_http_unprocessable_entity(self):
238+
"""Test handling of web.HTTPUnprocessableEntity with nested ValidationError."""
239+
with mock.patch.object(test_module, "LOGGER", mock.MagicMock()) as mock_logger:
240+
mock_logger.info = mock.MagicMock()
241+
# Mock the extract_validation_error_message function
242+
with mock.patch.object(
243+
test_module, "extract_validation_error_message"
244+
) as mock_extract:
245+
mock_extract.return_value = {"field": ["Invalid input"]}
246+
247+
request = mock.MagicMock(
248+
method="POST",
249+
path="/unprocessable",
250+
app=mock.MagicMock(_state={"ready": True}),
251+
)
252+
253+
# Create a HTTPUnprocessableEntity exception with a nested ValidationError
254+
validation_error = ValidationError({"field": ["Invalid input"]})
255+
http_error = web.HTTPUnprocessableEntity(reason="Unprocessable Entity")
256+
http_error.__cause__ = validation_error
257+
258+
handler = mock.CoroutineMock(side_effect=http_error)
259+
with self.assertRaises(web.HTTPUnprocessableEntity):
260+
await test_module.ready_middleware(request, handler)
261+
mock_extract.assert_called_once_with(http_error)
262+
mock_logger.info.assert_called_with(
263+
"Unprocessable Entity occurred during %s %s: %s",
264+
request.method,
265+
request.path,
266+
mock_extract.return_value,
267+
)
268+
111269
def get_admin_server(
112270
self, settings: Optional[dict] = None, context: Optional[InjectionContext] = None
113271
) -> AdminServer:

‎acapy_agent/askar/profile.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -75,7 +75,7 @@ def init_ledger_pool(self):
7575
read_only = bool(self.settings.get("ledger.read_only", False))
7676
socks_proxy = self.settings.get("ledger.socks_proxy")
7777
if read_only:
78-
LOGGER.error("Note: setting ledger to read-only mode")
78+
LOGGER.warning("Note: setting ledger to read-only mode")
7979
genesis_transactions = self.settings.get("ledger.genesis_transactions")
8080
cache = self.context.injector.inject_or(BaseCache)
8181
self.ledger_pool = IndyVdrLedgerPool(

‎acapy_agent/askar/profile_anon.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -77,7 +77,7 @@ def init_ledger_pool(self):
7777
read_only = bool(self.settings.get("ledger.read_only", False))
7878
socks_proxy = self.settings.get("ledger.socks_proxy")
7979
if read_only:
80-
LOGGER.error("Note: setting ledger to read-only mode")
80+
LOGGER.warning("Note: setting ledger to read-only mode")
8181
genesis_transactions = self.settings.get("ledger.genesis_transactions")
8282
cache = self.context.injector.inject_or(BaseCache)
8383
self.ledger_pool = IndyVdrLedgerPool(

‎acapy_agent/protocols/out_of_band/v1_0/manager.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -461,7 +461,7 @@ async def handle_use_did_method(
461461
did_method = PEER4 if did_peer_4 else PEER2
462462
my_info = await self.oob.fetch_invitation_reuse_did(did_method)
463463
if not my_info:
464-
LOGGER.warn("No invitation DID found, creating new DID")
464+
LOGGER.warning("No invitation DID found, creating new DID")
465465

466466
if not my_info:
467467
did_metadata = (

‎acapy_agent/utils/extract_validation_error.py‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,16 @@
1+
"""Extract validation error messages from nested exceptions."""
2+
3+
from aiohttp.web import HTTPUnprocessableEntity
4+
from marshmallow.exceptions import ValidationError
5+
6+
7+
def extract_validation_error_message(exc: HTTPUnprocessableEntity) -> str:
8+
"""Extract marshmallow error message from a nested UnprocessableEntity exception."""
9+
visited = set()
10+
current_exc = exc
11+
while current_exc and current_exc not in visited:
12+
visited.add(current_exc)
13+
if isinstance(current_exc, ValidationError):
14+
return current_exc.messages
15+
current_exc = current_exc.__cause__ or current_exc.__context__
16+
return exc.reason

0 commit comments

Comments
 (0)