Larry Osterman's WebLog

Confessions of an Old Fogey
Blog - Title

What's wrong with this code, part 6

What's wrong with this code, part 6

  • 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.

 

  • Well, if you compile it with UNICODE turned on you'll get a compilation error from the StringCbVPrintfEx call because you've declared everything else as byte-oriented strings. Changing it to StringCbVPrintfExA should sort that out, though.

    Could it be that you're not impersonating when the first call is made, and the file doesn't exist yet, but subsequently you're impersonating? If you're running as one of the service accounts, the NULL lpSecurityDescriptor causes the file to be created owned by that user. The subsequent calls to LogMessage, if we're impersonating at the time, fail at the CreateFile call because the user doesn't have permissions to write to the file.

    The solution is to specify an appropriate security descriptor when creating the file.
  • Good catch with the impersonation issue there. Sounds plasubile if the function is called during service startup, and then mostly while handling client requests.
  • Bingo! That's the problem I was thinking about Mike.

    But the problem doesn't only happen with service accounts. It can happen with normal users as well.

    Skywing: If I had anything to do with it, try/except should be removed from the language. You're right that EnterCriticalSection can throw, but that only happens if you didn't call InitializeCriticalSectionEx - I purposely left that call out (for size reasons), but the semaphore isn't the problem.

    StringCbVprintfEx doesn't allocate heap memory to my knowledge.
  • Remember that InitializeCriticalSectionAndSpinCount doesn't exist on NT4, though. So you can't avoid the problem there unless you use undocumented APIs.
  • Whoops; minor error there. It exists on NT4, but you can't set the high bit of dwSpinCount to enable early event creation (according to the PSDK, anyway).
  • Skywing: that's true, but I'll be honest and say that for these "what's wrong with this code" examples, they're generally about showing up a common mistake, or general principal. As a result, I don't tend to consider issues like code working on lower level revisions of the OS from the current one.
  • One thing that I see right off is a possible race condition on the traceLockHeld. Since it is set to false after returning the critical section. This could potentially lead to all threads except the one owning the CS to hang. It should be set to false before leaving the CS to avoid this.

    Also many function withing the CS and also EnterCriticalSection it self can cause an exception, so even if you say never, I say always use try catch, it will not cause you grief, and if it does I would happily hear the explaination to that, and also an example. My experience is the opposite of yours. If you take a shared lock always catch the exceptions, because if some function higher up catches it you will end up with hang thread and odd behavior. This is usually a cause because no logging is done in the catch, so noone will know easily from the log that an exception happened. This can of course be diagnosed with a failsafe log or counters for the exceptions.



  • I think you misread the code there; traceLockHeld is a local and not a static or global variable.
  • Actually EnterCriticalSection can throw if you are low on memory on the machine as well. There are many reasons things can through, and catch them will always save you. But everything has its pros can cons. My basic idea is that you write all code "throw" safe, and only guard crucial common section and the outer limits of each thread, so noone thread can bring down the process.

    Nice catch on the file securities, totally forgot about that one, happened to me a few times, but so easy to forget =)
  • Niclas, as to what's wrong with try/catch, consider this:
    http://blogs.msdn.com/LarryOsterman/archive/2004/05/18/134471.aspx

    Also, try/catch catches C++ exceptions, not SEH exceptions.

    It's VERY difficult to catch SEH exceptions correctly, 90% of the people out there don't know how to do it (consider the guard page exception mentioned in the linked post).

    Simply wrapping code in a try/except is absolutely NOT the way to go - that's guaranteed to be incorrect.
  • Only users with enough privileges may access the log file, that's not necessarily a problem.

    I don't see the point of traceLockHeld. The first thing the function does is a call to EnterCriticalSection, so it should always call ExitCriticalSection before exiting.

    Anyway, I'm glad this code uses goto instead of complicated nested if's or exceptions.
  • B.Y. There's a lot of code that was excised, and in that code, the TraceLockHeld variable made sense.
  • You could also use InitializeCriticalSectionAndSpinCount instead of EnterCriticalSection in case of low memory situations.
  • I was too late to throw in my 2 cents but I had a hunch that it had *something* to do with the recent bombardment of SID related posts.

    It does, in a NTFS sort of way, round-about, kind of.

    Having a file created with a service account is fun to try and read from say a normal user. Also in some instances Administrators can be locked out from certain service accounts so under certain circumstances it's possible to create a file that no one has access to. You would have to code some kind of cleanup mechanism to fix it, if such a rare occurance did happen.
  • Yup, actually this one was only vaguely related - someone came to my office on Friday and mentioned they were having a problem related to this issue, that's why I decided to write it up.

Page 2 of 3 (45 items) 123