Bug#680363: marked as done (cyrus-imapd-2.2: imapd gets mad falling into endless loop)

[Debian Bug Tracking System]

Your message dated Wed, 11 Jul 2012 15:11:06 -0300
with message-id <20120711181106.gd4...@khazad-dum.debian.net>
and subject line Re: Bug#680363: cyrus-imapd-2.2: imapd gets mad falling into 
endless loop
has caused the Debian Bug report #680363,
regarding cyrus-imapd-2.2: imapd gets mad falling into endless loop
to be marked as done.

This means that you claim that the problem has been dealt with.
If this is not the case it is now your responsibility to reopen the
Bug report if necessary, and/or fix the problem forthwith.

(NB: If you are a system administrator and have no idea what this
message is talking about, this may indicate a serious mail system
misconfiguration somewhere. Please contact ow...@bugs.debian.org
immediately.)


-- 
680363: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=680363
Debian Bug Tracking System
Contact ow...@bugs.debian.org with problems

--- Begin Message ---

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

--- End Message ---

--- Begin Message ---

tag 680363 + unreproducible
thanks

On Wed, 11 Jul 2012, Kiss Gabor (Bitman) wrote:
> > > Actually I bet function wait4msg() in libraries/libldap/result.c
> > > in OpenLDAP calls ldap_int_select() in endless loop with
> > > zero timeout.
> > 
> > The strace output looked like there were pending events on fd 16 for the
> > select() call.  In that case, it will return immediately...
> 
> Actually I cannot debug it more because I had to replace libnss-ldap
> with libnss-ldapd. I'm really sorry. Thanks for your efforts.

I am always too happy to see someone ditch libnss-ldap for *anything* else,
even if it is only libnss-ldapd, so don't worry about it :-)

I will close the bug as unreproducible for now.  If someone hits it and
decides to debug it further, *especially* if it hits in wheezy, we can just
reopen it.

-- 
  "One disk to rule them all, One disk to find them. One disk to bring
  them all and in the darkness grind them. In the Land of Redmond
  where the shadows lie." -- The Silicon Valley Tarot
  Henrique Holschuh

--- End Message ---