docs daemon example: i/o timeout

[rislah]

using this example: https://godoc.org/github.com/go-mail/mail#ex-package--Daemon.

the email gets sent however after 30 seconds it throws an error on s.Close()

error is: "write tcp [myipv6addr]:56186->[2a06:1700:0:b::c0cc]:465: i/o timeout". also tried different email providers, same issue

does anyone have any idea why?

[sedalu]

This is happening when a SMTP server doesn't respond to the QUIT command sent by s.Close(). The SendCloser implementation uses net/smtp for its SMTP client. I'm not sure how to remedy the issue. I just log.Println(err) and continue instead of panic(err)

[hellsius]

It seems that this problem is related to the timeout and how mail package handles it. The Dial method sets SetDeadline

if d.Timeout > 0 {
	conn.SetDeadline(time.Now().Add(d.Timeout))
}

and in net package specification

        // SetDeadline sets the read and write deadlines associated
        // with the connection. It is equivalent to calling both
        // SetReadDeadline and SetWriteDeadline.
        //
        // A deadline is an absolute time after which I/O operations
        // fail with a timeout (see type Error) instead of
        // blocking. The deadline applies to all future and pending
        // I/O, not just the immediately following call to ReadFrom or
        // WriteTo. After a deadline has been exceeded, the connection
        // can be refreshed by setting a deadline in the future.
        //
        // An idle timeout can be implemented by repeatedly extending
        // the deadline after successful ReadFrom or WriteTo calls.
        //
        // A zero value for t means I/O operations will not time out.
        SetDeadline(t time.Time) error

This should mean that the deadline occurs even for active connections. There are two parameters Timeout and Deadline, but it seems the timeout does not work as intended and the connection is terminated by deadline part. This lead to the situation where, it tries to close connection that was already closed by deadline, therefore such error occurs.

The NewDialer function (see bellow).

// NewDialer returns a new SMTP Dialer. The given parameters are used to connect
// to the SMTP server.
func NewDialer(host string, port int, username, password string) *Dialer {
	return &Dialer{
		Host:         host,
		Port:         port,
		Username:     username,
		Password:     password,
		SSL:          port == 465,
		Timeout:      10 * time.Second,
		RetryFailure: true,
	}
}

Uses default timeout for 10 seconds and in the description daemon is set to timeout after 30 seconds. Thus the connection would be closed 3 times before the action in the daemon occurs. Also, please note that after you send the message it will also set the deadline for the specified timeout.

To solve the problem, you have set dialer.Timeout to be greater (as equal does not work), than the timeout in the daemon.

But all in all I think that this is a bug in the implementation. The code snippet show the behavior of standard net.Dial vs the mail.Dialer and its timeouts.

package main

import (
	"fmt"
	"log"
	"net"
	"time"

	"github.com/go-mail/mail"
)

var MailerChannel = make(chan *mail.Message)

func addr(host string, port int) string {
	return fmt.Sprintf("%s:%d", host, port)
}

func runDaemon(dialer *mail.Dialer) {
	go func() {

		defer func() {
			if r := recover(); r != nil {
				fmt.Println("[DAEMON] Recovered ", r)
				time.Sleep(5 * time.Second)
				runDaemon(dialer)

			}
		}()
		var s mail.SendCloser
		var err error

		open := false

		for {
			if !open {
				log.Println("[DAEMON] Opening connection")
				s, err = dialer.Dial()
				if err != nil {
					log.Println("[DAEMON] failed dial:", err)
					panic(err)
				} else {
					open = true
				}

			}
			select {
			case m, ok := <-MailerChannel:
				log.Println("[DAEMON] Recevied message")
				if !ok {
					return
				}
				if err := mail.Send(s, m); err != nil {
					log.Print(err)
					open = false
				}
				if err := s.Close(); err != nil {
					log.Println("[DAEMON] Closing now", err)
				}

			// Change TIMEOUT to 4 * time.Second and everything will start working
			case <-time.After(TIMEOUT): // error occurs
				//			case <-time.After(4 * time.Second): // error does not occur
				log.Println("[DAEMON] timeout time")
				if open {
					log.Println("[DAEMON] conn still open")
					if err := s.Close(); err != nil {
						log.Println("[DAEMON] error closing connection", err)
					}
					open = false
				}
			}
		}
	}()

}

func InitiateDaemon() {

	dialer := mail.NewDialer(SERVER, PORT, USER, PASS)
	dialer.Timeout = TIMEOUT

	runDaemon(dialer)

}

var (
	SERVER  string        = "smtp.server.address"
	PORT    int           = 25
	USER    string        = "user"
	PASS    string        = "pass"
	TIMEOUT time.Duration = 5 * time.Second // seconds
)

func main() {
	log.Println("time:", time.Now())
	InitiateDaemon()

	for {
		con, err := net.DialTimeout("tcp", addr(SERVER, PORT), TIMEOUT)
		if err != nil {
			log.Println("Failed Dialer:", err)

		} else {
			log.Println("Regular connection success")
			err = con.Close()
			if err != nil {
				log.Println("failed to close connection", err)
			}
		}

		time.Sleep(1 * time.Second)
	}

}