Skip to content

Commit

Permalink
logging: consolidate logging functions to always take a context
Browse files Browse the repository at this point in the history 
Mechanical change to require a context on all logging functions.

I will file issues against various components for auditing the call sites to
replace context.TODO() with a real context.

Part of #1779.
  • Loading branch information
@RaduBerinde
RaduBerinde committed Jul 24, 2016
1 parent 8a87777 commit 21271f3
Show file tree
Hide file tree
Showing 135 changed files with 949 additions and 809 deletions.
28 changes: 15 additions & 13 deletions acceptance/allocator_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,8 @@ import (
"testing"
"time"

"golang.org/x/net/context"

"github.com/montanaflynn/stats"

"github.com/cockroachdb/cockroach/acceptance/terrafarm"
Expand Down Expand Up @@ -129,25 +131,25 @@ func (at *allocatorTest) Run(t *testing.T) {
}
at.f.AddVars["cockroach_disk_type"] = *flagATDiskType

log.Infof("creating cluster with %d node(s)", at.StartNodes)
log.Infof(context.TODO(), "creating cluster with %d node(s)", at.StartNodes)
if err := at.f.Resize(at.StartNodes, 0 /*writers*/); err != nil {
t.Fatal(err)
}
checkGossip(t, at.f, longWaitTime, hasPeers(at.StartNodes))
at.f.Assert(t)
log.Info("initial cluster is up")
log.Info(context.TODO(), "initial cluster is up")

// We must stop the cluster because a) `nodectl` pokes at the data directory
// and, more importantly, b) we don't want the cluster above and the cluster
// below to ever talk to each other (see #7224).
log.Info("stopping cluster")
log.Info(context.TODO(), "stopping cluster")
for i := 0; i < at.f.NumNodes(); i++ {
if err := at.f.Kill(i); err != nil {
t.Fatalf("error stopping node %d: %s", i, err)
}
}

log.Info("downloading archived stores from Google Cloud Storage in parallel")
log.Info(context.TODO(), "downloading archived stores from Google Cloud Storage in parallel")
errors := make(chan error, at.f.NumNodes())
for i := 0; i < at.f.NumNodes(); i++ {
go func(nodeNum int) {
Expand All @@ -160,22 +162,22 @@ func (at *allocatorTest) Run(t *testing.T) {
}
}

log.Info("restarting cluster with archived store(s)")
log.Info(context.TODO(), "restarting cluster with archived store(s)")
for i := 0; i < at.f.NumNodes(); i++ {
if err := at.f.Restart(i); err != nil {
t.Fatalf("error restarting node %d: %s", i, err)
}
}
at.f.Assert(t)

log.Infof("resizing cluster to %d nodes", at.EndNodes)
log.Infof(context.TODO(), "resizing cluster to %d nodes", at.EndNodes)
if err := at.f.Resize(at.EndNodes, 0 /*writers*/); err != nil {
t.Fatal(err)
}
checkGossip(t, at.f, longWaitTime, hasPeers(at.EndNodes))
at.f.Assert(t)

log.Info("waiting for rebalance to finish")
log.Info(context.TODO(), "waiting for rebalance to finish")
if err := at.WaitForRebalance(t); err != nil {
t.Fatal(err)
}
Expand Down Expand Up @@ -205,7 +207,7 @@ func (at *allocatorTest) printRebalanceStats(db *gosql.DB, host string, adminPor
// This can happen with single-node clusters.
rebalanceInterval = time.Duration(0)
}
log.Infof("cluster took %s to rebalance", rebalanceInterval)
log.Infof(context.TODO(), "cluster took %s to rebalance", rebalanceInterval)
}

// Output # of range events that occurred. All other things being equal,
Expand All @@ -216,7 +218,7 @@ func (at *allocatorTest) printRebalanceStats(db *gosql.DB, host string, adminPor
if err := db.QueryRow(q).Scan(&rangeEvents); err != nil {
return err
}
log.Infof("%d range events", rangeEvents)
log.Infof(context.TODO(), "%d range events", rangeEvents)
}

// Output standard deviation of the replica counts for all stores.
Expand All @@ -237,7 +239,7 @@ func (at *allocatorTest) printRebalanceStats(db *gosql.DB, host string, adminPor
if err != nil {
return err
}
log.Infof("stddev(replica count) = %.2f", stddev)
log.Infof(context.TODO(), "stddev(replica count) = %.2f", stddev)
}

return nil
Expand All @@ -261,21 +263,21 @@ func (at *allocatorTest) checkAllocatorStable(db *gosql.DB) (bool, error) {

row := db.QueryRow(q, eventTypes...)
if row == nil {
log.Errorf("couldn't find any range events")
log.Errorf(context.TODO(), "couldn't find any range events")
return false, nil
}
if err := row.Scan(&elapsedStr, &rangeID, &storeID, &eventType); err != nil {
// Log but don't return errors, to increase resilience against transient
// errors.
log.Errorf("error checking rebalancer: %s", err)
log.Errorf(context.TODO(), "error checking rebalancer: %s", err)
return false, nil
}
elapsedSinceLastRangeEvent, err := time.ParseDuration(elapsedStr)
if err != nil {
return false, err
}

log.Infof("last range event: %s for range %d/store %d (%s ago)",
log.Infof(context.TODO(), "last range event: %s for range %d/store %d (%s ago)",
eventType, rangeID, storeID, elapsedSinceLastRangeEvent)
return elapsedSinceLastRangeEvent >= StableInterval, nil
}
Expand Down
22 changes: 12 additions & 10 deletions acceptance/chaos_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,8 @@ import (
"testing"
"time"

"golang.org/x/net/context"

"github.com/cockroachdb/cockroach/acceptance/cluster"
"github.com/cockroachdb/cockroach/util"
"github.com/cockroachdb/cockroach/util/log"
Expand Down Expand Up @@ -171,7 +173,7 @@ func transferMoneyLoop(idx int, state *testState, numAccounts, maxTransfer int)
atomic.AddUint64(&client.count, 1)
}
}
log.Infof("client %d shutting down", idx)
log.Infof(context.TODO(), "client %d shutting down", idx)
state.errChan <- nil
}

Expand All @@ -196,7 +198,7 @@ func chaosMonkey(state *testState, c cluster.Cluster, stopClients bool, pickNode
state.clients[i].Lock()
}
}
log.Infof("round %d: restarting nodes %v", curRound, nodes)
log.Infof(context.TODO(), "round %d: restarting nodes %v", curRound, nodes)
for _, i := range nodes {
// Two early exit conditions.
select {
Expand All @@ -207,7 +209,7 @@ func chaosMonkey(state *testState, c cluster.Cluster, stopClients bool, pickNode
if state.done() {
break
}
log.Infof("round %d: restarting %d", curRound, i)
log.Infof(context.TODO(), "round %d: restarting %d", curRound, i)
if err := c.Kill(i); err != nil {
state.t.Error(err)
}
Expand Down Expand Up @@ -238,13 +240,13 @@ func chaosMonkey(state *testState, c cluster.Cluster, stopClients bool, pickNode
}

// Sleep until at least one client is writing successfully.
log.Warningf("round %d: monkey sleeping while cluster recovers...", curRound)
log.Warningf(context.TODO(), "round %d: monkey sleeping while cluster recovers...", curRound)
for !state.done() && !madeProgress() {
time.Sleep(time.Second)
}
c.Assert(state.t)
cluster.Consistent(state.t, c)
log.Warningf("round %d: cluster recovered", curRound)
log.Warningf(context.TODO(), "round %d: cluster recovered", curRound)
}
}

Expand Down Expand Up @@ -292,7 +294,7 @@ func waitClientsStop(num int, state *testState, stallDuration time.Duration) {
}
// This just stops the logs from being a bit too spammy.
if newOutput != prevOutput {
log.Infof(newOutput)
log.Infof(context.TODO(), newOutput)
prevOutput = newOutput
}
}
Expand Down Expand Up @@ -335,7 +337,7 @@ func testClusterRecoveryInner(t *testing.T, c cluster.Cluster, cfg cluster.TestC

// Chaos monkey.
rnd, seed := randutil.NewPseudoRand()
log.Warningf("monkey starts (seed %d)", seed)
log.Warningf(context.TODO(), "monkey starts (seed %d)", seed)
pickNodes := func() []int {
return rnd.Perm(num)[:rnd.Intn(num)+1]
}
Expand All @@ -352,7 +354,7 @@ func testClusterRecoveryInner(t *testing.T, c cluster.Cluster, cfg cluster.TestC
for _, c := range counts {
count += c
}
log.Infof("%d %.1f/sec", count, float64(count)/elapsed.Seconds())
log.Infof(context.TODO(), "%d %.1f/sec", count, float64(count)/elapsed.Seconds())
}

// TestNodeRestart starts up a cluster with an "accounts" table.
Expand Down Expand Up @@ -394,7 +396,7 @@ func testNodeRestartInner(t *testing.T, c cluster.Cluster, cfg cluster.TestConfi

// Chaos monkey.
rnd, seed := randutil.NewPseudoRand()
log.Warningf("monkey starts (seed %d)", seed)
log.Warningf(context.TODO(), "monkey starts (seed %d)", seed)
pickNodes := func() []int {
return []int{rnd.Intn(num - 1)}
}
Expand All @@ -407,5 +409,5 @@ func testNodeRestartInner(t *testing.T, c cluster.Cluster, cfg cluster.TestConfi

elapsed := timeutil.Since(start)
count := atomic.LoadUint64(&client.count)
log.Infof("%d %.1f/sec", count, float64(count)/elapsed.Seconds())
log.Infof(context.TODO(), "%d %.1f/sec", count, float64(count)/elapsed.Seconds())
}
30 changes: 15 additions & 15 deletions acceptance/cluster/docker.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -83,7 +83,7 @@ func hasImage(l *LocalCluster, ref string) bool {
name := strings.Split(ref, ":")[0]
images, err := l.client.ImageList(context.Background(), types.ImageListOptions{MatchName: name})
if err != nil {
log.Fatal(err)
log.Fatal(context.TODO(), err)
}
for _, image := range images {
for _, repoTag := range image.RepoTags {
Expand All @@ -95,7 +95,7 @@ func hasImage(l *LocalCluster, ref string) bool {
}
for _, image := range images {
for _, tag := range image.RepoTags {
log.Infof("ImageList %s %s", tag, image.ID)
log.Infof(context.TODO(), "ImageList %s %s", tag, image.ID)
}
}
return false
Expand All @@ -106,12 +106,12 @@ func pullImage(l *LocalCluster, ref string, options types.ImagePullOptions) erro
// acceptance test even though that image is already present. So we first
// check to see if our image is present in order to avoid this slowness.
if hasImage(l, ref) {
log.Infof("ImagePull %s already exists", ref)
log.Infof(context.TODO(), "ImagePull %s already exists", ref)
return nil
}

log.Infof("ImagePull %s starting", ref)
defer log.Infof("ImagePull %s complete", ref)
log.Infof(context.TODO(), "ImagePull %s starting", ref)
defer log.Infof(context.TODO(), "ImagePull %s complete", ref)

rc, err := l.client.ImagePull(context.Background(), ref, options)
if err != nil {
Expand All @@ -132,7 +132,7 @@ func pullImage(l *LocalCluster, ref string, options types.ImagePullOptions) erro
}
// The message is a status bar.
if log.V(2) {
log.Infof("ImagePull response: %s", message)
log.Infof(context.TODO(), "ImagePull response: %s", message)
} else {
_, _ = fmt.Fprintf(os.Stderr, ".")
}
Expand Down Expand Up @@ -250,7 +250,7 @@ func (c *Container) Wait() error {
}
if exitCode != 0 {
if err := c.Logs(os.Stderr); err != nil {
log.Warning(err)
log.Warning(context.TODO(), err)
}
return fmt.Errorf("non-zero exit code: %d", exitCode)
}
Expand Down Expand Up @@ -296,7 +296,7 @@ func (c *Container) Inspect() (types.ContainerJSON, error) {
func (c *Container) Addr(port nat.Port) *net.TCPAddr {
containerInfo, err := c.Inspect()
if err != nil {
log.Error(err)
log.Error(context.TODO(), err)
return nil
}
bindings, ok := containerInfo.NetworkSettings.Ports[port]
Expand All @@ -305,7 +305,7 @@ func (c *Container) Addr(port nat.Port) *net.TCPAddr {
}
portNum, err := strconv.Atoi(bindings[0].HostPort)
if err != nil {
log.Error(err)
log.Error(context.TODO(), err)
return nil
}
return &net.TCPAddr{
Expand All @@ -329,13 +329,13 @@ func (cli resilientDockerClient) ContainerCreate(
) (types.ContainerCreateResponse, error) {
response, err := cli.APIClient.ContainerCreate(ctx, config, hostConfig, networkingConfig, containerName)
if err != nil && strings.Contains(err.Error(), "already in use") {
log.Infof("unable to create container %s: %v", containerName, err)
log.Infof(context.TODO(), "unable to create container %s: %v", containerName, err)
containers, cerr := cli.ContainerList(ctx, types.ContainerListOptions{
All: true,
Limit: -1, // no limit, see docker/engine-api/client/container_list.go
})
if cerr != nil {
log.Infof("unable to list containers: %v", cerr)
log.Infof(context.TODO(), "unable to list containers: %v", cerr)
return types.ContainerCreateResponse{}, err
}
for _, c := range containers {
Expand All @@ -345,19 +345,19 @@ func (cli resilientDockerClient) ContainerCreate(
if n != containerName {
continue
}
log.Infof("trying to remove %s", c.ID)
log.Infof(context.TODO(), "trying to remove %s", c.ID)
options := types.ContainerRemoveOptions{
RemoveVolumes: true,
Force: true,
}
if rerr := cli.ContainerRemove(ctx, c.ID, options); rerr != nil {
log.Infof("unable to remove container: %v", rerr)
log.Infof(context.TODO(), "unable to remove container: %v", rerr)
return types.ContainerCreateResponse{}, err
}
return cli.ContainerCreate(ctx, config, hostConfig, networkingConfig, containerName)
}
}
log.Warningf("error indicated existing container %s, "+
log.Warningf(context.TODO(), "error indicated existing container %s, "+
"but none found:\nerror: %s\ncontainers: %+v",
containerName, err, containers)
// We likely raced with a previous (late) removal of the container.
Expand Down Expand Up @@ -421,7 +421,7 @@ func retry(
continue
} else if i > 0 && retryErrorsRE != matchNone {
if regexp.MustCompile(retryErrorsRE).MatchString(err.Error()) {
log.Infof("%s: swallowing expected error after retry: %v",
log.Infof(context.TODO(), "%s: swallowing expected error after retry: %v",
name, err)
return nil
}
Expand Down
Loading

0 comments on commit 21271f3

Please sign in to comment.