Merge lp:~jameinel/juju-core/bad-formatting-1216285 into lp:~go-bot/juju-core/trunk

[John A Meinel]

environs/tools: print out the correct version

Bug #1216285 is because we were miss-formatting a line about what
version we were filtering. It turns out that while we were printing out
an int as "%s" we were also not priting out what the filter would
actually match. (If you pass a version in that field, we match the exact
version, not just the major version.)

In the process, I realized we don't have much infrastructure for testing
what log messages we are writing, so I added a LogMatches checker. I
think it is something that actually fits better inside the loggo
package, but I wanted to give it some real experience before I tried to
get it into upstream.

https://codereview.appspot.com/12744051/

environs/tools: print out the correct version

Bug #1216285 is because we were miss-formatting a line about what
version we were filtering. It turns out that while we were printing out
an int as "%s" we were also not priting out what the filter would
actually match. (If you pass a version in that field, we match the exact
version, not just the major version.)

In the process, I realized we don't have much infrastructure for testing
what log messages we are writing, so I added a LogMatches checker. I
think it is something that actually fits better inside the loggo
package, but I wanted to give it some real experience before I tried to
get it into upstream.

https://codereview.appspot.com/12744051/

[John A Meinel (jameinel)]

Reviewers: mp+181983_code.launchpad.net,

Message:
Please take a look.

Description:
environs/tools: print out the correct version

Bug #1216285 is because we were miss-formatting a line about what
version we were filtering. It turns out that while we were printing out
an int as "%s" we were also not priting out what the filter would
actually match. (If you pass a version in that field, we match the exact
version, not just the major version.)

In the process, I realized we don't have much infrastructure for testing
what log messages we are writing, so I added a LogMatches checker. I
think it is something that actually fits better inside the loggo
package, but I wanted to give it some real experience before I tried to
get it into upstream.

https://code.launchpad.net/~jameinel/juju-core/bad-formatting-1216285/+merge/181983

(do not edit description out of merge proposal)

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

Affected files:
   A [revision details]
   M environs/tools/tools.go
   M environs/tools/tools_test.go
   A testing/checkers/log.go
   A testing/checkers/log_test.go

[Roger Peppe (rogpeppe)]

Thanks for the log fix - it had niggled at me but I hadn't filed a bug
or fixed it (except in passing in an outstanding CL).

I have some thoughts on the log checker - what do you think?

https://codereview.appspot.com/12744051/diff/1/environs/tools/tools.go
File environs/tools/tools.go (right):

https://codereview.appspot.com/12744051/diff/1/environs/tools/tools.go#newcode33
environs/tools/tools.go:33: logger.Infof("filtering tools by version:
%s", filter.Number.String())
s/.String()//

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

https://codereview.appspot.com/12744051/diff/1/testing/checkers/log.go#newcode41
testing/checkers/log.go:41: return reflect.DeepEqual(obtained,
params[1]), ""
I think this (and the below test for []string
should be a little more sophisticated and
allow other (unknown) messages to intersperse the
ones we're checking for.

That will make our tests less fragile when extra logging
messages are added, but still allow us to check
that the log produced at least the required messages.

Another thought is to allow specification by
regexp (which actually would fit the "Match" name
convention) so that it's possible to check
log messages that print pointers or other
transient identifiers.

How about simplifying things by saying
that we *always* check against a []string
containing regexps, with the obtained values
being formed in a consistent way before matching.

That way we can easily make the
matching strings ignore the level
if we want, but we don't have to muck about
with dynamic types so much.

c.Assert(c.Check(tw.Log, jc.LogMatches, []string{
        `INFO: reading tools with major version 1`,
        `.*: filtering tools by version: 1\.2\.3`, // ignore level
        etc,
}

https://codereview.appspot.com/12744051/

[William Reade (fwereade)]

LGTM. Rog's concerns are reasonable, and a better log checker might be
something we need one day, but I think that day is the day the fragility
has an actual impact. I wouldn't expect to see logs checked except in
very narrow situations, so that day may take a while to arrive.

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

https://codereview.appspot.com/12744051/diff/1/testing/checkers/log.go#newcode13
testing/checkers/log.go:13: type SimpleMessages struct {
SimpleMessage?

https://codereview.appspot.com/12744051/diff/1/testing/checkers/log.go#newcode51
testing/checkers/log.go:51: return false, "bork bork bork"
Can we just stop before this line, or can the compiler not detect that
there's no way out of the switch? I think we should panic("unreachable")
rather than returning "bork bork bork" regardless...

https://codereview.appspot.com/12744051/

[John A Meinel (jameinel)]

Please take a look.

https://codereview.appspot.com/12744051/diff/1/environs/tools/tools.go
File environs/tools/tools.go (right):

https://codereview.appspot.com/12744051/diff/1/environs/tools/tools.go#newcode33
environs/tools/tools.go:33: logger.Infof("filtering tools by version:
%s", filter.Number.String())
On 2013/08/25 14:33:54, rog wrote:
> s/.String()//

Done.

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

https://codereview.appspot.com/12744051/diff/1/testing/checkers/log.go#newcode13
testing/checkers/log.go:13: type SimpleMessages struct {
On 2013/08/28 10:58:24, fwereade wrote:
> SimpleMessage?

Done.

https://codereview.appspot.com/12744051/diff/1/testing/checkers/log.go#newcode41
testing/checkers/log.go:41: return reflect.DeepEqual(obtained,
params[1]), ""

...

> c.Assert(c.Check(tw.Log, jc.LogMatches, []string{
> `INFO: reading tools with major version 1`,
> `.*: filtering tools by version: 1\.2\.3`, // ignore level
> etc,
> }

I do like this a bit, but it is a fair effort to code, and I'd rather
see smart stuff land in loggo itself. I've put forward a request to get
feedback from Tim about how that would look. (haven't heard back yet).

https://codereview.appspot.com/12744051/diff/1/testing/checkers/log.go#newcode51
testing/checkers/log.go:51: return false, "bork bork bork"
On 2013/08/28 10:58:24, fwereade wrote:
> Can we just stop before this line, or can the compiler not detect that
there's
> no way out of the switch? I think we should panic("unreachable")
rather than
> returning "bork bork bork" regardless...

Just old code that I hadn't cleaned out. default() should be hitting
this case. Removed.

https://codereview.appspot.com/12744051/

=== modified file 'environs/tools/tools.go'
--- environs/tools/tools.go	2013-08-26 03:34:00 +0000
+++ environs/tools/tools.go	2013-08-28 12:04:57 +0000
@@ -30,7 +30,7 @@
 	// Construct a tools filter.
 	// Discard all that are known to be irrelevant.
 	if filter.Number != version.Zero {
-		logger.Infof("filtering tools by version: %s", filter.Number.Major)
+		logger.Infof("filtering tools by version: %s", filter.Number)
 	}
 	if filter.Series != "" {
 		logger.Infof("filtering tools by series: %s", filter.Series)

=== modified file 'environs/tools/tools_test.go'
--- environs/tools/tools_test.go	2013-08-24 13:50:05 +0000
+++ environs/tools/tools_test.go	2013-08-28 12:04:57 +0000
@@ -5,6 +5,7 @@
 
 import (
 	gc "launchpad.net/gocheck"
+	"launchpad.net/loggo"
 
 	"launchpad.net/juju-core/constraints"
 	"launchpad.net/juju-core/environs"
@@ -190,6 +191,24 @@
 	}
 }
 
+func (s *ToolsSuite) TestFindToolsFiltering(c *gc.C) {
+	tw := &loggo.TestWriter{}
+	c.Assert(loggo.RegisterWriter("filter-tester", tw, loggo.DEBUG), gc.IsNil)
+	defer loggo.RemoveWriter("filter-tester")
+	_, err := envtools.FindTools(s.env, 1, coretools.Filter{Number: version.Number{Major: 1, Minor: 2, Patch: 3}})
+	c.Assert(err, jc.Satisfies, errors.IsNotFoundError)
+	// This is slightly overly prescriptive, but feel free to change or add
+	// messages. This still helps to ensure that all log messages are
+	// properly formed.
+	c.Check(tw.Log, jc.LogMatches, []jc.SimpleMessage{
+		{loggo.INFO, "reading tools with major version 1"},
+		{loggo.INFO, "filtering tools by version: 1.2.3"},
+		{loggo.DEBUG, "reading v1.* tools"},
+		{loggo.INFO, "falling back to public bucket"},
+		{loggo.DEBUG, "reading v1.* tools"},
+	})
+}
+
 var findBootstrapToolsTests = []struct {
 	info          string
 	available     []version.Binary

=== added file 'testing/checkers/log.go'
--- testing/checkers/log.go	1970-01-01 00:00:00 +0000
+++ testing/checkers/log.go	2013-08-28 12:04:57 +0000
@@ -0,0 +1,60 @@
+// Copyright 2012, 2013 Canonical Ltd.
+// Licensed under the AGPLv3, see LICENCE file for details.
+
+package checkers
+
+import (
+	"reflect"
+
+	gc "launchpad.net/gocheck"
+	"launchpad.net/loggo"
+)
+
+type SimpleMessage struct {
+	Level   loggo.Level
+	Message string
+}
+
+func logToSimpleMessages(log []loggo.TestLogValues) []SimpleMessage {
+	out := make([]SimpleMessage, len(log))
+	for i, val := range log {
+		out[i].Level = val.Level
+		out[i].Message = val.Message
+	}
+	return out
+}
+
+type logMatches struct {
+	*gc.CheckerInfo
+}
+
+func (checker *logMatches) Check(params []interface{}, names []string) (result bool, error string) {
+	var obtained []SimpleMessage
+	switch params[0].(type) {
+	case []loggo.TestLogValues:
+		obtained = logToSimpleMessages(params[0].([]loggo.TestLogValues))
+	default:
+		return false, "Obtained value must be of type []loggo.TestLogValues or SimpleMessage"
+	}
+	switch params[1].(type) {
+	case []SimpleMessage:
+		return reflect.DeepEqual(obtained, params[1]), ""
+	case []string:
+		asString := make([]string, len(obtained))
+		for i, val := range obtained {
+			asString[i] = val.Message
+		}
+		return reflect.DeepEqual(asString, params[1]), ""
+	default:
+		return false, "Expected value must be of type []string or []SimpleMessage"
+	}
+}
+
+// LogMatches checks whether a given TestLogValues actually contains the log
+// messages we expected. If you compare it against a list of strings, we only
+// 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.
+var LogMatches gc.Checker = &logMatches{
+	&gc.CheckerInfo{Name: "LogMatches", Params: []string{"obtained", "expected"}},
+}

=== added file 'testing/checkers/log_test.go'
--- testing/checkers/log_test.go	1970-01-01 00:00:00 +0000
+++ testing/checkers/log_test.go	2013-08-28 12:04:57 +0000
@@ -0,0 +1,57 @@
+// Copyright 2013 Canonical Ltd.
+// Licensed under the AGPLv3, see LICENCE file for details.
+
+package checkers_test
+
+import (
+	gc "launchpad.net/gocheck"
+	"launchpad.net/loggo"
+
+	jc "launchpad.net/juju-core/testing/checkers"
+)
+
+type LogMatchesSuite struct{}
+
+var _ = gc.Suite(&LogMatchesSuite{})
+
+func (s *LogMatchesSuite) TestMatchSimpleMessage(c *gc.C) {
+	log := []loggo.TestLogValues{
+		{Level: loggo.INFO, Message: "foo"},
+		{Level: loggo.INFO, Message: "bar"},
+	}
+	c.Check(log, jc.LogMatches, []jc.SimpleMessage{
+		{loggo.INFO, "foo"},
+		{loggo.INFO, "bar"},
+	})
+	c.Check(log, gc.Not(jc.LogMatches), []jc.SimpleMessage{
+		{loggo.INFO, "foo"},
+		{loggo.DEBUG, "bar"},
+	})
+}
+
+func (s *LogMatchesSuite) TestMatchStrings(c *gc.C) {
+	log := []loggo.TestLogValues{
+		{Level: loggo.INFO, Message: "foo"},
+		{Level: loggo.INFO, Message: "bar"},
+	}
+	c.Check(log, jc.LogMatches, []string{"foo", "bar"})
+	c.Check(log, gc.Not(jc.LogMatches), []string{"baz", "bing"})
+}
+
+func (s *LogMatchesSuite) TestFromLogMatches(c *gc.C) {
+	tw := &loggo.TestWriter{}
+	_, err := loggo.ReplaceDefaultWriter(tw)
+	c.Assert(err, gc.IsNil)
+	defer loggo.ResetWriters()
+	logger := loggo.GetLogger("test")
+	logger.SetLogLevel(loggo.DEBUG)
+	logger.Infof("foo")
+	logger.Debugf("bar")
+	logger.Tracef("hidden")
+	c.Check(tw.Log, jc.LogMatches, []string{"foo", "bar"})
+	c.Check(tw.Log, gc.Not(jc.LogMatches), []string{"foo", "bad"})
+	c.Check(tw.Log, gc.Not(jc.LogMatches), []jc.SimpleMessage{
+		{loggo.INFO, "foo"},
+		{loggo.INFO, "bar"},
+	})
+}