Response delay following APPEND for Entourage (SSL?)
michael_moore at csnw.com
michael_moore at csnw.com
Thu Sep 11 01:38:37 EDT 2003
We run a Cyrus IMAP server (2.1.14) for about 150 users with most of our
client systems using Mulberry or Apple Mail. We have a small number of
Entourage (for Mac) users who have been reporting problems with Entourage
getting hung up on network operations while filing sent messages in
"INBOX.Sent" and with these messages remaining in their local "Sent"
mailbox under Entourage.
This only happens intermittently (perhaps less than 5% of the time for
these Entourage users). The issue may also be limited to users using SSL
connections.
My first reaction was "Oh, what evil protocol violation is Entourage up to
now," but logging Entourage's connections to the server by one of the users
and observing the problem seems to show that Cyrus IMAP server is not
reporting the completion of the append operation.
When it occurs, I can see in the Cyrus IMAP log (under
log/{username}/{pid}) that:
- the client issued an append command setting the "SEEN" flag.
- the server indicates "+ go ahead"
- the client sends the data of the message followed by a newline.
I have verified that the data in the log file following the append
command and go-ahead and excluding timestamps is always exactly the
data length indicated within the curly braces in the append command
plus one (for the following newline).
- there is no further activity in the log file for some time
(10 minutes to an hour)
- the log then shows the "OK" result and indicates "connection reset by
peer"
I have provided an edited example below, labeled "log".
My presumption is that the client is is spending all of the time following
sending the message data waiting for the response from the server and
unwilling to issue additional commands on this IMAP session until it
receieves a response. I believe that the the client subsequently closes the
connection (due to a timeout or due to the using forcing the client
application to quit) and this is causing the server to issue the command
response at that time.
Even though I'm not competent to know what additional information may be
useful, I've attached a gdb backtrace and lsof of the process while it is
in this long delay. I've also attached a heavily editied strace from the
time of the delay, which seems to indicate that a read from the SSL stream
is in progress. Please let me know if I should be looking for other
information when I have the chance to see the problem in progress.
Any advice would be appreciated. I'm not sure where to look next to find a
resolution to the problem.
Thanks,
Michael Moore
michael_moore at csnw.com
Director of MIS
Computer Stores Northwest
------
log
------
<1063128144<A005 APPEND "INBOX.Sent" (\SEEN) {8155}
>1063128144>+ go ahead
<1063128145<User-Agent: Microsoft-Entourage/10.0.0.1309
Date: Tue, 09 Sep 2003 10:20:06 -0700
Subject: Re: Staff Meeting Followup
...more header and message content...
</BODY>
</HTML>
--B_3145947641_5425191--
>1063141860>* 851 EXISTS
* 2 RECENT
A005 OK [APPENDUID 1043354644 1839] Completed
* BYE Connection reset by peer
------
gdb backtrace
------
(gdb) bt
#0 0x40283f14 in __libc_read () from /lib/libc.so.6
#1 0x4011cd94 in __DTOR_END__ () from /usr/lib/libcrypto.so.0
#2 0xdf442710 in ?? ()
Cannot access memory at address 0x317
------
lsof
------
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
imapd 18458 mail cwd DIR 9,4 16384 1860494
/var/imap/mail/user/USERNAME/Sent
imapd 18458 mail rtd DIR 9,1 4096 2 /
imapd 18458 mail txt REG 9,1 1675755 208956
/usr/cyrus/bin/imapd
imapd 18458 mail mem REG 9,1 432647 428
/lib/ld-2.2.3.so
imapd 18458 mail mem REG 9,1 258734 97607
/usr/local/lib/libsasl2.so.2.0.12
imapd 18458 mail mem REG 9,4 185 1860515
/var/imap/mail/user/USERNAME/Sent/cyrus.header
imapd 18458 mail mem REG 9,1 72701 436
/lib/libdl-2.2.3.so
imapd 18458 mail mem REG 9,1 215453 161622
/usr/lib/libssl.so.0.9.5
imapd 18458 mail mem REG 9,1 920669 161623
/usr/lib/libcrypto.so.0.9.5
imapd 18458 mail mem REG 9,1 225681 449
/lib/libresolv-2.2.3.so
imapd 18458 mail mem REG 9,1 557952 244457
/usr/local/BerkeleyDB.3.3/lib/libdb-3.3.so
imapd 18458 mail mem REG 9,1 357644 439
/lib/libnsl-2.2.3.so
imapd 18458 mail mem REG 9,1 4783716 431
/lib/libc-2.2.3.so
imapd 18458 mail mem REG 9,1 111902 132549
/usr/local/lib/sasl2/libsasldb.so.2.0.12
imapd 18458 mail mem REG 9,1 81036 132553
/usr/local/lib/sasl2/libcrammd5.so.2.0.12
imapd 18458 mail mem REG 9,1 143899 132557
/usr/local/lib/sasl2/libdigestmd5.so.2.0.12
imapd 18458 mail mem REG 9,1 75564 132565
/usr/local/lib/sasl2/libplain.so.2.0.12
imapd 18458 mail mem REG 9,1 80453 432
/lib/libcrypt-2.2.3.so
imapd 18458 mail mem REG 9,1 74830 132569
/usr/local/lib/sasl2/libanonymous.so.2.0.12
imapd 18458 mail mem REG 9,4 262768 20
/var/imap/mailboxes.db
imapd 18458 mail mem REG 9,1 238649 443
/lib/libnss_files-2.2.3.so
imapd 18458 mail mem REG 9,1 75894 442
/lib/libnss_dns-2.2.3.so
imapd 18458 mail mem REG 9,4 95492 29
/var/imap/tls_sessions.db
imapd 18458 mail mem REG 9,4 44536 1861709
/var/imap/mail/user/USERNAME/Sent/cyrus.index
imapd 18458 mail mem DEL 9,4 865507
/var/imap/user/j/USERNAME.seen.NEW
imapd 18458 mail mem DEL 9,4 865510
/var/imap/user/j/USERNAME.seen.NEW
imapd 18458 mail mem REG 9,4 915292 1861711
/var/imap/mail/user/USERNAME/Sent/cyrus.cache
imapd 18458 mail 0u IPv4 117322612 TCP
mail.ourcompany.com:imaps->IP41-179.corp.ourcompany.com:49601 (ESTABLISHED)
imapd 18458 mail 1u IPv4 117322612 TCP
mail.ourcompany.com:imaps->IP41-179.corp.ourcompany.com:49601 (ESTABLISHED)
imapd 18458 mail 2u IPv4 117322612 TCP
mail.ourcompany.com:imaps->IP41-179.corp.ourcompany.com:49601 (ESTABLISHED)
imapd 18458 mail 3w FIFO 0,0 113490750 pipe
imapd 18458 mail 4u IPv4 113490749 TCP *:imaps
(LISTEN)
imapd 18458 mail 5u REG 9,4 262768 20
/var/imap/mailboxes.db
imapd 18458 mail 6u REG 9,4 0 669124
/var/imap/socket/imaps.lock
imapd 18458 mail 7u REG 9,4 85 179730
/var/imap/proc/18458
imapd 18458 mail 8u unix 0xd853d780 117322332 socket
imapd 18458 mail 9u REG 9,4 95492 29
/var/imap/tls_sessions.db
imapd 18458 mail 10w REG 9,4 21282 1746654
/var/imap/log/USERNAME/18458
imapd 18458 mail 11u REG 9,4 185 1860515
/var/imap/mail/user/USERNAME/Sent/cyrus.header
imapd 18458 mail 12u REG 9,4 44536 1861709
/var/imap/mail/user/USERNAME/Sent/cyrus.index
imapd 18458 mail 13u REG 9,4 915292 1861711
/var/imap/mail/user/USERNAME/Sent/cyrus.cache
imapd 18458 mail 14u REG 9,4 17 360318
/var/imap/quota/j/user.USERNAME.NEW (deleted)
imapd 18458 mail 15u REG 9,4 1505 865507
/var/imap/user/j/USERNAME.seen.NEW (deleted)
imapd 18458 mail 19u REG 9,4 1505 865510
/var/imap/user/j/USERNAME.seen.NEW (deleted)
------
strace
------
read(0, 0x8133e20, 5) = -1 ECONNRESET (Connection reset
by peer)
time([1063141860]) = 1063141860
getpid() = 18458
rt_sigaction(SIGPIPE, {0x4028d4f8, [], 0x4000000}, {SIG_IGN}, 8) = 0
send(8, "<180>Sep 9 14:11:00 imapd[18458"..., 80, 0) = 80
rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
time([1063141860]) = 1063141860
write(10, ">1063141860>", 12) = 12
write(10, "* 851 EXISTS\r\n* 2 RECENT\r\nA005 O"..., 105) = 105
write(1, "\27\3\0\0y\320\331U\326\223\5\21\326=\377@\16\227\243\333"...,
126) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) ---
close(7) = 0
munmap(0x40029000, 4096) = 0
unlink("/var/imap/proc/18458") = 0
flock(15, LOCK_EX|LOCK_NB) = 0
fstat(15, {st_mode=S_IFREG|0600, st_size=1505, ...}) = 0
stat("/var/imap/user/U/USERNAME.seen", {st_mode=S_IFREG|0600, st_size=1505,
...}) = 0
open("/var/imap/user/U/USERNAME.seen", O_RDWR) = 7
dup2(7, 15) = 15
close(7) = 0
flock(15, LOCK_EX|LOCK_NB) = 0
fstat(15, {st_mode=S_IFREG|0600, st_size=1505, ...}) = 0
stat("/var/imap/user/j/julie_satterwhite.seen", {st_mode=S_IFREG|0600,
st_size=1505, ...}) = 0
munmap(0x403a0000, 16384) = 0
old_mmap(NULL, 16384, PROT_READ, MAP_SHARED, 15, 0) = 0x403a0000
flock(15, LOCK_UN) = 0
munmap(0x403b2000, 16384) = 0
close(19) = 0
munmap(0x40392000, 57344) = 0
munmap(0x404f8000, 917504) = 0
close(11) = 0
munmap(0x4002a000, 185) = 0
close(12) = 0
munmap(0x40384000, 57344) = 0
close(13) = 0
munmap(0x40418000, 917504) = 0
close(14) = 0
shutdown(0, 0 /* receive */) = -1 ENOTCONN (Transport endpoint
is not connected)
close(0) = 0
shutdown(1, 0 /* receive */) = -1 ENOTCONN (Transport endpoint
is not connected)
close(1) = 0
shutdown(2, 0 /* receive */) = -1 ENOTCONN (Transport endpoint
is not connected)
close(2) = 0
close(10) = 0
... lots more ...
_exit(0) = ?
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: text/enriched
Size: 10179 bytes
Desc: not available
Url : https://lists.andrew.cmu.edu/mailman/private/info-cyrus/attachments/20030910/5ba606ce/attachment.bin
More information about the Info-cyrus
mailing list