Ayende @ Rahien

It's a girl

Challenge: why 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?

Comments

Benny Thomas
06/05/2008 10:30 AM by
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
06/05/2008 11:08 AM by
Niki

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

Dragos
06/05/2008 11:10 AM by
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
06/05/2008 11:33 AM by
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
06/05/2008 11:55 AM by
Pieter

I agree with Dragos, it must be the Joins.

Joshua McKinney
06/05/2008 01:32 PM by
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
06/05/2008 02:28 PM by
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
06/05/2008 02:36 PM by
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
06/05/2008 02:42 PM by
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
06/05/2008 03:24 PM by
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
06/05/2008 03:24 PM by
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
06/05/2008 03:38 PM by
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
06/05/2008 05:22 PM by
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
06/05/2008 09:16 PM by
Ayende Rahien

Reshef,

BING BING BING!

Yep, that is my own observation!

Joshua McKinney
06/06/2008 12:25 AM by
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
06/25/2008 02:36 PM by
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
06/25/2008 02:56 PM by
Ayende Rahien

This should go to the mailing list.

Comments have been closed on this topic.