Newbie question about Roundcube & Dovecot lag

[Weslocke]

I'm not sure where to post this, so I figured this forum would work.

First the info:

CentOS 6.6
Roundcube 1.1.1
Dovecot 2.2.2


I've been running Roundcube for quite a while now, but recently it's started to get horribly slow. 

Though I should change that, it works fine until it doesn't.  Usually on changing folders it will either pop right in, or it will take twenty seconds (almost exactly) to pull up the index.

I've done all of the performance tweaking that I've been able to find, both under the Roundcube wiki as well as Dovecot.

Here's a bit of a wall of text from the log to show what I mean.  If you look, the action at 21:02:11 worked fine...  which was going into my "Trash" folder from my "Inbox (I believe).  It connects to Dovecot quickly and gave me the results immediately.  Right after that I clicked back on my "Inbox" and got hit with the lag of twenty seconds.  If you notice  at 21:02:23 it authenticates with Dovecot, but it's not until 21:02:43 that it gets back the capability string, whereupon it immediately returns the headers.

Again sometimes it works fine, other times I have that horrendous delay.

Any ideas or suggestions?

PS. as a quick note, when this happens my httpd process also pegs at around 100%.  Not sure how much that helps.

Code: [Select]

[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] C: A0001 ID ("name" "Roundcube" "version" "1.1.1" "php" "5.3.3" "os" "Linux" "command" "/roundcube/?_task=mail&_refresh=1&_mbox=Sent&_page=1&_remote=1&_unlock=loading1431824531873&_action=list&_=1431823543745")
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * ID ("name" "Dovecot")
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: A0001 OK ID completed.
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] C: A0002 AUTHENTICATE PLAIN ****** [25]
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: A0002 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] C: A0003 ENABLE QRESYNC
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * ENABLED QRESYNC
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: A0003 OK Enabled.
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] C: A0004 SELECT Sent
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded NonJunk $NotJunk)
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded NonJunk $NotJunk \*)] Flags permitted.
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * 1433 EXISTS
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * 0 RECENT
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * OK [UIDVALIDITY 1335887707] UIDs valid
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * OK [UIDNEXT 1524] Predicted next UID
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * OK [HIGHESTMODSEQ 2875] Highest
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: A0004 OK [READ-WRITE] Select completed (0.000 secs).
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] C: A0005 UID SEARCH RETURN (COUNT ALL MAX) ALL UNDELETED
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * ESEARCH (TAG "A0005") UID MAX 1523 ALL 1:60,63:64,66,68:101,103:104,115,119,122,127:133,136,138:139,141:146,148:149,151:163,166:173,178:184,192:193,201:204,206:207,219:220,233:235,239,241:246,248:251,262:1400,1402:1523 COUNT 1433
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: A0005 OK Search completed (0.000 secs).
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] C: A0006 UID SEARCH RETURN (COUNT) ALL UNDELETED UNSEEN
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * ESEARCH (TAG "A0006") UID COUNT 0
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: A0006 OK Search completed (0.000 secs).
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] C: A0007 LOGOUT
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: * BYE Logging out
[16-May-2015 21:02:11 -0400]: <5nm0c3un> [9BAF] S: A0007 OK Logout completed.
[16-May-2015 21:02:23 -0400]: <5nm0c3un> [7075] S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.
[16-May-2015 21:02:23 -0400]: <5nm0c3un> [7075] C: A0001 ID ("name" "Roundcube" "version" "1.1.1" "php" "5.3.3" "os" "Linux" "command" "/roundcube/?_task=mail&_refresh=1&_mbox=INBOX&_page=1&_remote=1&_unlock=loading1431824543612&_action=list&_=1431823543746")
[16-May-2015 21:02:23 -0400]: <5nm0c3un> [7075] S: * ID ("name" "Dovecot")
[16-May-2015 21:02:23 -0400]: <5nm0c3un> [7075] S: A0001 OK ID completed.
[16-May-2015 21:02:23 -0400]: <5nm0c3un> [7075] C: A0002 AUTHENTICATE PLAIN ****** [25]
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: A0002 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] C: A0003 ENABLE QRESYNC
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * ENABLED QRESYNC
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: A0003 OK Enabled.
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] C: A0004 SELECT INBOX
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent Junk NonJunk $NotJunk $Junk $Forwarded $label3)
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent Junk NonJunk $NotJunk $Junk $Forwarded $label3 \*)] Flags permitted.
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * 447 EXISTS
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * 0 RECENT
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * OK [UNSEEN 277] First unseen.
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * OK [UIDVALIDITY 1303905090] UIDs valid
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * OK [UIDNEXT 24007] Predicted next UID
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * OK [HIGHESTMODSEQ 149213] Highest
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: A0004 OK [READ-WRITE] Select completed (0.000 secs).
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] C: A0005 UID SEARCH RETURN (COUNT ALL MAX) ALL UNDELETED
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * ESEARCH (TAG "A0005") UID MAX 24005 ALL 18123,18151:18152,18171,18176:18177,18235,18243,18245,18247:18248,18250,18253,18327,18339,18344:18345,18367:18368,18383:18384,18403,18437,18547,18561,18575,18577,18581,18587:18588,18618,18633,18652,18675,18698,18711:18713,18724:18725,18744,18748,18774,18790,18808:18809,18818,18820:18821,18825:18826,18907,19118,19211,19252,19274,19287,19304:19305,19310,19313,19323,19325,19333,19335,19337:19338,19340,19346,19348,19367,19453,19479,19530,19533,19536,19543,19552,19650:19652,19657,19679:19680,19688,19695,19706:19707,19717,19719,19722,19796:19797,19799:19800,19826:19828,19830,19842,19895,19955,19971,20015,20017,20042,20049,20058:20059,20063,20066,20070,20080,20110,20117,20131,20133,20171,20173,20195,20206,20211,20230,20232,20234,20237,20242,20257,20264,20274,20280,20283:20285,20309,20364,20372,20380:20382,20397,20399:20400,20402:20403,20407,20412,20415,20417,20441:20443,20500,20505:20506,20546,20553,20599,20682,20690,20693,20734,20750,20756:20757,20759:20760,20762:20763,20772,20789:20790,20834,20912,20952,20961,20982,20991,21006,21008,21045,21054,21085,21113,21134:21137,21165,21169,21174,21177,21187,21192,21201,21208,21216:21217,21219:21220,21239,21249,21265:21266,21271:21272,21276,21278:21279,21284,21291:21292,21294,21301,21306,21313,21315,21317:21319,21332,21347:21350,21361,21366,21377,21381,21385:21387,21391,21394:21397,21402,21408,21413,21429,21438,21452,21460,21464,21493,21504,21524,21527,21545,21602,21618,21622,21625,21636,21710,21719,21721,21732,21773,21849,21894,21910,21940,21970,21989:21990,21992,22006,22009,22037,22078,22096,22108,22117,22146:22147,22197,22237:22238,22240,22282,22327,22416,22446,22457,22460,22465,22493,22513,22522,22525,22542,22550,22581,22590,22593,22606,22613,22617,22672,22684,22701,22721,22736,22742,22750,22757,22790,22795,22802,22839,22841,22846:22847,22849,22858,22861,22865,22869,22877:22878,22880,22884,22890,22892:22894,22906,22910,22914:22915,22921,22956,22989:22990,23058,23076,23079,23089,23140,23149,23158:23161,23178,23180,23183,23189,23207,23216,23218,23227,23231,23243:23244,23252,23260,23269,23280,23301,23399:23400,23412:23413,23423,23430,23442:23443,23454,23461,23465,23468:23476,23505,23515,23517:23518,23567,23598:23599,23604,23617:23620,23631:23633,23639,23643,23651,23667:23668,23683,23707,23713,23715,23720,23748,23753,23760,23800,23811,23815,23818:23819,23821:23822,23825,23835:23837,23845,23858,23880,23887,23889,23891,23903,23918:23919,23929:23931,23933:23934,23936:23938,23945,23955,23964,23967,23973,23997:23998,24002,24005 COUNT 447
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: A0005 OK Search completed (0.000 secs).
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] C: A0006 UID SEARCH RETURN (COUNT) ALL UNDELETED UNSEEN
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * ESEARCH (TAG "A0006") UID COUNT 4
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: A0006 OK Search completed (0.000 secs).
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] C: A0007 LOGOUT
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: * BYE Logging out
[16-May-2015 21:02:43 -0400]: <5nm0c3un> [7075] S: A0007 OK Logout completed.


[SKaero]

With a delay that long I'd wonder if something is timing out or being limited. Check the mail server and login logs on the server to see if they show any errors.

[Weslocke]

It does seem to be something timing out with PAM, or the auth daemon at least.

Unfortunately after a few hours of digging into it, I still can't figure that system out any better.

But here's what I'm seeing in case you have any authentication suggestions (which I realize is outside of the scope of Roundcube, but hey...  I have to ask)  :

Code: [Select]

May 16 23:56:08 auth: Debug: client in: AUTH    1       PLAIN   service=imap    secured session=xxxxxxxxxxxxxxxx        lip=127.0.0.1   rip=127.0.0.1   lport=143    rport=44575     resp=xxxxxxxxxxxxxxxxxxx== (previous base64 data may contain sensitive data)
May 16 23:56:08 auth-worker(12360): Debug: pam(weslocke,127.0.0.1): lookup service=dovecot
May 16 23:56:08 auth-worker(12360): Debug: pam(weslocke,127.0.0.1): #1/1 style=1 msg=Password:
May 16 23:56:08 auth: Debug: client passdb out: OK      1       user=weslocke
May 16 23:56:08 auth: Debug: master in: REQUEST xxxxxxxxxx      12652   1       xxxxxxxxxxxxxxxxxxxxxxxxxxa        session_pid=12653
May 16 23:56:08 auth-worker(12360): Debug: passwd(weslocke,127.0.0.1): lookup
May 16 23:56:08 auth: Debug: master userdb out: USER    xxxxxxxxxx      weslocke        system_groups_user=weslocke     uid=500 gid=500 home=/home/weslocke auth_token=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
May 16 23:56:08 imap(weslocke): Debug: Effective uid=500, gid=500, home=/home/weslocke
May 16 23:56:08 imap(weslocke): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mbox:~/mail:INBOX=/var/mail/weslocke
May 16 23:56:08 imap(weslocke): Debug: fs: root=/home/weslocke/mail, index=, indexpvt=, control=, inbox=/var/mail/weslocke, alt=
May 16 23:56:29 auth: Debug: auth client connected (pid=12655)
May 16 23:56:29 auth: Debug: client in: AUTH    1       PLAIN   service=imap    secured session=SbfnDz8WIAB/AAAB        lip=127.0.0.1   rip=127.0.0.1   lport=143    rport=44576     resp=xxxxxxxxxxxxxxxxxxxxxxx== (previous base64 data may contain sensitive data)
May 16 23:56:29 auth-worker(12360): Debug: pam(weslocke,127.0.0.1): lookup service=dovecot
May 16 23:56:29 auth-worker(12360): Debug: pam(weslocke,127.0.0.1): #1/1 style=1 msg=Password:
May 16 23:56:29 auth: Debug: client passdb out: OK      1       user=weslocke
May 16 23:56:29 auth: Debug: master in: REQUEST xxxxxxxxxx       12655   1       ecda195f010116e5e173b54fd24fd525        session_pid=12670
May 16 23:56:29 auth-worker(12360): Debug: passwd(weslocke,127.0.0.1): lookup
May 16 23:56:29 auth: Debug: master userdb out: USER    xxxxxxxxxxxx       weslocke        system_groups_user=weslocke     uid=500 gid=500 home=/home/weslocke auth_token=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
May 16 23:56:29 imap(weslocke): Debug: Effective uid=500, gid=500, home=/home/weslocke
May 16 23:56:29 imap(weslocke): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mbox:~/mail:INBOX=/var/mail/weslocke
May 16 23:56:29 imap(weslocke): Debug: fs: root=/home/weslocke/mail, index=, indexpvt=, control=, inbox=/var/mail/weslocke, alt=


[Weslocke]

Ok, as a followup...

I finally got it working by manually compiling Dovecot (2.2.2) instead of using the current CentOS bundle (2.2.17 I believe).

Once I copied my configuration back it started working again just fine.

Before that with imaptest (part of the Dovecot build, but you can run it against previous versions) I was getting a lot of IMAP stalls. 

It simply seems that between PAM and Dovecot something got onto a different revision level that the other didn't like.

/shrug