Open log file only once

Use File.Seek() to move to end of file for next read

runner/run.go

@@ -3,6 +3,7 @@ package runner
 import (
 	"errors"
 	"fmt"
+	"os"
 	"regexp"
 	"strconv"
 	"time"
@@ -26,13 +27,29 @@ import (
 func Run(include string, exclude string, showTime bool, output bool, ftwtests []test.FTWTest) TestRunContext {
 	printUnlessQuietMode(output, ":rocket:Running go-ftw!\n")
 
+	// TODO: this is a hack, there should only be one instance of FTWLogLines
+	logLines := &waflog.FTWLogLines{
+		FileName: config.FTWConfig.LogFile,
+	}
+	var logFile *os.File
+	if logLines.FileName != "" {
+		var err error
+		logFile, err = os.Open(logLines.FileName)
+		if err != nil {
+			log.Panic().Caller().Err(err).Msg("failed to open file")
+		}
+		defer logFile.Close()
+	}
+
 	client := ftwhttp.NewClient()
 	runContext := TestRunContext{
 		Include:  include,
 		Exclude:  exclude,
 		ShowTime: showTime,
 		Output:   output,
 		Client:   client,
+		LogLines: logLines,
+		LogFile:  logFile,
 	}
 
 	for _, test := range ftwtests {
@@ -81,6 +98,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
@@ -110,7 +128,7 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase tes
 		Protocol: testRequest.GetProtocol(),
 	}
 
-	startMarker, err := markAndFlush(runContext.Client, dest, stageID)
+	startMarker, err := markAndFlush(runContext, dest, stageID)
 	if err != nil && !expectedOutput.ExpectError {
 		log.Fatal().Caller().Err(err).Msg("Failed to find start marker")
 	}
@@ -132,7 +150,7 @@ 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)
+	endMarker, err := markAndFlush(runContext, dest, stageID)
 	if err != nil && !expectedOutput.ExpectError {
 		log.Fatal().Caller().Err(err).Msg("Failed to find end marker")
 
@@ -145,29 +163,25 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase tes
 	// 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{
@@ -177,27 +191,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(runContext.LogFile, 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 {
@@ -243,14 +257,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
 	}

runner/run_test.go

@@ -12,6 +12,7 @@ import (
 	"github.com/fzipi/go-ftw/config"
 	"github.com/fzipi/go-ftw/ftwhttp"
 	"github.com/fzipi/go-ftw/test"
+	"github.com/fzipi/go-ftw/waflog"
 )
 
 var yamlConfig = `
@@ -298,9 +299,7 @@ func setUpLogFileForTestServer(t *testing.T) (logFilePath string) {
 			t.Error(err)
 		}
 		logFilePath = file.Name()
-		t.Cleanup(func() {
-			os.Remove(logFilePath)
-		})
+		t.Cleanup(func() { os.Remove(logFilePath) })
 	}
 	return logFilePath
 }
@@ -560,6 +559,14 @@ func TestCloudRun(t *testing.T) {
 
 				replaceDestinationInConfiguration(*dest)
 				config.FTWConfig.LogFile = logFilePath
+				logLines := &waflog.FTWLogLines{
+					FileName: logFilePath,
+				}
+				logFile, err := os.Open(logFilePath)
+				if err != nil {
+					t.Fatal(err)
+				}
+				t.Cleanup(func() { logFile.Close() })
 
 				replaceDestinationInTest(&ftwTest, *dest)
 				if err != nil {
@@ -571,6 +578,8 @@ func TestCloudRun(t *testing.T) {
 					ShowTime: false,
 					Output:   true,
 					Client:   ftwhttp.NewClient(),
+					LogLines: logLines,
+					LogFile:  logFile,
 				}
 
 				RunStage(&runContext, ftwCheck, *testCase, *stage)
@@ -585,8 +594,8 @@ func TestCloudRun(t *testing.T) {
 }
 
 func TestFailedTestsRun(t *testing.T) {
-	dest, logFilePath := newTestServer(t, logText)
 	err := config.NewConfigFromString(yamlConfig)
+	dest, logFilePath := newTestServer(t, logText)
 	if err != nil {
 		t.Errorf("Failed!")
 	}

runner/types.go

@@ -1,9 +1,11 @@
 package runner
 
 import (
+	"os"
 	"time"
 
 	"github.com/fzipi/go-ftw/ftwhttp"
+	"github.com/fzipi/go-ftw/waflog"
 )
 
 // TestRunContext carries information about the current test run.
@@ -18,4 +20,6 @@ type TestRunContext struct {
 	Result   TestResult
 	Duration time.Duration
 	Client   *ftwhttp.Client
+	LogLines *waflog.FTWLogLines
+	LogFile  *os.File
 }

waflog/read.go

@@ -80,27 +80,25 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte {
 	return found
 }
 
-func (ll *FTWLogLines) CheckLogForMarker(stageId string) []byte {
-	logfile, err := os.Open(ll.FileName)
-
-	if err != nil {
-		log.Error().Caller().Err(err).Msg("failed to open file")
-		return nil
+// CheckLogForMarker reads the log file and searches for a marker line.
+// logFile is the file to search
+// stageID is the ID of the current stage, which is part of the marker line
+func (ll *FTWLogLines) CheckLogForMarker(logFile *os.File, stageID string) []byte {
+	if logFile == nil {
+		log.Fatal().Caller().Msg("No log file supplied")
 	}
-	defer logfile.Close()
-
-	fi, err := logfile.Stat()
+	offset, err := logFile.Seek(0, os.SEEK_END)
 	if err != nil {
-		log.Error().Caller().Err(err).Msgf("cannot read file's size")
+		log.Error().Caller().Err(err).Msgf("failed to seek end of log file")
 		return nil
 	}
 
 	// Lines in modsec logging can be quite large
 	backscannerOptions := &backscanner.Options{
 		ChunkSize: 4096,
 	}
-	scanner := backscanner.NewOptions(logfile, int(fi.Size()), backscannerOptions)
-	stageIdBytes := []byte(stageId)
+	scanner := backscanner.NewOptions(logFile, int(offset), backscannerOptions)
+	stageIDBytes := []byte(stageID)
 	crsHeaderBytes := bytes.ToLower([]byte(config.FTWConfig.LogMarkerHeaderName))
 
 	line := []byte{}
@@ -111,12 +109,11 @@ func (ll *FTWLogLines) CheckLogForMarker(stageId string) []byte {
 	if err != nil {
 		if err == io.EOF {
 			return nil
-		} else {
-			log.Trace().Err(err)
 		}
+		log.Trace().Err(err)
 	}
 	line = bytes.ToLower(line)
-	if bytes.Contains(line, crsHeaderBytes) && bytes.Contains(line, stageIdBytes) {
+	if bytes.Contains(line, crsHeaderBytes) && bytes.Contains(line, stageIDBytes) {
 		return line
 	}
 

waflog/read_test.go

@@ -28,14 +28,19 @@ func TestReadCheckLogForMarkerNoMarkerAtEnd(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
+	logFile, err := os.Open(filename)
+	if err != nil {
+		t.Fatal(err)
+	}
+	t.Cleanup(func() { logFile.Close() })
 	t.Cleanup(func() { os.Remove(filename) })
 
 	ll := &FTWLogLines{
 		FileName:    filename,
 		StartMarker: bytes.ToLower([]byte(markerLine)),
 	}
 
-	marker := ll.CheckLogForMarker(stageID)
+	marker := ll.CheckLogForMarker(logFile, stageID)
 	if marker != nil {
 		t.Fatal("unexpectedly found marker")
 	}
@@ -57,13 +62,18 @@ func TestReadCheckLogForMarkerWithMarkerAtEnd(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
+	logFile, err := os.Open(filename)
+	if err != nil {
+		t.Fatal(err)
+	}
+	t.Cleanup(func() { logFile.Close() })
 	t.Cleanup(func() { os.Remove(filename) })
 
 	ll := &FTWLogLines{
 		FileName: filename,
 	}
 
-	marker := ll.CheckLogForMarker(stageID)
+	marker := ll.CheckLogForMarker(logFile, stageID)
 	if marker == nil {
 		t.Fatal("no marker found")
 	}