Bug: Extended middleware not being called after assigned to route.

[charles-co]

Expected Behaviour

After registering middleware to route, once endpoint is called, registered route is called before endpoint function.

Current Behaviour

Skips registered middleware on route and calls funvtion

Code snippet

# middlewares.py

class UserMiddleWare(BaseMiddlewareHandler):
    def __init__(self, allowed_roles: list[UserRoles], authenticate: bool = True):
        super().__init__()
        self._allowed_roles = allowed_roles
        self._authenticate = authenticate

    def handler(self, app: APIGatewayRestResolver, next_middleware: NextMiddleware) -> Response:
        ...
        return next_middleware(app)

# users.py

...
from aws_lambda_powertools.event_handler.router import APIGatewayRouter

router = APIGatewayRouter()

@router.get("/me", cors=True, middlewares=[UserMiddleWare(allowed_roles=[UserRoles.INFLUENCER], authenticate=False)])
def get_user():
    user: UserDict = router.context["user"]
    ...

# main.py
...

app = APIGatewayRestResolver(
    strip_prefixes=["/xxx"], debug=get_settings().STAGE in ["staging", "dev"], cors=cors_config
)

def log_request_response(app: APIGatewayRestResolver, next_middleware: NextMiddleware) -> Response:
    logger.info("Incoming request", method=app.current_event.http_method, path=app.current_event.path)
    logger.append_keys(
        user_id=app.current_event.request_context.authorizer["id"],
        role=app.current_event.request_context.authorizer["role"],
    )
    result = next_middleware(app)
    logger.info("Response received", response=result.__dict__)
    return result

app.use(
    middlewares=[
        log_request_response,
    ]
)

app.include_router(
    users.router,
    prefix="/users",
)

@logger.inject_lambda_context(correlation_id_path=correlation_paths.API_GATEWAY_REST)
@event_source(data_class=APIGatewayProxyEvent)
@tracer.capture_lambda_handler
def wallets_gateway_handler(event: APIGatewayProxyEvent, context: LambdaContext):
    tracer.put_annotation(
        "user", event.request_context.authorizer["role"] + str(event.request_context.authorizer["id"])
    )
    return app.resolve(event, context)

Possible Solution

No response

Steps to Reproduce

• Create app
• Create middleware
• Create route in separate file and attach middleware to specific endpoint without using router.use()
• Include router to app with prefix

Powertools for AWS Lambda (Python) version

latest

AWS Lambda function runtime

3.11

Packaging format used

PyPi

Debugging logs

Processing Route:::get_user (/users/me)

Middleware Stack:
=================
log_request_response
_registered_api_adapter
=================

[boring-cyborg[bot]]

Thanks for opening your first issue here! We'll come back to you as soon as we can. In the meantime, check out the #python channel on our Powertools for AWS Lambda Discord: Invite link

[leandrodamascena]

Hi @charles-co! Thanks for reporting this possible bug. I think I need more information to reproduce the problem. I tried to reproduce this scenario here and I couldn't OR I'm missing something. Can you help me reproduce this error or check if I'm missing something? I simplified some things like roles, as this is not necessary for my test.

middleware.py

from aws_lambda_powertools.event_handler import APIGatewayRestResolver, Response
from aws_lambda_powertools.event_handler.middlewares.base import BaseMiddlewareHandler, NextMiddleware

from aws_lambda_powertools import Logger

logger = Logger()

class UserMiddleWare(BaseMiddlewareHandler):
    def __init__(self, allowed_roles: str, authenticate: bool = True):
        super().__init__()
        self._allowed_roles = allowed_roles
        self._authenticate = authenticate

    def handler(self, app: APIGatewayRestResolver, next_middleware: NextMiddleware) -> Response:
        logger.info("UserMiddleWare - TEST", role=self._allowed_roles)
        return next_middleware(app)

users.py

from aws_lambda_powertools.event_handler.router import APIGatewayRouter

from middleware import UserMiddleWare

router = APIGatewayRouter()

@router.get("/hello", cors=True, middlewares=[UserMiddleWare(allowed_roles="role-example", authenticate=False)])
def get_user():
    return "test"

app.py

import requests
from requests import Response
import users

from aws_lambda_powertools.event_handler import APIGatewayRestResolver
from aws_lambda_powertools.utilities.typing import LambdaContext
from aws_lambda_powertools.event_handler.middlewares.base import BaseMiddlewareHandler, NextMiddleware
from aws_lambda_powertools import Logger

logger = Logger()

app = APIGatewayRestResolver()

def log_request_response(app: APIGatewayRestResolver, next_middleware: NextMiddleware) -> Response:
    logger.info("Incoming request", method=app.current_event.http_method, path=app.current_event.path)
    result = next_middleware(app)
    logger.info("Response received", response=result.__dict__)
    return result

app.use(middlewares=[log_request_response])
app.include_router(users.router)

def lambda_handler(event: dict, context: LambdaContext) -> dict:
    return app.resolve(event, context)

event.json

{
  "body": "{\"message\": \"hello world\"}",
  "resource": "/hello",
  "path": "/hello",
  "httpMethod": "GET",
  "isBase64Encoded": false,
  "queryStringParameters": {
    "foo": "bar"
  },
  "pathParameters": {
    "proxy": "/path/to/resource"
  },
  "stageVariables": {
    "baz": "qux"
  },
  "headers": {
    "Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8",
    "Accept-Encoding": "gzip, deflate, sdch",
    "Accept-Language": "en-US,en;q=0.8",
    "Cache-Control": "max-age=0",
    "CloudFront-Forwarded-Proto": "https",
    "CloudFront-Is-Desktop-Viewer": "true",
    "CloudFront-Is-Mobile-Viewer": "false",
    "CloudFront-Is-SmartTV-Viewer": "false",
    "CloudFront-Is-Tablet-Viewer": "false",
    "CloudFront-Viewer-Country": "US",
    "Host": "1234567890.execute-api.us-east-1.amazonaws.com",
    "Upgrade-Insecure-Requests": "1",
    "User-Agent": "Custom User Agent String",
    "Via": "1.1 08f323deadbeefa7af34d5feb414ce27.cloudfront.net (CloudFront)",
    "X-Amz-Cf-Id": "cDehVQoZnx43VYQb9j2-nvCh-9z396Uhbp027Y2JvkCPNLmGJHqlaA==",
    "X-Forwarded-For": "127.0.0.1, 127.0.0.2",
    "X-Forwarded-Port": "443",
    "X-Forwarded-Proto": "https"
  },
  "requestContext": {
    "accountId": "123456789012",
    "resourceId": "123456",
    "stage": "prod",
    "requestId": "c6af9ac6-7b61-11e6-9a41-93e8deadbeef",
    "requestTime": "09/Apr/2015:12:34:56 +0000",
    "requestTimeEpoch": 1428582896000,
    "identity": {
      "cognitoIdentityPoolId": null,
      "accountId": null,
      "cognitoIdentityId": null,
      "caller": null,
      "accessKey": null,
      "sourceIp": "127.0.0.1",
      "cognitoAuthenticationType": null,
      "cognitoAuthenticationProvider": null,
      "userArn": null,
      "userAgent": "Custom User Agent String",
      "user": null
    },
    "path": "/prod/hello",
    "resourcePath": "/hello",
    "httpMethod": "POST",
    "apiId": "1234567890",
    "protocol": "HTTP/1.1"
  }
}

OUTPUT

START RequestId: 922547bc-a74b-4cad-a421-24db0a8b298d Version: $LATEST
{"level":"INFO","location":"log_request_response:17","message":"Incoming request","timestamp":"2023-10-25 21:09:26,797+0000","service":"service_undefined","method":"GET","path":"/hello"}
{"level":"INFO","location":"handler:16","message":"UserMiddleWare - TEST","timestamp":"2023-10-25 21:09:26,797+0000","service":"service_undefined","role":"role-example"}
{"level":"INFO","location":"log_request_response:19","message":"Response received","timestamp":"2023-10-25 21:09:26,797+0000","service":"service_undefined","response":{"status_code":200,"body":"\"test\"","base64_encoded":false,"headers":{"Content-Type":"application/json"},"cookies":[],"compress":null}}
END RequestId: 922547bc-a74b-4cad-a421-24db0a8b298d
REPORT RequestId: 922547bc-a74b-4cad-a421-24db0a8b298d  Init Duration: 0.12 ms  Duration: 380.93 ms Billed Duration: 381 ms Memory Size: 128 MB Max Memory Used: 128 MB 
{"statusCode": 200, "body": "\"test\"", "isBase64Encoded": false, "multiValueHeaders": {"Content-Type": ["application/json"]}

First line {"level":"INFO","location":"log_request_response:17","message":"Incoming request","timestamp":"2023-10-25 21:09:26,797+0000","service":"service_undefined","method":"GET","path":"/hello"}

After declaring app.use(middlewares=[log_request_response]), this is the first middleware called and logs the incoming request.

Second line {"level":"INFO","location":"handler:16","message":"UserMiddleWare - TEST","timestamp":"2023-10-25 21:09:26,797+0000","service":"service_undefined","role":"role-example"}

UserMiddleWare is called before the function to resolve the /hello endpoint.

Third line {"level":"INFO","location":"log_request_response:19","message":"Response received","timestamp":"2023-10-25 21:09:26,797+0000","service":"service_undefined","response":{"status_code":200,"body":"\"test\"","base64_encoded":false,"headers":{"Content-Type":"application/json"},"cookies":[],"compress":null}}

The UserMiddleWare has been executed, the get_user function has been invoked, and the workflow is now successfully concluded.

I know this is a complex workflow and debugging can be hard. Can you pls check my steps and see if you can find anything wrong on my side or on your side?

Thanks

[charles-co]

@leandrodamascena Thanks for the response!

Our codes are quite similar, so I do not understand why it isn't working for me. I am working with serverless-offline plugin but I do not think that is the issue because the log_request_response works. This is my current project structure if it adds more context also included my handler funtion above -

├── openapi-yaml-to-html.py
├── package-lock.json
├── package.json
├── pyproject.toml
├── requirements.txt
├── serverless-dev.yml
├── serverless-test.yml
├── serverless.yml
├── setup.cfg
├── src
 │   ├── __init__.py
 │   ├── config
 │    │   ├── __init__.py
 │    │   └── settings.py
 │   ├── db.py
 │   ├── enums.py
 │   ├── fields.py
 │   ├── main.py
 │   ├── queues
 │    │   ├── __init__.py
 │    │   └── transactions.py
│   ├── repository.py
│   ├── schemas
│   │   ├── __init__.py
│   │   ├── db.py
│   │   ├── interfaces.py
│   │   ├── requests.py
│   │   └── responses.py
│   ├── services
│   │   ├── __init__.py
│   │   ├── banks.py
│   │   ├── middlewares.py
│   │   ├── users.py
│   │   ├── wallets.py
│  └── utils
│       ├── __init__.py
│       ├── common.py
│       ├── crypto.py
│       ├── encoding.py
│       ├── exceptions.py
│       ├── hashers.py
│       └── json_util.py

[leandrodamascena]

I can't say that the problem is with the plugin, but I would bet not, since the logging middleware works.

I think of some ways to debug this:

1 - What do you think about creating a simple project with the serverless-offline plugin, as simple as a hello world that uses just 1 middleware and evolving it?

2 - I'm going to simulate the scenario on my side and do it the same way, create a hello world and evolve it into an idea with Pydantic models, classes, and things like that. If I find something I'll update it here.

Let's try to catch this fish. :fishing_pole_and_fish: :fish:

[charles-co]

@leandrodamascena I think I found the issue, my routes are included with prefix i.e. app.include_router(users.router, prefix="/users") and actual route will be something like @route.get("/me", ...) but as you can see the new_route variable is ('/users/me', ('GET',), True, False, None) while router._routes_with_middleware contains {('/me', (...), True, False, None): [<src.services.middle...105743390>]}

See screenshot below for reference

[leandrodamascena]

Yes, the prefix was the missing part of this debug. I was able to reproduce this and UserMiddleWare was not invoked.

I need some time to debug the code and find a better solution. How urgent is this bug on your end? We are working to add support for Swagger + OpenAPI Spec and plan a release for next week - November 3rd. Do you think it is ok to wait until then?

Thanks and sorry for this bug. Middleware support is a very new utility and we are still receiving user experience feedback and bug reports.

[charles-co]

Thanks @leandrodamascena I'll manage until then by adding the prefix to the endpoints. Just started using package last week and it's really awesome !!, having Swagger + OpenAPI Spec will be really awesome too as I'm having to do that manually.

Keep it going 🚀🚀🚀

[heitorlessa]

meanwhile we look into it this week, remove the prefix from the include_router and it should work. Apparently it only happens when you have both strip_prefixes and prefix, we managed to repreoduce in our tests. Leandro is on it!

[walmsles]

meanwhile we look into it this week, remove the prefix from the include_router and it should work. Apparently it only happens when you have both strip_prefixes and prefix, we managed to repreoduce in our tests. Leandro is on it!

When facing problems with Middleware like this, recommend turning on Powertools debug mode - there is a LOT of debug for the middleware stacks and also traces of execution order that are output when its turned on :-)

@heitorlessa and @leandrodamascena - shout out if you need any inputs on this.

[leandrodamascena]

Hi @walmsles, the debug thing is so helpful!

I debugged this for days to understand the Middleware code in detail and it was good because now I have a clear view on things. I submitted the PR to fix this issue, and I hope to release a new version this week.

Thanks everyone for the detailed explanation of this issue and your patience @charles-co!

[github-actions[bot]]

⚠️COMMENT VISIBILITY WARNING⚠️

This issue is now closed. Please be mindful that future comments are hard for our team to see.

If you need more assistance, please either tag a team member or open a new issue that references this one.

If you wish to keep having a conversation with other community members under this issue feel free to do so.

[github-actions[bot]]

This is now released under 2.26.1 version!

[charles-co]

Thanks @leandrodamascena I can confirm it works now.