Closed stevej closed 7 years ago
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?
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.
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.
Fixed the issue in d3386b0e75bf955342bb14dd28af71cc1cb398e5.
(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.