Closed tjareson closed 4 years ago
OCA\Mail\Exception\ServiceException: Sync failed: Mail server denied authentication.
I just debugged the exact same issue with a gmail account. There Google randomly started to block the app. So I had to allow less secure apps. This happens occasionally but I've not quite understood why.
In your case it's a bit strange that the app works sometimes. My wild guess would be that your provider might rate limit the number of requests and the initial population of the database cache (new in v1.3.0) dispatched (too) many IMAP commands. How much time passed between the app update and you opening the web interface? What type of cron do you use?
I think your guess is right. I just saw only now that messages are kept in a local cache now, so if every msg get retrieved with a separate login that would explain what's going on on the end of the provider. Meanwhile (like an hour later or so) it seems to work again. (And we have just 5 mailboxes with maybe 50 mails each) I guess bigger setups with maybe thousands of mails will probably face a more long lasting slow down. Regarding google: When I was migrating mailboxes in the past with thunderbird I often migrated like 5-10G of mails. At least I never saw any error msg from thunderbird that account access was denied. Not sure if the loading of mails can be handled in different ways?
So, I think I also ran into issues with another account now (how ironic this is happening after 2w of testing and stabilization …) and it sounds like a db issue: An exception occurred while executing 'UPDATE `oc_mail_messages` SET `flag_attachments` = ?, `preview_text` = ?, `structure_analyzed` = ?, `updated_at` = ? WHERE (BINARY `uid` = ?) AND (BINARY `mailbox_id` = ?)' with params [false, "", true, 1586969212, 8830, "2284"]:SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction
I guess bigger setups with maybe thousands of mails will probably face a more long lasting slow down. Regarding google: When I was migrating mailboxes in the past with thunderbird I often migrated like 5-10G of mails. At least I never saw any error msg from thunderbird that account access was denied. Not sure if the loading of mails can be handled in different ways?
I'm not saying that we have the best solution, but we spent quite some effort into optimizing this initialization process. We tested with accounts with 60-80k messages. It can take a few minutes then, but other clients behave similarly.
And we have just 5 mailboxes with maybe 50 mails each)
That should not really be an issue then :thinking:
Let me think about this a bit. If you are available for a bit of troubleshooting we could reset the cache of your account, enable all logs and try again to see what happens on IMAP.
When I had this behaviour I solely got the denied authentication msg in the logs, nothing else. I can help with debugging on Saturday, as during the week I cannot surely predict to what extent mail will be used...
No worries. I can just write down the steps and you do whenever fits your schedule.
Ok.
Let me think about this a bit. If you are available for a bit of troubleshooting we could reset the cache of your account, enable all logs and try again to see what happens on IMAP.
I have the same problem. Let me know if I can help to troubleshoot.
I think I'm affected by the same issue, it's TLS related, because connecting without TLS it disappears.
The mail server is Dovecot, TLS configuration on 993 is ok (I checked with openssl s_client
).
I enabled ssl_verbose log on dovecot, and it seems no ssl handshake is performed, resulting in a timeout:
Apr 15 21:43:26 mail dovecot: imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Apr 15 21:43:26 mail dovecot: imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Apr 15 21:43:26 mail dovecot: imap-login: Debug: SSL: where=0x10, ret=1: before SSL initialization [NEXTCLOUD_IP]
Apr 15 21:43:26 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization [NEXTCLOUD_IP]
Apr 15 21:43:26 mail dovecot: imap-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization [NEXTCLOUD_IP]
Apr 15 21:43:26 mail dovecot: auth: Debug: auth client connected (pid=1172)
Apr 15 21:43:46 mail dovecot: imap-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization [NEXTCLOUD_IP]
Apr 15 21:43:46 mail dovecot: imap-login: Debug: SSL error: SSL_accept() syscall failed: Success
Apr 15 21:43:46 mail dovecot: imap-login: Disconnected (no auth attempts in 20 secs): user=<>, rip=NEXTCLOUD_IP, lip=DOVECOT_IP, TLS handshaking: SSL_accept() syscall failed: Success, sessi
on=<EvbRiFmjPtvAqAIC>
it's TLS related
See https://github.com/nextcloud/mail/releases/tag/v1.1.4 :)
Let me know if I can help to troubleshoot.
Thanks! I'll write something tomorrow.
Btw, do you have access to your CLI? Then we could add a occ command to clear the cache. Might be easier than manual SQLs.
it's TLS related
See https://github.com/nextcloud/mail/releases/tag/v1.1.4 :)
Yes, but I'm quite sure about TLS configuration, checked with openssl s_client from nc host. Thunderbird, k-9 etc connect without problems.
I tried to downgrade to 1.1.4 and ssl handshake is correct (even if I get a "Request failed with status code 500", probably because db structure changed from 1.1.4 to 1.3.0):
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x10, ret=1: before SSL initialization [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client hello [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server hello [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write certificate [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write key exchange [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client key exchange [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read change cipher spec [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read finished [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write session ticket [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write change cipher spec [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write finished [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [NEXTCLOUD_IP]
Apr 15 22:50:31 mail dovecot: imap-login: Login: user=<roberto@resolutions.it>, method=PLAIN, rip=NEXTCLOUD_IP, lip=DOVECOT_IP, mpid=2018, TLS, session=<TGmKd1qjPN3AqAIC>
For some reason, after re-updating to 1.3.0, things started to work. I only had to delete multiple copies of my account which suddenly appeared on the web interface.
For some reason, after re-updating to 1.3.0, things started to work. I only had to delete multiple copies of my account which suddenly appeared on the web interface.
I can confirm, that I had the same behaviour yesterday with my Office365-Account, but my iCloud acct still doesn't work. To be more specific: Doesn't work means, that only the Inbox folder indexing isn't working, but i.e. the sent items are there and although it looks like it is not working at all, I'm able to send an email ... weird.
@ChristophWurst You are right - my reported issue seems to be the same or at least similar. I'll try to get tha logs tomorrow or during the weekend. I'm done for 2day.... 😐
I tried to downgrade to 1.1.4 and ssl handshake is correct (even if I get a "Request failed with status code 500", probably because db structure changed from 1.1.4 to 1.3.0):
Downgrades are not supported. Restoring a backup is the only way back.
I tried to downgrade to 1.1.4 and ssl handshake is correct (even if I get a "Request failed with status code 500", probably because db structure changed from 1.1.4 to 1.3.0):
Downgrades are not supported. Restoring a backup is the only way back.
OK. My aim was to test TLS connection only. As I reported, re-upgrading from 1.1.4 to 1.3.0 resulted in fixing my issues; don't ask me why.
And I'm very glad to use 1.3.0, speedup is huge. Very well done, congratulations.
And I'm very glad to use 1.3.0, speedup is huge. Very well done, congratulations.
Thank you. We really appreciate this :v:
Caused by Horde_Imap_Client_Exception: Mail server denied authentication.
I have had that on my private instance with the v1.3.0 prereleases as well. But only once and that was already a week ago. Not sure if this is a temporary failure (that can be ignored) or the real cause of this problem. Let's see if we can get more debugging info somehow.
This app offers an extensive logging system. Please enable debug mode and set the log level to debug in your admin settings. Then, try to reproduce your issue and take another look at data/nextcloud.log
and data/horde_imap.log
.
Things I'm most interested in is the IMAP log and the supposedly failed authentication. I read the Horde (abstraction lib we use for IMAP communication) code and it says Default to AUTHENTICATIONFAILED error (see RFC 5530[3]).
, so on IMAP it might say something more useful than just auth failed.
@ChristophWurst I have the same issue and already collected all debug logs. I've also applied #2912 patch and still having the issue (collected logs too). Where do I send them?
Where do I send them?
You can use https://gist.github.com/ or similar. Just makes sure no sensitive information is there, like the password, your email or a sensitive mailbox name. In doubt you can send me the link via email to christoph at nextcloud dot com.
@ChristophWurst secret gist link sent to mail, only sent logs after applying #2912 patch
Thanks a lot @scanom. The logs look clean. I can't find any signs of authentication errors. Also nextcloud.log shoulds successful syncs. Does the Mail server denied authentication.
show up anywhere?
@ChristophWurst after applying #2912 patch there is no Mail server denied authentication
message, but INBOX is stuck loading forever, there is no message. Other mail boxes work ok.
Could you inspect the requests sent to the server? What status code do they return? The ones that end with /sync
are the important ones here.
Status code 202, and on console enless loop: actions.js:433 (initial) sync is incomplete, retriggering
How many messages do you have in that mailbox?
Only 164, and before the loop there is an error:
ConsoleLogger.js:46 [INFO] mail: Mailbox not cached. Triggering initialization {app: "mail", uid: "EDITED", error: MailboxNotCachedError at t.convertAxiosError (https://EDITED/apps/mail/js/mail.js:1526…} actions.js:433 (initial) sync is incomplete, retriggering
Just before that Mailbox not cached
here is a request with status 400:
Request URL: https://EDITED/apps/mail/api/accounts/46/folders/SU5CT1g%3D/messages
Request Method: GET
Status Code: 400
That is all fine :)
1) Message list is fetched -> server detects the cache is not populated -> returns 400 2) Client detects 400 -> triggers sync 3) Sync is run, but not complete <- possible bug here 4) Client detects incomplete sync -> sends another request 5) Back to 3)
Please add
$this->logger->debug("findAll of " . $mailbox->getAccountId() . ":" . $mailbox->getName() . ", upper=$upper, all=$max");
As new line at L159 of lib/IMAP/MessageMapper.php
, like right before the return [
so it becomes this:
And check nextcloud.log for this new line.
Here you have:
{"reqId":"XphZaQzH-s-sBJgNPtjgTgAAAAI","level":0,"time":"2020-04-16T13:11:05+00:00","remoteAddr":"EDITED","user":"EDITED","app":"mail","method":"POST","url":"\/apps\/mail\/api\/accounts\/46\/folders\/SU5CT1g=\/sync","message":"findAll of 46:INBOX, upper=5001, all=17094","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/80.0.3987.163 Safari\/537.36","version":"17.0.5.0"}
findAll of 46:INBOX, upper=5001, all=17094
Put into an English sentence this means the app requested a batch of messages, of with the highest UID was 5001. However, the highest UID of that mailbox is 17094. Thus the logic correctly reports that the sync is not complete yet. Does that exact same mesage show up again when you leave the app open? It should keep trying to sync as we saw in your previous logs.
The same message endlessly, i kept the app trying to sync
Then please add
$this->logger->debug("min=$min max=$max total=$total totalRange=$totalRange estimatedPageSize=$estimatedPageSize upper=$upper");
To L133 like
Sorry if this is a bit weird but I don't know any other way to debug this until I can reproduce locally :speak_no_evil:
correction: please use $this->logger->debug("min=$min max=$max total=$total totalRange=$totalRange estimatedPageSize=$estimatedPageSize upper=$upper highestknown=$highestKnownUid");
as there is one more param I'm curious about
And here they are:
{"reqId":"XphgPW0fPlAINlkTZwbjYwAAAEw","level":0,"time":"2020-04-16T13:40:13+00:00","remoteAddr":"EDITED","user":"EDITED","app":"mail","method":"POST","url":"\/apps\/mail\/api\/accounts\/46\/folders\/SU5CT1g=\/sync","message":"min=16923 max=17097 total=175 totalRange=175 estimatedPageSize=5001 upper=5001 highestknown=","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/80.0.3987.163 Safari\/537.36","version":"17.0.5.0"} {"reqId":"XphgPW0fPlAINlkTZwbjYwAAAEw","level":0,"time":"2020-04-16T13:40:13+00:00","remoteAddr":"EDITED","user":"EDITED","app":"mail","method":"POST","url":"\/apps\/mail\/api\/accounts\/46\/folders\/SU5CT1g=\/sync","message":"findAll of 46:INBOX, upper=5001, all=17097","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit\/537.36 (KHTML, likeGecko) Chrome\/80.0.3987.163 Safari\/537.36","version":"17.0.5.0"}
Is this again tied to the message numbers? I remember a caching issue where an array was created with
That was issue #560 fixed with #752
Based on
min=16923 max=17097 total=175 totalRange=175 estimatedPageSize=5001 upper=5001 highestknown=
I think that the highest known UID is null
. Therefore the range of messages the fetch will be 1:5001
. That, however, won't match any messages as the lowest UID is 16923. There is an error in our logic. I just need to find it :mag:
In the browser console I see the following sermon repeated all over:
[DEBUG] mail: fetching envelopes Object { app: "mail", uid: "foxbow" } ConsoleLogger.js:42:18 [INFO] mail: Mailbox is locked Object { app: "mail", uid: "foxbow", error: MailboxLockedError } ConsoleLogger.js:46:18 (initial) sync is incomplete, retriggering actions.js:434:14 [.. repeats all over the place ..] [DEBUG] mail: fetching envelopes Object { app: "mail", uid: "foxbow" } ConsoleLogger.js:42:18 [ERROR] mail: Background sync failed: undefined Object { app: "mail", uid: "foxbow", error: MailboxLockedError
maybe it helps..
@ChristophWurst I came to the same conclusion. First time I doublechecked the variable as I wasn't expect it to be null, but IMHO that is the problem.
See https://github.com/nextcloud/mail/pull/2920. I think I got behind the problem. You can get the patch via https://patch-diff.githubusercontent.com/raw/nextcloud/mail/pull/2920.patch, maybe first replace your app with the original state from https://github.com/nextcloud/mail/releases/tag/v1.3.1 and then apply the patch over it.
In the meantime I'll write some unit tests to verify my fix :)
@ChristophWurst I can confirm that #2920 solves the issue, just applied the patch. Great work, and BTW this new version is awesome.
Thanks a lot for your testing and debugging help!
I'll release v1.3.2 soon.
@ChristophWurst Does the v1.3.2 fix the MailboxLockedError error?
@ChristophWurst Does the v1.3.2 fix the MailboxLockedError error?
Could you open a ticket for that? I don't think it does. But that is also not really an error but a technical necessity to prevent garbled data when more than one request attempts to synchronize. My colleague @rullzer noted that one of his accounts was locked and stayed in that state. This can only happen when there was an error and the process didn't get a chance to release the lock (it does so even in error cases but not when the process is killed). So please check your logs carefully and post them into the new ticket. I'll have a look tomorrow morning!
I just opened #2925 @ChristophWurst , thanks for your help
Expected behavior
Mail should get loaded and displayed when clicking on the header.
Actual behavior
The mail headers are getting loaded after minutes. When selecting an email it takes another 1-2 minutes, then it display "Not found Could not load your message" Occasionally the email get displayed like every 4th try or so.
Same mail account (IMAP account on MXROUTE) works with other mail clients (thunderbird, iPhone) w/o problems.
Mail app
Mail app version: 1.3.0
Mailserver or service: MXRoute (IMAP)
Server configuration
Operating system: Ubuntu server 16.04
Web server: Apache (Nextcloud Docker) and nginx reverse proxy
Database: MySQL 10.0.38
PHP version: 7.3.16
Nextcloud Version: official Nextcloud Docker 18.0.3
Client configuration
Browser: Opera, Google Chrome, Firefox
Operating system: Ubuntu 16.04, Win 10
Logfile content, when it doesn't work: OCA\Mail\Exception\ServiceException: Sync failed: Mail server denied authentication.
Caused by Horde_Imap_Client_Exception: Mail server denied authentication.