Merge lp:~pedronis/ubuntu-push/testlog into lp:ubuntu-push

[Samuele Pedroni]

base the simple logger only on having a log.Logger-style Output(); given this we can introduce a testing.TestLogger that does redirecting of logs to the gocheck.C object if wired in SetUpTest and also does its own capture

base the simple logger only on having a log.Logger-style Output()

reexport that as we will need it for mgo logging,

given this we can introduce a testing.TestLogger that does redirecting of logs to the gocheck.C object if wired in SetUpTest and also does its own capture.

start using that in the couple of places that were depending on SyncedLogBuffer

[lp:~pedronis/ubuntu-push/testlog]

54. By Samuele Pedroni on 2014-02-04

period

[John Lenton (chipaca)]

review: Approve

=== modified file 'logger/logger.go'
--- logger/logger.go	2014-01-16 13:36:32 +0000
+++ logger/logger.go	2014-02-04 21:37:48 +0000
@@ -27,6 +27,8 @@
 
 // Logger is a simple logger interface with logging at levels.
 type Logger interface {
+	// (Re)xpose base Output for logging events.
+	Output(calldept int, s string) error
 	// Errorf logs an error.
 	Errorf(format string, v ...interface{})
 	// Fatalf logs an error and exists the program with os.Exit(1).
@@ -41,8 +43,8 @@
 }
 
 type simpleLogger struct {
-	*log.Logger
-	nlevel int
+	outputFunc func(calldepth int, s string) error
+	nlevel     int
 }
 
 const (
@@ -57,24 +59,41 @@
 	"debug": lDebug,
 }
 
-// NewSimpleLogger creates a logger logging only up to the given level.
-// level can be in order: "error", "info", "debug".
-func NewSimpleLogger(w io.Writer, level string) Logger {
+// NewSimpleLoggerFromMinimalLogger creates a logger logging only up
+// to the given level. level can be in order: "error", "info",
+// "debug". It takes a value just implementing stlib Logger.Output().
+func NewSimpleLoggerFromMinimalLogger(minLog interface {
+	Output(calldepth int, s string) error
+}, level string) Logger {
 	nlevel := levelToNLevel[level]
 	return &simpleLogger{
+		minLog.Output,
+		nlevel,
+	}
+}
+
+// NewSimpleLogger creates a logger logging only up to the given
+// level. level can be in order: "error", "info", "debug". It takes a
+// io.Writer.
+func NewSimpleLogger(w io.Writer, level string) Logger {
+	return NewSimpleLoggerFromMinimalLogger(
 		log.New(w, "", log.Ldate|log.Ltime|log.Lmicroseconds),
-		nlevel,
-	}
+		level,
+	)
+}
+
+func (lg *simpleLogger) Output(calldepth int, s string) error {
+	return lg.outputFunc(calldepth+2, s)
 }
 
 func (lg *simpleLogger) Errorf(format string, v ...interface{}) {
-	lg.Printf("ERROR "+format, v...)
+	lg.outputFunc(2, fmt.Sprintf("ERROR "+format, v...))
 }
 
 var osExit = os.Exit // for testing
 
 func (lg *simpleLogger) Fatalf(format string, v ...interface{}) {
-	lg.Printf("ERROR "+format, v...)
+	lg.outputFunc(2, fmt.Sprintf("ERROR "+format, v...))
 	osExit(1)
 }
 
@@ -83,17 +102,17 @@
 	stack := make([]byte, 8*1024) // Stack writes less but doesn't fail
 	stackWritten := runtime.Stack(stack, false)
 	stack = stack[:stackWritten]
-	lg.Printf("ERROR(PANIC) %s:\n%s", msg, stack)
+	lg.outputFunc(2, fmt.Sprintf("ERROR(PANIC) %s:\n%s", msg, stack))
 }
 
 func (lg *simpleLogger) Infof(format string, v ...interface{}) {
 	if lg.nlevel >= lInfo {
-		lg.Printf("INFO "+format, v...)
+		lg.outputFunc(2, fmt.Sprintf("INFO "+format, v...))
 	}
 }
 
 func (lg *simpleLogger) Debugf(format string, v ...interface{}) {
 	if lg.nlevel >= lDebug {
-		lg.Printf("DEBUG "+format, v...)
+		lg.outputFunc(2, fmt.Sprintf("DEBUG "+format, v...))
 	}
 }

=== modified file 'logger/logger_test.go'
--- logger/logger_test.go	2014-01-16 13:36:32 +0000
+++ logger/logger_test.go	2014-02-04 21:37:48 +0000
@@ -20,6 +20,7 @@
 	"bytes"
 	"fmt"
 	. "launchpad.net/gocheck"
+	"log"
 	"os"
 	"runtime"
 	"testing"
@@ -127,3 +128,12 @@
 	panicAndRecover(logger, 6, false, &line, &ok)
 	c.Check(buf.String(), Equals, "")
 }
+
+func (s *loggerSuite) TestReexposeOutput(c *C) {
+	buf := &bytes.Buffer{}
+	baselog := log.New(buf, "", log.Lshortfile)
+	logger := NewSimpleLoggerFromMinimalLogger(baselog, "error")
+	baselog.Output(1, "foobar")
+	logger.Output(1, "foobaz")
+	c.Check(buf.String(), Matches, "logger_test.go:[0-9]+: foobar\nlogger_test.go:[0-9]+: foobaz\n")
+}

=== modified file 'server/broker/simple/suite_test.go'
--- server/broker/simple/suite_test.go	2014-02-03 15:13:00 +0000
+++ server/broker/simple/suite_test.go	2014-02-04 21:37:48 +0000
@@ -32,13 +32,13 @@
 }
 
 var _ = Suite(&commonBrokerSuite{testsuite.CommonBrokerSuite{
-	func(sto store.PendingStore, cfg broker.BrokerConfig, log logger.Logger) testsuite.FullBroker {
+	MakeBroker: func(sto store.PendingStore, cfg broker.BrokerConfig, log logger.Logger) testsuite.FullBroker {
 		return NewSimpleBroker(sto, cfg, log)
 	},
-	func(b broker.Broker, deviceId string) broker.BrokerSession {
+	RevealSession: func(b broker.Broker, deviceId string) broker.BrokerSession {
 		return b.(*SimpleBroker).registry[deviceId]
 	},
-	func(exchg broker.Exchange) *broker.BroadcastExchange {
+	RevealBroadcastExchange: func(exchg broker.Exchange) *broker.BroadcastExchange {
 		return exchg.(*broker.BroadcastExchange)
 	},
 }})

=== modified file 'server/broker/testsuite/suite.go'
--- server/broker/testsuite/suite.go	2014-02-03 15:13:00 +0000
+++ server/broker/testsuite/suite.go	2014-02-04 21:37:48 +0000
@@ -48,6 +48,12 @@
 	RevealSession func(broker.Broker, string) broker.BrokerSession
 	// Let us get to a broker.BroadcastExchange from an Exchange.
 	RevealBroadcastExchange func(broker.Exchange) *broker.BroadcastExchange
+	// private
+	testlog *helpers.TestLogger
+}
+
+func (s *CommonBrokerSuite) SetUpTest(c *C) {
+	s.testlog = helpers.NewTestLogger(c, "error")
 }
 
 var testBrokerConfig = &testing.TestBrokerConfig{10, 5}
@@ -110,16 +116,14 @@
 }
 
 func (s *CommonBrokerSuite) TestRegistrationFeedPendingError(c *C) {
-	buf := &helpers.SyncedLogBuffer{}
-	logger := logger.NewSimpleLogger(buf, "error")
 	sto := &testFailingStore{}
-	b := s.MakeBroker(sto, testBrokerConfig, logger)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	_, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev-1"})
 	c.Assert(err, IsNil)
 	// but
-	c.Check(buf.String(), Matches, ".*ERROR unsuccessful feed pending, get channel snapshot for 0: get channel snapshot fail\n")
+	c.Check(s.testlog.Captured(), Matches, "ERROR unsuccessful feed pending, get channel snapshot for 0: get channel snapshot fail\n")
 }
 
 func (s *CommonBrokerSuite) TestRegistrationLastWins(c *C) {
@@ -188,10 +192,9 @@
 }
 
 func (s *CommonBrokerSuite) TestBroadcastFail(c *C) {
-	buf := &helpers.SyncedLogBuffer{Written: make(chan bool, 1)}
-	logger := logger.NewSimpleLogger(buf, "error")
+	s.testlog.Written = make(chan bool, 1)
 	sto := &testFailingStore{countdownToFail: 1}
-	b := s.MakeBroker(sto, testBrokerConfig, logger)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	_, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev-1"})
@@ -200,7 +203,7 @@
 	select {
 	case <-time.After(5 * time.Second):
 		c.Fatal("taking too long to log error")
-	case <-buf.Written:
+	case <-s.testlog.Written:
 	}
-	c.Check(buf.String(), Matches, ".*ERROR unsuccessful broadcast, get channel snapshot for 0: get channel snapshot fail\n")
+	c.Check(s.testlog.Captured(), Matches, "ERROR unsuccessful broadcast, get channel snapshot for 0: get channel snapshot fail\n")
 }

=== modified file 'server/listener/listener_test.go'
--- server/listener/listener_test.go	2014-01-21 21:36:07 +0000
+++ server/listener/listener_test.go	2014-02-04 21:37:48 +0000
@@ -20,7 +20,6 @@
 	"crypto/tls"
 	"crypto/x509"
 	. "launchpad.net/gocheck"
-	"launchpad.net/ubuntu-push/logger"
 	helpers "launchpad.net/ubuntu-push/testing"
 	"net"
 	"syscall"
@@ -30,7 +29,9 @@
 
 func TestListener(t *testing.T) { TestingT(t) }
 
-type listenerSuite struct{}
+type listenerSuite struct {
+	testlog *helpers.TestLogger
+}
 
 var _ = Suite(&listenerSuite{})
 
@@ -50,6 +51,10 @@
 	}
 }
 
+func (s *listenerSuite) SetUpTest(c *C) {
+	s.testlog = helpers.NewTestLogger(c, "error")
+}
+
 type testDevListenerCfg struct {
 	addr string
 }
@@ -135,14 +140,12 @@
 }
 
 func (s *listenerSuite) TestDeviceAcceptLoop(c *C) {
-	buf := &helpers.SyncedLogBuffer{}
-	logger := logger.NewSimpleLogger(buf, "error")
 	lst, err := DeviceListen(&testDevListenerCfg{"127.0.0.1:0"})
 	c.Check(err, IsNil)
 	defer lst.Close()
 	errCh := make(chan error)
 	go func() {
-		errCh <- lst.AcceptLoop(testSession, logger)
+		errCh <- lst.AcceptLoop(testSession, s.testlog)
 	}()
 	listenerAddr := lst.Addr().String()
 	conn1, err := testTlsDial(c, listenerAddr)
@@ -157,12 +160,10 @@
 	testReadByte(c, conn2, '2')
 	lst.Close()
 	c.Check(<-errCh, ErrorMatches, ".*use of closed.*")
-	c.Check(buf.String(), Equals, "")
+	c.Check(s.testlog.Captured(), Equals, "")
 }
 
 func (s *listenerSuite) TestDeviceAcceptLoopTemporaryError(c *C) {
-	buf := &helpers.SyncedLogBuffer{}
-	logger := logger.NewSimpleLogger(buf, "error")
 	// ENFILE is not the temp network error we want to handle this way
 	// but is relatively easy to generate in a controlled way
 	var err error
@@ -171,7 +172,7 @@
 	defer lst.Close()
 	errCh := make(chan error)
 	go func() {
-		errCh <- lst.AcceptLoop(testSession, logger)
+		errCh <- lst.AcceptLoop(testSession, s.testlog)
 	}()
 	listenerAddr := lst.Addr().String()
 	conns := make([]net.Conn, 0, NofileMax)
@@ -195,12 +196,10 @@
 	testReadByte(c, conn2, '2')
 	lst.Close()
 	c.Check(<-errCh, ErrorMatches, ".*use of closed.*")
-	c.Check(buf.String(), Matches, ".*device listener:.*accept.*too many open.*-- retrying\n")
+	c.Check(s.testlog.Captured(), Matches, ".*device listener:.*accept.*too many open.*-- retrying\n")
 }
 
 func (s *listenerSuite) TestDeviceAcceptLoopPanic(c *C) {
-	buf := &helpers.SyncedLogBuffer{}
-	logger := logger.NewSimpleLogger(buf, "error")
 	lst, err := DeviceListen(&testDevListenerCfg{"127.0.0.1:0"})
 	c.Check(err, IsNil)
 	defer lst.Close()
@@ -209,12 +208,12 @@
 		errCh <- lst.AcceptLoop(func(conn net.Conn) error {
 			defer conn.Close()
 			panic("session crash")
-		}, logger)
+		}, s.testlog)
 	}()
 	listenerAddr := lst.Addr().String()
 	_, err = testTlsDial(c, listenerAddr)
 	c.Assert(err, Not(IsNil))
 	lst.Close()
 	c.Check(<-errCh, ErrorMatches, ".*use of closed.*")
-	c.Check(buf.String(), Matches, "(?s).* ERROR\\(PANIC\\) terminating device connection on: session crash:.*AcceptLoop.*")
+	c.Check(s.testlog.Captured(), Matches, "(?s)ERROR\\(PANIC\\) terminating device connection on: session crash:.*AcceptLoop.*")
 }

=== modified file 'testing/helpers.go'
--- testing/helpers.go	2014-01-21 21:36:07 +0000
+++ testing/helpers.go	2014-02-04 21:37:48 +0000
@@ -18,34 +18,74 @@
 package testing
 
 import (
-	"bytes"
+	"launchpad.net/ubuntu-push/logger"
 	"path/filepath"
 	"runtime"
+	"strings"
 	"sync"
 )
 
-// SyncedLogBuffer can be used with NewSimpleLogger avoiding races
-// when checking the logging done from different goroutines.
-type SyncedLogBuffer struct {
-	bytes.Buffer
-	lock    sync.Mutex
+type captureHelper struct {
+	outputFunc func(int, string) error
+	lock       sync.Mutex
+	logEvents  []string
+	written    *chan bool
+}
+
+func (h *captureHelper) Output(calldepth int, s string) error {
+	err := h.outputFunc(calldepth+2, s)
+	if err == nil {
+		h.lock.Lock()
+		defer h.lock.Unlock()
+		if *h.written != nil {
+			*h.written <- true
+		}
+		h.logEvents = append(h.logEvents, s+"\n")
+	}
+	return err
+}
+
+func (h *captureHelper) captured() string {
+	h.lock.Lock()
+	defer h.lock.Unlock()
+	return strings.Join(h.logEvents, "")
+}
+
+func (h *captureHelper) reset() {
+	h.lock.Lock()
+	defer h.lock.Unlock()
+	h.logEvents = nil
+}
+
+// TestLogger implements logger.Logger using gocheck.C and supporting
+// capturing log strings.
+type TestLogger struct {
+	logger.Logger
+	helper  *captureHelper
 	Written chan bool
 }
 
-func (buf *SyncedLogBuffer) Write(b []byte) (int, error) {
-	buf.lock.Lock()
-	defer buf.lock.Unlock()
-	n, err := buf.Buffer.Write(b)
-	if buf.Written != nil {
-		buf.Written <- true
+// NewTestLogger can be used in tests instead of NewSimpleLogger(FromMinimalLogger).
+func NewTestLogger(minLog interface {
+	Output(int, string) error
+}, level string) *TestLogger {
+	h := &captureHelper{outputFunc: minLog.Output}
+	log := &TestLogger{
+		Logger: logger.NewSimpleLoggerFromMinimalLogger(h, level),
+		helper: h,
 	}
-	return n, err
-}
-
-func (buf *SyncedLogBuffer) String() string {
-	buf.lock.Lock()
-	defer buf.lock.Unlock()
-	return buf.Buffer.String()
+	h.written = &log.Written
+	return log
+}
+
+// Captured returns accumulated log events.
+func (tlog *TestLogger) Captured() string {
+	return tlog.helper.captured()
+}
+
+// Reset resets accumulated log events.
+func (tlog *TestLogger) ResetCapture() {
+	tlog.helper.reset()
 }
 
 // SourceRelative produces a path relative to the source code, makes