[FIXED] Signal reopen suppresses NATS debug/trace in some cases

logger/logger.go

@@ -1,4 +1,4 @@
-// Copyright 2017-2019 The NATS Authors
+// Copyright 2017-2020 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
@@ -32,11 +32,14 @@ type Logger natsd.Logger
 // the Logger interface.
 type StanLogger struct {
 	mu    sync.RWMutex
+	ns    *natsd.Server
 	debug bool
 	trace bool
 	ltime bool
 	lfile string
 	fszl  int64
+	ndbg  bool
+	ntrc  bool
 	log   natsd.Logger
 }
 
@@ -46,6 +49,7 @@ func NewStanLogger() *StanLogger {
 }
 
 // SetLogger sets the logger, debug and trace
+// DEPRECATED: Use SetLoggerWithOpts instead.
 func (s *StanLogger) SetLogger(log Logger, logtime, debug, trace bool, logfile string) {
 	s.mu.Lock()
 	s.log = log
@@ -57,12 +61,37 @@ func (s *StanLogger) SetLogger(log Logger, logtime, debug, trace bool, logfile s
 }
 
 // SetFileSizeLimit sets the size limit for a logfile
+// DEPRECATED: Use SetLoggerWithOpts instead.
 func (s *StanLogger) SetFileSizeLimit(limit int64) {
 	s.mu.Lock()
 	s.fszl = limit
 	s.mu.Unlock()
 }
 
+// SetLoggerWithOpts sets the logger and various options.
+// Note that `debug` and `trace` here are for STAN.
+func (s *StanLogger) SetLoggerWithOpts(log Logger, nOpts *natsd.Options, debug, trace bool) {
+	s.mu.Lock()
+	s.log = log
+	s.ltime = nOpts.Logtime
+	s.debug = debug
+	s.trace = trace
+	s.lfile = nOpts.LogFile
+	s.fszl = nOpts.LogSizeLimit
+	s.ndbg = nOpts.Debug
+	s.ntrc = nOpts.Trace
+	s.mu.Unlock()
+}
+
+// SetNATSServer allows the logger to have a handle to the embedded NATS Server.
+// This sets the logger for the NATS Server and used during logfile re-opening.
+func (s *StanLogger) SetNATSServer(ns *natsd.Server) {
+	s.mu.Lock()
+	s.ns = ns
+	ns.SetLogger(s.log, s.ndbg, s.ntrc)
+	s.mu.Unlock()
+}
+
 // GetLogger returns the logger
 func (s *StanLogger) GetLogger() Logger {
 	s.mu.RLock()
@@ -87,10 +116,14 @@ func (s *StanLogger) ReopenLogFile() {
 			return
 		}
 	}
-	fileLog := natsdLogger.NewFileLogger(s.lfile, s.ltime, s.debug, s.trace, true)
+	// Pass true for debug and trace here. The higher level will suppress the debug/traces if needed.
+	fileLog := natsdLogger.NewFileLogger(s.lfile, s.ltime, true, true, true)
 	if s.fszl > 0 {
 		fileLog.SetSizeLimit(s.fszl)
 	}
+	if s.ns != nil {
+		s.ns.SetLogger(fileLog, s.ndbg, s.ntrc)
+	}
 	s.log = fileLog
 	s.mu.Unlock()
 	s.Noticef("File log re-opened")

server/server.go

@@ -1858,7 +1858,7 @@ func (s *StanServer) configureLogger() {
 		newLogger = natsdLogger.NewStdLogger(nOpts.Logtime, enableDebug, enableTrace, colors, true)
 	}
 
-	s.log.SetLogger(newLogger, nOpts.Logtime, sOpts.Debug, sOpts.Trace, nOpts.LogFile)
+	s.log.SetLoggerWithOpts(newLogger, nOpts, sOpts.Debug, sOpts.Trace)
 }
 
 // This is either running inside RunServerWithOpts() and before any reference
@@ -2366,9 +2366,7 @@ func (s *StanServer) startNATSServer() error {
 	if s.natsServer == nil {
 		return fmt.Errorf("no NATS Server object returned")
 	}
-	if stanLogger := s.log.GetLogger(); stanLogger != nil {
-		s.natsServer.SetLogger(stanLogger, opts.Debug, opts.Trace)
-	}
+	s.log.SetNATSServer(s.natsServer)
 	// Run server in Go routine.
 	go s.natsServer.Start()
 	// Wait for accept loop(s) to be started

server/server_run_test.go

@@ -1,4 +1,4 @@
-// Copyright 2016-2019 The NATS Authors
+// Copyright 2016-2020 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
@@ -17,6 +17,7 @@ import (
 	"crypto/tls"
 	"flag"
 	"fmt"
+	"io/ioutil"
 	"os"
 	"reflect"
 	"runtime"
@@ -1277,3 +1278,82 @@ func TestStreamingServerReadyLog(t *testing.T) {
 	getLeader(t, 5*time.Second, s, s2)
 	checkLog(t, l, true)
 }
+
+func TestReopenLogFileStopsNATSDebugTrace(t *testing.T) {
+	tmpDir, err := ioutil.TempDir("", "nats-streaming-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()
+
+	nOpts := natsdTest.DefaultTestOptions
+	nOpts.LogFile = file.Name()
+	nOpts.Debug = true
+	nOpts.Trace = true
+	nOpts.Logtime = true
+	nOpts.LogSizeLimit = 10 * 1024
+
+	sOpts := GetDefaultOptions()
+	// Ensure STAN debug and trace are set to false. This was the issue
+	sOpts.Debug = false
+	sOpts.Trace = false
+	sOpts.EnableLogging = true
+	s := runServerWithOpts(t, sOpts, &nOpts)
+	defer s.Shutdown()
+
+	check := func(str string, expected bool) {
+		t.Helper()
+		buf, err := ioutil.ReadFile(nOpts.LogFile)
+		if err != nil {
+			t.Fatalf("Error reading file: %v", err)
+		}
+		sbuf := string(buf)
+		present := strings.Contains(sbuf, str)
+		if expected && !present {
+			t.Fatalf("Expected to find %q, did not: %s", str, sbuf)
+		} else if !expected && present {
+			t.Fatalf("Expected to not find %q, but it was: %s", str, sbuf)
+		}
+	}
+	sc, err := stan.Connect(clusterName, "before_reopen")
+	if err != nil {
+		t.Fatalf("Error on connect: %v", err)
+	}
+	defer sc.Close()
+	check("before_reopen", true)
+	check("[DBG] STREAM: [Client:before_reopen]", false)
+
+	s.log.ReopenLogFile()
+	check("File log re-opened", true)
+
+	sc.Close()
+	sc, err = stan.Connect(clusterName, "after_reopen")
+	if err != nil {
+		t.Fatalf("Error on connect: %v", err)
+	}
+	defer sc.Close()
+	check("after_reopen", true)
+	check("[DBG] STREAM: [Client:after_reopen]", false)
+
+	payload := make([]byte, 1000)
+	for i := 0; i < len(payload); i++ {
+		payload[i] = 'A'
+	}
+	pstr := string(payload)
+	for i := 0; i < 10; i++ {
+		s.log.Noticef(pstr)
+	}
+	// Check that size limit has been applied.
+	files, err := ioutil.ReadDir(tmpDir)
+	if err != nil {
+		t.Fatalf("Error reading directory: %v", err)
+	}
+	if len(files) == 1 {
+		t.Fatal("Expected log to have been rotated, was not")
+	}
+}