Roundcube Community Forum

Release Support => Pending Issues => Topic started by: jjac on October 05, 2010, 07:02:54 PM

Title: inbox not populating at login
Post by: jjac on October 05, 2010, 07:02:54 PM
I've seen a few other threads about this around, and it usually seems to come down to config issues; but hopefully someone has some thoughts:

We upgraded to RC 0.4 and ever since then, people have been having issues where they don't have any messages listed after login.  If they wait a while, then click the inbox, the messages show up.  Also, once their info is all nicely cached, they have no problems seeing their messages.  These users don't even necessarily have that many messages; one guy just had the initial "welcome" message we send new users.

Our config:  Running RC 0.4, MySQL, connecting to Dovecot, using imapproxy on localhost.

Looking in the logs when the error happens, from immediately after the login success message:


roundcube: [05-Oct-2010 14:07:44 -0700]: S: * OK Dovecot ready.
roundcube: [05-Oct-2010 14:07:44 -0700]: C: a001 LOGIN "***@***" "***"
roundcube: [05-Oct-2010 14:07:44 -0700]: S: a001 OK User logged in
roundcube: [05-Oct-2010 14:07:44 -0700]: * OK Dovecot ready.
roundcube: [05-Oct-2010 14:07:44 -0700]: C: cp01 CAPABILITY
roundcube: [05-Oct-2010 14:07:44 -0700]: S: * CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS
roundcube: [05-Oct-2010 14:07:44 -0700]: S: cp01 OK Capability completed.
roundcube: [05-Oct-2010 14:07:44 -0700]: C: lsb LSUB "" "*"
roundcube: [05-Oct-2010 14:07:44 -0700]: S: * LSUB () "." "INBOX"
roundcube: [05-Oct-2010 14:07:44 -0700]: S: * LSUB () "." "Drafts"
roundcube: [05-Oct-2010 14:07:44 -0700]: S: * LSUB () "." "Sent"
roundcube: [05-Oct-2010 14:07:44 -0700]: S: * LSUB () "." "Junk"
roundcube: [05-Oct-2010 14:07:44 -0700]: S: * LSUB () "." "Trash"
roundcube: [05-Oct-2010 14:07:44 -0700]: S: lsb OK Lsub completed.
roundcube: [05-Oct-2010 14:07:44 -0700]: C: I LOGOUT
roundcube: [05-Oct-2010 14:07:48 -0700]: S: * OK Dovecot ready.
roundcube: [05-Oct-2010 14:07:48 -0700]: C: cp01 CAPABILITY
roundcube: [05-Oct-2010 14:07:48 -0700]: S: * CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS
roundcube: [05-Oct-2010 14:07:48 -0700]: S: cp01 OK Capability completed.
roundcube: [05-Oct-2010 14:07:48 -0700]: S: * OK Dovecot ready.
roundcube: [05-Oct-2010 14:07:48 -0700]: C: a001 LOGIN "***@***" "***"
roundcube: [05-Oct-2010 14:07:48 -0700]: C: sel1 SELECT "INBOX"
roundcube: [05-Oct-2010 14:07:48 -0700]: S: a001 OK User logged in
roundcube: [05-Oct-2010 14:07:48 -0700]: * OK Dovecot ready.
roundcube: [05-Oct-2010 14:07:48 -0700]: C: sel1 SELECT "INBOX"
roundcube: [05-Oct-2010 14:07:50 -0700]: S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent)
roundcube: [05-Oct-2010 14:07:50 -0700]: S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent \*)] Flags permitted.
roundcube: [05-Oct-2010 14:07:50 -0700]: S: * 20 EXISTS
roundcube: [05-Oct-2010 14:07:50 -0700]: S: * 1 RECENT
roundcube: [05-Oct-2010 14:07:50 -0700]: S: * OK [UNSEEN 20] First unseen.
roundcube: [05-Oct-2010 14:07:50 -0700]: S: * OK [UIDVALIDITY 1223538035] UIDs valid
roundcube: [05-Oct-2010 14:07:50 -0700]: S: * OK [UIDNEXT 138] Predicted next UID
roundcube: [05-Oct-2010 14:07:50 -0700]: S: sel1 OK [READ-WRITE] Select completed.
roundcube: [05-Oct-2010 14:07:50 -0700]: C: srch1 SEARCH ALL UNSEEN
roundcube: [05-Oct-2010 14:07:50 -0700]: S: * SEARCH 20
roundcube: [05-Oct-2010 14:07:50 -0700]: S: srch1 OK Search completed.
roundcube: [05-Oct-2010 14:07:50 -0700]: C: sel1 SELECT "Drafts"
roundcube: [05-Oct-2010 14:07:51 -0700]: S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
roundcube: [05-Oct-2010 14:07:51 -0700]: S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
roundcube: [05-Oct-2010 14:07:51 -0700]: S: * 1 EXISTS
roundcube: [05-Oct-2010 14:07:51 -0700]: S: * 0 RECENT
roundcube: [05-Oct-2010 14:07:51 -0700]: S: * OK [UIDVALIDITY 1223538043] UIDs valid
roundcube: [05-Oct-2010 14:07:51 -0700]: S: * OK [UIDNEXT 134] Predicted next UID
roundcube: [05-Oct-2010 14:07:51 -0700]: S: sel1 OK [READ-WRITE] Select completed.
roundcube: [05-Oct-2010 14:07:51 -0700]: C: srch1 SEARCH ALL UNSEEN
roundcube: [05-Oct-2010 14:07:51 -0700]: S: * SEARCH
roundcube: [05-Oct-2010 14:07:51 -0700]: S: srch1 OK Search completed.
roundcube: [05-Oct-2010 14:07:51 -0700]: C: sel1 SELECT "Sent"
roundcube: [05-Oct-2010 14:07:53 -0700]: S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
roundcube: [05-Oct-2010 14:07:53 -0700]: S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
roundcube: [05-Oct-2010 14:07:53 -0700]: S: * 12 EXISTS
roundcube: [05-Oct-2010 14:07:53 -0700]: S: * 0 RECENT
roundcube: [05-Oct-2010 14:07:53 -0700]: S: * OK [UIDVALIDITY 1223538045] UIDs valid
roundcube: [05-Oct-2010 14:07:53 -0700]: S: * OK [UIDNEXT 73] Predicted next UID
roundcube: [05-Oct-2010 14:07:53 -0700]: S: sel1 OK [READ-WRITE] Select completed.
roundcube: [05-Oct-2010 14:07:53 -0700]: C: srch1 SEARCH ALL UNSEEN
roundcube: [05-Oct-2010 14:07:53 -0700]: S: * SEARCH
roundcube: [05-Oct-2010 14:07:53 -0700]: S: srch1 OK Search completed.
roundcube: [05-Oct-2010 14:07:53 -0700]: C: sel1 SELECT "Junk"
roundcube: [05-Oct-2010 14:07:54 -0700]: S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
roundcube: [05-Oct-2010 14:07:54 -0700]: S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
roundcube: [05-Oct-2010 14:07:54 -0700]: S: * 0 EXISTS
roundcube: [05-Oct-2010 14:07:54 -0700]: S: * 0 RECENT
roundcube: [05-Oct-2010 14:07:54 -0700]: S: * OK [UIDVALIDITY 1223538051] UIDs valid
roundcube: [05-Oct-2010 14:07:54 -0700]: S: * OK [UIDNEXT 1] Predicted next UID
roundcube: [05-Oct-2010 14:07:54 -0700]: S: sel1 OK [READ-WRITE] Select completed.
roundcube: [05-Oct-2010 14:07:54 -0700]: C: sel1 SELECT "Trash"
roundcube: [05-Oct-2010 14:07:55 -0700]: S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent)
roundcube: [05-Oct-2010 14:07:55 -0700]: S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent \*)] Flags permitted.
roundcube: [05-Oct-2010 14:07:55 -0700]: S: * 182 EXISTS
roundcube: [05-Oct-2010 14:07:55 -0700]: S: * 0 RECENT
roundcube: [05-Oct-2010 14:07:55 -0700]: S: * OK [UIDVALIDITY 1223538053] UIDs valid
roundcube: [05-Oct-2010 14:07:55 -0700]: S: * OK [UIDNEXT 189] Predicted next UID
roundcube: [05-Oct-2010 14:07:55 -0700]: S: sel1 OK [READ-WRITE] Select completed.
roundcube: [05-Oct-2010 14:07:55 -0700]: C: srch1 SEARCH ALL UNSEEN
roundcube: [05-Oct-2010 14:07:55 -0700]: S: * SEARCH
roundcube: [05-Oct-2010 14:07:55 -0700]: S: srch1 OK Search completed.
roundcube: [05-Oct-2010 14:07:55 -0700]: C: I LOGOUT



Any thoughts on where to look from here?
Title: inbox not populating at login
Post by: alec on October 06, 2010, 02:10:22 AM
Nothing wrong in this log. Because in 0.4 initial list command is executed in parallel with getunread action, this maybe related to some simultaneous connections limit on IMAP server.
Title: inbox not populating at login
Post by: jjac on October 06, 2010, 12:55:27 PM
Hmm, we're using pretty stock dovecot configs (128 max login processes, 1024 max mail processes, etc; running on 3 load balanced servers) plus imapproxy (cache_size of 1024); and I'm not seeing any errors in either of their logs to indicate that we're hitting any connection limit.  Also, this is exactly the same layout we were running 0.3 on just last week, with the same approximate number of users, etc.

Is there anything else within Roundcube that I can tweak to try to get better info about where it might be failing?
Title: inbox not populating at login
Post by: jjac on October 13, 2010, 06:13:29 PM
Well, got a chance to dig around some, and the problem seems to be that Roundcube is halting when doing an fgets initiated from list.inc.  It looks like it's not receiving a reply from the mail server at all in some cases.  We're running Dovecot, and althrough I was originally going through imapproxy, I've taken that out of the equation and now connect directly to our Dovecot servers.  I've made sure the load on the servers is low and that there's plenty of available login threads, but no luck.

(Starting from list.inc:
when fetching message headers with $IMAP->messagecount()
messagecount() calls _messsagecount()
calls countMessages()
calls select()
calls readLine()
which calls fgets()
)