From b67a0547d2b8e643c3122cc794b5547cca6a2fab Mon Sep 17 00:00:00 2001 From: Matteo Pace Date: Mon, 9 Dec 2024 21:59:49 +0100 Subject: [PATCH 1/7] reduce flakiness --- runner/run.go | 11 +++--- waflog/read.go | 94 ++++++++++++++++++++++++++------------------- waflog/read_test.go | 6 +-- 3 files changed, 64 insertions(+), 47 deletions(-) diff --git a/runner/run.go b/runner/run.go index 71d3f8c..90564c4 100644 --- a/runner/run.go +++ b/runner/run.go @@ -164,9 +164,10 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch Port: testInput.GetPort(), Protocol: testInput.GetProtocol(), } - + var startMarker []byte if notRunningInCloudMode(ftwCheck) { - startMarker, err := markAndFlush(runContext, &testInput, stageId) + var err error + startMarker, err = markAndFlush(runContext, &testInput, stageId, nil) if err != nil && !expectErr { return fmt.Errorf("failed to find start marker: %w", err) } @@ -190,7 +191,7 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch } if notRunningInCloudMode(ftwCheck) { - endMarker, err := markAndFlush(runContext, &testInput, stageId) + endMarker, err := markAndFlush(runContext, &testInput, stageId, startMarker) if err != nil && !expectErr { return fmt.Errorf("failed to find end marker: %w", err) @@ -220,7 +221,7 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch return nil } -func markAndFlush(runContext *TestRunContext, testInput *test.Input, stageId string) ([]byte, error) { +func markAndFlush(runContext *TestRunContext, testInput *test.Input, stageId string, startMarker []byte) ([]byte, error) { req := buildMarkerRequest(runContext, testInput, stageId) dest := &ftwhttp.Destination{ DestAddr: testInput.GetDestAddr(), @@ -238,7 +239,7 @@ func markAndFlush(runContext *TestRunContext, testInput *test.Input, stageId str return nil, fmt.Errorf("ftw/run: failed sending request to %+v: %w", dest, err) } - marker := runContext.LogLines.CheckLogForMarker(stageId, runContext.Config.MaxMarkerLogLines) + marker := runContext.LogLines.CheckLogForMarker(stageId, runContext.Config.MaxMarkerLogLines, startMarker) if marker != nil { return marker, nil } diff --git a/waflog/read.go b/waflog/read.go index dc07569..0620421 100644 --- a/waflog/read.go +++ b/waflog/read.go @@ -9,6 +9,7 @@ import ( "io" "regexp" "strconv" + "time" "slices" @@ -17,6 +18,7 @@ import ( ) const maxRuleIdsEstimate = 15 +const maxSeekAttempts = 10 var ruleIdsSet = make(map[uint]bool, maxRuleIdsEstimate) @@ -134,7 +136,6 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { if ll.startMarker == nil || ll.endMarker == nil { log.Fatal().Msg("Both start and end marker must be set before the log can be inspected") } - fi, err := ll.logFile.Stat() if err != nil { log.Error().Caller().Msgf("cannot read file's size") @@ -146,6 +147,7 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { ChunkSize: 4096, } scanner := backscanner.NewOptions(ll.logFile, int(fi.Size()), backscannerOptions) + startFound := false endFound := false // end marker is the *first* marker when reading backwards, // start marker is the *last* marker @@ -170,6 +172,9 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { copy(saneCopy, line) ll.markedLines = append(ll.markedLines, saneCopy) } + if !startFound { + log.Debug().Msgf("starter marker not found while getting marked lines") + } return ll.markedLines } @@ -177,53 +182,64 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { // CheckLogForMarker reads the log file and searches for a marker line. // stageID is the ID of the current stage, which is part of the marker line // readLimit is the maximum numbers of lines to check -func (ll *FTWLogLines) CheckLogForMarker(stageID string, readLimit uint) []byte { - offset, err := ll.logFile.Seek(0, io.SeekEnd) - if err != nil { - log.Error().Caller().Err(err).Msgf("failed to seek end of log file") - return nil - } - - // Lines in logging can be quite large - backscannerOptions := &backscanner.Options{ - ChunkSize: 4096, - } - scanner := backscanner.NewOptions(ll.logFile, int(offset), backscannerOptions) - stageIDBytes := []byte(stageID) - crsHeaderBytes := bytes.ToLower([]byte(ll.LogMarkerHeaderName)) - +// When startMarker is not nil, the function will ensure that the marker line is not equal to startMarker +// otherwise, after some retries, a warning is raised. +func (ll *FTWLogLines) CheckLogForMarker(stageID string, readLimit uint, startMarker []byte) []byte { var line []byte - lineCounter := uint(0) - // Look for the header until EOF or `readLimit` lines at most - for { - if lineCounter > readLimit { - log.Debug().Msg("aborting search for marker") + for seekAttempts := 0; seekAttempts < maxSeekAttempts; seekAttempts++ { + offset, err := ll.logFile.Seek(0, io.SeekEnd) + if err != nil { + log.Error().Caller().Err(err).Msgf("failed to seek end of log file") return nil } - lineCounter++ - line, _, err = scanner.LineBytes() - if err != nil { - if errors.Is(err, io.EOF) { - log.Trace().Err(err).Msg("found EOF while looking for log marker") - return nil - } else { - log.Error().Err(err).Msg("failed to inspect next log line for marker") + // Lines in logging can be quite large + backscannerOptions := &backscanner.Options{ + ChunkSize: 4096, + } + scanner := backscanner.NewOptions(ll.logFile, int(offset), backscannerOptions) + stageIDBytes := []byte(stageID) + crsHeaderBytes := bytes.ToLower([]byte(ll.LogMarkerHeaderName)) + + lineCounter := uint(0) + // Look for the header until EOF or `readLimit` lines at most + for { + if lineCounter > readLimit { + log.Debug().Msg("aborting search for marker") return nil } + lineCounter++ + + line, _, err = scanner.LineBytes() + if err != nil { + if errors.Is(err, io.EOF) { + log.Trace().Err(err).Msg("found EOF while looking for log marker") + return nil + } else { + log.Error().Err(err).Msg("failed to inspect next log line for marker") + return nil + } + } + + line = bytes.ToLower(line) + if bytes.Contains(line, crsHeaderBytes) { + break + } } - line = bytes.ToLower(line) - if bytes.Contains(line, crsHeaderBytes) { - break + // Found the header, now the line should also match the stage ID + if bytes.Contains(line, stageIDBytes) { + if startMarker != nil && bytes.Equal(startMarker, line) { + log.Trace().Msgf("found equal start and end markers: %s. Seeking again...", startMarker) + time.Sleep(1 * time.Millisecond) + continue + } + return line } - } - // Found the header, now the line should also match the stage ID - if bytes.Contains(line, stageIDBytes) { - return line + log.Debug().Msgf("found unexpected marker line while looking for %s: %s", stageID, line) + return nil } - - log.Debug().Msgf("found unexpected marker line while looking for %s: %s", stageID, line) - return nil + log.Warn().Msgf("failed to find end marker different from start marker after %d attempts", maxSeekAttempts) + return line } diff --git a/waflog/read_test.go b/waflog/read_test.go index 4c86e6f..fb2f3f9 100644 --- a/waflog/read_test.go +++ b/waflog/read_test.go @@ -50,7 +50,7 @@ func (s *readTestSuite) TestReadCheckLogForMarkerNoMarkerAtEnd() { ll, err := NewFTWLogLines(cfg) s.Require().NoError(err) ll.WithStartMarker([]byte(markerLine)) - marker := ll.CheckLogForMarker(stageID, 100) + marker := ll.CheckLogForMarker(stageID, 100, []byte(markerLine)) s.Equal(string(marker), strings.ToLower(markerLine), "unexpectedly found marker") } @@ -75,7 +75,7 @@ func (s *readTestSuite) TestReadCheckLogForMarkerWithMarkerAtEnd() { ll.WithStartMarker([]byte(markerLine)) s.Require().NoError(err) - marker := ll.CheckLogForMarker(stageID, 100) + marker := ll.CheckLogForMarker(stageID, 100, []byte(markerLine)) s.NotNil(marker, "no marker found") s.Equal(marker, bytes.ToLower([]byte(markerLine)), "found unexpected marker") @@ -358,7 +358,7 @@ func (s *readTestSuite) TestFTWLogLines_CheckForLogMarkerIn404() { } ll.WithStartMarker([]byte(markerLine)) ll.WithEndMarker([]byte(markerLine)) - foundMarker := ll.CheckLogForMarker(stageID, 100) + foundMarker := ll.CheckLogForMarker(stageID, 100, nil) s.Equal(strings.ToLower(markerLine), strings.ToLower(string(foundMarker))) } From 3e31033563b5c9e644d8e53673ffd19a9f35482d Mon Sep 17 00:00:00 2001 From: Matteo Pace Date: Mon, 9 Dec 2024 22:40:47 +0100 Subject: [PATCH 2/7] space --- runner/run.go | 1 + 1 file changed, 1 insertion(+) diff --git a/runner/run.go b/runner/run.go index 90564c4..6131485 100644 --- a/runner/run.go +++ b/runner/run.go @@ -164,6 +164,7 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch Port: testInput.GetPort(), Protocol: testInput.GetProtocol(), } + var startMarker []byte if notRunningInCloudMode(ftwCheck) { var err error From 2cc5a0802e45de54daa63b68a746253269e03292 Mon Sep 17 00:00:00 2001 From: Matteo Pace Date: Mon, 9 Dec 2024 22:42:55 +0100 Subject: [PATCH 3/7] space --- waflog/read.go | 1 + 1 file changed, 1 insertion(+) diff --git a/waflog/read.go b/waflog/read.go index 0620421..df68c59 100644 --- a/waflog/read.go +++ b/waflog/read.go @@ -136,6 +136,7 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { if ll.startMarker == nil || ll.endMarker == nil { log.Fatal().Msg("Both start and end marker must be set before the log can be inspected") } + fi, err := ll.logFile.Stat() if err != nil { log.Error().Caller().Msgf("cannot read file's size") From 0d3cd4651cd4792039785cb44920af2367d9d5f2 Mon Sep 17 00:00:00 2001 From: Matteo Pace Date: Mon, 9 Dec 2024 23:07:45 +0100 Subject: [PATCH 4/7] true --- waflog/read.go | 1 + 1 file changed, 1 insertion(+) diff --git a/waflog/read.go b/waflog/read.go index df68c59..6a8c80c 100644 --- a/waflog/read.go +++ b/waflog/read.go @@ -166,6 +166,7 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { continue } if endFound && bytes.Equal(lineLower, ll.startMarker) { + startFound = true break } From 5b3386ad4a4f180a0dbd8ed15bfae737671a331c Mon Sep 17 00:00:00 2001 From: Matteo Pace Date: Wed, 11 Dec 2024 16:13:57 +0100 Subject: [PATCH 5/7] start and end marker --- check/logs_test.go | 19 +++++---- runner/run.go | 19 ++++++--- waflog/read.go | 101 ++++++++++++++++++++++---------------------- waflog/read_test.go | 50 ++++++++++++---------- 4 files changed, 102 insertions(+), 87 deletions(-) diff --git a/check/logs_test.go b/check/logs_test.go index 6b11ab3..297a92b 100644 --- a/check/logs_test.go +++ b/check/logs_test.go @@ -6,18 +6,24 @@ package check import ( "testing" - "github.com/google/uuid" "github.com/stretchr/testify/suite" "github.com/coreruleset/go-ftw/config" "github.com/coreruleset/go-ftw/utils" ) -var logText = `[Tue Jan 05 02:21:09.637165 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Pattern match "\\\\b(?:keep-alive|close),\\\\s?(?:keep-alive|close)\\\\b" at REQUEST_HEADERS:Connection. [file "/etc/modsecurity.d/owasp-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "339"] [id "920210"] [msg "Multiple/Conflicting Connection Header Data Found"] [data "close,close"] [severity "WARNING"] [ver "OWASP_CRS/3.3.0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"] +var ( + uuidString = "8677f1ed-3936-4999-82e4-39daf32ffff5" + markerStart = uuidString + "-s" + markerEnd = uuidString + "-e" + logText = markerStart + + ` +[Tue Jan 05 02:21:09.637165 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Pattern match "\\\\b(?:keep-alive|close),\\\\s?(?:keep-alive|close)\\\\b" at REQUEST_HEADERS:Connection. [file "/etc/modsecurity.d/owasp-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "339"] [id "920210"] [msg "Multiple/Conflicting Connection Header Data Found"] [data "close,close"] [severity "WARNING"] [ver "OWASP_CRS/3.3.0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"] [Tue Jan 05 02:21:09.637731 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Match of "pm AppleWebKit Android" against "REQUEST_HEADERS:User-Agent" required. [file "/etc/modsecurity.d/owasp-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "1230"] [id "920300"] [msg "Request Missing an Accept Header"] [severity "NOTICE"] [ver "OWASP_CRS/3.3.0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [tag "PCI/6.5.10"] [tag "paranoia-level/2"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"] [Tue Jan 05 02:21:09.638572 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Operator GE matched 5 at TX:anomaly_score. [file "/etc/modsecurity.d/owasp-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "91"] [id "949110"] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [severity "CRITICAL"] [ver "OWASP_CRS/3.3.0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"] [Tue Jan 05 02:21:09.647668 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Operator GE matched 5 at TX:inbound_anomaly_score. [file "/etc/modsecurity.d/owasp-crs/rules/RESPONSE-980-CORRELATION.conf"] [line "87"] [id "980130"] [msg "Inbound Anomaly Score Exceeded (Total Inbound Score: 5 - SQLI=0,XSS=0,RFI=0,LFI=0,RCE=0,PHPI=0,HTTP=0,SESS=0): individual paranoia level scores: 3, 2, 0, 0"] [ver "OWASP_CRS/3.3.0"] [tag "event-correlation"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"] -` +` + markerEnd +) type checkLogsTestSuite struct { suite.Suite @@ -41,11 +47,8 @@ func (s *checkLogsTestSuite) SetupTest() { s.check, err = NewCheck(s.cfg) s.Require().NoError(err) - // The log checker requires the markers to be set, but - // for these tests we can set them to random strings because - // we just check all lines. - s.check.log.WithStartMarker([]byte(uuid.NewString())) - s.check.log.WithEndMarker([]byte(uuid.NewString())) + s.check.log.WithStartMarker([]byte(markerStart)) + s.check.log.WithEndMarker([]byte(markerEnd)) } func (s *checkLogsTestSuite) TearDownTest() { diff --git a/runner/run.go b/runner/run.go index 6131485..58bcb9c 100644 --- a/runner/run.go +++ b/runner/run.go @@ -22,6 +22,13 @@ import ( "github.com/coreruleset/go-ftw/waflog" ) +const ( + // start and end UUID suffixes are used to disambiguate start and end markers. + // It permits to make the markers unique, while still maintaining one UUID per stage. + startUUIDSuffix = "-s" + endUUIDSuffix = "-e" +) + // Run runs your tests with the specified Config. func Run(cfg *config.FTWConfiguration, tests []*test.FTWTest, c RunnerConfig, out *output.Output) (*TestRunContext, error) { out.Println("%s", out.Message("** Running go-ftw!")) @@ -165,10 +172,9 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch Protocol: testInput.GetProtocol(), } - var startMarker []byte if notRunningInCloudMode(ftwCheck) { - var err error - startMarker, err = markAndFlush(runContext, &testInput, stageId, nil) + startUUID := stageId + startUUIDSuffix + startMarker, err := markAndFlush(runContext, &testInput, startUUID) if err != nil && !expectErr { return fmt.Errorf("failed to find start marker: %w", err) } @@ -192,7 +198,8 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch } if notRunningInCloudMode(ftwCheck) { - endMarker, err := markAndFlush(runContext, &testInput, stageId, startMarker) + endUUID := stageId + endUUIDSuffix + endMarker, err := markAndFlush(runContext, &testInput, endUUID) if err != nil && !expectErr { return fmt.Errorf("failed to find end marker: %w", err) @@ -222,7 +229,7 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch return nil } -func markAndFlush(runContext *TestRunContext, testInput *test.Input, stageId string, startMarker []byte) ([]byte, error) { +func markAndFlush(runContext *TestRunContext, testInput *test.Input, stageId string) ([]byte, error) { req := buildMarkerRequest(runContext, testInput, stageId) dest := &ftwhttp.Destination{ DestAddr: testInput.GetDestAddr(), @@ -240,7 +247,7 @@ func markAndFlush(runContext *TestRunContext, testInput *test.Input, stageId str return nil, fmt.Errorf("ftw/run: failed sending request to %+v: %w", dest, err) } - marker := runContext.LogLines.CheckLogForMarker(stageId, runContext.Config.MaxMarkerLogLines, startMarker) + marker := runContext.LogLines.CheckLogForMarker(stageId, runContext.Config.MaxMarkerLogLines) if marker != nil { return marker, nil } diff --git a/waflog/read.go b/waflog/read.go index 6a8c80c..ab99515 100644 --- a/waflog/read.go +++ b/waflog/read.go @@ -9,7 +9,6 @@ import ( "io" "regexp" "strconv" - "time" "slices" @@ -18,7 +17,6 @@ import ( ) const maxRuleIdsEstimate = 15 -const maxSeekAttempts = 10 var ruleIdsSet = make(map[uint]bool, maxRuleIdsEstimate) @@ -137,6 +135,10 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { log.Fatal().Msg("Both start and end marker must be set before the log can be inspected") } + if bytes.Equal(ll.startMarker, ll.endMarker) { + log.Fatal().Msg("Start and end markers must be different") + } + fi, err := ll.logFile.Stat() if err != nil { log.Error().Caller().Msgf("cannot read file's size") @@ -165,6 +167,14 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { endFound = true continue } + if !endFound { + // Skip lines until we find the end marker. Reading backwards, the line we are looking for are + // between the end and start markers. + if bytes.Equal(lineLower, ll.endMarker) { + endFound = true + } + continue + } if endFound && bytes.Equal(lineLower, ll.startMarker) { startFound = true break @@ -183,65 +193,54 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { // CheckLogForMarker reads the log file and searches for a marker line. // stageID is the ID of the current stage, which is part of the marker line +// At this point, stageID includes also the start or end suffix. // readLimit is the maximum numbers of lines to check -// When startMarker is not nil, the function will ensure that the marker line is not equal to startMarker -// otherwise, after some retries, a warning is raised. -func (ll *FTWLogLines) CheckLogForMarker(stageID string, readLimit uint, startMarker []byte) []byte { +func (ll *FTWLogLines) CheckLogForMarker(stageID string, readLimit uint) []byte { var line []byte - for seekAttempts := 0; seekAttempts < maxSeekAttempts; seekAttempts++ { - offset, err := ll.logFile.Seek(0, io.SeekEnd) - if err != nil { - log.Error().Caller().Err(err).Msgf("failed to seek end of log file") + offset, err := ll.logFile.Seek(0, io.SeekEnd) + if err != nil { + log.Error().Caller().Err(err).Msgf("failed to seek end of log file") + return nil + } + + // Lines in logging can be quite large + backscannerOptions := &backscanner.Options{ + ChunkSize: 4096, + } + scanner := backscanner.NewOptions(ll.logFile, int(offset), backscannerOptions) + stageIDBytes := []byte(stageID) + crsHeaderBytes := bytes.ToLower([]byte(ll.LogMarkerHeaderName)) + + lineCounter := uint(0) + // Look for the header until EOF or `readLimit` lines at most + for { + if lineCounter > readLimit { + log.Debug().Msg("aborting search for marker") return nil } + lineCounter++ - // Lines in logging can be quite large - backscannerOptions := &backscanner.Options{ - ChunkSize: 4096, - } - scanner := backscanner.NewOptions(ll.logFile, int(offset), backscannerOptions) - stageIDBytes := []byte(stageID) - crsHeaderBytes := bytes.ToLower([]byte(ll.LogMarkerHeaderName)) - - lineCounter := uint(0) - // Look for the header until EOF or `readLimit` lines at most - for { - if lineCounter > readLimit { - log.Debug().Msg("aborting search for marker") + line, _, err = scanner.LineBytes() + if err != nil { + if errors.Is(err, io.EOF) { + log.Trace().Err(err).Msg("found EOF while looking for log marker") + return nil + } else { + log.Error().Err(err).Msg("failed to inspect next log line for marker") return nil - } - lineCounter++ - - line, _, err = scanner.LineBytes() - if err != nil { - if errors.Is(err, io.EOF) { - log.Trace().Err(err).Msg("found EOF while looking for log marker") - return nil - } else { - log.Error().Err(err).Msg("failed to inspect next log line for marker") - return nil - } - } - - line = bytes.ToLower(line) - if bytes.Contains(line, crsHeaderBytes) { - break } } - // Found the header, now the line should also match the stage ID - if bytes.Contains(line, stageIDBytes) { - if startMarker != nil && bytes.Equal(startMarker, line) { - log.Trace().Msgf("found equal start and end markers: %s. Seeking again...", startMarker) - time.Sleep(1 * time.Millisecond) - continue - } - return line + line = bytes.ToLower(line) + if bytes.Contains(line, crsHeaderBytes) { + break } + } - log.Debug().Msgf("found unexpected marker line while looking for %s: %s", stageID, line) - return nil + // Found the header, now the line should also match the stage ID + if bytes.Contains(line, stageIDBytes) { + return line } - log.Warn().Msgf("failed to find end marker different from start marker after %d attempts", maxSeekAttempts) - return line + log.Debug().Msgf("found unexpected marker line while looking for %s: %s", stageID, line) + return nil } diff --git a/waflog/read_test.go b/waflog/read_test.go index fb2f3f9..36410e5 100644 --- a/waflog/read_test.go +++ b/waflog/read_test.go @@ -50,7 +50,7 @@ func (s *readTestSuite) TestReadCheckLogForMarkerNoMarkerAtEnd() { ll, err := NewFTWLogLines(cfg) s.Require().NoError(err) ll.WithStartMarker([]byte(markerLine)) - marker := ll.CheckLogForMarker(stageID, 100, []byte(markerLine)) + marker := ll.CheckLogForMarker(stageID, 100) s.Equal(string(marker), strings.ToLower(markerLine), "unexpectedly found marker") } @@ -75,7 +75,7 @@ func (s *readTestSuite) TestReadCheckLogForMarkerWithMarkerAtEnd() { ll.WithStartMarker([]byte(markerLine)) s.Require().NoError(err) - marker := ll.CheckLogForMarker(stageID, 100, []byte(markerLine)) + marker := ll.CheckLogForMarker(stageID, 100) s.NotNil(marker, "no marker found") s.Equal(marker, bytes.ToLower([]byte(markerLine)), "found unexpected marker") @@ -148,7 +148,7 @@ func (s *readTestSuite) TestReadGetMarkedLinesWithTrailingEmptyLines() { foundLines[i], foundLines[j] = foundLines[j], foundLines[i] } - s.Len(foundLines, 6, "found unexpected number of log lines") + s.Len(foundLines, 3, "found unexpected number of log lines") for index, line := range strings.Split(logLinesOnly, "\n") { s.Equalf(foundLines[index], []byte(line), "log lines don't match: \n%s\n%s", line, string(foundLines[index])) @@ -188,7 +188,7 @@ func (s *readTestSuite) TestReadGetMarkedLinesWithPrecedingLines() { foundLines[i], foundLines[j] = foundLines[j], foundLines[i] } - s.Len(foundLines, 4, "found unexpected number of log lines") + s.Len(foundLines, 3, "found unexpected number of log lines") for index, line := range strings.Split(logLinesOnly, "\n") { s.Equalf(foundLines[index], []byte(line), "log lines don't match: \n%s\n%s", line, string(foundLines[index])) @@ -201,12 +201,15 @@ func (s *readTestSuite) TestFTWLogLines_Contains() { s.NotNil(cfg) stageID := "dead-beaf-deadbeef-deadbeef-dead" - markerLine := "X-cRs-TeSt: " + stageID - logLines := ` + markerLineStart := "X-cRs-TeSt: " + stageID + "-s" + markerLineEnd := "X-cRs-TeSt: " + stageID + "-e" + logLines := + markerLineStart + + ` [Tue Jan 05 02:21:09.637165 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Pattern match "\\\\b(?:keep-alive|close),\\\\s?(?:keep-alive|close)\\\\b" at REQUEST_HEADERS:Connection. [file "/etc/modsecurity.d/owasp-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "339"] [id "920210"] [msg "Multiple/Conflicting Connection Header Data Found"] [data "close,close"] [severity "WARNING"] [ver "OWASP_CRS/3.3.0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"] [Tue Jan 05 02:21:09.637731 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Match of "pm AppleWebKit Android" against "REQUEST_HEADERS:User-Agent" required. [file "/etc/modsecurity.d/owasp-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "1230"] [id "920300"] [msg "Request Missing an Accept Header"] [severity "NOTICE"] [ver "OWASP_CRS/3.3.0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [tag "PCI/6.5.10"] [tag "paranoia-level/2"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"] [Tue Jan 05 02:21:09.638572 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Operator GE matched 5 at TX:anomaly_score. [file "/etc/modsecurity.d/owasp-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "91"] [id "949110"] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [severity "CRITICAL"] [ver "OWASP_CRS/3.3.0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"] -` + markerLine +` + markerLineEnd s.filename, err = utils.CreateTempFileWithContent(logLines, "test-errorlog-") s.Require().NoError(err) @@ -223,8 +226,8 @@ func (s *readTestSuite) TestFTWLogLines_Contains() { f := fields{ logFile: log, LogMarkerHeaderName: []byte(cfg.LogMarkerHeaderName), - StartMarker: []byte(markerLine), - EndMarker: []byte(markerLine), + StartMarker: []byte(markerLineStart), + EndMarker: []byte(markerLineEnd), } type args struct { @@ -273,13 +276,16 @@ func (s *readTestSuite) TestFTWLogLines_ContainsIn404() { s.NotNil(cfg) stageID := "dead-beaf-deadbeef-deadbeef-dead" - markerLine := fmt.Sprint(`[2022-11-12 23:08:18.012572] [-:error] 127.0.0.1:36126 Y3AZUo3Gja4gB-tPE9uasgAAAA4 [client 127.0.0.1] ModSecurity: Warning. Unconditional match in SecAction. [file "/apache/conf/httpd.conf_pod_2022-11-12_22:23"] [line "265"] [id "999999"] [msg "`, - "X-cRs-TeSt ", stageID, + markerLineStart := fmt.Sprint(`[2022-11-12 23:08:18.012572] [-:error] 127.0.0.1:36126 Y3AZUo3Gja4gB-tPE9uasgAAAA4 [client 127.0.0.1] ModSecurity: Warning. Unconditional match in SecAction. [file "/apache/conf/httpd.conf_pod_2022-11-12_22:23"] [line "265"] [id "999999"] [msg "`, + "X-cRs-TeSt ", stageID+"-s", `"] [hostname "localhost"] [uri "/status/200"] [unique_id "Y3AZUo3Gja4gB-tPE9uasgAAAA4"]`) - logLines := fmt.Sprint("\n", markerLine, + markerLineEnd := fmt.Sprint(`[2022-11-12 23:08:18.012580] [-:error] 127.0.0.1:36126 Y3AZUo3Gja4gB-tPE9uasgAAAA4 [client 127.0.0.1] ModSecurity: Warning. Unconditional match in SecAction. [file "/apache/conf/httpd.conf_pod_2022-11-12_22:23"] [line "265"] [id "999999"] [msg "`, + "X-cRs-TeSt ", stageID+"-e", + `"] [hostname "localhost"] [uri "/status/200"] [unique_id "Y3AZUo3Gja4gB-tPE9uasgBBBB4"]`) + logLines := fmt.Sprint("\n", markerLineStart, `[Tue Jan 05 02:21:09.637165 2021] [:error] [pid 76:tid 139683434571520] [client 172.23.0.1:58998] [client 172.23.0.1] ModSecurity: Warning. Pattern match "\\\\b(?:keep-alive|close),\\\\s?(?:keep-alive|close)\\\\b" at REQUEST_HEADERS:Connection. [file "/etc/modsecurity.d/owasp-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "339"] [id "920210"] [msg "Multiple/Conflicting Connection Header Data Found"] [data "close,close"] [severity "WARNING"] [ver "OWASP_CRS/3.3.0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [hostname "localhost"] [uri "/"] [unique_id "X-PNFSe1VwjCgYRI9FsbHgAAAIY"]`, `[2022-11-12 23:08:18.013007] [core:info] 127.0.0.1:36126 Y3AZUo3Gja4gB-tPE9uasgAAAA4 AH00128: File does not exist: /apache/htdocs/status/200`, - "\n", markerLine) + "\n", markerLineEnd) filename, err := utils.CreateTempFileWithContent(logLines, "test-errorlog-") s.Require().NoError(err) @@ -296,8 +302,8 @@ func (s *readTestSuite) TestFTWLogLines_ContainsIn404() { f := fields{ logFile: log, LogMarkerHeaderName: []byte(cfg.LogMarkerHeaderName), - StartMarker: []byte(markerLine), - EndMarker: []byte(markerLine), + StartMarker: []byte(markerLineStart), + EndMarker: []byte(markerLineEnd), } type args struct { @@ -336,7 +342,6 @@ func (s *readTestSuite) TestFTWLogLines_CheckForLogMarkerIn404() { cfg, err := config.NewConfigFromEnv() s.Require().NoError(err) s.NotNil(cfg) - stageID := "dead-beaf-deadbeef-deadbeef-dead" markerLine := fmt.Sprint(`[2022-11-12 23:08:18.012572] [-:error] 127.0.0.1:36126 Y3AZUo3Gja4gB-tPE9uasgAAAA4 [client 127.0.0.1] ModSecurity: Warning. Unconditional match in SecAction. [file "/apache/conf/httpd.conf_pod_2022-11-12_22:23"] [line "265"] [id "999999"] [msg "`, "X-cRs-TeSt ", stageID, @@ -358,7 +363,7 @@ func (s *readTestSuite) TestFTWLogLines_CheckForLogMarkerIn404() { } ll.WithStartMarker([]byte(markerLine)) ll.WithEndMarker([]byte(markerLine)) - foundMarker := ll.CheckLogForMarker(stageID, 100, nil) + foundMarker := ll.CheckLogForMarker(stageID, 100) s.Equal(strings.ToLower(markerLine), strings.ToLower(string(foundMarker))) } @@ -368,12 +373,13 @@ func (s *readTestSuite) TestFindAllIdsInLogs() { s.NotNil(cfg) stageID := "dead-beaf-deadbeef-deadbeef-dead" - markerLine := "X-cRs-TeSt: " + stageID - logLines := fmt.Sprint("\n", markerLine, + markerLineStart := "X-cRs-TeSt: " + stageID + "-s" + markerLineEnd := "X-cRs-TeSt: " + stageID + "-e" + logLines := fmt.Sprint("\n", markerLineStart, `[id "1"] something else [id "2"]`, `"id": 3, something else {"id":4},`, `something else [id \"5\"]`+"\n", - "\n", markerLine) + "\n", markerLineEnd) filename, err := utils.CreateTempFileWithContent(logLines, "test-errorlog-") s.Require().NoError(err) cfg.LogFile = filename @@ -384,8 +390,8 @@ func (s *readTestSuite) TestFindAllIdsInLogs() { logFile: log, LogMarkerHeaderName: bytes.ToLower([]byte(cfg.LogMarkerHeaderName)), } - ll.WithStartMarker([]byte(markerLine)) - ll.WithEndMarker([]byte(markerLine)) + ll.WithStartMarker([]byte(markerLineStart)) + ll.WithEndMarker([]byte(markerLineEnd)) foundRuleIds := ll.TriggeredRules() s.Len(foundRuleIds, 5) From 8a8ec48dfb77ad7a072a8405c1b37886cfee3724 Mon Sep 17 00:00:00 2001 From: Matteo Pace Date: Wed, 11 Dec 2024 16:35:20 +0100 Subject: [PATCH 6/7] fix --- waflog/read.go | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/waflog/read.go b/waflog/read.go index ab99515..e3d22e8 100644 --- a/waflog/read.go +++ b/waflog/read.go @@ -163,10 +163,7 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { break } lineLower := bytes.ToLower(line) - if !endFound && bytes.Equal(lineLower, ll.endMarker) { - endFound = true - continue - } + if !endFound { // Skip lines until we find the end marker. Reading backwards, the line we are looking for are // between the end and start markers. From 8c932351b92b108200811067b437ff68e11ed38d Mon Sep 17 00:00:00 2001 From: Matteo Pace Date: Wed, 11 Dec 2024 16:36:22 +0100 Subject: [PATCH 7/7] less diffs --- waflog/read.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/waflog/read.go b/waflog/read.go index e3d22e8..1f3e158 100644 --- a/waflog/read.go +++ b/waflog/read.go @@ -193,7 +193,6 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte { // At this point, stageID includes also the start or end suffix. // readLimit is the maximum numbers of lines to check func (ll *FTWLogLines) CheckLogForMarker(stageID string, readLimit uint) []byte { - var line []byte offset, err := ll.logFile.Seek(0, io.SeekEnd) if err != nil { log.Error().Caller().Err(err).Msgf("failed to seek end of log file") @@ -208,6 +207,7 @@ func (ll *FTWLogLines) CheckLogForMarker(stageID string, readLimit uint) []byte stageIDBytes := []byte(stageID) crsHeaderBytes := bytes.ToLower([]byte(ll.LogMarkerHeaderName)) + var line []byte lineCounter := uint(0) // Look for the header until EOF or `readLimit` lines at most for {