// Copyright 2012-2019 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 server import ( "bytes" "fmt" "io/ioutil" "os" "runtime" "strings" "sync" "testing" "time" "github.com/nats-io/nats-server/v2/logger" ) func TestSetLogger(t *testing.T) { server := &Server{} defer server.SetLogger(nil, false, false) dl := &DummyLogger{} server.SetLogger(dl, true, true) // We assert that the logger has change to the DummyLogger _ = server.logging.logger.(*DummyLogger) if server.logging.debug != 1 { t.Fatalf("Expected debug 1, received value %d\n", server.logging.debug) } if server.logging.trace != 1 { t.Fatalf("Expected trace 1, received value %d\n", server.logging.trace) } // Check traces expectedStr := "This is a Notice" server.Noticef(expectedStr) dl.checkContent(t, expectedStr) expectedStr = "This is an Error" server.Errorf(expectedStr) dl.checkContent(t, expectedStr) expectedStr = "This is a Fatal" server.Fatalf(expectedStr) dl.checkContent(t, expectedStr) expectedStr = "This is a Debug" server.Debugf(expectedStr) dl.checkContent(t, expectedStr) expectedStr = "This is a Trace" server.Tracef(expectedStr) dl.checkContent(t, expectedStr) expectedStr = "This is a Warning" server.Tracef(expectedStr) dl.checkContent(t, expectedStr) // Make sure that we can reset to fal server.SetLogger(dl, false, false) if server.logging.debug != 0 { t.Fatalf("Expected debug 0, got %v", server.logging.debug) } if server.logging.trace != 0 { t.Fatalf("Expected trace 0, got %v", server.logging.trace) } // Now, Debug and Trace should not produce anything dl.msg = "" server.Debugf("This Debug should not be traced") dl.checkContent(t, "") server.Tracef("This Trace should not be traced") dl.checkContent(t, "") } type DummyLogger struct { sync.Mutex msg string } func (l *DummyLogger) checkContent(t *testing.T, expectedStr string) { l.Lock() defer l.Unlock() if l.msg != expectedStr { stackFatalf(t, "Expected log to be: %v, got %v", expectedStr, l.msg) } } func (l *DummyLogger) Noticef(format string, v ...interface{}) { l.Lock() defer l.Unlock() l.msg = fmt.Sprintf(format, v...) } func (l *DummyLogger) Errorf(format string, v ...interface{}) { l.Lock() defer l.Unlock() l.msg = fmt.Sprintf(format, v...) } func (l *DummyLogger) Warnf(format string, v ...interface{}) { l.Lock() defer l.Unlock() l.msg = fmt.Sprintf(format, v...) } func (l *DummyLogger) Fatalf(format string, v ...interface{}) { l.Lock() defer l.Unlock() l.msg = fmt.Sprintf(format, v...) } func (l *DummyLogger) Debugf(format string, v ...interface{}) { l.Lock() defer l.Unlock() l.msg = fmt.Sprintf(format, v...) } func (l *DummyLogger) Tracef(format string, v ...interface{}) { l.Lock() defer l.Unlock() l.msg = fmt.Sprintf(format, v...) } func TestReOpenLogFile(t *testing.T) { // We can't rename the file log when still opened on Windows, so skip if runtime.GOOS == "windows" { t.SkipNow() } s := &Server{opts: &Options{}} defer s.SetLogger(nil, false, false) // First check with no logger s.SetLogger(nil, false, false) s.ReOpenLogFile() // Then when LogFile is not provided. dl := &DummyLogger{} s.SetLogger(dl, false, false) s.ReOpenLogFile() dl.checkContent(t, "File log re-open ignored, not a file logger") // Set a File log s.opts.LogFile = "test.log" defer os.Remove(s.opts.LogFile) defer os.Remove(s.opts.LogFile + ".bak") fileLog := logger.NewFileLogger(s.opts.LogFile, s.opts.Logtime, s.opts.Debug, s.opts.Trace, true) s.SetLogger(fileLog, false, false) // Add some log expectedStr := "This is a Notice" s.Noticef(expectedStr) // Check content of log buf, err := ioutil.ReadFile(s.opts.LogFile) if err != nil { t.Fatalf("Error reading file: %v", err) } if !strings.Contains(string(buf), expectedStr) { t.Fatalf("Expected log to contain: %q, got %q", expectedStr, string(buf)) } // Close the file and rename it if err := os.Rename(s.opts.LogFile, s.opts.LogFile+".bak"); err != nil { t.Fatalf("Unable to rename log file: %v", err) } // Now re-open LogFile s.ReOpenLogFile() // Content should indicate that we have re-opened the log buf, err = ioutil.ReadFile(s.opts.LogFile) if err != nil { t.Fatalf("Error reading file: %v", err) } if strings.HasSuffix(string(buf), "File log-reopened") { t.Fatalf("File should indicate that file log was re-opened, got: %v", string(buf)) } // Make sure we can append to the log s.Noticef("New message") buf, err = ioutil.ReadFile(s.opts.LogFile) if err != nil { t.Fatalf("Error reading file: %v", err) } if strings.HasSuffix(string(buf), "New message") { t.Fatalf("New message was not appended after file was re-opened, got: %v", string(buf)) } } func TestFileLoggerSizeLimitAndReopen(t *testing.T) { s := &Server{opts: &Options{}} defer s.SetLogger(nil, false, false) tmpDir, err := ioutil.TempDir("", "nats-server") if err != nil { t.Fatal("Could not create tmp dir") } defer os.RemoveAll(tmpDir) file, err := ioutil.TempFile(tmpDir, "log_") if err != nil { t.Fatalf("Could not create the temp file: %v", err) } file.Close() // Set a File log s.opts.LogFile = file.Name() s.opts.Logtime = true s.opts.LogSizeLimit = 1000 s.ConfigureLogger() // Add a trace s.Noticef("this is a notice") // Do a re-open... s.ReOpenLogFile() // Content should indicate that we have re-opened the log buf, err := ioutil.ReadFile(s.opts.LogFile) if err != nil { t.Fatalf("Error reading file: %v", err) } if strings.HasSuffix(string(buf), "File log-reopened") { t.Fatalf("File should indicate that file log was re-opened, got: %v", string(buf)) } // Now make sure that the limit is still honored. txt := make([]byte, 800) for i := 0; i < len(txt); i++ { txt[i] = 'A' } s.Noticef(string(txt)) for i := 0; i < len(txt); i++ { txt[i] = 'B' } s.Noticef(string(txt)) buf, err = ioutil.ReadFile(s.opts.LogFile) if err != nil { t.Fatalf("Error reading file: %v", err) } sbuf := string(buf) if strings.Contains(sbuf, "AAAAA") || strings.Contains(sbuf, "BBBBB") { t.Fatalf("Looks like file was not rotated: %s", sbuf) } if !strings.Contains(sbuf, "Rotated log, backup saved") { t.Fatalf("File should have been rotated, was not: %s", sbuf) } } func TestNoPasswordsFromConnectTrace(t *testing.T) { opts := DefaultOptions() opts.NoLog = false opts.Trace = true opts.Username = "derek" opts.Password = "s3cr3t" opts.PingInterval = 2 * time.Minute setBaselineOptions(opts) s := &Server{opts: opts} dl := &DummyLogger{} s.SetLogger(dl, false, true) _ = s.logging.logger.(*DummyLogger) if s.logging.trace != 1 { t.Fatalf("Expected trace 1, received value %d\n", s.logging.trace) } defer s.SetLogger(nil, false, false) c, _, _ := newClientForServer(s) defer c.close() connectOp := []byte("CONNECT {\"user\":\"derek\",\"pass\":\"s3cr3t\"}\r\n") err := c.parse(connectOp) if err != nil { t.Fatalf("Received error: %v\n", err) } dl.Lock() hasPass := strings.Contains(dl.msg, "s3cr3t") dl.Unlock() if hasPass { t.Fatalf("Password detected in log output: %s", dl.msg) } } func TestRemovePassFromTrace(t *testing.T) { tests := []struct { name string input string expected string }{ { "user and pass", "CONNECT {\"user\":\"derek\",\"pass\":\"s3cr3t\"}\r\n", "CONNECT {\"user\":\"derek\",\"pass\":\"[REDACTED]\"}\r\n", }, { "user and pass extra space", "CONNECT {\"user\":\"derek\",\"pass\": \"s3cr3t\"}\r\n", "CONNECT {\"user\":\"derek\",\"pass\": \"[REDACTED]\"}\r\n", }, { "user and pass is empty", "CONNECT {\"user\":\"derek\",\"pass\":\"\"}\r\n", "CONNECT {\"user\":\"derek\",\"pass\":\"[REDACTED]\"}\r\n", }, { "user and pass is empty whitespace", "CONNECT {\"user\":\"derek\",\"pass\":\" \"}\r\n", "CONNECT {\"user\":\"derek\",\"pass\":\"[REDACTED]\"}\r\n", }, { "user and pass whitespace", "CONNECT {\"user\":\"derek\",\"pass\": \"s3cr3t\" }\r\n", "CONNECT {\"user\":\"derek\",\"pass\": \"[REDACTED]\" }\r\n", }, { "only pass", "CONNECT {\"pass\":\"s3cr3t\",}\r\n", "CONNECT {\"pass\":\"[REDACTED]\",}\r\n", }, { "invalid json", "CONNECT {pass:s3cr3t , password = s3cr3t}", "CONNECT {pass:[REDACTED], password = s3cr3t}", }, { "invalid json no whitespace after key", "CONNECT {pass:s3cr3t , password= s3cr3t}", "CONNECT {pass:[REDACTED], password= s3cr3t}", }, { "both pass and wrong password key", `CONNECT {"pass":"s3cr3t4", "password": "s3cr3t4"}`, `CONNECT {"pass":"[REDACTED]", "password": "s3cr3t4"}`, }, { "invalid json", "CONNECT {user = hello, password = s3cr3t}", "CONNECT {user = hello, password = [REDACTED]}", }, { "complete connect", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"foo\",\"pass\":\"s3cr3t\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"foo\",\"pass\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n", }, { "invalid json with only pass key", "CONNECT {pass:s3cr3t\r\n", "CONNECT {pass:[REDACTED]\r\n", }, { "invalid password key also filtered", "CONNECT {\"password\":\"s3cr3t\",}\r\n", "CONNECT {\"password\":\"[REDACTED]\",}\r\n", }, { "single long password with whitespace", "CONNECT {\"pass\":\"secret password which is very long\",}\r\n", "CONNECT {\"pass\":\"[REDACTED]\",}\r\n", }, { "single long pass key is filtered", "CONNECT {\"pass\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\"}\r\n", "CONNECT {\"pass\":\"[REDACTED]\"}\r\n", }, { "duplicate keys only filtered once", "CONNECT {\"pass\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\",\"pass\":\"BBBBBBBBBBBBBBBBBBBB\",\"password\":\"CCCCCCCCCCCCCCCC\"}\r\n", "CONNECT {\"pass\":\"[REDACTED]\",\"pass\":\"BBBBBBBBBBBBBBBBBBBB\",\"password\":\"CCCCCCCCCCCCCCCC\"}\r\n", }, { "invalid json with multiple keys only one is filtered", "CONNECT {pass = \"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\",pass= \"BBBBBBBBBBBBBBBBBBBB\",password =\"CCCCCCCCCCCCCCCC\"}\r\n", "CONNECT {pass = \"[REDACTED]\",pass= \"BBBBBBBBBBBBBBBBBBBB\",password =\"CCCCCCCCCCCCCCCC\"}\r\n", }, { "complete connect protocol", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"foo\",\"pass\":\"s3cr3t\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"foo\",\"pass\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n", }, { "user and pass are filterered", "CONNECT {\"user\":\"s3cr3t\",\"pass\":\"s3cr3t\"}\r\n", "CONNECT {\"user\":\"s3cr3t\",\"pass\":\"[REDACTED]\"}\r\n", }, { "complete connect using password key with user and password being the same", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"pass\":\"s3cr3t\",\"tls_required\":false,\"name\":\"...\"}\r\n", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"pass\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"...\"}\r\n", }, { "complete connect with user password and name all the same", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"pass\":\"s3cr3t\",\"tls_required\":false,\"name\":\"s3cr3t\"}\r\n", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"pass\":\"[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\",\"pass\":\"s3cr3t\",\"tls_required\":false,\"name\":\"foo\"}\r\n", "CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"s3cr3t\",\"pass\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"foo\"}\r\n", }, } for _, test := range tests { t.Run(test.name, func(t *testing.T) { output := removePassFromTrace([]byte(test.input)) if !bytes.Equal(output, []byte(test.expected)) { t.Errorf("\nExpected %q\n got: %q", test.expected, string(output)) } }) } }