diff --git a/logging/log.go b/logging/log.go index ac631fb..b632932 100644 --- a/logging/log.go +++ b/logging/log.go @@ -10,23 +10,52 @@ import ( ) // A simple level-based logging system. -// Note that higher levels of logging are still usable via Log() -// Also, remember to call flag.Parse() near the start of your func main() + +// Note that higher levels of logging are still usable via Log(). They will be +// output to the debug log in split mode if --log.level is set high enough. + +// Also, remember to call flag.Parse() near the start of your func main()! + +// The enforced singleton style of the standard "log" pkg is very nice, but +// it encourages people to write less testable code, and while logging is one +// of the few places where a singleton is not necessarily bad practise, it's +// not *that* hard to propagate your logging to where it needs to be. +// Alternatively you can create your own damn singleton with this package ;-) + +type LogLevel int +type LogMap map[LogLevel]*log.Logger + const ( - LogFatal = iota - 1 - LogError - LogWarn - LogInfo - LogDebug + Fatal LogLevel = iota - 1 + Error + Warn + Info + Debug ) +var logString map[LogLevel]string = map[LogLevel]string{ + Fatal: "FATAL", + Error: "ERROR", + Warn: "WARN", + Info: "INFO", + Debug: "DEBUG", +} +func LogString(lv LogLevel) string { + if s, ok := logString[lv]; ok { + return s + } + return fmt.Sprintf("LOG(%d)", lv) +} + var ( file = flag.String("log.file", "", "Log to this file rather than STDERR") - level = flag.Int("log.level", LogError, + level = flag.Int("log.level", int(Error), "Level of logging to be output") only = flag.Bool("log.only", false, "Only log output at the selected level") + split = flag.Bool("log.split", false, + "Log to one file per log level Error/Warn/Info/Debug.") // Shortcut flags for great justice quiet = flag.Bool("log.quiet", false, @@ -53,143 +82,155 @@ type Logger interface { // Log at level -1, to STDERR always, and exit after logging. Fatal(string, ...interface{}) // Change the current log display level - SetLogLevel(int) + SetLogLevel(LogLevel) + // Set the logger to only output the current level + SetOnly(bool) } // A struct to implement the above interface type logger struct { - // We wrap a log.Logger for most of the heavy lifting + // We wrap a set of log.Logger for most of the heavy lifting // but it can't be anonymous thanks to the conflicting definitions of Fatal - log *log.Logger - level int + log LogMap + level LogLevel only bool *sync.Mutex // to ensure changing levels/flags is atomic } -var internal *logger +// Helper function for opening log files, causes lots of Fatal :-) +func openLog(fn string) *log.Logger { + fh, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) + if err != nil { + log.Fatalf("Error opening log file: %s", err) + } + return makeLogger(fh) +} -func init() { - /// Hopefully this won't cause pain and suffering - flag.Parse() +// Helper function to create log.Loggers out of io.Writers +func makeLogger(w io.Writer) *log.Logger { + return log.New(w, "", log.LstdFlags | log.Lshortfile) +} - // Where are we logging to? - var out io.Writer - if *file != "" { - fh, err := os.OpenFile(*file, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) - if err != nil { - log.Fatalf("Error opening log file: %s", err) - } else { - out = fh - } - } else { - out = os.Stderr +// Creates a new logger object using the flags declared above. +// You MUST call flag.Parse before calling this ;-) +// Calling this more than once is inadvisable, you may get log corruption. +func NewFromFlags() *logger { + // Sanity checks: if log.split is set, must have a log.file. + if *split && *file == "" { + log.Fatalf("You must pass --log.file with --log.split") } + lv := Error + logMap := make(LogMap) + // What are we logging? - var lv int // The shortcut flags prioritize by level, but an // explicit level flag takes first precedence. // I think the switch looks cleaner than if/else if, meh :-) switch { case *level != 0: - lv = *level + lv = LogLevel(*level) case *quiet: - lv = LogFatal + lv = Fatal case *warn: - lv = LogWarn + lv = Warn case *info: - lv = LogInfo + lv = Info case *debug: - lv = LogDebug + lv = Debug } - internal = New(out, lv, *only) + // Where are we logging to? + if *split { + // Fill in the logger map. + for l := Fatal; l <= Debug; l++ { + logMap[l] = openLog(*file + "." + logString[l]) + } + } else { + var _log *log.Logger + if *file != "" { + _log = openLog(*file) + } else { + _log = makeLogger(os.Stderr) + } + for l := Fatal; l <= Debug; l++ { + logMap[l] = _log + } + } + + return New(logMap, lv, *only) } -func New(out io.Writer, level int, only bool) *logger { - l := log.New(out, "", log.LstdFlags) - return &logger{l, level, only, &sync.Mutex{}} +// You'll have to set up your own loggers for this one... +func New(m LogMap, lv LogLevel, only bool) *logger { + // Sanity check the log map we've been passed. + // We need loggers for all levels in case SetLogLevel is called. + for l := Fatal; l <= Debug; l++ { + if _log, ok := m[l]; !ok || _log == nil { + log.Fatalf("Output log level %s has no logger configured.", + logString[l]) + } + } + return &logger{m, lv, only, &sync.Mutex{}} } // Internal function all others call to ensure identical call depth -func (l *logger) write(lv int, fm string, v ...interface{}) { - if lv > l.level { +func (l *logger) write(lv LogLevel, fm string, v ...interface{}) { + if lv > l.level || (l.only && lv != l.level) { // Your logs are not important to us, goodnight return } + fm = fmt.Sprintf(LogString(lv)+" "+fm, v...) + if _, ok := logString[lv]; !ok { + // This is an unrecognised log level, so log it to Debug + lv = Debug + } l.Lock() defer l.Unlock() - lineno := bool((l.log.Flags() & log.Lshortfile) > 0) - // Enable logging file:line if LogWarn level or worse - if lv <= LogWarn && !lineno { - l.log.SetFlags(log.LstdFlags | log.Lshortfile) - } else if lv > LogWarn && lineno { - l.log.SetFlags(log.LstdFlags) - } + _log := l.log[lv] // Writing the log is deceptively simple - l.log.Output(3, fmt.Sprintf(fm, v...)) - if lv == LogFatal { - // Always fatal to stderr too. - log.Fatalf(fm, v...) + _log.Output(3, fm) + if lv == Fatal { + // Always fatal to stderr too. Use panic so (a) we get a backtrace, + // and (b) it's trappable for testing (and maybe other times too). + log.Panic(fm) } } -func (l *logger) Log(lv int, fm string, v ...interface{}) { +func (l *logger) Log(lv LogLevel, fm string, v ...interface{}) { l.write(lv, fm, v...) } -func Log(lv int, fm string, v ...interface{}) { - internal.write(lv, fm, v...) -} - // Helper functions for specific levels func (l *logger) Debug(fm string, v ...interface{}) { - l.write(LogDebug, fm, v...) -} - -func Debug(fm string, v ...interface{}) { - internal.write(LogDebug, fm, v...) + l.write(Debug, fm, v...) } func (l *logger) Info(fm string, v ...interface{}) { - l.write(LogInfo, fm, v...) -} - -func Info(fm string, v ...interface{}) { - internal.write(LogInfo, fm, v...) + l.write(Info, fm, v...) } func (l *logger) Warn(fm string, v ...interface{}) { - l.write(LogWarn, fm, v...) -} - -func Warn(fm string, v ...interface{}) { - internal.write(LogWarn, fm, v...) + l.write(Warn, fm, v...) } func (l *logger) Error(fm string, v ...interface{}) { - l.write(LogError, fm, v...) -} - -func Error(fm string, v ...interface{}) { - internal.write(LogError, fm, v...) + l.write(Error, fm, v...) } func (l *logger) Fatal(fm string, v ...interface{}) { - l.write(LogFatal, fm, v...) + l.write(Fatal, fm, v...) } -func Fatal(fm string, v ...interface{}) { - internal.write(LogFatal, fm, v...) -} - -func (l *logger) SetLogLevel(lv int) { +func (l *logger) SetLogLevel(lv LogLevel) { l.Lock() defer l.Unlock() l.level = lv } -func SetLogLevel(lv int) { - internal.SetLogLevel(lv) +func (l *logger) SetOnly(only bool) { + l.Lock() + defer l.Unlock() + l.only = only } diff --git a/logging/log_test.go b/logging/log_test.go index 7575fa0..82e99c6 100644 --- a/logging/log_test.go +++ b/logging/log_test.go @@ -2,9 +2,22 @@ package logging import ( "os" + "strings" "testing" ) +// Note: the below is deliberately PLACED AT THE TOP OF THIS FILE because +// it is fragile. It ensures the right file:line is logged. Sorry! +func TestLogCorrectLineNumbers(t *testing.T) { + l, m := setUp() + l.Log(Error, "Error!") + if s := string(m[Error].written); s[20:] != "log_test.go:13: ERROR Error!\n" { + t.Errorf("Error incorrectly logged (check line numbers!)") + } +} + +type writerMap map[LogLevel]*mockWriter + type mockWriter struct { written []byte } @@ -14,19 +27,79 @@ func (w *mockWriter) Write(p []byte) (n int, err os.Error) { return len(p), nil } -func TestDefaultLogging(t *testing.T) { - w := &mockWriter{make([]byte, 0)} - l := New(w, LogError, false) - l.Log(4, "Nothing should be logged yet") - l.Log(LogDebug, "or yet...") - l.Log(LogWarn, "or yet!") - if len(w.written) > 0 { - t.Errorf("Unexpected low-level logging output.") +func (w *mockWriter) reset() { + w.written = w.written[:0] +} + +func setUp() (*logger, writerMap) { + wMap := writerMap{ + Debug: &mockWriter{make([]byte, 0)}, + Info: &mockWriter{make([]byte, 0)}, + Warn: &mockWriter{make([]byte, 0)}, + Error: &mockWriter{make([]byte, 0)}, + Fatal: &mockWriter{make([]byte, 0)}, } - l.Log(LogError, "Error!") - // Note: the below is deliberately fragile to ensure - // the right file:line is logged on errors. Sorry! - if s := string(w.written); s[20:] != "log_test.go:26: Error!\n" { - t.Errorf("Error incorrectly logged (check line numbers!)") + logMap := make(LogMap) + for lv, w := range wMap { + logMap[lv] = makeLogger(w) + } + return New(logMap, Error, false), wMap +} + +func (m writerMap) checkNothingWritten(t *testing.T) { + for lv, w := range m { + if len(w.written) > 0 { + t.Errorf("%d bytes logged at level %s, expected none:", + len(w.written), logString[lv]) + t.Errorf("\t%s", w.written) + w.reset() + } } } + +func (m writerMap) checkWrittenAtLevel(t *testing.T, lv LogLevel, exp string) { + var w *mockWriter + if _, ok := m[lv]; !ok { + w = m[Debug] + } else { + w = m[lv] + } + if len(w.written) == 0 { + t.Errorf("No bytes logged at level %s, expected:", LogString(lv)) + t.Errorf("\t%s", exp) + } + // 32 bytes covers the date, time and filename up to the colon in + // 2011/10/22 10:22:57 log_test.go:: + s := string(w.written[32:]) + // 3 covers the : itself and the two extra spaces + idx := strings.Index(s, ":") + len(LogString(lv)) + 3 + // s will end in "\n", so -1 to chop that off too + s = s[idx:len(s)-1] + if s != exp { + t.Errorf("Log message at level %s differed.", LogString(lv)) + t.Errorf("\texp: %s\n\tgot: %s", exp, s) + } + w.reset() +} + +func TestLogging(t *testing.T) { + l, m := setUp() + + l.Log(4, "Nothing should be logged yet") + m.checkNothingWritten(t) + + l.Log(Debug, "or yet...") + m.checkNothingWritten(t) + + l.Log(Info, "or yet...") + m.checkNothingWritten(t) + + l.Log(Warn, "or yet!") + m.checkNothingWritten(t) + + l.Log(Error, "Error!") + m.checkWrittenAtLevel(t, Error, "Error!") + // Calling checkNothingWritten here both tests that w.reset() works + // and verifies that nothing was written at any other levels than Error. + m.checkNothingWritten(t) +}