(114862256) Detected TCP Connection: x.x.x.x
(114862256) Received STARTTLS command
(114862256) Received MAIL FROM:

(114862256) Received RCPT TO:
(114862256) - SPF analysis for done: - none
(114862256) Mail from:
(114862256) - MAPS search done...
(114862256) RCPT TO: accepted
(114862256) Checking SFDE
(114862256) Checking SURBL
(114862256) Starting queueing procedures
(114862256) EMail from  to  was queued (IndyF5809ADD-332B-4420-8DE8-51F04D41ADA9.tmp). Size: 14 KB, 15027 bytes
(114862256) Created thread (60081616) to handle delivery
(60081616) Sending email from  to  --

 

At this point the thread number gets changed:

 

 

(60078736)  - forwarding to:xxx.xxx.xxx.xxx - server error - Invalid Message file:C:\Program Files\SpamFilter\queue\IndyF5809ADD-332B-4420-8DE8-51F04D41ADA9.tmp
(60078736) EMail from:  to:  --  was returned to sender - server error - Invalid Message file:C:\Program Files\SpamFilter\queue\IndyF5809ADD-332B-4420-8DE8-51F04D41ADA9.tmp
(60078736) There was an error sending the NDR to  :  Need RCPT (recipient) --

 

now the correct thread number returns

 

(60081616) EMail from to --  was forwarded to x.x.x.x

 

and the email has, in fact, gone through...

 

In the badmail folder there is no .tmp file but only the related .rcpt file that only contains sender and recipient.

 

 

Any ideas of what is going on?

Why does the server log that the email "was returned to sender" but the email gets sent anyway?

 

Running version 4.5.1.94 (standard, no av plugin)

 

 

 

 

Luigi,

We found the issue. In a very rare and unusual circumstance, just as SpamFilter was forwarding the email to the destination server at 127.0.0.1:25025 (the two entries with 60081616 in blue below), an hourly process that re-delivers any emails that may have been stuck in the queue due to delivery problems started (line in green with 74964544).

This process runs by default once an hour, and it (mistakenly) also picked up the email that was being delivered already (lines in red with 60078736). 

When receiving and forwarding an email, SpamFilter creates a .tmp file, and then immediately renames it specifically to avoid having it caught by mistake by that hourly process. Unfortunately here the renaming procedure occurred just as the queue was being processed. So the process that re-delivers emails stuck in the queue saw a .tmp file to be delivered, but when it tried to read it the file was already gone as it had been renamed. This caused the "server error - Invalid Message file" error to be logged. In the meantime, the email was being delivered to your server successfully, as the last entry "was forwarded to 127.0.0.1:25025" stated.

Flushing the queue every minute is indeed going to be causing issues like the one you're seeing, especially when large files are still present in the queue being delivered at that moment. I strongly recommend you increase that value back to the default of 60 minutes, and not less than 20-30 minutes, which should eliminate these errors in the logs.

I have upped the value to 95 and had no errors for a couple of days. This morning the error has shown up again.

I have now upped the value to 147, let's see if it changes anything...