Prototype of log markers instead of using log time

check/base.go

@@ -26,6 +26,8 @@ func NewCheck(c *config.FTWConfiguration) *FTWCheck {
 			Until:        time.Now(),
 			TimeTruncate: c.LogType.TimeTruncate,
 			LogTruncate:  c.LogTruncate,
+			StartMarker:  "",
+			EndMarker:    "",
 		},
 		expected:  &test.Output{},
 		overrides: &c.TestOverride,
@@ -106,3 +108,13 @@ func (c *FTWCheck) SetCloudMode() {
 	}
 	c.expected.Status = status
 }
+
+// SetStartMarker sets the log line that marks the start of the logs to analyze
+func (c *FTWCheck) SetStartMarker(marker string) {
+	c.log.StartMarker = marker
+}
+
+// SetEndMarker sets the log line that marks the end of the logs to analyze
+func (c *FTWCheck) SetEndMarker(marker string) {
+	c.log.EndMarker = marker
+}

runner/run.go

@@ -12,6 +12,7 @@ import (
 	"github.com/fzipi/go-ftw/ftwhttp"
 	"github.com/fzipi/go-ftw/test"
 	"github.com/fzipi/go-ftw/utils"
+	"github.com/fzipi/go-ftw/waflog"
 
 	"github.com/kyokomi/emoji"
 	"github.com/rs/zerolog/log"
@@ -30,7 +31,7 @@ func Run(include string, exclude string, showTime bool, output bool, ftwtests []
 
 	client := ftwhttp.NewClient()
 
-	for _, tests := range ftwtests {
+	for testIndex, tests := range ftwtests {
 		changed := true
 		for _, t := range tests.Tests {
 			// if we received a particular testid, skip until we find it
@@ -48,7 +49,7 @@ func Run(include string, exclude string, showTime bool, output bool, ftwtests []
 			// can we use goroutines here?
 			printUnlessQuietMode(output, "\trunning %s: ", t.TestTitle)
 			// Iterate over stages
-			for _, stage := range t.Stages {
+			for stageIndex, stage := range t.Stages {
 				// Apply global overrides initially
 				testRequest := stage.Stage.Input
 				err := applyInputOverride(&testRequest)
@@ -86,6 +87,9 @@ func Run(include string, exclude string, showTime bool, output bool, ftwtests []
 					log.Fatal().Msgf("ftw/run: can't connect to destination %+v - unexpected error found. Is your waf running?", dest)
 				}
 
+				startMarker := markAndFlush(client, config.FTWConfig, testIndex, stageIndex)
+				ftwcheck.SetStartMarker(startMarker)
+
 				req = getRequestFromTest(testRequest)
 
 				client.StartTrackingTime()
@@ -94,6 +98,9 @@ func Run(include string, exclude string, showTime bool, output bool, ftwtests []
 
 				client.StopTrackingTime()
 
+				endMarker := markAndFlush(client, config.FTWConfig, testIndex, stageIndex)
+				ftwcheck.SetEndMarker(endMarker)
+
 				ftwcheck.SetRoundTripTime(client.GetRoundTripTime().StartTime(), client.GetRoundTripTime().StopTime())
 
 				// Set expected test output in check
@@ -118,6 +125,45 @@ func Run(include string, exclude string, showTime bool, output bool, ftwtests []
 	return printSummary(output, stats)
 }
 
+func markAndFlush(client *ftwhttp.Client, ftwConfig *config.FTWConfiguration, testIndex int, stageIndex int) string {
+	var req *ftwhttp.Request
+	var logLines = &waflog.FTWLogLines{
+		FileName:     ftwConfig.LogFile,
+		TimeRegex:    ftwConfig.LogType.TimeRegex,
+		TimeFormat:   ftwConfig.LogType.TimeFormat,
+		Since:        time.Now(),
+		Until:        time.Now(),
+		TimeTruncate: ftwConfig.LogType.TimeTruncate,
+		LogTruncate:  ftwConfig.LogTruncate,
+	}
+
+	rline := &ftwhttp.RequestLine{
+		Method:  "GET",
+		URI:     "/",
+		Version: "HTTP/1.0",
+	}
+
+	stageId := fmt.Sprintf("%d-%d", testIndex, stageIndex)
+	headers := &ftwhttp.Header{"Accept": "*/*", "User-Agent": "go-ftw test agent", "Host": "localhost", "X-CRS-Test": stageId}
+
+	// create a new request
+	req = ftwhttp.NewRequest(rline, *headers,
+		nil, true)
+
+	for range [20]int{} {
+		_, err := client.Do(*req)
+		if err != nil {
+			log.Fatal().Msg("ftw/run: can't connect to destination - unexpected error found. Is your waf running?")
+		}
+		marker, found := logLines.CheckLogForMarker(stageId)
+		if found {
+			return marker
+		}
+	}
+	log.Fatal().Msgf("Can't find log marker. Am I reading the correct log? Log file: %s", ftwConfig.LogFile)
+	return ""
+}
+
 func needToSkipTest(include string, exclude string, title string, enabled bool) bool {
 	// skip disabled tests
 	if !enabled {

waflog/read.go

@@ -1,6 +1,7 @@
 package waflog
 
 import (
+	"bytes"
 	"io"
 	"os"
 	"regexp"
@@ -14,7 +15,7 @@ import (
 // Contains looks in logfile for regex
 func (ll *FTWLogLines) Contains(match string) bool {
 	// this should be a flag
-	lines := ll.getLinesSinceUntil()
+	lines := ll.getMarkedLines()
 	// if we need to truncate file
 	if ll.LogTruncate {
 		ll.truncateLogFile()
@@ -116,6 +117,83 @@ func (ll *FTWLogLines) getLinesSinceUntil() [][]byte {
 	return found
 }
 
+func (ll *FTWLogLines) getMarkedLines() [][]byte {
+	var found [][]byte
+	logfile, err := os.Open(ll.FileName)
+
+	if err != nil {
+		log.Fatal().Msgf("cannot open file %s", ll.FileName)
+	}
+	defer logfile.Close()
+
+	fi, err := logfile.Stat()
+	if err != nil {
+		log.Error().Msgf("cannot read file's size")
+		return found
+	}
+
+	// Lines in modsec logging can be quite large
+	backscannerOptions := &backscanner.Options{
+		ChunkSize: 4096,
+	}
+	scanner := backscanner.NewOptions(logfile, int(fi.Size()), backscannerOptions)
+	endFound := false
+	for {
+		line, _, err := scanner.LineBytes()
+		if err != nil {
+			if err != io.EOF {
+				log.Trace().Err(err)
+			}
+			break
+		}
+		if !endFound && bytes.Equal(line, []byte(ll.EndMarker)) {
+			endFound = true
+		}
+		// TODO: don't convert markers between string and []byte
+		if endFound && bytes.Equal(line, []byte(ll.StartMarker)) {
+			saneCopy := make([]byte, len(line))
+			copy(saneCopy, line)
+			found = append(found, saneCopy)
+		}
+
+	}
+	return found
+}
+
+func (ll *FTWLogLines) CheckLogForMarker(stageId string) (string, bool) {
+	logfile, err := os.Open(ll.FileName)
+
+	if err != nil {
+		log.Fatal().Msgf("cannot open file %s", ll.FileName)
+	}
+	defer logfile.Close()
+
+	fi, err := logfile.Stat()
+	if err != nil {
+		log.Error().Msgf("cannot read file's size")
+		return "", false
+	}
+
+	// Lines in modsec logging can be quite large
+	backscannerOptions := &backscanner.Options{
+		ChunkSize: 4096,
+	}
+	scanner := backscanner.NewOptions(logfile, int(fi.Size()), backscannerOptions)
+	stageIdBytes := []byte(stageId)
+	crsHeaderBytes := []byte("X-CRS-Test")
+	line, _, err := scanner.LineBytes()
+	if err != nil {
+		if err != io.EOF {
+			log.Trace().Err(err)
+		}
+	}
+	if bytes.Contains(line, crsHeaderBytes) && bytes.Contains(line, stageIdBytes) {
+		return string(line), true
+	}
+
+	return "", false
+}
+
 // truncateLogFile
 func (ll *FTWLogLines) truncateLogFile() {
 	err := os.Truncate(ll.FileName, 0)

waflog/types.go

@@ -18,4 +18,6 @@ type FTWLogLines struct {
 	TimeTruncate time.Duration
 	Since        time.Time
 	Until        time.Time
+	StartMarker  string
+	EndMarker    string
 }