CodeSOD: Threading the Needle in a Haystack of Files

Today we return to Jessica (previously), who still suffers under Windows Forms. But it's not all Windows Forms. There's also random CLI tools kicking around. CLI tools which should really be designed to run as a service,

Let's start with the Main method of this particular tool.

static void Main(string[] args){ if (!LoadConfigs()) { return; } if (args.Length > 0) { if (args.Any(a => string.Compare(a, "Test", true) == 0)) { RunTest(out string message); Console.WriteLine(message); return; } } _userCache = new Dictionary<string, Employee>(); _itemCache = new Dictionary<string, bool>(); InitializeFileCache(); WriteLog("File watcher started."); Task.Run(() => { ProcessLogQueue(); }); Task.Run(() => { ProcessFilesInFolder(); }); while (true) { Thread.Sleep(1000); }}

We first try and load a config file, and if we fail, we quit. Then, if the word "Test" appears in any of the CLI arguments, we run a test of some kind, and then quit. Then, we prepare a pair of cache objects that map IDs to either employees or boolean values, and initialize that from a file. Then we kick off a pair of background threads, and then we sleep forever. Now, there are obvious nits here- you're not meant to kick off tasks directly, really, and async/await keywords are a "better" way to do this.

That they aren't awaiting the tasks is a problem we'll come back to.

For now, let's start with the logging portion. You can see WriteLog, which Jessica did not provide the implementation of, but I can infer it's pretty simple: it puts your message into a thread safe queue. How do I know this? Because of ProcessLogQueue's implementation:

private static void ProcessLogQueue(){ if (!Directory.Exists(_config.LogLocation)) { Directory.CreateDirectory(_config.LogLocation); WriteLog($"Created Log location: {_config.LogLocation}"); } while (true) { while (_concurrentQueue.TryDequeue(out string result)) { string fileName = _config.LogLocation + $@"\{DateTime.Now.ToString("yyyy-MM-dd")}_CreationLog.log"; if (!File.Exists(fileName)) { using var fs = File.Create(fileName); } using (var fw = File.AppendText(fileName)) { fw.WriteLine(result); } } Thread.Sleep(5000); }}

They wrote their own logging library, but left out anything like "log levels" or "filtering" or "safe error handling against write failures". Mostly, this pulls a message off the queue and appends it to a file. It doesn't keep the filehandle open, which I'd make a comment about the performance overhead, but a bigger barrier to performance is the fact that if the queue is empty, this thread sleeps for five seconds. So if you're not logging so fast that multiple messages are in the queue, you're spacing out your log messages by five seconds at a time.

What's important to note about this logger is that this is not a logging program. It's a file watcher which needs to log messages. They just reinvented the logging library badly, is all. It'd be trivially easy to drop in a logging library and ditch this entirely.

How about processing files?

private static void ProcessFilesInFolder(){ while (true) { bool canAccess = RunTest(out string message); if (canAccess) { foreach (var file in Directory.GetFiles(_config.WatchLocation, "*.csv")) { ProcessFile(file); } } else { WriteLog(message); } Thread.Sleep(60000); }}

Here, we see RunTest is used again- clearly this is a test to see if we can read from the correct directory. If we can't, we keep trying once a minute, though. If we can, we scan a directory, do something to all the CSV files, and try again in a minute. Once again, we don't see any error handling around Directory.GetFiles. Maybe there is in ProcessFile somewhere.

But the key here is that if I'm reading the docs right, exceptions in Task objects arrive at the main thread when you call Wait or otherwise check the result of the task. Which means this is the kind of program which fails silently- nothing checks for exceptions in the child threads, and since the child threads are where the work happens, it's easy for this program to reach a state where the main thread spins away, waking up every second just to go back to sleep, without any errors being detected.

And that brings us to the other key point here. Remember those two "cache" dictionaries? They're populated out of a file, and the entire point of those caches is to keep tabs on which entries have already been processed. Something the program can't do otherwise. I mean, it could, because processed IDs are stored in the database and there is an API that lets you query the database. It just doesn't. It relies on a local cache file to tell it what it's already processed. And while you or I might use some sort of unique key constraint to keep existing entries from being reprocessed by the database, the people behind this did not. Which means if the cache file is inaccurate (because the program crashed), or worse gets lost this processing program will create hordes of duplicate entries in the database.

Which is a thing that has happened, and is the reason Jessica ended up looking into this code. The customer refuses to run the service, because they ran it and it created duplicate entries. Now they don't trust it to work correctly.

[Advertisement] Utilize BuildMaster to release your software with confidence, at the pace your business demands. Download today!