Monday 22 February 2021

Troubleshooting an issue with Kahlan

G'day:

I'm ramping-up to do some more development with this fullstackExercise codebase I've been working on (see "Creating a web site with Vue.js, Nginx, Symfony on PHP8 & MariaDB running in Docker containers", parts 1-12), and as part of the yak-shaving phase of things, I decided to port my PHP tests from PHPUnit to Kahlan. The reason for this is twofold. Firstly, I much prefer the describe / it syntax to writing and running tests over xUnit; and secondly - other than perpetually finding new ways to be frustrated by how PHPUnit handles/documents things - I am not learning a great deal about PHPUnit any more. So Kahlan fits in well with this learning exercise.

Porting the tests is easy, largely cos my tests are currently minimal in number and in complexity. But this PHPUnit class (test/functional/ExampleComTest.php):

namespace adamCameron\kahlanIssue\test\functional;

use GuzzleHttp\Client;
use PHPUnit\Framework\TestCase;
use Symfony\Component\HttpFoundation\Response;

class ExampleComTest extends TestCase
{
    /** @coversNothing */
    public function testExampleDotComReturnsExpectedContent()
    {
        $expectedContent = "Example Domain";


        $client = new Client([
            'base_uri' => 'http://example.com/'
        ]);

        $response = $client->get('index.html');

        $this->assertEquals(Response::HTTP_OK, $response->getStatusCode());

        $html = $response->getBody();
        $document = new \DOMDocument();
        $document->loadHTML($html);

        $xpathDocument = new \DOMXPath($document);

        $hasTitle = $xpathDocument->query('/html/head/title[text() = "' . $expectedContent . '"]');
        $this->assertCount(1, $hasTitle);

        $hasHeading = $xpathDocument->query('/html/body/div/h1[text() = "' . $expectedContent . '"]');
        $this->assertCount(1, $hasHeading);
    }
}

Becomes this Kahlan spec(spec/functional/example.com.spec.php):

namespace adamCameron\fullStackExercise\spec\functional;

use GuzzleHttp\Client;
use Symfony\Component\HttpFoundation\Response;

describe('Tests that example.com can be curled', function () {

    beforeAll(function () {
        $client = new Client([
            'base_uri' => 'http://example.com/'
        ]);

        $this->response = $client->get('index.html');

        $html = $this->response->getBody();
        $document = new \DOMDocument();
        $document->loadHTML($html);
        $this->xpathDocument = new \DOMXPath($document);
    });

    it("should have expected status code", function () {
        expect($this->response->getStatusCode())->toBe(Response::HTTP_OK);
    });

    it("should have expected title", function () {
        $hasTitle = $this->xpathDocument->query('/html/head/title[text() = "Example Domain"]');
        expect($hasTitle)->toHaveLength(1);
    });

    it("should have expected heading", function () {
        $hasHeading = $this->xpathDocument->query('/html/body/div/h1[text() = "Example Domain"]');
        expect($hasHeading)->toHaveLength(1);
    });
});

The problems for me started when I came to run that test in Kahlan. I got this:

            _     _
  /\ /\__ _| |__ | | __ _ _ __
 / //_/ _` | '_ \| |/ _` | '_ \
/ __ \ (_| | | | | | (_| | | | |
\/  \/\__,_|_| |_|_|\__,_|_| |_|

The PHP Test Framework for Freedom, Truth and Justice.

src directory  :
spec directory : /mnt/c/src/kahlanIssue/spec

                                                                    3 / 3 (100%)


Tests that example.com can be curled
  an uncaught exception has been thrown in `vendor/guzzlehttp/guzzle/src/Handler/CurlMultiHandler.php` line 158

  message:`ParseError` Code(0) with message "Unclosed '{' on line 142 does not match ')'"

    [NA] - vendor/guzzlehttp/guzzle/src/Handler/CurlMultiHandler.php, line  to 158
    Kahlan\Jit\ClassLoader::loadFile() - vendor/kahlan/kahlan/src/Jit/ClassLoader.php, line 759
    Kahlan\Jit\ClassLoader::loadClass() - vendor/guzzlehttp/guzzle/src/Utils.php, line 95
    [… etc …]


Expectations   : 0 Executed
Specifications : 0 Pending, 0 Excluded, 0 Skipped

Passed 0 of 1 FAIL (EXCEPTION: 1) in 0.015 seconds (using 7MB)

Eek, OK that's a compilation error, not a runtime exception, which is odd. I checked the code of CurlMultiHandler.php to see if anything was broken in there, and unsurprisingly it wasn't. I decided to chuck a try / catch around the code in question, and see if the actual issue was something other than being reported. I found it odd that Kahlan was reporting it as an Exception, when do me a code-parsing issue is an out-and-out Error. Two different things. So I wondered if Kahlan was doing something odd. I ran the code again and the error spewed out again. What the hell? Then I looked more closely. The error had changed slightly. Now it says this:

an uncaught exception has been thrown in `vendor/guzzlehttp/guzzle/src/Handler/StreamHandler.php` line 201

message:`ParseError` Code(0) with message "Unclosed '{' on line 192 does not match ')'"

Note before it was complaining about CurlMultiHandler.php. Now it's StreamHandler.php. OK. I'll play yer silly game. I stuck a try / catch around that code, and re-ran. Now it errors with this:

an uncaught exception has been thrown in `vendor/guzzlehttp/promises/src/Promise.php` line 151

message:`ParseError` Code(0) with message "Unclosed '{' on line 148 does not match ')'"

Grrr. OK, one last time with the try / catch:

            _     _
  /\ /\__ _| |__ | | __ _ _ __
 / //_/ _` | '_ \| |/ _` | '_ \
/ __ \ (_| | | | | | (_| | | | |
\/  \/\__,_|_| |_|_|\__,_|_| |_|

The PHP Test Framework for Freedom, Truth and Justice.

src directory  :
spec directory : /mnt/c/src/kahlanIssue/spec

...                                                                 3 / 3 (100%)



Expectations   : 3 Executed
Specifications : 0 Pending, 0 Excluded, 0 Skipped

Passed 3 of 3 PASS in 0.565 seconds (using 7MB)

Um. OK. Why's it working? Next I backed-out all my debug code and ran it again. And the tests worked still. Next I blew-away the entire vendor directory and re-did composer install, and the tests continued to work.

It's worth noting here that I know those are all Guzzle files, but If I run the equivalent code in PHPUnit, there is never any issue, hence me doubting it's anything to do with Guzzle specifically, it's how Kahlan is calling Guzzle. Probably with vendor/kahlan/kahlan/src/Jit/ClassLoader.php, which is the preceding file in the callstack, each time. I have to admit I did not look into that file to see what it is doing. I'll crack on with that shortly.

At this point I was thinking that it might be something to do with me running all this in a Docker container, and decided I should verify this in the native file system. At the same time I decided to create a simple repro case: my initial experiments at this stage had not been with the example spec above, they were with one of the fullstack-exercise test specs, and those required the rest of the Docker containers to be up and running, so too complicated to be portable (see "Short, Self Contained, Correct (Compilable), Example"). Accordingly I created the spec above, in a stand-alone application (as per the kahlan-issue repo on Github).

I sighed and installed PHP 8 and Composer on my PC - something I was hoping to avoid needing to do every again, now that I'm using Docker - and ran the test again. Again PHPUnit ran fine, but Kahlan errored-out. The act of putting debug code into the files erroring was enough to make that file now parse and compile, and the error moved on to the next file. Always the same three files. After touching the files once, the problem stayed away. Blowing away vendor and re-doing composer install did not make the erroring situation recur. However if I stuck the app in a different base directory - eg: I had it set up in C:\src\kahlanIssue initially, but moved it to C:\temp\kahlanIssue - then the error recurred again, until I tweakd the files. I noted that putting just whitespace into the file did not "fix" the issue; it needed to be something that PHP would need to parse. Even if I restarted the PC, once I had "touched" those three files once, even if I reverted the touches, the problem did not recur. That was weird.

I was also able to replicate the issue in all of:

  • on Ubuntu within a Docker container (host machine is a Windows PC);
  • on Ubuntu via WSL on that same Windows PC;
  • natively on that Windows PC;
  • natively on Windows on a different PC.

It was only when I downgraded from PHP 8.0.2 to 7.4.15 that I could no longer replicate the issue. So I guess something odd Kahlan is doing to load the PHP files worked fine in previous versions of PHP, but PHP 8 doesn't like it. Or something like that.

I think now I have enough to go on to raise an issue with the Kahlan bods, which I shall do now… done: 370.

All that kinda killed my Sunday afternoon (and now Monday morning writing this article). Hopefully I can get some actual work done this evening though…

Status update on this

The bod from the Kahlan project (specifically Simon Jaillet) jumped on this straight away. In the mean time I looked at what was going on in that vendor/kahlan/kahlan/src/Jit/ClassLoader.php file I mentioned earlier, which was the last touch point in Kahlan before the error. Part of that loading process was to take the original files, monkey-patch the hell out of them to make mocking easier, and then load the monkey-patched version of the file instead of the original one. It also cached the monkey-patched version so it only had to do that exercise once. When it was monkey-patching the erroring files on PHP8, it was ending up with this sort of thing. Original code:

// Step through the task queue which may add additional requests.
P\Utils::queue()->run();

And patching it to be this:

// Step through the task queue which may add additional requests.($__KMONKEY__396__?$__KMONKEY__396__:
$__KMONKEY__396::queue())->run();

Note how the first part of the patched code is stuck on the comment line, not the code line. It should be like this:

// Step through the task queue which may add additional requests.
($__KMONKEY__396__?$__KMONKEY__396__:$__KMONKEY__396::queue())->run();

And when I ran Kahlan on PHP 7.4, it was patching it correctly (as per the last block, above).

The bloke from Kahlan located the issue, which is down to a change in how PHP8 tokenises comments (see "Backward Incompatible Changes > Tokenizer":

T_COMMENT tokens will no longer include a trailing newline. The newline will instead be part of a following T_WHITESPACE token.

That explains that.

I raised the issue at 13:27, and it was fixed by 15:16. I've updated my Kahlan version, and it does indeed sort-out the issue. Brilliant work!

Righto.

--
Adam