Re: NSTask is intermittently failing to return results.
Re: NSTask is intermittently failing to return results.
- Subject: Re: NSTask is intermittently failing to return results.
- From: "email@hidden" <email@hidden>
- Date: Fri, 18 Mar 2011 10:39:16 +0000
Hi Jason
I haven't attempted to debug your code but I use NSTask extensively and have experienced some of the problems you describe.
In each case I was not correctly handling the asynchronous availability of data in the pipe ie: there is nothing wrong with the approach but implementation is all.
In my case I found that the implementation detailed in the following sample worked with great reliability on GC apps (search the xcode docs):
CommandLineToolPlugin.m
This sample uses NSFileHandle - waitForDataInBackgroundAndNotify.
This generates a single notification with all the available data - which may or may not be suitable for your needs.
The sample above calls NSTask - waitUntilExit but that is only a detail I think.
If this was my project I would instigate a branch that implemented the approach detailed in CommandLineToolPlugin.m and see where that got me.
It should have fewer moving parts at least.
Regards
Jonathan Mitchell
Developer
Mugginsoft LLP
http://www.mugginsoft.com
On 17 Mar 2011, at 09:01, Jason Harris wrote:
> General Problem:
> ------------------------------------
> NSTask is most of the time working for me, but intermittently it's failing to return results. Either the result is silently dropped, or more infrequently I am getting exceptions in:
>
> [NSConcreteData initWithBytes:length:copy:freeWhenDone:bytesAreVM:] or
> [NSConcreteFileHandle availableData] or
> [NSConcreteFileHandle readDataOfLength:]
>
> depending on the tweaks / experiments I am attempting to play with.
>
> If MacHg issues the *exact* same command a little later it will work.
>
>
>
> Background:
> ------------------------------------
> I write MacHg an open source OSX multithreaded GUI client for Mercurial. I have wanted to move to showing progress bars in MacHg as Mercurial progresses in doing its long running operations.
>
> In all my released versions of MacHg so far I have used only the readDataToEndOfFileIgnoringErrors approach to NSTask (since once I launch a task I am only ever reading data from it, and not actually ever sending data to its stdin). Ie something like:
>
> NSData* outData = [[outPipe fileHandleForReading] readDataToEndOfFileIgnoringErrors]
> NSData* errData = [[errPipe fileHandleForReading] readDataToEndOfFileIgnoringErrors];
>
> However, I have previously had problems with intermittent exceptions of [NSConcreteFileHandle readDataOfLength:] which bugged me. I spent some time trying to fix these but in the end couldn't figure out what was going wrong / how to fix them properly. In the end I used the bandaided approach of: http://www.cocoabuilder.com/archive/cocoa/173348-nstask-stealth-bug-in-readdataoflength.html#173647
>
> (Of note I have Garbage collection turned on in the MacHg project.)
>
>
>
> Moving to Notification based NSTask:
> ------------------------------------
> But it has nagged me as to why this was occurring using readDataToEndOfFileIgnoringErrors. In any case I had thought moving to a "Moriarity" style NSTask usage was going to solve my problems. I have now coded a "Moriarity" style NSTask usage up in MacHg. Ie using NSFileHandleReadCompletionNotification and NSTaskDidTerminateNotification. However, I discovered that the frequency of odd behavior has actually increased not decreased in moving to this approach.
>
> I have looked at (in fact studied in detail) the source code for Moriarity, AMShellWrapper, MyTask, and OpenFileKiller. (http://cocoadev.com/index.pl?NSTask ) (I have not really covered looking at MFTask, or trying to use Pseudo-TTYs or fork(), exec(), popen(), pipe() sorts of low level unix / posix things.)
>
> The hart of the code is the following (Note there are currently things in the code which won't be in the production code since they are used for debugging. Eg, the member theShellTask_ of ExecutionResult will be ripped out for production.)
>
>
>
> The Relevant Code:
> ------------------------------------
>
> - (void) setPendingTermination
> {
> pendingTermination_ = YES;
> [NSObject cancelPreviousPerformRequestsWithTarget:self selector:@selector(finishUp) object:nil];
> [self performSelector:@selector(finishUp) withObject:nil afterDelay:10.0];
> }
>
> - (void) resetPendingTermination
> {
> [NSObject cancelPreviousPerformRequestsWithTarget:self selector:@selector(finishUp) object:nil];
> pendingTermination_ = NO;
> }
>
> - (id) initWithCommand:(NSString*)cmd andArgs:(NSArray*)args onTask:(NSTask*)task
> {
> generatingCmd_ = cmd;
> generatingArgs_ = args;
> task_ = task ? task : [[NSTask alloc] init];
>
> outPipe_ = [[NSPipe alloc] init]; // Create the pipe to write standard out to
> errPipe_ = [[NSPipe alloc] init]; // Create the pipe to write standard error to
> outHandle_ = [outPipe_ fileHandleForReading];
> errHandle_ = [errPipe_ fileHandleForReading];
> outputData_ = [[NSMutableData alloc] init];
> errorData_ = [[NSMutableData alloc] init];
>
> [task_ setLaunchPath:cmd];
> [task_ setArguments:args];
> [task_ setStandardInput:[NSPipe pipe]];
> [task_ setStandardOutput:outPipe_];
> [task_ setStandardError:errPipe_];
>
> [self observe:NSFileHandleReadCompletionNotification from:outHandle_ byCalling:@selector(gotOutput:)];
> [self observe:NSFileHandleReadCompletionNotification from:errHandle_ byCalling:@selector(gotError:)];
> [self observe:NSTaskDidTerminateNotification from:task_ byCalling:@selector(gotExit:)];
>
> [outHandle_ readInBackgroundAndNotify];
> [errHandle_ readInBackgroundAndNotify];
> isFinished_ = NO;
> pendingTermination_ = NO;
>
> return self;
> }
>
> - (void) gotOutput:(NSNotification*)notification
> {
> NSData* data = [notification.userInfo objectForKey:NSFileHandleNotificationDataItem];
> if (notification.object == outHandle_)
> {
> if (data.length > 0)
> {
> DebugLog(@"...got Output for %@ ...", [self commandLineString]);
> [outHandle_ readInBackgroundAndNotify];
> [outputData_ appendData:data];
> [self resetPendingTermination];
> }
> else
> {
> DebugLog(@"...got NULL standard Output for %@ ...", [self commandLineString]);
> outHandle_ = nil;
> if ([self shouldFinishUp])
> [self finishUp];
> }
> }
> }
>
> - (void) gotError:(NSNotification*)notification
> {
> if (notification.object == errHandle_)
> {
> NSData* data = [notification.userInfo objectForKey:NSFileHandleNotificationDataItem];
> if (data.length > 0)
> {
> DebugLog(@"...got Error for %@ ...", [self commandLineString]);
> [errHandle_ readInBackgroundAndNotify];
> if (!arrayOfErrorData_)
> arrayOfErrorData_ = [[NSMutableArray alloc]init];
> [arrayOfErrorData_ addObject:data];
> [errorData_ appendData:data];
> [self resetPendingTermination];
> }
> else
> {
> DebugLog(@"...got NULL Error Output for %@ ...", [self commandLineString]);
> errHandle_ = nil;
> if ([self shouldFinishUp])
> [self finishUp];
> }
> }
> }
>
> - (void) gotExit:(NSNotification*)notification
> {
> if ([self shouldFinishUp])
> [self finishUp];
> else
> [self setPendingTermination];
> }
>
>
> - (BOOL) shouldFinishUp
> {
> return ![task_ isRunning] && !outHandle_ && !errHandle_;
> }
>
> - (void) finishUp
> {
> if (isFinished_)
> return;
>
> DebugLog(@"...Finishing up for %@ ...", [self commandLineString]);
>
> [NSObject cancelPreviousPerformRequestsWithTarget:self selector:@selector(finishUp) object:nil];
> [self stopObserving:NSFileHandleReadCompletionNotification from:nil];
> [self stopObserving:NSTaskDidTerminateNotification from:nil];
>
> [task_ terminate];
>
> // Clear standard out and standard error
> NSData* data;
> while ((data = [outHandle_ availableDataIgnoringErrors]) && [data length])
> [outputData_ appendData:data];
> while ((data = [errHandle_ availableDataIgnoringErrors]) && [data length])
> [errorData_ appendData:data];
>
> outHandle_ = nil;
> errHandle_ = nil;
> result_ = [task_ terminationStatus];
> isFinished_ = YES;
> }
>
>
> - (NSString*) commandLineString
> {
> NSMutableString* desc = [NSMutableString stringWithString:[generatingCmd_ lastPathComponent]];
> for (NSString* arg in generatingArgs_)
> {
> [desc appendString:@" "];
> [desc appendString:arg];
> }
> return desc;
> }
>
>
> - (BOOL) waitTillFinished
> {
> // wait for task to exit:
> while (![self shouldFinishUp])
> {
> // If the task is terminated we should set up a pending termination which will terminate in a bit. This catches some
> // zombie NSTasks where either the outputData or errorData of 0 were never posted..
> BOOL terminated = ![task_ isRunning];
> if (terminated && !pendingTermination_)
> {
> DebugLog(@"...Found terminated for %@ ...", [self commandLineString]);
> [self setPendingTermination];
> }
>
> BOOL runLoopRan = [[NSRunLoop currentRunLoop] runMode:NSDefaultRunLoopMode beforeDate:[NSDate distantFuture]];
> if (!runLoopRan)
> break;
> if (!isFinished_)
> DebugLog(@"...waitTillFinished still waiting for %@ ...", [self commandLineString]);
> }
>
> [self finishUp];
> DebugLog(@"...Exiting waitTillFinished for %@ ...", [self commandLineString]);
> return (result_ == 0);
> }
>
>
> + (ExecutionResult*) execute:(NSString*)cmd withArgs:(NSArray*)args onTask:(NSTask*)task
> {
> ShellTask* shellTask = [[ShellTask alloc] initWithCommand:cmd andArgs:args onTask:task];
>
> [shellTask->task_ launch]; // Start the process
> DebugLog(@"launched %@", [shellTask commandLineString]);
>
> [shellTask waitTillFinished];
>
> DebugLog(@"Finished execute cmd for %@", [shellTask commandLineString]);
>
> NSString* outStr = [[NSString alloc] initWithData:shellTask->outputData_ encoding:NSUTF8StringEncoding];
> NSString* errStr = [[NSString alloc] initWithData:shellTask->errorData_ encoding:NSUTF8StringEncoding];
> ExecutionResult* result = [ExecutionResult resultWithCmd:cmd args:args result:shellTask->result_ outStr:outStr errStr:errStr];
> result->theShellTask_ = shellTask;
> return result;
> }
>
>
> ------------------------------------
>
> The complete code is on bitbucket (MacHg is open source and I welcome contributions :) ) https://bitbucket.org/jfh/machg/src/cae197d03665/Classes/General/TaskExecutions.m
>
> If you are going the extra mile, building MacHg is quite simple. You need to (1) clone the repository to your local machine, (2) Double click the IB plugin MacHg/LinkedLibraries/BWToolkit/BWToolkit.ibplugin, (3) Compile and run. Note I have only tested MacHg with XCode 3.2 and not 4.0 yet. (See https://bitbucket.org/jfh/machg/wiki/Compiling.wiki) (If you are debugging this you might find it helpful to return directly from computeIncomingOutgoingToCompatibleRepositories so you don't see all the NSTask traffic to do with figuring out the incoming and outgoing statuses for the repositories.)
>
> So with all the debugging in place, when things fail, it looks like the task launches and then immediately exits. Eg here is a small transcript:
>
> BAD:
> --------
> 0x1014810/-[MacHgDocument initializeRepositoryData] Initializing log entry collection
> 0x1250100/+[ShellTask execute:withArgs:onTask:] launched localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/RhodeCode
> 0x1250100/-[ShellTask gotExit:] ...got Exit for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/RhodeCode ...
> 0x1250100/-[ShellTask gotError:] ...got NULL Error Output for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/RhodeCode ...
> 0x1250100/-[ShellTask waitTillFinished] ...waitTillFinished still waiting for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/RhodeCode ...
> 0x1250100/-[ShellTask finishUp] ...Finishing up for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/RhodeCode ...
>
> (Note how the first notification in the task which was received was the exit, then Null for the error was received, and then the task exited without ever sending anything for the output.) Normally this should be something like:
>
> GOOD:
> --------
> 0x1014810/-[MacHgDocument initializeRepositoryData] Initializing log entry collection
> 0x1250100/+[ShellTask execute:withArgs:onTask:] launched localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki
> 0x1250100/-[ShellTask gotOutput:] ...got Output for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki ...
> 0x1250100/-[ShellTask waitTillFinished] ...waitTillFinished still waiting for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki ...
> 0x1250100/-[ShellTask gotOutput:] ...got NULL standard Output for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki ...
> 0x1250100/-[ShellTask gotExit:] ...got Exit for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki ...
> 0x1250100/-[ShellTask waitTillFinished] ...waitTillFinished still waiting for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki ...
> 0x1250100/-[ShellTask gotError:] ...got NULL Error Output for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki ...
> 0x1250100/-[ShellTask finishUp] ...Finishing up for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki ...
> 0x1250100/-[ShellTask waitTillFinished] ...Exiting waitTillFinished for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki ...
> 0x1250100/+[ShellTask execute:withArgs:onTask:] Finished execute cmd for localhg combinedinfo --cwd /Volumes/QuickSilver/Development/sandbox/wiki
> 0x1014810/__-[RepositoryData loadCombinedInformationAndNotify:]_block_invoke_2 finished loadCombinedInformationAndNotify
>
> Now a couple things to note is that if the [self performSelector:@selector(finishUp) withObject:nil afterDelay:10.0] fires in the BAD case then the outer call to waitTillFinished just sort of vanishes, since there is always a DebugLog call which prints "...Exiting waitTillFinished for ..." but is can be seen in the BAD transcript this just isn't present.
>
> Here is a screen shot of the exception to do with concrete file problem. (In this case *** -[NSConcreteFileHandle availableData]: Bad file descriptor. In either the case BAD above or in the exception case if I step with a debugger up through the code then when it hits the __CFRunLoopRun at stack level 8 below then single stepping causes the debugger to act like I hit continue instead of step over and then it looks like its ignoring waitTillFinished and just sort of jumping out.
>
> <PastedGraphic-1.png>
>
>
> You only need a couple of repositories to show this problem. Eg if you create a new document in MacHg and then add say the following three test repositories to the document (You can clone them from within MacHg or the command line, it doesn't matter)
>
> https://time-tracker-mac.googlecode.com/hg/
> http://bitbucket.org/marcinkuzminski/rhodecode
> https://bitbucket.org/jfh/machg
>
> Then just click on one, then the next, then the third, then back to the first and pretty soon you will hit a case when the files don't update in the display. This happens because the NSTask just dropped the result / failed.
>
> I have experimented with lots of different variations, ie dropping the pending terminations, listing in different modes, keeping outPipe_, and errPipe_ as members just to ensure they can't possibly be collected, etc, etc. All to no avail. (I am happy to make a short screen capture movie of the behavior or make more screen shots but this email is already long enough...)
>
> If anybody can shed some light on anything which is going on here... Or at least avenues to explore I would be very grateful.... (And sorry for the long email...)
>
> Thanks,
> Jason_______________________________________________
>
> Cocoa-dev mailing list (email@hidden)
>
> Please do not post admin requests or moderator comments to the list.
> Contact the moderators at cocoa-dev-admins(at)lists.apple.com
>
> Help/Unsubscribe/Update your Subscription:
>
> This email sent to email@hidden
_______________________________________________
Cocoa-dev mailing list (email@hidden)
Please do not post admin requests or moderator comments to the list.
Contact the moderators at cocoa-dev-admins(at)lists.apple.com
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden