Larry Osterman's WebLog

Confessions of an Old Fogey
Common Tasks
Search
Recent Posts
Tags
Archives
Archives
Links
MSDN Blogs > Larry Osterman's WebLog > What's wrong with this code, part 6
Blog - Title

What's wrong with this code, part 6

What's wrong with this code, part 6

8 Sep 2004 4:39 PM
  • Comments 45

Today, let’s look at a trace log writer.  It’s the kind of thing that you’d find in many applications; it simply does a printf and writes its output to a log file.  In order to have maximum flexibility, the code re-opens the file every time the application writes to the filelog.  But there’s still something wrong with this code.

This “what’s wrong with this code” is a little different.  The code in question isn’t incorrect as far as I know, but it still has a problem.  The challenge is to understand the circumstances in which it doesn’t work.

/*++
 * LogMessage
 *      Trace output messages to log file.
 *
 * Inputs:
 *      FormatString - printf format string for logging.
 *
 * Returns:
 *      Nothing
 *     
 *--*/
void LogMessage(LPCSTR FormatString, ...)
#define LAST_NAMED_ARGUMENT FormatString
{
    CHAR outputBuffer[4096];
    LPSTR outputString = outputBuffer;
    size_t bytesRemaining = sizeof(outputBuffer);
    ULONG bytesWritten;
    bool traceLockHeld = false;
    HANDLE traceLogHandle = NULL;
    va_list parmPtr;                    // Pointer to stack parms.
    EnterCriticalSection(&g_TraceLock);
    traceLockHeld = TRUE;
    //
    // Open the trace log file.
    //
    traceLogHandle = CreateFile(TRACELOG_FILE_NAME, FILE_APPEND_DATA, FILE_SHARE_READ, NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
    if (traceLogHandle == INVALID_HANDLE_VALUE)
    {
        goto Exit;
    }
    //
    // printf the information requested by the caller onto the buffer
    //
    va_start(parmPtr, FormatString);
    StringCbVPrintfEx(outputString, bytesRemaining, &outputString, &bytesRemaining, 0, FormatString, parmPtr);
    va_end(parmPtr);
    //
    // Actually write the bytes.
    //
    DWORD lengthToWrite = static_cast<DWORD>(sizeof(outputBuffer) - bytesRemaining);
    if (!WriteFile(traceLogHandle, outputBuffer, lengthToWrite, &bytesWritten, NULL))
    {
        goto Exit;
    }
    if (bytesWritten != lengthToWrite)
    {
        goto Exit;
    }
Exit:
    if (traceLogHandle)
    {
        CloseHandle(traceLogHandle);
    }
    if (traceLockHeld)
    {
        LeaveCriticalSection(&g_TraceLock);
        traceLockHeld = FALSE;
    }
}

One hint: The circumstance I’m thinking of has absolutely nothing to do with out of disk space issues. 

As always, answers and kudos tomorrow.

 

, ,
Comments
  • Michael
    8 Sep 2004 10:55 AM
    In Exit, should check traceLogHandle against INVALID_HANDLE_VALUE.

    Hard coded file name
    Mixing bool & BOOL

    Uses over 4k of stack.

    WriteFile may only write part of the buffer, need to loop until all buffer is written.
  • Larry Osterman
    8 Sep 2004 11:07 AM
    In turn: Good point on checking traceLogHandle.

    The hard coded filename isn't a problem, you WANT your log file to be discoverable.

    Mixing bool and BOOL is also valid, it's more of a style issue than a correctness issue however (they're both interchangable with int).

    For a user mode component, using 4K of stack isn't an issue. For a kernel mode component it is, but that's not the case here.

    WriteFile will only write part of the buffer if there's an out-of-disk space situation if you're writing to a local file (which is the case here). And I've already said that the circumstance isn't out of disk space.

  • mschaef
    8 Sep 2004 11:08 AM
    My first thought was some kind of multi-thread/multi-process/multi-computer locking issue, but those seem to be handled (based on my limited knowledge of Win32 file sharing issues).

    That said, I see a couple potential issues:

    1) Every thread that calls LogMessage now has another choke point at which to serialize with every other thread that calls LogMessage.

    2) All that file opening/closing has to be a performance issue, particularly if LogMessage is frequently called.

    3) What happens at the CreateFile call when the log file is on a network share and two processes on different machines call LogMessage at the same time? If call fails, then log messages will be dropped, if it waits for the other process to close the file, that's yet another serialization point.
  • Larry Osterman
    8 Sep 2004 11:12 AM
    Good points mschaef:

    I wasn't concerned with the scalability of LogMessage - for 99% of its uses it's not going to affect things enough. This isn't to say that it's not something that can happen, but...

    Opening&Closing the log file CAN be a perf bottleneck. But I wasn't concerned with perf in this example.

    Network access - you're right, that could be an issue, but if there are two instances of the app running locally, it would have the same problem. It's a valid circumstance, realistically there should be a retry loop around the CreateFile call to handle that case.
  • mschaef
    8 Sep 2004 11:20 AM
    "I wasn't concerned with the scalability of LogMessage - for 99% of its uses it's not going to affect things enough."

    Part of my concern was scalability, part was debug-ability. I have visions of apps using this function failing with logging turned off, and succeeding with logging turned on, thanks to the extra synchronization in LogMessage.

    I guess a scalable log facility might maintain a queue for each worker thread, and a seperate log thread that waits for incoming log messages on any of the source queues, and dumps them to disk. At least then, the worker threads would only potentially serialize with the log thread. This approach would raise some interesting issues surrounding message ordering...
  • Larry Osterman
    8 Sep 2004 11:26 AM
    Then you have out-of-order issues. In practice, I've not seen this as an issue - we're not talking about the IIS logger here, this is a logging tool for something like setupapi or audiosrv or msi, or the NT browser.

    One thing that helps a lot with the debuggability issue is time stamping and sequencing the log records - I didn't include that in this example because the post was too long anyway - the actual code I stripped this example from is much more complicated.
  • Rob
    8 Sep 2004 11:30 AM
    Why can't you use OutputDebugString and keep the complexity of writing it to a file in another process?
  • Larry Osterman
    8 Sep 2004 11:33 AM
    Because OutputDebugString only outputs stuff when there's a debugger attached. And the idea behind logging tools like setupapi.log or other tools is that they passively log until there's a problem, then someone can use the debug log to diagnose the problem.

    No tools needed, just copying a text file to a network share.

    Logging to a file can be an extraordinarily powerful tool, especially when trying to debug complicated distributed failures.
  • Sayavanam
    8 Sep 2004 11:36 AM
    Hmm, I don't think I have the answer. But a few things:

    1. You are not checking the return value of StringCbVPrintfEx, your buffer may be too small, thus truncating the log message.

    2. The last 2 params of StringCbVPrintfEx could be null, it is an error to pass null args without appropriate flags.

    -Sayavanam
  • Keith Moore [exmsft]
    8 Sep 2004 11:40 AM
    Two comments:

    1. You're mixing charset "neutral" APIs like StringCbVPrintfEx() with charset "specific" types like LPCSTR. If the format string is *always* LPCSTR, then you should probably use StringCbVPrintfExA(). Otherwise, you should probably use LPCTSTR for the FormatString.

    2. Is it safe to pass outputString as the first *and* third parameters to StringCbVPrintfEx()? (The same goes for passing bytesRemaining as the second and third parameters.) It seems like one of those things that *should* be OK, but the documentation doesn't guarantee it.
  • Grant
    8 Sep 2004 11:41 AM
    Call me paranoid, but I'd feel a lot safer with code like this if there was a try/finally (or equivalent SEH).
    --Grant
  • Dave M.
    8 Sep 2004 11:41 AM
    1) Not using TCHAR, LPTSTR with generic StringCbVPrintfEx

    2) Not checking return code from StringCbVPrintfEx. If a failure occurs, can you count on bytesRemaining?

    3) Not checking FormatString for NULL

    4) Are size_t and DWORD safe to use interchangibly under 64 bit?
  • Ian Mayor
    8 Sep 2004 11:50 AM
    It's been a little while since I've done Win32 work so I may be off base here, but it looks like there's a race condition if you have more then one process writing to the log file (which could happen, since the name is hardcoded)... Since the file is opened with FILE_SHARE_READ, if a second process tried to open the log file while the first had it open, the CreateFile call would fail and the second process would just drop it's log message.
  • Larry Osterman
    8 Sep 2004 11:50 AM
    Grant: Never. SEH in this circumstance HIDES bugs. It turns easily diagnosable crashes into hard-to-detect problems.

    I guess I should have kept my comment in the draft of this post that the fact that the code's not unicode isn't the problem. I explicitly un-unicoded the code to simplify it.

    Everyone's missing my comment at the beginning:
    "The code in question isn’t incorrect as far as I know, but it still has a problem."

    There IS a very real problem that exists in this code, even though the code's ostensibly correct. The issue has to do with the circumstances in which the code is used.

    As a further hint, consider the failure mode: The LogMessage() API will only ever write one line to the file if the failure circumstance is in place.

  • Skywing
    8 Sep 2004 12:35 PM
    Because you aren't providing very much (if any) information about when this is supposed to work, identifying specific potential issues is difficult. Here's my go, though:

    If this is for logging in something like setupapi then you need to use a named mutex instead of a critical section, because the dlls may be concurrently executing in more than one process.

    Grant is right in that this function may need a try/except, though not because of the StringCbVPrintfEx call. Depending on how the caller creates the critical section and if the caller enables early critical section event creation in ntdll, EnterCriticalSection can throw an exception if you are running on Windows 2000 or earlier. The conditions for this happening are: the critical section's wait semaphore has yet to be created, there isn't enough memory to create it, and contention for the lock occurs that is not resolved by the time the spin count is exceeded. It's worth noting that on Windows NT 4.00, there's no documented way to enable early creation of the wait semaphore (one must instead use an undocumented ntdll Rtl routine).

    If you are writing to something like a pipe, this function could potentially take a very long time to complete.

    If this is a noninteractive service, and the error mode is not set appropriately, then a harderror messagebox could be raised without a user around to dismiss it.

    If this function is used in some kind of transient worker thread that may be terminated at any time, then the critical section could potentially get stuck (unless the function is changed to use a mutex). Even so, the process heap lock could still be frozen if StringCbVPrintfEx allocates heap memory and was in the middle of a heap allocation. You could also leak a file handle in this manner, which would keep the file unavailable for use to other threads until the process is terminated (because of incompatible share/open access types).
Page 1 of 3 (45 items) 123