Merge pull request #102 from wneessen/101-client-debug-logging

Implement SMTP client debug logging

client.go

@@ -130,6 +130,9 @@ type Client struct {
 
 	// user is the SMTP AUTH username
 	user string
+
+	// dl enables the debug logging on the SMTP client
+	dl bool
 }
 
 // Option returns a function that can be used for grouping Client options
@@ -240,6 +243,15 @@ func WithSSL() Option {
 	}
 }
 
+// WithDebugLog tells the client to log incoming and outgoing messages of the SMTP client
+// to StdErr
+func WithDebugLog() Option {
+	return func(c *Client) error {
+		c.dl = true
+		return nil
+	}
+}
+
 // WithHELO tells the client to use the provided string as HELO/EHLO greeting host
 func WithHELO(h string) Option {
 	return func(c *Client) error {
@@ -397,6 +409,14 @@ func (c *Client) SetSSL(s bool) {
 	c.ssl = s
 }
 
+// SetDebugLog tells the Client whether debug logging is enabled or not
+func (c *Client) SetDebugLog(v bool) {
+	c.dl = v
+	if c.sc != nil {
+		c.sc.SetDebugLog(v)
+	}
+}
+
 // SetTLSConfig overrides the current *tls.Config with the given *tls.Config value
 func (c *Client) SetTLSConfig(co *tls.Config) error {
 	if co == nil {
@@ -461,6 +481,9 @@ func (c *Client) DialWithContext(pc context.Context) error {
 	if err != nil {
 		return err
 	}
+	if c.dl {
+		c.sc.SetDebugLog(true)
+	}
 	if err := c.sc.Hello(c.helo); err != nil {
 		return err
 	}

client_test.go

@@ -105,6 +105,7 @@ func TestNewClientWithOptions(t *testing.T) {
 		{"WithDSNRcptNotifyType()", WithDSNRcptNotifyType(DSNRcptNotifySuccess), false},
 		{"WithDSNRcptNotifyType() wrong option", WithDSNRcptNotifyType("FAIL"), true},
 		{"WithoutNoop()", WithoutNoop(), false},
+		{"WithDebugLog()", WithDebugLog(), false},
 
 		{
 			"WithDSNRcptNotifyType() NEVER combination",
@@ -542,6 +543,30 @@ func TestClient_DialWithContext(t *testing.T) {
 	}
 }
 
+// TestClient_DialWithContext_Debug tests the DialWithContext method for the Client object with debug
+// logging enabled on the SMTP client
+func TestClient_DialWithContext_Debug(t *testing.T) {
+	c, err := getTestClient(true)
+	if err != nil {
+		t.Skipf("failed to create test client: %s. Skipping tests", err)
+	}
+	ctx := context.Background()
+	if err := c.DialWithContext(ctx); err != nil {
+		t.Errorf("failed to dial with context: %s", err)
+		return
+	}
+	if c.co == nil {
+		t.Errorf("DialWithContext didn't fail but no connection found.")
+	}
+	if c.sc == nil {
+		t.Errorf("DialWithContext didn't fail but no SMTP client found.")
+	}
+	c.SetDebugLog(true)
+	if err := c.Close(); err != nil {
+		t.Errorf("failed to close connection: %s", err)
+	}
+}
+
 // TestClient_DialWithContextInvalidHost tests the DialWithContext method with intentional breaking
 // for the Client object
 func TestClient_DialWithContextInvalidHost(t *testing.T) {
@@ -1087,7 +1112,6 @@ func getTestConnection(auth bool) (*Client, error) {
 	if th == "" {
 		return nil, fmt.Errorf("no TEST_HOST set")
 	}
-	fmt.Printf("XXX: TEST_HOST: %s\n", th)
 	tp := 25
 	if tps := os.Getenv("TEST_PORT"); tps != "" {
 		tpi, err := strconv.Atoi(tps)
@@ -1117,6 +1141,8 @@ func getTestConnection(auth bool) (*Client, error) {
 		if p != "" {
 			c.SetPassword(p)
 		}
+		// We don't want to log authentication data in tests
+		c.SetDebugLog(false)
 	}
 	if err := c.DialWithContext(context.Background()); err != nil {
 		return c, fmt.Errorf("connection to test server failed: %w", err)
@@ -1127,6 +1153,51 @@ func getTestConnection(auth bool) (*Client, error) {
 	return c, nil
 }
 
+// getTestClient takes environment variables to establish a client without connecting
+// to the SMTP server
+func getTestClient(auth bool) (*Client, error) {
+	if os.Getenv("TEST_SKIP_ONLINE") != "" {
+		return nil, fmt.Errorf("env variable TEST_SKIP_ONLINE is set. Skipping online tests")
+	}
+	th := os.Getenv("TEST_HOST")
+	if th == "" {
+		return nil, fmt.Errorf("no TEST_HOST set")
+	}
+	tp := 25
+	if tps := os.Getenv("TEST_PORT"); tps != "" {
+		tpi, err := strconv.Atoi(tps)
+		if err == nil {
+			tp = tpi
+		}
+	}
+	sv := false
+	if sve := os.Getenv("TEST_TLS_SKIP_VERIFY"); sve != "" {
+		sv = true
+	}
+	c, err := NewClient(th, WithPort(tp))
+	if err != nil {
+		return c, err
+	}
+	c.tlsconfig.InsecureSkipVerify = sv
+	if auth {
+		st := os.Getenv("TEST_SMTPAUTH_TYPE")
+		if st != "" {
+			c.SetSMTPAuth(SMTPAuthType(st))
+		}
+		u := os.Getenv("TEST_SMTPAUTH_USER")
+		if u != "" {
+			c.SetUsername(u)
+		}
+		p := os.Getenv("TEST_SMTPAUTH_PASS")
+		if p != "" {
+			c.SetPassword(p)
+		}
+		// We don't want to log authentication data in tests
+		c.SetDebugLog(false)
+	}
+	return c, nil
+}
+
 // getTestConnectionWithDSN takes environment variables to establish a connection to a real
 // SMTP server to test all functionality that requires a connection. It also enables DSN
 func getTestConnectionWithDSN(auth bool) (*Client, error) {

smtp/smtp.go

@@ -32,8 +32,10 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log"
 	"net"
 	"net/textproto"
+	"os"
 	"strings"
 )
 
@@ -55,8 +57,19 @@ type Client struct {
 	localName  string // the name to use in HELO/EHLO
 	didHello   bool   // whether we've said HELO/EHLO
 	helloError error  // the error from the hello
+
+	debug  bool        // debug logging is enabled
+	logger *log.Logger // logger will be used for debug logging
 }
 
+// logDirection is a type wrapper for the direction a debug log message goes
+type logDirection int
+
+const (
+	logIn  logDirection = iota // Incoming log message
+	logOut                     // Outgoing log message
+)
+
 // Dial returns a new Client connected to an SMTP server at addr.
 // The addr must include a port, as in "mail.example.com:smtp".
 func Dial(addr string) (*Client, error) {
@@ -81,6 +94,7 @@ func NewClient(conn net.Conn, host string) (*Client, error) {
 	}
 	c := &Client{Text: text, conn: conn, serverName: host, localName: "localhost"}
 	_, c.tls = conn.(*tls.Conn)
+
 	return c, nil
 }
 
@@ -119,6 +133,7 @@ func (c *Client) Hello(localName string) error {
 
 // cmd is a convenience function that sends a command and returns the response
 func (c *Client) cmd(expectCode int, format string, args ...interface{}) (int, string, error) {
+	c.debugLog(logOut, format, args...)
 	id, err := c.Text.Cmd(format, args...)
 	if err != nil {
 		return 0, "", err
@@ -126,6 +141,7 @@ func (c *Client) cmd(expectCode int, format string, args ...interface{}) (int, s
 	c.Text.StartResponse(id)
 	defer c.Text.EndResponse(id)
 	code, msg, err := c.Text.ReadResponse(expectCode)
+	c.debugLog(logIn, "%d %s", code, msg)
 	return code, msg, err
 }
 
@@ -415,6 +431,28 @@ func (c *Client) Quit() error {
 	return c.Text.Close()
 }
 
+// SetDebugLog enables the debug logging for incoming and outgoing SMTP messages
+func (c *Client) SetDebugLog(v bool) {
+	c.debug = v
+	if v {
+		c.logger = log.New(os.Stderr, "[DEBUG] ", log.LstdFlags|log.Lmsgprefix)
+		return
+	}
+	c.logger = nil
+}
+
+// debugLog checks if the debug flag is set and if so logs the provided message to StdErr
+func (c *Client) debugLog(d logDirection, f string, a ...interface{}) {
+	if c.debug {
+		p := "C <-- S:"
+		if d == logOut {
+			p = "C --> S:"
+		}
+		fs := fmt.Sprintf("%s %s", p, f)
+		c.logger.Printf(fs, a...)
+	}
+}
+
 // validateLine checks to see if a line has CR or LF as per RFC 5321.
 func validateLine(line string) error {
 	if strings.ContainsAny(line, "\n\r") {

smtp/smtp_test.go

@@ -633,6 +633,34 @@ func TestNewClient(t *testing.T) {
 	}
 }
 
+// TestClient_SetDebugLog tests the Client method with the Client.SetDebugLog method
+// to enable debug logging
+func TestClient_SetDebugLog(t *testing.T) {
+	server := strings.Join(strings.Split(newClientServer, "\n"), "\r\n")
+
+	var cmdbuf strings.Builder
+	bcmdbuf := bufio.NewWriter(&cmdbuf)
+	out := func() string {
+		if err := bcmdbuf.Flush(); err != nil {
+			t.Errorf("failed to flush: %s", err)
+		}
+		return cmdbuf.String()
+	}
+	var fake faker
+	fake.ReadWriter = bufio.NewReadWriter(bufio.NewReader(strings.NewReader(server)), bcmdbuf)
+	c, err := NewClient(fake, "fake.host")
+	if err != nil {
+		t.Fatalf("NewClient: %v\n(after %v)", err, out())
+	}
+	defer func() {
+		_ = c.Close()
+	}()
+	c.SetDebugLog(true)
+	if !c.debug {
+		t.Errorf("Expected DebugLog flag to be true but received false")
+	}
+}
+
 var newClientServer = `220 hello world
 250-mx.google.com at your service
 250-SIZE 35651584