Adds logfile output for WrapperRunner by prefixing bin/paratest with …

…PT_LOGGING_ENABLE='true'. Adds docs for logging. Cleans up README.

README.md

@@ -9,32 +9,26 @@ ParaTest
 The objective of ParaTest is to support parallel testing in PHPUnit. Provided you have well-written PHPUnit tests, you can drop `paratest` in your project and
 start using it with no additional bootstrap or configurations!
 
-Benefits
-------------
+# Benefits
 
 Why use `paratest` over the alternative parallel test runners out there?
 
 * Code Coverage report combining. *Run your tests in N parallel processes and all the code coverage output will be combined into one report.*
 * Zero configuration. *After composer install, run with `vendor/bin/paratest -p4 path/to/tests`. That's it!*
 * Flexible. *Isolate test files in separate processes or take advantage of WrapperRunner for even faster runs.*
 
-Installation
-------------
-
-### Composer ###
+# Installation
 
 To install with composer run the following command:
 
     composer require --dev brianium/paratest
 
-Versions
-------------
+# Versions
 For PHPUnit >= 7: Please use Paratest v2+
 
 For PHPUnit <= 6: Please use Paratest v1.
 
-Usage
------
+# Usage
 
 After installation, the binary can be found at `vendor/bin/paratest`. Usage is as follows:
 
@@ -79,7 +73,7 @@ Options:
  
 ```
 
-### Optimizing Speed ###
+### Optimizing Speed
 
 To get the most out of paratest, you have to adjust the parameters carefully.
 
@@ -114,7 +108,7 @@ To get the most out of paratest, you have to adjust the parameters carefully.
     Decrease max batch size to reduce command line length.
     Windows has limit around 32k, Linux - 2048k, Mac OS X - 256k.
 
-### Examples ###
+### Examples
 Examples assume your tests are located under `./test/unit`.
 
 ```
@@ -125,9 +119,16 @@ vendor/bin/paratest -p8 test/unit
 ```
 # Run all unit tests in 4 parallel processes with WrapperRunner and output html code coverage report to /tmp/coverage
 # (Code coverage requires Xdebug to be installed)
-vendor/bin/paratest -p8 --runner=WrapperRunner --coverage-html=/tmp/coverage test/unit
+vendor/bin/paratest -p4 --runner=WrapperRunner --coverage-html=/tmp/coverage test/unit
 ```
 
+### Troubleshooting
+If you run into problems with `paratest`, try to get more information about the issue by enabling debug output via `--verbose=1`.
+
+In case you are using the `WrapperRunner` for execution, consider enabling logging for troubleshooting via `export PT_LOGGING_ENABLE="true"`.
+The corresponding logfiles are placed in your `sys_get_temp_dir()`.
+
+See [Logging docs](docs/logging.md) for further information.
 
 ### Generating code coverage
 Examples assume your tests are located under `./test/unit`.
@@ -159,7 +160,7 @@ Code Coverage Report:
 **Caution**: Generating coverage is an art in itself. Please refer to our extensive guide on setting up everything correctly for 
 [code coverage generation with `paratest`](docs/code-coverage.md).
 
-### Windows ###
+### Windows
 
 Windows users be sure to use the appropriate batch files.
 
@@ -172,8 +173,7 @@ ParaTest assumes [PSR-0](https://github.com/php-fig/fig-standards/blob/master/ac
 For convenience paratest windows version use 79 columns mode to prevent blank lines in standard
 80x25 windows console.
 
-PHPUnit Xml Config Support
---------------------------
+# PHPUnit Xml Config Support
 
 When running PHPUnit tests, ParaTest will automatically pass the phpunit.xml or phpunit.xml.dist to the phpunit runner
 via the --configuration switch. ParaTest also allows the configuration path to be specified manually.
@@ -203,8 +203,7 @@ The following phpunit config file is used for ParaTest's test cases.
 </phpunit>
 ```
 
-Test token
-----------
+# Test token
 
 The `TEST_TOKEN` environment variable is guaranteed to have a value that is different
 from every other currently running test. This is useful to e.g. use a different database
@@ -218,8 +217,7 @@ if (getenv('TEST_TOKEN') !== false) {  // Using paratest
 }
 ```
 
-For Contributors: Testing paratest itself
--------------
+# For Contributors: Testing paratest itself
 
 ParaTest's test suite depends on PHPUnit being installed via composer. Make sure you run `composer install` after cloning.
 

bin/phpunit-wrapper

@@ -12,7 +12,22 @@ if (file_exists(__DIR__ . '/../../../autoload.php')) {
 
 $commands = fopen('php://stdin', 'r');
 $lastExitCode = 0;
+$rand = rand ( 0 , 999999 );
+$uniqueTestToken = getenv("UNIQUE_TEST_TOKEN") ?: "no_unique_test_token";
+$testToken = getenv("TEST_TOKEN") ?: "no_test_token";
+$filename = "paratest_t-{$testToken}_ut-{$uniqueTestToken}_r-{$rand}.log";
+$path = sys_get_temp_dir()."/".$filename;
+$loggingEnabled = getenv("PT_LOGGING_ENABLE");
+$logInfo = function(string $info) use ($path, $loggingEnabled){
+    if(!$loggingEnabled){
+        return;
+    }
+    file_put_contents($path, $info, FILE_APPEND | LOCK_EX);
+};
+
+$i = 0;
 while (true) {
+    $i++;
     if (feof($commands)) {
         exit($lastExitCode);
     }
@@ -27,11 +42,23 @@ while (true) {
     }
     echo "Executing: $command\n";
 
+    $info = [];
+    $info[] = "Time: ".(new \DateTime())->format(DateTime::RFC3339);
+    $info[] = "Iteration: $i";
+    $info[] = "Command: $command";
+    $info[] = PHP_EOL;
+    $infoText = implode(PHP_EOL,$info).PHP_EOL;
+    $logInfo($infoText);
+
     if (!preg_match_all('/\'([^\']*)\'[ ]?/', $command, $arguments)) {
         throw new \Exception("Failed to parse arguments from command line: \"" . $command . "\"");
     }
     $_SERVER['argv'] = $arguments[1];
 
+    ob_start();
     $lastExitCode = PHPUnit\TextUI\Command::main(false);
+    $infoText = ob_get_clean();
+    $logInfo($infoText);
+
     echo "FINISHED\n";
 }

docs/logging.md

@@ -0,0 +1,97 @@
+# Logging WrapperRunner output
+The `--runner WrapperRunner` option will start the script in `bin/phpunit-wrapper` as a long running process
+and send individual tests in via stdin/pipes. In order to make the execution of the process easier to understand,
+you can set the environment variable `PT_LOGGING_ENABLE` to true.
+
+## Enable logging: set `PT_LOGGING_ENABLE`
+Set the `PT_LOGGING_ENABLE` variable only for the `paratest` process:
+````
+PT_LOGGING_ENABLE="true" vendor/bin/paratest
+````
+
+Set the `PT_LOGGING_ENABLE` variable globally:
+````
+export PT_LOGGING_ENABLE="true" 
+vendor/bin/paratest
+````
+
+## Logfiles
+The logfiles are placed in the directory returned by `sys_get_temp_dir()`. The filename is determined 
+from the given `TEST_TOKEN`, `UNIQUE_TEST_TOKEN` and a random number via
+````
+$uniqueTestToken = getenv("UNIQUE_TEST_TOKEN") ?: "no_unique_test_token";
+$testToken = getenv("TEST_TOKEN") ?: "no_test_token";
+$filename = "paratest_t-{$testToken}_ut-{$uniqueTestToken}_r-{$rand}.log";
+$path = sys_get_temp_dir()."/".$filename;
+````
+If in doubt just check the contents of `bin/phpunit-wrapper`. 
+
+The resulting file names look like this:
+````
+ls -l /tmp
+total 5
+-rw-r--r-- 1 root root  Jan 25 17:57 paratest_t-1_ut-5c4b4e136692d_r-457700.log
+-rw-r--r-- 1 root root  Jan 25 17:57 paratest_t-2_ut-5c4b4e136855c_r-916202.log
+-rw-r--r-- 1 root root  Jan 25 17:57 paratest_t-3_ut-5c4b4e1368ada_r-75267.log
+-rw-r--r-- 1 root root  Jan 25 17:57 paratest_t-4_ut-5c4b4e1368ecf_r-536174.log
+-rw-r--r-- 1 root root  Jan 25 17:57 paratest_t-5_ut-5c4b4e136932c_r-666883.log
+````
+
+If paratest is run with the `--no-test-tokens` option, the files look like this:
+````
+ls -l /tmp
+total 5
+-rw-r--r-- 1 root root  Jan 25 17:59 paratest_t-no_test_token_ut-no_unique_test_token_r-142884.log
+-rw-r--r-- 1 root root  Jan 25 17:59 paratest_t-no_test_token_ut-no_unique_test_token_r-351471.log
+-rw-r--r-- 1 root root  Jan 25 17:59 paratest_t-no_test_token_ut-no_unique_test_token_r-455307.log
+-rw-r--r-- 1 root root  Jan 25 17:59 paratest_t-no_test_token_ut-no_unique_test_token_r-824877.log
+-rw-r--r-- 1 root root  Jan 25 17:59 paratest_t-no_test_token_ut-no_unique_test_token_r-827359.log
+````
+
+## Logged info
+The logged information contains:
+- Iteration: the incrementing job number
+- Time: current timestamp in RFC3339 format
+- Command: The command that is being executed
+- verbatim output of the command captured by `ob_start()` and returned by `ob_get_clean()`
+
+Example:
+````
+cat /tmp/paratest_t-5_ut-5c4b4e136932c_r-666883.log
+Time: 2019-01-25T18:19:09+00:00
+Iteration: 1
+Command: '/codebase/paratest/vendor/phpunit/phpunit/phpunit' '--configuration' '/codebase/paratest/phpunit.xml.dist' '--log-junit' '/tmp/PT_e4yf1N' 'ParaTest\Console\VersionProviderTest' 'test/unit//Console/VersionProviderTest.php'
+
+
+PHPUnit 7.5.2 by Sebastian Bergmann and contributors.
+
+....                                                                4 / 4 (100%)
+
+Time: 806 ms, Memory: 4.00MB
+
+OK (4 tests, 7 assertions)
+Time: 2019-01-25T18:19:10+00:00
+Iteration: 2
+Command: '/codebase/paratest/vendor/phpunit/phpunit/phpunit' '--configuration' '/codebase/paratest/phpunit.xml.dist' '--log-junit' '/tmp/PT_wGmQPE' 'ParaTest\Runners\PHPUnit\SuiteTest' 'test/unit//Runners/PHPUnit/SuiteTest.php'
+
+
+PHPUnit 7.5.2 by Sebastian Bergmann and contributors.
+
+.                                                                   1 / 1 (100%)
+
+Time: 826 ms, Memory: 4.00MB
+
+OK (1 test, 1 assertion)
+Time: 2019-01-25T18:19:10+00:00
+Iteration: 3
+Command: '/codebase/paratest/vendor/phpunit/phpunit/phpunit' '--configuration' '/codebase/paratest/phpunit.xml.dist' '--log-junit' '/tmp/PT_E2vYmt' 'ParaTest\Runners\PHPUnit\TestMethodTest' 'test/unit//Runners/PHPUnit/TestMethodTest.php'
+
+
+PHPUnit 7.5.2 by Sebastian Bergmann and contributors.
+
+.                                                                   1 / 1 (100%)
+
+Time: 845 ms, Memory: 4.00MB
+
+OK (1 test, 1 assertion)
+````