From 4a483f2871f3c9f4176e22878c921d2a75b68c40 Mon Sep 17 00:00:00 2001 From: Max Leske Date: Sun, 6 Mar 2022 21:50:20 +0100 Subject: [PATCH] Prototype of log markers instead of using log time --- check/base.go | 12 ++++++++ runner/run.go | 50 +++++++++++++++++++++++++++++-- waflog/read.go | 80 ++++++++++++++++++++++++++++++++++++++++++++++++- waflog/types.go | 2 ++ 4 files changed, 141 insertions(+), 3 deletions(-) diff --git a/check/base.go b/check/base.go index f1087d3..487df25 100644 --- a/check/base.go +++ b/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 +} diff --git a/runner/run.go b/runner/run.go index 2227bf7..1890fe3 100644 --- a/runner/run.go +++ b/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 { diff --git a/waflog/read.go b/waflog/read.go index 3053bcd..73c78e6 100644 --- a/waflog/read.go +++ b/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) diff --git a/waflog/types.go b/waflog/types.go index 2149e81..f0f0568 100644 --- a/waflog/types.go +++ b/waflog/types.go @@ -18,4 +18,6 @@ type FTWLogLines struct { TimeTruncate time.Duration Since time.Time Until time.Time + StartMarker string + EndMarker string }