panics when benchmarking with wrk

[kardeiz]

I wanted to do a quick benchmark of this with the server example and wrk.

When running wrk (wrk --latency -t2 -c100 -d10s "http://localhost:7878"), the example immediately panics with:

thread '<unnamed>' panicked at 'Error handling connection.: HttpParse(Token)', /checkout/src/libcore/result.rs:860:4
note: Run with `RUST_BACKTRACE=1` for a backtrace.
thread 'main' panicked at 'Thread pool worker panicked', ...

I tried changing a few flags in wrk and running the example in both debug and release mode, but didn't want to spend much time digging in.

Not sure if wrk does anything weird to HTTP connections, but I've never seen this in any Hyper-based web servers.

This is with Rust 1.20, the master branch of this project, and wrk 4.0.2 (on Linux).

[steveklabnik]

Interesting, is there a way to print out the full text of the request?

also, if you could re-run and get a backtrace that'd be great

[kardeiz]

Sorry, I don't know wrk well enough to know if that is possible/how to do that. Here is the full backtrace:

thread '<unnamed>' panicked at 'Error handling connection.: HttpParse(Token)', /checkout/src/libcore/result.rs:860:4
stack backtrace:
   0:     0x7f13558b8033 - std::sys::imp::backtrace::tracing::imp::unwind_backtrace::hcdf51e4c9dc54357
                               at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:     0x7f13558b42f4 - std::sys_common::backtrace::_print::h9da91fd31a37d0f1
                               at /checkout/src/libstd/sys_common/backtrace.rs:71
   2:     0x7f13558ba373 - std::panicking::default_hook::{{closure}}::h46820a72bf0cb624
                               at /checkout/src/libstd/sys_common/backtrace.rs:60
                               at /checkout/src/libstd/panicking.rs:380
   3:     0x7f13558ba0e2 - std::panicking::default_hook::h4c1ef1cc83189c8e
                               at /checkout/src/libstd/panicking.rs:396
   4:     0x7f13558ba837 - std::panicking::rust_panic_with_hook::h99016f44bdcb8544
                               at /checkout/src/libstd/panicking.rs:611
   5:     0x7f13558ba704 - std::panicking::begin_panic_new::hae931f4b9fe56a90
                               at /checkout/src/libstd/panicking.rs:553
   6:     0x7f13558ba609 - std::panicking::begin_panic_fmt::h3b8db4524c33692e
                               at /checkout/src/libstd/panicking.rs:521
   7:     0x7f13558ba59a - rust_begin_unwind
                               at /checkout/src/libstd/panicking.rs:497
   8:     0x7f13558e41d0 - core::panicking::panic_fmt::h955f7c5ec61a82d4
                               at /checkout/src/libcore/panicking.rs:92
   9:     0x7f1355851342 - core::result::unwrap_failed::h4f73e55c8329cfd7
  10:     0x7f135584d676 - <F as scoped_threadpool::FnBox>::call_box::h1723d65f9c5bb190
  11:     0x7f135589fe37 - std::sys_common::backtrace::__rust_begin_short_backtrace::h2b723462a3517148
  12:     0x7f13558a15ab - std::panicking::try::do_call::h774dd5426164cfa4
  13:     0x7f13558c175c - __rust_maybe_catch_panic
                               at /checkout/src/libpanic_unwind/lib.rs:98
  14:     0x7f13558a6016 - <F as alloc::boxed::FnBox<A>>::call_box::h77b5a809e9d5f576
  15:     0x7f13558b98db - std::sys::imp::thread::Thread::new::thread_start::h10fad04495d944f7
                               at /checkout/src/liballoc/boxed.rs:661
                               at /checkout/src/libstd/sys_common/thread.rs:21
                               at /checkout/src/libstd/sys/unix/thread.rs:84
  16:     0x7f1354ff1dc4 - start_thread
  17:     0x7f1354b0928c - clone
  18:                0x0 - <unknown>
thread 'main' panicked at 'Thread pool worker panicked', .../.cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/scoped_threadpool-0.1.8/src/lib.rs:236:12
stack backtrace:
   0:     0x7f13558b8033 - std::sys::imp::backtrace::tracing::imp::unwind_backtrace::hcdf51e4c9dc54357
                               at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:     0x7f13558b42f4 - std::sys_common::backtrace::_print::h9da91fd31a37d0f1
                               at /checkout/src/libstd/sys_common/backtrace.rs:71
   2:     0x7f13558ba373 - std::panicking::default_hook::{{closure}}::h46820a72bf0cb624
                               at /checkout/src/libstd/sys_common/backtrace.rs:60
                               at /checkout/src/libstd/panicking.rs:380
   3:     0x7f13558ba0e2 - std::panicking::default_hook::h4c1ef1cc83189c8e
                               at /checkout/src/libstd/panicking.rs:396
   4:     0x7f13558ba837 - std::panicking::rust_panic_with_hook::h99016f44bdcb8544
                               at /checkout/src/libstd/panicking.rs:611
   5:     0x7f13558a158a - std::panicking::begin_panic_new::hd755c1160f19acbd
   6:     0x7f13558a85e9 - scoped_threadpool::Scope::join_all::h2c33a47d52e1e676
   7:     0x7f1355853a45 - simple_server::Server::listen::h8327821b0fef33ff
   8:     0x7f13558457da - server::main::h7fe8cf31eba20a83
   9:     0x7f13558c175c - __rust_maybe_catch_panic
                               at /checkout/src/libpanic_unwind/lib.rs:98
  10:     0x7f13558baf6a - std::rt::lang_start::h97aba2334c85f570
                               at /checkout/src/libstd/panicking.rs:458
                               at /checkout/src/libstd/panic.rs:361
                               at /checkout/src/libstd/rt.rs:59
  11:     0x7f1354a34b14 - __libc_start_main
  12:     0x7f1355844cb8 - <unknown>
  13:                0x0 - <unknown>

[steveklabnik]

   6:     0x7f13558a85e9 - scoped_threadpool::Scope::join_all::h2c33a47d52e1e676
   7:     0x7f1355853a45 - simple_server::Server::listen::h8327821b0fef33ff

hmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmm

[gsquire]

If I am reading this correctly, it looks like

simple-server/src/lib.rs

Line 131 in 61d1d83

self.handle_connection(stream).expect(

is the offending line?

[binarybana]

I ran into this last night and am still debugging it. For some reason the read method in handle_connection will sometimes read 0 bytes and then http_parse will cause the token error you see. According to the rust docs, 0 bytes read indicates that the socket has been closed. I've put in #66 which seems to fix it under wrk.