File.close() not releasing file immediately?

[Flemoz]

Hi

I've come across a scenario that has proven to be a little tricky. Basically, we have multiple threads appending to a log file. We make sure to open and close the file for every append action, but sometimes a thread is still rejected due to STATUS_SHARING_VIOLATION error (we are opening the file for exclusive access), which seems to be due to the file not having been closed yet when the thread is trying to access it. So it looks like File.close() doesn't actually release the file immediately or at least it doesn't wait until it has been released? Is this expected behaviour? If we Thread.sleep after closing the file handle for enough time, we avoid the errors altogether.

Here's the source code:

public File getFileForReadWriteAccess(String pathToFile) throws IOException {
    if (session.getConnection().isConnected() && share.isConnected()) {
        File file = share.openFile(
                pathToFile,
                new HashSet<>(EnumSet.of(AccessMask.GENERIC_WRITE, AccessMask.GENERIC_READ)),
                null,
                new HashSet<>(), // empty set to get exclusive access,
                SMB2CreateDisposition.FILE_OPEN_IF,
                Collections.singleton(SMB2CreateOptions.FILE_NON_DIRECTORY_FILE));
        return file;
    } else {
        logger.info("Connection to share is closed, trying to reconnect and retry getFileForReadWriteAccess operation...");
        connectClientToShare();
        return getFileForReadWriteAccess(pathToFile);
    }
}

public synchronized void appendStringToFile(String contents, String path, String filename) throws IOException {
    try (File file = getFileForReadWriteAccess(path + filename)) {
        long fileOffset = file.getFileInformation().getStandardInformation().getEndOfFile();
        file.write(contents.getBytes("UTF-8"), fileOffset, 0, contents.length());
    }
    // if I sleep the thread for enough time here, it will avoid the STATUS_SHARING_VIOLATION errors
}

[neoxpert]

In two years of using smbj on different storages I have never observed such a behavior. If close is called to a file handle immediately get's closed by the server. Even with multiple reconnects to the same file / share in multithreaded contexts.

Judging by the small excerpt of code this could also be a problem with connection leaks due to insufficient resource handling. How are session connections and share connections managed - do they explicitly get closed if anything happens or do they idle in the backround until they time out? Have you tried to manually write the contents using a an outputstream to rule out eventual problems in the write method?

[Flemoz]

Connections are kept alive by sending echoes every 10 minutes. I don't think the issue would lie herein, as I do the tests as soon as I start up the application and it connects to the share. I also tried writing using the OutputStream, but I still occasionally see the STATUS_SHARING_VIOLATION errors.

public synchronized void appendStringToFile(String contents, String path, String filename) throws IOException {
    try (File file = getFileForReadWriteAccess(path + filename)) {
        //long fileOffset = file.getFileInformation().getStandardInformation().getEndOfFile();
        //file.write(contents.getBytes("UTF-8"), fileOffset, 0, contents.length());
        try (OutputStream out = file.getOutputStream()) {
            out.write(contents.getBytes("UTF-8"), 0, contents.length());
        }
    }
}

Needless to say, this issue is more likely to happen when trying to log entries in quick succession. Here is a stack trace of the error if it helps:

com.hierynomus.mssmb2.SMBApiException: STATUS_SHARING_VIOLATION (0xc0000043): Create failed for test.csv
    at com.hierynomus.smbj.share.Share.receive (Share.java:371)
    at com.hierynomus.smbj.share.Share.sendReceive (Share.java:351)
    at com.hierynomus.smbj.share.Share.createFile (Share.java:159)
    at com.hierynomus.smbj.share.DiskShare.createFileAndResolve (DiskShare.java:97)
    at com.hierynomus.smbj.share.DiskShare.resolveAndCreateFile (DiskShare.java:79)
    at com.hierynomus.smbj.share.DiskShare.open (DiskShare.java:66)
    at com.hierynomus.smbj.share.DiskShare.openFile (DiskShare.java:148)
    at smb.SMBService.getFileForReadWriteAccess (SMBService.java:111)
    at smb.SMBService.appendStringToFile (SMBService.java:167)
    at lambda$logCustomer$2 (LogService.java:175)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:617)
    at java.lang.Thread.run (Thread.java:745)

[neoxpert]

After some tests on different storages I was able to get some similar exceptions on a FreeNAS storage version 10.x running on a somewhat small VM, but I was not yet able to narrow it down to a good reproducable behavior :-/.

[Flemoz]

Yes, as mentioned I am only able to reproduce it by continuously sending a lot of simultaneous log requests thus performing many open and close operations in a small time frame and even then, the error is not guaranteed to happen. For now, I'm suppressing it by catching the STATUS_SHARING_VIOLATION error and retrying the request later so as to not lose any logs. Either way, thank you neoexpert for having a look :)

[hierynomus]

Closing this issue as it seems solved, and a server problem, rather than a client.