Skip to content

Add a trailing line break to console reports#782

Closed
tstarling wants to merge 2 commits intoergebnis:mainfrom
tstarling:trailing-newline
Closed

Add a trailing line break to console reports#782
tstarling wants to merge 2 commits intoergebnis:mainfrom
tstarling:trailing-newline

Conversation

@tstarling
Copy link
Contributor

@tstarling tstarling commented Mar 6, 2026

So that subsequent output appears on a new line.

For example, at https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-php83/47798/console we see

04:49:29       └─── secondsWorker exited with status 0

@tstarling
Add a trailing line break to console reports
b5484d7 
So that subsequent output appears on a new line.
@localheinz
Copy link
Member

localheinz commented Mar 6, 2026

@tstarling

What could be the reason for the output looking like this

04:49:31 PHPUnit 9.6.34 by Sebastian Bergmann and contributors.
04:49:31 
04:49:31 ...............................................................  63 / 804 (  7%)
04:49:31 ............................................................... 126 / 804 ( 15%)
04:49:31 ............................................................... 189 / 804 ( 23%)
04:49:31 ............................................................... 252 / 804 ( 31%)
04:49:31 ............................................................... 315 / 804 ( 39%)
04:49:31 ............................................................... 378 / 804 ( 47%)
04:49:31 ............................................................... 441 / 804 ( 54%)
04:49:31 ............................................................... 504 / 804 ( 62%)
04:49:31 ............................................................... 567 / 804 ( 70%)
04:49:31 ............................................................... 630 / 804 ( 78%)
04:49:31 ............................................................... 693 / 804 ( 86%)
04:49:31 ............................................................... 756 / 804 ( 94%)
04:49:31 ................................................                804 / 804 (100%)
04:49:31 
04:49:31 Time: 00:02.238, Memory: 48.50 MB
04:49:31 
04:49:31 OK (804 tests, 5753 assertions)
04:49:31 
04:49:31 
04:49:31 Detected 5 tests where the duration exceeded the global maximum duration (0.100).
04:49:31 
04:49:31 # Duration Test
04:49:31 --------------------------------------------------------------------------------------------------------------------------------------------------------------------------
04:49:31 1    0.260 MediaWiki\Tests\Structure\SettingsTest::testConfigGeneration with data set "includes/MainConfigNames.php" ('--names', '/workspace/src/includes/MainC...es.php')
04:49:31 2    0.238 MediaWiki\Tests\Structure\SettingsTest::testConfigGeneration with data set "docs/config-schema.yaml" ('--yaml', '/workspace/src/docs/config-schema.yaml')
04:49:31 3    0.197 MediaWiki\Tests\Structure\SettingsTest::testConfigGeneration with data set "docs/config-vars.php" ('--vars', '/workspace/src/docs/config-vars.php')
04:49:31 4    0.192 MediaWiki\Tests\Structure\SettingsTest::testConfigGeneration with data set "includes/config-schema.php" ('--schema', '/workspace/src/includes/confi...ma.php')
04:49:31 5    0.183 PHPUnitConfigTest::testConfigUpToDate
04:49:31 --------------------------------------------------------------------------------------------------------------------------------------------------------------------------
04:49:31      0.000
04:49:31       └─── secondsWorker exited with status 0

when it should look like this instead?

04:49:31 PHPUnit 9.6.34 by Sebastian Bergmann and contributors.
04:49:31 
04:49:31 ...............................................................  63 / 804 (  7%)
04:49:31 ............................................................... 126 / 804 ( 15%)
04:49:31 ............................................................... 189 / 804 ( 23%)
04:49:31 ............................................................... 252 / 804 ( 31%)
04:49:31 ............................................................... 315 / 804 ( 39%)
04:49:31 ............................................................... 378 / 804 ( 47%)
04:49:31 ............................................................... 441 / 804 ( 54%)
04:49:31 ............................................................... 504 / 804 ( 62%)
04:49:31 ............................................................... 567 / 804 ( 70%)
04:49:31 ............................................................... 630 / 804 ( 78%)
04:49:31 ............................................................... 693 / 804 ( 86%)
04:49:31 ............................................................... 756 / 804 ( 94%)
04:49:31 ................................................                804 / 804 (100%)
04:49:31 
04:49:31 Detected 5 tests where the duration exceeded the global maximum duration (0.100).
04:49:31 
04:49:31 # Duration Test
04:49:31 --------------------------------------------------------------------------------------------------------------------------------------------------------------------------
04:49:31 1    0.260 MediaWiki\Tests\Structure\SettingsTest::testConfigGeneration with data set "includes/MainConfigNames.php" ('--names', '/workspace/src/includes/MainC...es.php')
04:49:31 2    0.238 MediaWiki\Tests\Structure\SettingsTest::testConfigGeneration with data set "docs/config-schema.yaml" ('--yaml', '/workspace/src/docs/config-schema.yaml')
04:49:31 3    0.197 MediaWiki\Tests\Structure\SettingsTest::testConfigGeneration with data set "docs/config-vars.php" ('--vars', '/workspace/src/docs/config-vars.php')
04:49:31 4    0.192 MediaWiki\Tests\Structure\SettingsTest::testConfigGeneration with data set "includes/config-schema.php" ('--schema', '/workspace/src/includes/confi...ma.php')
04:49:31 5    0.183 PHPUnitConfigTest::testConfigUpToDate
04:49:31 --------------------------------------------------------------------------------------------------------------------------------------------------------------------------
04:49:31      0.000
04:49:31       └─── seconds
04:49:31 
04:49:31 Time: 00:02.238, Memory: 48.50 MB
04:49:31 
04:49:31 OK (804 tests, 5753 assertions)
04:49:31

Note the order of sections: the output of the extension in https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-php83/47798/console looks like it comes after and not before the summary rendered by phpunit/phpunit.

What would be the reason for that?

Is there a place I can inspect the configuration to reproduce the issue?

@localheinz localheinz self-assigned this Mar 6, 2026
@localheinz localheinz added the bug label Mar 6, 2026
@localheinz
Copy link
Member

localheinz commented Mar 6, 2026

Probably related to #762.

@localheinz localheinz mentioned this pull request Mar 6, 2026
Merged
1 task
@tstarling
Copy link
Contributor Author

tstarling commented Mar 6, 2026

Probably related to #762.

Yes, confirmed, our phpunit.xml has stderr="true" with the comment "Output only to stderr to avoid "Headers already sent" problems". There's an output buffer active, so your echo is captured and then flushed when PHP exits.

@jrchamp jrchamp mentioned this pull request Mar 12, 2026
Open
@localheinz
Copy link
Member

localheinz commented Mar 12, 2026

@tstarling

This may be a limitation with phpunit/phpunit:<10 because there seems to be no way to determine where the output should be directed.

I have no idea, but maybe you can help me out here: why use stderr in the first place?

@tstarling
Copy link
Contributor Author

tstarling commented Mar 13, 2026

This may be a limitation with phpunit/phpunit:<10 because there seems to be no way to determine where the output should be directed.

You could configure it in the extension separately, as I'm suggesting in #788.

I have no idea, but maybe you can help me out here: why use stderr in the first place?

So that header can be called without triggering a "headers already sent" warning. There is header_list and header_remove so it is possible to build isolated integration tests that send headers, except for this detail.

@reedy
Copy link

reedy commented Mar 26, 2026

https://phabricator.wikimedia.org/T420791 is the same issue (we're all from the same downstream)...

Locally running tests I end up with the next command on the same line as the last output, which is more obvious than in our CI logs from above too:

reedy@ubuntu64-web-esxi:/var/www/wiki/mediawiki/core$ composer phpunit extensions/OATHAuth/tests/phpunit/integration/Maintenance/DisableOATHAuthForUserTest.php
> Composer\Config::disableProcessTimeout
Using PHP 8.4.18
Generating PHPUnit config
Config already up-to-date.
Using PHP 8.4.18
Running with MediaWiki settings because there might be integration tests
PHPUnit 9.6.34 by Sebastian Bergmann and contributors.

..                                                                  2 / 2 (100%)

Time: 00:00.532, Memory: 78.50 MB

OK (2 tests, 5 assertions)


Detected 1 test where the duration exceeded the global maximum duration (0.100).

# Duration Test
----------------------------------------------------------------------------------------------------------------
1    0.438 MediaWiki\Extension\OATHAuth\Tests\Integration\DisableOATHAuthForUserTest::testDisableOATHAuthForUser
----------------------------------------------------------------------------------------------------------------
     0.000
      └─── secondsreedy@ubuntu64-web-esxi:/var/www/wiki/mediawiki/core$

Whereas this would be more desired:

reedy@ubuntu64-web-esxi:/var/www/wiki/mediawiki/core$ composer phpunit extensions/OATHAuth/tests/phpunit/integration/Maintenance/DisableOATHAuthForUserTest.php
> Composer\Config::disableProcessTimeout
Using PHP 8.4.18
Generating PHPUnit config
Config already up-to-date.
Using PHP 8.4.18
Running with MediaWiki settings because there might be integration tests
PHPUnit 9.6.34 by Sebastian Bergmann and contributors.

..                                                                  2 / 2 (100%)

Time: 00:00.532, Memory: 78.50 MB

OK (2 tests, 5 assertions)


Detected 1 test where the duration exceeded the global maximum duration (0.100).

# Duration Test
----------------------------------------------------------------------------------------------------------------
1    0.438 MediaWiki\Extension\OATHAuth\Tests\Integration\DisableOATHAuthForUserTest::testDisableOATHAuthForUser
----------------------------------------------------------------------------------------------------------------
     0.000
      └─── seconds
reedy@ubuntu64-web-esxi:/var/www/wiki/mediawiki/core$

@tstarling
Copy link
Contributor Author

tstarling commented Mar 26, 2026

@reedy My PR #788 to solve this issue was merged, and I assume this one is not going to be merged. ergebnis is deliberately omitting the line break because the PHPUnit report summary which is supposed to follow it includes an empty line. The slow test report appears at the end of our output because it's sent to the stdout output buffer and flushed on termination, it's not written to stderr like everything else. PHPUnit 10 provides a method for detecting where output should be sent, but in PHPUnit 9 you would probably have to reparse the command line and phpunit.xml. So my solution in #788 is to add a stderr parameter to the extension. This parameter needs to be added to MW's phpunit.xml.template.

Simply merging this PR is not going to be acceptable because the top-level stderr parameter is not on by default, MediaWiki is being weird by enabling that. Merging this PR would add an unwanted empty line in the default configuration.

@tstarling tstarling closed this Mar 26, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@ergebnis-bot ergebnis-bot Awaiting requested review from ergebnis-bot ergebnis-bot is a code owner

@localheinz localheinz Awaiting requested review from localheinz localheinz is a code owner

Assignees

@localheinz localheinz

Labels

bug

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

3 participants

@tstarling @localheinz @reedy