fix: properly handle multiple IDs in positive log match (#298)

The implementation for positive match of a list of IDs only required a
single ID to match instead of all.

This commit also introduces memoization to minimize IO when searching
the log.

Also fixed pre-commit config.

.pre-commit-config.yaml

@@ -14,21 +14,6 @@ repos:
       name: go-cyclo
       alias: go-cyclo
       args: [ gocyclo, -over=15]
-    - id: my-cmd
-      name: "Check files aren't using go's testing package"
-      entry: 'testing\.T'
-      files: 'test_.*\.go$'
-      language: 'pygrep'
-      description: >
-        Checks that no files are using `testing.T`, if you want developers to use
-        a different testing framework
-    - id: my-cmd
-      name: 'validate toml'
-      entry: 'tomlv'
-      files: '\.toml$'
-      language: 'system'
-      description: >
-        Runs `tomlv`, requires https://github.com/BurntSushi/toml/tree/master/cmd/tomlv"
 - repo: https://github.com/gitleaks/gitleaks
   rev: v8.18.1
   hooks:

check/base.go

@@ -4,9 +4,8 @@
 package check
 
 import (
-	"bytes"
-
 	schema "github.com/coreruleset/ftw-tests-schema/types"
+
 	"github.com/coreruleset/go-ftw/config"
 	"github.com/coreruleset/go-ftw/test"
 	"github.com/coreruleset/go-ftw/waflog"
@@ -105,10 +104,10 @@ func (c *FTWCheck) CloudMode() bool {
 
 // SetStartMarker sets the log line that marks the start of the logs to analyze
 func (c *FTWCheck) SetStartMarker(marker []byte) {
-	c.log.StartMarker = bytes.ToLower(marker)
+	c.log.WithStartMarker(marker)
 }
 
 // SetEndMarker sets the log line that marks the end of the logs to analyze
 func (c *FTWCheck) SetEndMarker(marker []byte) {
-	c.log.EndMarker = bytes.ToLower(marker)
+	c.log.WithEndMarker(marker)
 }

check/base_test.go

@@ -6,9 +6,9 @@ package check
 import (
 	"testing"
 
+	schema "github.com/coreruleset/ftw-tests-schema/types"
 	"github.com/stretchr/testify/suite"
 
-	schema "github.com/coreruleset/ftw-tests-schema/types"
 	"github.com/coreruleset/go-ftw/config"
 	"github.com/coreruleset/go-ftw/test"
 	"github.com/coreruleset/go-ftw/utils"
@@ -101,6 +101,6 @@ func (s *checkBaseTestSuite) TestSetMarkers() {
 
 	c.SetStartMarker([]byte("TesTingStArtMarKer"))
 	c.SetEndMarker([]byte("TestIngEnDMarkeR"))
-	s.Equal([]byte("testingstartmarker"), c.log.StartMarker, "Couldn't set start marker")
-	s.Equal([]byte("testingendmarker"), c.log.EndMarker, "Couldn't set end marker")
+	s.Equal("testingstartmarker", string(c.log.StartMarker()), "Couldn't set start marker")
+	s.Equal("testingendmarker", string(c.log.EndMarker()), "Couldn't set end marker")
 }

check/logs.go

@@ -4,9 +4,6 @@
 package check
 
 import (
-	"fmt"
-	"strings"
-
 	"github.com/rs/zerolog/log"
 )
 
@@ -24,15 +21,16 @@ func (c *FTWCheck) assertNoLogContains() bool {
 	logExpectations := c.expected.Log
 	result := true
 	if logExpectations.NoMatchRegex != "" {
-		result = !c.log.Contains(logExpectations.NoMatchRegex)
+		result = !c.log.MatchesRegex(logExpectations.NoMatchRegex)
 		if !result {
 			log.Debug().Msgf("Unexpectedly found match for '%s'", logExpectations.NoMatchRegex)
 		}
 	}
 	if result && len(logExpectations.NoExpectIds) > 0 {
-		result = !c.log.Contains(generateIdRegex(logExpectations.NoExpectIds))
-		if !result {
-			log.Debug().Msg("Unexpectedly found IDs")
+		found, foundRules := c.log.ContainsAnyId(logExpectations.NoExpectIds)
+		if found {
+			log.Debug().Msgf("Unexpectedly found the following IDs in the log: %v", foundRules)
+			result = false
 		}
 	}
 	return result
@@ -43,36 +41,18 @@ func (c *FTWCheck) assertLogContains() bool {
 	logExpectations := c.expected.Log
 	result := true
 	if logExpectations.MatchRegex != "" {
-		result = c.log.Contains(logExpectations.MatchRegex)
+		result = c.log.MatchesRegex(logExpectations.MatchRegex)
 		if !result {
 			log.Debug().Msgf("Failed to find match for match_regex. Expected to find '%s'", logExpectations.MatchRegex)
 		}
 	}
 	if result && len(logExpectations.ExpectIds) > 0 {
-		result = c.log.Contains(generateIdRegex(logExpectations.ExpectIds))
-		if !result {
-			log.Debug().Msg("Failed to find expected IDs")
+		found, missedRules := c.log.ContainsAllIds(logExpectations.ExpectIds)
+		if !found {
+			log.Debug().Msgf("Failed to find the following IDs in the log: %v", missedRules)
+			result = false
 		}
 	}
-	return result
-}
 
-// Search for both standard ModSecurity, and JSON output
-func generateIdRegex(ids []uint) string {
-	modSecLogSyntax := strings.Builder{}
-	jsonLogSyntax := strings.Builder{}
-	modSecLogSyntax.WriteString(`\[id "(?:`)
-	jsonLogSyntax.WriteString(`"id":\s*"?(?:`)
-	for index, id := range ids {
-		if index > 0 {
-			modSecLogSyntax.WriteRune('|')
-			jsonLogSyntax.WriteRune('|')
-		}
-		modSecLogSyntax.WriteString(fmt.Sprint(id))
-		jsonLogSyntax.WriteString(fmt.Sprint(id))
-	}
-	modSecLogSyntax.WriteString(`)"\]`)
-	jsonLogSyntax.WriteString(`)"?`)
-
-	return modSecLogSyntax.String() + "|" + jsonLogSyntax.String()
+	return result
 }

check/logs_test.go

@@ -7,6 +7,7 @@ import (
 	"os"
 	"testing"
 
+	"github.com/google/uuid"
 	"github.com/stretchr/testify/suite"
 
 	"github.com/coreruleset/go-ftw/config"
@@ -23,6 +24,7 @@ type checkLogsTestSuite struct {
 	suite.Suite
 	cfg     *config.FTWConfiguration
 	logName string
+	check   *FTWCheck
 }
 
 func TestCheckLogsTestSuite(t *testing.T) {
@@ -36,6 +38,15 @@ func (s *checkLogsTestSuite) SetupTest() {
 	s.logName, err = utils.CreateTempFileWithContent(logText, "test-*.log")
 	s.Require().NoError(err)
 	s.cfg.WithLogfile(s.logName)
+
+	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()))
 }
 
 func (s *checkLogsTestSuite) TearDownTest() {
@@ -44,85 +55,99 @@ func (s *checkLogsTestSuite) TearDownTest() {
 }
 
 func (s *checkLogsTestSuite) TestLogContains() {
-	c, err := NewCheck(s.cfg)
-	s.Require().NoError(err)
+	s.check.SetLogContains(`id "920300"`)
+	s.True(s.check.AssertLogs(), "did not find expected content 'id \"920300\"'")
 
-	c.SetLogContains(`id "920300"`)
-	s.True(c.AssertLogs(), "did not find expected content 'id \"920300\"'")
+	s.check.SetLogContains(`SOMETHING`)
+	s.False(s.check.AssertLogs(), "found something that is not there")
 
-	c.SetLogContains(`SOMETHING`)
-	s.False(c.AssertLogs(), "found something that is not there")
-
-	c.SetLogContains("")
-	s.True(c.AssertLogs(), "empty LogContains should return true")
+	s.check.SetLogContains("")
+	s.True(s.check.AssertLogs(), "empty LogContains should return true")
 }
 
 func (s *checkLogsTestSuite) TestNoLogContains() {
-	c, err := NewCheck(s.cfg)
-	s.Require().NoError(err)
-
-	c.SetNoLogContains(`id "920300"`)
-	s.False(c.AssertLogs(), "did not find expected content")
+	s.check.SetNoLogContains(`id "920300"`)
+	s.False(s.check.AssertLogs(), "did not find expected content")
 
-	c.SetNoLogContains("SOMETHING")
-	s.True(c.AssertLogs(), "found something that is not there")
+	s.check.SetNoLogContains("SOMETHING")
+	s.True(s.check.AssertLogs(), "found something that is not there")
 
-	c.SetNoLogContains("")
-	s.True(c.AssertLogs(), "should return true when empty string is passed")
+	s.check.SetNoLogContains("")
+	s.True(s.check.AssertLogs(), "should return true when empty string is passed")
 }
 
 func (s *checkLogsTestSuite) TestAssertLogMatchRegex() {
-	c, err := NewCheck(s.cfg)
-	s.Require().NoError(err)
-
-	c.expected.Log.MatchRegex = `id\s"920300"`
-	s.True(c.AssertLogs(), `did not find expected content 'id\s"920300"'`)
+	s.check.expected.Log.MatchRegex = `id\s"920300"`
+	s.True(s.check.AssertLogs(), `did not find expected content 'id\s"920300"'`)
 
-	c.expected.Log.MatchRegex = `SOMETHING`
-	s.False(c.AssertLogs(), "found something that is not there")
+	s.check.expected.Log.MatchRegex = `SOMETHING`
+	s.False(s.check.AssertLogs(), "found something that is not there")
 
-	c.expected.Log.MatchRegex = ""
-	s.True(c.AssertLogs(), "empty LogContains should return true")
+	s.check.expected.Log.MatchRegex = ""
+	s.True(s.check.AssertLogs(), "empty LogContains should return true")
 }
 
 func (s *checkLogsTestSuite) TestAssertLogNoMatchRegex() {
-	c, err := NewCheck(s.cfg)
-	s.Require().NoError(err)
+	s.check.expected.Log.NoMatchRegex = `id\s"920300"`
+	s.False(s.check.AssertLogs(), `expected to find 'id\s"920300"'`)
 
-	c.expected.Log.NoMatchRegex = `id\s"920300"`
-	s.False(c.AssertLogs(), `expected to find 'id\s"920300"'`)
+	s.check.expected.Log.NoMatchRegex = `SOMETHING`
+	s.True(s.check.AssertLogs(), "expected to _not_ find SOMETHING")
 
-	c.expected.Log.NoMatchRegex = `SOMETHING`
-	s.True(c.AssertLogs(), "expected to _not_ find SOMETHING")
-
-	c.expected.Log.NoMatchRegex = ""
-	s.True(c.AssertLogs(), "empty LogContains should return true")
+	s.check.expected.Log.NoMatchRegex = ""
+	s.True(s.check.AssertLogs(), "empty LogContains should return true")
 }
 
 func (s *checkLogsTestSuite) TestAssertLogExpectIds() {
-	c, err := NewCheck(s.cfg)
-	s.Require().NoError(err)
-
-	c.expected.Log.ExpectIds = []uint{920300}
-	s.True(c.AssertLogs(), `did not find expected content 'id\s"920300"'`)
+	s.check.expected.Log.ExpectIds = []uint{920300}
+	s.True(s.check.AssertLogs(), `did not find expected content 'id\s"920300"'`)
 
-	c.expected.Log.ExpectIds = []uint{123456}
-	s.False(c.AssertLogs(), "found something that is not there")
+	s.check.expected.Log.ExpectIds = []uint{123456}
+	s.False(s.check.AssertLogs(), "found something that is not there")
 
-	c.expected.Log.ExpectIds = []uint{}
-	s.True(c.AssertLogs(), "empty LogContains should return true")
+	s.check.expected.Log.ExpectIds = []uint{}
+	s.True(s.check.AssertLogs(), "empty LogContains should return true")
 }
 
 func (s *checkLogsTestSuite) TestAssertLogNoExpectId() {
-	c, err := NewCheck(s.cfg)
-	s.Require().NoError(err)
+	s.check.expected.Log.NoExpectIds = []uint{920300}
+	s.False(s.check.AssertLogs(), `expected to find 'id\s"920300"'`)
+
+	s.check.expected.Log.NoExpectIds = []uint{123456}
+	s.True(s.check.AssertLogs(), "expected to _not_ find SOMETHING")
+
+	s.check.expected.Log.NoExpectIds = []uint{}
+	s.True(s.check.AssertLogs(), "empty LogContains should return true")
+}
+
+func (s *checkLogsTestSuite) TestAssertLogExpectIds_Multiple() {
+	s.check.expected.Log.ExpectIds = []uint{920300}
+	s.True(s.check.AssertLogs(), "Expected to find '920300'")
+
+	s.check.expected.Log.ExpectIds = []uint{920300, 949110}
+	s.True(s.check.AssertLogs(), "Expected to find all IDs")
+}
+
+func (s *checkLogsTestSuite) TestAssertLogExpectIds_Subset() {
+	s.check.expected.Log.ExpectIds = []uint{920300}
+	s.True(s.check.AssertLogs(), "Expected to find '920300'")
+
+	s.check.expected.Log.ExpectIds = []uint{920300, 123}
+	s.False(s.check.AssertLogs(), "Did not expect to find '123'")
+}
+
+func (s *checkLogsTestSuite) TestAssertLogNoExpectIds_Multiple() {
+	s.check.expected.Log.NoExpectIds = []uint{123}
+	s.True(s.check.AssertLogs(), "Did not expect to find '123'")
 
-	c.expected.Log.NoExpectIds = []uint{920300}
-	s.False(c.AssertLogs(), `expected to find 'id\s"920300"'`)
+	s.check.expected.Log.NoExpectIds = []uint{123, 456}
+	s.True(s.check.AssertLogs(), "Did not expect to find any of the IDs")
+}
 
-	c.expected.Log.NoExpectIds = []uint{123456}
-	s.True(c.AssertLogs(), "expected to _not_ find SOMETHING")
+func (s *checkLogsTestSuite) TestAssertLogNoExpectIds_Subset() {
+	s.check.expected.Log.NoExpectIds = []uint{123}
+	s.True(s.check.AssertLogs(), "Did not expect to find '123'")
 
-	c.expected.Log.NoExpectIds = []uint{}
-	s.True(c.AssertLogs(), "empty LogContains should return true")
+	s.check.expected.Log.NoExpectIds = []uint{123, 920300}
+	s.False(s.check.AssertLogs(), "Expected to find '920300'")
 }

check/status_test.go

@@ -4,9 +4,10 @@
 package check
 
 import (
-	"slices"
 	"testing"
 
+	"slices"
+
 	"github.com/stretchr/testify/suite"
 
 	"github.com/coreruleset/go-ftw/config"

config/types.go

@@ -8,6 +8,7 @@ import (
 	"regexp"
 
 	schema "github.com/coreruleset/ftw-tests-schema/types/overrides"
+
 	"github.com/coreruleset/go-ftw/ftwhttp"
 )
 

ftwhttp/client.go

@@ -13,10 +13,9 @@ import (
 	"strings"
 	"time"
 
-	"golang.org/x/time/rate"
-
 	"github.com/rs/zerolog/log"
 	"golang.org/x/net/publicsuffix"
+	"golang.org/x/time/rate"
 )
 
 // NewClientConfig returns a new ClientConfig with reasonable defaults.

ftwhttp/client_test.go

@@ -11,9 +11,8 @@ import (
 	"testing"
 	"time"
 
-	"golang.org/x/time/rate"
-
 	"github.com/stretchr/testify/suite"
+	"golang.org/x/time/rate"
 )
 
 const (

go.sum

@@ -62,8 +62,6 @@ github.com/knadh/koanf/providers/rawbytes v0.1.0 h1:dpzgu2KO6uf6oCb4aP05KDmKmAmI
 github.com/knadh/koanf/providers/rawbytes v0.1.0/go.mod h1:mMTB1/IcJ/yE++A2iEZbY1MLygX7vttU+C+S/YmPu9c=
 github.com/knadh/koanf/v2 v2.1.1 h1:/R8eXqasSTsmDCsAyYj+81Wteg8AqrV9CP6gvsTsOmM=
 github.com/knadh/koanf/v2 v2.1.1/go.mod h1:4mnTRbZCK+ALuBXHZMjDfG9y714L7TykVnZkXbMU3Es=
-github.com/kyokomi/emoji/v2 v2.2.12 h1:sSVA5nH9ebR3Zji1o31wu3yOwD1zKXQA2z0zUyeit60=
-github.com/kyokomi/emoji/v2 v2.2.12/go.mod h1:JUcn42DTdsXJo1SWanHh4HKDEyPaR5CqkmoirZZP9qE=
 github.com/kyokomi/emoji/v2 v2.2.13 h1:GhTfQa67venUUvmleTNFnb+bi7S3aocF7ZCXU9fSO7U=
 github.com/kyokomi/emoji/v2 v2.2.13/go.mod h1:JUcn42DTdsXJo1SWanHh4HKDEyPaR5CqkmoirZZP9qE=
 github.com/leodido/go-urn v1.2.0 h1:hpXL4XnriNwQ/ABnpepYM/1vCLWNDfUNts8dX3xTG6Y=