A couple minor thoughts on logging

[BMorinDrifter]

Minor things things I've run into since I've started moving some parts of our serverless game service stack from python to rust.

ANSI

The examples do this:

tracing-subscriber = { version = "0.3", default-features = false, features = ["ansi", "fmt"] }

        // this needs to be set to false, otherwise ANSI color codes will
        // show up in a confusing manner in CloudWatch logs.
        .with_ansi(false)

However if we instead remove the ansi feature and the corresponding rust code

tracing-subscriber = { version = "0.3", default-features = false, features = ["fmt"] }

As far as I can tell, I get the same output and my bootstrap.zip file is slightly smaller when I omit the ansi feature. Perhaps this is something that changed with newer versions of the crate?

boostrap.zip Optimization

On a related note, should this be part of the .toml file for the examples as well? These settings seem to be used by multiple projects to reduce cold start time. Seems like it should be better communicated as minimal cold start times are a selling point of the lambda runtime.

[profile.release]
opt-level = "z"
lto = true
codegen-units = 1
panic = "abort"

Log Signal vs Noise

If I take the basic-lambda sample and add a single log entry to it:

use tracing::info;

info!("Command {command} executed.");

I get this output:

START RequestId: 4a13eece-897d-4eb7-9649-99ccc5db4b0c Version: $LATEST
INFO Lambda runtime invoke{requestId="4a13eece-897d-4eb7-9649-99ccc5db4b0c" xrayTraceId="Root=1-64a4983c-3d3c987a58fc4a6b58e70823;Parent=021c988b194e6648;Sampled=0;Lineage=16f3a795:0"}: Command hello executed.
END RequestId: 4a13eece-897d-4eb7-9649-99ccc5db4b0c
Max Memory Used: 12 MB	Init Duration: 6.29 ms

Compare this to what I get from a comparable Python example:

import json
import logging

logger = logging.getLogger()
logger.setLevel(logging.INFO)

def lambda_handler(event, context):
    
    logger.info("Hello From Lambda")
    
    return {
        'statusCode': 200,
        'body': json.dumps('Hello from Lambda!')
    }

START RequestId: b7ca4fac-77c4-472c-b623-9d3e7588d06a Version: $LATEST
[INFO]	2023-07-04T22:15:12.656Z	b7ca4fac-77c4-472c-b623-9d3e7588d06a	Hello From Lambda
END RequestId: b7ca4fac-77c4-472c-b623-9d3e7588d06a
REPORT RequestId: b7ca4fac-77c4-472c-b623-9d3e7588d06a	Duration: 19.32 ms	Billed Duration: 20 ms	Memory Size: 128 MB	Max Memory Used: 36 MB	Init Duration: 112.98 ms

You probably had to scroll right to see the text in the Rust example ;-) mostly because of the x-ray trace id, but the verbose span name of Lambda runtime invoke doesn't help either. When I started experimenting with rust lambda functions, I spent an hour trying to figure out "how do I turn that off".

Now I'm a little deeper under the hood on this, I found the root library code:

            let request_span = match &ctx.xray_trace_id {
                Some(trace_id) => {
                    env::set_var("_X_AMZN_TRACE_ID", trace_id);
                    tracing::info_span!("Lambda runtime invoke", requestId = request_id, xrayTraceId = trace_id)
                }
                None => {
                    env::remove_var("_X_AMZN_TRACE_ID");
                    tracing::info_span!("Lambda runtime invoke", requestId = request_id)
                }
            };

Outside of the initial developer experience this is totally the right thing to do. However it is a little frustrating not to have any agency to use a shorter span name, a different verbosity level, or opt out of requestId and/or xrayTraceId without forking the runtime.

I'm unsure what the best path forward would be from here. A few takes:

• There probably is a way to set-up environment variables or pass a filter string to omit this span (that said, I'd prefer it just to write less text)
• Maybe this is an tracing-subscriber short coming? I couldn't find a way to write the decoration after the event.
• Maybe there could be runtime configuration via either environment variables or a builder for the runtime object?
• Something else????

[calavera]

Thanks a lot for the feedback @BMorinDrifter! I'm leaving some comments below

ANSI

I agree with you. That feature should be removed from all our examples (feel free to open a PR). For most people following tutorials, we recommend starting projects with cargo lambda new, the template that we use for those projects doesn't include the ansi feature already, we should match that.

boostrap.zip Optimization

I'm not aware that any of those options improve cold start times. I'll appreciate it if you shared where you found that information. However, they do reduce the binary size. For most people, we recommend using cargo lambda build --release which does some of those optimizations by default, without setting anything in Cargo.toml. lto optimization is a tricky one because it can increase the compilation time. Some people are adverse to long compilation times, so I personally prefer to not enable it, and leave it up to everyone.

Log Signal vs Noise

I agree with you that the default log might not need the xray id. Do you enable the tracing option when you create or update the lambda function? It might make sense to not add the xray id if that option is not enabled, there is an environment variable for it. We'd have to check how to make a change like this because I know some people that use that xray id, so it's important to try not breaking backwards compatibility.

[BMorinDrifter]

boostrap.zip optimization

That block is used by the cold start comparison page:
https://maxday.github.io/lambda-perf/
https://github.com/maxday/lambda-perf/blob/main/s3-uploader/runtimes/rust_on_provided_al2/Cargo.toml

I managed to engineer most of it via https://github.com/johnthagen/min-sized-rust until I found that block. I've seen the exact same block in other projects as well. My concern is others trying to replicate those crazy times will fall short without this piece.

My observation using this in production so far is that the size of bootstrap.zip does correlate strongly to start-up time unless you're making RPCs in main() for configuration, etc. Also bringing in something like lambda extensions for monitoring might overshadow gains from a smaller bootstrap.zip. Outside of those cases, the impact on binary size grows as you add dependencies and do real work. If this result is in dispute, I can put together something reproducible so my results can be confirmed by others. That said, my Rust Lambda functions run so darn fast that the per-invoke cost is way higher than the per-mb-millisecond cost, so we're well into penny pinching territory here.

Do you enable the tracing option when you create or update the lambda function?

Can you be more specific? At this point most of my work starts with copying boilerplate from other projects I've done....

[rimutaka]

@calavera , the amount of noise in the logs feels counter-productive.

Can we start a discussion to make that entire tracing span optional / configurable / overwritable?

Not sure what is possible and would like to hear your opinion before investing any more time into this.

[calavera]

Well once nice thing about tracing-subscriber is that you can provide your own logic to print the logs if you don't like the default. There is nothing stopping you from changing it, you don't even need to change anything in this repo.

I'm open to improvements in form of Pull Requests.

[rimutaka]

Thanks @calavera! I'll look into it, but if you know if any examples, I'd love a link :)

[rimutaka]

@calavera , after a bit of experimenting, I figured that the easiest way to remove the span fields is to init a different subscriber within the handler, e.g.

pub(crate) async fn my_handler(event: LambdaEvent<Request>) -> Result<Response, Error> {
    info!("With global default provider"); // prints an extended message, incl x-trace-id

    // init a local subscriber
    let sub = tracing_subscriber::fmt().without_time().finish();
    let _guard = tracing::subscriber::set_default(sub);

    let command = event.payload.command;

    info!("With the local provider"); // prints short messages, no span info from now on
    info!("Command received: {}", command);

    Err(Error::from("Error"))
} // the local subscriber is dropped here, back to printing x-trace-id

it produces a log like this

 INFO Lambda runtime invoke{requestId="local-request-id" xrayTraceId="Root=0-00000000-000000000000000000000000;Parent=0000000000000000;Sampled=0;Lineage=00000000:0"}: With global default provider
 INFO test_lambda: With the local provider
 INFO test_lambda: Command received: echo
ERROR Lambda runtime invoke{requestId="local-request-id" xrayTraceId="Root=0-00000000-000000000000000000000000;Parent=0000000000000000;Sampled=0;Lineage=00000000:0"}: "Error"

where 1 and 3 were logged by the global default subscriber with the span info.
Lines 2 and 3 were logged by the subscriber created inside the handler fn (no span).

Shall I mention this in the logging section of the ReadMe or is there a better way of achieving the same result?

[calavera]

I'm not a tracing expert, but I think creating a subscriber per invocation is not a good pattern.

Tracing has the concepts of layers and visitors that allow you to modify how spans are handled and used. Perplexity gave me this answer, take it with a grain of salt because it was AI generated and I didn't test it.

Everything after this line was generated by Perplexity.ia

To create a custom adapter for the tracing subscriber that removes the "xRayId" field from spans before printing logs, we can implement a custom Layer that wraps another layer (like the formatting layer) and filters out the specified field. Here's how we can do this:

use std::any::TypeId;
use tracing_core::{span::Attributes, Subscriber};
use tracing_subscriber::Layer;

// Custom layer to remove xRayId field
struct RemoveXRayIdLayer<S> {
    inner: S,
}

impl<S> RemoveXRayIdLayer<S> {
    fn new(inner: S) -> Self {
        Self { inner }
    }
}

impl<S> Layer<S> for RemoveXRayIdLayer<S>
where
    S: Subscriber,
    Self: Layer<S>,
{
    fn on_new_span(&self, attrs: &Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) {
        // Create a new Attributes instance without the xRayId field
        let filtered_attrs = attrs.record(&mut RemoveXRayIdVisitor);
        self.inner.on_new_span(&filtered_attrs, id, ctx)
    }

    // Implement other Layer methods by delegating to the inner layer
    // ...
}

// Visitor to remove xRayId field
struct RemoveXRayIdVisitor;

impl tracing_core::field::Visit for RemoveXRayIdVisitor {
    fn record_debug(&mut self, field: &tracing_core::Field, value: &dyn std::fmt::Debug) {
        if field.name() != "xRayId" {
            // Record all fields except xRayId
            // Note: This is a simplified example. In a real implementation,
            // you'd need to handle different types of fields correctly.
            tracing_core::field::Visit::record_debug(self, field, value);
        }
    }

    // Implement other Visit methods similarly
    // ...
}

// Usage example
fn main() {
    use tracing_subscriber::prelude::*;

    let fmt_layer = tracing_subscriber::fmt::layer().pretty();
    let remove_xray_id_layer = RemoveXRayIdLayer::new(fmt_layer);

    tracing_subscriber::registry()
        .with(remove_xray_id_layer)
        .init();

    // Your tracing code here
    tracing::info!(xRayId = "1234", "This is a log message");
}

This implementation does the following:

1. We define a RemoveXRayIdLayer struct that wraps another layer (the "inner" layer).

2. We implement the Layer trait for RemoveXRayIdLayer. In the on_new_span method, we create a new Attributes instance without the "xRayId" field using our custom RemoveXRayIdVisitor.

3. The RemoveXRayIdVisitor implements the Visit trait. It records all fields except "xRayId".

4. In the usage example, we create a formatting layer, wrap it with our RemoveXRayIdLayer, and use it to initialize the tracing subscriber.

This implementation will remove the "xRayId" field from spans before they are processed by the inner formatting layer. Note that this is a simplified example and may need to be expanded to handle all types of fields and to implement all methods of the Layer and Visit traits for full functionality.

Also, keep in mind that this approach removes the field at the span creation level. If you need to remove the field from events as well, you'd need to implement similar logic in the on_event method of the Layer trait.

Citations:
[1] https://burgers.io/custom-logging-in-rust-using-tracing
[2] https://www.reddit.com/r/rust/comments/14pg0zh/how_can_i_write_a_tracing_subscriber_that_saves/
[3] https://docs.rs/tracing-subscriber/latest/tracing_subscriber/
[4] https://users.rust-lang.org/t/changing-a-fields-value-in-a-tracing-span/102435
[5] https://docs.rs/tracing/latest/tracing/span/index.html
[6] https://dtantsur.github.io/rust-openstack/tracing/span/struct.Span.html
[7] https://docs.rs/tracing-subscriber/latest/tracing_subscriber/layer/index.html
[8] https://stackoverflow.com/questions/73247589/how-to-turn-off-tracing-events-emitted-by-other-crates

[rimutaka]

@calavera, very interesting! Thank you for digging it out :)

I agree that creating a subscriber per invocation is inefficient.
It is more of a workaround to use during development / debugging.
I am probably not the only one getting frustrated by the clutter in the logs, so I thought adding the workaround to ReadMe was a good idea.

It would be nice to have an optional env var to tell the runtime not to add the span.
Then we'd need no code changes between different environments and it would be backward compatible.

Assuming that on_new_span approach works, do you suggest it goes into the runtime as an optional Layer or would the user have to implement it alongside the handler?

[calavera]

It could live here as an option for the default subscriber, or any other subscriber that people want to use: https://github.com/awslabs/aws-lambda-rust-runtime/blob/main/lambda-runtime-api-client/src/tracing.rs

[rimutaka]

@calavera , I tried the custom formatter approach, but it felt like a crutch for several reasons:

1. Removing fields did not remove the span name
2. Removing the span name required even more code
3. It is a lot of extra code to write, test and maintain

No fields

 INFO Lambda runtime invoke: With global default provider
 INFO Lambda runtime invoke: Command received: echo
ERROR Lambda runtime invoke: "Error"

Alternative solution

It seems that not adding the span in the first place is a more flexible and easier solution.
I repurposed AWS_LAMBDA_LOG_FORMAT env var for that.
It lets us have very concise logs for development / debugging and the full log in PROD without changing the code.

See my draft PR #911 for what it may look like.

Sample output:

 INFO With global default provider
 INFO Command received: echo
ERROR "Error"