HRTime::duration() throws InvalidArgumentException

[josep11]

Q	A
PHPUnit version	10.5.5
PHP version	8.3.0
Installation Method	Composer

Summary

\PHPUnit\Event\Telemetry\HRTime::duration throws InvalidArgumentException

This line is the one that throws, but only sometimes.

public function duration(self $start): Duration
    {
        ...

        if ($seconds < 0) {
            throw new InvalidArgumentException('Start needs to be smaller.');
        }

       ...
    }

In my test it fails when invoking the createMock method.
Today: $logger = $this->createMock(LoggerInterface::class);
Yesterday: $calendar = $this->createMock(Calendar::class);

We have had that test running on our CI pipeline for over a year. PRs have been rised on a daily basis and it never failed till yesterday.

We upgraded to PHPUnit 10 one month ago. Same thing, it always worked.

Current behavior

We get one failed test case when running it on our CI provider. The step looks like this:

XDEBUG_MODE=off php -d memory_limit=-1 vendor/bin/phpunit --testsuite unit --colors=never

The same does not happen if we add another pipeline step with the phpunit "--filter"

XDEBUG_MODE=off php -d memory_limit=-1 vendor/bin/phpunit --testsuite unit --colors=never --filter="AttendeeController"

How to reproduce

It is extremely difficult to reproduce. I tried reproducing it locally and cannot succeed. Also, on the CI pipeline it's somehow inconsistent.

• If I comment one of the data provider scenarios out, the error disappears. And then it appears on the immediately previous data provider scenario.
• If I comment the immediately previous data provider scenario, it disappears. 🤯
• If I comment all data providers out it disappears. But then randomly appears the next day on another test case.

Expected behavior

I would say that, if $seconds (which I am not sure how that can even happen 🤯) is less than 0, we should not care at all in the relevant test method. It should be caught and handled by PhpUnit as it's related to grabbing the total execution time.

In summary, it should not be leaked to the phpunit user.

[sebastianbergmann]

Thank you for your report.

Please provide a minimal, self-contained, reproducing test case that shows the problem you are reporting.

Without such a minimal, self-contained, reproducing test case I will not be able to investigate this issue.

[josep11]

@sebastianbergmann Sorry, I cannot provide a minimal, self-contained, reproducing test case with the flaky nature of what I described in the OP. As I said, I was never able to reproduce the error locally, just in the CI provider 🤷🏻‍♂️

[balazscsaba2006]

We are also having this issue, unfortunately.

[balazscsaba2006]

It seems to be related to some internal caching mechanism that relies on previous runs of some tests. It's inconsistently thrown on various tests, so it's not quite possible to create a reproducible test.

[sebastianbergmann]

internal caching mechanism

Internal to PHPUnit or internal to your software?

[balazscsaba2006]

internal caching mechanism

Internal to PHPUnit or internal to your software?

Internal to PHPUnit, as described in the summary #5652 (comment)

[demiankatz]

I also encountered this problem today while running a large test suite in PHPUnit 10.5.7. It occurred in two runs in a row. On the first run, it caused two tests to fail; on the second run, an entirely different single test failed. I run my test suite very frequently and have never seen this before. I have just updated to PHPUnit 10.5.10 to see if that makes a difference. So far, everything seems to be passing, but that could be coincidence. I'll report back here if I see this again (and I would be interested to hear if other posters here continue to see problems on the very latest release).

[sebastianbergmann]

Nothing has changed between 10.5.5 and 10.5.10 with regards to this issue, so that has to be a coincidence.

[demiankatz]

The backtraces I receive when the error occurs are a bit baffling and seem incomplete. I can share more details if there's any interest, but I suspect it will not shed much light. In any case, my run under 10.5.10 has finished successfully, so I have no further information to share until it happens again.

[sebastianbergmann]

Whenever PHPUnit emits an event (run your test suite using --debug or --no-output --log-events-text php://stdout to see the events that are emitted for your test suite), PHP's hrtime() is called and difference between the previous and the current result of hrtime() is calculated.

I do not see how this difference could ever become negative, so we must be doing something wrong in the duration() method where it is calculated.

Both HRTime and Duration were implemented by @theseer and @localheinz, and I did not look to closely at the implementation at the time. I am not mentioning them here to blame them, but rather to ask them for help. Maybe to them it's obvious what is going on here, to me it is unfortunately not. I already struggle with the fact that hrtime() is used instead of hrtime(true), resulting in the fact that both seconds and nanoseconds have to be dealt with for calculating the difference

[theseer]

I just spent some time looking into this.

While I cannot yet say why the described error occurs, I can shed some light as to why we - as in @localheinz and me - decided to use the array type.

This is from the php documentation on hrtime:

Returns an array of integers in the form [seconds, nanoseconds], if the parameter as_number is false. Otherwise the nanoseconds are returned as int (64bit platforms) or float (32bit platforms). Returns false on failure.

I'm not sure how relevant 32bit platforms (still?) are, but a change in return type is not acceptable imho. And having int|float as type declaration for everything feels broken.

We thus opted for using the stable type array, and do the extra effort on calculating.

Speaking of calculating: I can see how, logically, $seconds could easily become negative in our duration calculation. But for that to happen, the value for $start indeed has to be smaller and the exception is, from our business logic's perspective, correct. There is no way a duration could be negative in our world.

The fact that it happens anyhow means that we're apparently feeding it the wrong start time reference somewhere.

I'm at a loss though, how that can be the case - particularly given it only happens sometimes and cannot be reliably be reproduced.

[sebastianbergmann]

Thank you, @theseer, for providing context.

While I hope that nobody uses 32bit systems anymore (except for retrocomputing, of course), I do not think that we can drop support for 32bit systems just yet. Therefore, using the [seconds, nanoseconds] return value is the right thing to do here, IMO.

[demiankatz]

Thanks, @theseer and @sebastianbergmann for the ongoing investigation into this problem. I haven't seen it again since the day last week when it happened to me five times, but I also haven't been running my tests quite so frequently. I suspect I could reproduce it with enough test runs if needed -- so you want to create a temporary branch of PHPUnit that does extra-verbose logging around this issue, I'd be happy to set up my test environment to use that and see if I can catch it in the act to get some additional data for you.

[theseer]

I spent some more time trying to reproduce the issue and so far failed. So I guess, if we want to address this, we indeed need a bit of a debug build and we should take up on @demiankatz 's offer.

I'll try to build a phar with more debug output that might show us where the issue is coming from and make it available.

[demiankatz]

Just a follow-up to say that in another week, I haven't seen the problem return. If you do have a phar you want me to try, feel free to let me know and I can put in a best effort to reproduce the issue, but I'm a bit baffled at its disappearance, after it seemed to be a relatively frequent problem for one day.

[sebastianheuer]

@demiankatz @balazscsaba2006 @josep11 We are currently discussing this again in the course of a PHPUnit Code Sprint. As you all confirmed this happening, could you give some insights on the environments where you observed the issue? Most notably:

• does it only happen in CI environments or have you also encountered this in local environments?
• if CI, which one (e.g. GitHub Actions Runner)
• Operating System
• Virtualization (e.g. Docker)
• CPU architecture (e.g. x64, ARM)
• PHP version
• how PHPUnit is run (e.g. phpunit command is called directly, through paratest, ...)

That might help us to identify a pattern or at least form further hypotheses.

[demiankatz]

Thanks, @sebastianheuer. I encountered this in an Ubuntu 22.04 VirtualMachine running in VirtualBox on x86 architecture. The PHP version is 8.1.2-1ubuntu2.14, and I am running PHPUnit more or less directly (via a Phing task).

As noted above, I encountered the problem repeatedly on a single day, but it has not recurred since then. A very slippery bug!

[balazscsaba2006]

@demiankatz We've encountered in CI only, GitHub Actions Runner, Ubuntu (latest, x64), PHP 8.2.*;
The problem seems to have been caused by the cache we were using for PHPUnit (phpunit command directly); now we are not caching anything and the problem does not persist anymore.
We were caching files on the PR level; the first push created the cache and saved it in Github, and all subsequent CI runs on the same PR would load that cache and re-run the tests;
I haven't tried with Paratest, but we migrated our CI to it, so if you need help with reproducing with Paratest, I'm more than happy to try it out.

[sebastianheuer]

@demiankatz @balazscsaba2006 Any chance that the tests that failed with this (granted it's not always the same tests) run in process isolation, e.g. with the --process-isolation CLI option or by adding the @runInSeparateProcess annotation / using the RunInSeparateProcess attribute?

[balazscsaba2006]

None of the tests were run in process isolation

[theseer]

I created a snapshot phar from the current main branch with an added debug dump before the exception is thrown. It does not address the issue in any other way:

phpunit-11.1-g475907b38.phar.gz
(Github doesn't allow uploading of .phar files. So please run gzip -d phpunit-11.1-g475907b38.phar.gz to get the actual phar)

Please be aware: This is not an official release of PHPUnit, it is not meant to be used in any type of production and merely created to gather some additional information on this very issue. It may be completely broken otherwise and did not go through any type of QA testing.

That being said: It would be awesome if everybody experiencing this issue could add an (maybe additional?) build step running this phar to see if it can reproduce the issue. If so, please paste the relevant output from the debug output here.

[demiankatz]

I think @balazscsaba2006's comments about cache are very possibly the explanation here: I had just recently upgraded from PHPUnit 9 to PHPUnit 10 when I was encountering the problem. Perhaps there were some lingering cache files from 9 that were causing problems in 10... and the reason it has not returned is that the cache was eventually cleared.

[balazscsaba2006]

If it helps anything, I introduced caching when I upgraded to phpunit 10, to order tests by the first failed previously to be run first on the next PR run. We didn't have caching on CI at all previously when using 9.5.*

[balazscsaba2006]

I created a snapshot phar from the current main branch with an added debug dump before the exception is thrown. It does not address the issue in any other way:

phpunit-11.1-g475907b38.phar.gz

(Github doesn't allow uploading of .phar files. So please run gzip -d phpunit-11.1-g475907b38.phar.gz to get the actual phar)

Please be aware: This is not an official release of PHPUnit, it is not meant to be used in any type of production and merely created to gather some additional information on this very issue. It may be completely broken otherwise and did not go through any type of QA testing.

That being said: It would be awesome if everybody experiencing this issue could add an (maybe additional?) build step running this phar to see if it can reproduce the issue. If so, please paste the relevant output from the debug output here.

I will try it out early next week and share the cache artifact and output, hopefully it'll help pinpoint the issue, @theseer

[theseer]

If it helps anything, I introduced caching when I upgraded to phpunit 10, to order tests by the first failed previously to be run first on the next PR run. We didn't have caching on CI at all previously when using 9.5.*

As PHPUnit 9 didn't have events yet, the crashing code of this issue didn't exist yet either. So the fact you didn't use caching before is unrelated to that migration.

I'm also not yet convinced the result caching has anything to do with this. Caching has two direction of operation: The creating and using.

PHPUnit's Result Cache Data only contains calculated durations, so reloading this file doesn't trigger any HRTime calls.

But of course writing the cache file does. I fail to see - so far- how this could lead to this issue - particularly in such an unreliable and inconsistent manner.

But to be sure: Does using --cache-results make it more likely to trigger this issue for anyone?

[sebastianheuer]

@balazscsaba2006 @demiankatz Is it possible to share a stack trace of one of the failed runs? It would be helpful to see in which part of PHPUnit the exception is thrown.

[theseer]

As we cannot see any way this can happen in our code, we assume it has to be something infrastructure related. We have some theories, but decided there's no value in further investigating this.

Given we do not have any control over physical environmental issues, we decided to change the duration calculation to swallow negative intermediate results by converting them into 0.0.

While that doesn't fix the underlying - likely external - root cause, it fixes the problem at hand for PHPUnit.

[theseer]

I created a snapshot phar from the current main branch with an added debug dump before the exception is thrown. It does not address the issue in any other way:
phpunit-11.1-g475907b38.phar.gz
(Github doesn't allow uploading of .phar files. So please run gzip -d phpunit-11.1-g475907b38.phar.gz to get the actual phar)
Please be aware: This is not an official release of PHPUnit, it is not meant to be used in any type of production and merely created to gather some additional information on this very issue. It may be completely broken otherwise and did not go through any type of QA testing.
That being said: It would be awesome if everybody experiencing this issue could add an (maybe additional?) build step running this phar to see if it can reproduce the issue. If so, please paste the relevant output from the debug output here.

I will try it out early next week and share the cache artifact and output, hopefully it'll help pinpoint the issue, @theseer

If you feel like investing the time still, feel free to do so. I'm still interested in getting details - but for the time being this is rather for academic purposes ;)

[demiankatz]

@balazscsaba2006 @demiankatz Is it possible to share a stack trace of one of the failed runs? It would be helpful to see in which part of PHPUnit the exception is thrown.

Unfortunately, it looks like I failed to capture one at the time (though my earlier comment suggests this is because it seemed not to point in any clear direction). I am now unable to reproduce the problem, so I don't think I can help -- but if it somehow pops up again, I'll post more here.

In any case, the proposed workaround seems reasonable under the circumstances.