Hi Cyrus Experts,
Back on September 4, 2001, there was a discussion on this list about a locking
problem in Cyrus 2.0.16 where an imapd process would get a lock on a seen file
and not release it an all other attempts to access that mailbox either via imapd
or lmptd would await the lock. There was a another post about some workaround
scripts on 10/24, but I never saw a posting if anyone found the root cause.
I have a server sitting in this situation right now and I was wondering if there
was anything I could do to help debug this problem.
from gdb, the backtrace on the offending imapd process (PID 3098) is:
--------------------------------------------------------------------------------
(gdb) bt
#0 0x4028a8a1 in __flock () from /lib/libc.so.6
#1 0x807b293 in lock_reopen ()
#2 0x807cf63 in starttxn_or_refetch ()
#3 0x807d0d5 in myfetch ()
#4 0x807d175 in fetchlock ()
#5 0x8070e1e in seen_readit ()
#6 0x8070fbc in seen_lockread ()
#7 0x8061b1a in append_addseen ()
#8 0x806051d in append_commit ()
#9 0x805a1a0 in index_copy ()
#10 0x80532bb in cmd_copy ()
#11 0x804d9a1 in cmdloop ()
#12 0x804d09d in service_main ()
#13 0x804bd00 in main ()
#14 0x401d2f31 in __libc_start_main (main=0x804b8fc <main>, argc=1,
ubp_av=0xbffffe14, init=0x804a9e4 <_init>, fini=0x807fedc <_fini>,
rtld_fini=0x4000e274 <_dl_fini>, stack_end=0xbffffe0c)
at ../sysdeps/generic/libc-start.c:129
--------------------------------------------------------------------------------
All the other blocked imapd processes show the following
--------------------------------------------------------------------------------
(gdb) bt
#0 0x4028a8a1 in __flock () from /lib/libc.so.6
#1 0x807b377 in lock_blocking ()
#2 0x8062fa7 in mailbox_lock_index ()
#3 0x8059c6b in index_store ()
#4 0x8052c9e in cmd_store ()
#5 0x804ee2e in cmdloop ()
#6 0x804d09d in service_main ()
#7 0x804bd00 in main ()
#8 0x401d2f31 in __libc_start_main (main=0x804b8fc <main>, argc=1,
ubp_av=0xbffffe14, init=0x804a9e4 <_init>, fini=0x807fedc <_fini>,
rtld_fini=0x4000e274 <_dl_fini>, stack_end=0xbffffe0c)
at ../sysdeps/generic/libc-start.c:129
--------------------------------------------------------------------------------
Blocked lmtpd process back traces are similar
--------------------------------------------------------------------------------
gdb) bt
#0 0x4028a8a1 in __flock () from /lib/libc.so.6
#1 0x8073983 in lock_reopen ()
#2 0x80541ae in mailbox_lock_header ()
#3 0x8051545 in append_setup ()
#4 0x804d0c3 in deliver_mailbox ()
#5 0x804d6e7 in deliver ()
#6 0x804f6af in lmtpmode ()
#7 0x804b8b0 in service_main ()
#8 0x804b410 in main ()
#9 0x401d2f31 in __libc_start_main (main=0x804b00c <main>, argc=1,
ubp_av=0xbffffe14, init=0x804a350 <_init>, fini=0x80785cc <_fini>,
rtld_fini=0x4000e274 <_dl_fini>, stack_end=0xbffffe0c)
at ../sysdeps/generic/libc-start.c:129
--------------------------------------------------------------------------------
>From the imapd log
--------------------------------------------------------------------------------
Oct 24 20:31:53 romulan master[3098]: about to exec /usr/cyrus/bin/imapd
Oct 24 20:31:53 romulan service-imap[3098]: executed
Oct 24 20:31:53 romulan imapd[3098]: accepted connection
Oct 24 20:31:55 romulan imapd[3098]: login: occ10-2-134.oakton.edu[10.10.2.134]
gost9796 plaintext
Oct 24 20:31:55 romulan imapd[3098]: seen_db: user gost9796 opened /var/imap/use
r/g/gost9796.seen
Oct 24 20:31:55 romulan imapd[3098]: open: user gost9796 opened INBOX.Trash
Oct 24 20:36:25 romulan imapd[3098]: open: user gost9796 opened INBOX
Oct 24 20:36:25 romulan imapd[3098]: seen_db: user gost9796 opened /var/imap/use
r/g/gost9796.seen
--------------------------------------------------------------------------------
from an "lsof -p" of the errant process (PID 3098)
--------------------------------------------------------------------------------
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
imapd 3098 cyrus cwd DIR 8,11 4096 392002 /var/spool/imap/6/use
r/gost9796
imapd 3098 cyrus rtd DIR 8,1 4096 2 /
imapd 3098 cyrus txt REG 8,1 801951 212196 /usr/cyrus/bin/imapd
imapd 3098 cyrus mem REG 8,1 444843 634070 /lib/ld-2.2.so
imapd 3098 cyrus mem REG 8,1 187228 1122061 /usr/local/lib/libsas
l.so.7.1.8
imapd 3098 cyrus mem REG 8,1 45995 1004 /usr/local/lib/sasl/l
ibanonymous.so.1.0.15
imapd 3098 cyrus mem REG 8,1 47796 1008 /usr/local/lib/sasl/l
ibplain.so.1.0.14
imapd 3098 cyrus mem REG 8,15 8192 48313 /var/imap/db/__db.001
imapd 3098 cyrus mem REG 8,1 60598 634075 /lib/libdl-2.2.so
imapd 3098 cyrus mem REG 8,1 209759 976009 /usr/lib/libssl.so.0.
9.5a
imapd 3098 cyrus mem REG 8,1 865620 976008 /usr/lib/libcrypto.so
.0.9.5a
imapd 3098 cyrus mem REG 8,1 1564413 633989 /lib/libdb-3.1.so
imapd 3098 cyrus mem REG 8,1 243921 634089 /lib/libresolv-2.2.so
imapd 3098 cyrus mem REG 8,1 409599 634077 /lib/libnsl-2.2.so
imapd 3098 cyrus mem REG 8,1 5155229 634073 /lib/libc-2.2.so
imapd 3098 cyrus mem REG 8,1 83128 634074 /lib/libcrypt-2.2.so
imapd 3098 cyrus mem REG 8,1 33965 633991 /lib/libpam.so.0.72
imapd 3098 cyrus mem REG 8,15 270336 48509 /var/imap/db/__db.004
imapd 3098 cyrus mem REG 8,15 98304 48516 /var/imap/db/__db.003
imapd 3098 cyrus mem REG 8,15 11272192 48558 /var/imap/db/__db.002
imapd 3098 cyrus mem REG 8,15 24576 48564 /var/imap/db/__db.005
imapd 3098 cyrus mem REG 8,11 178 392004 /var/spool/imap/6/use
r/gost9796/cyrus.header
imapd 3098 cyrus mem REG 8,11 888 394636 /var/spool/imap/6/use
r/gost9796/cyrus.index
imapd 3098 cyrus mem REG 8,11 178 65547 /var/spool/imap/6/use
r/gost9796/Trash/cyrus.header
imapd 3098 cyrus mem REG 8,1 251005 634084 /lib/libnss_files-2.2
.so
imapd 3098 cyrus mem REG 8,1 310594 634087 /lib/libnss_nisplus-2
.2.so
imapd 3098 cyrus mem REG 8,1 294539 634086 /lib/libnss_nis-2.2.s
o
imapd 3098 cyrus mem REG 8,1 68049 634083 /lib/libnss_dns-2.2.s
o
imapd 3098 cyrus mem REG 8,11 18824 394643 /var/spool/imap/6/use
r/gost9796/cyrus.cache
imapd 3098 cyrus mem REG 8,11 108 65281 /var/spool/imap/6/use
r/gost9796/Trash/cyrus.index
imapd 3098 cyrus mem REG 8,11 932 65282 /var/spool/imap/6/use
r/gost9796/Trash/cyrus.cache
imapd 3098 cyrus 0u IPv4 5448713 TCP romulan.oakton.edu:im
ap2->occ10-2-134.oakton.edu:1162 (CLOSE_WAIT)
imapd 3098 cyrus 1u IPv4 5448713 TCP romulan.oakton.edu:im
ap2->occ10-2-134.oakton.edu:1162 (CLOSE_WAIT)
imapd 3098 cyrus 2u IPv4 5448713 TCP romulan.oakton.edu:im
ap2->occ10-2-134.oakton.edu:1162 (CLOSE_WAIT)
imapd 3098 cyrus 3w FIFO 0,0 964 pipe
imapd 3098 cyrus 4u IPv4 963 TCP *:imap2 (LISTEN)
imapd 3098 cyrus 5u REG 8,15 893770 48501 /var/imap/db/log.0000
000004
imapd 3098 cyrus 6r REG 8,1 940 422678 /etc/cyrus.conf
imapd 3098 cyrus 7r REG 8,1 940 422678 /etc/cyrus.conf
imapd 3098 cyrus 8r REG 8,1 940 422678 /etc/cyrus.conf
imapd 3098 cyrus 9r REG 8,15 893770 48501 /var/imap/db/log.0000
000004
imapd 3098 cyrus 10u REG 8,15 6717440 28 /var/imap/mailboxes.d
b
imapd 3098 cyrus 11u unix 0xe7398b00 5448712 socket
imapd 3098 cyrus 12u REG 8,15 59 32538 /var/imap/proc/3098
imapd 3098 cyrus 13u unix 0xe7398840 5448714 socket
imapd 3098 cyrus 14u REG 8,11 178 392004 /var/spool/imap/6/use
r/gost9796/cyrus.header
imapd 3098 cyrus 15u REG 8,11 888 394636 /var/spool/imap/6/use
r/gost9796/cyrus.index
imapd 3098 cyrus 16u REG 8,11 18824 394643 /var/spool/imap/6/use
r/gost9796/cyrus.cache
imapd 3098 cyrus 17u REG 8,15 114 177106 /var/imap/user/g/gost
9796.seen.NEW (deleted)
imapd 3098 cyrus 18u REG 8,11 178 65547 /var/spool/imap/6/use
r/gost9796/Trash/cyrus.header
imapd 3098 cyrus 19u REG 8,11 108 65281 /var/spool/imap/6/use
r/gost9796/Trash/cyrus.index
imapd 3098 cyrus 20u REG 8,11 932 65282 /var/spool/imap/6/use
r/gost9796/Trash/cyrus.cache
imapd 3098 cyrus 21u REG 8,15 122 177253 /var/imap/user/g/gost
9796.seen.NEW (deleted)
imapd 3098 cyrus 22u REG 8,15 15 64358 /var/imap/quota/g/use
r.gost9796.NEW (deleted)
imapd 3098 cyrus 25u REG 8,15 15 65101 /var/imap/quota/g/use
r.gost9796
--------------------------------------------------------------------------------
>From this I would read that the problem occured updating the seen file after
doing a message copy from one mailbox to another, probably using Netscape
Communicator's "move to trash" feature. This is still sitting out there (7 days
later.) Is there any other info I can pull off of this before I try to get
this user's mailbox back in service?
Other relevant info:
Redhat 7.0 (2.2.19 kernel) using:
Cyrus 2.0.16
SASL 1.5.24 (from source)
Berkeley DB 3.1.17-5 (redhat rpm)
Authentication via LDAP
openLDAP 1.2.11-15 (redhat RPM)
using a hacked version of LDAP pwcheck from
http://www.linc-dev.com/Files/pwcheck_ldap.c.txt
MTA is
qmail-1.03
managed by daemontools-0.76
with tcpserver from ucspi-tcp-0.88
Qmail calls Cyrus's deliver through a shell script.
Thanks in advance,
John Wade
