2
(a similar question has been asked by me before - this question relates to the same application, but a different - but probably related - problem)
I have an application that regularly writes records to a data file. The file is opened, updated, and closed each time. This same instance of the application also reads from the file.
Elsewhere on the network, there are several "slave" instances of the same application running that only read from the same data file across the network.
Occasionally (the occasions are days, sometimes weeks apart), the file access fails with an access denied error on all machines, and at the same instant, except that sometimes it fails on all machines apart from one of the slaves. The file can't be written to or read from. Usually all the PC's apart from one fail in the same fashion - "access denied" error code 5 - but sometimes one of the slaves can still continue to access the file.
Inspection of the system with utilities that tell who has a file open (LockHunter
, SysInternal's Handle
utility) tells us little - on the PC that writes to the file, they find the System
process has the handle, presumably because the application that has the file open opened it via a network share, the Slave that can still write to the file shows the handle as unlocked, and with the other slaves neither utility reports anything.
When we have been troubleshooting the system we have used NotePad
to quickly test if the file is unlocked. Notepad always reports that it can't open the file because another application has the file open - except for one of the slave machines, and not always the same one. When we open the file with NotePad
on that PC, it opens without complaint, and at the same instant, the file unlocks - all the other PCs can read and write to the file from then on (although things appear to function OK from then on, I'm not convinced that the file system hasn't been damaged in some way).
The following is a log obtained by ProcMon
of the slave file system operations over the period that Notepad
is used to "unstick" the file. The file APP.ZZZ
is read every second, corresponding to each group of 5 accesses from App.exe
... accesses from the remote machine
1:08:59.5706074 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:08:59.7993871 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:08:59.8081861 p.m. App.exe 6276 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: n/a, OpenResult: Opened"
1:08:59.8083675 p.m. App.exe 6276 QueryBasicInformationFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "CreationTime: 17/11/2014 5:46:01 p.m., LastAccessTime: 23/09/2015 4:00:01 a.m., LastWriteTime: 23/09/2015 11:53:21 a.m., ChangeTime: 23/09/2015 11:53:21 a.m., FileAttributes: ANCI"
1:08:59.8083874 p.m. App.exe 6276 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
1:09:00.5663175 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:00.7611667 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:00.7669819 p.m. App.exe 6276 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: n/a, OpenResult: Opened"
1:09:00.7671534 p.m. App.exe 6276 QueryBasicInformationFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "CreationTime: 17/11/2014 5:46:01 p.m., LastAccessTime: 23/09/2015 4:00:01 a.m., LastWriteTime: 23/09/2015 11:53:21 a.m., ChangeTime: 23/09/2015 11:53:21 a.m., FileAttributes: ANCI"
1:09:00.7671720 p.m. App.exe 6276 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
1:09:01.5654203 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
... NOTEPAD starts and opens the file
1:09:01.7112007 p.m. NOTEPAD.EXE 4508 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:01.7187932 p.m. NOTEPAD.EXE 4508 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
1:09:01.7233678 p.m. NOTEPAD.EXE 4508 QueryInformationVolume \\REMOTE\App\Datafiles\APP.ZZZ BUFFER OVERFLOW "VolumeCreationTime: 13/02/2014 11:58:47 a.m., VolumeSerialNumber: 6060-4BB9, SupportsObjects: True, VolumeLabel: Win?"
1:09:01.7248358 p.m. NOTEPAD.EXE 4508 QueryAllInformationFile \\REMOTE\App\Datafiles\APP.ZZZ BUFFER OVERFLOW "CreationTime: 17/11/2014 5:46:01 p.m., LastAccessTime: 23/09/2015 4:00:01 a.m., LastWriteTime: 23/09/2015 11:53:21 a.m., ChangeTime: 23/09/2015 11:53:21 a.m., FileAttributes: ANCI, AllocationSize: 692,224, EndOfFile: 691,600, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1000000000bdb5, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte"
1:09:01.7407505 p.m. NOTEPAD.EXE 4508 CreateFileMapping \\REMOTE\App\Datafiles\APP.ZZZ FILE LOCKED WITH WRITERS "SyncType: SyncTypeCreateSection, PageProtection: "
1:09:01.7407840 p.m. NOTEPAD.EXE 4508 QueryStandardInformationFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "AllocationSize: 692,224, EndOfFile: 691,600, NumberOfLinks: 1, DeletePending: False, Directory: False"
1:09:01.7408038 p.m. NOTEPAD.EXE 4508 CreateFileMapping \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS SyncType: SyncTypeOther
1:09:01.7408244 p.m. NOTEPAD.EXE 4508 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
1:09:01.7408578 p.m. NOTEPAD.EXE 4508 ReadFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Offset: 0, Length: 32,768, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
1:09:01.7459986 p.m. NOTEPAD.EXE 4508 ReadFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Offset: 32,768, Length: 32,768, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
1:09:01.7502571 p.m. NOTEPAD.EXE 4508 ReadFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Offset: 65,536, Length: 65,536, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
1:09:01.7567997 p.m. NOTEPAD.EXE 4508 ReadFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Offset: 131,072, Length: 131,072, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
1:09:01.7759753 p.m. NOTEPAD.EXE 4508 ReadFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Offset: 262,144, Length: 262,144, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
1:09:01.7995374 p.m. NOTEPAD.EXE 4508 ReadFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Offset: 524,288, Length: 167,312, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
1:09:01.8194679 p.m. NOTEPAD.EXE 4508 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:01.8228119 p.m. NOTEPAD.EXE 4508 RegQueryValue HKLM\SOFTWARE\MICROSOFT\Windows\CurrentVersion\Explorer\KindMap\.ZZZ NAME NOT FOUND Length: 144
.... NOTEPAD does a whole bunch of registry stuff
1:09:01.8245487 p.m. NOTEPAD.EXE 4508 RegCloseKey HKCU\Software\Classes\.ZZZ SUCCESS
... accesses from the remote machine again. File is now unstuck.
1:09:01.9170334 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:01.9249583 p.m. App.exe 6276 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: n/a, OpenResult: Opened"
1:09:01.9287995 p.m. App.exe 6276 QueryBasicInformationFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "CreationTime: 17/11/2014 5:46:01 p.m., LastAccessTime: 23/09/2015 4:00:01 a.m., LastWriteTime: 23/09/2015 11:53:21 a.m., ChangeTime: 23/09/2015 11:53:21 a.m., FileAttributes: ANCI"
1:09:01.9288154 p.m. App.exe 6276 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
1:09:02.5679077 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:02.8324048 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:02.8813660 p.m. App.exe 6276 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: n/a, OpenResult: Opened"
1:09:02.8924965 p.m. App.exe 6276 QueryBasicInformationFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "CreationTime: 17/11/2014 5:46:01 p.m., LastAccessTime: 23/09/2015 4:00:01 a.m., LastWriteTime: 23/09/2015 1:09:02 p.m., ChangeTime: 23/09/2015 1:09:02 p.m., FileAttributes: ANCI"
1:09:02.8925206 p.m. App.exe 6276 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
1:09:03.5661778 p.m. App.exe 6276 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
1:09:03.5749668 p.m. App.exe 6276 ReadFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Offset: 630,252, Length: 61,376, Priority: Normal"
1:09:03.5750069 p.m. App.exe 6276 ReadFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Offset: 626,688, Length: 64,940, I/O Flags: Non-cached, Paging I/O, Priority: Normal"
1:09:03.5820100 p.m. App.exe 6276 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
1:09:03.5862665 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:03.7772397 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:03.7848388 p.m. App.exe 6276 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: n/a, OpenResult: Opened"
1:09:03.7880212 p.m. App.exe 6276 QueryBasicInformationFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "CreationTime: 17/11/2014 5:46:01 p.m., LastAccessTime: 23/09/2015 4:00:01 a.m., LastWriteTime: 23/09/2015 1:09:02 p.m., ChangeTime: 23/09/2015 1:09:02 p.m., FileAttributes: ANCI"
1:09:03.7880374 p.m. App.exe 6276 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
1:09:04.5695737 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:04.7597043 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:04.7653450 p.m. App.exe 6276 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: n/a, OpenResult: Opened"
1:09:04.7711026 p.m. App.exe 6276 QueryBasicInformationFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "CreationTime: 17/11/2014 5:46:01 p.m., LastAccessTime: 23/09/2015 4:00:01 a.m., LastWriteTime: 23/09/2015 1:09:04 p.m., ChangeTime: 23/09/2015 1:09:04 p.m., FileAttributes: ANCI"
1:09:04.7711189 p.m. App.exe 6276 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
1:09:05.5674975 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:05.7744582 p.m. App.exe 6276 QueryDirectory \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Filter: APP.ZZZ, 1: APP.ZZZ"
1:09:05.7818819 p.m. App.exe 6276 CreateFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: n/a, OpenResult: Opened"
1:09:05.7898488 p.m. App.exe 6276 QueryBasicInformationFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS "CreationTime: 17/11/2014 5:46:01 p.m., LastAccessTime: 23/09/2015 4:00:01 a.m., LastWriteTime: 23/09/2015 1:09:04 p.m., ChangeTime: 23/09/2015 1:09:04 p.m., FileAttributes: ANCI"
1:09:05.7898647 p.m. App.exe 6276 CloseFile \\REMOTE\App\Datafiles\APP.ZZZ SUCCESS
I'm trying to determine what is putting the datafile in this state. I remember seeing a reference to problems if an exception occurs when a network file is closed. Could this problem point to something of that nature? I'm hoping that someone may be able to offer some insight as to what might be happening.
The application is written in Delphi 2007 (32-bit).
Openfiles appears to require elevated privileges, at least it does on my Windows 7 desktop here. I recommend opening the command prompt via "Run as Administrator" – dgnuff – 2017-06-27T02:15:39.060