Move tls handshake errors to debug

[ripienaar]

This turned out to be a much bigger undertaking due to how the logs are used in tests

Signed-off-by: R.I.Pienaar [email protected]

[derekcollison]

This feels like it should be a server opt-in to downgrade. I personally would not want this behavior in a production system I would run..

[ripienaar]

Yeah its hard to say, Phil and others have indicated these logs dont add any value other than being annoying so feature group decided to downgrade their level, but we could also make it opt in I suppose - though I do not find these useful due to the nature of modern networks with scanners, load balancers and all kind of other annoyances

[wallyqs]

would prefer instead to have two channels, leaving the errCh as it was and add another debugCh which can be used to capture only those entries on that level

[ripienaar]

considered that but all the tests only enable debugging when there are logs to match - so doing this didnt seem like it would improve anything

[ripienaar]

aside these log based checks are universally awful, some of these tests only acts on a message being logged regardless of content - incredibly brittle as we add logs over time.

[ripienaar]

nats-server/server/routes_test.go

Lines 1824 to 1829 in e9ee2a0

	select {
	case <-l.errCh:
	gotIt = true
	case <-time.After(time.Second):
	// Try again
	}

[kozlovic]

I fail to see why all tests that used captureErrorLogger{} need to be changed. For instance, I did just the client modification in client.go, and run this test (without modification) and it passes. Ditto for the gateway test, etc.. I think only tests that did check for TLS handshake should be changed to go to debug, and one can very well create a dedicated capture logger to check that only a given err/debug/whatever message matches before inserting in the channel (to avoid the test itself to have to deal with err/debug/whatever traces that are not relevant.

[ripienaar]

The only reason most of them changed is because I renamed the struct as its not anymore a error logger.

[ripienaar]

I've updated this - didnt rename the struct so I think its incorrectly named now but at least the change set is smaller and added a suggested filter to the one

[kozlovic]

@ripienaar Sorry for the back and forth. I think it is simpler to create a "dedicated" logger that captures TLS handshake errors and have the tests that were looking for those type of errors (now debug traces, but still an "error") to use that logger instead. Does that make sense?

[kozlovic]

That's not what I meant. We can create a specific logger for the TLS handshake error and modify only the tests that were checking for the handshake error (when using the generic error capture logger). I would say that in most cases we really only care that we got an error (now a debug trace, but still an handshake error), so a channel of struct{} would suffice, but since in one of the test TestLeafNodeTLSConfigReloadForRemote, we check that we get bad certificate, we could still have string.
So, I would add a dedicated logger, and modify the tests. Here is a diff on the addition of the logger and modification of only 2 of the tests (the others would be similar):

+type captureTLSHandshakeError struct {
+       DummyLogger
+       ch chan string
+}
+
+func (c *captureTLSHandshakeError) Debugf(format string, v ...any) {
+       msg := fmt.Sprintf(format, v...)
+       if strings.Contains(msg, "handshake error") {
+               select {
+               case c.ch <- msg:
+               default:
+               }
+       }
+}
+
 func TestLeafNodeTLSConfigReload(t *testing.T) {
        template := `
                listen: 127.0.0.1:-1
@@ -2623,8 +2638,8 @@ func TestLeafNodeTLSConfigReload(t *testing.T) {
        srvA, optsA := RunServerWithConfig(confA)
        defer srvA.Shutdown()
 
-       lg := &captureErrorLogger{errCh: make(chan string, 10)}
-       srvA.SetLogger(lg, false, false)
+       lg := &captureTLSHandshakeError{ch: make(chan string, 10)}
+       srvA.SetLogger(lg, true, false)
 
        confB := createConfFile(t, []byte(fmt.Sprintf(`
                listen: -1
@@ -2654,14 +2669,7 @@ func TestLeafNodeTLSConfigReload(t *testing.T) {
 
        // Wait for the error
        select {
-       case err := <-lg.errCh:
-               // Since Go 1.18, we had to regenerate certs to not have to use GODEBUG="x509sha1=1"
-               // But on macOS, with our test CA certs, no SCTs included, it will fail
-               // for the reason "x509: “localhost” certificate is not standards compliant"
-               // instead of "unknown authority".
-               if !strings.Contains(err, "unknown") && !strings.Contains(err, "compliant") {
-                       t.Fatalf("Unexpected error: %v", err)
-               }
+       case <-lg.ch:
        case <-time.After(2 * time.Second):
                t.Fatalf("Did not get TLS error")
        }
@@ -2696,8 +2704,8 @@ func TestLeafNodeTLSConfigReloadForRemote(t *testing.T) {
        srvA, optsA := RunServerWithConfig(confA)
        defer srvA.Shutdown()
 
-       lg := &captureErrorLogger{errCh: make(chan string, 10)}
-       srvA.SetLogger(lg, false, false)
+       lg := &captureTLSHandshakeError{ch: make(chan string, 10)}
+       srvA.SetLogger(lg, true, false)
 
        template := `
                listen: -1
@@ -2721,7 +2729,7 @@ func TestLeafNodeTLSConfigReloadForRemote(t *testing.T) {
 
        // Wait for the error
        select {
-       case err := <-lg.errCh:
+       case err := <-lg.ch:
                if !strings.Contains(err, "bad certificate") {
                        t.Fatalf("Unexpected error: %v", err)
                }

[kozlovic]

You need to modify the test in the /test package that uses this logger: TestClusterTLSInsecure.