Maddy sometimes blocks new connections while cleaning up stale connections

[cuu508]

I'm investigating an issue where maddy sends a message to a specific address every two minutes, but sometimes has hiccups and delays the message for 5+ minutes.

To investigate, I've added debug true in the target.queue and target.remote blocks. I have also set connect_timeout 1m and conn_max_idle_time 30 in the target.remote block.

Here are logs for two subsequent messages (I removed a few sensitive bits from the logs, and I converted the log lines for the second message to uppercase for visual separation):

01:58:34 submission: incoming message        {"msg_id":"cdc2c9aa", ...}
01:58:34 submission: RCPT ok        {"msg_id":"cdc2c9aa","rcpt":"[email protected]"}
01:58:34 submission: accepted        {"msg_id":"cdc2c9aa"}
01:58:34 [debug] queue: starting delivery for cdc2c9aa
01:58:34 [debug] queue: waiting on delivery semaphore for cdc2c9aa
01:58:34 [debug] queue: delivery semaphore acquired for cdc2c9aa
01:58:34 [debug] queue: using message ID = cdc2c9aa-65b6f83a        {"msg_id":"cdc2c9aa"}
01:58:34 [debug] queue: target.Start OK        {"msg_id":"cdc2c9aa"}
01:58:34 [debug] remote: opening new connection        {"cache_ignored":false,"domain":"hc-ping.com","msg_id":"cdc2c9aa-65b6f83a"}
01:58:34 [debug] remote: trying        {"domain":"hc-ping.com","msg_id":"cdc2c9aa-65b6f83a","remote_server":"hc-ping.com"}
01:58:34 [debug] remote: connected        {"msg_id":"cdc2c9aa-65b6f83a","remote_server":"hc-ping.com"}
01:58:34 [debug] queue: delivery.AddRcpt [email protected] OK        {"msg_id":"cdc2c9aa"}
01:58:34 [debug] queue: using delivery.BodyNonAtomic        {"msg_id":"cdc2c9aa"}
01:58:34 [debug] remote: returning connection for hc-ping.com to pool        {"msg_id":"cdc2c9aa-65b6f83a"}
01:58:34 [debug] queue: delivery.Commit OK        {"msg_id":"cdc2c9aa"}
01:58:34 [debug] queue: errors: map[]        {"msg_id":"cdc2c9aa"}
01:58:34 queue: delivered        {"attempt":1,"msg_id":"cdc2c9aa","rcpt":"[email protected]"}
01:58:34 [debug] queue: removed message from disk        {"msg_id":"cdc2c9aa"}
02:00:41 SUBMISSION: INCOMING MESSAGE        {"MSG_ID":"63308981", ...}
02:00:41 SUBMISSION: RCPT OK        {"MSG_ID":"63308981","RCPT":"[email protected]"}
02:00:41 SUBMISSION: ACCEPTED        {"MSG_ID":"63308981"}
02:00:41 [DEBUG] QUEUE: STARTING DELIVERY FOR 63308981
02:00:41 [DEBUG] QUEUE: WAITING ON DELIVERY SEMAPHORE FOR 63308981
02:00:41 [DEBUG] QUEUE: DELIVERY SEMAPHORE ACQUIRED FOR 63308981
02:00:41 [DEBUG] QUEUE: USING MESSAGE ID = 63308981-65B6F8B9        {"MSG_ID":"63308981"}
02:00:41 [DEBUG] QUEUE: TARGET.START OK        {"MSG_ID":"63308981"}
02:05:03 remote: QUIT error        {"msg_id":"cdc2c9aa-65b6f83a","reason":"write tcp ...-\u003e159.69.66.229:25: write: broken pipe","remote_server":"hc-ping.com"}
02:05:03 [DEBUG] REMOTE: OPENING NEW CONNECTION        {"CACHE_IGNORED":FALSE,"DOMAIN":"HC-PING.COM","MSG_ID":"63308981-65B6F8B9"}
02:05:03 [DEBUG] REMOTE: TRYING        {"DOMAIN":"HC-PING.COM","MSG_ID":"63308981-65B6F8B9","REMOTE_SERVER":"HC-PING.COM"}
02:05:04 [DEBUG] REMOTE: CONNECTED        {"MSG_ID":"63308981-65B6F8B9","REMOTE_SERVER":"HC-PING.COM"}
02:05:04 [DEBUG] QUEUE: DELIVERY.ADDRCPT [email protected] OK        {"MSG_ID":"63308981"}
02:05:04 [DEBUG] QUEUE: USING DELIVERY.BODYNONATOMIC        {"MSG_ID":"63308981"}
02:05:04 [DEBUG] REMOTE: RETURNING CONNECTION FOR HC-PING.COM TO POOL        {"MSG_ID":"63308981-65B6F8B9"}
02:05:04 [DEBUG] QUEUE: DELIVERY.COMMIT OK        {"MSG_ID":"63308981"}
02:05:04 [DEBUG] QUEUE: ERRORS: MAP[]        {"MSG_ID":"63308981"}
02:05:04 QUEUE: DELIVERED        {"ATTEMPT":1,"MSG_ID":"63308981","RCPT":"[email protected]"}
02:05:04 [DEBUG] QUEUE: REMOVED MESSAGE FROM DISK        {"MSG_ID":"63308981"}
02:07:06 REMOTE: QUIT ERROR        {"MSG_ID":"63308981-65B6F8B9","REASON":"SMTP ERROR 421: HC-PING.COM HEALTHCHECKS ESMTP SERVICE CLOSING TRANSMISSION CHANNEL AFTER TIMEOUT EXCEEDED","REMOTE_SERVER":"HC-PING.COM","SMTP_CODE":421,"SMTP_ENCHCODE":"4.4.2","SMTP_MSG":"HC-PING.COM SAID: HC-PING.COM HEALTHCHECKS ESMTP SERVICE CLOSING TRANSMISSION CHANNEL AFTER TIMEOUT EXCEEDED"}

• At 01:58:34 the first message is delivered and the connection is returned to the pool.
• At 02:00:41 the second message arrives, and gets stuck
• At 02:05:03 the first message's connection times out and right after a new connection is opened to deliver the second message.

What's confusing me here is, I have set conn_max_idle_time 30, so I did not expect maddy to reuse the connection if it has been sitting idle for more than 30 seconds.

Looking at pool.go, it looks like the lastUse field is shared by all connections inside a bucket, and last use time is not tracked per each individual connection. I may be misunderstanding the code, but doesn't it mean that some connections could linger in the bucket for much longer than conn_max_idle_time, if other connections gets taken out and put back in, bumping lastUse up?

The other suspicious thing I see in the logs is that the first connection times out ("broken pipe"), but the second connection gets closed gracefully (SMTP code 421). Not sure about this one, it could also be a timeout configuration issue on the recipient server.

[foxcpp]

02:00:41 [DEBUG] QUEUE: TARGET.START OK        {"MSG_ID":"63308981"}
  ... whats happening here ...
02:05:03 remote: QUIT error        {"msg_id":"cdc2c9aa-65b6f83a","reason":"write tcp ...-\u003e159.69.66.229:25: write: broken pipe","remote_server":"hc-ping.com"}
02:05:03 [DEBUG] REMOTE: OPENING NEW CONNECTION        {"CACHE_IGNORED":FALSE,"DOMAIN":"HC-PING.COM","MSG_ID":"63308981-65B6F8B9"}

There is no "reusing cached connection", maddy is attempting to send QUIT to close old connection (after correctly marking it as stale) but hangs for 5 minutes due to connection being dead.

[cuu508]

Thanks for looking into it!

I just did a quick test with sending multiple messages a few seconds apart to the same recipient, and I do see "reusing cached connection" in logs, and "transactions_counter" increasing. And when I let more than 30 seconds pass between messages, it opens a new connection instead.

maddy is attempting to send QUIT to close old connection (after correctly marking it as stale) but hangs for 5 minutes due to connection being dead.

It makes sense. It's unfortunate that pool cleanup blocks the sending of a new message. Since there's now Pool.cleanUpTick and Pool.CleanUp, perhaps Pool.Get does not need to do the [potentially slow] cleanup any more?

[cuu508]

... then again, if the slow cleanups happen frequently, the cleanup routine would not be able to keep up, and the pool would fill up with dead connections.

[foxcpp]

Pushed 7bdc981 to master that includes several improvements to pool code. This should fix your issue.

[cuu508]

Awesome, thanks, I'm testing these changes now.

[cuu508]

I've been running the changes for a week now, and all looks good, no issues with delivery delays any more 👍