Rewrite logging package for great justice.

Allowing people to use the static functions to log things makes testing
hard, so I've removed them. I've also rewritten things to allow logging
different levels to separate files.

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
+	Fatal LogLevel = iota - 1
-	LogError
+	Error
-	LogWarn
+	Warn
-	LogInfo
+	Info
-	LogDebug
+	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
+	log         LogMap
-	level       int
+	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 {
-func init() {
+	fh, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
-	/// Hopefully this won't cause pain and suffering
-	flag.Parse()
-
-	// 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 {
+	return makeLogger(fh)
-		out = os.Stderr
+}
+
+// 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)
+}
+
+// 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 {
+// You'll have to set up your own loggers for this one...
-	l := log.New(out, "", log.LstdFlags)
+func New(m LogMap, lv LogLevel, only bool) *logger {
-	return &logger{l, level, only, &sync.Mutex{}}
+	// 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{}) {
+func (l *logger) write(lv LogLevel, fm string, v ...interface{}) {
-	if lv > l.level {
+	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)
+	_log := l.log[lv]
-	// 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)
-	}
 	// Writing the log is deceptively simple
-	l.log.Output(3, fmt.Sprintf(fm, v...))
+	_log.Output(3, fm)
-	if lv == LogFatal {
+	if lv == Fatal {
-		// Always fatal to stderr too.
+		// Always fatal to stderr too. Use panic so (a) we get a backtrace,
-		log.Fatalf(fm, v...)
+		// 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...)
+	l.write(Debug, fm, v...)
-}
-
-func Debug(fm string, v ...interface{}) {
-	internal.write(LogDebug, fm, v...)
 }
 
 func (l *logger) Info(fm string, v ...interface{}) {
-	l.write(LogInfo, fm, v...)
+	l.write(Info, fm, v...)
-}
-
-func Info(fm string, v ...interface{}) {
-	internal.write(LogInfo, fm, v...)
 }
 
 func (l *logger) Warn(fm string, v ...interface{}) {
-	l.write(LogWarn, fm, v...)
+	l.write(Warn, fm, v...)
-}
-
-func Warn(fm string, v ...interface{}) {
-	internal.write(LogWarn, fm, v...)
 }
 
 func (l *logger) Error(fm string, v ...interface{}) {
-	l.write(LogError, fm, v...)
+	l.write(Error, fm, v...)
-}
-
-func Error(fm string, v ...interface{}) {
-	internal.write(LogError, 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{}) {
+func (l *logger) SetLogLevel(lv LogLevel) {
-	internal.write(LogFatal, fm, v...)
-}
-
-func (l *logger) SetLogLevel(lv int) {
 	l.Lock()
 	defer l.Unlock()
 	l.level = lv
 }
 
-func SetLogLevel(lv int) {
+func (l *logger) SetOnly(only bool) {
-	internal.SetLogLevel(lv)
+	l.Lock()
+	defer l.Unlock()
+	l.only = only
 }

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) {
+func (w *mockWriter) reset() {
-	w := &mockWriter{make([]byte, 0)}
+	w.written = w.written[:0]
-	l := New(w, LogError, false)
+}
-	l.Log(4, "Nothing should be logged yet")
+
-	l.Log(LogDebug, "or yet...")
+func setUp() (*logger, writerMap) {
-	l.Log(LogWarn, "or yet!")
+	wMap := writerMap{
-	if len(w.written) > 0 {
+		Debug: &mockWriter{make([]byte, 0)},
-		t.Errorf("Unexpected low-level logging output.")
+		Info:  &mockWriter{make([]byte, 0)},
+		Warn:  &mockWriter{make([]byte, 0)},
+		Error: &mockWriter{make([]byte, 0)},
+		Fatal: &mockWriter{make([]byte, 0)},
+	}
+	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()
 		}
-	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!)")
 	}
 }
+
+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:<line no>: <log message>
+	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)
+}