sql: Extend SQL audit logging to log operations run by admin users

Release note (sql change): SQL audit log can now be extended to track
operations run by admin users.
By enabling the cluster setting sql.log.admin_audit.enabled, the
sql-audit-log will note if a command has been run by an admin by
including "admin" in the log entry next to the statement.

docs/generated/eventlog.md

@@ -185,6 +185,34 @@ are only emitted via external logging.
 Events in this category are logged to channel SENSITIVE_ACCESS.
 
 
+### `admin_query`
+
+An event of type `admin_query` is recorded when a user with admin privileges (the user
+is directly or indirectly a member of the admin role) executes a query.
+
+
+
+
+#### Common fields
+
+| Field | Description | Sensitive |
+|--|--|--|
+| `Timestamp` | The timestamp of the event. Expressed as nanoseconds since the Unix epoch. | no |
+| `EventType` | The type of the event. | no |
+| `Statement` | A normalized copy of the SQL statement that triggered the event. | yes |
+| `User` | The user account that triggered the event. | yes |
+| `DescriptorID` | The primary object descriptor affected by the operation. Set to zero for operations that don't affect descriptors. | no |
+| `ApplicationName` | The application name for the session where the event was emitted. This is included in the event to ease filtering of logging output by application. | yes |
+| `PlaceholderValues` | The mapping of SQL placeholders to their values, for prepared statements. | yes |
+| `ExecMode` | How the statement was being executed (exec/prepare, etc.) | no |
+| `NumRows` | Number of rows returned. For mutation statements (INSERT, etc) that do not produce result rows, this field reports the number of rows affected. | no |
+| `SQLSTATE` | The SQLSTATE code for the error, if an error was encountered. Empty/omitted if no error. | no |
+| `ErrorText` | The text of the error if any. | yes |
+| `Age` | Age of the query in milliseconds. | no |
+| `NumRetries` | Number of retries, when the txn was reretried automatically by the server. | no |
+| `FullTableScan` | Whether the query contains a full table scan. | no |
+| `FullIndexScan` | Whether the query contains a full secondary index scan. | no |
+
 ### `sensitive_table_access`
 
 An event of type `sensitive_table_access` is recorded when an access is performed to

pkg/sql/BUILD.bazel

@@ -398,6 +398,7 @@ go_test(
     name = "sql_test",
     size = "medium",
     srcs = [
+        "admin_audit_log_test.go",
         "alter_column_type_test.go",
         "ambiguous_commit_test.go",
         "as_of_test.go",
@@ -579,7 +580,9 @@ go_test(
         "//pkg/util/json",
         "//pkg/util/leaktest",
         "//pkg/util/log",
+        "//pkg/util/log/channel",
         "//pkg/util/log/eventpb",
+        "//pkg/util/log/logconfig",
         "//pkg/util/metric",
         "//pkg/util/mon",
         "//pkg/util/protoutil",

pkg/sql/admin_audit_log_test.go

@@ -0,0 +1,344 @@
+// Copyright 2021 The Cockroach Authors.
+//
+// Use of this software is governed by the Business Source License
+// included in the file licenses/BSL.txt.
+//
+// As of the Change Date specified in that file, in accordance with
+// the Business Source License, use of this software will be governed
+// by the Apache License, Version 2.0, included in the file
+// licenses/APL.txt.
+
+package sql
+
+import (
+	"context"
+	gosql "database/sql"
+	"math"
+	"net/url"
+	"regexp"
+	"strings"
+	"testing"
+
+	"github.com/cockroachdb/cockroach/pkg/base"
+	"github.com/cockroachdb/cockroach/pkg/testutils/serverutils"
+	"github.com/cockroachdb/cockroach/pkg/testutils/sqlutils"
+	"github.com/cockroachdb/cockroach/pkg/util/leaktest"
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+	"github.com/cockroachdb/cockroach/pkg/util/log/channel"
+	"github.com/cockroachdb/cockroach/pkg/util/log/logconfig"
+	"github.com/cockroachdb/errors"
+)
+
+func installSensitiveAccessLogFileSink(sc *log.TestLogScope, t *testing.T) func() {
+	// Enable logging channels.
+	log.TestingResetActive()
+	cfg := logconfig.DefaultConfig()
+	// Make a sink for just the session log.
+	bt := true
+	cfg.Sinks.FileGroups = map[string]*logconfig.FileSinkConfig{
+		"sql-audit": {
+			CommonSinkConfig: logconfig.CommonSinkConfig{Auditable: &bt},
+			Channels:         logconfig.ChannelList{Channels: []log.Channel{channel.SENSITIVE_ACCESS}},
+		}}
+	dir := sc.GetDirectory()
+	if err := cfg.Validate(&dir); err != nil {
+		t.Fatal(err)
+	}
+	cleanup, err := log.ApplyConfig(cfg)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	return cleanup
+}
+
+// TestAdminAuditLogBasic verifies that after enabling the admin audit log,
+// a SELECT statement executed by the admin user is logged to the audit log.
+func TestAdminAuditLogBasic(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+	sc := log.ScopeWithoutShowLogs(t)
+	defer sc.Close(t)
+
+	cleanup := installSensitiveAccessLogFileSink(sc, t)
+	defer cleanup()
+
+	s, sqlDB, _ := serverutils.StartServer(t, base.TestServerArgs{})
+	defer s.Stopper().Stop(context.Background())
+
+	db := sqlutils.MakeSQLRunner(sqlDB)
+
+	db.Exec(t, `SET CLUSTER SETTING sql.log.admin_audit.enabled = true;`)
+	db.Exec(t, `SELECT 1;`)
+
+	var selectAdminRe = regexp.MustCompile(`"EventType":"admin_query","Statement":"‹SELECT 1›","User":"‹root›"`)
+
+	log.Flush()
+
+	entries, err := log.FetchEntriesFromFiles(0, math.MaxInt64, 10000, selectAdminRe,
+		log.WithMarkedSensitiveData)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	if len(entries) == 0 {
+		t.Fatal(errors.New("no entries found"))
+	}
+}
+
+// TestAdminAuditLogRegularUser verifies that after enabling the admin audit log,
+// a SELECT statement executed by the a regular user does not appear in the audit log.
+func TestAdminAuditLogRegularUser(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+	sc := log.ScopeWithoutShowLogs(t)
+	defer sc.Close(t)
+
+	cleanup := installSensitiveAccessLogFileSink(sc, t)
+	defer cleanup()
+
+	s, sqlDB, _ := serverutils.StartServer(t, base.TestServerArgs{})
+	defer s.Stopper().Stop(context.Background())
+
+	db := sqlutils.MakeSQLRunner(sqlDB)
+
+	db.Exec(t, `SET CLUSTER SETTING sql.log.admin_audit.enabled = true;`)
+
+	db.Exec(t, `CREATE USER testuser`)
+	pgURL, testuserCleanupFunc := sqlutils.PGUrl(
+		t, s.ServingSQLAddr(), "TestImportPrivileges-testuser",
+		url.User("testuser"),
+	)
+
+	defer testuserCleanupFunc()
+	testuser, err := gosql.Open("postgres", pgURL.String())
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	defer testuser.Close()
+
+	_, err = testuser.Exec(`SELECT 1`)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	var selectRe = regexp.MustCompile(`SELECT 1`)
+
+	log.Flush()
+
+	entries, err := log.FetchEntriesFromFiles(0, math.MaxInt64, 10000, selectRe,
+		log.WithMarkedSensitiveData)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	if len(entries) != 0 {
+		t.Fatal(errors.New("unexpected SELECT 1 entry found"))
+	}
+}
+
+// TestAdminAuditLogTransaction verifies that every statement in a transaction
+// is logged to the admin audit log.
+func TestAdminAuditLogTransaction(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+	sc := log.ScopeWithoutShowLogs(t)
+	defer sc.Close(t)
+
+	cleanup := installSensitiveAccessLogFileSink(sc, t)
+	defer cleanup()
+
+	s, sqlDB, _ := serverutils.StartServer(t, base.TestServerArgs{})
+	defer s.Stopper().Stop(context.Background())
+
+	db := sqlutils.MakeSQLRunner(sqlDB)
+
+	db.Exec(t, `SET CLUSTER SETTING sql.log.admin_audit.enabled = true;`)
+	db.Exec(t, `
+BEGIN;
+CREATE TABLE t();
+SELECT * FROM t;
+SELECT 1;
+COMMIT;
+`)
+
+	testCases := []struct {
+		name string
+		exp  string
+	}{
+		{
+			"select-1-query",
+			`"EventType":"admin_query","Statement":"‹SELECT 1›"`,
+		},
+		{
+			"select-*-from-table-query",
+			`"EventType":"admin_query","Statement":"‹SELECT * FROM \"\".\"\".t›"`,
+		},
+		{
+			"create-table-query",
+			`"EventType":"admin_query","Statement":"‹CREATE TABLE defaultdb.public.t ()›"`,
+		},
+	}
+
+	log.Flush()
+
+	entries, err := log.FetchEntriesFromFiles(
+		0,
+		math.MaxInt64,
+		10000,
+		regexp.MustCompile(`"EventType":"admin_query"`),
+		log.WithMarkedSensitiveData,
+	)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	if len(entries) == 0 {
+		t.Fatal(errors.Newf("no entries found"))
+	}
+
+	for _, tc := range testCases {
+		found := false
+		for _, e := range entries {
+			if !strings.Contains(e.Message, tc.exp) {
+				continue
+			}
+			found = true
+		}
+		if !found {
+			t.Fatal(errors.Newf("no matching entry found for test case %s", tc.name))
+		}
+	}
+}
+
+// TestAdminAuditLogMultipleTransactions verifies that after enabling the admin
+// audit log, statements executed in a transaction by a user with admin privilege
+// are all logged. Once the user loses admin privileges, the statements
+// should no longer be logged.
+func TestAdminAuditLogMultipleTransactions(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+	sc := log.ScopeWithoutShowLogs(t)
+	defer sc.Close(t)
+
+	cleanup := installSensitiveAccessLogFileSink(sc, t)
+	defer cleanup()
+
+	s, sqlDB, _ := serverutils.StartServer(t, base.TestServerArgs{})
+	defer s.Stopper().Stop(context.Background())
+
+	db := sqlutils.MakeSQLRunner(sqlDB)
+
+	db.Exec(t, `SET CLUSTER SETTING sql.log.admin_audit.enabled = true;`)
+
+	db.Exec(t, `CREATE USER testuser`)
+	pgURL, testuserCleanupFunc := sqlutils.PGUrl(
+		t, s.ServingSQLAddr(), "TestImportPrivileges-testuser",
+		url.User("testuser"),
+	)
+
+	defer testuserCleanupFunc()
+	testuser, err := gosql.Open("postgres", pgURL.String())
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	defer testuser.Close()
+
+	db.Exec(t, `GRANT admin TO testuser`)
+
+	_, err = testuser.Exec(`
+BEGIN;
+CREATE TABLE t();
+SELECT * FROM t;
+SELECT 1;
+COMMIT;
+`)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	testCases := []struct {
+		name string
+		exp  string
+	}{
+		{
+			"select-1-query",
+			`"EventType":"admin_query","Statement":"‹SELECT 1›"`,
+		},
+		{
+			"select-*-from-table-query",
+			`"EventType":"admin_query","Statement":"‹SELECT * FROM \"\".\"\".t›"`,
+		},
+		{
+			"create-table-query",
+			`"EventType":"admin_query","Statement":"‹CREATE TABLE defaultdb.public.t ()›"`,
+		},
+	}
+
+	log.Flush()
+
+	entries, err := log.FetchEntriesFromFiles(
+		0,
+		math.MaxInt64,
+		10000,
+		regexp.MustCompile(`"EventType":"admin_query"`),
+		log.WithMarkedSensitiveData,
+	)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	if len(entries) == 0 {
+		t.Fatal(errors.Newf("no entries found"))
+	}
+
+	for _, tc := range testCases {
+		found := false
+		for _, e := range entries {
+			if !strings.Contains(e.Message, tc.exp) {
+				continue
+			}
+			found = true
+		}
+		if !found {
+			t.Fatal(errors.Newf("no matching entry found for test case %s", tc.name))
+		}
+	}
+
+	// Remove admin from testuser, statements should no longer appear in the
+	// log.
+	db.Exec(t, "REVOKE admin FROM testuser")
+
+	// SELECT 2 should not appear in the log.
+	_, err = testuser.Exec(`
+BEGIN;
+SELECT 2;
+COMMIT;
+`)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	log.Flush()
+
+	entries, err = log.FetchEntriesFromFiles(
+		0,
+		math.MaxInt64,
+		10000,
+		regexp.MustCompile(`SELECT 2`),
+		log.WithMarkedSensitiveData,
+	)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	if len(entries) != 0 {
+		for _, e := range entries {
+			t.Log(e.Message)
+		}
+		t.Fatal(errors.Newf("unexpected entries found"))
+	}
+}