search

davisvansant / mesa

0 stars 0 forks source link

Response headers do not contain Lambda-Runtime-Invoked-Function-Arn header #1

Open davisvansant opened 3 years ago

davisvansant commented 3 years ago

After some digging, seemed to have finally figured out the cause of the panics and errors around not seeing any responses

Using the hello_world example, currently running the following:

cargo run --release --manifest-path ../../Cargo.toml --bin mesa build

After the build completes 

cargo run --release --manifest-path ../../Cargo.toml --bin mesa view

At this point we should have a running container with a port available locally at 9000

From the local machine, running the following

curl -XPOST "http://localhost:9000/2015-03-31/functions/function/invocations" -d '{"hi": "lambda!"}'

There is no response, and we can then gather the logs by running the docker logs command

What can be found in the logs is the following (with 3 retries):

2021-01-10 00:19:28,478 DEBUG [lambda_runtime_client::client] Starting new HttpRuntimeClient for 0.0.0.0:9001
2021-01-10 00:19:28,479 TRACE [mio::poll] registering with poller
2021-01-10 00:19:28,479 TRACE [mio::poll] registering with poller
2021-01-10 00:19:28,479 TRACE [tokio_threadpool::builder] build; num-workers=2
2021-01-10 00:19:28,479 TRACE [mio::poll] registering with poller
2021-01-10 00:19:28,480 DEBUG [lambda_runtime_core::runtime] Creating new runtime with 3 max retries for endpoint 0.0.0.0:9001
2021-01-10 00:19:28,480 DEBUG [lambda_runtime_core::runtime] Beginning main event loop
2021-01-10 00:19:28,480 TRACE [lambda_runtime_client::client] Polling for next event
2021-01-10 00:19:28,480 TRACE [hyper::client::pool] checkout waiting for idle connection: "http://0.0.0.0:9001"
2021-01-10 00:19:28,480 TRACE [hyper::client::connect::http] Http::connect; scheme=http, host=0.0.0.0, port=Some(9001)
2021-01-10 00:19:28,480 DEBUG [hyper::client::connect::http] connecting to 0.0.0.0:9001
2021-01-10 00:19:28,480 TRACE [mio::poll] registering with poller
2021-01-10 00:19:28,480 DEBUG [tokio_reactor] adding I/O source: 0
2021-01-10 00:19:28,480 DEBUG [tokio_reactor::background] starting background reactor
2021-01-10 00:19:28,480 TRACE [mio::poll] registering with poller
2021-01-10 00:19:28,481 DEBUG [tokio_reactor::registration] scheduling Write for: 0
2021-01-10 00:19:28,481 TRACE [tokio_reactor] event Writable Token(0)
2021-01-10 00:19:28,481 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2021-01-10 00:19:28,481 DEBUG [hyper::client::connect::http] connected to Some(127.0.0.1:9001)
2021-01-10 00:19:28,481 TRACE [hyper::client::conn] client handshake HTTP/1
2021-01-10 00:19:28,481 TRACE [hyper::client] handshake complete, spawning background dispatcher task
2021-01-10 00:19:28,481 TRACE [tokio_threadpool::sender] execute; count=1
2021-01-10 00:19:28,481 TRACE [tokio_threadpool::pool]     -> submit external
2021-01-10 00:19:28,481 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2021-01-10 00:19:28,481 TRACE [tokio_threadpool::pool] signal_work -- spawn; idx=1
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::worker]   sleeping -- push to stack; idx=1
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::worker]     -> starting to sleep; idx=1
2021-01-10 00:19:28,482 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::task] Task::run; state=Running
2021-01-10 00:19:28,482 DEBUG [tokio_reactor::registration] scheduling Read for: 0
2021-01-10 00:19:28,482 TRACE [want] signal: Want
2021-01-10 00:19:28,482 TRACE [want] signal found waiting giver, notifying
2021-01-10 00:19:28,482 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::task]     -> not ready
2021-01-10 00:19:28,482 TRACE [tokio_reactor] event Readable Token(4194303)
2021-01-10 00:19:28,482 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2021-01-10 00:19:28,482 TRACE [want] poll_want: taker wants!
2021-01-10 00:19:28,482 TRACE [hyper::client::pool] checkout dropped for "http://0.0.0.0:9001"
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x55d3bb52d6d0
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::pool]     -> submit external
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2021-01-10 00:19:28,482 TRACE [tokio_threadpool::pool] signal_work -- spawn; idx=0
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(0)
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::worker]   sleeping -- push to stack; idx=0
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::worker]     -> starting to sleep; idx=0
2021-01-10 00:19:28,483 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::task] Task::run; state=Running
2021-01-10 00:19:28,483 DEBUG [tokio_reactor::registration] scheduling Read for: 0
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2021-01-10 00:19:28,483 TRACE [hyper::proto::h1::role] Client::encode method=GET, body=None
2021-01-10 00:19:28,483 DEBUG [hyper::proto::h1::io] flushed 72 bytes
2021-01-10 00:19:28,483 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::task]     -> not ready
2021-01-10 00:19:28,483 TRACE [tokio_reactor] event Readable Token(4194303)
2021-01-10 00:19:28,483 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(0)
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::worker]   sleeping -- push to stack; idx=0
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::worker]     -> starting to sleep; idx=0
2021-01-10 00:19:28,483 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2021-01-10 00:19:28,483 TRACE [tokio_reactor] event Readable | Writable Token(0)
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x55d3bb52d6d0
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::pool]     -> submit external
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2021-01-10 00:19:28,483 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2021-01-10 00:19:28,483 TRACE [tokio_reactor] event Readable Token(4194303)
2021-01-10 00:19:28,484 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2021-01-10 00:19:28,484 TRACE [tokio_threadpool::worker]     -> wakeup; idx=0
2021-01-10 00:19:28,484 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(0)
2021-01-10 00:19:28,484 TRACE [tokio_threadpool::worker]   sleeping -- push to stack; idx=0
2021-01-10 00:19:28,484 TRACE [tokio_threadpool::worker]     -> starting to sleep; idx=0
2021-01-10 00:19:28,484 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2021-01-10 00:19:28,484 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2021-01-10 00:19:28,484 TRACE [tokio_threadpool::task] Task::run; state=Running
2021-01-10 00:19:28,484 TRACE [hyper::proto::h1::conn] Conn::read_head
2021-01-10 00:19:28,483 TRACE [tokio_threadpool::worker]   sleeping -- push to stack; idx=1
2021-01-10 00:19:28,484 TRACE [tokio_threadpool::worker]     -> starting to sleep; idx=1
2021-01-10 00:19:28,484 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2021-01-10 00:19:28,484 DEBUG [hyper::proto::h1::io] read 237 bytes
2021-01-10 00:19:28,484 TRACE [hyper::proto::h1::role] Response.parse([Header; 100], [u8; 237])
2021-01-10 00:19:28,484 TRACE [hyper::proto::h1::role] Response.parse Complete(220)
2021-01-10 00:19:28,484 DEBUG [hyper::proto::h1::io] parsed 5 headers
2021-01-10 00:19:28,484 DEBUG [hyper::proto::h1::conn] incoming body is content-length (17 bytes)
2021-01-10 00:19:28,484 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x55d3bb52d6d0
2021-01-10 00:19:28,485 TRACE [tokio_threadpool::sender] execute; count=2
2021-01-10 00:19:28,485 TRACE [tokio_threadpool::pool]     -> submit external
2021-01-10 00:19:28,485 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2021-01-10 00:19:28,485 ERROR [lambda_runtime_client::client] Response headers do not contain Lambda-Runtime-Invoked-Function-Arn header
2021-01-10 00:19:28,485 TRACE [lambda_runtime_client::client] Polling for next event
2021-01-10 00:19:28,485 TRACE [hyper::client::pool] checkout waiting for idle connection: "http://0.0.0.0:9001"
2021-01-10 00:19:28,485 TRACE [hyper::client::connect::http] Http::connect; scheme=http, host=0.0.0.0, port=Some(9001)
2021-01-10 00:19:28,485 DEBUG [hyper::client::connect::http] connecting to 0.0.0.0:9001

with an eventual panic 

thread 'main' panicked at 'Could not retrieve next event', /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/lambda_runtime_core-0.1.2/src/runtime.rs:266:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
2021-01-10 00:19:28,495 TRACE [tokio_threadpool::pool] shutdown; state=pool::State { lifecycle: Running, num_futures: 4 }
2021-01-10 00:19:28,495 TRACE [tokio_threadpool::pool]   -> transitioned to shutdown
2021-01-10 00:19:28,495 TRACE [tokio_threadpool::pool]   -> shutting down workers
2021-01-10 00:19:28,495 TRACE [tokio_reactor] loop process - 1 events, 0.001s
2021-01-10 00:19:28,495 TRACE [tokio_threadpool::worker]     -> wakeup; idx=0
2021-01-10 00:19:28,495 TRACE [tokio_threadpool::worker] shutting down thread; idx=0
2021-01-10 00:19:28,494 TRACE [hyper::proto::h1::decode] decode; state=Length(156)
2021-01-10 00:19:28,495 DEBUG [hyper::proto::h1::conn] incoming body completed
2021-01-10 00:19:28,495 DEBUG [tokio_reactor::registration] scheduling Read for: 1
2021-01-10 00:19:28,495 TRACE [hyper::proto::h1::conn] maybe_notify; read_from_io blocked
2021-01-10 00:19:28,495 DEBUG [tokio_reactor::registration] scheduling Read for: 1
2021-01-10 00:19:28,495 TRACE [want] signal: Want
2021-01-10 00:19:28,495 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
2021-01-10 00:19:28,495 DEBUG [tokio_reactor::registration] scheduling Read for: 1
2021-01-10 00:19:28,495 TRACE [want] signal: Want
2021-01-10 00:19:28,495 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
2021-01-10 00:19:28,495 TRACE [tokio_threadpool::task]     -> not ready
2021-01-10 00:19:28,495 TRACE [tokio_reactor] event Readable Token(4194303)
2021-01-10 00:19:28,495 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2021-01-10 00:19:28,495 TRACE [tokio_threadpool::worker] shutting down thread; idx=1
2021-01-10 00:19:28,496 TRACE [hyper::client::pool] put; add idle connection for "http://0.0.0.0:9001"
2021-01-10 00:19:28,496 DEBUG [hyper::client::pool] pooling idle connection for "http://0.0.0.0:9001"
2021-01-10 00:19:28,496 TRACE [mio::poll] deregistering handle with poller
2021-01-10 00:19:28,496 DEBUG [tokio_reactor] dropping I/O source: 0
2021-01-10 00:19:28,496 TRACE [want] signal: Closed
2021-01-10 00:19:28,496 TRACE [mio::poll] deregistering handle with poller
2021-01-10 00:19:28,496 DEBUG [tokio_reactor] dropping I/O source: 1
2021-01-10 00:19:28,496 TRACE [want] signal: Closed
END RequestId: 3b556aad-2251-486a-9f76-3604b0b172d9
REPORT RequestId: 3b556aad-2251-486a-9f76-3604b0b172d9  Init Duration: 0.80 ms  Duration: 22.93 ms  Billed Duration: 100 ms Memory Size: 3008 MB    Max Memory Used: 3008 MB    
time="2021-01-10T00:19:28.497" level=warning msg="First fatal error stored in appctx: Runtime.ExitError"
time="2021-01-10T00:19:28.497" level=warning msg="Process 15(bootstrap) exited: Runtime exited with error: exit status 101"
time="2021-01-10T00:19:28.497" level=warning msg="AwaitAgentsReady() = Runtime exited with error: exit status 101"

Key messages here

2021-01-10 00:19:28,484 DEBUG [hyper::proto::h1::io] parsed 5 headers
2021-01-10 00:19:28,485 ERROR [lambda_runtime_client::client] Response headers do not contain Lambda-Runtime-Invoked-Function-Arn header

If you exec into the container, and run the following

 curl localhost:9001/2018-06-01/runtime/invocation/next

the response is 

{"hi": "lambda!"}

Need to investigate deeper and figure out next steps for local tests to work as expected

davisvansant commented 3 years ago

For further clarity, it also appears to be failing using the `master' branch of