The Case of the Disappearing App

[Despite being almost 30 years ago, and the finer details being lost in the mists of time, the punchline has always stayed with me – it’s scar tissue I guess :o).]

I was contracting in a team which had taken over a codebase from another company, to try and improve the performance, as it was far below what was needed for even the smaller use cases they had in mind.

The front-end was a PowerBuilder based GUI and I was a C developer working on the in-process back-end library which was a scheduling engine (think: travelling salesman problem). To be more precise, the actual scheduling engine was written in Pascal which was then translated into C and statically linked into the back-end library which acted as the infrastructure code – reading & writing to the database, a large caching layer, providing the C API for PowerBuilder to interact with engine, etc.

One day there was a report from the QA team (which was effectively one guy – the same guy I mentioned before in A Not So Minor Hardware Revision) about the application just “disappearing”. There was no error message from the application, and no UAE / GPF style crash dialog from the OS either, which was Windows NT 4 at the time.

We could reproduce the problem fairly easily. It basically involved importing a new set of orders and running the scheduling engine. This was pretty much what we had been doing all along to profile the application and address the various performance issues we ran across. We had some nice test datasets that we kept using across the entire team and I suspect (now) he was probably using a newer one [1].

What was weird was that there no trace of the application terminating. If it was crashing Windows would have told us, and allowed us to attach the debugger. I even ran the application under the debugger and made sure I’d enabled “first chance exceptions” in case any Structured Exception Handling was being triggered and swallowed (it was C, not C++ so there would be no exceptions per-se). There was no mention in the event log either of anything unusual.

In the end I resorted to single stepping into the back-end and slowly drilling down into the code to see if I could work out if there was something in our code causing this. The core engine used a Tabu Search and called back out repeatedly to get various bit of data like product details, driving time between two points, etc. It was dying somewhere inside the core engine, but due to the cyclic nature of the execution it was hard to put a breakpoint anywhere useful. (This was Visual C++ 2.0 and conditional breakpoints had a habit of slowing things right down which added to the debugging burden as it didn’t trigger that quickly as-is.)

During my debugging attempts I began to notice that the memory footprint was spiking and had a suspicion that ultimately the cause was an out-of-memory problem. Native applications typically behave pretty badly when they run out of memory as it tends to lead to dereferencing a NULL pointer and the process unceremoniously crashing. But, as pointed out earlier the Windows crash handler was not being invoked so something else was going on.

Eventually I decided to put conditional breakpoints on the prologue of the CRT functions malloc() and calloc() in the hope that I could catch it returning a NULL pointer. It worked, and as I slowly walked back up the function stack I could see why the application simply disappeared – the error handling simply called abort()! Although this was quite an abrupt termination from a users perspective, from a Windows OS point of view the process had exited gracefully and therefore no crash handler was needed. Under the covers I suspect abort() called TerminateProcess() and so the PowerBuilder GUI would not have been able to catch the process’ impending doom either. If I remember correctly we found a couple of these calls to abort() and removed them so that the error could attempt to bubble back up the stack and at least the user would get notified one way or another of the unstable nature.

As an aside, this wasn’t the only memory issue we had on that project. Not counting the bizarre performance issue in A Not So Minor Hardware Revision we also suffered badly from heap fragmentation because this was before the days of the low-fragmentation heap. The knowledge I learned along the way debugging these, and other memory and heap issues elsewhere, paved the way for my first proper ACCU article Utilising More Than 4GB of Memory in a 32-bit Windows Process.

 

[1] I also seem to remember running Oracle locally so that each developer had their own database for testing which would have affected the overall memory footprint for the machine.

Chaining IF and && with CMD

An interesting bug cropped up the other day in a dub configuration file which made me realise I wasn’t consciously aware of the precedence of && when used in an IF statement with cmd.exe.

Batch File Idioms

I’ve written a ton of batch files over the years and, with error handling being a manual affair, the usual pattern is to alternate pairs of statement + error check, e.g.

mkdir folder
if %errorlevel% neq 0 exit /b %errorlevel%

It’s not uncommon for people to explicitly leave off the error check in this particular scenario so that (hopefully) the folder will exist whether not it already does. However it then masks a (not uncommon) failure where the folder can’t be created due to permissions and so I tend to go for the more verbose option:

if not exist "folder" (
  mkdir folder
  if !errorlevel! neq 0 exit /b !errorlevel!
)

Note the switch from %errorlevel% to !errorlevel!. I tend to use setlocal EnableDelayedExpansion at the beginning of every batch file and use !var! everywhere by convention to avoid forgetting this transformation as it’s an easy mistake to make in batch files.

Chaining Statements

In cmd you can chain commands with & (much like ; in bash) with && being used when the previous command succeeds and || for when it fails. This is useful with tools like dub which allow you to define “one liners” that will be executed during a build by “shelling out”. For example you might write this:

mkdir bin\media && copy media\*.* bin\media

This works fine first time but it’s not idempotent which might be okay for automated builds where the workspace is always clean but it’s annoying when running the build repeatedly, locally. Hence you might be inclined to fix this by changing it to:

if not exist "bin\media" mkdir bin\media && copy media\*.* bin\media

Sadly this doesn’t do what the author intended because the && is part of the IF statement “then” block – the copy is only executed if the folder doesn’t exist. Hence this was the aforementioned bug which wasn’t spotted at first as it worked fine for the automated builds but failed locally.

Here is a canonical example:

> if exist "C:\" echo A && echo B
A
B

> if not exist "C:\" echo A && echo B

As you can see, in the second case B is not printed so is part of the IF statement happy path.

Parenthesis to the Rescue

Naturally the solution to problems involving ordering or precedence is to introduce parenthesis to be more explicit.

If you look at how parenthesis were used in the second example right back at the beginning you might be inclined to write this thinking that the parenthesis create a scope somewhat akin to {} in C style languages:

> if not exist "C:\" (echo A) && echo B

But it won’t work as the parenthesis are still part of the “then” statement. (They are useful to control evaluation when mixing compound conditional commands that use, say, || and & [1].)

Hence the correct solution is to use parenthesis around the entire IF statement:

> (if not exist "C:\" echo A) && echo B
B

Applying this to the original problem, it’s:

(if not exist "bin\media" mkdir bin\media) && copy media\*.* bin\media

 

[1] Single line with multiple commands using Windows batch file

Fast Hardware Hides Many Sins

Way back at the beginning of my professional programming career I worked for a small software house that wrote graphics software. Although it had a desktop publisher and line-art based graphics package in its suite it didn’t have a bitmap editor and so they decided to outsource that to another local company.

A Different User Base

The company they chose to outsource to had a very high-end bitmap editing product and so the deal – to produce a cut-down version – suited both parties. In principle they would take their high-end product, strip out the features aimed at the more sophisticated market (professional photographers) and throw in a few others that the lower end of the market would find beneficial instead. For example their current product only supported 24-bit video cards, which were pretty unusual in the early to mid ‘90s due to their high price, and so supporting 8-bit palleted images was new to them. Due to the large images their high-end product could handle using its own virtual memory system they also demanded a large, fast hard disk too.

Even though I was only a year or two into my career at that point I was asked to look after the project and so I would get the first drop of each version as they delivered it so that I could evaluate their progress and also keep an eye on quality. The very first drop I got contained various issues that in retrospect did not bode well for the project, which ultimately fell through, although that was not until much later. (Naturally I didn’t have the experience I have now that would probably cause me to pull the alarm chord much sooner.)

Hard Disk Disco

One of the features that they partially supported but we wanted to make a little more prominent was the ability to see what the RGB value of the pixel under the cursor was – often referred to now as a colour dropper or eye dropper. When I first used the feature on my 486DX PC I noticed that it was a somewhat laggy; this surprised me as I had implemented algorithms like Floyd-Steinberg dithering so knew a fair bit about image manipulation and what algorithms were expensive and this definitely wasn’t one! As an aside I had also noticed that the hard disk light on my PC was pretty busy too which made no sense but was probably worth mentioning to them as an aside.

After feeding back to them about this and various other things I’d noticed they made some suggestions that their virtual memory system was probably overly aggressive as the product was designed for more beefier hardware. That kind of made sense and I waited for the next drop.

On the next drop they had apparently made various changes to their virtual memory system which helped it cope much better with smaller images so they didn’t page unnecessarily but I still found the feature laggy, and as I played with it some more I noticed that the hard disk light was definitely flashing lots when I moved the mouse although it didn’t stop flashing entirely when I stopped moving it. For our QA department who only had somewhat smaller 386SX machines it was almost even more noticeable.

DBWIN – Airing Dirty Laundry

At our company all the developers ran the debug version of Windows 3.1. enhanced mode with a second mono monitor to display messages from the Windows APIs to point out bugs in our software, but it was also very interesting to see what errors other software generated too [1]. You probably won’t be surprised to discover that the bitmap editor generated a lot of warnings. For example Windows complained about the amount of extra (custom) data it was storing against a window handle (hundreds of bytes) which I later discovered was caused by them constantly copying image attribute data back-and-forth as individual values instead of allocating a single struct with the data and copying that single pointer around.

Unearthing The Truth

Anyway, back to the performance problem. Part of the deal enabled our company to gain access to the bitmap editor source code which they gave to us earlier than originally planned so that I could help them by debugging some of their gnarlier crashes [2]. Naturally the first issue I looked into was the colour dropper and I quickly discovered the root cause of the dreadful performance – they were reading the application’s .ini file every time [3] the mouse moved! They also had a timer which simulated a WM_MOUSEMOVE message for other reasons which was why it still flashed the hard disk light even when the mouse wasn’t actually moving.

When I spoke to them about it they explained that once upon a time they ran into a Targa video card where the driver returned the RGB values as BGR when calling GetPixel(). Hence what they were doing was checking the .ini file to see if there was an application setting there to tell them to swap the GetPixel() result. Naturally I asked them why they didn’t just read this setting once at application start-up and cache the value given that the user can’t swap the video card whilst the machine (let alone the application) was running. Their response was simply a shrug, which wasn’t surprising by that time as it was becoming ever more apparent that the quality of the code was making it hard to implement the features we wanted and our QA team was turning up other issues which the mostly one-man team was never going to cope with in a reasonable time frame.

Epilogue

I don’t think it’s hard to see how this feature ended up this way. It wasn’t a prominent part of their high-end product and given the kit their users ran on and the kind of images they were dealing with it probably never even registered with all the other swapping going on. While I’d like to think it was just an oversight and one should never optimise until they have measured and prioritised there were too many other signs in the codebase that suggested they were relying heavily on the hardware to compensate for poor design choices. The other is that with pretty much only one full-time developer [5] the pressure was surely on to focus on new features first and quality was further down the list.

The project was eventually canned and with the company I was working for struggling too due to the huge growth of Microsoft Publisher and CorelDraw I only just missed the chop myself. Sadly neither company is around today despite quality playing a major part in the company I worked for and it being significantly better than many of the competing products.

 

[1]  One of the first pieces of open source software I ever published (on CiX) was a Mono Display Adapter Library.

[2] One involved taking Windows “out at the knees” – not even CodeView or BoundsChecker would trap it – the machine would just restart. Using SoftICE I eventually found the cause – calling EndDialog() instead of DestroyWindow() to close a modeless dialog.

[3] Although Windows cached the contents of the .ini file it still needed to stat() the file on every read access to see if it had changed and disk caching wasn’t exactly stellar back then [4].

[4] See this tweet of mine about how I used to grep my hard disk under Windows 3.1 :o).

[5] I ended up moonlighting for them in my spare time by writing them a scanner driver for one of their clients while they concentrated on getting the cut-down bitmap editor done for my company.

PowerShell’s Call Operator (&) Arguments with Embedded Spaces and Quotes

I was recently upgrading a PowerShell script that used the v2 nunit-console runner to use the v3 one instead when I ran across a weird issue with PowerShell. I’ve haven’t found a definitive bug report or release note yet to describe the change in behaviour, hence I’m documenting my observation here in the meantime.

When running the script on my desktop machine, which runs Windows 10 and PowerShell v5.x it worked first time, but when pushing the script to our build server, which was running Windows Server 2012 and PowerShell v4.x it failed with a weird error that suggested the command line being passed to nunit-console was borked.

Passing Arguments with Spaces

The v3 nunit-console command line takes a “/where” argument which allows you to provide a filter to describe which test cases to run. This is a form of expression and the script’s default filter was essentially this:

cat == Integration && cat != LongRunning

Formatting this as a command line argument it then becomes:

/where:“cat == Integration && cat != LongRunning”

Note that the value for the /where argument contains spaces and therefore needs to be enclosed in double quotes. An alternative of course is to enclose the whole argument in double quotes instead:

“/where:cat == Integration && cat != LongRunning”

or you can try splitting the argument name and value up into two separate arguments:

/where “cat == Integration && cat != LongRunning”

I’ve generally found these command-line argument games unnecessary unless the tool I’m invoking is using some broken or naïve command line parsing library [1]. (In this particular scenario I could have removed the spaces too but if it was a path, like “C:\Program Files\Xxx”, I would not have had that luxury.)

PowerShell Differences

What I discovered was that on PowerShell v4 when an argument has embedded spaces it appears to ignore the embedded quotes and therefore sticks an extra pair of quotes around the entire argument, which you can see here:

> $where='/where:"cat == Integration"'; & cmd /c echo $where
"/where:"cat == Integration""

…whereas on PowerShell v5 it “notices” that the value with spaces is already correctly quoted and therefore elides the outer pair of double quotes:

> $where='/where:"cat == Integration"'; & cmd /c echo $where
/where:"cat == Integration"

On PowerShell v4 only by removing the spaces, which I mentioned above may not always be possible, can you stop it adding the outer pair of quotes:

> $where='/where:"cat==Integration"'; & cmd /c echo $where
/where:"cat==Integration"

…of course now you don’t need the quotes anymore :o). However, if for some reason you are formatting the string, such as with the –f operator that might be useful (e.g. you control the value but not the format string).

I should point out that this doesn’t just affect PowerShell v4, I also tried it on my Vista machine with PowerShell v2 and that exhibited the same behaviour, so my guess is this was “fixed” in v5.

[1] I once worked with an in-house C++ based application framework that completely ignored the standard parser that fed main() and instead re-parsed the arguments, very badly, from the raw string obtained from GetCommandLine().

The Perils of DateTime.Parse()

The error message was somewhat flummoxing, largely because it was so generic, but also because the data all came from a database extract rather than manual input:

Input string was not in a correct format.

Naturally I looked carefully at all the various decimal and date values as I knew this was the kind of message you get when parsing those kind of values when they’re incorrectly formed, but none of them appeared to be at fault. The DateTime error message is actually slightly different [1] but I’d forgotten that at the time and so I eyeballed the dates as well as decimal values just in case.

Then I remembered that empty string values also caused this error, but lo-and-behold I was not missing any optional decimals or dates in my table either. Time to hit the debugger and see what was going on here [2].

The Plot Thickens

I changed the settings for the FormatException error type to break on throw, sent in my data to the service, and waited for it to trip. It didn’t take long before the debugger fired into life and I could see that the code was trying to parse a decimal value as a double but the string value was “0100/04/01”, i.e. the 1st April in the year 100. WTF!

I immediately went back to my table and checked my data again, aware that a date like this would have stood out a mile first time around, but I was happy to assume that I could have missed it. This time I used some regular expressions just to be sure my eyes were not deceiving me.

The thing was I knew what column the parser thought the value was in but I didn’t entirely trust that I hadn’t mucked up the file structure and added or removed an errant comma in the CSV input file. I didn’t appear to have done that and so the value that appeared to be causing this problem was the decimal number “100.04”, but how?

None of this made any sense and so I decided to debug the client code, right from reading in the CSV data file through to sending it across the wire to the service, to see what was happening. The service was invoked via a fairly simple WCF client assembly and as I stepped into that code I came across a method called NormaliseDate()...

The Mist Clears

What this method did was to attempt to parse the input string value as a date and if it was successful it would rewrite it in an unusual (to me) “universal” format – YYYY/MM/DD [3].

The first two parsing attempts it did were very specific, i.e. it used DateTime.ParseExact() to match the intended output format and the “sane” local time format of DD/MM/YYYY. So far, so good.

However the third and last attempt, for whatever reason, just used DateTime.Parse() in its no-frills form and that was happy to take a decimal number like “100.04” and treat it as a date in the format YYY.MM! At first I wondered if it was treating it as a serial or OLE date of some kind but I think it’s just more liberal in its choice of separators than the author of our method intended [4].

Naturally there are no unit tests for this code or any type of regression test suite that shows what kind of scenarios this method was intended to support. Due to lack of knowledge around deployment and use in the wild of the client library I was forced to pad the values in the input file with trailing zeroes in the short term to workaround the issue, yuck! [5]

JSON Parsers

This isn’t the first time I’ve had a run-in with a date parser. When I was working on REST APIs I always got frustrated by how permissive the JSON parser would be in attempting to coerce a string value into a date (and time). All we ever wanted was to keep it simple and only allow ISO-8601 format timestamps in UTC unless there was a genuine need to support other formats.

Every time I started writing the acceptance tests though for timestamp validation I’d find that I could never quite configure the JSON parser to reject everything but the desired format. In the earlier days of my time with ASP.Net even getting it to stop accepting local times was a struggle and even caused us a problem as we discovered a US/UK date format confusion error which the parser was hiding from us.

In the end we resorted to creating our own Iso8601DateTime type which used the .Net DateTimeOffest type under the covers but effectively allowed us to use our own custom JSON serializer methods to only support the exact format we wanted.

More recently JSON.Net has gotten better at letting you control the format and parsing of dates but it’s still not perfect and there are unit tests in past codebases that show variants that would unexpectedly pass, despite using the strictest settings. I wouldn’t be surprised if our Iso8601DateTime type was still in use as I can only assume everyone else is far less pedantic about the validation of datetimes and those that are have taken a similar route to ensure they control parsing.

A Dangerous Game

One should not lose sight though of the real issue here which the attempt to classify string values by attempting to parse them. Even if you limit yourself to a single locale you might get away with it but when you try and do that across arbitrary locales you’re just asking for trouble.

 

[1] “String was not recognized as a valid DateTime.”

[2] This whole fiasco falls squarely in the territory I’ve covered before in my Overload article “Terse Exception Messages”. Fixing this went to the top of my backlog, especially after I discovered it was a problem for our users too.

[3] Why they didn’t just pick THE universal format of ISO-8601 is anyone’s guess.

[4] I still need to go back and read the documentation for this method because it clearly caters for scenarios I just don’t normally see in my normal locale or user base.

[5] That’s what happens with tactical solutions, no one ever quite gets around to documenting anything because they never think it’ll survive for very long...

Network Saturation

The first indication that we seemed to have a problem was when some of the background processing jobs failed. The support team naturally looked at the log files where the jobs had failed and discovered that the cause was an inability to log-in to the database during process start-up. Naturally they tried to log-in themselves using SQL Server Management Studio or run a simple “SELECT GetDate();” style query via SQLCMD and discovered a similar problem.

Initial Symptoms

With the database appearing to be up the spout they raised a priority 1 ticket with the DBA team to investigate further. Whilst this was going on I started digging around the grid computation services we had built to see if any more light could be shed on what might be happening. This being the Windows Server 2003 era I had to either RDP onto a remote desktop or use PSEXEC to execute remote commands against our app servers. What surprised me was that these were behaving very erratically too.

This now started to look like some kind of network issue and so a ticket was raised with the infrastructure team to find out if they knew what was going on. In the meantime the DBAs came back and said they couldn’t find anything particularly wrong with the database, although the transaction log consumption was much higher than usual at this point.

Closing In

Eventually I managed to remote onto our central logging service [1] and found that the day’s log file was massive by comparison and eating up disk space fast. TAILing the central log file I discovered page upon page of the same error about some internal calculation that had failed on the compute nodes. At this point it was clearly time to pull the emergency chord and shut the whole thing down as no progress was being made for the business and very little in diagnosing the root of the problem.

With the tap now turned off I was able to easily jump onto a compute node and inspect its log. What I discovered there was every Monte Carlo simulation of every trade it was trying to value was failing immediately in some set-up calculation. The “best efforts” error handling approach meant that the error was simply logged and the valuation continued for the remaining simulations – rinse and repeat.

Errors at Scale

Of course what compounded the problem was the fact that there were approaching 100 compute nodes all sending any non-diagnostic log messages, i.e. all warnings and errors, across the network to one central service. This service would in turn log any error level messages in the database’s “error log” table.

Consequently with each compute node failing rapidly (see “Black Hole - The Fail Fast Anti-Pattern”) and flooding the network with thousands of log messages per-second the network eventually became saturated. Those processes which had long-lived network connections (we used a high-performance messaging product for IPC) would continue to receive and generate traffic, albeit slowly, but establishing new connections usually resulted in some form of timeout being hit instead.

The root cause of the compute node set-up calculation failure was later traced back to some bad data which itself had resulted from poor error handling in some earlier initial batch-level calculation.

Points of Failure

This all happened just before Michael Nygard published his excellent book Release It! Some months later when I finally read it I found myself frequently nodding my head as his tales of woe echoed my own experiences.

One of the patterns he talks about in his book is the use of bulkheads to stop failures “jumping the cracks”. On the compute nodes the poor error handling strategy meant that the same error occurred over-and-over needlessly instead of failing once. The use of a circuit breaker could also have mitigated the volume of errors generated and triggered some kind of cooling off period.

Duplicating the operational log data in the same database as the business data might have been a sane thing to do when the system was tiny and handling manual requests, but as the system became more automated and scaled out this kind of data should have been moved elsewhere where it could be used more effectively.

One of the characteristics of a system like this is that there are a lot of calculations forming a pipeline, so garbage-in, garbage-out means something might not go pop right away but sometime later when the error has compounded. In this instance an error return value of –1 was persisted as if it was normal data instead of being detected. Latter stages could do sanity checks on data to avoid poisoning the whole thing before it’s too late. It should also have been fairly easy to run a dummy calculation on the core inputs before opening the flood gates to mitigate a catastrophic failure, at least, for one due to bad input data.

Aside from the impedance mismatch in the error handling of different components there was also a disconnect in the error handling in the code that was biased towards one-off trader and support calculations, where the user is present, versus batch processing where the intention is for the system to run unattended. The design of the system needs to take both needs into consideration and adjust the error handling policy as appropriate. (See “The Generation, Management and Handling of Errors” for further ideas.)

Although the system had a monitoring page it only showed the progress of the entire batch – you needed to know the normal processing speed to realise something was up. A dashboard needs a variety of different indicators to show elevated error rates and other anomalous behaviour, ideally with automatic alerting when the things start heading south. Before you can do that though you need the data to work from, see “Instrument Everything You Can Afford To”.

The Devil is in the (Non-Functional) Details

Following Gall’s Law to the letter this particular system had grown over many, many years from a simple ad-hoc calculation tool to a full-blown grid-based compute engine. In the meantime some areas around stability and reliably had been addressed but ultimately the focus was generally on adding support for more calculation types rather than operational stability. The non-functional requirements are always the hardest to get buy-in for on an internal system but without them it can all come crashing down and end in tears with some dodgy inputs.

 

[1] Yes, back then everyone built their own logging libraries and tools like Splunk.

Stack Overflow With Custom JsonConverter

[There is a Gist on GitHub that contains a minimal working example and summary of this post.]

We recently needed to change our data model so that what was originally a list of one type, became a list of objects of different types with a common base, i.e. our JSON deserialization now needed to deal with polymorphic types.

Naturally we googled the problem to see what support, if any, Newtonsoft’s JSON.Net had. Although it has some built-in support, like many built-in solutions it stores fully qualified type names which we didn’t want in our JSON, we just wanted simple technology-agnostic type names like “cat” or “dog” that we would be happy to map manually somewhere in our code. We didn’t want to write all the deserialization logic manually, but was happy to give the library a leg-up with the mapping of types.

JsonConverter

Our searching quickly led to the following question on Stack Overflow: “Deserializing polymorphic json classes without type information using json.net”. The lack of type information mentioned in the question meant the exact .Net type (i.e. name, assembly, version, etc.), and so the answer describes how to do it where you can infer the resulting type from one or more attributes in the data itself. In our case it was a field unsurprisingly called “type” that held a simplified name as described earlier.

The crux of the solution involves creating a JsonConverter and implementing the two methods CanConvert and ReadJson. If we follow that Stack Overflow post’s top answer we end up with an implementation something like this:

public class CustomJsonConverter : JsonConverter
{
  public override bool CanConvert(Type objectType)
  {
    return typeof(BaseType).
                       IsAssignableFrom(objectType);
  }

  public override object ReadJson(JsonReader reader,
           Type objectType, object existingValue,
           JsonSerializer serializer)
  {
    JObject item = JObject.Load(reader);

    if (item.Value<string>(“type”) == “Derived”)
    {
      return item.ToObject<DerivedType>();
    }
    else
    . . .
  }
}

This all made perfect sense and even agreed with a couple of other blog posts on the topic we unearthed. However when we plugged it in we ended up with an infinite loop in the ReadJson method that resulted in a StackOverflowException. Doing some more googling and checking the Newtonsoft JSON.Net documentation didn’t point out our “obvious” mistake and so we resorted to the time honoured technique of fumbling around with the code to see if we could get this (seemingly promising) solution working.

A Blind Alley

One avenue that appeared to fix the problem was manually adding the JsonConverter to the list of Converters in the JsonSerializerSettings object instead of using the [JsonConverter] attribute on the base class. We went back and forth with some unit tests to prove that this was indeed the solution and even committed this fix to our codebase.

However I was never really satisfied with this outcome and so decided to write this incident up. I started to work through the simplest possible example to illustrate the behaviour but when I came to repro it I found that neither approach worked – attribute or serializer settings - I always got into an infinite loop.

Hence I questioned our original diagnosis and continued to see if there was a more satisfactory answer.

ToObject vs Populate

I went back and re-read the various hits we got with those additional keywords (recursion, infinite loop and stack overflow) to see if we’d missed something along the way. The two main candidates were “Polymorphic JSON Deserialization failing using Json.Net” and “Custom inheritance JsonConverter fails when JsonConverterAttribute is used”. Neither of these explicitly references the answer we initially found and what might be wrong with it – they give a different answer to a slightly different question.

However in these answers they suggest de-serializing the object in a different way, instead of using ToObject<DerivedType>() to do all the heavy lifting, they suggest creating the uninitialized object yourself and then using Populate() to fill in the details, like this:

{
  JObject item = JObject.Load(reader);

  if (item.Value<string>(“type”) == “Derived”)
  {
    var @object = new DerivedType();
    serializer.Populate(item.CreateReader(), @object);
    return @object;
  }
  else
    . . .
}

Plugging this approach into my minimal example worked, and for both the converter techniques too: attribute and serializer settings.

Unanswered Questions

So I’ve found another technique that works, which is great, but I still lack closure around the whole affair. For example, how come the answer in the the original Stack Overflow question “Deserializing polymorphic json classes” didn’t work for us? That answer has plenty of up-votes and so should be considered pretty reliable. Has there been a change to Newtonsoft’s JSON.Net library that has somehow caused this answer to now break for others? Is there a new bug that we’ve literally only just discovered (we’re using v10)? Why don’t the JSON.Net docs warn against this if it really is an issue, or are we looking in the wrong part of the docs?

As described right at the beginning I’ve published a Gist with my minimal example and added a comment to the Stack Overflow answer with that link so that anyone else on the same journey has some other pieces of the jigsaw to work with. Perhaps over time my comment will also acquire up-votes to help indicate that it’s not so cut-and-dried. Or maybe someone who knows the right answer will spot it and point out where we went wrong.

Ultimately though this is probably a case of not seeing the wood for the trees. It’s so easy when you’re trying to solve one problem to get lost in the accidental complexity and not take a step back. Answers on Stack Overflow generally carry a large degree of gravitas, but they should not be assumed to be infallible. All documentation can go out of date even if there are (seemingly) many eyes watching over it.

When your mind-set is one that always assumes the bugs are of your own making, unless the evidence is overwhelming, then those times when you might actually not be entirely at fault seem to feel all the more embarrassing when you realise the answer was probably there all along but you discounted it too early because your train of thought was elsewhere.

Poor Performance of log4net Context Properties

Back in September last year I wrote a post about a simple, low-latency web service we had to put together in a short timeframe (see “The Surgical Team”). During this project we hit a serious performance snag with log4net caused by using its context properties collection in the log message.

The Early Warning Indicator

The web service we were building had to perform a simple lookup on a multi-GB data set in less than 10 ms. We were going to use .Net and ASP.Net and so given its garbage collected environment we sought to verify first of all that garbage collections were not going to be a problem. Hence we got the CI pipeline in place and wrapped up a call to a NOP web API handler in a performance test to measure the basic solution infrastructure.

After a few false starts with the test itself (and the test framework) we found that each call was only taking a couple of ms [1] with an occasionally longer one as we hit a 2nd generation garbage collection (GC) which “stops the world” (at least in .Net 4). Even though the expensive GC meant we were occasionally more than an order of magnitude outside our SLA, the business were happy to go with it given the time constraints [2].

The Klaxon Goes Off

All of a sudden the core part of the build is succeeding but the performance tests are failing. We initially put it down to a blip, perhaps in the infrastructure, and ignore it for now. Then it trips again and again and so we decide to check the last few commits to see what’s happening as this now feels like it might be our code.

One of the developers had recently added log4net into the mix for diagnostic logging and to report SLA violations via the Windows event log, but that had been a few commits before things started going south. The commit that seemed to have pushed us over the edge was the addition of the HTTP request correlation ID to the log message. This was done via the context property bag in log4net, e.g.

%date %-5level %thread %property{correlationId} ...

This didn’t seem quite right at first though as we’d used the same property bag elsewhere, e.g. in the event log message. But of course we quickly realised the event log message only happened when we were already outside the SLA.

We reverted the change and the performance tests were green once more. At this point we didn’t know what it was about using properties that was causing it, or even if it really was that so we looked for another way as the information was important for support and monitoring (see “Causality – Relating Distributed Diagnostic Contexts”).

(This also got noticed and formally reported by someone else a few months later, and is now tracked in the log4net JIRA under LOGNET-421 and LOG4NET-429.)

Pattern Converters to the Rescue

Fortunately the property bag isn’t the only way to insert custom content into a log4net message (without just concatenating it into the message which was our fall-back), it also supports custom fields, called “pattern converters”.

As you can see from the documentation you specify your own field names and use them as placeholders too, e.g.

%date %-5level %thread %correlationId ...

Unlike the built-in property bag you have to do a little bit more work, such as creating some (thread-local) storage for the property value that you can fish out later when you need to invoke log4net to write the message [3].

public class CorrelationIdConverter : PatternConverter
{
  protected override void Convert(TextWriter writer,
                                  object state)
  {
    // The ID is stored in a thread-local property.
    writer.Write(Correlation.Id);
  }
}

You’ll also need to tell log4net about the field name and the class that should be invoked to format the value [4].

<converter>
  <name value="correlationId" />
  <type value="MyLib.CorrelationIdConverter, MyLib"/>
</converter>

We watched the build machine performance test results closely when the change was pushed but, just as we had hoped, the effect wasn’t noticeable.

 

[1] I am in no way suggesting that “a couple of ms” for an empty web API call could be considered decent performance. Quite frankly I was amazed when we discovered how much time and memory the ASP.Net pipeline itself used.

[2] We did suggest ways to mitigate this, such as fronting the service with a load balancer / service that could do a “best of three” as the service was read-only.

[3] Technically speaking it was stored in the ASP.Net HttpContext, if it exists, and if not we fall back to using traditional thread-local storage.

[4] We were actually using programmatic configuration of log4net there, but on another project we had to use the traditional log4net.config file and sadly it starts to add a bit of noise.

Leaky Abstractions: Querying a TIBCO Queue’s Pending Message Count

My team recently had a stark reminder about the Law of Leaky Abstractions. I wasn’t directly involved but feel compelled to pass the details on given the time we haemorrhaged [1] tracking it down...

Pending Messages

If you google how to find the number of messages that are pending in a TIBCO queue you’ll probably see a snippet of code like this:-

var admin = new Admin(hostname, login, password);
var queueInfo = admin.GetQueue(queueName);
var count = queueInfo.PendingMessageCount;

In fact I’m sure that’s how we came by this code ourselves as we didn’t have any formal documentation to work off right at the very start as this was only going in some test code. In case you're curious we were writing some acceptance tests and in the test code we needed to wait for the queue pending message count to drop to zero as a sign that the messages had been processed and we could safely perform our other asserts to very the behaviour.

Queue Monitoring

So far so good. The test code had been working flawlessly for months but then we started writing a new component. This time we needed to batch message handling up so instead of processing the stream as fast as possible we needed to wait for “a large enough batch”, then pull the messages and aggregate them. We could have buffered the messages in our own process but it felt safer to leave them in the durable storage for as long as possible as there was no two-phase commit going on.

The new acceptance tests were written in a similar style to before but the production code didn’t seem to be working properly - the pending message count always seemed to return 0. The pending message count check was just one of a number of triggers that could start the batch processing and so the code lived in a class something like this:-

public class QueueCountTrigger : IBatchTrigger
{
  public QueueCountTrigger(...)
  {
    _admin = new Admin(hostname, login, password);
    _queueInfo = _admin.GetQueue(queueName);
    _triggerLevel = triggerLevel;
  }

  public bool IsTriggered()
  {
    return (queueInfo.PendingMessageCount >=
            _triggerLevel);
  }

  private Admin _admin;
  private QueueInfo _queueInfo;
  private int _triggerLevel;
}

Granted polling is less than ideal but it would serve our purpose initially. This behaviour was most curious because as we saw it similar code had been working fine in the old acceptance tests for months.

The Leaky Abstraction

Eventually one of the team started poking around under the hood with a disassembler and everything began to fall into place. The QueueInfo object returned from the Admin type was just a snapshot of the queue. When subsequent attempts were made to query the PendingMessageCount property it was just returning a cached value. Because the service always started first, after the queue had been purged, it never saw the count change.

Looking at the TIBCO documentation for the classes (and method) in question you’d struggle to find anything that suggests you can’t hold on to the QueueInfo object and get real-time updates of the various queue attributes. Perhaps the “Info” suffix is supposed to be a clue? In retrospect perhaps QueueSnapshot would be a better name? Or maybe it’s documented clearly elsewhere in some kind of design rationale that you’re supposed to read up front?

I can’t remember if it was Steve Maguire in Writing Solid Code or Steve McConnell in Code Complete, but I’m sure one of them suggested that there is no such thing as a black box. Whilst the documentation may describe the interface there are often implementation details, such as performance or caching effects, that are left unspecified and eventually you’ll need to open the box to find out what’s really going on when it doesn’t behave as you would like in your scenario.

Back to the Tests

Looking more closely at the original code for the acceptance tests it made a sub-optimal call which opened a connection every time the message count was requested (just as the example code at the top would do):-

public int GetPendingMessageCount(...)
{
  var admin = new Admin(hostname, login, password);
  var queueInfo = admin.GetQueue(queueName);

  return queueInfo.PendingMessageCount;
}

This was later changed to an inline call, but re-fetched the QueueInfo snapshot the end of every loop iteration. Sadly the author of this change is no longer around so it’s hard to say if this was done after going through the same discovery exercise above, by basing it on a better example from somewhere else, prior knowledge of the problem, or just out-and-out luck.

public int WaitForQueueToEmpty(...)
{
  var admin = new Admin(hostname, login, password);
  var queueInfo = admin.GetQueue(queueName);

  while (queueInfo.PendingMessageCount > 0)
  {
    // Other timeout handling code
    . . .
    queueInfo = admin.GetQueue(queueName);
  }
}

 

[1] Exaggeration used for dramatic effect.

DDE XTYP_EXECUTE Command Corruption

A few months back I had a request to add support for the XTYP_EXECUTE transaction type to my COM based DDE client. The question came from someone who was using the component via VBScript to automate a TCL script which in turn was automating some other processes! My underlying C++ based DDE library already had support for this, along with my DDECmd tool so I thought it was going to be a simple job. What I didn’t expect was to get into the murky depths of what happens when you mix-and-match ANSI [1] and Unicode build DDE clients and servers...

Adding XTYP_EXECUTE Support

Due to the nature of COM the API to my COMDDEClient component is essentially Unicode. When I went into my code to check how the command strings were handled in my C++ library I discovered (after spelunking the last 10 years of my VSS repo) that when I ported the library to allow it to be dual build (ANSI & Unicode) I just took the command string as is (either char or wchar_t) and pushed it out directly as the value for the XTYP_EXECUTE transaction data.

The XTYP_EXECUTE DDE transaction type is an oddity in that the “format” argument to the DdeClientTransaction() function is ignored [2]. The format of this command is documented as being a string, but the exact semantics around whether it’s ANSI or Unicode appear left unsaid. I therefore decided to correct what I thought was my naive implementation and allow the format to be specified by the caller along with the value - this felt more like a belt-and-braces approach.

Naturally when I came to implement my new ExecuteTextCommand() method on the COM DDE server IDDEConversation interface, I followed the same pattern I had used in the rest of the COM server and defaulted to CF_TEXT as the wire format [3]. I tested it using the new support I’d added to my DDECmd tool via the --format switch and thought everything was great.

Impedance Mismatch

Quite unexpectedly I quickly got a reply from the original poster to say that it wasn’t working. After doing the obvious checks that the build I provided worked as expected (still using my own DDECmd tool as the test harness), I took a crash course in TCL. I put together a simple TCL script that acted as a DDE server and printed the command string send to it. When I tried it out I noticed I didn’t get what I expected, the string appeared to be empty, huh?

Naturally I Googled “TCL XTYP_EXECUTE” looking for someone who’s had the same issue in the past. Nothing. But I did find something better - the source code to TCL. It took seconds to track down “win/tclWinDde.c” which contains the implementation of the TCL DDE support and it shows that TCL does some shenanigans to try and guess whether the command string is ANSI or Unicode text (quite a recent change). The implementation makes sense given the fact that the uFmt parameter is documented as being ignored. What then occurred to me as I was reading the TCL source code (which is written in C) was that it was ANSI specific. I was actually looking at slightly older code it later transpired, but that was enough for the light bulb in head to go on.

A consequence of me using my own tools to test my XTYP_EXECUTE support was that I had actually only tested matched build pairs of the DDE client and server, i.e. ANSI <-> ANSI and Unicode <-> Unicode. What I had not tested was mixing-and-matching the two. I quickly discovered that one permutation always worked (ANSI client to Unicode server) but not the other way (a Unicode client sending CF_TEXT to an ANSI server failed).

Guess what, my DDECOMClient component was a Unicode build DDE client sending CF_TEXT command strings to a TCL DDE server that was an ANSI build. Here is a little table showing the results of my mix-and-match tests:-

Client	Sending	Server	Receives	Works?
ANSI	CF_TEXT	Unicode	CF_UNICODETEXT	Yes
ANSI	CF_UNICODETEXT	Unicode	CF_UNICODETEXT	Yes
Unicode	CF_TEXT	ANSI	???	No
Unicode	CF_UNICODETEXT	ANSI	CF_TEXT	Yes

Forward Compatible Only

I looked at the command string buffer received by the DDE server in the debugger and as far as I can tell DDE will attempt to convert the command string based on the target build of the DDE server, which it knows based on whether you called the ANSI or Unicode version of DdeInitialize() [4]. That means it will automatically convert between CF_TEXT and CF_UNICODETEXT format command strings to ensure interoperability of direct ports of DDE components from ANSI to Unicode.

In fact it does even better than that because it will also correctly convert a CF_TEXT format command sent from a Unicode build DDE client to a Unicode build DDE server. The scenario where it does fail though, and the one that I created by accident through trying to be flexible, is sending a CF_TEXT format command string from a Unicode build DDE client to an ANSI build DDE server.

Once I discovered that DDE was already doing The Right Thing I just backed out all my DDE library changes and went back to the implementation I had before! And hey presto, it now works.

 

[1] For “ANSI” you should probably read “Multi-byte Character Set” (MBCS), but that’s awkward to type and so I’m going to stick with the much simpler (and much abused) term ANSI. This means I’m now as guilty as many others about using this term incorrectly. Sorry Raymond.

[2] Not only is this documented but I also observed it myself whilst investigating my later changes on Windows XP - the uFormat argument always seemed to reach the DDE Server callback proc as 0 no matter what I set it to in the client.

[3] Given the uses for DDE that I know of (mostly financial and simple automation) CF_TEXT is more than adequate and is the lowest common denominator. Nobody has written to me yet complaining that it needs to support requests in CF_UNICODETEXT format.

[4] It is not obvious from looking at the DdeInitialize() signature that the function even has an ANSI and Unicode variant because there are no direct string parameters.

Intriguing SCHTASKS Bug

To get our system up and running quickly we chose to use the built-in Windows task scheduler to invoke our nightly batch. During initial development we added a couple of tasks by hand using the Scheduled Tasks UI, but as we got closer to our release date we created a batch file to script creation of the scheduled tasks so that we had a formal (and version controlled) deployment process, e.g.

C:\> SCHTASKS /CREATE /SC WEEKLY /D … /TN “RunBatch”

The script was written and tested on a Windows XP desktop machine, but when we came to test it on our Windows server the script failed with the following error:-

ERROR: The creation of the scheduled task failed.
Reason: The Task Name may not contain the characters: <, >, :, /, \,|.

This was most curious as the server was running Windows Server 2003 (which is the same family as XP) and the task names were all pretty simple using just a number, dash and short name, e.g. “01-EstablishValueDate” – there were no out-of-the-ordinary characters at all. Naturally I took the dash[*] out first – no luck. Then the numbers – nope. Finally I resorted to a binary search to try and pin down exactly which character(s) it was…

It turned out to be the letter ‘D’ at the start of the word “Date”! The first three tasks I tried all had the word “Date” in them somewhere and they all worked after just removing the letter ‘D’. To be more specific it was a capital letter D as a lower case ‘d’ worked! This became our temporarily workaround whilst I did a little Googling in the background as I just couldn’t entertain the idea that this was the real problem; I’ll always assume I’m doing something wrong until Occam's Razor tells me it’s not me :-). Fortunately I quickly discovered the following forum post “Error In Schtasks Command Line” where there author was having no joy in creating a scheduled task called “Defrag”. Sadly it doesn’t say they resorted to just calling their task “defrag” as a workaround. Anyway a short time later I managed to discover an MSDN article that appeared to confirm the behaviour. In the KB article it says the following:-

The Schtasks command verifies the task name by comparing the task name with an invalid character set. If the task name contains one or more characters from the invalid character set, the Schtasks command denies the task creation request.

However, in race conditions, the invalid character set may contain a valid character. Therefore, the Schtasks command cannot create some tasks even if the task names contain only valid characters.

My mind boggles at what the SCHTASKS code is doing to create such a race condition? And why just the letter D?

[*] A common source of error is pasting command lines out of Word documents or web pages into console windows; this often results in curious error messages from the application. The problem is the “clever” document editor converting a dash (en dash, minus sign, etc) into a proper hyphen (em dash) or equivalent Unicode character at a different code point from the ASCII one. It may look like a dash to you and me but the “computer says no”.