From 00aee5f70f9b0e6ffffc550c51fc3e061645fba8 Mon Sep 17 00:00:00 2001
From: Raphael 'kena' Poss <knz@thaumogen.net>
Date: Mon, 11 Jan 2021 16:13:51 +0100
Subject: [PATCH] util/log: conditionally include the server IDs on every line

For CC security logging we want the ability to route the logging
events from the files where they are written into a centralized
logging collector.

However this routing is done line-by-line. To enable log aggregation
across multiple clusters, or multiple nodes, we need to disambiguate
which log entries come from which cluster and which node.

This patch accommodates this requirement by adding the cluster ID and,
for tenant servers, the tenant and SQL instance ID, on every output
line when the env var `COCKROACH_ALWAYS_LOG_SERVER_IDS` is set to a
true-ish value.

Note: this feature is unneeded in v21.1 because in that version JSON
logging is available and that already includes the server identity
bits.

Release note: None
---
 .../interactive_tests/test_force_auth_log.tcl | 48 ++++++++++
 pkg/server/testserver.go                      |  7 ++
 pkg/util/log/clog.go                          | 92 ++++++++++++++++---
 pkg/util/log/sync_buffer.go                   |  6 +-
 4 files changed, 135 insertions(+), 18 deletions(-)
 create mode 100644 pkg/cli/interactive_tests/test_force_auth_log.tcl

diff --git a/pkg/cli/interactive_tests/test_force_auth_log.tcl b/pkg/cli/interactive_tests/test_force_auth_log.tcl
new file mode 100644
index 000000000000..77b659d74c25
--- /dev/null
+++ b/pkg/cli/interactive_tests/test_force_auth_log.tcl
@@ -0,0 +1,48 @@
+#! /usr/bin/env expect -f
+
+source [file join [file dirname $argv0] common.tcl]
+
+set ::env(COCKROACH_INSECURE) "false"
+set ::env(COCKROACH_HOST) "localhost"
+set certs_dir "/certs"
+
+
+set ::env(COCKROACH_ALWAYS_LOG_CLUSTER_ID) 1
+set ::env(COCKROACH_ALWAYS_LOG_AUTHN_EVENTS) 1
+
+proc start_secure_server {argv certs_dir extra} {
+    report "BEGIN START SECURE SERVER"
+    system "$argv start-single-node --host=localhost --socket-dir=. --certs-dir=$certs_dir --pid-file=server_pid -s=path=logs/db --background $extra >>expect-cmd.log 2>&1;
+            $argv sql --certs-dir=$certs_dir -e 'select 1'"
+    report "END START SECURE SERVER"
+}
+
+proc stop_secure_server {argv certs_dir} {
+    report "BEGIN STOP SECURE SERVER"
+    system "$argv quit --certs-dir=$certs_dir"
+    report "END STOP SECURE SERVER"
+}
+
+
+start_secure_server $argv $certs_dir ""
+
+set logfile logs/db/logs/cockroach-auth.log
+
+# run a client command, so we have at least one authn event in the log.
+system "$argv sql -e 'create user someuser' --certs-dir=$certs_dir"
+system "$argv sql -e 'select 1' --user someuser --certs-dir=$certs_dir</dev/null || true"
+
+start_test "Check that the authentication events are reported"
+
+system "grep -q 'authentication succeeded' $logfile"
+system "grep -q 'authentication failed' $logfile"
+
+end_test
+
+start_test "Check that the auth events have both node ID and cluster ID"
+
+system "grep -q '\\\[n1,.*clusterID=........-....-....-....-............\\\] . authentication' $logfile"
+
+end_test
+
+stop_secure_server $argv $certs_dir
diff --git a/pkg/server/testserver.go b/pkg/server/testserver.go
index 55e5efce0b92..667a2f66ce35 100644
--- a/pkg/server/testserver.go
+++ b/pkg/server/testserver.go
@@ -56,6 +56,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/ts"
 	"github.com/cockroachdb/cockroach/pkg/util"
 	"github.com/cockroachdb/cockroach/pkg/util/hlc"
+	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/metric"
 	"github.com/cockroachdb/cockroach/pkg/util/netutil"
 	"github.com/cockroachdb/cockroach/pkg/util/stop"
@@ -616,6 +617,7 @@ func StartTenant(
 	if err != nil {
 		return "", "", err
 	}
+
 	s, err := newSQLServer(ctx, args)
 	if err != nil {
 		return "", "", err
@@ -713,6 +715,11 @@ func StartTenant(
 		return "", "", err
 	}
 
+	// Inform the logging package of the cluster identifiers.
+	clusterID := args.rpcContext.ClusterID.Get().String()
+	log.SetClusterID(clusterID)
+	log.SetTenantIDs(args.TenantID.String(), int32(args.sqlServerOptionalKVArgs.nodeIDContainer.SQLInstanceID()))
+
 	return pgLAddr, httpLAddr, nil
 }
 
diff --git a/pkg/util/log/clog.go b/pkg/util/log/clog.go
index 99c0fb702ac8..4a51b4baed70 100644
--- a/pkg/util/log/clog.go
+++ b/pkg/util/log/clog.go
@@ -17,11 +17,14 @@ import (
 	"context"
 	"fmt"
 	"runtime/debug"
+	"strconv"
+	"strings"
 	"sync"
 	"sync/atomic"
 	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/cli/exit"
+	"github.com/cockroachdb/cockroach/pkg/util/envutil"
 	"github.com/cockroachdb/cockroach/pkg/util/syncutil"
 	"github.com/cockroachdb/logtags"
 )
@@ -62,10 +65,6 @@ type loggingT struct {
 			hideStack bool                   // hides stack trace; only in effect when f is not nil
 		}
 
-		// the Cluster ID is reported on every new log file so as to ease the correlation
-		// of panic reports with self-reported log files.
-		clusterID string
-
 		// fatalCh is closed on fatal errors.
 		fatalCh chan struct{}
 
@@ -74,6 +73,18 @@ type loggingT struct {
 		active        bool
 		firstUseStack string
 	}
+
+	// the Cluster ID is reported on every new log file so as to ease the correlation
+	// of panic reports with self-reported log files.
+	//
+	// It is also set conditionally by an env var. See the doc string
+	// for 'alwaysAddClusterID'. (Feature deprecated in v20.2)
+	clusterID syncutil.AtomicString
+
+	// The following identifiers are reported when enabled.
+	tenantID      syncutil.AtomicString
+	nodeID        int32
+	sqlInstanceID int32
 }
 
 type loggerT struct {
@@ -194,28 +205,49 @@ func (l *loggingT) signalFatalCh() {
 	}
 }
 
-// SetClusterID stores the Cluster ID for further reference.
-//
-// TODO(knz): This should not be configured per-logger.
-// See: https://github.com/cockroachdb/cockroach/issues/40983
+// SetClusterID stores the cluster ID for further reference.
 func SetClusterID(clusterID string) {
-	// Ensure that the clusterID is logged with the same format as for
+	// Ensure that the ID gets logged with the same format as for
 	// new log files, even on the first log file. This ensures that grep
 	// will always find it.
 	ctx := logtags.AddTag(context.Background(), "config", nil)
 	addStructured(ctx, Severity_INFO, 1, "clusterID: %s", []interface{}{clusterID})
 
 	// Perform the change proper.
-	logging.mu.Lock()
-	defer logging.mu.Unlock()
-
-	if logging.mu.clusterID != "" {
+	if logging.clusterID.Get() != "" {
 		panic("clusterID already set")
 	}
 
-	logging.mu.clusterID = clusterID
+	logging.clusterID.Set(clusterID)
 }
 
+// SetTenantIDs stores the tenant ID and instance ID for further reference.
+func SetTenantIDs(tenantID string, sqlInstanceID int32) {
+	// Ensure that the IDs are logged with the same format as for
+	// new log files, even on the first log file. This ensures that grep
+	// will always find it.
+	ctx := logtags.AddTag(context.Background(), "config", nil)
+	addStructured(ctx, Severity_INFO, 1, "tenantID: %s", []interface{}{tenantID})
+	addStructured(ctx, Severity_INFO, 1, "instanceID: %d", []interface{}{sqlInstanceID})
+
+	// Perform the change proper.
+	if logging.tenantID.Get() != "" {
+		panic("tenantID already set")
+	}
+
+	logging.tenantID.Set(tenantID)
+	atomic.StoreInt32(&logging.sqlInstanceID, sqlInstanceID)
+}
+
+// alwaysAddServerIDs, when set, indicates that the cluster and other
+// server IDs must be reported in the log tags on every log line.
+//
+// We use an env var here because we need this feature in SQL pod
+// logs, and in v20.2 SQL pods don't have access to cluster settings.
+// Note: This feature is immediately obsolete, as v21.1 has JSON
+// logging and includes the cluster ID in log events already.
+var alwaysAddServerIDs = envutil.EnvOrDefaultBool("COCKROACH_ALWAYS_LOG_SERVER_IDS", false)
+
 // 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.
@@ -228,6 +260,38 @@ func (l *loggerT) outputLogEntry(entry Entry) {
 	// TODO(tschottdorf): this is a pretty horrible critical section.
 	l.mu.Lock()
 
+	if alwaysAddServerIDs {
+		// Only emit the cluster ID in tags if requested, and after the
+		// cluster ID is known already. (It may not be known for
+		// uninitialized clusters.)
+		// NB: This code is superseded in CockroachDB v21.1 by JSON
+		// logging which includes these details unconditionally.
+		var buf strings.Builder
+		buf.WriteString(entry.Tags)
+		if clusterID := logging.clusterID.Get(); len(clusterID) > 0 {
+			if buf.Len() > 0 {
+				buf.WriteByte(',')
+			}
+			buf.WriteString("clusterID=")
+			buf.WriteString(clusterID)
+		}
+		if tenantID := logging.tenantID.Get(); len(tenantID) > 0 {
+			if buf.Len() > 0 {
+				buf.WriteByte(',')
+			}
+			buf.WriteString("tenantID=")
+			buf.WriteString(tenantID)
+		}
+		if sqlInstanceID := atomic.LoadInt32(&logging.sqlInstanceID); sqlInstanceID != 0 {
+			if buf.Len() > 0 {
+				buf.WriteByte(',')
+			}
+			buf.WriteString("instanceID=")
+			buf.WriteString(strconv.Itoa(int(sqlInstanceID)))
+		}
+		entry.Tags = buf.String()
+	}
+
 	// Mark the logger as active, so that further configuration changes
 	// are disabled. See IsActive() and its callers for details.
 	setActive()
diff --git a/pkg/util/log/sync_buffer.go b/pkg/util/log/sync_buffer.go
index c8fcdb1b773b..1e0f7bc19dec 100644
--- a/pkg/util/log/sync_buffer.go
+++ b/pkg/util/log/sync_buffer.go
@@ -253,11 +253,9 @@ func (l *loggerT) initializeNewOutputFile(
 		l.makeStartLine("arguments: %s", os.Args),
 	)
 
-	logging.mu.Lock()
-	if logging.mu.clusterID != "" {
-		messages = append(messages, l.makeStartLine("clusterID: %s", logging.mu.clusterID))
+	if clusterID := logging.clusterID.Get(); len(clusterID) > 0 {
+		messages = append(messages, l.makeStartLine("clusterID: %s", clusterID))
 	}
-	logging.mu.Unlock()
 
 	// Including a non-ascii character in the first 1024 bytes of the log helps
 	// viewers that attempt to guess the character encoding.