Bug: xray_trace_id is not populated in log lines

[humanzz]

Bug description

According to documentation, the xray_trace_id should be emitted in all log lines if the request is traced. However, I'm not seeing any setting of that field in my logs despite the REPORT log line showing the request is traced.

Expected Behavior

All log lines to have xray_trace_id populated if the request is traced (as confirmed by REPORT line).

Current Behavior

No log lines showing the xray_trace_id.

Possible Solution

I've read a little bit in the code in Logger.ts and I suspect that xRayTraceId is set only once at Logger construction time.

The traceId is read via an environment variable that'll change for each different request. As such, I think a possible solution is to leverage addContext to also set that value when calling this.addToPowertoolLogData

The actual behaviour I've seen is that xray_trace_id is not being written to the logs. If my understanding is correct, I believe this issue can be manifested in 1 of 2 ways

1. The one observed i.e. lack of xray_trace_id which is likely to happen if the first request is not traced (i.e. cold start request). In this case all subsequent requests will not have the field
2. Wrong xray_trace_id (not observed) if the first request is traced and the environment variables is read and the field is set in Logger's state but subsequent requests will not update that value.

Steps to Reproduce

For a handler looking like

export const handler = middy(vanillaHandler)
  .use(captureLambdaHandler(tracer))
  .use(logMetrics(metrics))
  .use(injectLambdaContext(logger)),

1. Invoke the function multiple times
2. Inspect the log lines looking for xray_trace_id in the different requests (especially those where REPORT line indicates request is traced)

xray_trace_id is missing

Environment

• Powertools version used: 0.8.0
• Packaging format (Layers, npm): npm
• AWS Lambda function runtime: Node.js 14.x
• Debugging logs:

Related issues, RFCs

N/A

[dreamorosi]

Hello @humanzz, thanks for opening this issue.

I made a couple of tests and was able to reproduce the behaviour you describe also in the latest version (v 0.8.1) - see screenshot below in which tracing is enabled and both executions were sampled (no xray_trace_id present):

We will be looking at a fix for this.

[dreamorosi]

After a closer look I just realised that it's not possible to piggy back on addContext like suggested by OP. We can guarantee that the addContext function is ran only when Logger is used with decorators and middleware, while when running in manual mode the function has to be called explicitly by customers.

The above would contradict with the statement (docs) that xray_trace_id is part of the standard structured keys.

Will be looking at alternatives.

[dreamorosi]

A fix is available in #776, it will be most probably included in one of the next two releases based on time needed for review & merge.

[humanzz]

Thanks @dreamorosi, really appreciate the prompt action. I'll keep an eye for the upcoming releases

[github-actions]

⚠️ COMMENT VISIBILITY WARNING ⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.