Deltachat-android: Sending and receiving mail on Android fails with error message "Future timed out"

Created on 25 Sep 2020  路  34Comments  路  Source: deltachat/deltachat-android

  • 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.

bug

Most helpful comment

@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

All 34 comments

@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...

@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.

@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.

@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.

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)

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

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 I can confirm that it works with v1.13.4 - thank you! I'm curious, what was the cause of the issue?

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.

@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.

@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).

@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  -



md5-eb2147816695f79c1e18cb789ad32daf



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

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

@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

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).

@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

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

@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.

@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

@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

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?

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.

@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...

@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.

@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?

@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

@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?

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?

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

Related issue: https://github.com/sfackler/rust-native-tls/issues/140

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

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.

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?

@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.

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

Was this page helpful?
0 / 5 - 0 ratings

Related issues

r10s picture r10s  路  4Comments

adbenitez picture adbenitez  路  4Comments

csb0730 picture csb0730  路  4Comments

BoFFire picture BoFFire  路  4Comments

escoand picture escoand  路  4Comments