bug fix: server-log was incorrectly pointing to the main-log, resul… (#180)

- bug fix: server-log was incorrectly pointing to the main-log, resulting in a blank server log (reported in issue #179)
- update Logrus to v1.4.2
- small code clean-ups
- add `dep ensure` to tarvis.yml file

.travis.yml

@@ -14,6 +14,7 @@ cache:
 
 install:
   - go get -u github.com/golang/dep/cmd/dep
+  - dep ensure
 
 script:
   - ./.travis.gofmt.sh

Gopkg.lock

@@ -36,12 +36,20 @@
   version = "v1.0"
 
 [[projects]]
-  digest = "1:d867dfa6751c8d7a435821ad3b736310c2ed68945d05b50fb9d23aee0540c8cc"
+  digest = "1:31e761d97c76151dde79e9d28964a812c46efc5baee4085b86f68f0c654450de"
+  name = "github.com/konsorten/go-windows-terminal-sequences"
+  packages = ["."]
+  pruneopts = "UT"
+  revision = "f55edac94c9bbba5d6182a4be46d86a2c9b5b50e"
+  version = "v1.0.2"
+
+[[projects]]
+  digest = "1:04457f9f6f3ffc5fea48e71d62f2ca256637dee0a04d710288e27e05c8b41976"
   name = "github.com/sirupsen/logrus"
   packages = ["."]
   pruneopts = "UT"
-  revision = "3e01752db0189b9157070a0e1668a620f9a85da2"
-  version = "v1.0.6"
+  revision = "839c75faf7f98a33d445d181f3018b5c3409a45e"
+  version = "v1.4.2"
 
 [[projects]]
   digest = "1:645cabccbb4fa8aab25a956cbcbdf6a6845ca736b2c64e197ca7cbb9d210b939"
@@ -59,14 +67,6 @@
   revision = "298182f68c66c05229eb03ac171abe6e309ee79a"
   version = "v1.0.3"
 
-[[projects]]
-  branch = "master"
-  digest = "1:bbe51412d9915d64ffaa96b51d409e070665efc5194fcf145c4a27d4133107a4"
-  name = "golang.org/x/crypto"
-  packages = ["ssh/terminal"]
-  pruneopts = "UT"
-  revision = "a29dc8fdc73485234dbef99ebedb95d2eced08de"
-
 [[projects]]
   branch = "master"
   digest = "1:a167b5c532f3245f5a147ade26185f16d6ee8f8d3f6c9846f447e9d8b9705505"
@@ -80,12 +80,9 @@
   revision = "f4e77d36d62c17c2336347bb2670ddbd02d092b7"
 
 [[projects]]
-  digest = "1:ad7a8ea578273222bf5cfe0e98b76ac0fe3fc713d856edcae1f61118c01a20aa"
+  digest = "1:3fe612db5a4468ac2846ae481c22bb3250fa67cf03bccb00c06fa8723a3077a8"
   name = "golang.org/x/sys"
-  packages = [
-    "unix",
-    "windows"
-  ]
+  packages = ["unix"]
   pruneopts = "UT"
   revision = "7dca6fe1f43775aa6d1334576870ff63f978f539"
 

Gopkg.toml

@@ -8,7 +8,7 @@
 
 [[constraint]]
   name = "github.com/sirupsen/logrus"
-  version = "~1.0.4"
+  version = "~1.4.2"
 
 [[constraint]]
   branch = "master"

Makefile

@@ -14,18 +14,18 @@ help:
 	@echo "  test         to run unittests"
 
 clean:
-	rm -f guerrillad vendor
+	rm -f guerrillad
 
 vendor:
 	dep ensure
 
-guerrillad: vendor
+guerrillad:
 	$(GO_VARS) $(GO) build -o="guerrillad" -ldflags="$(LD_FLAGS)" $(ROOT)/cmd/guerrillad
 
-guerrilladrace: vendor
+guerrilladrace:
 	$(GO_VARS) $(GO) build -o="guerrillad" -race -ldflags="$(LD_FLAGS)" $(ROOT)/cmd/guerrillad
 
-test: vendor
+test:
 	$(GO_VARS) $(GO) test -v .
 	$(GO_VARS) $(GO) test -v ./tests
 	$(GO_VARS) $(GO) test -v ./cmd/guerrillad
@@ -33,7 +33,7 @@ test: vendor
 	$(GO_VARS) $(GO) test -v ./backends
 	$(GO_VARS) $(GO) test -v ./mail
 
-testrace: vendor
+testrace:
 	$(GO_VARS) $(GO) test -v . -race
 	$(GO_VARS) $(GO) test -v ./tests -race
 	$(GO_VARS) $(GO) test -v ./cmd/guerrillad -race

api_test.go

@@ -228,6 +228,7 @@ func TestSMTPLoadFile(t *testing.T) {
 	}
 }
 
+// test re-opening the main log
 func TestReopenLog(t *testing.T) {
 	if err := os.Truncate("tests/testlog", 0); err != nil {
 		t.Error(err)
@@ -265,6 +266,72 @@ func TestReopenLog(t *testing.T) {
 	}
 }
 
+const testServerLog = "tests/testlog-server.log"
+
+// test re-opening the individual server log
+func TestReopenServerLog(t *testing.T) {
+	if err := os.Truncate("tests/testlog", 0); err != nil {
+		t.Error(err)
+	}
+
+	defer func() {
+		if _, err := os.Stat(testServerLog); err == nil {
+			if err = os.Remove(testServerLog); err != nil {
+				t.Error(err)
+			}
+		}
+	}()
+
+	cfg := &AppConfig{LogFile: "tests/testlog", LogLevel: log.DebugLevel.String(), AllowedHosts: []string{"grr.la"}}
+	sc := ServerConfig{
+		ListenInterface: "127.0.0.1:2526",
+		IsEnabled:       true,
+		LogFile:         testServerLog,
+	}
+	cfg.Servers = append(cfg.Servers, sc)
+	d := Daemon{Config: cfg}
+
+	err := d.Start()
+	if err != nil {
+		t.Error("start error", err)
+	} else {
+		if err := talkToServer("127.0.0.1:2526"); err != nil {
+			t.Error(err)
+		}
+		if err = d.ReopenLogs(); err != nil {
+			t.Error(err)
+		}
+		time.Sleep(time.Second * 2)
+		if err := talkToServer("127.0.0.1:2526"); err != nil {
+			t.Error(err)
+		}
+		d.Shutdown()
+	}
+
+	b, err := ioutil.ReadFile("tests/testlog")
+	if err != nil {
+		t.Error("could not read logfile")
+		return
+	}
+	if !strings.Contains(string(b), "re-opened log file") {
+		t.Error("Server log did not re-opened, expecting \"re-opened log file\"")
+	}
+	if !strings.Contains(string(b), "re-opened main log file") {
+		t.Error("Main log did not re-opened, expecting \"re-opened main log file\"")
+	}
+
+	b, err = ioutil.ReadFile(testServerLog)
+	if err != nil {
+		t.Error("could not read logfile")
+		return
+	}
+
+	if !strings.Contains(string(b), "Handle client") {
+		t.Error("server log does not contain \"handle client\"")
+	}
+
+}
+
 func TestSetConfig(t *testing.T) {
 
 	if err := os.Truncate("tests/testlog", 0); err != nil {
@@ -453,9 +520,6 @@ func talkToServer(address string) (err error) {
 	if err != nil {
 		return err
 	}
-	if err != nil {
-		return err
-	}
 	_, err = fmt.Fprint(conn, "RCPT TO:<[email protected]>\r\n")
 	if err != nil {
 		return err
@@ -498,6 +562,7 @@ func talkToServer(address string) (err error) {
 
 // Test hot config reload
 // Here we forgot to add FunkyLogger so backend will fail to init
+// it will log to stderr at the beginning, but then change to tests/testlog
 
 func TestReloadConfig(t *testing.T) {
 	if err := os.Truncate("tests/testlog", 0); err != nil {

cmd/guerrillad/serve.go

@@ -46,7 +46,7 @@ func init() {
 	// log to stderr on startup
 	var err error
 	mainlog, err = log.GetLogger(log.OutputStderr.String(), log.InfoLevel.String())
-	if err != nil {
+	if err != nil && mainlog != nil {
 		mainlog.WithError(err).Errorf("Failed creating a logger to %s", log.OutputStderr)
 	}
 	cfgFile := "goguerrilla.conf" // deprecated default name

cmd/guerrillad/serve_test.go

@@ -370,7 +370,7 @@ func grepTestlog(match string, lineNumber int) (found int, err error) {
 				}
 			}
 		}
-		if err != nil && err != io.EOF {
+		if err != io.EOF {
 			return found, err
 		}
 
@@ -549,7 +549,6 @@ func TestCmdConfigChangeEvents(t *testing.T) {
 		if val == false {
 			t.Error("Did not fire config change event:", event)
 			t.FailNow()
-			break
 		}
 	}
 

config.go

@@ -300,7 +300,7 @@ func (c *AppConfig) setDefaults() error {
 				c.Servers[i].MaxSize = defaultMaxSize // 10 Mebibytes
 			}
 			if c.Servers[i].ListenInterface == "" {
-				return fmt.Errorf("Listen interface not specified for server at index %d", i)
+				return fmt.Errorf("listen interface not specified for server at index %d", i)
 			}
 			if c.Servers[i].LogFile == "" {
 				c.Servers[i].LogFile = c.LogFile

config_test.go

@@ -307,7 +307,6 @@ func TestConfigChangeEvents(t *testing.T) {
 		if val == false {
 			t.Error("Did not fire config change event:", event)
 			t.FailNow()
-			break
 		}
 	}
 

server.go

@@ -86,8 +86,8 @@ func (c command) match(in []byte) bool {
 	return bytes.Index(in, []byte(c)) == 0
 }
 
-// Creates and returns a new ready-to-run Server from a configuration
-func newServer(sc *ServerConfig, b backends.Backend, l log.Logger) (*server, error) {
+// Creates and returns a new ready-to-run Server from a ServerConfig configuration
+func newServer(sc *ServerConfig, b backends.Backend, mainlog log.Logger) (*server, error) {
 	server := &server{
 		clientPool:      NewPool(sc.MaxClients),
 		closedListener:  make(chan bool, 1),
@@ -95,20 +95,21 @@ func newServer(sc *ServerConfig, b backends.Backend, l log.Logger) (*server, err
 		state:           ServerStateNew,
 		envelopePool:    mail.NewPool(sc.MaxClients),
 	}
-	server.logStore.Store(l)
-	server.backendStore.Store(b)
-	logFile := sc.LogFile
-	if logFile == "" {
-		// none set, use the same log file as mainlog
-		logFile = server.mainlog().GetLogDest()
-	}
-	// set level to same level as mainlog level
-	mainlog, logOpenError := log.GetLogger(logFile, server.mainlog().GetLevel())
 	server.mainlogStore.Store(mainlog)
-	if logOpenError != nil {
-		server.log().WithError(logOpenError).Errorf("Failed creating a logger for server [%s]", sc.ListenInterface)
+	server.backendStore.Store(b)
+	if sc.LogFile == "" {
+		// none set, use the mainlog for the server log
+		server.logStore.Store(mainlog)
+		server.log().Info("server [" + sc.ListenInterface + "] did not configure a separate log file, so using the main log")
+	} else {
+		// set level to same level as mainlog level
+		if l, logOpenError := log.GetLogger(sc.LogFile, server.mainlog().GetLevel()); logOpenError != nil {
+			server.log().WithError(logOpenError).Errorf("Failed creating a logger for server [%s]", sc.ListenInterface)
+			return server, logOpenError
+		} else {
+			server.logStore.Store(l)
+		}
 	}
-
 	server.setConfig(sc)
 	server.setTimeout(sc.Timeout)
 	if err := server.configureSSL(); err != nil {
@@ -615,23 +616,29 @@ func (s *server) handleClient(client *client) {
 }
 
 func (s *server) log() log.Logger {
-	if l, ok := s.logStore.Load().(log.Logger); ok {
-		return l
-	}
-	l, err := log.GetLogger(log.OutputStderr.String(), log.InfoLevel.String())
-	if err == nil {
-		s.logStore.Store(l)
-	}
-	return l
+	return s.loadLog(&s.logStore)
 }
 
 func (s *server) mainlog() log.Logger {
-	if l, ok := s.mainlogStore.Load().(log.Logger); ok {
+	return s.loadLog(&s.mainlogStore)
+}
+
+func (s *server) loadLog(value *atomic.Value) log.Logger {
+	if l, ok := value.Load().(log.Logger); ok {
 		return l
 	}
-	l, err := log.GetLogger(log.OutputStderr.String(), log.InfoLevel.String())
+	out := log.OutputStderr.String()
+	level := log.InfoLevel.String()
+	if value == &s.logStore {
+		if sc, ok := s.configStore.Load().(ServerConfig); ok && sc.LogFile != "" {
+			out = sc.LogFile
+		}
+		level = s.mainlog().GetLevel()
+	}
+
+	l, err := log.GetLogger(out, level)
 	if err == nil {
-		s.mainlogStore.Store(l)
+		value.Store(l)
 	}
 	return l
 }

tests/guerrilla_test.go

@@ -64,7 +64,7 @@ func init() {
 	} else {
 		logger, _ = log.GetLogger(config.LogFile, "debug")
 		initErr = setupCerts(config)
-		if err != nil {
+		if initErr != nil {
 			return
 		}
 		backend, _ := getBackend(config.BackendConfig, logger)
@@ -196,7 +196,6 @@ func TestStart(t *testing.T) {
 	app.Shutdown()
 	if read, err := ioutil.ReadFile("./testlog"); err == nil {
 		logOutput := string(read)
-		//fmt.Println(logOutput)
 		if i := strings.Index(logOutput, "Listening on TCP 127.0.0.1:4654"); i < 0 {
 			t.Error("Server did not listen on 127.0.0.1:4654")
 		}