"spec" tests are nearly impossible to debug due to bespoke testrunner

[waynr]

Describe the bug

dprint-plugin-markdown version: main branch

I'm currently attempting to work through tests broken by my local copy of the PR branch in https://github.com/dprint/dprint-plugin-markdown/pull/108. I've got several local commits on top of what I've pushed to that branch so far, so I am making progress. However, I am currently encountering tests broken by my changes that either don't report anything or seem to simply hang indefinitely.

example: test fails with no explanation

test specs::Issues::Issue0018 ... (12ms)
  should format as-is fail

test specs::Issues::Issue0052 ... (5ms)
  should keep meta information when there is no newline at the end fail

Granted these to print what appear to be test headings alongside the fail indicator, but what's missing for these tests is some kind of "here is the expect output: {expected}\nhere is the actual output: {actual}" message.

example: test helper function seems to panic

test specs::Lists::Lists_ListKind_Asterisks ... (18ms)
  should format an unordered list with asterisks ok
  should format an unordered list with plus signs ok
  should handle multiple lists one after the other ok
thread '<unnamed>' panicked at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/printer.rs:623:7:
Debug panic! Found a newline in the string. Before sending the string to the printer it needs to be broken up and the newline sent as a PrintItem::NewLine. <details>
   <summary>❌ Failure Steps</summary>
stack backtrace:
   0: rust_begin_unwind
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/std/src/panicking.rs:597:5
   1: core::panicking::panic_fmt
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/panicking.rs:72:14
   2: dprint_core::formatting::printer::Printer::validate_string
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/printer.rs:623:7
   3: dprint_core::formatting::printer::Printer::handle_string
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/printer.rs:598:5
   4: dprint_core::formatting::printer::Printer::handle_print_node
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/printer.rs:291:34
   5: dprint_core::formatting::printer::Printer::inner_print
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/printer.rs:151:7
   6: dprint_core::formatting::printer::Printer::print
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/printer.rs:133:5
   7: dprint_core::formatting::print::print_with_allocator
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/print.rs:67:9
   8: dprint_core::formatting::print::format::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/print.rs:41:18
   9: dprint_core::formatting::thread_state::with_bump_allocator::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/thread_state.rs:113:5
  10: std::thread::local::LocalKey<T>::try_with
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/std/src/thread/local.rs:270:16
  11: std::thread::local::LocalKey<T>::with
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/std/src/thread/local.rs:246:9
  12: dprint_core::formatting::thread_state::with_bump_allocator
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/thread_state.rs:111:3
  13: dprint_core::formatting::print::format
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-core-0.66.2/src/formatting/print.rs:40:16
  14: dprint_plugin_markdown::format_text::format_text_inner
             at ./src/format_text.rs:40:11
  15: dprint_plugin_markdown::format_text::format_text
             at ./src/format_text.rs:20:16
  16: specs::main::{{closure}}
             at ./tests/spec_test.rs:32:9
  17: dprint_development::spec_helpers::run_specs::run_spec::{{closure}}::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-development-0.10.1/src/spec_helpers.rs:148:53
  18: core::ops::function::FnOnce::call_once
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/ops/function.rs:250:5
  19: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/panic/unwind_safe.rs:271:9
  20: std::panicking::try::do_call
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/std/src/panicking.rs:504:40
  21: __rust_try
  22: std::panicking::try
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/std/src/panicking.rs:468:19
  23: std::panic::catch_unwind
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/std/src/panic.rs:142:14
  24: dprint_development::spec_helpers::run_specs::run_spec::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-development-0.10.1/src/spec_helpers.rs:148:20
  25: dprint_development::spec_helpers::run_specs::run_spec
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-development-0.10.1/src/spec_helpers.rs:161:20
  26: dprint_development::spec_helpers::run_specs::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-development-0.10.1/src/spec_helpers.rs:100:35
  27: file_test_runner::runner::ThreadPoolTestRunner<TData>::new::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/file_test_runner-0.5.0/src/runner.rs:401:24
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Panic in spec 'html in list' in ./tests/specs/Lists/Lists_All.txt

thread '<unnamed>' panicked at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-development-0.10.1/src/spec_helpers.rs:152:27:
called `Result::unwrap()` on an `Err` value: Any { .. }
stack backtrace:
   0: rust_begin_unwind
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/std/src/panicking.rs:597:5
   1: core::panicking::panic_fmt
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/panicking.rs:72:14
   2: core::result::unwrap_failed
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/result.rs:1652:5
   3: core::result::Result<T,E>::unwrap
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/result.rs:1077:23
   4: dprint_development::spec_helpers::run_specs::run_spec::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-development-0.10.1/src/spec_helpers.rs:152:20
   5: dprint_development::spec_helpers::run_specs::run_spec
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-development-0.10.1/src/spec_helpers.rs:161:20
   6: dprint_development::spec_helpers::run_specs::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dprint-development-0.10.1/src/spec_helpers.rs:100:35
   7: file_test_runner::runner::ThreadPoolTestRunner<TData>::new::{{closure}}
             at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/file_test_runner-0.5.0/src/runner.rs:401:24
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
test specs::Lists::Lists_All has been running for more than 60 seconds

The test suite as a whole gets stuck waiting for test specs::Lists::Lists_All even though the file_test_runner mechanisms couldn't possibly detect that it finishes.

I think this points to a problem with panic recovery in the test runner. Do newer versions of file_test_runner properly recover its threads from panics?

I realize that the tests work fine on main branch and are only failing this way on my branch so there is something I am ultimately doing wrong here. But normally when writing rust code with panics coming from todo!() or unimplemented!() the built-in test runner itself recovers gracefully enough to print relevant error messages.

[waynr]

Okay I've figured out that if I filter for a specific test case, it will output the actual vs expected in a helpful manner:

zsh/5 13154 [101]  (git)-[upgrade-dep/pulldown-cmark]-% cargo test specs::Issues::Issue0018
    Finished test [unoptimized + debuginfo] target(s) in 0.03s
     Running unittests src/lib.rs (target/debug/deps/dprint_plugin_markdown-2102e1c6bdb97ef3)

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 11 filtered out; finished in 0.00s

     Running tests/newline_test.rs (target/debug/deps/newline_test-ba542eeabbda887f)

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 4 filtered out; finished in 0.00s

     Running tests/spec_test.rs (target/debug/deps/specs-e5bd8a13f89a1de6)

     Running specs::Issues

test specs::Issues::Issue0018 ... (4ms)
  should format as-is fail

spec failures:

---- specs::Issues::Issue0018 ----
Failed:   should format as-is (./tests/specs/Issues/Issue0018.txt)
Expected: `"- [ ] a\n- [ ] b\n\n- [ ] c\n- [ ] d\n"`,
Actual:   `"- [ ]a\n- [ ]b\n\n- [ ]c\n- [ ]d\n"`,`,
Diff:
-- [ ] a
-- [ ] b
+- [ ]a
+- [ ]b

-- [ ] c
-- [ ] d
+- [ ]c
+- [ ]d

Test file: ./tests/specs/Issues/Issue0018.txt

failures:
    specs::Issues::Issue0018

thread 'main' panicked at /home/wayne/.cargo/registry/src/index.crates.io-6f17d22bba15001f/file_test_runner-0.5.0/src/runner.rs:176:5

[waynr]

For the specific test case I highlighted in my last comment it almost looks like the pulldown-cmark crate changed the way it tokenizes list items, ie they no longer include in the initial space between the list item symbol and the content of the list as part of the content :thinking:

If that's the case, then code that generates the formatted output would need to insert a new space, right?

[waynr]

I'm going to close this issue since I figured out my original problem and it doesn't seem likely worth the effort for this project to make significant changes to the test runner for my sake. I've since learned to deal with the test runner's idiosyncrasies.

For what it's worth, the original problem:

Debug panic! Found a newline in the string. Before sending the string to the printer it needs to be broken up and the newline sent as a PrintItem::NewLine. <details>

...resulted from a change I naively made to gen_html that resulted in capturing a newline in a PrintItem.