Defect #41515
closedConnection to mailserver is not properly terminated
0%
Description
Hi
Basic info first:
Environment: Redmine version 5.1.2.stable Ruby version 3.1.2-p20 (2022-04-12) [x86_64-linux-gnu] Rails version 6.1.7.7 Environment production Database adapter PostgreSQL Mailer queue ActiveJob::QueueAdapters::AsyncAdapter Mailer delivery smtp Redmine settings: Redmine theme Alternate SCM: Git 2.39.5 Filesystem Redmine plugins: no plugin installed Postgres: 15.8-0+deb12u1
The problem I’m actually seeing is that sometimes some mails don’t arrive.
I also noticed errors from my mailserver saying the following:
2024-10-21 10:01:51 [16088] 1t2pEO-0004BU-1Z SMTP connection lost after final dot H=wilhelm.netwichtig.de (localhost.localdomain) [95.216.1.126]:37214 I=[213.133.111.59]:587 P=esmtpsa
For reference:
- 95.216.1.126 is wilhelm.netwichtig.de is the server where a VM runs in which redmine runs.
- 213.133.111.59 is leonardo.netwichtig.de where the mailserver runs that redmine is configured to use with AUTH to send emails.
Exim says that the client did not properly close the SMTP connection but just abandoned it after the final dot, i.e. before exim could acknowledge that it received the message completely, and therefore exim does not accept the message and the message is lost.
At the same time I see in redmine logs:
I, [2024-10-21T10:01:48.228979 #585774] INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [cf534f2e-1f4a-48d5-a3d9-a60af7ed0052] Performed ActionMailer::MailDeliveryJob (Job ID: cf534f2e-1f4a-48d5-a3d9-a60af7ed0052) from Async(mailers) in 8286.05ms I, [2024-10-21T10:01:48.761573 #585774] INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [9eed43b3-8e56-4370-9372-468d0292c96f] Performed ActionMailer::MailDeliveryJob (Job ID: 9eed43b3-8e56-4370-9372-468d0292c96f) from Async(mailers) in 8824.51ms E, [2024-10-21T10:01:49.506526 #585774] ERROR -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [4c1324f7-b5a4-4fd6-9a48-e232501b1631] Email delivery error: Net::ReadTimeout with #<Socket:(closed)> I, [2024-10-21T10:01:49.506718 #585774] INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [4c1324f7-b5a4-4fd6-9a48-e232501b1631] Performed ActionMailer::MailDeliveryJob (Job ID: 4c1324f7-b5a4-4fd6-9a48-e232501b1631) from Async(mailers) in 9567.16ms
In this case it tried to notify 3 recipients who are involved with the ticket that was updated, hence three MailDeliveryJobs.
The relevant part is that it seems to timeout and just close the connection.
According to my research the default `read_timeout` for the `Net` module might be 5 seconds, which is way too low for SMTP! The RFC goes up to 5 minutes AFAIR and having delays of several seconds is not uncommon, e.g. for the reason that "at-SMTP-time" spamscanning of emails can take a few seconds.
So my suggestion is to increase that timeout to at least 30s, or to be fully RFC-compliant, 5 minutes.
I am not 100% sure that I am interpreting the situation correctly, though, so feel free to correct me, request more information, etc.
My only goal here is to get the problem fixed …
Updated by Hendrik Jaeger 2 months ago
Yet again, I forgot to preview before posting. Sorry for the broken formatting. I don’t see a way to edit the description afterwards, as I do in my redmine. Please let me know if there is any way to fix it and I will.
Updated by Hendrik Jaeger 2 months ago
In https://guides.rubyonrails.org/action_mailer_basics.html#action-mailer-configuration I found that I can just add
read_timeout: 300
in configuration.yml and that seems to fix the issue.
This should be made the default.
Updated by Holger Just 2 months ago
- Status changed from New to Closed
- Resolution set to Fixed
The default read timeout is 5 seconds which I believe is reasonable for most setups. Setting this to a higher value may be required for special setups where the mailserver is either rather slow or performs heavy processing on the sent mail before accepting it, both of which is rather rare in common setups. A very long timeout of 5 minutes however may also mask intermediate issues and could result in overflowing queues.
As such, I think the default value is still reasonable for most setups and should not be changed. However, I saw that you already added some documentation to EmailConfiguration which will help others who may run into your issue. As such, I'm going to close this issue as Fixed with the documentation update.
Thank you for your contribution!