Pegasus Mail & Mercury

Sadly it seems that the old problem with auto-replies being sent more than once to the same sender is still around in M/32 4.51. The problem, well documented by Troy Thompson on the Mercury mailing list May 3, 2005, is that the AREPLY.KFL file, that holds addresses to which auto-replies have been sent, gets deleted by the program. I quote Troy's post below for technical details.

In vacation times this is a source of annoyance for us and I'm sure a lot of other Mercury users, as well as a potential cause for mail storms. As the Mercury help file states:

To avoid the possibility of mail storms (which can happen when two accounts start auto-replying to each other, or when an autoreply is sent to a list server), Mercury remembers every address from which a message has been successfully delivered for the account in the last 48 hours; if more than one message comes in from the same address in any 48 hour period, Mercury will generate only one auto-reply. The auto-reply memory is stored in a file called AREPLY.KFL in the user's new mail directory.

/Rolf

Subject:	Mercury auto-reply : AREPLY.KFL killfile is getting destroyed/rewritten
From:	Troy Thompson <tthompson@ENVISIONWARE.COM>
Reply-To:	tthompson@envisionware.com
Date:	Tue, 3 May 2005 18:29:36 -0400
Content-Type:	text/plain

Ah HAH! I've finally caught this one "in the act" as it were. I've had
Sysinternals FileMon running for several days while one of our employees is
offsite.

His AREPLY.KFL file is getting repeatedly DELETED by mercury.exe.

The Sysinternals FileMon log contains the following columns:

line# Timestamp process-name:PID command path result

I'm sorry I can't format this any better; the lines are quite long. Try
maximizing on a hi-res screen perhaps to reduce line wrap.

Interesting lines from the capture log:

First message, and the KFL is created...
93438 4:24:35 AM mercury.exe:5656 DIRECTORY D:\MERCURY\MAIL\pdenig\ NO SUCH
FILE FileBothDirectoryInformation: AREPLY.KFL
93439 4:24:35 AM mercury.exe:5656 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
FILE NOT FOUND Options: Open Access: All
93440 4:24:35 AM mercury.exe:5656 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
FILE NOT FOUND Options: Open Access: All
93441 4:24:35 AM mercury.exe:5656 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
FILE NOT FOUND Options: Open Access: All
93442 4:24:35 AM mercury.exe:5656 CREATE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Options: OverwriteIf Access: All
93443 4:24:35 AM mercury.exe:5656 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
FILE NOT FOUND Options: Open Access: All
93444 4:24:35 AM mercury.exe:5656 WRITE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Offset: 0 Length: 18
93445 4:24:35 AM mercury.exe:5656 CLOSE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS


Later, it gets updated...

93546 5:08:27 AM mercury.exe:5656 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Options: Open Access: All
93547 5:08:27 AM mercury.exe:5656 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Options: Open Access: All
93548 5:08:27 AM mercury.exe:5656 QUERY INFORMATION
D:\MERCURY\MAIL\pdenig\AREPLY.KFL SUCCESS FileFsVolumeInformation
93549 5:08:27 AM mercury.exe:5656 QUERY INFORMATION
D:\MERCURY\MAIL\pdenig\AREPLY.KFL SUCCESS FileInternalInformation
93550 5:08:27 AM mercury.exe:5656 QUERY INFORMATION
D:\MERCURY\MAIL\pdenig\AREPLY.KFL SUCCESS Length: 18
93551 5:08:27 AM mercury.exe:5656 CLOSE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS
93552 5:08:27 AM mercury.exe:5656 READ D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Offset: 0 Length: 512
93553 5:08:27 AM mercury.exe:5656 READ D:\MERCURY\MAIL\pdenig\AREPLY.KFL END
OF FILE Offset: 18 Length: 512
93554 5:08:27 AM mercury.exe:5656 QUERY INFORMATION
D:\MERCURY\MAIL\pdenig\AREPLY.KFL SUCCESS Length: 18
93555 5:08:27 AM mercury.exe:5656 WRITE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Offset: 18 Length: 25
93556 5:08:27 AM mercury.exe:5656 CLOSE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS

All is happy for a very long time, over 1600+ lines. Then Something
Happened...

Note the PID of mercury.exe changed. Did it crash and get restarted by the
loader.exe? It's not supposed to restart until 2AM local time...

95065 11:55:15 PM mercury.exe:2284 DIRECTORY D:\MERCURY\MAIL\pdenig\ SUCCESS
FileBothDirectoryInformation: AREPLY.KFL
95066 11:55:15 PM mercury.exe:2284 DIRECTORY D:\MERCURY\MAIL\pdenig\ SUCCESS
FileBothDirectoryInformation: AREPLY.KFL
95067 11:55:15 PM mercury.exe:2284 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Options: Open Access: All
95068 11:55:15 PM mercury.exe:2284 QUERY INFORMATION
D:\MERCURY\MAIL\pdenig\AREPLY.KFL SUCCESS FileObjectIdInformation
95069 11:55:15 PM mercury.exe:2284 DELETE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS
95070 11:55:15 PM mercury.exe:2284 CLOSE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS
95071 11:55:15 PM mercury.exe:2284 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
FILE NOT FOUND Options: Open Access: All
95072 11:55:15 PM mercury.exe:2284 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
FILE NOT FOUND Options: Open Access: All
95073 11:55:15 PM mercury.exe:2284 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
FILE NOT FOUND Options: Open Access: All
95074 11:55:15 PM mercury.exe:2284 CREATE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Options: OverwriteIf Access: All
95075 11:55:15 PM mercury.exe:2284 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
FILE NOT FOUND Options: Open Access: All
95076 11:55:15 PM mercury.exe:2284 WRITE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Offset: 0 Length: 23
95077 11:55:15 PM mercury.exe:2284 CLOSE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS

Line 95069 really concerns me! DELETE? After that point, EVERY subsequent
open of his AREPLY.KFL gets a DELETE thrown in for good measure. The
AREPLY.KFL only shows one address line and will not grow beyond that point.

The KFL got up to 664 bytes apparently, then went goofy.

I renamed the "broken" KFL file and restarted Mercury; as of this moment,
it's happy again and is not DELETEing the KFL before it appends.

The server is a rather hefty Windows 2003 Server running Mercury/32 4.01b.
Other variables include Symantec AntiVirus Corporate Edition 9.03 in "file
system autoprotect" configuration only (no SMTP features).

-----
Troy Thompson
IT Manager, Envisionware, Inc
tthompson@envisionware.com

OK, could be that the first 48 hours after the file was created works correctly. However, after that point every attempt to update the file will cause it to be deleted according to my  experience. For instance, I sent several cc's to a colleague that's on vacation a few days ago, and received an autoreply for each (at 19.36, 19.52, and 20.10).

/Rolf 

Rolf Lindby:

OK, could be that the first 48 hours after the file was created works correctly. However, after that point every attempt to update the file will cause it to be deleted according to my  experience. For instance, I sent several cc's to a colleague that's on vacation a few days ago, and received an autoreply for each (at 19.36, 19.52, and 20.10).

In this case the program runs on a Windows 2000 Server under an account in the administrators group (which in itself may not be a brilliant idea, but at least rules out the possibility of insufficient user rights). It's been run on different hardware (and different disks) with the same result, so it's not likely to be due to disk problems or anything like that. There is no background A/V scanner running or installed, and this machine has no other roles than being a mail server, so I can't think of any process that would have a reason to access this file other than Mercury/32.

From the file access logs provided by Troy I'd say that the critical point is not the fopen call itself, but something happening shortly after that:

95067 11:55:15 PM mercury.exe:2284 OPEN D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS Options: Open Access: All
95068 11:55:15 PM mercury.exe:2284 QUERY INFORMATION
D:\MERCURY\MAIL\pdenig\AREPLY.KFL SUCCESS FileObjectIdInformation
95069 11:55:15 PM mercury.exe:2284 DELETE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS
95070 11:55:15 PM mercury.exe:2284 CLOSE D:\MERCURY\MAIL\pdenig\AREPLY.KFL
SUCCESS

I read this as
- file found and opened for r/w
- file system information about the file requested and recieved
- delete command sent
- file closed
At this time the contents of the file have not been read at all, actually.

If there is anything I can do to test this further I'm at your disposal.

/Rolf

Stranger and stranger.

When Mercury checks AREPLY.KFS, it does the 48-hour check as part of the process... So, before examining the contents of AREPLY.KFS, it first checks the age of the file and removes it if it's too old. I'm fairly sure that this is what is leading to the sequence of log entries in Rolf's last post. Here's the actual code from Mercury that does this test:

   sprintf (fname, "%s\\AREPLY.KFL", newmaildir);
   if (check_existence (fname) != 0)
      if (stat (fname, &statblk) == 0)
         if ((time (NULL) - statblk.st_ctime) > killfile_lifetime)
            remove (fname);

It checks to see whether or not the file exists: if it does, it calls "stat" (a posix runtime library function) to get the file time information and checks to see whether the file's creation time is more than 48 hours ago: if it is, it deletes the file.

Now, the only way this can happen, is if the Operating System is returning an invalid value for the "ctime" member of "statblk". Note also that for the file to be deleted, the call to "stat" has to be successful, so the value of "ctime" *should* be correct.

What file system are you using? NTFS, FAT, FAT32 or something else? It sounds as though the OS is failing to return sensible values, yet it worked here just now when I tried it (XP+SP2 on an NTFS volume).

I may be able to rewrite this so it does its tests a different way, but I recall running into problems with the way file times are reported by the OS in the past, so it might not be as straightforward as simply calling a different function.

Rolf, send me your e-mail address offline please - I might write a five-line utility to see just what "stat" is actually returning on your system.

Cheers!

-- David --

This installation runs on Windows 2000 Server sp4 with NTFS, so in theory it should behave the same as in your setup. Regional settings should probably not affect this, but anyhow it's the English OS version with Swedish locale selected. Troy wrote he used Windows 2003 Server, which most likely means that it was NTFS as well.

E-mail address is on it's way.

 /Rolf
 

There must be something bogus about the background routines. We're using Windows Server 2003 Swedish Version with Swedish Locale, and we're having the same problem. Our locale reads dates and times as: YYYY-MM-DD HH:MM:SS with a 24 hour clock. The file system is NTFS on all servers. A matching of a file log with your routine, seems to work when the file create timestamp is within 48 hours, but otherwise all fails. Even the delete seems to fail, or heaven forbid, the create timestamp attribute is altered to the previous timestamp. A correct file open/compare procedure looks like this:

23:42:17 mercury.exe:3716 DIRECTORY D:\MAIL1\MAIL\m1016005\ SUCCESS FileBothDirectoryInformation: AREPLY.KFL 
23:42:17 mercury.exe:3716 DIRECTORY D:\MAIL1\MAIL\m1016005\ SUCCESS FileBothDirectoryInformation: AREPLY.KFL 
23:42:17 mercury.exe:3716 QUERY INFORMATION D:\MAIL1\MAIL\m1016005\AREPLY.KFL SUCCESS Attributes: A 
23:42:17 mercury.exe:3716 OPEN D:\MAIL1\MAIL\m1016005\AREPLY.KFL SUCCESS Options: Open  Access: 0012019F 
23:42:17 mercury.exe:3716 READ  D:\MAIL1\MAIL\m1016005\AREPLY.KFL SUCCESS Offset: 0 Length: 512 
23:42:17 mercury.exe:3716 READ D:\MAIL1\MAIL\m1016005\AREPLY.KFL END OF FILE Offset: 55 Length: 512 
23:42:17 mercury.exe:3716 QUERY INFORMATION D:\MAIL1\MAIL\m1016005\AREPLY.KFL SUCCESS Length: 55 
23:42:17 mercury.exe:3716 WRITE  D:\MAIL1\MAIL\m1016005\AREPLY.KFL SUCCESS Offset: 55 Length: 30 
23:42:17 mercury.exe:3716 CLOSE D:\MAIL1\MAIL\m1016005\AREPLY.KFL SUCCESS  

And an incorrect file/open query looks like this:

23:43:57 mercury.exe:3716 DIRECTORY D:\MAIL1\MAIL\m1016029\ SUCCESS FileBothDirectoryInformation: AREPLY.KFL 
23:43:57 mercury.exe:3716 DIRECTORY D:\MAIL1\MAIL\m1016029\ SUCCESS FileBothDirectoryInformation: AREPLY.KFL 
23:43:57 mercury.exe:3716 OPEN D:\MAIL1\MAIL\m1016029\AREPLY.KFL SUCCESS Options: Open  Access: 00010080 
23:43:57 mercury.exe:3716 QUERY INFORMATION D:\MAIL1\MAIL\m1016029\AREPLY.KFL SUCCESS FileAttributeTagInformation 
23:43:57 mercury.exe:3716 DELETE  D:\MAIL1\MAIL\m1016029\AREPLY.KFL SUCCESS  
23:43:57 mercury.exe:3716 CLOSE D:\MAIL1\MAIL\m1016029\AREPLY.KFL SUCCESS  

David Harris:

When Mercury checks AREPLY.KFS, it does the 48-hour check as part of the process... So, before examining the contents of AREPLY.KFS, it first checks the age of the file and removes it if it's too old. I'm fairly sure that this is what is leading to the sequence of log entries in Rolf's last post. Here's the actual code from Mercury that does this test:

   sprintf (fname, "%s\\AREPLY.KFL", newmaildir);
   if (check_existence (fname) != 0)
      if (stat (fname, &statblk) == 0)
         if ((time (NULL) - statblk.st_ctime) > killfile_lifetime)
            remove (fname);

It checks to see whether or not the file exists: if it does, it calls "stat" (a posix runtime library function) to get the file time information and checks to see whether the file's creation time is more than 48 hours ago: if it is, it deletes the file.

Now, the only way this can happen, is if the Operating System is returning an invalid value for the "ctime" member of "statblk". Note also that for the file to be deleted, the call to "stat" has to be successful, so the value of "ctime" *should* be correct.

Did you mean AREPLY.KFL, or .KFS in your comment?

At present, one of my users has this precise issue. The Created date returned by Windows (right-click, get Properties) for the AREPLY.KFS and AREPLY.KFL files for said user is December 2005!

I suspect the "implementation-defined" behavior of remove() vs. unlink() might be an issue on Win32's "sort of POSIX" behavior. The Mercury code logic looks fine. I suspect remove() is not really removing and recreating the file, but rather keeping its old file creation date due to a lingering handle.

https://www.securecoding.cert.org/confluence/display/seccode/FIO08-A.+Take+care+when+calling+remove()+on+an+open+file states:

Invoking remove() on an open file is implementation-defined. Removing an open file is sometimes recommended to hide the names of temporary files that may prone to attack (see [TMP30-C. Temporary files must be created with unique and unpredictable file names]).

In cases when an open file needs to be removed, a more strongly defined function, such as the POSIX unlink() function, should be considered. To be strictly conforming and portable, remove() should not be called on an open file.

Non-Compliant Code Example

The following non-compliant code example illustrates a case where a file is removed while it is still open.

FILE *file;

/* ... */

file = fopen("myfile", "w+");
if (fopen == NULL) {
  /* Handle error condition */
}

/* ... */

remove("myfile");

/* ... */

Some implementations will not remove "myfile" because the stream is still open.

Implementation Details

Code compiled using Microsoft Visual Studio C++ 2005 and run on Microsoft Windows XP, prevents the remove() call from succeeding when the file is open, meaning that the file link will remain after execution completes.

Compliant Solution (POSIX)

This compliant solution uses the POSIX unlink() function to remove the file. The unlink() function is guaranteed to unlink the file from the file system hierarchy but keep the file on disk until all open instances of the file are closed) is used [Open Group 04].

#include <unistd.h>

FILE *file;

/* ... */

file = fopen("myfile", "w+");
if (fopen == NULL) {
  /* Handle error condition */
}
unlink("myfile");
fclose("myfile");

Risk Assessment

Calling remove() on an open file has different implications for different implementations and may cause abnormal termination if the closed file is written to or read from, or may result in unintended information disclosure from not actually deleting a file as intended.

The st_ctime value returned by the stat call is just a 64 bit number, so it's not localized. The testing I've done seems to support Troy's theory. But why this occurs only on some computers (and unfortunately not David's) is still unclear.

/Rolf