Merge pull request #43 from SimonRichardson/logging-config-for-new-lo…

…ggers

#43

As labels are created with lazy configurations, newly added loggers
didn't come up with the correct label set. To fix this, we keep around a
labels config map that can ensure that the labels is correctly set with
the right level.

benchmarks_test.go

@@ -28,15 +28,15 @@ func (s *BenchmarksSuite) SetUpTest(c *gc.C) {
 
 func (s *BenchmarksSuite) BenchmarkLoggingNoWriters(c *gc.C) {
 	// No writers
-	loggo.RemoveWriter("test")
+	_, _ = loggo.RemoveWriter("test")
 	for i := 0; i < c.N; i++ {
 		s.logger.Warningf("just a simple warning for %d", i)
 	}
 }
 
 func (s *BenchmarksSuite) BenchmarkLoggingNoWritersNoFormat(c *gc.C) {
 	// No writers
-	loggo.RemoveWriter("test")
+	_, _ = loggo.RemoveWriter("test")
 	for i := 0; i < c.N; i++ {
 		s.logger.Warningf("just a simple warning")
 	}
@@ -68,7 +68,10 @@ func (s *BenchmarksSuite) BenchmarkLoggingDiskWriterNoMessages(c *gc.C) {
 	// Change the log level
 	writer, err := loggo.RemoveWriter("testfile")
 	c.Assert(err, gc.IsNil)
-	loggo.RegisterWriter("testfile", loggo.NewMinimumLevelWriter(writer, loggo.WARNING))
+
+	err = loggo.RegisterWriter("testfile", loggo.NewMinimumLevelWriter(writer, loggo.WARNING))
+	c.Assert(err, gc.IsNil)
+
 	msg := "just a simple warning for %d"
 	for i := 0; i < c.N; i++ {
 		s.logger.Debugf(msg, i)
@@ -84,6 +87,7 @@ func (s *BenchmarksSuite) BenchmarkLoggingDiskWriterNoMessagesLogLevel(c *gc.C)
 	defer logFile.Close()
 	// Change the log level
 	s.logger.SetLogLevel(loggo.WARNING)
+
 	msg := "just a simple warning for %d"
 	for i := 0; i < c.N; i++ {
 		s.logger.Debugf(msg, i)
@@ -95,9 +99,10 @@ func (s *BenchmarksSuite) BenchmarkLoggingDiskWriterNoMessagesLogLevel(c *gc.C)
 }
 
 func (s *BenchmarksSuite) setupTempFileWriter(c *gc.C) *os.File {
-	loggo.RemoveWriter("test")
+	_, _ = loggo.RemoveWriter("test")
 	logFile, err := ioutil.TempFile(c.MkDir(), "loggo-test")
 	c.Assert(err, gc.IsNil)
+
 	writer := loggo.NewSimpleWriter(logFile, loggo.DefaultFormatter)
 	err = loggo.RegisterWriter("testfile", writer)
 	c.Assert(err, gc.IsNil)

context.go

@@ -16,8 +16,10 @@ type Context struct {
 	root *module
 
 	// Perhaps have one mutex?
-	modulesMutex sync.Mutex
-	modules      map[string]*module
+	// All `modules` variables are managed by the one mutex.
+	modulesMutex       sync.Mutex
+	modules            map[string]*module
+	modulesLabelConfig map[string]Level
 
 	writersMutex sync.Mutex
 	writers      map[string]Writer
@@ -33,8 +35,9 @@ func NewContext(rootLevel Level) *Context {
 		rootLevel = WARNING
 	}
 	context := &Context{
-		modules: make(map[string]*module),
-		writers: make(map[string]Writer),
+		modules:            make(map[string]*module),
+		modulesLabelConfig: make(map[string]Level),
+		writers:            make(map[string]Writer),
 	}
 	context.root = &module{
 		level:   rootLevel,
@@ -86,7 +89,7 @@ func (c *Context) getLoggerModule(name string, labels []string) *module {
 	if found {
 		return impl
 	}
-	parentName := ""
+	var parentName string
 	if i := strings.LastIndex(name, "."); i >= 0 {
 		parentName = name[0:i]
 	}
@@ -97,13 +100,21 @@ func (c *Context) getLoggerModule(name string, labels []string) *module {
 
 	// Ensure that we create a new logger module for the name, that includes the
 	// label.
-	labelMap := map[string]struct{}{}
+	level := UNSPECIFIED
+	labelMap := make(map[string]struct{})
 	for _, label := range labels {
 		labelMap[label] = struct{}{}
+
+		// First label wins when setting the logger label from the config label
+		// level cache. If there are no label configs, then fallback to
+		// UNSPECIFIED and inherit the level correctly.
+		if configLevel, ok := c.modulesLabelConfig[label]; ok && level == UNSPECIFIED {
+			level = configLevel
+		}
 	}
 	impl = &module{
 		name:         name,
-		level:        UNSPECIFIED,
+		level:        level,
 		parent:       parent,
 		context:      c,
 		labels:       labels,
@@ -168,6 +179,9 @@ func (c *Context) ApplyConfig(config Config) {
 			continue
 		}
 
+		// Ensure that we save the config for lazy loggers to pick up correctly.
+		c.modulesLabelConfig[label] = level
+
 		// Config contains a named label, use that for selecting the loggers.
 		modules := c.getLoggerModulesByLabel(label)
 		for _, module := range modules {
@@ -185,6 +199,8 @@ func (c *Context) ResetLoggerLevels() {
 	for _, module := range c.modules {
 		module.setLevel(UNSPECIFIED)
 	}
+	// We can safely just wipe everything here.
+	c.modulesLabelConfig = make(map[string]Level)
 }
 
 func (c *Context) write(entry Entry) {

context_test.go

@@ -104,7 +104,8 @@ func (*ContextSuite) TestNewContextNoWriter(c *gc.C) {
 func (*ContextSuite) newContextWithTestWriter(c *gc.C, level loggo.Level) (*loggo.Context, *loggo.TestWriter) {
 	writer := &loggo.TestWriter{}
 	context := loggo.NewContext(level)
-	context.AddWriter("test", writer)
+	err := context.AddWriter("test", writer)
+	c.Assert(err, gc.IsNil)
 	return context, writer
 }
 
@@ -259,6 +260,84 @@ func (*ContextSuite) TestApplyConfigLabels(c *gc.C) {
 		})
 }
 
+func (*ContextSuite) TestApplyConfigLabelsAppliesToNewLoggers(c *gc.C) {
+	context := loggo.NewContext(loggo.WARNING)
+
+	context.ApplyConfig(loggo.Config{"#one": loggo.TRACE})
+	context.ApplyConfig(loggo.Config{"#two": loggo.DEBUG})
+
+	context.GetLogger("a.b", "one")
+	context.GetLogger("c.d", "one")
+	context.GetLogger("e", "two")
+
+	c.Assert(context.Config(), gc.DeepEquals,
+		loggo.Config{
+			"":    loggo.WARNING,
+			"a.b": loggo.TRACE,
+			"c.d": loggo.TRACE,
+			"e":   loggo.DEBUG,
+		})
+	c.Assert(context.CompleteConfig(), gc.DeepEquals,
+		loggo.Config{
+			"":    loggo.WARNING,
+			"a":   loggo.UNSPECIFIED,
+			"a.b": loggo.TRACE,
+			"c":   loggo.UNSPECIFIED,
+			"c.d": loggo.TRACE,
+			"e":   loggo.DEBUG,
+		})
+}
+
+func (*ContextSuite) TestApplyConfigLabelsAppliesToNewLoggersWithMultipleTags(c *gc.C) {
+	context := loggo.NewContext(loggo.WARNING)
+
+	// Invert the order here, to ensure that the config order doesn't matter,
+	// but the way the tags are ordered in `GetLogger`.
+	context.ApplyConfig(loggo.Config{"#two": loggo.DEBUG})
+	context.ApplyConfig(loggo.Config{"#one": loggo.TRACE})
+
+	context.GetLogger("a.b", "one", "two")
+
+	c.Assert(context.Config(), gc.DeepEquals,
+		loggo.Config{
+			"":    loggo.WARNING,
+			"a.b": loggo.TRACE,
+		})
+	c.Assert(context.CompleteConfig(), gc.DeepEquals,
+		loggo.Config{
+			"":    loggo.WARNING,
+			"a":   loggo.UNSPECIFIED,
+			"a.b": loggo.TRACE,
+		})
+}
+
+func (*ContextSuite) TestApplyConfigLabelsResetLoggerLevels(c *gc.C) {
+	context := loggo.NewContext(loggo.WARNING)
+
+	context.ApplyConfig(loggo.Config{"#one": loggo.TRACE})
+	context.ApplyConfig(loggo.Config{"#two": loggo.DEBUG})
+
+	context.GetLogger("a.b", "one")
+	context.GetLogger("c.d", "one")
+	context.GetLogger("e", "two")
+
+	context.ResetLoggerLevels()
+
+	c.Assert(context.Config(), gc.DeepEquals,
+		loggo.Config{
+			"": loggo.WARNING,
+		})
+	c.Assert(context.CompleteConfig(), gc.DeepEquals,
+		loggo.Config{
+			"":    loggo.WARNING,
+			"a":   loggo.UNSPECIFIED,
+			"a.b": loggo.UNSPECIFIED,
+			"c":   loggo.UNSPECIFIED,
+			"c.d": loggo.UNSPECIFIED,
+			"e":   loggo.UNSPECIFIED,
+		})
+}
+
 func (*ContextSuite) TestApplyConfigLabelsAddative(c *gc.C) {
 	context := loggo.NewContext(loggo.WARNING)
 	context.ApplyConfig(loggo.Config{"#one": loggo.TRACE})
@@ -420,7 +499,6 @@ func (*ContextSuite) TestWriter(c *gc.C) {
 	c.Check(context.Writer("second"), gc.Equals, second)
 
 	c.Check(first, gc.Not(gc.Equals), second)
-
 }
 
 type writer struct {

example/main.go

@@ -2,18 +2,20 @@ package main
 
 import (
 	"fmt"
+	"log"
 	"os"
 
 	"github.com/juju/loggo"
 )
 
-var logger = loggo.GetLogger("main")
 var rootLogger = loggo.GetLogger("")
 
 func main() {
 	args := os.Args
 	if len(args) > 1 {
-		loggo.ConfigureLoggers(args[1])
+		if err := loggo.ConfigureLoggers(args[1]); err != nil {
+			log.Fatal(err)
+		}
 	} else {
 		fmt.Println("Add a parameter to configure the logging:")
 		fmt.Println("E.g. \"<root>=INFO;first=TRACE\"")

export_test.go

@@ -16,5 +16,5 @@ func (c *Context) WriterNames() []string {
 
 func ResetDefaultContext() {
 	ResetLogging()
-	DefaultContext().AddWriter(DefaultWriterName, defaultWriter())
+	_ = DefaultContext().AddWriter(DefaultWriterName, defaultWriter())
 }

global.go

@@ -9,7 +9,9 @@ var (
 
 func newDefaultContxt() *Context {
 	ctx := NewContext(WARNING)
-	ctx.AddWriter(DefaultWriterName, defaultWriter())
+	if err := ctx.AddWriter(DefaultWriterName, defaultWriter()); err != nil {
+		panic(err)
+	}
 	return ctx
 }
 

go.mod

@@ -0,0 +1,11 @@
+module github.com/juju/loggo
+
+go 1.14
+
+require (
+	github.com/juju/ansiterm v0.0.0-20180109212912-720a0952cc2a
+	github.com/lunixbochs/vtclean v0.0.0-20160125035106-4fbf7632a2c6
+	github.com/mattn/go-colorable v0.0.6
+	github.com/mattn/go-isatty v0.0.0-20160806122752-66b8e73f3f5c
+	gopkg.in/check.v1 v1.0.0-20160105164936-4f90aeace3a2
+)

go.sum

@@ -0,0 +1,8 @@
+github.com/juju/ansiterm v0.0.0-20180109212912-720a0952cc2a h1:FaWFmfWdAUKbSCtOU2QjDaorUexogfaMgbipgYATUMU=
+github.com/juju/ansiterm v0.0.0-20180109212912-720a0952cc2a/go.mod h1:UJSiEoRfvx3hP73CvoARgeLjaIOjybY9vj8PUPPFGeU=
+github.com/lunixbochs/vtclean v0.0.0-20160125035106-4fbf7632a2c6/go.mod h1:pHhQNgMf3btfWnGBVipUOjRYhoOsdGqdm/+2c2E2WMI=
+github.com/mattn/go-colorable v0.0.6 h1:jGqlOoCjqVR4hfTO9H1qrR2xi0xZNYmX2T1xlw7P79c=
+github.com/mattn/go-colorable v0.0.6/go.mod h1:9vuHe8Xs5qXnSaW/c/ABM9alt+Vo+STaOChaDxuIBZU=
+github.com/mattn/go-isatty v0.0.0-20160806122752-66b8e73f3f5c h1:3nKFouDdpgGUV/uerJcYWH45ZbJzX0SiVWfTgmUeTzc=
+github.com/mattn/go-isatty v0.0.0-20160806122752-66b8e73f3f5c/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4=
+gopkg.in/check.v1 v1.0.0-20160105164936-4f90aeace3a2/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=

logging_test.go

@@ -26,7 +26,8 @@ var _ = gc.Suite(&LoggingSuite{Labels: []string{"ONE", "TWO"}})
 func (s *LoggingSuite) SetUpTest(c *gc.C) {
 	s.writer = &writer{}
 	s.context = loggo.NewContext(loggo.TRACE)
-	s.context.AddWriter("test", s.writer)
+	err := s.context.AddWriter("test", s.writer)
+	c.Assert(err, gc.IsNil)
 	s.logger = s.context.GetLogger("test", s.Labels...)
 }
 

module.go

@@ -5,9 +5,7 @@ package loggo
 
 // Do not change rootName: modules.resolve() will misbehave if it isn't "".
 const (
-	rootString       = "<root>"
-	defaultRootLevel = WARNING
-	defaultLevel     = UNSPECIFIED
+	rootString = "<root>"
 )
 
 type module struct {