rust panic in remote::tests::wait_between_request_3_retry

[kwlzn]

on the heels of improved logging via #6060, I noted the following panic during test execution in travis today:

test remote::tests::successful_execution_after_four_getoperations ... ok
test remote::tests::wait_between_request_1_retry ... ok
test remote::tests::timeout_after_sufficiently_delayed_getoperations ... ok
thread 'remote::tests::wait_between_request_3_retry' panicked at 'called `Result::unwrap()` on an `Err` value: "Cancelled: \"Cancelled\""', libcore/result.rs:945:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
stack backtrace:
   0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace
             at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::print
             at libstd/sys_common/backtrace.rs:71
             at libstd/sys_common/backtrace.rs:59
   2: std::panicking::default_hook::{{closure}}
             at libstd/panicking.rs:211
   3: std::panicking::default_hook
             at libstd/panicking.rs:227
   4: std::panicking::rust_panic_with_hook
             at libstd/panicking.rs:463
   5: std::panicking::begin_panic_fmt
             at libstd/panicking.rs:350
   6: rust_begin_unwind
             at libstd/panicking.rs:328
   7: core::panicking::panic_fmt
             at libcore/panicking.rs:71
   8: core::result::unwrap_failed
             at /checkout/src/libcore/macros.rs:26
   9: <core::result::Result<T, E>>::unwrap
             at /checkout/src/libcore/result.rs:782
  10: process_execution::remote::tests::wait_between_request_3_retry
             at process_execution/src/remote.rs:1425
  11: process_execution::__test::TESTS::{{closure}}
             at process_execution/src/remote.rs:1403
  12: core::ops::function::FnOnce::call_once
             at /checkout/src/libcore/ops/function.rs:223
  13: <F as alloc::boxed::FnBox<A>>::call_box
             at libtest/lib.rs:1451
             at /checkout/src/libcore/ops/function.rs:223
             at /checkout/src/liballoc/boxed.rs:638
  14: __rust_maybe_catch_panic
             at libpanic_unwind/lib.rs:105
thread 'remote::tests::wait_between_request_3_retry' panicked at 'assertion failed: `(left == right)`
  left: `1`,
 right: `0`: Expected 1 more requests. Remaining expected responses:
(name: "gimme-foo" done: true response {type_url: "type.googleapis.com/build.bazel.remote.execution.v2.ExecuteResponse" value: "\n\005*\003foo"}, None)
Received requests:
("ExecuteRequest", action_digest {hash: "a0777a41a9341ca91def500e9723de783a1c6b212d9ce05b451dd6086c0bb421" size_bytes: 138}, Instant { tv_sec: 528, tv_nsec: 697905093 })
("GetOperationRequest", name: "gimme-foo", Instant { tv_sec: 529, tv_nsec: 198949745 })
("GetOperationRequest", name: "gimme-foo", Instant { tv_sec: 530, tv_nsec: 199953177 })
', testutil/mock/src/execution_server.rs:105:5
stack backtrace:
   0:     0x55d3af8635ae - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::he2ad84a733ff5a63
                               at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:     0x55d3af86c556 - std::sys_common::backtrace::print::hf6fb23a1794250a5
                               at libstd/sys_common/backtrace.rs:71
                               at libstd/sys_common/backtrace.rs:59
   2:     0x55d3af84f44b - std::panicking::default_hook::{{closure}}::ha69c5f3cb0459cff
                               at libstd/panicking.rs:211
   3:     0x55d3af84f123 - std::panicking::default_hook::hf08727ddbbbad4bb
                               at libstd/panicking.rs:227
   4:     0x55d3af84fa6e - std::panicking::rust_panic_with_hook::hd6baf0cfc62bef0f
                               at libstd/panicking.rs:463
   5:     0x55d3af84f60c - std::panicking::begin_panic_fmt::h067a7944e7e0f96e
                               at libstd/panicking.rs:350
   6:     0x55d3aef46a92 - <mock::execution_server::TestServer as core::ops::drop::Drop>::drop::h2113f323299764d7
                               at testutil/mock/src/execution_server.rs:105
   7:     0x55d3aed8ec30 - core::ptr::drop_in_place::hc515e2109c82fafb
                               at /checkout/src/libcore/ptr.rs:59
   8:     0x55d3aee0a157 - process_execution::remote::tests::wait_between_request_3_retry::h36e19785f6888b6a
                               at process_execution/src/remote.rs:1438
   9:     0x55d3aee36be9 - process_execution::__test::TESTS::{{closure}}::h3a36c589dcbe4962
                               at process_execution/src/remote.rs:1403
  10:     0x55d3aed82ead - core::ops::function::FnOnce::call_once::h92a2c7c1a47def5b
                               at /checkout/src/libcore/ops/function.rs:223
  11:     0x55d3aee85eee - <F as alloc::boxed::FnBox<A>>::call_box::h95acd7f5d5222eb8
                               at libtest/lib.rs:1451
                               at /checkout/src/libcore/ops/function.rs:223
                               at /checkout/src/liballoc/boxed.rs:638
  12:     0x55d3af8735d9 - __rust_maybe_catch_panic
                               at libpanic_unwind/lib.rs:105
  13:     0x55d3aee9a388 - std::sys_common::backtrace::__rust_begin_short_backtrace::h4351ab9fa3965f87
                               at /checkout/src/libstd/panicking.rs:289
                               at /checkout/src/libstd/panic.rs:374
                               at libtest/lib.rs:1406
                               at /checkout/src/libstd/sys_common/backtrace.rs:136
  14:     0x55d3aeeb1854 - std::panicking::try::do_call::hf99e9099bc1398a8
                               at /checkout/src/libstd/thread/mod.rs:409
                               at /checkout/src/libstd/panic.rs:305
                               at /checkout/src/libstd/panicking.rs:310
  15:     0x55d3af8735d9 - __rust_maybe_catch_panic
                               at libpanic_unwind/lib.rs:105
  16:     0x55d3aee9bdb6 - <F as alloc::boxed::FnBox<A>>::call_box::hfa3a2e2797accd88
                               at /checkout/src/libstd/panicking.rs:289
                               at /checkout/src/libstd/panic.rs:374
                               at /checkout/src/libstd/thread/mod.rs:408
                               at /checkout/src/liballoc/boxed.rs:638
  17:     0x55d3af86562a - std::sys_common::thread::start_thread::hd31f5c5fa3e47024
                               at /checkout/src/liballoc/boxed.rs:648
                               at libstd/sys_common/thread.rs:24
  18:     0x55d3af850085 - std::sys::unix::thread::Thread::new::thread_start::hb3e7825324ee0f62
                               at libstd/sys/unix/thread.rs:90
  19:     0x7f67a3ce6183 - start_thread
  20:     0x7f67a37fcffc - clone
  21:                0x0 - <unknown>
thread panicked while panicking. aborting.
error: 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)
Pants rust test failure

[kwlzn]

cc @illicitonion

[illicitonion]

Interesting... So the test is expecting to make four requests, and complete them within 5 seconds.
The server is seeing three requests at t=0, t=0.5, t=1.5, so shouldn't be timing out.
Then 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.

Some things we know for sure:

1. 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.
2. The client hasn't timed out - we'd see a message Exceeded time out... rather than Cancelled in that case.

We should probably be robust to to the server cancelling individual requests. Accordingly, we should change this code:

pants/src/rust/engine/process_execution/src/remote.rs

Lines 182 to 185 in 450de70

	operations_client
	.get()
	.get_operation(&operation_request)
	.map_err(rpcerror_to_string),

so that if it gets a Cancelled error, it translates that into a ExecutionError::NotFinished which will trigger the loop to benignly retry.

I 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.

[illicitonion]

We should also add a test which has the mock execution server not respond to a request, and verify that it is retried :)