SMTP Timeouts (Allegedly Due to "Incorrect" QUIT Cleanup) after updating from 140.11.0esr to 140.11.1esr
Categories
(MailNews Core :: Networking: SMTP, defect)
Tracking
(Not tracked)
People
(Reporter: ceplaw, Unassigned)
References
Details
Attachments
(1 file)
|
25.41 KB,
text/plain
|
Details |
User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:152.0) Gecko/20100101 Firefox/152.0
Steps to reproduce:
(This is 140ESR, not offered in the Version dropdown)
Updated to 140.11.1ESR. The SMTP settings are for port 465, ssl/tls, normal password (as they have been for years). No other settings of any kind were changed, and the ISP has stated that no other updates/settings were done at their end. No Windows update, other software installation, etc. was done at my end.
Actual results:
Starting about 24 hours after the update, SMTP sends began timing out, and when not timing out taking upward of five seconds. The ISP believes that something on my client is causing the problem, and pointed to this sequence:
{date} 15:24:32 SMTP connection from ([internalipaddress]) [ipaddress]:50162 D=37s closed by QUIT
{date} 15:28:26 SMTP connection from [ipaddress]:50226 (TCP/IP connection count = 97)
claiming that this sequence indicates that Thunderbird is not "properly closing the connection to the system."
At about the same time, read/delete for e-mails already successfully retrieved visibly slowed down.
Expected results:
Either "proper closure" or another, related issue from the client (Thunderbird) end appears to be resulting in timeouts for SMTP sending. I strongly suspect a timing problem was inadvertantly introduced. Updating to 140.12.0ESR did NOT fix the problem.
|
||
Comment 1•1 month ago
|
||
Which version did you update FROM?
Anyway, can you try latest release, v152?
|
|
||
Comment 2•1 month ago
|
||
And if still an issue, provide an SMTP log. See https://wiki.mozilla.org/MailNews:Logging
I will not use the non-ESR releases at present. If I understand things correctly, 140.12.0ESR is largely equivalent to 152.0 main. (I have to do tech support/advisories for clients who, due to international issues, have to use ESR... and I'm NOT in favor of some of the paths of "new features" now being worked on, and don't wish to struggle with incomplete implementations.)
That said:
- The update that preceded the problem was from 140.11.0ESR to 140.11.1ESR, approximately 24 hours prior to the first noted problem.
- As clarification, the problem has persisted in 140.12.0ESR (I just had a full-one "connection refused due to time-out" an hour ago, immediate resend resulted in a nine-second send for a 12k all-text message), which was done a couple days ago as noted in the initial report.
- Cannot initiate any logging until this evening due to medical appointments (when there won't be any SMTP activity to log anyway).
- The slowness in the rest of the program is primarily visible when attempting to delete messages in the inbox. Size of message, number/presence/absence of attachments, and individual/enveloped addressing seem irrelevant. Prior to this, deletion of a message was virtually instantaneous; now it's a visible delay, half a second to up to two seconds. This has continued even with a fresh reboot with only Signal Desktop and Firefox also running (neither of which has had a relevant update).
- No new software has been installed or system settings changed, in particular no new security software (antivirus, firewall, etc.), for several months. The last non-fingerprint-identification update to the antivirus was the night prior to the problem arising (Windows Defender).
Log provided in "all" mode, now downgrading mode to "warn" (my default)
|
||
Comment 6•1 month ago
|
||
This is very likely a duplicate of bug 1965690. Either try 152 or wait for ESR 153. If this issue should still occur with newer versions we can reopen this report.
I disagree that this has been fully resolved without further testing, or that it duplicates the 1965690 bug. There's some overlap, and potential for a partial fix, but:
-
Per the suggested solution in '690 (comment/addition isn't numbered), I checked the two hidden configs:
mail.smtpserver.default.max_messages_per_connection was 10, changed to 1, will be monitoring this (which leads to the question of why "10" has remained the default value for a year after the '690 bug was reported, unless it affects something else which would mean this isn't actually a resolution)
mail.smtpserver.default.max_cached_connections was already set to 1
n.b. I neither use nor have installed the MailMerge add-on, and nothing in '690 explains why this problem cropped up for me only after updating to 140.11.1ESR. -
This change would not appear to have any explanation for the other performance issue from that update: General slowness of deleting (not moving) messages from the inbox after reading (whether or not previously read, whether or not including an attachment, regardless of message size). General usage has not changed. If some "index threshold" was crossed in that interim — implausible because it would also affect moving messages to folders and filter operation/speed — that suggests a problem with indexing that I can't see as related to the number/persistence of SMTP connections, but can see as related to failure to complete release of resources that appears to have manifested only with the 140.11.0 to 140.11.1 update.
Please reopen this bug until there's actual confirmation that the fix works on 140ESR (and 153ESR when it's available, and I fully intend to update to 153ESR immediately when it becomes available).(In reply to Hartmut Welpmann [:welpy-cw] from comment #6)
This is very likely a duplicate of bug 1965690. Either try 152 or wait for ESR 153. If this issue should still occur with newer versions we can reopen this report.
*** This bug has been marked as a duplicate of bug 1965690 ***
|
|
||
Comment 8•1 month ago
|
||
(In reply to CEP from comment #7)
I disagree that this has been fully resolved without further testing, or that it duplicates the 1965690 bug. There's some overlap, and potential for a partial fix, but:
- Per the suggested solution in '690 (comment/addition isn't numbered), I checked the two hidden configs:
You mean bug 1965690 comment 0.
mail.smtpserver.default.max_messages_per_connection was 10, changed to 1, will be monitoring this (which leads to the question of why "10" has remained the default value for a year after the '690 bug was reported, unless it affects something else which would mean this isn't actually a resolution)
The suggested solution is just a workaround. While the bug was fixed in the 142 cycle, it was not backported to ESR 140, see bug 1965690 comment 25.
mail.smtpserver.default.max_cached_connections was already set to 1
n.b. I neither use nor have installed the MailMerge add-on, and nothing in '690 explains why this problem cropped up for me only after updating to 140.11.1ESR.
There were no Thunderbird-specific fixes whatsoever between 140.11.0 and 140.11.1. On the other hand, 140.11.0 included several security fixes which might have affected this timing-wise, but apparently that version worked for you.
- This change would not appear to have any explanation for the other performance issue from that update: General slowness of deleting (not moving) messages from the inbox after reading (whether or not previously read, whether or not including an attachment, regardless of message size). General usage has not changed. If some "index threshold" was crossed in that interim — implausible because it would also affect moving messages to folders and filter operation/speed — that suggests a problem with indexing that I can't see as related to the number/persistence of SMTP connections, but can see as related to failure to complete release of resources that appears to have manifested only with the 140.11.0 to 140.11.1 update.
This is a different problem that might warrant another report.
Please reopen this bug until there's actual confirmation that the fix works on 140ESR (and 153ESR when it's available, and I fully intend to update to 153ESR immediately when it becomes available).
If switching to Release 152 isn't an option for you, I think temporarily reverting to 140.11.0, disabling automatic updates, and setting mail.smtpserver.default.max_messages_per_connection back to 10 might be the best way forward. If the problems you've reported are gone and don't come back after two or three days, we can fairly be sure that specific ESR update to 140.11.1 to be the culprit.
|
||
Comment 9•1 month ago
•
|
||
The smtp sending in the attached log looks typical. I assume there were no problems with sending when you recorded the log?
I have 140.11.1ESR installed and tried sending several message to gmail smtp server (as in your log) and record about the same thing with similar timing.
Starting about 24 hours after the update, SMTP sends began timing out, and when not timing out taking upward of five seconds.
Do you have any idea where in the sending process the "time out" is occurring. Is it while TB is trying to make a new connection or later on during the sending process? How long after you try to send does the timeout notification occur? Of course, you may need to catch the timeout while recording the smtp log on tb to know for sure.
Taking 5 seconds to send a message might not be an extreme time. It depends on how big the message is and if you have tb configured to save the sent message into a "Sent" folder which also takes network time if you are using IMAP.
The 5 second delay you see in the log for sending the QUIT command doesn't actually delay the message send time from what I can tell.
The ISP believes that something on my client is causing the problem, and pointed to this sequence:
{date} 15:24:32 SMTP connection from ([internalipaddress]) [ipaddress]:50162 D=37s closed by QUIT
{date} 15:28:26 SMTP connection from [ipaddress]:50226 (TCP/IP connection count = 97)
claiming that this sequence indicates that Thunderbird is not "properly closing the connection to the system."
Edit: Is this from the smtp server log? Why does it indicate a tb closing connection problem? Why is there a 4 minute gap between them?
Do you see the problem only with the "scrivenerserror" server or with other servers too (e.g., gmail)?
My understand is that the QUIT command is supposed to tell the server to close the connection.
Anyhow, if you can record a log containing the "5 second delay problem" or the "timeout" it might show something.
One more thing: Any chance you are queuing up several messages and using the "Send Later" feature? This may still cause the problem worked on in bug 1965690
Regarding the slow-down issues when you see the smtp problem, lets take one thing at a time.
|
Reporter | |
Comment 10•1 month ago
|
||
Responding to comments 8 and 9 together, as there's quite a bit of overlap:
Clarification on scope: No IMAP usage at all, this is all POP3 + SMTP. And it's not restricted to the domain whose SMTP server log I noted — it includes gmail, two other non-gmail-based domains, and one other gmail-based domain.
First, 36 hours of testing with that workaround enabled (Hartmut, comment 8) has resulted in a mean drop from 9 seconds to 6 seconds in the time between hitting "send" and disappearance of the "sending" message. This could be an artifact of testing on a weekend as much as anything else.
As far as opening a separate bug report is concerned, I was loathe to do so when both problems arose with the same update and concerned a sudden and clear slowdown. In my experience, that usually means that things are at minimum related — and a "security fix" providing additional rewriting protection of some kind would affect both of these (although affecting only deletion and not moving of existing messages is puzzling).
Second, I'm not equipped to see where in the process the timeouts are occurring (Gene, comment 9). My timing (separate "stopwatch") begins with hitting "send" and ends when the "send message" popup closes. I think we can probably rule out "it's just that popup" problems due to the timeouts from the SMTP server (as reported initially); those imply that the delay is some time after the connection-open request has been sent and acknowledged. That's as specific as I can get.
I do NOT ordinarily use the Send Later add-on, but during testing I did test it and encountered the same behavior. All of the specific results here are WITHOUT Send Later (queueing would tend to mask some potential causes).
I'm not sure what more can be recorded log-wise than was already provided; I need to know more specifically about what you're looking for and what parameters are needed for that log ("All" and "Warn" are not all that detailed...).
Finally, if there were significant-enough security issues to justify a program update to the ESR, I'm loathe to revert to a prior version. I never enable automatic updates for anything, including the OS — all updates are always under manual control/command, and I'm quite "reliable" on doing them, so I wouldn't have to turn off automatic updates when I did so during initial installation. Is there an anticipated release date for 153ESR that looks reasonably achievable? As mentioned in the initial report, I need to remain on the ESR pathway if at all possible; this bug is an annoyance for me, but thus far has not done more than that.
|
|
||
Comment 11•1 month ago
|
||
CEP, Can you explain more what this is about?
The ISP believes that something on my client is causing the problem, and pointed to this sequence:
{date} 15:24:32 SMTP connection from ([internalipaddress]) [ipaddress]:50162 D=37s closed by QUIT
{date} 15:28:26 SMTP connection from [ipaddress]:50226 (TCP/IP connection count = 97)
claiming that this sequence indicates that Thunderbird is not "properly closing the connection to the system."
Is this from the smtp server's log? Why does it indicate a tb closing connection problem? Why is there a 4 minute gap between them?
Also, please indicate which hosts the "ipaddress" strings are referring to.
Do you have any more server log data before or after these two entries?
I'm not sure what more can be recorded log-wise than was already provided; I need to know more specifically about what you're looking for and what parameters are needed for that log ("All" and "Warn" are not all that detailed...).
"All" loglevel is as detailed as it gets while "Warn" is not so much.
If you see a timeout while recording the log with level "All" it would show where in the send process it is occurring.
How often does it timeout vs. being slow to send and close the sending popups? Does restarting TB fix the issues (at least for a while)?
|
|
||
Comment 12•1 month ago
|
||
Another thing:
If you are not typically using the "Sent Later" feature (FWIW, it's not an add-on) when you see the problem, is there any chance you have more than one email compose windows open ready to sent and then quickly click the send button on each of them? Doing this fast enough could also cause the issue fixed in bug 1965690 (which wasn't released until 143.)
|
|
Reporter | |
Comment 13•1 month ago
|
||
(In reply to gene smith from comment #11)
CEP, Can you explain more what this is about?
The ISP believes that something on my client is causing the problem, and pointed to this sequence:
{date} 15:24:32 SMTP connection from ([internalipaddress]) [ipaddress]:50162 D=37s closed by QUIT
{date} 15:28:26 SMTP connection from [ipaddress]:50226 (TCP/IP connection count = 97)claiming that this sequence indicates that Thunderbird is not "properly closing the connection to the system."
Is this from the smtp server's log? Why does it indicate a tb closing connection problem? Why is there a 4 minute gap between them?
Also, please indicate which hosts the "ipaddress" strings are referring to.
Do you have any more server log data before or after these two entries?
That is the SMTP server's log. I have masked ALL IP addresses (both internal and my own). I have no clue why there's a 4-minute gap. I don't have more server-log data.
I'm not sure what more can be recorded log-wise than was already provided; I need to know more specifically about what you're looking for and what parameters are needed for that log ("All" and "Warn" are not all that detailed...).
"All" loglevel is as detailed as it gets while "Warn" is not so much.
If you see a timeout while recording the log with level "All" it would show where in the send process it is occurring.
How often does it timeout vs. being slow to send and close the sending popups? Does restarting TB fix the issues (at least for a while)?
Actual full-timeout-with-required-resend has been fairly constant at about 10% since the problem arose. Restarting TB does not appear to have any effect; I typically restart TB at least once a day regardless.
|
|
Reporter | |
Comment 14•1 month ago
|
||
(In reply to gene smith from comment #12)
Another thing:
If you are not typically using the "Sent Later" feature (FWIW, it's not an add-on) when you see the problem, is there any chance you have more than one email compose windows open ready to sent and then quickly click the send button on each of them? Doing this fast enough could also cause the issue fixed in bug 1965690 (which wasn't released until 143.)
I've been using the SendLater add-on for years, so that's how I think of it...
But to answer the main question, I never have more than one e-mail compose window open at a time. That's just not how I work. Multiple sends within less than a minute or so are extremely rare (again, work habits more than anything else).
|
|
||
Comment 15•1 month ago
|
||
Ok, I see there really is a "send later" addon which I wasn't aware of: https://services.addons.thunderbird.net/en-us/thunderbird/addon/send-later-3/
I thought you were talking about the built-in tb File menu item "Send Later" and you were calling it incorrectly an "add-on". Sorry for misunderstanding.
Anyhow, since you say above:
I do NOT ordinarily use the Send Later add-on, but during testing I did test it and encountered the same behavior. All of the specific results here are WITHOUT Send Later (queueing would tend to mask some potential causes).
This probably confirms that the fix in bug 1965690 won't affect the problem you are seeing when just sending a single message. You might see the bug 1965690 problem if you queue several messages for sending (using the add-on or built-in feature) all to be sent at the SAME time.
|
|
Reporter | |
Comment 16•1 month ago
|
||
Minor notes following update to 140.12.1ESR:
The problem still exists, but the on-screen delay (the "sending message" popup) is about half as long on average in the last couple days since the update, averaging around 3-4 seconds. This is a complete mystery to me, as neither of the security fixes announced for .1 relate to my setup or these circumstances. I don't use autocomplete for non-locally-stored address book data, so there's no interface with LDAP at all. Similarly, I don't use Thunderbird for chat (in fact, I don't do chat and haven't for well over a decade... five machines ago).
The one good thing is that in the last four days, since applying the .1 update, I've NOT had a full-time-out rejection from SMTP requiring a retry, on any SMTP server. Crossing tentacles that 153ESR in a couple weeks will further smooth matters...
|
||
Comment 17•3 hours ago
|
||
I am closing this as incomplete, not reproducible as written but functionally adjacent to bug 2061085 among others. I will work on a bunch of additional SMTP fixes that hopefully will make everyones lives better.
With the answer from the ISP there may be sth lost in translation.
Description
•