Race on timeout

[ericychoi]

When SendTimeout is triggered, send() will result in a race since client is used in 2 different goroutines at the same time. This is happening because textproto.Conn isn't thread-safe, and we are calling .quit() and .Close() at the same time.

I am including test code here. Save it as a test file inside the same package and run it with go test -race -test.run=TestSendRace.

package mail

import (
    "fmt"
    "log"
    "net"
    "testing"
    "time"
)

func TestSendRace(t *testing.T) {
    port := 56666
    timeout := 1 * time.Second
    startService(port, []string{
        `220 test connected`,
        `250 after helo`,
        `250 after mail from`,
        `250 after rcpt to`,
        `354 after data`,
    })

    server := NewSMTPClient()
    server.ConnectTimeout = timeout
    server.SendTimeout = timeout
    server.KeepAlive = false
    server.Host = `localhost`
    server.Port = port

    smtpClient, err := server.Connect()
    if err != nil {
        log.Fatalf("couldn't connect: %s", err.Error())
    }
    defer smtpClient.Close()

    err = SendMessage(`foo@bar`, []string{`rcpt@bar`}, "body", smtpClient)
    if err != nil {
        log.Fatalf("couldn't send: %s", err.Error())
    }
}

func startService(port int, responses []string) {
    log.Printf("starting service at %d...\n", port)
    listener, err := net.Listen("tcp", fmt.Sprintf(":%d", port))
    if err != nil {
        log.Fatalf("couldn't listen to port %d: %s", port, err)
    }

    go func() {
        for {
            conn, err := listener.Accept()
            if err != nil {
                log.Fatalf("couldn't listen accept the request in port %d", port)
            }
            go respond(conn, responses)
        }
    }()
}

func respond(conn net.Conn, responses []string) {
    buf := make([]byte, 1024)
    for i, resp := range responses {
        conn.Write([]byte(resp + "\n"))
        n, err := conn.Read(buf)
        if err != nil {
            log.Println("couldn't read data")
            return
        }
        readStr := string(buf[:n])
        log.Printf("READ:%s", string(readStr))

        if i == len(responses)-1 {
            break
        }
    }
    time.Sleep(5 * time.Second)
    conn.Write([]byte(`221 after quit` + "\n"))
    conn.Close()
}

[ericychoi]

test output:

15:33:47 ❯ go test -race -test.run=TestSendRace
2023/03/24 15:34:41 starting service at 56666...
2023/03/24 15:34:41 READ:EHLO localhost
2023/03/24 15:34:41 READ:MAIL FROM:<foo@bar>
2023/03/24 15:34:41 READ:RCPT TO:<rcpt@bar>
2023/03/24 15:34:41 READ:DATA
2023/03/24 15:34:41 READ:body
.
==================
WARNING: DATA RACE
Read at 0x00c000214030 by goroutine 7:
  net/textproto.(*Writer).closeDot()
      /usr/local/opt/go/libexec/src/net/textproto/writer.go:50 +0x64
  net/textproto.(*Writer).PrintfLine()
      /usr/local/opt/go/libexec/src/net/textproto/writer.go:30 +0x50
  net/textproto.(*Conn).Cmd()
      /usr/local/opt/go/libexec/src/net/textproto/textproto.go:115 +0xa4
  github.com/xhit/go-simple-mail/v2.(*smtpClient).cmd()
      /Users/echoi/github/go-simple-mail/smtp.go:97 +0xc9
  github.com/xhit/go-simple-mail/v2.(*smtpClient).quit()
      /Users/echoi/github/go-simple-mail/smtp.go:319 +0x6e
  github.com/xhit/go-simple-mail/v2.checkKeepAlive()
      /Users/echoi/github/go-simple-mail/email.go:943 +0x6a
  github.com/xhit/go-simple-mail/v2.send()
      /Users/echoi/github/go-simple-mail/email.go:888 +0x4b6
  github.com/xhit/go-simple-mail/v2.SendMessage()
      /Users/echoi/github/go-simple-mail/email.go:856 +0x109
  github.com/xhit/go-simple-mail/v2.TestSendRace()
      /Users/echoi/github/go-simple-mail/email_test.go:35 +0x507
  testing.tRunner()
      /usr/local/opt/go/libexec/src/testing/testing.go:1446 +0x216
  testing.(*T).Run.func1()
      /usr/local/opt/go/libexec/src/testing/testing.go:1493 +0x47

Previous write at 0x00c000214030 by goroutine 15:
  net/textproto.(*dotWriter).Close()
      /usr/local/opt/go/libexec/src/net/textproto/writer.go:105 +0x84
  github.com/xhit/go-simple-mail/v2.(*dataCloser).Close()
      /Users/echoi/github/go-simple-mail/smtp.go:261 +0x4c
  github.com/xhit/go-simple-mail/v2.sendMailProcess()
      /Users/echoi/github/go-simple-mail/email.go:930 +0x2bb
  github.com/xhit/go-simple-mail/v2.send.func1()
      /Users/echoi/github/go-simple-mail/email.go:873 +0xa4
  github.com/xhit/go-simple-mail/v2.send.func2()
      /Users/echoi/github/go-simple-mail/email.go:874 +0xcc

[xhit]

Hi, thanks for catch it!.

I'm moving to another location, I will fix it when I finish.

Also, any PR are welcome, i will check it.

[xhit]

Hi @ericychoi can you test #82? In my tests data race are gone and mail sending is working as intended, but I need to test an especial environment first