Merge pull request #623 from nats-io/fix_logfile_issues

[FIXED] Possible panic and other issue with file logger

logger/logger.go

@@ -14,8 +14,10 @@
 package logger
 
 import (
+	"io"
 	"sync"
 
+	natsdLogger "github.com/nats-io/gnatsd/logger"
 	natsd "github.com/nats-io/gnatsd/server"
 )
 
@@ -32,6 +34,8 @@ type StanLogger struct {
 	mu    sync.RWMutex
 	debug bool
 	trace bool
+	ltime bool
+	lfile string
 	log   natsd.Logger
 }
 
@@ -41,11 +45,13 @@ func NewStanLogger() *StanLogger {
 }
 
 // SetLogger sets the logger, debug and trace
-func (s *StanLogger) SetLogger(log Logger, debug, trace bool) {
+func (s *StanLogger) SetLogger(log Logger, logtime, debug, trace bool, logfile string) {
 	s.mu.Lock()
 	s.log = log
+	s.ltime = logtime
 	s.debug = debug
 	s.trace = trace
+	s.lfile = logfile
 	s.mu.Unlock()
 }
 
@@ -57,6 +63,28 @@ func (s *StanLogger) GetLogger() Logger {
 	return l
 }
 
+// ReopenLogFile closes and reopen the logfile.
+// Does nothing if the logger is not a file based.
+func (s *StanLogger) ReopenLogFile() {
+	s.mu.Lock()
+	if s.lfile == "" {
+		s.mu.Unlock()
+		s.Noticef("File log re-open ignored, not a file logger")
+		return
+	}
+	if l, ok := s.log.(io.Closer); ok {
+		if err := l.Close(); err != nil {
+			s.mu.Unlock()
+			s.Errorf("Unable to close logger: %v", err)
+			return
+		}
+	}
+	fileLog := natsdLogger.NewFileLogger(s.lfile, s.ltime, s.debug, s.trace, true)
+	s.log = fileLog
+	s.mu.Unlock()
+	s.Noticef("File log re-opened")
+}
+
 // Noticef logs a notice statement
 func (s *StanLogger) Noticef(format string, v ...interface{}) {
 	s.executeLogCall(func(log Logger, format string, v ...interface{}) {

logger/logger_test.go

@@ -14,11 +14,15 @@
 package logger
 
 import (
+	"errors"
 	"flag"
 	"fmt"
+	"io/ioutil"
 	"os"
 	"strings"
 	"testing"
+
+	natsdLogger "github.com/nats-io/gnatsd/logger"
 )
 
 func TestMain(m *testing.M) {
@@ -52,46 +56,68 @@ func (d *dummyLogger) Fatalf(format string, args ...interface{}) {
 	d.msg = fmt.Sprintf(format, args...)
 }
 
+func (d *dummyLogger) Close() error {
+	return errors.New("dummy error")
+}
+
 func (d *dummyLogger) Reset() {
 	d.msg = ""
 }
 
 func TestLogger(t *testing.T) {
 	logger := NewStanLogger()
 
-	check := func(log Logger, debug, trace bool) {
+	check := func(log Logger, logtime, debug, trace bool, logfile string) {
 		logger.mu.RLock()
-		l, dbg, trc := logger.log, logger.debug, logger.trace
+		l, ltime, dbg, trc, lfile := logger.log, logger.ltime, logger.debug, logger.trace, logger.lfile
 		logger.mu.RUnlock()
 		if log != l {
 			t.Fatalf("Expected log to be %v, got %v", log, l)
 		}
+		if logtime != ltime {
+			t.Fatalf("Expected ltime to be %v, got %v", logtime, ltime)
+		}
 		if debug != dbg {
 			t.Fatalf("Expected debug to be %v, got %v", debug, dbg)
 		}
 		if trace != trc {
 			t.Fatalf("Expected trace to be %v, got %v", trace, trc)
 		}
+		if logfile != lfile {
+			t.Fatalf("Expected lfile to be %v, got %v", logfile, lfile)
+		}
 	}
-	check(nil, false, false)
+	check(nil, false, false, false, "")
 	// This should not produce any logging, but should not crash
 	logger.Noticef("Should not crash")
 
-	logger.SetLogger(nil, false, false)
-	check(nil, false, false)
+	logger.SetLogger(nil, false, false, false, "")
+	check(nil, false, false, false, "")
+
+	logger.SetLogger(nil, true, false, false, "")
+	check(nil, true, false, false, "")
 
-	logger.SetLogger(nil, true, false)
-	check(nil, true, false)
+	logger.SetLogger(nil, false, true, false, "")
+	check(nil, false, true, false, "")
 
-	logger.SetLogger(nil, false, true)
-	check(nil, false, true)
+	logger.SetLogger(nil, false, false, true, "")
+	check(nil, false, false, true, "")
 
-	logger.SetLogger(nil, true, true)
-	check(nil, true, true)
+	logger.SetLogger(nil, false, false, false, "test.log")
+	check(nil, false, false, false, "test.log")
+
+	logger.SetLogger(nil, true, false, false, "test.log")
+	check(nil, true, false, false, "test.log")
+
+	logger.SetLogger(nil, true, true, false, "test.log")
+	check(nil, true, true, false, "test.log")
+
+	logger.SetLogger(nil, true, true, true, "test.log")
+	check(nil, true, true, true, "test.log")
 
 	dl := &dummyLogger{}
-	logger.SetLogger(dl, false, false)
-	check(dl, false, false)
+	logger.SetLogger(dl, false, false, false, "")
+	check(dl, false, false, false, "")
 
 	ls := logger.GetLogger()
 	if dl != ls {
@@ -125,7 +151,7 @@ func TestLogger(t *testing.T) {
 	checkLogger("")
 
 	// enable debug and trace
-	logger.SetLogger(dl, true, true)
+	logger.SetLogger(dl, false, true, true, "")
 
 	// Debug is set so we should have the value
 	logger.Debugf("foo")
@@ -134,4 +160,30 @@ func TestLogger(t *testing.T) {
 	// Trace is set so we should have the value
 	logger.Tracef("foo")
 	checkLogger("foo")
+
+	// Trying to re-open should log that this is not a filelog based
+	logger.ReopenLogFile()
+	checkLogger("File log re-open ignored, not a file logger")
+
+	// Set a filename but still use the dummy logger
+	logger.SetLogger(dl, true, true, true, "dummy.log")
+	// Try to re-open, this should produce an error
+	logger.ReopenLogFile()
+	checkLogger("Unable to close logger: dummy error")
+
+	// Switch to file log
+	fname := "test.log"
+	defer os.Remove(fname)
+	fl := natsdLogger.NewFileLogger(fname, true, true, true, true)
+	logger.SetLogger(fl, true, true, true, fname)
+	// Reopen and check file content
+	logger.ReopenLogFile()
+	buf, err := ioutil.ReadFile(fname)
+	if err != nil {
+		t.Fatalf("Error reading file: %v", err)
+	}
+	expectedStr := "File log re-opened"
+	if !strings.Contains(string(buf), expectedStr) {
+		t.Fatalf("Expected log to contain %q, got %q", expectedStr, string(buf))
+	}
 }

server/server.go

@@ -1401,7 +1401,7 @@ func RunServerWithOpts(stanOpts *Options, natsOpts *server.Options) (newServer *
 	// If a custom logger is provided, use this one, otherwise, check
 	// if we should configure the logger or not.
 	if sOpts.CustomLogger != nil {
-		s.log.SetLogger(sOpts.CustomLogger, sOpts.Debug, sOpts.Trace)
+		s.log.SetLogger(sOpts.CustomLogger, nOpts.Logtime, sOpts.Debug, sOpts.Trace, "")
 	} else if sOpts.EnableLogging {
 		s.configureLogger()
 	}
@@ -1564,7 +1564,7 @@ func (s *StanServer) configureLogger() {
 		newLogger = natsdLogger.NewStdLogger(nOpts.Logtime, enableDebug, enableTrace, colors, true)
 	}
 
-	s.log.SetLogger(newLogger, sOpts.Debug, sOpts.Trace)
+	s.log.SetLogger(newLogger, nOpts.Logtime, sOpts.Debug, sOpts.Trace, nOpts.LogFile)
 }
 
 // This is either running inside RunServerWithOpts() and before any reference

server/signal.go

@@ -36,7 +36,7 @@ func (s *StanServer) handleSignals() {
 				os.Exit(0)
 			case syscall.SIGUSR1:
 				// File log re-open for rotating file logs.
-				s.natsServer.ReOpenLogFile()
+				s.log.ReopenLogFile()
 			}
 		}
 	}()

server/signal_test.go

@@ -16,6 +16,7 @@
 package server
 
 import (
+	"fmt"
 	"io/ioutil"
 	"os"
 	"strings"
@@ -24,6 +25,7 @@ import (
 	"time"
 
 	natsd "github.com/nats-io/gnatsd/server"
+	natsdTest "github.com/nats-io/gnatsd/test"
 )
 
 func TestSignalIgnoreUnknown(t *testing.T) {
@@ -42,44 +44,73 @@ func TestSignalIgnoreUnknown(t *testing.T) {
 
 func TestSignalToReOpenLogFile(t *testing.T) {
 	logFile := "test.log"
-	defer os.Remove(logFile)
-	defer os.Remove(logFile + ".bak")
-	sopts := GetDefaultOptions()
-	sopts.HandleSignals = true
-	nopts := &natsd.Options{
-		Host:    "localhost",
-		Port:    -1,
-		NoSigs:  true,
-		LogFile: logFile,
-	}
-	sopts.EnableLogging = true
-	s := runServerWithOpts(t, sopts, nopts)
-	defer s.Shutdown()
+	f := func(iter int) {
+		defer os.Remove(logFile)
+		defer os.Remove(logFile + ".bak")
 
-	// Add a trace
-	expectedStr := "This is a Notice"
-	s.log.Noticef(expectedStr)
-	buf, err := ioutil.ReadFile(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))
-	}
-	// Rename the file
-	if err := os.Rename(logFile, logFile+".bak"); err != nil {
-		t.Fatalf("Unable to rename file: %v", err)
-	}
-	// This should cause file to be reopened.
-	syscall.Kill(syscall.Getpid(), syscall.SIGUSR1)
-	// Wait a bit for action to be performed
-	time.Sleep(500 * time.Millisecond)
-	buf, err = ioutil.ReadFile(logFile)
-	if err != nil {
-		t.Fatalf("Error reading file: %v", err)
+		var ns *natsd.Server
+		if iter == 0 {
+			ns = natsdTest.RunDefaultServer()
+			defer ns.Shutdown()
+		}
+		sopts := GetDefaultOptions()
+		sopts.HandleSignals = true
+		nopts := &natsd.Options{
+			Host:    "localhost",
+			Port:    -1,
+			NoSigs:  true,
+			LogFile: logFile,
+		}
+		sopts.EnableLogging = true
+		if iter == 0 {
+			sopts.NATSServerURL = "nats://" + ns.Addr().String()
+		}
+		s := runServerWithOpts(t, sopts, nopts)
+		defer s.Shutdown()
+
+		// Repeat twice to ensure that signal is processed more than once
+		for i := 0; i < 2; i++ {
+			// Add a trace
+			expectedStr := "This is a Notice"
+			s.log.Noticef(expectedStr)
+			buf, err := ioutil.ReadFile(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))
+			}
+			// Rename the file
+			if err := os.Rename(logFile, logFile+".bak"); err != nil {
+				t.Fatalf("Unable to rename file: %v", err)
+			}
+			// This should cause file to be reopened.
+			syscall.Kill(syscall.Getpid(), syscall.SIGUSR1)
+			// Wait a bit for action to be performed
+			waitFor(t, 2*time.Second, 15*time.Millisecond, func() error {
+				buf, err = ioutil.ReadFile(logFile)
+				if err != nil {
+					return fmt.Errorf("Error reading file: %v", err)
+				}
+				expectedStr = "File log re-opened"
+				if !strings.Contains(string(buf), expectedStr) {
+					return fmt.Errorf("Expected log to contain %q, got %q", expectedStr, string(buf))
+				}
+				return nil
+			})
+			// Make sure that new traces are added
+			expectedStr = "This is a new notice"
+			s.log.Noticef(expectedStr)
+			buf, err = ioutil.ReadFile(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))
+			}
+		}
 	}
-	expectedStr = "File log re-opened"
-	if !strings.Contains(string(buf), expectedStr) {
-		t.Fatalf("Expected log to contain %q, got %q", expectedStr, string(buf))
+	for iter := 0; iter < 2; iter++ {
+		f(iter)
 	}
 }