Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: flaky results: same start and end marker #413

Open
wants to merge 7 commits into
base: main
Choose a base branch
from
Open

fix: flaky results: same start and end marker #413

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
b67a054
reduce flakiness
M4tteoP Dec 9, 2024
3e31033
space
M4tteoP Dec 9, 2024
2cc5a08
space
M4tteoP Dec 9, 2024
0d3cd46
true
M4tteoP Dec 9, 2024
5b3386a
start and end marker
M4tteoP Dec 11, 2024
8a8ec48
fix
M4tteoP Dec 11, 2024
8c93235
less diffs
M4tteoP Dec 11, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 11 additions & 8 deletions check/logs_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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() {
Expand Down
13 changes: 11 additions & 2 deletions runner/run.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Comment on lines +28 to +29
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
startUUIDSuffix = "-s"
endUUIDSuffix = "-e"
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!"))
Expand Down Expand Up @@ -166,7 +173,8 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch
}

if notRunningInCloudMode(ftwCheck) {
startMarker, err := markAndFlush(runContext, &testInput, stageId)
startUUID := stageId + startUUIDSuffix
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
startUUID := stageId + startUUIDSuffix
startId := stageId + startUUIDSuffix

startMarker, err := markAndFlush(runContext, &testInput, startUUID)
if err != nil && !expectErr {
return fmt.Errorf("failed to find start marker: %w", err)
}
Expand All @@ -190,7 +198,8 @@ func RunStage(runContext *TestRunContext, ftwCheck *check.FTWCheck, testCase sch
}

if notRunningInCloudMode(ftwCheck) {
endMarker, err := markAndFlush(runContext, &testInput, stageId)
endUUID := stageId + endUUIDSuffix
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
endUUID := stageId + endUUIDSuffix
endId := stageId + endUUIDSuffix

endMarker, err := markAndFlush(runContext, &testInput, endUUID)
if err != nil && !expectErr {
return fmt.Errorf("failed to find end marker: %w", err)

Expand Down
20 changes: 17 additions & 3 deletions waflog/read.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -135,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")
Expand All @@ -146,6 +150,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
Expand All @@ -158,24 +163,34 @@ func (ll *FTWLogLines) getMarkedLines() [][]byte {
break
}
lineLower := bytes.ToLower(line)
if !endFound && bytes.Equal(lineLower, ll.endMarker) {
endFound = true

if !endFound {
// Skip lines until we find the end marker. Reading backwards, the line we are looking for are
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
// Skip lines until we find the end marker. Reading backwards, the line we are looking for are
// Skip lines until we find the end marker. Reading backwards, the lines 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
}

saneCopy := make([]byte, len(line))
copy(saneCopy, line)
ll.markedLines = append(ll.markedLines, saneCopy)
}
if !startFound {
log.Debug().Msgf("starter marker not found while getting marked lines")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
log.Debug().Msgf("starter marker not found while getting marked lines")
log.Debug().Msg("starter marker not found while getting marked lines")

}

return ll.markedLines
}

// 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.
Comment on lines 192 to +193
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
// 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.
// markerId is the ID of the current stage + suffix (for start / end), 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 {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
func (ll *FTWLogLines) CheckLogForMarker(stageID string, readLimit uint) []byte {
func (ll *FTWLogLines) CheckLogForMarker(markerId string, readLimit uint) []byte {

offset, err := ll.logFile.Seek(0, io.SeekEnd)
Expand Down Expand Up @@ -223,7 +238,6 @@ func (ll *FTWLogLines) CheckLogForMarker(stageID string, readLimit uint) []byte
if bytes.Contains(line, stageIDBytes) {
return line
}

log.Debug().Msgf("found unexpected marker line while looking for %s: %s", stageID, line)
return nil
}
44 changes: 25 additions & 19 deletions waflog/read_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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]))
Expand Down Expand Up @@ -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]))
Expand All @@ -201,12 +201,15 @@ func (s *readTestSuite) TestFTWLogLines_Contains() {
s.NotNil(cfg)

stageID := "dead-beaf-deadbeef-deadbeef-dead"
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
stageID := "dead-beaf-deadbeef-deadbeef-dead"
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)

Expand All @@ -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 {
Expand Down Expand Up @@ -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)

Expand All @@ -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 {
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -368,12 +373,13 @@ func (s *readTestSuite) TestFindAllIdsInLogs() {
s.NotNil(cfg)

stageID := "dead-beaf-deadbeef-deadbeef-dead"
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
stageID := "dead-beaf-deadbeef-deadbeef-dead"
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
Expand All @@ -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)
Expand Down
Loading