Potential bug in the runtime

[jakejscott]

I just noticed a lambda that kept logging errors. I had to delete the lambda to stop it from running.

I'm using the new HTTP API Gateway to invoke the lambda.

This is what was being logged:

2020-08-05T21:34:40.255+12:00 START RequestId: 7d8b64ee-f309-529e-9710-334a8c61539a Version: $LATEST
2020-08-05T21:34:40.259+12:00 Error: Error("data did not match any variant of untagged enum LambdaRequest", line: 0, column: 0)
2020-08-05T21:34:40.296+12:00 END RequestId: 7d8b64ee-f309-529e-9710-334a8c61539a
2020-08-05T21:34:40.296+12:00 REPORT RequestId: 7d8b64ee-f309-529e-9710-334a8c61539a Duration: 37.58 ms Billed Duration: 100 ms Memory Size: 1024 MB Max Memory Used: 7 MB

Is this a serde error deseralizing into the LambdaRequest type here: https://github.com/awslabs/aws-lambda-rust-runtime/blob/master/lambda-http/src/request.rs#L25

[jakejscott]

I'll do some more investigation when I get a chance and see if I can reproduce it with a minimal example

[jakejscott]

This is the trace output

2020-08-07T11:10:04.876+12:00 START RequestId: c55dcc86-4e8f-5ab3-bd2f-9b20de852b16 Version: $LATEST
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"Conn::read_head "}
2020-08-07T11:10:04.879+12:00 {"level":"DEBUG","ts":"2020-08-06T23:10:04.879Z","msg":"read 1445 bytes "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"Response.parse([Header; 100], [u8; 1445]) "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"Response.parse Complete(451) "}
2020-08-07T11:10:04.879+12:00 {"level":"DEBUG","ts":"2020-08-06T23:10:04.879Z","msg":"parsed 7 headers "}
2020-08-07T11:10:04.879+12:00 {"level":"DEBUG","ts":"2020-08-06T23:10:04.879Z","msg":"incoming body is content-length (994 bytes) "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"decode; state=Length(994) "}
2020-08-07T11:10:04.879+12:00 {"level":"DEBUG","ts":"2020-08-06T23:10:04.879Z","msg":"incoming body completed "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"put; add idle connection for (\"http\", 127.0.0.1:9001) "}
2020-08-07T11:10:04.879+12:00 {"level":"DEBUG","ts":"2020-08-06T23:10:04.879Z","msg":"pooling idle connection for (\"http\", 127.0.0.1:9001) "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"maybe_notify; read_from_io blocked "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"signal: Want"}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"signal: Want"}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"signal: Want"}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"client tx closed "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"State::close_read() "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"State::close_write() "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"shut down IO complete "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"deregistering handle with poller"}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"signal: Closed"}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"pool closed, canceling idle interval "}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"deregistering handle with poller"}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"signal: Closed"}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"deregistering handle with poller"}
2020-08-07T11:10:04.879+12:00 {"level":"TRACE","ts":"2020-08-06T23:10:04.879Z","msg":"signal: Closed"}
2020-08-07T11:10:04.880+12:00 Error: Error("data did not match any variant of untagged enum LambdaRequest", line: 0, column: 0)
2020-08-07T11:10:04.926+12:00 END RequestId: c55dcc86-4e8f-5ab3-bd2f-9b20de852b16
2020-08-07T11:10:04.926+12:00 REPORT RequestId: c55dcc86-4e8f-5ab3-bd2f-9b20de852b16	Duration: 44.92 ms	Billed Duration: 100 ms	Memory Size: 1024 MB	Max Memory Used: 45 MB

[softprops]

Can you share your trigger configuration?

[softprops]

Separately could you capture you're trigger's event payload and past it here?

You can do that by downgrading to an untyped serde_json::Value and using the default handler_fn the log the event with serde_json::to_string(...)

We've got a unit test harness to make these types of issues easy to reproduce with sample payloads.

https://github.com/awslabs/aws-lambda-rust-runtime/tree/master/lambda-http/tests/data

[jakejscott]

I've manage to fix the issue I was having. I had changed my code to use the anyhow crate for error's.

When I get a chance tonight I'll build a simple repository (if I can reproduce it). I'm probably just doing something really wrong.

[softprops]

No worries. The more test cases we have the better

[jakejscott]

@softprops I tried to reproduce it, but not having any luck.

I did run into something else wondering if you could help me?

I have the following function, which get's 403 back from github. I don't see any error logs in cloudwatch. I get back a 500 Internal Server Error from api gateway though.

This is the function

// use anyhow::{Context, Result};
use kv_log_macro as log;
use lambda_http::{
    handler,
    lambda::{self},
    IntoResponse, Request, Response,
};
use serde::{Deserialize, Serialize};
use serde_json::json;

pub type LambdaError = Box<dyn std::error::Error + Send + Sync + 'static>;

#[derive(Deserialize, Serialize, Debug)]
struct User {
    login: String,
    id: u32,
}

async fn get_users() -> Result<Vec<User>, LambdaError> {
    let url = format!(
        "https://api.github.com/repos/{owner}/{repo}/stargazers",
        owner = "rust-lang-nursery",
        repo = "rust-cookbook"
    );

    log::info!("Sending request", { url: url });

    let response: reqwest::Response = reqwest::get(&url).await?; //.expect("Error sending request");
    let body = response.text().await?; //.expect("Error reading body");
    let users: Vec<User> = serde_json::from_str(&body)?; //.expect("Error deserializing users");

    log::info!("{:?}", users);

    Ok(users)
}

async fn func(request: Request, _: lambda::Context) -> Result<impl IntoResponse, LambdaError> {
    log::info!("Request: {:?}", request);
    let users = get_users().await?; //.expect("Error getting users");

    let json = json!(users).to_string();
    let response = Response::builder().status(200).body(json)?;
    //.expect("Error building response");

    log::info!("Finished");
    return Ok(response);
}

#[tokio::main]
async fn main() -> Result<(), LambdaError> {
    json_env_logger::init();
    json_env_logger::panic_hook();
    lambda::run(handler(func)).await?;
    Ok(())
}

And what I get in the logs is this:

2020-08-07T20:58:21.552+12:00 | START RequestId: 6b17a474-e829-4f3f-82be-517b738e3102 Version: $LATEST
-- | --
  | 2020-08-07T20:58:21.553+12:00 | {"level":"INFO","ts":"2020-08-07T08:58:21.553Z","msg":"Request: Request { method: GET, uri: https://4ws74n3rbb.execute-api.ap-southeast-2.amazonaws.com/lambda-bug, version: HTTP/1.1, headers: {\"accept\": \"*/*\", \"accept-encoding\": \"gzip, deflate, br\", \"cache-control\": \"no-cache\", \"content-length\": \"0\", \"host\": \"4ws74n3rbb.execute-api.ap-southeast-2.amazonaws.com\", \"postman-token\": \"1fc38ceb-4910-4482-8a81-785cff8c3eaf\", \"user-agent\": \"PostmanRuntime/7.26.2\", \"x-amzn-trace-id\": \"Root=1-5f2d17ad-81f5f306fe3571b30906a896\", \"x-forwarded-for\": \"122.58.114.67\", \"x-forwarded-port\": \"443\", \"x-forwarded-proto\": \"https\"}, body: Empty }"}
  | 2020-08-07T20:58:21.553+12:00 | {"level":"INFO","ts":"2020-08-07T08:58:21.553Z","msg":"Sending request","url":https://api.github.com/repos/rust-lang-nursery/rust-cookbook/stargazers}
  | 2020-08-07T20:58:21.596+12:00 | END RequestId: 6b17a474-e829-4f3f-82be-517b738e3102
  | 2020-08-07T20:58:21.596+12:00 | REPORT RequestId: 6b17a474-e829-4f3f-82be-517b738e3102 Duration: 43.63 ms Billed Duration: 100 ms Memory Size: 1024 MB Max Memory Used: 39 MB Init Duration: 53.71 ms

I was hoping that the error would bubble up to the runtime and the panic would get logged.

[rimutaka]

@jakejscott, we have an unfinished PR #244 where the handler errors are logged by the runtime, but it does not compile with the ApiGateway examples. A bit of a catch 22 for you. That PR is on a different branch.

You can make a few simple changes to your master branch to log the error. See https://github.com/rimutaka/aws-lambda-rust-runtime/blob/master/lambda/src/lib.rs#L218. Remember to init the logger in main as in https://github.com/rimutaka/aws-lambda-rust-runtime/tree/master/lambda/examples.

[jakejscott]

I found the issue!!! It was a copy-paste bug in my CDK code. I had the following code hooking up the SQS event source to wrong lambda.

Wrong:

scheduleEmail.addEventSource(new SqsEventSource(queue, {
    batchSize: 1
}));

Right:

sendEmailFunction.addEventSource(new SqsEventSource(queue, {
    batchSize: 1
}));

Which meant after I published an event to the schedule function, it would publish the message to SQS, and then immediately be reinvoked and error.

Sorry for this!
Jake

[softprops]

Good to hear.

Thanks for reaching out.