Failing tests: tests/snapshots out of date

[oceanlewis]

It looks like the latest few releases have broken tests caused by a change in loggin output. Not sure when it happened, but it's causing tests to fail. Here's the output from running cargo test locally on my machine:

     Running target/debug/deps/echo-7079832437b58e65

running 4 tests
test with_poll ... FAILED
test with_announce ... FAILED
test without_announce ... FAILED
test with_error ... FAILED

failures:

---- with_poll stdout ----
thread 'with_poll' panicked at 'Unexpected failure.
code=<interrupted>
stderr=```"WARN - Polling for changes every 500ms ms\n"```
code=<interrupted>
stdout=```""```
stderr=```"WARN - Polling for changes every 500ms ms\n"```
', /Users/david/.cargo/registry/src/jackfan.us.kg-1ecc6299db9ec823/assert_cmd-1.0.3/src/assert.rs:149:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

---- with_announce stdout ----
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Snapshot Differences ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Snapshot file: tests/snapshots/echo__with_announce.stderr.snap
Snapshot: with_announce.stderr
Source: tests/echo.rs:132
-old snapshot
+new results
───────────────────────────────────────────────────────────────────────────────────
std_to_string(&mut main.stderr)
────────────┬──────────────────────────────────────────────────────────────────────
    1       │-WARN - Polling for changes every 500 ms
    2       │-
          1 │+WARN - Polling for changes every 500ms ms
          2 │+
────────────┴──────────────────────────────────────────────────────────────────────
stored new snapshot /Users/david/Developer/src/cargo-watch/tests/snapshots/echo__with_announce.stderr.snap.new
To update snapshots run `cargo insta review`
thread 'with_announce' panicked at 'snapshot assertion for 'with_announce.stderr' failed in line 132', /Users/david/.cargo/registry/src/jackfan.us.kg-1ecc6299db9ec823/insta-0.16.1/src/runtime.rs:995:9

---- without_announce stdout ----
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Snapshot Differences ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Snapshot file: tests/snapshots/echo__without_announce.stdout.snap
Snapshot: without_announce.stdout
Source: tests/echo.rs:167
-old snapshot
+new results
───────────────────────────────────────────────────────────────────────────────────
std_to_string(&mut main.stdout)
────────────┬──────────────────────────────────────────────────────────────────────
    1       │-without announce
    2       │-
────────────┴──────────────────────────────────────────────────────────────────────
stored new snapshot /Users/david/Developer/src/cargo-watch/tests/snapshots/echo__without_announce.stdout.snap.new
To update snapshots run `cargo insta review`
thread 'without_announce' panicked at 'snapshot assertion for 'without_announce.stdout' failed in line 167', /Users/david/.cargo/registry/src/jackfan.us.kg-1ecc6299db9ec823/insta-0.16.1/src/runtime.rs:995:9

---- with_error stdout ----
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Snapshot Differences ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Snapshot file: tests/snapshots/echo__with_error.stderr.snap
Snapshot: with_error.stderr
Source: tests/echo.rs:202
-old snapshot
+new results
───────────────────────────────────────────────────────────────────────────────────
std_to_string(&mut main.stderr)
────────────┬──────────────────────────────────────────────────────────────────────
    1       │-WARN - Polling for changes every 500 ms
    2       │-
          1 │+WARN - Polling for changes every 500ms ms
          2 │+
────────────┴──────────────────────────────────────────────────────────────────────
stored new snapshot /Users/david/Developer/src/cargo-watch/tests/snapshots/echo__with_error.stderr.snap.new
To update snapshots run `cargo insta review`
thread 'with_error' panicked at 'snapshot assertion for 'with_error.stderr' failed in line 202', /Users/david/.cargo/registry/src/jackfan.us.kg-1ecc6299db9ec823/insta-0.16.1/src/runtime.rs:995:9


failures:
    with_announce
    with_error
    with_poll
    without_announce

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

I think this might be related to Jenkins not having been run during the last few releases.

[passcod]

The tests don't really run on macOS to start with. I’ve restored running them in CI anyway.

[oceanlewis]

Oh, they don't? Weird, they seem to at least run. I think either the Debug or Display impl of the duration type being used in the failing test above has changed and that's the reason the tests are failing.

I'm bringing it up because right now Nixpkgs packages this tool but the package is currently broken in repo for macOS. It's a great tool, maybe I can try my hand at a fix if you can point me in the direction of this Debug|Display impl that's causing failing tests?

Or if there's a root cause I'm not seeing that's further work, I suppose I can send a PR to Nixpkgs to skip tests on Darwin.

[passcod]

I've fixed the display discrepancy tests (well, I've changed the tests to pass, and I'll fix the actual issue upstream in the next point update), but the tests still won't work on macOS for platform differences reasons at a different level (iirc, notify, due to fsevents, but might be something else), so it's not really testing what it's purporting to. They don't work on Windows for... yet another reason, which I'm really confused about and haven't tracked down.

You can absolutely use this issue as justification for not running tests in the nixos package, if needed.

Also, the tests are stateful and need a directory to be cleared (or to run somewhere that's cleared every time, like CI) to complete, which is awful, but as mentioned in the latest commit here, the real behaviour tests are in watchexec, and it wasn't really a priority to have them here, given it's quite a bare "shell" over it. Always happy to have more / better tests contributed, of course.

[oceanlewis]

Weird! Would the issue in tweet you linked happen to be cause by Windows using a different encoding (UTF-16, perhaps?) than on the usual unix-y system?

[passcod]

Most likely, but how to make it either work...?

[rpearce]

I'm seeing the same thing when trying to patch this for nixpkgs to include libiconv as a Darwin dependency: NixOS/nixpkgs#120688

[oceanlewis]

Most likely, but how to make it either work...?

That's a good question. I don't know how this comparison is being made, but some kind of normalization would probably be necessary? I don't know much about the idiosyncrasies of the Windows platform, but maybe doing an in-memory comparison where you specifically encode the file contents to UTF-8 would fix the issue?

That is even if that's what's exploding.

[passcod]

It's all done by the insta tool, so maybe that's got an option. It might also be newlines: mitsuhiko/insta#172

[oceanlewis]

Well, updating insta to the latest 1.7.1 does still run the tests properly, but there's still an issue with an extra ms being tacked on to the output that's failing the tests same as above.

[passcod]

watchexec/watchexec#191

[passcod]

I've updated the tests to insta 1.7.1 among other things for 7.7.1, may help here.

[rpearce]

@davidarmstronglewis Can you handle the nixpkgs side to get it to latest?

[oceanlewis]

PR's been updated, confirming that I can disable the disabling of tests :)
Nice work!