Tech Notes

Tech Note #20020002

A sendmail filter (milter) misses random debug file entries under heavy loads. Sendmail has multiple threads running, in various states, due to heavy mail load. The debug entry was supposed to be appended to a log file but was omitted instead.

Problem Description:

A debugging routine writes trace file entries to a file, logging the various steps that a sendmail filter (milter) takes during its processing of a message. For each trace entry written, the log file is opened with fopen and one or more calls are made to the stream I/O routines fprintf and fputc.

Under heavy mail loads, when sendmail has multiple threads running, fopen fails and returns a NULL file pointer. This is despite the fact that the filter has all of the correct permissions, etc. and has previously been able to write thousands of entries to the file. No out of space condition exists, either. One can only speculate that there is some problem with fopen exacerbated by contention in this situation. This problem was noticed on a BSD platform with 8-10 sendmail threads running/blocked.

Problem Resolution:

No specific problem resolution is known. Normally, the low-level I/O routines issue flockfile requests as each I/O is done. Perhaps the continual locking/unlocking of the file, when the locking is left to the low-level, aggravates the problem. It was thought that moving the flockfile to a higher level (i.e. in the logging routine after the log file was opened and prior to any calls to fprintf or fputc were made) might at least ameliorate, if not solve the problem. Minimally, the number of times the file was locked/unlocked would be reduced, thereby closing the window of opportunity for contention.

Should you experience unknown, random fopen failures in your milter and should you be using a logging technique of a similar nature, you might consider applying flockfile to your log file open/write/close sequences in a similar manner. For example:


FILE *ptDebugFile;

if ((ptDebugFile = fopen(chDebugFileName, "a")) == NULL) return;
flockfile(ptDebugFile);
     .
     .
     .
fprintf(ptDebugFile, "%s", s);
     .
     .
     .
fprintf(ptDebugFile, "%d", d);
     .
     .
     .
fputc('\n', ptDebugFile);
     .
     .
     .
funlockfile(ptDebugFile); fclose(ptDebugFile);