lachlann
10/16/2014 3:09:00 PM
I am having a very strange issue with the System.IO.File.Move operation. On subsequent moves i get an error "file is in use by another process" using process explorer it is my application that is holding the lock.
This is a .net service that is supposed to process files, at the start of the program it loads the list of files and then grabs the first X files and renames them to .pending. it is then supposed to transform these files and when finished moves them to an 'archive' folder. however if there is a problem with the transform or transforming and an exception is raised its supposed to rename the file to '.failed'. it is this piece that is failing.
When i attempt to rename the file from .pending -> .failed i get an error "file is in use by another process". originally this service was multi-threaded so i assumed it was a collision with other threads however upon further investigation i've made it single-threaded and it is still failing. it even happens when stepping through the code using the debugger (VS2010).
I've moved all "file" logic into 3 methods:
readfromfile
writetofile
movefile
in each of these 3 methods i've added 3 debugging lines:
1) Enter method
2) finish method (success) or exception
3) exit method
i record the timestamp, thread and details of the move.
If i deliberately point it at a bad transform the read/write methods are bypassed so the only method involving the filesystem is the "movefile" method.
the move method checks for file in use error and waits 1 second and retries 3x. interestingly when it gives up on the 3rd attempt i'm able to rename the file without issues using windows explorer however i am unable to delete the file unless the service is turned off.
i'm testing on a windows 7 (64-bit) machine with an NTFS filesystem.
here is the full code for the movefile method
private bool AttemptMoveFile(FileInfo OldFile, string NewName, int iRetries, string FileTypeName)
{
try
{
IOException FinalException = null;
FileInfo NewFile = new FileInfo(NewName);
alertError(System.Threading.Thread.CurrentThread.ManagedThreadId + "," + AppDomain.GetCurrentThreadId().ToString() + " " + DateTime.Now.ToString() + " Enter Move: " + OldFile.FullName + " --> " + NewName);
try
{
// attempt to recover 3 times
for (int i = 0; i < iRetries; i++)
{
try
{
if (OldFile.Exists)
{
if (!NewFile.Directory.Exists)
{
NewFile.Directory.Create();
}
try
{
if (NewFile.Exists)
{
alertError("WARNING! Overwriting new " + FileTypeName + " file: " + NewName + " with " + OldFile.FullName);
NewFile.Delete();
}
alertError("DEBUG! Moving File " + OldFile.FullName + "-->" + NewName);
//NewFile = null;
File.Move(OldFile.FullName, NewName);
//OldFile.MoveTo(NewName);
}
// if file doesn't exist, return failed to moved
catch (FileNotFoundException)
{
return false;
}
}
else
{
return false;
}
return true;
}
catch (PathTooLongException e)
{
PathTooLongException ex = new PathTooLongException("Source/Destination file path is too long, OldFile: " + OldFile + " (len=" + OldFile.Length.ToString() + "), NewFile: " + NewFile + " (len=" + NewFile.Length.ToString() + "). The fully qualified file name must be less than 260 characters, and the directory name must be less than 248 characters.", e);
ex.Data.Add("Action", "Move");
ex.Data.Add("NewFile", NewFile);
ex.Data.Add("OldFile", OldFile);
throw ex;
}
catch (IOException e)
{
if (IsFileInUseException(e))
{
e.Data.Add("Action", "Move");
e.Data.Add("NewFile", NewFile);
e.Data.Add("OldFile", OldFile);
FinalException = e;
// wait 1 second and try again
Pause(1000);
}
else
{
e.Data.Add("Action", "Move");
e.Data.Add("NewFile", NewFile);
e.Data.Add("OldFile", OldFile);
FinalException = e;
throw;
}
}
}
}
// ignore file not found errors
catch (FileNotFoundException)
{ }
if (FinalException != null)
{
if (IsFileInUseException(FinalException))
{
// do something
throw new IOException(sMessage, FinalException);
}
else
{
throw FinalException;
}
}
return false;
}
finally
{
alertError(System.Threading.Thread.CurrentThread.ManagedThreadId + "," + AppDomain.GetCurrentThreadId().ToString() +" "+DateTime.Now.ToString()+ " Exit Move: " + OldFile.FullName + " --> " + NewName);
}
}
here is the log excerpt, as you will see there are a few calls to the "write" method however they are the 'output' of the transform and to a completely different file. i've added comments prefixed by ** to help
2014_10_15_LNOSPUPDebug.log is the debug filename, the next # is the filename.
** first move xml -> pending
2014_10_15_LNOSPUPDebug.log 14491 * 21:19:01.5862608 [5-Timer] * 5,13328 10/15/2014 9:19:01 PM Enter Move: C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.xml --> C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending Move
2014_10_15_LNOSPUPDebug.log 14493 * 21:19:01.5882608 [5-Timer] * DEBUG! Moving File C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.xml-->C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending File
2014_10_15_LNOSPUPDebug.log 14495 * 21:19:01.5912608 [5-Timer] * 5,13328 10/15/2014 9:19:01 PM Exit Move: C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.xml --> C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending Move
** giving up due to bad config
2014_10_15_LNOSPUPDebug.log 14497 * 21:19:01.5982608 [5-Timer] * Failed to Load File before failure limit: C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending File
** writing a failure response to a DIFFERENT file
2014_10_15_LNOSPUPDebug.log 14499 * 21:19:01.5992608 [5-Timer] * 5,13328 10/15/2014 9:19:01 PM Enter Write: C:\LNOSDataFiles\BOLRouteImport\ARCH\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Response File
2014_10_15_LNOSPUPDebug.log 14501 * 21:19:01.6032608 [5-Timer] * 5,13328 10/15/2014 9:19:01 PM Finished Write: C:\LNOSDataFiles\BOLRouteImport\ARCH\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Response File
2014_10_15_LNOSPUPDebug.log 14503 * 21:19:01.6042608 [5-Timer] * 5,13328 10/15/2014 9:19:01 PM Exit Write: C:\LNOSDataFiles\BOLRouteImport\ARCH\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Response File
** recognition of the issue
2014_10_15_LNOSPUPDebug.log 14505 * 21:19:01.6062608 [5-Timer] * File failed to be processed: C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending, Response: Transform is configured but is invalid: C:\LNOSDataFiles\Transforms\WRtoRP_20140925_bad.xsl File
** attempt to "fail" the file, this is what fails
2014_10_15_LNOSPUPDebug.log 14507 * 21:19:01.6702608 [5-Timer] * 5,13328 10/15/2014 9:19:01 PM Enter Move: C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending --> C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.Failed Move
** try 3 times to rename
2014_10_15_LNOSPUPDebug.log 14509 * 21:19:01.6712608 [5-Timer] * DEBUG! Moving File C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending-->C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.Failed File
2014_10_15_LNOSPUPDebug.log 14511 * 21:19:02.6872608 [5-Timer] * DEBUG! Moving File C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending-->C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.Failed File
2014_10_15_LNOSPUPDebug.log 14513 * 21:19:03.7092608 [5-Timer] * DEBUG! Moving File C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending-->C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.Failed File
2014_10_15_LNOSPUPDebug.log 14515 * 21:19:23.5912608 [5-Timer] * 5,13328
** give up - (finally) logging
10/15/2014 9:19:23 PM Exit Move: C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending --> C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.Failed Move
** logging of the file in use exception from the 3 attempts
2014_10_15_LNOSPUPDebug.log 14517 * 21:19:23.5922608 [5-Timer] * Error! A final file could not be failed: C:\LNOSDataFiles\BOLRouteImport\IN\RP\ExportCaseTestAuditFailure-bad.BAT-L00704-141015211901585-5-PreProcess.Pending, System.IO.IOException ---> System.IO.IOException: The process cannot access the file because it is being used by another process. file
I've been fighting this for several weeks and I am completely stumped as to what could be happening.