Bug#680363: cyrus-imapd-2.2: imapd gets mad falling into endless loop
Gabor Kiss
kissg at ssg.ki.iif.hu
Thu Jul 5 11:04:31 UTC 2012
Package: cyrus-imapd-2.2
Version: 2.2.13-19+squeeze3
Severity: normal
I'm migrating some 40 IMAP users to a new server.
I found that "imapd -s" processes are proliferating and produce high load.
Strace shows that they call poll() continously:
12:40:01.934613 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
12:40:01.934915 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
12:40:01.935024 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
12:40:01.935127 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
12:40:01.935231 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
12:40:01.935330 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
12:40:01.935430 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
12:40:01.935530 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
12:40:01.935630 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
I could catch the moment when an imapd gets mad:
14862 write(16, "\27\3\1\0\2738\276\303\7d\216\274\r\274\303]Z\253\203\217\214\2
51\200\206\240\375\23\371\2109\\\367"..., 192) = 192
14862 time(NULL) = 1341478919
14862 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16
, revents=POLLIN}])
14862 read(16, "\25\3\1\0\26", 5) = 5
14862 read(16, "<\t\357Rp\321\324\331;\206\255v\217\360\20\355\305\271\273U\260\
302", 22) = 22
14862 gettimeofday({1341478919, 642090}, NULL) = 0
14862 getrusage(RUSAGE_SELF, {ru_utime={0, 548034}, ru_stime={0, 124007}, ...}) = 0
14862 time(NULL) = 1341478919
14862 times({tms_utime=54, tms_stime=12, tms_cutime=0, tms_cstime=0}) = 1862420508
14862 gettimeofday({1341478919, 642386}, NULL) = 0
14862 getrusage(RUSAGE_SELF, {ru_utime={0, 548034}, ru_stime={0, 124007}, ...}) = 0
14862 time(NULL) = 1341478919
14862 times({tms_utime=54, tms_stime=12, tms_cutime=0, tms_cstime=0}) = 1862420508
14862 time(NULL) = 1341478919
14862 send(5, "<83>Jul 5 11:01:59 cyrus/imaps2"..., 104, MSG_NOSIGNAL) = 104
14862 rt_sigaction(SIGPIPE, {SIG_IGN, [], SA_RESTART}, NULL, 8) = 0
14862 close(15) = 0
14862 munmap(0xb5025000, 4096) = 0
14862 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], SA_RESTART}, 8) = 0
14862 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
14862 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
14862 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
14862 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
14862 poll([{fd=16, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, -1) = 1 ([{fd=16, revents=POLLIN|POLLERR|POLLHUP}])
Its log entries before I killed them manually:
Jul 5 11:01:59 strudel cyrus/imaps2[14862]: accepted connection
Jul 5 11:01:59 strudel cyrus/imaps2[14862]: mydelete: starting txn 2147486956
Jul 5 11:01:59 strudel cyrus/imaps2[14862]: mydelete: committing txn 2147486956
Jul 5 11:01:59 strudel cyrus/imaps2[14862]: mystore: starting txn 2147486957
Jul 5 11:01:59 strudel cyrus/imaps2[14862]: mystore: committing txn 2147486957
Jul 5 11:01:59 strudel cyrus/imaps2[14862]: starttls: TLSv1 with cipher AES256-
SHA (256/256 bits new) no authentication
ltrace -S shows a bit more:
21814 getgrent( <unfinished ...>
21814 <... getgrent resumed> ) = 0xb7262b64
21814 getgrent( <unfinished ...>
21814 <... getgrent resumed> ) = 0xb7262b64
21814 getgrent( <unfinished ...>
21814 <... getgrent resumed> ) = 0xb7262b64
21814 getgrent( <unfinished ...>
21814 <... getgrent resumed> ) = 0xb7262b64
21814 getgrent( <unfinished ...>
21814 <... getgrent resumed> ) = 0xb7262b64
21814 getgrent( <unfinished ...>
21814 SYS_read(15, "", 1024) = 0
21814 SYS_rt_sigaction(13, 0xbf8a7180, 0xbf8a70f4, 8, 0xb7260ff4 <unfinished ...>
21814 <... SYS_rt_sigaction resumed> ) = 0
21814 SYS_rt_sigaction(13, 0xbf8a7220, 0, 8, 0xb7260ff4 <unfinished ...>
21814 <... SYS_rt_sigaction resumed> ) = 0
21814 SYS_rt_sigaction(13, 0xbf8a7150, 0xbf8a70c4, 8, 0xb7260ff4) = 0
21814 SYS_stat64(0xb4e364f6, 0xbf8a58ac, 0xb7260ff4, 3, 0xbf8a5938 <unfinished ...>
21814 <... SYS_stat64 resumed> ) = 0
21814 SYS_geteuid32(0xb4e371f4, 0x4fed83fc, 0x4fb505ee, 0xb4e38614, 0xb4e2d9f0 <unfinished ...>
21814 <... SYS_geteuid32 resumed> ) = 114
21814 SYS_socketcall(6, 0xbf8a5860, 0xb4e371f4, 0xbf8a69dc, 0xbf8a58f8) = 0
21814 SYS_socketcall(7, 0xbf8a5860, 0xb4e371f4, 0xbf8a69dc, 0xbf8a5878 <unfinished ...>
21814 <... SYS_socketcall resumed> ) = 0
21814 SYS_stat64(0xb4e364f6, 0xbf8a581c, 0xb7260ff4, 3, 0xbf8a58a8 <unfinished ...>
21814 <... SYS_stat64 resumed> ) = 0
21814 SYS_geteuid32(0xb4e371f4, 0x4fed83fc, 0x4fb505ee, 0xb4e37894, 0) = 114
21814 SYS_socketcall(6, 0xbf8a57d0, 0xb4e371f4, 0xbf8a694c, 0xbf8a5868) = 0
21814 SYS_socketcall(7, 0xbf8a57d0, 0xb4e371f4, 0xbf8a694c, 0xbf8a57e8) = 0
21814 SYS_time(0, 0xb5006818, 0, 0x824f5b8, 0x8274a98 <unfinished ...>
21814 <... SYS_time resumed> ) = 0x4ff57263
21814 SYS_gettimeofday(0xbf8a62f4, NULL <unfinished ...>
21814 <... SYS_gettimeofday resumed> ) = 0
21814 SYS_getrusage(0, 0xbf8a62ac, 0xb4f0dad4, 0xbf8a62ac, 0xbf8a62ac) = 0
21814 SYS_time(0, 0xb4f0dad4, 0, 0xbf8a62fc, 0xbf8a62f4 <unfinished ...>
21814 <... SYS_time resumed> ) = 0x4ff57263
21814 SYS_times(0xbf8a625c, 0xb7260ff4, 0xbf8a625c, 100, 0xbf8a62f4 <unfinished ...>
21814 <... SYS_times resumed> ) = 0x6f0c943a
21814 SYS_gettimeofday(0xbf8a6274, NULL) = 0
21814 SYS_getrusage(0, 0xbf8a622c, 0xb4f0dad4, 0xbf8a622c, 0xbf8a622c <unfinished ...>
21814 <... SYS_getrusage resumed> ) = 0
21814 SYS_time(0, 0xb4f0dad4, 0, 0xbf8a627c, 0xbf8a6274 <unfinished ...>
21814 <... SYS_time resumed> ) = 0x4ff57263
21814 SYS_times(0xbf8a61dc, 0xb7260ff4, 0xbf8a61dc, 100, 0xbf8a6274) = 0x6f0c943a
21814 SYS_write(16, "\027\003\001", 192 <unfinished ...>
21814 <... SYS_write resumed> ) = 192
21814 SYS_time(0, 0xb4e371f4, 0xb4e373c8, 0xb4e37580, 0 <unfinished ...>
21814 <... SYS_time resumed> ) = 0x4ff57263
21814 SYS_poll(0x08284cc4, 1, -1) = 1
21814 SYS_read(16, <unfinished ...>
21814 <... SYS_read resumed> "\025\003\001", 5) = 5
21814 SYS_read(16, <unfinished ...>
21814 <... SYS_read resumed> ""Sfc\366\346\275a\036\254{\370\247V\016\004Kv\374\240\340s", 22) = 22
21814 SYS_gettimeofday(0xbf8a6b54, NULL) = 0
21814 SYS_getrusage(0, 0xbf8a6b0c, 0xb4f0dad4, 0xbf8a6b0c, 0xbf8a6b0c <unfinished ...>
21814 <... SYS_getrusage resumed> ) = 0
21814 SYS_time(0, 0xb4f0dad4, 0, 0xbf8a6b5c, 0xbf8a6b54 <unfinished ...>
21814 <... SYS_time resumed> ) = 0x4ff57263
21814 SYS_times(0xbf8a6abc, 0xb7260ff4, 0xbf8a6abc, 100, 0xbf8a6b54) = 0x6f0c943a
21814 SYS_gettimeofday(0xbf8a6ad4, NULL <unfinished ...>
21814 <... SYS_gettimeofday resumed> ) = 0
21814 SYS_getrusage(0, 0xbf8a6a8c, 0xb4f0dad4, 0xbf8a6a8c, 0xbf8a6a8c <unfinished ...>
21814 <... SYS_getrusage resumed> ) = 0
21814 SYS_time(0, 0xb4f0dad4, 0, 0xbf8a6adc, 0xbf8a6ad4) = 0x4ff57263
21814 SYS_times(0xbf8a6a3c, 0xb7260ff4, 0xbf8a6a3c, 100, 0xbf8a6ad4 <unfinished ...>
21814 <... SYS_times resumed> ) = 0x6f0c943a
21814 SYS_time(0, 0xb7260ff4, 0xbf8a7170, 0xbf8a7170, 0x8251360 <unfinished ...>
21814 <... SYS_time resumed> ) = 0x4ff57263
21814 SYS_socketcall(9, 0xbf8a70e8, 0xb7260ff4, 20, 0x8251360) = 104
21814 SYS_rt_sigaction(13, 0xbf8a71f0, 0, 8, 0xb7260ff4 <unfinished ...>
21814 <... SYS_rt_sigaction resumed> ) = 0
21814 <... getgrent resumed> ) = NULL
21814 endgrent( <unfinished ...>
21814 SYS_close(15) = 0
21814 SYS_munmap(0xb5009000, 4096 <unfinished ...>
21814 <... SYS_munmap resumed> ) = 0
21814 SYS_rt_sigaction(13, 0xbf8a7238, 0xbf8a71ac, 8, 0xb7260ff4 <unfinished ...>
21814 <... SYS_rt_sigaction resumed> ) = 0
21814 SYS_poll(0x08284cc4, 1, -1) = 1
21814 SYS_poll(0x08284cc4, 1, -1 <unfinished ...>
21814 <... SYS_poll resumed> ) = 1
21814 SYS_poll(0x08284cc4, 1, -1 <unfinished ...>
21814 <... SYS_poll resumed> ) = 1
21814 SYS_poll(0x08284cc4, 1, -1) = 1
21814 SYS_poll(0x08284cc4, 1, -1 <unfinished ...>
21814 <... SYS_poll resumed> ) = 1
21814 SYS_poll(0x08284cc4, 1, -1 <unfinished ...>
21814 <... SYS_poll resumed> ) = 1
21814 SYS_poll(0x08284cc4, 1, -1) = 1
21814 SYS_poll(0x08284cc4, 1, -1 <unfinished ...>
21814 <... SYS_poll resumed> ) = 1
21814 SYS_poll(0x08284cc4, 1, -1 <unfinished ...>
21814 <... SYS_poll resumed> ) = 1
21814 SYS_poll(0x08284cc4, 1, -1) = 1
21814 SYS_poll(0x08284cc4, 1, -1 <unfinished ...>
21814 <... SYS_poll resumed> ) = 1
21814 SYS_poll(0x08284cc4, 1, -1 <unfinished ...>
21814 <... SYS_poll resumed> ) = 1
21814 SYS_poll(0x08284cc4, 1, -1) = 1
The critical point is somewhere after of retrieving UNIX group informations
when a new user logs in.
Gabor
-- System Information:
Debian Release: 6.0.5
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'proposed-updates'), (500, 'stable')
Architecture: i386 (i686)
Kernel: Linux 2.6.32-5-686 (SMP w/4 CPU cores)
Locale: LANG=C, LC_CTYPE=C (charmap=ANSI_X3.4-1968)
Shell: /bin/sh linked to /bin/dash
Versions of packages cyrus-imapd-2.2 depends on:
ii cyru 2.2.13-19+squeeze3 Cyrus mail system - common files
ii liba 1.4.0~git20100726.dfsg.1-2+squeeze1 Heimdal Kerberos - ASN.1 library
ii libc 2.11.3-4 Embedded GNU C Library: Shared lib
ii libc 1.41.12-4stable1 common error description library
ii libd 4.7.25-9 Berkeley v4.7 Database Libraries [
ii libg 1.4.0~git20100726.dfsg.1-2+squeeze1 Heimdal Kerberos - GSSAPI support
ii libk 1.4.0~git20100726.dfsg.1-2+squeeze1 Heimdal Kerberos - libraries
ii libr 1.4.0~git20100726.dfsg.1-2+squeeze1 Heimdal Kerberos - roken support l
ii libs 2.1.23.dfsg1-7 Cyrus SASL - authentication abstra
ii libs 0.9.8o-4squeeze13 SSL shared libraries
ii libw 7.6.q-19 Wietse Venema's TCP wrappers libra
cyrus-imapd-2.2 recommends no packages.
cyrus-imapd-2.2 suggests no packages.
-- Configuration Files:
/etc/pam.d/imap changed [not included]
-- no debconf information
More information about the Pkg-Cyrus-imapd-Debian-devel
mailing list