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:
- (01 Jul 2024) Efficient snapshotable state
- (13 Oct 2023) Fastest node selection metastable error state–answer
- (12 Oct 2023) Fastest node selection metastable error state
- (19 Sep 2023) Spot the bug
- (04 Jan 2023) what does this code print?
- (14 Dec 2022) What does this code print?
- (01 Jul 2022) Find the stack smash bug… – answer
- (30 Jun 2022) Find the stack smash bug…
- (03 Jun 2022) Spot the data corruption
- (06 May 2022) Spot the optimization–solution
- (05 May 2022) Spot the optimization
- (06 Apr 2022) Why is this code broken?
- (16 Dec 2021) Find the slow down–answer
- (15 Dec 2021) Find the slow down
- (03 Nov 2021) The code review bug that gives me nightmares–The fix
- (02 Nov 2021) The code review bug that gives me nightmares–the issue
- (01 Nov 2021) The code review bug that gives me nightmares
- (16 Jun 2021) Detecting livelihood in a distributed cluster
- (21 Apr 2020) Generate matching shard id–answer
- (20 Apr 2020) Generate matching shard id
- (02 Jan 2020) Spot the bug in the stream
- (28 Sep 2018) The loop that leaks–Answer
- (27 Sep 2018) The loop that leaks
- (03 Apr 2018) The invisible concurrency bug–Answer
- (02 Apr 2018) The invisible concurrency bug
- (31 Jan 2018) Find the bug in the fix–answer
- (30 Jan 2018) Find the bug in the fix
- (19 Jan 2017) What does this code do?
- (26 Jul 2016) The race condition in the TCP stack, answer
- (25 Jul 2016) The race condition in the TCP stack
- (28 Apr 2015) What is the meaning of this change?
- (26 Sep 2013) Spot the bug
- (27 May 2013) The problem of locking down tasks…
- (17 Oct 2011) Minimum number of round trips
- (23 Aug 2011) Recent Comments with Future Posts
- (02 Aug 2011) Modifying execution approaches
- (29 Apr 2011) Stop the leaks
- (23 Dec 2010) This code should never hit production
- (17 Dec 2010) Your own ThreadLocal
- (03 Dec 2010) Querying relative information with RavenDB
- (29 Jun 2010) Find the bug
- (23 Jun 2010) Dynamically dynamic
- (28 Apr 2010) What killed the application?
- (19 Mar 2010) What does this code do?
- (04 Mar 2010) Robust enumeration over external code
- (16 Feb 2010) Premature optimization, and all of that…
- (12 Feb 2010) Efficient querying
- (10 Feb 2010) Find the resource leak
- (21 Oct 2009) Can you spot the bug?
- (18 Oct 2009) Why is this wrong?
- (17 Oct 2009) Write the check in comment
- (15 Sep 2009) NH Prof Exporting Reports
- (02 Sep 2009) The lazy loaded inheritance many to one association OR/M conundrum
- (01 Sep 2009) Why isn’t select broken?
- (06 Aug 2009) Find the bug fixes
- (26 May 2009) Find the bug
- (14 May 2009) multi threaded test failure
- (11 May 2009) The regex that doesn’t match
- (24 Mar 2009) probability based selection
- (13 Mar 2009) C# Rewriting
- (18 Feb 2009) write a self extracting program
- (04 Sep 2008) Don't stop with the first DSL abstraction
- (02 Aug 2008) What is the problem?
- (28 Jul 2008) What does this code do?
- (26 Jul 2008) Find the bug fix
- (05 Jul 2008) Find the deadlock
- (03 Jul 2008) Find the bug
- (02 Jul 2008) What is wrong with this code
- (05 Jun 2008) why did the tests fail?
- (27 May 2008) Striving for better syntax
- (13 Apr 2008) calling generics without the generic type
- (12 Apr 2008) The directory tree
- (24 Mar 2008) Find the version
- (21 Jan 2008) Strongly typing weakly typed code
- (28 Jun 2007) Windsor Null Object Dependency Facility
Comments
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?
Close, but no
Where does the old code Join the two work items? Who says the last output.AppendLine(line) has finished when you return?
Is it the join of the 2 threads? On the previous implementation,
the sequence
if (string.IsNullOrEmpty(err) == false)
was called before the ThreadPool threads finished execution ?!?
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.
I agree with Dragos, it must be the Joins.
for reference:
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.
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
?
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.
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!
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?
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
will throw an exception because err is still null.
tell the application to wait for the two thread to finish before continue.
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.
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
Reshef,
BING BING BING!
Yep, that is my own observation!
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.
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).
This should go to the mailing list.
Comment preview