dovecot - Jan 2014 - IDLE dropping EXISTS events on mass message arrival

Hi, I'm not sure if this is some throttling/DoS protection or a bug.  I
didn't see notice anything like it mentioned looking at the NEWS file
from hg, this is on 2.1.7 on Debian stable.

I have a client doing IDLE on INBOX.vomiteer.  When individual messages
arrive with some time interval in between them, I get EXISTS events for
each message as expected.

However, when I store a bunch of messages at once (via tag + mass copy
in mutt on a fast-ish connection), I get a few EXISTS events (sometimes
one, sometimes two) even though I copied a lot of new messages over.

I expected to get an EXISTS event for each message which arrived, but
perhaps there's some sort of DoS/throttling mechanism.

strace -t -s4096 output of the dovecot process below:
fd=13 is inotify, you'll see large read(13, ... indicating
multiple filenames from inotify.  However, only one EXISTS message
got written to the socket.

I've filtered out the gettimeofday syscalls for brevity.

07:30:02 epoll_wait(9, {}, 6, 3937)     = 0
07:30:06 stat64("/home/ew/.maildir/.INBOX.vomiteer/cur",
{st_mode=S_IFDIR|0700, st_size=12288, ...}) = 0
07:30:06 stat64("/home/ew/.maildir/.INBOX.vomiteer/new",
{st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
07:30:06 stat64("/home/ew/.maildir/.INBOX.vomiteer/new",
{st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
07:30:06 stat64("/home/ew/.maildir/.INBOX.vomiteer/cur",
{st_mode=S_IFDIR|0700, st_size=12288, ...}) = 0
07:30:06 stat64("/home/ew/.maildir/.INBOX.vomiteer/dovecot.index.log",
{st_mode=S_IFREG|0600, st_size=25920, ...}) = 0
07:30:06 fstat64(10, {st_mode=S_IFREG|0600, st_size=25920, ...}) = 0
07:30:06 epoll_wait(9, {}, 6, 7865)     = 0
07:30:14 setsockopt(11, SOL_TCP, TCP_CORK, [1], 4) = 0
07:30:14 write(11, "* OK Still here\r\n", 17) = 17
07:30:14 setsockopt(11, SOL_TCP, TCP_CORK, [0], 4) = 0
07:30:14 time(NULL)                     = 1390289414
07:30:14 epoll_wait(9, {{EPOLLIN, {u32=4159555408, u64=4159555408}}}, 6, 22124)
= 1
07:30:17 read(13,
"\2\0\0\0\200\0\0\0\t\365\r\0000\0\0\0001390289417.M94623P14841.dcvr,S=1580,W=1619:2,S\0\0\2\0\0\0\200\0\0\0\n\365\r\0000\0\0\0001390289417.M94624P14841.dcvr,S=1580,W=1619:2,S\0\0\2\0\0\0\200\0\0\0\v\365\r\0000\0\0\0001390289417.M94625P14841.dcvr,S=1422,W=1460:2,S\0\0\2\0\0\0\200\0\0\0\f\365\r\0000\0\0\0001390289417.M94626P14841.dcvr,S=1422,W=1460:2,S\0\0\2\0\0\0\200\0\0\0\r\365\r\0000\0\0\0001390289417.M94627P14841.dcvr,S=1861,W=1907:2,S\0\0\2\0\0\0\200\0\0\0\16\365\r\0000\0\0\0001390289417.M94628P14841.dcvr,S=1861,W=1907:2,S\0\0\2\0\0\0\200\0\0\0\17\365\r\0000\0\0\0001390289417.M94629P14841.dcvr,S=4732,W=4854:2,S\0\0\2\0\0\0\200\0\0\0\20\365\r\0000\0\0\0001390289417.M94630P14841.dcvr,S=4732,W=4854:2,S\0\0\2\0\0\0\200\0\0\0\21\365\r\0000\0\0\0001390289417.M94631P14841.dcvr,S=4028,W=4128:2,S\0\0\2\0\0\0\200\0\0\0\22\365\r\0000\0\0\0001390289417.M94632P14841.dcvr,S=4028,W=4128:2,S\0\0\2\0\0\0\200\0\0\0\23\365\r\0000\0\0\0001390289417.M94633P14841.dcvr,S=3865,W=3968:2,S\0\0\2\0\0\0\200\0\0\0\24\365\r\0000\0\0\0001390289417.M94634P14841.dcvr,S=3865,W=3968:2,S\0\0",
32768) = 768
07:30:17 epoll_wait(9, {{EPOLLIN, {u32=4159555408, u64=4159555408}}}, 6, 499) =
1
07:30:17 read(13,
"\2\0\0\0\200\0\0\0\25\365\r\0000\0\0\0001390289417.M94635P14841.dcvr,S=4092,W=4189:2,S\0\0\2\0\0\0\200\0\0\0\26\365\r\0000\0\0\0001390289417.M94636P14841.dcvr,S=4092,W=4189:2,S\0\0\2\0\0\0\200\0\0\0\27\365\r\0000\0\0\0001390289417.M94637P14841.dcvr,S=1517,W=1552:2,S\0\0\2\0\0\0\200\0\0\0\30\365\r\0000\0\0\0001390289417.M94638P14841.dcvr,S=1517,W=1552:2,S\0\0",
32768) = 256
07:30:17 epoll_wait(9, {}, 6, 498)      = 0
07:30:17 stat64("/home/ew/.maildir/.INBOX.vomiteer/new",
{st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
07:30:17 stat64("/home/ew/.maildir/.INBOX.vomiteer/cur",
{st_mode=S_IFDIR|0700, st_size=12288, ...}) = 0
07:30:17 stat64("/home/ew/.maildir/.INBOX.vomiteer/dovecot.index.log",
{st_mode=S_IFREG|0600, st_size=26328, ...}) = 0
07:30:17 fstat64(10, {st_mode=S_IFREG|0600, st_size=26328, ...}) = 0
07:30:17 pread64(10,
"\200\200\200\207@\0\0\20\0\0\0\0\0\0\0\0$\0\0\0\0\0\0\0\1\0\0\0\200\200\200\214\0\1\0\20\0\0$\0\337!\336R\344\231\2L\0\0\0\0\t\"\336R\t\"\336R\0\0\0\0\t\"\336R\0\0\0\0007\n\0\0\200\200\200\204
\0\0\20@\0\4\0\234e\0\0\200\200\200\242\2\0\0\20\317\0\0\0\10\0\0\0\320\0\0\0\10\0\0\0\321\0\0\0\10\0\0\0\322\0\0\0\10\0\0\0\323\0\0\0\10\0\0\0\324\0\0\0\10\0\0\0\325\0\0\0\10\0\0\0\326\0\0\0\10\0\0\0\327\0\0\0\10\0\0\0\330\0\0\0\10\0\0\0\331\0\0\0\10\0\0\0\332\0\0\0\10\0\0\0\333\0\0\0\10\0\0\0\334\0\0\0\10\0\0\0\335\0\0\0\10\0\0\0\336\0\0\0\10\0\0\0\200\200\200\207@\0\0\20\1\0\0\0\0\260\2L\0\0\0\0\4\0\4\0\1\0\0\0\200\200\200\242\0\2\0\20\317\0\0\0\250\275\0\0\320\0\0\0\234\277\0\0\321\0\0\0|\301\0\0\322\0\0\0|\304\0\0\323\0\0\0\200\307\0\0\324\0\0\0|\312\0\0\325\0\0\0h\315\0\0\326\0\0\0\\\320\0\0\327\0\0\0\224\323\0\0\330\0\0\0\210\325\0\0\331\0\0\0h\327\0\0\332\0\0\0h\332\0\0\333\0\0\0l\335\0\0\334\0\0\0h\340\0\0\335\0\0\0T\343\0\0\336\0\0\0H\346\0\0\200\200\200\204
\0\0\0200\0\4\0\337\0\0\0", 8192, 25920) = 408
07:30:17 pread64(10, "", 8192, 26328)   = 0
07:30:17 stat64("/home/ew/.maildir/.INBOX.vomiteer/dovecot.index.log",
{st_mode=S_IFREG|0600, st_size=26328, ...}) = 0
07:30:17 fstat64(10, {st_mode=S_IFREG|0600, st_size=26328, ...}) = 0
07:30:17 time(NULL)                     = 1390289417
07:30:17 setsockopt(11, SOL_TCP, TCP_CORK, [1], 4) = 0
07:30:17 write(11, "* 32 EXISTS\r\n", 13) = 13
07:30:17 setsockopt(11, SOL_TCP, TCP_CORK, [0], 4) = 0
07:30:17 epoll_wait(9,  <unfinished ...>

(Nothing happened after this)

# 2.1.7: /etc/dovecot/dovecot.conf
# OS: Linux 3.9.2-x86_64-xxxxxx x86_64 Debian 7.3 
auth_mechanisms = plain login
log_timestamp = "%Y-%m-%d %H:%M:%S "
mail_fsync = never
mail_location = maildir:~/.maildir
mail_max_userip_connections = 666
mail_privileged_group = mail
passdb {
  driver = shadow
}
protocols = imap
service auth {
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
  user = root
}
service imap-login {
  inet_listener imap {
    address = 127.0.0.1
    port = 1434
  }
  process_limit = 10
  process_min_avail = 1
}
service imap {
  process_limit = 32
}
service pop3-login {
  process_limit = 10
  process_min_avail = 1
}
service pop3 {
  process_limit = 32
}
ssl = no
userdb {
  driver = passwd
}
protocol lda {
  postmaster_address = postmaster at dcvr.yhbt.net
}
-- 
Eric Wong

Quoting Eric Wong <normalperson at yhbt.net>:
> Hi, I'm not sure if this is some throttling/DoS protection or a bug.  I
> didn't see notice anything like it mentioned looking at the NEWS file
> from hg, this is on 2.1.7 on Debian stable.
>
> I have a client doing IDLE on INBOX.vomiteer.  When individual messages
> arrive with some time interval in between them, I get EXISTS events for
> each message as expected.
>
> However, when I store a bunch of messages at once (via tag + mass copy
> in mutt on a fast-ish connection), I get a few EXISTS events (sometimes
> one, sometimes two) even though I copied a lot of new messages over.
>
> I expected to get an EXISTS event for each message which arrived, but
> perhaps there's some sort of DoS/throttling mechanism.
This is correct IMAP behavior.  EXISTS is defined as enumerating the  
current number of messages in the mailbox.  Nowhere in the RFC does it  
say that a separate EXISTS is needed for every message added.

michael