[PHPUnit 10+ only] Make dump() output in tests no longer use standard streams

Created on 25 March 2024, 4 months ago
Updated 1 July 2024, 17 days ago

Problem/Motivation

In 🐛 dump() no longer produces output in PHPUnit tests running under PHP 8.3 Fixed we fixed dump() no longer producing output in PHPUnit tests running in isolation under PHP 8.3, by changing writing to STDERR instead of STDOUT.

However, the fix is not sufficient as later 🐛 dump() calls in tests are producing a PHPUnit\Framework\Exception Active reported that dump() in kernel tests leads to test failures.

In this issue for PHPUnit 10+, see if we can adopt a different technique instead of using standard streams.

Proposed resolution

Take clues from HtmlOutputLogger and 📌 Bootstrap HtmlOutputLogger from phpunit.xml RTBC , and introduce a PHPUnit extension that captures the output of dump() during the tests, and prints it cumulatively at the end of the testrunner execution. In this, enhance the experience to also add information about where each dump() call happened.

The bigger hurdle here are processes run in isolation (many unit ones, and all kernel/functional/functionaljavascript ones): there's no easy way to return information from the 'isolated' test back to its parent testrunner. However, using an environment variable and a staging file likewise HtmlOutputLogger, we can achieve that.

Remaining tasks

User interface changes

API changes

Data model changes

Release notes snippet

📌 Task
Status

Needs review

Version

11.0 🔥

Component
PHPUnit 

Last updated about 2 hours ago

Created by

🇮🇹Italy mondrake 🇮🇹

Live updates comments and jobs are added and updated live.
  • Needs change record

    A change record needs to be drafted before an issue is committed. Note: Change records used to be called change notifications.

Sign in to follow issues

Merge Requests

Comments & Activities

  • Issue created by @mondrake
  • 🇮🇳India dineshkumarbollu

    Hi @mondrake
    Any reason for postpone of issue,

    In this issue for PHPUnit 10+, see if we can adopt a different technique instead of using standard streams.

    Looking for different technique, will be good if the status is Active. Any Thoughts on this.

  • Status changed to Active 4 months ago
  • 🇬🇧United Kingdom longwave UK

    The parent was committed but not sure there is anything worth fixing here, I think stderr is a fine place to put debugging information during tests.

  • 🇮🇹Italy mondrake 🇮🇹

    My idea: during the test execution, make TestVarDumper store the dump strings in an array instead of outputting it (so we do not pollute SUT output with output).

    Then, after test end (or testrunner end), subscribe to PHPUnit events and print the dump - similar to what we are doing for the HTMLOutputLogger.

    That would make it more aligned to PHPUnit architecture.

    Waiting for PHPUnit 10 though, where the event system is implemented. Trying it before would mean to touch listeners which are deprecated in PHPUnit 9 and gone in 10.

  • Status changed to Postponed 4 months ago
  • 🇬🇧United Kingdom longwave UK

    Personally I find it more valuable to get immediate debug feedback as the test runs rather than wait until the end - and if somehow you crash the test or the test runner, is there a chance the captured output is lost? I guess this needs to still be postponed until we are on PHPUnit 10, in any case.

  • 🇮🇹Italy mondrake 🇮🇹

    Well hopefully the post test execution events should still run even if the test itself crashes, otherwise we'd have a problem in PHPUnit. Anyway, let's see what we can do once the right time comes.

  • 🇮🇹Italy mondrake 🇮🇹
  • 🇮🇹Italy mondrake 🇮🇹
  • Status changed to Active 2 months ago
  • 🇮🇹Italy mondrake 🇮🇹
  • Merge request !8345Closes #3436029 → (Open) created by mondrake
  • Pipeline finished with Failed
    about 1 month ago
    Total: 178s
    #195003
  • Pipeline finished with Failed
    about 1 month ago
    Total: 693s
    #195005
  • Pipeline finished with Failed
    about 1 month ago
    Total: 532s
    #196551
  • Pipeline finished with Failed
    about 1 month ago
    Total: 635s
    #196656
  • Pipeline finished with Failed
    about 1 month ago
    Total: 646s
    #197446
  • Pipeline finished with Failed
    about 1 month ago
    Total: 616s
    #198236
  • Pipeline finished with Failed
    about 1 month ago
    Total: 614s
    #198279
  • Pipeline finished with Success
    about 1 month ago
    Total: 549s
    #198329
  • Status changed to Needs review about 1 month ago
  • Status changed to Needs work about 1 month ago
  • 🇺🇸United States smustgrave

    Sorry if I missed something but can the issue summary be updated then reviewed?

  • Pipeline finished with Failed
    about 1 month ago
    Total: 235s
    #199285
  • Pipeline finished with Success
    about 1 month ago
    Total: 517s
    #199290
  • Status changed to Needs review about 1 month ago
  • 🇮🇹Italy mondrake 🇮🇹

    Updated IS

  • Status changed to Needs work 29 days ago
  • The Needs Review Queue Bot tested this issue. It no longer applies to Drupal core. Therefore, this issue status is now "Needs work".

    This does not mean that the patch necessarily needs to be re-rolled or the MR rebased. Read the Issue Summary, the issue tags and the latest discussion here to determine what needs to be done.

    Consult the Drupal Contributor Guide to find step-by-step guides for working with issues.

  • Status changed to Needs review 23 days ago
  • 🇮🇹Italy mondrake 🇮🇹
  • Pipeline finished with Failed
    23 days ago
    Total: 586s
    #208634
  • Status changed to Needs work 23 days ago
  • 🇬🇧United Kingdom joachim

    First time I'm looking at this, and wow, totally new approach! I guess this is required because of changes in PHPUnit 10?

    This needs a CR to explain that phpunit.xml files need to be updated.

    I like the printing of the file and line number, though in some instances that might get noisy.

    For example, if I'm developing a migration and I want to see the value that's computed on each processing of a row. I'm going to add a single dump() statement and what I want to see is a monotonic list of values:

    foo
    foo
    foo
    somethingbad 
    foo
    

    I want 'somethingbad' to stick out in the last, and the list being simple is important to being able to do this. Filenames and line numbers will hamper this.

    > Personally I find it more valuable to get immediate debug feedback as the test runs rather than wait until the end -

    Same! Though I appreciate there may not be a way to do that with this approach.

    The testVarDump() test outputs the dump statements it is testing. Is there a way of capturing the dump() output from testVarDump(), like it used to be?

    I suspect some test runners will spot dump() output and not like it. It's also going to be noise in the test results from d.org CI.

    Also, if the DebugDump extension it not registered, the testVarDump() test fails.

    > public static function setDebugDumpHandler

    The docs here could do with a @see to a fully-qualified DebugDump

    > + * Drupal's extension for printing dump() output results.

    Say it's a PHPUnit extension.

    > self::$stagingFilePath = tempnam(sys_get_temp_dir(), 'dpd');

    Could we use the VFS here? Would that be quicker?

    > and if somehow you crash the test or the test runner, is there a chance the captured output is lost?

    I think it's more likely that the file won't get cleaned up from the tmp directory. Though if we switch to using the VFS then that is solved.

  • 🇮🇹Italy mondrake 🇮🇹

    No VFS, sorry. In tests run in process isolation, the VFS instance will only be visibile to the child process, and then destructed before returning to the main process. Or viceversa, if visible to the main process, it won't be visible to the children.

    I want 'somethingbad' to stick out in the last, and the list being simple is important to being able to do this. Filenames and line numbers will hamper this.

    We could add a parameter in the extension configuration in the xml file to opt-out from printing the whereabouts of the dump() call.

  • 🇬🇧United Kingdom joachim

    Ahh right. That's a shame!

    Parameter in the extension config -- perfect! :)

  • 🇮🇹Italy mondrake 🇮🇹

    I guess this is required because of changes in PHPUnit 10?

    Well yes and no. There were already changes in PHPUnit 9 that forced to change the current solution to print to STDERR instead of STDOUT. The real problem is that, to an extent, test code and SUT code share the same standard streams. Quite rightly IMHO, especially if tests need to run in isolation, PHPUnit is 'sealing' more and more the SUT to prevent confusion between SUT and test output.

  • 🇮🇹Italy mondrake 🇮🇹

    Added

    <parameter name="printCaller" value="true"/>

    as a config parameter for the extension.

  • Pipeline finished with Success
    22 days ago
    Total: 585s
    #208819
  • Pipeline finished with Success
    22 days ago
    Total: 674s
    #209450
  • 🇬🇧United Kingdom joachim

    > There were already changes in PHPUnit 9 that forced to change the current solution to print to STDERR instead of STDOUT. The real problem is that, to an extent, test code and SUT code share the same standard streams

    So is output to STERR still possible, even if not always desirable?

    If so, could we add an option for it?

  • 🇮🇹Italy mondrake 🇮🇹

    No, we changed from STDOUT to STDERR already, and the newly reported failures in kernel tests are related to this.

  • 🇬🇧United Kingdom joachim

    If we want 'live' output, would it work to `tail -f` the file in which the output is getting sent to? If so, it would be useful to document that solution.

  • 🇮🇹Italy mondrake 🇮🇹

    Well that would mean writing to STDOUT, so back to square one. This issue is, fundamentally, avoiding to use standard streams - just capture the output of dump in a temp file, and post-test-mortem, print it via the standard streams of the CLI testrunner that are no longer being checked by PHPUnit for unexpected output. No live output, in this case, sorry - it's the design of the MR itself that prevents it.

    Note that if you call dump() from a component test that extends directly from PHPUnit's TestCase, or from a Drupal unit test case not run isolation, without the extension being active, then yes, you got exactly that - live dumps, and for free since there is not even the need to do anything.

    This entire issue is about tests run in isolation. It's process isolation (and all kernel+functional tests, plus a few Drupal unit tests, are executied in isolation) that causes the dump() failures.

    At least, that's my understanding - but I'd love to be proven wrong :)

  • 🇬🇧United Kingdom joachim

    > Well that would mean writing to STDOUT, so back to square one. This issue is, fundamentally, avoiding to use standard streams - just capture the output of dump in a temp file,

    No, you don't need STDOUT. If the temp file is readable by a second terminal window, then `tail -f` outputs the end of the file *LIVE* as it is being written to. `tail -f` is particularly useful for watching log files, but would work here too, as long as the file is accessible and readable.

  • 🇮🇹Italy mondrake 🇮🇹

    Interesting. If I understand your idea, that would mean running two separate terminals, one running PHPUnit CLI, and the other the tail command? That would pose the problem of knowing in advance the filepath of the temp file across both terminals, and of course of avoiding the hashing of the file content that the MR is currently doing.

  • 🇬🇧United Kingdom joachim

    > If I understand your idea, that would mean running two separate terminals, one running PHPUnit CLI, and the other the tail command?

    Yup.

    I wouldn't want that to be the main intended mode of operation, but it would be useful in some circumstances -- such as something that crashes PHPUnit so badly the output is not printed.

  • Status changed to Needs review 17 days ago
  • 🇮🇹Italy mondrake 🇮🇹

    Thought about this, and IMHO dumping to a file for it to be tracked in real time via tail -f would better be done with an alternative extension, rather than trying to fit both behaviors in one.

Production build 0.69.0 2024