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

[jan-stehlik]

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

[Josh-Walker-GM]

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]

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:

2. 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]

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]

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]

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]

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!

[jan-stehlik]

hey guys, any update on this one please? 🙏

[jan-stehlik]

hey @Josh-Walker-GM , any chance this could be looked into? thanks!

[Tobbe]

@jan-stehlik Thanks for your patience. I'm about to hit the hay, but I'll read through the issue tomorrow to get up to speed. And then we'll see what I can do from there

[Tobbe]

Finally found some time to read through this and think about it.
Like Josh said, I can fix the babel plugin to also support the function syntax in addition to the arrow function syntax. But that won't be enough. The actual fix you need is a much larger problem. I do remember discussing the work Josh did on making sure we isolate the context. IIRC we both agreed what we were doing wasn't ideal. But we also agreed not leaking data between requests was the top priority, so we went with the solution that guaranteed that.

That said, I have been noticing some context-related issues in one of my own apps as well. I'll try to see if there's any overlap between my issue and yours.

BTW, are you running RW in a serverless environment or serverfull? Maybe we just have to give up on the idea of being able to support both environments with identical code in our user's projects...

[jan-stehlik]

Hey @Tobbe , agreed that function syntax is not a problem here, the issue persist if we switch to arrow syntax too. We define our own server.ts so we run serverful envrionment. This wasn't an issue when we ran serverless env, but we had to switch to defining our own fastify server so that we could support more features (file upload with our own content type parser etc).

At the core I'm looking for a solution to have context aware logs, isolated per request. If there is different way to achieve it without using AsyncLocalStorage I'm more than happy to try those, I just haven't figured out any other alternative.

[Tobbe]

AsyncLocalStorage does sound like the best (only?) option here. I'll spend a couple of hours working on this issue tomorrow. Unfortunately can't spend much more time on it than that right now.

Sorry I can't provide a better answer :'(

[kovacss]

Hey team,

We managed to get around the wrapper limitation by implementing a yoga plugin

const executionContextPlugin: Plugin = {
  onExecute({ args, executeFn, setExecuteFn }) {
    const context = args.contextValue
    const store: Store = new Map([])
    const requestId = context.event.headers['x-request-id'] ?? scuid()
    store.set('requestId', requestId)
    setExecuteFn(async (args) => {
      return executionContext.run(store, async () => {
        return await executeFn(args)
      })
    })
  },
}

And then use use it with createGraphQLHandler

const graphqlHandler = createGraphQLHandler({
  loggerConfig: { logger, options: {} },
  directives,
  sdls,
  services,
  onException: () => {
    db.$disconnect()
  },
 // Inject plugins
 extraPlugins: [executionContextPlugin],
})

Hope that helps for anyone looking to achieve something similar !