Heh... I just spent an amusing yet frustrating 8+ hours tracking down an obscure bug. (Non-coders, you probably want to stop reading now.)

I thought there was something bizarre going on with our logging framework. We're working on some new validation code (checking for things like invalid characters in names, etc.). One of the things we log is the number of calls to various functions handled in each request. The logs should look like (simplified):

Request 1: RequestHandler:1,Validation:1,IsClientAuthorized:1,IsValidName:1
Request 2: RequestHandler:1,Validation:1,IsClientAuthorized:1,IsValidName:1
Request 3: RequestHandler:1,Validation:1,IsClientAuthorized:1,IsValidName:1
Request 4: RequestHandler:1,Validation:1,IsClientAuthorized:1,IsValidName:1

Instead, I was getting:
Request 1: RequestHandler:1,Validation:1,IsClientAuthorized:1,IsValidName:1
Request 2: RequestHandler:1,Validation:1,IsClientAuthorized:1,IsValidName:2
Request 3: RequestHandler:1,Validation:1,IsClientAuthorized:1,IsValidName:3
Request 4: RequestHandler:1,Validation:1,IsClientAuthorized:1,IsValidName:4

This indicates we're calling IsValidName() four times on the fourth request. Huh? This is utter nonsense. That's got to be a bug in the logging framework or our log4j configuration, right?

Nope. We really were. My desktop started getting *really* slow around the 100,000th request.

The culprit? We screwed up a singleton initialization. The RequestHandler initializes the validation framework each time; the first call should do the real setup work, and the follow ons should be no-ops. Except... we forgot to set the alreadyInitialized flags and we were adding the same set of validations to the framework each time. For various obscure reasons, the setup actually appends to the framework rather than replacing it.

Amusing because I didn't believe what my eyes were telling me. Frustrating because it took 8 hours of me looking in the wrong place to track this down.