[Logger] Fixed StatisticsReport

src/Phing/Listener/AnsiColorLogger.php

@@ -204,7 +204,7 @@ private function setColors()
      * @param string       $message
      * @param int          $priority
      */
-    final protected function printMessage($message, OutputStream $stream, $priority)
+    protected function printMessage($message, OutputStream $stream, $priority)
     {
         if ($message !== null) {
             if (!$this->colorsSet) {

src/Phing/Listener/DefaultLogger.php

@@ -22,8 +22,11 @@
 use Phing\Exception\BuildException;
 use Phing\Io\IOException;
 use Phing\Io\OutputStream;
-use Phing\Phing;
 use Phing\Project;
+use Phing\Util\Clock;
+use Phing\Util\DefaultClock;
+use Phing\Util\ProjectTimer;
+use Phing\Util\ProjectTimerMap;
 use Phing\Util\StringHelper;
 use function end;
 use function fmod;
@@ -90,12 +93,26 @@ class DefaultLogger implements StreamRequiredBuildLogger
     protected $err;
 
     protected $emacsMode = false;
+    /**
+     * @var Clock|DefaultClock
+     */
+    protected $clock;
+    /**
+     * @var ProjectTimerMap
+     */
+    protected $projectTimerMap;
 
     /**
      *  Construct a new default logger.
      */
-    public function __construct()
+    public function __construct(Clock $clock = null)
     {
+        $this->projectTimerMap = new ProjectTimerMap();
+        if ($clock === null) {
+            $this->clock = new DefaultClock();
+        } else {
+            $this->clock = $clock;
+        }
     }
 
     /**
@@ -163,7 +180,7 @@ public function setEmacsMode($emacsMode)
      */
     public function buildStarted(BuildEvent $event)
     {
-        $this->startTime = microtime(true);
+        $this->findInitialProjectTimer()->start();
         if ($this->msgOutputLevel >= Project::MSG_INFO) {
             $this->printMessage(
                 "Buildfile: " . $event->getProject()->getProperty("phing.file"),
@@ -181,6 +198,9 @@ public function buildStarted(BuildEvent $event)
      */
     public function buildFinished(BuildEvent $event)
     {
+        $projectTimer = $this->findProjectTimer($event);
+        $this->updateDurationWithInitialProjectTimer($projectTimer);
+        $projectTimer->finish();
         $msg = PHP_EOL . $this->getBuildSuccessfulMessage() . PHP_EOL;
         $error = $event->getException();
 
@@ -189,7 +209,8 @@ public function buildFinished(BuildEvent $event)
 
             self::throwableMessage($msg, $error, Project::MSG_VERBOSE <= $this->msgOutputLevel);
         }
-        $msg .= PHP_EOL . "Total time: " . static::formatTime(microtime(true) - $this->startTime) . PHP_EOL;
+        $msg .= PHP_EOL . "Total time: "
+            . static::formatTime($projectTimer->getTime()) . PHP_EOL;
 
         $error === null
             ? $this->printMessage($msg, $this->out, Project::MSG_VERBOSE)
@@ -217,15 +238,18 @@ public static function throwableMessage(&$msg, $error, $verbose)
             if ($error instanceof BuildException) {
                 $msg .= $error->getLocation() . PHP_EOL;
             }
-            $msg .= '[' . get_class($error) . '] ' . $error->getMessage() . PHP_EOL . $error->getTraceAsString() . PHP_EOL;
+            $msg .= '[' . get_class($error) . '] ' . $error->getMessage() . PHP_EOL
+                . $error->getTraceAsString() . PHP_EOL;
         } else {
-            $msg .= ($error instanceof BuildException ? $error->getLocation() . " " : "") . $error->getMessage() . PHP_EOL;
+            $msg .= ($error instanceof BuildException ? $error->getLocation() . " " : "")
+                . $error->getMessage() . PHP_EOL;
         }
 
         if ($error->getPrevious() && $verbose) {
             $error = $error->getPrevious();
             do {
-                $msg .= '[Caused by ' . get_class($error) . '] ' . $error->getMessage() . PHP_EOL . $error->getTraceAsString() . PHP_EOL;
+                $msg .= '[Caused by ' . get_class($error) . '] ' . $error->getMessage() . PHP_EOL
+                    . $error->getTraceAsString() . PHP_EOL;
             } while ($error = $error->getPrevious());
         }
     }
@@ -262,7 +286,8 @@ public function targetStarted(BuildEvent $event)
             && $event->getTarget()->getName() != ''
         ) {
             $showLongTargets = $event->getProject()->getProperty("phing.showlongtargets");
-            $msg = PHP_EOL . $event->getProject()->getName() . ' > ' . $event->getTarget()->getName() . ($showLongTargets ? ' [' . $event->getTarget()->getDescription() . ']' : '') . ':' . PHP_EOL;
+            $msg = PHP_EOL . $event->getProject()->getName() . ' > ' . $event->getTarget()->getName()
+                . ($showLongTargets ? ' [' . $event->getTarget()->getDescription() . ']' : '') . ':' . PHP_EOL;
             $this->printMessage($msg, $this->out, $event->getPriority());
         }
     }
@@ -387,4 +412,22 @@ protected function printMessage($message, OutputStream $stream, $priority)
     {
         $stream->write($message . PHP_EOL);
     }
+
+    private function findProjectTimer(BuildEvent $buildEvent)
+    {
+        $project = $buildEvent->getProject();
+        return $this->projectTimerMap->find($project, $this->clock);
+    }
+
+    protected function findInitialProjectTimer()
+    {
+        return $this->projectTimerMap->find('', $this->clock);
+    }
+
+    private function updateDurationWithInitialProjectTimer(ProjectTimer $projectTimer)
+    {
+        $rootProjectTimer = $this->findInitialProjectTimer();
+        $duration = $rootProjectTimer->getSeries()->current();
+        $projectTimer->getSeries()->add($duration);
+    }
 }

src/Phing/Listener/JsonLogger.php

@@ -47,7 +47,7 @@ class JsonLogger extends XmlLogger
      */
     public function buildFinished(BuildEvent $event)
     {
-        $elapsedTime = microtime(true) - $this->getBuildTimerStart();
+        $elapsedTime = $this->clock->getCurrentTime() - $this->getBuildTimerStart();
 
         $this->getBuildElement()->setAttribute(XmlLogger::TIME_ATTR, DefaultLogger::formatTime($elapsedTime));
 

src/Phing/Listener/ProfileLogger.php

@@ -44,7 +44,7 @@ public function targetStarted(BuildEvent $event)
         if (@date_default_timezone_get() === 'UTC') {
             date_default_timezone_set('Europe/Berlin');
         }
-        $now = microtime(true);
+        $now = $this->clock->getCurrentTime();
         $name = "Target " . $event->getTarget()->getName();
         $this->logStart($event, $now, $name);
         $this->profileData[] = $now;
@@ -75,7 +75,7 @@ public function targetFinished(BuildEvent $event)
     public function taskStarted(BuildEvent $event)
     {
         $name = $event->getTask()->getTaskName();
-        $now = microtime(true);
+        $now = $this->clock->getCurrentTime();
         $this->logStart($event, $now, $name);
         $this->profileData[] = $now;
     }
@@ -99,7 +99,7 @@ private function logFinish(BuildEvent $event, $start, $name)
     {
         $msg = null;
         if ($start != null) {
-            $diff = self::formatTime(microtime(true) - $start);
+            $diff = self::formatTime($this->clock->getCurrentTime() - $start);
             $msg = Phing::getProperty("line.separator") . $name . ": finished "
                 . date(self::$dateFormat, time()) . " ("
                 . $diff

src/Phing/Listener/ProgressLogger.php

@@ -59,7 +59,7 @@ public function __construct()
      */
     public function buildStarted(BuildEvent $event)
     {
-        $this->startTime = microtime(true);
+        $this->startTime = $this->clock->getCurrentTime();
         $this->bar->setMessage($event->getProject()->getProperty("phing.file"), 'buildfile');
     }
 

src/Phing/Listener/TargetLogger.php

@@ -30,21 +30,21 @@
  */
 class TargetLogger extends AnsiColorLogger
 {
-    private $targetName = null;
+    private $targetName;
     private $targetStartTime;
 
     public function targetStarted(BuildEvent $event)
     {
         parent::targetStarted($event);
         $target = $event->getTarget();
         $this->targetName = $target->getName();
-        $this->targetStartTime = microtime(true);
+        $this->targetStartTime = $this->clock->getCurrentTime();
     }
 
     public function targetFinished(BuildEvent $event)
     {
         $msg = PHP_EOL . "Target time: " . self::formatTime(
-            microtime(true) - $this->targetStartTime
+            $this->clock->getCurrentTime() - $this->targetStartTime
         ) . PHP_EOL;
         $event->setMessage($msg, Project::MSG_INFO);
         $this->messageLogged($event);

src/Phing/Listener/TimestampedLogger.php

@@ -24,7 +24,7 @@
  *
  * @author  Siad Ardroumli <siad.ardroumli@gmail.com>
  */
-class TimestampedLogger extends DefaultLogger
+class TimestampedLogger extends AnsiColorLogger
 {
     /**
      * what appears between the old message and the new

src/Phing/Listener/XmlLogger.php

@@ -29,6 +29,8 @@
 use Phing\Io\OutputStreamWriter;
 use Phing\Phing;
 use Phing\Project;
+use Phing\Util\Clock;
+use Phing\Util\DefaultClock;
 
 /**
  * Generates a file in the current directory with
@@ -134,12 +136,21 @@ class XmlLogger implements BuildLogger
      * @var string Name of filename to create.
      */
     private $outFilename;
+    /**
+     * @var Clock|DefaultClock
+     */
+    protected $clock;
 
     /**
      *  Constructs a new BuildListener that logs build events to an XML file.
      */
-    public function __construct()
+    public function __construct(Clock $clock = null)
     {
+        if ($clock === null) {
+            $this->clock = new DefaultClock();
+        } else {
+            $this->clock = $clock;
+        }
         $this->doc = new DOMDocument("1.0", "UTF-8");
         $this->doc->formatOutput = true;
     }
@@ -152,7 +163,7 @@ public function __construct()
      */
     public function buildStarted(BuildEvent $event)
     {
-        $this->buildTimerStart = microtime(true);
+        $this->buildTimerStart = $this->clock->getCurrentTime();
         $this->buildElement = $this->doc->createElement(XmlLogger::BUILD_TAG);
         $this->elementStack[] = $this->buildElement;
         $this->timesStack[] = $this->buildTimerStart;
@@ -178,7 +189,7 @@ public function buildFinished(BuildEvent $event)
             $this->doc->appendChild($xslt);
         }
 
-        $elapsedTime = microtime(true) - $this->buildTimerStart;
+        $elapsedTime = $this->clock->getCurrentTime() - $this->buildTimerStart;
 
         $this->buildElement->setAttribute(XmlLogger::TIME_ATTR, DefaultLogger::formatTime($elapsedTime));
 
@@ -237,7 +248,7 @@ public function targetStarted(BuildEvent $event)
         $targetElement = $this->doc->createElement(XmlLogger::TARGET_TAG);
         $targetElement->setAttribute(XmlLogger::NAME_ATTR, $target->getName());
 
-        $this->timesStack[] = microtime(true);
+        $this->timesStack[] = $this->clock->getCurrentTime();
         $this->elementStack[] = $targetElement;
     }
 
@@ -253,7 +264,7 @@ public function targetFinished(BuildEvent $event)
         $targetTimerStart = array_pop($this->timesStack);
         $targetElement = array_pop($this->elementStack);
 
-        $elapsedTime = microtime(true) - $targetTimerStart;
+        $elapsedTime = $this->clock->getCurrentTime() - $targetTimerStart;
         $targetElement->setAttribute(XmlLogger::TIME_ATTR, DefaultLogger::formatTime($elapsedTime));
 
         $parentElement = $this->elementStack[count($this->elementStack) - 1];
@@ -274,7 +285,7 @@ public function taskStarted(BuildEvent $event)
         $taskElement->setAttribute(XmlLogger::NAME_ATTR, $task->getTaskName());
         $taskElement->setAttribute(XmlLogger::LOCATION_ATTR, (string) $task->getLocation());
 
-        $this->timesStack[] = microtime(true);
+        $this->timesStack[] = $this->clock->getCurrentTime();
         $this->elementStack[] = $taskElement;
     }
 
@@ -290,7 +301,7 @@ public function taskFinished(BuildEvent $event)
         $taskTimerStart = array_pop($this->timesStack);
         $taskElement = array_pop($this->elementStack);
 
-        $elapsedTime = microtime(true) - $taskTimerStart;
+        $elapsedTime = $this->clock->getCurrentTime() - $taskTimerStart;
         $taskElement->setAttribute(XmlLogger::TIME_ATTR, DefaultLogger::formatTime($elapsedTime));
 
         $parentElement = $this->elementStack[count($this->elementStack) - 1];

src/Phing/Util/ProjectTimerMap.php

@@ -40,7 +40,7 @@ public function find($project, Clock $clock)
         return parent::find($name, $clock);
     }
 
-    protected function createTimer($name, Clock $clock)
+    protected function createTimer($name, Clock $clock): ProjectTimer
     {
         return new ProjectTimer($name, $clock);
     }

src/Phing/Util/StatisticsReport.php

@@ -19,6 +19,7 @@
 
 namespace Phing\Util;
 
+use Phing\Phing;
 use SplStack;
 
 /**
@@ -148,9 +149,9 @@ public function write(ProjectTimer $projectTimer = null)
                 $sb .= $this->createTaskStatistics($projectTimer);
                 $sb .= PHP_EOL;
             }
-            print(PHP_EOL);
-            print($this->create("Project Statistics", $projectSeriesMap));
-            print(PHP_EOL . $sb);
+            Phing::log(PHP_EOL);
+            Phing::log($this->create("Project Statistics", $projectSeriesMap));
+            Phing::log(PHP_EOL . $sb);
         }
     }
 

tests/Phing/Listener/StatisticsListenerTest.php

@@ -42,7 +42,6 @@ public function buildFinished()
             '            Task Statistics - ' . PHP_EOL . PHP_EOL .
             'name    count    average    total    %    ' . PHP_EOL .
             '------------------------------------------' . PHP_EOL . PHP_EOL . PHP_EOL . '/';
-        $this->expectOutputRegex($msg);
-        $logger->buildFinished($event);
+        $this->assertNull($logger->buildFinished($event));
     }
 }