phpunit: `HRTime::duration()` throws `InvalidArgumentException`
| 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.
About this issue
- Original URL
- State: closed
- Created 6 months ago
- Reactions: 1
- Comments: 29 (8 by maintainers)
Whenever PHPUnit emits an event (run your test suite using
--debugor--no-output --log-events-text php://stdoutto see the events that are emitted for your test suite), PHP’shrtime()is called and difference between the previous and the current result ofhrtime()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
HRTimeandDurationwere 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 thathrtime()is used instead ofhrtime(true), resulting in the fact that both seconds and nanoseconds have to be dealt with for calculating the differenceNone of the tests were run in process isolation
@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 (
phpunitcommand 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.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!
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.
Nothing has changed between 10.5.5 and 10.5.10 with regards to this issue, so that has to be a coincidence.
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.