new, simpler? logger

2 files changed, 121 insertions, 383 deletions

diff --git a/logger/logger.go b/logger/logger.go
index 3d3af0e271..d55f589dfd 100644
--- a/logger/logger.go
+++ b/logger/logger.go
@@ -19,171 +19,115 @@ package logger
 
 import (
	"fmt"
+	"io"
+	"log"
	"log/syslog"
-	"runtime/debug"
-	"strings"
+	"os"
	"sync"
-	"time"
-
-	"github.com/juju/loggo"
 )
 
-// Name used in the prefix for all logged messages
-const LoggerName = "snappy"
-
-// logWriterInterface allows the tests to replace the syslog
-// implementation.
-type logWriterInterface interface {
-	// syslog.Writer
-	Debug(m string) error
-	Info(m string) error
-	Warning(m string) error
-	Err(m string) error
-	Crit(m string) error
-}
-
-// LogWriter object that handles writing log entries
-type LogWriter struct {
-	systemLog logWriterInterface
+type Logger interface {
+	// Notify is for messages that the user should see
+	Notice(msg string)
+	// Debug is for messages that the user should be able to find if they're debugging something
+	Debug(msg string)
 }
 
-// Used to ensure that only a single connection to syslog is created
-var once sync.Once
+const (
+	DefaultFlags = log.Ldate | log.Ltime | log.Lmicroseconds | log.Lshortfile
+	SyslogFlags = log.Lshortfile
+	SyslogPriority = syslog.LOG_DEBUG | syslog.LOG_USER
+)
 
-// A single connection to the system logger
-var syslogConnection logWriterInterface
+type nullLogger struct{}
 
-// Write sends the log details specified by the params to the logging
-// back-end (in this case syslog).
-func (l *LogWriter) Write(level loggo.Level, name string, filename string, line int, timestamp time.Time, message string) {
-	var f func(string) error
+func (nullLogger) Notice(string) {}
+func (nullLogger) Debug(string) {}
 
-	record := l.Format(level, name, filename, line, timestamp, message)
+// NullLogger is a logger that does nothing
+var NullLogger = nullLogger{}
 
-	// map log level to syslog priority
-	switch level {
-	case loggo.DEBUG:
-	f = l.systemLog.Debug
+var (
+	logger Logger = NullLogger
+	lock sync.Mutex
+)
 
-	case loggo.INFO:
-	f = l.systemLog.Info
+// Panic notifies the user and then panics
+func Panic(format string, v ...interface{}) {
+	msg := fmt.Sprintf(format, v...)
 
-	case loggo.WARNING:
-	f = l.systemLog.Warning
+	lock.Lock()
+	defer lock.Unlock()
 
-	case loggo.ERROR:
-	f = l.systemLog.Err
+	logger.Notice("PANIC " + msg)
+	panic(msg)
+}
 
-	case loggo.CRITICAL:
-	f = l.systemLog.Crit
-	}
+// Notice notifies the user of something
+func Notice(format string, v ...interface{}) {
+	msg := fmt.Sprintf(format, v...)
 
-	// write the log record.
-	//
-	// Note that with loggo, the actual logging functions never
-	// return errors, so although these syslog functions may fail,
-	// there's not much we can do about it.
-	f(record)
+	lock.Lock()
+	defer lock.Unlock()
 
-	if level >= loggo.ERROR {
-	l.logStacktrace(level, name, filename, line, timestamp, f)
-	}
+	logger.Notice(msg)
 }
 
-func (l *LogWriter) logStacktrace(level loggo.Level, name string, filename string, line int, timestamp time.Time, f func(string) error) {
-	stack := debug.Stack()
-
-	str := "Stack trace:"
-	record := l.Format(level, name, filename, line, timestamp, str)
-	f(record)
+// Debug records something in the debug log
+func Debug(format string, v ...interface{}) {
+	msg := fmt.Sprintf(format, v...)
 
-	for _, entry := range strings.Split(string(stack), "\n") {
-	if entry == "" {
-	continue
-	}
+	lock.Lock()
+	defer lock.Unlock()
 
-	formatted := fmt.Sprintf(" %s", strings.Replace(entry, "\t", " ", -1))
-	record := l.Format(level, name, filename, line, timestamp, formatted)
-	f(record)
-	}
+	logger.Debug(msg)
 }
 
-// Format handles how each log entry should appear.
-// Note that the timestamp field is not used as syslog adds that for us.
-func (l *LogWriter) Format(level loggo.Level, module, filename string, line int, timestamp time.Time, message string) string {
-	if level < loggo.ERROR {
-	// keep it relatively succinct for low priority messages
-	return fmt.Sprintf("%s:%s:%s", level, module, message)
-	}
+// Set the global logger to the given one
+func SetLogger(l Logger) {
+	lock.Lock()
+	defer lock.Unlock()
 
-	return fmt.Sprintf("%s:%s:%s:%d:%s", level, module, filename, line, message)
+	logger = l
 }
 
-// A variable to make testing easier
-var getSyslog = func(priority syslog.Priority, tag string) (w logWriterInterface, err error) {
-	return syslog.New(syslog.LOG_NOTICE|syslog.LOG_LOCAL0, LoggerName)
+// ConsoleLog sends Notices to a log.Logger and Debugs to syslog
+type ConsoleLog struct {
+	log *log.Logger
+	sys *log.Logger
 }
 
-// newLogWriter creates a new LogWriter, ensuring that only a single
-// connection to the system logger is created.
-func newLogWriter() (l *LogWriter, err error) {
-
-	l = new(LogWriter)
-
-	once.Do(func() {
+// Debug sends the msg to syslog
+func (l *ConsoleLog) Debug(msg string) {
+	l.sys.Output(3, "DEBUG: "+msg)
+}
 
-	// Note that the log level here is just the default - Write()
-	// will alter it as needed.
-	syslogConnection, err = getSyslog(syslog.LOG_NOTICE|syslog.LOG_LOCAL0, LoggerName)
-	})
+// Notice alerts the user about something, as well as putting it syslog
+func (l *ConsoleLog) Notice(msg string) {
+	l.sys.Output(3, msg)
+	l.log.Output(3, msg)
+}
 
+// NewConsoleLog creates a ConsoleLog with a log.Logger using the given
+// io.Writer and flag, and a syslog.Writer.
+func NewConsoleLog(w io.Writer, flag int) (*ConsoleLog, error) {
+	sys, err := syslog.NewLogger(SyslogPriority, SyslogFlags)
	if err != nil {
	return nil, err
	}
 
-	l.systemLog = syslogConnection
-
-	return l, nil
+	return &ConsoleLog{
+	log: log.New(w, "", flag),
+	sys: sys,
+	}, nil
 }
 
-// ActivateLogger handles creating, configuring and enabling a new syslog logger.
-func ActivateLogger() (err error) {
-	// Remove any existing loggers of the type we care about.
-	//
-	// No check on the success of these operations is performed since the
-	// loggo API does not allow the existing loggers to be iterated so we
-	// cannot know if there is already a syslog writer registered (for
-	// example if newLogWriter() gets called multiple times).
-	_, _, _ = loggo.RemoveWriter("default")
-	_, _, _ = loggo.RemoveWriter("syslog")
-
-	writer, err := newLogWriter()
-	if err != nil {
-	return err
-	}
-
-	// activate our syslog logger
-	err = loggo.RegisterWriter("syslog", writer, loggo.TRACE)
+func SimpleSetup() error {
+	l, err := NewConsoleLog(os.Stderr, DefaultFlags)
	if err != nil {
	return err
	}
-
-	logger := loggo.GetLogger(LoggerName)
-
-	// ensure that all log messages are output
-	logger.SetLogLevel(loggo.TRACE)
+	SetLogger(l)
 
	return nil
 }
-
-// LogAndPanic logs the specified error, including a backtrace, then calls
-// panic().
-func LogAndPanic(err error) {
-	if err == nil {
-	return
-	}
-
-	logger := loggo.GetLogger(LoggerName)
-	logger.Criticalf(err.Error())
-	panic(err)
-}
diff --git a/logger/logger_test.go b/logger/logger_test.go
index 53fe31687a..9e820bfe33 100644
--- a/logger/logger_test.go
+++ b/logger/logger_test.go
@@ -18,293 +18,87 @@
 package logger
 
 import (
-	"bytes"
-	"errors"
-	"fmt"
-	"log/syslog"
-	"regexp"
-	"strings"
	"testing"
-	"time"
 
-	"github.com/juju/loggo"
+	"bytes"
	. "launchpad.net/gocheck"
+	"log"
 )
 
+// Hook up gocheck into the "go test" runner
 func Test(t *testing.T) { TestingT(t) }
 
-type LoggerTestSuite struct {
-}
-
-var _ = Suite(&LoggerTestSuite{})
-
-type MockLogWriter struct {
-	buf bytes.Buffer
-}
-
-var mockWriter *MockLogWriter
-
-var loggoLevels = []string{"DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"}
-
-func mockGetSyslog(priority syslog.Priority, tag string) (w logWriterInterface, err error) {
-	mockWriter = &MockLogWriter{}
-	return mockWriter, nil
-}
-
-func readLines() (lines []string) {
-	lines = strings.Split(string(mockWriter.buf.Bytes()), "\n")
-
-	// remove the last line if empty due to split.
-	length := len(lines)
-	last := lines[length-1]
-	if last == "" {
-	lines = lines[:length-1]
-	}
-	// clear the buffer to avoid contents accumulating indefinitely
-	mockWriter.buf.Reset()
-	return lines
-}
-
-func (ts *LoggerTestSuite) SetUpTest(c *C) {
-	getSyslog = mockGetSyslog
-}
+var _ = Suite(&LogSuite{})
 
-func (w *MockLogWriter) Debug(m string) error {
-	_, err := w.buf.Write([]byte(fmt.Sprintf("DEBUG: %s\n", m)))
-	return err
-}
+type LogSuite struct{}
 
-func (w *MockLogWriter) Info(m string) error {
-	_, err := w.buf.Write([]byte(fmt.Sprintf("INFO: %s\n", m)))
-	return err
+func (s *LogSuite) SetUpTest(c *C) {
+	c.Assert(logger, Equals, NullLogger)
 }
 
-func (w *MockLogWriter) Warning(m string) error {
-	_, err := w.buf.Write([]byte(fmt.Sprintf("WARNING: %s\n", m)))
-	return err
-}
-
-func (w *MockLogWriter) Err(m string) error {
-	_, err := w.buf.Write([]byte(fmt.Sprintf("ERROR: %s\n", m)))
-	return err
-}
-
-func (w *MockLogWriter) Crit(m string) error {
-	_, err := w.buf.Write([]byte(fmt.Sprintf("CRITICAL: %s\n", m)))
-	return err
-}
-
-// Search for value in array and return true if found
-func sliceContainsString(array []string, value string) bool {
-	str := string(strings.Join(array, ""))
-
-	return strings.Contains(str, value)
-}
-
-// Return true if array contains the pattern regex.
-func sliceContainsRegex(array []string, regex string) bool {
-	str := string(strings.Join(array, ""))
-
-	pattern := regexp.MustCompile(regex)
-
-	matches := pattern.FindAllStringSubmatch(str, -1)
-
-	return matches != nil
-}
-
-func (ts *LoggerTestSuite) TestNewLogWriter(c *C) {
-	var w, w2 *LogWriter
-	var err error
-
-	w, err = newLogWriter()
-	c.Assert(err, IsNil)
-	c.Assert(w, Not(IsNil))
-	c.Assert(w.systemLog, Not(IsNil))
-
-	w2, err = newLogWriter()
-	c.Assert(err, IsNil)
-	c.Assert(w2, Not(IsNil))
-	c.Assert(w2.systemLog, Not(IsNil))
-
-	// There should be a single shared syslog connection, hence the
-	// systemLog objects should be identical.
-	c.Assert(w.systemLog, Equals, w2.systemLog)
-	c.Assert(w.systemLog, DeepEquals, w2.systemLog)
-}
-
-func (ts *LoggerTestSuite) TestWrite(c *C) {
-	w, err := newLogWriter()
-	c.Assert(err, IsNil)
-	c.Assert(w, Not(IsNil))
-	c.Assert(w.systemLog, Not(IsNil))
-
-	t := time.Now()
-	strTime := fmt.Sprintf("%s", t)
-
-	for _, l := range loggoLevels {
-	level := stringToLogLevel(l)
-
-	w.Write(level, "module", "filename", 1234, t, "a message")
-	lines := readLines()
-
-	if level < loggo.ERROR {
-	c.Assert(len(lines), Equals, 1)
-	} else {
-	c.Assert(len(lines) > 1, Equals, true)
-
-	c.Assert(sliceContainsString(lines, "filename"), Equals, true)
-	c.Assert(sliceContainsString(lines, "1234"), Equals, true)
-	}
-
-	c.Assert(sliceContainsString(lines, "module"), Equals, true)
-
-	// We discard the timestamp as syslog adds that itself
-	c.Assert(sliceContainsString(lines, strTime), Equals, false)
-
-	c.Assert(sliceContainsString(lines, "a message"), Equals, true)
-	}
-
+func (s *LogSuite) TearDownTest(c *C) {
+	SetLogger(NullLogger)
 }
 
-// Convert a loggo log level string representation into a real log
-// level.
-func stringToLogLevel(name string) loggo.Level {
-	level, ok := loggo.ParseLevel(name)
-
-	if !ok {
-	panic(fmt.Sprintf("unknown loggo level string: %q", name))
+func (s *LogSuite) TestDefault(c *C) {
+	if logger != nil {
+	SetLogger(nil)
	}
+	c.Check(logger, IsNil)
 
-	return level
+	err := SimpleSetup()
+	c.Check(err, IsNil)
+	c.Check(logger, NotNil)
+	SetLogger(nil)
 }
 
-func (ts *LoggerTestSuite) TestFormat(c *C) {
-	w, err := newLogWriter()
+func (s *LogSuite) TestNew(c *C) {
+	var buf bytes.Buffer
+	l, err := NewConsoleLog(&buf, DefaultFlags)
	c.Assert(err, IsNil)
-	c.Assert(w, Not(IsNil))
-	c.Assert(w.systemLog, Not(IsNil))
-
-	for _, l := range loggoLevels {
-	level := stringToLogLevel(l)
-
-	if level < loggo.ERROR {
-	out := w.Format(level, "module", "filename", 1234, time.Now(), "a message")
-	c.Assert(out, Equals, fmt.Sprintf("%s:%s:%s", l, "module", "a message"))
-	} else {
-	out := w.Format(level, "module", "filename", 1234, time.Now(), "a message")
-	c.Assert(out, Equals, fmt.Sprintf("%s:%s:%s:%d:%s", l, "module", "filename", 1234, "a message"))
-	}
-	}
+	c.Assert(l, NotNil)
+	c.Check(l.sys, NotNil)
+	c.Check(l.log, NotNil)
 }
 
-func (ts *LoggerTestSuite) TestLogStackTrace(c *C) {
-	var output []string
-
-	w, err := newLogWriter()
+func (s *LogSuite) TestDebug(c *C) {
+	var logbuf bytes.Buffer
+	var sysbuf bytes.Buffer
+	l, err := NewConsoleLog(&logbuf, DefaultFlags)
	c.Assert(err, IsNil)
-	c.Assert(w, Not(IsNil))
 
-	f := func(s string) error {
-	output = append(output, s)
-	return nil
-	}
-
-	t := time.Now()
-	strTime := fmt.Sprintf("%s", t)
-
-	w.logStacktrace(loggo.DEBUG, "name", "filename", 9876, t, f)
+	l.sys = log.New(&sysbuf, "", SyslogFlags)
+	SetLogger(l)
 
-	c.Assert(sliceContainsString(output, "Stack trace"), Equals, true)
-	c.Assert(sliceContainsString(output, "name"), Equals, true)
-	c.Assert(sliceContainsString(output, "filename"), Equals, true)
-	c.Assert(sliceContainsString(output, "9876"), Equals, true)
-
-	// We discard the timestamp as syslog adds that itself
-	c.Assert(sliceContainsString(output, strTime), Equals, false)
+	Debug("xyzzy")
+	c.Check(sysbuf.String(), Matches, `(?m).*logger_test\.go:\d+: DEBUG: xyzzy`)
+	c.Check(logbuf.String(), Equals, "")
 }
 
-func (ts *LoggerTestSuite) checkLogLevel(c *C, level, msg string) {
-	err := ActivateLogger()
+func (s *LogSuite) TestNotice(c *C) {
+	var logbuf bytes.Buffer
+	var sysbuf bytes.Buffer
+	l, err := NewConsoleLog(&logbuf, DefaultFlags)
	c.Assert(err, IsNil)
 
-	expectBacktrace := (level == "ERROR" || level == "CRITICAL")
-
-	logger := loggo.GetLogger("snappy")
-	c.Assert(logger, Not(IsNil))
+	l.sys = log.New(&sysbuf, "", SyslogFlags)
+	SetLogger(l)
 
-	switch level {
-	case "DEBUG":
-	c.Assert(logger.IsDebugEnabled(), Equals, true)
-	logger.Debugf(msg)
-
-	case "INFO":
-	c.Assert(logger.IsInfoEnabled(), Equals, true)
-	logger.Infof(msg)
-
-	case "WARNING":
-	c.Assert(logger.IsWarningEnabled(), Equals, true)
-	logger.Warningf(msg)
-
-	case "ERROR":
-	c.Assert(logger.IsErrorEnabled(), Equals, true)
-	logger.Errorf(msg)
-
-	case "CRITICAL":
-	// loggo doesn't provide a IsCriticalEnabled()
-	c.Assert(logger.IsErrorEnabled(), Equals, true)
-	logger.Criticalf(msg)
-	}
-
-	lines := readLines()
-
-	if expectBacktrace {
-	c.Assert(len(lines) > 1, Equals, true)
-	} else {
-	c.Assert(len(lines), Equals, 1)
-	}
-
-	needle := fmt.Sprintf("%s.*%s", level, msg)
-	c.Assert(sliceContainsRegex(lines, needle), Equals, true)
-
-	c.Assert(sliceContainsString(lines, "Stack trace"), Equals, expectBacktrace)
+	Notice("xyzzy")
+	c.Check(sysbuf.String(), Matches, `(?m).*logger_test\.go:\d+: xyzzy`)
+	c.Check(logbuf.String(), Matches, `(?m).*logger_test\.go:\d+: xyzzy`)
 }
 
-func (ts *LoggerTestSuite) TestLogLevels(c *C) {
-	msg := "an error message"
-
-	for _, level := range loggoLevels {
-	ts.checkLogLevel(c, level, msg)
-	}
-}
-
-func (ts *LoggerTestSuite) TestLogAndPanic(c *C) {
-	level := "CRITICAL"
-	msg := "I am a fatal error"
-
-	panicked := false
-
-	err := ActivateLogger()
+func (s *LogSuite) TestPanic(c *C) {
+	var logbuf bytes.Buffer
+	var sysbuf bytes.Buffer
+	l, err := NewConsoleLog(&logbuf, DefaultFlags)
	c.Assert(err, IsNil)
 
-	// If the specified error is nil, no panic is expected and no
-	// log entry should be added.
-	func() {
-	defer func() {
-	if r := recover(); r != nil {
-	panicked = true
-	}
-	}()
-	LogAndPanic(nil)
-	}()
-
-	c.Assert(panicked, Equals, false)
-	c.Assert(len(readLines()), Equals, 0)
-
-	err = errors.New(msg)
-
-	// expect a panic...
-	c.Assert(func() { LogAndPanic(err) }, Panics, err)
+	l.sys = log.New(&sysbuf, "", SyslogFlags)
+	SetLogger(l)
 
-	// ... and a log entry
-	ts.checkLogLevel(c, level, msg)
+	c.Check(func() { Panic("xyzzy") }, Panics, "xyzzy")
+	c.Check(sysbuf.String(), Matches, `(?m).*logger_test\.go:\d+: PANIC xyzzy`)
+	c.Check(logbuf.String(), Matches, `(?m).*logger_test\.go:\d+: PANIC xyzzy`)
 }