Merge lp:~thumper/juju-core/use-loggo into lp:~juju/juju-core/trunk

[Tim Penhey]

Integrate loggo as a hierarchical logger.

The existing logging is very flat and has very little control over what is output.

I wrote loggo as a Go port of a C++ library I wrote for nux/unity (my third or fourth logging library). Loggers are very lightweight objects that have a single pointer to the module. A module is defined by a dotted name, like "juju.uniter" or "juju.provider.ec2". There is no limit to the depth of nesting. Logging levels are inherited unless explicitly set. The root logger, identified by the module "" (empty string), defaults to WARNING.

The existing log package has been updated to use the loggo methods so we don't have to change all the call sites immediately. However we should start to move to more detailed modules for logging as we can have better control over it.

We should, as a soon to be done step, provide a way, probably using set-env, to configure logging for various machine agents or unit agents. This would allow a high level of control over what information gets logged.

https://codereview.appspot.com/9738051/

[Tim Penhey (thumper)]

Reviewers: mp+166611_code.launchpad.net,

Message:
Please take a look.

Description:

https://code.launchpad.net/~thumper/juju-core/use-loggo/+merge/166611

(do not edit description out of merge proposal)

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

Affected files:
   A [revision details]
   M charm/dir_test.go
   M charm/repo_test.go
   M cmd/builddb/main.go
   M cmd/charmd/main.go
   M cmd/charmload/main.go
   M cmd/juju/main_test.go
   M cmd/logging.go
   M cmd/logging_test.go
   M cmd/supercommand_test.go
   M environs/cloudinit/cloudinit.go
   M log/log.go
   M log/log_test.go
   M state/watcher/watcher_test.go
   M store/store_test.go
   M testing/log.go
   M worker/uniter/context_test.go
   M worker/uniter/jujuc/juju-log_test.go
   M worker/uniter/jujuc/server_test.go
   M worker/uniter/uniter_test.go

[Dave Cheney (dave-cheney)]

LGTM.

On Fri, May 31, 2013 at 12:47 PM, Tim Penhey <email address hidden>wrote:

> The proposal to merge lp:~thumper/juju-core/use-loggo into lp:juju-core
> has been updated.
>
> Description changed to:
>
> Integrate loggo as a hierarchical logger.
>
> The existing logging is very flat and has very little control over what is
> output.
>
> I wrote loggo as a Go port of a C++ library I wrote for nux/unity (my
> third or fourth logging library). Loggers are very lightweight objects
> that have a single pointer to the module. A module is defined by a dotted
> name, like "juju.uniter" or "juju.provider.ec2". There is no limit to the
> depth of nesting. Logging levels are inherited unless explicitly set. The
> root logger, identified by the module "" (empty string), defaults to
> WARNING.
>
> The existing log package has been updated to use the loggo methods so we
> don't have to change all the call sites immediately. However we should
> start to move to more detailed modules for logging as we can have better
> control over it.
>
> We should, as a soon to be done step, provide a way, probably using
> set-env, to configure logging for various machine agents or unit agents.
> This would allow a high level of control over what information gets logged.
>
> https://codereview.appspot.com/9738051/
>
> For more details, see:
> https://code.launchpad.net/~thumper/juju-core/use-loggo/+merge/166611
> --
> https://code.launchpad.net/~thumper/juju-core/use-loggo/+merge/166611
> Your team juju hackers is requested to review the proposed merge of
> lp:~thumper/juju-core/use-loggo into lp:juju-core.
>

[Frank Mueller (themue)]

LGTM

https://codereview.appspot.com/9738051/diff/1/cmd/logging.go
File cmd/logging.go (right):

https://codereview.appspot.com/9738051/diff/1/cmd/logging.go#newcode26
cmd/logging.go:26: // TODO: rename verbose to --show-log
TODO for whom? Use // TODO(nick) ...

https://codereview.appspot.com/9738051/diff/1/worker/uniter/uniter_test.go
File worker/uniter/uniter_test.go (right):

https://codereview.appspot.com/9738051/diff/1/worker/uniter/uniter_test.go#newcode170
worker/uniter/uniter_test.go:170: // TODO: fix this to actually use a
log writer to catch interesting log messages.
Again // TODO(nick) ...

https://codereview.appspot.com/9738051/

[John A Meinel (jameinel)]

Just to codify it, the switch to loggo LGTM, but I think I uncovered a
couple bugs in loggo itself. (if you do SetLoggingLevel(DEBUG) it
actually doesn't emit logger.Debug() messages (the check is
getEffectiveLevel() > level rather than getEffectiveLevel() >= level).

I'd like us to get some of that sorted out before then.

https://codereview.appspot.com/9738051/

[Tim Penhey (thumper)]

On 03/06/13 21:21, <email address hidden> wrote:
> Just to codify it, the switch to loggo LGTM, but I think I uncovered a
> couple bugs in loggo itself. (if you do SetLoggingLevel(DEBUG) it
> actually doesn't emit logger.Debug() messages (the check is
> getEffectiveLevel() > level rather than getEffectiveLevel() >= level).

Yes it does, this is just a misunderstanding.

Tests for this are in loggo/writer_test.go

[John A Meinel (jameinel)]

...

> Yes it does, this is just a misunderstanding.

> Tests for this are in loggo/writer_test.go

Right, I had the comparison turned around. LGTM

https://codereview.appspot.com/9738051/

[Tim Penhey (thumper)]

*** Submitted:

Integrate loggo as a hierarchical logger.

The existing logging is very flat and has very little control over what
is output.

I wrote loggo as a Go port of a C++ library I wrote for nux/unity (my
third or fourth logging library). Loggers are very lightweight objects
that have a single pointer to the module. A module is defined by a
dotted name, like "juju.uniter" or "juju.provider.ec2". There is no
limit to the depth of nesting. Logging levels are inherited unless
explicitly set. The root logger, identified by the module "" (empty
string), defaults to WARNING.

The existing log package has been updated to use the loggo methods so we
don't have to change all the call sites immediately. However we should
start to move to more detailed modules for logging as we can have better
control over it.

We should, as a soon to be done step, provide a way, probably using
set-env, to configure logging for various machine agents or unit agents.
  This would allow a high level of control over what information gets
logged.

R=mue, jameinel
CC=
https://codereview.appspot.com/9738051

https://codereview.appspot.com/9738051/

=== modified file 'charm/dir_test.go'
--- charm/dir_test.go	2013-05-02 15:55:42 +0000
+++ charm/dir_test.go	2013-06-04 23:43:27 +0000
@@ -10,7 +10,6 @@
 	"io/ioutil"
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/charm"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/testing"
 	"os"
 	"path/filepath"
@@ -18,7 +17,9 @@
 	"syscall"
 )
 
-type DirSuite struct{}
+type DirSuite struct {
+	testing.LoggingSuite
+}
 
 var _ = Suite(&DirSuite{})
 
@@ -121,7 +122,6 @@
 
 // Bug #864164: Must complain if charm hooks aren't executable
 func (s *DirSuite) TestBundleToWithNonExecutableHooks(c *C) {
-	defer log.SetTarget(log.SetTarget(c))
 	hooks := []string{"install", "start", "config-changed", "upgrade-charm", "stop"}
 	for _, relName := range []string{"foo", "bar", "self"} {
 		for _, kind := range []string{"joined", "changed", "departed", "broken"} {
@@ -140,7 +140,7 @@
 	tlog := c.GetTestLog()
 	for _, hook := range hooks {
 		fullpath := filepath.Join(dir.Path, "hooks", hook)
-		exp := fmt.Sprintf(`^(.|\n)*WARNING charm: making "%s" executable in charm(.|\n)*$`, fullpath)
+		exp := fmt.Sprintf(`^(.|\n)*WARNING juju charm: making "%s" executable in charm(.|\n)*$`, fullpath)
 		c.Assert(tlog, Matches, exp, Commentf("hook %q was not made executable", fullpath))
 	}
 

=== modified file 'charm/repo_test.go'
--- charm/repo_test.go	2013-05-02 15:55:42 +0000
+++ charm/repo_test.go	2013-06-04 23:43:27 +0000
@@ -11,7 +11,6 @@
 	"io/ioutil"
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/charm"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/testing"
 	"net"
 	"net/http"
@@ -150,6 +149,7 @@
 }
 
 type StoreSuite struct {
+	testing.LoggingSuite
 	server      *MockStore
 	store       *charm.CharmStore
 	oldCacheDir string
@@ -158,19 +158,24 @@
 var _ = Suite(&StoreSuite{})
 
 func (s *StoreSuite) SetUpSuite(c *C) {
+	s.LoggingSuite.SetUpSuite(c)
 	s.server = NewMockStore(c)
 	s.oldCacheDir = charm.CacheDir
 }
 
 func (s *StoreSuite) SetUpTest(c *C) {
+	s.LoggingSuite.SetUpTest(c)
 	charm.CacheDir = c.MkDir()
 	s.store = charm.NewStore("http://127.0.0.1:4444")
 	s.server.downloads = nil
 }
 
+// Uses the TearDownTest from testing.LoggingSuite
+
 func (s *StoreSuite) TearDownSuite(c *C) {
 	charm.CacheDir = s.oldCacheDir
 	s.server.lis.Close()
+	s.LoggingSuite.TearDownSuite(c)
 }
 
 func (s *StoreSuite) TestMissing(c *C) {
@@ -192,9 +197,8 @@
 }
 
 func (s *StoreSuite) TestWarning(c *C) {
-	defer log.SetTarget(log.SetTarget(c))
 	curl := charm.MustParseURL("cs:series/unwise")
-	expect := `.* WARNING charm: charm store reports for "cs:series/unwise": foolishness` + "\n"
+	expect := `.* WARNING juju charm: charm store reports for "cs:series/unwise": foolishness` + "\n"
 	r, err := s.store.Latest(curl)
 	c.Assert(r, Equals, 23)
 	c.Assert(err, IsNil)
@@ -495,9 +499,9 @@
 	c.Assert(err, IsNil)
 	c.Assert(ch.Revision(), Equals, 1)
 	c.Assert(c.GetTestLog(), Matches, `
-.* WARNING charm: failed to load charm at ".*/series/blah": .*
-.* WARNING charm: failed to load charm at ".*/series/blah.charm": .*
-.* WARNING charm: failed to load charm at ".*/series/upgrade2": .*
+.* WARNING juju charm: failed to load charm at ".*/series/blah": .*
+.* WARNING juju charm: failed to load charm at ".*/series/blah.charm": .*
+.* WARNING juju charm: failed to load charm at ".*/series/upgrade2": .*
 `[1:])
 }
 

=== modified file 'cmd/builddb/main.go'
--- cmd/builddb/main.go	2013-05-02 15:55:42 +0000
+++ cmd/builddb/main.go	2013-06-04 23:43:27 +0000
@@ -5,15 +5,15 @@
 
 import (
 	"fmt"
+	"os"
+	"path/filepath"
+	"time"
+
 	"launchpad.net/juju-core/charm"
 	"launchpad.net/juju-core/environs"
 	"launchpad.net/juju-core/juju"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/state/api/params"
-	stdlog "log"
-	"os"
-	"path/filepath"
-	"time"
+	"launchpad.net/loggo"
 )
 
 // Import the providers.
@@ -21,8 +21,9 @@
 	_ "launchpad.net/juju-core/environs/all"
 )
 
+var logger = loggo.GetLogger("juju.builddb")
+
 func main() {
-	log.SetTarget(stdlog.New(os.Stdout, "", stdlog.LstdFlags))
 	if err := build(); err != nil {
 		fmt.Fprintf(os.Stderr, "%v\n", err)
 		os.Exit(1)
@@ -56,13 +57,13 @@
 		return err
 	}
 
-	log.Infof("builddb: Waiting for unit to reach %q status...", params.StatusStarted)
+	logger.Info("Waiting for unit to reach %q status...", params.StatusStarted)
 	unit := units[0]
 	last, info, err := unit.Status()
 	if err != nil {
 		return err
 	}
-	logStatus(last, info)
+	logger.Info("Unit status is %q: %s", last, info)
 	for last != params.StatusStarted {
 		time.Sleep(2 * time.Second)
 		if err := unit.Refresh(); err != nil {
@@ -73,7 +74,7 @@
 			return err
 		}
 		if status != last {
-			logStatus(status, info)
+			logger.Info("Unit status is %q: %s", status, info)
 			last = status
 		}
 	}
@@ -81,15 +82,7 @@
 	if !ok {
 		return fmt.Errorf("cannot retrieve files: build unit lacks a public-address")
 	}
-	log.Noticef("builddb: Built files published at http://%s", addr)
-	log.Noticef("builddb: Remember to destroy the environment when you're done...")
+	logger.Info("Built files published at http://%s", addr)
+	logger.Info("Remember to destroy the environment when you're done...")
 	return nil
 }
-
-func logStatus(status params.Status, info string) {
-	if info == "" {
-		log.Infof("builddb: Unit status is %q", status)
-	} else {
-		log.Infof("builddb: Unit status is %q: %s", status, info)
-	}
-}

=== modified file 'cmd/charmd/main.go'
--- cmd/charmd/main.go	2013-05-02 15:55:42 +0000
+++ cmd/charmd/main.go	2013-06-04 23:43:27 +0000
@@ -7,16 +7,13 @@
 	"fmt"
 	"io/ioutil"
 	"launchpad.net/goyaml"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/store"
-	stdlog "log"
 	"net/http"
 	"os"
 	"path/filepath"
 )
 
 func main() {
-	log.SetTarget(stdlog.New(os.Stdout, "", stdlog.LstdFlags))
 	err := serve()
 	if err != nil {
 		fmt.Fprintf(os.Stderr, "%v\n", err)

=== modified file 'cmd/charmload/main.go'
--- cmd/charmload/main.go	2013-05-02 15:55:42 +0000
+++ cmd/charmload/main.go	2013-06-04 23:43:27 +0000
@@ -7,16 +7,13 @@
 	"fmt"
 	"io/ioutil"
 	"launchpad.net/goyaml"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/store"
 	"launchpad.net/lpad"
-	stdlog "log"
 	"os"
 	"path/filepath"
 )
 
 func main() {
-	log.SetTarget(stdlog.New(os.Stdout, "", stdlog.LstdFlags))
 	err := load()
 	if err != nil {
 		fmt.Fprintf(os.Stderr, "%v\n", err)

=== modified file 'cmd/juju/main_test.go'
--- cmd/juju/main_test.go	2013-05-28 02:05:06 +0000
+++ cmd/juju/main_test.go	2013-06-04 23:43:27 +0000
@@ -15,6 +15,7 @@
 	_ "launchpad.net/juju-core/environs/dummy"
 	"launchpad.net/juju-core/testing"
 	"launchpad.net/juju-core/version"
+	"launchpad.net/loggo"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -71,6 +72,10 @@
 	return helpText(&SyncToolsCommand{}, "juju sync-tools")
 }
 
+func (s *MainSuite) TestTearDown(c *C) {
+	loggo.ResetLogging()
+}
+
 func (s *MainSuite) TestRunMain(c *C) {
 	defer testing.MakeSampleHome(c).Restore()
 	// The test array structure needs to be inline here as some of the
@@ -188,7 +193,7 @@
 	c.Assert(out, Equals, "error: "+msg+"\n")
 	content, err := ioutil.ReadFile(logpath)
 	c.Assert(err, IsNil)
-	fullmsg := fmt.Sprintf(`(.|\n)*ERROR command failed: %s\n`, msg)
+	fullmsg := fmt.Sprintf(`(.|\n)*ERROR .* command failed: %s\n`, msg)
 	c.Assert(string(content), Matches, fullmsg)
 }
 
@@ -201,7 +206,7 @@
 	c.Assert(out, Equals, "error: "+msg+"\n")
 	content, err := ioutil.ReadFile(logpath)
 	c.Assert(err, IsNil)
-	fullmsg := fmt.Sprintf(`(.|\n)*ERROR command failed: %s\n`, msg)
+	fullmsg := fmt.Sprintf(`(.|\n)*ERROR .* command failed: %s\n`, msg)
 	c.Assert(string(content), Matches, fullmsg)
 }
 
@@ -295,6 +300,7 @@
 var globalFlags = []string{
 	"--debug .*",
 	"-h, --help .*",
+	"--log-config .*",
 	"--log-file .*",
 	"-v, --verbose .*",
 }

=== modified file 'cmd/logging.go'
--- cmd/logging.go	2013-05-02 15:55:42 +0000
+++ cmd/logging.go	2013-06-04 23:43:27 +0000
@@ -5,10 +5,10 @@
 
 import (
 	"io"
+	"os"
+
 	"launchpad.net/gnuflag"
-	"launchpad.net/juju-core/log"
-	stdlog "log"
-	"os"
+	"launchpad.net/loggo"
 )
 
 // Log supplies the necessary functionality for Commands that wish to set up
@@ -17,37 +17,45 @@
 	Path    string
 	Verbose bool
 	Debug   bool
-	log.Logger
+	Config  string
 }
 
 // AddFlags adds appropriate flags to f.
 func (l *Log) AddFlags(f *gnuflag.FlagSet) {
 	f.StringVar(&l.Path, "log-file", "", "path to write log to")
+	// TODO: rename verbose to --show-log
 	f.BoolVar(&l.Verbose, "v", false, "if set, log additional messages")
 	f.BoolVar(&l.Verbose, "verbose", false, "if set, log additional messages")
 	f.BoolVar(&l.Debug, "debug", false, "if set, log debugging messages")
-}
-
-func (l *Log) Output(calldepth int, s string) error {
-	return l.Logger.Output(calldepth, s)
+	f.StringVar(&l.Config, "log-config", "", "specify log levels for modules")
 }
 
 // Start starts logging using the given Context.
 func (l *Log) Start(ctx *Context) (err error) {
-	log.Debug = l.Debug
 	var target io.Writer
 	if l.Path != "" {
 		path := ctx.AbsPath(l.Path)
 		target, err = os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
 		if err != nil {
-			return
+			return err
 		}
 	} else if l.Verbose || l.Debug {
 		target = ctx.Stderr
 	}
+
 	if target != nil {
-		l.Logger = stdlog.New(target, "", stdlog.LstdFlags)
-		log.SetTarget(l)
-	}
-	return
+		writer := loggo.NewSimpleWriter(target, &loggo.DefaultFormatter{})
+		_, err = loggo.ReplaceDefaultWriter(writer)
+		if err != nil {
+			return err
+		}
+	} else {
+		loggo.RemoveWriter("default")
+	}
+	if l.Debug {
+		logger := loggo.GetLogger("juju")
+		logger.SetLogLevel(loggo.DEBUG)
+	}
+	loggo.ConfigureLogging(l.Config)
+	return nil
 }

=== modified file 'cmd/logging_test.go'
--- cmd/logging_test.go	2013-05-02 15:55:42 +0000
+++ cmd/logging_test.go	2013-06-04 23:43:27 +0000
@@ -13,7 +13,6 @@
 )
 
 type LogSuite struct {
-	testing.LoggingSuite
 }
 
 var _ = Suite(&LogSuite{})
@@ -28,53 +27,28 @@
 	c.Assert(l.Path, Equals, "")
 	c.Assert(l.Verbose, Equals, false)
 	c.Assert(l.Debug, Equals, false)
+	c.Assert(l.Config, Equals, "")
 
-	err = f.Parse(false, []string{"--log-file", "foo", "--verbose", "--debug"})
+	err = f.Parse(false, []string{"--log-file", "foo", "--verbose", "--debug",
+		"--log-config=juju.cmd=INFO;juju.worker.deployer=DEBUG"})
 	c.Assert(err, IsNil)
 	c.Assert(l.Path, Equals, "foo")
 	c.Assert(l.Verbose, Equals, true)
 	c.Assert(l.Debug, Equals, true)
-}
-
-func (s *LogSuite) TestStart(c *C) {
-	for _, t := range []struct {
-		path    string
-		verbose bool
-		debug   bool
-		check   Checker
-	}{
-		{"", true, true, NotNil},
-		{"", true, false, NotNil},
-		{"", false, true, NotNil},
-		{"", false, false, IsNil},
-		{"foo", true, true, NotNil},
-		{"foo", true, false, NotNil},
-		{"foo", false, true, NotNil},
-		{"foo", false, false, NotNil},
-	} {
-		// commands always start with the log target set to its zero value.
-		log.SetTarget(nil)
-
-		l := &cmd.Log{Path: t.path, Verbose: t.verbose, Debug: t.debug}
-		ctx := testing.Context(c)
-		err := l.Start(ctx)
-		c.Assert(err, IsNil)
-		c.Assert(log.Target(), t.check)
-		c.Assert(log.Debug, Equals, t.debug)
-	}
+	c.Assert(l.Config, Equals, "juju.cmd=INFO;juju.worker.deployer=DEBUG")
 }
 
 func (s *LogSuite) TestStderr(c *C) {
-	l := &cmd.Log{Verbose: true}
+	l := &cmd.Log{Verbose: true, Config: "<root>=INFO"}
 	ctx := testing.Context(c)
 	err := l.Start(ctx)
 	c.Assert(err, IsNil)
 	log.Infof("hello")
-	c.Assert(bufferString(ctx.Stderr), Matches, `^.* INFO hello\n`)
+	c.Assert(bufferString(ctx.Stderr), Matches, `^.* INFO .* hello\n`)
 }
 
 func (s *LogSuite) TestRelPathLog(c *C) {
-	l := &cmd.Log{Path: "foo.log"}
+	l := &cmd.Log{Path: "foo.log", Config: "<root>=INFO"}
 	ctx := testing.Context(c)
 	err := l.Start(ctx)
 	c.Assert(err, IsNil)
@@ -82,12 +56,12 @@
 	c.Assert(bufferString(ctx.Stderr), Equals, "")
 	content, err := ioutil.ReadFile(filepath.Join(ctx.Dir, "foo.log"))
 	c.Assert(err, IsNil)
-	c.Assert(string(content), Matches, `^.* INFO hello\n`)
+	c.Assert(string(content), Matches, `^.* INFO .* hello\n`)
 }
 
 func (s *LogSuite) TestAbsPathLog(c *C) {
 	path := filepath.Join(c.MkDir(), "foo.log")
-	l := &cmd.Log{Path: path}
+	l := &cmd.Log{Path: path, Config: "<root>=INFO"}
 	ctx := testing.Context(c)
 	err := l.Start(ctx)
 	c.Assert(err, IsNil)
@@ -95,5 +69,5 @@
 	c.Assert(bufferString(ctx.Stderr), Equals, "")
 	content, err := ioutil.ReadFile(path)
 	c.Assert(err, IsNil)
-	c.Assert(string(content), Matches, `^.* INFO hello\n`)
+	c.Assert(string(content), Matches, `^.* INFO .* hello\n`)
 }

=== modified file 'cmd/supercommand_test.go'
--- cmd/supercommand_test.go	2013-05-21 22:09:29 +0000
+++ cmd/supercommand_test.go	2013-06-04 23:43:27 +0000
@@ -8,7 +8,6 @@
 
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/cmd"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/testing"
 )
 
@@ -104,17 +103,12 @@
 }
 
 func (s *SuperCommandSuite) TestLogging(c *C) {
-	target, debug := log.Target(), log.Debug
-	defer func() {
-		log.SetTarget(target)
-		log.Debug = debug
-	}()
 	jc := cmd.NewSuperCommand(cmd.SuperCommandParams{Name: "jujutest", Log: &cmd.Log{}})
 	jc.Register(&TestCommand{Name: "blah"})
 	ctx := testing.Context(c)
 	code := cmd.Main(jc, ctx, []string{"blah", "--option", "error", "--debug"})
 	c.Assert(code, Equals, 1)
-	c.Assert(bufferString(ctx.Stderr), Matches, `^.* ERROR command failed: BAM!
+	c.Assert(bufferString(ctx.Stderr), Matches, `^.* ERROR .* command failed: BAM!
 error: BAM!
 `)
 }

=== modified file 'environs/cloudinit/cloudinit.go'
--- environs/cloudinit/cloudinit.go	2013-05-31 07:39:15 +0000
+++ environs/cloudinit/cloudinit.go	2013-06-04 23:43:27 +0000
@@ -11,7 +11,6 @@
 	"launchpad.net/juju-core/constraints"
 	"launchpad.net/juju-core/environs/agent"
 	"launchpad.net/juju-core/environs/config"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/log/syslog"
 	"launchpad.net/juju-core/state"
 	"launchpad.net/juju-core/state/api"
@@ -131,9 +130,10 @@
 		fmt.Sprintf("echo -n %s > $bin/downloaded-url.txt", shquote(cfg.Tools.URL)),
 	)
 
+	// TODO (thumper): work out how to pass the logging config to the children
 	debugFlag := ""
 	// TODO: disable debug mode by default when the system is stable.
-	if true || log.Debug {
+	if true {
 		debugFlag = " --debug"
 	}
 

=== modified file 'log/log.go'
--- log/log.go	2013-05-02 15:55:42 +0000
+++ log/log.go	2013-06-04 23:43:27 +0000
@@ -4,71 +4,40 @@
 package log
 
 import (
-	"fmt"
-	"sync"
+	"launchpad.net/loggo"
 )
 
-type Logger interface {
-	Output(calldepth int, s string) error
-}
-
 var (
-	target struct {
-		sync.Mutex
-		logger Logger
-	}
-	Debug bool
+	logger = loggo.GetLogger("juju")
 )
 
-// Target returns the current log target.
-func Target() Logger {
-	target.Lock()
-	defer target.Unlock()
-	return target.logger
-}
-
-// SetTarget sets the logging target and returns its
-// previous value.
-func SetTarget(logger Logger) (prev Logger) {
-	target.Lock()
-	defer target.Unlock()
-	prev = target.logger
-	target.logger = logger
-	return
-}
-
-func logf(format string, a ...interface{}) error {
-	if target := Target(); target != nil {
-		const calldepth = 3 // magic
-		return target.Output(calldepth, fmt.Sprintf(format, a...))
-	}
-	return nil
-}
-
 // Errorf logs a message using the ERROR priority.
 func Errorf(format string, a ...interface{}) error {
-	return logf("ERROR "+format, a...)
+	logger.Log(loggo.ERROR, format, a...)
+	return nil
 }
 
 // Warningf logs a message using the WARNING priority.
 func Warningf(format string, a ...interface{}) error {
-	return logf("WARNING "+format, a...)
+	logger.Log(loggo.WARNING, format, a...)
+	return nil
 }
 
 // Noticef logs a message using the NOTICE priority.
+// Notice doesn't really convert to the loggo priorities...
 func Noticef(format string, a ...interface{}) error {
-	return logf("NOTICE "+format, a...)
+	logger.Log(loggo.INFO, format, a...)
+	return nil
 }
 
 // Infof logs a message using the INFO priority.
 func Infof(format string, a ...interface{}) error {
-	return logf("INFO "+format, a...)
+	logger.Log(loggo.INFO, format, a...)
+	return nil
 }
 
 // Debugf logs a message using the DEBUG priority.
 func Debugf(format string, a ...interface{}) (err error) {
-	if Debug {
-		return logf("DEBUG "+format, a...)
-	}
+	logger.Log(loggo.DEBUG, format, a...)
 	return nil
 }

=== modified file 'log/log_test.go'
--- log/log_test.go	2013-05-02 15:55:42 +0000
+++ log/log_test.go	2013-06-04 23:43:27 +0000
@@ -5,61 +5,79 @@
 
 import (
 	"bytes"
+	"fmt"
+	"testing"
+	"time"
+
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/log"
-	stdlog "log"
-	"testing"
+	"launchpad.net/loggo"
 )
 
 func Test(t *testing.T) {
 	TestingT(t)
 }
 
-type suite struct{}
-
-var _ = Suite(suite{})
-
-func (suite) TestLoggerDebugFlag(c *C) {
-	var buf bytes.Buffer
-	defer log.SetTarget(log.SetTarget(stdlog.New(&buf, "JUJU:", 0)))
-	log.Debug = false
+type testWriter struct {
+	bytes.Buffer
+}
+
+type suite struct {
+	writer    *testWriter
+	oldWriter loggo.Writer
+	oldLevel  loggo.Level
+}
+
+var _ = Suite(&suite{})
+
+func (t *testWriter) Write(level loggo.Level, module, filename string, line int, timestamp time.Time, message string) {
+	t.Buffer.WriteString(fmt.Sprintf("%s %s %s", level, module, message))
+}
+
+func (s *suite) SetUpTest(c *C) {
+	var err error
+	s.writer = &testWriter{}
+	s.oldWriter, s.oldLevel, err = loggo.RemoveWriter("default")
+	c.Assert(err, IsNil)
+	err = loggo.RegisterWriter("test", s.writer, loggo.TRACE)
+	c.Assert(err, IsNil)
+	logger := loggo.GetLogger("juju")
+	logger.SetLogLevel(loggo.TRACE)
+}
+
+func (s *suite) TearDownTest(c *C) {
+	_, _, err := loggo.RemoveWriter("test")
+	c.Assert(err, IsNil)
+	err = loggo.RegisterWriter("default", s.oldWriter, s.oldLevel)
+	c.Assert(err, IsNil)
+}
+
+func (s *suite) TestLoggerDebug(c *C) {
 	input := "Hello World"
 	log.Debugf(input)
-	c.Assert(buf.String(), Equals, "")
-	buf.Reset()
-	log.Debug = true
-	log.Debugf(input)
-	c.Assert(buf.String(), Equals, "JUJU:DEBUG "+input+"\n")
+	c.Assert(s.writer.String(), Equals, "DEBUG juju "+input)
 }
 
-func (suite) TestInfoLogger(c *C) {
-	var buf bytes.Buffer
-	defer log.SetTarget(log.SetTarget(stdlog.New(&buf, "JUJU:", 0)))
+func (s *suite) TestInfoLogger(c *C) {
 	input := "Hello World"
 	log.Infof(input)
-	c.Assert(buf.String(), Equals, "JUJU:INFO "+input+"\n")
+	c.Assert(s.writer.String(), Equals, "INFO juju "+input)
 }
 
-func (suite) TestErrorLogger(c *C) {
-	var buf bytes.Buffer
-	defer log.SetTarget(log.SetTarget(stdlog.New(&buf, "JUJU:", 0)))
+func (s *suite) TestErrorLogger(c *C) {
 	input := "Hello World"
 	log.Errorf(input)
-	c.Assert(buf.String(), Equals, "JUJU:ERROR "+input+"\n")
+	c.Assert(s.writer.String(), Equals, "ERROR juju "+input)
 }
 
-func (suite) TestWarningLogger(c *C) {
-	var buf bytes.Buffer
-	defer log.SetTarget(log.SetTarget(stdlog.New(&buf, "JUJU:", 0)))
+func (s *suite) TestWarningLogger(c *C) {
 	input := "Hello World"
 	log.Warningf(input)
-	c.Assert(buf.String(), Equals, "JUJU:WARNING "+input+"\n")
+	c.Assert(s.writer.String(), Equals, "WARNING juju "+input)
 }
 
-func (suite) TestNoticeLogger(c *C) {
-	var buf bytes.Buffer
-	defer log.SetTarget(log.SetTarget(stdlog.New(&buf, "JUJU:", 0)))
+func (s *suite) TestNoticeLogger(c *C) {
 	input := "Hello World"
 	log.Noticef(input)
-	c.Assert(buf.String(), Equals, "JUJU:NOTICE "+input+"\n")
+	c.Assert(s.writer.String(), Equals, "INFO juju "+input)
 }

=== modified file 'state/watcher/watcher_test.go'
--- state/watcher/watcher_test.go	2013-05-02 15:55:42 +0000
+++ state/watcher/watcher_test.go	2013-06-04 23:43:27 +0000
@@ -7,7 +7,6 @@
 	"labix.org/v2/mgo"
 	"labix.org/v2/mgo/txn"
 	. "launchpad.net/gocheck"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/state/watcher"
 	"launchpad.net/juju-core/testing"
 	"launchpad.net/tomb"
@@ -359,15 +358,6 @@
 	const N = 500
 	const T = 10
 
-	// Too much data.. doesn't help.
-	debug := log.Debug
-	defer func() { log.Debug = debug }()
-	log.Debug = false
-	// There is a data race on log.Debug. To avoid this race stop the
-	// watcher before restoring the value of log.Debug so the watcher
-	// does not observe a stale value of log.Debug.
-	defer s.w.Stop()
-
 	c.Logf("Creating %d documents, %d per transaction...", N, T)
 	ops := make([]txn.Op, T)
 	for i := 0; i < (N / T); i++ {

=== modified file 'store/store_test.go'
--- store/store_test.go	2013-05-02 15:55:42 +0000
+++ store/store_test.go	2013-06-04 23:43:27 +0000
@@ -10,7 +10,6 @@
 	"labix.org/v2/mgo/bson"
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/charm"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/store"
 	"launchpad.net/juju-core/testing"
 	"strconv"
@@ -29,6 +28,7 @@
 type StoreSuite struct {
 	MgoSuite
 	testing.HTTPSuite
+	testing.LoggingSuite
 	store *store.Store
 }
 
@@ -37,23 +37,25 @@
 func (s *StoreSuite) SetUpSuite(c *C) {
 	s.MgoSuite.SetUpSuite(c)
 	s.HTTPSuite.SetUpSuite(c)
+	s.LoggingSuite.SetUpSuite(c)
 }
 
 func (s *StoreSuite) TearDownSuite(c *C) {
+	s.LoggingSuite.TearDownSuite(c)
 	s.HTTPSuite.TearDownSuite(c)
 	s.MgoSuite.TearDownSuite(c)
 }
 
 func (s *StoreSuite) SetUpTest(c *C) {
 	s.MgoSuite.SetUpTest(c)
+	s.LoggingSuite.SetUpTest(c)
 	var err error
 	s.store, err = store.Open(s.Addr)
 	c.Assert(err, IsNil)
-	log.SetTarget(c)
-	log.Debug = true
 }
 
 func (s *StoreSuite) TearDownTest(c *C) {
+	s.LoggingSuite.TearDownTest(c)
 	s.HTTPSuite.TearDownTest(c)
 	if s.store != nil {
 		s.store.Close()

=== modified file 'testing/log.go'
--- testing/log.go	2013-05-02 15:55:42 +0000
+++ testing/log.go	2013-06-04 23:43:27 +0000
@@ -4,8 +4,11 @@
 package testing
 
 import (
+	"fmt"
+	"time"
+
 	. "launchpad.net/gocheck"
-	"launchpad.net/juju-core/log"
+	"launchpad.net/loggo"
 )
 
 // LoggingSuite redirects the juju logger to the test logger
@@ -14,18 +17,26 @@
 	restoreLog func()
 }
 
+type gocheckWriter struct {
+	c *C
+}
+
+func (w *gocheckWriter) Write(level loggo.Level, module, filename string, line int, timestamp time.Time, message string) {
+	// Magic calldepth value...
+	w.c.Output(3, fmt.Sprintf("%s %s %s", level, module, message))
+}
+
 func (t *LoggingSuite) SetUpSuite(c *C)    {}
 func (t *LoggingSuite) TearDownSuite(c *C) {}
 
 func (t *LoggingSuite) SetUpTest(c *C) {
-	target, debug := log.SetTarget(c), log.Debug
-	t.restoreLog = func() {
-		log.SetTarget(target)
-		log.Debug = debug
-	}
-	log.Debug = true
+	loggo.ResetWriters()
+	loggo.ReplaceDefaultWriter(&gocheckWriter{c})
+	loggo.ResetLogging()
+	loggo.GetLogger("juju").SetLogLevel(loggo.DEBUG)
 }
 
 func (t *LoggingSuite) TearDownTest(c *C) {
-	t.restoreLog()
+	loggo.ResetLogging()
+	loggo.ResetWriters()
 }

=== modified file 'worker/uniter/context_test.go'
--- worker/uniter/context_test.go	2013-05-27 13:16:23 +0000
+++ worker/uniter/context_test.go	2013-06-04 23:43:27 +0000
@@ -8,7 +8,6 @@
 	"io/ioutil"
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/juju/testing"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/state"
 	"launchpad.net/juju-core/utils"
 	"launchpad.net/juju-core/worker/uniter"
@@ -197,23 +196,7 @@
 	},
 }
 
-type logRecorder struct {
-	c      *C
-	prefix string
-	lines  []string
-}
-
-func (l *logRecorder) Output(calldepth int, s string) error {
-	if strings.HasPrefix(s, l.prefix) {
-		l.lines = append(l.lines, s[len(l.prefix):])
-	}
-	l.c.Logf("%s", s)
-	return nil
-}
-
 func (s *RunHookSuite) TestRunHook(c *C) {
-	logger := &logRecorder{c: c, prefix: "INFO worker/uniter: HOOK "}
-	defer log.SetTarget(log.SetTarget(logger))
 	uuid, err := utils.NewUUID()
 	c.Assert(err, IsNil)
 	for i, t := range runHookTests {
@@ -229,7 +212,6 @@
 			charmDir, outPath = makeCharm(c, spec)
 		}
 		toolsDir := c.MkDir()
-		logger.lines = nil
 		t0 := time.Now()
 		err := ctx.RunHook("something-happened", charmDir, toolsDir, "/path/to/socket")
 		if t.err == "" {
@@ -244,17 +226,9 @@
 			}
 			AssertEnv(c, outPath, charmDir, env, uuid.String())
 		}
-		var expectLog []string
-		if t.spec.stdout != "" {
-			expectLog = append(expectLog, splitLine(t.spec.stdout)...)
-		}
-		if t.spec.stderr != "" {
-			expectLog = append(expectLog, splitLine(t.spec.stderr)...)
-		}
 		if t.spec.background != "" && time.Now().Sub(t0) > 5*time.Second {
 			c.Errorf("background process holding up hook execution")
 		}
-		c.Assert(logger.lines, DeepEquals, expectLog)
 	}
 }
 

=== modified file 'worker/uniter/jujuc/juju-log_test.go'
--- worker/uniter/jujuc/juju-log_test.go	2013-05-02 15:55:42 +0000
+++ worker/uniter/jujuc/juju-log_test.go	2013-06-04 23:43:27 +0000
@@ -4,14 +4,13 @@
 package jujuc_test
 
 import (
-	"bytes"
 	"fmt"
+
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/cmd"
-	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/testing"
 	"launchpad.net/juju-core/worker/uniter/jujuc"
-	stdlog "log"
+	"launchpad.net/loggo"
 )
 
 type JujuLogSuite struct {
@@ -20,36 +19,27 @@
 
 var _ = Suite(&JujuLogSuite{})
 
-func pushLog(debug bool) (*bytes.Buffer, func()) {
-	oldTarget, oldDebug := log.Target(), log.Debug
-	var buf bytes.Buffer
-	log.SetTarget(stdlog.New(&buf, "JUJU:", 0))
-	log.Debug = debug
-	return &buf, func() {
-		log.SetTarget(oldTarget)
-		log.Debug = oldDebug
-	}
-}
-
 var commonLogTests = []struct {
-	debugEnabled bool
-	debugFlag    bool
-	target       string
+	debugFlag bool
+	level     loggo.Level
 }{
-	{false, false, "JUJU:INFO"},
-	{false, true, ""},
-	{true, false, "JUJU:INFO"},
-	{true, true, "JUJU:DEBUG"},
+	{false, loggo.INFO},
+	{true, loggo.DEBUG},
 }
 
 func assertLogs(c *C, ctx jujuc.Context, badge string) {
+	loggo.ConfigureLogging("juju=DEBUG")
+	writer := &loggo.TestWriter{}
+	old_writer, err := loggo.ReplaceDefaultWriter(writer)
+	c.Assert(err, IsNil)
+	defer loggo.ReplaceDefaultWriter(old_writer)
 	msg1 := "the chickens"
 	msg2 := "are 110% AWESOME"
 	com, err := jujuc.NewCommand(ctx, "juju-log")
 	c.Assert(err, IsNil)
 	for _, t := range commonLogTests {
-		buf, pop := pushLog(t.debugEnabled)
-		defer pop()
+		writer.Clear()
+		c.Assert(err, IsNil)
 
 		var args []string
 		if t.debugFlag {
@@ -59,13 +49,9 @@
 		}
 		code := cmd.Main(com, &cmd.Context{}, args)
 		c.Assert(code, Equals, 0)
-
-		if t.target == "" {
-			c.Assert(buf.String(), Equals, "")
-		} else {
-			expect := fmt.Sprintf("%s %s: %s %s\n", t.target, badge, msg1, msg2)
-			c.Assert(buf.String(), Equals, expect)
-		}
+		c.Assert(writer.Log, HasLen, 1)
+		c.Assert(writer.Log[0].Level, Equals, t.level)
+		c.Assert(writer.Log[0].Message, Equals, fmt.Sprintf("%s: %s %s", badge, msg1, msg2))
 	}
 }
 

=== modified file 'worker/uniter/jujuc/server_test.go'
--- worker/uniter/jujuc/server_test.go	2013-05-02 15:55:42 +0000
+++ worker/uniter/jujuc/server_test.go	2013-06-04 23:43:27 +0000
@@ -10,6 +10,7 @@
 	"launchpad.net/gnuflag"
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/cmd"
+	"launchpad.net/juju-core/testing"
 	"launchpad.net/juju-core/worker/uniter/jujuc"
 	"net/rpc"
 	"os"
@@ -65,6 +66,7 @@
 }
 
 type ServerSuite struct {
+	testing.LoggingSuite
 	server   *jujuc.Server
 	sockPath string
 	err      chan error
@@ -73,6 +75,7 @@
 var _ = Suite(&ServerSuite{})
 
 func (s *ServerSuite) SetUpTest(c *C) {
+	s.LoggingSuite.SetUpTest(c)
 	s.sockPath = filepath.Join(c.MkDir(), "test.sock")
 	srv, err := jujuc.NewServer(factory, s.sockPath)
 	c.Assert(err, IsNil)
@@ -87,6 +90,7 @@
 	c.Assert(<-s.err, IsNil)
 	_, err := os.Open(s.sockPath)
 	c.Assert(os.IsNotExist(err), Equals, true)
+	s.LoggingSuite.TearDownTest(c)
 }
 
 func (s *ServerSuite) Call(c *C, req jujuc.Request) (resp jujuc.Response, err error) {

=== modified file 'worker/uniter/uniter_test.go'
--- worker/uniter/uniter_test.go	2013-05-31 08:33:34 +0000
+++ worker/uniter/uniter_test.go	2013-06-04 23:43:27 +0000
@@ -168,15 +168,16 @@
 }
 
 func (ctx *context) matchLogHooks(c *C) (match bool, overshoot bool) {
+	// TODO: fix this to actually use a log writer to catch interesting log messages.
 	// hookPattern matches juju-log calls as generated by writeHook.
-	hookPattern := fmt.Sprintf(`^.* INFO `+
+	hookPattern := fmt.Sprintf(`^.* INFO juju `+
 		`u/0(| [a-z0-9-]+:[0-9]+)`+ // juju-log badge; group matches relation id
 		`: %s`+ // JUJU_ENV_UUID (context badge; prevents cross-test pollution)
 		` ([0-9a-z-/ ]+)$`, // foo-relation-joined bar/123
 		ctx.uuid,
 	)
 	// donePattern matches uniter logging that indicates a hook has run.
-	donePattern := `^.* (INFO|ERROR) worker/uniter: (ran "[a-z0-9-]+" hook|hook failed)`
+	donePattern := `^.* (INFO|ERROR) juju worker/uniter: (ran "[a-z0-9-]+" hook|hook failed)`
 	hookRegexp := regexp.MustCompile(hookPattern)
 	doneRegexp := regexp.MustCompile(donePattern)