[INFO] fetching crate rsnip 0.6.1...
[INFO] testing rsnip-0.6.1 against master#414482f6a0d4e7290f614300581a0b55442552a3 for pr-140985
[INFO] extracting crate rsnip 0.6.1 into /workspace/builds/worker-4-tc1/source
[INFO] validating manifest of crates.io crate rsnip 0.6.1 on toolchain 414482f6a0d4e7290f614300581a0b55442552a3
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+414482f6a0d4e7290f614300581a0b55442552a3" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] started tweaking crates.io crate rsnip 0.6.1
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate rsnip 0.6.1
[INFO] tweaked toml for crates.io crate rsnip 0.6.1 written to /workspace/builds/worker-4-tc1/source/Cargo.toml
[INFO] crate crates.io crate rsnip 0.6.1 already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+414482f6a0d4e7290f614300581a0b55442552a3" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded config v0.15.4
[INFO] [stderr]   Downloaded shell-quote v0.7.2
[INFO] [stderr]   Downloaded skim v0.16.0
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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:eea15d5475069c3ef791f10c2c6b5af2ee421ef2da1e680ecce1cba46243983b" "/opt/rustwide/cargo-home/bin/cargo" "+414482f6a0d4e7290f614300581a0b55442552a3" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 0cc97f0f4b6ddba4a3aca6312947e35ab1c6221818191a04af7555eac0e7946f
[INFO] running `Command { std: "docker" "start" "-a" "0cc97f0f4b6ddba4a3aca6312947e35ab1c6221818191a04af7555eac0e7946f", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "0cc97f0f4b6ddba4a3aca6312947e35ab1c6221818191a04af7555eac0e7946f", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "0cc97f0f4b6ddba4a3aca6312947e35ab1c6221818191a04af7555eac0e7946f", kill_on_drop: false }`
[INFO] [stdout] 0cc97f0f4b6ddba4a3aca6312947e35ab1c6221818191a04af7555eac0e7946f
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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" "RUSTDOCFLAGS=--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:eea15d5475069c3ef791f10c2c6b5af2ee421ef2da1e680ecce1cba46243983b" "/opt/rustwide/cargo-home/bin/cargo" "+414482f6a0d4e7290f614300581a0b55442552a3" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 83fa9bd27228b77f48190acabb2f552a231739377b04dcd46f01365023adfd3e
[INFO] running `Command { std: "docker" "start" "-a" "83fa9bd27228b77f48190acabb2f552a231739377b04dcd46f01365023adfd3e", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.92
[INFO] [stderr]    Compiling unicode-ident v1.0.14
[INFO] [stderr]    Compiling cfg-if v1.0.0
[INFO] [stderr]    Compiling libc v0.2.169
[INFO] [stderr]    Compiling once_cell v1.20.2
[INFO] [stderr]    Compiling serde v1.0.217
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling byteorder v1.5.0
[INFO] [stderr]    Compiling regex-syntax v0.8.5
[INFO] [stderr]    Compiling crossbeam-utils v0.8.21
[INFO] [stderr]    Compiling log v0.4.25
[INFO] [stderr]    Compiling strsim v0.11.1
[INFO] [stderr]    Compiling anstyle v1.0.10
[INFO] [stderr]    Compiling crunchy v0.2.2
[INFO] [stderr]    Compiling rustix v0.38.42
[INFO] [stderr]    Compiling version_check v0.9.5
[INFO] [stderr]    Compiling tiny-keccak v2.0.2
[INFO] [stderr]    Compiling linux-raw-sys v0.4.14
[INFO] [stderr]    Compiling thiserror v2.0.9
[INFO] [stderr]    Compiling fnv v1.0.7
[INFO] [stderr]    Compiling ident_case v1.0.1
[INFO] [stderr]    Compiling utf8parse v0.2.2
[INFO] [stderr]    Compiling is_terminal_polyfill v1.70.1
[INFO] [stderr]    Compiling colorchoice v1.0.3
[INFO] [stderr]    Compiling aho-corasick v1.1.3
[INFO] [stderr]    Compiling anstyle-query v1.1.2
[INFO] [stderr]    Compiling ahash v0.8.11
[INFO] [stderr]    Compiling anstyle-parse v0.2.6
[INFO] [stderr]    Compiling ucd-trie v0.1.7
[INFO] [stderr]    Compiling simd-adler32 v0.3.7
[INFO] [stderr]    Compiling bitflags v1.3.2
[INFO] [stderr]    Compiling anstream v0.6.18
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling smallvec v1.13.2
[INFO] [stderr]    Compiling num-traits v0.2.19
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling adler2 v2.0.0
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling equivalent v1.0.1
[INFO] [stderr]    Compiling miniz_oxide v0.8.2
[INFO] [stderr]    Compiling crc32fast v1.4.2
[INFO] [stderr]    Compiling heck v0.5.0
[INFO] [stderr]    Compiling quote v1.0.38
[INFO] [stderr]    Compiling scopeguard v1.2.0
[INFO] [stderr]    Compiling crossbeam-epoch v0.9.18
[INFO] [stderr]    Compiling signal-hook v0.3.17
[INFO] [stderr]    Compiling cfg_aliases v0.2.1
[INFO] [stderr]    Compiling syn v2.0.95
[INFO] [stderr]    Compiling rayon-core v1.12.1
[INFO] [stderr]    Compiling clap_lex v0.7.4
[INFO] [stderr]    Compiling crossbeam-deque v0.8.6
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling either v1.13.0
[INFO] [stderr]    Compiling predicates-core v1.0.9
[INFO] [stderr]    Compiling flate2 v1.0.35
[INFO] [stderr]    Compiling getrandom v0.2.15
[INFO] [stderr]    Compiling clap_builder v4.5.27
[INFO] [stderr]    Compiling nix v0.29.0
[INFO] [stderr]    Compiling crossbeam-channel v0.5.14
[INFO] [stderr]    Compiling fdeflate v0.3.7
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling const-random-macro v0.1.16
[INFO] [stderr]    Compiling indexmap v2.7.1
[INFO] [stderr]    Compiling serde_json v1.0.135
[INFO] [stderr]    Compiling float-cmp v0.10.0
[INFO] [stderr]    Compiling unicode-width v0.2.0
[INFO] [stderr]    Compiling difflib v0.4.0
[INFO] [stderr]    Compiling iana-time-zone v0.1.61
[INFO] [stderr]    Compiling const-random v0.1.18
[INFO] [stderr]    Compiling mockall_derive v0.13.1
[INFO] [stderr]    Compiling dlv-list v0.5.2
[INFO] [stderr]    Compiling regex-syntax v0.6.29
[INFO] [stderr]    Compiling termtree v0.5.1
[INFO] [stderr]    Compiling regex-automata v0.4.9
[INFO] [stderr]    Compiling powerfmt v0.2.0
[INFO] [stderr]    Compiling normalize-line-endings v0.3.0
[INFO] [stderr]    Compiling doc-comment v0.3.3
[INFO] [stderr]    Compiling thiserror v1.0.69
[INFO] [stderr]    Compiling winnow v0.7.1
[INFO] [stderr]    Compiling deranged v0.3.11
[INFO] [stderr]    Compiling predicates-tree v1.0.12
[INFO] [stderr]    Compiling dirs-sys-next v0.1.2
[INFO] [stderr]    Compiling signal-hook-registry v1.4.2
[INFO] [stderr]    Compiling rand_core v0.6.4
[INFO] [stderr]    Compiling dirs-next v2.0.0
[INFO] [stderr]    Compiling term v0.7.0
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling nix v0.24.3
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling png v0.17.16
[INFO] [stderr]    Compiling crossbeam-queue v0.3.12
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling itoa v1.0.14
[INFO] [stderr]    Compiling ryu v1.0.18
[INFO] [stderr]    Compiling pin-project-lite v0.2.15
[INFO] [stderr]    Compiling assert_cmd v2.0.16
[INFO] [stderr]    Compiling env_home v0.1.0
[INFO] [stderr]    Compiling bytemuck v1.21.0
[INFO] [stderr]    Compiling option-ext v0.2.0
[INFO] [stderr]    Compiling trim-in-place v0.1.7
[INFO] [stderr]    Compiling x11rb-protocol v0.13.1
[INFO] [stderr]    Compiling anyhow v1.0.95
[INFO] [stderr]    Compiling arrayvec v0.7.6
[INFO] [stderr]    Compiling time-core v0.1.2
[INFO] [stderr]    Compiling unicode-width v0.1.14
[INFO] [stderr]    Compiling arraydeque v0.5.1
[INFO] [stderr]    Compiling humantime v2.1.0
[INFO] [stderr]    Compiling num-conv v0.1.0
[INFO] [stderr]    Compiling base64 v0.21.7
[INFO] [stderr]    Compiling fastrand v2.3.0
[INFO] [stderr]    Compiling byteorder-lite v0.1.0
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling time v0.3.37
[INFO] [stderr]    Compiling vte v0.14.1
[INFO] [stderr]    Compiling regex-automata v0.1.10
[INFO] [stderr]    Compiling image v0.25.5
[INFO] [stderr]    Compiling dirs-sys v0.4.1
[INFO] [stderr]    Compiling signal-hook-mio v0.2.4
[INFO] [stderr]    Compiling rayon v1.10.0
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling convert_case v0.6.0
[INFO] [stderr]    Compiling crossbeam v0.8.4
[INFO] [stderr]    Compiling wait-timeout v0.2.0
[INFO] [stderr]    Compiling darling_core v0.20.10
[INFO] [stderr]    Compiling tuikit v0.5.0
[INFO] [stderr]    Compiling console v0.15.10
[INFO] [stderr]    Compiling defer-drop v1.3.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling fuzzy-matcher v0.3.7
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling regex v1.11.1
[INFO] [stderr]    Compiling bstr v1.11.3
[INFO] [stderr]    Compiling zeroize v1.8.1
[INFO] [stderr]    Compiling matchers v0.1.0
[INFO] [stderr]    Compiling beef v0.5.2
[INFO] [stderr]    Compiling predicates v3.1.3
[INFO] [stderr]    Compiling env_filter v0.1.3
[INFO] [stderr]    Compiling winnow v0.6.22
[INFO] [stderr]    Compiling downcast v0.11.0
[INFO] [stderr]    Compiling env_logger v0.11.6
[INFO] [stderr]    Compiling fragile v2.0.0
[INFO] [stderr]    Compiling pathdiff v0.2.3
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling shell-words v1.1.0
[INFO] [stderr]    Compiling dirs v5.0.1
[INFO] [stderr]    Compiling itertools v0.14.0
[INFO] [stderr]    Compiling shell-quote v0.7.2
[INFO] [stderr]    Compiling serde_derive v1.0.217
[INFO] [stderr]    Compiling zerocopy-derive v0.7.35
[INFO] [stderr]    Compiling thiserror-impl v2.0.9
[INFO] [stderr]    Compiling clap_derive v4.5.24
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror-impl v1.0.69
[INFO] [stderr]    Compiling async-trait v0.1.84
[INFO] [stderr]    Compiling ctor v0.2.9
[INFO] [stderr]    Compiling darling_macro v0.20.10
[INFO] [stderr]    Compiling zerocopy v0.7.35
[INFO] [stderr]    Compiling darling v0.20.10
[INFO] [stderr]    Compiling derive_builder_core v0.20.2
[INFO] [stderr]    Compiling pest v2.7.15
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling ppv-lite86 v0.2.20
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling hashbrown v0.14.5
[INFO] [stderr]    Compiling rand_chacha v0.3.1
[INFO] [stderr]    Compiling derive_builder_macro v0.20.2
[INFO] [stderr]    Compiling rand v0.8.5
[INFO] [stderr]    Compiling clap v4.5.27
[INFO] [stderr]    Compiling derive_builder v0.20.2
[INFO] [stderr]    Compiling clap_complete v4.5.40
[INFO] [stderr]    Compiling pest_meta v2.7.15
[INFO] [stderr]    Compiling hashlink v0.9.1
[INFO] [stderr]    Compiling ordered-multimap v0.7.3
[INFO] [stderr]    Compiling pest_generator v2.7.15
[INFO] [stderr]    Compiling mockall v0.13.1
[INFO] [stderr]    Compiling yaml-rust2 v0.9.0
[INFO] [stderr]    Compiling rust-ini v0.21.1
[INFO] [stderr]    Compiling pest_derive v2.7.15
[INFO] [stderr]    Compiling bitflags v2.6.0
[INFO] [stderr]    Compiling toml_datetime v0.6.8
[INFO] [stderr]    Compiling serde_spanned v0.6.8
[INFO] [stderr]    Compiling chrono v0.4.39
[INFO] [stderr]    Compiling json5 v0.4.1
[INFO] [stderr]    Compiling minijinja v2.6.0
[INFO] [stderr]    Compiling ron v0.8.1
[INFO] [stderr]    Compiling toml_edit v0.22.23
[INFO] [stderr]    Compiling timer v0.2.0
[INFO] [stderr]    Compiling toml v0.8.20
[INFO] [stderr]    Compiling config v0.15.4
[INFO] [stderr]    Compiling which v7.0.1
[INFO] [stderr]    Compiling tempfile v3.15.0
[INFO] [stderr]    Compiling x11rb v0.13.1
[INFO] [stderr]    Compiling crossterm v0.28.1
[INFO] [stderr]    Compiling dialoguer v0.11.0
[INFO] [stderr]    Compiling skim v0.16.0
[INFO] [stderr]    Compiling arboard v3.4.1
[INFO] [stderr]    Compiling rsnip v0.6.1 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 26s
[INFO] running `Command { std: "docker" "inspect" "83fa9bd27228b77f48190acabb2f552a231739377b04dcd46f01365023adfd3e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "83fa9bd27228b77f48190acabb2f552a231739377b04dcd46f01365023adfd3e", kill_on_drop: false }`
[INFO] [stdout] 83fa9bd27228b77f48190acabb2f552a231739377b04dcd46f01365023adfd3e
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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" "RUSTDOCFLAGS=--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:eea15d5475069c3ef791f10c2c6b5af2ee421ef2da1e680ecce1cba46243983b" "/opt/rustwide/cargo-home/bin/cargo" "+414482f6a0d4e7290f614300581a0b55442552a3" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] d6dfc37f8ed79df1de6256267f1e32d03b471e44cbbab826a500503ac749ea10
[INFO] running `Command { std: "docker" "start" "-a" "d6dfc37f8ed79df1de6256267f1e32d03b471e44cbbab826a500503ac749ea10", kill_on_drop: false }`
[INFO] [stderr]    Compiling rsnip v0.6.1 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 7.10s
[INFO] running `Command { std: "docker" "inspect" "d6dfc37f8ed79df1de6256267f1e32d03b471e44cbbab826a500503ac749ea10", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "d6dfc37f8ed79df1de6256267f1e32d03b471e44cbbab826a500503ac749ea10", kill_on_drop: false }`
[INFO] [stdout] d6dfc37f8ed79df1de6256267f1e32d03b471e44cbbab826a500503ac749ea10
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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" "RUSTDOCFLAGS=--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:eea15d5475069c3ef791f10c2c6b5af2ee421ef2da1e680ecce1cba46243983b" "/opt/rustwide/cargo-home/bin/cargo" "+414482f6a0d4e7290f614300581a0b55442552a3" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] a7fe3e44dd6ab4b84b8a4c0dfad9c40e02a9cec75ef5468b75792de5ae6e2566
[INFO] running `Command { std: "docker" "start" "-a" "a7fe3e44dd6ab4b84b8a4c0dfad9c40e02a9cec75ef5468b75792de5ae6e2566", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.40s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/rsnip-0a9167050f82e4fe)
[INFO] [stderr] 2025-05-16T22:55:11.324509Z  INFO rsnip::util::testing: Test Setup complete
[INFO] [stderr] 2025-05-16T22:55:11.324653Z DEBUG rsnip::util::testing: INIT: Attempting logger init from testing.rs
[INFO] [stdout] 
[INFO] [stderr] 2025-05-16T22:55:11.324927Z DEBUG rsnip::util::testing: Tracing subscriber already set
[INFO] [stdout] running 14 tests
[INFO] [stderr] 2025-05-16T22:55:11.325117Z  INFO rsnip::util::testing: Test Setup complete
[INFO] [stderr] 2025-05-16T22:55:11.327383Z DEBUG create{format=Scls}: rsnip::infrastructure::parsers: close time.busy=9.50µs time.idle=21.5µs
[INFO] [stdout] test config::tests::given_combined_type_when_getting_snippet_type_then_returns_none ... ok
[INFO] [stderr] 2025-05-16T22:55:11.327408Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=7.08µs time.idle=14.0µs
[INFO] [stdout] test config::tests::given_concrete_type_when_getting_sources_then_returns_none ... ok
[INFO] [stderr] 2025-05-16T22:55:11.327469Z DEBUG parse{path="/tmp/.tmp4TscRq"}: rsnip::infrastructure::parsers::scls: Parsing SCLS format snippets from: "/tmp/.tmp4TscRq"
[INFO] [stdout] test cli::args::tests::given_generate_config_flag_when_parsing_then_sets_flag ... ok
[INFO] [stderr] 2025-05-16T22:55:11.327474Z DEBUG parse{path="/tmp/.tmpZqoWDp"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpZqoWDp"
[INFO] [stderr] 2025-05-16T22:55:11.327585Z TRACE parse{path="/tmp/.tmpZqoWDp"}:new{content="content"}: rsnip::domain::content: SnippetContent::new called with: content
[INFO] [stderr] 2025-05-16T22:55:11.327622Z TRACE parse{path="/tmp/.tmpZqoWDp"}:new{content="content"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.327652Z DEBUG parse{path="/tmp/.tmpZqoWDp"}:new{content="content"}: rsnip::domain::content: close time.busy=73.2µs time.idle=10.3µs
[INFO] [stderr] 2025-05-16T22:55:11.327691Z DEBUG parse{path="/tmp/.tmpZqoWDp"}: rsnip::infrastructure::parsers::default: close time.busy=219µs time.idle=8.80µs
[INFO] [stderr] 2025-05-16T22:55:11.341440Z DEBUG find_snippet_line_number{content="some content\n--- test\ncontent\n---" snippet_name="test"}: rsnip::infrastructure::edit_snippets: close time.busy=22.8µs time.idle=34.9µs
[INFO] [stderr] 2025-05-16T22:55:11.341689Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.64µs time.idle=11.5µs
[INFO] [stderr] 2025-05-16T22:55:11.341761Z DEBUG create{format=Scls}: rsnip::infrastructure::parsers: close time.busy=5.85µs time.idle=9.22µs
[INFO] [stderr] 2025-05-16T22:55:11.341808Z DEBUG parse{path="dummy"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "dummy"
[INFO] [stderr] 2025-05-16T22:55:11.341913Z DEBUG parse{path="dummy"}: rsnip::infrastructure::parsers::default: close time.busy=102µs time.idle=9.10µs
[INFO] [stderr] 2025-05-16T22:55:11.341985Z DEBUG parse{path="dummy"}: rsnip::infrastructure::parsers::scls: Parsing SCLS format snippets from: "dummy"
[INFO] [stderr] 2025-05-16T22:55:11.342045Z DEBUG parse{path="dummy"}: rsnip::infrastructure::parsers::scls: close time.busy=57.5µs time.idle=9.94µs
[INFO] [stdout] test util::path_utils::tests::given_invalid_tilde_path_when_expanding_then_returns_error ... ok
[INFO] [stderr] 2025-05-16T22:55:11.347403Z DEBUG find_snippet_line_number{content="some content\n--- test\ncontent\n---" snippet_name="nonexistent"}: rsnip::infrastructure::edit_snippets: close time.busy=29.2µs time.idle=18.8µs
[INFO] [stdout] test infrastructure::parsers::tests::given_default_format_file_when_parsing_then_succeeds ... ok
[INFO] [stdout] test config::tests::given_concrete_type_when_getting_snippet_type_then_returns_correct_type ... ok
[INFO] [stdout] test config::tests::given_combined_type_when_getting_sources_then_returns_source_list ... ok
[INFO] [stdout] test util::path_utils::tests::given_path_with_tilde_when_expanding_then_replaces_with_home ... ok
[INFO] [stdout] test util::path_utils::tests::given_relative_path_when_expanding_then_returns_unchanged ... ok
[INFO] [stdout] test infrastructure::edit_snippets::tests::given_valid_content_when_finding_snippet_then_returns_correct_line ... ok
[INFO] [stdout] test infrastructure::parsers::tests::given_format_when_creating_parser_then_returns_correct_implementation ... ok
[INFO] [stdout] test util::path_utils::tests::given_absolute_path_when_expanding_then_returns_unchanged ... ok
[INFO] [stderr] 2025-05-16T22:55:11.352655Z TRACE parse{path="/tmp/.tmp4TscRq"}:new{content="content"}: rsnip::domain::content: SnippetContent::new called with: content
[INFO] [stdout] test infrastructure::edit_snippets::tests::given_nonexistent_snippet_when_finding_line_then_returns_none ... ok
[INFO] [stdout] test infrastructure::parsers::tests::given_scls_format_file_when_parsing_then_succeeds ... ok
[INFO] [stdout] 
[INFO] [stderr] 2025-05-16T22:55:11.355229Z TRACE parse{path="/tmp/.tmp4TscRq"}:new{content="content"}: rsnip::domain::content: Detected as static
[INFO] [stdout] test result: ok. 14 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.03s
[INFO] [stderr] 2025-05-16T22:55:11.355322Z DEBUG parse{path="/tmp/.tmp4TscRq"}:new{content="content"}: rsnip::domain::content: close time.busy=2.67ms time.idle=18.0µs
[INFO] [stdout] 
[INFO] [stderr] 2025-05-16T22:55:11.355381Z DEBUG parse{path="/tmp/.tmp4TscRq"}: rsnip::infrastructure::parsers::scls: close time.busy=27.9ms time.idle=9.57µs
[INFO] [stderr]      Running unittests src/main.rs (/opt/rustwide/target/debug/deps/rsnip-cd61248dd4f025fb)
[INFO] [stdout] 
[INFO] [stdout] running 1 test
[INFO] [stdout] test tests::verify_cli ... ok
[INFO] [stderr]      Running tests/test_commands.rs (/opt/rustwide/target/debug/deps/test_commands-8260074e389541d4)
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 1 test
[INFO] [stdout] test given_types_list_flag_when_execute_then_outputs_space_separated ... ok
[INFO] [stderr]      Running tests/test_fuzzy.rs (/opt/rustwide/target/debug/deps/test_fuzzy-187cf44398765048)
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test given_empty_query_when_fuzzy_finder_then_shows_all ... ignored, todo fix
[INFO] [stdout] test given_multiple_matches_when_fuzzy_finder_then_shows_interface ... ignored, This test is interactive via Makefile
[INFO] [stdout] test given_no_matches_when_fuzzy_finder_then_shows_interface ... ignored, Interactive test requires terminal
[INFO] [stdout] test given_empty_items_when_fuzzy_finder_then_returns_none ... ok
[INFO] [stdout] test test_fuzzy_finder_output_is_clean ... ignored, Interactive test requires terminal
[INFO] [stdout] test given_snippets_when_creating_skim_items_then_returns_formatted_items ... ok
[INFO] [stdout] test given_exact_match_when_fuzzy_finder_then_returns_immediately ... ok
[INFO] [stdout] test given_single_partial_match_when_fuzzy_finder_then_auto_selects ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 4 ignored; 0 measured; 0 filtered out; finished in 0.01s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/test_lib.rs (/opt/rustwide/target/debug/deps/test_lib-5c72483e9f5402d4)
[INFO] [stderr] 2025-05-16T22:55:11.457215Z  INFO rsnip::util::testing: Test Setup complete
[INFO] [stdout] 
[INFO] [stdout] running 35 tests
[INFO] [stderr] 2025-05-16T22:55:11.458533Z DEBUG find_completion_exact{completion_type="test" user_input=""}: rsnip::application::snippet_service: close time.busy=11.7µs time.idle=18.6µs
[INFO] [stderr] 2025-05-16T22:55:11.458653Z DEBUG find_completion_fuzzy{completion_type="test" user_input=""}: rsnip::application::snippet_service: close time.busy=6.21µs time.idle=9.58µs
[INFO] [stderr] 2025-05-16T22:55:11.461883Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}:get_snippets{snippet_type="test"}: rsnip::application::snippet_service: Loading snippets from /tmp/.tmpkWKX8T
[INFO] [stderr] 2025-05-16T22:55:11.462059Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}:get_snippets{snippet_type="test"}:create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.98µs time.idle=11.2µs
[INFO] [stderr] 2025-05-16T22:55:11.461943Z DEBUG get_snippets{snippet_type="combined"}: rsnip::application::snippet_service: Loading combined snippets from sources: ["source1", "source2"]
[INFO] [stderr] 2025-05-16T22:55:11.462144Z DEBUG get_snippets{snippet_type="combined"}: rsnip::application::snippet_service: Loading snippets from /tmp/.tmprOXy9D
[INFO] [stderr] 2025-05-16T22:55:11.462211Z DEBUG get_snippets{snippet_type="combined"}:create{format=Default}: rsnip::infrastructure::parsers: close time.busy=5.47µs time.idle=8.11µs
[INFO] [stderr] 2025-05-16T22:55:11.462275Z DEBUG get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmprOXy9D"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmprOXy9D"
[INFO] [stderr] 2025-05-16T22:55:11.462396Z TRACE get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmprOXy9D"}:new{content="Content1"}: rsnip::domain::content: SnippetContent::new called with: Content1
[INFO] [stderr] 2025-05-16T22:55:11.462436Z TRACE get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmprOXy9D"}:new{content="Content1"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.462468Z DEBUG get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmprOXy9D"}:new{content="Content1"}: rsnip::domain::content: close time.busy=79.6µs time.idle=10.2µs
[INFO] [stderr] 2025-05-16T22:55:11.462508Z DEBUG get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmprOXy9D"}: rsnip::infrastructure::parsers::default: close time.busy=234µs time.idle=7.98µs
[INFO] [stderr] 2025-05-16T22:55:11.462544Z DEBUG get_snippets{snippet_type="combined"}: rsnip::application::snippet_service: Loading snippets from /tmp/.tmpKtUBw7
[INFO] [stderr] 2025-05-16T22:55:11.462590Z DEBUG get_snippets{snippet_type="combined"}:create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.12µs time.idle=9.47µs
[INFO] [stderr] 2025-05-16T22:55:11.462636Z DEBUG get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmpKtUBw7"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpKtUBw7"
[INFO] [stderr] 2025-05-16T22:55:11.462733Z TRACE get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmpKtUBw7"}:new{content="Content2"}: rsnip::domain::content: SnippetContent::new called with: Content2
[INFO] [stderr] 2025-05-16T22:55:11.462763Z TRACE get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmpKtUBw7"}:new{content="Content2"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.462798Z DEBUG get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmpKtUBw7"}:new{content="Content2"}: rsnip::domain::content: close time.busy=64.2µs time.idle=11.7µs
[INFO] [stderr] 2025-05-16T22:55:11.462840Z DEBUG get_snippets{snippet_type="combined"}:parse{path="/tmp/.tmpKtUBw7"}: rsnip::infrastructure::parsers::default: close time.busy=202µs time.idle=8.95µs
[INFO] [stderr] 2025-05-16T22:55:11.462883Z DEBUG get_snippets{snippet_type="combined"}: rsnip::application::snippet_service: close time.busy=1.00ms time.idle=15.3µs
[INFO] [stderr] 2025-05-16T22:55:11.463041Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}:get_snippets{snippet_type="test"}: rsnip::application::snippet_service: Loading snippets from /tmp/.tmp6GJWBV
[INFO] [stderr] 2025-05-16T22:55:11.463106Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}:get_snippets{snippet_type="test"}:create{format=Default}: rsnip::infrastructure::parsers: close time.busy=13.7µs time.idle=8.86µs
[INFO] [stderr] 2025-05-16T22:55:11.463191Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmp6GJWBV"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmp6GJWBV"
[INFO] [stderr] 2025-05-16T22:55:11.463261Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpkWKX8T"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpkWKX8T"
[INFO] [stderr] 2025-05-16T22:55:11.463290Z TRACE copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmp6GJWBV"}:new{content="{{current_date|strftime('%Y-%m-%d')}}"}: rsnip::domain::content: SnippetContent::new called with: {{current_date|strftime('%Y-%m-%d')}}
[INFO] [stderr] 2025-05-16T22:55:11.463347Z TRACE copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmp6GJWBV"}:new{content="{{current_date|strftime('%Y-%m-%d')}}"}: rsnip::domain::content: Detected as template
[INFO] [stderr] 2025-05-16T22:55:11.465031Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.74µs time.idle=12.2µs
[INFO] [stderr] 2025-05-16T22:55:11.465097Z DEBUG parse{path="/tmp/.tmp5fjgVZ"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmp5fjgVZ"
[INFO] [stderr] 2025-05-16T22:55:11.465277Z TRACE parse{path="/tmp/.tmp5fjgVZ"}:new{content="content"}: rsnip::domain::content: SnippetContent::new called with: content
[INFO] [stderr] 2025-05-16T22:55:11.465321Z TRACE parse{path="/tmp/.tmp5fjgVZ"}:new{content="content"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.463435Z TRACE copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpkWKX8T"}:new{content="A red fruit"}: rsnip::domain::content: SnippetContent::new called with: A red fruit
[INFO] [stderr] 2025-05-16T22:55:11.464203Z DEBUG find_completion_exact{completion_type="test" user_input="test"}:get_snippets{snippet_type="test"}: rsnip::application::snippet_service: Loading snippets from /tmp/.tmpijTuKR
[INFO] [stdout] test application::test_snippet_service::given_empty_input_when_finding_completion_then_returns_none ... ok
[INFO] [stdout] test application::test_snippet_service::given_combined_type_when_getting_snippets_then_returns_all_snippets ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_empty_snippet_when_parse_then_returns_error ... ok
[INFO] [stdout] test application::test_snippet_service::given_exact_match_when_finding_completion_then_returns_snippet ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_malformed_snippet_with_extra_start_when_parse_then_returns_error ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_snippet_with_closing_without_opening_when_parse_then_returns_error ... ok
[INFO] [stderr] 2025-05-16T22:55:11.464538Z DEBUG find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}: rsnip::application::snippet_service: Loading snippets from /tmp/.tmpRU9Z0l
[INFO] [stderr] 2025-05-16T22:55:11.464821Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=7.69µs time.idle=13.6µs
[INFO] [stderr] 2025-05-16T22:55:11.465580Z DEBUG find_completion_exact{completion_type="test" user_input="test"}:get_snippets{snippet_type="test"}:create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.20µs time.idle=10.3µs
[INFO] [stderr] 2025-05-16T22:55:11.465603Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmp6GJWBV"}:new{content="{{current_date|strftime('%Y-%m-%d')}}"}: rsnip::domain::content: close time.busy=2.31ms time.idle=11.3µs
[INFO] [stderr] 2025-05-16T22:55:11.465614Z DEBUG find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:create{format=Default}: rsnip::infrastructure::parsers: close time.busy=7.35µs time.idle=12.2µs
[INFO] [stderr] 2025-05-16T22:55:11.465622Z DEBUG parse{path="/tmp/.tmpBj92qp"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpBj92qp"
[INFO] [stderr] 2025-05-16T22:55:11.465628Z DEBUG find_completion_exact{completion_type="test" user_input="test"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpijTuKR"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpijTuKR"
[INFO] [stderr] 2025-05-16T22:55:11.465677Z DEBUG find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpRU9Z0l"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpRU9Z0l"
[INFO] [stderr] 2025-05-16T22:55:11.465727Z TRACE find_completion_exact{completion_type="test" user_input="test"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpijTuKR"}:new{content="Content"}: rsnip::domain::content: SnippetContent::new called with: Content
[INFO] [stderr] 2025-05-16T22:55:11.465760Z TRACE find_completion_exact{completion_type="test" user_input="test"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpijTuKR"}:new{content="Content"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.465791Z DEBUG find_completion_exact{completion_type="test" user_input="test"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpijTuKR"}:new{content="Content"}: rsnip::domain::content: close time.busy=63.2µs time.idle=9.31µs
[INFO] [stderr] 2025-05-16T22:55:11.465805Z DEBUG parse{path="/tmp/.tmpBj92qp"}: rsnip::infrastructure::parsers::default: close time.busy=181µs time.idle=11.9µs
[INFO] [stderr] 2025-05-16T22:55:11.465789Z TRACE find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpRU9Z0l"}:new{content="Content"}: rsnip::domain::content: SnippetContent::new called with: Content
[INFO] [stderr] 2025-05-16T22:55:11.465833Z DEBUG find_completion_exact{completion_type="test" user_input="test"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpijTuKR"}: rsnip::infrastructure::parsers::default: close time.busy=204µs time.idle=7.09µs
[INFO] [stderr] 2025-05-16T22:55:11.465862Z DEBUG find_completion_exact{completion_type="test" user_input="test"}:get_snippets{snippet_type="test"}: rsnip::application::snippet_service: close time.busy=1.67ms time.idle=47.9µs
[INFO] [stderr] 2025-05-16T22:55:11.465854Z TRACE find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpRU9Z0l"}:new{content="Content"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.465887Z DEBUG find_completion_exact{completion_type="test" user_input="test"}: rsnip::application::snippet_service: close time.busy=1.81ms time.idle=82.8µs
[INFO] [stderr] 2025-05-16T22:55:11.465881Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=7.43µs time.idle=19.9µs
[INFO] [stderr] 2025-05-16T22:55:11.465892Z DEBUG find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpRU9Z0l"}:new{content="Content"}: rsnip::domain::content: close time.busy=102µs time.idle=11.3µs
[INFO] [stderr] 2025-05-16T22:55:11.465890Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=10.1µs time.idle=12.9µs
[INFO] [stderr] 2025-05-16T22:55:11.465939Z DEBUG parse{path="/tmp/.tmpWj2kCl"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpWj2kCl"
[INFO] [stderr] 2025-05-16T22:55:11.465957Z TRACE find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpRU9Z0l"}:new{content="Content2"}: rsnip::domain::content: SnippetContent::new called with: Content2
[INFO] [stderr] 2025-05-16T22:55:11.465988Z TRACE find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpRU9Z0l"}:new{content="Content2"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.466015Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmp6GJWBV"}: rsnip::infrastructure::parsers::default: close time.busy=2.82ms time.idle=11.1µs
[INFO] [stderr] 2025-05-16T22:55:11.466022Z DEBUG find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpRU9Z0l"}:new{content="Content2"}: rsnip::domain::content: close time.busy=63.6µs time.idle=9.97µs
[INFO] [stderr] 2025-05-16T22:55:11.466053Z TRACE parse{path="/tmp/.tmpWj2kCl"}:new{content="content"}: rsnip::domain::content: SnippetContent::new called with: content
[INFO] [stderr] 2025-05-16T22:55:11.465374Z DEBUG parse{path="/tmp/.tmp5fjgVZ"}:new{content="content"}: rsnip::domain::content: close time.busy=74.9µs time.idle=38.1µs
[INFO] [stderr] 2025-05-16T22:55:11.466080Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}:get_snippets{snippet_type="test"}: rsnip::application::snippet_service: close time.busy=3.05ms time.idle=6.98µs
[INFO] [stderr] 2025-05-16T22:55:11.466089Z DEBUG find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpRU9Z0l"}: rsnip::infrastructure::parsers::default: close time.busy=404µs time.idle=9.95µs
[INFO] [stderr] 2025-05-16T22:55:11.466102Z TRACE parse{path="/tmp/.tmpWj2kCl"}:new{content="content"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.466134Z DEBUG find_completion_fuzzy{completion_type="test" user_input="tst"}:get_snippets{snippet_type="test"}: rsnip::application::snippet_service: close time.busy=1.60ms time.idle=8.55µs
[INFO] [stderr] 2025-05-16T22:55:11.466135Z DEBUG parse{path="/tmp/.tmpWj2kCl"}:new{content="content"}: rsnip::domain::content: close time.busy=90.8µs time.idle=10.9µs
[INFO] [stderr] 2025-05-16T22:55:11.466180Z DEBUG parse{path="/tmp/.tmp5fjgVZ"}: rsnip::infrastructure::parsers::default: close time.busy=1.08ms time.idle=10.1µs
[INFO] [stderr] 2025-05-16T22:55:11.466213Z DEBUG parse{path="/tmp/.tmpWj2kCl"}: rsnip::infrastructure::parsers::default: close time.busy=272µs time.idle=9.73µs
[INFO] [stderr] 2025-05-16T22:55:11.466270Z DEBUG find_completion_fuzzy{completion_type="test" user_input="tst"}: rsnip::application::snippet_service: close time.busy=1.74ms time.idle=13.3µs
[INFO] [stderr] 2025-05-16T22:55:11.466280Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.14µs time.idle=11.3µs
[INFO] [stderr] 2025-05-16T22:55:11.466347Z DEBUG parse{path="/tmp/.tmpVIz1Yp"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpVIz1Yp"
[INFO] [stderr] 2025-05-16T22:55:11.466396Z DEBUG create{format=Scls}: rsnip::infrastructure::parsers: close time.busy=6.16µs time.idle=10.2µs
[INFO] [stderr] 2025-05-16T22:55:11.466407Z DEBUG parse{path="/tmp/.tmpVIz1Yp"}: rsnip::infrastructure::parsers::default: close time.busy=63.4µs time.idle=8.41µs
[INFO] [stderr] 2025-05-16T22:55:11.466447Z DEBUG parse{path="/tmp/.tmp2tL88l"}: rsnip::infrastructure::parsers::scls: Parsing SCLS format snippets from: "/tmp/.tmp2tL88l"
[INFO] [stderr] 2025-05-16T22:55:11.466626Z DEBUG parse{path="/tmp/.tmp2tL88l"}: rsnip::infrastructure::parsers::scls: close time.busy=177µs time.idle=8.33µs
[INFO] [stderr] 2025-05-16T22:55:11.467329Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.55µs time.idle=11.2µs
[INFO] [stderr] 2025-05-16T22:55:11.467376Z DEBUG parse{path="/tmp/.tmpBQJYFi"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpBQJYFi"
[INFO] [stderr] 2025-05-16T22:55:11.467466Z TRACE parse{path="/tmp/.tmpBQJYFi"}:new{content="this is green\nand nothing else"}: rsnip::domain::content: SnippetContent::new called with: this is green
[INFO] [stderr] and nothing else
[INFO] [stderr] 2025-05-16T22:55:11.467495Z TRACE parse{path="/tmp/.tmpBQJYFi"}:new{content="this is green\nand nothing else"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.467520Z DEBUG parse{path="/tmp/.tmpBQJYFi"}:new{content="this is green\nand nothing else"}: rsnip::domain::content: close time.busy=52.3µs time.idle=9.28µs
[INFO] [stderr] 2025-05-16T22:55:11.467567Z TRACE parse{path="/tmp/.tmpBQJYFi"}:new{content="this is green2"}: rsnip::domain::content: SnippetContent::new called with: this is green2
[INFO] [stderr] 2025-05-16T22:55:11.467589Z TRACE parse{path="/tmp/.tmpBQJYFi"}:new{content="this is green2"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.467614Z DEBUG parse{path="/tmp/.tmpBQJYFi"}:new{content="this is green2"}: rsnip::domain::content: close time.busy=45.0µs time.idle=9.22µs
[INFO] [stderr] 2025-05-16T22:55:11.467672Z TRACE parse{path="/tmp/.tmpBQJYFi"}:new{content="this is yellow"}: rsnip::domain::content: SnippetContent::new called with: this is yellow
[INFO] [stderr] 2025-05-16T22:55:11.467695Z TRACE parse{path="/tmp/.tmpBQJYFi"}:new{content="this is yellow"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.467720Z DEBUG parse{path="/tmp/.tmpBQJYFi"}:new{content="this is yellow"}: rsnip::domain::content: close time.busy=46.5µs time.idle=9.10µs
[INFO] [stderr] 2025-05-16T22:55:11.467766Z TRACE parse{path="/tmp/.tmpBQJYFi"}:new{content="this is other"}: rsnip::domain::content: SnippetContent::new called with: this is other
[INFO] [stderr] 2025-05-16T22:55:11.467787Z TRACE parse{path="/tmp/.tmpBQJYFi"}:new{content="this is other"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.467810Z DEBUG parse{path="/tmp/.tmpBQJYFi"}:new{content="this is other"}: rsnip::domain::content: close time.busy=42.9µs time.idle=8.16µs
[INFO] [stderr] 2025-05-16T22:55:11.467846Z DEBUG parse{path="/tmp/.tmpBQJYFi"}: rsnip::infrastructure::parsers::default: close time.busy=468µs time.idle=8.15µs
[INFO] [stderr] 2025-05-16T22:55:11.468567Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=11.9µs time.idle=20.4µs
[INFO] [stderr] 2025-05-16T22:55:11.468659Z DEBUG parse{path="/tmp/.tmpbCXVVj"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpbCXVVj"
[INFO] [stderr] 2025-05-16T22:55:11.468793Z TRACE parse{path="/tmp/.tmpbCXVVj"}:new{content="line"}: rsnip::domain::content: SnippetContent::new called with: line
[INFO] [stderr] 2025-05-16T22:55:11.468832Z TRACE parse{path="/tmp/.tmpbCXVVj"}:new{content="line"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.468864Z DEBUG parse{path="/tmp/.tmpbCXVVj"}:new{content="line"}: rsnip::domain::content: close time.busy=70.7µs time.idle=12.0µs
[INFO] [stderr] 2025-05-16T22:55:11.468913Z DEBUG parse{path="/tmp/.tmpbCXVVj"}: rsnip::infrastructure::parsers::default: close time.busy=255µs time.idle=11.1µs
[INFO] [stderr] 2025-05-16T22:55:11.469354Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=8.85µs time.idle=14.1µs
[INFO] [stderr] 2025-05-16T22:55:11.469416Z DEBUG parse{path="/tmp/.tmpl8N4HE"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpl8N4HE"
[INFO] [stderr] 2025-05-16T22:55:11.469507Z TRACE parse{path="/tmp/.tmpl8N4HE"}:new{content="content"}: rsnip::domain::content: SnippetContent::new called with: content
[INFO] [stderr] 2025-05-16T22:55:11.469539Z TRACE parse{path="/tmp/.tmpl8N4HE"}:new{content="content"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.469567Z DEBUG parse{path="/tmp/.tmpl8N4HE"}:new{content="content"}: rsnip::domain::content: close time.busy=59.7µs time.idle=10.2µs
[INFO] [stderr] 2025-05-16T22:55:11.469595Z DEBUG get_snippets{snippet_type="test"}: rsnip::application::snippet_service: Loading snippets from /tmp/.tmptRsfci
[INFO] [stderr] 2025-05-16T22:55:11.469639Z DEBUG parse{path="/tmp/.tmpl8N4HE"}: rsnip::infrastructure::parsers::default: close time.busy=221µs time.idle=8.86µs
[INFO] [stderr] 2025-05-16T22:55:11.469654Z DEBUG get_snippets{snippet_type="test"}:create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.81µs time.idle=10.0µs
[INFO] [stderr] 2025-05-16T22:55:11.469704Z DEBUG get_snippets{snippet_type="test"}:parse{path="/tmp/.tmptRsfci"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmptRsfci"
[INFO] [stderr] 2025-05-16T22:55:11.469788Z TRACE get_snippets{snippet_type="test"}:parse{path="/tmp/.tmptRsfci"}:new{content="Content"}: rsnip::domain::content: SnippetContent::new called with: Content
[INFO] [stderr] 2025-05-16T22:55:11.469818Z TRACE get_snippets{snippet_type="test"}:parse{path="/tmp/.tmptRsfci"}:new{content="Content"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.469847Z DEBUG get_snippets{snippet_type="test"}:parse{path="/tmp/.tmptRsfci"}:new{content="Content"}: rsnip::domain::content: close time.busy=57.5µs time.idle=17.5µs
[INFO] [stderr] 2025-05-16T22:55:11.469881Z DEBUG get_snippets{snippet_type="test"}:parse{path="/tmp/.tmptRsfci"}: rsnip::infrastructure::parsers::default: close time.busy=176µs time.idle=8.49µs
[INFO] [stderr] 2025-05-16T22:55:11.469911Z DEBUG get_snippets{snippet_type="test"}: rsnip::application::snippet_service: close time.busy=327µs time.idle=11.8µs
[INFO] [stderr] 2025-05-16T22:55:11.469972Z DEBUG create{format=Scls}: rsnip::infrastructure::parsers: close time.busy=7.09µs time.idle=12.4µs
[INFO] [stderr] 2025-05-16T22:55:11.470024Z DEBUG parse{path="/tmp/.tmpttZK7r"}: rsnip::infrastructure::parsers::scls: Parsing SCLS format snippets from: "/tmp/.tmpttZK7r"
[INFO] [stderr] 2025-05-16T22:55:11.470203Z DEBUG parse{path="/nonexistent/file"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/nonexistent/file"
[INFO] [stderr] 2025-05-16T22:55:11.470253Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.14µs time.idle=11.6µs
[INFO] [stderr] 2025-05-16T22:55:11.470302Z DEBUG parse{path="/tmp/.tmpqd7UeN"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpqd7UeN"
[INFO] [stderr] 2025-05-16T22:55:11.466121Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:find_completion_exact{completion_type="test" user_input="date"}: rsnip::application::snippet_service: close time.busy=3.10ms time.idle=7.07µs
[INFO] [stderr] 2025-05-16T22:55:11.470330Z DEBUG parse{path="/tmp/.tmpttZK7r"}: rsnip::infrastructure::parsers::scls: close time.busy=302µs time.idle=9.57µs
[INFO] [stderr] 2025-05-16T22:55:11.470583Z DEBUG create{format=Scls}: rsnip::infrastructure::parsers: close time.busy=7.10µs time.idle=11.8µs
[INFO] [stderr] 2025-05-16T22:55:11.465405Z TRACE copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpkWKX8T"}:new{content="A red fruit"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.470635Z DEBUG parse{path="/nonexistent/file"}: rsnip::infrastructure::parsers::scls: Parsing SCLS format snippets from: "/nonexistent/file"
[INFO] [stderr] 2025-05-16T22:55:11.470667Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpkWKX8T"}:new{content="A red fruit"}: rsnip::domain::content: close time.busy=7.23ms time.idle=10.7µs
[INFO] [stderr] 2025-05-16T22:55:11.470689Z DEBUG create{format=Default}: rsnip::infrastructure::parsers: close time.busy=6.88µs time.idle=12.2µs
[INFO] [stderr] 2025-05-16T22:55:11.470395Z TRACE parse{path="/tmp/.tmpqd7UeN"}:new{content="this is green\nand nothing else"}: rsnip::domain::content: SnippetContent::new called with: this is green
[INFO] [stderr] and nothing else
[INFO] [stderr] 2025-05-16T22:55:11.470734Z TRACE parse{path="/tmp/.tmpqd7UeN"}:new{content="this is green\nand nothing else"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.470740Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}:get_snippets{snippet_type="test"}:parse{path="/tmp/.tmpkWKX8T"}: rsnip::infrastructure::parsers::default: close time.busy=7.51ms time.idle=10.8µs
[INFO] [stderr] 2025-05-16T22:55:11.470748Z DEBUG parse{path="/tmp/.tmpDpDL6J"}: rsnip::infrastructure::parsers::default: Parsing default format snippets from: "/tmp/.tmpDpDL6J"
[INFO] [stderr] 2025-05-16T22:55:11.470786Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}:get_snippets{snippet_type="test"}: rsnip::application::snippet_service: close time.busy=8.92ms time.idle=7.39µs
[INFO] [stderr] 2025-05-16T22:55:11.470688Z DEBUG parse{path="/nonexistent/file"}: rsnip::infrastructure::parsers::scls: close time.busy=51.4µs time.idle=9.27µs
[INFO] [stderr] 2025-05-16T22:55:11.470821Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}:find_completion_exact{completion_type="test" user_input="nonexistent"}: rsnip::application::snippet_service: close time.busy=8.97ms time.idle=8.16µs
[INFO] [stderr] 2025-05-16T22:55:11.470839Z DEBUG parse{path="/tmp/.tmpDpDL6J"}: rsnip::infrastructure::parsers::default: close time.busy=87.9µs time.idle=9.09µs
[INFO] [stderr] 2025-05-16T22:55:11.470854Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="nonexistent" exact=true}: rsnip::application::snippet_service: close time.busy=9.03ms time.idle=15.7µs
[INFO] [stderr] 2025-05-16T22:55:11.470765Z DEBUG parse{path="/tmp/.tmpqd7UeN"}:new{content="this is green\nand nothing else"}: rsnip::domain::content: close time.busy=369µs time.idle=10.6µs
[INFO] [stderr] 2025-05-16T22:55:11.470894Z DEBUG parse{path="/tmp/.tmpqd7UeN"}: rsnip::infrastructure::parsers::default: close time.busy=589µs time.idle=9.09µs
[INFO] [stderr] 2025-05-16T22:55:11.470916Z DEBUG create{format=Scls}: rsnip::infrastructure::parsers: close time.busy=7.08µs time.idle=12.1µs
[INFO] [stderr] 2025-05-16T22:55:11.470913Z TRACE copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}:copy_to_clipboard{text="2025-05-16"}: rsnip::infrastructure::clipboard: close time.busy=82.8µs time.idle=11.5µs
[INFO] [stderr] 2025-05-16T22:55:11.470977Z DEBUG copy_snippet_to_clipboard{completion_type="test" input="date" exact=true}: rsnip::application::snippet_service: close time.busy=7.98ms time.idle=11.2µs
[INFO] [stderr] 2025-05-16T22:55:11.470985Z DEBUG parse{path="/tmp/.tmp4Ppr96"}: rsnip::infrastructure::parsers::scls: Parsing SCLS format snippets from: "/tmp/.tmp4Ppr96"
[INFO] [stderr] 2025-05-16T22:55:11.471218Z DEBUG parse{path="/nonexistent/file"}: rsnip::infrastructure::parsers::default: close time.busy=1.01ms time.idle=19.0µs
[INFO] [stderr] 2025-05-16T22:55:11.471647Z DEBUG parse{path="/tmp/.tmpw9Zd3L"}: rsnip::infrastructure::parsers::vcode: Parsing VSCode format snippets from: "/tmp/.tmpw9Zd3L"
[INFO] [stderr] 2025-05-16T22:55:11.472018Z TRACE parse{path="/tmp/.tmpw9Zd3L"}:new{content="fn main() {\n    println!(\"Hello, world!\");\n}"}: rsnip::domain::content: SnippetContent::new called with: fn main() {
[INFO] [stderr]     println!("Hello, world!");
[INFO] [stderr] }
[INFO] [stderr] 2025-05-16T22:55:11.472079Z TRACE parse{path="/tmp/.tmpw9Zd3L"}:new{content="fn main() {\n    println!(\"Hello, world!\");\n}"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.472140Z DEBUG parse{path="/tmp/.tmpw9Zd3L"}:new{content="fn main() {\n    println!(\"Hello, world!\");\n}"}: rsnip::domain::content: close time.busy=140µs time.idle=13.4µs
[INFO] [stderr] 2025-05-16T22:55:11.472323Z TRACE parse{path="/tmp/.tmpw9Zd3L"}:new{content="fn ${1:function_name}(${2:params}) -> ${3:ReturnType} {\n    ${4:// function body}\n}"}: rsnip::domain::content: SnippetContent::new called with: fn ${1:function_name}(${2:params}) -> ${3:ReturnType} {
[INFO] [stderr]     ${4:// function body}
[INFO] [stderr] }
[INFO] [stderr] 2025-05-16T22:55:11.472400Z TRACE parse{path="/tmp/.tmpw9Zd3L"}:new{content="fn ${1:function_name}(${2:params}) -> ${3:ReturnType} {\n    ${4:// function body}\n}"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.472545Z DEBUG parse{path="/tmp/.tmpw9Zd3L"}:new{content="fn ${1:function_name}(${2:params}) -> ${3:ReturnType} {\n    ${4:// function body}\n}"}: rsnip::domain::content: close time.busy=140µs time.idle=12.7µs
[INFO] [stderr] 2025-05-16T22:55:11.472697Z DEBUG parse{path="/tmp/.tmpw9Zd3L"}: rsnip::infrastructure::parsers::vcode: close time.busy=1.08ms time.idle=11.8µs
[INFO] [stderr] 2025-05-16T22:55:11.473412Z DEBUG create{format=Scls}: rsnip::infrastructure::parsers: close time.busy=7.10µs time.idle=12.7µs
[INFO] [stderr] 2025-05-16T22:55:11.473476Z DEBUG parse{path="/tmp/.tmpGslkSo"}: rsnip::infrastructure::parsers::scls: Parsing SCLS format snippets from: "/tmp/.tmpGslkSo"
[INFO] [stdout] test application::test_snippet_service::given_fuzzy_match_when_finding_completion_then_returns_best_match ... ok
[INFO] [stderr] 2025-05-16T22:55:11.473868Z DEBUG parse{path="/tmp/.tmpQiRoXo"}: rsnip::infrastructure::parsers::vcode: Parsing VSCode format snippets from: "/tmp/.tmpQiRoXo"
[INFO] [stdout] test infrastructure::parsers::test_default::given_empty_file_when_parse_then_returns_empty_vec ... ok
[INFO] [stderr] 2025-05-16T22:55:11.473947Z DEBUG parse{path="/tmp/.tmpQiRoXo"}: rsnip::infrastructure::parsers::vcode: close time.busy=77.3µs time.idle=11.3µs
[INFO] [stdout] test infrastructure::parsers::test_scls::given_empty_scls_file_when_parse_then_returns_empty_vec ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_valid_snippet_file_when_parse_then_returns_correct_snippets ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_extra_text_outside_snippets_when_parse_then_ignores_it ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_malformed_snippet_without_closing_delimiter_when_parse_then_returns_error ... ok
[INFO] [stdout] test application::test_snippet_service::given_valid_snippet_file_when_getting_snippets_then_returns_snippets ... ok
[INFO] [stdout] test infrastructure::parsers::test_scls::given_malformed_toml_when_parse_then_returns_error ... ok
[INFO] [stderr] 2025-05-16T22:55:11.474678Z DEBUG parse{path="/tmp/.tmp5mcmuw"}: rsnip::infrastructure::parsers::vcode: Parsing VSCode format snippets from: "/tmp/.tmp5mcmuw"
[INFO] [stdout] test infrastructure::parsers::test_scls::given_nonexistent_file_when_parse_then_returns_error ... ok
[INFO] [stdout] test infrastructure::test_minijinja::given_static_content_when_rendering_then_returns_unchanged ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_missing_trailing_delimiter_when_parse_then_returns_error ... ok
[INFO] [stderr] 2025-05-16T22:55:11.475019Z  INFO rsnip::infrastructure::minijinja: Executing shell command: echo Hello
[INFO] [stdout] test application::test_snippet_service::given_nonexistent_snippet_when_copying_then_returns_none ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_snippet_with_comments_when_parse_then_preserves_comments ... ok
[INFO] [stdout] test infrastructure::parsers::test_default::given_nonexistent_file_when_parse_then_returns_error ... ok
[INFO] [stdout] test infrastructure::parsers::test_vcode::given_valid_vscode_file_when_parse_then_returns_snippets ... ok
[INFO] [stdout] test infrastructure::parsers::test_vcode::given_empty_vscode_file_when_parse_then_returns_empty_vec ... ok
[INFO] [stderr] 2025-05-16T22:55:11.477412Z DEBUG parse{path="/tmp/.tmp3Pjp1k"}: rsnip::infrastructure::parsers::vcode: Parsing VSCode format snippets from: "/tmp/.tmp3Pjp1k"
[INFO] [stderr] 2025-05-16T22:55:11.477558Z TRACE parse{path="/tmp/.tmp3Pjp1k"}:new{content="println!(\"${1:message}\");"}: rsnip::domain::content: SnippetContent::new called with: println!("${1:message}");
[INFO] [stderr] 2025-05-16T22:55:11.477608Z TRACE parse{path="/tmp/.tmp3Pjp1k"}:new{content="println!(\"${1:message}\");"}: rsnip::domain::content: Detected as static
[INFO] [stderr] 2025-05-16T22:55:11.477630Z  INFO rsnip::infrastructure::minijinja: Executing shell command: nonexistent_command
[INFO] [stderr] 2025-05-16T22:55:11.477643Z DEBUG parse{path="/tmp/.tmp3Pjp1k"}:new{content="println!(\"${1:message}\");"}: rsnip::domain::content: close time.busy=83.4µs time.idle=11.3µs
[INFO] [stderr] 2025-05-16T22:55:11.477693Z DEBUG parse{path="/tmp/.tmp3Pjp1k"}: rsnip::infrastructure::parsers::vcode: close time.busy=279µs time.idle=14.6µs
[INFO] [stderr] 2025-05-16T22:55:11.482060Z TRACE parse{path="/tmp/.tmp4Ppr96"}:new{content="print({{ param1 }})"}: rsnip::domain::content: SnippetContent::new called with: print({{ param1 }})
[INFO] [stderr] 2025-05-16T22:55:11.482125Z TRACE parse{path="/tmp/.tmp4Ppr96"}:new{content="print({{ param1 }})"}: rsnip::domain::content: Detected as template
[INFO] [stderr] 2025-05-16T22:55:11.482183Z DEBUG parse{path="/tmp/.tmp4Ppr96"}:new{content="print({{ param1 }})"}: rsnip::domain::content: close time.busy=128µs time.idle=18.1µs
[INFO] [stderr] 2025-05-16T22:55:11.482851Z TRACE parse{path="/tmp/.tmp4Ppr96"}:new{content="def {{ name }}({{ args }}):\n    {{ pass }}"}: rsnip::domain::content: SnippetContent::new called with: def {{ name }}({{ args }}):
[INFO] [stderr]     {{ pass }}
[INFO] [stderr] 2025-05-16T22:55:11.482893Z TRACE parse{path="/tmp/.tmp4Ppr96"}:new{content="def {{ name }}({{ args }}):\n    {{ pass }}"}: rsnip::domain::content: Detected as template
[INFO] [stderr] 2025-05-16T22:55:11.482929Z DEBUG parse{path="/tmp/.tmp4Ppr96"}:new{content="def {{ name }}({{ args }}):\n    {{ pass }}"}: rsnip::domain::content: close time.busy=77.5µs time.idle=10.9µs
[INFO] [stderr] 2025-05-16T22:55:11.482996Z DEBUG parse{path="/tmp/.tmp4Ppr96"}: rsnip::infrastructure::parsers::scls: close time.busy=12.0ms time.idle=10.9µs
[INFO] [stdout] test infrastructure::test_minijinja::given_template_with_date_arithmetic_when_rendering_then_calculates_correctly ... ok
[INFO] [stdout] test infrastructure::test_minijinja::given_template_with_add_days_when_rendering_then_calculates_correctly ... ok
[INFO] [stdout] test infrastructure::parsers::test_vcode::given_single_line_body_when_parse_then_handles_correctly ... ok
[INFO] [stdout] test infrastructure::test_minijinja::given_template_with_shell_command_when_rendering_then_executes ... ok
[INFO] [stdout] test infrastructure::parsers::test_scls::given_valid_scls_file_when_parse_then_returns_snippets ... ok
[INFO] [stderr] 2025-05-16T22:55:11.484972Z TRACE parse{path="/tmp/.tmpGslkSo"}:new{content="class {{ ClassName }}:\n    def __init__(self):\n        {{ pass }}\n"}: rsnip::domain::content: SnippetContent::new called with: class {{ ClassName }}:
[INFO] [stderr]     def __init__(self):
[INFO] [stderr]         {{ pass }}
[INFO] [stderr] 
[INFO] [stderr] 2025-05-16T22:55:11.485027Z TRACE parse{path="/tmp/.tmpGslkSo"}:new{content="class {{ ClassName }}:\n    def __init__(self):\n        {{ pass }}\n"}: rsnip::domain::content: Detected as template
[INFO] [stderr] 2025-05-16T22:55:11.485060Z DEBUG parse{path="/tmp/.tmpGslkSo"}:new{content="class {{ ClassName }}:\n    def __init__(self):\n        {{ pass }}\n"}: rsnip::domain::content: close time.busy=103µs time.idle=13.8µs
[INFO] [stderr] 2025-05-16T22:55:11.485110Z DEBUG parse{path="/tmp/.tmpGslkSo"}: rsnip::infrastructure::parsers::scls: close time.busy=11.6ms time.idle=9.09µs
[INFO] [stdout] test infrastructure::parsers::test_scls::given_multiline_array_body_when_parse_then_handles_correctly ... ok
[INFO] [stdout] test infrastructure::test_minijinja::given_template_with_env_var_when_rendering_then_substitutes_value ... ok
[INFO] [stderr] 2025-05-16T22:55:11.489413Z DEBUG create{format=Scls}: rsnip::infrastructure::parsers: close time.busy=10.6µs time.idle=20.6µs
[INFO] [stderr] 2025-05-16T22:55:11.489506Z DEBUG parse{path="/tmp/.tmp88cOI6"}: rsnip::infrastructure::parsers::scls: Parsing SCLS format snippets from: "/tmp/.tmp88cOI6"
[INFO] [stderr] 2025-05-16T22:55:11.490585Z TRACE parse{path="/tmp/.tmp88cOI6"}:new{content="{{ first }} {{ second }} {{ param3 }}"}: rsnip::domain::content: SnippetContent::new called with: {{ first }} {{ second }} {{ param3 }}
[INFO] [stderr] 2025-05-16T22:55:11.490629Z TRACE parse{path="/tmp/.tmp88cOI6"}:new{content="{{ first }} {{ second }} {{ param3 }}"}: rsnip::domain::content: Detected as template
[INFO] [stderr] 2025-05-16T22:55:11.490659Z DEBUG parse{path="/tmp/.tmp88cOI6"}:new{content="{{ first }} {{ second }} {{ param3 }}"}: rsnip::domain::content: close time.busy=74.4µs time.idle=11.6µs
[INFO] [stderr] 2025-05-16T22:55:11.490713Z DEBUG parse{path="/tmp/.tmp88cOI6"}: rsnip::infrastructure::parsers::scls: close time.busy=1.20ms time.idle=18.1µs
[INFO] [stderr] 2025-05-16T22:55:11.490752Z  INFO rsnip::infrastructure::minijinja: Executing shell command: echo hello; rm -rf /
[INFO] [stderr] 2025-05-16T22:55:11.491088Z  INFO rsnip::infrastructure::minijinja: Executing shell command: echo hello | rm -rf /
[INFO] [stderr] 2025-05-16T22:55:11.491394Z  INFO rsnip::infrastructure::minijinja: Executing shell command: echo hello && rm -rf /
[INFO] [stderr] 2025-05-16T22:55:11.491661Z  INFO rsnip::infrastructure::minijinja: Executing shell command: sudo echo hello
[INFO] [stderr] 2025-05-16T22:55:11.491963Z  INFO rsnip::infrastructure::minijinja: Executing shell command: `echo hello`
[INFO] [stderr] 2025-05-16T22:55:11.492263Z  INFO rsnip::infrastructure::minijinja: Executing shell command: $(echo hello)
[INFO] [stdout] test infrastructure::test_minijinja::given_template_with_date_when_rendering_then_formats_date ... ok
[INFO] [stdout] test infrastructure::test_minijinja::given_template_with_invalid_shell_command_when_rendering_then_returns_error ... ok
[INFO] [stdout] test infrastructure::parsers::test_scls::given_snippet_with_named_placeholders_when_parse_then_converts_correctly ... ok
[INFO] [stdout] test infrastructure::test_minijinja::given_template_with_dangerous_shell_commands_then_returns_error ... ok
[INFO] [stdout] test application::test_snippet_service::given_template_snippet_when_copying_then_returns_rendered_content ... FAILED
[INFO] [stderr] 2025-05-16T22:55:11.620561Z DEBUG parse{path="/tmp/.tmp5mcmuw"}: rsnip::infrastructure::parsers::vcode: close time.busy=146ms time.idle=15.4µs
[INFO] [stdout] test infrastructure::parsers::test_vcode::given_malformed_json_when_parse_then_returns_error ... ok
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout] 
[INFO] [stdout] ---- application::test_snippet_service::given_template_snippet_when_copying_then_returns_rendered_content stdout ----
[INFO] [stdout] Error: Failed to initialize clipboard
[INFO] [stdout] 
[INFO] [stdout] Caused by:
[INFO] [stdout]     Unknown error while interacting with the clipboard: X11 server connection timed out because it was unreachable
[INFO] [stdout] 
[INFO] [stdout] Stack backtrace:
[INFO] [stdout]    0: <E as anyhow::context::ext::StdError>::ext_context
[INFO] [stdout]              at /opt/rustwide/cargo-home/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.95/src/backtrace.rs:27:14
[INFO] [stdout]    1: anyhow::context::<impl anyhow::Context<T,E> for core::result::Result<T,E>>::context
[INFO] [stdout]              at /opt/rustwide/cargo-home/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.95/src/context.rs:54:31
[INFO] [stdout]    2: rsnip::infrastructure::clipboard::copy_to_clipboard
[INFO] [stdout]              at ./src/infrastructure/clipboard.rs:7:25
[INFO] [stdout]    3: rsnip::application::snippet_service::SnippetService::copy_snippet_to_clipboard
[INFO] [stdout]              at ./src/application/snippet_service.rs:151:13
[INFO] [stdout]    4: test_lib::application::test_snippet_service::given_template_snippet_when_copying_then_returns_rendered_content
[INFO] [stdout]              at ./tests/application/test_snippet_service.rs:167:18
[INFO] [stdout]    5: test_lib::application::test_snippet_service::given_template_snippet_when_copying_then_returns_rendered_content::{{closure}}
[INFO] [stdout]              at ./tests/application/test_snippet_service.rs:157:75
[INFO] [stdout]    6: core::ops::function::FnOnce::call_once
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/core/src/ops/function.rs:250:5
[INFO] [stdout]    7: core::ops::function::FnOnce::call_once
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/core/src/ops/function.rs:250:5
[INFO] [stdout]    8: test::__rust_begin_short_backtrace
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/test/src/lib.rs:648:18
[INFO] [stdout]    9: test::run_test_in_process::{{closure}}
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/test/src/lib.rs:671:60
[INFO] [stdout]   10: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/core/src/panic/unwind_safe.rs:272:9
[INFO] [stdout]   11: std::panicking::try::do_call
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/panicking.rs:589:40
[INFO] [stdout]   12: std::panicking::try
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/panicking.rs:552:19
[INFO] [stdout]   13: std::panic::catch_unwind
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/panic.rs:359:14
[INFO] [stdout]   14: test::run_test_in_process
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/test/src/lib.rs:671:27
[INFO] [stdout]   15: test::run_test::{{closure}}
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/test/src/lib.rs:592:43
[INFO] [stdout]   16: test::run_test::{{closure}}
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/test/src/lib.rs:622:41
[INFO] [stdout]   17: std::sys::backtrace::__rust_begin_short_backtrace
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/sys/backtrace.rs:152:18
[INFO] [stdout]   18: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/thread/mod.rs:559:17
[INFO] [stdout]   19: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/core/src/panic/unwind_safe.rs:272:9
[INFO] [stdout]   20: std::panicking::try::do_call
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/panicking.rs:589:40
[INFO] [stdout]   21: std::panicking::try
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/panicking.rs:552:19
[INFO] [stdout]   22: std::panic::catch_unwind
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/panic.rs:359:14
[INFO] [stdout]   23: std::thread::Builder::spawn_unchecked_::{{closure}}
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/thread/mod.rs:557:30
[INFO] [stdout]   24: core::ops::function::FnOnce::call_once{{vtable.shim}}
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   25: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/alloc/src/boxed.rs:1966:9
[INFO] [stdout]   26: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/alloc/src/boxed.rs:1966:9
[INFO] [stdout]   27: std::sys::pal::unix::thread::Thread::new::thread_start
[INFO] [stdout]              at /rustc/414482f6a0d4e7290f614300581a0b55442552a3/library/std/src/sys/pal/unix/thread.rs:97:17
[INFO] [stdout]   28: <unknown>
[INFO] [stdout]   29: clone
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout]     application::test_snippet_service::given_template_snippet_when_copying_then_returns_rendered_content
[INFO] [stdout] 
[INFO] [stdout] test result: FAILED. 34 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.16s
[INFO] [stdout] 
[INFO] [stderr] error: test failed, to rerun pass `--test test_lib`
[INFO] running `Command { std: "docker" "inspect" "a7fe3e44dd6ab4b84b8a4c0dfad9c40e02a9cec75ef5468b75792de5ae6e2566", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a7fe3e44dd6ab4b84b8a4c0dfad9c40e02a9cec75ef5468b75792de5ae6e2566", kill_on_drop: false }`
[INFO] [stdout] a7fe3e44dd6ab4b84b8a4c0dfad9c40e02a9cec75ef5468b75792de5ae6e2566