Panic at 'Could not retrieve next event'

[LeakyBucket]

I thought maybe it was something in my code but I get the same panic with the example here: https://docs.rs/crate/lambda_runtime/0.2.0

START RequestId: 967aad3f-eaaa-4946-bc51-dc717f81aa71 Version: $LATEST
thread 'main' panicked at 'Could not retrieve next event', /Users/redacted/.cargo/registry/src/git.colasdn.top-1ecc6299db9ec823/lambda_runtime_core-0.1.0/src/runtime.rs:266:17
stack backtrace:
   0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace
             at src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at src/libstd/sys_common/backtrace.rs:59
             at src/libstd/panicking.rs:211
   3: std::panicking::default_hook
             at src/libstd/panicking.rs:227
   4: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:491
   5: std::panicking::begin_panic
   6: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
   7: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
   8: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
   9: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
  10: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
  11: lambda_runtime_core::runtime::start_with_config
  12: bootstrap::main
  13: std::rt::lang_start::{{closure}}
  14: std::panicking::try::do_call
             at src/libstd/rt.rs:59
             at src/libstd/panicking.rs:310
  15: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:102
  16: std::rt::lang_start_internal
             at src/libstd/panicking.rs:289
             at src/libstd/panic.rs:398
             at src/libstd/rt.rs:58
  17: main
END RequestId: 967aad3f-eaaa-4946-bc51-dc717f81aa71
REPORT RequestId: 967aad3f-eaaa-4946-bc51-dc717f81aa71	Duration: 1050.16 ms	Billed Duration: 1100 ms 	Memory Size: 128 MB	Max Memory Used: 26 MB	
RequestId: 967aad3f-eaaa-4946-bc51-dc717f81aa71 Error: Runtime exited with error: exit status 101
Runtime.ExitError

[davidbarsky]

Where are you running this? Since lambda_runtime_core::runtime::start_with_config is showing up in the panic logs, I'm thinking that you may have tried to run an example outside of a Lambda-like environment. I'd suggest looking at lambci's docker-lambda as a local runtime image.

[LeakyBucket]

This output was copied from the test results UI element in Lambda, the CloudWatch Logs show the same error.

[LeakyBucket]

I am in GovCloud but otherwise it is running in Lambda.

[davidbarsky]

Oh dear—I have no idea. I'm not sure how air-gapped regions work with Lambda. Perhaps @sapessi would know?

[sapessi]

First dumb question, have you configured your function to use the "provided" runtime?

Any chance you could share the function code @LeakyBucket (just the pieces that start the runtime and the handler definition)?

[LeakyBucket]

@sapessi no dumb questions when you are asking me ;)

There is no option for "provided" in the runtime list, there is a "Use custom runtime in function code or layer" which I have selected but doesn't sound at all similar.

I can definitely share code if that helps but it sounds like ^ might be the issue and I just can't use Rust in GovCloud.

[sapessi]

@LeakyBucket that's the option - it's spelled out like that in the console but behind the scenes (for the API) the value is "provided". That's what you'd set it to with SAM.

Yes, would be good to take a quick look at the code. That error is thrown by hyper if we just cannot get an answer from the runtime API. It's probably worth including simple_logger as a dependency and setting the log level to Debug or even Trace (see example)

[LeakyBucket]

@sapessi here is the main function and the handler:

fn main() {
    simple_logger::init().unwrap();
    lambda!(my_handler);
}

fn my_handler(batch: CustomEvent, _ctx: Context) -> Result<CustomOutput, HandlerError> {
    for event in batch.records {
        let keys = event.dynamodb.keys;
        let dest = env::var("DESTINATION_TABLE").unwrap();
        let data = event.dynamodb.new_image.unwrap();
    
        match event.event_name {
            EventType::INSERT => do_insert(data, &dest),
            EventType::MODIFY => do_insert(data, &dest),
            EventType::REMOVE => do_remove(keys, &dest),
        }
    }

    Ok(CustomOutput{
        message: "Batch Processed".to_string(),
    })
}

If I get time today I can try playing around with the logging.

[sapessi]

Thanks @LeakyBucket - would be good to get trace log about. it's likely to contain the exact client issue.

[LeakyBucket]

@sapessi below is the trace output from a test run in Lambda

2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2019-02-24 01:38:39 TRACE [lambda_runtime_client::client] Polling for next event
2019-02-24 01:38:39 TRACE [hyper::client::pool] take? "http://127.0.0.1:9001": expiration = Some(90s)
2019-02-24 01:38:39 DEBUG [hyper::client::pool] reuse idle connection for "http://127.0.0.1:9001"
2019-02-24 01:38:39 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1db3ef0
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.038s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> wakeup; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(0)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=0
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit internal; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [hyper::proto::h1::role] Client::encode method=GET, body=None
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::io] flushed 74 bytes
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(0)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=0
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable | Writable Token(4194305)
2019-02-24 01:38:39 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1db3ef0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit external
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> wakeup; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(0)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=0
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit internal; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] Conn::read_head
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::io] read 1984 bytes
2019-02-24 01:38:39 TRACE [hyper::proto::h1::role] Response.parse([Header; 100], [u8; 1984])
2019-02-24 01:38:39 TRACE [hyper::proto::h1::role] Response.parse Complete(344)
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::io] parsed 6 headers
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::conn] incoming body is content-length (1640 bytes)
2019-02-24 01:38:39 TRACE [hyper::proto::h1::decode] decode; state=Length(1640)
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::conn] incoming body completed
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] maybe_notify; read_from_io blocked
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [want] signal: Want
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle, error: None }
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [want] signal: Want
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle, error: None }
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1db3ef0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit external
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 TRACE [hyper::client::pool] put; add idle connection for "http://127.0.0.1:9001"
2019-02-24 01:38:39 DEBUG [hyper::client::pool] pooling idle connection for "http://127.0.0.1:9001"
2019-02-24 01:38:39 ERROR [lambda_runtime_client::client] Response headers do not contain Lambda-Runtime-Trace-Id header
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> wakeup; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit internal; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [want] signal: Want
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle, error: None }
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1db3ef0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit external
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 ERROR [lambda_runtime_core::runtime] Unrecoverable error while fetching next event: Recoverable API error: Missing Lambda-Runtime-Trace-Id header
2019-02-24 01:38:39 ERROR [lambda_runtime_client::client] Calling fail_init Runtime API: Recoverable API error: Missing Lambda-Runtime-Trace-Id header
2019-02-24 01:38:39 TRACE [hyper::client::pool] take? "http://127.0.0.1:9001": expiration = Some(90s)
2019-02-24 01:38:39 DEBUG [hyper::client::pool] reuse idle connection for "http://127.0.0.1:9001"
2019-02-24 01:38:39 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1db3ef0
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(0)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=0
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit internal; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [hyper::proto::h1::role] Client::encode method=POST, body=Some(Known(136))
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::io] flushed 384 bytes
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(0)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=0
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=0
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> wakeup; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable | Writable Token(4194305)
2019-02-24 01:38:39 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1db3ef0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit external
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> wakeup; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit internal; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] Conn::read_head
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::io] read 242 bytes
2019-02-24 01:38:39 TRACE [hyper::proto::h1::role] Response.parse([Header; 100], [u8; 242])
2019-02-24 01:38:39 TRACE [hyper::proto::h1::role] Response.parse Complete(116)
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::io] parsed 3 headers
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::conn] incoming body is content-length (126 bytes)
2019-02-24 01:38:39 TRACE [hyper::proto::h1::decode] decode; state=Length(126)
2019-02-24 01:38:39 DEBUG [hyper::proto::h1::conn] incoming body completed
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] maybe_notify; read_from_io blocked
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [want] signal: Want
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle, error: None }
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [want] signal: Want
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle, error: None }
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1db3ef0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit external
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> wakeup; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit internal; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [want] signal: Want
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle, error: None }
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [hyper::client::pool] put; add idle connection for "http://127.0.0.1:9001"
2019-02-24 01:38:39 DEBUG [hyper::client::pool] pooling idle connection for "http://127.0.0.1:9001"
2019-02-24 01:38:39 INFO [lambda_runtime_client::client] Successfully sent error response to the runtime API: Response { status: 403, version: HTTP/1.1, headers: {"content-type": "application/json", "date": "Sun, 24 Feb 2019 01:38:39 GMT", "content-length": "126"}, body: Body }
2019-02-24 01:38:39 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1db3ef0
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit external
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> wakeup; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] -> submit internal; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:39 TRACE [want] signal: Want
2019-02-24 01:38:39 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle, error: None }
2019-02-24 01:38:39 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:39 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:39 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:39 TRACE [tokio_reactor] loop process - 0 events, 0.000s
thread 'main' panicked at 'Could not retrieve next event', /Users/lawrenceholcomb/.cargo/registry/src/git.colasdn.top-1ecc6299db9ec823/lambda_runtime_core-0.1.0/src/runtime.rs:266:17
stack backtrace:
0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace
at src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
1: std::sys_common::backtrace::_print
at src/libstd/sys_common/backtrace.rs:71
2: std::panicking::default_hook::{{closure}}
at src/libstd/sys_common/backtrace.rs:59
at src/libstd/panicking.rs:211
3: std::panicking::default_hook
at src/libstd/panicking.rs:227
4: std::panicking::rust_panic_with_hook
at src/libstd/panicking.rs:491
5: std::panicking::begin_panic
6: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
7: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
8: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
9: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
10: <lambda_runtime_core::runtime::Runtime<Function, EventError>>::get_next_event
11: lambda_runtime_core::runtime::start_with_config
12: bootstrap::main
13: std::rt::lang_start::{{closure}}
14: std::panicking::try::do_call
at src/libstd/rt.rs:59
at src/libstd/panicking.rs:310
15: __rust_maybe_catch_panic
at src/libpanic_unwind/lib.rs:102
16: std::rt::lang_start_internal
at src/libstd/panicking.rs:289
at src/libstd/panic.rs:398
at src/libstd/rt.rs:58
17: main
2019-02-24 01:38:40 TRACE [tokio_threadpool::pool] shutdown; state=pool::State { lifecycle: Running, num_futures: 2 }
2019-02-24 01:38:40 TRACE [tokio_threadpool::pool] -> transitioned to shutdown
2019-02-24 01:38:40 TRACE [tokio_threadpool::pool] -> shutting down workers
2019-02-24 01:38:40 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:40 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] -> wakeup; idx=1
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] shutting down thread; idx=1
2019-02-24 01:38:40 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:40 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] -> wakeup; idx=0
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] shutting down thread; idx=0
2019-02-24 01:38:40 TRACE [mio::poll] deregistering handle with poller
2019-02-24 01:38:40 DEBUG [tokio_reactor] dropping I/O source: 1
2019-02-24 01:38:40 TRACE [want] signal: Closed
END RequestId: 3de56d6e-8443-453b-9167-3cfa430bb859
REPORT RequestId: 3de56d6e-8443-453b-9167-3cfa430bb859	Init Duration: 9.43 ms	Duration: 914.65 ms	Billed Duration: 1000 ms Memory Size: 128 MB	Max Memory Used: 36 MB	
RequestId: 3de56d6e-8443-453b-9167-3cfa430bb859 Error: Runtime exited with error: exit status 101
Runtime.ExitError
2019-02-24 01:38:40 DEBUG [lambda_runtime_client::client] Starting new HttpRuntimeClient for 127.0.0.1:9001
2019-02-24 01:38:40 TRACE [mio::poll] registering with poller
2019-02-24 01:38:40 TRACE [mio::poll] registering with poller
2019-02-24 01:38:40 TRACE [tokio_threadpool::builder] build; num-workers=2
2019-02-24 01:38:40 TRACE [mio::poll] registering with poller
2019-02-24 01:38:40 DEBUG [lambda_runtime_core::runtime] Creating new runtime with 3 max retries for endpoint 127.0.0.1:9001
2019-02-24 01:38:40 DEBUG [lambda_runtime_core::runtime] Beginning main event loop
2019-02-24 01:38:40 TRACE [lambda_runtime_client::client] Polling for next event
2019-02-24 01:38:40 TRACE [hyper::client::pool] checkout waiting for idle connection: "http://127.0.0.1:9001"
2019-02-24 01:38:40 TRACE [hyper::client::connect::http] Http::connect; scheme=http, host=127.0.0.1, port=Some(9001)
2019-02-24 01:38:40 DEBUG [hyper::client::connect::http] connecting to 127.0.0.1:9001
2019-02-24 01:38:40 TRACE [mio::poll] registering with poller
2019-02-24 01:38:40 TRACE [mio::poll] registering with poller
2019-02-24 01:38:40 DEBUG [tokio_reactor::background] starting background reactor
2019-02-24 01:38:40 TRACE [tokio_reactor] event Writable Token(0)
2019-02-24 01:38:40 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:40 TRACE [hyper::client::conn] client handshake HTTP/1
2019-02-24 01:38:40 TRACE [tokio_threadpool::sender] execute; count=1
2019-02-24 01:38:40 TRACE [tokio_threadpool::pool] -> submit external
2019-02-24 01:38:40 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:40 TRACE [tokio_threadpool::pool] signal_work -- spawn; idx=1
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:40 TRACE [tokio_reactor] loop process - 0 events, 0.000s
2019-02-24 01:38:40 TRACE [tokio_threadpool::pool] -> submit internal; idx=1
2019-02-24 01:38:40 TRACE [tokio_threadpool::pool] signal_work -- notify; idx=1
2019-02-24 01:38:40 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:40 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:40 TRACE [want] signal: Want
2019-02-24 01:38:40 TRACE [want] signal found waiting giver, notifying
2019-02-24 01:38:40 TRACE [want] poll_want: taker wants!
2019-02-24 01:38:40 TRACE [tokio_threadpool::notifier] Notifier::notify; id=0x1babe30
2019-02-24 01:38:40 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy, error: None }
2019-02-24 01:38:40 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:40 TRACE [tokio_reactor] event Readable Token(4194303)
2019-02-24 01:38:40 TRACE [tokio_reactor] loop process - 1 events, 0.000s
2019-02-24 01:38:40 TRACE [tokio_threadpool::task] Task::run; state=Running
2019-02-24 01:38:40 TRACE [hyper::proto::h1::conn] read_keep_alive; is_mid_message=false
2019-02-24 01:38:40 TRACE [hyper::proto::h1::role] Client::encode method=GET, body=None
2019-02-24 01:38:40 DEBUG [hyper::proto::h1::io] flushed 74 bytes
2019-02-24 01:38:40 TRACE [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
2019-02-24 01:38:40 TRACE [tokio_threadpool::task] -> not ready
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] Worker::sleep; worker=WorkerId(1)
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] sleeping -- push to stack; idx=1
2019-02-24 01:38:40 TRACE [tokio_threadpool::worker] -> starting to sleep; idx=1
2019-02-24 01:38:40 TRACE [tokio_reactor] loop process - 0 events, 0.000s

[LeakyBucket]

This is maybe the important line?

2019-02-24 01:38:39 ERROR [lambda_runtime_core::runtime] Unrecoverable error while fetching next event: Recoverable API error: Missing Lambda-Runtime-Trace-Id header

[sapessi]

Yes, that is indeed the issue @LeakyBucket. X-Ray is not available in the GovCloud regions. I'll try to publish a patch release of the library today or tomorrow to make that header optional.

[sapessi]

I've sent #91 to address this. When it's merged, I will have to ask you to test pointing your Cargo.toml directly to the github repo @LeakyBucket. Unfortunately I do not have a GovCloud account to test with.