Larry Osterman's WebLog

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.

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.

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.

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.

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

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.

Why can't you use OutputDebugString and keep the complexity of writing it to a file in another process?

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.

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

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.

Call me paranoid, but I'd feel a lot safer with code like this if there was a try/finally (or equivalent SEH).
--Grant

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?

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.

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.

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

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.

Skywing:

Yes, I misread the code, my head somehow made the variable global since the lock was global otherwise the variable didn't make much sense....

My bad.

Well, I believe you mix to different issues together, whoever would find it useful to check the validity of the memory a pointer points to? As long as it doesn't point to NULL which most of all access violation I ever encounter are. People tend to go to extreme in both direction, checking nothing, checking everything, the way to go is probably in the middle.

But anyhow, yes those are the troubles you might get into, and eventually it will lead you to a crash that would have happened earlier anyways. With proper diagnose funtions built in to you exception handling it will not be hard to find, so I will still disagree with you, it is useful and it is possible to do it right.

C++ exception handling in windows does catch hardware exceptions(SEH) such as access violation(if you want it to), I will not vouch that it won't screw up the OS handling of that exception, if you want to be safe doing SEH go with try/finally to achieve resource guarding.

However for the thread stack guard page, it is indeed a bit tricky, and the guard bit of the page is cleared the first time it is triggered.

But then again if you catch exceptions without handling them, or at least have logic to figure out if you want to catch it or not, then you might get into trouble. But then again, you are already in trouble as the application is about to crash, what to do, what to do. For the thread stack issue, I personally would either relocate the stack(if I expect the code running under the try/catch block to do something like that, or merely abort that thread. That is handle the exception silently by ending the thread and cleaning up its resources, letting the rest of the process continue running, and maybe restart the thread(sure you might lose some memory and other resources).

Let's take a real world example, consider that you have an application that loads plugin dlls for running different kinds of telephony protocols (DTMF, pulse, tones, SIA etc). The application loading them provides an interface and a framework to answer the ISDN calls and send tones or what have you.

Also consider that this is a 24/7 system and that the customer can write their own modules to plug into this system. Just because you have one misbehaving plugin (each plugin runs in its own thread) does not mean you want to crash the system. All you want to do is recover from the problem, kill the thread(if you deam the problem serious enough), start a new one, log vastely and live with the fact that you lost some resources (perhaps a handle or two and some memory), and let the customer reboot the system at the convience. Report the problem to the writer of the module for proper analysis.

Also imagine that this happens in the middle of the night with no immediate support on site and that this is actually a 911 alarm central.

You could argue that things should be tested better, you could argue that it is good to find faults immidiately, I will only agree to the extend that you should find the fault as early as possible, but on a live site it is better to function, however poorly, than not to function at all.

If one thread goes bazooka, who cares, as long as the 400 other on going alarm calls can continue?

Later, when you want to diagnose this odd behavior (let's say it is odd like in the post above), all you do is run your system in your _lab_ in your debugger catching all exceptions before the application, run through the "traffic" scenario(you have logs right?) and wait for the exception to happen. Or merely check your exception log to see if you had any odd exceptions occuring that could take you to this fault.

Now instead imagine that you didn't catch that exception, this is an alarm dispatcher central remember, the sender of the alarm that caused the system to crash will surely try again, it must get through, it will repeat and rinse the system all night, the 400 other calls per minute will not get handled and suddenly alot of people didn't get through to 911 with life threatening issues. I do not believe they will settle for an explanation "It was easier for us to diagnose this way"

I agree with you, use exceptions with care, and try to know what you are doing. But please do make sure that your application do not crash. You can use any insane amount of ASSERT and aborts you want in a debug build, but your retail build should let the user of the program make the decision to restart it or not. He or she doesn't care if it is easier to find unless he or she can get immediate support.

Take the Visual Studio 2003 for instance, it crashes so many times it is annoying on a day's work due to for instance failing plugins, or odd behaviour from a source control provider. Me as a user will blame the studio, even if it is the plug in or SCC that causes it to crash.

Internet explorer used to do the same if a plugin failed it would crash, which of course in return gave the IE the reputation of crashing.

Much like the BSOD reputation of Windows mostly comes from badly written device drivers than windows itself(however I will agree that this one is a few magnitudes harder to guard against =).

I hope you get my point however, that unlikely events do occur, be paranoid, know your safe passage out in case of an emergency. To me it is as silly as not knowing the fire escape routes and instead in case of a fire just drop down and die on the spot(with a note saying "This couldn't happen"). Or not having some extra fuel and spare tire in the trunk of your car, sure it might help, but it might just take you those few extra miles to get to proper maintance place.

In the case of this Log function, it is important to remember that you are only logging, logging should never cause the system to crash... Even if you think it is stupid to let a strangely formatted printf string get through because someone used a %s instead of a %d. It is always better to analyse that in the lab than on customer sites...

Those are my pennies.

Niclas, you bring up enough interesting points that I want to take them in turn in a separate post, so I'm going to defer responding to that part until somewhat later.

Although this was not an intended answer, in my experience it is one: When CreateFile fails it can return either 0 or -1. I don't recall which of these values is INVALID_HANDLE_VALUE, but it doesn't matter. A test for failure has to do <= 0 instead of == INVALID_HANDLE_VALUE.

Another unintended answer: Any handle might happen to be the straw that breaks the camel's back, yielding a BSOD.
http://support.microsoft.com/?scid=kb;ja;195857
(According to the article MS only reproduced the problem when the handles are for registry keys, but the description implies that the problem can happen with any kind of handle.)

IIRC, that bug is only present on Win9x, and only then when opening handles to drivers.

I agree with you Larry, these are very interesting topics, sadly and usually it becomes a religious war, especially for parameter validation.

I wish there was a simple rule above all, my simple rule is, never crash. But then again I wouldn't want to take that to the extreme either, sometimes you have no options but to restart the application.

There are cons and pros with everything and I eagerly await your answer, as it is always fun to get insight into more intricate problems =), besides you have a ton of interesting points.


I would also like to add that of course even if the application mentioned in my example would reboot all night until support personal got there (usually within the hour depending on how sleepy they are) it would redirect all calls to a backup system if it notices that it is thrashing a certain protocol. The backup system usually is a low capacity hardware based receiver.

What we wanted to prevent was that one protocol could group punish the rest of the system =). And basically we know, even if we try to write fault free code, we know that we will make mistakes, so it is safer to also make it fault tolerant.

Regarding exceptions, I totally agree with you Larry, that an API like this should not swallow unexpected exceptions.

Deciding on life-or-death issues for the whole process in the face of unexpected exceptions is the responsibility of a higher-level function.

Not something that a low-level function like LogMessage should do.

But, I think that to be perfectly safe you should still use __try __finally to avoid leaving open handles and held critical sections.
Each function should guarantee that it performs its own cleanup properly even under unexpected circumstances.

You could rewrite the function like this:

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);
__try {
//
// 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)
// return inside a __try block passes control to the __finally block
return;
//
// 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))
// return inside a __try block passes control to the __finally block
return;
}
}
__finally {
if (traceLogHandle != INVALID_HANDLE_VALUE) {
CloseHandle(traceLogHandle);
}
LeaveCriticalSection(&g_TraceLock);
}
}


Imagine that the user of LogMessage tries to log a message with a badly formatted printf-string - perhaps using %s instead of %d for example.

Your original code would have left the critical section held which would mean that no other thread in the process could log anything.

Just to elaborate a little on my standpoint regarding exception handling:

I think that Niclas is right that there are definitely processes that have a valid reason to try to keep running even in the face of unexpected exceptions.

The correct way to do that is to put a try/catch around the block of code that could cause unexpected exceptions. It could be around a call to third-party code, or perhaps all the code in a worker thread could be encapsulated in a try/catch.

The high-level exception handler should of course log as much information as it can about the exception, and then it could try to continue.

The problem is that unless the lower-level code is written in an exception-safe way (using __finally for example), the process might still hang because of issues like abondoned critical sections and open files.

It is the responsibility of lower-level functions to use __finally to perform any necessary cleanup in the face of unexpected exceptions. Low-level functions should almost never catch unexpected exceptions. They should only catch exceptions that they explicitly know they might cause during normal operations. Imagine for example that CreateFile would have thrown an exception if the file was open by another process. In that case, LogMessage should handle the FileAlreadOpenException and ignore it. It should absolutely not swallow any other exceptions.

It is the responsibility of higher-level functions to use try/catch to decide if the process should be kept alive or not.

buffer overflow?!?!?!

"Because OutputDebugString only outputs stuff when there's a debugger attached."

This isn't true. And since I don't remember the details of how to get at this without a debugger, I will just say go to www.sysinternals.com and look at the debugview it doesn't attach to a process, it just intercepts the messages.


I actually wrote my own version of debugview before discovering the tool, perhaps I will dedicate some blog space to how to achieve this.


Evan
http://EvanFreeman.blogspot.com

Evan, there needs to be SOME application running to intercept the debug trace calls. They don't get queued up somewhere waiting for them to be written.

So if the user isn't running the trace monitoring tool, they don't see the output.

Which means that we lose an opportunity to post-mortem a failure.

I will just add another thought to this, since I never really pointed it out.

I do agree that lower level functions should not do exception handling, it is the responsibility of the higher level logic.

However in this case, the log function is indeed acquiring a lock, which it must not ever forget to release, or it will block all threads in the entire process. That is why this is an exception to the rule. And API:s that handle internal resources must also make sure to supervise and care for them.

Which is why I proposed using SEH handling with try/finally, but it can also be achieved with C++ exception handling, which ismore portable.

And about performance of a logger you have a few options, they all have pros and cons.

One way is to merely queue the log call, and let another low prio thread handle the actual logging. However if you do that, you might not get the logs during a failure(if you don't care for exception handling properly).

My own thoughts though are that you might as well do all the work right away, since logging should be an exception or failure case, which means we most likely have time to log.


There are however instances when you do want a seperate thread doing the actual logging, for instance if you are logging from a message pump to a window that message pump is handling. If you log anything before the message pump starts you will hang (if you are using synchronous signalling).

9/10/2004 12:14 AM Niclas Lindgren

> since logging should be an exception or
> failure case,

Not really. In the Windows world, remember that even Windows 95 would write boot logs reporting successful driver start-ups, because at the point where the log ended the user might be able to guess that the failure came after that point. In the modern Windows world, it is often prudent to log every successful login, and maybe successful access to files and registry keys etc. In the Internet world, consider that it is often prudent to log every packet that goes in or out.