Incorrect trace ID in express middleware

[seeARMS]

I'm having issues using this library alongside the cloud-trace-nodejs 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:

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":

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:

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:

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.

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

[seeARMS]

I filed a bug in the cloud-trace-nodejs component, as I actually think the problem may be with the trace context being lost somehow during the request. Feel free to close this, if you agree.

[minherz]

Thank you for reporting it. Would it be possible for you to clarify/confirm the terminology that you used in the report:

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

What do you mean by "tied to"? Do you reference to a grouping feature which allows you to see logs ingested within the specific request transaction as folded under the request log?

This also includes child loggers.

and

Triggering an arbitrary request, with one child log entry...

What do you mean by "child" loggers and log entries? Are these the logs ingested by the handler of the original request or another request? In the latter case, was another request issued by the handler of the original request or by the client?

In general, the application logs will be grouped under the request log ingested by a load balancer IFF the following conditions hold:

• The request log entry and application log entry have to have different lognames but to be ingested in the same project
• Both the request and application logs have to have the exactly same resource metadata (type and labels)
• The application log entries' timestamps must be within the range of the [request_log.timestamp−request_log.httpRequest.latency−60s, request_log.timestamp]
• All log entries have to have the same trace field (as you correctly noticed)

[losalex]

Closing due to prolong inactivity