Closing the socket from a streaming client early results in a panic

[stevej]

(I have a fix for this in a branch)

If you exit a client without sending an end-of-stream indicator on the stream, the server will panic. This is technically out of spec but grpc-rust should be resilient to it.

DEBUG:tokio_core::reactor: consuming notification queue
DEBUG:tokio_core::reactor: scheduling direction for: 31
DEBUG:tokio_core::reactor: consuming notification queue
DEBUG:tokio_core::reactor: scheduling direction for: 30
DEBUG:tokio_core::reactor: consuming notification queue
DEBUG:tokio_core::reactor: scheduling direction for: 3
DEBUG:grpc::http_common: received frame: Stream(WindowUpdate(WindowUpdateFrame { stream_id: 1, increment: 16402, flags: 0 }))
thread '<unnamed>' panicked at 'stream not found', ../src/libcore/option.rs:705
stack backtrace:
   1:        0x109911d88 - std::sys::backtrace::tracing::imp::write::h6f1d53a70916b90d
   2:        0x10991474f - std::panicking::default_hook::{{closure}}::h137e876f7d3b5850
   3:        0x1099136c5 - std::panicking::default_hook::h0ac3811ec7cee78c
   4:        0x109913cd6 - std::panicking::rust_panic_with_hook::hc303199e04562edf
   5:        0x109913b74 - std::panicking::begin_panic::h6ed03353807cf54d
   6:        0x109913a92 - std::panicking::begin_panic_fmt::hc321cece241bb2f5
   7:        0x1099139f7 - rust_begin_unwind
   8:        0x10993dfa0 - core::panicking::panic_fmt::h27224b181f9f037f
   9:        0x10993e00d - core::option::expect_failed::h8606bc228cd3f504
  10:        0x109503a83 - <core::option::Option<T>>::expect::hd1c224735b6d5b7e
  11:        0x1095b4251 - grpc::http_common::HttpReadLoopInner::process_stream_window_update_frame::h4a77850c9c5e9bad
  12:        0x1095b5032 - grpc::http_common::HttpReadLoopInner::process_stream_frame::h71cda37509159b2b
  13:        0x1095b5589 - grpc::http_common::HttpReadLoopInner::process_raw_frame::h3d9300ed22391085
  14:        0x1095ca559 - <grpc::http_common::HttpReadLoopData<I, N>>::process_raw_frame::{{closure}}::h9edcd3c2c8b4639f
  15:        0x1095c84ca - <grpc::futures_misc::task_data::TaskRcMut<A>>::with::{{closure}}::hdd8f2fce5f681796
  16:        0x1095c8389 - <futures::task_impl::task_rc::TaskRc<A>>::with::{{closure}}::h23e6222f832c3e39
  17:        0x10959820d - futures::task_impl::with::h1a77c05e9abdca7e
  18:        0x10956be18 - <futures::task_impl::task_rc::TaskRc<A>>::with::h92bcf6250cca322a
  19:        0x1095b667e - <grpc::futures_misc::task_data::TaskRcMut<A>>::with::ha244e3141b1cb783
  20:        0x1095b627e - <grpc::http_common::HttpReadLoopData<I, N>>::process_raw_frame::h0abde819d55bdc45
  21:        0x1095c2070 - <grpc::http_common::HttpReadLoopData<I, N>>::read_process_frame::{{closure}}::hbe5e6b2bc994a733
  22:        0x1095c1f09 - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::{{closure}}::{{closure}}::h523e5700c98cd748
  23:        0x10951cddc - <core::result::Result<T, E>>::map::h87edfc063f082977
  24:        0x1095c1d95 - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::{{closure}}::h337bf07b06bb4ebd
  25:        0x109575c47 - <futures::future::chain::Chain<A, B, C>>::poll::h0ac3825a08b979bd
  26:        0x1094ee2cb - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::h6e39038c1485d2c6
  27:        0x10956cab0 - <Box<F> as futures::future::Future>::poll::h566b91994cc8de79
  28:        0x1094f0179 - <futures::stream::fold::Fold<S, F, Fut, T> as futures::future::Future>::poll::hf356629c8aabac77
  29:        0x10959d942 - <futures::future::map::Map<A, F> as futures::future::Future>::poll::h3ab6139582a3a55f
  30:        0x10956ca70 - <Box<F> as futures::future::Future>::poll::h31d9da5fdf92f3a3
  31:        0x109560cec - <futures::future::join::MaybeDone<A>>::poll::h2737411e5c64adb5
  32:        0x1095a054c - <futures::future::join::Join<A, B> as futures::future::Future>::poll::h378db279c54d5c85
  33:        0x10959f7c2 - <futures::future::map::Map<A, F> as futures::future::Future>::poll::hea98821f2a71dbb9
  34:        0x109578c84 - <futures::future::chain::Chain<A, B, C>>::poll::h4afc42c83afc2f84
  35:        0x1094ee38b - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::hdb826d97350693a6
  36:        0x10957edc7 - <futures::future::chain::Chain<A, B, C>>::poll::hfc3e86a1153e5dc5
  37:        0x1095a907b - <futures::future::then::Then<A, B, F> as futures::future::Future>::poll::h446cf0aba072d6e8
  38:        0x10956ca70 - <Box<F> as futures::future::Future>::poll::h31d9da5fdf92f3a3
  39:        0x1095a50aa - <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll::hc64e08dbe707cd36
  40:        0x10978d981 - <Box<F> as futures::future::Future>::poll::hdcde478ef4e8da40
  41:        0x1097a47fc - <futures::task_impl::Spawn<F>>::poll_future::{{closure}}::h4593987aece2335f
  42:        0x1097a484e - <futures::task_impl::Spawn<T>>::enter::{{closure}}::h96233ed4af8f7a98
  43:        0x1097a4965 - futures::task_impl::set::{{closure}}::h06a53b1d516ec9fe
  44:        0x109780694 - <std::thread::local::LocalKey<T>>::with::hafd993f9e3933e97
  45:        0x1097935d7 - futures::task_impl::set::hd0fa5ec781774660
  46:        0x10977fd4c - <futures::task_impl::Spawn<T>>::enter::haa5fa2f5d202f777
  47:        0x10977fb92 - <futures::task_impl::Spawn<F>>::poll_future::h0ccf585be6916a7e
  48:        0x1097a4446 - tokio_core::reactor::Core::dispatch_task::{{closure}}::h80049e866b2a20c1
  49:        0x10977ce0e - <scoped_tls::ScopedKey<T>>::set::h4537c6755a99f191
  50:        0x10979f09f - tokio_core::reactor::Core::dispatch_task::he97843a353c5112d
  51:        0x10979e308 - tokio_core::reactor::Core::dispatch::h756d49fd8a309683
  52:        0x10979df1b - tokio_core::reactor::Core::poll::hb80b0fedd628e39d
  53:        0x1094f3437 - tokio_core::reactor::Core::run::h7f6313bcbc91d331
  54:        0x1095ae40b - grpc::server::run_server_event_loop::h76e03d25a0f0cd66
  55:        0x1095c8d68 - grpc::server::GrpcServer::new::{{closure}}::hcd41d52da0bae7d4
  56:        0x1095a2dbb - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::h5c9d794b2db5435f
  57:        0x10950ed16 - std::panicking::try::do_call::h39ac82e24b244e58
  58:        0x109914d0a - __rust_maybe_catch_panic
  59:        0x10950e9a0 - std::panicking::try::he0cef71b38587938
  60:        0x10950dc05 - std::panic::catch_unwind::h29077e42a5630281
  61:        0x1095c537d - std::thread::Builder::spawn::{{closure}}::hd0e2341b25be272b
  62:        0x10955f850 - <F as alloc::boxed::FnBox<A>>::call_box::h4a3944545481bfc9
  63:        0x109912f34 - std::sys::thread::Thread::new::thread_start::h759e10bc4abc7e72
  64:     0x7fffce7f7aba - _pthread_body
  65:     0x7fffce7f7a06 - _pthread_start

[stepancheg]

I managed to reproduce the issues.

rust-grpc repository contains various clients and servers implemented in rust and go.

I did this:

# start rust server
RUST_LOG=grpc=debug RUST_BACKTRACE=1 ./target/debug/long_tests_server
# execute client in go
./long-tests/with-go/long_tests_client/long_tests_client random_strings 10000

Server panics with error:

INFO:grpc::server: accepted connection from [::1]:55537
DEBUG:grpc::http_common: received frame: Conn(WindowUpdate(WindowUpdateFrame { stream_id: 0, increment: 983025, flags: 0 }))
DEBUG:grpc::http_common: received frame: Stream(Headers(HeadersFrame { header_fragment: [131, 134, 68, 146, 99, 57, 234, 155, 121, 80, 148, 49, 96, 234, 144, 244, 196, 132, 216, 106, 166, 71, 65, 134, 160, 228, 29, 19, 157, 9, 95, 139, 29, 117, 208, 98, 13, 38, 61, 76, 77, 101, 100, 122, 136, 154, 202, 200, 180, 199, 96, 43, 131, 64, 2, 116, 101, 134, 77, 131, 53, 5, 177, 31], stream_id: 1, stream_dep: None, padding_len: None, flags: 4 }))
DEBUG:grpc::http_server: new stream: 1
DEBUG:grpc::http_common: received frame: Stream(Data(DataFrame { data: [0, 0, 0, 0, 3, 8, 144, 78], flags: 0, stream_id: 1, padding_len: None }))
DEBUG:grpc::http_common: received frame: Stream(Data(DataFrame { data: [], flags: 1, stream_id: 1, padding_len: None }))
DEBUG:grpc::http_common: close remote: 1
DEBUG:grpc::http_common: received frame: Stream(WindowUpdate(WindowUpdateFrame { stream_id: 1, increment: 16384, flags: 0 }))
thread '<unnamed>' panicked at 'stream not found: 1', ../src/libcore/option.rs:705
stack backtrace:
   1:        0x106ca6a2a - std::sys::imp::backtrace::tracing::imp::write::he3d1bfbdbf113480
   2:        0x106ca99af - std::panicking::default_hook::{{closure}}::h575f1b40d2e88f07
   3:        0x106ca860f - std::panicking::default_hook::h3d5dccce8125d0cf
   4:        0x106ca8c46 - std::panicking::rust_panic_with_hook::h00b81bb3dcbd51f2
   5:        0x106ca8ae4 - std::panicking::begin_panic::ha6a0d553db9869ff
   6:        0x106ca8a02 - std::panicking::begin_panic_fmt::h24d113aee3ee4081
   7:        0x106ca8967 - rust_begin_unwind
   8:        0x106cd4500 - core::panicking::panic_fmt::he441b2ea2036b98a
   9:        0x106cd456d - core::option::expect_failed::h7136772e5b75d3f8
  10:        0x10681a383 - <core::option::Option<T>>::expect::h7475a53262497516
  11:        0x1068ca9db - grpc::http_common::HttpReadLoopInner::process_stream_window_update_frame::h84590c4c597a5344
  12:        0x1068cb925 - grpc::http_common::HttpReadLoopInner::process_stream_frame::h3b68b4044117a4bf
  13:        0x1068cbec0 - grpc::http_common::HttpReadLoopInner::process_raw_frame::h11ec3b0967b478c5
  14:        0x1068de9c9 - <grpc::http_common::HttpReadLoopData<I, N>>::process_raw_frame::{{closure}}::h3e3b2e0090472d5a
  15:        0x1068dcce2 - <grpc::futures_misc::task_data::TaskRcMut<A>>::with::{{closure}}::h2b1c5518b606176b
  16:        0x1068dcbb5 - <futures::task_impl::task_rc::TaskRc<A>>::with::{{closure}}::hc41b58f9250f6d9c
  17:        0x1068b0eae - futures::task_impl::with::hc9240904b9aaffd2
  18:        0x106885438 - <futures::task_impl::task_rc::TaskRc<A>>::with::hc8b3f5189684736b
  19:        0x1068cd10e - <grpc::futures_misc::task_data::TaskRcMut<A>>::with::h0df4d71756d5f048
  20:        0x1068ccd28 - <grpc::http_common::HttpReadLoopData<I, N>>::process_raw_frame::hb1723927e9503bea
  21:        0x1068d5070 - <grpc::http_common::HttpReadLoopData<I, N>>::read_process_frame::{{closure}}::h1a079b2cfee90f86
  22:        0x1068d4f19 - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::{{closure}}::{{closure}}::heb22795848e551f2
  23:        0x1068354ac - <core::result::Result<T, E>>::map::h5284fa15ba9b832d
  24:        0x1068d4da5 - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::{{closure}}::h97ce8fb6f34cfb7c
  25:        0x106891aa9 - <futures::future::chain::Chain<A, B, C>>::poll::h4c9140cc3574fb7b
  26:        0x106805e6b - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::h2882bfd199490ebb
  27:        0x106885f70 - <Box<F> as futures::future::Future>::poll::h1da1aaef4c5baa2e
  28:        0x106807e1b - <futures::stream::fold::Fold<S, F, Fut, T> as futures::future::Future>::poll::ha8d5708480dbb0e8
  29:        0x1068b6c3f - <futures::future::map::Map<A, F> as futures::future::Future>::poll::h8d5305e5f80fe6ff
  30:        0x106885ef0 - <Box<F> as futures::future::Future>::poll::h0e862fdaef0d9a48
  31:        0x106879caf - <futures::future::join::MaybeDone<A>>::poll::h0c5235d447821185
  32:        0x1068b8b1b - <futures::future::join::Join<A, B> as futures::future::Future>::poll::h0d8e32ca077b508e
  33:        0x1068b705f - <futures::future::map::Map<A, F> as futures::future::Future>::poll::h9f9eeb2db71cd507
  34:        0x10688eccb - <futures::future::chain::Chain<A, B, C>>::poll::h06f4074d25c2bbae
  35:        0x106805fab - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::hcaec1f30165addad
  36:        0x10689241e - <futures::future::chain::Chain<A, B, C>>::poll::h53726427cb165a3d
  37:        0x1068c159b - <futures::future::then::Then<A, B, F> as futures::future::Future>::poll::h5282bbb6acb6c97b
  38:        0x106885ef0 - <Box<F> as futures::future::Future>::poll::h0e862fdaef0d9a48
  39:        0x1068bd987 - <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll::hc7db638831690559
  40:        0x106907231 - <Box<F> as futures::future::Future>::poll::h8bb3ed854c1ea8a4
  41:        0x1069175bc - <futures::task_impl::Spawn<F>>::poll_future::{{closure}}::h5053ec0ec0bf40fd
  42:        0x10691760e - <futures::task_impl::Spawn<T>>::enter::{{closure}}::h608f69f619cd3e3c
  43:        0x106917725 - futures::task_impl::set::{{closure}}::h381abb739e197643
  44:        0x1068fc81b - <std::thread::local::LocalKey<T>>::with::h45d3a6c2d31f2e33
  45:        0x10690a0a7 - futures::task_impl::set::heff505c09279e75c
  46:        0x1068fc1e3 - <futures::task_impl::Spawn<T>>::enter::h9cc801ded2178292
  47:        0x1068fc032 - <futures::task_impl::Spawn<F>>::poll_future::hd742ab2f772a3bf6
  48:        0x106917226 - tokio_core::reactor::Core::dispatch_task::{{closure}}::h50bd3eb5e79d11ff
  49:        0x1068f94d5 - <scoped_tls::ScopedKey<T>>::set::h0bc6a4f55fc60c12
  50:        0x1069124b9 - tokio_core::reactor::Core::dispatch_task::h43d2203f204b7b3e
  51:        0x1069116f8 - tokio_core::reactor::Core::dispatch::hc0e60f8c69d85e60
  52:        0x10691130f - tokio_core::reactor::Core::poll::hf3964f2740624cf1
  53:        0x10680b127 - tokio_core::reactor::Core::run::h1fb8209651b50112
  54:        0x1068c6881 - grpc::server::run_server_event_loop::hf0cdfa194c91a3c1
  55:        0x1068dd1bb - grpc::server::GrpcServer::new::{{closure}}::h3a68ca42492356a7
  56:        0x1068bb43b - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::h97cfa1de4cb6b076
  57:        0x106827736 - std::panicking::try::do_call::h3f1302c358d2ac0d
  58:        0x106ca9f6a - __rust_maybe_catch_panic
  59:        0x1068273c0 - std::panicking::try::h23cbd8983be9cf65
  60:        0x106826635 - std::panic::catch_unwind::hbc49d97d3d4f11db
  61:        0x1068d9778 - std::thread::Builder::spawn::{{closure}}::hc8b89202ae662ec9
  62:        0x106878e90 - <F as alloc::boxed::FnBox<A>>::call_box::hd391601d58c191ed
  63:        0x106ca80f4 - std::sys::imp::thread::Thread::new::thread_start::h990fb082eb5abe34
  64:     0x7fff9750b99c - _pthread_body
  65:     0x7fff9750b919 - _pthread_start

So, according to these logs, go client sends WINDOW_UPDATE update after data frame with end-of-stream flag.

So, Go implementation violates HTTP/2 spec, right?

[stepancheg]

No, seems like it is correct:

   WINDOW_UPDATE can be sent by a peer that has sent a frame bearing the
   END_STREAM flag.  This means that a receiver could receive a
   WINDOW_UPDATE frame on a "half-closed (remote)" or "closed" stream.
   A receiver MUST NOT treat this as an error (see Section 5.1).

I don't understand why spec allows it.

[stepancheg]

Ah, I got it! WINDOW_UPDATE is sent because peer doesn't know yet if my part if finished sending the data to the stream, and must still provide window credits. It is perfectly reasonable.

[stepancheg]

Fixed the issue in d3386b0.