strawberry-graphql/strawberry

Surprising FIFO behaviour of lifecycle hooks

Closed this issue · 2 comments

kkom commented

Describe the (maybe) Bug

I'm surprised that various lifecycle hooks (on_operation, on_parse, on_validate, on_execute) are completed in a FIFO fashion, rather than LIFO.

I would expect that if we're wrapping an operation with on_operation with 2 extension the following will happen (LIFO):

  • First extension starts (before yield part)
  • Second extension starts (before yield part)
  • Second extension completes (after yield part)
  • First extension completes (after yield part)

However, the order I'm actually seeing is the following (FIFO):

  • First extension starts (before yield part)
  • Second extension starts (before yield part)
  • First extension completes (after yield part)
  • Second extension completes (after yield part)

I'm concerned about it because extension can mutate state, so it would be good for them to behave like a context manager. Example of state mutation.

In fact, I do find it surprising that this is how things work out. Notably, overriding resolve doesn't have the same problem – but it also happens in a slightly different way.

Repro details

Here're some toy extensions I built to investigate things:

class MyCustomExtension(SchemaExtension):
    id = "?"

    @override
    async def on_validate(self) -> AsyncGenerator[None, None]:
        print(f"GraphQL validation start ({self.id})")
        yield
        print(f"GraphQL validation end ({self.id})")

    @override
    def on_parse(self) -> Generator[None, None, None]:
        print(f"GraphQL parsing start ({self.id})")
        yield
        print(f"GraphQL parsing end ({self.id})")

    @override
    def on_execute(self) -> Generator[None, None, None]:
        print(f"GraphQL execution start ({self.id})")
        yield
        print(f"GraphQL execution end ({self.id})")

    @override
    def on_operation(self) -> Generator[None, None, None]:
        print(f"GraphQL operation start ({self.id})")
        yield
        print(f"GraphQL operation end ({self.id})")

    @override
    async def resolve(
        self,
        _next: Callable[..., object],
        root: object,
        info: GraphQLResolveInfo,
        *args,
        **kwargs,
    ) -> AwaitableOrValue[object]:
        random_id = randint(0, 1000)

        print(f"GraphQL resolver {random_id} start ({self.id})")
        result = await await_maybe(_next(root, info, *args, **kwargs))
        print(f"GraphQL resolver {random_id} end ({self.id})")
        return result


class MyCustomExtensionA(MyCustomExtension):
    id = "A"


class MyCustomExtensionB(MyCustomExtension):
    id = "B"

I'm testing it by running a simple query against a GraphQL Schema:

@strawberry.type
class Me:
    id: str

@strawberry.type
class Query:
    @strawberry.field
    @staticmethod
    async def me() -> Me:
        return Me(id="foo")

schema = MySchema(
    query=Query,
    extensions=[MyCustomExtensionA, MyCustomExtensionB],
)

When running a simple GraphQL query against this schema:

query {
  me { id }
}

I see the following lines being printed:

GraphQL operation start (A)
GraphQL operation start (B)
GraphQL parsing start (A)
GraphQL parsing start (B)
GraphQL parsing end (A)
GraphQL parsing end (B)
GraphQL validation start (A)
GraphQL validation start (B)
GraphQL validation end (A)
GraphQL validation end (B)
GraphQL execution start (A)
GraphQL execution start (B)
GraphQL resolver 598 start (B)
GraphQL resolver 975 start (A)
GraphQL resolver 975 end (A)
GraphQL resolver 598 end (B)
GraphQL resolver 196 start (B)
GraphQL resolver 638 start (A)
GraphQL resolver 638 end (A)
GraphQL resolver 196 end (B)
GraphQL execution end (A)
GraphQL execution end (B)
GraphQL operation end (A)
GraphQL operation end (B)

System Information

  • Strawberry version (if applicable): 0.220.0

Upvote & Fund

  • We're using Polar.sh so you can upvote and help fund this issue.
  • We receive the funding once the issue is completed & confirmed by you.
  • Thank you in advance for helping prioritize & fund our backlog.
Fund with Polar
kkom commented

I'm not sure if this is actually a bug... Perhaps this is a natural consequence of the Python pattern Strawberry is leveraging?

However, it would be nice to get a second pair of eyes and opinion on this!

It is actually tested as the wanted behaviour for some reason

"ExtensionA, on_operation Exited",