Unexpected OperationMiddleware execution

[jszwedko]

What happened?

This might just be a matter of documentation clarification, but we were using to wrap operations to record timings and other metadata and found that the next OperationHandler that is passed in returns before the operation is actually completed.

Is this expected behavior?

This was the output when I just added log statements to a handler extension that implements:

graphql.ResponseInterceptor
graphql.OperationInterceptor 
graphql.FieldInterceptor
graphql.HandlerExtension

2020/04/24 11:23:25 1 before operation                                                                                 
2020/04/24 11:23:25 1 after operation                                                                                  
2020/04/24 11:23:25 1 before response                     
2020/04/24 11:23:25 1 before field Query.todos        
2020/04/24 11:23:25 in resolver                                                                                        
2020/04/24 11:23:25 1 after field Query.todos                                                                          
2020/04/24 11:23:25 1 before field Todo.id             
2020/04/24 11:23:25 1 after field Todo.id                                                                              
2020/04/24 11:23:25 1 before field Query.todos                                                                         
2020/04/24 11:23:25 in resolver                                                                                        
2020/04/24 11:23:25 1 after field Query.todos            
2020/04/24 11:23:25 1 before field Todo.id                                                                             
2020/04/24 11:23:25 1 after field Todo.id                                                                              
2020/04/24 11:23:25 1 before field Todo.id          
2020/04/24 11:23:25 1 after field Todo.id            
2020/04/24 11:23:25 1 before field Todo.id                
2020/04/24 11:23:25 1 after field Todo.id                
2020/04/24 11:23:25 1 after response   

For a query:

query {
  todos {
    id
  }
  foo: todos {
    id
  }
}

We can see here that the operation middleware is called and returns before the response middleware starts.

What did you expect?

We expected the handler passed to our operation middleware to not return until the operation finished execution and the response was resolved.

Minimal graphql.schema and models to reproduce

I used gqlgen init to create the default models. This is my server.go file:

package main

import (
    "context"
    "log"
    "net/http"
    "os"
    "strconv"
    "test/graph"
    "test/graph/generated"

    "github.com/99designs/gqlgen/graphql"
    "github.com/99designs/gqlgen/graphql/handler"
    "github.com/99designs/gqlgen/graphql/playground"
)

const defaultPort = "8080"

func main() {
    port := os.Getenv("PORT")
    if port == "" {
        port = defaultPort
    }

    srv := handler.NewDefaultServer(generated.NewExecutableSchema(generated.Config{Resolvers: &graph.Resolver{}}))
    srv.Use(testExtension(1))

    http.Handle("/", playground.Handler("GraphQL playground", "/query"))
    http.Handle("/query", srv)

    log.Printf("connect to http://localhost:%s/ for GraphQL playground", port)
    log.Fatal(http.ListenAndServe(":"+port, nil))
}

// Tracer is an opencensus tracer that instruments GraphQL requests with opencensus spans
type testExtension int

var _ interface {
    graphql.ResponseInterceptor
    graphql.OperationInterceptor
    graphql.FieldInterceptor
    graphql.HandlerExtension
} = testExtension(0)

func (t testExtension) ExtensionName() string {
    return strconv.FormatInt(int64(t), 0)
}

func (t testExtension) Validate(schema graphql.ExecutableSchema) error {
    return nil
}

func (t testExtension) InterceptOperation(ctx context.Context, next graphql.OperationHandler) graphql.ResponseHandler {
    opctx := graphql.GetOperationContext(ctx)
    log.Printf("%d before operation %s\n", t, opctx.OperationName)
    defer func() {
        log.Printf("%d after operation %s\n", t, opctx.OperationName)
    }()
    return next(ctx)
}

func (t testExtension) InterceptField(ctx context.Context, next graphql.Resolver) (res interface{}, err error) {
    fctx := graphql.GetFieldContext(ctx)
    log.Printf("%d before field %s.%s\n", t, fctx.Object, fctx.Field.Name)
    defer func() {
        log.Printf("%d after field %s.%s\n", t, fctx.Object, fctx.Field.Name)
    }()
    return next(ctx)
}

func (t testExtension) InterceptResponse(ctx context.Context, next graphql.ResponseHandler) *graphql.Response {
    log.Printf("%d before response\n", t)
    defer func() {
        log.Printf("%d after response\n", t)
    }()
    return next(ctx)
}

And the schema.resolvers.go:

// This file will be automatically regenerated based on the schema, any resolver implementations
// will be copied through when generating and any unknown code will be moved to the end.
package graph

import (
    "context"
    "fmt"
    "log"
    "test/graph/generated"
    "test/graph/model"
)

func (r *mutationResolver) CreateTodo(ctx context.Context, input model.NewTodo) (*model.Todo, error) {
    panic(fmt.Errorf("not implemented"))
}

func (r *queryResolver) Todos(ctx context.Context) ([]*model.Todo, error) {
    log.Printf("in resolver")

    return []*model.Todo{
        {
            ID:   "1234",
            Text: "todo",
            Done: true,
            User: &model.User{
                ID:   "4567",
                Name: "Joe",
            },
        },
        {
            ID:   "9827",
            Text: "todo",
            Done: true,
            User: &model.User{
                ID:   "4567",
                Name: "Joe",
            },
        },
    }, nil
}

func (r *Resolver) Mutation() generated.MutationResolver { return &mutationResolver{r} }
func (r *Resolver) Query() generated.QueryResolver       { return &queryResolver{r} }

type mutationResolver struct{ *Resolver }
type queryResolver struct{ *Resolver }

versions

• gqlgen version? v0.11.0
• go version? go version go1.14.2 linux/amd64
• dep or go modules? go modules

[jszwedko]

For a subscription I saw:

2020/04/24 11:39:31 1 before operation
2020/04/24 11:39:31 1 before field Subscription.todo
2020/04/24 11:39:31 in resolver
2020/04/24 11:39:31 1 after field Subscription.todo
2020/04/24 11:39:31 1 after operation
2020/04/24 11:39:31 1 before response
2020/04/24 11:39:31 1 before field Todo.id
2020/04/24 11:39:31 1 after field Todo.id
2020/04/24 11:39:31 1 after response
2020/04/24 11:39:31 1 before response
2020/04/24 11:39:32 1 before field Todo.id
2020/04/24 11:39:32 1 after field Todo.id
2020/04/24 11:39:32 1 after response
2020/04/24 11:39:32 1 before response
2020/04/24 11:39:33 1 before field Todo.id
2020/04/24 11:39:33 1 after field Todo.id
2020/04/24 11:39:33 1 after response

which seems to call the resolver during the operation middleware execution as opposed to the query operation which calls it after.

[vinicio]

I guess the same problem is affecting the AroundOperation extension. Unlike AroundResponse, it is executing the code after next(ctx) before the operation is actually done, making it useless if you want to execute code right after operations are done.

[Draiken]

The problem is that you need to add your logic to the returned function from the interception. That function will be called when the response is finished. By using defer you are not in fact waiting for the response.

func InterceptOperation(ctx context.Context, next graphql.OperationHandler) graphql.ResponseHandler {
    // Before the operation
    handler := next(ctx)

    return func(ctx context.Context) *graphql.Response {
        response := handler(ctx)

                // After each response!

        return response
    }
}

[kylechadha]

This was very non-obvious to me as well :). Would be great to have a page in the docs about request lifecycle, operation context, etc

In either case, thank you for the solution @Draiken!