Occasionally creating a directory will fail

[pollylm]

Environment

• Windows version: Windows 10
• Processor architecture: x64
• Dokany version: 1.3.0.1000
• Library type (Dokany/FUSE): Dokany

Check List

• I checked my issue doesn't exist yet
• My issue is valid with mirror default sample and not specific to my user-mode driver implementation
• I can always reproduce the issue with the provided description below.
• I have updated Dokany to the latest version and have reboot my computer after.
• I tested one of the last snapshot from appveyor CI

Description

When mounted as a network drive, if you repeatedly create and delete a directory then it will eventually fail. It can take anywhere from 5 to 800 times to fail. This never occurs when mounting as a normal drive (have tested up to 10,000 iterations).

As far as I can see, problems begin after the account name starts to print as 'SYSTEM'. For some reason when mounted as a network drive it there appears to be two different access tokens in use, though I have no idea why. When mounted as a regular drive the account name is never 'SYSTEM'.

I mounted the network drive with the options:

mirror.exe /s /d /n /t 1 /r

Logs

Single threaded log
dokan only minimal test single thread.log

Multi-threaded log
dokan only minimal test.log

I have attached the logs for multi-threaded run as well as it had a strange behaviour where two processes took the same handle (0133). I'm not sure if that would have caused any problems. I don't think it would affect my current issue though as it still failed as a single-threaded application

[pollylm]

Hi all.

My assertion was wrong in the original post, this is an issue that affects all versions (since at least 1.0.5) regardless of how the volume is mounted.
It is just a lot more regular in 1.3.0.1000 when mounted as a network drive.

I ran several versions of dokany 3 times to check how many times of recreating a directory it would take before the mkdir call failed;

1.0.5.1000 network drive: 7538, 191430, 180839
1.0.5.1000 regular drive: 504957, 83225, 102414

1.1.0 network drive: 8876, 133077, 132777
1.1.0 regular drive: 155701, 128160, 4265

1.2.2.1000 network drive: 208233, 340988, 772136
1.2.2.1000 regular drive: 18055, 410294, 432345

1.3.0.1000 network drive: 661, 633, 685
1.3.0.1000 regular drive: 128144, 804424, 118907

In the past it would take a very high number of runs to fail. It seems like something has changed in the newer version to make it a more regular occurrence.

I'm currently working on getting logs for the older versions of dokany but they are taking much longer to reproduce. It could be a few days before I have them ready for you.

[pollylm]

Sorry for the slow reply. I have not been able to get the appropriate debug logs because the task is refusing the fail in debug mode on the old builds. It seems that only mounting as a network drive in 1.3.0.1000 is regular enough to allow me to collect debug logs.

Let me know if there is anything I can do to help with this issue, but at the moment I have no idea of where to start looking in the code

[Liryna]

Hi @pollylm ,

Thank you for your report.
I haven't seen the behavior you are describing. Yes logs are needed here. It could be different applications.
Could you point at which moment in the single thread log you had the error ?
For the multi-thread, if a process opens the folder when the delete is/will call, it may fail the delete depending on the sharing requested during the createfile.

[pollylm]

The point of failure in the single thread log appears to be

###Create 0046
CreateFile : C:\Users\matrixstore\Desktop\dokan\folder
AccountName: matrixstore, DomainName: matrixstore-PC
ShareMode = 0x7
FILE_SHARE_READ
FILE_SHARE_WRITE
FILE_SHARE_DELETE
DesiredAccess = 0x80
FILE_READ_ATTRIBUTES
FlagsAndAttributes = 0x200000
FILE_FLAG_OPEN_REPARSE_POINT
OPEN_EXISTING
error code = 2

All following handles report the same error code. However, this error has been reported and overcome in previous parts of the logs so I'm not sure what makes this section different

I'm still wondering if it is to do with the fact that we start reporting 'AccountName: SYSTEM, DomainName: NT AUTHORITY' at handle 39. I'm not confident about that but I can't see what else has changed.

I'm trying again to get debug logs for 1.3.0.1000 regular mount but so far no failure whilst debugging. Hopefully that will change soon.

I am running these tests by mounting the mirror class, then run a java class that repeatedly makes and deletes a folder on the mount. I can't upload the java file, but the code I'm running is

import java.io.File;
public class MkdirTest {

	public static void main(String[] args) {
		MkdirTest test = new MkdirTest();
		test.mkdirTest();
	}

	private void mkdirTest() {
		try {
			File f = new File("M:\\folder");
			for(int i=0; i<1000000; i++) {
				f.mkdir();
				if (!f.exists())
					throw new RuntimeException("Failed to create folder. Iteration " + i);
				f.delete();
				if (f.exists())
					throw new RuntimeException("Failed to delete folder. Iteration " + i);
			}
		} catch (Exception e) {
			System.out.println(e.getMessage());
		}
	}
}

Mount mirror: mirror.exe /s /d /n /t 1 /r C:\Users\matrixstore\Desktop\dokan /l m
Build java file: javac MkdirTest.java
Run java file: java MkdirTest

[Liryna]

The status of 0046 is file not found as expected since ###Cleanup 0045 was the operation to remove it.
You can use procmon to look at logs with a release version.

[Liryna]

@pollylm have you been able to get more info on this ?

[pollylm]

I have found a consistent pattern;
On the times that we receive the expected 'NAME_NOT_FOUND' status, a call has just been made by Explorer.EXE for operation 'NotifyChangeDirectory'.
On the times that we receive the problematic 'ACCESS_DENIED' this call is not made.

This pattern has been consistent across multiple tests. I have no idea why the explorer process sometimes does not send this notification however.
It also raises the question if this is actually a problem with Dokan or Windows. Is it necessary for Dokan to depend on that notification?