smtp_proxy sending data before receiving 354 go ahead

[lwimble]

Describe the bug
We have Haraka set up using smtp_proxy which proxies all connections to Amazon SES. This works great, except that on (seemingly random) occasion, Haraka seems to get "out of sync" in the process of brokering the connection between the client and SES. Haraka seems to solicit data from the client by providing it with the 354 code to go head, but has not yet seen the 354 from SES.

Expected behavior
After sending the DATA command to SES, smtp_proxy should wait for a 354 response code before soliciting data from the client and passing it to the ongoing server.

Observed behavior
smtp_proxy appears to be soliciting data from the client in form of a 354 prior to receiving the 354 from the ongoing server.

Here is the send log from the client:
`
2021-04-21 11:23:43 SERVER -> CLIENT: 220 mailproxy.mydomain.com ESMTP Haraka/2.8.27 ready
2021-04-21 11:23:43 CLIENT -> SERVER: EHLO eagle.mydomain.com
2021-04-21 11:23:43 SERVER -> CLIENT: 250-mailproxy.mydomain.com Hello {hostname redacted} [{ip address redacted}]Haraka is at your service.
2021-04-21 11:23:43 CLIENT -> SERVER: AUTH CRAM-MD5
2021-04-21 11:23:43 SERVER -> CLIENT: 334 {redacted}
2021-04-21 11:23:43 CLIENT -> SERVER: {redacted}
2021-04-21 11:23:43 SERVER -> CLIENT: 235 2.7.0 Authentication successful
2021-04-21 11:23:43 CLIENT -> SERVER: MAIL FROM:[email protected]
2021-04-21 11:23:43 SERVER -> CLIENT: 250 sender [email protected] OK
2021-04-21 11:23:43 CLIENT -> SERVER: RCPT TO:[email protected]
2021-04-21 11:23:43 SERVER -> CLIENT: 250 recipient [email protected] OK
2021-04-21 11:23:43 CLIENT -> SERVER: DATA
2021-04-21 11:23:43 SERVER -> CLIENT: 354 go ahead, make my day
2021-04-21 11:23:43 CLIENT -> SERVER: Date: Wed, 21 Apr 2021 04:23:43 -0700
2021-04-21 11:23:43 CLIENT -> SERVER: To: [email protected]
2021-04-21 11:23:43 CLIENT -> SERVER: From: CIP Trial [email protected]
2021-04-21 11:23:43 CLIENT -> SERVER: Reply-To: CIP Trial [email protected]
2021-04-21 11:23:43 CLIENT -> SERVER: Subject: Notification 2 from CIP Reporting
2021-04-21 11:23:43 CLIENT -> SERVER: Message-ID: [email protected]
2021-04-21 11:23:43 CLIENT -> SERVER: X-Mailer: PHPMailer 5.2.23 (https://github.com/PHPMailer/PHPMailer)
2021-04-21 11:23:43 CLIENT -> SERVER: MIME-Version: 1.0
2021-04-21 11:23:43 CLIENT -> SERVER: Content-Type: text/html; charset=iso-8859-1
2021-04-21 11:23:43 CLIENT -> SERVER:
2021-04-21 11:23:43 CLIENT -> SERVER: Just Testing

2021-04-21 11:23:43 CLIENT -> SERVER:
2021-04-21 11:23:43 CLIENT -> SERVER: .
2021-04-21 11:23:43 SERVER -> CLIENT: 250 End data with <CR><LF>.<CR><LF> (90752533-1542-41EF-8ACF-1D635A3EAEB8.1)
2021-04-21 11:23:43 CLIENT -> SERVER: QUIT
2021-04-21 11:23:43 SERVER -> CLIENT: 221 mailproxy.mydomain.com closing connection. Have a jolly good day.

`
If you look carefully at the transaction above, you will see that Haraka issued a 354 to the client, but later transcoded the 354 from SES to a 250 and passed it along to the client, making the client think that email was successful even though it was not.

Here is the log from the server side:

`
[NOTICE] [core] connect ip=34.228.238.223 port=52680 local_ip=:: local_port=465
[DEBUG] [core] running connect_init hooks
[DEBUG] [core] running connect_init_respond
[DEBUG] [core] running lookup_rdns hooks
[DEBUG] [core] running connect hooks
[PROTOCOL] [core] S: 220 mailproxy.mydomain.com ESMTP Haraka/2.8.27 ready
[PROTOCOL] [core] C: EHLO eagle.mydomain.com state=1
[DEBUG] [core] running ehlo hooks
[DEBUG] [core] running capabilities hooks
[DEBUG] [core] running capabilities hook in tls plugin
[DEBUG] [core] hook=capabilities plugin=tls function=advertise_starttls params="" retval=CONT msg=""
[DEBUG] [core] running capabilities hook in auth/flat_file plugin
[DEBUG] [core] hook=capabilities plugin=auth/flat_file function=hook_capabilities params="" retval=CONT msg=""
[PROTOCOL] [core] S: 250-mailproxy.mydomain.com Hello ec2-34-228-238-223.compute-1.amazonaws.com [34.228.238.223]Haraka is at your service.
[PROTOCOL] [core] S: 250-PIPELINING
[PROTOCOL] [core] S: 250-8BITMIME
[PROTOCOL] [core] S: 250-SMTPUTF8
[PROTOCOL] [core] S: 250-SIZE 0
[PROTOCOL] [core] S: 250 AUTH PLAIN LOGIN CRAM-MD5
[PROTOCOL] [core] C: AUTH CRAM-MD5 state=1
[DEBUG] [core] running unrecognized_command hooks
[DEBUG] [core] running unrecognized_command hook in tls plugin
[DEBUG] [core] hook=unrecognized_command plugin=tls function=upgrade_connection params=AUTH retval=CONT msg=""
[DEBUG] [core] running unrecognized_command hook in auth/flat_file plugin
[INFO] [auth/flat_file] ticket: <72473. [email protected]>
[PROTOCOL] [core] S: 334 {redacted}
[INFO] [core] hook=unrecognized_command plugin=auth/flat_file function=hook_unrecognized_command params=AUTH retval=OK msg=""
[PROTOCOL] [core] C: {redacted}
[DEBUG] [core] running unrecognized_command hooks
[DEBUG] [core] running unrecognized_command hook in tls plugin
[DEBUG] [core] hook=unrecognized_command plugin=tls function=upgrade_connection params="{redacted}" retval=CONT msg=""
[DEBUG] [core] running unrecognized_command hook in auth/flat_file plugin
[PROTOCOL] [core] S: 235 2.7.0 Authentication successful
[INFO] [core] hook=unrecognized_command plugin=auth/flat_file function=hook_unrecognized_command params="{redacted}" retval=OK msg=""
[PROTOCOL] [core] C: MAIL FROM:<[email protected]> state=1
[DEBUG] [core] running mail hooks
[DEBUG] [core] running mail hook in queue/smtp_proxy plugin
[INFO] [queue/smtp_proxy] forwarding to email-smtp.us-east-1.amazonaws.com:587
[INFO] [core] [smtp_client_pool] [587:email-smtp.us-east-1.amazonaws.com:300:{redacted}] dispense() clients=1 available=0
[DEBUG] [core] [smtp_client_pool] [587:email-smtp.us-east-1.amazonaws.com:300:{redacted}] createResource() - creating obj - count=1 min=0 max=10
[DEBUG] [core] [smtp_client_pool] uuid=3A046759-7BB8-4F78-8874-3685D63A9C9D host=email-smtp.us-east-1.amazonaws.com port=587 pool_timeout=300 created
[DEBUG] [queue/smtp_proxy] Got smtp_client: 3A046759-7BB8-4F78-8874-3685D63A9C9D
[DEBUG] [core] socket.remoteAddress undefined
[PROTOCOL] [queue/smtp_proxy] S: 220 email-smtp.amazonaws.com ESMTP SimpleEmailService-d-43V1O3ZGA vSsLXifzZNTpkzuNDQsS\r\n
[PROTOCOL] [queue/smtp_proxy] C: EHLO mailproxy.mydomain.com
[PROTOCOL] [queue/smtp_proxy] S: 250-email-smtp.amazonaws.com\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-8BITMIME\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-STARTTLS\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-AUTH PLAIN LOGIN\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250 Ok\r\n
[PROTOCOL] [queue/smtp_proxy] C: STARTTLS
[PROTOCOL] [queue/smtp_proxy] S: 220 Ready to start TLS\r\n
[DEBUG] [core] client TLS upgrade in progress, awaiting secured.
[DEBUG] [core] client TLS secured.
[INFO] [core] secured: cipher=ECDHE-RSA-AES128-GCM-SHA256 version=TLSv1.2 verified=true cn="email-smtp.us-east-1.amazonaws.com" organization="undefined" issuer="Amazon" expires="Oct 31 23:59:59 2021 GMT" fingerprint=96:44:E2:FD:3E:C9:A2:66:45:F2:C4:E9:1F:FF:45:AE:C8:DD:53:12
[PROTOCOL] [queue/smtp_proxy] C: EHLO mailproxy.mydomain.com
[PROTOCOL] [queue/smtp_proxy] C: EHLO mailproxy.mydomain.com
[PROTOCOL] [queue/smtp_proxy] S: 250-email-smtp.amazonaws.com\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-8BITMIME\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-STARTTLS\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-AUTH PLAIN LOGIN\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250 Ok\r\n
[DEBUG] [core] [smtp_client_pool] uuid=3A046759-7BB8-4F78-8874-3685D63A9C9D authenticating as "{redacted}"
[PROTOCOL] [queue/smtp_proxy] C: AUTH PLAIN {redacted}=
[PROTOCOL] [queue/smtp_proxy] S: 250-email-smtp.amazonaws.com\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-8BITMIME\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-STARTTLS\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250-AUTH PLAIN LOGIN\r\n
[PROTOCOL] [queue/smtp_proxy] S: 250 Ok\r\n
[INFO] [core] SERVER RESPONSE, CLIENT auth, authenticating=false,code=250,cont= ,msg=Ok
[PROTOCOL] [queue/smtp_proxy] C: MAIL FROM:<[email protected]>
[PROTOCOL] [queue/smtp_proxy] S: 235 Authentication successful.\r\n
[DEBUG] [core] hook=mail plugin=queue/smtp_proxy function=hook_mail params=<[email protected]> retval=CONT msg=""
[NOTICE] [core] sender <[email protected]> code=CONT msg=""
[PROTOCOL] [core] S: 250 sender <[email protected]> OK
[PROTOCOL] [core] C: RCPT TO:<[email protected]> state=1
[DEBUG] [core] running rcpt hooks
[DEBUG] [core] running rcpt_ok hooks
[DEBUG] [core] running rcpt_ok hook in queue/smtp_proxy plugin
[PROTOCOL] [queue/smtp_proxy] C: RCPT TO:<[email protected]>
[PROTOCOL] [queue/smtp_proxy] S: 250 Ok\r\n
[DEBUG] [core] hook=rcpt_ok plugin=queue/smtp_proxy function=hook_rcpt_ok params="" retval=CONT msg=""
[NOTICE] [core] recipient <[email protected]> code=OK msg="" sender=[email protected]
[PROTOCOL] [core] S: 250 recipient <[email protected]> OK
[PROTOCOL] [core] C: DATA state=1
[DEBUG] [core] running data hooks
[DEBUG] [core] running data hook in queue/smtp_proxy plugin
[PROTOCOL] [queue/smtp_proxy] C: DATA
[PROTOCOL] [queue/smtp_proxy] S: 250 Ok\r\n
[DEBUG] [core] hook=data plugin=queue/smtp_proxy function=hook_data params="" retval=CONT msg=""
[PROTOCOL] [core] S: 354 go ahead, make my day
[DEBUG] [core] running data_post hooks
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=duplicate_singular params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=missing_required params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=invalid_return_path params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [headers] message date: Wed, 21 Apr 2021 04:23:43 -0700
[DEBUG] [core] hook=data_post plugin=headers function=invalid_date params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=user_agent params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=direct_to_mx params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=from_match params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=delivered_to params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=mailing_list params="" retval=CONT msg=""
[DEBUG] [core] running data_post hook in headers plugin
[DEBUG] [core] hook=data_post plugin=headers function=from_phish params="" retval=CONT msg=""
[NOTICE] [core] message mid=<[email protected]> size=554 rcpts=1/0/0 delay=0.001 code=CONT msg=""
[DEBUG] [core] running queue_outbound hooks
[DEBUG] [core] running queue_outbound hook in queue/smtp_proxy plugin
[PROTOCOL] [queue/smtp_proxy] S: 354 End data with <CR><LF>.<CR><LF>\r\n
[INFO] [core] hook=queue_outbound plugin=queue/smtp_proxy function=hook_queue params="" retval=OK msg="End data with <CR><LF>.<CR><LF>"
[DEBUG] [core] running queue_ok hooks
[NOTICE] [core] queue code=OK msg="End data with <CR><LF>.<CR><LF> (90752533-1542-41EF-8ACF-1D635A3EAEB8.1)"
[PROTOCOL] [core] S: 250 End data with <CR><LF>.<CR><LF> (90752533-1542-41EF-8ACF-1D635A3EAEB8.1)
[DEBUG] [core] running reset_transaction hooks
[DEBUG] [core] [smtp_client_pool] 3A046759-7BB8-4F78-8874-3685D63A9C9D resetting, state=2
[PROTOCOL] [core] C: QUIT state=1
[DEBUG] [core] running quit hooks
[DEBUG] [core] running quit hook in queue/smtp_proxy plugin
[DEBUG] [core] hook=quit plugin=queue/smtp_proxy function=hook_quit params="" retval=CONT msg=""
[PROTOCOL] [core] S: 221 mailproxy.mydomain.com closing connection. Have a jolly good day.
[DEBUG] [core] client has disconnected
[DEBUG] [core] running disconnect hooks
[DEBUG] [core] client has disconnected
[DEBUG] [core] running disconnect hook in tls plugin
[DEBUG] [core] client has disconnected
[DEBUG] [core] hook=disconnect plugin=tls function=hook_disconnect params="" retval=CONT msg=""
[DEBUG] [core] client has disconnected
[DEBUG] [core] running disconnect hook in queue/smtp_proxy plugin
[DEBUG] [core] client has disconnected
[DEBUG] [core] hook=disconnect plugin=queue/smtp_proxy function=hook_disconnect params="" retval=CONT msg=""
[NOTICE] [core] disconnect ip={redacted} rdns={redacted} helo=eagle.mydomain.com relay=Y early=N esmtp=Y tls=Y pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=554 lr="" time=0.206
[DEBUG] [core] [smtp_client_pool] 3A046759-7BB8-4F78-8874-3685D63A9C9D releasing, state=3

`
I've bolded the main lines of interest above. I would normally expect a 354 in response to DATA (and in cases where emails are successful, that's exactly what I see in the logs) , but it's seeing a 250 instead, then sending the data.

Does anyone have any idea what's really going on here ?

Steps To Reproduce

Since this only happens on occasion, I'm unsure how to reliably reproduce it. I captured these instances out of our logs by running tests until it happened.

System Info:

Haraka	Haraka.js — Version: 2.8.27
Node	v14.16.1
OS	Linux ip-172-30-0-173 5.4.0-1038-aws #40-Ubuntu SMP Fri Feb 5 23:50:40 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
openssl	OpenSSL 1.1.1f 31 Mar 2020

Additional context

No additional context to provide, but I'm happy to answer questions or provide the contents of any files you are interested in.

[msimerson]

While troubleshooting a related issue with smtp_forward, I have observed this same behavior and it's related to using generic-pool. When I disable the pooling (as PR 3113 does, this issue goes away.

[msimerson]

Until we have evidence otherwise, I'm assuming this was also fixed by #3115