[Dovecot] 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@dcvr.yhbt.net }
Eric Wong
Quoting Eric Wong <normalperson@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
participants (2)
-
Eric Wong
-
Michael M Slusarz