util/log: improvements, simplifications and bug fixes

pkg/cli/cli_test.go

@@ -448,6 +448,10 @@ func Example_demo() {
 	// find the certs that demo sets up.
 	security.ResetAssetLoader()
 	for _, cmd := range testData {
+		// `demo` sets up a server and log file redirection, which asserts
+		// that the logging subsystem has not been initialized yet. Fake
+		// this to be true.
+		log.TestingResetActive()
 		c.RunWithArgs(cmd)
 	}
 

pkg/cli/demo.go

@@ -252,8 +252,6 @@ func checkDemoConfiguration(
 }
 
 func runDemo(cmd *cobra.Command, gen workload.Generator) (err error) {
-	defer log.ScopeWithoutFiles().Close()
-
 	if gen, err = checkDemoConfiguration(cmd, gen); err != nil {
 		return err
 	}

pkg/cli/demo_locality_test.go

@@ -12,7 +12,10 @@
 
 package cli
 
-import "github.com/cockroachdb/cockroach/pkg/security"
+import (
+	"github.com/cockroachdb/cockroach/pkg/security"
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+)
 
 func Example_demo_locality() {
 	c := newCLITest(cliTestParams{noServer: true})
@@ -30,6 +33,10 @@ func Example_demo_locality() {
 	// find the certs that demo sets up.
 	security.ResetAssetLoader()
 	for _, cmd := range testData {
+		// `demo` sets up a server and log file redirection, which asserts
+		// that the logging subsystem has not been initialized yet.  Fake
+		// this to be true.
+		log.TestingResetActive()
 		c.RunWithArgs(cmd)
 	}
 

pkg/cli/testdata/zip/unavailable

@@ -83,7 +83,6 @@ requesting goroutine files for node 1... writing: debug/nodes/1/goroutines.err.t
   ^- resulted in ...
 requesting log file ...
 requesting log file ...
-requesting log file ...
 requesting list of SQL databases... writing: debug/schema.err.txt
   ^- resulted in ...
 writing: debug/pprof-summary.sh

pkg/kv/kvserver/protectedts/ptstorage/storage_test.go

@@ -428,6 +428,10 @@ func TestCorruptData(t *testing.T) {
 	ctx := context.Background()
 
 	t.Run("corrupt spans", func(t *testing.T) {
+		// Set the log scope so we can introspect the logged errors.
+		scope := log.Scope(t)
+		defer scope.Close(t)
+
 		tc := testcluster.StartTestCluster(t, 1, base.TestClusterArgs{})
 		defer tc.Stopper().Stop(ctx)
 
@@ -448,10 +452,6 @@ func TestCorruptData(t *testing.T) {
 		require.NoError(t, err)
 		require.Equal(t, 1, affected)
 
-		// Set the log scope so we can introspect the logged errors.
-		scope := log.Scope(t)
-		defer scope.Close(t)
-
 		var got *ptpb.Record
 		msg := regexp.MustCompile("failed to unmarshal spans for " + rec.ID.String() + ": ")
 		require.Regexp(t, msg,
@@ -474,6 +474,10 @@ func TestCorruptData(t *testing.T) {
 		}
 	})
 	t.Run("corrupt hlc timestamp", func(t *testing.T) {
+		// Set the log scope so we can introspect the logged errors.
+		scope := log.Scope(t)
+		defer scope.Close(t)
+
 		tc := testcluster.StartTestCluster(t, 1, base.TestClusterArgs{})
 		defer tc.Stopper().Stop(ctx)
 
@@ -498,10 +502,6 @@ func TestCorruptData(t *testing.T) {
 		require.NoError(t, err)
 		require.Equal(t, 1, affected)
 
-		// Set the log scope so we can introspect the logged errors.
-		scope := log.Scope(t)
-		defer scope.Close(t)
-
 		var got *ptpb.Record
 		msg := regexp.MustCompile("failed to parse timestamp for " + rec.ID.String() +
 			": logical part has too many digits")

pkg/server/status_test.go

@@ -535,7 +535,7 @@ func TestStatusLocalLogs(t *testing.T) {
 	if err := getStatusJSONProto(ts, "logfiles/local", &wrapper); err != nil {
 		t.Fatal(err)
 	}
-	if a, e := len(wrapper.Files), 2; a != e {
+	if a, e := len(wrapper.Files), 1; a != e {
 		t.Fatalf("expected %d log files; got %d", e, a)
 	}
 
@@ -705,17 +705,14 @@ func TestStatusLogRedaction(t *testing.T) {
 			if err := getStatusJSONProto(ts, "logfiles/local", &wrapper); err != nil {
 				t.Fatal(err)
 			}
-			// We expect a main log and a stderr log.
-			if a, e := len(wrapper.Files), 2; a != e {
+			// We expect only the main log.
+			if a, e := len(wrapper.Files), 1; a != e {
 				t.Fatalf("expected %d log files; got %d: %+v", e, a, wrapper.Files)
 			}
-			var file log.FileInfo
-			// Find the main log.
-			for _, f := range wrapper.Files {
-				if !strings.Contains("stderr", f.Name) {
-					file = f
-					break
-				}
+			file := wrapper.Files[0]
+			// Assert that the log that's present is not a stderr log.
+			if strings.Contains("stderr", file.Name) {
+				t.Fatalf("expected main log, found %v", file.Name)
 			}
 
 			for _, tc := range testData {

pkg/sql/pgwire/auth_test.go

@@ -106,7 +106,6 @@ import (
 //
 func TestAuthenticationAndHBARules(t *testing.T) {
 	defer leaktest.AfterTest(t)()
-	skip.WithIssue(t, 52026, "temporarily skip due to repeated failures")
 
 	testutils.RunTrueAndFalse(t, "insecure", func(t *testing.T, insecure bool) {
 		hbaRunTest(t, insecure)

pkg/util/log/clog.go

@@ -94,20 +94,6 @@ type loggerT struct {
 	// stderr sink.
 	stderrThreshold Severity
 
-	// redirectInternalStderrWrites, when set, causes this logger to
-	// capture writes to system-wide file descriptor 2 (the standard
-	// error stream) and os.Stderr and redirect them to this logger's
-	// output file.
-	// Users of the logging package should ensure that at most one
-	// logger has this flag set to redirect the system-wide stderr.
-	//
-	// Note that this mechanism redirects file descriptor 2, and does
-	// not only assign a different *os.File reference to
-	// os.Stderr. This is because the Go runtime hardcodes stderr writes
-	// as writes to file descriptor 2 and disregards the value of
-	// os.Stderr entirely.
-	redirectInternalStderrWrites bool
-
 	// whether or not to include redaction markers.
 	// This is atomic because tests using TestLogScope might
 	// override this asynchronously with log calls.
@@ -132,6 +118,29 @@ type loggerT struct {
 
 		// syncWrites if true calls file.Flush and file.Sync on every log write.
 		syncWrites bool
+
+		// redirectInternalStderrWrites, when set, causes this logger to
+		// capture writes to system-wide file descriptor 2 (the standard
+		// error stream) and os.Stderr and redirect them to this logger's
+		// output file.
+		// This is managed by the takeOverInternalStderr() method.
+		//
+		// Note that this mechanism redirects file descriptor 2, and does
+		// not only assign a different *os.File reference to
+		// os.Stderr. This is because the Go runtime hardcodes stderr writes
+		// as writes to file descriptor 2 and disregards the value of
+		// os.Stderr entirely.
+		//
+		// There can be at most one logger with this boolean set. This
+		// constraint is enforced by takeOverInternalStderr().
+		redirectInternalStderrWrites bool
+
+		// currentlyOwnsInternalStderr determines whether a logger
+		// _currently_ has taken over fd 2. This may be false while
+		// redirectInternalStderrWrites above is true, when the logger has
+		// not yet opened its output file, or is in the process of
+		// switching over from one directory to the next.
+		currentlyOwnsInternalStderr bool
 	}
 }
 
@@ -160,7 +169,7 @@ func init() {
 	mainLog.fileThreshold = Severity_INFO
 	// Don't capture stderr output until
 	// SetupRedactionAndStderrRedirects() has been called.
-	mainLog.redirectInternalStderrWrites = false
+	mainLog.mu.redirectInternalStderrWrites = false
 }
 
 // FatalChan is closed when Fatal is called. This can be used to make
@@ -207,28 +216,6 @@ func SetClusterID(clusterID string) {
 	logging.mu.clusterID = clusterID
 }
 
-// ensureFile ensures that l.file is set and valid.
-// Assumes that l.mu is held by the caller.
-func (l *loggerT) ensureFile() error {
-	if l.mu.file == nil {
-		return l.createFile()
-	}
-	return nil
-}
-
-// writeToFile writes to the file and applies the synchronization policy.
-// Assumes that l.mu is held by the caller.
-func (l *loggerT) writeToFile(data []byte) error {
-	if _, err := l.mu.file.Write(data); err != nil {
-		return err
-	}
-	if l.mu.syncWrites {
-		_ = l.mu.file.Flush()
-		_ = l.mu.file.Sync()
-	}
-	return nil
-}
-
 // outputLogEntry marshals a log entry proto into bytes, and writes
 // the data to the log files. If a trace location is set, stack traces
 // are added to the entry before marshaling.
@@ -322,7 +309,7 @@ func (l *loggerT) outputLogEntry(entry Entry) {
 		}
 	}
 	if l.logDir.IsSet() && entry.Severity >= l.fileThreshold.get() {
-		if err := l.ensureFile(); err != nil {
+		if err := l.ensureFileLocked(); err != nil {
 			// We definitely do not like to lose log entries, so we stop
 			// here. Note that exitLocked() shouts the error to both stderr
 			// and the log file, so even though the file is not available
@@ -335,7 +322,7 @@ func (l *loggerT) outputLogEntry(entry Entry) {
 		buf := logging.processForFile(entry, stacks)
 		data := buf.Bytes()
 
-		if err := l.writeToFile(data); err != nil {
+		if err := l.writeToFileLocked(data); err != nil {
 			l.exitLocked(err)
 			l.mu.Unlock()  // unreachable except in tests
 			putBuffer(buf) // unreachable except in tests
@@ -346,7 +333,7 @@ func (l *loggerT) outputLogEntry(entry Entry) {
 	}
 	// Flush and exit on fatal logging.
 	if entry.Severity == Severity_FATAL {
-		l.flushAndSync(true /*doSync*/)
+		l.flushAndSyncLocked(true /*doSync*/)
 		close(fatalTrigger)
 		// Note: although it seems like the function is allowed to return
 		// below when s == Severity_FATAL, this is not so, because the
@@ -377,23 +364,6 @@ func setActive() {
 	}
 }
 
-func resetActive() (restore func()) {
-	logging.mu.Lock()
-	defer logging.mu.Unlock()
-
-	prevActive, prevFirstuse := logging.mu.active, logging.mu.firstUseStack
-	// Mark loggging as non-active: a test log scope
-	// resets the active bit to override the logging destination.
-	logging.mu.active = false
-
-	return func() {
-		logging.mu.Lock()
-		defer logging.mu.Unlock()
-		logging.mu.active = prevActive
-		logging.mu.firstUseStack = prevFirstuse
-	}
-}
-
 // outputToStderr writes the provided entry and potential stack
 // trace(s) to the process' external stderr stream.
 func (l *loggerT) outputToStderr(entry Entry, stacks []byte) error {

pkg/util/log/clog_test.go

@@ -623,6 +623,13 @@ func TestRedirectStderr(t *testing.T) {
 
 	Infof(context.Background(), "test")
 
+	TestingResetActive()
+	cleanup, err := SetupRedactionAndStderrRedirects()
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer cleanup()
+
 	const stderrText = "hello stderr"
 	fmt.Fprint(os.Stderr, stderrText)
 

pkg/util/log/exit_override.go

@@ -109,5 +109,5 @@ func (l *loggerT) reportErrorEverywhereLocked(ctx context.Context, err error) {
 		// here, we can't do anything but raise our hands in the air.
 		_, _ = w.Write(buf.Bytes())
 	}
-	l.flushAndSync(true /*doSync*/)
+	l.flushAndSyncLocked(true /*doSync*/)
 }

pkg/util/log/file.go

@@ -224,12 +224,14 @@ var errDirectoryNotSet = errors.New("log: log directory not set")
 // create creates a new log file and returns the file and its
 // filename. If the file is created successfully, create also attempts
 // to update the symlink for that tag, ignoring errors.
+//
+// It is invalid to call this with an unset output directory.
 func create(
 	logDir *DirName, prefix string, t time.Time, lastRotation int64,
-) (f *os.File, updatedRotation int64, filename string, err error) {
+) (f *os.File, updatedRotation int64, filename, symlink string, err error) {
 	dir, isSet := logDir.get()
 	if !isSet {
-		return nil, lastRotation, "", errDirectoryNotSet
+		return nil, lastRotation, "", "", errDirectoryNotSet
 	}
 
 	// Ensure that the timestamp of the new file name is greater than
@@ -243,28 +245,27 @@ func create(
 
 	// Generate the file name.
 	name, link := logName(prefix, t)
+	symlink = filepath.Join(dir, link)
 	fname := filepath.Join(dir, name)
 	// Open the file os.O_APPEND|os.O_CREATE rather than use os.Create.
 	// Append is almost always more efficient than O_RDRW on most modern file systems.
 	f, err = os.OpenFile(fname, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
-	if err == nil {
-		symlink := filepath.Join(dir, link)
-
-		// Symlinks are best-effort.
+	return f, updatedRotation, fname, symlink, errors.Wrapf(err, "log: cannot create output file")
+}
 
-		if err := os.Remove(symlink); err != nil && !os.IsNotExist(err) {
-			fmt.Fprintf(OrigStderr, "log: failed to remove symlink %s: %s", symlink, err)
-		}
-		if err := os.Symlink(filepath.Base(fname), symlink); err != nil {
-			// On Windows, this will be the common case, as symlink creation
-			// requires special privileges.
-			// See: https://docs.microsoft.com/en-us/windows/device-security/security-policy-settings/create-symbolic-links
-			if runtime.GOOS != "windows" {
-				fmt.Fprintf(OrigStderr, "log: failed to create symlink %s: %s", symlink, err)
-			}
+func createSymlink(fname, symlink string) {
+	// Symlinks are best-effort.
+	if err := os.Remove(symlink); err != nil && !os.IsNotExist(err) {
+		fmt.Fprintf(OrigStderr, "log: failed to remove symlink %s: %s\n", symlink, err)
+	}
+	if err := os.Symlink(filepath.Base(fname), symlink); err != nil {
+		// On Windows, this will be the common case, as symlink creation
+		// requires special privileges.
+		// See: https://docs.microsoft.com/en-us/windows/device-security/security-policy-settings/create-symbolic-links
+		if runtime.GOOS != "windows" {
+			fmt.Fprintf(OrigStderr, "log: failed to create symlink %s: %s\n", symlink, err)
 		}
 	}
-	return f, updatedRotation, fname, errors.Wrapf(err, "log: cannot create log")
 }
 
 // ListLogFiles returns a slice of FileInfo structs for each log file