Hi, I have an IMAP server which was (and still is) working fine when people use a mail client. I decided to offer a web interface and installed Roundcube. I have gotten it to the point where I can login and it will list the folders, but it doesn't list any e-mails. The logs (access and errors) don't show any issues, so I enabled IMAP debug. Here is the output:
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] C: A0001 ID ("name" "Roundcube" "version" "1.3.1 " "php" "7.1.10-1+ubuntu16.04.1+deb.sury.org+1" "os" "Linux" "command" "/?_task=login")
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] S: * ID ("name" "Dovecot")
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] S: A0001 OK ID completed.
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] C: A0002 AUTHENTICATE PLAIN ****** [57]
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] 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 BINARY MOVE SPECIAL-USE] Logged in
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] C: A0003 NAMESPACE
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] S: * NAMESPACE (("" "/")) NIL NIL
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] S: A0003 OK Namespace completed.
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] C: A0004 LIST (SPECIAL-USE) "" "*" RETURN (SUBSCRIBED)
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] S: * LIST (\Subscribed \Drafts) "/" Drafts
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] S: * LIST (\Subscribed \Sent) "/" Sent
[07-Oct-2017 03:25:53 +0000]: <9eba626l> [14A2] S: A0004 OK List completed (0.000 + 0.000 secs).
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [14A2] C: A0005 LOGOUT
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [14A2] S: * BYE Logging out
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [14A2] S: A0005 OK Logout completed.
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] C: A0001 ID ("name" "Roundcube" "version" "1.3.1 " "php" "7.1.10-1+ubuntu16.04.1+deb.sury.org+1" "os" "Linux" "command" "/?_task=mail&_token=RN6ZYmUNhXvcgGXrx4jcZCw4crgtIGUW&_token=1B4dPmE59br7SN5ODYvhwFVheaQMp8d8")
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: * ID ("name" "Dovecot")
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: A0001 OK ID completed.
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] C: A0002 AUTHENTICATE PLAIN ****** [57]
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] 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 BINARY MOVE SPECIAL-USE] Logged in
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] C: A0003 LIST (SUBSCRIBED) "" "*"
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: * LIST (\Subscribed) "/" "Sent Items"
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: * LIST (\Subscribed) "/" "Deleted Items"
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: * LIST (\Subscribed) "/" Drafts
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: * LIST (\Subscribed) "/" "Junk Email"
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: * LIST (\Subscribed) "/" Sent
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: A0003 OK List completed (0.000 + 0.000 secs).
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] C: A0004 LOGOUT
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: * BYE Logging out
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [F400] S: A0004 OK Logout completed.
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] C: A0001 ID ("name" "Roundcube" "version" "1.3.1 " "php" "7.1.10-1+ubuntu16.04.1+deb.sury.org+1" "os" "Linux" "command" "/program/js/jquery.min.js")
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: * ID ("name" "Dovecot")
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: A0001 OK ID completed.
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] C: A0002 AUTHENTICATE PLAIN ****** [57]
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] 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 BINARY MOVE SPECIAL-USE] Logged in
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] C: A0003 LIST (SUBSCRIBED) "" "*"
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: * LIST (\Subscribed) "/" "Sent Items"
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: * LIST (\Subscribed) "/" "Deleted Items"
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: * LIST (\Subscribed) "/" Drafts
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: * LIST (\Subscribed) "/" "Junk Email"
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: * LIST (\Subscribed) "/" Sent
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: A0003 OK List completed (0.000 + 0.000 secs).
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] C: A0004 LOGOUT
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: * BYE Logging out
[07-Oct-2017 03:25:53 +0000]: <kqi3lm2j> [6F5B] S: A0004 OK Logout completed.
The dovecot logs don't show any warning or errors. The only thing I seem to notice is that the connection was closed within 1 second
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [88.188.188.188]
Oct 07 03:25:53 imap-login: Info: Login: user=<username@example.com>, method=PLAIN, rip=88.188.188.188, lip=172.31.29.197, mpid=25357, TLS
Oct 07 03:25:53 imap(username@example.com): Debug: Effective uid=5000, gid=5000, home=/data/mail/sdbox/example.com/username
Oct 07 03:25:53 imap(username@example.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=sdbox:/data/mail/sdbox/example.com/username:UTF-8
Oct 07 03:25:53 imap(username@example.com): Debug: fs: root=/data/mail/sdbox/example.com/username, index=, indexpvt=, control=, inbox=, alt=
Oct 07 03:25:53 imap(username@example.com): Info: Logged out in=82 out=591
Oct 07 03:25:53 imap-login: Debug: SSL alert: close notify [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [88.188.188.188]
Oct 07 03:25:53 imap-login: Info: Login: user=<username@example.com>, method=PLAIN, rip=88.188.188.188, lip=172.31.29.197, mpid=25360, TLS
Oct 07 03:25:53 imap(username@example.com): Debug: Effective uid=5000, gid=5000, home=/data/mail/sdbox/example.com/username
Oct 07 03:25:53 imap(username@example.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=sdbox:/data/mail/sdbox/example.com/username:UTF-8
Oct 07 03:25:53 imap(username@example.com): Debug: fs: root=/data/mail/sdbox/example.com/username, index=, indexpvt=, control=, inbox=, alt=
Oct 07 03:25:53 imap(username@example.com): Info: Logged out in=44 out=634
Oct 07 03:25:53 imap-login: Debug: SSL alert: close notify [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv2/v3 read client hello A [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [88.188.188.188]
Oct 07 03:25:53 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [88.188.188.188]
Oct 07 03:25:53 imap-login: Info: Login: user=<username@example.com>, method=PLAIN, rip=88.188.188.188, lip=172.31.29.197, mpid=25363, TLS
Oct 07 03:25:53 imap(username@example.com): Debug: Effective uid=5000, gid=5000, home=/data/mail/sdbox/example.com/username
Oct 07 03:25:53 imap(username@example.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=sdbox:/data/mail/sdbox/example.com/username:UTF-8
Oct 07 03:25:53 imap(username@example.com): Debug: fs: root=/data/mail/sdbox/example.com/username, index=, indexpvt=, control=, inbox=, alt=
Oct 07 03:25:53 imap(username@example.com): Info: Logged out in=44 out=634
Oct 07 03:25:53 imap-login: Debug: SSL alert: close notify [88.188.188.188]
The nginx access log similarly doesn't show any errors/warnings.
It actually only has 3 lines for this event:
[07/Oct/2017:03:25:53 +0000] "POST /?_task=login HTTP/2.0" 302 0 "
https://mail.example.com/?_task=mail&_token=RN6ZYmUNhXvcgGXrx4jcZCw4crgtIGUW" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:55.0) Gecko/20100101 Firefox/55.0"
[07/Oct/2017:03:25:53 +0000] "GET /?_task=mail&_token=RN6ZYmUNhXvcgGXrx4jcZCw5crgtIGUW&_token=1B4dPmE59br7SN6ODYvhwFVheaQMp8d8 HTTP/2.0" 200 42545 "
https://mail.example.com/?_task=mail&_token=RN6ZYmUNhXvcgGXrx4jcZCw5crgtIGUW" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:55.0) Gecko/20100101 Firefox/55.0"
[07/Oct/2017:03:25:53 +0000] "GET /program/js/jquery.min.js HTTP/2.0" 200 42545 "
https://mail.example.com/?_task=mail&_token=RN6ZYmUNhXvcgGXrx4jcZCw5crgtIGUW&_token=1B4dPmE59br7SN6ODYvhwFVheaQMp8d8" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:55.0) Gecko/20100101 Firefox/55.0"
Does anybody have any idea what might be going on?
Thank you!