Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: Graphql handler is not executed if it's a wrapper #11450

Open
1 task
jan-stehlik opened this issue Sep 6, 2024 · 6 comments
Open
1 task

[Bug]: Graphql handler is not executed if it's a wrapper #11450

jan-stehlik opened this issue Sep 6, 2024 · 6 comments
Assignees
Labels
bug/confirmed We have confirmed this is a bug topic/graphql

Comments

@jan-stehlik
Copy link

What's not working?

When creating a wrapper called handler around createGraphQLHandler function it never get executed.

Example graphql.ts

const graphqlHandler = createGraphQLHandler({
  loggerConfig: { logger, options: {} },
  directives,
  sdls,
  services,
  onException: () => {
    // Disconnect from your database with an unhandled exception.
    db.$disconnect()
  },
})

export async function handler(event, context) {
  // this never gets fired
  console.log(`in handler wrapper`)

  const requestIdHeader = 'x-request-id'
  const requestId = event.headers[requestIdHeader]
  const store: Store = new Map([['requestId', requestId]])
  const response = await executionContext.run(store, () => {
    return graphqlHandler(event, context)
  })
  return {
    ...response,
    headers: { ...(response.headers ?? {}), [requestIdHeader]: requestId },
  }
}

When you run this app, the console.log(in handler wrapper) never gets fired.

How do we reproduce the bug?

  1. clone https://github.com/jan-stehlik/rw-graphql-issue/tree/main
  2. yarn install
  3. yarn rw dev
  4. open http://localhost:8910/ and have a look at server logs - console.log(in handler wrapper) doesn't get triggered

What's your environment? (If it applies)

Redwood 8.0.0
Node 20.16
Yarn 4.4

Are you interested in working on this?

  • I'm interested in working on this
@jan-stehlik jan-stehlik added the bug/needs-info More information is needed for reproduction label Sep 6, 2024
@Josh-Walker-GM Josh-Walker-GM self-assigned this Sep 6, 2024
@Josh-Walker-GM
Copy link
Collaborator

Josh-Walker-GM commented Sep 6, 2024

Hey @jan-stehlik, thanks for super clear issue and the reproduction repo!

Can you try switching your handler to an arrow function?

- export async function handler(event, context) {
+ export const handler = async (event, context) => {

I think this might let you move forward but even if it does this is still something I will address. The syntactic flavour shouldn't break your app.

@Josh-Walker-GM Josh-Walker-GM added bug/confirmed We have confirmed this is a bug and removed bug/needs-info More information is needed for reproduction labels Sep 6, 2024
@Josh-Walker-GM Josh-Walker-GM changed the title [Bug?]: Graphql handler is not executed if it's a wrapper [Bug]: Graphql handler is not executed if it's a wrapper Sep 6, 2024
@Josh-Walker-GM
Copy link
Collaborator

Josh-Walker-GM commented Sep 6, 2024

Hmm there's more problems here than just that syntax issue we have.


So the root cause here is two fold:

  1. We have a babel plugin which wraps the handler in a context isolation function - to ensure that even on serverless deployments the context is isolated. This currently only handles the arrow function syntax.

But turns out it doesn't even matter that there's a bug with 1. because:

  1. With dev and serve we now always do a slight misdirection... If you have a graphql function we actually ignore that serverless function and setup a serverful version of graphql and direct requests from /graphql to that graphql server. We still extract all the correct graphql options from your serverless function to apply those to the graphql server but of course we now don't execute the handler function on every request so your wrapper doesn't get called.

I'll probably need to sound this out again with the team because when I write out the behaviour here it feels a little icky. The less misdirection we do the better.

For what it's worth I might suggest looking into the server file: https://docs.redwoodjs.com/docs/docker/#using-the-server-file. I don't know if this could make it more ergonomic to do things at the request level like your wrapping. The server file is a little under loved and needs more attention. I'm personally pushing for it to be a first class redwood citizen.

@jan-stehlik
Copy link
Author

Thanks @Josh-Walker-GM . We are actually using server file, but don't think that helps with this issue. We use it to configure our fastify server, not sure how can you configure graphql server via that?

@Josh-Walker-GM
Copy link
Collaborator

Cool to hear! What I'll do is try to see if it is possible to that configuration or not and get back to you.

@dthyresson
Copy link
Contributor

dthyresson commented Sep 24, 2024

Hi @jan-stehlik might you explain the goal or purpose of the wrappers is:

export async function handler(event, context) {
  // this never gets fired
  console.log(`in handler wrapper`)

  const requestIdHeader = 'x-request-id'
  const requestId = event.headers[requestIdHeader]
  const store: Store = new Map([['requestId', requestId]])
  const response = await executionContext.run(store, () => {
    return graphqlHandler(event, context)
  })
  return {
    ...response,
    headers: { ...(response.headers ?? {}), [requestIdHeader]: requestId },
  }
}

Do you want to pass in a request id on header, extract it, and then also include it on the headers back in the response?

If so I think writing a custom envelop/yoga plugin could work great here to:

  • extend the context so request id is available in services/resolvers
  • enrich the execution result with the header info

See: https://the-guild.dev/graphql/envelop/v4/plugins/lifecycle

@jan-stehlik
Copy link
Author

thanks @dthyresson , the reason for our wrapper is to have improved observability capabilities. We log extra metadata that is dynamic per request

we are interested in logging metadata like requestId or userId

// executionContext.ts
import { AsyncLocalStorage } from 'node:async_hooks'

export type StoreKey = 'userId' | 'requestId' | 'webhook'
export type Store = Map<StoreKey, string>

export const executionContext = new AsyncLocalStorage<Store>()

we use this context to log custom data that is dynamic

// logger.ts
function createLogger()_ {
  return winston.createLogger({
    format: winston.format.combine(
      winston.format((info) => {
        // log context specific data
        const store = executionContext.getStore()
          ? executionContext.getStore()
          : new Map()
        for (const [key, value] of store) {
          info[key] = value
        }

        return info
      })(),
    ),
    // ..
  })
}
export const logger = createLogger()

finally we populate this metadata on request basis

// graphql.ts
const graphQLHandler = createGraphQLHandler({
  async context({ context }: { context: RedwoodGraphQLContext }) {
    const enrichedContext = await buildContext(context)

    if (enrichedContext.currentUserId) {
      executionContext.getStore()?.set('userId', enrichedContext.currentUserId)
    }

    return enrichedContext
  },
  // ...
})

export async function handler(event, context) {
  const requestIdHeader = 'x-request-id'
  const requestId = event.headers[requestIdHeader] ?? scuid()
  const store: Store = new Map([['requestId', requestId]])
  const response = await executionContext.run(store, () =>
    graphQLHandler(event, context)
  )
  return {
    ...response,
    headers: { ...(response.headers ?? {}), [requestIdHeader]: requestId },
  }
}

then when we e.g. use logger in our resolver, we automatically log requestId & userId making it easy to correlate and debug code in logs

// mutation.ts
// automatically logs requestId & userId
logger.info('my mutation', { data: { currentUser } })

i'll look into envelop plugin, but i'm not sure if I can have a logger that retrieves request specific metadata and automatically attaches it, any ideas welcome!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug/confirmed We have confirmed this is a bug topic/graphql
Projects
Status: Ready
Development

No branches or pull requests

3 participants