Closed Bug 1986367 Opened 11 months ago Closed 4 months ago

Intermittent delay in smtp protocol exchange while sending messages

Categories

(MailNews Core :: Networking: SMTP, defect)

Product:
MailNews Core
Component:
Networking: SMTP
Version:
Thunderbird 143
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: 52qtuqm9, Unassigned)

References

Details

I am seeing relatively frequent, intermittent delays in my email delivery. After I type Ctrl-Enter or click the Send button, the window pops up telling me the message is being sent. Then sometimes it sends immediately, but sometimes there is a delay of 2 or even 4 or even as many as 7 seconds. I enabled SMTP logging and captured one of the delays:

18:41:11.562 mailnews.smtp: C: STARTTLS SmtpClient.sys.mjs:683:19
18:41:11.574 mailnews.smtp: S: 220 2.0.0 Ready to start TLS SmtpClient.sys.mjs:452:17
18:41:11.575 mailnews.smtp: C: EHLO [192.168.4.24] SmtpClient.sys.mjs:683:19
18:41:17.894 mailnews.smtp: S: 250-[elided] Hello [elided] [[elided]], pleased to meet you SmtpClient.sys.mjs:452:17
250-ENHANCEDSTATUSCODES
250-PIPELINING
250-EXPN
250-VERB
250-8BITMIME
250-SIZE
250-AUTH LOGIN
250-DELIVERBY
250 HELP

Notice the >6-second delay between the timestamp on the EHLO line and the next Hello line.

The timestamps above make it looks like the delay is happening on the server, but that's not actually what happening. I ran strace on the sendmail process on the server while one of these delays was happening, and during the delay sendmail is actually waiting for data from Thunderbird:

813   11:22:10.354545 accept(7, {sa_family=AF_INET6, sin6_port=htons(43280), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "[elided], &sin6_addr), sin6_scope_id=0}, [28]) = 9
...
1301069 11:22:10.506737 read(9,  <unfinished ...>
1301069 11:22:17.504935 <... read resumed>"\24\3\3\0\1", 5) = 5

The first line above shows that the file descriptor of the SMTP socket is 9, and the lines excerpted from later in the log show a 7-second delay reading data from that socket.

I thought this might be a delay doing an OCSP certificate check, but I set security.OCSP.enabled to 0 and restarted Thunderbird and the problem kept happening.

I am at a loss to debug this further. Any suggestions?

xref bug 1965690
For more detailed debugging you'd probably have to add more logging to SmtpClient.sys.mjs

(In reply to Magnus Melin [:mkmelin] from comment #1)

xref bug 1965690

What do you think the relevance of that bug is to this one? It's not obvious to me.

For more detailed debugging you'd probably have to add more logging to SmtpClient.sys.mjs

Is there any way for me to replace SmtpClient.sys.mjs in a Thunderbird beta install, overriding the version in omni.ja, without having to repeatedly repack omni.ja itself with the new version of the file in it?

Just that it was worked on recently, (and the retry-mechanism there could be why it eventually works, with a delay.

It's probably easiest do a self-compile. You can choose to use an artifact build (it's fast to build and set up), and run with --purgecaches. Then changes you do to js will be picked up on restart.

All signs point to this being a delay inside the TCPSocket code which I'm not going to be able to debug at the SmtpClient.sys.mjs level.

I just saw an 18-second delay in my logs between when SmtpClient.sys.mjs thinks it sent the EHLO command to the server after STARTTLS finished, and when the server sent back the response to the EHLO command.

I added enough logging to SmtpClient.sys.mjs to confirm that the delay happens after SmtpClient.sys.mjs calls this.socket.send, i.e., after the client command data is handed off to TCPSocket to transmit to the server.

Fortunately, I was running tcpdump while all this was going on, so I captured the actual TCP packets from the perspective of the machine thunderbird is running on. And according to those packets, the client command was sent to the server after the 18-second delay, not before it:

Timing in Thunderbird:

07:07:06.762 mailnews.smtp: C: EHLO [[client private IP address]] SmtpClient.sys.mjs:686:19
07:07:06.762 mailnews.smtp: _sendCommand end SmtpClient.sys.mjs:692:17
07:07:06.762 mailnews.smtp: _actionSTARTTLS end SmtpClient.sys.mjs:1011:17
07:07:25.185 mailnews.smtp: S: 250-jik4.kamens.us Hello [client host name] [[client public IP address]], pleased to meet you

Timing in the network packet capture:

Time                            Source                          Destination                     Protocol        Length  Info
2025-09-02 07:07:06.725449      [client private IP address]     [server IP address]             SMTP    76      C: STARTTLS
2025-09-02 07:07:06.738208      [server IP address]             [client private IP address]     SMTP    96      S: 220 2.0.0 Ready to start TLS
2025-09-02 07:07:06.762822      [client private IP address]     [server IP address]             TLSv1.3 1940    Client Hello (SNI=email.kamens.us)
2025-09-02 07:07:06.799796      [client private IP address]     [server IP address]             TCP     492     [TCP Retransmission] 35274 → 587 [PSH, ACK] Seq=1480 Ack=330 Win=64512 Len=426 TSval=3773918230 TSecr=1503368339
2025-09-02 07:07:06.898225      [server IP address]             [client private IP address]     TCP     66      587 → 35274 [ACK] Seq=330 Ack=1906 Win=63488 Len=0 TSval=1503368380 TSecr=3773918193
2025-09-02 07:07:06.898229      [server IP address]             [client private IP address]     TLSv1.3 2615    Server Hello, Change Cipher Spec, Application Data, Application Data, Application Data, Application Data, Application Data
2025-09-02 07:07:06.898229      [server IP address]             [client private IP address]     TCP     1167    [TCP Retransmission] 587 → 35274 [PSH, ACK] Seq=1778 Ack=1906 Win=63488 Len=1101 TSval=1503368440 TSecr=3773918193
2025-09-02 07:07:06.898299      [client private IP address]     [server IP address]             TCP     78      35274 → 587 [ACK] Seq=1906 Ack=2879 Win=62464 Len=0 TSval=3773918328 TSecr=1503368381 SLE=1778 SRE=2879
2025-09-02 07:07:06.908891      [server IP address]             [client private IP address]     TCP     78      [TCP Dup ACK 13#1] 587 → 35274 [ACK] Seq=2879 Ack=1906 Win=63488 Len=0 TSval=1503368510 TSecr=3773918230 SLE=1480 SRE=1906
2025-09-02 07:07:25.157275      [client private IP address]     [server IP address]             TLSv1.3 138     Change Cipher Spec, Application Data
2025-09-02 07:07:25.158073      [client private IP address]     [server IP address]             TLSv1.3 109     Application Data

If the tcpdump were running on the server then we could consider network packet delays as an explanation for the problem (though then I imagine you would see retransmits in the capture), but since the tcpdump is running on the client it seems clear from these logs that thunderbird isn't actually transmitting the EHLO command over the network to the server until 18 seconds after it logs that it has handed the command off to TCPSocket for transmission.

I think the TCPSocket stuff is probably too arcane and low-level for me to debug this any further in the time I have available. sigh

I attempted to do a regression window on this, which was challenging because it's a somewhat intermittent problem. However, I think there's a good chance I got it right.

Here's the end of the mozregression output. I think it's likely that the problem isn't in the changes shown in the pushlog, but rather in the changes between the versions of mozilla-central in the two builds, but I don't know how to tell what those two versions are or what's different between them.

451:48.94 INFO: Running comm-central build built on 2025-07-25 05:21:29.951000, revision e67e286c
451:49.06 WARNING: Skipping build adbaa28578a6: Unable to find build info using the taskcluster route 'comm.v2.comm-central.revision.adbaa28578a6909a5967942219456639773e1ba8.thunderbird.linux64-opt'
451:50.94 INFO: Launching /tmp/tmp_07wo4oj/thunderbird/thunderbird
451:50.95 INFO: Application command: /tmp/tmp_07wo4oj/thunderbird/thunderbird --allow-downgrade -profile /tmp/tmpztaf46hn
451:50.95 INFO: application_buildid: 20250725043758
451:50.95 INFO: application_changeset: e67e286c9296ddf2f96cb6ffaef30f39e10303f1
451:50.95 INFO: application_name: Thunderbird
451:50.95 INFO: application_profile: Thunderbird
451:50.95 INFO: application_repository: https://hg.mozilla.org/comm-central
451:50.95 INFO: application_version: 143.0a1
Was this integration build good, bad, or broken? (type 'good', 'bad', 'skip', 'retry' or 'exit' and press Enter): bad
452:59.26 INFO: Narrowed integration regression window from [1303d19b, 3be38fdc] (5 builds) to [1303d19b, e67e286c] (4 builds) (~2 steps left)
452:59.26 INFO: Pushlog:
https://hg.mozilla.org/comm-central/pushloghtml?fromchange=1303d19b8800ec0f52acb4b615af15d23e897538&tochange=e67e286c9296ddf2f96cb6ffaef30f39e10303f1

452:59.26 INFO: Using local file: /tmp/tmpz52ah3qi/337a3f0e9290--comm-central--target.tar.xz (downloaded in background)
452:59.26 INFO: Running comm-central build built on 2025-07-24 23:17:18.162000, revision 337a3f0e
452:59.53 WARNING: Skipping build 2bf7e88d8cea: Unable to find build info using the taskcluster route 'comm.v2.comm-central.revision.2bf7e88d8cea93021023db870db98fcfbfa91c88.thunderbird.linux64-opt'
453:01.26 INFO: Launching /tmp/tmpg0m06vc6/thunderbird/thunderbird
453:01.26 INFO: Application command: /tmp/tmpg0m06vc6/thunderbird/thunderbird --allow-downgrade -profile /tmp/tmpztaf46hn
453:01.26 INFO: application_buildid: 20250724221952
453:01.26 INFO: application_changeset: 337a3f0e92900fed5f829874b5b79fa5545f0c98
453:01.26 INFO: application_name: Thunderbird
453:01.26 INFO: application_profile: Thunderbird
453:01.26 INFO: application_repository: https://hg.mozilla.org/comm-central
453:01.26 INFO: application_version: 143.0a1
Was this integration build good, bad, or broken? (type 'good', 'bad', 'skip', 'retry', 'back' or 'exit' and press Enter): good
551:37.91 INFO: Narrowed integration regression window from [1303d19b, e67e286c] (3 builds) to [337a3f0e, e67e286c] (2 builds) (~1 steps left)
551:37.91 INFO: No more integration revisions, bisection finished.
551:37.91 INFO: Last good revision: 337a3f0e92900fed5f829874b5b79fa5545f0c98
551:37.91 INFO: First bad revision: e67e286c9296ddf2f96cb6ffaef30f39e10303f1
551:37.91 INFO: Pushlog:
https://hg.mozilla.org/comm-central/pushloghtml?fromchange=337a3f0e92900fed5f829874b5b79fa5545f0c98&tochange=e67e286c9296ddf2f96cb6ffaef30f39e10303f1
Status: NEW → UNCONFIRMED
Ever confirmed: false
See Also: → 1993576

What's that, you say? A significant bug that I reported months ago when it appeared in beta, because after all the whole point of people like me running beta is so that we can find and report significant bugs before they get released and impact the whole world, has now been released and is impacting the whole world because no one investigated the bug after I reported it?

Wow, what a surprise.

I tried to warn y'all that this was coming.

*sigh*

Thanks for the regression testing. I also don't see anything in "m-c changes should be this https://hg-edge.mozilla.org/mozilla-central/pushloghtml?startdate=2025-06-25+00%3A00&enddate=2025-06-25+08%3A%3A00" :(

Gene, is anything familiar here?

Flags: needinfo?(gds)

Hi Wayne, I probably won't be able to look at this in detail during holiday so might be Monday or a bit later. But, no, I've never noticed this problem before.
Has reporter tried TB with the fix referenced above: bug 1993576? I realize it's not the exact same thing but the low level fix in the network stack might affect this.
Other questions for reporter Jonathan:

About what % of time do you notice this delay?
Does it ever happen on the first message sent after tb restart?
Do you see it with other servers than Sendmail?
Do you see it with the current daily build?

I have not seen this issue in recent betas. I imagine whatever was broken in m-c has been fixed.

Thanks for the update

Status: UNCONFIRMED → RESOLVED
Closed: 4 months ago
Flags: needinfo?(gds)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.