Investigating an automation failure

  • Article

One of the automated tests we had failed last week and I got the chance to investigate the failure. The first level of investigation was determining if the test script had failed or if there was a new bug that had crept into OneNote. Here's what happened.

The first I noticed was an automated email I received about a test failing. Since we have moved from UI based testing to UI-Less, this happened a lot at first, but now is more rare. I looked at the error the test found and this is what I saw:

Error: Test method threw an exception. System.ArgumentException: An entry with the same key already exists.    at System.ThrowHelper.ThrowArgumentException(ExceptionResource resource)    at System.Collections.Generic.SortedList`2.Add(TKey key, TValue value)

Hmm. At first glance, this had nothing to do with OneNote and looked like the test script itself was faulty. Since OneNote was booting and otherwise functioning (this was the only failing test), I disabled the test while I continued the investigation into what was failing.

Here's what the code looked like that was throwing the error, with line numbers added for clarity (go BASIC!):

  1. SortedList<string, string> loadedModules = new SortedList<string, string>(StringComparer.InvariantCulture);
  2. System.Diagnostics.Process onenote = System.Diagnostics.Process.GetProcessesByName("onenote")[0];
  3. foreach (System.Diagnostics.ProcessModule loadedModule in onenote.Modules)
  4. {
  5. loadedModules.Add(loadedModule.ModuleName.ToLower(), loadedModule.FileName);
  6. }

I left out the logging commands which log results to a text file (there were none, by the way).

Here's what was happening. Line 1 creates a list of items which, when new items get added, get added into alphabetical order. This turns out to be critical.

Line 2 gets a handle to the running instance of OneNote. Since the test had progressed past this line, I was reassured OneNote had actually started and was running (in fact, if OneNote is not running, this line gives an array index out of bounds type of error).

Line 3 starts looping through the list of all the DLLs ("modules") OneNote has loaded.

Line 5 adds the name of the loaded module to the alphabetically sorted list.

I ran this a few times and line 4 kept giving me the error I had seen before. Hmm. A quick check on MSDN for SortedList showed me this line of information: "Every key in a SortedList<(Of <(TKey, TValue>)>) must be unique." And if a key with one name already exists, the CLR will throw an ArgumentException. This sounded like exactly what was happening to me.

 

For instance, if OneNote were loading a module named “onmain.dll” twice, the first time the sorted list would add it between “main.dll” and “sps.dll” since it adds the names in alphabetical order.  The next time the sorted list tries to add this name it gives an error since the name already exists in the list. 

I figured the problem was we were loading a DLL twice which would be a bug in OneNote. Since there was no way to tell from the way the test code was written, there was no way to tell which module was being loaded a second time, which means there is also a bug in the test code. Here are the changes I made to discover which module was loaded twice:

  1. SortedList<string, string> loadedModules =new SortedList<string, string>(StringComparer.InvariantCulture);
  2. System.Diagnostics.Process onenote = System.Diagnostics.Process.GetProcessesByName("onenote")[0];
  3. int i = 0;
  4. Console.WriteLine("There are this many module loaded: " + onenote.Modules.Count);
  5. foreach (System.Diagnostics.ProcessModule loadedModule in onenote.Modules)
  6. {
  7. Console.WriteLine ("Trying to add module " + i + " named " + loadedModule.ModuleName.ToString());
  8. loadedModules.Add(loadedModule.ModuleName.ToLower(), loadedModule.FileName);
  9. i++;
  10. }

Maybe it's not obvious, but we do not log to the console - I just added that to make this a little easier to read. We have our own logging class which is quite robust.

Anyway, I checked in my changes and the script will now fail the next time it is run, but now I will know which module is being loaded twice.  And the script will still fail when it detects a module already loaded, and I want the script to fail to alert me to the problem.

And I'm not sold that my changes are the best possible fix. I can still see some room for improvement, which I may try to implement this week. Stay tuned.

Question, comments, concerns and criticisms are always welcome,

John