sebastianbergmann / php-code-coverage

Library that provides collection, processing, and rendering functionality for PHP code coverage information.
BSD 3-Clause "New" or "Revised" License
8.83k stars 374 forks source link

Executable code not shown as executed/executable #488

Closed sebastianbergmann closed 7 years ago

sebastianbergmann commented 8 years ago

Moved here from #411 (where more than one issue was discussed).

Environment

Steps to reproduce

git clone https://github.com/ramsey/uuid-doctrine.git
cd uuid-doctrine
git checkout abbcbe56b023319dea7a72177333089cf47f5a69
composer install
./vendor/bin/phpunit

Actual result

e9f95398-d168-11e5-901a-a8b81661e3a2

Expected result

Lines 50-52 of the uuid-doctrine/src/UuidBinaryType.php files should not be white.

sebastianbergmann commented 8 years ago

I have removed PHPUnit from require-dev in the composer.json file of the uuid-doctrine project:

diff --git a/composer.json b/composer.json
index ee86d64..e8923a0 100644
--- a/composer.json
+++ b/composer.json
@@ -30,12 +30,6 @@
         "ramsey/uuid": "^3.0",
         "doctrine/dbal": "^2.3|^2.5"
     },
-    "require-dev": {
-        "phpunit/phpunit": "^4.7|^5.0",
-        "squizlabs/php_codesniffer": "^2.3",
-        "jakub-onderka/php-parallel-lint": "^0.9.0",
-        "satooshi/php-coveralls": "^0.6.1"
-    },
     "autoload": {
         "psr-4": {"Ramsey\\Uuid\\Doctrine\\": "src/"}
     }

This allows me to use a development version of PHPUnit (and its dependencies) which investigating this issue.

sebastianbergmann commented 8 years ago

I have added a print_r() statement to src/Driver/Xdebug.php for printing the raw code coverage data that comes from Xdebug:

diff --git a/src/Driver/Xdebug.php b/src/Driver/Xdebug.php
index 30099e0..5636297 100644
--- a/src/Driver/Xdebug.php
+++ b/src/Driver/Xdebug.php
@@ -65,6 +65,9 @@ public function start($determineUnusedAndDead = true)
     public function stop()
     {
         $data = xdebug_get_code_coverage();
+
+        print_r($data);
+
         xdebug_stop_code_coverage();

         return $this->cleanup($data);
sebastianbergmann commented 8 years ago

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the first call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [28] => 1
        [88] => 1
        [89] => -1
        [92] => 1
        [93] => 1
        [97] => -1
        [98] => -1
        [99] => -1
        [102] => -1
        [103] => -2
        [126] => 1
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the second call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [88] => 1
        [89] => -1
        [92] => 1
        [93] => -1
        [97] => 1
        [98] => -1
        [99] => -1
        [102] => 1
        [103] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the third call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [88] => 1
        [89] => -1
        [92] => 1
        [93] => -1
        [97] => 1
        [98] => 1
        [99] => 1
        [102] => -1
        [103] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the fourth call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [88] => 1
        [89] => 1
        [92] => -1
        [93] => -1
        [97] => -1
        [98] => -1
        [99] => -1
        [102] => -1
        [103] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the fifth call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [63] => 1
        [64] => -1
        [67] => 1
        [68] => -1
        [72] => 1
        [73] => -1
        [74] => -1
        [77] => 1
        [78] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the sixth call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [63] => 1
        [64] => -1
        [67] => 1
        [68] => -1
        [72] => 1
        [73] => 1
        [74] => 1
        [77] => -1
        [78] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the seventh call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [63] => 1
        [64] => 1
        [67] => -1
        [68] => -1
        [72] => -1
        [73] => -1
        [74] => -1
        [77] => -1
        [78] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the eigth call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [63] => 1
        [64] => -1
        [67] => 1
        [68] => 1
        [72] => -1
        [73] => -1
        [74] => -1
        [77] => -1
        [78] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the ninth call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [112] => 1
        [113] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the tenth call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [43] => 1
        [44] => 1
        [45] => 1
        [50] => -1
        [51] => -1
        [53] => -2
    )

This is the raw code coverage data for uuid-doctrine/src/UuidBinaryType.php returned by the eleventh call to xdebug_get_code_coverage():

[/home/sb/uuid-doctrine/src/UuidBinaryType.php] => Array
    (
        [123] => 1
        [124] => -2
    )
sebastianbergmann commented 8 years ago

The tenth call to xdebug_get_code_coverage() returns information about the lines of code in question (uuid-doctrine/src/UuidBinaryType.php:50-52). Now we need to figure out why this information is not used (correctly) by this component.

sebastianbergmann commented 8 years ago

The problem persists with all @covers annotations removed from the tests. It is not related to annotation-based filtering of code coverage data.

sebastianbergmann commented 8 years ago

The problem persists when processUncoveredFilesFromWhitelist is set to true in the uuid-doctrine project's phpunit.xml:

diff --git a/phpunit.xml.dist b/phpunit.xml.dist
index 3514dd4..2e8b335 100644
--- a/phpunit.xml.dist
+++ b/phpunit.xml.dist
@@ -6,7 +6,7 @@
         </testsuite>
     </testsuites>
     <filter>
-        <whitelist>
+        <whitelist processUncoveredFilesFromWhitelist="true">
             <directory suffix=".php">./src</directory>
         </whitelist>
     </filter>
sebastianbergmann commented 8 years ago

I have added a print_r() statement to src/Driver/Xdebug.php for printing the "cleaned" code coverage data:

diff --git a/src/Driver/Xdebug.php b/src/Driver/Xdebug.php
index 30099e0..1cd4cbc 100644
--- a/src/Driver/Xdebug.php
+++ b/src/Driver/Xdebug.php
@@ -67,7 +67,11 @@ public function stop()
         $data = xdebug_get_code_coverage();
         xdebug_stop_code_coverage();

-        return $this->cleanup($data);
+        $cleanData = $this->cleanup($data);
+
+        print_r($cleanData);
+
+        return $cleanData;
     }

     /**

After cleanup(), no array contains information about the lines of code in question (uuid-doctrine/src/UuidBinaryType.php:50-52) anymore.

sebastianbergmann commented 8 years ago

I have removed the call to cleanup() (mentioned in https://github.com/sebastianbergmann/php-code-coverage/issues/488#issuecomment-263555328):

diff --git a/src/Driver/Xdebug.php b/src/Driver/Xdebug.php
index 30099e0..ea8e4f2 100644
--- a/src/Driver/Xdebug.php
+++ b/src/Driver/Xdebug.php
@@ -67,7 +67,7 @@ public function stop()
         $data = xdebug_get_code_coverage();
         xdebug_stop_code_coverage();

-        return $this->cleanup($data);
+        return $data;
     }

     /**

The problem persists. So cleanup() is not the (only) cause for this issue.

sebastianbergmann commented 8 years ago

Better debugging code:

diff --git a/src/CodeCoverage.php b/src/CodeCoverage.php
index 35dab3d..5464557 100644
--- a/src/CodeCoverage.php
+++ b/src/CodeCoverage.php
@@ -248,6 +248,8 @@ public function start($id, $clear = false)
             );
         }

+        print $id->toString() . PHP_EOL . PHP_EOL;
+
         if ($clear) {
             $this->clear();
         }
diff --git a/src/Driver/Xdebug.php b/src/Driver/Xdebug.php
index 30099e0..2002727 100644
--- a/src/Driver/Xdebug.php
+++ b/src/Driver/Xdebug.php
@@ -67,7 +67,21 @@ public function stop()
         $data = xdebug_get_code_coverage();
         xdebug_stop_code_coverage();

-        return $this->cleanup($data);
+        if (isset($data['/home/sb/uuid-doctrine/src/UuidBinaryType.php'])) {
+            print 'RAW:' . PHP_EOL;
+            print_r($data['/home/sb/uuid-doctrine/src/UuidBinaryType.php']);
+            print PHP_EOL;
+        }
+
+        $clean = $this->cleanup($data);
+
+        if (isset($clean['/home/sb/uuid-doctrine/src/UuidBinaryType.php'])) {
+            print 'CLEANED:' . PHP_EOL;
+            print_r($clean['/home/sb/uuid-doctrine/src/UuidBinaryType.php']);
+            print PHP_EOL . PHP_EOL;
+        }
+
+        return $clean;
     }

     /**

Output:

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testUuidConvertsToDatabaseValue

RAW:
Array
(
    [28] => 1
    [126] => 1
)

CLEANED:
Array
(
    [28] => 1
)

RAW:
Array
(
    [88] => 1
    [92] => 1
    [93] => 1
)

CLEANED:
Array
(
    [88] => 1
    [92] => 1
    [93] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testStringUuidConvertsToDatabaseValue

RAW:
Array
(
    [88] => 1
    [92] => 1
    [97] => 1
    [102] => 1
)

CLEANED:
Array
(
    [88] => 1
    [92] => 1
    [97] => 1
    [102] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testInvalidUuidConversionForDatabaseValue

RAW:
Array
(
    [88] => 1
    [92] => 1
    [97] => 1
    [98] => 1
    [99] => 1
)

CLEANED:
Array
(
    [88] => 1
    [92] => 1
    [97] => 1
    [98] => 1
    [99] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testNullConversionForDatabaseValue

RAW:
Array
(
    [88] => 1
    [89] => 1
)

CLEANED:
Array
(
    [88] => 1
    [89] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testUuidConvertsToPHPValue

RAW:
Array
(
    [63] => 1
    [67] => 1
    [72] => 1
    [77] => 1
)

CLEANED:
Array
(
    [63] => 1
    [67] => 1
    [72] => 1
    [77] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testInvalidUuidConversionForPHPValue

RAW:
Array
(
    [63] => 1
    [67] => 1
    [72] => 1
    [73] => 1
    [74] => 1
)

CLEANED:
Array
(
    [63] => 1
    [67] => 1
    [72] => 1
    [73] => 1
    [74] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testNullConversionForPHPValue

RAW:
Array
(
    [63] => 1
    [64] => 1
)

CLEANED:
Array
(
    [63] => 1
    [64] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testReturnValueIfUuidForPHPValue

RAW:
Array
(
    [63] => 1
    [67] => 1
    [68] => 1
)

CLEANED:
Array
(
    [63] => 1
    [67] => 1
    [68] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testGetName

RAW:
Array
(
    [112] => 1
)

CLEANED:
Array
(
    [112] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testGetGuidTypeDeclarationSQLWithDoctrineDbal25

RAW:
Array
(
    [43] => 1
    [44] => 1
    [45] => 1
)

CLEANED:
Array
(
    [43] => 1
    [44] => 1
    [45] => 1
)

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testGetGuidTypeDeclarationSQLWithDoctrineDbal23

Ramsey\Uuid\Doctrine\UuidBinaryTypeTest::testRequiresSQLCommentHint

RAW:
Array
(
    [123] => 1
)

CLEANED:
Array
(
    [123] => 1
)

Ramsey\Uuid\Doctrine\UuidTypeTest::testUuidConvertsToDatabaseValue

Ramsey\Uuid\Doctrine\UuidTypeTest::testInvalidUuidConversionForDatabaseValue

Ramsey\Uuid\Doctrine\UuidTypeTest::testNullConversionForDatabaseValue

Ramsey\Uuid\Doctrine\UuidTypeTest::testUuidConvertsToPHPValue

Ramsey\Uuid\Doctrine\UuidTypeTest::testInvalidUuidConversionForPHPValue

Ramsey\Uuid\Doctrine\UuidTypeTest::testNullConversionForPHPValue

Ramsey\Uuid\Doctrine\UuidTypeTest::testReturnValueIfUuidForPHPValue

Ramsey\Uuid\Doctrine\UuidTypeTest::testGetName

Ramsey\Uuid\Doctrine\UuidTypeTest::testGetGuidTypeDeclarationSQL

Ramsey\Uuid\Doctrine\UuidTypeTest::testRequiresSQLCommentHint
sebastianbergmann commented 8 years ago

Thoroughly confused now. Earlier today (https://github.com/sebastianbergmann/php-code-coverage/issues/488#issuecomment-263549966) xdebug_get_code_coverage() return data for the lines in question and now (https://github.com/sebastianbergmann/php-code-coverage/issues/488#issuecomment-263646758) it does not.

henrikauppinen commented 7 years ago

I did some digging into this and here's my findings.

First off I removed all tests except UuidBinaryTypetest/testGetName and UuidBinaryTypetest/testGetGuidTypeDeclarationSQLWithDoctrineDbal25 to limit the amount of data.

xdebug_get_code_coverage data for /src/UuidBinaryType.php:

UuidBinaryTypetest/testGetName:
 28 = 1
 112 = 1
 113 = -2
 126 = 1
(correct data for UuidBinaryType/getName)

UuidBinaryTypetest/testGetGuidTypeDeclarationSQLWithDoctrineDbal25:
43 = 1
44 = 1
45 = 1
50 = -1
51 = -1
53 = -2
(correct data for UuidBinaryType/getSqlDeclaration)

So the data seems to be there but something goes wrong with merging the results.

It seems that when file appears in the data for the first time, it is expected that xdebug data returns coverage for all rows in the executed file, and if that file is accessed for second time, only results for the used lines are returned. However for some reason in this case the first result for UuidBinaryType.php contains only data for the accessed function.

If inheritance is removed from UuidBinaryType:

class UuidBinaryType # extends Type
{

Xdebug output starts to look like this:

xdebug_get_code_coverage data for /src/UuidBinaryType.php:

UuidBinaryTypetest/testGetName:
 28 = 1
 43 = -1
 44 = -1
 45 = -1
 50 = -1
 51 = -1
 53 = -2
 63 = -1
 64 = -1
 67 = -1
 68 = -1
 72 = -1
 73 = -1
 74 = -1
 77 = -1
 78 = -2
 88 = -1
 89 = -1
 92 = -1
 93 = -1
 97 = -1
 98 = -1
 99 = -1
 102 = -1
 103 = -2
 112 = 1
 113 = -2
 123 = -1
 124 = -2
 126 = 1
(results for all rows in the file)

UuidBinaryTypetest/testGetGuidTypeDeclarationSQLWithDoctrineDbal25:
43 = 1
44 = 1
45 = 1
50 = -1
51 = -1
53 = -2
(results for getSqlDeclaration)

With this data the coverage gets appended correctly.

I tried to determine the exact point where xdebug behaviour changes by building a new project which imitates uuid-doctrine, but for now haven't been able to reproduce this.

To me it seems that this behaviour is related to xdebug internals?

sebastianbergmann commented 7 years ago

@henrikauppinen Yes, that is my interpretation of the situation as well.

@derick Is the assumption wrong that when Xdebug's code coverage collector "sees" a file for the first time it returns information for all lines?

derickr commented 7 years ago

After having read this, I think the answer is yes. Do you set the $cleanup argument when calling xdebug_get_code_coverage()? Xdebug tries to only do the expensive analysys on where code is once, and it would likely not redo this after you call xdebug_get_code_coverage( true );.

But I would like to investigate this - without having @phpunit in the "way". @henrikauppinen , can you reproduce this by just the standard Xdebug code coverage functions and a test and a few files? From what I understand, that shouldn't be hard.

derickr commented 7 years ago

Hmm, I just ran into https://bugs.xdebug.org/view.php?id=1278 — need to see whether that is effecting anything here.

derickr commented 7 years ago

Nope :-)

henrikauppinen commented 7 years ago

I removed phpunit and created a custom test file:

<?php

xdebug_start_code_coverage(XDEBUG_CC_UNUSED | XDEBUG_CC_DEAD_CODE);

include dirname(__FILE__).'/vendor/autoload.php'; 

use Doctrine\DBAL\Types\Type;

Type::addType('uuid_binary', 'Ramsey\Uuid\Doctrine\UuidBinaryType');
$type = Type::getType('uuid_binary');

$xdebugData = xdebug_get_code_coverage();

print_r(
    $xdebugData['/Users/henrikauppinen/Sites/uuid-doctrine/src/UuidBinaryType.php']
);

composer.json:

{
    "require": {
        "php": ">=5.4",
        "ramsey/uuid": "^3.0",
        "doctrine/dbal": "^2.3|^2.5"
    },
    "autoload": {
        "psr-4": {"Ramsey\\Uuid\\Doctrine\\": "src/"}
    }
}

Behaviour is same as in previous example. Unused rows for UuidBinaryType.php are missing if UuidBinaryType inherits from Type.

@derickr, here's a fork of Ramsey/uuid-doctrine with this test in case you wish to investigate (test.php): https://github.com/henrikauppinen/uuid-doctrine/tree/xdebug-testing

JoepRoebroek commented 7 years ago

Hello guys, thought I'd try and work with you on this issue. I investigated the CodeCoverage\CodeCoverage class and found there is a mismatch between the way $this->data is built in the ->append() function and the way it is interpreted by

CodeCoverage\Report\Html\File

from line 306

if (array_key_exists($i, $coverageData)) {
    $numTests = count($coverageData[$i]);
if ($coverageData[$i] === null) {
       $trClass = ' class="warning"';
} elseif ($numTests == 0) {
       $trClass = ' class="danger"';
} else {

To fix this mismatch, I changed CodeCoverage\Coverage in the following way:

@@ -370,6 +370,14 @@
public function append(array $data, $id = null, $append = true, $linesToBeCovere
                      if (empty($this->data[$file][$k]) || !in_array($id, $this->data[$file][$k])) {
                          $this->data[$file][$k][] = $id;
                      }
+                } else if ($v == Driver::LINE_NOT_EXECUTED) {
+                    if (!isset($this->data[$file][$k])) {
+                        $this->data[$file][$k] = [];
+                    }
+                } else if ($v == Driver::LINE_NOT_EXECUTABLE) {
+                    if (!isset($this->data[$file][$k])) {
+                        $this->data[$file][$k] = null;
+                    }
                  }
              }
          }

I see that my pull request bounced, but that the master branch builds on travis are also failing, so I am unable to verify if my fix is correct.

JoepRoebroek commented 7 years ago

Ok, I investigated the code some more and concluded that my initial addition should already be done by the function initializeFilesThatAreSeenTheFirstTime. However this function is flawed when it is called multiple times and is presented with the same file, but where each file contains different lines in its array.

Therefore, the following fix also works:

 foreach ($data as $file => $lines) {
-    if ($this->filter->isFile($file) && !isset($this->data[$file])) {
+    if ($this->filter->isFile($file)) {
+        if(!isset($this->data[$file])) {
               $this->data[$file] = [];
+       }
        foreach ($lines as $k => $v) {
+           if (!isset($this->data[$file][$k])) {
                $this->data[$file][$k] = $v == -2 ? null : [];
+           }
        }
    }
}

Let me know what you think. I tried phpunit with #!/usr/bin/env php5 aswell, to see what the difference is. And with PHP5, the inital call to xdebug_get_code_coverage returns an array with all lines containing executable code, whereas in PHP7 this does not happen. Therefore, I think the above fix is sufficient.

JoepRoebroek commented 7 years ago

Ok, I applied the fix to my own project and it solves the problem somewhat, but not entirely. So I started diving into the mismatch between PHP5 and PHP7, and here is what I've come up with so far.

Since the process to get to the following test was quite long, I'll just post the result for you to try.

  1. Edit the phpunit file and add the following code before the command PHPUnit_TextUI_Command::main(); on the last line:
require PHPUNIT_COMPOSER_INSTALL;

// New code start 

/*
    TEST START
    Explanation:
        IF either STEP1 or STEP2 is commented out: xdebug data is correct
        OTHERWISE: xdebug data is not correct
 */
function checkData($data)
{
    if (isset($data['/<uuid-doctrine>/src/UuidBinaryType.php'])) {
        print_r($data['/<uuid-doctrine>/src/UuidBinaryType.php']);
    }
}

// STEP1: Do class exists
class_exists('Doctrine\\DBAL\\Types\\Type');

// Start code coverage
xdebug_start_code_coverage(XDEBUG_CC_UNUSED | XDEBUG_CC_DEAD_CODE);

// STEP2: Include a random file
    include '/<uuid-doctrine>/vendor/composer/../phpunit/php-token-stream/src/Token.php';
    //include '/<uuid-doctrine>/vendor/composer/../phpunit/php-text-template/src/Template.php';
    //include '/<uuid-doctrine>/vendor/composer/../phpunit/php-timer/src/Timer.php';
// STEP2: End

include '/<uuid-doctrine>/vendor/composer/../../src/UuidBinaryType.php';
$data = xdebug_get_code_coverage(true);
checkData($data);

die;

// New code end

PHPUnit_TextUI_Command::main();

If you comment out either STEP1 or STEP2, the code works normally. Otherwise, the $data will only contain two lines, which is incorrect. Adding a second argument false to class_exists will also get the code working normally, because it will prevent the file from actually being loaded. Since the file contains many dependencies which will all be loaded due to the class_exists call, debugging this is still going to be a tough challenge, but I hope this helps in further investigating this issue.

JoepRoebroek commented 7 years ago

Ok, after some digging I have been able to build a small script that reproduces the problem in XDebug and it is completely independent of the phpunit code. Here it is:

// test.php
xdebug_start_code_coverage(XDEBUG_CC_UNUSED | XDEBUG_CC_DEAD_CODE);

include 'TestClass2.php';
include 'TestClass.php';
$Test1 = new TestClass();

var_dump(xdebug_get_code_coverage());
// TestClass.php
class TestClass extends TestClass2
{
    public function test()
    {
        $a = 5*5;
        $b = $a*2;
        return $b;
    }
}
// TestClass2.php
class TestClass2
{
    public function test()
    {
        $a = 5*5;
        $b = $a*2;
        return $b;
    }
}

As you can see TestClass extends TestClass2. When I remove extends TestClass2, the bug does not occur. Also, when I put the line include 'TestClass2.php' directly in TestClass.php, the bug also does not occur. So it has to do with the fact that the class is included in a top level file, but extended from in another file. The bug does occur in PHP7, but not in PHP5.

This shows an XDebug related issue, therefore I will start an issue thread on their bugtracker.

derickr commented 7 years ago

Thanks for investigating!

michaelbutler commented 7 years ago

Much much thanks John for getting to the bottom of this, reproducing in native xdebug!

JoepRoebroek commented 7 years ago

Thanks guys. Enjoying the process so far, thankfully. I think I have nailed what causes the bug, but there are a number of possible solutions. I did not open a ticket on xdebug since all the information and people who could help are here and this way they also receive updates on the issue. Please correct me if I'm wrong and I'll open a ticket on your tracker @derickr.

So, in xdebug_code_coverage.c there is a function prefill_from_class_table. This function uses the zend_class_entry to fill the initial code coverage. To check whether the file was already processed it does the following:

if (!(ce->ce_flags & ZEND_XDEBUG_VISITED)) {
    ce->ce_flags |= ZEND_XDEBUG_VISITED;
    // code to fill initial code coverage table
}

I noticed this flag being set by something other than the xdebug code and it had to do with the expanding of the class_table by php-src and when a parent class was already present in that class_table.

Therefore, I searched php-src and found the function zend_do_inheritance of which the last line is:

ce->ce_flags |= parent_ce->ce_flags & (ZEND_HAS_STATIC_IN_METHODS | ZEND_ACC_USE_GUARDS);

The following statement I did not verify since I did not build php-src yet to check if it actually does it in this way. But the hypothesis is that: this line causes the class_entry to be flagged as ZEND_XDEBUG_VISITED, while it was not actually visited.

To solve this issue I see a couple of solutions, whichever is considered best:

  1. The most viable solution is to keep track of visited classes in a different way than using the internal ce_flags of the class_entry. A hash table could be an option. Maybe @derickr has more ideas on this? I am to unfamiliar with the rest of the xdebug code to give a more detailed solution.
  2. The simple and quick fix for this bug is to remove the ZEND_XDEBUG_VISITED check, however, performance wise this will be an absolute killer and I am unsure if visiting a class twice would cause new issues. But for those who need a quick fix, this is probably the easiest.
  3. Maybe the bug is related to PHP. Check with PHP if the ce_flags behavior for inheritance actually works as intended, maybe it is an unknown bug to them as well, I am not sure. If they fix it, xdebug will not require a fix.

Let me know what you guys think.

lordelph commented 7 years ago

That's some good work JoepRoebroek :)

Could a reasonable fix (at least for 7.0/7.1) simply be for xdebug to pick a different bit for ZEND_XDEBUG_VISITED? PHP internals aren't my thing, but I've done a bit of legwork here which might help...

It appears xdebug defines this as #define ZEND_XDEBUG_VISITED 0x1000000 (source)

This is the same value as #define ZEND_ACC_USE_GUARDS 0x1000000(source), so it looks like JoepRoebroek hypothesis is correct.

I did a search through php-src to find what other bits might be used by ce_flags, I came up with this list of constants which are actually referenced (there's a few times where some magic numbers are used instead of constants, but I caught those too).

ZEND_ACC_ABSTRACT                       0x02
ZEND_ACC_FINAL                          0x04
ZEND_ACC_IMPLICIT_ABSTRACT_CLASS        0x10
ZEND_ACC_EXPLICIT_ABSTRACT_CLASS        0x20
ZEND_ACC_INTERFACE                      0x40
ZEND_ACC_TRAIT                          0x80
ZEND_ACC_ANON_CLASS                    0x100
ZEND_ACC_ANON_BOUND                    0x200
ZEND_ACC_IMPLEMENT_INTERFACES        0x80000
ZEND_ACC_CONSTANTS_UPDATED          0x100000
ZEND_ACC_IMPLEMENT_TRAITS           0x400000
ZEND_HAS_STATIC_IN_METHODS          0x800000
ZEND_ACC_USE_GUARDS                0x1000000

#so I humbly suggest
ZEND_XDEBUG_VISITED               0x10000000

So, I'd suggest a value of 0x10000000. That bit does not appear to currently referenced in ce_flags. This is the same value as ZEND_ACC_HAS_TYPE_HINTS but that flag is used in fn_flags, and not ce_flags.

Hope that helps!

derickr commented 7 years ago

It does! Please add an xdebug ticket with the relevant info!

lordelph commented 7 years ago

OK, added as an xdebug ticket here https://bugs.xdebug.org/view.php?id=1386

JoepRoebroek commented 7 years ago

Thanks @lordelph :+1:

derickr commented 7 years ago

https://github.com/xdebug/xdebug/commit/80e9144b47f1847eb80f33f89e6f9c07eb4d8c7c

So I guess this can be closed now.

lordelph commented 7 years ago

Fast work there! Thank you so much, I'll compile and try out the master branch now. Kudos to JoepRoebroek for figuring the cause. Happy New Year!

lordelph commented 7 years ago

FYI I see xdebug 2.5.1 was released today and includes the patch for this issue https://xdebug.org/updates.php#x_2_5_1