Merge pull request #20 from fzipi/fix-nginx-time-comparision

Fix nginx time comparision

README.md

@@ -46,13 +46,16 @@ logtype:
   timeformat: '%a %b %d %H:%M:%S.%f %Y'
 ```
 
+For nginx, as logs will be to the second, you need to add the amount of time you want to truncate to. This will for example discard anything less than one second:
+
 ```yaml
 ---
 logfile: '../coreruleset/tests/logs/modsec3-nginx/nginx/error.log'
 logtype:
   name: 'nginx'
   timeregex:  '(\d{4}\/\d{2}\/\d{2} \d{2}:\d{2}:\d{2})'
   timeformat: 'YYYY/MM/DD HH:mm:ss'
+  timetruncate: 1s
 ```
 
 If your webserver uses a different time format, please [create an issue](https://github.com/fzipi/go-ftw/issues/new/choose) and we can extend the documentation to cover it.

check/base.go

@@ -6,6 +6,7 @@ import (
 	"github.com/fzipi/go-ftw/config"
 	"github.com/fzipi/go-ftw/test"
 	"github.com/fzipi/go-ftw/waflog"
+	"github.com/rs/zerolog/log"
 )
 
 // FTWCheck is the base struct for checks
@@ -18,15 +19,17 @@ type FTWCheck struct {
 func NewCheck(c *config.FTWConfiguration) *FTWCheck {
 	check := &FTWCheck{
 		log: &waflog.FTWLogLines{
-			FileName:   c.LogFile,
-			TimeRegex:  c.LogType.TimeRegex,
-			TimeFormat: c.LogType.TimeFormat,
-			Since:      time.Now(),
-			Until:      time.Now(),
+			FileName:     c.LogFile,
+			TimeRegex:    c.LogType.TimeRegex,
+			TimeFormat:   c.LogType.TimeFormat,
+			Since:        time.Now(),
+			Until:        time.Now(),
+			TimeTruncate: c.LogType.TimeTruncate,
 		},
 		expected: &test.Output{},
 	}
 
+	log.Trace().Msgf("check/base: truncate set to %s", check.log.TimeTruncate)
 	return check
 }
 

check/base_test.go

@@ -1,5 +1,12 @@
 package check
 
+import (
+	"testing"
+	"time"
+
+	"github.com/fzipi/go-ftw/config"
+)
+
 var yamlApacheConfig = `
 ---
 logfile: 'tests/logs/modsec2-apache/apache2/error.log'
@@ -16,4 +23,15 @@ logtype:
   name: 'nginx'
   timeregex:  '(\d{4}\/\d{2}\/\d{2} \d{2}:\d{2}:\d{2})'
   timeformat: 'YYYY/MM/DD HH:mm:ss'
+  timetruncate: 1s
 `
+
+func TestNewCheck(t *testing.T) {
+	config.ImportFromString(yamlNginxConfig)
+
+	c := NewCheck(config.FTWConfig)
+
+	if c.log.TimeTruncate != time.Second {
+		t.Errorf("Failed")
+	}
+}

check/logs.go

@@ -12,6 +12,7 @@ func (c *FTWCheck) AssertNoLogContains() bool {
 
 // AssertLogContains returns true when the logs contain the string
 func (c *FTWCheck) AssertLogContains() bool {
+	log.Trace().Msgf("ftw/check: check will truncate at %s", c.log.TimeTruncate)
 	if c.expected.LogContains != "" {
 		log.Debug().Msgf("ftw/check: log contains? -> %s", c.expected.LogContains)
 		return c.log.Contains(c.expected.LogContains)

config/config.go

@@ -1,17 +1,24 @@
 package config
 
+import (
+	"time"
+)
+
 // FTWConfig is being exported to be used across the app
 var FTWConfig *FTWConfiguration
 
 // FTWConfiguration FTW global Configuration
 type FTWConfiguration struct {
-	LogFile string     `yaml:"logfile"`
-	LogType FTWLogType `yaml:"logtype"`
+	LogFile string
+	LogType FTWLogType
 }
 
 // FTWLogType log readers must implement this one
+// TimeTruncate is a string that represents a golang time, e.g. 'time.Microsecond', 'time.Second', etc.
+// It will be used when comparing times to match logs
 type FTWLogType struct {
-	Name       string `yaml:"name"`
-	TimeRegex  string `yaml:"timeregex"`
-	TimeFormat string `yaml:"timeformat"`
+	Name         string
+	TimeRegex    string
+	TimeFormat   string
+	TimeTruncate time.Duration
 }

config/config_test.go

@@ -2,7 +2,9 @@ package config
 
 import (
 	"io/ioutil"
+	"os"
 	"testing"
+	"time"
 
 	"github.com/fzipi/go-ftw/utils"
 )
@@ -25,6 +27,16 @@ logtype:
   timeformat: 'ddd MMM DD HH:mm:ss.S YYYY'
 `
 
+var yamlTruncateConfig = `
+---
+logfile: 'tests/logs/modsec3-nginx/nginx/error.log'
+logtype:
+  name: nginx
+  timetruncate:  1s
+  timeformat: 'ddd MMM DD HH:mm:ss'
+
+`
+
 var jsonConfig = `
 {"test": "type"}
 `
@@ -45,13 +57,13 @@ func TestInitConfig(t *testing.T) {
 
 func TestInitBadFileConfig(t *testing.T) {
 	filename, _ := utils.CreateTempFileWithContent(jsonConfig, "test-*.yaml")
-
+	defer os.Remove(filename)
 	Init(filename)
 }
 
 func TestInitBadConfig(t *testing.T) {
 	filename, _ := utils.CreateTempFileWithContent(yamlBadConfig, "test-*.yaml")
-
+	defer os.Remove(filename)
 	Init(filename)
 
 	if FTWConfig == nil {
@@ -81,3 +93,21 @@ func TestImportConfig(t *testing.T) {
 		t.Errorf("Failed !")
 	}
 }
+
+func TestTimeTruncateConfig(t *testing.T) {
+	filename, _ := utils.CreateTempFileWithContent(yamlTruncateConfig, "test-*.yaml")
+	defer os.Remove(filename)
+	Init(filename)
+
+	if FTWConfig.LogType.Name != "nginx" {
+		t.Errorf("Failed !")
+	}
+
+	if FTWConfig.LogType.TimeFormat != "ddd MMM DD HH:mm:ss" {
+		t.Errorf("Failed !")
+	}
+
+	if FTWConfig.LogType.TimeTruncate != time.Second {
+		t.Errorf("Failed !")
+	}
+}

config/init.go

@@ -31,6 +31,11 @@ func Init(cfgFile string) {
 	if err != nil {
 		log.Fatal().Msgf("ftw/config: fatal error decoding config: %s", err.Error())
 	}
+	if duration := viper.GetDuration("logtype.timetruncate"); duration != 0 {
+		log.Info().Msgf("ftw/config: will truncate logs to %s", duration)
+	} else {
+		log.Info().Msgf("ftw/config: no duration found")
+	}
 }
 
 // ImportFromString initializes the configuration from a yaml formatted string. Useful for testing.

waflog/base.go

@@ -11,6 +11,9 @@ type FTWLogLines struct {
 	TimeRegex string
 	// Gostradamus time format, e.g. 'ddd MMM DD HH:mm:ss.S YYYY'
 	TimeFormat string
-	Since      time.Time
-	Until      time.Time
+	// Truncate time to this time.Duration. Example is nginx logs will be up to the second,
+	// so you want to truncate using '1s'.
+	TimeTruncate time.Duration
+	Since        time.Time
+	Until        time.Time
 }

waflog/read.go

@@ -13,10 +13,11 @@ import (
 
 // Contains looks in logfile for regex
 func (ll *FTWLogLines) Contains(match string) bool {
-	log.Debug().Msgf("ftw/waflog: Looking at file %s, between %s and %s", ll.FileName, ll.Since, ll.Until)
+	log.Trace().Msgf("ftw/waflog: truncating at %s", ll.TimeTruncate)
+	log.Trace().Msgf("ftw/waflog: Looking at file %s, between %s and %s, truncating on %s", ll.FileName, ll.Since, ll.Until, ll.TimeTruncate.String())
 	// this should be a flag
 	lines := ll.getLinesSinceUntil()
-	log.Debug().Msgf("ftw/waflog: got %d lines", len(lines))
+	log.Trace().Msgf("ftw/waflog: got %d lines", len(lines))
 
 	result := false
 	for _, line := range lines {
@@ -34,6 +35,28 @@ func (ll *FTWLogLines) Contains(match string) bool {
 	return result
 }
 
+func isBetweenOrEqual(dt gostradamus.DateTime, start gostradamus.DateTime, end gostradamus.DateTime, duration time.Duration) bool {
+	log.Trace().Msgf("ftw/waflog: truncating to %s", duration)
+	// First check if we need to truncate times
+	dtTime := dt.Time().Truncate(duration)
+	startTime := start.Time().Truncate(duration)
+	endTime := end.Time().Truncate(duration)
+
+	isBetween := dtTime.After(startTime) && dtTime.Before(endTime)
+	log.Trace().Msgf("ftw/waflog: time %s is between %s and %s? %t", dtTime,
+		startTime, endTime, isBetween)
+
+	isEqualStart := dtTime.Equal(startTime)
+	log.Trace().Msgf("ftw/waflog: time %s is equal to %s ? %t", dtTime,
+		startTime, isEqualStart)
+
+	isEqualEnd := dtTime.Equal(endTime)
+	log.Trace().Msgf("ftw/waflog: time %s is equal to %s ? %t", dtTime,
+		startTime, isEqualEnd)
+
+	return isBetween || isEqualStart || isEqualEnd
+}
+
 func (ll *FTWLogLines) getLinesSinceUntil() [][]byte {
 	var found [][]byte
 	logfile, err := os.Open(ll.FileName)
@@ -60,30 +83,39 @@ func (ll *FTWLogLines) getLinesSinceUntil() [][]byte {
 		line, _, err := scanner.LineBytes()
 		if err != nil {
 			if err == io.EOF {
-				log.Debug().Msgf("got to the beginning of file")
+				log.Trace().Msgf("got to the beginning of file")
 			} else {
 				log.Debug().Err(err)
 			}
 			break
 		}
 		if matchedLine := compiledRegex.FindSubmatch(line); matchedLine != nil {
 			date := matchedLine[1]
+			log.Trace().Msgf("ftw/waflog: matched %s in line %s", date, matchedLine)
 			// well, go doesn't want to have a proper time format, so we need to use gostradamus
 			t, err := gostradamus.Parse(string(date), ll.TimeFormat)
 			if err != nil {
-				log.Error().Msgf("ftw/waflog: %s", err.Error())
+				log.Error().Msgf("ftw/waflog: error parsing date %s", err.Error())
 				// return with what we got up to now
 				break
 			}
 			// compare dates now
-			if t.IsBetween(gostradamus.DateTimeFromTime(ll.Since), gostradamus.DateTimeFromTime(ll.Until)) {
+			since := gostradamus.DateTimeFromTime(ll.Since).InTimezone(gostradamus.Local())
+			until := gostradamus.DateTimeFromTime(ll.Until).InTimezone(gostradamus.Local())
+			// Comparision will need to truncate
+			if isBetweenOrEqual(t, since, until, ll.TimeTruncate) {
 				saneCopy := make([]byte, len(line))
 				copy(saneCopy, line)
 				found = append(found, saneCopy)
 				continue
+			} else {
+				log.Trace().Msgf("ftw/waflog: time %s is not between %s and %s", t.Time(),
+					since.Format(ll.TimeFormat),
+					until.Format(ll.TimeFormat))
 			}
 			// if we are before since, we need to stop searching
-			if t.IsBetween(gostradamus.DateTimeFromTime(time.Time{}), gostradamus.DateTimeFromTime(ll.Since)) {
+			if t.IsBetween(gostradamus.DateTimeFromTime(time.Time{}).InTimezone(gostradamus.Local()),
+				since) {
 				break
 			}
 		}