Merge pull request #56 from fzipi/open-log-file-only-once

check/base.go

@@ -78,7 +78,7 @@ func (c *FTWCheck) ForcedFail(id string) bool {
 
 // CloudMode returns true if we are running in cloud mode
 func (c *FTWCheck) CloudMode() bool {
-	return c.overrides.Mode == config.CloudMode
+	return config.FTWConfig.RunMode == config.CloudRunMode
 }
 
 // SetCloudMode alters the values for expected logs and status code

check/base_test.go

@@ -20,8 +20,7 @@ testoverride:
 `
 
 var yamlCloudConfig = `---
-testoverride:
-  mode: "cloud"
+mode: "cloud"
 `
 
 func TestNewCheck(t *testing.T) {

cmd/root.go

@@ -60,6 +60,6 @@ func initConfig() {
 		}
 	}
 	if cloud {
-		config.FTWConfig.TestOverride.Mode = config.CloudMode
+		config.FTWConfig.RunMode = config.CloudRunMode
 	}
 }

config/config.go

@@ -95,7 +95,7 @@ func loadDefaults() {
 	if FTWConfig.LogMarkerHeaderName == "" {
 		FTWConfig.LogMarkerHeaderName = DefaultLogMarkerHeaderName
 	}
-	if FTWConfig.TestOverride.Mode == "" {
-		FTWConfig.TestOverride.Mode = DefaultMode
+	if FTWConfig.RunMode == "" {
+		FTWConfig.RunMode = DefaultRunMode
 	}
 }

config/config_test.go

@@ -10,7 +10,6 @@ import (
 
 var yamlConfig = `---
 logfile: 'tests/logs/modsec2-apache/apache2/error.log'
-cloudmode: True
 testoverride:
   input:
     dest_addr: 'httpbin.org'
@@ -19,6 +18,10 @@ testoverride:
     '920400-1': 'This test result must be ignored'
 `
 
+var yamlCloudConfig = `---
+mode: 'cloud'
+`
+
 var yamlBadConfig = `
 ---
 logfile: 'tests/logs/modsec2-apache/apache2/error.log'
@@ -130,8 +133,8 @@ func TestNewConfigFromEnvHasDefaults(t *testing.T) {
 		t.Error(err)
 	}
 
-	if FTWConfig.TestOverride.Mode != DefaultMode {
-		t.Errorf("unexpected default value '%s' for testoverride.mode", FTWConfig.TestOverride.Mode)
+	if FTWConfig.RunMode != DefaultRunMode {
+		t.Errorf("unexpected default value '%s' for run mode", FTWConfig.RunMode)
 	}
 	if FTWConfig.LogMarkerHeaderName != DefaultLogMarkerHeaderName {
 		t.Errorf("unexpected default value '%s' for logmarkerheadername", FTWConfig.LogMarkerHeaderName)
@@ -146,8 +149,8 @@ func TestNewConfigFromFileHasDefaults(t *testing.T) {
 		t.Error(err)
 	}
 
-	if FTWConfig.TestOverride.Mode != DefaultMode {
-		t.Errorf("unexpected default value '%s' for testoverride.mode", FTWConfig.TestOverride.Mode)
+	if FTWConfig.RunMode != DefaultRunMode {
+		t.Errorf("unexpected default value '%s' for run mode", FTWConfig.RunMode)
 	}
 	if FTWConfig.LogMarkerHeaderName != DefaultLogMarkerHeaderName {
 		t.Errorf("unexpected default value '%s' for logmarkerheadername", FTWConfig.LogMarkerHeaderName)
@@ -159,10 +162,23 @@ func TestNewConfigFromStringHasDefaults(t *testing.T) {
 		t.Error(err)
 	}
 
-	if FTWConfig.TestOverride.Mode != DefaultMode {
-		t.Errorf("unexpected default value '%s' for testoverride.mode", FTWConfig.TestOverride.Mode)
+	if FTWConfig.RunMode != DefaultRunMode {
+		t.Errorf("unexpected default value '%s' for run mode", FTWConfig.RunMode)
 	}
 	if FTWConfig.LogMarkerHeaderName != DefaultLogMarkerHeaderName {
 		t.Errorf("unexpected default value '%s' for logmarkerheadername", FTWConfig.LogMarkerHeaderName)
 	}
 }
+
+func TestNewConfigFromFileRunMode(t *testing.T) {
+	filename, _ := utils.CreateTempFileWithContent(yamlCloudConfig, "test-*.yaml")
+	defer os.Remove(filename)
+
+	if err := NewConfigFromFile(filename); err != nil {
+		t.Error(err)
+	}
+
+	if FTWConfig.RunMode != CloudRunMode {
+		t.Errorf("unexpected value '%s' for run mode, expected '%s;", FTWConfig.RunMode, CloudRunMode)
+	}
+}

config/types.go

@@ -1,10 +1,14 @@
 package config
 
+// RunMode represents the mode of the test run
+type RunMode string
+
 const (
-	// CloudMode is the string that will be used to override the mode of execution to cloud
-	CloudMode string = "cloud"
-	// DefaultMode is the default execution mode
-	DefaultMode                string = "default"
+	// CloudRunMode is the string that will be used to override the run mode of execution to cloud
+	CloudRunMode RunMode = "cloud"
+	// DefaultRunMode is the default execution run mode
+	DefaultRunMode RunMode = "default"
+	// DefaultLogMarkerHeaderName is the default log marker header name
 	DefaultLogMarkerHeaderName string = "X-CRS-Test"
 )
 
@@ -16,6 +20,7 @@ type FTWConfiguration struct {
 	LogFile             string          `koanf:"logfile"`
 	TestOverride        FTWTestOverride `koanf:"testoverride"`
 	LogMarkerHeaderName string          `koanf:"logmarkerheadername"`
+	RunMode             RunMode         `koanf:"mode"`
 }
 
 // FTWTestOverride holds four lists:
@@ -28,5 +33,4 @@ type FTWTestOverride struct {
 	Ignore    map[string]string `koanf:"ignore"`
 	ForcePass map[string]string `koanf:"forcepass"`
 	ForceFail map[string]string `koanf:"forcefail"`
-	Mode      string            `koanf:"mode"`
 }

runner/run.go

@@ -26,13 +26,17 @@ import (
 func Run(include string, exclude string, showTime bool, output bool, ftwtests []test.FTWTest) TestRunContext {
 	printUnlessQuietMode(output, ":rocket:Running go-ftw!\n")
 
+	logLines := waflog.NewFTWLogLines(waflog.WithLogFile(config.FTWConfig.LogFile))
+
 	client := ftwhttp.NewClient()
 	runContext := TestRunContext{
 		Include:  include,
 		Exclude:  exclude,
 		ShowTime: showTime,
 		Output:   output,
 		Client:   client,
+		LogLines: logLines,
+		RunMode:  config.FTWConfig.RunMode,
 	}
 
 	for _, test := range ftwtests {
@@ -41,6 +45,8 @@ func Run(include string, exclude string, showTime bool, output bool, ftwtests []
 
 	printSummary(output, runContext.Stats)
 
+	defer cleanLogs(logLines)
+
 	return runContext
 }
 
@@ -54,7 +60,9 @@ func RunTest(runContext *TestRunContext, ftwTest test.FTWTest) {
 		// if we received a particular testid, skip until we find it
 		if needToSkipTest(runContext.Include, runContext.Exclude, testCase.TestTitle, ftwTest.Meta.Enabled) {
 			addResultToStats(Skipped, testCase.TestTitle, &runContext.Stats)
-			printUnlessQuietMode(runContext.Output, "Skipping test %s\n", testCase.TestTitle)
+			if !ftwTest.Meta.Enabled {
+				printUnlessQuietMode(runContext.Output, "Skipping test %s\n", testCase.TestTitle)
+			}
 			continue
 		}
 		// this is just for printing once the next test
@@ -79,6 +87,7 @@ func RunTest(runContext *TestRunContext, ftwTest test.FTWTest) {
 // testCase is the test case the stage belongs to
 // stage is the stage you want to run
 func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase test.Test, stage test.Stage) {
+	stageStartTime := time.Now()
 	stageID := uuid.NewString()
 	// Apply global overrides initially
 	testRequest := stage.Input
@@ -108,11 +117,13 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase tes
 		Protocol: testRequest.GetProtocol(),
 	}
 
-	startMarker, err := markAndFlush(runContext.Client, dest, stageID)
-	if err != nil && !expectedOutput.ExpectError {
-		log.Fatal().Caller().Err(err).Msg("Failed to find start marker")
+	if notRunningInCloudMode(ftwCheck) {
+		startMarker, err := markAndFlush(runContext, dest, stageID)
+		if err != nil && !expectedOutput.ExpectError {
+			log.Fatal().Caller().Err(err).Msg("Failed to find start marker")
+		}
+		ftwCheck.SetStartMarker(startMarker)
 	}
-	ftwCheck.SetStartMarker(startMarker)
 
 	req = getRequestFromTest(testRequest)
 
@@ -130,42 +141,40 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase tes
 		log.Fatal().Caller().Err(err).Msgf("can't connect to destination %+v - unexpected error found. Is your waf running?", dest)
 	}
 
-	endMarker, err := markAndFlush(runContext.Client, dest, stageID)
-	if err != nil && !expectedOutput.ExpectError {
-		log.Fatal().Caller().Err(err).Msg("Failed to find end marker")
+	if notRunningInCloudMode(ftwCheck) {
+		endMarker, err := markAndFlush(runContext, dest, stageID)
+		if err != nil && !expectedOutput.ExpectError {
+			log.Fatal().Caller().Err(err).Msg("Failed to find end marker")
 
+		}
+		ftwCheck.SetEndMarker(endMarker)
 	}
-	ftwCheck.SetEndMarker(endMarker)
 
 	// Set expected test output in check
 	ftwCheck.SetExpectTestOutput(&expectedOutput)
 
 	// now get the test result based on output
 	testResult := checkResult(ftwCheck, response, responseErr)
 
-	duration := runContext.Client.GetRoundTripTime().RoundTripDuration()
+	roundTripTime := runContext.Client.GetRoundTripTime().RoundTripDuration()
+	stageTime := time.Since(stageStartTime)
 
 	addResultToStats(testResult, testCase.TestTitle, &runContext.Stats)
 
 	runContext.Result = testResult
 
 	// show the result unless quiet was passed in the command line
-	displayResult(runContext.Output, testResult, duration)
+	displayResult(runContext.Output, testResult, roundTripTime, stageTime)
 
 	runContext.Stats.Run++
-	runContext.Stats.RunTime += duration
+	runContext.Stats.RunTime += stageTime
 }
 
-func markAndFlush(client *ftwhttp.Client, dest *ftwhttp.Destination, stageID string) ([]byte, error) {
-	var req *ftwhttp.Request
-	var logLines = &waflog.FTWLogLines{
-		FileName: config.FTWConfig.LogFile,
-	}
-
+func markAndFlush(runContext *TestRunContext, dest *ftwhttp.Destination, stageID string) ([]byte, error) {
 	rline := &ftwhttp.RequestLine{
 		Method:  "GET",
 		URI:     "/",
-		Version: "HTTP/1.0",
+		Version: "HTTP/1.1",
 	}
 
 	headers := &ftwhttp.Header{
@@ -175,27 +184,27 @@ func markAndFlush(client *ftwhttp.Client, dest *ftwhttp.Destination, stageID str
 		config.FTWConfig.LogMarkerHeaderName: stageID,
 	}
 
-	req = ftwhttp.NewRequest(rline, *headers, nil, true)
+	req := ftwhttp.NewRequest(rline, *headers, nil, true)
 
 	// 20 is a very conservative number. The web server should flush its
 	// buffer a lot earlier but we have absolutely no control over that.
 	for range [20]int{} {
-		err := client.NewConnection(*dest)
+		err := runContext.Client.NewConnection(*dest)
 		if err != nil {
 			return nil, fmt.Errorf("ftw/run: can't connect to destination %+v - unexpected error found. Is your waf running?", dest)
 		}
 
-		_, err = client.Do(*req)
+		_, err = runContext.Client.Do(*req)
 		if err != nil {
 			return nil, fmt.Errorf("ftw/run: failed sending request to %+v - unexpected error found. Is your waf running?", dest)
 		}
 
-		marker := logLines.CheckLogForMarker(stageID)
+		marker := runContext.LogLines.CheckLogForMarker(stageID)
 		if marker != nil {
 			return marker, nil
 		}
 	}
-	return nil, fmt.Errorf("can't find log marker. Am I reading the correct log? Log file: %s", logLines.FileName)
+	return nil, fmt.Errorf("can't find log marker. Am I reading the correct log? Log file: %s", runContext.LogLines.FileName)
 }
 
 func needToSkipTest(include string, exclude string, title string, enabled bool) bool {
@@ -241,14 +250,14 @@ func checkTestSanity(testRequest test.Input) bool {
 		(testRequest.EncodedRequest != "" && testRequest.RAWRequest != "")
 }
 
-func displayResult(quiet bool, result TestResult, duration time.Duration) {
+func displayResult(quiet bool, result TestResult, roundTripTime time.Duration, stageTime time.Duration) {
 	switch result {
 	case Success:
-		printUnlessQuietMode(quiet, ":check_mark:passed in %s\n", duration)
+		printUnlessQuietMode(quiet, ":check_mark:passed in %s (RTT %s)\n", stageTime, roundTripTime)
 	case Failed:
-		printUnlessQuietMode(quiet, ":collision:failed in %s\n", duration)
+		printUnlessQuietMode(quiet, ":collision:failed in %s (RTT %s)\n", stageTime, roundTripTime)
 	case Ignored:
-		printUnlessQuietMode(quiet, ":equal:test result ignored in %s\n", duration)
+		printUnlessQuietMode(quiet, ":equal:test result ignored in %s (RTT %s)\n", stageTime, roundTripTime)
 	default:
 		// don't print anything if skipped test
 	}
@@ -367,3 +376,13 @@ func applyInputOverride(testRequest *test.Input) error {
 	}
 	return retErr
 }
+
+func notRunningInCloudMode(c *check.FTWCheck) bool {
+	return !c.CloudMode()
+}
+
+func cleanLogs(logLines *waflog.FTWLogLines) {
+	if err := logLines.Cleanup(); err != nil {
+		log.Fatal().Err(err).Msg("Failed to cleanup log file")
+	}
+}