Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

lost connection with 127.0.0.1[127.0.0.1] while sending end of data #1523

Closed
MasterPCUK opened this issue Feb 18, 2019 · 41 comments
Closed

lost connection with 127.0.0.1[127.0.0.1] while sending end of data #1523

MasterPCUK opened this issue Feb 18, 2019 · 41 comments

Comments

@MasterPCUK
Copy link
Contributor

MasterPCUK commented Feb 18, 2019

Hello

I tired to debug this my self, but I can't.
This happens every time with incoming emails with three or more recipients.

So in comes and email to recipient=info@myhost.tld, with CC's to print@myhost.tld, sales@myhost.tld.
lmtp saves message for info@myhost.tld and for print@myhost.tld.
But for sales@myhost.tld message get's sent twice and this error.

box spampd[29412]: WARNING!! Error in process_request eval block: Child server process timed out!
box spampd[29409]: Starting "1" children
box spampd[14162]: Child Preforked (14162)

box postfix/lmtp[13676]: 57E773F9E1: to=<sales@myhost.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=382, delays=21/0.02/0.01/361, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once)

I am really lost. At first I and another person suspected spampd as seen here:
mpaperno/spampd#23

But that does not seem to be the case.

Here is log related to this issue.
Not sure where to look, so I hope that some one can help to figure this one out.

box postfix/smtpd[13257]: connect from mail.host.tld[IP ADDRESS]

box postgrey[7874]: action=pass, reason=triplet found, client_name=mail.host.tld, client_address=IP ADDRESS/32, sender=olga@host.tld, recipient=info@myhost.tld
box postfix/smtpd[13257]: 57E773F9E1: client=mail.host.tld[IP ADDRESS]
box postgrey[7874]: 57E773F9E1: action=pass, reason=triplet found, client_name=mail.host.tld, client_address=IP ADDRESS/32, sender=olga@host.tld, recipient=print@myhost.tld
box postgrey[7874]: 57E773F9E1: action=pass, reason=triplet found, client_name=mail.host.tld, client_address=IP ADDRESS/32, sender=olga@host.tld, recipient=sales@myhost.tld

box postfix/cleanup[13261]: 57E773F9E1: message-id=<001501d4c797$b6f844e0$0201a8c0@cairo>
box opendkim[19680]: 57E773F9E1: s=18520318-927B-11E8-8BE3-405F35632131 d=host.tld SSL
box opendmarc[1157]: implicit authentication service: box.host.uk
box opendmarc[1157]: 57E773F9E1: host.tld none
box postfix/qmgr[30914]: 57E773F9E1: from=<olga@host.tld>, size=10571183, nrcpt=3 (queue active)


box spampd[29412]: CONNECT TCP Peer: "[127.0.0.1]:43940" Local: "[127.0.0.1]:10025"
box spampd[29412]: Initiated Server
box spampd[29412]: Initiated Client
box spampd[29412]: smtp_server state: 'started'
box spampd[29412]: smtp_server state: 'LHLO box.host.uk'
box spampd[29412]: Destination response: '250-box.host.uk#015#012250-STARTTLS#015#012250-8BITMIME#015#012250-ENHANCEDSTATUSCODES#015#012250 PIPELINING'
box spampd[29412]: smtp_server state: 'MAIL FROM:<olga@host.tld> BODY=7BIT'
box spampd[29412]: Destination response: '250 2.1.0 OK'
box spampd[29412]: smtp_server state: 'RCPT TO:<info@myhost.tld>'
box spampd[29412]: Destination response: '250 2.1.5 OK'
box spampd[29412]: smtp_server state: 'RCPT TO:<print@myhost.tld>'
box spampd[29412]: Destination response: '250 2.1.5 OK'
box spampd[29412]: smtp_server state: 'RCPT TO:<sales@myhost.tld>'
box spampd[29412]: Destination response: '250 2.1.5 OK'
box spampd[29412]: smtp_server state: 'DATA'
box spampd[29412]: Destination response: '354 OK'

box postfix/smtpd[13257]: disconnect from mail.host.tld[IP ADDRESS] ehlo=2 starttls=1 mail=1 rcpt=3 data=1 quit=1 commands=9

box spampd[29412]: smtp_server state: '.'
box spampd[29412]: skipped large message (10323.654296875KB)
box spampd[29412]: Finished sending DATA
box spampd[29412]: Destination response: '250 2.0.0 <info@myhost.tld> KNQaFirGalxtNQAA9K/kkg Saved'
box spampd[29412]: smtp_server state: 'QUIT'

box postfix/lmtp[13676]: 57E773F9E1: to=<info@myhost.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=22, delays=21/0.02/0.01/0.65, dsn=2.0.0, status=sent (250 2.0.0 <info@myhost.tld> KNQaFirGalxtNQAA9K/kkg Saved)

box spampd[29412]: Destination response: '250 2.0.0 <print@myhost.tld> KNQaFirGalxtNQAA9K/kkg:2 Saved'

box postfix/lmtp[13676]: 57E773F9E1: to=<print@myhost.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=22, delays=21/0.02/0.01/0.98, dsn=2.0.0, status=sent (250 2.0.0 <print@myhost.tld> KNQaFirGalxtNQAA9K/kkg:2 Saved)

box spampd[29412]: WARNING!! Error in process_request eval block: Child server process timed out!
box spampd[29409]: Starting "1" children
box spampd[14162]: Child Preforked (14162)

box postfix/lmtp[13676]: 57E773F9E1: to=<sales@myhost.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=382, delays=21/0.02/0.01/361, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once)

@sgrimmett
Copy link

sgrimmett commented Feb 18, 2019

I haven't had time to debug this either, but I've seen the issue of double sent emails in similar circumstances. It only started with version 0.40 - nothing else changed for us, if that helps in any way. I'll update if I get time to look into this more.

@MasterPCUK
Copy link
Contributor Author

@sgrimmett I also think that this started from v0.40 but not 100% sure as I didn't scan logs before.
But, yes that be great, if you get time. I will of course monitor logs and dig deeper.

@sgrimmett
Copy link

sgrimmett commented Feb 18, 2019

@MasterPCUK the only thing I can think of without actually digging is that it is related to graylisting - this changed (from what I recall) when moving up to .40. For the life of me, though, I can't find where I read that!

@JoshData
Copy link
Member

We dropped a custom package and are using the stock postgrey package now.

Very little in Mail-in-a-Box changed in v0.40 (it's 40, not 4 --- the number just goes up by 1 each release). If there's a configuration problem, it might be more likely to be in the Ubuntu defaults that might have changed from 14.04 to 18.04.

@MasterPCUK
Copy link
Contributor Author

MasterPCUK commented Feb 18, 2019

I'm not sure if we should suspect graylisting as in my case: postgrey[7874]: action=pass

@sgrimmett
Copy link

Thanks Josh - updated my typo to 0.40! It's probably not greylisting if stock and based on MasterPCUK's comment... just throwing out what I recall being different from 0.3x versions. Will advise if I find anything further related to this issue.

@MasterPCUK
Copy link
Contributor Author

A little update.

I created 4 email address for one domain.
user1@, user2@, user3@, user4@.
Sent an email from gmail using all four newly created email address in TO field.

Email arrived in all four mailboxes, but got saved only for first two, getting delivered twice for user3 and user4.
If anyone could try to replicate this issue, that be great.

Could this be something to do with RCPT TO in postfix and or timing issue?

Below log with time codes.

18:07:19 box postfix/smtpd[3215]: connect from mail-qt1-f179.google.com[gmail-ip]
18:07:20 box postgrey[1364]: action=pass, reason=client whitelist, client_name=mail-qt1-f179.google.com, client_address=gmail-ip/32, sender=testuser@gmail.com, recipient=user1@domain.tld
18:07:20 box postfix/smtpd[3215]: B99E33F9E2: client=mail-qt1-f179.google.com[gmail-ip]
18:07:20 box postgrey[1364]: B99E33F9E2: action=pass, reason=client whitelist, client_name=mail-qt1-f179.google.com, client_address=gmail-ip/32, sender=testuser@gmail.com, recipient=user2@domain.tld
18:07:20 box postgrey[1364]: B99E33F9E2: action=pass, reason=client whitelist, client_name=mail-qt1-f179.google.com, client_address=gmail-ip/32, sender=testuser@gmail.com, recipient=user3@domain.tld
18:07:20 box postgrey[1364]: B99E33F9E2: action=pass, reason=client whitelist, client_name=mail-qt1-f179.google.com, client_address=gmail-ip/32, sender=testuser@gmail.com, recipient=user4@domain.tld

18:07:20 box postfix/cleanup[3217]: B99E33F9E2: message-id=<message-id>
18:07:21 box opendkim[3177]: B99E33F9E2: s=20161025 d=gmail.com SSL
18:07:21 box opendmarc[1186]: implicit authentication service: box.domain.tld
18:07:21 box opendmarc[1186]: B99E33F9E2: gmail.com pass
18:07:21 box postfix/qmgr[1576]: B99E33F9E2: from=<testuser@gmail.com>, size=2820, nrcpt=4 (queue active)
18:07:21 box spampd[1950]: 2019/02/19-18:07:21 CONNECT TCP Peer: "[127.0.0.1]:49766" Local: "[127.0.0.1]:10025"
18:07:21 box spampd[1950]: Initiated Server
18:07:21 box spampd[1950]: Initiated Client
18:07:21 box dovecot: lmtp(2701): Connect from 127.0.0.1
18:07:21 box spampd[1950]: smtp_server state: 'started'
18:07:21 box spampd[1950]: smtp_server state: 'LHLO box.domain.tld'
18:07:21 box spampd[1950]: Destination response: '250-box.domain.tld#015#012250-STARTTLS#015#012250-8BITMIME#015#012250-ENHANCEDSTATUSCODES#015#012250 PIPELINING'
18:07:21 box spampd[1950]: smtp_server state: 'MAIL FROM:<testuser@gmail.com>'
18:07:21 box spampd[1950]: Destination response: '250 2.1.0 OK'
18:07:21 box spampd[1950]: smtp_server state: 'RCPT TO:<user1@domain.tld>'
18:07:21 box spampd[1950]: Destination response: '250 2.1.5 OK'
18:07:21 box spampd[1950]: smtp_server state: 'RCPT TO:<user2@domain.tld>'
18:07:21 box spampd[1950]: Destination response: '250 2.1.5 OK'
18:07:21 box spampd[1950]: smtp_server state: 'RCPT TO:<user3@domain.tld>'
18:07:21 box spampd[1950]: Destination response: '250 2.1.5 OK'
18:07:21 box spampd[1950]: smtp_server state: 'RCPT TO:<user4@domain.tld>'
18:07:21 box spampd[1950]: Destination response: '250 2.1.5 OK'
18:07:21 box spampd[1950]: smtp_server state: 'DATA'
18:07:21 box spampd[1950]: Destination response: '354 OK'
18:07:21 box spampd[1950]: smtp_server state: '.'
18:07:21 box spampd[1950]: processing message <message-id> for <user1@domain.tld>,<user2@domain.tld>,<user3@domain.tld>,<user4@domain.tld>
18:07:21 box postfix/smtpd[3215]: disconnect from mail-qt1-f179.google.com[gmail-ip] ehlo=2 starttls=1 mail=1 rcpt=4 data=1 quit=1 commands=10
18:07:23 box spampd[1950]: Returned from checking by SpamAssassin
18:07:23 box spampd[1950]: Rewriting mail using SpamAssassin
18:07:23 box spampd[1950]: clean message <message-id> (0.88/4.30) from <testuser@gmail.com> for <user1@domain.tld>,<user2@domain.tld>,<user3@domain.tld>,<user4@domain.tld> in 2.33s, 3047 bytes.
18:07:23 box spampd[1950]: Finished sending DATA


18:07:23 box dovecot: lmtp(user1@domain.tld): aLZLE8k3bFyNCgAA9K/kkg: sieve: msgid=<message-id>: stored mail into mailbox 'INBOX'
18:07:23 box postfix/lmtp[2638]: B99E33F9E2: to=<user1@domain.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=3.1, delays=0.73/0/0.01/2.4, dsn=2.0.0, status=sent (250 2.0.0 <user1@domain.tld> aLZLE8k3bFyNCgAA9K/kkg Saved)
18:07:23 box spampd[1950]: Destination response: '250 2.0.0 <user1@domain.tld> aLZLE8k3bFyNCgAA9K/kkg Saved'
18:07:23 box spampd[1950]: smtp_server state: 'QUIT'
18:07:23 box dovecot: lmtp(user2@domain.tld): aLZLE8k3bFyNCgAA9K/kkg:2: sieve: msgid=<message-id>: stored mail into mailbox 'INBOX'
18:07:23 box spampd[1950]: Destination response: '250 2.0.0 <user2@domain.tld> aLZLE8k3bFyNCgAA9K/kkg:2 Saved'
18:07:23 box dovecot: lmtp(user3@domain.tld): aLZLE8k3bFyNCgAA9K/kkg:3: sieve: msgid=<message-id>: stored mail into mailbox 'INBOX'
18:07:23 box postfix/lmtp[2638]: B99E33F9E2: to=<user2@domain.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=3.2, delays=0.73/0/0.01/2.4, dsn=2.0.0, status=sent (250 2.0.0 <user2@domain.tld> aLZLE8k3bFyNCgAA9K/kkg:2 Saved)
18:07:23 box dovecot: lmtp(user4@domain.tld): aLZLE8k3bFyNCgAA9K/kkg:4: sieve: msgid=<message-id>: stored mail into mailbox 'INBOX'
18:07:23 box dovecot: lmtp(2701): Disconnect from 127.0.0.1: Successful quit



18:13:23 box spampd[1950]: WARNING!! Error in process_request eval block: Child server process timed out!
18:13:23 box spampd[1938]: Starting "1" children
18:13:23 box spampd[3729]: Child Preforked (3729)

18:13:23 box postfix/lmtp[2638]: B99E33F9E2: to=<user3@domain.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=363, delays=0.73/0/0.01/362, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once)
18:13:23 box postfix/lmtp[2638]: B99E33F9E2: to=<user4@domain.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=363, delays=0.73/0/0.01/362, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once)

@MasterPCUK
Copy link
Contributor Author

MasterPCUK commented Feb 19, 2019

Ok, one workaround is to set lmtp_destination_recipient_limit = 1 in main.cf (postfix)
Update spampd to v2.53 https://github.com/mpaperno/spampd/releases/tag/2.53

This will cause spampd to scan the same message multiple times and putting an extra load on CPU though.

@marcosms
Copy link

marcosms commented Feb 21, 2019

Hello.

I had a lot of troubles this week caused by this bug. I finally found this thread and your workaround seems to work well (The CPU has higher loads when we receive a mail, but at least it works).

I have commented on all the symptoms in this other thread.

https://discourse.mailinabox.email/t/cant-receive-mails/4624

In my case, we have about 120 users in the mail-in-a-box server. The server with version 14.04 of ubuntu worked perfectly. This saturday we migrate to 18.04 and the troubles started at monday (when the users begins to send emails). A large number of these emails have 3 or more recipients. In fact, in some of our accounts, we have rules on roundcube to forward the incoming mail to a big number of users (12). So, the queues begins to grow very quickly. I reinstalled the backup another time this night to be sure that the migration was correct, but in 40 minutes we have 500 messages in the queue again. When we use your workaround the queues were reduced gradually. Now we havn't got any mail in the server's queue.

You may have a lot of information of our troubles in the link of the forum, but I am at your disposal if you want me to do some test on my server to try to solve this problem.

In my opinion, it is important that the next version of mail-in-a-box has this problem corrected (because this trouble has to affect a lot more people).

@JoshData
Copy link
Member

Hi folks. I did a little Googling and didn't see any documentation suggesting lmtp_destination_recipient_limit = 1 would be necessary either for spampd, which is the SpamAssassin service, or dovecot's LMTP service (although it does suggest it for its LDA service, but the LDA service works differently).

I tried sending my box an email with To: containing two local users, and the mail was delivered fine.

Before making a change to lmtp_destination_recipient_limit I'd like to understand better what the problem is. Would either of you mind trying out something like lmtp_destination_recipient_limit = 10 (ten instead of one) and seeing if the problem comes back or stays gone?

@marcosms
Copy link

No problem. I will try lmtp_destination_recipient_limit = 10 and i will keep an eye on the queues to see what happens. I tell you in a while what happens in these circumstances.

@sgrimmett
Copy link

@JoshData on my box, the issue is not sending an email to two local users, it is when there is more than 2.

I switched to lmtp_destination_recipient_limit = 1, and my issues were gone.

I'm just tried lmtp_destination_recipient_limit = 10.. and got double messages still. I haven't had time to dig into the logs to see if they differ, but will post when I have a chance to do so.

For now, I'm sticking with lmtp_destination_recipient_limit = 1, until I have more time to explore further.

@marcosms
Copy link

marcosms commented Feb 21, 2019

OK. I made the test. I sended a message to 5 email destination with the "=10" parameter. When i change this parameter i made a "sudo service postfix restart" an then i send the message. One of the recipients have roules in roundcube to resend it to more persons. I wait 4 minutes and the message still in queque. So i change again the parameter to "=1" and restart postfix again and the message come out of the queue quickly. Then, i send another message in same conditions. The new message with the "=1" parameter come out in a few seconds.

If you need me to do more tests, tell me.

@sgrimmett says anything about double messages. This days many people complained about repeated emails lot of times. Since I change the parameter to "=1" we haven't got this trouble.

Regards.

@MasterPCUK
Copy link
Contributor Author

@JoshData This issue only happens when mail is sent to three or more recipients in TO field. Can you please try that?

@mpaperno
Copy link

In the log posted above, the issue seems to be that Dovecot is not sending proper 250 responses for recipients 3 and 4, even though it says it has stored the mail. Hence Postfix doesn't know they were delivered and will retry again next time. spampd times out because it is waiting for responses about the last 2 recipients (code). If spampd wasn't in the mix, postfix would just disconnect when Dovecot does and the end result would be the same (postfix would retry the last 2 recipients later).

From LMTP protocol RFC §4.2:

after the final ".", the server returns one reply
for each previously successful RCPT command in the mail transaction,
in the order that the RCPT commands were issued.

@JoshData

spampd, which is the SpamAssassin service

For the record, spampd is an independent project, no official association with SpamAssassin. LMTP works AFAIK, though mostly by virtue of being nearly identical to SMTP and spampd being a simple proxy. The only real exception for LMTP processing is the code I linked above.

Right now the only change I might see in spampd for this issue is that it disconnect from the sender (postfix) if the destination (Dovecot) hangs up. Instead of waiting for the replies that will obviously never come and then timing out. Would not solve the delivery issue at all, but it might better represent where the actual problem lies.

@bharatbugss
Copy link

bharatbugss commented Feb 25, 2019

I got the same "lost connection with 127.0.0.1[127.0.0.1] while sending end of data" issue with mail delivering more than 2 times for email with more than 3 cc lists.

I am using MIAB 0.40 in Ubuntu 18.4 with 200GB spaces in DO
Trying the lmtp_destination_recipient_limit = 1 I hope it works for long. Its working for past 15 mins..

@mpaperno
Copy link

Actually I just noticed in the log that Postfix sent a QUIT command after the first 250 response. W/out waiting for all the recipients to be ack'd.

18:07:23 box spampd[1950]: Finished sending DATA
18:07:23 box dovecot: lmtp(user1@domain.tld): aLZLE8k3bFyNCgAA9K/kkg: sieve: msgid=<message-id>: stored mail into mailbox 'INBOX'
18:07:23 box postfix/lmtp[2638]: B99E33F9E2: to=<user1@domain.tld>, relay=127.0.0.1[127.0.0.1]:10025, delay=3.1, delays=0.73/0/0.01/2.4, dsn=2.0.0, status=sent (250 2.0.0 <user1@domain.tld> aLZLE8k3bFyNCgAA9K/kkg Saved)
18:07:23 box spampd[1950]: Destination response: '250 2.0.0 <user1@domain.tld> aLZLE8k3bFyNCgAA9K/kkg Saved'
18:07:23 box spampd[1950]: smtp_server state: 'QUIT'   <--- This is from postfix to dovecot

So now I'm not sure what exactly postfix is expecting. Dovecot does in fact happily quit, though not before sending one more 250 response through. Which postfix still seems to process... even after having sent QUIT. 😕

It might be useful to see what happens if spampd is taken out of the loop (for a test) and postfix was set up to deliver directly to dovecot. Should be just a matter of changing the port postfix delivers to... but I don't know anything about MIAB setup.

The only possibly relevant postfix setting I could find offhand is:

lmtp_skip_quit_response (default: no)
Wait for the response to the LMTP QUIT command.

Not clear to me what response it would be waiting for. The smtp_skip_quit_response default is yes and a typical server response to QUIT is just to hang up.

@MasterPCUK
Copy link
Contributor Author

Hello

I took spampd out of the loop and delivered mail straight to dovecot.
@mpaperno

Feb 25 09:39:16 mail postfix/qmgr[26229]: 6C33B40C49: from=<testuser@gmail.com>, size=3723, nrcpt=3 (queue active)
Feb 25 09:39:16 mail postfix/lmtp[26240]: 6C33B40C49: to=<test@domain.tld>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.45, delays=0.39/0/0/0.05, dsn=2.0.0, status=sent (250 2.0.0 <test@domain.tld> KGBKLbSpc1yBZgAA3Opvgg Saved)
Feb 25 09:39:16 mail postfix/lmtp[26240]: 6C33B40C49: to=<test1@domain.tld>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.46, delays=0.39/0/0/0.06, dsn=2.0.0, status=sent (250 2.0.0 <test1@domain.tld> KGBKLbSpc1yBZgAA3Opvgg:2 Saved)
Feb 25 09:39:16 mail postfix/lmtp[26240]: 6C33B40C49: to=<test2@domain.tld>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.46, delays=0.39/0/0/0.06, dsn=2.0.0, status=sent (250 2.0.0 <test2@domain.tld> KGBKLbSpc1yBZgAA3Opvgg:3 Saved)
Feb 25 09:39:16 mail postfix/qmgr[26229]: 6C33B40C49: removed

@mpaperno
Copy link

mpaperno commented Feb 25, 2019

@MasterPCUK Could you try this version? I just commented out the "patch for LMTP" code where it waits for all recipients to be ack'd. Keep the debugging on please. Thanks.

spampd.pl.txt (removed, not working)

@MasterPCUK
Copy link
Contributor Author

@mpaperno
Just tested it, same issue with only first two begin saved.

Feb 25 10:18:53 mail postfix/qmgr[1625]: 548FB40C4F: from=<testuser@gmail.com>, size=4987, nrcpt=3 (queue active)
Feb 25 10:18:53 mail spampd[2571]: 2019/02/25-10:18:53 CONNECT TCP Peer: "[127.0.0.1]:33070" Local: "[127.0.0.1]:10025"
Feb 25 10:18:53 mail spampd[2571]: Initiated Server
Feb 25 10:18:53 mail spampd[2571]: Initiated Client
Feb 25 10:18:53 lmtp(2829): Info: Connect from 127.0.0.1
Feb 25 10:18:53 mail spampd[2571]: smtp_server state: 'started'
Feb 25 10:18:53 mail spampd[2571]: smtp_server state: 'LHLO mail.domain.uk'
Feb 25 10:18:53 mail spampd[2571]: Destination response: '250-mail.domain.uk#015#012250-STARTTLS#015#012250-8BITMIME#015#012250-ENHANCEDSTATUSCODES#015#012250 PIPELINING'
Feb 25 10:18:53 mail spampd[2571]: smtp_server state: 'MAIL FROM:<testuser@gmail.com>'
Feb 25 10:18:53 mail spampd[2571]: Destination response: '250 2.1.0 OK'
Feb 25 10:18:53 mail spampd[2571]: smtp_server state: 'RCPT TO:<janis@domain.uk>'
Feb 25 10:18:53 mail spampd[2571]: Destination response: '250 2.1.5 OK'
Feb 25 10:18:53 mail spampd[2571]: smtp_server state: 'RCPT TO:<test1@domain.uk>'
Feb 25 10:18:53 mail spampd[2571]: Destination response: '250 2.1.5 OK'
Feb 25 10:18:53 mail spampd[2571]: smtp_server state: 'RCPT TO:<test2@domain.uk>'
Feb 25 10:18:53 mail spampd[2571]: Destination response: '250 2.1.5 OK'
Feb 25 10:18:53 mail spampd[2571]: smtp_server state: 'DATA'
Feb 25 10:18:53 mail spampd[2571]: Destination response: '354 OK'
Feb 25 10:18:54 mail spampd[2571]: smtp_server state: '.'

Feb 25 10:18:54 mail spampd[2571]: processing message <CAJ3=9XHfARYxSG0s4N7OD+9dtpUdkHxVNmbT35PyJwq1JPnMow@mail.gmail.com> for <janis@domain.uk>,<test1@domain.uk>,<test2@domain.uk>
Feb 25 10:18:54 mail postfix/smtpd[2817]: disconnect from mail-qt1-x832.google.com[2607:f8b0:4864:20::832] ehlo=2 starttls=1 mail=1 rcpt=3 data=1 quit=1 commands=9
Feb 25 10:18:56 mail spampd[2571]: Returned from checking by SpamAssassin
Feb 25 10:18:56 mail spampd[2571]: Rewriting mail using SpamAssassin
Feb 25 10:18:56 mail spampd[2571]: clean message <CAJ3=9XHfARYxSG0s4N7OD+9dtpUdkHxVNmbT35PyJwq1JPnMow@mail.gmail.com> (0.01/5.00) from <testuser@gmail.com> for <janis@domain.uk>,<test1@domain.uk>,<test2@domain.uk> in 2.50s, 5209 bytes.
Feb 25 10:18:56 mail spampd[2571]: Finished sending DATA
Feb 25 10:18:56 lmtp(janis@domain.uk): Info: aEXWOv2yc1wNCwAA3Opvgg: sieve: msgid=<CAJ3=9XHfARYxSG0s4N7OD+9dtpUdkHxVNmbT35PyJwq1JPnMow@mail.gmail.com>: stored mail into mailbox 'INBOX'
Feb 25 10:18:56 mail spampd[2571]: Destination response: '250 2.0.0 <janis@domain.uk> aEXWOv2yc1wNCwAA3Opvgg Saved'
Feb 25 10:18:56 mail postfix/lmtp[2828]: 548FB40C4F: to=<janis@domain.uk>, relay=127.0.0.1[127.0.0.1]:10025, delay=3.6, delays=0.98/0.01/0.02/2.6, dsn=2.0.0, status=sent (250 2.0.0 <janis@domain.uk> aEXWOv2yc1wNCwAA3Opvgg Saved)
Feb 25 10:18:56 mail spampd[2571]: smtp_server state: 'QUIT'
Feb 25 10:18:56 lmtp(test1@domain.uk): Info: aEXWOv2yc1wNCwAA3Opvgg:2: sieve: msgid=<CAJ3=9XHfARYxSG0s4N7OD+9dtpUdkHxVNmbT35PyJwq1JPnMow@mail.gmail.com>: stored mail into mailbox 'INBOX'
Feb 25 10:18:56 mail spampd[2571]: Destination response: '250 2.0.0 <test1@domain.uk> aEXWOv2yc1wNCwAA3Opvgg:2 Saved'
Feb 25 10:18:56 imap-login: Info: Login: user=<test2@domain.uk>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=2836, TLS, session=<H/wabrSCToR/AAAB>
Feb 25 10:18:56 lmtp(test2@domain.uk): Info: aEXWOv2yc1wNCwAA3Opvgg:3: sieve: msgid=<CAJ3=9XHfARYxSG0s4N7OD+9dtpUdkHxVNmbT35PyJwq1JPnMow@mail.gmail.com>: stored mail into mailbox 'INBOX'
Feb 25 10:18:56 lmtp(2829): Info: Disconnect from 127.0.0.1: Successful quit
Feb 25 10:18:56 imap(test2@domain.uk): Info: Logged out in=531 out=2740
Feb 25 10:18:56 mail postfix/lmtp[2828]: 548FB40C4F: to=<test1@domain.uk>, relay=127.0.0.1[127.0.0.1]:10025, delay=3.6, delays=0.98/0.01/0.02/2.6, dsn=2.0.0, status=sent (250 2.0.0 <test1@domain.uk> aEXWOv2yc1wNCwAA3Opvgg:2 Saved)

@bharatbugss
Copy link

Ok, one workaround is to set lmtp_destination_recipient_limit = 1 in main.cf (postfix)

This will cause spampd to scan the same message multiple times and putting an extra load on CPU though.

Thank you... @MasterPCUK .... its working for now..

@mpaperno
Copy link

Strange... does it (spampd or postfix) still time out? Or does spampd ever log "Closed connections" message at the end? Also a bit confusing because we can't see the lmtp messages in the "w/out spampd" test log and of course don't have the detailed protocol exchange which spampd logs in debug mode. Sorry I don't have a way to test this locally ATM.

Not understanding right now why Dovecot would send 3 250 responses in the "no-spampd" test but only 2 with spampd involved... if that's in fact what is going on. Or if Postfix just assumes the rest were delivered after Dovecot disconnects. It is possible spampd prevents Postfix from detecting when the receiving side closed the socket (which isn't trivial to detect).

@MasterPCUK
Copy link
Contributor Author

@mpaperno As far as I can see, LMTP patch code is never hit.
Also, I removed comment and added debug straight after first if statement, and it was never hit.

if ($smtp_server->{proto} eq 'lmtp') {
$self->dbg("Test");
spampd[2571]: Destination response: **// is coming from** 

      # pass on whatever the relayhost said in response
      # $client->hear can handle multiline responses so no need to loop
      my $destresp = $client->hear;
      $smtp_server->ok($destresp)
        or die "Error in server->ok(client->hear): $!";

      $self->dbg("**Destination response:** '" . $destresp . "'");

@mpaperno
Copy link

Okay... that could explain things. :) But why does it not detect the protocol?

Can you see what

$self->dbg("proto: '" . $smtp_server->{proto} . "' helo: '" . $smtp_server->{helo} . "'");

says? Could stick that just before the if ($smtp_server->{proto} eq 'lmtp').

What version of spampd was originally installed in this setup? 2.42?

@MasterPCUK
Copy link
Contributor Author

MasterPCUK commented Feb 25, 2019

@mpaperno Yes, original version was 2.42.
Here:

Feb 25 11:48:43 mail spampd[11758]: smtp_server state: 'LHLO mail.domain.uk'
Feb 25 11:48:43 mail spampd[11758]: Destination response: '250-mail.domain.uk#015#012250-STARTTLS#015#012250-8BITMIME#015#012250-ENHANCEDSTATUSCODES#015#012250 PIPELINING'
Feb 25 11:48:43 mail spampd[11758]: proto: 'unknown' helo: 'mail.domain.uk'
Feb 25 11:48:43 mail spampd[11758]: smtp_server state: 'MAIL FROM:<testuzer@gmail.com>'
Feb 25 11:48:43 mail spampd[11758]: Destination response: '250 2.1.0 OK'
Feb 25 11:48:43 mail spampd[11758]: proto: 'unknown' helo: 'mail.domain.uk'
Feb 25 11:48:43 mail spampd[11758]: smtp_server state: 'RCPT TO:<janis@domain.uk>'
Feb 25 11:48:43 mail spampd[11758]: Destination response: '250 2.1.5 OK'
Feb 25 11:48:43 mail spampd[11758]: proto: 'unknown' helo: 'mail.domain.uk'
Feb 25 11:48:43 mail spampd[11758]: smtp_server state: 'RCPT TO:<test1@domain.uk>'
Feb 25 11:48:43 mail spampd[11758]: Destination response: '250 2.1.5 OK'
Feb 25 11:48:43 mail spampd[11758]: proto: 'unknown' helo: 'mail.domain.uk'
Feb 25 11:48:43 mail spampd[11758]: smtp_server state: 'RCPT TO:<test2@domain.uk>'
Feb 25 11:48:43 mail spampd[11758]: Destination response: '250 2.1.5 OK'
Feb 25 11:48:43 mail spampd[11758]: proto: 'unknown' helo: 'mail.domain.uk'
Feb 25 11:48:43 mail spampd[11758]: smtp_server state: 'DATA'
Feb 25 11:48:43 mail spampd[11758]: Destination response: '354 OK'
Feb 25 11:48:43 mail spampd[11758]: proto: 'unknown' helo: 'mail.domain.uk'

@mpaperno
Copy link

Wow... I'm not sure that ever worked. Wonder how that "LMTP patch" was tested :)

This is the original code (LMTP patch restored) with the protocol detection (hopefully) working. Simple regex change in SpamPD::Server::chat().

spampd.pl.txt

@MasterPCUK
Copy link
Contributor Author

@mpaperno Yes, I can confirm this working.

Log:

Feb 25 12:20:12 mail postfix/qmgr[15194]: 3B3B340BC8: from=<testuser@gmail.com>, size=5500, nrcpt=3 (queue active)
Feb 25 12:20:12 mail spampd[15281]: 2019/02/25-12:20:12 CONNECT TCP Peer: "[127.0.0.1]:33768" Local: "[127.0.0.1]:10025"
Feb 25 12:20:12 mail spampd[15281]: Initiated Server
Feb 25 12:20:12 mail spampd[15281]: Initiated Client
Feb 25 12:20:12 lmtp(15726): Info: Connect from 127.0.0.1
Feb 25 12:20:12 mail spampd[15281]: smtp_server state: 'started'
Feb 25 12:20:12 mail spampd[15281]: smtp_server state: 'LHLO mail.domain.uk'
Feb 25 12:20:12 mail spampd[15281]: Destination response: '250-mail.domain.uk#015#012250-STARTTLS#015#012250-8BITMIME#015#012250-ENHANCEDSTATUSCODES#015#012250 PIPELINING'
Feb 25 12:20:12 mail spampd[15281]: smtp_server state: 'MAIL FROM:<testuser@gmail.com>'
Feb 25 12:20:12 mail spampd[15281]: Destination response: '250 2.1.0 OK'
Feb 25 12:20:12 mail spampd[15281]: smtp_server state: 'RCPT TO:<janis@domain.uk>'
Feb 25 12:20:12 mail spampd[15281]: Destination response: '250 2.1.5 OK'
Feb 25 12:20:12 mail spampd[15281]: smtp_server state: 'RCPT TO:<test1@domain.uk>'
Feb 25 12:20:12 mail spampd[15281]: Destination response: '250 2.1.5 OK'
Feb 25 12:20:12 mail spampd[15281]: smtp_server state: 'RCPT TO:<test2@domain.uk>'
Feb 25 12:20:12 mail spampd[15281]: Destination response: '250 2.1.5 OK'
Feb 25 12:20:12 mail spampd[15281]: smtp_server state: 'DATA'
Feb 25 12:20:12 mail spampd[15281]: Destination response: '354 OK'
Feb 25 12:20:12 mail spampd[15281]: smtp_server state: '.'
Feb 25 12:20:12 mail spampd[15281]: processing message <CAJ3=9XFVevb-f9z-tmJ4w62Wnyu1nLYDWctd6oCfQYB681RrfA@mail.gmail.com> for <janis@domain.uk>,<test1@domain.uk>,<test2@domain.uk>
Feb 25 12:20:12 mail postfix/smtpd[15719]: disconnect from mail-qk1-x735.google.com[2607:f8b0:4864:20::735] ehlo=2 starttls=1 mail=1 rcpt=3 data=1 quit=1 commands=9
Feb 25 12:20:14 mail spampd[15281]: Returned from checking by SpamAssassin
Feb 25 12:20:14 mail spampd[15281]: Rewriting mail using SpamAssassin
Feb 25 12:20:14 mail spampd[15281]: clean message <CAJ3=9XFVevb-f9z-tmJ4w62Wnyu1nLYDWctd6oCfQYB681RrfA@mail.gmail.com> (0.01/5.00) from <testuser@gmail.com> for <janis@domain.uk>,<test1@domain.uk>,<test2@domain.uk> in 1.91s, 5722 bytes.
Feb 25 12:20:14 mail spampd[15281]: Finished sending DATA

Feb 25 12:20:14 lmtp(janis@domain.uk): Info: ACbmJWzPc1xuPQAA3Opvgg: sieve: msgid=<CAJ3=9XFVevb-f9z-tmJ4w62Wnyu1nLYDWctd6oCfQYB681RrfA@mail.gmail.com>: stored mail into mailbox 'INBOX'
Feb 25 12:20:14 mail postfix/lmtp[15725]: 3B3B340BC8: to=<janis@domain.uk>, relay=127.0.0.1[127.0.0.1]:10025, delay=2.4, delays=0.4/0.01/0.02/2, dsn=2.0.0, status=sent (250 2.0.0 <janis@domain.uk> ACbmJWzPc1xuPQAA3Opvgg Saved)

Feb 25 12:20:14 mail spampd[15281]: Destination response: '250 2.0.0 <janis@domain.uk> ACbmJWzPc1xuPQAA3Opvgg Saved'
Feb 25 12:20:14 lmtp(test1@domain.uk): Info: ACbmJWzPc1xuPQAA3Opvgg:2: sieve: msgid=<CAJ3=9XFVevb-f9z-tmJ4w62Wnyu1nLYDWctd6oCfQYB681RrfA@mail.gmail.com>: stored mail into mailbox 'INBOX'
Feb 25 12:20:14 mail spampd[15281]: Destination response: '250 2.0.0 <test1@domain.uk> ACbmJWzPc1xuPQAA3Opvgg:2 Saved'
Feb 25 12:20:14 lmtp(test2@domain.uk): Info: ACbmJWzPc1xuPQAA3Opvgg:3: sieve: msgid=<CAJ3=9XFVevb-f9z-tmJ4w62Wnyu1nLYDWctd6oCfQYB681RrfA@mail.gmail.com>: stored mail into mailbox 'INBOX'
Feb 25 12:20:14 mail spampd[15281]: Destination response: '250 2.0.0 <test2@domain.uk> ACbmJWzPc1xuPQAA3Opvgg:3 Saved'
Feb 25 12:20:14 mail spampd[15281]: smtp_server state: 'QUIT'
Feb 25 12:20:14 lmtp(15726): Info: Disconnect from 127.0.0.1: Successful quit
Feb 25 12:20:14 mail spampd[15281]: Destination response: '221 2.0.0 OK'

Feb 25 12:20:14 mail postfix/lmtp[15725]: 3B3B340BC8: to=<test1@domain.uk>, relay=127.0.0.1[127.0.0.1]:10025, delay=2.4, delays=0.4/0.01/0.02/2, dsn=2.0.0, status=sent (250 2.0.0 <test1@domain.uk> ACbmJWzPc1xuPQAA3Opvgg:2 Saved)
Feb 25 12:20:14 mail postfix/lmtp[15725]: 3B3B340BC8: to=<test2@domain.uk>, relay=127.0.0.1[127.0.0.1]:10025, delay=2.4, delays=0.4/0.01/0.02/2, dsn=2.0.0, status=sent (250 2.0.0 <test2@domain.uk> ACbmJWzPc1xuPQAA3Opvgg:3 Saved)

Feb 25 12:20:14 mail postfix/qmgr[15194]: 3B3B340BC8: removed
Feb 25 12:20:14 mail spampd[15281]: Closed connections

@mpaperno
Copy link

👍 Thanks for all the testing!

I'll have a new official spampd version released shortly, which is essentially the same as the last version I posted above.

@MasterPCUK
Copy link
Contributor Author

@mpaperno Fantastic! Thank you for your help!
Will the new release be official ( in apt ) for Ubuntu 18.04 or will we have to update via other means?

@JoshData
Copy link
Member

JoshData commented Feb 25, 2019

Looks like Debian or Ubuntu was patching it to work, and they must have removed the patch somewhere between Ubuntu 14.04 and now.

mpaperno added a commit to mpaperno/spampd that referenced this issue Feb 25, 2019
…a-box/mailinabox#1523);

Fix Warning for "Use of uninitialized value in string" (closes #22).
@mpaperno
Copy link

https://github.com/mpaperno/spampd/releases/tag/2.53

I doubt the old Ubuntu releases will be updated, at least not by default. There's an auto-updated list of Linux distros and which versions of spampd they package on https://github.com/mpaperno/spampd/blob/master/readme.md . As you can see, they're not quick to update :)

I'd recommend MIAB install/update spampd directly from the GH repo instead of relying on distro versions. After proper testing, of course ;-)

Looks like Debian or Ubuntu was patching it to work, and they must have removed the patch somewhere between Ubuntu 14.04 and now.

Huh? They'd have to publish the changes somewhere... never mind maybe file a bug report. Anyway, the LMTP patch was added in v2.40, and you can see from that list that Ubuntu 14.04 is still using spampd v2.30. So it either somehow worked before the "LMTP patch" (which seems unlikely based on above tests), or maybe no one used multi-delivery/lmtp... or something else changed.

@JoshData
Copy link
Member

The Debian patch is at https://sources.debian.org/patches/spampd/2.30-23/52-fix-multidest-lmtp.patch/. (This took me a long time to find.) The patch was removed in the latest version.

@mpaperno
Copy link

@JoshData Sorry, actually I think you're right... I looked at the old spampd release notes and the LMTP patch did come upstream. I found the version Debian Stretch uses, and it's patched with the LMTP fix. At first it looked like the same fix they submitted to me upstream (which got included in 2.40), but there's one crucial difference in that regex check which breaks detection of lmtp in the first place. So I guess after they updated to 2.42 (in Ubuntu 18.04) they dropped the patch, but no one ever reported the new issue until now.

@MasterPCUK
Copy link
Contributor Author

I'm currently testing latest spampd https://github.com/mpaperno/spampd/releases/tag/2.53 on a live Mail-In-A-Box v0.40. So far it works as expected.

It would be great if other could also test and let us know the results.

@JoshData
Copy link
Member

JoshData commented Feb 25, 2019

Thanks everyone!! I'm adding lmtp_destination_recipient_limit=1 and will post a new version of Mail-in-a-Box tomorrow, and once we figure out how to get the updated spampd in, we'll switch to that instead.

@mpaperno
Copy link

I dropped a note to the maintainer of the Debian spampd package about the bug/update, FWIW.

I also reviewed the remaining patches which the Debian package applies, and there are two which change the default settings of spampd as of v2.53. Both can be controlled via startup options, or patched in the code.

Add startup options to configure like patched Debian/Ubuntu package default settings:

  • --setsid
  • --homedir=/var/cache/spampd

Or patch:
2.53.deb.patch.txt

Or use patched version:
spampd-2.53-1.deb.pl.txt

@marcosms
Copy link

marcosms commented Feb 26, 2019

OK. I'm testing the complete patch. I made the following.

In my home folder:

wget https://github.com/mpaperno/spampd/archive/2.53.zip
unzip 2.53.zip
cd spampd-2.53
cp spampd.pl /usr/sbin
cd /usr/sbin
cp spampd spampdold
rm spampd
mv spampd.pl spampd
cd /etc/postfix
nano main.cf

An then i commented the line who I added before,

#lmtp_destination_recipient_limit = 1

I saved the changes an i made

sudo shutdown -r now

I made all this 10 minutes ago and i made some tests (And all my users are sending and receiving mails) and it seems that all works well. In a cople of hours i'll say you if all remains working.

@JoshData Perhaps is better test the complete patch instead of doing only lmtp_destination_recipient_limit = 1 . If this patch is working, it can be added to 0.41and resolve all the troubles at same time.

@marcosms
Copy link

Since the change of my previous post, it seems that all works normally. The mails with multiple recipients get out of the queues fast and all mail are arriving.

@marcosms
Copy link

marcosms commented Feb 26, 2019

6 hours from apply the patch and all works perfect. All mail is sent and received correctly and there are no mails in queue. As soon as they enter in the queue, they go out. Seems that it solves the trouble

(Note: my MIAB has 120 users and it does a hard work dialy, so I think is a good test). My last stats of received mail are this.

Totals: 17685 │ 6.96 days
┬ totals by time of day:
│ hour 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23
│ received 133 103 106 65 65 89 828 183 776 1485 1595 1385 1683 1570 579 824 1616 1491 1667 592 304 204 186 156

@mpaperno
Copy link

Updated spampd Debian package has been released to unstable (sid): https://packages.debian.org/unstable/source/spampd . This patched version includes using --setsid at start and the adjusted homedir I mentioned earlier.

I have no idea how to get Ubuntu to update their older releases, or if it's even possible.

@myfirstnameispaul
Copy link
Contributor

Has anyone considered requesting a backport? 2.53 is available in 20.04.

Although I've successfully built a PPA for myself a loooong time ago, I've never requested a backport.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants