Mail: Error while loading messages

[mzellho]

Steps to reproduce

1. create account
2. open account (opens automatically)
   

   Expected behaviour

Load messages of inbox folder

Actual behaviour

Shows spinner and error "Error while loading messages". Since the app can load all the inbox folders, I would say that auth is okay. Mailserver is on the same host - I tried localhost as well as full domain names-

Mail app

Mail app version: 0.5.3

Mailserver or service: imap

Transport security - IMAP: SSL

Transport security - SMTP: STARTTLS

Number of accounts: 1

Server configuration

Operating system: Ubuntu

Web server: Apache 2.2.14

Database: MySQL 5.1.73

PHP version: 5.5.19

Version: 10.0.0

Updated from an older version or fresh install: fresh install

Client configuration

Browser: Chrome

Operating system: Windows 10

Logs

Web server error log

[Wed Sep 07 14:28:53 2016] [crit] [client MY_IP_ADDRESS] (13)Permission denied: PATH_TO_NEXTCLOUD/nextcloud/data/.htaccess pcfg_openfile: unable to check htaccess file, ensure it is readable

Server log (data/nextcloud.log)

{"reqId":"V9AFGX8AAQEAABSjhA4AABAv","remoteAddr":"MY_IP_ADDRESS","app":"mail","message":"Setting up manually configured account","level":1,"time":"2016-09-07T12:16:25+00:00","method":"POST","url":"\/index.php\/apps\/mail\/accounts","user":"myuser"}
{"reqId":"V9AFGX8AAQEAABSjhA4AABAv","remoteAddr":"MY_IP_ADDRESS","app":"mail","message":"Connecting to account [email protected]","level":0,"time":"2016-09-07T12:16:25+00:00","method":"POST","url":"\/index.php\/apps\/mail\/accounts","user":"myuser"}
{"reqId":"V9AFGX8AAQEAABSjhA4AABAv","remoteAddr":"MY_IP_ADDRESS","app":"mail","message":"account created 8","level":0,"time":"2016-09-07T12:16:25+00:00","method":"POST","url":"\/index.php\/apps\/mail\/accounts","user":"myuser"}
{"reqId":"V9AFG38AAQEAABSjhDIAABAv","remoteAddr":"MY_IP_ADDRESS","app":"mail","message":"loading messages 0 to 20 of folder <SU5CT1g=>","level":0,"time":"2016-09-07T12:16:27+00:00","method":"GET","url":"\/index.php\/apps\/mail\/accounts\/8\/folders\/SU5CT1g%3D\/messages","user":"myuser"}
{"reqId":"V9AFG38AAQEAABSjhDIAABAv","remoteAddr":"MY_IP_ADDRESS","app":"index","message":"Exception: {\"Exception\":\"Horde_Imap_Client_Exception_ServerResponse\",\"Message\":\"IMAP error reported by server.\",\"Code\":0,\"Trace\":\"#0 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/apps\\\/mail\\\/vendor\\\/pear-pear.horde.org\\\/Horde_Imap_Client\\\/Horde\\\/Imap\\\/Client\\\/Socket.php(4302): Horde_Imap_Client_Socket->_getLine(Object(Horde_Imap_Client_Interaction_Pipeline))\\n#1 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/apps\\\/mail\\\/vendor\\\/pear-pear.horde.org\\\/Horde_Imap_Client\\\/Horde\\\/Imap\\\/Client\\\/Socket.php(4230): Horde_Imap_Client_Socket->_sendCmdChunk(Object(Horde_Imap_Client_Interaction_Pipeline), Array)\\n#2 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/apps\\\/mail\\\/vendor\\\/pear-pear.horde.org\\\/Horde_Imap_Client\\\/Horde\\\/Imap\\\/Client\\\/Socket.php(2473): Horde_Imap_Client_Socket->_sendCmd(Object(Horde_Imap_Client_Interaction_Pipeline))\\n#3 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/apps\\\/mail\\\/vendor\\\/pear-pear.horde.org\\\/Horde_Imap_Client\\\/Horde\\\/Imap\\\/Client\\\/Base.php(2260): Horde_Imap_Client_Socket->_search(Object(Horde_Imap_Client_Search_Query), Array)\\n#4 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/apps\\\/mail\\\/lib\\\/mailbox.php(105): Horde_Imap_Client_Base->search(Object(Horde_Imap_Client_Mailbox), Object(Horde_Imap_Client_Search_Query), Array)\\n#5 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/apps\\\/mail\\\/lib\\\/mailbox.php(137): OCA\\\\Mail\\\\Mailbox->getSearchIds(0, 21, NULL)\\n#6 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/apps\\\/mail\\\/lib\\\/controller\\\/messagescontroller.php(133): OCA\\\\Mail\\\\Mailbox->getMessages(0, 21, NULL)\\n#7 [internal function]: OCA\\\\Mail\\\\Controller\\\\MessagesController->index(8, 'SU5CT1g=', 0, 20, NULL, NULL)\\n#8 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/lib\\\/private\\\/AppFramework\\\/Http\\\/Dispatcher.php(160): call_user_func_array(Array, Array)\\n#9 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/lib\\\/private\\\/AppFramework\\\/Http\\\/Dispatcher.php(90): OC\\\\AppFramework\\\\Http\\\\Dispatcher->executeController(Object(OCA\\\\Mail\\\\Controller\\\\MessagesController), 'index')\\n#10 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/lib\\\/private\\\/AppFramework\\\/App.php(111): OC\\\\AppFramework\\\\Http\\\\Dispatcher->dispatch(Object(OCA\\\\Mail\\\\Controller\\\\MessagesController), 'index')\\n#11 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/lib\\\/private\\\/AppFramework\\\/Routing\\\/RouteActionHandler.php(47): OC\\\\AppFramework\\\\App::main('MessagesControl...', 'index', Object(OC\\\\AppFramework\\\\DependencyInjection\\\\DIContainer), Array)\\n#12 [internal function]: OC\\\\AppFramework\\\\Routing\\\\RouteActionHandler->__invoke(Array)\\n#13 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/lib\\\/private\\\/Route\\\/Router.php(293): call_user_func(Object(OC\\\\AppFramework\\\\Routing\\\\RouteActionHandler), Array)\\n#14 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/lib\\\/base.php(967): OC\\\\Route\\\\Router->match('\\\/apps\\\/mail\\\/acco...')\\n#15 \\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/index.php(48): OC::handleRequest()\\n#16 {main}\",\"File\":\"\\\/PATH_TO_NEXTCLOUD\\\/nextcloud\\\/apps\\\/mail\\\/vendor\\\/pear-pear.horde.org\\\/Horde_Imap_Client\\\/Horde\\\/Imap\\\/Client\\\/Socket.php\",\"Line\":4590}","level":3,"time":"2016-09-07T12:16:27+00:00","method":"GET","url":"\/index.php\/apps\/mail\/accounts\/8\/folders\/SU5CT1g%3D\/messages","user":"myuser"}

Horde IMAP log (data/horde_imap.log)

------------------------------
>> Wed, 07 Sep 2016 13:04:08 +0000
>> Connection to: imap://imap.mydomain.tld:993/
>> Server connection took 0.0211 seconds.
S: * OK [CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE AUTH=PLAIN ACL ACL2=UNION] Courier-IMAP ready. Copyright 1998-2008 Double Precision, Inc.  See COPYING for distribution information.
C: 1 [INITIAL CLIENT RESPONSE (username: MY_USERNAME)]
S: +
C: ####CREDENTIALS_REPLACED####
S: 1 OK LOGIN Ok.
>> Command 1 took 0.016 seconds.
C: 2 CAPABILITY
S: * CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE AUTH=PLAIN ACL ACL2=UNION
S: 2 OK CAPABILITY completed
>> Command 2 took 0.0007 seconds.
C: 3 LIST "" *
S: * LIST (\HasNoChildren) "." "INBOX.Sent"
S: * LIST (\Unmarked \HasChildren) "." "INBOX"
S: * LIST (\HasNoChildren) "." "INBOX.Drafts"
S: 3 OK LIST completed
>> Command 3 took 0.0052 seconds.
C: 4 STATUS INBOX (MESSAGES RECENT UIDNEXT UIDVALIDITY UNSEEN)
C: 5 STATUS INBOX.Drafts (MESSAGES RECENT UIDNEXT UIDVALIDITY UNSEEN)
C: 6 STATUS INBOX.Sent (MESSAGES RECENT UIDNEXT UIDVALIDITY UNSEEN)
S: * STATUS "INBOX" (MESSAGES 5712 RECENT 0 UIDNEXT 17205 UIDVALIDITY 1162366424 UNSEEN 0)
S: 4 OK STATUS Completed.
>> Command 4 took 0.0772 seconds.
S: * STATUS "INBOX.Drafts" (MESSAGES 5 RECENT 0 UIDNEXT 114 UIDVALIDITY 1166634516 UNSEEN 0)
S: 5 OK STATUS Completed.
>> Command 5 took 0.1188 seconds.
S: * STATUS "INBOX.Sent" (MESSAGES 566 RECENT 0 UIDNEXT 586 UIDVALIDITY 1165864546 UNSEEN 0)
S: 6 OK STATUS Completed.
>> Command 6 took 0.1189 seconds.
C: 18 STATUS INBOX (MESSAGES RECENT UIDNEXT UIDVALIDITY UNSEEN)
S: * STATUS "INBOX" (MESSAGES 5712 RECENT 0 UIDNEXT 17205 UIDVALIDITY 1162366424 UNSEEN 0)
S: 18 OK STATUS Completed.
>> Command 18 took 0.0197 seconds.
C: 19 LOGOUT
S: * BYE Courier-IMAP server shutting down
S: 19 OK LOGOUT completed
>> Command 19 took 0.0005 seconds.
------------------------------
>> Wed, 07 Sep 2016 13:04:09 +0000
>> Connection to: imap://imap.mydomain.tld:993/
>> Server connection took 0.0332 seconds.
S: * OK [CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE AUTH=PLAIN ACL ACL2=UNION] Courier-IMAP ready. Copyright 1998-2008 Double Precision, Inc.  See COPYING for distribution information.
C: 1 [INITIAL CLIENT RESPONSE (username: MY_USERNAME)]
S: +
C: ####CREDENTIALS_REPLACED####
S: 1 OK LOGIN Ok.
>> Command 1 took 0.0098 seconds.
C: 2 CAPABILITY
S: * CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE AUTH=PLAIN ACL ACL2=UNION
S: 2 OK CAPABILITY completed
>> Command 2 took 0.0006 seconds.
C: 3 EXAMINE INBOX
S: * FLAGS ($MDNSent $Forwarded $has_cal \Draft \Answered \Flagged \Deleted \Seen \Recent)
S: * OK [PERMANENTFLAGS ()] No permanent flags permitted
S: * 5712 EXISTS
S: * 0 RECENT
S: * OK [UIDVALIDITY 1162366424] Ok
S: * OK [MYRIGHTS "acdilrsw"] ACL
S: 3 OK [READ-ONLY] Ok
>> Command 3 took 0.0175 seconds.
C: 4 UID SORT (DATE) US-ASCII UNDELETED
S: 4 NO This command is disabled by the system administrator.
>> Command 4 took 0.0004 seconds.
C: 5 LOGOUT
S: * BYE Courier-IMAP server shutting down
S: 5 OK LOGOUT completed
>> Command 5 took 0.0006 seconds.

Horde SMTP log (data/horde_smtp.log)

no log available (??)

Browser log

jquery.js:8630 GET http://nextcloud.mydomain.tld/index.php/apps/mail/accounts/8/folders/SU5CT1g%3D/messages 500 (Internal Server Error)

[ChristophWurst]

IMAP error reported by server

Please try again after enabling IMAP logging. Hopefully the imap log will shed more light on what's failing there.

[mzellho]

Added imap log

[ChristophWurst]

C: 4 UID SORT (DATE) US-ASCII UNDELETED S: 4 NO This command is disabled by the system administrator.

Hm. That looks suspicious

[ChristophWurst]

S: * CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE AUTH=PLAIN ACL ACL2=UNION

Well, the server seems to support SORT

[mzellho]

Hmm, any idea on how to proceed? I could get in touch with my provider, but they will most likely go "Well, other Mail-Clients work. Use ours, this one is supported". I have Roundcube running on the same server as well, works fine. Also, I could try to install horde and see if it works, but I'm not sure if I have all the necessary permissions for that...

[ChristophWurst]

I'm pretty sure https://github.com/nextcloud/mail/blob/3249331af79ce4cb2d811e9eac88db0f6af6facf/lib/mailbox.php#L93-L147 is the faulty code. But I don't know yet why it's failing there, sorry.

"UID SORT" seems to be the right command, see https://tools.ietf.org/html/rfc5256#section-4

Maybe we need to query the capability differently or more precisely…

[mzellho]

Well, sadly I don't have too much clue here, but maybe I can find some time in the evening to look into it. If you want me to try something, just let me know.

[ChristophWurst]

Well, sadly I don't have too much clue here, but maybe I can find some time in the evening to look into it. If you want me to try something, just let me know.

Sure, go ahead. Would be great if we could debug and fix this together :-)

[mzellho]

Christoph, did you find out anything in the meantime? I could be looking into it now - any (new) suggestions where to start?

[zeugmatis]

Random suggestion but maybe can you test directly with your account / ISP using telnet? Over CLI - then copy/paste here. Simple tutorial is here. (There are lots of them on the web) - maybe try to duplicate the issue by hand going along with what is in your imap logs.

[mzellho]

Sorry, my SSH does not allow me telnet, ps, lsof ... (maybe I should just change the provider), but in the meantime I found some interesting facts:

Like, reading my own logfile, that my provider is using Courier-IMAP, apparently a 2008 version. In Roundcube's Forum I learned that Courier used to disable SORT even if it advertises it (maybe it still does?) :

##NAME: IMAP_DISABLETHREADSORT:0
#
# Set IMAP_DISABLETHREADSORT to disable the THREAD and SORT commands -
# server side sorting and threading.
#
# Those capabilities will still be advertised, but the server will reject
# them.  Set this option if you want to disable all the extra load from
# server-side threading and sorting.  Not advertising those capabilities
# will simply result in the clients reading the entire folder, and sorting
# it on the client side.  That will still put some load on the server.
# advertising these capabilities, but rejecting the commands, will stop this
# silliness.
#
IMAP_DISABLETHREADSORT=0

I would not be surprised if this was the case for the version on my provider's server.

For the moment, I commented out lines 143 and 145-147 in mailbox.php in order to always call getFetchIds(). This is an "okay" workaround for me at the moment. I'll try to find out why my provider is running such an outdated version (there are more recent versions, up to 03-Aug-2016) and why they have IMAP_DISABLETHREADSORT set to 0.

I know it will probably be impossible to get along with fake-advertised capabilities, but do you think you could somehow handle such a "lie" in a future version your app? If I can help, please just let me know. I wonder, how Roundcube does it. Maybe I can get their imap-logs and see what they do.

BTW: now, that I can see and use the app: pretty cool, so far. Keep up the good work :-)

[ChristophWurst]

What? Seriously? :angry:

I knew not all servers support SORT, so I've added the check at https://github.com/nextcloud/mail/blob/3249331af79ce4cb2d811e9eac88db0f6af6facf/lib/mailbox.php#L143.

The problem is that we really want to use SORT as it gives a nice performance improvement when loading the list of messages (we need it sorted and paginated). Therefore I won't simply remove that one method. Hm… let me think about a solution

[ChristophWurst]

well, we could wrap the SORT call in a try-catch block and use the slow fetching as fallback. Sounds hacky, but could work…

[mzellho]

Yep, I know - couldn't belileve what I was reading, especially that "advertising these capabilities, but rejecting the commands, will stop this silliness". Well, maybe there were some good reasons back in '08, but honestly: why would the client have to know that much detail about the server?

Regarding the fix I was also thinking of a try/catch. At least it would make the app working with medieval mailservers and that is a benefit for users of such while not causing troubles for others.

In any case: Thanks for your support! I'll try to find out more about the mailserver and its version tomorrow. Would you kindly ping me if a new version is shipped?

[ChristophWurst]

Regarding the fix I was also thinking of a try/catch.. At least it would make the app working with medieval mailservers and that is a benefit for users of such while not causing troubles for others.

Could you please try that and if that works, submit a pull request? If I'd fix it, I couldn't test it :-)

Would you kindly ping me if a new version is shipped?

Sure. You can also star/watch the repo, then you'll be notified about releases AFAIK.

You are also welcome to join us on IRC in #nextcloud-mail on freenode, help.nextcloud.com :dancer:

[ChristophWurst]

And there's an important event next week – the Nextcloud conf https://conf.nextcloud.com come and join us in Berlin ;-)

[zeugmatis]

I'm running Courier-imap as well and can confirm. Tested via telnet, and with IMAP_DISABLE_THREADSORT=0 it is fine, but changing it to IMAP_DISABLE_THREADSORT=1 throws the same error:

a OK [READ-ONLY] Ok
a UID SORT (DATE) US-ASCII UNDELETED
a NO This command is disabled by the system administrator.
a logout

...so it looks like the ISP has set IMAP_DISABLE_THREADSORT=1 (which is not the default). If so, they should also remove the keywords "SORT" and "THREAD" in IMAP_CAPABILITY setting as well, so that it does not advertise it anymore:

IMAP_CAPABILITY="IMAP4rev1 UIDPLUS CHILDREN NAMESPACE QUOTA IDLE"

...as far as app:mail, I guess upon error for the command it could fallback to same behavior as if SORT is not advertised. Looks like more of an imap server config issue though, since they disabled serverside THREAD and SORT but did not remove it from their IMAP_CAPABILITY setting as well.

[lock[bot]]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs and questions.