change queueID() to use hash/fnv instead of md5 (also fixed test)

add ServerIface property to Envelope
add more structured logging

api.go

@@ -65,7 +65,7 @@ func (d *Daemon) Start() (err error) {
 	err = d.g.Start()
 	if err == nil {
 		if err := d.resetLogger(); err == nil {
-			d.Log().Infof("main log configured to %s", d.Config.LogFile)
+			d.Log().Fields("file", d.Config.LogFile).Info("main log configured")
 		}
 	}
 	return err
@@ -122,7 +122,7 @@ func (d *Daemon) ReloadConfig(c AppConfig) error {
 		d.Log().WithError(err).Error("Error while reloading config")
 		return err
 	}
-	d.Log().Infof("Configuration was reloaded at %s", d.configLoadTime)
+	d.Log().Info("configuration was reloaded")
 	d.Config.EmitChangeEvents(&oldConfig, d.g)
 
 	return nil
@@ -137,7 +137,7 @@ func (d *Daemon) ReloadConfigFile(path string) error {
 	} else if d.Config != nil {
 		oldConfig := *d.Config
 		d.Config = &ac
-		d.Log().Infof("Configuration was reloaded at %s", d.configLoadTime)
+		d.Log().Info("configuration was reloaded")
 		d.Config.EmitChangeEvents(&oldConfig, d.g)
 	}
 	return nil

api_test.go

@@ -354,7 +354,7 @@ func TestReopenServerLog(t *testing.T) {
 		return
 	}
 
-	if !strings.Contains(string(b), "Handle client") {
+	if !strings.Contains(string(b), "handle client") {
 		t.Error("server log does not contain \"handle client\"")
 	}
 

client.go

@@ -56,12 +56,12 @@ type client struct {
 }
 
 // NewClient allocates a new client.
-func NewClient(conn net.Conn, clientID uint64, logger log.Logger, envelope *mail.Pool) *client {
+func NewClient(conn net.Conn, clientID uint64, logger log.Logger, envelope *mail.Pool, iface string) *client {
 	c := &client{
 		conn: conn,
 		// Envelope will be borrowed from the envelope pool
 		// the envelope could be 'detached' from the client later when processing
-		Envelope:    envelope.Borrow(getRemoteAddr(conn), clientID),
+		Envelope:    envelope.Borrow(getRemoteAddr(conn), clientID, iface),
 		ConnectedAt: time.Now(),
 		bufin:       newSMTPBufferedReader(conn),
 		bufout:      bufio.NewWriter(conn),
@@ -172,7 +172,7 @@ func (c *client) init(conn net.Conn, clientID uint64, ep *mail.Pool) {
 	c.ID = clientID
 	c.errors = 0
 	// borrow an envelope from the envelope pool
-	c.Envelope = ep.Borrow(getRemoteAddr(conn), clientID)
+	c.Envelope = ep.Borrow(getRemoteAddr(conn), clientID, c.ServerIface)
 }
 
 // getID returns the client's unique ID

cmd/guerrillad/serve_test.go

@@ -399,7 +399,6 @@ func grepTestlog(match string, lineNumber int) (found int, err error) {
 	var ln int
 	var line string
 	for tries := 0; tries < 6; tries++ {
-		//fmt.Println("try..", tries)
 		for {
 			ln++
 			line, err = buff.ReadString('\n')
@@ -407,7 +406,6 @@ func grepTestlog(match string, lineNumber int) (found int, err error) {
 				break
 			}
 			if ln > lineNumber {
-				//fmt.Print(ln, line)
 				if i := strings.Index(line, match); i != -1 {
 					return ln, nil
 				}
@@ -663,7 +661,7 @@ func TestServe(t *testing.T) {
 	if runtime.GOOS != "windows" {
 		sigHup("pidfile.pid")
 		// did the pidfile change as expected?
-		if _, err := grepTestlog("Configuration was reloaded", 0); err != nil {
+		if _, err := grepTestlog("configuration was reloaded", 0); err != nil {
 			t.Error("server did not catch sighup")
 		}
 	}
@@ -927,7 +925,7 @@ func TestServerStopEvent(t *testing.T) {
 	// send a sighup signal to the server
 	sigHup("pidfile.pid")
 	// detect config change
-	if _, err := grepTestlog("Server [127.0.0.1:2228] has stopped accepting new clients", 27); err != nil {
+	if _, err := grepTestlog("msg=\"server has stopped accepting new clients\" iface=\"127.0.0.1:2228\"", 27); err != nil {
 		t.Error("127.0.0.1:2228 did not stop")
 	}
 
@@ -1521,7 +1519,7 @@ func TestDebugLevelChange(t *testing.T) {
 	// send a sighup signal to the server to reload config
 	sigHup("pidfile.pid")
 	// did the config reload?
-	if _, err := grepTestlog("Configuration was reloaded", 0); err != nil {
+	if _, err := grepTestlog("configuration was reloaded", 0); err != nil {
 		t.Error("config did not reload")
 		t.FailNow()
 	}
@@ -1586,7 +1584,7 @@ func TestBadBackendReload(t *testing.T) {
 
 		d.Shutdown()
 
-		if _, err := grepTestlog("Configuration was reloaded", 0); err != nil {
+		if _, err := grepTestlog("configuration was reloaded", 0); err != nil {
 			t.Error("config didn't update")
 		}
 

mail/envelope.go

@@ -2,9 +2,9 @@ package mail
 
 import (
 	"bytes"
-	"crypto/md5"
 	"errors"
 	"fmt"
+	"hash/fnv"
 	"io"
 	"mime"
 	"net"
@@ -154,20 +154,24 @@ type Envelope struct {
 	MessageID uint64
 	// ESMTP: true if EHLO was used
 	ESMTP bool
+	// ServerIface records the server's interface in the config
+	ServerIface string
 	// When locked, it means that the envelope is being processed by the backend
 	sync.Mutex
 }
 
-func NewEnvelope(remoteAddr string, clientID uint64) *Envelope {
+func NewEnvelope(remoteAddr string, clientID uint64, iface string) *Envelope {
 	return &Envelope{
-		RemoteIP: remoteAddr,
-		Values:   make(map[string]interface{}),
-		QueuedId: queuedID(clientID),
+		RemoteIP:    remoteAddr,
+		Values:      make(map[string]interface{}),
+		ServerIface: iface,
+		QueuedId:    queuedID(clientID, iface),
 	}
 }
 
-func queuedID(clientID uint64) string {
-	return fmt.Sprintf("%x", md5.Sum([]byte(string(time.Now().Unix())+string(clientID))))
+func queuedID(clientID uint64, iface string) string {
+	h := fnv.New128a()
+	return fmt.Sprintf("%x", h.Sum([]byte(fmt.Sprintf("%v%v%v", time.Now(), clientID, iface))))
 }
 
 // ParseHeaders parses the headers into Header field of the Envelope struct.
@@ -232,9 +236,10 @@ func (e *Envelope) ResetTransaction() {
 }
 
 // Reseed is called when used with a new connection, once it's accepted
-func (e *Envelope) Reseed(remoteIP string, clientID uint64) {
+func (e *Envelope) Reseed(remoteIP string, clientID uint64, iface string) {
 	e.RemoteIP = remoteIP
-	e.QueuedId = queuedID(clientID)
+	e.ServerIface = iface
+	e.QueuedId = queuedID(clientID, iface)
 	e.Helo = ""
 	e.TLS = false
 	e.ESMTP = false
@@ -428,14 +433,14 @@ func NewPool(poolSize int) *Pool {
 	}
 }
 
-func (p *Pool) Borrow(remoteAddr string, clientID uint64) *Envelope {
+func (p *Pool) Borrow(remoteAddr string, clientID uint64, iface string) *Envelope {
 	var e *Envelope
 	p.sem <- true // block the envelope until more room
 	select {
 	case e = <-p.pool:
-		e.Reseed(remoteAddr, clientID)
+		e.Reseed(remoteAddr, clientID, iface)
 	default:
-		e = NewEnvelope(remoteAddr, clientID)
+		e = NewEnvelope(remoteAddr, clientID, iface)
 	}
 	return e
 }

pool.go

@@ -127,7 +127,7 @@ func (p *Pool) GetActiveClientsCount() int {
 }
 
 // Borrow a Client from the pool. Will block if len(activeClients) > maxClients
-func (p *Pool) Borrow(conn net.Conn, clientID uint64, logger log.Logger, ep *mail.Pool) (Poolable, error) {
+func (p *Pool) Borrow(conn net.Conn, clientID uint64, logger log.Logger, ep *mail.Pool, iface string) (Poolable, error) {
 	p.poolGuard.Lock()
 	defer p.poolGuard.Unlock()
 
@@ -142,7 +142,7 @@ func (p *Pool) Borrow(conn net.Conn, clientID uint64, logger log.Logger, ep *mai
 		case c = <-p.pool:
 			c.init(conn, clientID, ep)
 		default:
-			c = NewClient(conn, clientID, logger, ep)
+			c = NewClient(conn, clientID, logger, ep, iface)
 		}
 		p.activeClientsAdd(c)
 

server.go

@@ -6,7 +6,6 @@ import (
 	"crypto/tls"
 	"crypto/x509"
 	"fmt"
-	"github.com/sirupsen/logrus"
 	"io"
 	"io/ioutil"
 	"net"
@@ -84,7 +83,7 @@ var (
 )
 
 func (c command) match(in []byte) bool {
-	return bytes.Index(in, []byte(c)) == 0
+	return bytes.Index(in, c) == 0
 }
 
 // Creates and returns a new ready-to-run Server from a ServerConfig configuration
@@ -101,11 +100,11 @@ func newServer(sc *ServerConfig, b backends.Backend, mainlog log.Logger) (*serve
 	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")
+		server.log().Fields("iface", sc.ListenInterface).Info("server 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)
+			server.log().Fields("error", logOpenError, "iface", sc.ListenInterface).Error("Failed creating a logger for server")
 			return server, logOpenError
 		} else {
 			server.logStore.Store(l)
@@ -158,7 +157,8 @@ func (s *server) configureTLS() error {
 		if len(sConfig.TLS.RootCAs) > 0 {
 			caCert, err := ioutil.ReadFile(sConfig.TLS.RootCAs)
 			if err != nil {
-				s.log().WithError(err).Errorf("failed opening TLSRootCAs file [%s]", sConfig.TLS.RootCAs)
+				s.log().Fields("error", err, "file", sConfig.TLS.RootCAs).Error("failed opening TLSRootCAs file")
+				return err
 			} else {
 				caCertPool := x509.NewCertPool()
 				caCertPool.AppendCertsFromPEM(caCert)
@@ -239,7 +239,7 @@ func (s *server) Start(startWG *sync.WaitGroup) error {
 	if err != nil {
 		startWG.Done() // don't wait for me
 		s.state = ServerStateStartError
-		return fmt.Errorf("[%s] Cannot listen on port: %s ", s.listenInterface, err.Error())
+		return fmt.Errorf("[%s] cannot listen on port: %s ", s.listenInterface, err.Error())
 	}
 
 	s.log().Fields("iface", s.listenInterface).Info("listening on TCP")
@@ -247,21 +247,21 @@ func (s *server) Start(startWG *sync.WaitGroup) error {
 	startWG.Done() // start successful, don't wait for me
 
 	for {
-		s.log().Debugf("[%s] Waiting for a new client. Next Client ID: %d", s.listenInterface, clientID+1)
+		s.log().Fields("iface", s.listenInterface, "nextSeq", clientID+1).Debug("waiting for a new client")
 		conn, err := listener.Accept()
 		clientID++
 		if err != nil {
 			if e, ok := err.(net.Error); ok && !e.Temporary() {
-				s.log().Infof("Server [%s] has stopped accepting new clients", s.listenInterface)
+				s.log().Fields("iface", s.listenInterface).Info("server has stopped accepting new clients")
 				// the listener has been closed, wait for clients to exit
-				s.log().Infof("shutting down pool [%s]", s.listenInterface)
+				s.log().Fields("iface", s.listenInterface).Info("shutting down pool")
 				s.clientPool.ShutdownState()
 				s.clientPool.ShutdownWait()
 				s.state = ServerStateStopped
 				s.closedListener <- true
 				return nil
 			}
-			s.mainlog().WithError(err).Info("Temporary error accepting client")
+			s.mainlog().Fields("error", err, "iface", s.listenInterface).Info("temporary error accepting client")
 			continue
 		}
 		go func(p Poolable, borrowErr error) {
@@ -278,7 +278,7 @@ func (s *server) Start(startWG *sync.WaitGroup) error {
 			}
 			// intentionally placed Borrow in args so that it's called in the
 			// same main goroutine.
-		}(s.clientPool.Borrow(conn, clientID, s.log(), s.envelopePool))
+		}(s.clientPool.Borrow(conn, clientID, s.log(), s.envelopePool, s.listenInterface))
 
 	}
 }
@@ -373,7 +373,7 @@ const advertiseHelp = "250 HELP"
 func (s *server) handleClient(client *client) {
 	defer client.closeConn()
 	sc := s.configStore.Load().(ServerConfig)
-	s.log().Infof("Handle client [%s], id: %d", client.RemoteIP, client.ID)
+	s.log().Fields("peer", client.RemoteIP, "seq", client.ID).Info("handle client")
 
 	// Initial greeting
 	greeting := fmt.Sprintf("220 %s SMTP Guerrilla(%s) #%d (%d) %s",
@@ -397,7 +397,7 @@ func (s *server) handleClient(client *client) {
 		} else if err := client.upgradeToTLS(tlsConfig); err == nil {
 			advertiseTLS = ""
 		} else {
-			s.log().WithError(err).Warnf("[%s] Failed TLS handshake", client.RemoteIP)
+			s.log().Fields("error", err, "peer", client.RemoteIP).Warn("failed TLS handshake")
 			// server requires TLS, but can't handshake
 			client.kill()
 		}
@@ -415,19 +415,19 @@ func (s *server) handleClient(client *client) {
 		case ClientCmd:
 			client.bufin.setLimit(CommandLineMaxLength)
 			input, err := s.readCommand(client)
-			s.log().Debugf("Client sent: %s", input)
+			s.log().Fields("input", string(input)).Debugf("client said")
 			if err == io.EOF {
-				s.log().WithError(err).Warnf("Client closed the connection: %s", client.RemoteIP)
+				s.log().Fields("error", err, "peer", client.RemoteIP).Warn("client closed the connection")
 				return
 			} else if netErr, ok := err.(net.Error); ok && netErr.Timeout() {
-				s.log().WithError(err).Warnf("Timeout: %s", client.RemoteIP)
+				s.log().Fields("error", err, "peer", client.RemoteIP).Warn("timeout")
 				return
 			} else if err == LineLimitExceeded {
 				client.sendResponse(r.FailLineTooLong)
 				client.kill()
 				break
 			} else if err != nil {
-				s.log().WithError(err).Warnf("Read error: %s", client.RemoteIP)
+				s.log().Fields("error", err, "peer", client.RemoteIP).Warn("read error")
 				client.kill()
 				break
 			}
@@ -446,7 +446,7 @@ func (s *server) handleClient(client *client) {
 				if h, err := client.parser.Helo(input[4:]); err == nil {
 					client.Helo = h
 				} else {
-					s.log().WithFields(logrus.Fields{"helo": h, "client": client.ID}).Warn("invalid helo")
+					s.log().Fields("helo", h, "seq", client.ID).Warn("invalid helo")
 					client.sendResponse(r.FailSyntaxError)
 					break
 				}
@@ -458,7 +458,7 @@ func (s *server) handleClient(client *client) {
 					client.Helo = h
 				} else {
 					client.sendResponse(r.FailSyntaxError)
-					s.log().WithFields(logrus.Fields{"ehlo": h, "client": client.ID}).Warn("invalid ehlo")
+					s.log().Fields("ehlo", h, "seq", client.ID).Warn("invalid ehlo")
 					client.sendResponse(r.FailSyntaxError)
 					break
 				}
@@ -501,7 +501,7 @@ func (s *server) handleClient(client *client) {
 				}
 				client.MailFrom, err = client.parsePath(input[10:], client.parser.MailFrom)
 				if err != nil {
-					s.log().WithError(err).Error("MAIL parse error", "["+string(input[10:])+"]")
+					s.log().Fields("error", err, "raw", string(input[10:])).Error("MAIL parse error")
 					client.sendResponse(err)
 					break
 				} else if client.parser.NullPath {
@@ -527,7 +527,7 @@ func (s *server) handleClient(client *client) {
 				}
 				to, err := client.parsePath(input[8:], client.parser.RcptTo)
 				if err != nil {
-					s.log().WithError(err).Error("RCPT parse error", "["+string(input[8:])+"]")
+					s.log().Fields("error", err, "raw", string(input[8:])).Error("RCPT parse error")
 					client.sendResponse(err.Error())
 					break
 				}
@@ -645,12 +645,13 @@ func (s *server) handleClient(client *client) {
 			if !client.TLS && sc.TLS.StartTLSOn {
 				tlsConfig, ok := s.tlsConfigStore.Load().(*tls.Config)
 				if !ok {
-					s.mainlog().Error("Failed to load *tls.Config")
+					s.mainlog().Fields("iface", s.listenInterface).Error("failed to load *tls.Config")
 				} else if err := client.upgradeToTLS(tlsConfig); err == nil {
 					advertiseTLS = ""
 					client.resetTransaction()
 				} else {
-					s.log().WithError(err).Warnf("[%s] Failed TLS handshake", client.RemoteIP)
+					s.log().Fields("error", err, "iface", s.listenInterface, "ip", client.RemoteIP).
+						Warn("failed TLS handshake")
 					// Don't disconnect, let the client decide if it wants to continue
 				}
 			}
@@ -669,7 +670,7 @@ func (s *server) handleClient(client *client) {
 		// flush the response buffer
 		if client.bufout.Buffered() > 0 {
 			if s.log().IsDebug() {
-				s.log().Debugf("Writing response to client: \n%s", client.response.String())
+				s.log().Fields("out", client.response.String()).Debug("writing response to client")
 			}
 			err := s.flushResponse(client)
 			if err != nil {
@@ -715,9 +716,8 @@ func (s *server) defaultHost(a *mail.Address) {
 		sc := s.configStore.Load().(ServerConfig)
 		a.Host = sc.Hostname
 		if !s.allowsHost(a.Host) {
-			s.log().WithFields(
-				logrus.Fields{"hostname": sc.Hostname}).
-				Warn("the hostname is not present in AllowedHosts config setting")
+			s.log().Fields("hostname", sc.Hostname).
+				Warn("the hostname is not present in the AllowedHosts config setting")
 		}
 	}
 }

tests/guerrilla_test.go

@@ -207,16 +207,17 @@ func TestStart(t *testing.T) {
 		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 {
+		// msg="waiting for a new client" iface="127.0.0.1:4654"
+		if i := strings.Index(logOutput, "msg=\"waiting for a new client\" iface=\"127.0.0.1:4654\""); i < 0 {
 			t.Error("Server did not wait on 127.0.0.1:4654")
 		}
-		if i := strings.Index(logOutput, "[127.0.0.1:2526] Waiting for a new client"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"waiting for a new client\" iface=\"127.0.0.1:2526\""); i < 0 {
 			t.Error("Server did not wait on 127.0.0.1:2526")
 		}
-		if i := strings.Index(logOutput, "Server [127.0.0.1:4654] has stopped accepting new clients"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"server has stopped accepting new clients\" iface=\"127.0.0.1:4654\""); i < 0 {
 			t.Error("Server did not stop on 127.0.0.1:4654")
 		}
-		if i := strings.Index(logOutput, "Server [127.0.0.1:2526] has stopped accepting new clients"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"server has stopped accepting new clients\" iface=\"127.0.0.1:2526\""); i < 0 {
 			t.Error("Server did not stop on 127.0.0.1:2526")
 		}
 		if i := strings.Index(logOutput, "msg=\"shutdown completed\" iface=\"127.0.0.1:4654\""); i < 0 {
@@ -225,10 +226,10 @@ func TestStart(t *testing.T) {
 		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 {
+		if i := strings.Index(logOutput, "msg=\"shutting down pool\" iface=\"127.0.0.1:4654\""); i < 0 {
 			t.Error("Server did not shutdown pool on 127.0.0.1:4654")
 		}
-		if i := strings.Index(logOutput, "shutting down pool [127.0.0.1:2526]"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"shutting down pool\" iface=\"127.0.0.1:2526\""); i < 0 {
 			t.Error("Server did not shutdown pool on 127.0.0.1:2526")
 		}
 		if i := strings.Index(logOutput, "Backend shutdown completed"); i < 0 {
@@ -305,7 +306,7 @@ func TestGreeting(t *testing.T) {
 	app.Shutdown()
 	if read, err := ioutil.ReadFile("./testlog"); err == nil {
 		logOutput := string(read)
-		if i := strings.Index(logOutput, "Handle client [127.0.0.1"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"handle client\" peer=127.0.0.1"); i < 0 {
 			t.Error("Server did not handle any clients")
 		}
 	}
@@ -363,7 +364,7 @@ func TestShutDown(t *testing.T) {
 	if read, err := ioutil.ReadFile("./testlog"); err == nil {
 		logOutput := string(read)
 		//	fmt.Println(logOutput)
-		if i := strings.Index(logOutput, "Handle client [127.0.0.1"); i < 0 {
+		if i := strings.Index(logOutput, "msg=\"handle client\" peer=127.0.0.1"); i < 0 {
 			t.Error("Server did not handle any clients")
 		}
 	}