CMake/Source/CTest/cmCTestRunTest.cxx

/*============================================================================
  CMake - Cross Platform Makefile Generator
  Copyright 2000-2009 Kitware, Inc., Insight Software Consortium

  Distributed under the OSI-approved BSD License (the "License");
  see accompanying file Copyright.txt for details.

  This software is distributed WITHOUT ANY WARRANTY; without even the
  implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
  See the License for more information.
============================================================================*/

#include "cmCTestRunTest.h"
#include "cmCTestMemCheckHandler.h"
#include "cmCTest.h"
#include "cmSystemTools.h"
#include "cm_curl.h"

#include <cm_zlib.h>
#include <cmsys/Base64.h>

cmCTestRunTest::cmCTestRunTest(cmCTestTestHandler* handler)
{
  this->CTest = handler->CTest;
  this->TestHandler = handler;
  this->TestProcess = 0;
  this->TestResult.ExecutionTime =0;
  this->TestResult.ReturnValue = 0;
  this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  this->TestResult.TestCount = 0;
  this->TestResult.Properties = 0;
  this->ProcessOutput = "";
  this->CompressedOutput = "";
  this->CompressionRatio = 2;
  this->StopTimePassed = false;
}

cmCTestRunTest::~cmCTestRunTest()
{
}

//----------------------------------------------------------------------------
bool cmCTestRunTest::CheckOutput()
{
  // Read lines for up to 0.1 seconds of total time.
  double timeout = 0.1;
  double timeEnd = cmSystemTools::GetTime() + timeout;
  std::string line;
  while((timeout = timeEnd - cmSystemTools::GetTime(), timeout > 0))
    {
    int p = this->TestProcess->GetNextOutputLine(line, timeout);
    if(p == cmsysProcess_Pipe_None)
      {
      // Process has terminated and all output read.
      return false;
      }
    else if(p == cmsysProcess_Pipe_STDOUT ||
            p == cmsysProcess_Pipe_STDERR)
      {
      // Store this line of output.
      cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
                 this->GetIndex() << ": " << line << std::endl);
      this->ProcessOutput += line;
      this->ProcessOutput += "\n";
      }
    else // if(p == cmsysProcess_Pipe_Timeout)
      {
      break;
      }
    }
  return true;
}

//---------------------------------------------------------
// Streamed compression of test output.  The compressed data
// is appended to this->CompressedOutput
void cmCTestRunTest::CompressOutput()
{
  int ret;
  z_stream strm;

  unsigned char* in =
    reinterpret_cast<unsigned char*>(
    const_cast<char*>(this->ProcessOutput.c_str()));
  //zlib makes the guarantee that this is the maximum output size
  int outSize = static_cast<int>(
    static_cast<double>(this->ProcessOutput.size()) * 1.001 + 13.0);
  unsigned char* out = new unsigned char[outSize];

  strm.zalloc = Z_NULL;
  strm.zfree = Z_NULL;
  strm.opaque = Z_NULL;
  ret = deflateInit(&strm, -1); //default compression level
  if (ret != Z_OK)
    {
    delete[] out;
    return;
    }

  strm.avail_in = static_cast<uInt>(this->ProcessOutput.size());
  strm.next_in = in;
  strm.avail_out = outSize;
  strm.next_out = out;
  ret = deflate(&strm, Z_FINISH);

  if(ret == Z_STREAM_ERROR || ret != Z_STREAM_END)
    {
    cmCTestLog(this->CTest, ERROR_MESSAGE, "Error during output "
      "compression. Sending uncompressed output." << std::endl);
    delete[] out;
    return;
    }

  (void)deflateEnd(&strm);

  unsigned char *encoded_buffer
    = new unsigned char[static_cast<int>(outSize * 1.5)];

  unsigned long rlen
    = cmsysBase64_Encode(out, strm.total_out, encoded_buffer, 1);

  for(unsigned long i = 0; i < rlen; i++)
    {
    this->CompressedOutput += encoded_buffer[i];
    }

  if(strm.total_in)
    {
    this->CompressionRatio = static_cast<double>(strm.total_out) /
                             static_cast<double>(strm.total_in);
    }

  delete [] encoded_buffer;
  delete [] out;
}

//---------------------------------------------------------
bool cmCTestRunTest::EndTest(size_t completed, size_t total, bool started)
{
  if ((!this->TestHandler->MemCheck &&
      this->CTest->ShouldCompressTestOutput()) ||
      (this->TestHandler->MemCheck &&
      this->CTest->ShouldCompressMemCheckOutput()))
    {
    this->CompressOutput();
    }

  this->WriteLogOutputTop(completed, total);
  std::string reason;
  bool passed = true;
  int res = started ? this->TestProcess->GetProcessStatus()
                    : cmsysProcess_State_Error;
  int retVal = this->TestProcess->GetExitValue();
  std::vector<std::pair<cmsys::RegularExpression,
    std::string> >::iterator passIt;
  bool forceFail = false;
  bool outputTestErrorsToConsole = false;
  if ( this->TestProperties->RequiredRegularExpressions.size() > 0 )
    {
    bool found = false;
    for ( passIt = this->TestProperties->RequiredRegularExpressions.begin();
          passIt != this->TestProperties->RequiredRegularExpressions.end();
          ++ passIt )
      {
      if ( passIt->first.find(this->ProcessOutput.c_str()) )
        {
        found = true;
        reason = "Required regular expression found.";
        break;
        }
      }
    if ( !found )
      {
      reason = "Required regular expression not found.";
      forceFail = true;
      }
    reason +=  "Regex=[";
    for ( passIt = this->TestProperties->RequiredRegularExpressions.begin();
          passIt != this->TestProperties->RequiredRegularExpressions.end();
          ++ passIt )
      {
      reason += passIt->second;
      reason += "\n";
      }
    reason += "]";
    }
  if ( this->TestProperties->ErrorRegularExpressions.size() > 0 )
    {
    for ( passIt = this->TestProperties->ErrorRegularExpressions.begin();
          passIt != this->TestProperties->ErrorRegularExpressions.end();
          ++ passIt )
      {
      if ( passIt->first.find(this->ProcessOutput.c_str()) )
        {
        reason = "Error regular expression found in output.";
        reason += " Regex=[";
        reason += passIt->second;
        reason += "]";
        forceFail = true;
        break;
        }
      }
    }
  if (res == cmsysProcess_State_Exited)
    {
    bool success =
      !forceFail &&  (retVal == 0 ||
      this->TestProperties->RequiredRegularExpressions.size());
    if(this->TestProperties->SkipReturnCode >= 0
      && this->TestProperties->SkipReturnCode == retVal)
      {
      this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
      cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Skipped ");
      }
    else if((success && !this->TestProperties->WillFail)
      || (!success && this->TestProperties->WillFail))
      {
      this->TestResult.Status = cmCTestTestHandler::COMPLETED;
      cmCTestLog(this->CTest, HANDLER_OUTPUT, "   Passed  " );
      }
    else
      {
      this->TestResult.Status = cmCTestTestHandler::FAILED;
      cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Failed  " << reason );
      outputTestErrorsToConsole = this->CTest->OutputTestOutputOnTestFailure;
      }
    }
  else if ( res == cmsysProcess_State_Expired )
    {
    cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Timeout ");
    this->TestResult.Status = cmCTestTestHandler::TIMEOUT;
    outputTestErrorsToConsole = this->CTest->OutputTestOutputOnTestFailure;
    }
  else if ( res == cmsysProcess_State_Exception )
    {
    outputTestErrorsToConsole = this->CTest->OutputTestOutputOnTestFailure;
    cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Exception: ");
    switch(this->TestProcess->GetExitException())
      {
      case cmsysProcess_Exception_Fault:
        cmCTestLog(this->CTest, HANDLER_OUTPUT, "SegFault");
        this->TestResult.Status = cmCTestTestHandler::SEGFAULT;
        break;
      case cmsysProcess_Exception_Illegal:
        cmCTestLog(this->CTest, HANDLER_OUTPUT, "Illegal");
        this->TestResult.Status = cmCTestTestHandler::ILLEGAL;
        break;
      case cmsysProcess_Exception_Interrupt:
        cmCTestLog(this->CTest, HANDLER_OUTPUT, "Interrupt");
        this->TestResult.Status = cmCTestTestHandler::INTERRUPT;
        break;
      case cmsysProcess_Exception_Numerical:
        cmCTestLog(this->CTest, HANDLER_OUTPUT, "Numerical");
        this->TestResult.Status = cmCTestTestHandler::NUMERICAL;
        break;
      default:
        cmCTestLog(this->CTest, HANDLER_OUTPUT, "Other");
        this->TestResult.Status = cmCTestTestHandler::OTHER_FAULT;
      }
    }
  else //cmsysProcess_State_Error
    {
    cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Not Run ");
    }

  passed = this->TestResult.Status == cmCTestTestHandler::COMPLETED;
  char buf[1024];
  sprintf(buf, "%6.2f sec", this->TestProcess->GetTotalTime());
  cmCTestLog(this->CTest, HANDLER_OUTPUT, buf << "\n" );

  if ( outputTestErrorsToConsole )
    {
    cmCTestLog(this->CTest, HANDLER_OUTPUT, this->ProcessOutput << std::endl );
    }

  if ( this->TestHandler->LogFile )
    {
    *this->TestHandler->LogFile << "Test time = " << buf << std::endl;
    }

  // Set the working directory to the tests directory
  std::string oldpath = cmSystemTools::GetCurrentWorkingDirectory();
  cmSystemTools::ChangeDirectory(this->TestProperties->Directory.c_str());

  this->DartProcessing();

  // restore working directory
  cmSystemTools::ChangeDirectory(oldpath.c_str());


  // if this is doing MemCheck then all the output needs to be put into
  // Output since that is what is parsed by cmCTestMemCheckHandler
  if(!this->TestHandler->MemCheck && started)
    {
    this->TestHandler->CleanTestOutput(this->ProcessOutput,
      static_cast<size_t>
      (this->TestResult.Status == cmCTestTestHandler::COMPLETED ?
      this->TestHandler->CustomMaximumPassedTestOutputSize :
      this->TestHandler->CustomMaximumFailedTestOutputSize));
    }
  this->TestResult.Reason = reason;
  if (this->TestHandler->LogFile)
    {
    bool pass = true;
    const char* reasonType = "Test Pass Reason";
    if(this->TestResult.Status != cmCTestTestHandler::COMPLETED &&
       this->TestResult.Status != cmCTestTestHandler::NOT_RUN)
      {
      reasonType = "Test Fail Reason";
      pass = false;
      }
    double ttime = this->TestProcess->GetTotalTime();
    int hours = static_cast<int>(ttime / (60 * 60));
    int minutes = static_cast<int>(ttime / 60) % 60;
    int seconds = static_cast<int>(ttime) % 60;
    char buffer[100];
    sprintf(buffer, "%02d:%02d:%02d", hours, minutes, seconds);
    *this->TestHandler->LogFile
      << "----------------------------------------------------------"
      << std::endl;
    if(this->TestResult.Reason.size())
      {
      *this->TestHandler->LogFile << reasonType << ":\n"
        << this->TestResult.Reason << "\n";
      }
    else
      {
      if(pass)
        {
        *this->TestHandler->LogFile << "Test Passed.\n";
        }
      else
        {
        *this->TestHandler->LogFile << "Test Failed.\n";
        }
      }
    *this->TestHandler->LogFile << "\"" << this->TestProperties->Name.c_str()
      << "\" end time: " << this->CTest->CurrentTime() << std::endl
      << "\"" << this->TestProperties->Name.c_str() << "\" time elapsed: "
      << buffer << std::endl
      << "----------------------------------------------------------"
      << std::endl << std::endl;
    }
  // if the test actually started and ran
  // record the results in TestResult
  if(started)
    {
    bool compress = !this->TestHandler->MemCheck &&
      this->CompressionRatio < 1 &&
      this->CTest->ShouldCompressTestOutput();
    this->TestResult.Output = compress ? this->CompressedOutput
      : this->ProcessOutput;
    this->TestResult.CompressOutput = compress;
    this->TestResult.ReturnValue = this->TestProcess->GetExitValue();
    this->TestResult.CompletionStatus = "Completed";
    this->TestResult.ExecutionTime = this->TestProcess->GetTotalTime();
    this->MemCheckPostProcess();
    this->ComputeWeightedCost();
    }
  // Always push the current TestResult onto the
  // TestHandler vector
  this->TestHandler->TestResults.push_back(this->TestResult);
  delete this->TestProcess;
  return passed;
}

//----------------------------------------------------------------------
void cmCTestRunTest::ComputeWeightedCost()
{
  double prev = static_cast<double>(this->TestProperties->PreviousRuns);
  double avgcost = static_cast<double>(this->TestProperties->Cost);
  double current = this->TestResult.ExecutionTime;

  if(this->TestResult.Status == cmCTestTestHandler::COMPLETED)
    {
    this->TestProperties->Cost =
      static_cast<float>(((prev * avgcost) + current) / (prev + 1.0));
    this->TestProperties->PreviousRuns++;
    }
}

//----------------------------------------------------------------------
void cmCTestRunTest::MemCheckPostProcess()
{
  if(!this->TestHandler->MemCheck)
    {
    return;
    }
  cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT, this->Index
             << ": process test output now: "
             << this->TestProperties->Name.c_str() << " "
             << this->TestResult.Name.c_str() << std::endl);
  cmCTestMemCheckHandler * handler = static_cast<cmCTestMemCheckHandler*>
    (this->TestHandler);
  switch ( handler->MemoryTesterStyle )
    {
    case cmCTestMemCheckHandler::VALGRIND:
      handler->PostProcessValgrindTest(this->TestResult, this->Index);
      break;
    case cmCTestMemCheckHandler::PURIFY:
      handler->PostProcessPurifyTest(this->TestResult, this->Index);
      break;
    case cmCTestMemCheckHandler::BOUNDS_CHECKER:
      handler->PostProcessBoundsCheckerTest(this->TestResult, this->Index);
      break;
    default:
      break;
    }
}

//----------------------------------------------------------------------
// Starts the execution of a test.  Returns once it has started
bool cmCTestRunTest::StartTest(size_t total)
{
  cmCTestLog(this->CTest, HANDLER_OUTPUT, std::setw(2*getNumWidth(total) + 8)
    << "Start "
    << std::setw(getNumWidth(this->TestHandler->GetMaxIndex()))
    << this->TestProperties->Index << ": "
    << this->TestProperties->Name << std::endl);
  this->ComputeArguments();
  std::vector<std::string>& args = this->TestProperties->Args;
  this->TestResult.Properties = this->TestProperties;
  this->TestResult.ExecutionTime = 0;
  this->TestResult.CompressOutput = false;
  this->TestResult.ReturnValue = -1;
  this->TestResult.CompletionStatus = "Failed to start";
  this->TestResult.Status = cmCTestTestHandler::BAD_COMMAND;
  this->TestResult.TestCount = this->TestProperties->Index;
  this->TestResult.Name = this->TestProperties->Name;
  this->TestResult.Path = this->TestProperties->Directory.c_str();

  if(args.size() >= 2 && args[1] == "NOT_AVAILABLE")
    {
    this->TestProcess = new cmProcess;
    std::string msg;
    if(this->CTest->GetConfigType().empty())
      {
      msg = "Test not available without configuration.";
      msg += "  (Missing \"-C <config>\"?)";
      }
    else
      {
      msg = "Test not available in configuration \"";
      msg += this->CTest->GetConfigType();
      msg += "\".";
      }
    *this->TestHandler->LogFile << msg << std::endl;
    cmCTestLog(this->CTest, ERROR_MESSAGE, msg << std::endl);
    this->TestResult.Output = msg;
    this->TestResult.FullCommandLine = "";
    this->TestResult.CompletionStatus = "Not Run";
    this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
    return false;
    }

  // Check if all required files exist
  for(std::vector<std::string>::iterator i =
    this->TestProperties->RequiredFiles.begin();
    i != this->TestProperties->RequiredFiles.end(); ++i)
    {
    std::string file = *i;

    if(!cmSystemTools::FileExists(file.c_str()))
      {
      //Required file was not found
      this->TestProcess = new cmProcess;
      *this->TestHandler->LogFile << "Unable to find required file: "
               << file.c_str() << std::endl;
      cmCTestLog(this->CTest, ERROR_MESSAGE, "Unable to find required file: "
               << file.c_str() << std::endl);
      this->TestResult.Output = "Unable to find required file: " + file;
      this->TestResult.FullCommandLine = "";
      this->TestResult.CompletionStatus = "Not Run";
      this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
      return false;
      }
    }
  // log and return if we did not find the executable
  if (this->ActualCommand == "")
    {
    // if the command was not found create a TestResult object
    // that has that information
    this->TestProcess = new cmProcess;
    *this->TestHandler->LogFile << "Unable to find executable: "
                   << args[1].c_str() << std::endl;
    cmCTestLog(this->CTest, ERROR_MESSAGE, "Unable to find executable: "
               << args[1].c_str() << std::endl);
    this->TestResult.Output = "Unable to find executable: " + args[1];
    this->TestResult.FullCommandLine = "";
    this->TestResult.CompletionStatus = "Not Run";
    this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
    return false;
    }
  this->StartTime = this->CTest->CurrentTime();

  double timeout = this->ResolveTimeout();

  if(this->StopTimePassed)
    {
    return false;
    }
  return this->ForkProcess(timeout, this->TestProperties->ExplicitTimeout,
                           &this->TestProperties->Environment);
}

//----------------------------------------------------------------------
void cmCTestRunTest::ComputeArguments()
{
  std::vector<std::string>::const_iterator j =
    this->TestProperties->Args.begin();
  ++j; // skip test name

  // find the test executable
  if(this->TestHandler->MemCheck)
    {
    cmCTestMemCheckHandler * handler = static_cast<cmCTestMemCheckHandler*>
      (this->TestHandler);
    this->ActualCommand = handler->MemoryTester.c_str();
    this->TestProperties->Args[1] = this->TestHandler->FindTheExecutable(
      this->TestProperties->Args[1].c_str());
    }
  else
    {
    this->ActualCommand =
      this->TestHandler->FindTheExecutable(
      this->TestProperties->Args[1].c_str());
    ++j; //skip the executable (it will be actualCommand)
    }
  std::string testCommand
    = cmSystemTools::ConvertToOutputPath(this->ActualCommand.c_str());

  //Prepends memcheck args to our command string
  this->TestHandler->GenerateTestCommand(this->Arguments, this->Index);
  for(std::vector<std::string>::iterator i = this->Arguments.begin();
      i != this->Arguments.end(); ++i)
    {
    testCommand += " \"";
    testCommand += *i;
    testCommand += "\"";
    }

  for(;j != this->TestProperties->Args.end(); ++j)
    {
    testCommand += " \"";
    testCommand += *j;
    testCommand += "\"";
    this->Arguments.push_back(*j);
    }
  this->TestResult.FullCommandLine = testCommand;

  cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT, std::endl
             << this->Index << ": "
             << (this->TestHandler->MemCheck?"MemCheck":"Test")
             << " command: " << testCommand
             << std::endl);
}

//----------------------------------------------------------------------
void cmCTestRunTest::DartProcessing()
{
  if (!this->ProcessOutput.empty() &&
     this->ProcessOutput.find("<DartMeasurement") != this->ProcessOutput.npos)
    {
    if (this->TestHandler->DartStuff.find(this->ProcessOutput.c_str()))
      {
      std::string dartString = this->TestHandler->DartStuff.match(1);
      // keep searching and replacing until none are left
      while (this->TestHandler->DartStuff1.find(this->ProcessOutput.c_str()))
        {
        // replace the exact match for the string
        cmSystemTools::ReplaceString(this->ProcessOutput,
                         this->TestHandler->DartStuff1.match(1).c_str(), "");
        }
      this->TestResult.RegressionImages
        = this->TestHandler->GenerateRegressionImages(dartString);
      }
    }
}

//----------------------------------------------------------------------
double cmCTestRunTest::ResolveTimeout()
{
  double timeout = this->TestProperties->Timeout;

  if(this->CTest->GetStopTime() == "")
    {
    return timeout;
    }
  struct tm* lctime;
  time_t current_time = time(0);
  lctime = gmtime(&current_time);
  int gm_hour = lctime->tm_hour;
  time_t gm_time = mktime(lctime);
  lctime = localtime(&current_time);
  int local_hour = lctime->tm_hour;

  int tzone_offset = local_hour - gm_hour;
  if(gm_time > current_time && gm_hour < local_hour)
    {
    // this means gm_time is on the next day
    tzone_offset -= 24;
    }
  else if(gm_time < current_time && gm_hour > local_hour)
    {
    // this means gm_time is on the previous day
    tzone_offset += 24;
    }

  tzone_offset *= 100;
  char buf[1024];
  // add todays year day and month to the time in str because
  // curl_getdate no longer assumes the day is today
  sprintf(buf, "%d%02d%02d %s %+05i",
          lctime->tm_year + 1900,
          lctime->tm_mon + 1,
          lctime->tm_mday,
          this->CTest->GetStopTime().c_str(),
          tzone_offset);

  time_t stop_time = curl_getdate(buf, &current_time);
  if(stop_time == -1)
    {
    return timeout;
    }

  //the stop time refers to the next day
  if(this->CTest->NextDayStopTime)
    {
    stop_time += 24*60*60;
    }
  int stop_timeout = static_cast<int>(stop_time - current_time) % (24*60*60);
  this->CTest->LastStopTimeout = stop_timeout;

  if(stop_timeout <= 0 || stop_timeout > this->CTest->LastStopTimeout)
    {
    cmCTestLog(this->CTest, ERROR_MESSAGE, "The stop time has been passed. "
      "Stopping all tests." << std::endl);
    this->StopTimePassed = true;
    return 0;
    }
  return timeout == 0 ? stop_timeout :
    (timeout < stop_timeout ? timeout : stop_timeout);
}

//----------------------------------------------------------------------
bool cmCTestRunTest::ForkProcess(double testTimeOut, bool explicitTimeout,
                     std::vector<std::string>* environment)
{
  this->TestProcess = new cmProcess;
  this->TestProcess->SetId(this->Index);
  this->TestProcess->SetWorkingDirectory(
        this->TestProperties->Directory.c_str());
  this->TestProcess->SetCommand(this->ActualCommand.c_str());
  this->TestProcess->SetCommandArguments(this->Arguments);

  // determine how much time we have
  double timeout = this->CTest->GetRemainingTimeAllowed() - 120;
  if (this->CTest->GetTimeOut() > 0 && this->CTest->GetTimeOut() < timeout)
    {
    timeout = this->CTest->GetTimeOut();
    }
  if (testTimeOut > 0
      && testTimeOut < this->CTest->GetRemainingTimeAllowed())
    {
    timeout = testTimeOut;
    }
  // always have at least 1 second if we got to here
  if (timeout <= 0)
    {
    timeout = 1;
    }
  // handle timeout explicitly set to 0
  if (testTimeOut == 0 && explicitTimeout)
    {
    timeout = 0;
    }
  cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT, this->Index << ": "
             << "Test timeout computed to be: " << timeout << "\n");

  this->TestProcess->SetTimeout(timeout);

#ifdef CMAKE_BUILD_WITH_CMAKE
  cmSystemTools::SaveRestoreEnvironment sre;
#endif

  if (environment && environment->size()>0)
    {
    cmSystemTools::AppendEnv(*environment);
    }

  return this->TestProcess->StartProcess();
}

void cmCTestRunTest::WriteLogOutputTop(size_t completed, size_t total)
{
  cmCTestLog(this->CTest, HANDLER_OUTPUT, std::setw(getNumWidth(total))
             << completed << "/");
  cmCTestLog(this->CTest, HANDLER_OUTPUT, std::setw(getNumWidth(total))
             << total << " ");

  if ( this->TestHandler->MemCheck )
    {
    cmCTestLog(this->CTest, HANDLER_OUTPUT, "MemCheck");
    }
  else
    {
    cmCTestLog(this->CTest, HANDLER_OUTPUT, "Test");
    }

  cmOStringStream indexStr;
  indexStr << " #" << this->Index << ":";
  cmCTestLog(this->CTest, HANDLER_OUTPUT,
             std::setw(3 + getNumWidth(this->TestHandler->GetMaxIndex()))
             << indexStr.str().c_str());
  cmCTestLog(this->CTest, HANDLER_OUTPUT, " ");
  const int maxTestNameWidth = this->CTest->GetMaxTestNameWidth();
  std::string outname = this->TestProperties->Name + " ";
  outname.resize(maxTestNameWidth + 4, '.');

  *this->TestHandler->LogFile << this->TestProperties->Index << "/"
    << this->TestHandler->TotalNumberOfTests << " Testing: "
    << this->TestProperties->Name << std::endl;
  *this->TestHandler->LogFile << this->TestProperties->Index << "/"
    << this->TestHandler->TotalNumberOfTests
    << " Test: " << this->TestProperties->Name.c_str() << std::endl;
  *this->TestHandler->LogFile << "Command: \"" << this->ActualCommand << "\"";

  for (std::vector<std::string>::iterator i = this->Arguments.begin();
       i != this->Arguments.end(); ++i)
    {
    *this->TestHandler->LogFile
      << " \"" << i->c_str() << "\"";
    }
  *this->TestHandler->LogFile << std::endl
    << "Directory: " << this->TestProperties->Directory << std::endl
    << "\"" << this->TestProperties->Name.c_str() << "\" start time: "
    << this->StartTime << std::endl;

  *this->TestHandler->LogFile
    << "Output:" << std::endl
    << "----------------------------------------------------------"
    << std::endl;
  *this->TestHandler->LogFile
    << this->ProcessOutput.c_str() << "<end of output>" << std::endl;

  cmCTestLog(this->CTest, HANDLER_OUTPUT, outname.c_str());
  cmCTestLog(this->CTest, DEBUG, "Testing "
             << this->TestProperties->Name.c_str() << " ... ");
}