Repository: nats-io/nats-server (go)

Issue:
NATS Server can log secret information on permissions violations
### Observed behavior

When a NATS client has successfully connected to the NATS server and is granted certain permissions, if they attempt to take actions that are outside the scope of their permissions, they will get something like a "Permission Violation" error. At the same time, the NATS server will log this permissions violation and includes the "auth user" that encountered a permissions violation. The [auth user] can include secret information depending on how the client originally connected. 

Based on my understanding of the potential things that can be logged, the Nkey option, Username option, and JWT option likely shouldn't have secret information. The Nkey that a client presents as part of its request to connect (I think) is the public half of the Nkey pair. It also looks like the JWT option explicitly calls out putting `pubKey` in the output. 

Things get dicey with the Token user though.  In my use case, I am using auth callouts and the auth callout service only cares about the information stuffed into the Token option. NATS clients in my environment put their credentials into the Token option. If one of those clients commits a permissions violation, their entire Token (which includes their credentials) are logged by the NATS server.

[auth user]:  https://github.com/nats-io/nats-server/blob/0efea661bac82ec5de6da3b3035b5257947875a0/server/client.go#L6081

### Expected behavior

Expect secret information is not logged by the NATS server. 

We are working around this by now having our clients also specify a username (that is unused by our auth callout service) because that is higher in the switch statement that determines what gets logged. But this is brittle. Any changes to the switch statement inside of the `getAuthUser` method could land us back at where we were originally. 

### Server and client version

- nats-server: `2.10.18`
- nats.go: `v1.37.0`
- nats.net: `v2.5.10`

### Host environment

_No response_

### Steps to reproduce

- Connect to the nats server using the token option
- Violate the permissions that you are granted
- See the NATS server will log your token

Pull request description:
Redact auth tokens in trace logs for enhanced security
Updated trace functionality to redact auth_tokens in addition to passwords in logs to prevent sensitive information leakage. Refactored logic to use a generalized `redact` function and added extensive tests to ensure proper redaction in various scenarios.

Fix #6666

Signed-off-by: Alberto Ricart <alberto@synadia.com>


Patch:
diff --git a/server/client.go b/server/client.go
index c6e76a95..bc59b725 100644
--- a/server/client.go
+++ b/server/client.go
@@ -1991,20 +1991,26 @@ func (c *client) processErr(errStr string) {
 
 // Password pattern matcher.
 var passPat = regexp.MustCompile(`"?\s*pass\S*?"?\s*[:=]\s*"?(([^",\r\n}])*)`)
+var tokenPat = regexp.MustCompile(`"?\s*auth_token\S*?"?\s*[:=]\s*"?(([^",\r\n}])*)`)
 
-// removePassFromTrace removes any notion of passwords from trace
+// removeSecretsFromTrace removes any notion of passwords/tokens from trace
 // messages for logging.
-func removePassFromTrace(arg []byte) []byte {
-	if !bytes.Contains(arg, []byte(`pass`)) {
-		return arg
+func removeSecretsFromTrace(arg []byte) []byte {
+	buf := redact("pass", passPat, arg)
+	return redact("auth_token", tokenPat, buf)
+}
+
+func redact(name string, pat *regexp.Regexp, proto []byte) []byte {
+	if !bytes.Contains(proto, []byte(name)) {
+		return proto
 	}
 	// Take a copy of the connect proto just for the trace message.
 	var _arg [4096]byte
-	buf := append(_arg[:0], arg...)
+	buf := append(_arg[:0], proto...)
 
-	m := passPat.FindAllSubmatchIndex(buf, -1)
+	m := pat.FindAllSubmatchIndex(buf, -1)
 	if len(m) == 0 {
-		return arg
+		return proto
 	}
 
 	redactedPass := []byte("[REDACTED]")
@@ -2015,7 +2021,7 @@ func removePassFromTrace(arg []byte) []byte {
 		start := i[2]
 		end := i[3]
 
-		// Replace password substring.
+		// Replace value substring.
 		buf = append(buf[:start], append(redactedPass, buf[end:]...)...)
 		break
 	}
@@ -6112,7 +6118,7 @@ func (c *client) getRawAuthUser() string {
 	case c.opts.JWT != _EMPTY_:
 		return c.pubKey
 	case c.opts.Token != _EMPTY_:
-		return c.opts.Token
+		return "[REDACTED]"
 	default:
 		return _EMPTY_
 	}
@@ -6129,7 +6135,7 @@ func (c *client) getAuthUser() string {
 	case c.opts.JWT != _EMPTY_:
 		return fmt.Sprintf("JWT User %q", c.pubKey)
 	case c.opts.Token != _EMPTY_:
-		return fmt.Sprintf("Token %q", c.opts.Token)
+		return fmt.Sprintf("Token %q", "[REDACTED]")
 	default:
 		return `User "N/A"`
 	}
diff --git a/server/consumer.go b/server/consumer.go
index 5cb78306..f9a1beca 100644
--- a/server/consumer.go
+++ b/server/consumer.go
@@ -5042,9 +5042,9 @@ func (o *consumer) didNotDeliver(seq uint64, subj string) {
 	}
 	o.mu.Unlock()
 
-	if checkDeliveryInterest {
-		localInterest := !o.hasNoLocalInterest()
-		o.updateDeliveryInterest(localInterest)
+	// If we do not have interest update that here.
+	if checkDeliveryInterest && o.hasNoLocalInterest() {
+		o.updateDeliveryInterest(false)
 	}
 }
 
diff --git a/server/parser.go b/server/parser.go
index ed3eaa15..3ba608d6 100644
--- a/server/parser.go
+++ b/server/parser.go
@@ -940,7 +940,7 @@ func (c *client) parse(buf []byte) error {
 					return err
 				}
 				if trace {
-					c.traceInOp("CONNECT", removePassFromTrace(arg))
+					c.traceInOp("CONNECT", removeSecretsFromTrace(arg))
 				}
 				if err := c.processConnect(arg); err != nil {
 					return err


Test patch:
diff --git a/server/client_test.go b/server/client_test.go
index 1b37b48f..eb59248f 100644
--- a/server/client_test.go
+++ b/server/client_test.go
@@ -1624,6 +1624,18 @@ func TestClientUserInfo(t *testing.T) {
 	if got != expected {
 		t.Errorf("Expected %q, got %q", expected, got)
 	}
+
+	c = &client{
+		cid: 1024,
+		opts: ClientOpts{
+			Token: "s3cr3t!",
+		},
+	}
+	got = c.getAuthUser()
+	expected = `Token "[REDACTED]"`
+	if got != expected {
+		t.Errorf("Expected %q, got %q", expected, got)
+	}
 }
 
 type captureWarnLogger struct {
diff --git a/server/jetstream_cluster_1_test.go b/server/jetstream_cluster_1_test.go
index aa2bdaef..5be0e01d 100644
--- a/server/jetstream_cluster_1_test.go
+++ b/server/jetstream_cluster_1_test.go
@@ -8242,72 +8242,6 @@ func TestJetStreamClusterConsumerResetPendingDeliveriesOnMaxAckPendingUpdate(t *
 	require_Equal(t, l, 0)
 }
 
-func TestJetStreamClusterConsumerActiveAfterDidNotDeliverOverRoute(t *testing.T) {
-	c := createJetStreamClusterExplicit(t, "R3S", 3)
-	defer c.shutdown()
-
-	nc, js := jsClientConnect(t, c.randomServer())
-	defer nc.Close()
-
-	_, err := js.AddStream(&nats.StreamConfig{
-		Name:     "TEST",
-		Subjects: []string{"foo"},
-		Replicas: 3,
-	})
-	require_NoError(t, err)
-
-	pubAck, err := js.Publish("foo", nil)
-	require_NoError(t, err)
-	require_Equal(t, pubAck.Sequence, 1)
-
-	_, err = js.AddConsumer("TEST", &nats.ConsumerConfig{
-		Durable:        "CONSUMER",
-		Replicas:       3,
-		DeliverSubject: "deliver_subject",
-	})
-	require_NoError(t, err)
-
-	ci, err := js.ConsumerInfo("TEST", "CONSUMER")
-	require_NoError(t, err)
-	require_False(t, ci.PushBound)
-
-	cl := c.consumerLeader(globalAccountName, "TEST", "CONSUMER")
-	rs := c.randomNonConsumerLeader(globalAccountName, "TEST", "CONSUMER")
-	ncRs, jsRs := jsClientConnect(t, rs)
-	defer ncRs.Close()
-
-	// Just noop callback.
-	cb := func(msg *nats.Msg) {}
-	_, err = jsRs.Subscribe("foo", cb, nats.Bind("TEST", "CONSUMER"))
-	require_NoError(t, err)
-
-	// Eventually the sub should be known to the leader, and report active/bound.
-	checkFor(t, 2*time.Second, 100*time.Millisecond, func() error {
-		ci, err = js.ConsumerInfo("TEST", "CONSUMER")
-		if err != nil {
-			return err
-		}
-		if !ci.PushBound {
-			return errors.New("push not bound")
-		}
-		return nil
-	})
-
-	// Simulate failed delivery over route connection.
-	acc, err := cl.lookupAccount(globalAccountName)
-	require_NoError(t, err)
-	mset, err := acc.lookupStream("TEST")
-	require_NoError(t, err)
-	o := mset.lookupConsumer("CONSUMER")
-	require_NotNil(t, o)
-	o.didNotDeliver(1, "foo")
-
-	// Consumer should still be active/bound.
-	ci, err = js.ConsumerInfo("TEST", "CONSUMER")
-	require_NoError(t, err)
-	require_True(t, ci.PushBound)
-}
-
 //
 // DO NOT ADD NEW TESTS IN THIS FILE (unless to balance test times)
 // Add at the end of jetstream_cluster_<n>_test.go, with <n> being the highest value.
diff --git a/server/log_test.go b/server/log_test.go
index 57add588..55220489 100644
--- a/server/log_test.go
+++ b/server/log_test.go
@@ -341,7 +341,135 @@ func TestRemovePassFromTrace(t *testing.T) {
 
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
-			output := removePassFromTrace([]byte(test.input))
+			output := removeSecretsFromTrace([]byte(test.input))
+			if !bytes.Equal(output, []byte(test.expected)) {
+				t.Errorf("\nExpected %q\n    got: %q", test.expected, string(output))
+			}
+		})
+	}
+}
+
+func TestRemoveAuthTokenFromTrace(t *testing.T) {
+	tests := []struct {
+		name     string
+		input    string
+		expected string
+	}{
+		{
+			"user and auth_token",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":\"s3cr3t\"}\r\n",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":\"[REDACTED]\"}\r\n",
+		},
+		{
+			"user and pass extra space",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":  \"s3cr3t\"}\r\n",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":  \"[REDACTED]\"}\r\n",
+		},
+		{
+			"user and pass is empty",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":\"\"}\r\n",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":\"[REDACTED]\"}\r\n",
+		},
+		{
+			"user and pass is empty whitespace",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":\"               \"}\r\n",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":\"[REDACTED]\"}\r\n",
+		},
+		{
+			"user and pass whitespace",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":    \"s3cr3t\"     }\r\n",
+			"CONNECT {\"user\":\"derek\",\"auth_token\":    \"[REDACTED]\"     }\r\n",
+		},
+		{
+			"only pass",
+			"CONNECT {\"auth_token\":\"s3cr3t\",}\r\n",
+			"CONNECT {\"auth_token\":\"[REDACTED]\",}\r\n",
+		},
+		{
+			"invalid json",
+			"CONNECT {auth_token:s3cr3t ,   password =  s3cr3t}",
+			"CONNECT {auth_token:[REDACTED],   password =  [REDACTED]}",
+		},
+		{
+			"invalid json no whitespace after key",
+			"CONNECT {auth_token:s3cr3t ,   password=  s3cr3t}",
+			"CONNECT {auth_token:[REDACTED],   password=  [REDACTED]}",
+		},
+		{
+			"both pass and wrong password key",
+			`CONNECT {"auth_token":"s3cr3t4", "password": "s3cr3t4"}`,
+			`CONNECT {"auth_token":"[REDACTED]", "password": "[REDACTED]"}`,
+		},
+		{
+			"invalid json",
+			"CONNECT {user = hello, auth_token =  s3cr3t}",
+			"CONNECT {user = hello, auth_token =  [REDACTED]}",
+		},
+		{
+			"complete connect",
+			"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"auth_token\":\"s3cr3t\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n",
+			"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"auth_token\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n",
+		},
+		{
+			"invalid json with only pass key",
+			"CONNECT {auth_token:s3cr3t\r\n",
+			"CONNECT {auth_token:[REDACTED]\r\n",
+		},
+		{
+			"invalid password key also filtered",
+			"CONNECT {\"auth_token\":\"s3cr3t\",}\r\n",
+			"CONNECT {\"auth_token\":\"[REDACTED]\",}\r\n",
+		},
+		{
+			"single long password with whitespace",
+			"CONNECT {\"auth_token\":\"secret password which is very long\",}\r\n",
+			"CONNECT {\"auth_token\":\"[REDACTED]\",}\r\n",
+		},
+		{
+			"single long pass key is filtered",
+			"CONNECT {\"auth_token\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\"}\r\n",
+			"CONNECT {\"auth_token\":\"[REDACTED]\"}\r\n",
+		},
+		{
+			"duplicate keys only filtered once",
+			"CONNECT {\"auth_token\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\",\"auth_token\":\"BBB\",\"pass\":\"BBBBBBBBBBBBBBBBBBBB\",\"password\":\"CCCCCCCCCCCCCCCC\"}\r\n",
+			"CONNECT {\"auth_token\":\"[REDACTED]\",\"auth_token\":\"BBB\",\"pass\":\"[REDACTED]\",\"password\":\"CCCCCCCCCCCCCCCC\"}\r\n",
+		},
+		{
+			"invalid json with multiple keys only one is filtered",
+			"CONNECT {auth_token = \"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\",pass= \"BBBBBBBBBBBBBBBBBBBB\",password =\"CCCCCCCCCCCCCCCC\"}\r\n",
+			"CONNECT {auth_token = \"[REDACTED]\",pass= \"[REDACTED]\",password =\"CCCCCCCCCCCCCCCC\"}\r\n",
+		},
+		{
+			"complete connect protocol",
+			"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"foo\",\"auth_token\":\"s3cr3t\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n",
+			"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"foo\",\"auth_token\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n",
+		},
+		{
+			"user and token are filterered",
+			"CONNECT {\"user\":\"s3cr3t\",\"auth_token\":\"s3cr3t\"}\r\n",
+			"CONNECT {\"user\":\"s3cr3t\",\"auth_token\":\"[REDACTED]\"}\r\n",
+		},
+		{
+			"complete connect using token key with user and token being the same",
+			"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"auth_token\":\"s3cr3t\",\"tls_required\":false,\"name\":\"...\"}\r\n",
+			"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"auth_token\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"...\"}\r\n",
+		},
+		{
+			"complete connect with user, token and name all the same",
+			"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"auth_token\":\"s3cr3t\",\"tls_required\":false,\"name\":\"s3cr3t\"}\r\n",
+			"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"auth_token\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"s3cr3t\"}\r\n",
+		},
+		{
+			"complete connect extra white space at the beginning",
+			"CONNECT 	 {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"auth_token\":\"s3cr3t\",\"tls_required\":false,\"name\":\"foo\"}\r\n",
+			"CONNECT 	 {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"auth_token\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"foo\"}\r\n",
+		},
+	}
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			output := removeSecretsFromTrace([]byte(test.input))
 			if !bytes.Equal(output, []byte(test.expected)) {
 				t.Errorf("\nExpected %q\n    got: %q", test.expected, string(output))
 			}
diff --git a/server/monitor_test.go b/server/monitor_test.go
index 86111cb2..d9e9255b 100644
--- a/server/monitor_test.go
+++ b/server/monitor_test.go
@@ -4752,7 +4752,7 @@ func TestMonitorAuthorizedUsers(t *testing.T) {
 		nats.Token("sometoken"))
 	defer c.Close()
 	// We should get the token specified by the user
-	checkAuthUser("sometoken")
+	checkAuthUser("[REDACTED]")
 	c.Close()
 	s.Shutdown()