{"action":"created","issue":{"url":"https://api.github.com/repos/pantsbuild/pants/issues/6100","repository_url":"https://api.github.com/repos/pantsbuild/pants","labels_url":"https://api.github.com/repos/pantsbuild/pants/issues/6100/labels{/name}","comments_url":"https://api.github.com/repos/pantsbuild/pants/issues/6100/comments","events_url":"https://api.github.com/repos/pantsbuild/pants/issues/6100/events","html_url":"https://github.com/pantsbuild/pants/issues/6100","id":340445812,"node_id":"MDU6SXNzdWUzNDA0NDU4MTI=","number":6100,"title":"rust panic in `remote::tests::wait_between_request_3_retry`","user":{"login":"kwlzn","id":1883523,"node_id":"MDQ6VXNlcjE4ODM1MjM=","avatar_url":"https://avatars0.githubusercontent.com/u/1883523?v=4","gravatar_id":"","url":"https://api.github.com/users/kwlzn","html_url":"https://github.com/kwlzn","followers_url":"https://api.github.com/users/kwlzn/followers","following_url":"https://api.github.com/users/kwlzn/following{/other_user}","gists_url":"https://api.github.com/users/kwlzn/gists{/gist_id}","starred_url":"https://api.github.com/users/kwlzn/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kwlzn/subscriptions","organizations_url":"https://api.github.com/users/kwlzn/orgs","repos_url":"https://api.github.com/users/kwlzn/repos","events_url":"https://api.github.com/users/kwlzn/events{/privacy}","received_events_url":"https://api.github.com/users/kwlzn/received_events","type":"User","site_admin":false},"labels":[{"id":604059552,"node_id":"MDU6TGFiZWw2MDQwNTk1NTI=","url":"https://api.github.com/repos/pantsbuild/pants/labels/remoting","name":"remoting","color":"e99695","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2018-07-12T00:04:05Z","updated_at":"2018-07-12T10:35:37Z","closed_at":null,"author_association":"MEMBER","body":"on the heels of improved logging via #6060, I noted the following panic during test execution in travis today:\r\n\r\n```\r\ntest remote::tests::successful_execution_after_four_getoperations ... ok\r\ntest remote::tests::wait_between_request_1_retry ... ok\r\ntest remote::tests::timeout_after_sufficiently_delayed_getoperations ... ok\r\nthread 'remote::tests::wait_between_request_3_retry' panicked at 'called `Result::unwrap()` on an `Err` value: \"Cancelled: \\\"Cancelled\\\"\"', libcore/result.rs:945:5\r\nnote: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.\r\nstack backtrace:\r\n   0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace\r\n             at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49\r\n   1: std::sys_common::backtrace::print\r\n             at libstd/sys_common/backtrace.rs:71\r\n             at libstd/sys_common/backtrace.rs:59\r\n   2: std::panicking::default_hook::{{closure}}\r\n             at libstd/panicking.rs:211\r\n   3: std::panicking::default_hook\r\n             at libstd/panicking.rs:227\r\n   4: std::panicking::rust_panic_with_hook\r\n             at libstd/panicking.rs:463\r\n   5: std::panicking::begin_panic_fmt\r\n             at libstd/panicking.rs:350\r\n   6: rust_begin_unwind\r\n             at libstd/panicking.rs:328\r\n   7: core::panicking::panic_fmt\r\n             at libcore/panicking.rs:71\r\n   8: core::result::unwrap_failed\r\n             at /checkout/src/libcore/macros.rs:26\r\n   9: <core::result::Result<T, E>>::unwrap\r\n             at /checkout/src/libcore/result.rs:782\r\n  10: process_execution::remote::tests::wait_between_request_3_retry\r\n             at process_execution/src/remote.rs:1425\r\n  11: process_execution::__test::TESTS::{{closure}}\r\n             at process_execution/src/remote.rs:1403\r\n  12: core::ops::function::FnOnce::call_once\r\n             at /checkout/src/libcore/ops/function.rs:223\r\n  13: <F as alloc::boxed::FnBox<A>>::call_box\r\n             at libtest/lib.rs:1451\r\n             at /checkout/src/libcore/ops/function.rs:223\r\n             at /checkout/src/liballoc/boxed.rs:638\r\n  14: __rust_maybe_catch_panic\r\n             at libpanic_unwind/lib.rs:105\r\nthread 'remote::tests::wait_between_request_3_retry' panicked at 'assertion failed: `(left == right)`\r\n  left: `1`,\r\n right: `0`: Expected 1 more requests. Remaining expected responses:\r\n(name: \"gimme-foo\" done: true response {type_url: \"type.googleapis.com/build.bazel.remote.execution.v2.ExecuteResponse\" value: \"\\n\\005*\\003foo\"}, None)\r\nReceived requests:\r\n(\"ExecuteRequest\", action_digest {hash: \"a0777a41a9341ca91def500e9723de783a1c6b212d9ce05b451dd6086c0bb421\" size_bytes: 138}, Instant { tv_sec: 528, tv_nsec: 697905093 })\r\n(\"GetOperationRequest\", name: \"gimme-foo\", Instant { tv_sec: 529, tv_nsec: 198949745 })\r\n(\"GetOperationRequest\", name: \"gimme-foo\", Instant { tv_sec: 530, tv_nsec: 199953177 })\r\n', testutil/mock/src/execution_server.rs:105:5\r\nstack backtrace:\r\n   0:     0x55d3af8635ae - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::he2ad84a733ff5a63\r\n                               at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49\r\n   1:     0x55d3af86c556 - std::sys_common::backtrace::print::hf6fb23a1794250a5\r\n                               at libstd/sys_common/backtrace.rs:71\r\n                               at libstd/sys_common/backtrace.rs:59\r\n   2:     0x55d3af84f44b - std::panicking::default_hook::{{closure}}::ha69c5f3cb0459cff\r\n                               at libstd/panicking.rs:211\r\n   3:     0x55d3af84f123 - std::panicking::default_hook::hf08727ddbbbad4bb\r\n                               at libstd/panicking.rs:227\r\n   4:     0x55d3af84fa6e - std::panicking::rust_panic_with_hook::hd6baf0cfc62bef0f\r\n                               at libstd/panicking.rs:463\r\n   5:     0x55d3af84f60c - std::panicking::begin_panic_fmt::h067a7944e7e0f96e\r\n                               at libstd/panicking.rs:350\r\n   6:     0x55d3aef46a92 - <mock::execution_server::TestServer as core::ops::drop::Drop>::drop::h2113f323299764d7\r\n                               at testutil/mock/src/execution_server.rs:105\r\n   7:     0x55d3aed8ec30 - core::ptr::drop_in_place::hc515e2109c82fafb\r\n                               at /checkout/src/libcore/ptr.rs:59\r\n   8:     0x55d3aee0a157 - process_execution::remote::tests::wait_between_request_3_retry::h36e19785f6888b6a\r\n                               at process_execution/src/remote.rs:1438\r\n   9:     0x55d3aee36be9 - process_execution::__test::TESTS::{{closure}}::h3a36c589dcbe4962\r\n                               at process_execution/src/remote.rs:1403\r\n  10:     0x55d3aed82ead - core::ops::function::FnOnce::call_once::h92a2c7c1a47def5b\r\n                               at /checkout/src/libcore/ops/function.rs:223\r\n  11:     0x55d3aee85eee - <F as alloc::boxed::FnBox<A>>::call_box::h95acd7f5d5222eb8\r\n                               at libtest/lib.rs:1451\r\n                               at /checkout/src/libcore/ops/function.rs:223\r\n                               at /checkout/src/liballoc/boxed.rs:638\r\n  12:     0x55d3af8735d9 - __rust_maybe_catch_panic\r\n                               at libpanic_unwind/lib.rs:105\r\n  13:     0x55d3aee9a388 - std::sys_common::backtrace::__rust_begin_short_backtrace::h4351ab9fa3965f87\r\n                               at /checkout/src/libstd/panicking.rs:289\r\n                               at /checkout/src/libstd/panic.rs:374\r\n                               at libtest/lib.rs:1406\r\n                               at /checkout/src/libstd/sys_common/backtrace.rs:136\r\n  14:     0x55d3aeeb1854 - std::panicking::try::do_call::hf99e9099bc1398a8\r\n                               at /checkout/src/libstd/thread/mod.rs:409\r\n                               at /checkout/src/libstd/panic.rs:305\r\n                               at /checkout/src/libstd/panicking.rs:310\r\n  15:     0x55d3af8735d9 - __rust_maybe_catch_panic\r\n                               at libpanic_unwind/lib.rs:105\r\n  16:     0x55d3aee9bdb6 - <F as alloc::boxed::FnBox<A>>::call_box::hfa3a2e2797accd88\r\n                               at /checkout/src/libstd/panicking.rs:289\r\n                               at /checkout/src/libstd/panic.rs:374\r\n                               at /checkout/src/libstd/thread/mod.rs:408\r\n                               at /checkout/src/liballoc/boxed.rs:638\r\n  17:     0x55d3af86562a - std::sys_common::thread::start_thread::hd31f5c5fa3e47024\r\n                               at /checkout/src/liballoc/boxed.rs:648\r\n                               at libstd/sys_common/thread.rs:24\r\n  18:     0x55d3af850085 - std::sys::unix::thread::Thread::new::thread_start::hb3e7825324ee0f62\r\n                               at libstd/sys/unix/thread.rs:90\r\n  19:     0x7f67a3ce6183 - start_thread\r\n  20:     0x7f67a37fcffc - clone\r\n  21:                0x0 - <unknown>\r\nthread panicked while panicking. aborting.\r\nerror: process didn't exit successfully: `/home/travis/build/pantsbuild/pants/src/rust/engine/target/debug/deps/process_execution-1103f35cbf54936e  --nocapture` (signal: 4, SIGILL: illegal instruction)\r\nPants rust test failure\r\n```"},"comment":{"url":"https://api.github.com/repos/pantsbuild/pants/issues/comments/404468711","html_url":"https://github.com/pantsbuild/pants/issues/6100#issuecomment-404468711","issue_url":"https://api.github.com/repos/pantsbuild/pants/issues/6100","id":404468711,"node_id":"MDEyOklzc3VlQ29tbWVudDQwNDQ2ODcxMQ==","user":{"login":"illicitonion","id":1131704,"node_id":"MDQ6VXNlcjExMzE3MDQ=","avatar_url":"https://avatars0.githubusercontent.com/u/1131704?v=4","gravatar_id":"","url":"https://api.github.com/users/illicitonion","html_url":"https://github.com/illicitonion","followers_url":"https://api.github.com/users/illicitonion/followers","following_url":"https://api.github.com/users/illicitonion/following{/other_user}","gists_url":"https://api.github.com/users/illicitonion/gists{/gist_id}","starred_url":"https://api.github.com/users/illicitonion/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/illicitonion/subscriptions","organizations_url":"https://api.github.com/users/illicitonion/orgs","repos_url":"https://api.github.com/users/illicitonion/repos","events_url":"https://api.github.com/users/illicitonion/events{/privacy}","received_events_url":"https://api.github.com/users/illicitonion/received_events","type":"User","site_admin":false},"created_at":"2018-07-12T10:35:37Z","updated_at":"2018-07-12T10:35:37Z","author_association":"CONTRIBUTOR","body":"Interesting... So the test is expecting to make four requests, and complete them within 5 seconds.\r\nThe server is seeing three requests at t=0, t=0.5, t=1.5, so shouldn't be timing out.\r\nThen the client is seeing a cancelled response - this happens when the server drops its `UnarySink` before writing anything to it. This _shouldn't_ be happening according to the code, but may be a weird timing effect of our whole \"pretend a streaming RPC is unary RPC\" thing. Accordingly, the client is failing.. Then when the server is dropped, it's failing its assertion that it got all four requests it was meant to see.\r\n\r\nSome things we know for sure:\r\n1. The server hasn't been dropped. It gets dropped later, which is why we see the panicked while panicking. So it should still be serving.\r\n2. The client hasn't timed out - we'd see a message `Exceeded time out...` rather than `Cancelled` in that case.\r\n\r\nWe should probably be robust to to the server cancelling individual requests. Accordingly, we should change this code: https://github.com/pantsbuild/pants/blob/450de702414f87f563081ddefaefd8a554de07a3/src/rust/engine/process_execution/src/remote.rs#L182-L185 so that if it gets a `Cancelled` error, it translates that into a `ExecutionError::NotFinished` which will trigger the loop to benignly retry.\r\n\r\nI imagine this looking like a new `.or_else` call before the `.map_err` call in that block, which matches to see if the error is an RpcFailure with status Cancelled, and if so, returns an `Ok` of an `Operation` with a `name` set to `operation_request.take_name()`, and otherwise returns the error back."}}
{"actor":{"display_login":"illicitonion"}}