Adding a Logger interface, tests and using it.

This is so we can have background operations that log,
and keep the logs. We can then display them on a web page
or on the console depending on the usage.
(this is part of vtctl refactor).

go/cmd/vtctl/vtctl.go

@@ -1811,7 +1811,7 @@ func main() {
 	topoServer := topo.GetServer()
 	defer topo.CloseServers()
 
-	wr := wrangler.New(topoServer, *waitTime, *lockWaitTimeout)
+	wr := wrangler.New(logutil.NewConsoleLogger(), topoServer, *waitTime, *lockWaitTimeout)
 	var actionPath string
 	var err error
 

go/cmd/vtctld/vtctld.go

@@ -15,7 +15,7 @@ import (
 
 	log "github.com/golang/glog"
 	"github.com/youtube/vitess/go/acl"
-	_ "github.com/youtube/vitess/go/vt/logutil"
+	"github.com/youtube/vitess/go/vt/logutil"
 	"github.com/youtube/vitess/go/vt/servenv"
 	"github.com/youtube/vitess/go/vt/topo"
 	"github.com/youtube/vitess/go/vt/wrangler"
@@ -346,7 +346,7 @@ func main() {
 	ts := topo.GetServer()
 	defer topo.CloseServers()
 
-	wr := wrangler.New(ts, 30*time.Second, 30*time.Second)
+	wr := wrangler.New(logutil.NewConsoleLogger(), ts, 30*time.Second, 30*time.Second)
 
 	actionRepo = NewActionRepository(wr)
 

go/cmd/vtjanitor/vtjanitor.go

@@ -9,6 +9,7 @@ import (
 	log "github.com/golang/glog"
 	"github.com/youtube/vitess/go/flagutil"
 	"github.com/youtube/vitess/go/vt/janitor"
+	"github.com/youtube/vitess/go/vt/logutil"
 	"github.com/youtube/vitess/go/vt/servenv"
 	"github.com/youtube/vitess/go/vt/tabletmanager/actionnode"
 	"github.com/youtube/vitess/go/vt/topo"
@@ -49,7 +50,7 @@ func main() {
 
 	ts := topo.GetServer()
 
-	scheduler, err := janitor.New(*keyspace, *shard, ts, wrangler.New(ts, *actionTimeout, *lockTimeout), *sleepTime)
+	scheduler, err := janitor.New(*keyspace, *shard, ts, wrangler.New(logutil.NewConsoleLogger(), ts, *actionTimeout, *lockTimeout), *sleepTime)
 	if err != nil {
 		log.Fatalf("janitor.New: %v", err)
 	}

go/cmd/vtworker/vtworker.go

@@ -22,6 +22,7 @@ import (
 	"time"
 
 	log "github.com/golang/glog"
+	"github.com/youtube/vitess/go/vt/logutil"
 	"github.com/youtube/vitess/go/vt/servenv"
 	"github.com/youtube/vitess/go/vt/tabletmanager/initiator"
 	"github.com/youtube/vitess/go/vt/topo"
@@ -92,11 +93,12 @@ func main() {
 	ts := topo.GetServer()
 	defer topo.CloseServers()
 
-	wr := wrangler.New(ts, 30*time.Second, 30*time.Second)
+	wr := wrangler.New(logutil.NewConsoleLogger(), ts, 30*time.Second, 30*time.Second)
 	if len(args) == 0 {
 		// interactive mode, initialize the web UI to chose a command
 		initInteractiveMode(wr)
 	} else {
+		// single command mode, just runs it
 		runCommand(wr, args)
 	}
 	initStatusHandling()

go/vt/logutil/logger.go

@@ -0,0 +1,251 @@
+package logutil
+
+import (
+	"bytes"
+	"fmt"
+	"runtime"
+	"strings"
+	"time"
+
+	log "github.com/golang/glog"
+)
+
+// Logger defines the interface to use for our logging interface.
+// All methods should be thread safe (i.e. multiple go routines can
+// call these methods simultaneously).
+type Logger interface {
+	Infof(format string, v ...interface{})
+	Warningf(format string, v ...interface{})
+	Errorf(format string, v ...interface{})
+}
+
+// ConsoleLogger is a Logger that uses glog directly to log
+type ConsoleLogger struct{}
+
+// NewConsoleLogger returns a simple ConsoleLogger
+func NewConsoleLogger() ConsoleLogger {
+	return ConsoleLogger{}
+}
+
+// Infof is part of the Logger interface
+func (cl ConsoleLogger) Infof(format string, v ...interface{}) {
+	log.Infof(format, v...)
+}
+
+// Warningf is part of the Logger interface
+func (cl ConsoleLogger) Warningf(format string, v ...interface{}) {
+	log.Warningf(format, v...)
+}
+
+// Errorf is part of the Logger interface
+func (cl ConsoleLogger) Errorf(format string, v ...interface{}) {
+	log.Errorf(format, v...)
+}
+
+// The logger levels are used to store individual logging events
+const (
+	LOGGER_INFO = iota
+	LOGGER_WARNING
+	LOGGER_ERROR
+)
+
+// LoggerEvent is used to manage individual logging events. It is used
+// by ChannelLogger and MemoryLogger.
+type LoggerEvent struct {
+	Time  time.Time
+	Level int
+	File  string
+	Line  int
+	Value string
+}
+
+// ToBuffer formats an individual LoggerEvent into a buffer
+func (event *LoggerEvent) ToBuffer(buf *bytes.Buffer) {
+	// Avoid Fprintf, for speed. The format is so simple that we
+	// can do it quickly by hand.  It's worth about 3X. Fprintf is hard.
+
+	// Lmmdd hh:mm:ss.uuuuuu file:line]
+	switch event.Level {
+	case LOGGER_INFO:
+		buf.WriteByte('I')
+	case LOGGER_WARNING:
+		buf.WriteByte('W')
+	case LOGGER_ERROR:
+		buf.WriteByte('E')
+	}
+
+	_, month, day := event.Time.Date()
+	hour, minute, second := event.Time.Clock()
+	twoDigits(buf, int(month))
+	twoDigits(buf, day)
+	buf.WriteByte(' ')
+	twoDigits(buf, hour)
+	buf.WriteByte(':')
+	twoDigits(buf, minute)
+	buf.WriteByte(':')
+	twoDigits(buf, second)
+	buf.WriteByte('.')
+	nDigits(buf, 6, event.Time.Nanosecond()/1000, '0')
+	buf.WriteByte(' ')
+	buf.WriteString(event.File)
+	buf.WriteByte(':')
+	someDigits(buf, event.Line)
+	buf.WriteByte(']')
+	buf.WriteByte(' ')
+	buf.WriteString(event.Value)
+	buf.WriteByte('\n')
+}
+
+// ChannelLogger is a Logger that sends the logging events through a channel for
+// consumption.
+type ChannelLogger chan LoggerEvent
+
+// NewChannelLogger returns a ChannelLogger fo the given size
+func NewChannelLogger(size int) ChannelLogger {
+	return make(chan LoggerEvent, size)
+}
+
+// Infof is part of the Logger interface
+func (cl ChannelLogger) Infof(format string, v ...interface{}) {
+	file, line := fileAndLine()
+	(chan LoggerEvent)(cl) <- LoggerEvent{
+		Time:  time.Now(),
+		Level: LOGGER_INFO,
+		File:  file,
+		Line:  line,
+		Value: fmt.Sprintf(format, v...),
+	}
+}
+
+// Warningf is part of the Logger interface
+func (cl ChannelLogger) Warningf(format string, v ...interface{}) {
+	file, line := fileAndLine()
+	(chan LoggerEvent)(cl) <- LoggerEvent{
+		Time:  time.Now(),
+		Level: LOGGER_WARNING,
+		File:  file,
+		Line:  line,
+		Value: fmt.Sprintf(format, v...),
+	}
+}
+
+// Errorf is part of the Logger interface
+func (cl ChannelLogger) Errorf(format string, v ...interface{}) {
+	file, line := fileAndLine()
+	(chan LoggerEvent)(cl) <- LoggerEvent{
+		Time:  time.Now(),
+		Level: LOGGER_ERROR,
+		File:  file,
+		Line:  line,
+		Value: fmt.Sprintf(format, v...),
+	}
+}
+
+// MemoryLogger keeps the logging events in memory
+type MemoryLogger struct {
+	Events []LoggerEvent
+}
+
+// NewMemoryLogger returns a new MemoryLogger
+func NewMemoryLogger() *MemoryLogger {
+	return &MemoryLogger{}
+}
+
+// Infof is part of the Logger interface
+func (ml *MemoryLogger) Infof(format string, v ...interface{}) {
+	file, line := fileAndLine()
+	ml.Events = append(ml.Events, LoggerEvent{
+		Time:  time.Now(),
+		Level: LOGGER_INFO,
+		File:  file,
+		Line:  line,
+		Value: fmt.Sprintf(format, v...),
+	})
+}
+
+// Warningf is part of the Logger interface
+func (ml *MemoryLogger) Warningf(format string, v ...interface{}) {
+	file, line := fileAndLine()
+	ml.Events = append(ml.Events, LoggerEvent{
+		Time:  time.Now(),
+		Level: LOGGER_WARNING,
+		File:  file,
+		Line:  line,
+		Value: fmt.Sprintf(format, v...),
+	})
+}
+
+// Errorf is part of the Logger interface
+func (ml *MemoryLogger) Errorf(format string, v ...interface{}) {
+	file, line := fileAndLine()
+	ml.Events = append(ml.Events, LoggerEvent{
+		Time:  time.Now(),
+		Level: LOGGER_ERROR,
+		File:  file,
+		Line:  line,
+		Value: fmt.Sprintf(format, v...),
+	})
+}
+
+// String returns all the lines in one String
+func (ml *MemoryLogger) String() string {
+	buf := new(bytes.Buffer)
+	for _, event := range ml.Events {
+		event.ToBuffer(buf)
+	}
+	return buf.String()
+}
+
+const digits = "0123456789"
+
+// twoDigits adds a zero-prefixed two-digit integer to buf
+func twoDigits(buf *bytes.Buffer, value int) {
+	buf.WriteByte(digits[value/10])
+	buf.WriteByte(digits[value%10])
+}
+
+// nDigits adds an n-digit integer d to buf
+// padding with pad on the left.
+// It assumes d >= 0.
+func nDigits(buf *bytes.Buffer, n, d int, pad byte) {
+	tmp := make([]byte, n)
+	j := n - 1
+	for ; j >= 0 && d > 0; j-- {
+		tmp[j] = digits[d%10]
+		d /= 10
+	}
+	for ; j >= 0; j-- {
+		tmp[j] = pad
+	}
+	buf.Write(tmp)
+}
+
+// someDigits adds a zero-prefixed variable-width integer to buf
+func someDigits(buf *bytes.Buffer, d int) {
+	// Print into the top, then copy down.
+	tmp := make([]byte, 10)
+	j := 10
+	for {
+		j--
+		tmp[j] = digits[d%10]
+		d /= 10
+		if d == 0 {
+			break
+		}
+	}
+	buf.Write(tmp[j:])
+}
+
+// fileAndLine returns the caller's file and line 2 levels above
+func fileAndLine() (string, int) {
+	_, file, line, ok := runtime.Caller(2)
+	if !ok {
+		return "???", 1
+	}
+
+	slash := strings.LastIndex(file, "/")
+	if slash >= 0 {
+		file = file[slash+1:]
+	}
+	return file, line
+}

go/vt/logutil/logger_test.go

@@ -0,0 +1,70 @@
+package logutil
+
+import (
+	"bytes"
+	"testing"
+	"time"
+)
+
+func TestLoggerEventFormat(t *testing.T) {
+	testValues := []struct {
+		event    LoggerEvent
+		expected string
+	}{
+		{
+			event: LoggerEvent{
+				Time:  time.Date(2014, time.November, 10, 23, 30, 12, 123456000, time.UTC),
+				Level: LOGGER_INFO,
+				File:  "file.go",
+				Line:  123,
+				Value: "message",
+			},
+			expected: "I1110 23:30:12.123456 file.go:123] message\n",
+		},
+		{
+			event: LoggerEvent{
+				Time:  time.Date(2014, time.January, 20, 23, 30, 12, 0, time.UTC),
+				Level: LOGGER_WARNING,
+				File:  "file2.go",
+				Line:  567,
+				Value: "message %v %v",
+			},
+			expected: "W0120 23:30:12.000000 file2.go:567] message %v %v\n",
+		},
+	}
+	for _, testValue := range testValues {
+		buf := new(bytes.Buffer)
+		testValue.event.ToBuffer(buf)
+		if testValue.expected != buf.String() {
+			t.Errorf("invalid printing of %v: want '%v' got '%v'", testValue.event, testValue.expected, buf.String())
+		}
+	}
+}
+
+func TestMemoryLogger(t *testing.T) {
+	ml := NewMemoryLogger()
+	ml.Infof("test %v", 123)
+	if len(ml.Events) != 1 {
+		t.Fatalf("Invalid MemoryLogger size: %v", ml)
+	}
+	if ml.Events[0].File != "logger_test.go" {
+		t.Errorf("Invalid file name: %v", ml.Events[0].File)
+	}
+	ml.Errorf("test %v", 456)
+	if len(ml.Events) != 2 {
+		t.Fatalf("Invalid MemoryLogger size: %v", ml)
+	}
+	if ml.Events[1].File != "logger_test.go" {
+		t.Errorf("Invalid file name: %v", ml.Events[1].File)
+	}
+}
+
+func TestChannelLogger(t *testing.T) {
+	cl := NewChannelLogger(10)
+	cl.Warningf("test %v", 123)
+
+	e := <-cl
+	if e.File != "logger_test.go" {
+		t.Errorf("Invalid file name: %v", e.File)
+	}
+}

go/vt/tabletmanager/healthcheck.go

@@ -17,6 +17,7 @@ import (
 	log "github.com/golang/glog"
 	"github.com/youtube/vitess/go/timer"
 	"github.com/youtube/vitess/go/vt/health"
+	"github.com/youtube/vitess/go/vt/logutil"
 	"github.com/youtube/vitess/go/vt/servenv"
 	"github.com/youtube/vitess/go/vt/tabletmanager/actionnode"
 	"github.com/youtube/vitess/go/vt/topo"
@@ -222,7 +223,7 @@ func (agent *ActionAgent) rebuildShardIfNeeded(tablet *topo.TabletInfo, targetTa
 		interrupted := make(chan struct{})
 
 		// no need to take the shard lock in this case
-		if err := topotools.RebuildShard(agent.TopoServer, tablet.Keyspace, tablet.Shard, []string{tablet.Alias.Cell}, lockTimeout, interrupted); err != nil {
+		if err := topotools.RebuildShard(logutil.NewConsoleLogger(), agent.TopoServer, tablet.Keyspace, tablet.Shard, []string{tablet.Alias.Cell}, lockTimeout, interrupted); err != nil {
 			return fmt.Errorf("topotools.RebuildShard returned an error: %v", err)
 		}
 	}

go/vt/topo/test/faketopo/faketopo.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"github.com/youtube/vitess/go/vt/key"
+	"github.com/youtube/vitess/go/vt/logutil"
 	"github.com/youtube/vitess/go/vt/mysqlctl"
 	"github.com/youtube/vitess/go/vt/tabletmanager/actionnode"
 	"github.com/youtube/vitess/go/vt/tabletmanager/actor"
@@ -51,7 +52,7 @@ type Fixture struct {
 func New(t *testing.T, cells []string) *Fixture {
 	ts := zktopo.NewTestServer(t, cells)
 
-	wr := wrangler.New(ts, 1*time.Second, 1*time.Second)
+	wr := wrangler.New(logutil.NewConsoleLogger(), ts, 1*time.Second, 1*time.Second)
 	wr.UseRPCs = false
 
 	return &Fixture{

go/vt/topotools/rebuild.go

@@ -10,8 +10,8 @@ import (
 	"sync"
 	"time"
 
-	log "github.com/golang/glog"
 	"github.com/youtube/vitess/go/vt/concurrency"
+	"github.com/youtube/vitess/go/vt/logutil"
 	"github.com/youtube/vitess/go/vt/tabletmanager/actionnode"
 	"github.com/youtube/vitess/go/vt/topo"
 )
@@ -27,7 +27,7 @@ var UseSrvShardLocks = flag.Bool("use_srv_shard_locks", true, "DEPRECATED: If tr
 //
 // This function locks individual SvrShard paths, so it doesn't need a lock
 // on the shard.
-func RebuildShard(ts topo.Server, keyspace, shard string, cells []string, timeout time.Duration, interrupted chan struct{}) error {
+func RebuildShard(log logutil.Logger, ts topo.Server, keyspace, shard string, cells []string, timeout time.Duration, interrupted chan struct{}) error {
 	log.Infof("RebuildShard %v/%v", keyspace, shard)
 
 	// read the existing shard info. It has to exist.
@@ -97,7 +97,7 @@ func RebuildShard(ts topo.Server, keyspace, shard string, cells []string, timeou
 			}
 
 			// write the data we need to
-			rebuildErr := rebuildCellSrvShard(ts, shardInfo, cell, tablets)
+			rebuildErr := rebuildCellSrvShard(log, ts, shardInfo, cell, tablets)
 
 			// and unlock
 			if err := actionNode.UnlockSrvShard(ts, cell, keyspace, shard, lockPath, rebuildErr); err != nil {
@@ -112,7 +112,7 @@ func RebuildShard(ts topo.Server, keyspace, shard string, cells []string, timeou
 
 // rebuildCellSrvShard computes and writes the serving graph data to a
 // single cell
-func rebuildCellSrvShard(ts topo.Server, shardInfo *topo.ShardInfo, cell string, tablets map[topo.TabletAlias]*topo.TabletInfo) error {
+func rebuildCellSrvShard(log logutil.Logger, ts topo.Server, shardInfo *topo.ShardInfo, cell string, tablets map[topo.TabletAlias]*topo.TabletInfo) error {
 	log.Infof("rebuildCellSrvShard %v/%v in cell %v", shardInfo.Keyspace(), shardInfo.ShardName(), cell)
 
 	// Get all existing db types so they can be removed if nothing

go/vt/wrangler/rebuild.go

@@ -19,7 +19,7 @@ import (
 // Rebuild the serving and replication rollup data data while locking
 // out other changes.
 func (wr *Wrangler) RebuildShardGraph(keyspace, shard string, cells []string) error {
-	return topotools.RebuildShard(wr.ts, keyspace, shard, cells, wr.lockTimeout, interrupted)
+	return topotools.RebuildShard(wr.logger, wr.ts, keyspace, shard, cells, wr.lockTimeout, interrupted)
 }
 
 // Rebuild the serving graph data while locking out other changes.

go/vt/wrangler/reparent_action.go

@@ -385,7 +385,7 @@ func (wr *Wrangler) finishReparent(si *topo.ShardInfo, masterElect *topo.TabletI
 	// We rebuild all the cells, as we may have taken tablets in and
 	// out of the graph.
 	log.Infof("rebuilding shard serving graph data")
-	return topotools.RebuildShard(wr.ts, masterElect.Keyspace, masterElect.Shard, nil, wr.lockTimeout, interrupted)
+	return topotools.RebuildShard(wr.logger, wr.ts, masterElect.Keyspace, masterElect.Shard, nil, wr.lockTimeout, interrupted)
 }
 
 func (wr *Wrangler) breakReplication(slaveMap map[topo.TabletAlias]*topo.TabletInfo, masterElect *topo.TabletInfo) error {

go/vt/wrangler/reparent_external.go

@@ -110,7 +110,7 @@ func (wr *Wrangler) shardExternallyReparentedLocked(keyspace, shard string, mast
 	// and rebuild the shard serving graph
 	ev.UpdateStatus("rebuilding shard serving graph")
 	log.Infof("Rebuilding shard serving graph data")
-	if err = topotools.RebuildShard(wr.ts, masterElectTablet.Keyspace, masterElectTablet.Shard, cells, wr.lockTimeout, interrupted); err != nil {
+	if err = topotools.RebuildShard(wr.logger, wr.ts, masterElectTablet.Keyspace, masterElectTablet.Shard, cells, wr.lockTimeout, interrupted); err != nil {
 		return err
 	}
 

go/vt/wrangler/tablet.go

@@ -286,7 +286,7 @@ func (wr *Wrangler) changeTypeInternal(tabletAlias topo.TabletAlias, dbType topo
 
 	// rebuild if necessary
 	if rebuildRequired {
-		err = topotools.RebuildShard(wr.ts, ti.Keyspace, ti.Shard, []string{ti.Alias.Cell}, wr.lockTimeout, interrupted)
+		err = topotools.RebuildShard(wr.logger, wr.ts, ti.Keyspace, ti.Shard, []string{ti.Alias.Cell}, wr.lockTimeout, interrupted)
 		if err != nil {
 			return err
 		}

go/vt/wrangler/wrangler.go

@@ -9,6 +9,7 @@ import (
 	"flag"
 	"time"
 
+	"github.com/youtube/vitess/go/vt/logutil"
 	"github.com/youtube/vitess/go/vt/tabletmanager/actionnode"
 	"github.com/youtube/vitess/go/vt/tabletmanager/initiator"
 	"github.com/youtube/vitess/go/vt/topo"
@@ -26,6 +27,7 @@ var tabletManagerProtocol = flag.String("tablet_manager_protocol", "bson", "the
 // Wrangler manages complex actions on the topology, like reparents,
 // snapshots, restores, ...
 type Wrangler struct {
+	logger      logutil.Logger
 	ts          topo.Server
 	ai          *initiator.ActionInitiator
 	deadline    time.Time
@@ -52,8 +54,8 @@ type Wrangler struct {
 // of the time, we want to immediately know that our action will
 // fail. However, automated action will need some time to arbitrate
 // the locks.
-func New(ts topo.Server, actionTimeout, lockTimeout time.Duration) *Wrangler {
-	return &Wrangler{ts, initiator.NewActionInitiator(ts, *tabletManagerProtocol), time.Now().Add(actionTimeout), lockTimeout, true}
+func New(logger logutil.Logger, ts topo.Server, actionTimeout, lockTimeout time.Duration) *Wrangler {
+	return &Wrangler{logger, ts, initiator.NewActionInitiator(ts, *tabletManagerProtocol), time.Now().Add(actionTimeout), lockTimeout, true}
 }
 
 func (wr *Wrangler) actionTimeout() time.Duration {