Support tracing crate

[dfeyer]

In most of our Lambdas we use tracing crate to have more advanced and structured logging. Can it be possible to add tracing support to this project ? I can be an optional feature.

Thanks for the good work, really like the current features

[JeremieRodon]

Hey,
Yeah sure.

Currently, I have few points of adherence with log and env_logger in the proc_macro, that should not be too difficult to adapt.

There is the main generation:

lambda-appsync/lambda-appsync-proc/src/appsync_lambda_main/mod.rs

Lines 382 to 396 in fa72a0b

	#[tokio::main]
	async fn main() -> ::core::result::Result<(), ::lambda_appsync::lambda_runtime::Error> {
	::lambda_appsync::env_logger::Builder::from_env(
	::lambda_appsync::env_logger::Env::default()
	.default_filter_or("info,tracing::span=warn")
	.default_write_style_or("never"),
	)
	.format_timestamp_micros()
	.init();
	#config_init
	::lambda_appsync::lambda_runtime::run(::lambda_appsync::lambda_runtime::service_fn(function_handler)).await
	}
	});

The function_handler is logging the event and the payload:

lambda-appsync/lambda-appsync-proc/src/appsync_lambda_main/mod.rs

Lines 369 to 373 in fa72a0b

	async fn function_handler(
	event: ::lambda_appsync::lambda_runtime::LambdaEvent<::lambda_appsync::serde_json::Value>,
	) -> ::core::result::Result<#ret_type, ::lambda_appsync::lambda_runtime::Error> {
	::lambda_appsync::log::debug!("{event:?}");
	::lambda_appsync::log::info!("{}", ::lambda_appsync::serde_json::json!(event.payload));

And the appsync_handler is logging the appsync_event and the extracted operation:

lambda-appsync/lambda-appsync-proc/src/appsync_lambda_main/mod.rs

Lines 318 to 320 in fa72a0b

	async fn appsync_handler(event: ::lambda_appsync::AppsyncEvent<Operation>) -> ::lambda_appsync::AppsyncResponse {
	::lambda_appsync::log::info!("event={event:?}");
	::lambda_appsync::log::info!("operation={:?}", event.info.operation);

I could make the current usage of log and env_logger a default feature and add a new feature to switch to tracing, but that still means I will generate initialization code which may not suits you. As I don't use tracing for my projects (yet) I will just use AWS provided doc example and I doubt it will be all you need (personally I would like tracing to use the RUST_LOG env var for example).

I feel I should generate a sensible default (can you help me?) like the one I have for env_logger and add a way to override entirely the initialization code in main.

So if you are OK, my current plan is:

• Add a env_logger feature and make it default so I do not introduce a breaking change
• feature-gate the current re-export of log and env_logger behind that feature
• feature-gate the current env_logger initialization code in main behind that feature
• feature-gate the usages of log::info and log::debug behind that feature
• Add a tracing feature
• feature-gate a re-export of tracing and tracing_subscriber behind that feature
• feature-gate a new tracing_subscriber initialization code behind that feature
• feature-gate usages of tracing::info and tracing::debug where I currently use log (should I also instrument appsync_handler or function_handler as shown in the AWS doc?).
• Bonus: introduce a new optional parameter to appsync_lambda_main, named log_init, allowing to provide a custom block of code that will be inserted in main instead of the default env_logger/tracing one

Thoughts?

[dfeyer]

Thanks, your plan looks really nice. I think log_init is kind of mandatory, tracing is flexible, and it's hard to find a perfect sweet spot for the default, my suggestion will be to mix RUST_LOG and the default suggested by AWS, and JSON format:

tracing_subscriber::fmt()
        .json()
        .with_env_filter(
            tracing_subscriber::EnvFilter::from_default_env()
                .add_directive(tracing::Level::INFO.into()),
        )
        // this needs to be set to remove duplicated information in the log.
        .with_current_span(false)
        // this needs to be set to false, otherwise ANSI color codes will
        // show up in a confusing manner in CloudWatch logs.
        .with_ansi(false)
        // disabling time is handy because CloudWatch will add the ingestion time.
        .without_time()
        // remove the name of the function from every log entry
        .with_target(false)
        .init();

[JeremieRodon]

Just so you know: I did not forget you and I plan to work on this this week. I happen to be rather busy at the moment, sry.

[dfeyer]

No problem it's a request not an order, don't rush, I can wait. Thanks

[JeremieRodon]

@dfeyer I have created a new branch so you can test the new features before I merge into master.

You can test what I did by modifying your Cargo.toml as follow (you can do it at workspace level if you use one):

[dependencies]
lambda-appsync = { version = "0.8.0", default-features = false, features = ["tracing"] }
# Other deps...

[patch.crates-io]
lambda-appsync = { git = "https://github.com/JeremieRodon/lambda-appsync", branch = "feat-tracing" }

If you compile and deploy with that, you will notice it is using tracing.

The default initialization code is the one you suggested (I reactivated the timestamp so we don't have to rely solely on CloudWatch ingestion time, which is not at all accurate). You can write a custom initialization function and pass it to the macro with the log_init option:

fn tracing_init_fct() {
    todo!("Awesome custom init code")
}
lambda_appsync::appsync_lambda_main!(
     "schema.graphql",
     log_init = tracing_init_fct
);

I tested it on one of my projects and it works, but I'm not really happy with the current format. I don't know how to log the payload as a true JSON structure so it is displayed nicely in CloudWatch (currently it is an escaped string in the tracing event). If you know how to do it, I'm all ears.

I added some code to instrument the function_handler (which is invoked by the Lambda runtime) and the appsync_handler (which gets one parsed AppsyncEvent structure, call the authentication hook if present and execute the downstream Operation function defined by users), I'm not sure it is really useful to instrument both or how I should instrument them...

For easiness if you want to suggest something, the relevant code generated when using the tracing feature looks something like that:

#[tracing::instrument(skip(event), fields(operation = ?event.info.operation))]
async fn appsync_handler(event: AppsyncEvent<Operation>) -> AppsyncResponse {
    tracing::info!("event={event:?}")
    event.info.operation.execute(event).await
}

async fn appsync_batch_handler(events: Vec<AppsyncEvent<Operation>>) -> Vec<AppsyncResponse> {
    let handles = events
        .into_iter()
        .map(|e| tokio::spawn(appsync_handler(e)))
        .collect::<Vec<_>>();

    let mut results = vec![];
    for h in handles {
        results.push(h.await.unwrap())
    }
    results
}

#[tracing::instrument(skip(event), fields(req_id = %event.context.request_id))]
async fn function_handler(event: lambda_runtime::LambdaEvent<serde_json::Value>) -> Result<Vec<AppsyncResponse>, lambda_runtime::Error> {
    tracing::debug!("{event:?}");
    tracing::info!({payload = %serde_json::json!(event.payload)});
    Ok(appsync_batch_handler(serde_json::from_value(event.payload)?).await)
}

Tell me what you think.

[JeremieRodon]

Also note that with the way I did things, it is now possible to just disable the 2 features env_logger and tracing, use whatever dependencies suits the user and use the log_init option to inset any initialization code.

The only downside I see then is that the macro-generated boilerplate code will no longer log anything (because the appsync-lambda crate will not re-export anything either). Maybe I will end-up keeping a dependency to log and have 2-3 log::debug!() no matter what... as the log crate is really common I suppose that would not really be an issue.

[JeremieRodon]

Following my own thoughts of yesterday, I introduced a log feature that controls the use and re-export of the log crate.

When using either the env_logger or tracing features, the log feature is also enabled, so it does not change the usage I highlighted yesterday. But the log feature can also be enabled standalone, in that case users can bring in any log/tracing crate they wish and initialize them with the log_init option of the macro.

When the log feature is enabled, the macro generates code to log the event in function_handler and appsync_handler. That may not be desirable if the event contains sensitive information, so I added a new optional parameter to the macro: event_logging, a boolean defaulting to true. If set to false, then the macro will not generate code to dump the event anywhere. I believe it is a good compromise.

I will leave the branch as it is until you have the opportunity to give me a feedback :)

[JeremieRodon]

PR #11

[dfeyer]

Hi thanks a lot, I will review and test the PR this week. Just back from holidays.

[JeremieRodon]

@dfeyer As discussed in the PR, I merged the feature and publish a new version of the crate.
You can now rely on v0.9.0 and remove the patching code mapping the feature branch.