Fix bug in terratest-log-parser that mixes result lines

modules/logger/parser/fixtures/basic_example_expected/TestGetOrCreateChannelCreatesNewChannel.log

@@ -4,14 +4,6 @@
 TestGetOrCreateChannelCreatesNewChannel INFO 2018-10-20T13:03:33-07:00 Spawned log writer for test TestGetOrCreateChannelCreatesNewChannel
 TestGetOrCreateChannelCreatesNewChannel INFO 2018-10-20T13:03:33-07:00 Storing logs for test TestGetOrCreateChannelCreatesNewChannel to /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory272503116/TestGetOrCreateChannelCreatesNewChannel.log
 --- PASS: TestGetOrCreateChannelCreatesNewChannel (0.00s)
---- PASS: TestGetOrCreateChannelCreatesNewChannel (0.00s)
---- PASS: TestEnsureDirectoryExistsHandlesExistingDirectory (0.00s)
 TestGetOrCreateChannelCreatesNewChannel INFO 2018-10-20T13:03:33-07:00 Creating directory /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory272503116
---- PASS: TestIsPanicLine (0.00s)
---- PASS: TestStackPop (0.00s)
---- PASS: TestStackPopEmpty (0.00s)
 TestGetOrCreateChannelCreatesNewChannel INFO 2018-10-20T13:03:33-07:00 Channel closed for log writer of test TestGetOrCreateChannelCreatesNewChannel
---- PASS: TestEnsureDirectoryExistsCreatesDirectory (0.00s)
---- PASS: TestGetOrCreateChannelSpawnsLogCollectorOnCreate (1.01s)
---- PASS: TestLogCollectorCreatesAndWritesToFile (1.01s)
 PASS

modules/logger/parser/fixtures/basic_example_expected/TestGetOrCreateChannelSpawnsLogCollectorOnCreate.log

@@ -3,13 +3,6 @@
 === CONT  TestGetOrCreateChannelSpawnsLogCollectorOnCreate
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:03:33-07:00 Spawned log writer for test TestGetOrCreateChannelSpawnsLogCollectorOnCreate
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:03:33-07:00 Storing logs for test TestGetOrCreateChannelSpawnsLogCollectorOnCreate to /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory894837527/TestGetOrCreateChannelSpawnsLogCollectorOnCreate.log
---- PASS: TestCloseChannelsClosesAll (0.00s)
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:03:33-07:00 Directory /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory894837527 already exists
---- PASS: TestIsStatusLine (0.00s)
---- PASS: TestGetIndent (0.00s)
---- PASS: TestIsEmpty (0.00s)
---- PASS: TestPeekEmpty (0.00s)
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:03:33-07:00 Channel closed for log writer of test TestGetOrCreateChannelSpawnsLogCollectorOnCreate
---- PASS: TestGetTestNameFromResultLine (0.00s)
---- PASS: TestIsResultLine (0.00s)
 --- PASS: TestGetOrCreateChannelSpawnsLogCollectorOnCreate (1.01s)

modules/logger/parser/fixtures/basic_example_expected/TestLogCollectorCreatesAndWritesToFile.log

@@ -2,10 +2,7 @@
 === PAUSE TestLogCollectorCreatesAndWritesToFile
 === CONT  TestLogCollectorCreatesAndWritesToFile
 TestLogCollectorCreatesAndWritesToFile INFO 2018-10-20T13:03:33-07:00 Spawned log writer for test TestLogCollectorCreatesAndWritesToFile
---- PASS: TestGetOrCreateChannelReturnsExistingChannel (0.00s)
---- PASS: TestPeek (0.00s)
 TestLogCollectorCreatesAndWritesToFile INFO 2018-10-20T13:03:33-07:00 Storing logs for test TestLogCollectorCreatesAndWritesToFile to /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestLogCollectorCreatesAndWritesToFile509683594/TestLogCollectorCreatesAndWritesToFile.log
 TestLogCollectorCreatesAndWritesToFile INFO 2018-10-20T13:03:33-07:00 Directory /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestLogCollectorCreatesAndWritesToFile509683594 already exists
---- PASS: TestGetTestNameFromStatusLine (0.00s)
 TestLogCollectorCreatesAndWritesToFile INFO 2018-10-20T13:03:33-07:00 Channel closed for log writer of test TestLogCollectorCreatesAndWritesToFile
 --- PASS: TestLogCollectorCreatesAndWritesToFile (1.01s)

modules/logger/parser/fixtures/failing_example.log

@@ -18,19 +18,19 @@
 --- PASS: TestRemoveDedentedTestResultMarkersAll (0.00s)
 === RUN   TestBasicExample
 --- FAIL: TestBasicExample (0.00s)
-    integration_test.go:10: 
+    integration_test.go:10:
         	Error Trace:	integration_test.go:10
         	Error:      	Expected value not to be nil.
         	Test:       	TestBasicExample
 === RUN   TestPanicExample
 --- FAIL: TestPanicExample (0.00s)
-    integration_test.go:14: 
+    integration_test.go:14:
         	Error Trace:	integration_test.go:14
         	Error:      	Expected value not to be nil.
         	Test:       	TestPanicExample
 === RUN   TestRealWorldExample
 --- FAIL: TestRealWorldExample (0.00s)
-    integration_test.go:18: 
+    integration_test.go:18:
         	Error Trace:	integration_test.go:18
         	Error:      	Expected value not to be nil.
         	Test:       	TestRealWorldExample

modules/logger/parser/fixtures/failing_example_expected/TestBasicExample.log

@@ -1,6 +1,6 @@
 === RUN   TestBasicExample
 --- FAIL: TestBasicExample (0.00s)
-    integration_test.go:10: 
+    integration_test.go:10:
         	Error Trace:	integration_test.go:10
         	Error:      	Expected value not to be nil.
         	Test:       	TestBasicExample

modules/logger/parser/fixtures/failing_example_expected/TestCloseChannelsClosesAll.log

@@ -2,5 +2,4 @@
 === PAUSE TestCloseChannelsClosesAll
 === CONT  TestCloseChannelsClosesAll
 TestCloseChannelsClosesAll INFO 2018-10-20T13:15:09-07:00 Closing all the channels in log writer
---- PASS: TestStackPop (0.00s)
 --- PASS: TestCloseChannelsClosesAll (0.00s)

modules/logger/parser/fixtures/failing_example_expected/TestGetOrCreateChannelCreatesNewChannel.log

@@ -4,12 +4,6 @@
 --- PASS: TestGetOrCreateChannelCreatesNewChannel (0.00s)
 TestGetOrCreateChannelCreatesNewChannel INFO 2018-10-20T13:15:09-07:00 Spawned log writer for test TestGetOrCreateChannelCreatesNewChannel
 TestGetOrCreateChannelCreatesNewChannel INFO 2018-10-20T13:15:09-07:00 Storing logs for test TestGetOrCreateChannelCreatesNewChannel to /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory867148002/TestGetOrCreateChannelCreatesNewChannel.log
---- PASS: TestEnsureDirectoryExistsHandlesExistingDirectory (0.00s)
 TestGetOrCreateChannelCreatesNewChannel INFO 2018-10-20T13:15:09-07:00 Creating directory /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory867148002
---- PASS: TestIsPanicLine (0.00s)
 TestGetOrCreateChannelCreatesNewChannel INFO 2018-10-20T13:15:09-07:00 Channel closed for log writer of test TestGetOrCreateChannelCreatesNewChannel
---- PASS: TestEnsureDirectoryExistsCreatesDirectory (0.00s)
---- PASS: TestLogCollectorCreatesAndWritesToFile (1.01s)
---- PASS: TestGetOrCreateChannelSpawnsLogCollectorOnCreate (1.01s)
-FAIL
 exit status 1

modules/logger/parser/fixtures/failing_example_expected/TestGetOrCreateChannelSpawnsLogCollectorOnCreate.log

@@ -5,6 +5,4 @@ TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:15:09-07:00
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:15:09-07:00 Storing logs for test TestGetOrCreateChannelSpawnsLogCollectorOnCreate to /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory945346773/TestGetOrCreateChannelSpawnsLogCollectorOnCreate.log
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:15:09-07:00 Directory /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory945346773 already exists
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:15:09-07:00 Channel closed for log writer of test TestGetOrCreateChannelSpawnsLogCollectorOnCreate
---- PASS: TestGetOrCreateChannelCreatesNewChannel (0.00s)
---- PASS: TestIsResultLine (0.00s)
 --- PASS: TestGetOrCreateChannelSpawnsLogCollectorOnCreate (1.01s)

modules/logger/parser/fixtures/failing_example_expected/TestLogCollectorCreatesAndWritesToFile.log

@@ -3,8 +3,6 @@
 === CONT  TestLogCollectorCreatesAndWritesToFile
 TestLogCollectorCreatesAndWritesToFile INFO 2018-10-20T13:15:09-07:00 Spawned log writer for test TestLogCollectorCreatesAndWritesToFile
 TestLogCollectorCreatesAndWritesToFile INFO 2018-10-20T13:15:09-07:00 Storing logs for test TestLogCollectorCreatesAndWritesToFile to /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestLogCollectorCreatesAndWritesToFile262063152/TestLogCollectorCreatesAndWritesToFile.log
---- PASS: TestCloseChannelsClosesAll (0.00s)
 TestLogCollectorCreatesAndWritesToFile INFO 2018-10-20T13:15:09-07:00 Directory /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestLogCollectorCreatesAndWritesToFile262063152 already exists
---- PASS: TestIsSummaryLine (0.00s)
 TestLogCollectorCreatesAndWritesToFile INFO 2018-10-20T13:15:09-07:00 Channel closed for log writer of test TestLogCollectorCreatesAndWritesToFile
 --- PASS: TestLogCollectorCreatesAndWritesToFile (1.01s)

modules/logger/parser/fixtures/failing_example_expected/TestPanicExample.log

@@ -1,6 +1,6 @@
 === RUN   TestPanicExample
 --- FAIL: TestPanicExample (0.00s)
-    integration_test.go:14: 
+    integration_test.go:14:
         	Error Trace:	integration_test.go:14
         	Error:      	Expected value not to be nil.
         	Test:       	TestPanicExample

modules/logger/parser/fixtures/failing_example_expected/TestRealWorldExample.log

@@ -1,6 +1,6 @@
 === RUN   TestRealWorldExample
 --- FAIL: TestRealWorldExample (0.00s)
-    integration_test.go:18: 
+    integration_test.go:18:
         	Error Trace:	integration_test.go:18
         	Error:      	Expected value not to be nil.
         	Test:       	TestRealWorldExample

modules/logger/parser/fixtures/failing_example_expected/report.xml

@@ -14,13 +14,13 @@
 		<testcase classname="parser" name="TestRemoveDedentedTestResultMarkersEmpty" time="0.000"></testcase>
 		<testcase classname="parser" name="TestRemoveDedentedTestResultMarkersAll" time="0.000"></testcase>
 		<testcase classname="parser" name="TestBasicExample" time="0.000">
-			<failure message="Failed" type="">integration_test.go:10: &#xA;Error Trace:&#x9;integration_test.go:10&#xA;Error:      &#x9;Expected value not to be nil.&#xA;Test:       &#x9;TestBasicExample</failure>
+			<failure message="Failed" type="">integration_test.go:10:&#xA;Error Trace:&#x9;integration_test.go:10&#xA;Error:      &#x9;Expected value not to be nil.&#xA;Test:       &#x9;TestBasicExample</failure>
 		</testcase>
 		<testcase classname="parser" name="TestPanicExample" time="0.000">
-			<failure message="Failed" type="">integration_test.go:14: &#xA;Error Trace:&#x9;integration_test.go:14&#xA;Error:      &#x9;Expected value not to be nil.&#xA;Test:       &#x9;TestPanicExample</failure>
+			<failure message="Failed" type="">integration_test.go:14:&#xA;Error Trace:&#x9;integration_test.go:14&#xA;Error:      &#x9;Expected value not to be nil.&#xA;Test:       &#x9;TestPanicExample</failure>
 		</testcase>
 		<testcase classname="parser" name="TestRealWorldExample" time="0.000">
-			<failure message="Failed" type="">integration_test.go:18: &#xA;Error Trace:&#x9;integration_test.go:18&#xA;Error:      &#x9;Expected value not to be nil.&#xA;Test:       &#x9;TestRealWorldExample</failure>
+			<failure message="Failed" type="">integration_test.go:18:&#xA;Error Trace:&#x9;integration_test.go:18&#xA;Error:      &#x9;Expected value not to be nil.&#xA;Test:       &#x9;TestRealWorldExample</failure>
 		</testcase>
 		<testcase classname="parser" name="TestGetIndent" time="0.000"></testcase>
 		<testcase classname="parser" name="TestGetTestNameFromResultLine" time="0.000"></testcase>

modules/logger/parser/fixtures/failing_example_expected/summary.log

@@ -53,4 +53,5 @@
 --- PASS: TestEnsureDirectoryExistsCreatesDirectory (0.00s)
 --- PASS: TestLogCollectorCreatesAndWritesToFile (1.01s)
 --- PASS: TestGetOrCreateChannelSpawnsLogCollectorOnCreate (1.01s)
+FAIL
 FAIL	github.com/gruntwork-io/terratest/modules/logger/parser	1.020s

modules/logger/parser/fixtures/new_go_failing_example.log

@@ -0,0 +1,20 @@
+=== RUN   TestIntegrationBasicExample
+=== PAUSE TestIntegrationBasicExample
+=== RUN   TestIntegrationFailingExample
+=== PAUSE TestIntegrationFailingExample
+=== RUN   TestIntegrationPanicExample
+=== PAUSE TestIntegrationPanicExample
+=== CONT  TestIntegrationBasicExample
+=== CONT  TestIntegrationPanicExample
+=== CONT  TestIntegrationFailingExample
+=== CONT  TestIntegrationBasicExample
+    integration_test.go:57: 
+        	Error Trace:	integration_test.go:57
+        	Error:      	Should be true
+        	Test:       	TestIntegrationBasicExample
+--- PASS: TestIntegrationPanicExample (0.00s)
+--- PASS: TestIntegrationFailingExample (0.00s)
+--- FAIL: TestIntegrationBasicExample (0.00s)
+FAIL
+FAIL	github.com/gruntwork-io/terratest/modules/logger/parser	1.589s
+FAIL

modules/logger/parser/fixtures/new_go_failing_example_expected/TestIntegrationBasicExample.log

@@ -0,0 +1,9 @@
+=== RUN   TestIntegrationBasicExample
+=== PAUSE TestIntegrationBasicExample
+=== CONT  TestIntegrationBasicExample
+=== CONT  TestIntegrationBasicExample
+    integration_test.go:57: 
+        	Error Trace:	integration_test.go:57
+        	Error:      	Should be true
+        	Test:       	TestIntegrationBasicExample
+--- FAIL: TestIntegrationBasicExample (0.00s)

modules/logger/parser/fixtures/new_go_failing_example_expected/TestIntegrationFailingExample.log

@@ -0,0 +1,4 @@
+=== RUN   TestIntegrationFailingExample
+=== PAUSE TestIntegrationFailingExample
+=== CONT  TestIntegrationFailingExample
+--- PASS: TestIntegrationFailingExample (0.00s)

modules/logger/parser/fixtures/new_go_failing_example_expected/TestIntegrationPanicExample.log

@@ -0,0 +1,4 @@
+=== RUN   TestIntegrationPanicExample
+=== PAUSE TestIntegrationPanicExample
+=== CONT  TestIntegrationPanicExample
+--- PASS: TestIntegrationPanicExample (0.00s)

modules/logger/parser/fixtures/new_go_failing_example_expected/report.xml

@@ -0,0 +1,13 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<testsuites>
+	<testsuite tests="3" failures="1" time="1.589" name="github.com/gruntwork-io/terratest/modules/logger/parser">
+		<properties>
+			<property name="go.version" value="go1.16.3"></property>
+		</properties>
+		<testcase classname="parser" name="TestIntegrationBasicExample" time="0.000">
+			<failure message="Failed" type="">    integration_test.go:57: </failure>
+		</testcase>
+		<testcase classname="parser" name="TestIntegrationFailingExample" time="0.000"></testcase>
+		<testcase classname="parser" name="TestIntegrationPanicExample" time="0.000"></testcase>
+	</testsuite>
+</testsuites>

modules/logger/parser/fixtures/new_go_failing_example_expected/summary.log

@@ -0,0 +1,6 @@
+--- PASS: TestIntegrationPanicExample (0.00s)
+--- PASS: TestIntegrationFailingExample (0.00s)
+--- FAIL: TestIntegrationBasicExample (0.00s)
+FAIL
+FAIL	github.com/gruntwork-io/terratest/modules/logger/parser	1.589s
+FAIL

modules/logger/parser/fixtures/panic_example_expected/TestEnsureDirectoryExistsCreatesDirectory.log

@@ -2,5 +2,3 @@
 === PAUSE TestEnsureDirectoryExistsCreatesDirectory
 === CONT  TestEnsureDirectoryExistsCreatesDirectory
 TestEnsureDirectoryExistsCreatesDirectory INFO 2018-10-20T13:03:19-07:00 Creating directory /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory601920052/tmpdir
---- PASS: TestGetOrCreateChannelCreatesNewChannel (0.00s)
---- FAIL: TestIsPanicLine (0.00s)

modules/logger/parser/fixtures/panic_example_expected/TestGetOrCreateChannelSpawnsLogCollectorOnCreate.log

@@ -4,6 +4,4 @@
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:03:19-07:00 Spawned log writer for test TestGetOrCreateChannelSpawnsLogCollectorOnCreate
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:03:19-07:00 Storing logs for test TestGetOrCreateChannelSpawnsLogCollectorOnCreate to /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory724282597/TestGetOrCreateChannelSpawnsLogCollectorOnCreate.log
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:03:19-07:00 Directory /var/folders/n2/pljz6dq52bd1ksmw23qyr3sr0000gn/T/TestEnsureDirectoryCreatesDirectory724282597 already exists
---- PASS: TestCloseChannelsClosesAll (0.00s)
---- PASS: TestEnsureDirectoryExistsHandlesExistingDirectory (0.00s)
 TestGetOrCreateChannelSpawnsLogCollectorOnCreate INFO 2018-10-20T13:03:19-07:00 Channel closed for log writer of test TestGetOrCreateChannelSpawnsLogCollectorOnCreate

modules/logger/parser/integration_test.go

@@ -52,17 +52,22 @@ func testExample(t *testing.T, example string) {
 	assert.True(t, DirectoryEqual(t, dir, expectedOutputDirName))
 }
 
-func TestBasicExample(t *testing.T) {
+func TestIntegrationBasicExample(t *testing.T) {
 	t.Parallel()
 	testExample(t, "basic")
 }
 
-func TestFailingExample(t *testing.T) {
+func TestIntegrationFailingExample(t *testing.T) {
 	t.Parallel()
 	testExample(t, "failing")
 }
 
-func TestPanicExample(t *testing.T) {
+func TestIntegrationPanicExample(t *testing.T) {
 	t.Parallel()
 	testExample(t, "panic")
 }
+
+func TestIntegrationNewGoExample(t *testing.T) {
+	t.Parallel()
+	testExample(t, "new_go_failing")
+}

modules/logger/parser/parser.go

@@ -41,7 +41,7 @@ func SpawnParsers(logger *logrus.Logger, reader io.Reader, outputDir string) {
 var (
 	regexResult  = regexp.MustCompile(`--- (PASS|FAIL|SKIP): (.+) \((\d+\.\d+)(?: ?seconds|s)\)`)
 	regexStatus  = regexp.MustCompile(`=== (RUN|PAUSE|CONT)\s+(.+)`)
-	regexSummary = regexp.MustCompile(`^(ok|FAIL)\s+([^ ]+)\s+(?:(\d+\.\d+)s|\(cached\)|(\[\w+ failed]))(?:\s+coverage:\s+(\d+\.\d+)%\sof\sstatements(?:\sin\s.+)?)?$`)
+	regexSummary = regexp.MustCompile(`(^FAIL$)|(^(ok|FAIL)\s+([^ ]+)\s+(?:(\d+\.\d+)s|\(cached\)|(\[\w+ failed]))(?:\s+coverage:\s+(\d+\.\d+)%\sof\sstatements(?:\sin\s.+)?)?$)`)
 	regexPanic   = regexp.MustCompile(`^panic:`)
 )
 
@@ -140,6 +140,7 @@ func parseAndStoreTestOutput(
 
 			case isStatusLine(data):
 				testName := getTestNameFromStatusLine(data)
+				previousTestName = testName
 				logWriter.writeLog(logger, testName, data)
 
 			case strings.HasPrefix(data, "Test"):
@@ -149,12 +150,11 @@ func parseAndStoreTestOutput(
 				// This must be modified when `logger.DoLog` changes.
 				vals := strings.Split(data, " ")
 				testName := vals[0]
-				logWriter.writeLog(logger, testName, data)
 				previousTestName = testName
+				logWriter.writeLog(logger, testName, data)
 
-			case isIndented && previousTestName != "summary":
-				// In a test result block, so collect the line into all the test results we have seen so far.
-				// Note that previousTestName would only be set to summary if we saw a panic line.
+			case isIndented && isResultLine(data):
+				// In a nested test result block, so collect the line into all the test results we have seen so far.
 				for _, marker := range testResultMarkers {
 					logWriter.writeLog(logger, marker.TestName, data)
 				}
@@ -164,13 +164,15 @@ func parseAndStoreTestOutput(
 				previousTestName = "summary"
 				logWriter.writeLog(logger, "summary", data)
 
+			case isResultLine(data):
+				// We ignore result lines, because that is handled specially below.
+
 			case previousTestName != "":
 				// Base case: roll up to the previous test line, if it exists.
 				// Handles case where terratest log has entries with newlines in them.
 				logWriter.writeLog(logger, previousTestName, data)
 
-			case !isResultLine(data):
-				// Result Lines are handled below
+			default:
 				logger.Warnf("Found test line that does not match known cases: %s", data)
 			}