cloud-trace-nodejs icon indicating copy to clipboard operation
cloud-trace-nodejs copied to clipboard

Context lost using nodejs-logging-bunyan Express middleware

Open seeARMS opened this issue 4 years ago • 0 comments

I'm having issues using this library alongside the nodejs-logging-bunyan library.

In my node.js app, the trace IDs that the middleware is using for the parent request as well as all log entries are not actually tied to the request's trace. This also includes child loggers.

I have the middleware configured as so (since I'm using ESModules everywhere and compiling TS into JS, I'm using the solution described here to ensure the Cloud Trace library runs before everything else):

// app.ts

import { createRequire } from "module"

const require = createRequire(import.meta.url)
const express = await require("express")
const { logger, mw } = await lb.express.middleware({
  logName: "papyrus-api",
  level: "debug",
  //maxEntrySize: 256000,
})

app.use(mw)

// Further below I create a child logger 
req.log = req.log.child({
  labels: { user: decoded?.email || "" },
})

I have the Cloud Trace library configured as so:

// trace.ts
import { createRequire } from "module"

const require = createRequire(import.meta.url)

require("@google-cloud/trace-agent").start({
  projectId: "my-project-id",
  keyFilename: "my-key-filename",
  ignoreUrls: [/^\/health/],
  serviceContext: {
    service: "papyrus-api",
    version: "0.0.1",
  },
  logLevel: 1,
})

const run = await import("./app")

Triggering an arbitrary request, with one child log entry, gives the following in Stackdriver logging:

image

This is properly nested and generally looks correct. However, looking at the trace for this request, it uses a different trace ID and says "no logs found for this trace":

image

I tried manually setting the trace IDs using a custom middleware, and surprisingly, this began showing proper trace IDs (for the log entries) in the trace UI:

 app.use((req: any, res: any, next: any) => {
    const agent = global._google_trace_agent
    const traceId = agent?.getCurrentContextId()
    const traceProjectId = agent?.getWriterProjectId()

    if (traceId && traceProjectId) {
      req.log = req.log.child({
        [LOGGING_TRACE_KEY]: `projects/${traceProjectId}/traces/${traceId}`,
      })
    }

    next()
  })

The trace UI:

image

After doing this, though, the log entries (in Stackdriver Logging) became un-nested, presumably because the trace ID for the parent request is now different from the child requests:

image

I'm not quite sure why Stackdriver Logging is using a different trace ID than what is actually being used to trace the request. I also couldn't figure out how to override the parent request log entry to set the trace ID, similar to how I set it for the child logger.

I am using ESModules and import statements everywhere else (including for all my routes), but I'm not sure if that could cause this bug either.

Environment details

  • Environment: Node.js is deployed on fly.io, NOT on GCP. I'm using a serviceaccount to connect to the Cloud Trace and Stackdriver APIs on my GCP account.
  • Node.js version: Node v17
  • npm version: 8.1.2
  • @google-cloud/logging-bunyan version: 3.1.1
  • @google-cloud/trace-agent version: 5.1.6

seeARMS avatar Dec 04 '21 19:12 seeARMS