Re: [Dovecot] Particular user post-login hang

2011-01-31 Thread Henry C.
On Mon, January 31, 2011 16:06, Timo Sirainen wrote:
> On 31.1.2011, at 13.50, Henry C. wrote:
>
>
 Rawlog looks good

>> ...
>>
 epoll_wait(0x8, 0x806c4f8, 0x6, 0x1b708d
>>>
>>> Dovecot is just waiting for more commands here.
>>>
>>>
>>> To me everything here points to a client problem.
>>>
>>
>> By client, I presume you're referring to the process which is talking to
>> imap (or some other process/intermediary)?
>
>> From imap process's point of view that would be the IMAP client. Or if it's
>> SSL connection then it's imap-login process that's proxying the SSL
>> traffic.
>
>> That'll be the imap-proxy.
>>
>
> Which proxy? Dovecot or something else?

up-imapproxy (http://squirrelmail.org/download.php#imap_proxy).

However, I tried bypassing the proxy completely and connected directly.  It
does the same thing.

>
>> Only problem is everything works flawlessly if I login with a different
>> user, using the same software/etc.
>
> Which client?

Squirrelmail - sorry should have mentioned that from the start.

What's odd is that this only seems to occur with this one particular login. 
Everything else I've tested with works fine.





Re: [Dovecot] Particular user post-login hang

2011-01-31 Thread Timo Sirainen
On 31.1.2011, at 13.50, Henry C. wrote:

>>> Rawlog looks good
> ...
>>> epoll_wait(0x8, 0x806c4f8, 0x6, 0x1b708d
>> 
>> Dovecot is just waiting for more commands here.
>> 
>> To me everything here points to a client problem.
> 
> By client, I presume you're referring to the process which is talking to
> imap (or some other process/intermediary)?

From imap process's point of view that would be the IMAP client. Or if it's SSL 
connection then it's imap-login process that's proxying the SSL traffic.

>  That'll be the imap-proxy. 

Which proxy? Dovecot or something else?

> Only problem is everything works flawlessly if I login with a different
> user, using the same software/etc.

Which client?

Re: [Dovecot] Particular user post-login hang

2011-01-31 Thread Henry C.
> On 31.1.2011, at 13.15, Henry C. wrote:
>
>> In a nutshell:  User authenticates OK, then the imap process hangs.
>
> imap process, or the client?..

Thanks for the quick feedback.

The imap process is waiting on the event poll, so I suppose it's not
really hung.  Who/what process is talking on the other end?  I can then do
some more scratching around...

>
>> Rawlog looks good
...
>> epoll_wait(0x8, 0x806c4f8, 0x6, 0x1b708d
>
> Dovecot is just waiting for more commands here.
>
> To me everything here points to a client problem.

By client, I presume you're referring to the process which is talking to
imap (or some other process/intermediary)?  That'll be the imap-proxy. 
Only problem is everything works flawlessly if I login with a different
user, using the same software/etc.

Thanks




Re: [Dovecot] Particular user post-login hang

2011-01-31 Thread Timo Sirainen
On 31.1.2011, at 13.15, Henry C. wrote:

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

imap process, or the client?..

> Rawlog looks good:
> 
> IN:
> A008 UID FETCH 2533:2588 (FLAGS BODY.PEEK[HEADER.FIELDS (RECEIVED)])
> 
> A008 OK Fetch completed.

So Dovecot answered all commands.

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

According to rawlog there's nothing more for Dovecot to do.

> 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

Dovecot is just waiting for more commands here.

To me everything here points to a client problem.

[Dovecot] Particular user post-login hang

2011-01-31 Thread Henry C.
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: AUTH1   PLAIN   service=imapsecured
lip=127.0.0.1   rip=127.0.0.1   lport=144   rport=41641 resp=
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=usernameuid=17286   gid=300
home=/home/mailusers/username
imap-login: Info: Login: user=, 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 : 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=0xfffc)
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�\006\bp�\006\b\200�\006\b\b"
username = 0x0
c = -4
(gdb)



lsof shows:

COMMAND  PID  USER   FD   TYPE DEVICE SIZE   NODE NAME
imap6574 username  cwdDIR9,0 4096   30130787
/home2/home/mailusers/username
imap6574 username  rtdDIR3,1 4096  2 /
imap6574 username  txtREG9,0   941700   35836003
/home2/local/libexec/dovecot/imap
imap6574 username  memREG0,0   0 [heap] (stat:
No such file or directory)
imap6574 username  memREG9,0   109568   30130578
/home2/home/mailusers/username/.imap/INBOX/dovecot.index.cache
imap6574 username  memREG3,141351   13749135
/lib/tls/libnss_files-2.3.5.so
imap6574 username  memREG3,141583   13749137
/lib/tls/libnss_nis-2.3.5.so
imap6574 username  memREG3,192501   13749132
/lib/tls/libnsl-2.3.5.so
imap6574 username  memREG3,135866   13749133
/lib/tls/libnss_compat-2.3.5.so
imap6574 username  memREG3,187827   13749140
/lib/tls/libpthread-2.3.5.so
imap6574 username  memREG3,1  1366940   13749126
/lib/tls/libc-2.3.5.so
imap6574 username  memREG3,134582   13749142
/lib/tls/librt-2.3.5.so
imap6574 username  memREG3,113120   13749129
/lib/tls/libdl-2.3.5.so
imap6574 username  memREG9,0173806897709
/home2/home/mailusers/usernam