logging: log more details in the DATA command, including the length of data read

backends/backend.go

@@ -46,7 +46,7 @@ type Backend interface {
 	ValidateRcpt(e *mail.Envelope) RcptError
 	ProcessBackground(e *mail.Envelope)
 	// ProcessStream is the alternative for Process, a stream is read from io.Reader
-	ProcessStream(r io.Reader, e *mail.Envelope) (Result, error)
+	ProcessStream(r io.Reader, e *mail.Envelope) (Result, int64, error)
 	// StreamOn signals if ProcessStream can be used
 	StreamOn() bool
 	// Initializes the backend, eg. creates folders, sets-up database connections

backends/gateway.go

@@ -364,10 +364,10 @@ func (gw *BackendGateway) ProcessBackground(e *mail.Envelope) {
 	}
 }
 
-func (gw *BackendGateway) ProcessStream(r io.Reader, e *mail.Envelope) (Result, error) {
+func (gw *BackendGateway) ProcessStream(r io.Reader, e *mail.Envelope) (Result, int64, error) {
 	res := response.Canned
 	if gw.State != BackendStateRunning {
-		return NewResult(res.FailBackendNotRunning, response.SP, gw.State), errors.New(res.FailBackendNotRunning.String())
+		return NewResult(res.FailBackendNotRunning, response.SP, gw.State), 0, errors.New(res.FailBackendNotRunning.String())
 	}
 	// borrow a workerMsg from the pool
 	workerMsg := workerMsgPool.Get().(*workerMsg)
@@ -382,29 +382,23 @@ func (gw *BackendGateway) ProcessStream(r io.Reader, e *mail.Envelope) (Result,
 	case status := <-workerMsg.notifyMe:
 		// email saving transaction completed
 		if status.result == BackendResultOK && status.queuedID != "" {
-			return NewResult(res.SuccessMessageQueued, response.SP, status.queuedID), status.err
+			return NewResult(res.SuccessMessageQueued, response.SP, status.queuedID), e.Size, status.err
 		}
-
 		// A custom result, there was probably an error, if so, log it
 		if status.result != nil {
-			if status.err != nil {
-				Log().Error(status.err)
-			}
-			return status.result, status.err
+			return status.result, e.Size, status.err
 		}
-
 		// if there was no result, but there's an error, then make a new result from the error
 		if status.err != nil {
 			if _, err := strconv.Atoi(status.err.Error()[:3]); err != nil {
-				return NewResult(res.FailBackendTransaction, response.SP, status.err), status.err
+				return NewResult(res.FailBackendTransaction, response.SP, status.err), e.Size, status.err
 			}
-			return NewResult(status.err), status.err
+			return NewResult(status.err), e.Size, status.err
 		}
-
 		// both result & error are nil (should not happen)
 		err := errors.New("no response from backend - processor did not return a result or an error")
 		Log().Error(err)
-		return NewResult(res.FailBackendTransaction, response.SP, err), err
+		return NewResult(res.FailBackendTransaction, response.SP, err), e.Size, err
 
 	case <-time.After(gw.saveTimeout()):
 		Log().Fields("queuedID", e.QueuedId).Error("backend has timed out while saving email stream")
@@ -415,9 +409,8 @@ func (gw *BackendGateway) ProcessStream(r io.Reader, e *mail.Envelope) (Result,
 			e.Done()
 			Log().Fields("queuedID", e.QueuedId).Info("backend has finished saving email stream after timeout")
 		}()
-		return NewResult(res.FailBackendTimeout), errors.New("gateway timeout")
+		return NewResult(res.FailBackendTimeout), -1, errors.New("gateway timeout")
 	}
-
 }
 
 // Shutdown shuts down the backend and leaves it in BackendStateShuttered state

server.go

@@ -376,13 +376,18 @@ func (s *server) handleClient(client *client) {
 		s.log().Fields(
 			"peer", client.RemoteIP,
 			"event", "disconnect",
-			"id":    client.ID,
-			"queuedID": client.QueuedID,
+			"id", client.ID,
+			"queuedID", client.QueuedId,
 		).Info("Disconnect client")
 		client.closeConn()
 	}()
 	sc := s.configStore.Load().(ServerConfig)
-	s.log().Fields("peer", client.RemoteIP, "id", client.ID, "event", "connect").Info("handle client")
+	s.log().Fields(
+		"peer", client.RemoteIP,
+		"id", client.ID,
+		"event", "connect",
+		"queuedID", client.QueuedId,
+	).Info("handle client")
 
 	// Initial greeting
 	greeting := fmt.Sprintf("220 %s SMTP Guerrilla(%s) #%d (%d) %s",
@@ -518,13 +523,13 @@ func (s *server) handleClient(client *client) {
 					client.MailFrom = mail.Address{}
 				} else {
 					s.log().Fields(
-						"event",   "mailfrom",
-						"helo",    client.Helo,
-						"domain",  client.MailFrom.Host,
+						"event", "mailfrom",
+						"helo", client.Helo,
+						"domain", client.MailFrom.Host,
 						"address", client.RemoteIP,
-						"id":      client.ID,
-						"queuedID" : client.queuedID,
-					}).Info("mail from")
+						"id", client.ID,
+						"queuedID", client.QueuedId,
+					).Info("mail from")
 				}
 				client.TransportType = smtp.TransportTypeUnspecified
 				for i := range client.MailFrom.PathParams {
@@ -598,9 +603,7 @@ func (s *server) handleClient(client *client) {
 					client.sendResponse(r.FailUnrecognizedCmd)
 				}
 			}
-
 		case ClientData:
-
 			// intentionally placed the limit 1MB above so that reading does not return with an error
 			// if the client goes a little over. Anything above will err
 			client.bufin.setLimit(sc.MaxSize + 1024000) // This a hard limit.
@@ -610,9 +613,18 @@ func (s *server) handleClient(client *client) {
 				err error
 				res backends.Result
 			)
+			fields := []interface{}{
+				"event", "data",
+				"id", client.ID,
+				"queuedID", client.QueuedId,
+				"messageID", client.MessageID,
+				"peer", client.RemoteIP,
+				"serverID", s.serverID,
+			}
+			s.log().Fields(fields...).Info("receive DATA")
 			if be.StreamOn() {
 				// process the message as a stream
-				res, err = be.ProcessStream(client.smtpReader.DotReader(), client.Envelope)
+				res, n, err = be.ProcessStream(client.smtpReader.DotReader(), client.Envelope)
 				if err == nil && res.Code() < 300 {
 					e := s.envelopePool.Borrow(
 						client.Envelope.RemoteIP,
@@ -637,8 +649,8 @@ func (s *server) handleClient(client *client) {
 					}
 				}
 				// All done. we can close the smtpReader, the protocol will reset the transaction, expecting a new message
-				if err := client.smtpReader.Close(); err != nil {
-					s.log().WithError(err).Error("could not close DATA reader")
+				if closeErr := client.smtpReader.Close(); closeErr != nil {
+					s.log().WithError(closeErr).Error("could not close DATA reader")
 				}
 			}
 
@@ -653,7 +665,7 @@ func (s *server) handleClient(client *client) {
 					client.sendResponse(r.FailReadErrorDataCmd, " ", err.Error())
 					client.kill()
 				}
-				s.log().WithError(err).Warn("Error reading data")
+				s.log().Fields(append(fields, "error", err)...).Error("error reading DATA")
 				client.resetTransaction()
 				break
 			}
@@ -664,12 +676,7 @@ func (s *server) handleClient(client *client) {
 
 			if res.Code() < 300 {
 				client.messagesSent++
-				s.log().Fields(
-					"event" : "received"
-					"helo":          client.Helo,
-					"remoteAddress": getRemoteAddr(client.conn),
-					"success":       true,
-				).Info("Received message")
+				s.log().Fields(append(fields, "length", n)...).Info("received message DATA")
 			}
 			client.sendResponse(res)
 			client.state = ClientCmd

tests/guerrilla_test.go

@@ -346,7 +346,7 @@ func TestGreeting(t *testing.T) {
 	app.Shutdown()
 	if read, err := ioutil.ReadFile("./testlog"); err == nil {
 		logOutput := string(read)
-		if i := strings.Index(logOutput, "msg=\"handle client\" peer=127.0.0.1"); i < 0 {
+		if !MatchLog(logOutput, 1, "msg", "handle client", "peer", "127.0.0.1") {
 			t.Error("Server did not handle any clients")
 		}
 	}
@@ -404,9 +404,10 @@ func TestShutDown(t *testing.T) {
 	if read, err := ioutil.ReadFile("./testlog"); err == nil {
 		logOutput := string(read)
 		//	fmt.Println(logOutput)
-		if i := strings.Index(logOutput, "msg=\"handle client\" peer=127.0.0.1"); i < 0 {
+		if !MatchLog(logOutput, 1, "msg", "handle client", "peer", "127.0.0.1") {
 			t.Error("Server did not handle any clients")
 		}
+
 	}
 
 }

tests/util.go

@@ -2,6 +2,7 @@ package test
 
 import (
 	"fmt"
+	"regexp"
 	"strings"
 )
 
@@ -15,6 +16,7 @@ func MatchLog(input string, startLine int, args ...interface{}) bool {
 	if len(lines) < startLine {
 		panic("log too short, lines:" + fmt.Sprintf("%v", len(lines)))
 	}
+	re, _ := regexp.Compile(`[[:space:]:\\]`)
 	var lookFor string
 	// for each line
 	found := false
@@ -26,18 +28,14 @@ func MatchLog(input string, startLine int, args ...interface{}) bool {
 			}
 			key := args[j]
 			val := args[j+1]
-			switch val.(type) {
-			case string:
+			lookFor = fmt.Sprintf("%v", val)
+			if re.MatchString(lookFor) {
 				// quote it
 				lookFor = fmt.Sprintf(`%s="%s"`, key, val)
-				break
-			case fmt.Stringer:
-				// quote it
-				lookFor = fmt.Sprintf(`%s="%s"`, key, val)
-				break
-			default:
+			} else {
 				lookFor = fmt.Sprintf(`%s=%v`, key, val)
 			}
+
 			if pos := strings.Index(lines[i], lookFor); pos != -1 {
 				found = true
 			} else {