Ayende @ Rahien

Hi!
My name is Oren Eini
Founder of Hibernating Rhinos LTD and RavenDB.
You can reach me by phone or email:

ayende@ayende.com

+972 52-548-6969

, @ Q c

Posts: 5,953 | Comments: 44,410

filter by tags archive

Challengewhy did the tests fail?


For a few days, some (~4) of SvnBridge integration tests would fail. Not always the same ones (but usually the same group), and only if I run them all as a group, never if I run each test individually, or if I run the entire test class (which rules out most of the test dependencies that causes this). This was incredibly annoying, but several attempts to track down this issue has been less than successful.

Today I got annoyed enough to say that I am not leaving until I solve this. Considering that a full test run of all SvnBridge's tests is... lengthy, that took a while, but I finally tracked down what was going on. The fault was with this method:

protected string Svn(string command)
{
	StringBuilder output = new StringBuilder();
	string err = null;
	ExecuteInternal(command, delegate(Process svn)
	{
		ThreadPool.QueueUserWorkItem(delegate

		{
			err = svn.StandardError.ReadToEnd();
		});
		ThreadPool.QueueUserWorkItem(delegate
		{
			string line;
			while ((line = svn.StandardOutput.ReadLine()) != null)
			{
				Console.WriteLine(line);
				output.AppendLine(line);
			}
		});
	});
	if (string.IsNullOrEmpty(err) == false)
	{
		throw new InvalidOperationException("Failed to execute command: " + err);
	}
	return output.ToString();
}

This will execute svn.exe and gather its input. Only sometimes it would not do so.

I fixed it by changing the implementation to:

protected static string Svn(string command)
{
	var output = new StringBuilder();
	var err = new StringBuilder();
	var readFromStdError = new Thread(prc =>
	{
		string line;
		while ((line = ((Process)prc).StandardError.ReadLine()) != null)
		{
			Console.WriteLine(line);
			err.AppendLine(line);
		}
	});
	var readFromStdOut = new Thread(prc =>
	{
		string line;
		while ((line = ((Process) prc).StandardOutput.ReadLine()) != null)
		{
			Console.WriteLine(line);
			output.AppendLine(line);
		}
	});
	ExecuteInternal(command, svn =>
	{
		readFromStdError.Start(svn);
		readFromStdOut.Start(svn);
	});

	readFromStdError.Join();
	readFromStdOut.Join();

	if (err.Length!=0)
	{
		throw new InvalidOperationException("Failed to execute command: " + err);
	}
	return output.ToString();
}

And that fixed the problem. What was the problem?

More posts in "Challenge" series:

  1. (28 Apr 2015) What is the meaning of this change?
  2. (26 Sep 2013) Spot the bug
  3. (27 May 2013) The problem of locking down tasks…
  4. (17 Oct 2011) Minimum number of round trips
  5. (23 Aug 2011) Recent Comments with Future Posts
  6. (02 Aug 2011) Modifying execution approaches
  7. (29 Apr 2011) Stop the leaks
  8. (23 Dec 2010) This code should never hit production
  9. (17 Dec 2010) Your own ThreadLocal
  10. (03 Dec 2010) Querying relative information with RavenDB
  11. (29 Jun 2010) Find the bug
  12. (23 Jun 2010) Dynamically dynamic
  13. (28 Apr 2010) What killed the application?
  14. (19 Mar 2010) What does this code do?
  15. (04 Mar 2010) Robust enumeration over external code
  16. (16 Feb 2010) Premature optimization, and all of that…
  17. (12 Feb 2010) Efficient querying
  18. (10 Feb 2010) Find the resource leak
  19. (21 Oct 2009) Can you spot the bug?
  20. (18 Oct 2009) Why is this wrong?
  21. (17 Oct 2009) Write the check in comment
  22. (15 Sep 2009) NH Prof Exporting Reports
  23. (02 Sep 2009) The lazy loaded inheritance many to one association OR/M conundrum
  24. (01 Sep 2009) Why isn’t select broken?
  25. (06 Aug 2009) Find the bug fixes
  26. (26 May 2009) Find the bug
  27. (14 May 2009) multi threaded test failure
  28. (11 May 2009) The regex that doesn’t match
  29. (24 Mar 2009) probability based selection
  30. (13 Mar 2009) C# Rewriting
  31. (18 Feb 2009) write a self extracting program
  32. (04 Sep 2008) Don't stop with the first DSL abstraction
  33. (02 Aug 2008) What is the problem?
  34. (28 Jul 2008) What does this code do?
  35. (26 Jul 2008) Find the bug fix
  36. (05 Jul 2008) Find the deadlock
  37. (03 Jul 2008) Find the bug
  38. (02 Jul 2008) What is wrong with this code
  39. (05 Jun 2008) why did the tests fail?
  40. (27 May 2008) Striving for better syntax
  41. (13 Apr 2008) calling generics without the generic type
  42. (12 Apr 2008) The directory tree
  43. (24 Mar 2008) Find the version
  44. (21 Jan 2008) Strongly typing weakly typed code
  45. (28 Jun 2007) Windsor Null Object Dependency Facility

Comments

Benny Thomas

Could it be that your err-handling from string to StringBuilder was the solution to fix the problem.

And that way that the String manpulation on err was the problem?

Niki

Where does the old code Join the two work items? Who says the last output.AppendLine(line) has finished when you return?

Dragos

Is it the join of the 2 threads? On the previous implementation,

the sequence

if (string.IsNullOrEmpty(err) == false)

{

    throw new InvalidOperationException("Failed to execute command: " + err);

}

was called before the ThreadPool threads finished execution ?!?

Roger Alsing

My guess would be that there is some problem because threadpool only allocates new threads once you reach a certain level of work.

if you only queue two tasks they will be executed in the same thread in a syncronous way instead of async.

Atleast that have been a problem in the past, don't know if it is fixed nowdays in threadpool.

Pieter

I agree with Dragos, it must be the Joins.

Joshua McKinney

for reference:

    private static void ExecuteInternal(string command, Action<Process> process)

    {

       Console.WriteLine("svn " + command);

        ProcessStartInfo psi = new ProcessStartInfo("svn", command);

        psi.RedirectStandardOutput = true;

        psi.RedirectStandardError = true;

        psi.CreateNoWindow = true;

        psi.UseShellExecute = false;

        Process svn = Process.Start(psi);

        process(svn);

        svn.WaitForExit();

    }

svn.WaitForExit() finishes waiting when the call to ReadToEnd() / ReadLine() both complete. At this point the "err =" part of the statement has not executed. If a thread switch happens before the assignment takes place, err will still be null directly after the ExecuteInternal() call.

Philip

err being null should be fine, unless I'm reading that incorrectly.

Here's a theory:

  • The threadpool is not spining up both worker threads - it didn't spin up your stdout reading thread yet waiting for another thread to finish.

  • svn.exe is filling stdout stream buffer, and blocking on writing more, so it never finishes

  • since svn isn't finishing, it's not closing stderr, so the error reading thread is never recycled to the threadpool, so the stdout reading thread is never spun up

-deadlock

?

Jeff Lewis

The docs actually tell you what the error was: http://msdn.microsoft.com/en-us/library/system.diagnostics.process.standarderror.aspx

I ran into exactly the same thing when controlling SVN.exe from another process and ended up using the ErrorDataReceived and OutputDataReceived events on Process.

Neil Mosafi

That's what I thought, but it's hard to know if err being null is actually fine. If an error occurs, and it's not reported, then the output would presumably be empty or incorrect, and whatever test is calling that function may fail.

Basically, it could be a number of things, I think you need more context to get it. But maybe I'm wrong!

Reshef Mann

My guess is that when u r running the group of tests, u r exhausting the thread pool, meaning that some thread will queue-up before they will start execution.

in case that the svn process ends (and thus we don't wait for it anymore) before, lets say, the thread that reads the error stream runs, u will see that err is null, and therefore no error occured, although your test expects an error.

Is that right?

firefly

Because Excute internal doesn't wait for the two thread to complete it just queue them to be execute. This will work most of the time since computer is so fast even though it's queuing the action took place almost in orders... But if the computer is busy.... i.e. when you are running integration test then

if (string.IsNullOrEmpty(err) == false)

{

    throw new InvalidOperationException("Failed to execute command: " + err);

}

will throw an exception because err is still null.

readFromStdError.Join();

readFromStdOut.Join();

tell the application to wait for the two thread to finish before continue.

firefly

I knew I got something wrong... :) I glance it over it too quick. Two thing could go wrong here. svn actually produce an error but the application fail to catch it. or output string is still empty or both because the two worker thread never got a chance to execute. Wont throw an exception just doesn't produce anything.

Philip

Yes, now after looking at it and the comments a bit, there's actually several potential problems with the original code:

1) Potential deadlock when the threadpool is taxed

2) Potential empty output when the svn command is fast but background thread isn't started immediately (not uncommon on queueuserworkitem when app is active). - The WaitForExit() call can return before all output is read if the buffers aren't full... so for a fast svn call with little output, this may actually be relatively common

3) Empty error when an error did actually occur (false success) - same reasons as #2

Ayende Rahien

Reshef,

BING BING BING!

Yep, that is my own observation!

Joshua McKinney

Ah, I read the following in regards to WaitForExit()

"This overload ensures that all processing has been completed, including the handling of asynchronous events for redirected standard output. You should use this overload after a call to the WaitForExit(Int32) overload when standard output has been redirected to asynchronous event handlers."

I assumed that meant that synchronous reads would complete before WaitForExit() returns, however this is not the case, only asynch calls to Begin... on the process object will complete.

Mark McGee

I think I may have found a bug in Rhino.Mocks v3.4.0 (the version I'm using - I haven't tested it in other versions).

I've been asked to write some unit tests involving this interface; 

        public interface IConfigurationSource 

        { 

                void Open(); 

                bool MoveNext(); 

                string[] Key { get;} 

                object Value { get;} 

                void Close(); 

                string Name { get;} 

        } 


Which I create a couple of mocks for (I tried DynamicMock and Stub with the same results) 

        IConfigurationSource source1 = mocks.CreateMock<IConfigurationSource>(); 

        IConfigurationSource source2 = mocks.CreateMock<IConfigurationSource>(); 


However, when I do this; 

            using (mocks.Record()) 

            { 

                using (mocks.Ordered()) 

                { 

                    source1.Open(); 


                    Expect.Call(source1.MoveNext()).Return(true); 

                    Expect.Call(source1.Key).Return(new string[] { "IntField" }); 

                    Expect.Call(source1.Value).Return(12345); 


                    Expect.Call(source1.MoveNext()).Return(true); 

                    Expect.Call(source1.Key).Return(new string[] { "IntProperty" }); 

                    Expect.Call(source1.Value).Return(14321); 


                    Expect.Call(source1.MoveNext()).Return(false); 


                    source1.Close(); 

                    source1.Open(); 


                    Expect.Call(source1.ToString()).Return("source1"); 


This last line throws an exception saying  this; 

"InnerException {"Type 'System.String' doesn't match the return type 'System.Void' for method 'IConfigurationSource.Open();'"}  System.Exception {System.InvalidOperationException}"


It's somehow confusing the ToString() call with the preceeding void function (source1.Open)Obviously, something is not right with regards to the set-up of Object.ToString() virtual function.  I got the latest trunk (https://rhino-tools.svn.sourceforge.net/svnroot/rhino-tools/trunk <https://rhino-tools.svn.sourceforge.net/svnroot/rhino-tools/trunk> ) source code, but unfortunately, I can't get it to build with VS2005 using the instructions in "How to build.txt" file (msbuild buildall.build), so I am a bit stuck with this problem.


Am I doing something wrong here, or have I uncovered a bug? 
Ayende Rahien

This should go to the mailing list.

Comment preview

Comments have been closed on this topic.

FUTURE POSTS

No future posts left, oh my!

RECENT SERIES

  1. The RavenDB Comic Strip (3):
    28 May 2015 - Part III – High availability & sleeping soundly
  2. Special Offer (2):
    27 May 2015 - 29% discount for all our products
  3. RavenDB Sharding (3):
    22 May 2015 - Adding a new shard to an existing cluster, splitting the shard
  4. Challenge (45):
    28 Apr 2015 - What is the meaning of this change?
  5. Interview question (2):
    30 Mar 2015 - fix the index
View all series

Syndication

Main feed Feed Stats
Comments feed   Comments Feed Stats