IDLE DONE doesn't work with Exchange when multiple updates are sent

[andreasbenzing]

I tried to get the updated messages as described by @taisph in #11 (comment)
However, the client hangs on the last <-done

How can I interrupt idling to fetch mails from the update?

[emersion]

Can you post debug logs?

client.SetDebug(os.Stderr)

[andreasbenzing]

The initial processing finishes with the following:

* 145 FETCH (BODY[] {16750}
... Message clipped ...
 UID 3387 FLAGS (\Seen \Recent))
QBlS2w OK FETCH completed.
1E1qHg UID MOVE 3387 "Deleted Items"
* OK [COPYUID 12 3387 59727]
* 145 EXPUNGE
* 144 EXISTS
1E1qHg OK MOVE completed.

Then comes the idling part:

yZABFw CAPABILITY
* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS MOVE ID UNSELECT CLIENTNETWORKPRESENCELOCATION CHILDREN IDLE NAMESPACE LITERAL+
yZABFw OK CAPABILITY completed.
Jq5U9w IDLE
+ IDLE accepted, awaiting DONE command.
* 1 RECENT
* 145 EXISTS
DONE

[emersion]

Hmm. At this point the server is supposed to send:

Jq5U9w OK IDLE terminated

[andreasbenzing]

This is an Exchange server, not sure if there are known problems. I also found that the problem occurs if two updates are received from the server in short sequence. For reference, here is the whole test program:

func Run() {
	log.Println("Connecting to server...")

	// Connect to server
	ic, err := client.DialTLS(viper.GetString("server"), nil)
	if err != nil {
		log.Fatal(err)
	}
	c = newImapClient(ic)
	log.Println("Connected")

	// Don't forget to logout
	defer func() {
		c.Logout()
		log.Println("Logged out")
	}()

	c.SetDebug(os.Stderr)
	username := viper.GetString("username")
	password := viper.GetString("password")
	if err := c.Login(username, password); err != nil {
		log.Fatal(err)
	}
	log.Println("Logged in")

	// Select a mailbox
	_, err = c.Select("INBOX/Notifications", false)
	if err != nil {
		log.Fatal(err)
	}

	updates := make(chan client.Update)
	c.Updates = updates

	for {
		upd, err := waitForMailboxUpdate(updates)
		if err != nil {
			panic(err)
		}
		fetchMessages(upd.Mailbox)
	}
}

func fetchMessages(status *imap.MailboxStatus) {
	log.Println("fetching...")
}

func waitForMailboxUpdate(chupd chan client.Update) (*client.MailboxUpdate, error) {
	done := make(chan error, 1)
	stop := make(chan struct{})
	go func() {
		done <- c.IdleWithFallback(stop, 5*time.Minute)
	}()

	var mboxupd *client.MailboxUpdate
waitLoop:
	for {
		select {
		case upd := <-chupd:
			if mboxupd = asMailboxUpdate(upd); mboxupd != nil {
				break waitLoop
			}
		case err := <-done:
			if err != nil {
				return nil, fmt.Errorf("error while idling: %s", err.Error())
			}
			return nil, nil
		}
	}

	close(stop)
	<-done

	return mboxupd, nil
}

func asMailboxUpdate(upd client.Update) *client.MailboxUpdate {
	if v, ok := upd.(*client.MailboxUpdate); ok {
		return v
	}
	return nil
}

[emersion]

I also found that the problem occurs if two updates are received from the server in short sequence

Ah, this is interesting.

[andreasbenzing]

I worked around the issue by first "emptying" the chupd chan before <-done. However, the next client.Select() now hangs on client.go:284 waiting for a reply which was already sent according to the debug logs:

+ IDLE accepted, awaiting DONE command.
* 1 RECENT
* 171 EXISTS
2020/08/06 10:20:27 dangling update - logged from emptying
2020/08/06 10:20:27 no further updates - logged from emptying
DONE
_nJBtA OK IDLE completed.
C0CbmQ SELECT "INBOX/Notifications"
* 172 EXISTS
* 1 RECENT
* FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
* OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
* OK [UNSEEN 171] Is the first unseen message
* OK [UIDVALIDITY 57] UIDVALIDITY value
* OK [UIDNEXT 3621] The next unique identifier value
C0CbmQ OK [READ-WRITE] SELECT completed.

[andreasbenzing]

One more update: setting c.Updates = nil and creating a new chan when going to idle again solves the issue. I assume the Updates channel creates problems with my

func newImapClient(c *client.Client) *imapClient {
	return &imapClient{
		c,
		idle.NewClient(c),
		move.NewClient(c),
	}
}

The initialization is

// Connect to server
ic, err := client.DialTLS(viper.GetString("server"), nil)
if err != nil {
	log.Fatal(err)
}
c = newImapClient(ic)

[ghost]

The same here. For the test purposes I send an e-mail to myself and receive two mailbox updates one after another in a quick succession. If after the first update I close the stop channel I passed to the idle client:

go func() {
    done <- idleClient.IdleWithFallback(stop, time.Minute)
}()

and then wait for IdleWithFallback to exit (<-done):

for_loop:
for {
	select {
	case update := <-updates:
		switch u := update.(type) {
		case *client.MailboxUpdate:
			close(stop)
			<-done

			// unreachable

		}
	case err := <-done:
		break for_loop
	}
}

the program hangs indefinitely.

[ghost]

It looks like go-imap/client.Client.Execute doesn't react to the closing of the stopOrRestart channel passed here:

go-imap-idle/client.go

Line 60 in f05f546

done <- c.idle(stopOrRestart)

and then here:

go-imap-idle/client.go

Lines 33 to 38 in f05f546

	res := &Response{
	Stop: stop,
	RepliesCh: make(chan []byte, 10),
	}
	if status, err := c.c.Execute(cmd, res); err != nil {

[ghost]

has this been fixed? I am also seeing a lock up when doing <-done after getting a MailboxUpdate.

[meskio]

I have the same problem, but with dovecot imap server instead of Exchange. As @andreasbenzing has pointed out, it looks like when you close the stop channel IdleWithFallback does write something to the updates channel, and if the channel is not buffered it will hang there.

My solution to the problem is to nil the updates channel before closing the idle:

c.Updates = nil
close(stop)
<-done

And recreate the channel just before entering into another idle.

I guess another option will be to have a permanent goroutine listening to updates and consuming the updates channel.

[qjebbs]

+1 with double MailboxUpdate sent.

I Guess this happens when a response have these two line:

* 1 RECENT
* 145 EXISTS

The relevant codes are here:

• https://github.com/emersion/go-imap/blob/0e5bf8b8c24d2bb1481e94a44c18d3fa2dfbb630/client/client.go#L394-L432

switch name {
case "EXISTS":
	// ...
	if c.Updates != nil {
		c.Updates <- &MailboxUpdate{c.Mailbox()}
	}
case "RECENT":
	// ...
	if c.Updates != nil {
		c.Updates <- &MailboxUpdate{c.Mailbox()}
	}
}

A quick solution came into my mind is that we hold updates in the response struct, which are shared between handling:

// DataResp is an IMAP response containing data.
type DataResp struct {
	// The response tag. Can be either "" for untagged responses, "+" for continuation
	// requests or a previous command's tag.
	Tag string
	// The parsed response fields.
	Fields []interface{}
	Updates map[UpdateType]interface{}
}

After we collect all updates, fires them at the last.

[qjebbs]

BTW: I introduced a throttle func to limit the executing, which also benefits when server send notification densely.

func throttle(fn OnUpdate, delay time.Duration) OnUpdate {
	lock := sync.Mutex{}
	prevs := make(map[reflect.Type]*time.Timer)
	return func(mailbox string, update interface{}) {
		lock.Lock()
		defer lock.Unlock()
		tp := reflect.TypeOf(update)
		if prev, ok := prevs[tp]; ok {
			prev.Stop()
		}
		prevs[tp] = time.AfterFunc(delay, func() {
			fn(mailbox, update)
		})
	}
}