Spam Filter ISP Support Forum

  New Posts New Posts RSS Feed - Invalid mesage file and no ndr
  FAQ FAQ  Forum Search   Register Register  Login Login

Invalid mesage file and no ndr

 Post Reply Post Reply
Author
luigi View Drop Down
Newbie
Newbie


Joined: 24 October 2005
Status: Offline
Points: 11
Post Options Post Options   Thanks (0) Thanks(0)   Quote luigi Quote  Post ReplyReply Direct Link To This Post Topic: Invalid mesage file and no ndr
    Posted: 06 November 2013 at 7:45am

Sometimes email with correct sender and recipient generate entries similar to this (ips, domain and emails removed for privacy reasons):

(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)
 
 
 
 
Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4104
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 06 November 2013 at 2:20pm
luigi,

From your log snippet it seems as if some entries are missing. Once a thread (114862256) in SpamFilter processes an incoming email, it will spawn a different thread (60081616) that will deliver it to destination.

It should thus be the thread 60081616 that delivers the email, not 60078736.

Can you please zip and email us the complete logfile to support at logsat dot com so we can take a look? If the file is over 8MB in size, I'll send you a PM with an alternate web uploader.
Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4104
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 07 November 2013 at 10:02am
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.


11/06/13 12:01:21:131 -- (114862256) Detected TCP Connection:
11/06/13 12:01:24:677 -- (114862256) EMail from SSS to LLL was queued (IndyF5809ADD-332B-4420-8DE8-51F04D41ADA9.tmp). Size: 14 KB, 15027 bytes
11/06/13 12:01:24:677 -- (114862256) Created thread (60081616) to handle delivery
11/06/13 12:01:25:021 -- (114862256) Disconnect

11/06/13 12:01:24:677 -- (60081616) Sending email from SSS to LLL -- 

11/06/13 12:01:24:677 -- (74964544) Starting to process queue directory...

11/06/13 12:01:24:740 -- (60078736)  - forwarding to:127.0.0.1:25025 - server error - Invalid Message file:C:\Program Files\SpamFilter\queue\IndyF5809ADD-332B-4420-8DE8-51F04D41ADA9.tmp
11/06/13 12:01:24:740 -- (60078736) EMail from: <SSS> to: LLL --  was returned to sender - server error - Invalid Message file:C:\Program Files\SpamFilter\queue\IndyF5809ADD-332B-4420-8DE8-51F04D41ADA9.tmp
11/06/13 12:01:24:865 -- (60078736) There was an error sending the NDR to  :  Need RCPT (recipient) -- 

11/06/13 12:01:25:584 -- (60081616) EMail from SSS to LLL --  was forwarded to 127.0.0.1:25025

Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
luigi View Drop Down
Newbie
Newbie


Joined: 24 October 2005
Status: Offline
Points: 11
Post Options Post Options   Thanks (0) Thanks(0)   Quote luigi Quote  Post ReplyReply Direct Link To This Post Posted: 09 November 2013 at 10:20am
Sorry for my late reply, I was out of the office for a business trip.
 
I have checked the logs and found out that this situation happens at least once a day, therefore it's not that unusual for our system...
 
 
Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4104
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 09 November 2013 at 11:11pm
Checking your logs, I see that SpamFilter is processing the queue directory every minute, instead of the default value of every hour. This would mean that this parameter in the SpamFilter.ini file was changed from 60 to 1:
FlushQueueInterval=60

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.
Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
luigi View Drop Down
Newbie
Newbie


Joined: 24 October 2005
Status: Offline
Points: 11
Post Options Post Options   Thanks (0) Thanks(0)   Quote luigi Quote  Post ReplyReply Direct Link To This Post Posted: 10 November 2013 at 3:30am
ok, I changed the setting back to 60 minutes.
I will monitor the server and see if we get this situation again.
 
Thank you...
 
 
 
Back to Top
luigi View Drop Down
Newbie
Newbie


Joined: 24 October 2005
Status: Offline
Points: 11
Post Options Post Options   Thanks (0) Thanks(0)   Quote luigi Quote  Post ReplyReply Direct Link To This Post Posted: 19 November 2013 at 4:33am
After a few days with the default flushqueue set at 60, the error would still show up.
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...
Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4104
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 21 November 2013 at 4:29pm
Luigi, as you're still having issues with longer queue interval, we're creating a patch that should resolve this issue permanently. It should be available to the public within the next 2-3 days. I'll update this thread as soon as it's available for download.
Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4104
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 27 November 2013 at 8:12am
FYI the build with a fix for this issue is v4.5.1.96, and it is available in the registered user area.
Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
luigi View Drop Down
Newbie
Newbie


Joined: 24 October 2005
Status: Offline
Points: 11
Post Options Post Options   Thanks (0) Thanks(0)   Quote luigi Quote  Post ReplyReply Direct Link To This Post Posted: 27 November 2013 at 8:54am
Thank you, I have installed the build. Will report back in a few days...
Back to Top
 Post Reply Post Reply
  Share Topic   

Forum Jump Forum Permissions View Drop Down



This page was generated in 2.967 seconds.