Project

General

Profile

Actions

Defect #41515

closed

Connection to mailserver is not properly terminated

Added by Hendrik Jaeger about 1 month ago. Updated about 1 month ago.

Status:
Closed
Priority:
Normal
Assignee:
-
Category:
Email notifications
Target version:
-
Start date:
Due date:
% Done:

0%

Estimated time:
Resolution:
Fixed
Affected version:

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 …

Actions #1

Updated by Hendrik Jaeger about 1 month 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.

Actions #2

Updated by Hendrik Jaeger about 1 month 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.

Actions #3

Updated by Holger Just about 1 month ago

  • Description updated (diff)
Actions #4

Updated by Holger Just about 1 month 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!

Actions

Also available in: Atom PDF