debugging in progress 7

new Fields logging helper, structured logging

api_test.go

@@ -429,7 +429,7 @@ func TestSetConfigError(t *testing.T) {
 
 	err := d.SetConfig(cfg)
 	if err == nil {
-		t.Error("SetConfig should have returned an error compalning about bad tls settings")
+		t.Error("SetConfig should have returned an error complaining about bad tls settings")
 		return
 	}
 }
@@ -815,6 +815,7 @@ func TestCustomBackendResult(t *testing.T) {
 
 	if err := d.Start(); err != nil {
 		t.Error(err)
+		return
 	}
 	// lets have a talk with the server
 	if err := talkToServer("127.0.0.1:2525", ""); err != nil {
@@ -839,6 +840,99 @@ func TestCustomBackendResult(t *testing.T) {
 
 }
 
+// Test a backends removed, 2 new backends added added
+func TestBackendAddRemove(t *testing.T) {
+
+	if err := os.Truncate("tests/testlog", 0); err != nil {
+		t.Error(err)
+	}
+
+	servers := []ServerConfig{
+		0: {
+			IsEnabled:       true,
+			Hostname:        "mail.guerrillamail.com",
+			MaxSize:         100017,
+			Timeout:         160,
+			ListenInterface: "127.0.0.1:2526",
+			MaxClients:      2,
+			TLS: ServerTLSConfig{
+				PrivateKeyFile: "",
+				PublicKeyFile:  "",
+				StartTLSOn:     false,
+				AlwaysOn:       false,
+			},
+		},
+	}
+
+	cfg := &AppConfig{
+		LogFile:      "tests/testlog",
+		PidFile:      "tests/go-guerrilla.pid",
+		AllowedHosts: []string{"grr.la", "spam4.me"},
+		BackendConfig: backends.BackendConfig{
+			"gateways": {
+				"default": {
+					"save_process":     "HeadersParser|Debugger|Custom",
+					"validate_process": "Custom",
+				},
+				"temp": {
+					"save_process":     "HeadersParser|Debugger|Custom",
+					"validate_process": "Custom",
+				},
+			},
+		},
+		Servers: servers,
+	}
+
+	d := Daemon{Config: cfg}
+	d.AddProcessor("Custom", customBackend2)
+
+	if err := d.Start(); err != nil {
+		t.Error(err)
+		return
+	}
+
+	cfg2 := *cfg
+	cfg2.BackendConfig = backends.BackendConfig{
+		"gateways": {
+			"client1": {
+				"save_process":     "HeadersParser|Debugger|Custom",
+				"validate_process": "Custom",
+			},
+			"client2": {
+				"save_process":     "HeadersParser|Debugger",
+				"validate_process": "Custom",
+			},
+		},
+	}
+
+	eventFiredAdded := false
+	_ = d.Subscribe(EventConfigBackendConfigAdded, backendEvent(func(appConfig *AppConfig, name string) {
+		eventFiredAdded = true
+	}))
+
+	eventFiredRemoved := false
+	_ = d.Subscribe(EventConfigBackendConfigRemoved, backendEvent(func(appConfig *AppConfig, name string) {
+		eventFiredRemoved = true
+	}))
+
+	// default changed, temp removed, client1 and client2 added
+
+	if err := d.ReloadConfig(cfg2); err != nil {
+		t.Error(err)
+		return
+	}
+
+	d.Shutdown()
+
+	if eventFiredAdded == false {
+		t.Error("EventConfigBackendConfigAdded did not fired")
+	}
+	if eventFiredRemoved == false {
+		t.Error("EventConfigBackendConfigRemoved did not get fired")
+	}
+
+}
+
 func TestStreamProcessor(t *testing.T) {
 	if err := os.Truncate("tests/testlog", 0); err != nil {
 		t.Error(err)

backends/gateway.go

@@ -596,7 +596,8 @@ func (gw *BackendGateway) workDispatcher(
 
 	}()
 	state = dispatcherStateIdle
-	Log().Infof("processing worker started (#%d)", workerId)
+	Log().Fields("id", workerId, "gateway", gw.name).
+		Infof("processing worker started")
 	for {
 		select {
 		case <-stop:

cmd/guerrillad/serve_test.go

@@ -630,7 +630,7 @@ func TestServe(t *testing.T) {
 	go func() {
 		serve(cmd, []string{})
 	}()
-	if _, err := grepTestlog("istening on TCP 127.0.0.1:3536", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:3536\"", 0); err != nil {
 		t.Error("server not started")
 	}
 
@@ -711,7 +711,7 @@ func TestServerAddEvent(t *testing.T) {
 	}()
 
 	// allow the server to start
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:3536", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:3536\"", 0); err != nil {
 		t.Error("server didn't start")
 	}
 
@@ -731,13 +731,14 @@ func TestServerAddEvent(t *testing.T) {
 		}
 	}
 	// send a sighup signal to the server
-	sigHup("pidfile.pid")
-	if _, err := grepTestlog("[127.0.0.1:2526] Waiting for a new client", 0); err != nil {
+	sigHup("./pidfile.pid")
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:2526\"", 0); err != nil {
 		t.Error("new server didn't start")
 	}
 
 	if conn, buffin, err := test.Connect(newServer, 20); err != nil {
 		t.Error("Could not connect to new server", newServer.ListenInterface, err)
+		return
 	} else {
 		if result, err := test.Command(conn, buffin, "HELO example.com"); err == nil {
 			expect := "250 mail.test.com Hello"
@@ -791,7 +792,7 @@ func TestServerStartEvent(t *testing.T) {
 	go func() {
 		serve(cmd, []string{})
 	}()
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:3536", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:3536\"", 0); err != nil {
 		t.Error("server didn't start")
 	}
 	// now change the config by adding a server
@@ -813,7 +814,7 @@ func TestServerStartEvent(t *testing.T) {
 	sigHup("pidfile.pid")
 
 	// see if the new server started?
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:2228", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:2228\"", 0); err != nil {
 		t.Error("second server didn't start")
 	}
 
@@ -872,7 +873,7 @@ func TestServerStopEvent(t *testing.T) {
 		serve(cmd, []string{})
 	}()
 	// allow the server to start
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:3536", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:3536\"", 0); err != nil {
 		t.Error("server didn't start")
 	}
 	// now change the config by enabling a server
@@ -893,7 +894,7 @@ func TestServerStopEvent(t *testing.T) {
 	// send a sighup signal to the server
 	sigHup("pidfile.pid")
 	// detect config change
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:2228", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:2228\"", 0); err != nil {
 		t.Error("new server didn't start")
 	}
 
@@ -1005,7 +1006,7 @@ func TestAllowedHostsEvent(t *testing.T) {
 		serve(cmd, []string{})
 	}()
 	// wait for start
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:2552", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:2552\"", 0); err != nil {
 		t.Error("server didn't start")
 	}
 
@@ -1114,7 +1115,7 @@ func TestTLSConfigEvent(t *testing.T) {
 	}()
 
 	// wait for server to start
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:2552", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:2552\"", 0); err != nil {
 		t.Error("server didn't start")
 	}
 
@@ -1302,7 +1303,7 @@ func TestBadTLSReload(t *testing.T) {
 		serve(cmd, []string{})
 	}()
 	// wait for server to start
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:4655", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:4655\"", 0); err != nil {
 		t.Error("server didn't start")
 	}
 
@@ -1398,7 +1399,7 @@ func TestSetTimeoutEvent(t *testing.T) {
 		serve(cmd, []string{})
 	}()
 	// wait for start
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:4655", 0); err != nil {
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:4655\"", 0); err != nil {
 		t.Error("server didn't start")
 	}
 
@@ -1490,7 +1491,8 @@ func TestDebugLevelChange(t *testing.T) {
 	go func() {
 		serve(cmd, []string{})
 	}()
-	if _, err := grepTestlog("Listening on TCP 127.0.0.1:2552", 0); err != nil {
+
+	if _, err := grepTestlog("msg=\"listening on TCP\" iface=\"127.0.0.1:2552\"", 0); err != nil {
 		t.Error("server didn't start")
 	}
 
@@ -1595,7 +1597,7 @@ func TestBadBackendReload(t *testing.T) {
 
 		// did the pidfile change as expected?
 
-		if _, err := grepTestlog("pid_file (./pidfile2.pid) written", 0); err != nil {
+		if _, err := grepTestlog("msg=\"pid_file written\" file=./pidfile2.pid", 0); err != nil {
 			t.Error("pid_file (./pidfile2.pid) not written")
 		}
 		if _, err := os.Stat("./pidfile2.pid"); os.IsNotExist(err) {

config.go

@@ -253,7 +253,7 @@ func (c *AppConfig) emitBackendChangeEvents(oldConfig *AppConfig, app Guerrilla)
 		app.Publish(EventConfigBackendConfigAdded, c, b)
 	}
 	for b := range removed {
-		app.Publish(EventConfigBackendConfigAdded, c, b)
+		app.Publish(EventConfigBackendConfigRemoved, c, b)
 	}
 }
 

guerrilla.go

@@ -3,7 +3,6 @@ package guerrilla
 import (
 	"errors"
 	"fmt"
-	"github.com/sirupsen/logrus"
 	"os"
 	"strings"
 	"sync"
@@ -443,7 +442,7 @@ func (g *guerrilla) subscribeEvents() {
 	events[EventConfigServerGatewayConfig] = serverEvent(func(sc *ServerConfig) {
 		b := g.backend(sc.Gateway)
 		if b == nil {
-			g.mainlog().WithField("gateway", sc.Gateway).Error("could not change to gateway, not configured")
+			g.mainlog().Fields("gateway", sc.Gateway).Error("could not change to gateway, not configured")
 			return
 		}
 		g.storeBackend(b)
@@ -451,21 +450,18 @@ func (g *guerrilla) subscribeEvents() {
 
 	revertIfError := func(err error, name string, logger log.Logger, g *guerrilla) {
 		if err != nil {
-			fields := logrus.Fields{"error": err, "gateway": name}
-			logger.WithFields(fields).Error("cannot change gateway config, reverting to old config")
+			logger.Fields("error", err, "gateway", name).Error("cannot change gateway config, reverting to old config")
 			err = g.backend(name).Reinitialize()
 			if err != nil {
-				fields = logrus.Fields{"error": err, "gateway": name}
-				logger.WithFields(fields).Error("failed to revert to old gateway config")
+				logger.Fields("error", err, "gateway", name).Error("failed to revert to old gateway config")
 				return
 			}
 			err = g.backend(name).Start()
 			if err != nil {
-				fields = logrus.Fields{"error": err, "gateway": name}
-				logger.WithFields(fields).Error("failed to start gateway with old config")
+				logger.Fields("error", err, "gateway", name).Error("failed to start gateway with old config")
 				return
 			}
-			logger.WithField("gateway", name).Info("reverted to old gateway config")
+			logger.Fields("gateway", name).Info("reverted to old gateway config")
 		}
 	}
 
@@ -474,8 +470,7 @@ func (g *guerrilla) subscribeEvents() {
 		var err error
 		// shutdown the backend first.
 		if err = g.backend(name).Shutdown(); err != nil {
-			fields := logrus.Fields{"error": err, "gateway": name}
-			logger.WithFields(fields).Error("gateway failed to shutdown")
+			logger.Fields("error", err, "gateway", name).Error("gateway failed to shutdown")
 			return // we can't do anything then
 		}
 		if newBackend, newErr := backends.New(name, appConfig.BackendConfig, logger); newErr != nil {
@@ -484,12 +479,11 @@ func (g *guerrilla) subscribeEvents() {
 			return
 		} else {
 			if err = newBackend.Start(); err != nil {
-				fields := logrus.Fields{"error": err, "gateway": name}
-				logger.WithFields(fields).Error("gateway could not start")
+				logger.Fields("error", err, "gateway", name).Error("gateway could not start")
 				revertIfError(err, name, logger, g) // revert to old backend
 				return
 			} else {
-				logger.WithField("gateway", name).Info("gateway with new config started")
+				logger.Fields("gateway", name).Info("gateway with new config started")
 				g.storeBackend(newBackend)
 			}
 		}
@@ -499,20 +493,16 @@ func (g *guerrilla) subscribeEvents() {
 	events[EventConfigBackendConfigAdded] = backendEvent(func(appConfig *AppConfig, name string) {
 		logger, _ := log.GetLogger(appConfig.LogFile, appConfig.LogLevel)
 		// shutdown any old backend first.
-
 		if newBackend, newErr := backends.New(name, appConfig.BackendConfig, logger); newErr != nil {
-			fields := logrus.Fields{"error": newErr, "gateway": name}
-			logger.WithFields(fields).Error("cannot add new gateway")
+			logger.Fields("error", newErr, "gateway", name).Error("cannot add new gateway")
 		} else {
 			// swap to the bew gateway (assuming old gateway was shutdown so it can be safely swapped)
 			if err := newBackend.Start(); err != nil {
-				fields := logrus.Fields{"error": err, "gateway": name}
-				logger.WithFields(fields).Error("cannot start new gateway")
+				logger.Fields("error", err, "gateway", name).Error("cannot start new gateway")
 			}
-			logger.WithField("gateway", name).Info("new gateway started")
+			logger.Fields("gateway", name).Info("new gateway started")
 			g.storeBackend(newBackend)
 		}
-
 	})
 
 	// remove a gateway (shut it down)
@@ -523,11 +513,11 @@ func (g *guerrilla) subscribeEvents() {
 		// revert
 		defer revertIfError(err, name, logger, g)
 		if err = g.backend(name).Shutdown(); err != nil {
-			logger.WithFields(logrus.Fields{"error": err, "gateway": name}).Warn("gateway failed to shutdown")
+			logger.Fields("error", err, "gateway", name).Warn("gateway failed to shutdown")
 			return
 		}
 		g.removeBackend(g.backend(name))
-		logger.WithField("gateway", name).Info("gateway removed")
+		logger.Fields("gateway", name).Info("gateway removed")
 	})
 
 	var err error
@@ -610,7 +600,7 @@ func (g *guerrilla) Start() error {
 		}
 		startWG.Add(1)
 		go func(s *server) {
-			g.mainlog().Infof("Starting: %s", s.listenInterface)
+			g.mainlog().Fields("iface", s.listenInterface).Info("starting server")
 			if err := s.Start(&startWG); err != nil {
 				errs <- err
 			}
@@ -638,7 +628,7 @@ func (g *guerrilla) Shutdown() {
 	g.mapServers(func(s *server) {
 		if s.state == ServerStateRunning {
 			s.Shutdown()
-			g.mainlog().Infof("shutdown completed for [%s]", s.listenInterface)
+			g.mainlog().Fields("iface", s.listenInterface).Info("shutdown completed")
 		}
 	})
 
@@ -675,7 +665,7 @@ func (g *guerrilla) writePid() (err error) {
 			}
 		}
 		if err != nil {
-			g.mainlog().WithError(err).Errorf("error while writing pidFile (%s)", g.Config.PidFile)
+			g.mainlog().Fields("error", err, "file", g.Config.PidFile).Errorf("error while writing pidFile")
 		}
 	}()
 	if len(g.Config.PidFile) > 0 {
@@ -689,7 +679,7 @@ func (g *guerrilla) writePid() (err error) {
 		if err = f.Sync(); err != nil {
 			return err
 		}
-		g.mainlog().Infof("pid_file (%s) written with pid:%v", g.Config.PidFile, pid)
+		g.mainlog().Fields("file", g.Config.PidFile, "pid", pid).Info("pid_file written")
 	}
 	return nil
 }

log/log.go

@@ -1,6 +1,7 @@
 package log
 
 import (
+	"fmt"
 	loglib "github.com/sirupsen/logrus"
 	"io"
 	"io/ioutil"
@@ -60,6 +61,7 @@ type Logger interface {
 	GetLevel() string
 	IsDebug() bool
 	AddHook(h loglib.Hook)
+	Fields(fields ...interface{}) *loglib.Entry
 }
 
 // Implements the Logger interface
@@ -218,3 +220,26 @@ func (l *HookedLogger) WithConn(conn net.Conn) *loglib.Entry {
 	}
 	return l.WithField("addr", addr)
 }
+
+// Fields accepts an even number of arguments in the format of ([<string> <interface{}>)1*
+func (l *HookedLogger) Fields(spec ...interface{}) *loglib.Entry {
+	size := len(spec)
+	if size < 2 || size%2 != 0 {
+		return l.WithField("oops", "wrong fields specified")
+	}
+	fields := make(map[string]interface{}, size/2)
+	for i := range spec {
+		if i%2 != 0 {
+			continue
+		}
+		if key, ok := spec[i].(string); ok {
+			fields[key] = spec[i+1]
+		} else if key, ok := spec[i].(fmt.Stringer); ok {
+			fields[key.String()] = spec[i+1]
+		} else {
+			fields[fmt.Sprintf("%d", i)] = spec[i+1]
+		}
+
+	}
+	return l.WithFields(fields)
+}

server.go

@@ -242,7 +242,7 @@ func (s *server) Start(startWG *sync.WaitGroup) error {
 		return fmt.Errorf("[%s] Cannot listen on port: %s ", s.listenInterface, err.Error())
 	}
 
-	s.log().Infof("Listening on TCP %s", s.listenInterface)
+	s.log().Fields("iface", s.listenInterface).Info("listening on TCP")
 	s.state = ServerStateRunning
 	startWG.Done() // start successful, don't wait for me
 

tests/guerrilla_test.go

@@ -201,10 +201,10 @@ func TestStart(t *testing.T) {
 	app.Shutdown()
 	if read, err := ioutil.ReadFile("./testlog"); err == nil {
 		logOutput := string(read)
-		if i := strings.Index(logOutput, "Listening on TCP 127.0.0.1:4654"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"listening on TCP\" iface=\"127.0.0.1:4654\""); i < 0 {
 			t.Error("Server did not listen on 127.0.0.1:4654")
 		}
-		if i := strings.Index(logOutput, "Listening on TCP 127.0.0.1:2526"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"listening on TCP\" iface=\"127.0.0.1:2526\""); i < 0 {
 			t.Error("Server did not listen on 127.0.0.1:2526")
 		}
 		if i := strings.Index(logOutput, "[127.0.0.1:4654] Waiting for a new client"); i < 0 {
@@ -219,10 +219,10 @@ func TestStart(t *testing.T) {
 		if i := strings.Index(logOutput, "Server [127.0.0.1:2526] has stopped accepting new clients"); i < 0 {
 			t.Error("Server did not stop on 127.0.0.1:2526")
 		}
-		if i := strings.Index(logOutput, "shutdown completed for [127.0.0.1:4654]"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"shutdown completed\" iface=\"127.0.0.1:4654\""); i < 0 {
 			t.Error("Server did not complete shutdown on 127.0.0.1:4654")
 		}
-		if i := strings.Index(logOutput, "shutdown completed for [127.0.0.1:2526]"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"shutdown completed\" iface=\"127.0.0.1:2526\""); i < 0 {
 			t.Error("Server did not complete shutdown on 127.0.0.1:2526")
 		}
 		if i := strings.Index(logOutput, "shutting down pool [127.0.0.1:4654]"); i < 0 {