Redact URLs before logging or returning in error (nats-io#2643)

* Redact URLs before logging or returning in error This does not affect strings which failed to parse, and in such a scenario there's a mix of "which evil" to accept; we can't sanely find what should be redacted in those cases, so we leave them alone for debugging. The JWT library returns some errors for Operator URLs, but it rejects URLs which contain userinfo, so there can't be passwords in those and they're safe. Fixes nats-io#2597 * Test the URL redaction auxiliary functions * End-to-end tests for secrets in debug/trace Create internal/testhelper and move DummyLogger there, so it can be used from the test/ sub-dir too. Let DummyLogger optionally accumulate all log messages, not just retain the last-seen message. Confirm no passwords logged by TestLeafNodeBasicAuthFailover. Change TestNoPasswordsFromConnectTrace to check all trace messages, not just the most recent. Validate existing trace redaction in TestRouteToSelf. * Test for password in solicited route reconnect debug
dmpriso · Oct 27, 2021 · fc6df0f · fc6df0f
1 parent 7dc5014
commit fc6df0f
Show file tree

Hide file tree

Showing 13 changed files with 291 additions and 81 deletions.
diff --git a/internal/testhelper/logging.go b/internal/testhelper/logging.go
@@ -0,0 +1,127 @@
+// Copyright 2019-2021 The NATS Authors
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package testhelper
+
+// These routines need to be accessible in both the server and test
+// directories, and tests importing a package don't get exported symbols from
+// _test.go files in the imported package, so we put them here where they can
+// be used freely.
+
+import (
+	"fmt"
+	"strings"
+	"sync"
+	"testing"
+)
+
+type DummyLogger struct {
+	sync.Mutex
+	Msg     string
+	AllMsgs []string
+}
+
+func (l *DummyLogger) CheckContent(t *testing.T, expectedStr string) {
+	t.Helper()
+	l.Lock()
+	defer l.Unlock()
+	if l.Msg != expectedStr {
+		t.Fatalf("Expected log to be: %v, got %v", expectedStr, l.Msg)
+	}
+}
+
+func (l *DummyLogger) aggregate() {
+	if l.AllMsgs != nil {
+		l.AllMsgs = append(l.AllMsgs, l.Msg)
+	}
+}
+
+func (l *DummyLogger) Noticef(format string, v ...interface{}) {
+	l.Lock()
+	defer l.Unlock()
+	l.Msg = fmt.Sprintf(format, v...)
+	l.aggregate()
+}
+func (l *DummyLogger) Errorf(format string, v ...interface{}) {
+	l.Lock()
+	defer l.Unlock()
+	l.Msg = fmt.Sprintf(format, v...)
+	l.aggregate()
+}
+func (l *DummyLogger) Warnf(format string, v ...interface{}) {
+	l.Lock()
+	defer l.Unlock()
+	l.Msg = fmt.Sprintf(format, v...)
+	l.aggregate()
+}
+func (l *DummyLogger) Fatalf(format string, v ...interface{}) {
+	l.Lock()
+	defer l.Unlock()
+	l.Msg = fmt.Sprintf(format, v...)
+	l.aggregate()
+}
+func (l *DummyLogger) Debugf(format string, v ...interface{}) {
+	l.Lock()
+	defer l.Unlock()
+	l.Msg = fmt.Sprintf(format, v...)
+	l.aggregate()
+}
+func (l *DummyLogger) Tracef(format string, v ...interface{}) {
+	l.Lock()
+	defer l.Unlock()
+	l.Msg = fmt.Sprintf(format, v...)
+	l.aggregate()
+}
+
+// NewDummyLogger creates a dummy logger and allows to ask for logs to be
+// retained instead of just keeping the most recent. Use retain to provide an
+// initial size estimate on messages (not to provide a max capacity).
+func NewDummyLogger(retain uint) *DummyLogger {
+	l := &DummyLogger{}
+	if retain > 0 {
+		l.AllMsgs = make([]string, 0, retain)
+	}
+	return l
+}
+
+func (l *DummyLogger) Drain() {
+	l.Lock()
+	defer l.Unlock()
+	if l.AllMsgs == nil {
+		return
+	}
+	l.AllMsgs = make([]string, 0, len(l.AllMsgs))
+}
+
+func (l *DummyLogger) CheckForProhibited(t *testing.T, reason, needle string) {
+	t.Helper()
+	l.Lock()
+	defer l.Unlock()
+
+	if l.AllMsgs == nil {
+		t.Fatal("DummyLogger.CheckForProhibited called without AllMsgs being collected")
+	}
+
+	// Collect _all_ matches, rather than have to re-test repeatedly.
+	// This will particularly help with less deterministic tests with multiple matches.
+	shouldFail := false
+	for i := range l.AllMsgs {
+		if strings.Contains(l.AllMsgs[i], needle) {
+			t.Errorf("log contains %s: %v", reason, l.AllMsgs[i])
+			shouldFail = true
+		}
+	}
+	if shouldFail {
+		t.FailNow()
+	}
+}
diff --git a/server/accounts.go b/server/accounts.go
@@ -3473,11 +3473,11 @@ func (ur *URLAccResolver) Fetch(name string) (string, error) {
 	url := ur.url + name
 	resp, err := ur.c.Get(url)
 	if err != nil {
-		return _EMPTY_, fmt.Errorf("could not fetch <%q>: %v", url, err)
+		return _EMPTY_, fmt.Errorf("could not fetch <%q>: %v", redactURLString(url), err)
 	} else if resp == nil {
-		return _EMPTY_, fmt.Errorf("could not fetch <%q>: no response", url)
+		return _EMPTY_, fmt.Errorf("could not fetch <%q>: no response", redactURLString(url))
 	} else if resp.StatusCode != http.StatusOK {
-		return _EMPTY_, fmt.Errorf("could not fetch <%q>: %v", url, resp.Status)
+		return _EMPTY_, fmt.Errorf("could not fetch <%q>: %v", redactURLString(url), resp.Status)
 	}
 	defer resp.Body.Close()
 	body, err := ioutil.ReadAll(resp.Body)

diff --git a/server/client.go b/server/client.go
@@ -4826,10 +4826,10 @@ func (c *client) reconnect() {
 			srv.Debugf("Not attempting reconnect for solicited route, already connected to \"%s\"", rid)
 			return
 		} else if rid == srv.info.ID {
-			srv.Debugf("Detected route to self, ignoring %q", rurl)
+			srv.Debugf("Detected route to self, ignoring %q", rurl.Redacted())
 			return
 		} else if rtype != Implicit || retryImplicit {
-			srv.Debugf("Attempting reconnect for solicited route \"%s\"", rurl)
+			srv.Debugf("Attempting reconnect for solicited route \"%s\"", rurl.Redacted())
 			// Keep track of this go-routine so we can wait for it on
 			// server shutdown.
 			srv.startGoRoutine(func() { srv.reConnectToRoute(rurl, rtype) })

diff --git a/server/client_test.go b/server/client_test.go
@@ -1819,7 +1819,7 @@ func TestTraceMsg(t *testing.T) {
 
 		c.traceMsg(ut.Msg)
 
-		got := c.srv.logging.logger.(*DummyLogger).msg
+		got := c.srv.logging.logger.(*DummyLogger).Msg
 		if !reflect.DeepEqual(ut.Wanted, got) {
 			t.Errorf("Desc: %s. Msg %q. Traced msg want: %s, got: %s", ut.Desc, ut.Msg, ut.Wanted, got)
 		}
@@ -2427,15 +2427,15 @@ func TestClientConnectionName(t *testing.T) {
 			checkLog := func(suffix string) {
 				t.Helper()
 				l.Lock()
-				msg := l.msg
+				msg := l.Msg
 				l.Unlock()
 				if strings.Contains(msg, "(MISSING)") {
 					t.Fatalf("conn name was not escaped properly, got MISSING: %s", msg)
 				}
-				if !strings.Contains(l.msg, test.kindStr) {
+				if !strings.Contains(l.Msg, test.kindStr) {
 					t.Fatalf("expected kind to be %q, got: %s", test.kindStr, msg)
 				}
-				if !strings.HasSuffix(l.msg, suffix) {
+				if !strings.HasSuffix(l.Msg, suffix) {
 					t.Fatalf("expected statement to end with %q, got %s", suffix, msg)
 				}
 			}

diff --git a/server/gateway_test.go b/server/gateway_test.go
@@ -2946,7 +2946,7 @@ type checkErrorLogger struct {
 func (l *checkErrorLogger) Errorf(format string, args ...interface{}) {
 	l.DummyLogger.Errorf(format, args...)
 	l.Lock()
-	if strings.Contains(l.msg, l.checkErrorStr) {
+	if strings.Contains(l.Msg, l.checkErrorStr) {
 		l.gotError = true
 	}
 	l.Unlock()

diff --git a/server/leafnode.go b/server/leafnode.go
@@ -320,7 +320,7 @@ func validateLeafNode(o *Options) error {
 				}
 			}
 			if !ok {
-				return fmt.Errorf("remote leaf node configuration cannot have a mix of websocket and non-websocket urls: %q", rcfg.URLs)
+				return fmt.Errorf("remote leaf node configuration cannot have a mix of websocket and non-websocket urls: %q", redactURLList(rcfg.URLs))
 			}
 		}
 	}
@@ -1187,6 +1187,7 @@ func (c *client) doUpdateLNURLs(cfg *leafNodeCfg, scheme string, URLs []string)
 	for _, surl := range URLs {
 		url, err := url.Parse(fmt.Sprintf("%s://%s", scheme, surl))
 		if err != nil {
+			// As per below, the URLs we receive should not have contained URL info, so this should be safe to log.
 			c.Errorf("Error parsing url %q: %v", surl, err)
 			continue
 		}

diff --git a/server/leafnode_test.go b/server/leafnode_test.go
@@ -32,6 +32,8 @@ import (
 
 	jwt "github.com/nats-io/jwt/v2"
 	"github.com/nats-io/nats.go"
+
+	"github.com/nats-io/nats-server/v2/internal/testhelper"
 )
 
 type captureLeafNodeRandomIPLogger struct {
@@ -409,7 +411,12 @@ func TestLeafNodeAccountNotFound(t *testing.T) {
 
 // This test ensures that we can connect using proper user/password
 // to a LN URL that was discovered through the INFO protocol.
+// We also check that the password doesn't leak to debug/trace logs.
 func TestLeafNodeBasicAuthFailover(t *testing.T) {
+	// Something a little longer than "pwd" to prevent false positives amongst many log lines;
+	// don't make it complex enough to be subject to %-escaping, we want a simple needle search.
+	fatalPassword := "pwdfatal"
+
 	content := `
 	listen: "127.0.0.1:-1"
 	cluster {
@@ -421,18 +428,18 @@ func TestLeafNodeBasicAuthFailover(t *testing.T) {
 		listen: "127.0.0.1:-1"
 		authorization {
 			user: foo
-			password: pwd
+			password: %s
 			timeout: 1
 		}
 	}
 	`
-	conf := createConfFile(t, []byte(fmt.Sprintf(content, "")))
+	conf := createConfFile(t, []byte(fmt.Sprintf(content, "", fatalPassword)))
 	defer removeFile(t, conf)
 
 	sb1, ob1 := RunServerWithConfig(conf)
 	defer sb1.Shutdown()
 
-	conf = createConfFile(t, []byte(fmt.Sprintf(content, fmt.Sprintf("routes: [nats://127.0.0.1:%d]", ob1.Cluster.Port))))
+	conf = createConfFile(t, []byte(fmt.Sprintf(content, fmt.Sprintf("routes: [nats://127.0.0.1:%d]", ob1.Cluster.Port), fatalPassword)))
 	defer removeFile(t, conf)
 
 	sb2, _ := RunServerWithConfig(conf)
@@ -450,17 +457,20 @@ func TestLeafNodeBasicAuthFailover(t *testing.T) {
 		remotes [
 			{
 				account: "foo"
-				url: "nats://foo:pwd@127.0.0.1:%d"
+				url: "nats://foo:%s@127.0.0.1:%d"
 			}
 		]
 	}
 	`
-	conf = createConfFile(t, []byte(fmt.Sprintf(content, ob1.LeafNode.Port)))
+	conf = createConfFile(t, []byte(fmt.Sprintf(content, fatalPassword, ob1.LeafNode.Port)))
 	defer removeFile(t, conf)
 
 	sa, _ := RunServerWithConfig(conf)
 	defer sa.Shutdown()
 
+	l := testhelper.NewDummyLogger(100)
+	sa.SetLogger(l, true, true) // we want debug & trace logs, to check for passwords in them
+
 	checkLeafNodeConnected(t, sa)
 
 	// Shutdown sb1, sa should reconnect to sb2
@@ -471,6 +481,10 @@ func TestLeafNodeBasicAuthFailover(t *testing.T) {
 
 	// Should be able to reconnect
 	checkLeafNodeConnected(t, sa)
+
+	// Look at all our logs for the password; at time of writing it doesn't appear
+	// but we want to safe-guard against it.
+	l.CheckForProhibited(t, "fatal password", fatalPassword)
 }
 
 func TestLeafNodeRTT(t *testing.T) {