Invalid window size

[weiznich]

I've seeing calls to 'WindowSize::try_decrease_to_positive` with a current window size of 0 and a non zero delta using big streams (multiple megabyte of data).

[stepancheg]

If you know how to reproduce a problem, that would be perfect.

Please attach backtrace at least, please?

(Backtrace can be obtained by executing program with RUST_BACKTRACE=1 env var set.)

[weiznich]

This does not produce any panic, so there is no Backtrace. Instead this returns an error of the type FlowControlError (thrown here). Adding a panic inside of WindowSize::try_decrease_to_positive for the zero case results in the following backtrace:

stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at /checkout/src/libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:60
             at /checkout/src/libstd/panicking.rs:355
   3: std::panicking::default_hook
             at /checkout/src/libstd/panicking.rs:371
   4: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:549
   5: std::panicking::begin_panic
             at /checkout/src/libstd/panicking.rs:511
   6: httpbis::solicit::WindowSize::try_decrease_to_positive
             at /home/user/rust/rust-http2/src/solicit/mod.rs:131
   7: <httpbis::common::conn::ConnData<T>>::process_data_frame
             at /home/user/rust/rust-http2/src/common/conn.rs:547
   8: <httpbis::common::conn::ConnData<T>>::process_stream_frame
             at /home/user/rust/rust-http2/src/common/conn.rs:625
   9: <httpbis::common::conn::ConnData<T>>::process_http_frame
             at /home/user/rust/rust-http2/src/common/conn.rs:649
  10: <httpbis::common::conn::ReadLoopData<I, T>>::process_http_frame::{{closure}}
             at /home/user/rust/rust-http2/src/common/conn.rs:818
  11: <httpbis::rc_mut::RcMut<A>>::with
             at /home/user/rust/rust-http2/src/rc_mut.rs:27
  12: <httpbis::common::conn::ReadLoopData<I, T>>::process_http_frame
             at /home/user/rust/rust-http2/src/common/conn.rs:817
  13: <httpbis::common::conn::ReadLoopData<I, T>>::read_process_frame::{{closure}}
             at /home/user/rust/rust-http2/src/common/conn.rs:798

This happens on client side while using server side streaming. Unfortunately I do not have any minimal example how to reproduce this. Any ideas how to further dig into this?

[stepancheg]

What implementation do you use on the server?

Does it happen all the time, or occasionally?

[weiznich]

Both client and server use rust-grpc.

It happens in ~90% of an specific request.

[stepancheg]

Can you provide log until the error? It may help to understand what's going on. If possible, on both client and server.

Log can be obtained with RUST_LOG=debug (or RUST_LOG=httpbis=debug).

[weiznich]

Hmm, thats strange. If I turn on logging on client side the bug is not triggered. So this seems to be some timing issue somewhere?

[weiznich]

I've added some warn statements to only enable some part of the logging (increasing/decreasing window size) The last "few" lines of the log are as following:

WARN    | 2017-7-5 23:17:53:8924 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-5 23:17:53:8924 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |    Next value -> 65535
WARN    | 2017-7-5 23:17:53:8936 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 65535 9245
WARN    | 2017-7-5 23:17:53:8937 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 56290
WARN    | 2017-7-5 23:17:53:8937 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 56290
WARN    | 2017-7-5 23:17:53:8937 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:8938 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:8938 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 65535 9245
WARN    | 2017-7-5 23:17:53:8938 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 56290
WARN    | 2017-7-5 23:17:53:8957 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 56290 16384
WARN    | 2017-7-5 23:17:53:8958 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 39906
WARN    | 2017-7-5 23:17:53:8958 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 39906
WARN    | 2017-7-5 23:17:53:8959 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:8959 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:8959 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 56290 16384
WARN    | 2017-7-5 23:17:53:8960 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 39906
WARN    | 2017-7-5 23:17:53:8975 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 39906 16384
WARN    | 2017-7-5 23:17:53:8976 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 23522
WARN    | 2017-7-5 23:17:53:8976 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 23522
WARN    | 2017-7-5 23:17:53:8976 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:8976 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 23522 65535
WARN    | 2017-7-5 23:17:53:8976 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |    Next value -> 89057
WARN    | 2017-7-5 23:17:53:8976 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:8977 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 39906 16384
WARN    | 2017-7-5 23:17:53:8977 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 23522
WARN    | 2017-7-5 23:17:53:8990 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 89057 16384
WARN    | 2017-7-5 23:17:53:8990 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 72673
WARN    | 2017-7-5 23:17:53:8991 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 72673
WARN    | 2017-7-5 23:17:53:8991 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:8991 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:8991 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 23522 16384
WARN    | 2017-7-5 23:17:53:8991 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 7138
WARN    | 2017-7-5 23:17:53:8998 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 72673 7138
WARN    | 2017-7-5 23:17:53:8998 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 65535
WARN    | 2017-7-5 23:17:53:8998 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 65535
WARN    | 2017-7-5 23:17:53:8998 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:8999 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:8999 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 7138 7138
WARN    | 2017-7-5 23:17:53:8999 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 0
WARN    | 2017-7-5 23:17:53:9001 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-5 23:17:53:9001 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |    Next value -> 65535
WARN    | 2017-7-5 23:17:53:9011 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 65535 9245
WARN    | 2017-7-5 23:17:53:9011 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 56290
WARN    | 2017-7-5 23:17:53:9012 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 56290
WARN    | 2017-7-5 23:17:53:9012 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:9012 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:9013 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 65535 9245
WARN    | 2017-7-5 23:17:53:9013 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 56290
WARN    | 2017-7-5 23:17:53:9031 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 56290 16384
WARN    | 2017-7-5 23:17:53:9032 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 39906
WARN    | 2017-7-5 23:17:53:9032 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 39906
WARN    | 2017-7-5 23:17:53:9033 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:9033 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:9033 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 56290 16384
WARN    | 2017-7-5 23:17:53:9034 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 39906
WARN    | 2017-7-5 23:17:53:9050 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 39906 16384
WARN    | 2017-7-5 23:17:53:9050 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 23522
WARN    | 2017-7-5 23:17:53:9050 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 23522
WARN    | 2017-7-5 23:17:53:9051 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:9051 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 23522 65535
WARN    | 2017-7-5 23:17:53:9051 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |    Next value -> 89057
WARN    | 2017-7-5 23:17:53:9051 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:9052 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 39906 16384
WARN    | 2017-7-5 23:17:53:9052 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 23522
WARN    | 2017-7-5 23:17:53:9069 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 89057 16384
WARN    | 2017-7-5 23:17:53:9070 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 72673
WARN    | 2017-7-5 23:17:53:9070 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 72673
WARN    | 2017-7-5 23:17:53:9070 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:9070 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:9071 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 23522 16384
WARN    | 2017-7-5 23:17:53:9071 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 7138
WARN    | 2017-7-5 23:17:53:9080 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 72673 7138
WARN    | 2017-7-5 23:17:53:9081 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 65535
WARN    | 2017-7-5 23:17:53:9081 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 65535
WARN    | 2017-7-5 23:17:53:9082 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:9082 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:9082 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 7138 7138
WARN    | 2017-7-5 23:17:53:9082 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 0
WARN    | 2017-7-5 23:17:53:9095 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 65535 9245
WARN    | 2017-7-5 23:17:53:9096 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |  New value: 56290
WARN    | 2017-7-5 23:17:53:9096 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 56290
WARN    | 2017-7-5 23:17:53:9096 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-5 23:17:53:9096 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-5 23:17:53:9097 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 0 9245

[stepancheg]

If I understand this log properly, server sends data frame when it shouldn't.

BTW, if you by any chance can reproduce it inside httpbis like this: https://github.com/stepancheg/rust-http2/commit/973a013288708e77a29ce03dfdbdf53313e81405 it would be very helpful.

[stepancheg]

Could you please show the patch which generates the log you've attached? I don't understand it.

[weiznich]

See this gist.

[stepancheg]

I'll ask again, if it possible to include server log as well, please include. I don't understand even if it a server or client error. If log is very large, that's OK to me.

[stepancheg]

If log may contain something sensitive, you can send a log/link to stepan.koltsov@gmail.com.

[stepancheg]

I've read sources 50 times, and still don't understand, how it may happen.

Any more details? What does server do? Is server configured to use cpupool?

[stepancheg]

Implemented stress test, still cannot reproduce.

[stepancheg]

Is your httpbis version at least 0.2? (Default for grpc; in 0.2 there were major internal refactorings, and I'm trying to reproduce things in master).

[weiznich]

Is your httpbis version at least 0.2? (Default for grpc; in 0.2 there were major internal refactorings, and I'm trying to reproduce things in master).

This happens against rust-grpc master and httpbis master (I've set a manual override)

I'll ask again, if it possible to include server log as well, please include. I don't understand even if it a server or client error. If log is very large, that's OK to me.

It's the same with the server side logging. As soon as I turn RUST_LOG=httpbis=debug on the error does not occur :disappointed: Same logging as for the client above: (Server Side)

WARN    | 2017-7-6 9:24:18:4603 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-6 9:24:18:4604 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:4605 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 9558 65535
WARN    | 2017-7-6 9:24:18:4605 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 75093
WARN    | 2017-7-6 9:24:18:4606 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 75093 65535
WARN    | 2017-7-6 9:24:18:4607 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 9558
WARN    | 2017-7-6 9:24:18:4607 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 65535 65535
WARN    | 2017-7-6 9:24:18:4607 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 0
WARN    | 2017-7-6 9:24:18:4724 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-6 9:24:18:4725 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:4726 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 9558 9558
WARN    | 2017-7-6 9:24:18:4727 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 0
WARN    | 2017-7-6 9:24:18:4727 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 65535 9558
WARN    | 2017-7-6 9:24:18:4727 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 55977
WARN    | 2017-7-6 9:24:18:4739 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-6 9:24:18:4739 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:4740 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 65535 55977
WARN    | 2017-7-6 9:24:18:4740 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 9558
WARN    | 2017-7-6 9:24:18:4741 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 55977 55977
WARN    | 2017-7-6 9:24:18:4741 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 0
WARN    | 2017-7-6 9:24:18:4900 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-6 9:24:18:4900 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:4902 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 9558 9558
WARN    | 2017-7-6 9:24:18:4903 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 0
WARN    | 2017-7-6 9:24:18:4903 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 65535 9558
WARN    | 2017-7-6 9:24:18:4903 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 55977
WARN    | 2017-7-6 9:24:18:4912 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-6 9:24:18:4912 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:4914 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 65535 55977
WARN    | 2017-7-6 9:24:18:4914 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 9558
WARN    | 2017-7-6 9:24:18:4914 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 55977 55977
WARN    | 2017-7-6 9:24:18:4915 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 0
WARN    | 2017-7-6 9:24:18:5030 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-6 9:24:18:5030 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:5032 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 9558 9558
WARN    | 2017-7-6 9:24:18:5032 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 0
WARN    | 2017-7-6 9:24:18:5033 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 65535 9558
WARN    | 2017-7-6 9:24:18:5033 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 55977
WARN    | 2017-7-6 9:24:18:5037 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-6 9:24:18:5037 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:5038 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 65535 55977
WARN    | 2017-7-6 9:24:18:5038 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 9558
WARN    | 2017-7-6 9:24:18:5039 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 55977 55977
WARN    | 2017-7-6 9:24:18:5039 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 0
WARN    | 2017-7-6 9:24:18:5125 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 0 65535
WARN    | 2017-7-6 9:24:18:5125 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:5126 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 9558 9558
WARN    | 2017-7-6 9:24:18:5126 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 0
WARN    | 2017-7-6 9:24:18:5127 | /home/user/rust/rust-http2/src/solicit/mod.rs:121 | Try decrease: 65535 9558
WARN    | 2017-7-6 9:24:18:5127 | /home/user/rust/rust-http2/src/solicit/mod.rs:124 |   New value: 55977

(Client Side of the same request)

WARN    | 2017-7-6 9:24:18:5035 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 65535
WARN    | 2017-7-6 9:24:18:5054 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 65535 9558
WARN    | 2017-7-6 9:24:18:5055 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 55977
WARN    | 2017-7-6 9:24:18:5055 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 55977
WARN    | 2017-7-6 9:24:18:5055 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-6 9:24:18:5055 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-6 9:24:18:5056 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 65535 9558
WARN    | 2017-7-6 9:24:18:5056 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 55977
WARN    | 2017-7-6 9:24:18:5074 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 55977 16384
WARN    | 2017-7-6 9:24:18:5074 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 39593
WARN    | 2017-7-6 9:24:18:5075 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 39593
WARN    | 2017-7-6 9:24:18:5075 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-6 9:24:18:5075 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-6 9:24:18:5075 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 55977 16384
WARN    | 2017-7-6 9:24:18:5076 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 39593
WARN    | 2017-7-6 9:24:18:5093 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 39593 16384
WARN    | 2017-7-6 9:24:18:5093 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 23209
WARN    | 2017-7-6 9:24:18:5093 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 23209
WARN    | 2017-7-6 9:24:18:5093 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-6 9:24:18:5094 | /home/user/rust/rust-http2/src/solicit/mod.rs:75 | Increase: 23209 65535
WARN    | 2017-7-6 9:24:18:5094 | /home/user/rust/rust-http2/src/solicit/mod.rs:88 |     Next value -> 88744
WARN    | 2017-7-6 9:24:18:5094 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-6 9:24:18:5094 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 39593 16384
WARN    | 2017-7-6 9:24:18:5095 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 23209
WARN    | 2017-7-6 9:24:18:5111 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 88744 16384
WARN    | 2017-7-6 9:24:18:5112 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 72360
WARN    | 2017-7-6 9:24:18:5112 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 72360
WARN    | 2017-7-6 9:24:18:5112 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-6 9:24:18:5112 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-6 9:24:18:5113 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 23209 16384
WARN    | 2017-7-6 9:24:18:5113 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 6825
WARN    | 2017-7-6 9:24:18:5120 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 72360 6825
WARN    | 2017-7-6 9:24:18:5121 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 65535
WARN    | 2017-7-6 9:24:18:5121 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 65535
WARN    | 2017-7-6 9:24:18:5121 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-6 9:24:18:5121 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-6 9:24:18:5121 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 6825 6825
WARN    | 2017-7-6 9:24:18:5122 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 0
WARN    | 2017-7-6 9:24:18:5141 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 65535 9558
WARN    | 2017-7-6 9:24:18:5141 | /home/user/rust/rust-http2/src/solicit/mod.rs:136 |   New value: 55977
WARN    | 2017-7-6 9:24:18:5141 | /home/user/rust/rust-http2/src/common/conn.rs:523 | in_window_size: 55977
WARN    | 2017-7-6 9:24:18:5142 | /home/user/rust/rust-http2/src/common/conn.rs:524 | Default: 65535
WARN    | 2017-7-6 9:24:18:5142 | /home/user/rust/rust-http2/src/common/conn.rs:539 | Stream id: 9
WARN    | 2017-7-6 9:24:18:5142 | /home/user/rust/rust-http2/src/solicit/mod.rs:133 | Try decrease positive: 0 9558

A wild guess would be that the client mixes somehow different windows? Because the server tells that it decreases from 9558 by 9558 to 0 and the client tells that it decreases from 0 by 9558 which causes the error?

Any more details? What does server do? Is server configured to use cpupool?

Server is configured as following:

let api_impl = NetworkApiServer::new_service_def( NetworkApiAsyncImpl { api: api.clone() }l);
println!("Creating server");

let mut server = ServerBuilder::new_plain();
server.http.addr = Some(socket_addr);
server.add_service(api_impl);
let server = server
    .build()
    .expect("Could start server");

[stepancheg]

Would you mind patching your logging output to distinguish between stream/conn window updates/sizes?

I'd suggest adding (temporarily) two parameter to try_increase/try_decrease function (in or out and Option<StreamId>).

[stepancheg]

OK, I think I've found the problem.

[stepancheg]

Trying to reproduce it now.

[weiznich]

So the logging is not required anymore? (I'm fine to spend an afternoon or so on helping debugging/fixing this)

[stepancheg]

So the logging is not required anymore?

I hope not. Wait a bit.

[stepancheg]

OK, should be fixed now.

It is single line fix.

I'm positive problem was there, although I couldn't reliably reproduce it because of asynchronous nature of http client. Test simply asserts that variable is initialized as it is required by specification.

Thank you for helping me debug it.

[weiznich]

Those line fixed it :tada: