Merge lp:~axwalk/juju-core/logmatches-inexact into lp:~go-bot/juju-core/trunk

[Andrew Wilkins]

testing/checkers: make LogMatches inexact

In the rare case that we want to check log messages,
we want to check a particular message has been logged,
not check the entirety of the log. This allows for
changes (unrelated additions/removals) in logging
without affecting tests.

https://codereview.appspot.com/14430064/

testing/checkers: make LogMatches inexact

In the rare case that we want to check log messages,
we want to check a particular message has been logged,
not check the entirety of the log. This allows for
changes (unrelated additions/removals) in logging
without affecting tests.

https://codereview.appspot.com/14430064/

[Andrew Wilkins (axwalk)]

Reviewers: mp+191092_code.launchpad.net,

Message:
Please take a look.

Description:
testing/checkers: make LogMatches inexact

In the rare case that we want to check log messages,
we want to check a particular message has been logged,
not check the entirety of the log. This allows for
changes (unrelated additions/removals) in logging
without affecting tests.

https://code.launchpad.net/~axwalk/juju-core/logmatches-inexact/+merge/191092

(do not edit description out of merge proposal)

Please review this at https://codereview.appspot.com/14430064/

Affected files (+55, -30 lines):
   A [revision details]
   M testing/checkers/log.go
   M testing/checkers/log_test.go

Index: [revision details]
=== added file '[revision details]'
--- [revision details] 2012-01-01 00:00:00 +0000
+++ [revision details] 2012-01-01 00:00:00 +0000
@@ -0,0 +1,2 @@
+Old revision: tarmac-20131014040553-f18jp0xnxw45qkt2
+New revision: <email address hidden>

Index: testing/checkers/log.go
=== modified file 'testing/checkers/log.go'
--- testing/checkers/log.go 2013-10-01 16:46:31 +0000
+++ testing/checkers/log.go 2013-10-15 02:36:40 +0000
@@ -36,41 +36,38 @@
   default:
    return false, "Obtained value must be of type []loggo.TestLogValues or
SimpleMessage"
   }
- switch params[1].(type) {
+
+ var expected []SimpleMessage
+ switch param := params[1].(type) {
   case []SimpleMessage:
- expected := params[1].([]SimpleMessage)
- if len(obtained) != len(expected) {
- return false, ""
- }
- for i := 0; i < len(obtained); i++ {
- if obtained[i].Level != expected[i].Level {
- return false, ""
- }
- re := regexp.MustCompile(expected[i].Message)
- if !re.MatchString(obtained[i].Message) {
- return false, ""
- }
- }
- return true, ""
+ expected = param
   case []string:
- asString := make([]string, len(obtained))
- for i, val := range obtained {
- asString[i] = val.Message
- }
- expected := params[1].([]string)
- if len(obtained) != len(expected) {
- return false, ""
- }
- for i := 0; i < len(obtained); i++ {
- re := regexp.MustCompile(expected[i])
- if !re.MatchString(obtained[i].Message) {
- return false, ""
- }
- }
- return true, ""
+ expected = make([]SimpleMessage, len(param))
+ for i, s := range param {
+ expected[i].Message = s
+ }
   default:
    return false, "Expected value must be of type []string or
[]SimpleMessage"
   }
+
+ for len(expected) > 0 && len(obtained) >= len(expected) {
+ var msg SimpleMessage
+ msg, obtained = obtained[0], obtained[1:]
+ if expected[0].Level != loggo.UNSPECIFIED {
+ if msg.Level != expected[0].Level {
+ continue
+ }
+ }
+ re := regexp.MustCompile(expected[0].Message)
+ if !re.MatchString(msg.Message) {
+ continue
+ }
+ expected = expected[1:]
+ }
+ if len(obtained) < len(expected) {
+ return false, ""
+ }
+ return true, ""
  }

  // LogMatches checks whether a given TestLogValues actually contains the
log
@@ -78,6 +75,10 @@
  // compare that the strings in the messages are correct. You can
alternatively
  // pass a slice of SimpleMessage and we will check that the log levels are
  // also correct.
+//
+// The log may conta...

[Roger Peppe (rogpeppe)]

Great stuff - you beat me to it!

LGTM modulo the below suggestions and remarks.

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go
File testing/checkers/log.go (right):

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go#newcode47
testing/checkers/log.go:47: expected[i].Message = s
I think I'd like to see Level set explicitly to
UNSPECIFIED here, so that I don't need to
check to see if it's zero when checking
the logic below.

Perhaps:
expected[i] = SimpleMessage{
     Message: s,
     Level: loggo.UNSPECIFIED,
}

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go#newcode56
testing/checkers/log.go:56: if expected[0].Level != loggo.UNSPECIFIED {
expect := expected[0]
if expect.Level != loggo.UNSPECIFIED && msg.Level != expect.Level {
     continue
}

might possibly read slightly better?
and then you can use expect rather than expected[0]
in a few places below too.

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go#newcode61
testing/checkers/log.go:61: re :=
regexp.MustCompile(expected[0].Message)
I'm not sure we really want to panic if someone gets a pattern
wrong in the expected log messages.

How about:

ok, err := regexp.MatchString(expected[0].Message, msg.Message)
if err != nil {
     return false, "bad message regexp %q: %v", expected[0].Message, err)
}
if !ok {
     continue
}

?

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go#newcode80
testing/checkers/log.go:80: // expected messages; the specified messages
will be matched to the left-most
I think you can lose the part after the semicolon - the semantics are
the same whether it's leftmost or rightmost match or anything in
between, aren't they?

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log_test.go
File testing/checkers/log_test.go (right):

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log_test.go#newcode65
testing/checkers/log_test.go:65: c.Check(log, gc.Not(jc.LogMatches),
[]string{"67890", ".*"})
I'd like to see at least one test that tests log level matching in an
inexact context.

Also, perhaps a test that checks that {".*", "foo bar"} doesn't match.

https://codereview.appspot.com/14430064/

[Andrew Wilkins (axwalk)]

Please take a look.

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go
File testing/checkers/log.go (right):

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go#newcode47
testing/checkers/log.go:47: expected[i].Message = s
On 2013/10/15 08:54:04, rog wrote:
> I think I'd like to see Level set explicitly to
> UNSPECIFIED here, so that I don't need to
> check to see if it's zero when checking
> the logic below.

> Perhaps:
> expected[i] = SimpleMessage{
> Message: s,
> Level: loggo.UNSPECIFIED,
> }

Done.

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go#newcode56
testing/checkers/log.go:56: if expected[0].Level != loggo.UNSPECIFIED {
On 2013/10/15 08:54:04, rog wrote:
> expect := expected[0]
> if expect.Level != loggo.UNSPECIFIED && msg.Level != expect.Level {
> continue
> }

> might possibly read slightly better?
> and then you can use expect rather than expected[0]
> in a few places below too.

Done.

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go#newcode61
testing/checkers/log.go:61: re :=
regexp.MustCompile(expected[0].Message)
On 2013/10/15 08:54:04, rog wrote:
> I'm not sure we really want to panic if someone gets a pattern
> wrong in the expected log messages.

> How about:

> ok, err := regexp.MatchString(expected[0].Message, msg.Message)
> if err != nil {
> return false, "bad message regexp %q: %v", expected[0].Message,
err)
> }
> if !ok {
> continue
> }

> ?

Done.

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log.go#newcode80
testing/checkers/log.go:80: // expected messages; the specified messages
will be matched to the left-most
On 2013/10/15 08:54:04, rog wrote:
> I think you can lose the part after the semicolon - the semantics are
the same
> whether it's leftmost or rightmost match or anything in between,
aren't they?

Indeed, I didn't think that through properly. Removed, thanks.

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log_test.go
File testing/checkers/log_test.go (right):

https://codereview.appspot.com/14430064/diff/1/testing/checkers/log_test.go#newcode65
testing/checkers/log_test.go:65: c.Check(log, gc.Not(jc.LogMatches),
[]string{"67890", ".*"})
On 2013/10/15 08:54:04, rog wrote:
> I'd like to see at least one test that tests log level matching in an
inexact
> context.

> Also, perhaps a test that checks that {".*", "foo bar"} doesn't match.

Done.

https://codereview.appspot.com/14430064/

=== modified file 'testing/checkers/log.go'
--- testing/checkers/log.go	2013-10-01 16:46:31 +0000
+++ testing/checkers/log.go	2013-10-16 02:08:15 +0000
@@ -4,6 +4,7 @@
 package checkers
 
 import (
+	"fmt"
 	"regexp"
 
 	gc "launchpad.net/gocheck"
@@ -36,41 +37,42 @@
 	default:
 		return false, "Obtained value must be of type []loggo.TestLogValues or SimpleMessage"
 	}
-	switch params[1].(type) {
+
+	var expected []SimpleMessage
+	switch param := params[1].(type) {
 	case []SimpleMessage:
-		expected := params[1].([]SimpleMessage)
-		if len(obtained) != len(expected) {
-			return false, ""
-		}
-		for i := 0; i < len(obtained); i++ {
-			if obtained[i].Level != expected[i].Level {
-				return false, ""
-			}
-			re := regexp.MustCompile(expected[i].Message)
-			if !re.MatchString(obtained[i].Message) {
-				return false, ""
-			}
-		}
-		return true, ""
+		expected = param
 	case []string:
-		asString := make([]string, len(obtained))
-		for i, val := range obtained {
-			asString[i] = val.Message
-		}
-		expected := params[1].([]string)
-		if len(obtained) != len(expected) {
-			return false, ""
-		}
-		for i := 0; i < len(obtained); i++ {
-			re := regexp.MustCompile(expected[i])
-			if !re.MatchString(obtained[i].Message) {
-				return false, ""
+		expected = make([]SimpleMessage, len(param))
+		for i, s := range param {
+			expected[i] = SimpleMessage{
+				Message: s,
+				Level:   loggo.UNSPECIFIED,
 			}
 		}
-		return true, ""
 	default:
 		return false, "Expected value must be of type []string or []SimpleMessage"
 	}
+
+	for len(expected) > 0 && len(obtained) >= len(expected) {
+		var msg SimpleMessage
+		msg, obtained = obtained[0], obtained[1:]
+		expect := expected[0]
+		if expect.Level != loggo.UNSPECIFIED && msg.Level != expect.Level {
+			continue
+		}
+		matched, err := regexp.MatchString(expect.Message, msg.Message)
+		if err != nil {
+			return false, fmt.Sprintf("bad message regexp %q: %v", expect.Message, err)
+		} else if !matched {
+			continue
+		}
+		expected = expected[1:]
+	}
+	if len(obtained) < len(expected) {
+		return false, ""
+	}
+	return true, ""
 }
 
 // LogMatches checks whether a given TestLogValues actually contains the log
@@ -78,6 +80,9 @@
 // compare that the strings in the messages are correct. You can alternatively
 // pass a slice of SimpleMessage and we will check that the log levels are
 // also correct.
+//
+// The log may contain additional messages before and after each of the specified
+// expected messages.
 var LogMatches gc.Checker = &logMatches{
 	&gc.CheckerInfo{Name: "LogMatches", Params: []string{"obtained", "expected"}},
 }

=== modified file 'testing/checkers/log_test.go'
--- testing/checkers/log_test.go	2013-10-01 16:46:31 +0000
+++ testing/checkers/log_test.go	2013-10-16 02:08:15 +0000
@@ -27,6 +27,12 @@
 		{loggo.INFO, "foo .*"},
 		{loggo.INFO, "12345"},
 	})
+	// UNSPECIFIED means we don't care what the level is,
+	// just check the message string matches.
+	c.Check(log, jc.LogMatches, []jc.SimpleMessage{
+		{loggo.UNSPECIFIED, "foo .*"},
+		{loggo.INFO, "12345"},
+	})
 	c.Check(log, gc.Not(jc.LogMatches), []jc.SimpleMessage{
 		{loggo.INFO, "foo bar"},
 		{loggo.DEBUG, "12345"},
@@ -43,6 +49,50 @@
 	c.Check(log, gc.Not(jc.LogMatches), []string{"baz", "bing"})
 }
 
+func (s *LogMatchesSuite) TestMatchInexact(c *gc.C) {
+	log := []loggo.TestLogValues{
+		{Level: loggo.INFO, Message: "foo bar"},
+		{Level: loggo.INFO, Message: "baz"},
+		{Level: loggo.DEBUG, Message: "12345"},
+		{Level: loggo.ERROR, Message: "12345"},
+		{Level: loggo.INFO, Message: "67890"},
+	}
+	c.Check(log, jc.LogMatches, []string{"foo bar", "12345"})
+	c.Check(log, jc.LogMatches, []string{"foo .*", "12345"})
+	c.Check(log, jc.LogMatches, []string{"foo .*", "67890"})
+	c.Check(log, jc.LogMatches, []string{"67890"})
+
+	// Matches are always left-most after the previous match.
+	c.Check(log, jc.LogMatches, []string{".*", "baz"})
+	c.Check(log, jc.LogMatches, []string{"foo bar", ".*", "12345"})
+	c.Check(log, jc.LogMatches, []string{"foo bar", ".*", "67890"})
+
+	// Order is important: 67890 advances to the last item in obtained,
+	// and so there's nothing after to match against ".*".
+	c.Check(log, gc.Not(jc.LogMatches), []string{"67890", ".*"})
+	// ALL specified patterns MUST match in the order given.
+	c.Check(log, gc.Not(jc.LogMatches), []string{".*", "foo bar"})
+
+	// Check that levels are matched.
+	c.Check(log, jc.LogMatches, []jc.SimpleMessage{
+		{loggo.UNSPECIFIED, "12345"},
+		{loggo.UNSPECIFIED, "12345"},
+	})
+	c.Check(log, jc.LogMatches, []jc.SimpleMessage{
+		{loggo.DEBUG, "12345"},
+		{loggo.ERROR, "12345"},
+	})
+	c.Check(log, jc.LogMatches, []jc.SimpleMessage{
+		{loggo.DEBUG, "12345"},
+		{loggo.INFO, ".*"},
+	})
+	c.Check(log, gc.Not(jc.LogMatches), []jc.SimpleMessage{
+		{loggo.DEBUG, "12345"},
+		{loggo.INFO, ".*"},
+		{loggo.UNSPECIFIED, ".*"},
+	})
+}
+
 func (s *LogMatchesSuite) TestFromLogMatches(c *gc.C) {
 	tw := &loggo.TestWriter{}
 	_, err := loggo.ReplaceDefaultWriter(tw)