Dec 07 20:40:11.445 INFO testing chttp-0.2.4 against master#906deae0790bd18681b937fe9a141a3c26cf1855 for pr-56514
Dec 07 20:40:11.445 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-56514/worker-5/master#906deae0790bd18681b937fe9a141a3c26cf1855:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-5/pr-56514/master#906deae0790bd18681b937fe9a141a3c26cf1855:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +906deae0790bd18681b937fe9a141a3c26cf1855-alt build --frozen" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Dec 07 20:40:12.037 INFO [stdout] e6ed04a6732638ce6d9e38fecfed307bdb38f5b283ee5f863cc7e03d882f4691
Dec 07 20:40:12.039 INFO running `"docker" "start" "-a" "e6ed04a6732638ce6d9e38fecfed307bdb38f5b283ee5f863cc7e03d882f4691"`
Dec 07 20:40:14.752 INFO [stderr] usermod: no changes
Dec 07 20:40:15.141 INFO [stderr]    Compiling libnghttp2-sys v0.1.1
Dec 07 20:40:15.143 INFO [stderr]    Compiling curl-sys v0.4.15
Dec 07 20:40:15.158 INFO [stderr]    Compiling withers_derive v0.2.0
Dec 07 20:40:15.159 INFO [stderr]    Compiling crossbeam-channel v0.2.6
Dec 07 20:40:37.038 INFO [stderr]    Compiling curl v0.4.19
Dec 07 20:40:40.776 INFO [stderr]    Compiling chttp v0.2.4 (/source)
Dec 07 20:40:48.640 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 33.87s
Dec 07 20:40:48.660 INFO [stderr] su: No module specific data is present
Dec 07 20:40:49.244 INFO running `"docker" "inspect" "e6ed04a6732638ce6d9e38fecfed307bdb38f5b283ee5f863cc7e03d882f4691"`
Dec 07 20:40:49.486 INFO running `"docker" "rm" "-f" "e6ed04a6732638ce6d9e38fecfed307bdb38f5b283ee5f863cc7e03d882f4691"`
Dec 07 20:40:49.844 INFO [stdout] e6ed04a6732638ce6d9e38fecfed307bdb38f5b283ee5f863cc7e03d882f4691
Dec 07 20:40:49.846 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-56514/worker-5/master#906deae0790bd18681b937fe9a141a3c26cf1855:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-5/pr-56514/master#906deae0790bd18681b937fe9a141a3c26cf1855:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +906deae0790bd18681b937fe9a141a3c26cf1855-alt test --frozen --no-run" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Dec 07 20:40:50.139 INFO [stdout] 486a744b436233e71aa5e260ab6a4fa1adfcd582dfca9a58ae9b223e81554892
Dec 07 20:40:50.141 INFO running `"docker" "start" "-a" "486a744b436233e71aa5e260ab6a4fa1adfcd582dfca9a58ae9b223e81554892"`
Dec 07 20:40:51.216 INFO [stderr] usermod: no changes
Dec 07 20:40:51.604 INFO [stderr]    Compiling chttp v0.2.4 (/source)
Dec 07 20:41:45.338 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 54.10s
Dec 07 20:41:45.368 INFO [stderr] su: No module specific data is present
Dec 07 20:41:48.136 INFO running `"docker" "inspect" "486a744b436233e71aa5e260ab6a4fa1adfcd582dfca9a58ae9b223e81554892"`
Dec 07 20:41:48.480 INFO running `"docker" "rm" "-f" "486a744b436233e71aa5e260ab6a4fa1adfcd582dfca9a58ae9b223e81554892"`
Dec 07 20:41:48.728 INFO [stdout] 486a744b436233e71aa5e260ab6a4fa1adfcd582dfca9a58ae9b223e81554892
Dec 07 20:41:48.730 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-56514/worker-5/master#906deae0790bd18681b937fe9a141a3c26cf1855:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-5/pr-56514/master#906deae0790bd18681b937fe9a141a3c26cf1855:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +906deae0790bd18681b937fe9a141a3c26cf1855-alt test --frozen" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Dec 07 20:41:49.168 INFO [stdout] fb5ce8c06b156e7f4a65e6e754ee3f592b606e4c87dd6be5f0794af768ca8c0e
Dec 07 20:41:49.174 INFO running `"docker" "start" "-a" "fb5ce8c06b156e7f4a65e6e754ee3f592b606e4c87dd6be5f0794af768ca8c0e"`
Dec 07 20:41:50.267 INFO [stderr] usermod: no changes
Dec 07 20:41:50.640 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 0.34s
Dec 07 20:41:50.664 INFO [stderr]      Running /target/debug/deps/chttp-3ad2c731694b3629
Dec 07 20:41:50.668 INFO [stderr]      Running /target/debug/deps/redirects-99d8625ce8d35201
Dec 07 20:41:50.668 INFO [stdout] 
Dec 07 20:41:50.668 INFO [stdout] running 0 tests
Dec 07 20:41:50.668 INFO [stdout] 
Dec 07 20:41:50.668 INFO [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Dec 07 20:41:50.668 INFO [stdout] 
Dec 07 20:41:50.672 INFO [stdout] 
Dec 07 20:41:50.672 INFO [stdout] running 3 tests
Dec 07 20:41:50.764 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::agent: agent ready
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: BeginRequest(CurlRequest(Easy { handle: 0x7f5a58025be0, handler: 0x7f5a58025be0 }))
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: BeginRequest(CurlRequest(Easy { handle: 0x7f5a60002720, handler: 0x7f5a60002720 }))
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: BeginRequest(CurlRequest(Easy { handle: 0x7f5a54001e20, handler: 0x7f5a54001e20 }))
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request:   Trying 127.0.0.1...
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 43699 (#0)
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /0 HTTP/1.1\r\nHost: 127.0.0.1:43699\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f5a3800ff90 [serially]
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Server doesn't support multi-use (yet)
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request:   Trying 127.0.0.1...
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 44667 (#1)
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /a HTTP/1.1\r\nHost: 127.0.0.1:44667\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f5a3800ff90 [serially]
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Server doesn't support multi-use (yet)
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request:   Trying 127.0.0.1...
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 38035 (#2)
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /a HTTP/1.1\r\nHost: 127.0.0.1:38035\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.764 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.765 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: woke up from notify fd
Dec 07 20:41:50.765 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.772 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 301 Moved Permanently\r\n
Dec 07 20:41:50.772 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.796 INFO [stdout] test response_301_no_follow ... ok
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Location: /b\r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 0\r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #2 to host 127.0.0.1 left intact
Dec 07 20:41:50.796 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::agent: request with token 2 completed
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 301 Moved Permanently\r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Location: /b\r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 0\r\n
Dec 07 20:41:50.796 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::request: preparing for redirect to Some("/b")
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #1 to host 127.0.0.1 left intact
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Issue another request to this URL: 'http://127.0.0.1:44667/b'
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f5a3800ff90 [can pipeline]
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Could pipeline, but not asked to!
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Re-using existing connection! (#1) with host 127.0.0.1
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 44667 (#1)
Dec 07 20:41:50.796 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /b HTTP/1.1\r\nHost: 127.0.0.1:44667\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.797 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 301 Moved Permanently\r\n
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Location: /1\r\n
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 0\r\n
Dec 07 20:41:50.800 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::request: preparing for redirect to Some("/1")
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #0 to host 127.0.0.1 left intact
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Issue another request to this URL: 'http://127.0.0.1:43699/1'
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f5a3800ff90 [can pipeline]
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Could pipeline, but not asked to!
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Re-using existing connection! (#0) with host 127.0.0.1
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 43699 (#0)
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /1 HTTP/1.1\r\nHost: 127.0.0.1:43699\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.800 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 301 Moved Permanently\r\n
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Location: /2\r\n
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 0\r\n
Dec 07 20:41:50.824 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::request: preparing for redirect to Some("/2")
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #0 to host 127.0.0.1 left intact
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Issue another request to this URL: 'http://127.0.0.1:43699/2'
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f5a3800ff90 [can pipeline]
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Could pipeline, but not asked to!
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Re-using existing connection! (#0) with host 127.0.0.1
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 43699 (#0)
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /2 HTTP/1.1\r\nHost: 127.0.0.1:43699\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.824 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 200 OK\r\n
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Type: text/plain; charset=utf8\r\n
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 2\r\n
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 32 bytes
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: buffer is empty, read is pending
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << ok
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received 2 bytes of data
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 32 bytes
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 2 bytes, consuming 2 bytes
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 30 bytes
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: buffer is empty, read is pending
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #1 to host 127.0.0.1 left intact
Dec 07 20:41:50.840 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::agent: request with token 1 completed
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 30 bytes
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: request is closed, satisfying read request with EOF
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: woke up from notify fd
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: UnpauseWrite(1)
Dec 07 20:41:50.840 INFO [stderr]  WARN 2018-12-07T20:41:50Z: chttp::internal::agent: received unpause request for unknown request token: 1
Dec 07 20:41:50.840 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: UnpauseWrite(1)
Dec 07 20:41:50.841 INFO [stderr]  WARN 2018-12-07T20:41:50Z: chttp::internal::agent: received unpause request for unknown request token: 1
Dec 07 20:41:50.841 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 301 Moved Permanently\r\n
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Location: /3\r\n
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 0\r\n
Dec 07 20:41:50.848 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::request: preparing for redirect to Some("/3")
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #0 to host 127.0.0.1 left intact
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Issue another request to this URL: 'http://127.0.0.1:43699/3'
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f5a3800ff90 [can pipeline]
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Could pipeline, but not asked to!
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Re-using existing connection! (#0) with host 127.0.0.1
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 43699 (#0)
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /3 HTTP/1.1\r\nHost: 127.0.0.1:43699\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.848 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.848 INFO [stdout] test response_301_auto_follow ... ok
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 301 Moved Permanently\r\n
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Location: /4\r\n
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 0\r\n
Dec 07 20:41:50.864 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::request: preparing for redirect to Some("/4")
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #0 to host 127.0.0.1 left intact
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Issue another request to this URL: 'http://127.0.0.1:43699/4'
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f5a3800ff90 [can pipeline]
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Could pipeline, but not asked to!
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Re-using existing connection! (#0) with host 127.0.0.1
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 43699 (#0)
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /4 HTTP/1.1\r\nHost: 127.0.0.1:43699\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.864 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 301 Moved Permanently\r\n
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Location: /5\r\n
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 0\r\n
Dec 07 20:41:50.884 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::request: preparing for redirect to Some("/5")
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #0 to host 127.0.0.1 left intact
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Issue another request to this URL: 'http://127.0.0.1:43699/5'
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f5a3800ff90 [can pipeline]
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Could pipeline, but not asked to!
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Re-using existing connection! (#0) with host 127.0.0.1
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 43699 (#0)
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET /5 HTTP/1.1\r\nHost: 127.0.0.1:43699\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.884 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 301 Moved Permanently\r\n
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Location: /6\r\n
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 0\r\n
Dec 07 20:41:50.889 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::request: preparing for redirect to Some("/6")
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #0 to host 127.0.0.1 left intact
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Maximum (5) redirects followed
Dec 07 20:41:50.889 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::agent: curl error: [47] Number of redirects hit maximum amount
Dec 07 20:41:50.889 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 100ms
Dec 07 20:41:50.896 INFO [stdout] test redirect_limit_is_respected ... ok
Dec 07 20:41:50.896 INFO [stdout] 
Dec 07 20:41:50.896 INFO [stdout] test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Dec 07 20:41:50.896 INFO [stdout] 
Dec 07 20:41:50.896 INFO [stderr]      Running /target/debug/deps/response-2bb43626646036d9
Dec 07 20:41:50.900 INFO [stdout] 
Dec 07 20:41:50.900 INFO [stdout] running 2 tests
Dec 07 20:41:50.912 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::agent: agent ready
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: BeginRequest(CurlRequest(Easy { handle: 0x7f1058025a30, handler: 0x7f1058025a30 }))
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: BeginRequest(CurlRequest(Easy { handle: 0x7f1050001e10, handler: 0x7f1050001e10 }))
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request:   Trying 127.0.0.1...
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 43495 (#0)
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET / HTTP/1.1\r\nHost: 127.0.0.1:43495\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Found bundle for host 127.0.0.1: 0x7f104000ff70 [serially]
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Server doesn't support multi-use (yet)
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request:   Trying 127.0.0.1...
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 36289 (#1)
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: >> GET / HTTP/1.1\r\nHost: 127.0.0.1:36289\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\n\r\n
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: woke up from notify fd
Dec 07 20:41:50.912 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.920 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 200 OK\r\n
Dec 07 20:41:50.920 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Type: text/plain; charset=utf8\r\n
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 13000\r\n
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 32 bytes
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: buffer is empty, read is pending
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: woke up from notify fd
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: UnpauseWrite(0)
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wo
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received 8192 bytes of data
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 32 bytes
Dec 07 20:41:50.928 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 8192 bytes, consuming 32 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 32 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 8160 bytes, consuming 32 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 64 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 8128 bytes, consuming 64 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 128 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 8064 bytes, consuming 128 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 256 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 7936 bytes, consuming 256 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 512 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 7680 bytes, consuming 512 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 1024 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 7168 bytes, consuming 1024 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 2048 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 6144 bytes, consuming 2048 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 4096 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 4096 bytes, consuming 4096 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 8192 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: buffer is empty, read is pending
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: woke up from notify fd
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: UnpauseWrite(0)
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << w so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large wow so large 
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received 4808 bytes of data
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 8192 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 4808 bytes, consuming 4808 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 3384 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: buffer is empty, read is pending
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #0 to host 127.0.0.1 left intact
Dec 07 20:41:50.929 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::agent: request with token 0 completed
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 3384 bytes
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: request is closed, satisfying read request with EOF
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: woke up from notify fd
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: received message from agent handle: UnpauseWrite(0)
Dec 07 20:41:50.929 INFO [stderr]  WARN 2018-12-07T20:41:50Z: chttp::internal::agent: received unpause request for unknown request token: 0
Dec 07 20:41:50.929 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:50.929 INFO [stdout] test large_response_body ... ok
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << HTTP/1.1 200 OK\r\n
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Server: tiny-http (Rust)\r\n
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Date: Fri,  7 Dec 2018 20:41:50 GMT\r\n
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Type: text/plain; charset=utf8\r\n
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << Content-Length: 11\r\n
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << \r\n
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: << hello world
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received 11 bytes of data
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: Connection #1 to host 127.0.0.1 left intact
Dec 07 20:41:50.968 INFO [stderr] DEBUG 2018-12-07T20:41:50Z: chttp::internal::agent: request with token 1 completed
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::agent: polling with timeout of 100ms
Dec 07 20:41:50.968 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 32 bytes
Dec 07 20:41:50.969 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: read buffer contains 11 bytes, consuming 11 bytes
Dec 07 20:41:50.969 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: received read request for 21 bytes
Dec 07 20:41:50.969 INFO [stderr] TRACE 2018-12-07T20:41:50Z: chttp::internal::request: request is closed, satisfying read request with EOF
Dec 07 20:41:50.982 INFO [stdout] test simple_response_body ... ok
Dec 07 20:41:50.982 INFO [stdout] 
Dec 07 20:41:50.982 INFO [stdout] test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Dec 07 20:41:50.982 INFO [stdout] 
Dec 07 20:41:50.996 INFO [stdout] 
Dec 07 20:41:50.996 INFO [stdout] running 1 test
Dec 07 20:41:50.996 INFO [stderr]      Running /target/debug/deps/timeouts-5ac4dc2a3a99ecc2
Dec 07 20:41:51.016 INFO [stderr] DEBUG 2018-12-07T20:41:51Z: chttp::internal::agent: agent ready
Dec 07 20:41:51.016 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::agent: received message from agent handle: BeginRequest(CurlRequest(Easy { handle: 0x7ff64c025f50, handler: 0x7ff64c025f50 }))
Dec 07 20:41:51.016 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::request:   Trying 127.0.0.1...
Dec 07 20:41:51.016 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::request: Connected to 127.0.0.1 (127.0.0.1) port 35451 (#0)
Dec 07 20:41:51.016 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::request: >> POST / HTTP/1.1\r\nHost: 127.0.0.1:35451\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\nContent-Length: 11\r\nExpect: 100-continue\r\n\r\n
Dec 07 20:41:51.016 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:51.016 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::agent: woke up from notify fd
Dec 07 20:41:51.016 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:51.214 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:51.424 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:51.628 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:51.821 INFO [stderr] TRACE 2018-12-07T20:41:51Z: chttp::internal::agent: polling with timeout of 200ms
Dec 07 20:41:52.028 INFO [stderr] TRACE 2018-12-07T20:41:52Z: chttp::internal::request: Done waiting for 100-continue
Dec 07 20:41:52.028 INFO [stderr] TRACE 2018-12-07T20:41:52Z: chttp::internal::agent: polling with timeout of 1s
Dec 07 20:41:52.028 INFO [stderr] TRACE 2018-12-07T20:41:52Z: chttp::internal::request: >> hello world
Dec 07 20:41:52.028 INFO [stderr] TRACE 2018-12-07T20:41:52Z: chttp::internal::request: We are completely uploaded and fine
Dec 07 20:41:52.028 INFO [stderr] TRACE 2018-12-07T20:41:52Z: chttp::internal::agent: polling with timeout of 1s
Dec 07 20:41:53.023 INFO [stderr] TRACE 2018-12-07T20:41:53Z: chttp::internal::request: Operation timed out after 2000 milliseconds with 0 bytes received
Dec 07 20:41:53.023 INFO [stderr] TRACE 2018-12-07T20:41:53Z: chttp::internal::request: Closing connection 0
Dec 07 20:41:53.023 INFO [stderr] DEBUG 2018-12-07T20:41:53Z: chttp::internal::agent: curl error: [28] Timeout was reached
Dec 07 20:41:53.023 INFO [stderr] TRACE 2018-12-07T20:41:53Z: chttp::internal::agent: polling with timeout of 100ms
Dec 07 20:41:53.024 INFO [stdout] test request_errors_if_read_timeout_is_reached ... ok
Dec 07 20:41:53.024 INFO [stdout] 
Dec 07 20:41:53.024 INFO [stdout] test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Dec 07 20:41:53.024 INFO [stdout] 
Dec 07 20:41:53.026 INFO [stderr]    Doc-tests chttp
Dec 07 20:42:00.961 INFO [stdout] 
Dec 07 20:42:00.961 INFO [stdout] running 6 tests
Dec 07 20:42:41.403 INFO [stdout] test src/lib.rs -  (line 53) ... ok
Dec 07 20:42:43.001 INFO [stdout] test src/lib.rs -  (line 37) ... ok
Dec 07 20:42:43.256 INFO [stdout] test src/lib.rs -  (line 74) ... ok
Dec 07 20:42:44.490 INFO [stdout] test src/lib.rs -  (line 11) ... ok
Dec 07 20:42:44.877 INFO [stdout] test src/lib.rs -  (line 26) ... ok
Dec 07 20:42:45.380 INFO [stdout] test src/client.rs - client::ClientBuilder (line 17) ... ok
Dec 07 20:42:45.380 INFO [stdout] 
Dec 07 20:42:45.380 INFO [stdout] test result: ok. 6 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Dec 07 20:42:45.380 INFO [stdout] 
Dec 07 20:42:45.422 INFO [stderr] su: No module specific data is present
Dec 07 20:42:45.902 INFO running `"docker" "inspect" "fb5ce8c06b156e7f4a65e6e754ee3f592b606e4c87dd6be5f0794af768ca8c0e"`
Dec 07 20:42:46.190 INFO running `"docker" "rm" "-f" "fb5ce8c06b156e7f4a65e6e754ee3f592b606e4c87dd6be5f0794af768ca8c0e"`
Dec 07 20:42:46.432 INFO [stdout] fb5ce8c06b156e7f4a65e6e754ee3f592b606e4c87dd6be5f0794af768ca8c0e