File source tests are inherently flaky

[thomasqueirozb]

All tests use 500 millis sleeps instead of actually waiting for files to be processed/checkpointed/observed in any manner.

It also doesn't help that some stuff internally is using fixed timeouts but we shouldn't arbitrary sleep.

Related issues:

• Test file_start_position_server_restart_acknowledged is flakey on non-Linux #7988

[thomasqueirozb]

Example:

test sources::file::tests::test_oldest_first ... FAILED

Run

Relevant output:

  TRY 4 FAIL [   2.644s] vector sources::file::tests::test_oldest_first
  stdout ───

    running 1 test
    test sources::file::tests::test_oldest_first ... FAILED

    failures:

    failures:
        sources::file::tests::test_oldest_first

    test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 1711 filtered out; finished in 2.62s

  stderr ───

    thread 'sources::file::tests::test_oldest_first' panicked at src\sources\file.rs:2169:9:
    assertion failed: `(left == right)`'
      left: `"[Bytes(b\"hello i am the old file\")]"`
     right: `"[Bytes(b\"hello i am the old file\"), Bytes(b\"i have been around a while\"), Bytes(b\"you should definitely read all of me first\"), Bytes(b\"i'm new\"), Bytes(b\"hopefully you read all the old stuff first\"),..."` (truncated)

    Differences (-left|+right):
     [
         Bytes(
             b"hello i am the old file",
         ),
    +    Bytes(
    +        b"i have been around a while",
    +    ),
    +    Bytes(
    +        b"you should definitely read all of me first",
    +    ),
    +    Bytes(
    +        b"i'm new",
    +    ),
    +    Bytes(
    +        b"hopefully you read all the old stuff first",
    +    ),
    +    Bytes(
    +        b"because otherwise i'm not going to make sense",
    +    ),
     ]


    note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

error: test run failed

[strophy]

I have started to get this error since v0.51.0 building under Alpine Linux:

  TRY 1 FAIL [   1.532s] (─────────) vector sources::file::tests::test_oldest_first
  stdout ───
    running 1 test
    test sources::file::tests::test_oldest_first ... FAILED
    failures:
    failures:
        sources::file::tests::test_oldest_first
    test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 1812 filtered out; finished in 1.51s
  stderr ───
    thread 'sources::file::tests::test_oldest_first' panicked at src/sources/file.rs:2136:9:
    assertion failed: `(left == right)`'
      left: `"[Bytes(b\"i'm new\"), Bytes(b\"hopefully you read all the old stuff first\"), Bytes(b\"because otherwise i'm not going to make sense\"), Bytes(b\"hello i am the old file\"), Bytes(b\"i have been around a while..."` (truncated)
     right: `"[Bytes(b\"hello i am the old file\"), Bytes(b\"i have been around a while\"), Bytes(b\"you should definitely read all of me first\"), Bytes(b\"i'm new\"), Bytes(b\"hopefully you read all the old stuff first\"),..."` (truncated)
    Differences (-left|+right):
     [
         Bytes(
    +        b"hello i am the old file",
    +    ),
    +    Bytes(
    +        b"i have been around a while",
    +    ),
    +    Bytes(
    +        b"you should definitely read all of me first",
    +    ),
    +    Bytes(
             b"i'm new",
         ),
         Bytes(
             b"hopefully you read all the old stuff first",
         ),
         Bytes(
             b"because otherwise i'm not going to make sense",
         ),
    -    Bytes(
    -        b"hello i am the old file",
    -    ),
    -    Bytes(
    -        b"i have been around a while",
    -    ),
    -    Bytes(
    -        b"you should definitely read all of me first",
    -    ),
     ]
    note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

This looks a bit different to the way it fails above for you, but also weird that the test_fair_reads test broke at the same time, like this:

  TRY 1 FAIL [   1.532s] (─────────) vector sources::file::tests::test_fair_reads
  stdout ───

    running 1 test
    test sources::file::tests::test_fair_reads ... FAILED

    failures:

    failures:
        sources::file::tests::test_fair_reads

    test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 1812 filtered out; finished in 1.51s

  stderr ───

    thread 'sources::file::tests::test_fair_reads' panicked at src/sources/file.rs:2084:9:
    assertion failed: `(left == right)`'
      left: `"[Bytes(b\"and i am the new file\"), Bytes(b\"hello i am the old file\"), Bytes(b\"this should be interleaved with the old one\"), Bytes(b\"i have been around a while\"), Bytes(b\"which is fine because we want ..."` (truncated)
     right: `"[Bytes(b\"hello i am the old file\"), Bytes(b\"and i am the new file\"), Bytes(b\"i have been around a while\"), Bytes(b\"this should be interleaved with the old one\"), Bytes(b\"you can read newer files at th..."` (truncated)

    Differences (-left|+right):
     [
         Bytes(
    +        b"hello i am the old file",
    +    ),
    +    Bytes(
             b"and i am the new file",
         ),
         Bytes(
    -        b"hello i am the old file",
    +        b"i have been around a while",
         ),
         Bytes(
             b"this should be interleaved with the old one",
         ),
         Bytes(
    -        b"i have been around a while",
    -    ),
    -    Bytes(
    -        b"which is fine because we want fairness",
    -    ),
    -    Bytes(
             b"you can read newer files at the same time",
         ),
    +    Bytes(
    +        b"which is fine because we want fairness",
    +    ),
     ]


    note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Did something change about how these timings are handled in v0.51.0?

[thomasqueirozb]

Nothing has changed in that source lately, this might just be a flake. The issue you're seeing in those tests is that they don't flush to disk but they sleep after writing instead (very wrong). I'll follow up in a PR which should make them less flaky, however the tests are inherently flawed since there is no metric that is checked before assertions are made and everything is sleep based.

[thomasqueirozb]

After changes in that PR the most flaky test is now file_start_position_server_restart_unfinalized. It fails once every 5 tries or so.

[strophy]

I have updated to vector 0.52.0 and I am still getting this error every single time on ppc64le arch, other archs don't have the error:

  TRY 4 FAIL [   1.058s] (2108/2580) vector sources::file::tests::test_oldest_first
  stdout ───
    running 1 test
    test sources::file::tests::test_oldest_first ... FAILED
    failures:
    failures:
        sources::file::tests::test_oldest_first
    test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 1831 filtered out; finished in 1.04s
  stderr ───
    thread 'sources::file::tests::test_oldest_first' (42541) panicked at src/sources/file.rs:2157:9:
    assertion failed: `(left == right)`'
      left: `"[Bytes(b\"i'm new\"), Bytes(b\"hopefully you read all the old stuff first\"), Bytes(b\"because otherwise i'm not going to make sense\"), Bytes(b\"hello i am the old file\"), Bytes(b\"i have been around a while..."` (truncated)
     right: `"[Bytes(b\"hello i am the old file\"), Bytes(b\"i have been around a while\"), Bytes(b\"you should definitely read all of me first\"), Bytes(b\"i'm new\"), Bytes(b\"hopefully you read all the old stuff first\"),..."` (truncated)
    Differences (-left|+right):
     [
         Bytes(
    +        b"hello i am the old file",
    +    ),
    +    Bytes(
    +        b"i have been around a while",
    +    ),
    +    Bytes(
    +        b"you should definitely read all of me first",
    +    ),
    +    Bytes(
             b"i'm new",
         ),
         Bytes(
             b"hopefully you read all the old stuff first",
         ),
         Bytes(
             b"because otherwise i'm not going to make sense",
         ),
    -    Bytes(
    -        b"hello i am the old file",
    -    ),
    -    Bytes(
    -        b"i have been around a while",
    -    ),
    -    Bytes(
    -        b"you should definitely read all of me first",
    -    ),
     ]

Maybe it is falling back to Utc::now() for both files on this line? https://github.com/vectordotdev/vector/blob/v0.52.0/lib/file-source/src/file_server.rs#L129

[thomasqueirozb]

@strophy this is likely related to #24327 (related, not caused by). That PRs description provides some insight. I didn't dig that deep into it but it seems like the following code

        let older_path = dir.path().join("z_older_file");
        let mut older = File::create(&older_path).unwrap();
        older.sync_all().unwrap();

        let newer_path = dir.path().join("a_newer_file");
        let mut newer = File::create(&newer_path).unwrap();
        newer.sync_all().unwrap();

would sometimes make it so z_older_file and a_newer_file had the same timestamp, even though sync_all is called! That's my best guess at least, but it should be verifiable by removing the sleep in test_oldest_first.

Adding the sleep made it so the files had different creation times. If I had to guess is that your specific arch/fs is exhibiting this weird behavior even after 500ms.

Some debugging steps would be:

1. Insert a log or even a panic!() in that unwrap_or you mentioned to make sure that it is not defaulting to Utc::now().
2. Add some more sleeps here. Maybe sleep for 2 seconds or so.
3. Test any changes you made by running cargo test --no-run --lib, grab the output path target/debug/deps/vector-XXXX, and then run seq 1 5000 | parallel --progress --bar --halt now,fail=1 'true "{}"; if ! out=$(target/debug/deps/vector-XXXX sources::file::tests::test_oldest_first 2>&1); then echo "$out"; exit 1; fi'

[strophy]

@thomasqueirozb that helped me figure it out, it's an interesting issue! I made a small patch to force a panic like this:

--- a/lib/file-source/src/file_server.rs
+++ b/lib/file-source/src/file_server.rs
@@ -126,7 +126,9 @@ where
         let created = metadata.into_iter().map(|m| {
             m.and_then(|m| m.created())
                 .map(DateTime::<Utc>::from)
-                .unwrap_or_else(|_| Utc::now())
+                .unwrap_or_else(|e| {
+                    panic!("Failed to get file creation time, defaulting to Utc::now(). Error: {:?}", e);
+                })
         });
 
         let mut existing_files: Vec<(DateTime<Utc>, PathBuf, FileFingerprint)> = existing_files

And suddenly many more tests started failing on ppc64le like this:

  stderr ───
    thread 'tokio-runtime-worker' (42986) panicked at /builds/strophy/aports/testing/vector/src/vector-0.52.0/lib/file-source/src/file_server.rs:130:21:
    Failed to get file creation time, defaulting to Utc::now(). Error: Error { kind: Unsupported, message: "creation time is not available on this platform currently" }

It turns out the concept of "creation time" is not part of POSIX and was therefore only added as an extension in musl libc 1.2.5. Rust has been using 1.2.3 until a few days ago, so these errors should fix themselves once Rust 1.93.0 is released.