I did not receive messages for more than two hours

[agutierrez25249]

The messages went well, but I didn't receive anything in Delta, I checked my email from another mobile and the messages were, but Delta didn't receive them,
Log:
deltachat-log-20191216-212254.txt

[r10s]

according to the log, there is a crash in dc_perform_smtp_jobs()

there were some changes from 0.981 to 1.0, however, this would probably not affect this issue.

[link2xt]

@r10s The crash is inside SMTP connect(). We don't have unsafe unwraps inside deltachat::smtp, so it must be somewhere inside async-smtp. We need to eliminate all unwraps and similar panicking functions in async-smtp.

Also there is an expect_failed in the log below Imap::connect_configured. It was fixed in f81f3fb The log file says the version is beta.17, so it doesn't include this fix, it is included since beta.18. That IMAP crash is likely the reason you didn't receive anything. @hpk42 checked all IMAP code for other crashes similar to this when this fix was made, so IMAP shouldn't crash like this anymore.

[r10s]

@link2xt thanks for the detailed explanations. not sure about beta.17, that was the time github had some issues and the version in Cargo.toml was not updated. what a mess :) so not totally sure about that, https://github.com/deltachat/deltachat-android/tree/preview-v0.981.0/jni shows a beta.18

but i think @agutierrez25249 should definitely retry with 1.0, then we can be sure.

[link2xt]

not sure about beta.17

The logfile contains this line:

deltachat_core_version=v1.0.0-beta.17

[r10s]

yip, but afaik, the output of the logfile comes from the version from Cargo.toml - and at some point, this was not updated through an github failure (on commit did not made it to the upstream), so, in this case, this information may be unreliable.

but anyway, both, beta.17 and beta.18 versions are outdated :)

[M4ss1ck]

I tried to send a single message and in the meantime I received 11. It took more than 2 minutes to be delivered, I'm going to attach a log for you to see if this is normal. I'm using v1.0.1
deltachat-log-20191220-093756.txt

[link2xt]

I filtered SMTP log messages:

12-20 09:02:56.487  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:02:56.488  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:02:56.489  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3071, action SendMsgToSmtp started...
12-20 09:02:57.718  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:02:57.719  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...
12-20 09:03:08.697  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:03:08.698  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:03:08.698  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3072, action SendMsgToSmtp started...
12-20 09:03:09.888  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:03:09.889  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...
12-20 09:05:33.477  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:05:33.479  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:05:33.480  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3080, action SendMsgToSmtp started...
12-20 09:05:34.706  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:05:34.707  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...
12-20 09:09:44.161  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:09:44.169  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:09:44.170  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3087, action SendMsgToSmtp started...
12-20 09:10:44.173  9567  9596 W DeltaChat: ThreadId(8) src/job.rs:214: SMTP failed to send: future timed out
12-20 09:11:09.351 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:11:09.356 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3087, action SendMsgToSmtp started...
12-20 09:11:13.877 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3089, action SendMsgToSmtp started...
12-20 09:11:15.103 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3091, action SendMsgToSmtp started...
12-20 09:11:16.305 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:11:16.308 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...
12-20 09:11:16.308 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:549: SMTP-idle will not be started because of waiting jobs.
12-20 09:11:16.308 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:11:16.310 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:11:16.313 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:11:16.315 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...
12-20 09:14:40.331 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:14:40.332 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:14:40.333 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3102, action SendMsgToSmtp started...
12-20 09:14:41.572 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:14:41.573 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...
12-20 09:22:16.676 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:22:16.677 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:22:16.678 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3114, action SendMsgToSmtp started...
12-20 09:23:16.682 14223 14250 W DeltaChat: ThreadId(8) src/job.rs:214: SMTP failed to send: future timed out
12-20 09:23:51.539 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:23:51.542 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...
12-20 09:26:49.247 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:26:49.248 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:26:49.249 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3132, action SendMsgToSmtp started...
12-20 09:26:50.460 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:26:50.462 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...
12-20 09:34:42.605 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:571: SMTP-idle ended.
12-20 09:34:42.606 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:529: SMTP-jobs started...
12-20 09:34:42.608 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3147, action SendMsgToSmtp started...
12-20 09:35:42.610 14223 14250 W DeltaChat: ThreadId(8) src/job.rs:214: SMTP failed to send: future timed out
12-20 09:36:17.145 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:531: SMTP-jobs ended.
12-20 09:36:17.147 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:542: SMTP-idle started...

The most interesting parts:

12-20 09:09:44.170  9567  9596 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3087, action SendMsgToSmtp started...
12-20 09:10:44.173  9567  9596 W DeltaChat: ThreadId(8) src/job.rs:214: SMTP failed to send: future timed out
...
12-20 09:22:16.678 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3114, action SendMsgToSmtp started...
12-20 09:23:16.682 14223 14250 W DeltaChat: ThreadId(8) src/job.rs:214: SMTP failed to send: future timed out
...
12-20 09:34:42.608 14223 14250 I DeltaChat: ThreadId(8) src/job.rs:744: SMTP-job #3147, action SendMsgToSmtp started...
12-20 09:35:42.610 14223 14250 W DeltaChat: ThreadId(8) src/job.rs:214: SMTP failed to send: future timed out

Each time it takes almost exactly one minute to timeout, even though the timeout is 30 seconds. That is odd, probably async-smtp recovers some timeout error and only fails at the next one. We need to ensure we never try to recover a job from timeout errors.

It took more than 2 minutes to be delivered, I'm going to attach a log for you to see if this is normal.

That is strange. I don't even see in the logs where failed job is rescheduled. We probably want to add more logging to try_again_later function.

Another problem I see is that .disconnect() is a blocking function that may actually take some time trying to close TCP connection properly.

[link2xt]

@M4ss1ck Do you still experience this problem? Can we close the issue?