X-ray / opentelemetry issues

[mreimer]

Hi devs, I have a few issues using X-ray with the lambda runtime. For context, I'm using a custom lambda image with aws-otel-collector loaded as an extension, and my function sets up an opentelemetry pipeline to trace and export to the collector. I'm pretty new to rust, lambda, x-ray, and opentelemetry so please correct me if I've misunderstood how this all works. Here are my issues:

1. If I have active tracing enabled on the lambda, for each execution I end up with two unconnected traces in the x-ray console. One is the active trace with initialization, invocation, and overhead. The other is the "Lambda runtime invoke" instrumentation built into the lambda runtime. I see that the lambda runtime is pulling a request id and x-ray trace id from the headers, but that doesn't seem to be sufficient to connect the instrumented span to the active trace. For contrast, within my handler if I use opentelemetry to extract a context from the headers and create a span with that context, it will end up in the active trace, which I think is a better behaviour. I don't know exactly what use cases this runtime was designed for, but IMO we only ever want one trace whether or not active tracing is enabled.

2. The lambda runtime instrumentation from the most recent lambda execution isn't viewable in the x-ray console. It shows up in the list of traces, but attempting to view it just gets "An error occurred fetching your data" message. I'm inferring this is because the trace isn't complete, as execution of the lambda runtime was suspended before the end of the instrumented section (and subsequent flush). If I execute the lambda again, the previous trace now works, but the new most recent trace doesn't. If the lambda is unloaded after an idle period, the latest trace will stay in that broken state forever.

3. I'm explicitly flushing the opentelemetry pipeline at the end of my lambda handler. This has nothing to do with the rust lambda runtime, but I've found that the flush takes about 40ms which is a huge performance hit. It would be a lot easier to stomach if there were a way to do it after sending the response to the end user.

I'd be happy to work on a PR for these issues if it would help, but I don't know what the appropriate solutions would be in this ecosystem. It seems to me that 2 and 3 are straightforward to solve if lambda offers any mechanism to execute code after sending a response to the end user. Is that possible or is execution suspended immediately at that point?

[timClicks]

Thanks for raising these issues @mreimer. I'm sorry to hear that you're having trouble. Do you have example of some of the code that you've written so far?

[mreimer]

Sure, I put together a minimal example here: https://github.com/mreimer/rust-lambda-xray-example

There are some minor differences in its behaviour, relative to what I described:

1. As described.
2. The trace from the latest lambda execution doesn't show up at all until the lambda is executed again (rather than showing up in a broken state until the lambda is executed again).
3. Timing of the flush is highly variable. Around 20-100ms.

[ymwjbxxq]

Hi @mreimer

It is normal with X-Ray I think you have the same issue with other runtimes.

I'd be happy to work on a PR for these issues if it would help, but I don't know what the appropriate solutions would be in this ecosystem. It seems to me that 2 and 3 are straightforward to solve if lambda offers any mechanism to execute code after sending a response to the end user. Is that possible or is execution suspended immediately at that point?

Were you able to check the Lambda extensions?

• https://docs.aws.amazon.com/lambda/latest/dg/lambda-extensions.html
• https://github.com/aws-samples/lambda-extension-optimization/tree/main/src/rust

[jeastham1993]

Hi @mreimer ,

I think the issue with the disconnected traces is coming from it not loading the parent trace context when you're handling the individual request. I'm just testing a sample at the moment, will post it here when done.

For example, in the .NET world there is a library in the OTEL contrib that you can wrap around the Lambda function handler to parse these variables from the various locations. I think the outcome here could be a contribution to the Rust Open Telemetry contrib for an AWS Lambda handler.

Let me get back to you though.

[jeastham1993]

Just following up on the above, this works from the perspective of getting a single trace that's all linked together, including API Gateway right through to the Lambda context and the application specific traces. I'm still hitting an issue with traces coming through intermittently, but I think that's more reflective OTEL with the Lambda environment. As @ymwjbxxq mentions, it's the same in other runtimes. I sometimes see it in .NET as well

EDIT: Issue with traces coming through intermittently also resolved by settings the OTEL_BSP_MAX_EXPORT_BATCH_SIZE environment variable to be 1. This forces the BatchSpanProcessor to run right away instead of queuing up spans to send together. There is a performance hit to this however, but in my tests it seems to align with the ~40ms you referenced in the original issue.

There's a full example on my GitHub, deployed using AWS SAM and using the AWS Open Telemetry Lambda layer.

use aws_sdk_dynamodb::{types::AttributeValue, Client};
use lambda_http::{service_fn, Body, Error, Request, RequestExt, Response};
use std::env;
use opentelemetry::{
    global,
    sdk::trace as sdktrace,
    trace::{Span, Tracer}, Key, Context,
};
use opentelemetry_aws::trace::XrayPropagator;
use opentelemetry_otlp::WithExportConfig;
use opentelemetry_http::{HeaderExtractor};

fn init_tracer() -> sdktrace::Tracer {
    global::set_text_map_propagator(XrayPropagator::new());

    let tracer = opentelemetry_otlp::new_pipeline()
        .tracing()
        .with_exporter(
            opentelemetry_otlp::new_exporter()
                .tonic()
                .with_endpoint("http://localhost:4317"),
        )
        .with_trace_config(
            sdktrace::config()
                .with_sampler(sdktrace::Sampler::AlwaysOn)
                .with_id_generator(sdktrace::XrayIdGenerator::default()),
        )
        .install_simple();

    tracer.unwrap()
}

/// Main function
#[tokio::main]
async fn main() -> Result<(), Error> {
    // Initialize the AWS SDK for Rust
    let config = aws_config::load_from_env().await;
    let table_name = env::var("TABLE_NAME").expect("TABLE_NAME must be set");
    let dynamodb_client = Client::new(&config);

    let tracer = init_tracer();

    lambda_http::run(service_fn(|request: Request| {
        let provider = tracer
            .provider()
            .unwrap();

        let parent_context = global::get_text_map_propagator(|propagator| {
            propagator.extract(&HeaderExtractor(request.headers()))
        });

        let res = put_item(&dynamodb_client, &table_name, parent_context, request);

        provider.force_flush();

        res
    }))
    .await?;

    Ok(())
}

/// Put Item Lambda function
///
/// This function will run for every invoke of the Lambda function.
async fn put_item(
    client: &Client,
    table_name: &str,
    ctx: Context,
    request: Request,
) -> Result<Response<Body>, Error> {

    println!("Sample log message");

    let mut span = global::tracer("lambda-xray").start_with_context("Processing", &ctx);

    // code removed

    let mut dynamo_span = global::tracer("lambda-xray").start_with_context("Write to DynamoDB", &ctx);
    
    // code removed

    dynamo_span.end();

    // Return a response to the end-user
    match res {
        Ok(_) => Ok(Response::builder().status(200).body("item saved".into())?),
        Err(_) => Ok(Response::builder().status(500).body("internal error".into())?),
    }
}

[mreimer]

Thanks @jeastham1993 , this looks very helpful. I'll give it a try as soon as I can.

[mreimer]

@jeastham1993 I've unpacked your example and used it to figure out what was wrong with mine. It seems that as soon as I remove tracing-subscriber all of my problems are solved, including performance. I can probably live without tracing-subscriber so this is a fine solution for me. Thanks again.

[github-actions]

⚠️COMMENT VISIBILITY WARNING⚠️

Comments on closed issues are hard for the maintainers of this repository to see.
If you need more assistance, please 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.

[calavera]

as soon as I remove tracing-subscriber all of my problems are solved

oh, this is interesting, thanks for letting us know @mreimer. Maybe we should consider removing it as part of our recommended setup 🤔

[mreimer]

Well, it's quite possible that I just don't know how to configure it properly.

[davidbarsky]

Generally speaking, performance issues in tracing-subscriber like you describe @mreimer is something we treat as a bug (and as something pretty concerning). When you say performance issues, are you referring to the following?

This has nothing to do with the rust lambda runtime, but I've found that the flush takes about 40ms which is a huge performance hit

[mreimer]

Hi @davidbarsky. Yes, however I wasn't really being scientific about it so give me a few days to take some measurements with and without tracing-subscriber, and let me know where would be best to post results.

[davidbarsky]

Hi @davidbarsky. Yes, however I wasn't really being scientific about it so give me a few days to take some measurements with and without tracing-subscriber, and let me know where would be best to post results.

I suppose there is fine—unless @calavera has any objections—and I can always open a new issue on the tracing repo as needed with the details.