XRay Subsegment In Lambda Constructor Not Appearing in XRay Trace

[BradKnowles]

I'm using XRay in a .NET 6, pure (no ASP.NET), Lambda function and attempting to get insight into initialization performance. Below is a sample of the Function's constructor.

AWSSDKHandler.RegisterXRayForAllServices();
AWSXRayRecorder.InitializeInstance();
_recorder = AWSXRayRecorder.Instance;
_recorder.ContextMissingStrategy = ContextMissingStrategy.LOG_ERROR;

_recorder.BeginSubsegment("Constructor");
... more code...
_recorder.EndSubsegment();

The Constructor subsegment never appears in the XRay Trace. Is there something else needed to have these subsegments appear in XRay.

Package Versions
Amazon.Lambda.Core - 2.1.0
AWSXRayRecorder.Core - 2.14.0
AWSXRayRecorder.Handlers.AwsSdk - 2.12.0

[srprash]

Hi @BradKnowles
Can you ensure you have enabled active tracing on your Lambda function, and that the IAM role used for the function invocation has the xray:PutTraceSegments permission or the AWSXRayDaemonWriteAccess policy attached to it?

If you've done the above, can you provide us the debug logs for investigation? You can find the information to setup logging here.

Alternatively, if you are interested in using OpenTelemetry, you can try out the AWS Distro for OpenTelemetry to instrument your Lambda function using the vended lambda layer.

[BradKnowles]

I'll work on providing the logging, as we are getting XRay traces for all other subsegments, just not ones placed in the constructor.

[BradKnowles]

These are the logs I recorded. The logs before START RequestId: are from the constructor. Complains about _X_AMZN_TRACE_ID are missing/not valid trace id, parent id or sampling decision, discarding subsegment : LoggingConfig

5/12/2023 10:48:41 AM	INIT_START Runtime Version: dotnet:6.v16 Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:43a35057cab96aae0f4c1fd3290aaa60f3b9bbc856b97639391c62b3ce111444
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.207Z  info AWSXRayRecorderImpl 1|2023-05-12T14:48:42.206Z|DEBUG|Context missing mode : LOG_ERROR
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.212Z  info AWSXRayRecorderImpl 2|2023-05-12T14:48:42.212Z|DEBUG|AWS_XRAY_CONTEXT_MISSING environment variable is set to LOG_ERROR. Override local value.
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.212Z  info XRayStopWatch=685
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.212Z  info AWSXRayRecorder 3|2023-05-12T14:48:42.212Z|DEBUG|Lambda Environment detected. Lambda variables:
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.212Z  info AWSXRayRecorder 4|2023-05-12T14:48:42.212Z|DEBUG|Lambda variables :  for X-Ray trace header environment variable under key : _X_AMZN_TRACE_ID are missing/not valid trace id, parent id or sampling decision, discarding subsegment : LoggingConfig
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.217Z  info LoggingStopWatch=2
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.217Z  info AWSXRayRecorder 5|2023-05-12T14:48:42.217Z|DEBUG|Lambda Environment detected. Lambda variables:
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.217Z  info AWSXRayRecorder 6|2023-05-12T14:48:42.217Z|DEBUG|Lambda variables :  for X-Ray trace header environment variable under key : _X_AMZN_TRACE_ID are missing/not valid trace id, parent id or sampling decision, discarding subsegment : RedisFactorySetup
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.446Z  info RedisServiceFactoryStopWatch=228
5/12/2023 10:48:42 AM	START RequestId: 3f87eac1-62dc-455f-8a5c-8f99a8810c23 Version: $LATEST
5/12/2023 10:48:42 AM	2023-05-12T14:48:42.693Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info AWSXRayRecorder 7|2023-05-12T14:48:42.693Z|DEBUG|Lambda Environment detected. Lambda variables: Root=1-645e51c9-70a0557b6a21c99473b0a931;Parent=ab770f33cbfe47fe;Sampled=1;Lineage=c8554449:0
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.795Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info UdpSegmentEmitter 8|2023-05-12T14:48:43.795Z|DEBUG|UDP Segment emitter endpoint: 169.254.79.129:2000.
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.796Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info AWSXRayRecorder 9|2023-05-12T14:48:43.796Z|DEBUG|Lambda Environment detected. Lambda variables: Root=1-645e51c9-70a0557b6a21c99473b0a931;Parent=ab770f33cbfe47fe;Sampled=1;Lineage=c8554449:0
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.875Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info UdpSegmentEmitter 10|2023-05-12T14:48:43.875Z|DEBUG|UDP Segment emitter endpoint: 169.254.79.129:2000.
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.875Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info AWSXRayRecorder 11|2023-05-12T14:48:43.875Z|DEBUG|Lambda Environment detected. Lambda variables: Root=1-645e51c9-70a0557b6a21c99473b0a931;Parent=ab770f33cbfe47fe;Sampled=1;Lineage=c8554449:0
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.916Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info UdpSegmentEmitter 12|2023-05-12T14:48:43.916Z|DEBUG|UDP Segment emitter endpoint: 169.254.79.129:2000.
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.916Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info UdpSegmentEmitter 13|2023-05-12T14:48:43.916Z|DEBUG|UDP Segment emitter endpoint: 169.254.79.129:2000.
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.916Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info UdpSegmentEmitter 14|2023-05-12T14:48:43.916Z|DEBUG|UDP Segment emitter endpoint: 169.254.79.129:2000.
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.916Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info AWSXRayRecorder 15|2023-05-12T14:48:43.916Z|DEBUG|Lambda Environment detected. Lambda variables: Root=1-645e51c9-70a0557b6a21c99473b0a931;Parent=ab770f33cbfe47fe;Sampled=1;Lineage=c8554449:0
5/12/2023 10:48:43 AM	2023-05-12T14:48:43.933Z 3f87eac1-62dc-455f-8a5c-8f99a8810c23 info UdpSegmentEmitter 16|2023-05-12T14:48:43.933Z|DEBUG|UDP Segment emitter endpoint: 169.254.79.129:2000.
5/12/2023 10:48:44 AM	END RequestId: 3f87eac1-62dc-455f-8a5c-8f99a8810c23
5/12/2023 10:48:44 AM	REPORT RequestId: 3f87eac1-62dc-455f-8a5c-8f99a8810c23 Duration: 1624.64 ms Billed Duration: 1625 ms Memory Size: 256 MB Max Memory Used: 132 MB Init Duration: 1081.00 ms 
XRAY TraceId: 1-645e51c9-70a0557b6a21c99473b0a931 SegmentId: 4f18188646c64c67 Sampled: true

[BradKnowles]

Have you gotten a chance to review my posted logs @srprash ?

[srprash]

Thanks for providing the logs. It seems like the trace header is only present in the _X_AMZN_TRACE_ID after the line 5/12/2023 10:48:42 AM START RequestId: 3f87eac1-62dc-455f-8a5c-8f99a8810c23 Version: $LATEST. This measn that every subsegment created above this will be ignored.

However, I'm confused by the fact that we don't even see any logs indicating creation of the Constructor subsegment.
Can you provide a small reproduction code that I can run on my side for debugging?

[BradKnowles]

Apologies for the delay, I will try to get something to you this week.

[BradKnowles]

@srprash a demo repository can be found here - https://github.com/BradKnowles/xray-constructor-issue-289

[BradKnowles]

Following up with you @srprash to see if I can provide any more help in tracking this down.

[BradKnowles]

Following up with you @srprash to see if I can provide any more help in tracking this down.