Open lacabra opened 5 years ago
Cool Bug! The problem is here: https://github.com/enigmampc/enigma-core/blob/develop/enigma-core/app/src/networking/messages.rs#L201
Will fix tomorrow or on sunday.
Nice edge case, we should search for any unwrap
and document why it will never fail for an outside reason.
The related core issue is https://github.com/enigmampc/enigma-core/issues/131. I suggest to add a test to the core for this fix (@elichai, @lacabra).
Ok, I was wrong about the source of the crash.
But, I can't seem to be able to recreate the crash.
when I pass a bad contract address I get back a system error: https://github.com/enigmampc/enigma-p2p/blob/develop/docs/IPC_MESSAGES.md#general-error-system-message
that looks like this:
{"id":"2887257684","msg":"DBErr { command: \"read\", kind: MissingKey }","type":"Error"}
@lacabra after debugging this, we noticed that the error was printing the trace as well (which had the panic in it). This happens since the error was a Failure error (an error class we use only in the DB code) and when printing the failure error as debug it adds the trace as opposed to display which print's the error only which is what we are supposed to have there. Thanks to @elichai for finding this. will add the change very soon.
@lacabra , I added a fix for this issue, please close this issue, if you see it solves the problem. Great catch!
While I see some change, this still doesn't fix the error, as core
and p2p
still don't handle the error properly. This is what I'm seeing now (the most relevant lines are probably the last two):
core_1 | 15:24:38 [INFO] LOG DERIVE: Err(DBErr { command: "read", kind: MissingKey }
core_1 |
core_1 | stack backtrace:
core_1 | 0: failure::backtrace::internal::InternalBacktrace::new::h7137c1aede0a56e5 (0x5598e6dcff4e)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.5/src/backtrace/internal.rs:44
core_1 | 1: failure::backtrace::Backtrace::new::hbd13385411f06bd0 (0x5598e6dcfa1d)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.5/src/backtrace/mod.rs:111
core_1 | 2: <failure::error::error_impl::ErrorImpl as core::convert::From<F>>::from::h55a29392cd5cd513 (0x5598e635cd5d)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.5/src/error/error_impl.rs:19
core_1 | 3: <failure::error::Error as core::convert::From<F>>::from::h3c8dacce639c967f (0x5598e635b9c0)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.5/src/error/mod.rs:36
core_1 | 4: <enigma_core_app::db::dal::DB as enigma_core_app::db::dal::CRUDInterface<failure::error::Error, &'a K, alloc::vec::Vec<u8>, &'a [u8]>>::read::{{closure}}::{{closure}}::h41f0d6d42a562dcd (0x5598e63d3eb1)
core_1 | at src/lib.rs:1
core_1 | 5: <enigma_core_app::db::primitives::DeltaKey as enigma_core_app::db::primitives::SplitKey>::as_split::h7e83883f5bc3ab39 (0x5598e6450ad9)
core_1 | at src/db/primitives.rs:76
core_1 | 6: <enigma_core_app::db::dal::DB as enigma_core_app::db::dal::CRUDInterface<failure::error::Error, &'a K, alloc::vec::Vec<u8>, &'a [u8]>>::read::{{closure}}::h16f75b89c6f4cd78 (0x5598e63d454f)
core_1 | at src/lib.rs:1
core_1 | 7: <enigma_core_app::db::dal::DB as enigma_core_app::db::dal::CRUDInterface<failure::error::Error, &'a K, alloc::vec::Vec<u8>, &'a [u8]>>::read::hde8e4d13aed6ac2a (0x5598e63d34f1)
core_1 | at src/db/dal.rs:180
core_1 | 8: <enigma_core_app::db::dal::DB as enigma_core_app::db::iterator::P2PCalls<alloc::vec::Vec<u8>>>::get_contract::{{closure}}::h32bb31376a4756cc (0x5598e63a1f29)
core_1 | at src/db/iterator.rs:330
core_1 | 9: <enigma_core_app::db::dal::DB as enigma_core_app::db::iterator::P2PCalls<alloc::vec::Vec<u8>>>::get_contract::h2d5b97a5b11f666d (0x5598e63ac299)
core_1 | at src/db/iterator.rs:330
core_1 | 10: enigma_core_app::networking::ipc_listener::handling::compute_task::{{closure}}::ha435556785c815af (0x5598e63e0788)
core_1 | at src/networking/ipc_listener.rs:336
core_1 | 11: enigma_core_app::networking::ipc_listener::handling::compute_task::h8399a935552a4750 (0x5598e63e7b5b)
core_1 | at src/networking/ipc_listener.rs:336
core_1 | 12: enigma_core_app::networking::ipc_listener::handle_message::ha7802af2e35b514b (0x5598e63a8f92)
core_1 | at src/networking/ipc_listener.rs:49
core_1 | 13: enigma_core_app::main::{{closure}}::hee8c0afd755e77bd (0x5598e633ecc4)
core_1 | at src/main.rs:35
core_1 | 14: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &'a mut F>::call_once::h2b57c1706f165b97 (0x5598e633eb8a)
core_1 | at libcore/ops/function.rs:286
core_1 | 15: <core::option::Option<T>>::map::h79ea38a1d2e28340 (0x5598e63332ac)
core_1 | at libcore/option.rs:424
core_1 | 16: <futures::stream::map::Map<S, F> as futures::stream::Stream>::poll::h29435f33684a26e7 (0x5598e63503aa)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/stream/map.rs:79
core_1 | 17: <futures::stream::forward::Forward<T, U> as futures::future::Future>::poll::h851da5c7a7b7524d (0x5598e634b803)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/stream/forward.rs:94
core_1 | 18: <futures::future::map::Map<A, F> as futures::future::Future>::poll::h53c41830ba76c59f (0x5598e633431d)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/future/map.rs:30
core_1 | 19: <futures::future::chain::Chain<A, B, C>>::poll::hb32fc7ee3789926c (0x5598e633c2e5)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/future/chain.rs:32
core_1 | 20: <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::hb437cbd5a5213806 (0x5598e633a309)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/future/and_then.rs:32
core_1 | 21: <futures::task_impl::Spawn<T>>::poll_future_notify::{{closure}}::hf3d63ad05b064965 (0x5598e633d8d9)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/mod.rs:329
core_1 | 22: <futures::task_impl::Spawn<T>>::enter::{{closure}}::h3c71a7bb592450c6 (0x5598e633da56)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/mod.rs:399
core_1 | 23: futures::task_impl::std::set::h05d1707d1ffbe5ed (0x5598e634f0bc)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/std/mod.rs:78
core_1 | 24: <futures::task_impl::Spawn<T>>::enter::h24b2f470651dcf7d (0x5598e633d9e2)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/mod.rs:399
core_1 | 25: <futures::task_impl::Spawn<T>>::poll_fn_notify::h46ce4c84d2679086 (0x5598e633d804)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/mod.rs:291
core_1 | 26: <futures::task_impl::Spawn<T>>::poll_future_notify::h16b6539c441676e0 (0x5598e633d8ad)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/mod.rs:329
core_1 | 27: futures::task_impl::std::<impl futures::task_impl::Spawn<F>>::wait_future::{{closure}}::h7350efc19c2ba6ad (0x5598e634f198)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/std/mod.rs:231
core_1 | 28: futures::task_impl::std::ThreadNotify::with_current::{{closure}}::h7ecc535dabce851b (0x5598e634efce)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/std/mod.rs:478
core_1 | 29: <std::thread::local::LocalKey<T>>::try_with::h4d1c17767ac12fa4 (0x5598e634c8d3)
core_1 | at libstd/thread/local.rs:294
core_1 | 30: <std::thread::local::LocalKey<T>>::with::h30942d2e580669c4 (0x5598e634c6d0)
core_1 | at libstd/thread/local.rs:248
core_1 | 31: futures::task_impl::std::ThreadNotify::with_current::hc3b6d07bea73ea93 (0x5598e634ef8d)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/std/mod.rs:478
core_1 | 32: futures::task_impl::std::<impl futures::task_impl::Spawn<F>>::wait_future::hb50697d94effbfc4 (0x5598e633da83)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/task_impl/std/mod.rs:228
core_1 | 33: futures::future::Future::wait::hdd5bcbdfdd1d518d (0x5598e633a501)
core_1 | at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.26/src/future/mod.rs:299
core_1 | 34: enigma_core_app::main::hd82a343b8e899cf5 (0x5598e633e504)
core_1 | at src/main.rs:34
core_1 | 35: std::rt::lang_start::{{closure}}::h3e330605da9dfb89 (0x5598e633be8f)
core_1 | at libstd/rt.rs:74
core_1 | 36: std::rt::lang_start_internal::{{closure}}::hdc2a896aeffb5179 (0x5598e71f0b12)
core_1 | at libstd/rt.rs:59
core_1 | std::panicking::try::do_call::h5a4eb2ce70a501f5
core_1 | at libstd/panicking.rs:310
core_1 | 37: __rust_maybe_catch_panic (0x5598e7211b19)
core_1 | at libpanic_unwind/lib.rs:102
core_1 | 38: std::panicking::try::h97436c380f30f437 (0x5598e71f2fd5)
core_1 | at libstd/panicking.rs:289
core_1 | std::panic::catch_unwind::h9c28ef6e0c478c5d
core_1 | at libstd/panic.rs:392
core_1 | std::rt::lang_start_internal::h6abd6befa9748e41
core_1 | at libstd/rt.rs:58
core_1 | 39: std::rt::lang_start::hdf970baf0f67e0d6 (0x5598e633be67)
core_1 | at libstd/rt.rs:74
core_1 | 40: main (0x5598e633e699)
core_1 | 41: __libc_start_main (0x7f06ab62eb96)
core_1 | 42: _start (0x5598e63323c9)
core_1 | 43: <unknown> (0x0))
core_1 | 15:24:38 [ERROR] Unwrapped p2p Message failed: Error while trying to read, Because: The Key doesn't exist
p2p_1 | [Mon May 06 2019 15:24:38 GMT+0000 (Coordinated Universal Time)] ERROR response from Core[object Object]
@elichai it seems that the logs output this backtrace. is there some way to fix this?
@lacabra it seems that the output you are getting now is actually as a result of the logger you defined when running the core docker. in start_core.bash
you defined to run the core logger on debug level (-vv), so notice that once you remove the verbosity/ run on release (make- without DEBUG=1) the message with the backtrace won't appear and you'll get only this line: core_1 | 15:24:38 [ERROR] Unwrapped p2p Message failed: Error while trying to read, Because: The Key doesn't exist
Thanks @avishaiW, that’s fine. My problem is that error message you mention does not get processed as a failed computation by p2p, and does not get submitted as a failed computation to the contract, and will remain forever as pending, whereas it has failed. So the user that submitted the task has no way to know that computation has failed.
Cc: @lenak25
@lacabra What happens here is what we call system error. It shouldn't happen in this case, but instead the failed task should be returned to the user. As we discussed, this will be fixed for the testnet. But luckily, this issue reveals us how system errors are treated in general. Actually we never defined what the right behavior should be. According to @lenak25, when system error occurs, nothing happens and the user can withdraw the fees after a timeout . We can discuss to add a task status for system errors in enigma contract, but I think that at this stage this is less important than other issues.
One note about the backtrack that can seem as a panic.
This is a result of the combination of these two:
RUST_BACKTRACE=1
as you do in the integration tests.Debug
trait.I think that the right thing to do is when we pass errors through sockets or between services we should use the Display trait to avoid accidentally adding backtrace even if we compile with RUST_BACKTRACE=1
(which helps debugging).
But I don't think this is a concern on logs and local prints because they aren't sent anywhere.
more info can be read here: https://docs.rs/failure/0.1.5/failure/struct.Backtrace.html
Describe the bug This is a Rainy Day Scenario in that when requesting a secret computation for an address that doesn't exist,
core
throws an exception withErr(DBErr { command: "read", kind: MissingKey }
but never returns an error, so the task remains in a pending state forever.To Reproduce Steps to reproduce the behavior:
Expected behavior The request should error out properly, so that the final state of that task is
FAILURE
.Backtrace