[INFO] cloning repository https://github.com/mbirtwell/mikes_crawler [INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/mbirtwell/mikes_crawler" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fmbirtwell%2Fmikes_crawler", kill_on_drop: false }` [INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fmbirtwell%2Fmikes_crawler'... [INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }` [INFO] [stdout] 7cea81e081345fbb4591192d02e709f3cce089f0 [INFO] testing mbirtwell/mikes_crawler against try#1b74e096b9bfb06f84a3007193dcd2f059cbdf6a for pr-96025 [INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fmbirtwell%2Fmikes_crawler" "/workspace/builds/worker-24/source", kill_on_drop: false }` [INFO] [stderr] Cloning into '/workspace/builds/worker-24/source'... [INFO] [stderr] done. [INFO] validating manifest of git repo https://github.com/mbirtwell/mikes_crawler on toolchain 1b74e096b9bfb06f84a3007193dcd2f059cbdf6a [INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+1b74e096b9bfb06f84a3007193dcd2f059cbdf6a" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }` [INFO] removed /workspace/builds/worker-24/source/rust-toolchain.toml [INFO] started tweaking git repo https://github.com/mbirtwell/mikes_crawler [INFO] finished tweaking git repo https://github.com/mbirtwell/mikes_crawler [INFO] tweaked toml for git repo https://github.com/mbirtwell/mikes_crawler written to /workspace/builds/worker-24/source/Cargo.toml [INFO] crate git repo https://github.com/mbirtwell/mikes_crawler already has a lockfile, it will not be regenerated [INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+1b74e096b9bfb06f84a3007193dcd2f059cbdf6a" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-24/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-24/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:b0c94ce3c1162fcb8e57cac5b65ec2f72eabb1eebea4fcc35e269e823f681646" "/opt/rustwide/cargo-home/bin/cargo" "+1b74e096b9bfb06f84a3007193dcd2f059cbdf6a" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] db87826eb40b9a90166c96d3138738f2c152e80fa3a59d81d2e14b8759a00f3e [INFO] running `Command { std: "docker" "start" "-a" "db87826eb40b9a90166c96d3138738f2c152e80fa3a59d81d2e14b8759a00f3e", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "db87826eb40b9a90166c96d3138738f2c152e80fa3a59d81d2e14b8759a00f3e", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "db87826eb40b9a90166c96d3138738f2c152e80fa3a59d81d2e14b8759a00f3e", kill_on_drop: false }` [INFO] [stdout] db87826eb40b9a90166c96d3138738f2c152e80fa3a59d81d2e14b8759a00f3e [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-24/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-24/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:b0c94ce3c1162fcb8e57cac5b65ec2f72eabb1eebea4fcc35e269e823f681646" "/opt/rustwide/cargo-home/bin/cargo" "+1b74e096b9bfb06f84a3007193dcd2f059cbdf6a" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 7123781bb2c392b255d97c05bd368eb43db717246e11ac166a433a6be8f48b2f [INFO] running `Command { std: "docker" "start" "-a" "7123781bb2c392b255d97c05bd368eb43db717246e11ac166a433a6be8f48b2f", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Compiling proc-macro2 v1.0.32 [INFO] [stderr] Compiling unicode-xid v0.2.2 [INFO] [stderr] Compiling autocfg v1.0.1 [INFO] [stderr] Compiling syn v1.0.81 [INFO] [stderr] Compiling libc v0.2.106 [INFO] [stderr] Compiling cfg-if v1.0.0 [INFO] [stderr] Compiling version_check v0.9.3 [INFO] [stderr] Compiling pin-project-lite v0.2.7 [INFO] [stderr] Compiling futures-core v0.3.17 [INFO] [stderr] Compiling serde_derive v1.0.130 [INFO] [stderr] Compiling bytes v1.1.0 [INFO] [stderr] Compiling log v0.4.14 [INFO] [stderr] Compiling serde v1.0.130 [INFO] [stderr] Compiling proc-macro-hack v0.5.19 [INFO] [stderr] Compiling lazy_static v1.4.0 [INFO] [stderr] Compiling futures-sink v0.3.17 [INFO] [stderr] Compiling itoa v0.4.8 [INFO] [stderr] Compiling memchr v2.4.1 [INFO] [stderr] Compiling fnv v1.0.7 [INFO] [stderr] Compiling pin-utils v0.1.0 [INFO] [stderr] Compiling once_cell v1.8.0 [INFO] [stderr] Compiling slab v0.4.5 [INFO] [stderr] Compiling hashbrown v0.11.2 [INFO] [stderr] Compiling yansi v0.5.0 [INFO] [stderr] Compiling ppv-lite86 v0.2.15 [INFO] [stderr] Compiling futures-task v0.3.17 [INFO] [stderr] Compiling getrandom v0.1.16 [INFO] [stderr] Compiling proc-macro-nested v0.1.7 [INFO] [stderr] Compiling futures-channel v0.3.17 [INFO] [stderr] Compiling httparse v1.5.1 [INFO] [stderr] Compiling try-lock v0.2.3 [INFO] [stderr] Compiling parking_lot_core v0.8.5 [INFO] [stderr] Compiling bitflags v1.3.2 [INFO] [stderr] Compiling scopeguard v1.1.0 [INFO] [stderr] Compiling percent-encoding v2.1.0 [INFO] [stderr] Compiling futures-io v0.3.17 [INFO] [stderr] Compiling smallvec v1.7.0 [INFO] [stderr] Compiling pkg-config v0.3.22 [INFO] [stderr] Compiling tower-service v0.3.1 [INFO] [stderr] Compiling httpdate v1.0.1 [INFO] [stderr] Compiling const_fn v0.4.8 [INFO] [stderr] Compiling siphasher v0.3.7 [INFO] [stderr] Compiling cc v1.0.71 [INFO] [stderr] Compiling ryu v1.0.5 [INFO] [stderr] Compiling inlinable_string v0.1.14 [INFO] [stderr] Compiling mime v0.3.16 [INFO] [stderr] Compiling ref-cast v1.0.6 [INFO] [stderr] Compiling foreign-types-shared v0.1.1 [INFO] [stderr] Compiling encoding_rs v0.8.29 [INFO] [stderr] Compiling state v0.5.2 [INFO] [stderr] Compiling openssl v0.10.38 [INFO] [stderr] Compiling serde_json v1.0.69 [INFO] [stderr] Compiling slog v2.7.0 [INFO] [stderr] Compiling either v1.6.1 [INFO] [stderr] Compiling native-tls v0.2.8 [INFO] [stderr] Compiling ident_case v1.0.1 [INFO] [stderr] Compiling tinyvec_macros v0.1.0 [INFO] [stderr] Compiling matches v0.1.9 [INFO] [stderr] Compiling strsim v0.10.0 [INFO] [stderr] Compiling new_debug_unreachable v1.0.4 [INFO] [stderr] Compiling mac v0.1.1 [INFO] [stderr] Compiling async-trait v0.1.51 [INFO] [stderr] Compiling openssl-probe v0.1.4 [INFO] [stderr] Compiling unchecked-index v0.2.2 [INFO] [stderr] Compiling schemars v0.8.6 [INFO] [stderr] Compiling glob v0.3.0 [INFO] [stderr] Compiling dyn-clone v1.0.4 [INFO] [stderr] Compiling remove_dir_all v0.5.3 [INFO] [stderr] Compiling spin v0.9.2 [INFO] [stderr] Compiling arc-swap v1.4.0 [INFO] [stderr] Compiling precomputed-hash v0.1.1 [INFO] [stderr] Compiling utf-8 v0.7.6 [INFO] [stderr] Compiling unicode-bidi v0.3.7 [INFO] [stderr] Compiling anyhow v1.0.45 [INFO] [stderr] Compiling binascii v0.1.4 [INFO] [stderr] Compiling ipnet v2.3.1 [INFO] [stderr] Compiling base64 v0.13.0 [INFO] [stderr] Compiling robotstxt v0.3.0 [INFO] [stderr] Compiling tracing-core v0.1.21 [INFO] [stderr] Compiling instant v0.1.12 [INFO] [stderr] Compiling lock_api v0.4.5 [INFO] [stderr] Compiling foreign-types v0.3.2 [INFO] [stderr] Compiling tinyvec v1.5.0 [INFO] [stderr] Compiling form_urlencoded v1.0.1 [INFO] [stderr] Compiling futf v0.1.4 [INFO] [stderr] Compiling phf_shared v0.8.0 [INFO] [stderr] Compiling thread_local v1.1.3 [INFO] [stderr] Compiling http v0.2.5 [INFO] [stderr] Compiling phf v0.8.0 [INFO] [stderr] Compiling tendril v0.4.2 [INFO] [stderr] Compiling futures-macro v0.3.17 [INFO] [stderr] Compiling tokio v1.13.0 [INFO] [stderr] Compiling futures-util v0.3.17 [INFO] [stderr] Compiling indexmap v1.7.0 [INFO] [stderr] Compiling num-traits v0.2.14 [INFO] [stderr] Compiling num-integer v0.1.44 [INFO] [stderr] Compiling atomic v0.5.0 [INFO] [stderr] Compiling proc-macro2-diagnostics v0.9.1 [INFO] [stderr] Compiling standback v0.2.17 [INFO] [stderr] Compiling time v0.2.27 [INFO] [stderr] Compiling cookie v0.15.1 [INFO] [stderr] Compiling uncased v0.9.6 [INFO] [stderr] Compiling figment v0.10.6 [INFO] [stderr] Compiling multer v2.0.1 [INFO] [stderr] Compiling rocket v0.5.0-rc.1 [INFO] [stderr] Compiling want v0.3.0 [INFO] [stderr] Compiling stable-pattern v0.1.0 [INFO] [stderr] Compiling twoway v0.2.2 [INFO] [stderr] Compiling tracing v0.1.29 [INFO] [stderr] Compiling openssl-sys v0.9.70 [INFO] [stderr] Compiling unicode-normalization v0.1.19 [INFO] [stderr] Compiling slog-scope v4.4.0 [INFO] [stderr] Compiling signal-hook-registry v1.4.0 [INFO] [stderr] Compiling num_cpus v1.13.0 [INFO] [stderr] Compiling mio v0.7.14 [INFO] [stderr] Compiling socket2 v0.4.2 [INFO] [stderr] Compiling getrandom v0.2.3 [INFO] [stderr] Compiling atty v0.2.14 [INFO] [stderr] Compiling dirs-sys-next v0.1.2 [INFO] [stderr] Compiling time v0.1.43 [INFO] [stderr] Compiling slog-scope-futures v0.1.1 [INFO] [stderr] Compiling slog-stdlog v4.1.0 [INFO] [stderr] Compiling quote v1.0.10 [INFO] [stderr] Compiling rand_core v0.5.1 [INFO] [stderr] Compiling dirs-next v2.0.0 [INFO] [stderr] Compiling rand_core v0.6.3 [INFO] [stderr] Compiling parking_lot v0.11.2 [INFO] [stderr] Compiling rand_chacha v0.2.2 [INFO] [stderr] Compiling rand_pcg v0.2.1 [INFO] [stderr] Compiling term v0.7.0 [INFO] [stderr] Compiling rand_chacha v0.3.1 [INFO] [stderr] Compiling rand v0.7.3 [INFO] [stderr] Compiling idna v0.2.3 [INFO] [stderr] Compiling rand v0.8.4 [INFO] [stderr] Compiling http-body v0.4.4 [INFO] [stderr] Compiling url v2.2.2 [INFO] [stderr] Compiling chrono v0.4.19 [INFO] [stderr] Compiling phf_generator v0.8.0 [INFO] [stderr] Compiling tempfile v3.2.0 [INFO] [stderr] Compiling string_cache_codegen v0.5.1 [INFO] [stderr] Compiling phf_codegen v0.8.0 [INFO] [stderr] Compiling slog-term v2.8.0 [INFO] [stderr] Compiling markup5ever v0.10.1 [INFO] [stderr] Compiling tokio-util v0.6.9 [INFO] [stderr] Compiling h2 v0.3.7 [INFO] [stderr] Compiling serde_derive_internals v0.25.0 [INFO] [stderr] Compiling darling_core v0.13.0 [INFO] [stderr] Compiling devise_core v0.3.1 [INFO] [stderr] Compiling tokio-macros v1.5.1 [INFO] [stderr] Compiling time-macros-impl v0.1.2 [INFO] [stderr] Compiling pear_codegen v0.2.3 [INFO] [stderr] Compiling ref-cast-impl v1.0.6 [INFO] [stderr] Compiling schemars_derive v0.8.6 [INFO] [stderr] Compiling async-stream-impl v0.3.2 [INFO] [stderr] Compiling html5ever v0.25.1 [INFO] [stderr] Compiling devise_codegen v0.3.1 [INFO] [stderr] Compiling hyper v0.14.14 [INFO] [stderr] Compiling darling_macro v0.13.0 [INFO] [stderr] Compiling async-stream v0.3.2 [INFO] [stderr] Compiling time-macros v0.1.1 [INFO] [stderr] Compiling pear v0.2.3 [INFO] [stderr] Compiling devise v0.3.1 [INFO] [stderr] Compiling darling v0.13.0 [INFO] [stderr] Compiling rocket_http v0.5.0-rc.1 [INFO] [stderr] Compiling futures-executor v0.3.17 [INFO] [stderr] Compiling futures v0.3.17 [INFO] [stderr] Compiling tokio-stream v0.1.8 [INFO] [stderr] Compiling tokio-native-tls v0.3.0 [INFO] [stderr] Compiling rocket_codegen v0.5.0-rc.1 [INFO] [stderr] Compiling rocket_okapi_codegen v0.8.0-rc.1 [INFO] [stderr] Compiling toml v0.5.8 [INFO] [stderr] Compiling string_cache v0.8.2 [INFO] [stderr] Compiling ubyte v0.10.1 [INFO] [stderr] Compiling serde_urlencoded v0.7.0 [INFO] [stderr] Compiling okapi v0.7.0-rc.1 [INFO] [stderr] Compiling hyper-tls v0.5.0 [INFO] [stderr] Compiling reqwest v0.11.6 [INFO] [stderr] Compiling rocket_okapi v0.8.0-rc.1 [INFO] [stderr] Compiling mikes_crawler v0.1.0 (/opt/rustwide/workdir) [INFO] [stderr] Finished dev [unoptimized + debuginfo] target(s) in 47.48s [INFO] running `Command { std: "docker" "inspect" "7123781bb2c392b255d97c05bd368eb43db717246e11ac166a433a6be8f48b2f", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "7123781bb2c392b255d97c05bd368eb43db717246e11ac166a433a6be8f48b2f", kill_on_drop: false }` [INFO] [stdout] 7123781bb2c392b255d97c05bd368eb43db717246e11ac166a433a6be8f48b2f [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-24/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-24/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:b0c94ce3c1162fcb8e57cac5b65ec2f72eabb1eebea4fcc35e269e823f681646" "/opt/rustwide/cargo-home/bin/cargo" "+1b74e096b9bfb06f84a3007193dcd2f059cbdf6a" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 8e5bfb240ab76d5e64bdc07696f0fd5d9aed6100370b39cf3b1ae3bb23e05b68 [INFO] running `Command { std: "docker" "start" "-a" "8e5bfb240ab76d5e64bdc07696f0fd5d9aed6100370b39cf3b1ae3bb23e05b68", kill_on_drop: false }` [INFO] [stderr] Compiling log v0.4.14 [INFO] [stderr] Compiling futures-io v0.3.17 [INFO] [stderr] Compiling cache-padded v1.1.1 [INFO] [stderr] Compiling event-listener v2.5.1 [INFO] [stderr] Compiling waker-fn v1.1.0 [INFO] [stderr] Compiling parking v2.0.0 [INFO] [stderr] Compiling fastrand v1.5.0 [INFO] [stderr] Compiling regex-syntax v0.6.25 [INFO] [stderr] Compiling crunchy v0.2.2 [INFO] [stderr] Compiling tiny-keccak v2.0.2 [INFO] [stderr] Compiling signal-hook v0.3.10 [INFO] [stderr] Compiling async-task v4.0.3 [INFO] [stderr] Compiling crossbeam-utils v0.8.5 [INFO] [stderr] Compiling fixedbitset v0.2.0 [INFO] [stderr] Compiling bit-vec v0.6.3 [INFO] [stderr] Compiling diff v0.1.12 [INFO] [stderr] Compiling atomic-waker v1.0.0 [INFO] [stderr] Compiling pico-args v0.4.2 [INFO] [stderr] Compiling curl v0.4.40 [INFO] [stderr] Compiling isahc v1.5.1 [INFO] [stderr] Compiling castaway v0.1.1 [INFO] [stderr] Compiling lalrpop-util v0.19.6 [INFO] [stderr] Compiling unindent v0.1.7 [INFO] [stderr] Compiling difference v2.0.0 [INFO] [stderr] Compiling levenshtein v1.0.5 [INFO] [stderr] Compiling urlencoding v2.1.0 [INFO] [stderr] Compiling value-bag v1.0.0-alpha.8 [INFO] [stderr] Compiling futures-util v0.3.17 [INFO] [stderr] Compiling libz-sys v1.1.3 [INFO] [stderr] Compiling libnghttp2-sys v0.1.7+1.45.0 [INFO] [stderr] Compiling curl-sys v0.4.50+curl-7.79.1 [INFO] [stderr] Compiling itertools v0.10.1 [INFO] [stderr] Compiling qstring v0.7.2 [INFO] [stderr] Compiling socket2 v0.4.2 [INFO] [stderr] Compiling aho-corasick v0.7.18 [INFO] [stderr] Compiling ena v0.14.0 [INFO] [stderr] Compiling ctor v0.1.21 [INFO] [stderr] Compiling tracing-attributes v0.1.18 [INFO] [stderr] Compiling string_cache v0.8.2 [INFO] [stderr] Compiling pin-project-internal v1.0.8 [INFO] [stderr] Compiling concurrent-queue v1.2.2 [INFO] [stderr] Compiling ascii-canvas v3.0.0 [INFO] [stderr] Compiling assert-json-diff v2.0.1 [INFO] [stderr] Compiling petgraph v0.5.1 [INFO] [stderr] Compiling bit-set v0.5.2 [INFO] [stderr] Compiling async-mutex v1.4.0 [INFO] [stderr] Compiling async-lock v2.4.0 [INFO] [stderr] Compiling indoc v1.0.3 [INFO] [stderr] Compiling async-channel v1.6.1 [INFO] [stderr] Compiling futures-lite v1.12.0 [INFO] [stderr] Compiling sluice v0.5.5 [INFO] [stderr] Compiling async-executor v1.4.1 [INFO] [stderr] Compiling blocking v1.0.2 [INFO] [stderr] Compiling regex v1.5.4 [INFO] [stderr] Compiling pin-project v1.0.8 [INFO] [stderr] Compiling mio v0.7.14 [INFO] [stderr] Compiling want v0.3.0 [INFO] [stderr] Compiling polling v2.1.0 [INFO] [stderr] Compiling native-tls v0.2.8 [INFO] [stderr] Compiling kv-log-macro v1.0.7 [INFO] [stderr] Compiling markup5ever v0.10.1 [INFO] [stderr] Compiling okapi v0.7.0-rc.1 [INFO] [stderr] Compiling slog-stdlog v4.1.0 [INFO] [stderr] Compiling tracing v0.1.29 [INFO] [stderr] Compiling async-io v1.6.0 [INFO] [stderr] Compiling tracing-futures v0.2.5 [INFO] [stderr] Compiling tokio v1.13.0 [INFO] [stderr] Compiling async-global-executor v2.0.2 [INFO] [stderr] Compiling async-process v1.2.0 [INFO] [stderr] Compiling serde_regex v1.1.0 [INFO] [stderr] Compiling futures-executor v0.3.17 [INFO] [stderr] Compiling html5ever v0.25.1 [INFO] [stderr] Compiling futures v0.3.17 [INFO] [stderr] Compiling lalrpop v0.19.6 [INFO] [stderr] Compiling async-std v1.10.0 [INFO] [stderr] Compiling tokio-util v0.6.9 [INFO] [stderr] Compiling tokio-native-tls v0.3.0 [INFO] [stderr] Compiling tokio-stream v0.1.8 [INFO] [stderr] Compiling h2 v0.3.7 [INFO] [stderr] Compiling multer v2.0.1 [INFO] [stderr] Compiling async-object-pool v0.1.4 [INFO] [stderr] Compiling hyper v0.14.14 [INFO] [stderr] Compiling basic-cookies v0.1.4 [INFO] [stderr] Compiling rocket_http v0.5.0-rc.1 [INFO] [stderr] Compiling hyper-tls v0.5.0 [INFO] [stderr] Compiling reqwest v0.11.6 [INFO] [stderr] Compiling httpmock v0.6.2 [INFO] [stderr] Compiling rocket v0.5.0-rc.1 [INFO] [stderr] Compiling rocket_okapi v0.8.0-rc.1 [INFO] [stderr] Compiling mikes_crawler v0.1.0 (/opt/rustwide/workdir) [INFO] [stderr] Finished test [unoptimized + debuginfo] target(s) in 34.68s [INFO] [stderr] Executable unittests src/lib.rs (/opt/rustwide/target/debug/deps/mikes_crawler-dafc3f1698090ab0) [INFO] [stderr] Executable unittests src/main.rs (/opt/rustwide/target/debug/deps/mikes_crawler-e04be120686ad0b1) [INFO] [stderr] Executable tests/integration.rs (/opt/rustwide/target/debug/deps/integration-4903ee5657a9e8f4) [INFO] running `Command { std: "docker" "inspect" "8e5bfb240ab76d5e64bdc07696f0fd5d9aed6100370b39cf3b1ae3bb23e05b68", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "8e5bfb240ab76d5e64bdc07696f0fd5d9aed6100370b39cf3b1ae3bb23e05b68", kill_on_drop: false }` [INFO] [stdout] 8e5bfb240ab76d5e64bdc07696f0fd5d9aed6100370b39cf3b1ae3bb23e05b68 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-24/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-24/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:b0c94ce3c1162fcb8e57cac5b65ec2f72eabb1eebea4fcc35e269e823f681646" "/opt/rustwide/cargo-home/bin/cargo" "+1b74e096b9bfb06f84a3007193dcd2f059cbdf6a" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 58a9dbcbc42575f38a9cad242d777db08e0f92c85f6ec2c66914cf1c06fef0f2 [INFO] running `Command { std: "docker" "start" "-a" "58a9dbcbc42575f38a9cad242d777db08e0f92c85f6ec2c66914cf1c06fef0f2", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Finished test [unoptimized + debuginfo] target(s) in 2.50s [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/mikes_crawler-dafc3f1698090ab0) [INFO] [stdout] [INFO] [stdout] running 27 tests [INFO] [stdout] Apr 26 20:20:24.857 INFO[mikes_crawler::crawler] Got redirect from https://example.com/redirect to https://notexample.com/target [INFO] [stdout] Apr 26 20:20:24.858 INFO[mikes_crawler::crawler] Got body to process from https://example.com/page containing 190 chars [INFO] [stdout] Apr 26 20:20:24.878 WARN[rocket::config::config] 🔧 Configured for debug. [INFO] [stdout] Apr 26 20:20:24.878 WARN[rocket::config::config] address: 127.0.0.1 [INFO] [stdout] Apr 26 20:20:24.878 WARN[rocket::config::config] port: 8000 [INFO] [stdout] Apr 26 20:20:24.878 WARN[rocket::config::config] workers: 56 [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::config::config] ident: Rocket [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::config::config] keep-alive: 5s [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::config::config] limits: bytes = 8KiB, data-form = 2MiB, file = 1MiB, form = 32KiB, json = 1MiB, msgpack = 1MiB, string = 8KiB [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::config::config] tls: disabled [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::config::config] temp dir: /tmp [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::config::config] log level: normal [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::config::config] cli colors: true [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::config::config] shutdown: ctrlc = true, force = true, signals = [SIGTERM], grace = 2s, mercy = 3s [INFO] [stdout] Apr 26 20:20:24.879 WARN[rocket::rocket] 🛰 Routes: [INFO] [stdout] Apr 26 20:20:24.880 WARN[rocket::rocket] (status) GET /status [INFO] [stdout] Apr 26 20:20:24.880 WARN[rocket::rocket] (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.880 WARN[rocket::rocket] (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:24.880 WARN[rocket::rocket] (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:24.878 INFO[mikes_crawler::crawler] Got redirect from https://example.com/redirect to https://example.com/target [INFO] [stdout] Apr 26 20:20:24.882 INFO[mikes_crawler::crawler] Got body to process from https://example.com/target containing 129 chars [INFO] [stdout] Apr 26 20:20:24.883 WARN[rocket::fairing::fairings] 📡 Fairings: [INFO] [stdout] Apr 26 20:20:24.883 WARN[rocket::fairing::fairings] Shield (liftoff, response, singleton) [INFO] [stdout] Apr 26 20:20:24.883 WARN[rocket::fairing::fairings] BetterLogging (request, response) [INFO] [stdout] Apr 26 20:20:24.883 INFO[rocket::shield::shield] 🛡️ Shield: [INFO] [stdout] Apr 26 20:20:24.883 INFO[rocket::shield::shield] Permissions-Policy: interest-cohort=() [INFO] [stdout] Apr 26 20:20:24.883 INFO[rocket::shield::shield] X-Content-Type-Options: nosniff [INFO] [stdout] Apr 26 20:20:24.883 INFO[rocket::shield::shield] X-Frame-Options: SAMEORIGIN [INFO] [stdout] Apr 26 20:20:24.884 WARN[rocket::rocket] 🚀 Rocket has launched into local orbit [INFO] [stdout] Apr 26 20:20:24.884 INFO[mikes_crawler::better_logging] Received request: /status, REQ: Rd4f [INFO] [stdout] Apr 26 20:20:24.884 INFO[rocket::server] GET /status: [INFO] [stdout] Apr 26 20:20:24.884 INFO[rocket::server] Matched: (status) GET /status [INFO] [stdout] Apr 26 20:20:24.885 INFO[mikes_crawler::crawler] Got body to process from https://example.com/start containing 180 chars [INFO] [stdout] Apr 26 20:20:24.893 INFO[mikes_crawler::crawler] Got body to process from https://example.com/start containing 135 chars [INFO] [stdout] Apr 26 20:20:24.893 INFO[mikes_crawler::crawler] Got non html response containing: x-application/pdf [INFO] [stdout] Apr 26 20:20:24.896 INFO[mikes_crawler::crawler] Got body to process from https://example.com/start containing 133 chars [INFO] [stdout] Apr 26 20:20:24.897 INFO[mikes_crawler::crawler] Got redirect from https://example.com/redirect to https://example.com/start [INFO] [stdout] Apr 26 20:20:24.898 INFO[mikes_crawler::crawler] Got body to process from https://example.com/start containing 180 chars [INFO] [stdout] Apr 26 20:20:24.906 INFO[mikes_crawler::crawler] Got body to process from https://example.com/page containing 133 chars [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] 🔧 Configured for debug. [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] address: 127.0.0.1 [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] port: 8000 [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] workers: 56 [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] ident: Rocket [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] keep-alive: 5s [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] limits: bytes = 8KiB, data-form = 2MiB, file = 1MiB, form = 32KiB, json = 1MiB, msgpack = 1MiB, string = 8KiB [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] tls: disabled [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] temp dir: /tmp [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] log level: normal [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] cli colors: true [INFO] [stdout] Apr 26 20:20:24.907 WARN[rocket::config::config] shutdown: ctrlc = true, force = true, signals = [SIGTERM], grace = 2s, mercy = 3s [INFO] [stdout] Apr 26 20:20:24.908 WARN[rocket::rocket] 🛰 Routes: [INFO] [stdout] Apr 26 20:20:24.910 WARN[rocket::rocket] (status) GET /status [INFO] [stdout] Apr 26 20:20:24.910 WARN[rocket::rocket] (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.910 WARN[rocket::rocket] (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:24.910 WARN[rocket::rocket] (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:24.910 INFO[mikes_crawler::crawler] Got body to process from https://example.com/page1 containing 0 chars [INFO] [stdout] Apr 26 20:20:24.908 INFO[mikes_crawler::crawler] Got body to process from https://example.com/start containing 130 chars [INFO] [stdout] Apr 26 20:20:24.910 INFO[mikes_crawler::crawler] Got body to process from https://example.com/page2 containing 0 chars [INFO] [stdout] Apr 26 20:20:24.910 WARN[rocket::fairing::fairings] 📡 Fairings: [INFO] [stdout] Apr 26 20:20:24.910 WARN[rocket::fairing::fairings] Shield (liftoff, response, singleton) [INFO] [stdout] Apr 26 20:20:24.910 WARN[rocket::fairing::fairings] BetterLogging (request, response) [INFO] [stdout] Apr 26 20:20:24.916 INFO[mikes_crawler::crawler] Got body to process from https://example.com/start containing 180 chars [INFO] [stdout] test crawler::tests::dont_follow_external_redirects ... ok [INFO] [stdout] test crawler::tests::dont_visit_fragments_separately ... ok [INFO] [stdout] test crawler::tests::ignores_non_html ... ok [INFO] [stdout] test crawler::tests::dont_revisit_due_to_redirect ... ok [INFO] [stdout] test link_extractor::tests::continues_after_script_tags ... ok [INFO] [stdout] Apr 26 20:20:24.917 INFO[rocket::shield::shield] 🛡️ Shield: [INFO] [stdout] Apr 26 20:20:24.917 INFO[rocket::shield::shield] Permissions-Policy: interest-cohort=() [INFO] [stdout] Apr 26 20:20:24.917 INFO[rocket::shield::shield] X-Frame-Options: SAMEORIGIN [INFO] [stdout] Apr 26 20:20:24.917 INFO[rocket::shield::shield] X-Content-Type-Options: nosniff [INFO] [stdout] Apr 26 20:20:24.917 WARN[rocket::rocket] 🚀 Rocket has launched into local orbit [INFO] [stdout] test link_extractor::tests::extracts_links_in_domain_as_internal_link ... ok [INFO] [stdout] test crawler::tests::get_some_status ... ok [INFO] [stdout] Apr 26 20:20:24.921 INFO[mikes_crawler::crawler] Got body to process from https://example.com/link1 containing 180 chars [INFO] [stdout] Apr 26 20:20:24.922 INFO[mikes_crawler::crawler] Got body to process from https://example.com/link2 containing 180 chars [INFO] [stdout] test link_extractor::tests::extracts_links_in_other_domain_as_external_link ... ok [INFO] [stdout] test link_extractor::tests::relative_links_are_internal_links ... ok [INFO] [stdout] Apr 26 20:20:24.927 INFO[mikes_crawler::better_logging] Received request: /crawl/https%3A%2F%2Fexample.com%2F, REQ: 9DN8 [INFO] [stdout] Apr 26 20:20:24.927 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:24.927 INFO[rocket::server] GET /crawl/https%3A%2F%2Fexample.com%2F: [INFO] [stdout] Apr 26 20:20:24.927 INFO[mikes_crawler::better_logging] Completed request /status with status 500 Internal Server Error in 0.043s, REQ: Rd4f [INFO] [stdout] Apr 26 20:20:24.928 INFO[rocket::server] Matched: (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.928 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:24.929 INFO[mikes_crawler::better_logging] Completed request /crawl/https%3A%2F%2Fexample.com%2F with status 200 OK in 0.010s, REQ: 9DN8 [INFO] [stdout] test api::tests::status_return_internal_error_from_crawler ... ok [INFO] [stdout] test crawler::tests::stop_after_parallel_loop_of_pages ... ok [INFO] [stdout] Apr 26 20:20:24.932 INFO[mikes_crawler::crawler] Got body to process from https://example.com/start containing 180 chars [INFO] [stdout] Apr 26 20:20:24.933 INFO[mikes_crawler::crawler] Got body to process from https://example.com/back containing 131 chars [INFO] [stdout] Apr 26 20:20:24.935 INFO[mikes_crawler::crawler] Got body to process from https://example.com/link1 containing 0 chars [INFO] [stdout] Apr 26 20:20:24.935 INFO[mikes_crawler::crawler] Got body to process from https://example.com/link2 containing 0 chars [INFO] [stdout] test crawler::tests::ignores_link_to_page_excluded_by_robots_txt ... ok [INFO] [stdout] test link_extractor::tests::empty_lists_for_empty_html ... ok [INFO] [stdout] test crawler::tests::dont_revisit_if_found_from_redirect ... ok [INFO] [stdout] Apr 26 20:20:24.937 INFO[mikes_crawler::crawler] Got body to process from https://example.com/link1 containing 130 chars [INFO] [stdout] Apr 26 20:20:24.950 INFO[mikes_crawler::crawler] Got redirect from https://example.com/redirect to https://example.com/target [INFO] [stdout] Apr 26 20:20:24.950 INFO[mikes_crawler::crawler] Got body to process from https://example.com/target containing 135 chars [INFO] [stdout] Apr 26 20:20:24.953 INFO[mikes_crawler::crawler] Got body to process from https://example.com/link2 containing 130 chars [INFO] [stdout] Apr 26 20:20:24.954 INFO[mikes_crawler::crawler] Got response with status 500 Internal Server Error: Not processing the body [INFO] [stdout] test crawler::tests::reports_single_page_with_external_links ... ok [INFO] [stdout] test api::tests::crawl_returns_result_from_crawler ... ok [INFO] [stdout] test crawler::tests::reports_single_server_error ... ok [INFO] [stdout] test crawler::tests::stop_after_loop_of_pages ... ok [INFO] [stdout] test crawler::tests::follows_multiple_internal_links ... ok [INFO] [stdout] Apr 26 20:20:24.970 WARN[rocket::config::config] 🔧 Configured for debug. [INFO] [stdout] Apr 26 20:20:24.970 WARN[rocket::config::config] address: 127.0.0.1 [INFO] [stdout] Apr 26 20:20:24.970 WARN[rocket::config::config] port: 8000 [INFO] [stdout] Apr 26 20:20:24.970 WARN[rocket::config::config] workers: 56 [INFO] [stdout] Apr 26 20:20:24.970 WARN[rocket::config::config] ident: Rocket [INFO] [stdout] Apr 26 20:20:24.970 WARN[rocket::config::config] keep-alive: 5s [INFO] [stdout] Apr 26 20:20:24.970 WARN[rocket::config::config] limits: bytes = 8KiB, data-form = 2MiB, file = 1MiB, form = 32KiB, json = 1MiB, msgpack = 1MiB, string = 8KiB [INFO] [stdout] Apr 26 20:20:24.970 WARN[rocket::config::config] tls: disabled [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::config::config] temp dir: /tmp [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::config::config] log level: normal [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::config::config] cli colors: true [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::config::config] shutdown: ctrlc = true, force = true, signals = [SIGTERM], grace = 2s, mercy = 3s [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::rocket] 🛰 Routes: [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::rocket] (status) GET /status [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::rocket] (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::rocket] (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::rocket] (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::fairing::fairings] 📡 Fairings: [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::fairing::fairings] BetterLogging (request, response) [INFO] [stdout] Apr 26 20:20:24.971 WARN[rocket::fairing::fairings] Shield (liftoff, response, singleton) [INFO] [stdout] Apr 26 20:20:24.972 INFO[rocket::shield::shield] 🛡️ Shield: [INFO] [stdout] Apr 26 20:20:24.972 INFO[rocket::shield::shield] X-Content-Type-Options: nosniff [INFO] [stdout] Apr 26 20:20:24.972 INFO[rocket::shield::shield] X-Frame-Options: SAMEORIGIN [INFO] [stdout] Apr 26 20:20:24.972 INFO[rocket::shield::shield] Permissions-Policy: interest-cohort=() [INFO] [stdout] Apr 26 20:20:24.972 WARN[rocket::rocket] 🚀 Rocket has launched into local orbit [INFO] [stdout] Apr 26 20:20:24.972 INFO[mikes_crawler::better_logging] Received request: /crawl/https%3A%2F%2Fexample.com, REQ: mM2P [INFO] [stdout] Apr 26 20:20:24.972 INFO[rocket::server] GET /crawl/https%3A%2F%2Fexample.com: [INFO] [stdout] Apr 26 20:20:24.972 INFO[rocket::server] Matched: (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.977 WARN[rocket::config::config] 🔧 Configured for debug. [INFO] [stdout] Apr 26 20:20:24.978 WARN[rocket::config::config] address: 127.0.0.1 [INFO] [stdout] Apr 26 20:20:24.978 WARN[rocket::config::config] port: 8000 [INFO] [stdout] Apr 26 20:20:24.978 WARN[rocket::config::config] workers: 56 [INFO] [stdout] Apr 26 20:20:24.978 WARN[rocket::config::config] ident: Rocket [INFO] [stdout] Apr 26 20:20:24.979 WARN[rocket::config::config] keep-alive: 5s [INFO] [stdout] Apr 26 20:20:24.979 WARN[rocket::config::config] limits: bytes = 8KiB, data-form = 2MiB, file = 1MiB, form = 32KiB, json = 1MiB, msgpack = 1MiB, string = 8KiB [INFO] [stdout] Apr 26 20:20:24.979 WARN[rocket::config::config] tls: disabled [INFO] [stdout] Apr 26 20:20:24.979 WARN[rocket::config::config] temp dir: /tmp [INFO] [stdout] Apr 26 20:20:24.979 WARN[rocket::config::config] log level: normal [INFO] [stdout] Apr 26 20:20:24.980 WARN[rocket::config::config] cli colors: true [INFO] [stdout] Apr 26 20:20:24.980 WARN[rocket::config::config] shutdown: ctrlc = true, force = true, signals = [SIGTERM], grace = 2s, mercy = 3s [INFO] [stdout] Apr 26 20:20:24.980 WARN[rocket::rocket] 🛰 Routes: [INFO] [stdout] Apr 26 20:20:24.981 WARN[rocket::rocket] (status) GET /status [INFO] [stdout] Apr 26 20:20:24.981 WARN[rocket::rocket] (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.981 WARN[rocket::rocket] (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:24.981 WARN[rocket::rocket] (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:24.981 WARN[rocket::fairing::fairings] 📡 Fairings: [INFO] [stdout] Apr 26 20:20:24.981 WARN[rocket::fairing::fairings] BetterLogging (request, response) [INFO] [stdout] Apr 26 20:20:24.981 WARN[rocket::fairing::fairings] Shield (liftoff, response, singleton) [INFO] [stdout] test crawler::tests::reports_redirect_and_target ... ok [INFO] [stdout] Apr 26 20:20:24.982 INFO[rocket::shield::shield] 🛡️ Shield: [INFO] [stdout] Apr 26 20:20:24.982 INFO[rocket::shield::shield] X-Frame-Options: SAMEORIGIN [INFO] [stdout] Apr 26 20:20:24.982 INFO[rocket::shield::shield] Permissions-Policy: interest-cohort=() [INFO] [stdout] Apr 26 20:20:24.982 INFO[rocket::shield::shield] X-Content-Type-Options: nosniff [INFO] [stdout] Apr 26 20:20:24.982 WARN[rocket::rocket] 🚀 Rocket has launched into local orbit [INFO] [stdout] Apr 26 20:20:24.983 INFO[mikes_crawler::better_logging] Received request: /crawl/garbage, REQ: Sjwr [INFO] [stdout] Apr 26 20:20:24.983 INFO[rocket::server] GET /crawl/garbage: [INFO] [stdout] Apr 26 20:20:24.984 INFO[rocket::server] Matched: (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.984 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:24.984 INFO[mikes_crawler::better_logging] Completed request /crawl/garbage with status 400 Bad Request in 0.001s, REQ: Sjwr [INFO] [stdout] Apr 26 20:20:24.983 WARN[rocket::config::config] 🔧 Configured for debug. [INFO] [stdout] Apr 26 20:20:24.984 WARN[rocket::config::config] address: 127.0.0.1 [INFO] [stdout] Apr 26 20:20:24.984 WARN[rocket::config::config] port: 8000 [INFO] [stdout] Apr 26 20:20:24.984 WARN[rocket::config::config] workers: 56 [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::config::config] ident: Rocket [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::config::config] keep-alive: 5s [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::config::config] limits: bytes = 8KiB, data-form = 2MiB, file = 1MiB, form = 32KiB, json = 1MiB, msgpack = 1MiB, string = 8KiB [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::config::config] tls: disabled [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::config::config] temp dir: /tmp [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::config::config] log level: normal [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::config::config] cli colors: true [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::config::config] shutdown: ctrlc = true, force = true, signals = [SIGTERM], grace = 2s, mercy = 3s [INFO] [stdout] Apr 26 20:20:24.985 WARN[rocket::rocket] 🛰 Routes: [INFO] [stdout] Apr 26 20:20:24.986 WARN[rocket::rocket] (status) GET /status [INFO] [stdout] Apr 26 20:20:24.986 WARN[rocket::rocket] (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.986 WARN[rocket::rocket] (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:24.986 WARN[rocket::rocket] (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:24.986 WARN[rocket::fairing::fairings] 📡 Fairings: [INFO] [stdout] Apr 26 20:20:24.986 WARN[rocket::fairing::fairings] BetterLogging (request, response) [INFO] [stdout] Apr 26 20:20:24.986 WARN[rocket::fairing::fairings] Shield (liftoff, response, singleton) [INFO] [stdout] Apr 26 20:20:24.986 INFO[rocket::shield::shield] 🛡️ Shield: [INFO] [stdout] Apr 26 20:20:24.987 INFO[rocket::shield::shield] X-Content-Type-Options: nosniff [INFO] [stdout] Apr 26 20:20:24.987 INFO[rocket::shield::shield] X-Frame-Options: SAMEORIGIN [INFO] [stdout] Apr 26 20:20:24.987 INFO[rocket::shield::shield] Permissions-Policy: interest-cohort=() [INFO] [stdout] Apr 26 20:20:24.987 WARN[rocket::rocket] 🚀 Rocket has launched into local orbit [INFO] [stdout] test api::tests::crawl_return_bad_request_for_non_url ... ok [INFO] [stdout] Apr 26 20:20:24.989 INFO[mikes_crawler::better_logging] Received request: /crawl/https%3A%2F%2Fexample.com%2F/list, REQ: JQsr [INFO] [stdout] Apr 26 20:20:24.990 INFO[rocket::server] GET /crawl/https%3A%2F%2Fexample.com%2F/list: [INFO] [stdout] Apr 26 20:20:24.990 INFO[rocket::server] Matched: (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:24.990 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:24.990 INFO[mikes_crawler::better_logging] Completed request /crawl/https%3A%2F%2Fexample.com%2F/list with status 200 OK in 0.003s, REQ: JQsr [INFO] [stdout] Apr 26 20:20:24.992 WARN[rocket::config::config] 🔧 Configured for debug. [INFO] [stdout] Apr 26 20:20:24.993 WARN[rocket::config::config] address: 127.0.0.1 [INFO] [stdout] Apr 26 20:20:24.993 WARN[rocket::config::config] port: 8000 [INFO] [stdout] Apr 26 20:20:24.993 WARN[rocket::config::config] workers: 56 [INFO] [stdout] Apr 26 20:20:24.993 WARN[rocket::config::config] ident: Rocket [INFO] [stdout] Apr 26 20:20:24.993 WARN[rocket::config::config] keep-alive: 5s [INFO] [stdout] Apr 26 20:20:24.993 WARN[rocket::config::config] limits: bytes = 8KiB, data-form = 2MiB, file = 1MiB, form = 32KiB, json = 1MiB, msgpack = 1MiB, string = 8KiB [INFO] [stdout] Apr 26 20:20:24.993 WARN[rocket::config::config] tls: disabled [INFO] [stdout] Apr 26 20:20:24.994 WARN[rocket::config::config] temp dir: /tmp [INFO] [stdout] Apr 26 20:20:24.994 WARN[rocket::config::config] log level: normal [INFO] [stdout] Apr 26 20:20:24.994 WARN[rocket::config::config] cli colors: true [INFO] [stdout] Apr 26 20:20:24.994 WARN[rocket::config::config] shutdown: ctrlc = true, force = true, signals = [SIGTERM], grace = 2s, mercy = 3s [INFO] [stdout] Apr 26 20:20:24.995 WARN[rocket::rocket] 🛰 Routes: [INFO] [stdout] Apr 26 20:20:24.995 WARN[rocket::rocket] (status) GET /status [INFO] [stdout] Apr 26 20:20:24.995 WARN[rocket::rocket] (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.995 WARN[rocket::rocket] (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:24.995 WARN[rocket::rocket] (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::fairing::fairings] 📡 Fairings: [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::fairing::fairings] BetterLogging (request, response) [INFO] [stdout] Apr 26 20:20:24.995 WARN[rocket::config::config] 🔧 Configured for debug. [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::config::config] address: 127.0.0.1 [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::config::config] port: 8000 [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::config::config] workers: 56 [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::config::config] ident: Rocket [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::config::config] keep-alive: 5s [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::config::config] limits: bytes = 8KiB, data-form = 2MiB, file = 1MiB, form = 32KiB, json = 1MiB, msgpack = 1MiB, string = 8KiB [INFO] [stdout] Apr 26 20:20:24.996 WARN[rocket::config::config] tls: disabled [INFO] [stdout] Apr 26 20:20:24.997 WARN[rocket::config::config] temp dir: /tmp [INFO] [stdout] Apr 26 20:20:24.997 WARN[rocket::fairing::fairings] Shield (liftoff, response, singleton) [INFO] [stdout] Apr 26 20:20:24.997 WARN[rocket::config::config] log level: normal [INFO] [stdout] Apr 26 20:20:24.997 WARN[rocket::config::config] cli colors: true [INFO] [stdout] Apr 26 20:20:24.997 WARN[rocket::config::config] shutdown: ctrlc = true, force = true, signals = [SIGTERM], grace = 2s, mercy = 3s [INFO] [stdout] test api::tests::list_returns_all_visited_urls ... ok [INFO] [stdout] Apr 26 20:20:24.997 WARN[rocket::rocket] 🛰 Routes: [INFO] [stdout] Apr 26 20:20:24.997 WARN[rocket::rocket] (status) GET /status [INFO] [stdout] Apr 26 20:20:24.998 WARN[rocket::rocket] (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:24.998 WARN[rocket::rocket] (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:24.998 WARN[rocket::rocket] (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:24.998 WARN[rocket::fairing::fairings] 📡 Fairings: [INFO] [stdout] Apr 26 20:20:24.998 WARN[rocket::fairing::fairings] Shield (liftoff, response, singleton) [INFO] [stdout] Apr 26 20:20:24.998 WARN[rocket::fairing::fairings] BetterLogging (request, response) [INFO] [stdout] Apr 26 20:20:24.998 INFO[rocket::shield::shield] 🛡️ Shield: [INFO] [stdout] Apr 26 20:20:24.998 INFO[rocket::shield::shield] X-Frame-Options: SAMEORIGIN [INFO] [stdout] Apr 26 20:20:24.997 INFO[rocket::shield::shield] 🛡️ Shield: [INFO] [stdout] Apr 26 20:20:24.998 INFO[rocket::shield::shield] Permissions-Policy: interest-cohort=() [INFO] [stdout] Apr 26 20:20:24.998 INFO[rocket::shield::shield] X-Content-Type-Options: nosniff [INFO] [stdout] Apr 26 20:20:24.998 WARN[rocket::rocket] 🚀 Rocket has launched into local orbit [INFO] [stdout] Apr 26 20:20:24.998 INFO[rocket::shield::shield] X-Content-Type-Options: nosniff [INFO] [stdout] Apr 26 20:20:24.998 INFO[rocket::shield::shield] X-Frame-Options: SAMEORIGIN [INFO] [stdout] Apr 26 20:20:24.998 INFO[rocket::shield::shield] Permissions-Policy: interest-cohort=() [INFO] [stdout] Apr 26 20:20:24.998 WARN[rocket::rocket] 🚀 Rocket has launched into local orbit [INFO] [stdout] Apr 26 20:20:24.999 INFO[mikes_crawler::better_logging] Received request: /status, REQ: gfKW [INFO] [stdout] Apr 26 20:20:24.999 INFO[rocket::server] GET /status: [INFO] [stdout] Apr 26 20:20:24.999 INFO[rocket::server] Matched: (status) GET /status [INFO] [stdout] Apr 26 20:20:24.999 INFO[mikes_crawler::better_logging] Received request: /crawl/https%3A%2F%2Fexample.com%2F/count, REQ: x3f3 [INFO] [stdout] Apr 26 20:20:24.999 INFO[rocket::server] GET /crawl/https%3A%2F%2Fexample.com%2F/count: [INFO] [stdout] Apr 26 20:20:24.999 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:24.999 INFO[rocket::server] Matched: (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:24.999 INFO[mikes_crawler::better_logging] Completed request /status with status 200 OK in 0.000s, REQ: gfKW [INFO] [stdout] Apr 26 20:20:25.000 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:25.000 INFO[mikes_crawler::better_logging] Completed request /crawl/https%3A%2F%2Fexample.com%2F/count with status 200 OK in 0.000s, REQ: x3f3 [INFO] [stdout] test api::tests::status_returns_result_from_crawler ... ok [INFO] [stdout] test api::tests::count_returns_the_number_of_visited_urls ... ok [INFO] [stdout] Apr 26 20:20:25.033 INFO[mikes_crawler::crawler] Error trying to make request or process response: Connection failed [INFO] [stdout] Apr 26 20:20:25.033 INFO[mikes_crawler::crawler] Got body to process from https://example.com/page1 containing 0 chars [INFO] [stdout] test crawler::tests::reports_single_network_error ... ok [INFO] [stdout] test crawler::tests::crawl_tracking_is_removed_if_theres_an_error ... ok [INFO] [stdout] Apr 26 20:20:25.033 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:25.037 INFO[mikes_crawler::better_logging] Completed request /crawl/https%3A%2F%2Fexample.com with status 500 Internal Server Error in 0.065s, REQ: mM2P [INFO] [stdout] test api::tests::crawl_return_internal_error_from_crawler ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 27 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.18s [INFO] [stdout] [INFO] [stderr] Running unittests src/main.rs (/opt/rustwide/target/debug/deps/mikes_crawler-e04be120686ad0b1) [INFO] [stdout] [INFO] [stdout] running 0 tests [INFO] [stdout] [INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s [INFO] [stdout] [INFO] [stderr] Running tests/integration.rs (/opt/rustwide/target/debug/deps/integration-4903ee5657a9e8f4) [INFO] [stdout] [INFO] [stdout] running 5 tests [INFO] [stdout] Apr 26 20:20:25.100 INFO[httpmock::server] Listening on 127.0.0.1:43837 [INFO] [stdout] Apr 26 20:20:25.100 TRCE[polling::epoll] add: epoll_fd=14, fd=16, ev=Event { key: 18446744073709551615, readable: false, writable: false } [INFO] [stdout] Apr 26 20:20:25.104 TRCE[polling::epoll] add: epoll_fd=14, fd=15, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.104 TRCE[polling::epoll] new: epoll_fd=14, event_fd=15, timer_fd=Some(16) [INFO] [stdout] Apr 26 20:20:25.104 DEBG[] agent_thread; id=0 [INFO] [stdout] Apr 26 20:20:25.105 TRCE[] -> agent_thread [INFO] [stdout] Apr 26 20:20:25.105 DEBG[] agent took 5.686989ms to start up [INFO] [stdout] Apr 26 20:20:25.106 DEBG[] send_async; method=GET uri=http://127.0.0.1:43837/__httpmock__/ping [INFO] [stdout] Apr 26 20:20:25.106 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.106 DEBG[] handler [INFO] [stdout] Apr 26 20:20:25.106 INFO[httpmock::server] Listening on 127.0.0.1:34631 [INFO] [stdout] Apr 26 20:20:25.106 TRCE[polling] Poller::notify() [INFO] [stdout] Apr 26 20:20:25.106 TRCE[polling::epoll] notify: epoll_fd=14, event_fd=15 [INFO] [stdout] Apr 26 20:20:25.106 TRCE[polling::epoll] add: epoll_fd=25, fd=27, ev=Event { key: 18446744073709551615, readable: false, writable: false } [INFO] [stdout] Apr 26 20:20:25.106 TRCE[polling::epoll] add: epoll_fd=25, fd=26, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.106 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.106 TRCE[] received message from agent handle [INFO] [stdout] Apr 26 20:20:25.107 TRCE[polling::epoll] new: epoll_fd=25, event_fd=26, timer_fd=Some(27) [INFO] [stdout] Apr 26 20:20:25.107 DEBG[] agent_thread; id=1 [INFO] [stdout] Apr 26 20:20:25.107 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.107 DEBG[] handler; id=0 [INFO] [stdout] Apr 26 20:20:25.107 TRCE[] -> agent_thread [INFO] [stdout] Apr 26 20:20:25.107 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.107 DEBG[] agent took 1.12855ms to start up [INFO] [stdout] Apr 26 20:20:25.107 TRCE[polling] Poller::wait(_, Some(0ns)) [INFO] [stdout] Apr 26 20:20:25.107 TRCE[polling::epoll] wait: epoll_fd=14, timeout=Some(0ns) [INFO] [stdout] Apr 26 20:20:25.108 TRCE[polling::epoll] modify: epoll_fd=14, fd=16, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.107 DEBG[] send_async; method=GET uri=http://127.0.0.1:34631/__httpmock__/ping [INFO] [stdout] Apr 26 20:20:25.108 TRCE[polling::epoll] new events: epoll_fd=14, res=1 [INFO] [stdout] Apr 26 20:20:25.108 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.108 TRCE[polling::epoll] modify: epoll_fd=14, fd=15, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.108 DEBG[] handler [INFO] [stdout] Apr 26 20:20:25.108 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.108 DEBG[] Trying 127.0.0.1:43837... [INFO] [stdout] Apr 26 20:20:25.108 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.108 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.108 TRCE[polling] Poller::notify() [INFO] [stdout] Apr 26 20:20:25.108 TRCE[] received message from agent handle [INFO] [stdout] Apr 26 20:20:25.108 TRCE[polling::epoll] notify: epoll_fd=25, event_fd=26 [INFO] [stdout] Apr 26 20:20:25.108 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.108 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.108 DEBG[] handler; id=0 [INFO] [stdout] Apr 26 20:20:25.108 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.108 DEBG[] Failed to set TCP_KEEPINTVL on fd 33 [INFO] [stdout] Apr 26 20:20:25.109 TRCE[polling::epoll] add: epoll_fd=36, fd=38, ev=Event { key: 18446744073709551615, readable: false, writable: false } [INFO] [stdout] Apr 26 20:20:25.109 TRCE[polling::epoll] add: epoll_fd=36, fd=37, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.109 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.109 INFO[httpmock::server] Listening on 127.0.0.1:33773 [INFO] [stdout] Apr 26 20:20:25.109 TRCE[polling::epoll] new: epoll_fd=36, event_fd=37, timer_fd=Some(38) [INFO] [stdout] Apr 26 20:20:25.109 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.110 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.109 DEBG[] agent_thread; id=2 [INFO] [stdout] Apr 26 20:20:25.108 TRCE[polling] Poller::wait(_, Some(0ns)) [INFO] [stdout] Apr 26 20:20:25.110 TRCE[polling::epoll] wait: epoll_fd=25, timeout=Some(0ns) [INFO] [stdout] Apr 26 20:20:25.110 TRCE[polling::epoll] modify: epoll_fd=25, fd=27, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.110 TRCE[polling::epoll] new events: epoll_fd=25, res=1 [INFO] [stdout] Apr 26 20:20:25.110 TRCE[polling::epoll] modify: epoll_fd=25, fd=26, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.110 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.110 DEBG[] Trying 127.0.0.1:34631... [INFO] [stdout] Apr 26 20:20:25.110 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.110 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.110 DEBG[] Failed to set TCP_KEEPINTVL on fd 40 [INFO] [stdout] Apr 26 20:20:25.110 TRCE[] -> agent_thread [INFO] [stdout] Apr 26 20:20:25.110 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.111 DEBG[] agent took 1.96788ms to start up [INFO] [stdout] Apr 26 20:20:25.111 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.111 DEBG[] Connected to 127.0.0.1 (127.0.0.1) port 34631 (#0) [INFO] [stdout] Apr 26 20:20:25.111 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.111 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.111 DEBG[] send_async; method=GET uri=http://127.0.0.1:33773/__httpmock__/ping [INFO] [stdout] Apr 26 20:20:25.111 TRCE[] >> GET /__httpmock__/ping HTTP/1.1\r\nHost: 127.0.0.1:34631\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\nuser-agent: curl/7.79.1-DEV isahc/1.5.1\r\nContent-Length: 0\r\n\r\n [INFO] [stdout] Apr 26 20:20:25.111 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.111 TRCE[polling::epoll] add: epoll_fd=25, fd=40, ev=Event { key: 40, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.111 TRCE[polling] Poller::wait(_, Some(198.92178ms)) [INFO] [stdout] Apr 26 20:20:25.111 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.111 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.111 TRCE[polling::epoll] wait: epoll_fd=25, timeout=Some(198.92178ms) [INFO] [stdout] Apr 26 20:20:25.112 DEBG[] Connected to 127.0.0.1 (127.0.0.1) port 43837 (#0) [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] >> GET /__httpmock__/ping HTTP/1.1\r\nHost: 127.0.0.1:43837\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\nuser-agent: curl/7.79.1-DEV isahc/1.5.1\r\nContent-Length: 0\r\n\r\n [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] received 163 bytes [INFO] [stdout] Apr 26 20:20:25.112 TRCE[polling::epoll] add: epoll_fd=14, fd=33, ev=Event { key: 33, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.112 TRCE[polling] Poller::wait(_, Some(198.92294ms)) [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.112 TRCE[polling::epoll] wait: epoll_fd=14, timeout=Some(198.92294ms) [INFO] [stdout] Apr 26 20:20:25.112 TRCE[polling::epoll] modify: epoll_fd=14, fd=16, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.112 INFO[httpmock::server] Listening on 127.0.0.1:38145 [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.112 TRCE[polling::epoll] modify: epoll_fd=25, fd=27, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] Request.parse bytes=163 [INFO] [stdout] Apr 26 20:20:25.112 DEBG[] handler [INFO] [stdout] Apr 26 20:20:25.112 TRCE[] Request.parse Complete(163) [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.113 TRCE[polling] Poller::notify() [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] received message from agent handle [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.113 DEBG[] parsed 5 headers [INFO] [stdout] Apr 26 20:20:25.113 DEBG[] handler; id=0 [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.113 TRCE[polling::epoll] notify: epoll_fd=36, event_fd=37 [INFO] [stdout] Apr 26 20:20:25.113 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] received 163 bytes [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.113 TRCE[polling] Poller::wait(_, Some(0ns)) [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.113 TRCE[polling::epoll] wait: epoll_fd=36, timeout=Some(0ns) [INFO] [stdout] Apr 26 20:20:25.113 TRCE[polling::epoll] modify: epoll_fd=36, fd=38, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] Request.parse bytes=163 [INFO] [stdout] Apr 26 20:20:25.113 TRCE[polling::epoll] new events: epoll_fd=36, res=1 [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] Request.parse Complete(163) [INFO] [stdout] Apr 26 20:20:25.113 TRCE[polling::epoll] modify: epoll_fd=36, fd=37, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.113 DEBG[] parsed 5 headers [INFO] [stdout] Apr 26 20:20:25.113 DEBG[] Trying 127.0.0.1:33773... [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.113 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.113 DEBG[] Failed to set TCP_KEEPINTVL on fd 52 [INFO] [stdout] Apr 26 20:20:25.113 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.113 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/__httpmock__/ping", query: "", headers: [("host", "127.0.0.1:43837"), ("accept", "*/*"), ("accept-encoding", "deflate, gzip"), ("user-agent", "curl/7.79.1-DEV isahc/1.5.1"), ("content-length", "0")] } [INFO] [stdout] Apr 26 20:20:25.113 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/__httpmock__/ping", query: "", headers: [("host", "127.0.0.1:34631"), ("accept", "*/*"), ("accept-encoding", "deflate, gzip"), ("user-agent", "curl/7.79.1-DEV isahc/1.5.1"), ("content-length", "0")] } [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.114 DEBG[] Connected to 127.0.0.1 (127.0.0.1) port 33773 (#0) [INFO] [stdout] Apr 26 20:20:25.112 TRCE[polling::epoll] add: epoll_fd=49, fd=51, ev=Event { key: 18446744073709551615, readable: false, writable: false } [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.114 TRCE[polling::epoll] add: epoll_fd=49, fd=50, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.114 TRCE[polling::epoll] new: epoll_fd=49, event_fd=50, timer_fd=Some(51) [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.114 DEBG[] agent_thread; id=3 [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] >> GET /__httpmock__/ping HTTP/1.1\r\nHost: 127.0.0.1:33773\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\nuser-agent: curl/7.79.1-DEV isahc/1.5.1\r\nContent-Length: 0\r\n\r\n [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.114 TRCE[polling::epoll] add: epoll_fd=36, fd=52, ev=Event { key: 52, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.114 TRCE[polling] Poller::wait(_, Some(198.91553ms)) [INFO] [stdout] Apr 26 20:20:25.114 TRCE[polling::epoll] wait: epoll_fd=36, timeout=Some(198.91553ms) [INFO] [stdout] Apr 26 20:20:25.114 TRCE[polling::epoll] modify: epoll_fd=36, fd=38, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] -> agent_thread [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] received 163 bytes [INFO] [stdout] Apr 26 20:20:25.114 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.115 DEBG[] agent took 2.51774ms to start up [INFO] [stdout] Apr 26 20:20:25.115 DEBG[] send_async; method=GET uri=http://127.0.0.1:38145/__httpmock__/ping [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] Request.parse bytes=163 [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] Request.parse Complete(163) [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.115 DEBG[] handler [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.115 DEBG[] parsed 5 headers [INFO] [stdout] Apr 26 20:20:25.115 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.115 TRCE[polling] Poller::notify() [INFO] [stdout] Apr 26 20:20:25.115 TRCE[polling::epoll] notify: epoll_fd=49, event_fd=50 [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] received message from agent handle [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.115 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/__httpmock__/ping", query: "", headers: [("host", "127.0.0.1:33773"), ("accept", "*/*"), ("accept-encoding", "deflate, gzip"), ("user-agent", "curl/7.79.1-DEV isahc/1.5.1"), ("content-length", "0")] } [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.115 DEBG[] handler; id=0 [INFO] [stdout] Apr 26 20:20:25.115 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.115 INFO[httpmock::server] Listening on 127.0.0.1:42087 [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling] Poller::wait(_, Some(0ns)) [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] add: epoll_fd=61, fd=63, ev=Event { key: 18446744073709551615, readable: false, writable: false } [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] wait: epoll_fd=49, timeout=Some(0ns) [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] modify: epoll_fd=49, fd=51, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] add: epoll_fd=61, fd=62, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] new events: epoll_fd=49, res=1 [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] new: epoll_fd=61, event_fd=62, timer_fd=Some(63) [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] modify: epoll_fd=49, fd=50, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.116 DEBG[] agent_thread; id=4 [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] Server::encode status=200, body=None, req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] -> agent_thread [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.116 DEBG[] flushed 75 bytes [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] Server::encode status=200, body=None, req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] new events: epoll_fd=14, res=1 [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.116 TRCE[polling::epoll] modify: epoll_fd=14, fd=15, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] socket event socket=33 readable=true writable=false [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.117 DEBG[] Mark bundle as not supporting multiuse [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] << HTTP/1.1 200 OK\r\n [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] << content-length: 0\r\n [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.117 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] << date: Tue, 26 Apr 2022 20:20:25 GMT\r\n [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] << \r\n [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.118 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.118 DEBG[] Connection #0 to host 127.0.0.1 left intact [INFO] [stdout] Apr 26 20:20:25.119 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.119 TRCE[polling::epoll] remove: epoll_fd=14, fd=33 [INFO] [stdout] Apr 26 20:20:25.119 TRCE[] -- handler [INFO] [stdout] Apr 26 20:20:25.119 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.119 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.119 TRCE[] -- send_async [INFO] [stdout] Apr 26 20:20:25.119 TRCE[httpmock::server::web::handlers] Deleted all mocks [INFO] [stdout] Apr 26 20:20:25.119 TRCE[httpmock::server::web::handlers] Deleted request history [INFO] [stdout] Apr 26 20:20:25.119 DEBG[httpmock::server::web::handlers] Adding new mock with ID=0 [INFO] [stdout] Apr 26 20:20:25.119 DEBG[httpmock::server::web::handlers] Adding new mock with ID=1 [INFO] [stdout] Apr 26 20:20:25.120 DEBG[httpmock::server::web::handlers] Adding new mock with ID=2 [INFO] [stdout] Apr 26 20:20:25.120 DEBG[httpmock::server::web::handlers] Adding new mock with ID=3 [INFO] [stdout] Apr 26 20:20:25.120 TRCE[reqwest::blocking::wait] (ThreadId(4)) park without timeout [INFO] [stdout] Apr 26 20:20:25.120 DEBG[] flushed 75 bytes [INFO] [stdout] Apr 26 20:20:25.120 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.120 TRCE[polling::epoll] new events: epoll_fd=25, res=1 [INFO] [stdout] Apr 26 20:20:25.120 TRCE[polling::epoll] modify: epoll_fd=25, fd=26, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.120 TRCE[] socket event socket=40 readable=true writable=false [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.121 DEBG[] Mark bundle as not supporting multiuse [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] << HTTP/1.1 200 OK\r\n [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] << content-length: 0\r\n [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.121 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] << date: Tue, 26 Apr 2022 20:20:25 GMT\r\n [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.122 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] << \r\n [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.123 DEBG[] Connection #0 to host 127.0.0.1 left intact [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.123 TRCE[polling::epoll] remove: epoll_fd=25, fd=40 [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] -- handler [INFO] [stdout] Apr 26 20:20:25.123 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.123 WARN[rocket::config::config] 🔧 Configured for debug. [INFO] [stdout] Apr 26 20:20:25.124 WARN[rocket::config::config] address: 127.0.0.1 [INFO] [stdout] Apr 26 20:20:25.124 WARN[rocket::config::config] port: 8000 [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.124 WARN[rocket::config::config] workers: 56 [INFO] [stdout] Apr 26 20:20:25.124 WARN[rocket::config::config] ident: Rocket [INFO] [stdout] Apr 26 20:20:25.124 WARN[rocket::config::config] keep-alive: 5s [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] -- send_async [INFO] [stdout] Apr 26 20:20:25.116 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] Server::encode status=200, body=None, req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.124 TRCE[httpmock::server::web::handlers] Deleted all mocks [INFO] [stdout] Apr 26 20:20:25.124 DEBG[] flushed 75 bytes [INFO] [stdout] Apr 26 20:20:25.124 TRCE[polling::epoll] new events: epoll_fd=36, res=1 [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.124 TRCE[httpmock::server::web::handlers] Deleted request history [INFO] [stdout] Apr 26 20:20:25.124 TRCE[polling::epoll] modify: epoll_fd=36, fd=37, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] socket event socket=52 readable=true writable=false [INFO] [stdout] Apr 26 20:20:25.124 DEBG[httpmock::server::web::handlers] Adding new mock with ID=0 [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.124 DEBG[] Mark bundle as not supporting multiuse [INFO] [stdout] Apr 26 20:20:25.124 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] << HTTP/1.1 200 OK\r\n [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[reqwest::blocking::wait] (ThreadId(3)) park without timeout [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.124 WARN[rocket::config::config] limits: bytes = 8KiB, data-form = 2MiB, file = 1MiB, form = 32KiB, json = 1MiB, msgpack = 1MiB, string = 8KiB [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.125 WARN[rocket::config::config] tls: disabled [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.125 WARN[rocket::config::config] temp dir: /tmp [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] << content-length: 0\r\n [INFO] [stdout] Apr 26 20:20:25.125 WARN[rocket::config::config] log level: normal [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.125 WARN[rocket::config::config] cli colors: true [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.125 WARN[rocket::config::config] shutdown: ctrlc = true, force = true, signals = [SIGTERM], grace = 2s, mercy = 3s [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] << date: Tue, 26 Apr 2022 20:20:25 GMT\r\n [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.125 WARN[rocket::rocket] 🛰 Routes: [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.125 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.126 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] (status) GET /status [INFO] [stdout] Apr 26 20:20:25.126 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] GET /openapi.json [INFO] [stdout] Apr 26 20:20:25.126 TRCE[] << \r\n [INFO] [stdout] Apr 26 20:20:25.126 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:25.126 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.126 DEBG[] Connection #0 to host 127.0.0.1 left intact [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] (list) GET /crawl//list [INFO] [stdout] Apr 26 20:20:25.126 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] (count) GET /crawl//count [INFO] [stdout] Apr 26 20:20:25.126 TRCE[polling::epoll] remove: epoll_fd=36, fd=52 [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] GET /swagger/ [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] GET /swagger/index.html [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] GET /swagger/swagger-ui.css [INFO] [stdout] Apr 26 20:20:25.126 TRCE[] -- handler [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] GET /swagger/oauth2-redirect.html [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] GET /swagger/swagger-ui-bundle.js [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] GET /swagger/swagger-ui-config.json [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::rocket] GET /swagger/swagger-ui-standalone-preset.js [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::fairing::fairings] 📡 Fairings: [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::fairing::fairings] BetterLogging (request, response) [INFO] [stdout] Apr 26 20:20:25.126 WARN[rocket::fairing::fairings] Shield (liftoff, response, singleton) [INFO] [stdout] Apr 26 20:20:25.128 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.128 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.128 TRCE[] -- send_async [INFO] [stdout] Apr 26 20:20:25.128 TRCE[httpmock::server::web::handlers] Deleted all mocks [INFO] [stdout] Apr 26 20:20:25.128 TRCE[httpmock::server::web::handlers] Deleted request history [INFO] [stdout] Apr 26 20:20:25.129 DEBG[httpmock::server::web::handlers] Adding new mock with ID=0 [INFO] [stdout] Apr 26 20:20:25.129 TRCE[reqwest::blocking::wait] (ThreadId(6)) park without timeout [INFO] [stdout] Apr 26 20:20:25.176 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.176 DEBG[] Trying 127.0.0.1:38145... [INFO] [stdout] Apr 26 20:20:25.176 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.177 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.176 DEBG[] agent took 60.967035ms to start up [INFO] [stdout] Apr 26 20:20:25.177 INFO[rocket::shield::shield] 🛡️ Shield: [INFO] [stdout] Apr 26 20:20:25.176 TRCE[reqwest::blocking::client] (ThreadId(73)) start runtime::block_on [INFO] [stdout] Apr 26 20:20:25.177 DEBG[] send_async; method=GET uri=http://127.0.0.1:42087/__httpmock__/ping [INFO] [stdout] Apr 26 20:20:25.177 INFO[rocket::shield::shield] X-Content-Type-Options: nosniff [INFO] [stdout] Apr 26 20:20:25.178 INFO[rocket::shield::shield] Permissions-Policy: interest-cohort=() [INFO] [stdout] Apr 26 20:20:25.178 INFO[rocket::shield::shield] X-Frame-Options: SAMEORIGIN [INFO] [stdout] Apr 26 20:20:25.178 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.178 WARN[rocket::rocket] 🚀 Rocket has launched from http://127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.177 TRCE[reqwest::blocking::client] (ThreadId(75)) start runtime::block_on [INFO] [stdout] Apr 26 20:20:25.178 DEBG[] handler [INFO] [stdout] Apr 26 20:20:25.178 TRCE[polling] Poller::notify() [INFO] [stdout] Apr 26 20:20:25.178 TRCE[] received message from agent handle [INFO] [stdout] Apr 26 20:20:25.178 TRCE[polling::epoll] notify: epoll_fd=61, event_fd=62 [INFO] [stdout] Apr 26 20:20:25.178 DEBG[] Failed to set TCP_KEEPINTVL on fd 64 [INFO] [stdout] Apr 26 20:20:25.178 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.178 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.181 DEBG[] handler; id=0 [INFO] [stdout] Apr 26 20:20:25.181 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.181 TRCE[polling] Poller::wait(_, Some(0ns)) [INFO] [stdout] Apr 26 20:20:25.181 TRCE[polling::epoll] wait: epoll_fd=61, timeout=Some(0ns) [INFO] [stdout] Apr 26 20:20:25.181 TRCE[polling::epoll] modify: epoll_fd=61, fd=63, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.181 TRCE[polling::epoll] new events: epoll_fd=61, res=1 [INFO] [stdout] Apr 26 20:20:25.181 TRCE[polling::epoll] modify: epoll_fd=61, fd=62, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.178 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.177 TRCE[reqwest::blocking::client] (ThreadId(74)) start runtime::block_on [INFO] [stdout] Apr 26 20:20:25.181 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.181 DEBG[] Trying 127.0.0.1:42087... [INFO] [stdout] Apr 26 20:20:25.181 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.181 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.182 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.182 DEBG[] Failed to set TCP_KEEPINTVL on fd 81 [INFO] [stdout] Apr 26 20:20:25.184 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.184 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.184 DEBG[] Connected to 127.0.0.1 (127.0.0.1) port 42087 (#0) [INFO] [stdout] Apr 26 20:20:25.184 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.184 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] >> GET /__httpmock__/ping HTTP/1.1\r\nHost: 127.0.0.1:42087\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\nuser-agent: curl/7.79.1-DEV isahc/1.5.1\r\nContent-Length: 0\r\n\r\n [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.185 TRCE[polling::epoll] add: epoll_fd=61, fd=81, ev=Event { key: 81, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.185 TRCE[polling] Poller::wait(_, Some(199.91003ms)) [INFO] [stdout] Apr 26 20:20:25.185 TRCE[polling::epoll] wait: epoll_fd=61, timeout=Some(199.91003ms) [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.185 DEBG[] Connected to 127.0.0.1 (127.0.0.1) port 38145 (#0) [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] >> GET /__httpmock__/ping HTTP/1.1\r\nHost: 127.0.0.1:38145\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\nuser-agent: curl/7.79.1-DEV isahc/1.5.1\r\nContent-Length: 0\r\n\r\n [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.185 TRCE[polling::epoll] add: epoll_fd=49, fd=64, ev=Event { key: 64, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.185 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.185 TRCE[polling::epoll] modify: epoll_fd=61, fd=63, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.186 TRCE[polling] Poller::wait(_, Some(196.888ms)) [INFO] [stdout] Apr 26 20:20:25.186 TRCE[polling::epoll] wait: epoll_fd=49, timeout=Some(196.888ms) [INFO] [stdout] Apr 26 20:20:25.186 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.186 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.186 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.186 TRCE[polling::epoll] modify: epoll_fd=49, fd=51, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.186 TRCE[] received 163 bytes [INFO] [stdout] Apr 26 20:20:25.186 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.187 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.187 TRCE[] Request.parse bytes=163 [INFO] [stdout] Apr 26 20:20:25.187 TRCE[] Request.parse Complete(163) [INFO] [stdout] Apr 26 20:20:25.187 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.187 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.187 DEBG[] parsed 5 headers [INFO] [stdout] Apr 26 20:20:25.188 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.188 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/__httpmock__/ping", query: "", headers: [("host", "127.0.0.1:38145"), ("accept", "*/*"), ("accept-encoding", "deflate, gzip"), ("user-agent", "curl/7.79.1-DEV isahc/1.5.1"), ("content-length", "0")] } [INFO] [stdout] Apr 26 20:20:25.188 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.188 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.188 TRCE[] Server::encode status=200, body=None, req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.188 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.188 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.186 TRCE[] received 163 bytes [INFO] [stdout] Apr 26 20:20:25.189 TRCE[polling::epoll] new events: epoll_fd=49, res=1 [INFO] [stdout] Apr 26 20:20:25.189 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.189 TRCE[polling::epoll] modify: epoll_fd=49, fd=50, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.190 TRCE[] socket event socket=64 readable=true writable=false [INFO] [stdout] Apr 26 20:20:25.190 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.190 DEBG[] Mark bundle as not supporting multiuse [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] << HTTP/1.1 200 OK\r\n [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] << content-length: 0\r\n [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.191 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] << date: Tue, 26 Apr 2022 20:20:25 GMT\r\n [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.192 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.193 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.193 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.193 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.193 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.189 DEBG[] flushed 75 bytes [INFO] [stdout] Apr 26 20:20:25.190 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.193 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.193 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.193 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.194 TRCE[] Request.parse bytes=163 [INFO] [stdout] Apr 26 20:20:25.194 TRCE[] Request.parse Complete(163) [INFO] [stdout] Apr 26 20:20:25.194 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.194 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.194 DEBG[] parsed 5 headers [INFO] [stdout] Apr 26 20:20:25.194 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.195 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/__httpmock__/ping", query: "", headers: [("host", "127.0.0.1:42087"), ("accept", "*/*"), ("accept-encoding", "deflate, gzip"), ("user-agent", "curl/7.79.1-DEV isahc/1.5.1"), ("content-length", "0")] } [INFO] [stdout] Apr 26 20:20:25.195 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.195 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.195 TRCE[] Server::encode status=200, body=None, req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.193 TRCE[] << \r\n [INFO] [stdout] Apr 26 20:20:25.195 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.195 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.195 TRCE[polling::epoll] new events: epoll_fd=61, res=1 [INFO] [stdout] Apr 26 20:20:25.196 TRCE[polling::epoll] modify: epoll_fd=61, fd=62, ev=Event { key: 18446744073709551615, readable: true, writable: false } [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] socket event socket=81 readable=true writable=false [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.196 DEBG[] Mark bundle as not supporting multiuse [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] << HTTP/1.1 200 OK\r\n [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.196 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] << content-length: 0\r\n [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] << date: Tue, 26 Apr 2022 20:20:25 GMT\r\n [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] -> header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] <- header [INFO] [stdout] Apr 26 20:20:25.197 TRCE[] -- header [INFO] [stdout] Apr 26 20:20:25.198 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.198 TRCE[] << \r\n [INFO] [stdout] Apr 26 20:20:25.198 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.195 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.198 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.198 TRCE[reqwest::blocking::wait] (ThreadId(6)) park timeout 29.99999143s [INFO] [stdout] Apr 26 20:20:25.198 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.198 DEBG[] Connection #0 to host 127.0.0.1 left intact [INFO] [stdout] Apr 26 20:20:25.198 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.198 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.198 TRCE[reqwest::blocking::wait] (ThreadId(3)) park timeout 29.999993691s [INFO] [stdout] Apr 26 20:20:25.198 TRCE[] -> handler [INFO] [stdout] Apr 26 20:20:25.198 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:8000/ [INFO] [stdout] Apr 26 20:20:25.198 DEBG[] Connection #0 to host 127.0.0.1 left intact [INFO] [stdout] Apr 26 20:20:25.198 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(8000)) [INFO] [stdout] Apr 26 20:20:25.199 TRCE[polling::epoll] remove: epoll_fd=61, fd=81 [INFO] [stdout] Apr 26 20:20:25.198 DEBG[] flushed 75 bytes [INFO] [stdout] Apr 26 20:20:25.198 TRCE[] <- handler [INFO] [stdout] Apr 26 20:20:25.199 DEBG[] connecting to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] -- handler [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.199 TRCE[polling::epoll] remove: epoll_fd=49, fd=64 [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.199 DEBG[] connected to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] -- send_async [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] -- handler [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] client handshake Http1 [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] -> send_async [INFO] [stdout] Apr 26 20:20:25.199 TRCE[httpmock::server::web::handlers] Deleted all mocks [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] <- send_async [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] handshake complete, spawning background dispatcher task [INFO] [stdout] Apr 26 20:20:25.199 TRCE[] -- send_async [INFO] [stdout] Apr 26 20:20:25.199 TRCE[httpmock::server::web::handlers] Deleted request history [INFO] [stdout] Apr 26 20:20:25.200 TRCE[httpmock::server::web::handlers] Deleted all mocks [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.200 DEBG[httpmock::server::web::handlers] Adding new mock with ID=0 [INFO] [stdout] Apr 26 20:20:25.200 TRCE[httpmock::server::web::handlers] Deleted request history [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] checkout dropped for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.200 DEBG[httpmock::server::web::handlers] Adding new mock with ID=0 [INFO] [stdout] Apr 26 20:20:25.200 DEBG[httpmock::server::web::handlers] Adding new mock with ID=1 [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.200 DEBG[httpmock::server::web::handlers] Adding new mock with ID=2 [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.200 DEBG[httpmock::server::web::handlers] Adding new mock with ID=3 [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.200 DEBG[httpmock::server::web::handlers] Adding new mock with ID=4 [INFO] [stdout] Apr 26 20:20:25.200 DEBG[] flushed 97 bytes [INFO] [stdout] Apr 26 20:20:25.200 DEBG[httpmock::server::web::handlers] Adding new mock with ID=5 [INFO] [stdout] Apr 26 20:20:25.200 TRCE[reqwest::blocking::wait] (ThreadId(5)) park without timeout [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.200 TRCE[] received 97 bytes [INFO] [stdout] Apr 26 20:20:25.201 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.201 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.201 TRCE[reqwest::blocking::client] (ThreadId(76)) start runtime::block_on [INFO] [stdout] Apr 26 20:20:25.201 TRCE[] Request.parse bytes=97 [INFO] [stdout] Apr 26 20:20:25.201 TRCE[] Request.parse Complete(97) [INFO] [stdout] Apr 26 20:20:25.201 TRCE[reqwest::blocking::wait] (ThreadId(2)) park without timeout [INFO] [stdout] Apr 26 20:20:25.201 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.201 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.201 DEBG[] parsed 2 headers [INFO] [stdout] Apr 26 20:20:25.201 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.201 TRCE[] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.201 INFO[mikes_crawler::better_logging] Received request: /crawl/http%3A%2F%2F127.0.0.1%3A34631%2Fstart, REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.202 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.202 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.202 INFO[rocket::server] GET /crawl/http%3A%2F%2F127.0.0.1%3A34631%2Fstart: [INFO] [stdout] Apr 26 20:20:25.202 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.202 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:8000/ [INFO] [stdout] Apr 26 20:20:25.202 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:8000/ [INFO] [stdout] Apr 26 20:20:25.202 INFO[rocket::server] Matched: (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:25.202 TRCE[reqwest::blocking::wait] (ThreadId(4)) park timeout 29.99999381s [INFO] [stdout] Apr 26 20:20:25.206 TRCE[reqwest::blocking::client] (ThreadId(77)) start runtime::block_on [INFO] [stdout] Apr 26 20:20:25.214 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.214 TRCE[reqwest::blocking::wait] (ThreadId(2)) park timeout 29.99999068s [INFO] [stdout] Apr 26 20:20:25.215 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(8000)) [INFO] [stdout] Apr 26 20:20:25.215 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:34631) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.215 DEBG[] connecting to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.215 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:34631/, REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.216 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.220 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:8000/ [INFO] [stdout] Apr 26 20:20:25.216 DEBG[] connected to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.220 TRCE[] client handshake Http1 [INFO] [stdout] Apr 26 20:20:25.221 TRCE[] handshake complete, spawning background dispatcher task [INFO] [stdout] Apr 26 20:20:25.221 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.221 TRCE[] checkout dropped for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.221 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.221 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.222 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.222 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.222 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.222 DEBG[] flushed 97 bytes [INFO] [stdout] Apr 26 20:20:25.222 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.218 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.223 TRCE[] received 97 bytes [INFO] [stdout] Apr 26 20:20:25.223 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.224 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.224 TRCE[] Request.parse bytes=97 [INFO] [stdout] Apr 26 20:20:25.224 TRCE[] Request.parse Complete(97) [INFO] [stdout] Apr 26 20:20:25.224 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.224 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.224 DEBG[] parsed 2 headers [INFO] [stdout] Apr 26 20:20:25.225 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.225 TRCE[] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.216 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(34631)) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.225 INFO[mikes_crawler::better_logging] Received request: /crawl/http%3A%2F%2F127.0.0.1%3A43837%2Fstart, REQ: FraR [INFO] [stdout] Apr 26 20:20:25.225 DEBG[] connecting to 127.0.0.1:34631 , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.225 INFO[rocket::server] GET /crawl/http%3A%2F%2F127.0.0.1%3A43837%2Fstart: [INFO] [stdout] Apr 26 20:20:25.226 DEBG[] connected to 127.0.0.1:34631 , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.216 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(8000)) [INFO] [stdout] Apr 26 20:20:25.226 INFO[rocket::server] Matched: (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:25.226 DEBG[] connecting to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.226 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.227 TRCE[reqwest::blocking::wait] (ThreadId(5)) park timeout 29.9999923s [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:43837) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.227 DEBG[] connected to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.227 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:43837/, REQ: FraR [INFO] [stdout] Apr 26 20:20:25.226 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] client handshake Http1 [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] handshake complete, spawning background dispatcher task [INFO] [stdout] Apr 26 20:20:25.227 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:8000/ [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(43837)) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(8000)) [INFO] [stdout] Apr 26 20:20:25.227 TRCE[] checkout dropped for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.227 DEBG[] connecting to 127.0.0.1:43837 , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.228 DEBG[] connecting to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.228 DEBG[] connected to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] client handshake Http1 [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] handshake complete, spawning background dispatcher task [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.228 DEBG[] flushed 97 bytes [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] checkout dropped for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.228 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.229 DEBG[] connected to 127.0.0.1:43837 , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] client handshake Http1 , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.229 DEBG[] flushed 97 bytes [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] handshake complete, spawning background dispatcher task , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] checkout dropped for ("http", 127.0.0.1:43837) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.220 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(8000)) [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.230 DEBG[] connecting to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.230 DEBG[] flushed 90 bytes [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.230 DEBG[] connected to 127.0.0.1:8000 [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] received 90 bytes [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] Request.parse bytes=90 [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] client handshake Http1 [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] Request.parse Complete(90) [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] handshake complete, spawning background dispatcher task [INFO] [stdout] Apr 26 20:20:25.230 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.231 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.231 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.231 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/robots.txt", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:43837")] } [INFO] [stdout] Apr 26 20:20:25.231 TRCE[] checkout dropped for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.231 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.231 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.231 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.232 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.233 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.234 DEBG[] flushed 97 bytes [INFO] [stdout] Apr 26 20:20:25.234 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.235 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.235 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.235 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.235 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.236 DEBG[httpmock::server::web::handlers] Matched mock with id=1 to the following request: HttpMockRequest { [INFO] [stdout] path: "/robots.txt", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:43837", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] Server::encode status=200, body=Some(Known(36)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] buffer.queue self.len=102 buf.len=36 [INFO] [stdout] Apr 26 20:20:25.236 DEBG[] flushed 138 bytes [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] received 138 bytes [INFO] [stdout] Apr 26 20:20:25.236 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.237 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.237 TRCE[] Response.parse bytes=138 [INFO] [stdout] Apr 26 20:20:25.237 TRCE[] Response.parse Complete(102) [INFO] [stdout] Apr 26 20:20:25.231 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.237 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.237 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.229 TRCE[] client handshake Http1 , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.238 TRCE[] handshake complete, spawning background dispatcher task , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.238 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.238 TRCE[] checkout dropped for ("http", 127.0.0.1:34631) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.238 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.238 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.237 TRCE[] received 97 bytes [INFO] [stdout] Apr 26 20:20:25.239 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.239 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.239 TRCE[] Request.parse bytes=97 [INFO] [stdout] Apr 26 20:20:25.239 TRCE[] Request.parse Complete(97) [INFO] [stdout] Apr 26 20:20:25.240 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.240 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.240 DEBG[] parsed 2 headers [INFO] [stdout] Apr 26 20:20:25.241 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.241 TRCE[] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.242 INFO[mikes_crawler::better_logging] Received request: /crawl/http%3A%2F%2F127.0.0.1%3A42087%2Fstart, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.238 DEBG[] incoming body is content-length (36 bytes) [INFO] [stdout] Apr 26 20:20:25.242 TRCE[] decode; state=Length(36) [INFO] [stdout] Apr 26 20:20:25.242 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.242 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.242 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.242 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.231 TRCE[] received 97 bytes [INFO] [stdout] Apr 26 20:20:25.242 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.243 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.242 INFO[rocket::server] GET /crawl/http%3A%2F%2F127.0.0.1%3A42087%2Fstart: [INFO] [stdout] Apr 26 20:20:25.243 INFO[rocket::server] Matched: (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:25.243 TRCE[] Request.parse bytes=97 [INFO] [stdout] Apr 26 20:20:25.243 TRCE[] Request.parse Complete(97) [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.243 TRCE[] put; add idle connection for ("http", 127.0.0.1:43837) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.244 DEBG[] parsed 2 headers [INFO] [stdout] Apr 26 20:20:25.230 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] received 97 bytes [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] Request.parse bytes=97 [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] Request.parse Complete(97) [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.244 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.244 DEBG[] parsed 2 headers [INFO] [stdout] Apr 26 20:20:25.244 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.245 TRCE[] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.245 INFO[mikes_crawler::better_logging] Received request: /crawl/http%3A%2F%2F127.0.0.1%3A33773%2Fstart, REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.245 INFO[rocket::server] GET /crawl/http%3A%2F%2F127.0.0.1%3A33773%2Fstart: [INFO] [stdout] Apr 26 20:20:25.238 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.244 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.245 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.245 TRCE[] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.246 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.246 INFO[mikes_crawler::better_logging] Received request: /crawl/http%3A%2F%2F127.0.0.1%3A38145%2Fstart, REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.246 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.246 INFO[rocket::server] GET /crawl/http%3A%2F%2F127.0.0.1%3A38145%2Fstart: [INFO] [stdout] Apr 26 20:20:25.249 INFO[rocket::server] Matched: (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:25.246 DEBG[] flushed 90 bytes [INFO] [stdout] Apr 26 20:20:25.250 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.245 INFO[rocket::server] Matched: (crawl) GET /crawl/ [INFO] [stdout] Apr 26 20:20:25.246 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.250 TRCE[] received 90 bytes [INFO] [stdout] Apr 26 20:20:25.250 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.250 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.250 TRCE[] Request.parse bytes=90 [INFO] [stdout] Apr 26 20:20:25.250 TRCE[] Request.parse Complete(90) [INFO] [stdout] Apr 26 20:20:25.251 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.251 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.251 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.251 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.251 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/robots.txt", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:34631")] } [INFO] [stdout] Apr 26 20:20:25.252 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.252 DEBG[httpmock::server::web::handlers] Could not match any mock to the following request: HttpMockRequest { [INFO] [stdout] path: "/robots.txt", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:34631", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.252 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.252 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] Server::encode status=404, body=Some(Known(53)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] buffer.queue self.len=115 buf.len=53 [INFO] [stdout] Apr 26 20:20:25.253 DEBG[] flushed 168 bytes [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] received 168 bytes [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.253 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.254 TRCE[] Response.parse bytes=168 [INFO] [stdout] Apr 26 20:20:25.254 TRCE[] Response.parse Complete(115) [INFO] [stdout] Apr 26 20:20:25.254 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.254 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.254 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.254 DEBG[] incoming body is content-length (53 bytes) [INFO] [stdout] Apr 26 20:20:25.254 TRCE[] decode; state=Length(53) [INFO] [stdout] Apr 26 20:20:25.254 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.254 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.254 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.254 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.244 DEBG[] pooling idle connection for ("http", 127.0.0.1:43837) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.255 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.255 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:42087/, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.255 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(42087)) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.255 DEBG[] connecting to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.255 DEBG[] connected to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] client handshake Http1 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] handshake complete, spawning background dispatcher task , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] checkout dropped for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.256 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.257 DEBG[] flushed 90 bytes [INFO] [stdout] Apr 26 20:20:25.257 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.257 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.257 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:38145/, REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.257 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(38145)) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.257 DEBG[] connecting to 127.0.0.1:38145 , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.257 DEBG[] connected to 127.0.0.1:38145 , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.257 TRCE[] client handshake Http1 , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] handshake complete, spawning background dispatcher task , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] checkout dropped for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] received 90 bytes [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Request.parse bytes=90 [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Request.parse Complete(90) [INFO] [stdout] Apr 26 20:20:25.258 DEBG[] flushed 90 bytes [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] received 90 bytes [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] put; add idle connection for ("http", 127.0.0.1:34631) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.258 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.258 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Request.parse bytes=90 [INFO] [stdout] Apr 26 20:20:25.258 DEBG[] pooling idle connection for ("http", 127.0.0.1:34631) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.258 TRCE[] Request.parse Complete(90) [INFO] [stdout] Apr 26 20:20:25.258 DEBG[reqwest::async_impl::client] response '404 Not Found' for http://127.0.0.1:34631/robots.txt, REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.259 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/robots.txt", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:42087")] } [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.259 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.259 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.259 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.259 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] take? ("http", 127.0.0.1:34631): expiration = Some(90s) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.259 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/robots.txt", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:38145")] } [INFO] [stdout] Apr 26 20:20:25.259 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.259 DEBG[] reuse idle connection for ("http", 127.0.0.1:34631) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.259 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.259 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.259 DEBG[httpmock::server::web::handlers] Could not match any mock to the following request: HttpMockRequest { [INFO] [stdout] path: "/robots.txt", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:38145", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.259 DEBG[] flushed 85 bytes [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.259 TRCE[] received 85 bytes [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] Server::encode status=404, body=Some(Known(53)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] Request.parse bytes=85 [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] Request.parse Complete(85) [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] buffer.queue self.len=115 buf.len=53 [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.260 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.260 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.260 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.260 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:33773) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.260 DEBG[httpmock::server::web::handlers] Could not match any mock to the following request: HttpMockRequest { [INFO] [stdout] path: "/robots.txt", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:42087", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.260 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:43837/robots.txt, REQ: FraR [INFO] [stdout] Apr 26 20:20:25.260 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] received 168 bytes [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] Response.parse bytes=168 [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] Response.parse Complete(115) [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] take? ("http", 127.0.0.1:43837): expiration = Some(90s) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.261 DEBG[] reuse idle connection for ("http", 127.0.0.1:43837) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] idle interval checking for expired [INFO] [stdout] Apr 26 20:20:25.261 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.261 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.262 DEBG[] incoming body is content-length (53 bytes) [INFO] [stdout] Apr 26 20:20:25.262 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:33773/, REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] decode; state=Length(53) [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] Server::encode status=404, body=Some(Known(53)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.262 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.263 TRCE[] put; add idle connection for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.263 DEBG[] pooling idle connection for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.263 DEBG[reqwest::async_impl::client] response '404 Not Found' for http://127.0.0.1:38145/robots.txt, REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.263 TRCE[] take? ("http", 127.0.0.1:38145): expiration = Some(90s) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.263 DEBG[] reuse idle connection for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.264 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.264 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.264 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.264 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.264 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.264 DEBG[] flushed 85 bytes [INFO] [stdout] Apr 26 20:20:25.260 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/start", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:34631")] } [INFO] [stdout] Apr 26 20:20:25.264 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.264 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.264 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.265 DEBG[] flushed 85 bytes [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.265 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.265 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.260 DEBG[] flushed 168 bytes [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] received 85 bytes [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] Request.parse bytes=85 [INFO] [stdout] Apr 26 20:20:25.266 TRCE[] Request.parse Complete(85) [INFO] [stdout] Apr 26 20:20:25.266 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.266 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.266 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.266 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.266 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/start", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:38145")] } [INFO] [stdout] Apr 26 20:20:25.266 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.266 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.267 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.267 DEBG[httpmock::server::web::handlers] Matched mock with id=0 to the following request: HttpMockRequest { [INFO] [stdout] path: "/start", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:38145", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.267 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.267 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.267 TRCE[] Server::encode status=301, body=None, req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.267 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.267 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.267 DEBG[] flushed 107 bytes [INFO] [stdout] Apr 26 20:20:25.268 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.268 TRCE[] received 85 bytes [INFO] [stdout] Apr 26 20:20:25.268 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.268 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.268 TRCE[] Request.parse bytes=85 [INFO] [stdout] Apr 26 20:20:25.268 TRCE[] Request.parse Complete(85) [INFO] [stdout] Apr 26 20:20:25.268 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.268 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.268 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.268 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.268 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/start", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:43837")] } [INFO] [stdout] Apr 26 20:20:25.269 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.269 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.269 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.269 DEBG[httpmock::server::web::handlers] Matched mock with id=0 to the following request: HttpMockRequest { [INFO] [stdout] path: "/start", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:43837", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.269 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.269 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.269 TRCE[] Server::encode status=200, body=Some(Known(205)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.269 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.265 DEBG[httpmock::server::web::handlers] Matched mock with id=0 to the following request: HttpMockRequest { [INFO] [stdout] path: "/start", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:34631", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.269 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.265 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(33773)) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.269 TRCE[] buffer.queue self.len=102 buf.len=205 [INFO] [stdout] Apr 26 20:20:25.267 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.269 DEBG[] flushed 307 bytes [INFO] [stdout] Apr 26 20:20:25.269 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.262 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] received 107 bytes [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] Server::encode status=200, body=Some(Known(4)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] Response.parse bytes=107 [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] buffer.queue self.len=114 buf.len=4 [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] Response.parse Complete(107) [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.270 DEBG[] connecting to 127.0.0.1:33773 , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.270 DEBG[] flushed 118 bytes [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.270 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.270 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] buffer.queue self.len=115 buf.len=53 [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] received 118 bytes [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.270 DEBG[] flushed 168 bytes [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] received 168 bytes [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] received 307 bytes [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] Response.parse bytes=118 [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] Response.parse Complete(114) [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] Response.parse bytes=168 [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] Response.parse Complete(115) [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.271 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.271 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.271 DEBG[] incoming body is content-length (4 bytes) [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] Response.parse bytes=307 [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] decode; state=Length(4) [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] Response.parse Complete(102) [INFO] [stdout] Apr 26 20:20:25.271 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.271 DEBG[] incoming body is content-length (53 bytes) [INFO] [stdout] Apr 26 20:20:25.271 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.271 DEBG[] connected to 127.0.0.1:33773 , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.272 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.272 DEBG[] incoming body is content-length (205 bytes) [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] client handshake Http1 , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] decode; state=Length(205) [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] handshake complete, spawning background dispatcher task , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.272 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] checkout dropped for ("http", 127.0.0.1:33773) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] decode; state=Length(53) [INFO] [stdout] Apr 26 20:20:25.272 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] put; add idle connection for ("http", 127.0.0.1:34631) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.273 DEBG[] pooling idle connection for ("http", 127.0.0.1:34631) , REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.273 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:34631/start, REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.273 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.273 TRCE[] put; add idle connection for ("http", 127.0.0.1:43837) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.273 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.270 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.273 INFO[mikes_crawler::crawler] Got non html response containing: x-application/something, REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.273 DEBG[] pooling idle connection for ("http", 127.0.0.1:43837) , REQ: FraR [INFO] [stdout] Apr 26 20:20:25.273 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:43837/start, REQ: FraR [INFO] [stdout] Apr 26 20:20:25.273 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.273 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:25.273 INFO[mikes_crawler::crawler] Got body to process from http://127.0.0.1:43837/start containing 205 chars, REQ: FraR [INFO] [stdout] Apr 26 20:20:25.273 TRCE[] put; add idle connection for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.273 DEBG[] pooling idle connection for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.273 INFO[mikes_crawler::better_logging] Completed request /crawl/http%3A%2F%2F127.0.0.1%3A34631%2Fstart with status 200 OK in 0.071s, REQ: 9Oy4 [INFO] [stdout] Apr 26 20:20:25.273 DEBG[reqwest::async_impl::client] redirect policy disallowed redirection to 'http://127.0.0.1:38145/next', REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.273 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.273 DEBG[reqwest::async_impl::client] response '301 Moved Permanently' for http://127.0.0.1:38145/start, REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.273 INFO[rocket::server] Response succeeded. [INFO] [stdout] Apr 26 20:20:25.273 TRCE[] put; add idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.273 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.273 INFO[mikes_crawler::crawler] Got redirect from http://127.0.0.1:38145/start to http://127.0.0.1:38145/next, REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.273 DEBG[] pooling idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.274 DEBG[reqwest::async_impl::client] response '404 Not Found' for http://127.0.0.1:42087/robots.txt, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] Server::encode status=200, body=Some(Unknown), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] take? ("http", 127.0.0.1:38145): expiration = Some(90s) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] sized write, len = 85 [INFO] [stdout] Apr 26 20:20:25.274 DEBG[] reuse idle connection for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] take? ("http", 127.0.0.1:42087): expiration = Some(90s) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] buffer.queue self.len=242 buf.len=85 [INFO] [stdout] Apr 26 20:20:25.274 DEBG[] reuse idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] no more write body allowed, user body is_end_stream = false [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.274 DEBG[] flushed 327 bytes [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] received 327 bytes [INFO] [stdout] Apr 26 20:20:25.274 DEBG[] flushed 84 bytes [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.272 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.275 DEBG[] flushed 85 bytes [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.275 DEBG[] flushed 90 bytes [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] received 90 bytes [INFO] [stdout] Apr 26 20:20:25.275 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] Request.parse bytes=90 [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] received 84 bytes [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.274 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] Request.parse Complete(90) [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] Response.parse bytes=327 [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] Response.parse Complete(242) [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.275 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.276 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.276 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/robots.txt", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:33773")] } [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.275 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.276 DEBG[] parsed 8 headers [INFO] [stdout] Apr 26 20:20:25.276 DEBG[] incoming body is content-length (85 bytes) [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] Request.parse bytes=84 [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] Request.parse Complete(84) [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] decode; state=Length(85) [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.276 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.276 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.276 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.276 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/next", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:38145")] } [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] put; add idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.276 DEBG[] pooling idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.276 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.276 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:8000/crawl/http%3A%2F%2F127.0.0.1%3A34631%2Fstart [INFO] [stdout] Apr 26 20:20:25.276 DEBG[httpmock::server::web::handlers] Could not match any mock to the following request: HttpMockRequest { [INFO] [stdout] path: "/next", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:38145", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.277 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[reqwest::blocking::client] closing runtime thread (ThreadId(74)) [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] Server::encode status=404, body=Some(Known(53)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.276 TRCE[] received 85 bytes [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[reqwest::blocking::client] signaled close for runtime thread (ThreadId(74)) [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] buffer.queue self.len=115 buf.len=53 [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] Request.parse bytes=85 [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] Request.parse Complete(85) [INFO] [stdout] Apr 26 20:20:25.277 DEBG[] flushed 168 bytes [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.277 TRCE[reqwest::blocking::client] (ThreadId(74)) Receiver is shutdown [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.276 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] received 168 bytes [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.275 INFO[mikes_crawler::better_logging] Completed request /crawl/http%3A%2F%2F127.0.0.1%3A43837%2Fstart with status 200 OK in 0.050s, REQ: FraR [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.277 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.277 DEBG[httpmock::server::web::handlers] Could not match any mock to the following request: HttpMockRequest { [INFO] [stdout] path: "/robots.txt", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:33773", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.277 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] Response.parse bytes=168 [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] Response.parse Complete(115) [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.277 INFO[rocket::server] Response succeeded. [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] Server::encode status=404, body=Some(Known(53)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.277 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/start", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:42087")] } [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.277 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.277 DEBG[] incoming body is content-length (53 bytes) [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] buffer.queue self.len=115 buf.len=53 [INFO] [stdout] Apr 26 20:20:25.277 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.278 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] decode; state=Length(53) [INFO] [stdout] Apr 26 20:20:25.278 DEBG[] flushed 168 bytes [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] Server::encode status=200, body=Some(Unknown), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.278 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.278 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.278 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] sized write, len = 221 [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] buffer.queue self.len=243 buf.len=221 [INFO] [stdout] Apr 26 20:20:25.278 DEBG[httpmock::server::web::handlers] Matched mock with id=0 to the following request: HttpMockRequest { [INFO] [stdout] path: "/start", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:42087", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] put; add idle connection for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.278 DEBG[] pooling idle connection for ("http", 127.0.0.1:38145) , REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.278 DEBG[reqwest::async_impl::client] response '404 Not Found' for http://127.0.0.1:38145/next, REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] received 168 bytes [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] Server::encode status=200, body=Some(Known(436)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] Response.parse bytes=168 [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] Response.parse Complete(115) [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.279 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.279 DEBG[] incoming body is content-length (53 bytes) [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] decode; state=Length(53) [INFO] [stdout] Apr 26 20:20:25.279 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.279 TRCE[reqwest::blocking::client] (ThreadId(74)) end runtime::block_on [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] put; add idle connection for ("http", 127.0.0.1:33773) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.279 DEBG[] pooling idle connection for ("http", 127.0.0.1:33773) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.279 TRCE[reqwest::blocking::client] (ThreadId(74)) finished [INFO] [stdout] Apr 26 20:20:25.279 DEBG[reqwest::async_impl::client] response '404 Not Found' for http://127.0.0.1:33773/robots.txt, REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.280 TRCE[reqwest::blocking::client] closed runtime thread (ThreadId(74)) [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] take? ("http", 127.0.0.1:33773): expiration = Some(90s) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.280 DEBG[] reuse idle connection for ("http", 127.0.0.1:33773) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.278 TRCE[] no more write body allowed, user body is_end_stream = false [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.280 DEBG[] flushed 464 bytes [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.280 DEBG[] flushed 85 bytes [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] received 85 bytes [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] received 0 bytes [INFO] [stdout] Apr 26 20:20:25.279 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] parse eof [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] received 464 bytes [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.280 DEBG[] read eof [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] buffer.queue self.len=102 buf.len=436 [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] Response.parse bytes=464 [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] Response.parse Complete(243) [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.280 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] received 538 bytes [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.281 DEBG[] parsed 8 headers [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.281 DEBG[] incoming body is content-length (221 bytes) [INFO] [stdout] Apr 26 20:20:25.281 DEBG[] flushed 538 bytes [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] decode; state=Length(221) [INFO] [stdout] Apr 26 20:20:25.281 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled } [INFO] [stdout] test ignore_non_html ... ok [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] shut down IO complete [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] put; add idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.282 INFO[mikes_crawler::crawler] Got response with status 404 Not Found: Not processing the body, REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.282 DEBG[] pooling idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.282 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:8000/crawl/http%3A%2F%2F127.0.0.1%3A43837%2Fstart [INFO] [stdout] Apr 26 20:20:25.282 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:25.282 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.282 INFO[mikes_crawler::better_logging] Completed request /crawl/http%3A%2F%2F127.0.0.1%3A38145%2Fstart with status 200 OK in 0.036s, REQ: wa0O [INFO] [stdout] Apr 26 20:20:25.282 TRCE[reqwest::blocking::client] closing runtime thread (ThreadId(73)) [INFO] [stdout] Apr 26 20:20:25.282 TRCE[reqwest::blocking::client] signaled close for runtime thread (ThreadId(73)) [INFO] [stdout] Apr 26 20:20:25.282 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.282 TRCE[reqwest::blocking::client] (ThreadId(73)) Receiver is shutdown [INFO] [stdout] Apr 26 20:20:25.283 TRCE[reqwest::blocking::client] (ThreadId(73)) end runtime::block_on [INFO] [stdout] Apr 26 20:20:25.284 TRCE[reqwest::blocking::client] (ThreadId(73)) finished [INFO] [stdout] Apr 26 20:20:25.281 TRCE[] Response.parse bytes=538 [INFO] [stdout] Apr 26 20:20:25.284 TRCE[reqwest::blocking::client] closed runtime thread (ThreadId(73)) [INFO] [stdout] Apr 26 20:20:25.284 TRCE[] Response.parse Complete(102) [INFO] [stdout] Apr 26 20:20:25.284 TRCE[] <- parse_headers [INFO] [stdout] test ignores_things_excluded_by_robots ... ok [INFO] [stdout] Apr 26 20:20:25.284 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.284 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.284 DEBG[] incoming body is content-length (436 bytes) [INFO] [stdout] Apr 26 20:20:25.284 TRCE[] decode; state=Length(436) [INFO] [stdout] Apr 26 20:20:25.285 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.285 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.285 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.285 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.285 TRCE[] put; add idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.285 DEBG[] pooling idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.285 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:42087/start, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.285 INFO[mikes_crawler::crawler] Got body to process from http://127.0.0.1:42087/start containing 436 chars, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.285 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.285 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.282 TRCE[] Request.parse bytes=85 [INFO] [stdout] Apr 26 20:20:25.282 INFO[rocket::server] Response succeeded. [INFO] [stdout] Apr 26 20:20:25.285 TRCE[] received 0 bytes [INFO] [stdout] Apr 26 20:20:25.285 TRCE[] parse eof [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] Request.parse Complete(85) [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] Server::encode status=200, body=Some(Unknown), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.286 DEBG[] read eof [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.286 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.286 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] sized write, len = 241 [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] buffer.queue self.len=243 buf.len=241 [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] no more write body allowed, user body is_end_stream = false [INFO] [stdout] Apr 26 20:20:25.286 DEBG[] flushed 484 bytes [INFO] [stdout] Apr 26 20:20:25.286 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/start", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:33773")] } [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled } [INFO] [stdout] Apr 26 20:20:25.286 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.286 TRCE[] shut down IO complete [INFO] [stdout] Apr 26 20:20:25.287 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.287 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.287 DEBG[httpmock::server::web::handlers] Matched mock with id=0 to the following request: HttpMockRequest { [INFO] [stdout] path: "/start", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:33773", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] received 484 bytes [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] Response.parse bytes=484 [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] Server::encode status=200, body=Some(Known(137)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] Response.parse Complete(243) [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] buffer.queue self.len=102 buf.len=137 [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.287 DEBG[] parsed 8 headers [INFO] [stdout] Apr 26 20:20:25.287 DEBG[] incoming body is content-length (241 bytes) [INFO] [stdout] Apr 26 20:20:25.287 DEBG[] flushed 239 bytes [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] decode; state=Length(241) [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.287 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] take? ("http", 127.0.0.1:42087): expiration = Some(90s) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.287 DEBG[] reuse idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] received 239 bytes [INFO] [stdout] Apr 26 20:20:25.287 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] put; add idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] Response.parse bytes=239 [INFO] [stdout] Apr 26 20:20:25.288 DEBG[] pooling idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] Response.parse Complete(102) [INFO] [stdout] Apr 26 20:20:25.288 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:8000/crawl/http%3A%2F%2F127.0.0.1%3A38145%2Fstart [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.288 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.288 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:42087/, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(42087)) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.288 DEBG[] connecting to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.288 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.288 DEBG[] incoming body is content-length (137 bytes) [INFO] [stdout] Apr 26 20:20:25.288 TRCE[reqwest::blocking::client] closing runtime thread (ThreadId(76)) [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] decode; state=Length(137) [INFO] [stdout] Apr 26 20:20:25.288 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:42087/, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.288 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.288 TRCE[reqwest::blocking::client] (ThreadId(76)) Receiver is shutdown [INFO] [stdout] Apr 26 20:20:25.288 TRCE[reqwest::blocking::client] signaled close for runtime thread (ThreadId(76)) [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(42087)) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.288 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.289 DEBG[] connecting to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.289 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:42087/, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(42087)) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.289 DEBG[] connecting to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] put; add idle connection for ("http", 127.0.0.1:33773) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.289 DEBG[] pooling idle connection for ("http", 127.0.0.1:33773) , REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.289 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:33773/start, REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] checkout waiting for idle connection: ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.289 DEBG[reqwest::connect] starting new connection: http://127.0.0.1:42087/, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.290 INFO[mikes_crawler::crawler] Got body to process from http://127.0.0.1:33773/start containing 137 chars, REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.290 TRCE[reqwest::blocking::client] (ThreadId(76)) end runtime::block_on [INFO] [stdout] Apr 26 20:20:25.289 TRCE[] Http::connect; scheme=Some("http"), host=Some("127.0.0.1"), port=Some(Port(42087)) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.290 DEBG[] connecting to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.290 TRCE[reqwest::blocking::client] (ThreadId(76)) finished [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.290 TRCE[reqwest::blocking::client] closed runtime thread (ThreadId(76)) [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.290 DEBG[] flushed 87 bytes [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] test relative_redirects ... ok [INFO] [stdout] Apr 26 20:20:25.290 DEBG[] connected to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.290 TRCE[] client handshake Http1 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] received 0 bytes [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] parse eof [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] handshake complete, spawning background dispatcher task , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.291 DEBG[] read eof [INFO] [stdout] Apr 26 20:20:25.291 DEBG[] connected to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] client handshake Http1 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] handshake complete, spawning background dispatcher task , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled } [INFO] [stdout] Apr 26 20:20:25.291 DEBG[] connected to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] client handshake Http1 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] shut down IO complete [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] handshake complete, spawning background dispatcher task , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 DEBG[] connected to 127.0.0.1:42087 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] client handshake Http1 , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] handshake complete, spawning background dispatcher task , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.291 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.291 INFO[mikes_crawler::better_logging] Completed request /crawl/http%3A%2F%2F127.0.0.1%3A33773%2Fstart with status 200 OK in 0.046s, REQ: lrs9 [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.291 TRCE[] checkout dropped for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.292 INFO[rocket::server] Response succeeded. [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] checkout dropped for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] checkout dropped for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] Server::encode status=200, body=Some(Unknown), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] checkout dropped for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] sized write, len = 128 [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] buffer.queue self.len=243 buf.len=128 [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] no more write body allowed, user body is_end_stream = false [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.292 DEBG[] flushed 371 bytes [INFO] [stdout] Apr 26 20:20:25.292 DEBG[] flushed 88 bytes [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] received 371 bytes [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] Response.parse bytes=371 [INFO] [stdout] Apr 26 20:20:25.292 DEBG[] flushed 88 bytes [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] Response.parse Complete(243) [INFO] [stdout] Apr 26 20:20:25.292 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.293 DEBG[] flushed 85 bytes [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] Client::encode method=GET, body=None [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.293 DEBG[] parsed 8 headers [INFO] [stdout] Apr 26 20:20:25.293 DEBG[] incoming body is content-length (128 bytes) [INFO] [stdout] Apr 26 20:20:25.293 DEBG[] flushed 83 bytes [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] decode; state=Length(128) [INFO] [stdout] Apr 26 20:20:25.293 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] put; add idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.293 DEBG[] pooling idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.293 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:8000/crawl/http%3A%2F%2F127.0.0.1%3A33773%2Fstart [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] idle interval checking for expired [INFO] [stdout] Apr 26 20:20:25.293 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.293 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.294 TRCE[] received 87 bytes [INFO] [stdout] Apr 26 20:20:25.294 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.294 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.294 TRCE[reqwest::blocking::client] closing runtime thread (ThreadId(75)) [INFO] [stdout] Apr 26 20:20:25.294 TRCE[] Request.parse bytes=87 [INFO] [stdout] Apr 26 20:20:25.294 TRCE[reqwest::blocking::client] signaled close for runtime thread (ThreadId(75)) [INFO] [stdout] Apr 26 20:20:25.294 TRCE[] Request.parse Complete(87) [INFO] [stdout] Apr 26 20:20:25.294 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.294 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.294 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.294 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.294 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/another", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:42087")] } [INFO] [stdout] Apr 26 20:20:25.294 TRCE[reqwest::blocking::client] (ThreadId(75)) Receiver is shutdown [INFO] [stdout] Apr 26 20:20:25.294 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.294 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.295 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.295 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.295 DEBG[httpmock::server::web::handlers] Matched mock with id=1 to the following request: HttpMockRequest { [INFO] [stdout] path: "/another", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:42087", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.295 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.295 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.295 TRCE[] Server::encode status=200, body=Some(Known(135)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.295 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.295 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.295 TRCE[] buffer.queue self.len=117 buf.len=135 [INFO] [stdout] Apr 26 20:20:25.295 TRCE[reqwest::blocking::client] (ThreadId(75)) end runtime::block_on [INFO] [stdout] Apr 26 20:20:25.295 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.295 TRCE[] received 252 bytes [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.296 TRCE[reqwest::blocking::client] (ThreadId(75)) finished [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] Response.parse bytes=252 [INFO] [stdout] Apr 26 20:20:25.296 TRCE[reqwest::blocking::client] closed runtime thread (ThreadId(75)) [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] Response.parse Complete(117) [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] -- parse_headers [INFO] [stdout] test simple ... ok [INFO] [stdout] Apr 26 20:20:25.296 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.296 DEBG[] incoming body is content-length (135 bytes) [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] decode; state=Length(135) [INFO] [stdout] Apr 26 20:20:25.296 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.296 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.295 DEBG[] flushed 252 bytes [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] put; add idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.297 DEBG[] pooling idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.297 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:42087/another, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] received 88 bytes [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.297 INFO[mikes_crawler::crawler] Got body to process from http://127.0.0.1:42087/another containing 135 chars, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] Request.parse bytes=88 [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] Request.parse Complete(88) [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.297 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] received 0 bytes [INFO] [stdout] Apr 26 20:20:25.297 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] parse eof [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.297 DEBG[] read eof [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.297 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/redirect", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:42087")] } [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.297 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled } [INFO] [stdout] Apr 26 20:20:25.297 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.297 TRCE[] shut down IO complete [INFO] [stdout] Apr 26 20:20:25.297 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.298 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.298 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.298 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.298 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.298 DEBG[httpmock::server::web::handlers] Matched mock with id=4 to the following request: HttpMockRequest { [INFO] [stdout] path: "/redirect", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:42087", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] Server::encode status=301, body=None, req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.298 DEBG[] flushed 130 bytes [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] received 85 bytes [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] Request.parse bytes=85 [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] Request.parse Complete(85) [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.298 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.298 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.298 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.299 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/third", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:42087")] } [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.299 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] received 130 bytes [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.299 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.299 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.299 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.299 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.299 DEBG[httpmock::server::web::handlers] Matched mock with id=2 to the following request: HttpMockRequest { [INFO] [stdout] path: "/third", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:42087", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] Server::encode status=200, body=Some(Known(116)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] buffer.queue self.len=117 buf.len=116 [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] Response.parse bytes=130 [INFO] [stdout] Apr 26 20:20:25.299 DEBG[] flushed 233 bytes [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] Response.parse Complete(130) [INFO] [stdout] Apr 26 20:20:25.299 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] received 83 bytes [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.300 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.300 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] Request.parse bytes=83 [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] Request.parse Complete(83) [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.300 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.300 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.300 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/pdf", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:42087")] } [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] put; add idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.300 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.300 DEBG[] pooling idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.300 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.300 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.300 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.300 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.300 DEBG[reqwest::async_impl::client] redirect policy disallowed redirection to 'http://127.0.0.1:42087/start', REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.300 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.300 DEBG[httpmock::server::web::handlers] Matched mock with id=3 to the following request: HttpMockRequest { [INFO] [stdout] path: "/pdf", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:42087", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] Server::encode status=200, body=Some(Known(4)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] buffer.queue self.len=114 buf.len=4 [INFO] [stdout] Apr 26 20:20:25.301 DEBG[] flushed 118 bytes [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] received 118 bytes [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy } [INFO] [stdout] Apr 26 20:20:25.300 DEBG[reqwest::async_impl::client] response '301 Moved Permanently' for http://127.0.0.1:42087/redirect, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] received 88 bytes [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] Response.parse bytes=118 [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] Request.parse bytes=88 [INFO] [stdout] Apr 26 20:20:25.301 TRCE[] Response.parse Complete(114) [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] Request.parse Complete(88) [INFO] [stdout] Apr 26 20:20:25.301 INFO[mikes_crawler::crawler] Got redirect from http://127.0.0.1:42087/redirect to http://127.0.0.1:42087/start, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.302 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.302 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.302 DEBG[] incoming body is content-length (4 bytes) [INFO] [stdout] Apr 26 20:20:25.302 DEBG[] incoming body is empty [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] decode; state=Length(4) [INFO] [stdout] Apr 26 20:20:25.302 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server] Routing incoming request: ServerRequestHeader { method: "GET", path: "/relative", query: "", headers: [("accept", "*/*"), ("user-agent", "MikesCrawler"), ("host", "127.0.0.1:42087")] } [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] put; add idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server::web::handlers] Matching incoming HTTP request [INFO] [stdout] Apr 26 20:20:25.302 DEBG[] pooling idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.302 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:42087/pdf, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.302 TRCE[httpmock::server::matchers::targets] Cannot parse json value: EOF while parsing a value at line 1 column 0 [INFO] [stdout] Apr 26 20:20:25.302 INFO[mikes_crawler::crawler] Got non html response containing: x-application/something, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.302 DEBG[httpmock::server::web::handlers] Matched mock with id=5 to the following request: HttpMockRequest { [INFO] [stdout] path: "/relative", [INFO] [stdout] method: "GET", [INFO] [stdout] headers: Some( [INFO] [stdout] [ [INFO] [stdout] ( [INFO] [stdout] "accept", [INFO] [stdout] "*/*", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "user-agent", [INFO] [stdout] "MikesCrawler", [INFO] [stdout] ), [INFO] [stdout] ( [INFO] [stdout] "host", [INFO] [stdout] "127.0.0.1:42087", [INFO] [stdout] ), [INFO] [stdout] ], [INFO] [stdout] ), [INFO] [stdout] query_params: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] body: Some( [INFO] [stdout] [], [INFO] [stdout] ), [INFO] [stdout] } [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.302 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] Server::encode status=200, body=Some(Known(113)), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] buffer.queue self.len=117 buf.len=113 [INFO] [stdout] Apr 26 20:20:25.303 DEBG[] flushed 230 bytes [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.300 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] received 233 bytes [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] received 230 bytes [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] Response.parse bytes=233 [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] Response.parse bytes=230 [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] Response.parse Complete(117) [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] Response.parse Complete(117) [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.303 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.303 DEBG[] incoming body is content-length (116 bytes) [INFO] [stdout] Apr 26 20:20:25.303 DEBG[] parsed 3 headers [INFO] [stdout] Apr 26 20:20:25.303 DEBG[] incoming body is content-length (113 bytes) [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] decode; state=Length(116) [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] decode; state=Length(113) [INFO] [stdout] Apr 26 20:20:25.303 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.303 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.303 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.304 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.304 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.304 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.304 TRCE[] put; add idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.304 DEBG[] pooling idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.304 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:42087/third, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.304 INFO[mikes_crawler::crawler] Got body to process from http://127.0.0.1:42087/third containing 116 chars, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.304 TRCE[] put; add idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.304 DEBG[] pooling idle connection for ("http", 127.0.0.1:42087) , REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.304 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:42087/relative, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.304 INFO[mikes_crawler::crawler] Got body to process from http://127.0.0.1:42087/relative containing 113 chars, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.305 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.305 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.305 INFO[rocket::server] Outcome: Success [INFO] [stdout] Apr 26 20:20:25.306 INFO[mikes_crawler::better_logging] Completed request /crawl/http%3A%2F%2F127.0.0.1%3A42087%2Fstart with status 200 OK in 0.064s, REQ: 8DF8 [INFO] [stdout] Apr 26 20:20:25.306 INFO[rocket::server] Response succeeded. [INFO] [stdout] Apr 26 20:20:25.306 TRCE[] encode_headers [INFO] [stdout] Apr 26 20:20:25.306 TRCE[] -> encode_headers [INFO] [stdout] Apr 26 20:20:25.306 TRCE[] Server::encode status=200, body=Some(Unknown), req_method=Some(GET) [INFO] [stdout] Apr 26 20:20:25.306 TRCE[] <- encode_headers [INFO] [stdout] Apr 26 20:20:25.306 TRCE[] -- encode_headers [INFO] [stdout] Apr 26 20:20:25.306 TRCE[] sized write, len = 817 [INFO] [stdout] Apr 26 20:20:25.306 TRCE[] buffer.queue self.len=243 buf.len=817 [INFO] [stdout] Apr 26 20:20:25.306 TRCE[] no more write body allowed, user body is_end_stream = false [INFO] [stdout] Apr 26 20:20:25.307 DEBG[] flushed 1060 bytes [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] received 1060 bytes [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] parse_headers [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] -> parse_headers [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] Response.parse bytes=1060 [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] Response.parse Complete(243) [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] <- parse_headers [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] -- parse_headers [INFO] [stdout] Apr 26 20:20:25.307 DEBG[] parsed 8 headers [INFO] [stdout] Apr 26 20:20:25.307 DEBG[] incoming body is content-length (817 bytes) [INFO] [stdout] Apr 26 20:20:25.307 TRCE[] decode; state=Length(817) [INFO] [stdout] Apr 26 20:20:25.308 DEBG[] incoming body completed [INFO] [stdout] Apr 26 20:20:25.308 TRCE[] maybe_notify; read_from_io blocked [INFO] [stdout] Apr 26 20:20:25.308 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.308 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.308 TRCE[] put; add idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.308 DEBG[] pooling idle connection for ("http", 127.0.0.1:8000) [INFO] [stdout] Apr 26 20:20:25.308 DEBG[reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:8000/crawl/http%3A%2F%2F127.0.0.1%3A42087%2Fstart [INFO] [stdout] Apr 26 20:20:25.309 TRCE[reqwest::blocking::wait] wait at most 30s [INFO] [stdout] Apr 26 20:20:25.310 TRCE[] idle interval checking for expired [INFO] [stdout] Apr 26 20:20:25.310 TRCE[] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } [INFO] [stdout] Apr 26 20:20:25.310 TRCE[reqwest::blocking::client] closing runtime thread (ThreadId(77)) [INFO] [stdout] Apr 26 20:20:25.310 TRCE[reqwest::blocking::client] signaled close for runtime thread (ThreadId(77)) [INFO] [stdout] Apr 26 20:20:25.310 TRCE[reqwest::blocking::client] (ThreadId(77)) Receiver is shutdown [INFO] [stdout] Apr 26 20:20:25.311 TRCE[reqwest::blocking::client] (ThreadId(77)) end runtime::block_on [INFO] [stdout] Apr 26 20:20:25.311 TRCE[] Conn::read_head [INFO] [stdout] Apr 26 20:20:25.311 TRCE[] received 0 bytes [INFO] [stdout] Apr 26 20:20:25.311 TRCE[reqwest::blocking::client] (ThreadId(77)) finished [INFO] [stdout] Apr 26 20:20:25.311 TRCE[] parse eof [INFO] [stdout] Apr 26 20:20:25.311 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.311 DEBG[] read eof [INFO] [stdout] Apr 26 20:20:25.311 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.311 TRCE[] State::close_read() [INFO] [stdout] Apr 26 20:20:25.311 TRCE[] State::close_write() [INFO] [stdout] Apr 26 20:20:25.311 TRCE[reqwest::blocking::client] closed runtime thread (ThreadId(77)) [INFO] [stdout] Apr 26 20:20:25.311 TRCE[] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled } [INFO] [stdout] Apr 26 20:20:25.312 TRCE[] shut down IO complete [INFO] [stdout] test collected_things ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.25s [INFO] [stdout] [INFO] [stderr] Doc-tests mikes_crawler [INFO] [stdout] [INFO] [stdout] running 0 tests [INFO] [stdout] [INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s [INFO] [stdout] [INFO] running `Command { std: "docker" "inspect" "58a9dbcbc42575f38a9cad242d777db08e0f92c85f6ec2c66914cf1c06fef0f2", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "58a9dbcbc42575f38a9cad242d777db08e0f92c85f6ec2c66914cf1c06fef0f2", kill_on_drop: false }` [INFO] [stdout] 58a9dbcbc42575f38a9cad242d777db08e0f92c85f6ec2c66914cf1c06fef0f2