Envelope never gets failure line added
SMTP email proxy and relay server
Brought to you by:
graeme_walker
Menu
▾
▴
#46 Envelope never gets failure line added
OK, so the envelope is not getting updated with a failure during this scenario. Running 2.2.
The envelope never gets the failure line added, so it never "ages out". Log section further down.
X-MailRelay-Format: #2821.4
X-MailRelay-Content: 7bit
X-MailRelay-From: admin@localhost
X-MailRelay-ToCount: 1
X-MailRelay-To-Remote: pxxxx@xxxt.biz
X-MailRelay-Authentication:
X-MailRelay-Client: 127.0.0.1
X-MailRelay-ClientName:
X-MailRelay-ClientCertificate:
X-MailRelay-End: 1
mildly edited log section:
emailrelay: info: locking file "emailrelay.8740.685547.166939.envelope"
emailrelay: info: rx<<: "220 B.outlook.com Microsoft ESMTP MAIL Service ready at Wed, 5 May 2021 20:19:19 +0000"
emailrelay: info: tx>>: "EHLO J"
emailrelay: info: rx<<: "250-n.outlook.com Hello []"
emailrelay: info: rx<<: "250-SIZE 157286400"
emailrelay: info: rx<<: "250-PIPELINING"
emailrelay: info: rx<<: "250-DSN"
emailrelay: info: rx<<: "250-ENHANCEDSTATUSCODES"
emailrelay: info: rx<<: "250-STARTTLS"
emailrelay: info: rx<<: "250-8BITMIME"
emailrelay: info: rx<<: "250-BINARYMIME"
emailrelay: info: rx<<: "250-CHUNKING"
emailrelay: info: rx<<: "250 SMTPUTF8"
emailrelay: info: tx>>: "STARTTLS"
emailrelay: info: rx<<: "220 2.0.0 SMTP server ready"
emailrelay: info: tls: certificate verification: [peer certificate not signed by a trusted ca]
emailrelay: info: tls protocol established with 104.47.51.110:25 protocol TLSv1.2 cipher TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
emailrelay: info: tx>>: "EHLO J"
emailrelay: info: rx<<: "250-Boutlook.com Hello []"
emailrelay: info: rx<<: "250-SIZE 157286400"
emailrelay: info: rx<<: "250-PIPELINING"
emailrelay: info: rx<<: "250-DSN"
emailrelay: info: rx<<: "250-ENHANCEDSTATUSCODES"
emailrelay: info: rx<<: "250-8BITMIME"
emailrelay: info: rx<<: "250-BINARYMIME"
emailrelay: info: rx<<: "250-CHUNKING"
emailrelay: info: rx<<: "250 SMTPUTF8"
emailrelay: info: tx>>: "MAIL FROM:admin@localhost BODY=7BIT"
emailrelay: info: rx<<: "250 2.1.0 Sender OK"
emailrelay: info: tx>>: "RCPT TO:"
emailrelay: info: rx<<: "250 2.1.5 Recipient OK"
emailrelay: info: tx>>: "DATA"
emailrelay: info: rx<<: "354 Start mail input; end with <crlf>.<crlf>"
emailrelay: info: tx>>: [24 line(s) of content]
emailrelay: info: tx>>: "."
emailrelay: info: rx<<: "550 5.7.750 Service unavailable. Client blocked from sending from unregistered domains. For more information please go to http://go.microsoft.com/fwlink/?LinkId=526653. AS(800051) [BN1NAM02FT020.eop-nam02.prod.protection.outlook.com]"
emailrelay: info: failing file: "emailrelay.8740.685547.166939.envelope.busy" -> "emailrelay.8740.685547.166939.envelope.bad"</crlf></crlf>
also this appears to be related (i think) to a change in behavior on O365 and their SMTP connectors and how it handles invalid source domains. Obviously we should send from valid domains but users are users. It used to fail differently and that woudl let the envelope update properly.
Hello! Any thoughts on this? It continues to be a problem for us.
Sorry I missed this, but it is hard to see how this could happen except as a file permissioning issue on Linux or a file locking issue on Windows. You didn't say what o/s you are on. Windows has a nasty habit of locking files whenever they are opened, so perhaps you have something reading the envelope file while it is still '.busy'. Or perhaps a virus scanner.
We are on windows. It's only this scenario that doesn't get a line added to the envelope: "550 5.7.750 Service unavailable. Client blocked from sending from unregistered domains. For more information please go to http://go.microsoft.com/fwlink/?LinkId=526653. AS(800051) [BN1NAM02FT020.eop-nam02.prod.protection.outlook.com]" -- otherwise it works as expected.
The only thing that makes sense is if the file cannot be opened when the reason is appended; there is no code path that gives you the 'failing file' line in the log file that does not first try to append the reason. So I have built you an executable that adds some more diagnostics around the relevant code. Please could you give that a go and let me know what the logs show.
https://sourceforge.net/projects/emailrelay/files/OldFiles/emailrelay-2.2-pw700z.exe/download
Log Section
emailrelay-2.2-pw700z: info: forwarding: [startup]
emailrelay-2.2-pw700z: info: smtp connection to 104.47.51.110:25
emailrelay-2.2-pw700z: info: locking file "emailrelay.2352.641941.105153.envelope"
emailrelay-2.2-pw700z: info: rx<<: "220 BN1NAM02FT062.mail.protection.outlook.com Microsoft ESMTP MAIL Service ready at Sat, 5 Mar 2022 18:51:34 +0000"
emailrelay-2.2-pw700z: info: tx>>: "EHLO JFSCORPSG02.local.xxx.com"
emailrelay-2.2-pw700z: info: rx<<: "250-BN1NAM02FT062.mail.protection.outlook.com Hello [xxx]"
emailrelay-2.2-pw700z: info: rx<<: "250-SIZE 157286400"
emailrelay-2.2-pw700z: info: rx<<: "250-PIPELINING"
emailrelay-2.2-pw700z: info: rx<<: "250-DSN"
emailrelay-2.2-pw700z: info: rx<<: "250-ENHANCEDSTATUSCODES"
emailrelay-2.2-pw700z: info: rx<<: "250-STARTTLS"
emailrelay-2.2-pw700z: info: rx<<: "250-8BITMIME"
emailrelay-2.2-pw700z: info: rx<<: "250-BINARYMIME"
emailrelay-2.2-pw700z: info: rx<<: "250-CHUNKING"
emailrelay-2.2-pw700z: info: rx<<: "250 SMTPUTF8"
emailrelay-2.2-pw700z: info: tx>>: "STARTTLS"
emailrelay-2.2-pw700z: info: rx<<: "220 2.0.0 SMTP server ready"
emailrelay-2.2-pw700z: info: tls: certificate verification: [peer certificate not signed by a trusted ca]
emailrelay-2.2-pw700z: info: tls protocol established with 104.47.51.110:25 protocol TLSv1.2 cipher TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
emailrelay-2.2-pw700z: info: tx>>: "EHLO JFSCORPSG02.local.xxx.com"
emailrelay-2.2-pw700z: info: rx<<: "250-BN1NAM02FT062.mail.protection.outlook.com Hello [xxx]"
emailrelay-2.2-pw700z: info: rx<<: "250-SIZE 157286400"
emailrelay-2.2-pw700z: info: rx<<: "250-PIPELINING"
emailrelay-2.2-pw700z: info: rx<<: "250-DSN"
emailrelay-2.2-pw700z: info: rx<<: "250-ENHANCEDSTATUSCODES"
emailrelay-2.2-pw700z: info: rx<<: "250-8BITMIME"
emailrelay-2.2-pw700z: info: rx<<: "250-BINARYMIME"
emailrelay-2.2-pw700z: info: rx<<: "250-CHUNKING"
emailrelay-2.2-pw700z: info: rx<<: "250 SMTPUTF8"
emailrelay-2.2-pw700z: info: tx>>: "MAIL FROM:endofngt@capuat2.local.xxx.com BODY=7BIT"
emailrelay-2.2-pw700z: info: rx<<: "250 2.1.0 Sender OK"
emailrelay-2.2-pw700z: info: tx>>: "RCPT TO:<xxx>"
emailrelay-2.2-pw700z: info: rx<<: "250 2.1.5 Recipient OK"
emailrelay-2.2-pw700z: info: tx>>: "DATA"
emailrelay-2.2-pw700z: info: rx<<: "354 Start mail input; end with <crlf>.<crlf>"
emailrelay-2.2-pw700z: info: tx>>: [17 line(s) of content]
emailrelay-2.2-pw700z: info: tx>>: "."
emailrelay-2.2-pw700z: info: rx<<: "550 5.4.1 All recipient addresses rejected : Access denied. AS(201806271) [BN1NAM02FT062.eop-nam02.prod.protection.outlook.com]"
emailrelay-2.2-pw700z: info: failing file: reason=smtp client failure: 5.4.1 All recipient addresses rejected : Access denied. AS(201806271) [BN1NAM02FT062.eop-nam02.prod.protection.outlook.com] code=550
emailrelay-2.2-pw700z: info: appending reason to [D:\spool\out-jfs\emailrelay.2352.641941.105153.envelope.busy]: good=0 is-open=0 pos=-1
emailrelay-2.2-pw700z: info: appended reason: good=0 is-open=0 pos=-1
emailrelay-2.2-pw700z: info: appended reason: closed-ok=0
emailrelay-2.2-pw700z: info: failing file: "emailrelay.2352.641941.105153.envelope.busy" -> "emailrelay.2352.641941.105153.envelope.bad"</crlf></crlf></xxx>
X-MailRelay-Format: #2821.4
X-MailRelay-Content: 7bit
X-MailRelay-From: endofngt@capuat2.local.xxx.com
X-MailRelay-ToCount: 1
X-MailRelay-To-Remote: xxx@xxx.com
X-MailRelay-Authentication:
X-MailRelay-Client: 127.0.0.1
X-MailRelay-ClientName:
X-MailRelay-ClientCertificate:
X-MailRelay-End: 1
hopefully there's something helpful in there for you. It does rename the envelope .bad, but it never appends the failure line.
Here's an example where it worked:
emailrelay-2.2-pw700z: info: locking file "emailrelay.2352.641941.121886.envelope"
emailrelay-2.2-pw700z: info: tx>>: "MAIL FROM:DoNotReply@xxx.com BODY=7BIT"
emailrelay-2.2-pw700z: info: rx<<: "250 2.1.0 Sender OK"
emailrelay-2.2-pw700z: info: tx>>: "RCPT TO:xxx@xxx.com"
emailrelay-2.2-pw700z: info: rx<<: "550 5.4.1 Recipient address rejected: Access denied. AS(201806281) [BN1NAM02FT062.eop-nam02.prod.protection.outlook.com]"
emailrelay-2.2-pw700z: info: tx>>: "RSET"
emailrelay-2.2-pw700z: info: rx<<: "250 2.0.0 Resetting"
emailrelay-2.2-pw700z: info: failing file: reason=smtp client failure: one or more recipients rejected code=250
emailrelay-2.2-pw700z: info: appending reason to [D:\spool\out-jfs\emailrelay.2352.641941.121886.envelope.busy]: good=1 is-open=1 pos=0
emailrelay-2.2-pw700z: info: appended reason: good=1 is-open=1 pos=1481
emailrelay-2.2-pw700z: info: appended reason: closed-ok=1
emailrelay-2.2-pw700z: info: failing file: "emailrelay.2352.641941.121886.envelope.busy" -> "emailrelay.2352.641941.121886.envelope.bad"
and
X-MailRelay-Format: #2821.5
X-MailRelay-Content: 7bit
X-MailRelay-From: DoNotReply@xxx.com
X-MailRelay-ToCount: 1
X-MailRelay-To-Remote:xxx@xxx.com
X-MailRelay-Authentication:
X-MailRelay-Client: 127.0.0.1
X-MailRelay-ClientCertificate:
X-MailRelay-MailFromAuthIn:
X-MailRelay-MailFromAuthOut:
X-MailRelay-End: 1
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
X-MailRelay-Reason: smtp client failure: one or more recipients rejected
X-MailRelay-ReasonCode: 250
Help! :)
Hmm, I did respond at the time, but I am not seeing the response here...
I spotted a mistake in the code which meant that the envelope file was not being opened lock-free as intended. I did you another build of the emailrelay binary for you to test:
https://sourceforge.net/projects/emailrelay/files/OldFiles/emailrelay-2.2-pw700z-2.exe/download
By way of a recap, the logs from your testing of 5 March do show the the envelope file cannot be opened when emailrelay tries to add the failure reason. It is likely IMO that that is because something else in your environment opens the file and locks it briefly. There is a coding error which means that when emailrelay tries to open the file it does not specify the SH_DENYNO flag. I have corrected this in the "-2" binary, but I have not investigated whether this is a likely fix for the proposed failure scenario. If it's not a fix then I don't think there is anything else I can do because the problem lies with whatever it is that is locking the file.
OK, seems to be no change in behavior with the new exe. :( I disabled antivirus to see if that made any difference, it did not. Below is a large section of the log if it's helpful. We push probably 10k+ emails through a day, and something like 3-7 emails get into this scenario, and they all seem to have bad sender addresses.
The filename there is "emailrelay-2.2-pw700z" and not "emailrelay-2.2-pw700z-2". Are you sure you are testing the "-2" binary? I would expect to see log lines like 'file open failed: ... get-last-error=...", which would give the reason code for the failed file-open operation.
OK, sorry for the confusion, i was using the new file, but i pulled a log section that I guess was before the new file was in use. Since today's log was purely the new version, i grabbed a section, and noticed the "permission denied" error, seen below.
I gave the group users "full control" of the folder and that seems to have resolved it. It was running as my admin account, but i guess needed to be elevated to use the administrator permissions. Why it only impacted a small number of files, i suppose we will never know, but it seems to be working now.
Thank you for working through it with me.
I'm glad this is working for you now, It's rather odd that a file just created by a process cannot be opened again by the same process a few milliseconds later for appending. In emailrelay on windows every file is created with open permissions and 'denyno' sharing (typos permitting) via the C or C++ run-time library -- but I am not sure exactly how that maps down to the windows file-system. I long ago gave up trying to understand windows permissioning. It's like it was designed by a student who had swallowed the text book but had no real-world admin experience.
The new v2.3 release fixes the typo so that the envelope is opened with a sharing mode of 'sh-denyno', and an error is logged if the envelope file cannot be reopened to append the failure reason.