The configurations are compiled in multiple build steps. At the first build step there is no concept of configurations. It is just one initial compile that needs to work properly for it to be possible to build the subsequent build steps, which consist of one compile per configuration.

Each test result is available in separate log files, which also contain the names of the configurations that the tests belong to.

When Do I Need to Use Build Steps?

You need build steps when you have multiple build configurations where each configuration has multiple build logs which cannot easily be associated with the relevant configuration.

images/whenbuildsteps.png

Example

Each build step has its own compilation log. In build step 1 there is just one compile and no concept of configurations. In build step 2 and 3 there are one compilation per configuration.

Test results are available in separate log files, which also contain the names of the configurations that the tests belong to.

compilation/compile_buildstep1.log
Build First Step
Compiling
...
Done!
CPU time 124.8 seconds
compilation/compile_buildstep2.log
Build config_A
Compiling project
...
Done!
CPU time 12.3 seconds
Build config_B
Compiling project
Done!
...
CPU time 14.7 seconds
Build config_C
Compiling project
Syntax Error: iff <- unknown command
...
CPU time 12.1 seconds
compilation/compile_buildstep3.log
Build config_A
Compiling project
...
Done!
CPU time 8.2 seconds
Build config_B
Compiling project
Syntax Error: elsse <- unknown command
...
CPU time 16.2 seconds
Build config_C
Compiling project
...
CPU time 17.5 seconds
testlogs/results_a.log
Command: run -test test1
Build: config_A
seed 22442244
Test Result: PASSED
CPU time 122.7 seconds
testlogs/results_b.log
Command: run -test test2
Build: config_A
seed 12341234
Compare mismatch 34( got) !=33 (expected)
Test Result: FAILED
CPU time 234.3 seconds
testlogs/results_c.log
Command: run -test test3
Build: config_A
seed 45674567
Test Result: PASSED
CPU time 217.1 seconds
testlogs/results_d.log
Command: run -test test4
Build: config_B
seed 31576784
Test not run
Test Result: FAILED
CPU time 10.9 seconds
testlogs/results_e.log
Command: run -test test5
Build: config_B
seed 89516342
Test not run
Test Result: FAILED
CPU time 9.9 seconds

PinDown Extraction

Which Merge Should I Use?

There are two merge functions, one merges one result with many results. The other one merges many results to many results.

images/whichmerge.png

Step 1. Extract Build Step 1 Results

Build step 1 is a first compile at which point there is not yet any concept of configurations (see pindown_config.txt below). In order to simplify debug we want to associate a default configuration name to the build such that if the build fails this early PinDown can still debug the problem by simply requesting the default configuration name to be re-built on older revisions. During debug the default configuration name must be the name of the build that PinDown actually requested (DEBUG_CONFIGURATION) otherwise PinDown will report that the flow is broken. E.g. if PinDown during debug re-runs a test failure on an older revision where build step 1 breaks because of an old compilation issue (which has since been fixed, otherwise we would not be debugging a test failure) then by returning the requested configuration PinDown will accept and understand the results and continue to debug.

However, during the initial test phase when the customer’s regression test script is running, PinDown has not requested anything and consequently the variable DEBUG_CONFIGURATION is set to "all" to indicate that no specific configuration has been requested. In this case we must set the default configuration to any of the known existing configurations, in this example it is hardcoded to "config_A". All this in order to ensure that there is always a useful configuration name that PinDown can use to debug any compilation issues that occur this early.

pindown_config.txt
group -name "test" -commands {

  // Step 1. Build Step 1 - Only one compilation that affects all configs in later build steps
  extract -type "configlabel" -label "buildstep1" -source "value" -path "%DEBUG_CONFIGURATION%" -keywords "";
  extract -type "replace" -label "buildstep1" -text "^all$" -with "config_A";
  extract -type "buildfail" -path "compilation/compile_buildstep1.log" -keywords "Error|error|failed";
  extract -type "buildend" -path "compilation/compile_buildstep1.log" -keywords "CPU time";

  // Step 2. Build Step 2 - Now there are several configs.
  extract -type "configlabel" -path "compilation/compile_buildstep2.log" -keywords "Build";
  extract -type "buildfail" -path "compilation/compile_buildstep2.log" -keywords "Error|error|failed";
  extract -type "buildend" -path "compilation/compile_buildstep2.log" -keywords "CPU time";
  extract -type "replace" -label "configlabel" -text ".*Build " -with "";
  extract -type "merge" -label "buildstep1,configlabel" -containing "";

  // Step 3. Build Step 3 - Another compile for each config
  extract -type "configlabel" -path "compilation/compile_buildstep3.log" -keywords "Build";
  extract -type "buildpass" -path "compilation/compile_buildstep3.log" -keywords "CPU time";
  extract -type "buildfail" -path "compilation/compile_buildstep3.log" -keywords "Error|error|failed";
  extract -type "buildend" -path "compilation/compile_buildstep3.log" -keywords "CPU time";
  extract -type "replace" -label "configlabel" -text ".*Build " -with "";
  extract -type "merge" -label "configlabel" -containing "";

  // Step 4. Test Results
  extract -type "configlabel" -path "testlogs/results.*log" -keywords "Build";
  extract -type "replace" -label "configlabel" -text ":.*" -with "";
  extract -type "testname" -path "%configlabel%" -keywords "run \-test";
  extract -type "testseed" -path "%configlabel%" -keywords "seed";
  extract -type "testpass" -path "%configlabel%" -keywords "PASSED";
  extract -type "testfail" -path "%configlabel%" -keywords "FAILED";
  extract -type "testend" -path "%configlabel%" -keywords "CPU time";
  extract -type "restore" -label "configlabel" -containing "testlogs"; // only restore configlabel associated with tests
  extract -type "replace" -label "configlabel" -text ".*Build: " -with "";
  extract -type "merge" -label "configlabel" -containing "";

  // Step 5. Clean the test results
  extract -type "replace" -label "testname" -text ".*run -test " -with "";
  extract -type "replace" -label "testseed" -text ".*seed " -with "";
  extract -type "replace" -label "testend" -text ".*CPU time " -with "";
  extract -type "replace" -label "testend" -text "\..*" -with "";
  extract -type "replace" -label "buildend" -text ".*CPU time " -with "";
  extract -type "replace" -label "buildend" -text "\..*" -with "";
};
extract -group "test" -file "test_results.xml";

Step 2. Extract Build Step 2 Results

In build step 2 we extract one compilation result per configuration from one log file. Then we merge the results from Build Step 1 and 2 by specifying the two different labels used to extract the configuration names. There is only one configuration associated with the label "buildstep1" whereas there are 3 configurations associated with the label "configlabel" from Build Step 2. The result of this merge is to merge any build failures in the single configuration in Build Step 1 into all 3 configurations in label "configlabel" from Build Step 2. The names of the configurations will still be that of Build Step 2 because "configlabel" is specified last in the list of labels to be merge.

If Build Step 1 was failing then all configurations of Build Step 2 would be marked as failing after this operation. However if there are no results at all in Build Step 2, because Build Step 1 failed in a fatal way, then the configuration name and results of Build Step 1 would be preserved as there is nothing to merge with.

Step 3. Extract Build Step 3 Results

In build step 3 we again extract one compilation result per configuration from one log file and then merge it with the results from Build Step 2. This type of merge is different than the merge that occurred in Build Step 2. Here we are just specifying one label to merge ("configlabel"), which means the merger will take place within a label (Build Step 2 and 3 are using the same name for their configurations) provided the configuration names are the same. E.g in this case the build results for configuration "config_A", from both Build Step 2 and 3, will be merged together such that any failure from either step will be picked up.

Step 4. Extract Test Results

The next step is to extract the Test Results. First we extract the configuration names to label "configlabel" from inside each test log. The results contain filepath:content, i.e. both the file name and the content that match the keyword in this search. In order to associate the test name and the test results together with the correct configuration names we use the file names, as we know that the content of each file belong together. We do this by cleaning away the content so we only have the file path left to the test log. The label "configlabel" is now set to the list of all test logs. Then we extract the test names and test results by referring to this label. By doing so PinDown understands how to group the extracted data.

The next part of extracting the test results is to set the label "configlabel" to its correct name. So far we used it to group the results in each test log together, but now that this has been done we need to set "configlabel" to the actual names of the configurations. We do that first by restoring the "configlabel" back the original content containing filepath:content. Note that we only do this restore if the "configlabel" contains the keyword "testlogs", which is only the case with configuration names extracted from the test logs. We do this to leave the configuration names untouched from the build steps.

OK, so we have restored the configuration names that we extracted from the test logs. This time we remove the file path instead, and also the "Build: "-part of the content in order to rename the configuration to the actual configuration names (i.e. "config_A", "config_B"). Now we have good configuration names associated with the complete test results. The final step is to merge these test results with the compilation results from the build steps.

Step 5. Clean Results

The final thing to do is to clean the results to get clean test names and test and build end times that consist of whole seconds, as decimals are not allowed.

The last line is the one that actually runs the extraction as defined by the group "test" and writes the result to the file test_results.xml.

Test Results 1/2

The result of running pindown_config.txt is written to the test_results.xml file.

Note that for failures multiple lines are extracted from the log files in order to see the lines above and below the failure message as they may contain interesting information. The actual error message is shown between PinDownMatchStart and PinDownMatchEnd.

test_results.xml
<?xml version="1.0" encoding="UTF-8"?><com.verifyter.pindown.TestResultList formatOwner="Verifyter" formatVersion="1.1" tool="PinDown">
    <com.verifyter.pindown.TestResults>
        <com.verifyter.pindown.ExtractionCommands>
            <com.verifyter.pindown.ExtractionCommand command="extract_config_label" label="buildstep1"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="buildstep1"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_fail" label="buildfail"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_end" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_config_label" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_fail" label="buildfail"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_end" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_merge" label="buildstep1,configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_config_label" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_pass" label="buildpass"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_fail" label="buildfail"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_end" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_merge" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_config_label" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_name" label="testname"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_seed" label="testseed"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_pass" label="testpass"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_fail" label="testfail"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_end" label="testend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_restore" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_merge" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="testname"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="testseed"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="testend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="testend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_results" label=""/>
            <com.verifyter.pindown.ExtractionCommand command="extract_repository" label="repository"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_revision" label="revision"/>
        </com.verifyter.pindown.ExtractionCommands>
        <com.verifyter.pindown.BuildResult buildEnd="%buildend%12" buildResult="%buildfail%fail" buildResultLine="&lt;PinDownContextStart&gt;compilation/compile_buildstep2.log:Done!&lt;PinDownNL&gt;compilation/compile_buildstep2.log:...&lt;PinDownNL&gt;compilation/compile_buildstep2.log:CPU time 14.7 seconds&lt;PinDownNL&gt;compilation/compile_buildstep2.log:Build config_C&lt;PinDownNL&gt;compilation/compile_buildstep2.log:Compiling project&lt;PinDownNL&gt;&lt;PinDownMatchStart&gt;compilation/compile_buildstep2.log:Syntax Error: iff &lt;- unknown command&lt;PinDownMatchEnd&gt;&lt;PinDownNL&gt;compilation/compile_buildstep2.log:...&lt;PinDownNL&gt;compilation/compile_buildstep2.log:CPU time 12.1 seconds&lt;PinDownNL&gt;">
            <com.verifyter.pindown.TestedConfiguration configurationLabel="%configlabel%config_C"/>
            <com.verifyter.pindown.LogFile path="compilation/compile_buildstep2.log"/>
        </com.verifyter.pindown.BuildResult>
        <com.verifyter.pindown.BuildResult buildEnd="%buildend%16" buildResult="%buildfail%fail" buildResultLine="&lt;PinDownContextStart&gt;compilation/compile_buildstep3.log:...&lt;PinDownNL&gt;compilation/compile_buildstep3.log:Done!&lt;PinDownNL&gt;compilation/compile_buildstep3.log:CPU time 8.2 seconds&lt;PinDownNL&gt;compilation/compile_buildstep3.log:Build config_B&lt;PinDownNL&gt;compilation/compile_buildstep3.log:Compiling project&lt;PinDownNL&gt;&lt;PinDownMatchStart&gt;compilation/compile_buildstep3.log:Syntax Error: elsse &lt;- unknown command&lt;PinDownMatchEnd&gt;&lt;PinDownNL&gt;compilation/compile_buildstep3.log:...&lt;PinDownNL&gt;compilation/compile_buildstep3.log:CPU time 16.2 seconds&lt;PinDownNL&gt;compilation/compile_buildstep3.log:Build config_C&lt;PinDownNL&gt;compilation/compile_buildstep3.log:Compiling project&lt;PinDownNL&gt;compilation/compile_buildstep3.log:...&lt;PinDownNL&gt;">
            <com.verifyter.pindown.TestedConfiguration configurationLabel="%configlabel%config_B"/>
            <com.verifyter.pindown.Test testEnd="%testend%10" testName="%testname%test4" testResult="%testfail%fail" testResultLine="&lt;PinDownContextStart&gt;testlogs/results_d.log:Command: run -test test4&lt;PinDownNL&gt;testlogs/results_d.log:Build: config_B&lt;PinDownNL&gt;testlogs/results_d.log:seed 31576784&lt;PinDownNL&gt;testlogs/results_d.log:Test not run&lt;PinDownNL&gt;&lt;PinDownMatchStart&gt;testlogs/results_d.log:Test Result: FAILED&lt;PinDownMatchEnd&gt;&lt;PinDownNL&gt;testlogs/results_d.log:CPU time 10.9 seconds&lt;PinDownNL&gt;" testSeed="%testseed%31576784"/>
            <com.verifyter.pindown.Test testEnd="%testend%9" testName="%testname%test5" testResult="%testfail%fail" testResultLine="&lt;PinDownContextStart&gt;testlogs/results_e.log:Command: run -test test5&lt;PinDownNL&gt;testlogs/results_e.log:Build: config_B&lt;PinDownNL&gt;testlogs/results_e.log:seed 89516342&lt;PinDownNL&gt;testlogs/results_e.log:Test not run&lt;PinDownNL&gt;&lt;PinDownMatchStart&gt;testlogs/results_e.log:Test Result: FAILED&lt;PinDownMatchEnd&gt;&lt;PinDownNL&gt;testlogs/results_e.log:CPU time 9.9 seconds&lt;PinDownNL&gt;" testSeed="%testseed%89516342"/>
            <com.verifyter.pindown.LogFile path="compilation/compile_buildstep3.log"/>
            <com.verifyter.pindown.LogFile path="testlogs/results_d.log"/>
            <com.verifyter.pindown.LogFile path="testlogs/results_e.log"/>
        </com.verifyter.pindown.BuildResult>
        <com.verifyter.pindown.BuildResult buildEnd="%buildend%8" buildResult="%buildpass%pass" buildResultLine="compilation/compile_buildstep3.log:CPU time 8.2 seconds">
            <com.verifyter.pindown.TestedConfiguration configurationLabel="%configlabel%config_A"/>
            <com.verifyter.pindown.Test testEnd="%testend%122" testName="%testname%test1" testResult="%testpass%pass" testResultLine="testlogs/results_a.log:Test Result: PASSED" testSeed="%testseed%22442244"/>
            <com.verifyter.pindown.Test testEnd="%testend%234" testName="%testname%test2" testResult="%testfail%fail" testResultLine="&lt;PinDownContextStart&gt;testlogs/results_b.log:Command: run -test test2&lt;PinDownNL&gt;testlogs/results_b.log:Build: config_A&lt;PinDownNL&gt;testlogs/results_b.log:seed 12341234&lt;PinDownNL&gt;testlogs/results_b.log:Compare mismatch 34( got) !=33 (expected)&lt;PinDownNL&gt;&lt;PinDownMatchStart&gt;testlogs/results_b.log:Test Result: FAILED&lt;PinDownMatchEnd&gt;&lt;PinDownNL&gt;testlogs/results_b.log:CPU time 234.3 seconds&lt;PinDownNL&gt;" testSeed="%testseed%12341234"/>
            <com.verifyter.pindown.Test testEnd="%testend%217" testName="%testname%test3" testResult="%testpass%pass" testResultLine="testlogs/results_c.log:Test Result: PASSED" testSeed="%testseed%45674567"/>
            <com.verifyter.pindown.LogFile path="compilation/compile_buildstep3.log"/>
            <com.verifyter.pindown.LogFile path="testlogs/results_a.log"/>
            <com.verifyter.pindown.LogFile path="testlogs/results_b.log"/>
            <com.verifyter.pindown.LogFile path="testlogs/results_c.log"/>
        </com.verifyter.pindown.BuildResult>
    </com.verifyter.pindown.TestResults>
</com.verifyter.pindown.TestResultList>

Test Results 2/2

If we get a fatal build failure in build step 1 then there will be no attempt to do build step 2 or 3 and there will be no test test results. All we got in that scenario is this log file:

compilation/compile_buildstep1.log
Build First Step
Compiling
...
Fatal Error: No target
CPU time 124.8 seconds

Using the same pindown_config.txt file as described above we would get the following test results. Notice that the configuration is set to "config_A" which is hardcoded in pindown_config.txt in Build Step 1 if we are in the initial test phase.

test_results.xml
<?xml version="1.0" encoding="UTF-8"?><com.verifyter.pindown.TestResultList formatOwner="Verifyter" formatVersion="1.1" tool="PinDown">
    <com.verifyter.pindown.TestResults>
        <com.verifyter.pindown.ExtractionCommands>
            <com.verifyter.pindown.ExtractionCommand command="extract_config_label" label="buildstep1"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="buildstep1"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_fail" label="buildfail"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_end" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_config_label" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_fail" label="buildfail"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_end" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_merge" label="buildstep1,configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_config_label" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_pass" label="buildpass"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_fail" label="buildfail"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_build_end" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_merge" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_config_label" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_name" label="testname"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_seed" label="testseed"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_pass" label="testpass"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_fail" label="testfail"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_test_end" label="testend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_restore" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_merge" label="configlabel"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="testname"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="testseed"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="testend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="testend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_replace" label="buildend"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_results" label=""/>
            <com.verifyter.pindown.ExtractionCommand command="extract_repository" label="repository"/>
            <com.verifyter.pindown.ExtractionCommand command="extract_revision" label="revision"/>
        </com.verifyter.pindown.ExtractionCommands>
        <com.verifyter.pindown.BuildResult buildEnd="%buildend%124" buildResult="%buildfail%fail" buildResultLine="&lt;PinDownContextStart&gt;compilation/compile_buildstep1.log:Build First Step&lt;PinDownNL&gt;compilation/compile_buildstep1.log:Compiling&lt;PinDownNL&gt;compilation/compile_buildstep1.log:...&lt;PinDownNL&gt;&lt;PinDownMatchStart&gt;compilation/compile_buildstep1.log:Fatal Error: No target&lt;PinDownMatchEnd&gt;&lt;PinDownNL&gt;compilation/compile_buildstep1.log:CPU time 124.8 seconds&lt;PinDownNL&gt;">
            <com.verifyter.pindown.TestedConfiguration configurationLabel="%buildstep1%config_A"/>
            <com.verifyter.pindown.LogFile path="compilation/compile_buildstep1.log"/>
        </com.verifyter.pindown.BuildResult>
    </com.verifyter.pindown.TestResults>
</com.verifyter.pindown.TestResultList>