Merge pull request #12662 from knz/fix-clog

Miscellaneous logging improvements

.gitignore

@@ -11,6 +11,7 @@
 #   git ls-files '*.gitignore' | xargs cat >> ~/.gitignore_global &&
 #   git config --global core.excludesfile ~/.gitignore_global)
 
+artifacts
 .bootstrap
 /cockroach
 /cockroach-data

build/builder.sh

@@ -1,6 +1,6 @@
 #!/usr/bin/env bash
 
-set -euo pipefail
+set -xeuo pipefail
 
 image="cockroachdb/builder"
 
@@ -50,6 +50,12 @@ fi
 # Absolute path to the toplevel cockroach directory.
 cockroach_toplevel="$(dirname "$(cd "$(dirname "${0}")"; pwd)")"
 
+# Ensure the artifact sub-directory always exists and redirect
+# temporary file creation to it, so that CI always picks up temp files
+# (including stray log files).
+mkdir -p "${cockroach_toplevel}"/artifacts
+export TMPDIR=$cockroach_toplevel/artifacts
+
 # Make a fake passwd file for the invoking user.
 #
 # This setup is so that files created from inside the container in a mounted
@@ -130,6 +136,7 @@ docker run -i ${tty-} --rm \
   -u "${uid_gid}" \
   ${vols} \
   --workdir="/go/src/github.com/cockroachdb/cockroach" \
+  --env="TMPDIR=/go/src/github.com/cockroachdb/cockroach/artifacts" \
   --env="PAGER=cat" \
   --env="JSPM_GITHUB_AUTH_TOKEN=${JSPM_GITHUB_AUTH_TOKEN-763c42afb2d31eb7bc150da33402a24d0e081aef}" \
   --env="CIRCLE_NODE_INDEX=${CIRCLE_NODE_INDEX-0}" \

build/teamcity-acceptance.sh

@@ -1,7 +1,18 @@
 #!/usr/bin/env bash
 set -euxo pipefail
+
+# Ensure that no stale binary remains.
+rm -f acceptance.test
+
 build/builder.sh make build
 build/builder.sh make install
 build/builder.sh go test -v -c -tags acceptance ./pkg/acceptance
+
+# The log files that should be created by -l below can only
+# be created if the parent directory already exists. Ensure
+# that it exists before running the test.
+mkdir -p artifacts/acceptance
+export TMPDIR=$PWD/artifacts/acceptance
+
 cd pkg/acceptance
-../../acceptance.test -nodes 3 -l ../../artifacts/acceptance -test.v -test.timeout 10m 2>&1 | go-test-teamcity
+../../acceptance.test -nodes 3 -l "$TMPDIR" -test.v -test.timeout 10m 2>&1 | tee "$TMPDIR/acceptance.log" | go-test-teamcity

build/teamcity-check.sh

@@ -8,7 +8,11 @@ set -exuo pipefail
 # https://github.com/golang/go/issues/10249 for some more concrete discussion
 # on `stringer` and https://github.com/golang/go/issues/16086 for `vet`.
 build/builder.sh make gotestdashi
-build/builder.sh make check 2>&1 | go-test-teamcity
+
+mkdir -p artifacts
+
+build/builder.sh make check 2>&1 | tee artifacts/check.log | go-test-teamcity
+
 build/builder.sh go generate ./pkg/...
 build/builder.sh /bin/bash -c '! git status --porcelain | read || (git status; git diff -a 1>&2; exit 1)'
 

build/teamcity-stress.sh

@@ -1,7 +1,7 @@
 #!/usr/bin/env bash
 set -euxo pipefail
 
-mkdir artifacts
+mkdir -p artifacts
 
 exit_status=0
 build/builder.sh make stress COCKROACH_NIGHTLY_STRESS="${COCKROACH_NIGHTLY_STRESS-}" COCKROACH_PROPOSER_EVALUATED_KV="${COCKROACH_PROPOSER_EVALUATED_KV-}" PKG="$PKG" GOFLAGS="${GOFLAGS-}" TAGS="${TAGS-}" TESTTIMEOUT=30m TESTFLAGS='-test.v' STRESSFLAGS='-maxtime 15m -maxfails 1 -stderr' 2>&1 | tee artifacts/stress.log || exit_status=$?

build/teamcity-test.sh

@@ -1,5 +1,8 @@
 #!/usr/bin/env bash
 set -euxo pipefail
-build/builder.sh make test COCKROACH_PROPOSER_EVALUATED_KV="${COCKROACH_PROPOSER_EVALUATED_KV-}" TESTFLAGS='-v' 2>&1 | go-test-teamcity
+
+mkdir -p artifacts
+
+build/builder.sh make test COCKROACH_PROPOSER_EVALUATED_KV="${COCKROACH_PROPOSER_EVALUATED_KV-}" TESTFLAGS='-v' 2>&1 | tee artifacts/test.log | go-test-teamcity
 
 build/builder.sh env BUILD_VCS_NUMBER="$BUILD_VCS_NUMBER" TARGET=stress github-pull-request-make

build/teamcity-testrace.sh

@@ -1,5 +1,8 @@
 #!/usr/bin/env bash
 set -euxo pipefail
-build/builder.sh make testrace COCKROACH_PROPOSER_EVALUATED_KV="${COCKROACH_PROPOSER_EVALUATED_KV-}" TESTFLAGS='-v' 2>&1 | go-test-teamcity
+
+mkdir -p artifacts
+
+build/builder.sh make testrace COCKROACH_PROPOSER_EVALUATED_KV="${COCKROACH_PROPOSER_EVALUATED_KV-}" TESTFLAGS='-v' 2>&1 | tee artifacts/testrace.log | go-test-teamcity
 
 build/builder.sh env BUILD_VCS_NUMBER="$BUILD_VCS_NUMBER" TARGET=stressrace github-pull-request-make

pkg/acceptance/admin_test.go

@@ -29,10 +29,14 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/server/status"
 	"github.com/cockroachdb/cockroach/pkg/ts/tspb"
 	"github.com/cockroachdb/cockroach/pkg/util/httputil"
+	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 )
 
 func TestAdminLossOfQuorum(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	runTestOnConfigs(t, testAdminLossOfQuorumInner)
 }
 

pkg/acceptance/allocator_test.go

@@ -203,6 +203,9 @@ func (at *allocatorTest) Run(ctx context.Context, t *testing.T) {
 }
 
 func (at *allocatorTest) RunAndCleanup(ctx context.Context, t *testing.T) {
+	s := log.Scope(t, "AllocatorTest-"+at.Prefix)
+	defer s.Close(t)
+
 	defer at.Cleanup(t)
 	at.Run(ctx, t)
 }

pkg/acceptance/build_info_test.go

@@ -26,9 +26,13 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/server/serverpb"
 	"github.com/cockroachdb/cockroach/pkg/testutils"
 	"github.com/cockroachdb/cockroach/pkg/util/httputil"
+	"github.com/cockroachdb/cockroach/pkg/util/log"
 )
 
 func TestBuildInfo(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	runTestOnConfigs(t, testBuildInfoInner)
 }
 

pkg/acceptance/c_test.go

@@ -20,10 +20,15 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+
 	"golang.org/x/net/context"
 )
 
 func TestDockerC(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	ctx := context.Background()
 	testDockerSuccess(ctx, t, "c", []string{"/bin/sh", "-c", strings.Replace(c, "%v", "SELECT $1, $2, $3, $4, $5, $6, $7", 1)})
 	testDockerFail(ctx, t, "c", []string{"/bin/sh", "-c", strings.Replace(c, "%v", "SELECT 1", 1)})

pkg/acceptance/cli_test.go

@@ -37,6 +37,9 @@ var cmdBase = []string{
 }
 
 func TestDockerCLI(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	containerConfig := container.Config{
 		Image: postgresTestImage,
 		Cmd:   []string{"stat", cluster.CockroachBinaryInContainer},
@@ -59,6 +62,7 @@ func TestDockerCLI(t *testing.T) {
 		testFile := filepath.Base(p)
 		testPath := filepath.Join(containerPath, testFile)
 		t.Run(testFile, func(t *testing.T) {
+			log.Infof(ctx, "-- starting tests from: %s", testFile)
 			cmd := cmdBase
 			if verbose {
 				cmd = append(cmd, "-d")

pkg/acceptance/cluster/localcluster.go

@@ -493,7 +493,6 @@ func (l *LocalCluster) startNode(ctx context.Context, node *testNode) {
 		"--cert=/certs/node.crt",
 		"--key=/certs/node.key",
 		"--host=" + node.nodeStr,
-		"--alsologtostderr=INFO",
 		"--verbosity=1",
 	}
 
@@ -522,9 +521,10 @@ func (l *LocalCluster) startNode(ctx context.Context, node *testNode) {
 		maybePanic(os.MkdirAll(locallogDir, 0777))
 		cmd = append(
 			cmd,
-			"--log-dir="+dockerlogDir,
-			"--logtostderr=false")
-
+			"--alsologtostderr=ERROR",
+			"--log-dir="+dockerlogDir)
+	} else {
+		cmd = append(cmd, "--alsologtostderr=INFO")
 	}
 	env := []string{
 		"COCKROACH_SCAN_MAX_IDLE_TIME=200ms",

pkg/acceptance/continuous_load_test.go

@@ -90,6 +90,9 @@ func (cl continuousLoadTest) queryCount(f *terrafarm.Farmer) (float64, error) {
 // by the `test.timeout` flag, minus the time it takes to reliably tear down
 // the test cluster.
 func (cl continuousLoadTest) Run(ctx context.Context, t testing.TB) {
+	s := log.Scope(t, "TestContinousLoad-"+cl.Prefix)
+	defer s.Close(t)
+
 	f := MakeFarmer(t, cl.Prefix+cl.shortTestTimeout(), stopper)
 	// If the timeout flag was set, calculate an appropriate lower timeout by
 	// subtracting expected cluster creation and teardown times to allow for

pkg/acceptance/event_log_test.go

@@ -28,12 +28,16 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/roachpb"
 	csql "github.com/cockroachdb/cockroach/pkg/sql"
 	"github.com/cockroachdb/cockroach/pkg/testutils"
+	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/uuid"
 )
 
 // TestEventLog verifies that "node joined" and "node restart" events are
 // recorded whenever a node starts and contacts the cluster.
 func TestEventLog(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	runTestOnConfigs(t, testEventLogInner)
 }
 

pkg/acceptance/finagle_test.go

@@ -17,13 +17,19 @@ package acceptance
 import (
 	"testing"
 
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+
 	"golang.org/x/net/context"
 )
 
 // This runs the `finagle-postgres` tests from the upstream project.
 func TestDockerFinagle(t *testing.T) {
 	ctx := context.Background()
 	t.Skip("#8332. Upstream has a 2s timeout, disabled until we run tests somewhere more consistent.")
+
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	testDockerSuccess(ctx, t, "finagle", []string{"/bin/sh", "-c", finagle})
 }
 

pkg/acceptance/freeze_test.go

@@ -39,6 +39,9 @@ import (
 
 func TestFreezeCluster(t *testing.T) {
 	t.Skip("#7957")
+
+	s := log.Scope(t, "")
+	defer s.Close(t)
 	runTestOnConfigs(t, testFreezeClusterInner)
 }
 

pkg/acceptance/gossip_peerings_test.go

@@ -33,6 +33,9 @@ const longWaitTime = 2 * time.Minute
 const shortWaitTime = 20 * time.Second
 
 func TestGossipPeerings(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	runTestOnConfigs(t, testGossipPeeringsInner)
 }
 
@@ -75,6 +78,9 @@ func testGossipPeeringsInner(
 // re-bootstrapped after a time when all nodes were down
 // simultaneously.
 func TestGossipRestart(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	// TODO(bram): #4559 Limit this test to only the relevant cases. No chaos
 	// agents should be required.
 	runTestOnConfigs(t, testGossipRestartInner)

pkg/acceptance/java_test.go

@@ -20,10 +20,15 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+
 	"golang.org/x/net/context"
 )
 
 func TestDockerJava(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	ctx := context.Background()
 	testDockerSuccess(ctx, t, "java", []string{"/bin/sh", "-c", strings.Replace(java, "%v", "Int(2, 3)", 1)})
 	testDockerFail(ctx, t, "java", []string{"/bin/sh", "-c", strings.Replace(java, "%v", `String(2, "a")`, 1)})

pkg/acceptance/monotonic_insert_test.go

@@ -30,11 +30,15 @@ import (
 
 	"github.com/cockroachdb/cockroach-go/crdb"
 	"github.com/cockroachdb/cockroach/pkg/acceptance/cluster"
+	"github.com/cockroachdb/cockroach/pkg/util/log"
 )
 
 // TestMonotonicInserts replicates the 'monotonic' test from the Jepsen
 // CockroachDB test suite (https://github.com/cockroachdb/jepsen).
 func TestMonotonicInserts(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	runTestOnConfigs(t, testMonotonicInsertsInner)
 }
 
@@ -100,7 +104,10 @@ INSERT INTO mono.mono VALUES(-1, '0', -1, -1)`); err != nil {
 	invoke := func(client mtClient) {
 		logPrefix := fmt.Sprintf("%03d.%03d: ", atomic.AddUint64(&idGen, 1), client.ID)
 		l := func(msg string, args ...interface{}) {
-			t.Logf(logPrefix+msg, args...)
+			log.Infof(ctx, logPrefix+msg, args...)
+			if log.V(2) {
+				t.Logf(logPrefix+msg, args...)
+			}
 		}
 		l("begin")
 		defer l("done")

pkg/acceptance/node_test.go

@@ -20,10 +20,15 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+
 	"golang.org/x/net/context"
 )
 
 func TestDockerNodeJS(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	ctx := context.Background()
 	testDockerSuccess(ctx, t, "node.js", []string{"node", "-e", strings.Replace(nodeJS, "%v", "3", 1)})
 	testDockerFail(ctx, t, "node.js", []string{"node", "-e", strings.Replace(nodeJS, "%v", `'a'`, 1)})

pkg/acceptance/partition_test.go

@@ -35,6 +35,10 @@ import (
 func TestPartitionNemesis(t *testing.T) {
 	t.Skip("only enabled for manually playing with the partitioning agent")
 	SkipUnlessLocal(t)
+
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	runTestOnConfigs(t, func(ctx context.Context, t *testing.T, c cluster.Cluster, cfg cluster.TestConfig) {
 		stopper.RunWorker(func() {
 			BidirectionalPartitionNemesis(ctx, t, c, stopper)
@@ -47,6 +51,7 @@ func TestPartitionNemesis(t *testing.T) {
 }
 
 func TestPartitionBank(t *testing.T) {
+	t.Skip("#12654")
 	SkipUnlessPrivileged(t)
 	runTestOnConfigs(t, testBankWithNemesis(BidirectionalPartitionNemesis))
 }

pkg/acceptance/php_test.go

@@ -20,10 +20,15 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+
 	"golang.org/x/net/context"
 )
 
 func TestDockerPHP(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	ctx := context.Background()
 	testDockerSuccess(ctx, t, "php", []string{"php", "-r", strings.Replace(php, "%v", "3", 1)})
 	testDockerFail(ctx, t, "php", []string{"php", "-r", strings.Replace(php, "%v", `"a"`, 1)})

pkg/acceptance/put_test.go

@@ -33,6 +33,9 @@ import (
 // TestPut starts up an N node cluster and runs N workers that write
 // to independent keys.
 func TestPut(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	runTestOnConfigs(t, testPutInner)
 }
 

pkg/acceptance/python_test.go

@@ -20,10 +20,15 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+
 	"golang.org/x/net/context"
 )
 
 func TestDockerPython(t *testing.T) {
+	s := log.Scope(t, "")
+	defer s.Close(t)
+
 	ctx := context.Background()
 	testDockerSuccess(ctx, t, "python", []string{"python", "-c", strings.Replace(python, "%v", "3", 1)})
 	testDockerFail(ctx, t, "python", []string{"python", "-c", strings.Replace(python, "%v", `"a"`, 1)})