Potential BUG - specific package running cargo mutants indefinitely on Github CI

[ASuciuX]

Hey @sourcefrog , I've created this as Q&A, please let me know if it should be placed instead as general or something else.

There is a specific package in stacks-core repository called stacks-signer. The workflows that include the cargo mutants for it run indefinitely. Locally, on linux and mac os it finishes after a very short period of time as it is very small.

It happened with v24.2.0, v24.1.1, and the commit having dynamic timeout on top of v24.2.0.

The command is run without jobs and cargo nextest test threads 1 specified.

Debug runs that showcase the issue that appeared when running stacks-signer mutants:

1. Run working with cargo build and cargo nextest run before cargo mutants:
   Action run: https://github.com/ASuciuX/stacks-core/actions/runs/7901429286/attempts/2?pr=57
   Action file: https://github.com/stacks-network/actions/blob/8a7cb7ed0249b473d241b57228cd718d2bd1e3ef/stacks-core/mutation-testing/pr-differences/action.yml#L[…]9
2. Run not working without cargo build and cargo nextest run:
   Action run: https://github.com/ASuciuX/stacks-core/actions/runs/7901429286/attempts/3?pr=57
   Action file: https://github.com/stacks-network/actions/blob/801b21e8294c032686dab54b74cb579074141764/stacks-core/mutation-testing/pr-differences/action.yml#L[…]3
3. Run working with only cargo nextest run before cargo mutants:
   Action run: https://github.com/ASuciuX/stacks-core/actions/runs/7901429286?pr=57
   Action file: https://github.com/stacks-network/actions/blob/b9971c8063623e9f4dee82164652264cce703216/stacks-core/mutation-testing/pr-differences/action.yml#L[…]6

Could you please take a look at what might be the cause of this issue? It seems very specific and the fact that it works with cargo nextest called before cargo mutants is quite strange.

[sourcefrog]

Sounds like an interesting bug, thanks for the report.

[sourcefrog]

Just on a quick initial look

Run not working without cargo build and cargo nextest run:
Action run: https://github.com/ASuciuX/stacks-core/actions/runs/7901429286/attempts/3?pr=57

This does not seem to have failed or hung, though?

The actual mutants invocation says

Running mutants without shards on stackslib package
Found 3 mutants to test
 INFO Set test timeout to 35m 40s
ok       Unmutated baseline in 436.5s build + 1427.9s test
caught   stackslib/src/burnchains/affirmation.rs:547:5: replace read_prepare_phase_commits -> Result<Vec<Vec<LeaderBlockCommitOp>>, Error> with Ok(vec![]) in 156.5s build + 11.3s test
caught   stackslib/src/burnchains/affirmation.rs:547:5: replace read_prepare_phase_commits -> Result<Vec<Vec<LeaderBlockCommitOp>>, Error> with Ok(vec![vec![]]) in 26.5s build + 11.3s test
unviable stackslib/src/burnchains/affirmation.rs:547:5: replace read_prepare_phase_commits -> Result<Vec<Vec<LeaderBlockCommitOp>>, Error> with Ok(vec![vec![Default::default()]]) in 6.2s build
3 mutants tested in 34m 37s: 2 caught, 1 unviable

You have some kind of error in your "Output Mutants" script

/home/runner/work/_temp/08e87cce-b2ee-4783-8303-9ff8cb711203.sh: line 13: ==: command not found

That looks like it might just be a quoting bug in your shell script.

Are you sure that's the right link?

Can you reproduce this in a smaller invocation of just cargo-mutants without all the wrappers?

[ASuciuX]

That output error was related to how i was handling CI, it was expected to work in that way, but I updated it now to have false/true to check with in order to not show that error as well. The error in output job is because not all the other started jobs finished with a file output and it couldn't find the expected ones.

The problem is not in stackslib, even though that is the biggest package. It is in stacks-signer.

https://github.com/ASuciuX/stacks-core/actions/runs/7901429286/job/21566447350?pr=57#step:2:2026

[sourcefrog]

Well, I was looking at stackslib because that was the failure in your earlier link.

https://github.com/ASuciuX/stacks-core/actions/runs/7901429286/job/21566447350?pr=57#step:2:2026

OK, so in that run I see

Running mutants without shards on stacks-signer package
Found 13 mutants to test
Error: The operation was canceled.

Is this the problem you're pointing to?

I'm not sure why it says "the operation was canceled." Maybe this is due to a timeout at the GitHub Actions level, or maybe something else.

There's not a lot of information to go on here. I think to usefully debug this we have to get a copy of mutants.out, and that doesn't seem to be captured by your workflow as far as I can see.

Also, your workflow seems to be very complicated, which is making it harder to see what's going on. Maybe you should make a separate workflow that just runs cargo-mutants on the stacks-signer package in a simpler way, at least for the sake of debugging this.

[sourcefrog]

The filename runloop.rs sticks out in your screenshot and the code: as we might expect from the name, it has a potentially infinite loop that terminates on a timeout or if the code decides to hang up.

If there's a bug injected by cargo-mutants (or in your own code) then that loop might run forever. That's not necessarily a problem because cargo-mutants will eventually time out and kill it, and report a TIMEOUT result as it's doing here. However, it does make the run longer, so you might want to mark a minimal set of potentially-looping functions as #[mutants::skip].

It looks like you have a nice separation of the actual work of the loop into straight-line functions like execute_command so testing them should get you most of the coverage.

The timeouts are potentially also going to be a problem for you getting really deterministic tests, regardless of cargo-mutants: it's always hard to pick a timeout for tests that is enough to make the tests never falsely timeout but also to avoid the tests hanging forever, and ideally even to test the timeout behavior. As much as possible it's good for tests to avoid looking at the real wall clock. This will be especially important when the suite is already slow as it is here, and when it's run many times by mutants. I didn't look really thoroughly, maybe you're already doing this.

[sourcefrog]

I'm running it here and basically just looking at what mutant was applied and what tests are running.

The first one my machine ran is

Mutant { function: Some(Function { function_name: "StacksClient::pox_path", return_type: "-> String", span: Span(408, 5, 410, 6) }), replacement: "String::new()", genre: FnValue, span: Span(409, 9, 409, 47), package_name: "stacks-signer" }

It looks like that generates a URL path, and here it's replaced to be empty. Looking at where that's used in client.rs get_pox~contract, it looks like you call it in a backoff::retry_notify loop that will retry forever:

       let send_request = || {
            self.stacks_node_client
                .get(self.pox_path())
                .send()
                .map_err(backoff::Error::transient)
        };
        let response = retry_with_exponential_backoff(send_request)?;

So, that's one obvious potential cause of a hang. If I were there I would think about perhaps in general disabling retries during the test suite and expecting that every call succeeds on the first try, unless it's a test specifically about retry behavior, in which case I'd try to set it up to fail once or twice and then succeed once, etc.

Since I was working on a very dusty old test suite elsewhere yesterday I sympathize that this is easy to say and hard to do in a big existing program. But I would try to go in that general direction if you want a reliable test suite.

[ASuciuX]

The expected behavior, even if it had that loop, would have been to run the unmutated test suite, finish it fast as locally it takes 13 seconds and then have that timeout that would take care of the problem. But the unmutated run doesn't finish and that is the strange part.

Also, there are places where nextest works and then cargo mutants with nextest doesn't:

1. L2812 cargo nextest command successful
   https://github.com/ASuciuX/stacks-core/actions/runs/7901429286/job/21624383740?pr=57#step:2:2812
2. L2813 cargo mutants with nextest command is being run, and the failures on L3169 are from cargo mutants test https://github.com/ASuciuX/stacks-core/actions/runs/7901429286/job/21624383740?pr=57#step:2:3169

[sourcefrog]

OK so it looks like your problem is

    SLOW [> 60.000s] stacks-signer runloop::tests::verify_transactions_valid

I can't think of anything cargo-mutants would be doing when running the unmutated code that would cause an otherwise-reliable test to hang.

Actually, one difference is: cargo-mutants runs tests in a copy of the source directory. If this test relies on being run from the original source, that could cause a difference in behavior. Try with --in-place, which will in any case make CI faster.

What I would suggest is:

1. Take the exact cargo nextest command run by mutants, run that yourself in the CI environment and see if you can reproduce the hang.
2. Run it repeatedly in case it is flaky.
3. Read the test code and try to work out what nondeterminicity or timing related behavior would cause it to hang.

[sourcefrog]

That test looks potentially racey to me in how it spawns a thread and seems to assume that the on-thread config will happen before the rest of the test runs, which is not guaranteed. At any rate I think it's much more likely this is a bug in your test than in mutants.