Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Error while loading messages #50

Closed
mzellho opened this issue Sep 7, 2016 · 18 comments
Closed

Error while loading messages #50

mzellho opened this issue Sep 7, 2016 · 18 comments

Comments

@mzellho
Copy link
Contributor

mzellho commented Sep 7, 2016

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 myuser@mydomain.tld","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
Copy link
Member

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
Copy link
Contributor Author

mzellho commented Sep 7, 2016

Added imap log

@ChristophWurst
Copy link
Member

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

Hm. That looks suspicious

@ChristophWurst
Copy link
Member

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
Copy link
Contributor Author

mzellho commented Sep 7, 2016

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
Copy link
Member

I'm pretty sure

mail/lib/mailbox.php

Lines 93 to 147 in 3249331

/**
* @param integer $from
* @param integer $count
* @param string $filter
*/
private function getSearchIds($from, $count, $filter) {
if ($filter instanceof Horde_Imap_Client_Search_Query) {
$query = $filter;
} else {
$query = new Horde_Imap_Client_Search_Query();
if ($filter) {
$query->text($filter, false);
}
}
if ($this->getSpecialRole() !== 'trash') {
$query->flag(Horde_Imap_Client::FLAG_DELETED, false);
}
$result = $this->conn->search($this->mailBox, $query, ['sort' => [Horde_Imap_Client::SORT_DATE]]);
$ids = array_reverse($result['match']->ids);
if ($from >= 0 && $count >= 0) {
$ids = array_slice($ids, $from, $count);
}
return new \Horde_Imap_Client_Ids($ids, false);
}
/**
* @param integer $from
* @param integer $count
*/
private function getFetchIds($from, $count) {
$q = new Horde_Imap_Client_Fetch_Query();
$q->uid();
$q->imapDate();
$result = $this->conn->fetch($this->mailBox, $q);
$uidMap = [];
foreach ($result as $r) {
$uidMap[$r->getUid()] = $r->getImapDate()->getTimeStamp();
}
// sort by time
uasort($uidMap, function($a, $b) {
return $a < $b;
});
if ($from >= 0 && $count >= 0) {
$uidMap = array_slice($uidMap, $from, $count, true);
}
return new \Horde_Imap_Client_Ids(array_keys($uidMap), false);
}
public function getMessages($from = 0, $count = 2, $filter = '') {
if (!$this->conn->capability->query('SORT') && (is_null($filter) || $filter === '')) {
$ids = $this->getFetchIds($from, $count);
} else {
$ids = $this->getSearchIds($from, $count, $filter);
}
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
Copy link
Contributor Author

mzellho commented Sep 7, 2016

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
Copy link
Member

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
Copy link
Contributor Author

mzellho commented Sep 7, 2016

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

@zeugmatis
Copy link

zeugmatis commented Sep 7, 2016

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
Copy link
Contributor Author

mzellho commented Sep 7, 2016

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
Copy link
Member

What? Seriously? 😠

I knew not all servers support SORT, so I've added the check at

if (!$this->conn->capability->query('SORT') && (is_null($filter) || $filter === '')) {
.

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
Copy link
Member

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
Copy link
Contributor Author

mzellho commented Sep 7, 2016

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
Copy link
Member

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 💃

@ChristophWurst
Copy link
Member

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

@zeugmatis
Copy link

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
Copy link

lock bot commented Nov 21, 2018

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.

@lock lock bot locked and limited conversation to collaborators Nov 21, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants