Skip to content

Potential bug in the runtime #250

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
jakejscott opened this issue Aug 5, 2020 · 10 comments
Closed

Potential bug in the runtime #250

jakejscott opened this issue Aug 5, 2020 · 10 comments

Comments

@jakejscott
Copy link

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
Copy link
Author

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

@jakejscott
Copy link
Author

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
Copy link
Contributor

Can you share your trigger configuration?

@softprops
Copy link
Contributor

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
Copy link
Author

jakejscott commented Aug 7, 2020

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
Copy link
Contributor

No worries. The more test cases we have the better

@jakejscott
Copy link
Author

@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
Copy link
Contributor

rimutaka commented Aug 7, 2020

@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
Copy link
Author

jakejscott commented Aug 8, 2020

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
Copy link
Contributor

Good to hear.

Thanks for reaching out.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants