strangely delayed SMTP-connect (on desktop with main core of 2024-09-18)

[hpk42]

a roughly commented log and an by now often occuring smtp-sending delay.

/me sending a message on desktop in some chat

73303.9s [D]core/event: MsgsChanged 38 { chatId: 2643, kind: 'MsgsChanged', msgId: 617341 }
73303.9s [D]core/event: ChatlistChanged 38 { kind: 'ChatlistChanged' }
73303.9s [D]core/event: ChatlistItemChanged 38 { chatId: 2643, kind: 'ChatlistItemChanged' }
73304.3s [D]core/event: MsgsChanged 38 { chatId: 2643, kind: 'MsgsChanged', msgId: 0 }
73304.3s [D]core/event: ChatlistChanged 38 { kind: 'ChatlistChanged' }
73304.3s [D]core/event: ChatlistItemChanged 38 { chatId: 2643, kind: 'ChatlistItemChanged' }
73304.3s [i]core/event: 38 src/e2ee.rs:66: Peerstate for "xxx@REDACTED" is mutual.
73304.3s [D]core/event: MsgsChanged 38 { chatId: 2643, kind: 'MsgsChanged', msgId: 617341 }
73304.3s [D]core/event: ChatlistChanged 38 { kind: 'ChatlistChanged' }
73304.3s [D]core/event: ChatlistItemChanged 38 { chatId: 2643, kind: 'ChatlistItemChanged' }
73304.3s [i]core/event: 38 src/scheduler.rs:814: SMTP fake idle interrupted.
73304.3s [i]core/event: 38 src/smtp.rs:511: Selected rows from SMTP queue: [21506].
73304.3s [i]core/event: 38 src/smtp.rs:82: Closing stale connection.

there now is a message to be send and the smtp-connection was determined to be stale.

73304.3s [D]core/event: ConnectivityChanged 38 { kind: 'ConnectivityChanged' }
73304.3s [i]core/event: 38 src/smtp.rs:130: SMTP trying to connect to smtp.deltachat.de:465:tls.
73304.4s [i]core/event: 38 src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 131h 14m 48s or interrupt
73304.4s [i]core/event: 38 src/net/dns.rs:66: Resolved smtp.deltachat.de:465 into 85.13.163.218:465.
73304.4s [i]core/event: 38 src/smtp/connect.rs:86: Attempting SMTP connection to smtp.deltachat.de (85.13.163.218:465).

now this takes a long while. On the same computer i can connect to smtp.deltachat.de port 465 fine (via telnet).
But core's attempt seems to go nowhere ...

73311.9s [D]core/event: MsgsChanged 38 { chatId: 2643, kind: 'MsgsChanged', msgId: 617342 }
73311.9s [D]core/event: ChatlistChanged 38 { kind: 'ChatlistChanged' }
73311.9s [D]core/event: ChatlistItemChanged 38 { chatId: 2643, kind: 'ChatlistItemChanged' }
73316.8s [i]core/event: 38 src/e2ee.rs:66: Peerstate for "xxx@REDACTED" is mutual.
73316.8s [D]core/event: MsgsChanged 38 { chatId: 2643, kind: 'MsgsChanged', msgId: 0 }
73316.8s [D]core/event: ChatlistChanged 38 { kind: 'ChatlistChanged' }
73316.8s [D]core/event: ChatlistItemChanged 38 { chatId: 2643, kind: 'ChatlistItemChanged' }
73316.8s [D]core/event: MsgsChanged 38 { chatId: 2643, kind: 'MsgsChanged', msgId: 617343 }
73316.8s [D]core/event: ChatlistChanged 38 { kind: 'ChatlistChanged' }
73316.8s [D]core/event: ChatlistItemChanged 38 { chatId: 2643, kind: 'ChatlistItemChanged' }
73316.8s [i]core/event: 38 src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 131h 14m 36s or interrupt
73343.8s [i]core/event: 38 src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(482471)) }
73343.9s [D]core/event: ConnectivityChanged 38 { kind: 'ConnectivityChanged' }
73343.9s [D]core/event: ConnectivityChanged 38 { kind: 'ConnectivityChanged' }
73343.9s [i]core/event: 38 src/imap.rs:1240: Starting a full FETCH of message set "627012".
73343.9s [i]core/event: 38 src/imap.rs:1353: Passing message UID 627012 to receive_imf().
73344s [i]core/event: 38 src/receive_imf.rs:221: Receiving message "Mr.nOabE_MX0WO.BelU-FCPJ4z@localhost", seen=false...
73344s [i]core/event: 38 src/receive_imf.rs:789: Message is an MDN (TRASH).
73344s [i]core/event: 38 src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.
73344s [D]core/event: ContactsChanged 38 { contactId: 348, kind: 'ContactsChanged' }
73344s [i]core/event: 38 src/contact.rs:1850: Recently seen loop waiting for 0h 4m 10s or interrupt
73344s [i]core/event: 38 src/imap.rs:1395: Successfully received 1 UIDs.
73344s [i]core/event: 38 src/imap.rs:727: 1 mails read from "INBOX".
73344s [D]core/event: IncomingMsgBunch 38 { kind: 'IncomingMsgBunch' }
73344.2s [i]core/event: 38 src/imap/scan_folders.rs:31: Starting full folder scan
73344.3s [i]core/event: 38 src/imap.rs:525: No new emails in folder "Sent".
73344.3s [i]core/event: 38 src/imap.rs:525: No new emails in folder "archiv".
73344.3s [i]core/event: 38 src/imap.rs:525: No new emails in folder "INBOX/DeltaChat".
73344.4s [i]core/event: 38 src/imap.rs:525: No new emails in folder "Chats".
73344.7s [i]core/event: 38 src/imap.rs:525: No new emails in folder "Spam".
73344.7s [i]core/event: 38 src/imap.rs:525: No new emails in folder "INBOX".
73344.9s [D]core/event: ConnectivityChanged 38 { kind: 'ConnectivityChanged' }
73344.9s [D]core/event: ImapInboxIdle 38 { kind: 'ImapInboxIdle' }
73344.9s [i]core/event: 38 src/scheduler.rs:669: IMAP session supports IDLE, using it.
73344.9s [i]core/event: 38 src/imap/idle.rs:44: skip idle, got interrupt
73345s [i]core/event: 38 src/imap.rs:1073: Marked messages 627012 in folder INBOX as seen.
73345s [i]core/event: 38 src/imap.rs:525: No new emails in folder "INBOX".
73345.3s [D]core/event: ConnectivityChanged 38 { kind: 'ConnectivityChanged' }
73345.3s [D]core/event: ImapInboxIdle 38 { kind: 'ImapInboxIdle' }
73345.3s [i]core/event: 38 src/scheduler.rs:669: IMAP session supports IDLE, using it.
73345.4s [i]core/event: 38 src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state

seems network connectivity was fine for the incoming pipeline during the time smtp was attempted.

73364.4s [w]core/event: 38 src/smtp/connect.rs:111: Failed to connect to smtp.deltachat.de (85.13.163.218:465): timed out: timed out.
73364.5s [w]core/event: 38 src/smtp.rs:145: SMTP failed to connect: timed out: timed out.
73364.5s [w]core/event: 38 src/scheduler.rs:765: send_smtp_messages failed: Failed to send message: SMTP connection failure: SMTP failed to connect.

the smtp-connection attempt timed out after ~60 seconds, it seems.

73364.5s [i]core/event: 38 src/scheduler.rs:782: SMTP fake idle started.
73364.5s [D]core/event: ConnectivityChanged 38 { kind: 'ConnectivityChanged' }
73364.5s [i]core/event: 38 src/scheduler.rs:794: SMTP has messages to retry, planning to retry 30 seconds later.
73364.5s [i]core/event: 38 src/scheduler.rs:814: SMTP fake idle interrupted.
73364.5s [i]core/event: 38 src/smtp.rs:511: Selected rows from SMTP queue: [21506, 21507].
73364.5s [D]core/event: ConnectivityChanged 38 { kind: 'ConnectivityChanged' }
73364.5s [i]core/event: 38 src/smtp.rs:130: SMTP trying to connect to smtp.deltachat.de:465:tls.
73364.5s [i]core/event: 38 src/net/dns.rs:66: Resolved smtp.deltachat.de:465 into 85.13.163.218:465.
73364.5s [i]core/event: 38 src/smtp/connect.rs:86: Attempting SMTP connection to smtp.deltachat.de (85.13.163.218:465).
73364.8s [D]core/event: SmtpConnected 38 { kind: 'SmtpConnected', msg: 'SMTP-LOGIN as [email protected] ok' }

now it immediately re-connects and message sending succeeds afterwards immediately.

I don't think that my cable network connection changed. If this log does not help, please let me know what tcpdump or similar
command i should try to provide more info. thanks.

[link2xt]

What is the output of sysctl net.ipv4.tcp_syn_retries on your system?

I am pretty sure SYN should be retried by the kernel several times, so should not be easily lost.

The problem may be in the greeting protocol. SMTP requires that client waits for the banner immediately after connecting which results in problems similar to https://www.evanjones.ca/tcp-stuck-connection-mystery.html
If TLS connection is established, but the segment with the server banner 220 dd46606.kasserver.com ESMTP is lost, the server should resend the last TCP segment as it does not receive the ACK from the client. Otherwise the client will wait for the banner for 60 seconds and then timeout.

If lost banner segment is the case, it should be fixed server-side by enabling Tail Loss Probe to retransmit the banner (which is the last TCP segment sent, hence "tail").

This should be possible to confirm from tcpdump, but I also created a PR to add more logging so we can confirm the failure to read the banner from Delta Chat logs: #5985

[hpk42]

On Thu, Sep 19, 2024 at 04:57 -0700, link2xt wrote: What is the output of `sysctl net.ipv4.tcp_syn_retries` on your system?

`net.ipv4.tcp_syn_retries = 6`

[link2xt]

#5985 is now merged, so main should have better logs pointing to where exactly timeout happened.

[link2xt]

Another source of delay may be DNS, but in this case the logs say it is a connection timeout and DNS resolution took 0.1 s.
In any case, I made a PR to mostly exclude DNS delays: #6073