[Dovecot] Particular user post-login hang

Henry C. henka at cityweb.co.za
Mon Jan 31 13:15:53 EET 2011


Greets,

I'm using dovecot 2.0.9 (also tried rolling back to 2.0.8 which does the same
- the output below is from 2.0.8), and this problem is imap specific.
The following is a recurring problem with a specific user - as far as we can
tell, other users are working just fine (there are thousands); but I bet there
are others.

In a nutshell:  User authenticates OK, then the imap process hangs.

It's almost as if something in the user's inbox is causing the problem, since
if I clear all emails (and cache), then things work fine.  The user will then
receive emails OK for some random period (maybe a few days) and be able to
read/write OK via imap, and the problem will re-occur.

The debug output shows nothing untoward:

auth: Debug: auth client connected (pid=20774)
auth: Debug: client in: AUTH    1   PLAIN   service=imap    secured
lip=127.0.0.1   rip=127.0.0.1   lport=144   rport=41641 resp=<hidden>
auth: Debug: shadow(username,127.0.0.1): lookup
auth: Debug: client out: OK 1   user=username
auth: Debug: master in: REQUEST 1938161665  20774   1  
238230058d076a9af1cd4405244d33ba
auth: Debug: passwd(username,127.0.0.1): lookup
auth: Debug: master out: USER   1938161665  username  
system_groups_user=username    uid=17286   gid=300
home=/home/mailusers/username
imap-login: Info: Login: user=<username>, method=PLAIN, rip=127.0.0.1,
lip=127.0.0.1, mpid=20775, secured
imap(username): Debug: Effective uid=17286, gid=300,
home=/home/mailusers/username
imap(username): Debug: fs: root=/home/mailusers/username/., index=, control=,
inbox=/var/mail/username


Rawlog looks good:

IN:
A002 CAPABILITY
A003 NAMESPACE
C64 EXAMINE ""
A002 STATUS "INBOX" (MESSAGES UNSEEN RECENT)
A003 SELECT "INBOX"
A004 EXPUNGE
A005 SELECT "INBOX"
A006 EXPUNGE
A007 UID SEARCH UNSEEN
A008 UID FETCH 2533:2588 (FLAGS BODY.PEEK[HEADER.FIELDS (RECEIVED)])

OUT:
...
* 15 FETCH (UID 2536 FLAGS () BODY[HEADER.FIELDS (RECEIVED)] {944}
...
* 67 FETCH (UID 2588 FLAGS () BODY[HEADER.FIELDS (RECEIVED)] {945}
...
A008 OK Fetch completed.


It's at this point that nothing happens for a short while and the user gets a
blank screen.

I tried running it through gdb (ie, "Talk IMAP Directly" - as described at
http://dovecot.org/bugreport.html), but that fails with "Cannot find
user-level thread for LWP nnnn: generic error", which is probably specific to
our old box/installation.


strace hangs with:

Process 6574 attached - interrupt to quit
gettimeofday({1296472202, 318955}, NULL) = 0
gettimeofday({1296472202, 319073}, NULL) = 0
epoll_wait(0x8, 0x806c4f8, 0x6, 0x1b708d


gdb backtrace gives:

0xb7e2bff9 in epoll_wait () from /lib/tls/libc.so.6
(gdb) bt full
#0  0xb7e2bff9 in epoll_wait () from /lib/tls/libc.so.6
No symbol table info available.
#1  0xb7eed4eb in io_loop_handler_run (ioloop=0x806c390) at ioloop-epoll.c:181
	ctx = (struct ioloop_handler_context *) 0x806c4b8
	list = (struct io_list *) 0x8082850
	io = (struct io_file *) 0x806c4f8
	tv = {tv_sec = 1696, tv_usec = 510098}
	msecs = 8
	ret = -1
	i = 0
	j = -1208929836
	call = 8
#2  0xb7eec249 in io_loop_run (ioloop=0x806c390) at ioloop.c:404
No locals.
#3  0xb7ed8e15 in master_service_run (service=0x806c2e0, callback=0xfffffffc)
at master-service.c:484
No locals.
#4  0x0805ee75 in main (argc=1, argv=0x806c1d8) at main.c:375
	set_roots = {0x8061d80, 0x0}
	service_flags = 6
	storage_service_flags = MAIL_STORAGE_SERVICE_FLAG_DISALLOW_ROOT
	postlogin_socket_path = 0x806c2e0
"\220&#65533;\006\bp&#65533;\006\b\200&#65533;\006\b\b"
	username = 0x0
	c = -4
(gdb)



lsof shows:

COMMAND  PID      USER   FD   TYPE     DEVICE     SIZE       NODE NAME
imap    6574 username  cwd    DIR        9,0     4096   30130787
/home2/home/mailusers/username
imap    6574 username  rtd    DIR        3,1     4096          2 /
imap    6574 username  txt    REG        9,0   941700   35836003
/home2/local/libexec/dovecot/imap
imap    6574 username  mem    REG        0,0                   0 [heap] (stat:
No such file or directory)
imap    6574 username  mem    REG        9,0   109568   30130578
/home2/home/mailusers/username/.imap/INBOX/dovecot.index.cache
imap    6574 username  mem    REG        3,1    41351   13749135
/lib/tls/libnss_files-2.3.5.so
imap    6574 username  mem    REG        3,1    41583   13749137
/lib/tls/libnss_nis-2.3.5.so
imap    6574 username  mem    REG        3,1    92501   13749132
/lib/tls/libnsl-2.3.5.so
imap    6574 username  mem    REG        3,1    35866   13749133
/lib/tls/libnss_compat-2.3.5.so
imap    6574 username  mem    REG        3,1    87827   13749140
/lib/tls/libpthread-2.3.5.so
imap    6574 username  mem    REG        3,1  1366940   13749126
/lib/tls/libc-2.3.5.so
imap    6574 username  mem    REG        3,1    34582   13749142
/lib/tls/librt-2.3.5.so
imap    6574 username  mem    REG        3,1    13120   13749129
/lib/tls/libdl-2.3.5.so
imap    6574 username  mem    REG        9,0    17380    6897709
/home2/home/mailusers/username/.imap/INBOX/dovecot.index.log
imap    6574 username  mem    REG        9,0  1980063   35835914
/home2/local/lib/dovecot/libdovecot.so.0.0.0
imap    6574 username  mem    REG        9,0  4911010   35835915
/home2/local/lib/dovecot/libdovecot-storage.so.0.0.0
imap    6574 username  mem    REG        3,1    27274     654816
/lib/libsafe.so.2.0.16
imap    6574 username  mem    REG        3,1    99790     654754 /lib/ld-2.3.5.so
imap    6574 username    0w   CHR        1,3              327760 /dev/null
imap    6574 username    1w   CHR        1,3              327760 /dev/null
imap    6574 username    2w  FIFO        0,5          1548069248 pipe
imap    6574 username    3w  FIFO        0,5          1548064788 pipe
imap    6574 username    4r  FIFO        0,5          1548414049 pipe
imap    6574 username    5w  FIFO        0,5          1548069260 pipe
imap    6574 username    6u  unix 0xe481b180          1548069218
/usr/local/var/run/dovecot/login/imap
imap    6574 username    7w  FIFO        0,5          1548414049 pipe
imap    6574 username    8u  0000        0,6        0          9 unknown inode
type
imap    6574 username    9u   REG        9,0    17380    6897709
/home2/home/mailusers/username/.imap/INBOX/dovecot.index.log
imap    6574 username   10u  IPv4 1548412828                 TCP
localhost:144->localhost:38067 (ESTABLISHED)
imap    6574 username   11u   REG        9,0     2632   30130623
/home2/home/mailusers/username/.imap/INBOX/dovecot.index
imap    6574 username   12u   REG        9,0   109568   30130578
/home2/home/mailusers/username/.imap/INBOX/dovecot.index.cache
imap    6574 username   13u   REG        9,0 10472498    9257043
/home2/var/spool/mail/username




Any pointers?

Thanks
Henry



----------------------

CONFIG:
-------
auth_debug = yes
auth_mechanisms = plain login
default_login_user = nobody
first_valid_uid = 200
listen = *
log_path = /var/log/dovecot.log
mail_debug = yes
mail_location = mbox:~/.:INBOX=/var/mail/%u
passdb {
  driver = shadow
}
protocols = imap
service imap-login {
  inet_listener imap {
    port = 144     # 143 is for imap proxy
  }
}
ssl = no
userdb {
  driver = passwd
}




More information about the dovecot mailing list