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

Sending and receiving mail on Android fails with error message "Future timed out" #1631

Closed
ghost opened this issue Sep 25, 2020 · 34 comments
Closed
Labels

Comments

@ghost
Copy link

ghost commented Sep 25, 2020

  • Operating System (Linux/Mac/Windows/iOS/Android): Android 10
  • Delta Chat Version: 1.12.5
  • Expected behavior: Messages are sent and retrieved successfully.
  • Actual behavior: Sending and receiving mails fails with error message "Future timed out"
  • Steps to reproduce the problem:
  1. Install DeltaChat v1.12.5 from Google Play Store.
  2. Import a backup from DeltaChat on Windows.
  3. Send a test message in the "Saved messages" chat.
  4. Wait for the error message to appear.
  • Screenshots:

error

Edit: This bug seems to be present in the beta version v1.13.2 as well.

@gerryfrancis
Copy link
Contributor

gerryfrancis commented Sep 25, 2020

@WhaleHub Thanks for your report.

Import a backup from DeltaChat on Windows.

I do not know if this is intended, it would be a surprise to me if this worked out well...

@ghost
Copy link
Author

ghost commented Sep 25, 2020

@WhaleHub Thanks for your report.

Import a backup from DeltaChat on Windows.

I do not know if this is intended, it would be a surprise for me if this worked out well...

It has always worked fine for me in the past.

@r10s r10s added the bug label Sep 25, 2020
@ghost
Copy link
Author

ghost commented Sep 30, 2020

@gerryfrancis I tried logging into the app manually without a backup just now and DeltaChat gets stuck on One moment... 20% with a spinning circle forever. I can create a mailbox for you on my mailserver if that would help narrow down the cause of the issue.

@gerryfrancis
Copy link
Contributor

@WhaleHub Thank you for your offer, although I am not a member of the development team. But maybe someone else of them is interested. Could you post an anonymized log that might have a little information why the login stalls? Thanks in advance.

@Hocuri
Copy link
Collaborator

Hocuri commented Oct 2, 2020

I'll give it a try. @WhaleHub can you send it to hocuri at gmx .de? (writing my address in a weird way to maybe confuse spambots)

@ghost
Copy link
Author

ghost commented Oct 2, 2020

@Hocuri Thanks! I just sent you an email with the credentials for your test account.

@Hocuri
Copy link
Collaborator

Hocuri commented Oct 2, 2020

Just tried it, I can reproduce the problem with the current releases but it works fine with the current master. If you don't want to wait for the next release, https://testrun.org/deltachat-gplay-release-1.13.4.apk works fine already.

@Hocuri Hocuri closed this as completed Oct 2, 2020
@ghost
Copy link
Author

ghost commented Oct 2, 2020

@Hocuri I can confirm that it works with v1.13.4 - thank you! I'm curious, what was the cause of the issue?

@Hocuri
Copy link
Collaborator

Hocuri commented Oct 2, 2020

I don't know, lots of things were improved for configuration. E.g. some additional configurations are tried now, maybe DC just hadn't tried the right one. "Future timed out" seems to be a very general error message like "the server did not respond" -> Timeout.

@ghost
Copy link
Author

ghost commented Oct 2, 2020

@Hocuri It sadly looks like I spoke too soon. After installing DeltaChat 1.13.4, it was able to find the correct settings on my first login attempt, but then when trying to send a message, I received the "Future timed out" error message again. I reset the app and tried again and this time it failed to find the right settings via autoconfig again and had me stuck on the login screen.

@Hocuri Hocuri reopened this Oct 2, 2020
@Hocuri
Copy link
Collaborator

Hocuri commented Oct 4, 2020

@WhaleHub I could not reproduce this. Using your credentials again, I could perfectly fine send a message. Some of the messages I sent took a bit longer than usual (~10s instead of ~1s until the first green checkmark appears) but that might as well have been my flaky internet or because your server is not so fast or whatever.

There is an archive at https://download.delta.chat/android/ but we changed so much in every version, I don't think I will be able to guess the cause if I know which version introduced this (thx for the offer, anyway).

What would help me is a log from right after this happened (via ADB or at Settings->Advanced->View log).

@ghost
Copy link
Author

ghost commented Oct 4, 2020

@Hocuri I've attached five log files to this comment. Logs A and B were saved immediately after login attempts that took two and four minutes respectively. When I examined these log files, the following lines stood out to me:

Log A: deltachat-log-20201004-154359.txt

10-04 15:41:21.372  9768  9808 I DeltaChat: src/configure/mod.rs:81: Configure ...
10-04 15:41:21.375  9768  9808 I DeltaChat: src/configure/mod.rs:442: checking internal provider-info for offline autoconfig
10-04 15:41:21.375  9768  9808 I DeltaChat: src/configure/mod.rs:484: no offline autoconfig found
10-04 15:41:21.375  9768  9808 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 15:43:28.737  9768  9808 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 15:43:28.748  9768  9808 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 15:43:42.299  9768  9808 I DeltaChat: src/configure/mod.rs:500: Trying: imap: [email protected]@mail.datahoarder.dev:993 security=SSL certificate_checks=automatic oauth2=false
10-04 15:43:42.310  9768  9808 I DeltaChat: src/configure/mod.rs:525: Trying: smtp: [email protected]@mail.datahoarder.dev:465 security=SSL certificate_checks=automatic oauth2=false
10-04 15:43:42.709  9768  9808 I DeltaChat: src/configure/mod.rs:509: success: imap: [email protected]@mail.datahoarder.dev:993 security=SSL certificate_checks=automatic oauth2=false
10-04 15:43:42.736  9768  9808 I DeltaChat: src/configure/mod.rs:534: success: smtp: [email protected]@mail.datahoarder.dev:465 security=SSL certificate_checks=automatic oauth2=false

Log B: deltachat-log-20201004-161145.txt

10-04 16:07:19.945 10739 10779 I DeltaChat: src/configure/mod.rs:81: Configure ...
10-04 16:07:19.948 10739 10779 I DeltaChat: src/configure/mod.rs:442: checking internal provider-info for offline autoconfig
10-04 16:07:19.948 10739 10779 I DeltaChat: src/configure/mod.rs:484: no offline autoconfig found
10-04 16:07:19.948 10739 10779 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 16:09:27.281 10739 10779 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 16:09:27.281 10739 10779 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 16:11:34.640 10739 10779 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 16:11:34.641 10739 10779 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/autodiscover/autodiscover.xml
10-04 16:11:34.905 10739 10779 W DeltaChat: src/configure/auto_outlook.rs:198: XML error at position 4022
10-04 16:11:34.906 10739 10779 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autodiscover.datahoarder.dev/autodiscover/autodiscover.xml
10-04 16:11:35.156 10739 10779 W DeltaChat: src/configure/auto_outlook.rs:198: XML error at position 121
10-04 16:11:35.157 10739 10779 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.thunderbird.net/v1.1/datahoarder.dev
10-04 16:11:35.615 10739 10779 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.thunderbird.net/v1.1/datahoarder.dev
10-04 16:11:35.618 10739 10779 I DeltaChat: src/configure/mod.rs:500: Trying: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 16:11:35.618 10739 10779 I DeltaChat: src/configure/mod.rs:525: Trying: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 16:11:35.963 10739 10779 I DeltaChat: src/configure/mod.rs:534: success: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 16:11:36.027 10739 10779 I DeltaChat: src/configure/mod.rs:509: success: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false

It looks like DeltaChat, for whatever reason, gets stuck on trying to fetch the autoconfig information for my mail account from the standardized URLs for several minutes and only infrequently succeeds on one of them and sometimes fails on both of them when both URLs should work instantly. The timeout duration should be significantly shorter than two minutes in any case.

You can visit the two URLs in the browser or fetch them via curl and see that they return the identical content immediately.

whalehub@pdh:~# curl -sSL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder.dev | sha256sum
69b948b0763b7f539c7a77f7d3714da001d337871ea7a2a59670c5dcdfeb2ea3  -
whalehub@pdh:~# curl -sSL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev | sha256sum
69b948b0763b7f539c7a77f7d3714da001d337871ea7a2a59670c5dcdfeb2ea3  -

Thunderbird, DeltaChat on Windows (see below) and AquaMail on Android all have no problem fetching these URL instantly, which leads me to think that the issue must be somewhere in DeltaChat for Android.

Log C: 2020-10-04-16-29-04.log

2020-10-04T14:29:09.580Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\mod.rs:69: Configure ..."
2020-10-04T14:29:09.580Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\mod.rs:392: checking internal provider-info for offline autoconfig"
2020-10-04T14:29:09.580Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\mod.rs:442: no offline autoconfig found"
2020-10-04T14:29:09.581Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\read_url.rs:10: Requesting URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev"
2020-10-04T14:29:09.714Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\mod.rs:178: Got autoconfig: unset imap:[email protected]:0:mail.datahoarder.dev:993:cert_automatic smtp:[email protected]:0:mail.datahoarder.dev:465:cert_automatic IMAP_SSL 0x200SMTP_SSL 0x20000"
2020-10-04T14:29:09.714Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\mod.rs:532: Trying: imap: [email protected]@mail.datahoarder.dev:993 flags=0x20204 certificate_checks=automatic"
2020-10-04T14:29:10.083Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\mod.rs:535: success: imap: [email protected]@mail.datahoarder.dev:993 flags=0x20204 certificate_checks=automatic"
2020-10-04T14:29:10.084Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\mod.rs:591: Trying: smtp: [email protected]@mail.datahoarder.dev:465 flags: 0x20204"
2020-10-04T14:29:10.352Z	core/event            	INFO		"DC_EVENT_INFO"	0	"src\\configure\\mod.rs:597: success: smtp: [email protected]@mail.datahoarder.dev:465 flags: 0x20204"

The last two log files were saved immediately after I received the "Future timed out" error message when I tried to send a message after login attempts A and B.

Log D: deltachat-log-20201004-154505.txt

Log E: deltachat-log-20201004-161238.txt

@Hocuri
Copy link
Collaborator

Hocuri commented Oct 4, 2020

@WhaleHub but that's version 1.12 again! Didn't you install version 1.13.4?

@ghost
Copy link
Author

ghost commented Oct 4, 2020

@Hocuri Why do you think it's version 1.12?

Log A: app=Delta Chat 1.13.4-gplay
Log B: app=Delta Chat 1.13.4-gplay
Log D: app=Delta Chat 1.13.4-gplay
Log E: app=Delta Chat 1.13.4-gplay

@Hocuri
Copy link
Collaborator

Hocuri commented Oct 4, 2020

Sry, my fault, I must have opened an old version of the logs.

Thanks for the logs, unfortunately I realized that our logs are not very good at this point. I'm afraid we have to improve them first if we want to find the cause (in #1967).

@ghost
Copy link
Author

ghost commented Oct 4, 2020

@Hocuri No worries. I built DeltaChat from source with your commit and made a few login attempts again, but the error messages don't appear to be much more useful.

Log A: deltachat-log-20201004-190849.txt

10-04 19:08:14.211 18156 18198 I DeltaChat: src/configure/mod.rs:81: Configure ...
10-04 19:08:14.222 18156 18198 I DeltaChat: src/configure/mod.rs:443: checking internal provider-info for offline autoconfig
10-04 19:08:14.222 18156 18198 I DeltaChat: src/configure/mod.rs:485: no offline autoconfig found
10-04 19:08:14.223 18156 18198 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 19:08:19.262 18156 18198 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev: Connection reset by peer (os error 104)
10-04 19:08:19.263 18156 18198 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 19:08:24.298 18156 18198 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev: Connection reset by peer (os error 104)
10-04 19:08:24.299 18156 18198 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/autodiscover/autodiscover.xml
10-04 19:08:29.333 18156 18198 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://datahoarder.dev/autodiscover/autodiscover.xml: Connection reset by peer (os error 104)
10-04 19:08:29.334 18156 18198 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autodiscover.datahoarder.dev/autodiscover/autodiscover.xml
10-04 19:08:34.368 18156 18198 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autodiscover.datahoarder.dev/autodiscover/autodiscover.xml: Connection reset by peer (os error 104)
10-04 19:08:34.370 18156 18198 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.thunderbird.net/v1.1/datahoarder.dev
10-04 19:08:39.396 18156 18198 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.thunderbird.net/v1.1/datahoarder.dev: Connection reset by peer (os error 104)
10-04 19:08:39.396 18156 18198 I DeltaChat: src/configure/mod.rs:501: Trying: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:08:39.397 18156 18198 I DeltaChat: src/configure/mod.rs:526: Trying: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:08:40.432 18156 18198 I DeltaChat: src/configure/mod.rs:535: success: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:08:40.513 18156 18198 I DeltaChat: src/configure/mod.rs:510: success: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false

Log B: deltachat-log-20201004-190652.txt

10-04 19:04:32.251 17680 17721 I DeltaChat: src/configure/mod.rs:81: Configure ...
10-04 19:04:32.256 17680 17721 I DeltaChat: src/configure/mod.rs:443: checking internal provider-info for offline autoconfig
10-04 19:04:32.256 17680 17721 I DeltaChat: src/configure/mod.rs:485: no offline autoconfig found
10-04 19:04:32.256 17680 17721 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 19:06:39.752 17680 17721 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev: Connection timed out (os error 110)
10-04 19:06:39.755 17680 17721 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 19:06:40.153 17680 17721 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate)
10-04 19:06:40.154 17680 17721 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/autodiscover/autodiscover.xml
10-04 19:06:40.327 17680 17721 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://datahoarder.dev/autodiscover/autodiscover.xml: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate)
10-04 19:06:40.327 17680 17721 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autodiscover.datahoarder.dev/autodiscover/autodiscover.xml
10-04 19:06:40.520 17680 17721 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autodiscover.datahoarder.dev/autodiscover/autodiscover.xml: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate)
10-04 19:06:40.521 17680 17721 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.thunderbird.net/v1.1/datahoarder.dev
10-04 19:06:40.885 17680 17721 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.thunderbird.net/v1.1/datahoarder.dev: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate)
10-04 19:06:40.908 17680 17721 I DeltaChat: src/configure/mod.rs:526: Trying: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:06:40.909 17680 17721 I DeltaChat: src/configure/mod.rs:501: Trying: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:06:41.829 17680 17721 I DeltaChat: src/configure/mod.rs:510: success: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:06:42.422 17680 17721 I DeltaChat: src/configure/mod.rs:535: success: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false

Log C: deltachat-log-20201004-185550.txt

10-04 18:50:28.253 16571 16612 I DeltaChat: src/configure/mod.rs:81: Configure ...
10-04 18:50:28.259 16571 16612 I DeltaChat: src/configure/mod.rs:443: checking internal provider-info for offline autoconfig
10-04 18:50:28.259 16571 16612 I DeltaChat: src/configure/mod.rs:485: no offline autoconfig found
10-04 18:50:28.259 16571 16612 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 18:52:35.680 16571 16612 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.datahoarder.dev/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev: Connection timed out (os error 110)
10-04 18:52:35.686 16571 16612 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev
10-04 18:54:43.028 16571 16612 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://datahoarder.dev/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=deltachat%40datahoarder%2Edev: Connection timed out (os error 110)
10-04 18:54:43.030 16571 16612 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://datahoarder.dev/autodiscover/autodiscover.xml
10-04 18:54:45.306 16571 16612 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://datahoarder.dev/autodiscover/autodiscover.xml: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate)
10-04 18:54:45.307 16571 16612 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autodiscover.datahoarder.dev/autodiscover/autodiscover.xml
10-04 18:54:45.615 16571 16612 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autodiscover.datahoarder.dev/autodiscover/autodiscover.xml: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate)
10-04 18:54:45.616 16571 16612 I DeltaChat: src/configure/read_url.rs:10: Requesting URL https://autoconfig.thunderbird.net/v1.1/datahoarder.dev
10-04 18:54:46.336 16571 16612 I DeltaChat: src/configure/read_url.rs:15: Can't read URL https://autoconfig.thunderbird.net/v1.1/datahoarder.dev: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate)
10-04 18:54:46.338 16571 16612 I DeltaChat: src/configure/mod.rs:526: Trying: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 18:54:46.338 16571 16612 I DeltaChat: src/configure/mod.rs:501: Trying: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 18:54:46.891 16571 16612 I DeltaChat: src/configure/mod.rs:510: success: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 18:54:48.298 16571 16612 I DeltaChat: src/configure/mod.rs:535: success: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false

@Hocuri
Copy link
Collaborator

Hocuri commented Oct 4, 2020

I built DeltaChat from source with your commit

Great!

but the error messages don't appear to be much more useful.

not so great but least now we know why DC thinks it fails (whether this is the actual reason or not):
Connection reset by peer (os error 104): This means that the server sent an RST message, closing the connection. This could be because Delta Chat sent data when the server did not expect it or because the server is blocked for whatever reason
Connection timed out (os error 110): Server can't be reached?
error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate): Has a file and line (doesn't help much though)

I also wonder why there are so many different errors but anyway. And the xml parsing error does not even turn up.

Possible next steps:

  • Disable the provider db and try to login to another (popular) server using the same device. I could do a commit for this that you can install again (but not today)
  • use wireshark to see if there actually is an RST message and if yes maybe see why it was sent

@gerryfrancis
Copy link
Contributor

gerryfrancis commented Oct 5, 2020

@WhaleHub When I try to load the first file mentioned in the logs, https://datahoarder.dev/autodiscover/autodiscover.xml) , in a browser (e.g. Firefox), all I get is a blank page when I was expecting some "file not found error". Viewing the source of that site, I can see that actually a lot of HTML code is produced, and stuff like JS is loaded. I think there seems to be some kind of CMS that jumps in when some file does not exist, literally throwing lines of code on Delta Chat which just cannot do anything with it. Maybe you can get an idea of what might be going on with this information.

@gerryfrancis
Copy link
Contributor

@WhaleHub Looking at your config-v1.1.xml file, I recognized this:

<domain>%EMAILDOMAIN%</domain>

I guess the line should be corrected to this:

<domain>datahoarder.dev</domain>

More information on how to create an Autoconfig configuration file is available here: https://developer.mozilla.org/en-US/docs/Mozilla/Thunderbird/Autoconfiguration/FileFormat/HowTo

@ghost
Copy link
Author

ghost commented Oct 5, 2020

@gerryfrancis Thanks, I appreciate the suggestions. I just set up Nginx to return an explicit 404 for the URLs below and modified my config-v1.1.xml file (although the placeholder should be valid according to the wiki page), but the issue in DeltaChat sadly persists with the same error messages occurring in the logs (os error 104, os error 110 and the SSL one).

https://datahoarder.dev/autodiscover/autodiscover.xml
https://autodiscover.datahoarder.dev/autodiscover/autodiscover.xml

@gerryfrancis
Copy link
Contributor

gerryfrancis commented Oct 6, 2020

and modified my config-v1.1.xml file (although the placeholder should be valid according to the wiki page)

@WhaleHub Thanks for clarifying, because I already wanted to ask how the username is specified. (It could have been %EMAILLOCALPART% as well.) SSL certificate check is set to "Automatic", and, as @Hocuri has pointed out,

Connection timed out (os error 110): Server can't be reached?
error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:ssl/statem/statem_clnt.c:1915: (unable to get local issuer certificate)

So, it might be caused by a certificate check that fails due to the respective server being unavailable. Can you verify if some firewall probably blocks access to the other server used to check validity? Or, as an alternative: Could you disable certificate check temporarily?

@ghost
Copy link
Author

ghost commented Oct 6, 2020

So, it might be caused by a certificate check that fails due to the respective server being unavailable. Can you verify if some firewall probably blocks access to the other server used to check validity? Or, as an alternative: Could you disable certificate check temporarily?

@gerryfrancis My server is neither unavailable nor is there a firewall blocking access to it. As I've mentioned in previous comments, any and all mail clients I've tried, including DeltaChat for Windows, have no problems connecting to it and fetching the correct configuration from the autoconfig URLs. The only client that is having issues is DeltaChat for Android. My phone is connected to the same network as the desktop PC where DeltaChat for Windows is running and when I visit the autoconfig URLs in Chrome and Firefox on Android, they load instantly.

@gerryfrancis
Copy link
Contributor

@WhaleHub Well, then I think this is a Delta Chat issue. You have mentioned that the failure occurs after a backup has been imported. I just wonder if it is an important step to reproduce the behavior, maybe we have overseen something...

@ghost
Copy link
Author

ghost commented Oct 6, 2020

@gerryfrancis The only time I imported a backup was when I observed the failure that lead me to open this issue. Every subsequent test since then has been performed after resetting the app to stock (via "clear cache" and "clear storage") and logging in normally.

@gerryfrancis
Copy link
Contributor

gerryfrancis commented Oct 6, 2020

@WhaleHub Thanks for the information, so it is obvious that we can skip step 2 ("import a backup[...]") of your procedure that should reproduce the failure, right?

@ghost
Copy link
Author

ghost commented Oct 6, 2020

@gerryfrancis Well, there has to be something about my setup - I don't know what yet - that DeltaChat on Android is not accounting for because it's uncommon in some way. Since the issue occurs for me even without importing a backup, the steps to reproduce it right now are essentially just "install DeltaChat, log in and send a message to yourself" which has to be working fine for the vast majority of DeltaChat users, otherwise I wouldn't be the only one reporting the issue on here.

There are a number of things I can think of off the top of my head which most people using DeltaChat might not have:

  • a smartphone running Android 10
  • a dual stack setup (IPv4+IPv6) on their mail server [1]
  • a dual stack setup (IPv4+IPv6) at home
  • a server with autoconfig URLs set up
  • a server with autoconfig URLs which only support modern TLS versions and ciphers [2]
  • an autoconfig policy in which implicit TLS (465/993) is preferred over explicit TLS (587/143)
  • a mail server that supports DANE [3]
  • a mail server that supports MTA-STS [4]
  • a mail server which only supports modern TLS versions and ciphers [5]
  • a domain which is secured with DNSSEC [6]

@Hocuri You said that you were able to reproduce the issue with the credentials I sent you in the current version of DeltaChat for Android but that it worked fine for you on master, right? It might be worth looking through the commits that were made to the relevant components of DeltaChat between now and then to figure out why you can reproduce the issue in v1.12.5 but not in v1.13.4.

[1] https://internet.nl/mail/datahoarder.dev/423732/
[2] https://www.hardenize.com/report/datahoarder.dev/1602012349#www_tls
[3] https://www.hardenize.com/report/datahoarder.dev/1602012349#email_dane
[4] https://www.hardenize.com/report/datahoarder.dev/1602012349#email_mta_sts
[5] https://www.hardenize.com/report/datahoarder.dev/1602012349#email_tls
[6] https://www.hardenize.com/report/datahoarder.dev/1602012349#domain_dnssec

@gerryfrancis
Copy link
Contributor

gerryfrancis commented Oct 6, 2020

@WhaleHub Wow, that is a lot of useful information, thanks a lot! Although Delta Chat seems to connect fine with "datahoarder.dev" as logged here

[email protected] imap:[email protected]:***:datahoarder.dev:143:cert_automatic smtp:[email protected]:***:datahoarder.dev:587:cert_automatic AUTH_NORMAL 0x4

10-04 19:08:39.396 18156 18198 I DeltaChat: src/configure/mod.rs:501: Trying: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:08:39.397 18156 18198 I DeltaChat: src/configure/mod.rs:526: Trying: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:08:40.432 18156 18198 I DeltaChat: src/configure/mod.rs:535: success: smtp: [email protected]@datahoarder.dev:587 security=STARTTLS certificate_checks=automatic oauth2=false
10-04 19:08:40.513 18156 18198 I DeltaChat: src/configure/mod.rs:510: success: imap: [email protected]@datahoarder.dev:143 security=STARTTLS certificate_checks=automatic oauth2=false

, your autoconfig specifies the hostname for IMAP and SMTP differently:

<hostname>mail.datahoarder.dev</hostname>

Which is correct?

@gerryfrancis
Copy link
Contributor

gerryfrancis commented Oct 6, 2020

One more thing:

a server with autoconfig URLs which only support modern TLS versions and ciphers [2]

A quick TLS check on checktls.com has revealed:

SSLVersion in use: TLSv1_3

Now, the only thing that fails which I can read from the log files is accessing URLs, by using https. Who knows if Delta Chat can cope with TLS 1.3 already on https calls?

@link2xt
Copy link
Contributor

link2xt commented Oct 7, 2020

Who knows if Delta Chat can cope with TLS 1.3 already on https calls?

Related issue: sfackler/rust-native-tls#140

@gerryfrancis
Copy link
Contributor

@WhaleHub Any concerns about supporting TLS 1.2? Mozilla still support it in Firefox.

@ghost
Copy link
Author

ghost commented Oct 7, 2020

Which is correct?

@gerryfrancis The correct hostname is mail.datahoarder.dev.

Any concerns about supporting TLS 1.2? Mozilla still support it in Firefox.

@gerryfrancis As the links I posted in an earlier comment show, my server already supports both TLS 1.2 and TLS 1.3.

@gerryfrancis
Copy link
Contributor

gerryfrancis commented Oct 7, 2020

The correct hostname is mail.datahoarder.dev.

@WhaleHub Due to the lack of autoconfig, Delta Chat connects to datahoarder.dev, not mail.datahoarder.dev. I cannot say whether that might influence verification of certificate check or not.

As the links I posted in an earlier comment show, my server already supports both TLS 1.2 and TLS 1.3.

@WhaleHub Thanks, I should have noticed. Meanwhile I used ssllabs.com to compare OpenSSL handshakes with autoconfig.datahoarder.dev to those with posteo.de, which is my mail provider:

posteo.de:
grafik

mail.datahoarder.dev & autoconfig.datahoarder.dev:
grafik

Not sure if I am on the right track, but for me this raises another question: Do we support EC 384 key handshakes in Delta Chat, yet, not only for IMAP and SMTP but HTTPS, too?

@ghost
Copy link
Author

ghost commented Oct 15, 2020

@Hocuri @gerryfrancis Just FYI, this issue seems to have been caused by a peculiarity with the IPv6 implementation in my router (FRITZ!Box 6490). I'm not sure why it only affected this app and only on Android, but after adjusting the settings on the router (namely disabling "stealth mode" and "teredo filtering"), DeltaChat works again even with v1.12.5.

@ghost ghost closed this as completed Oct 15, 2020
@gerryfrancis
Copy link
Contributor

@WhaleHub My gosh!! Thank you for sharing this information, I am happy that it works for you now!

This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants