From bf1e87d9bde1a0677394f08a71cea56d4fa2f6f8 Mon Sep 17 00:00:00 2001 From: "John R. Lenton" Date: Fri, 8 May 2015 18:02:45 +0100 Subject: new, simpler? logger --- logger/logger.go | 198 ++++++++++++-------------------- logger/logger_test.go | 306 +++++++++----------------------------------------- 2 files changed, 121 insertions(+), 383 deletions(-) (limited to 'logger') 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`) } -- cgit v1.2.3