Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Issue with MEMFS when the Cache Manager is used #96

Closed
FrKaram opened this Issue Jul 3, 2017 · 41 comments

Comments

Projects
None yet
3 participants
@FrKaram
Copy link
Contributor

commented Jul 3, 2017

Hi Bill,

I was having file corruption issues with PowerPoint files with my implementation and so I decided to check with memfs-dotnet to see how it behave.

Memfs-dotnet have the same problem.

I managed to find a reproductible procedure to hightlight this behavour (corruption does not open everytime ) :

1\ Download this document with which I do my tests : www.unm.edu/~unmvclib/powerpoint/pptexamples.ppt
2\ Copy this document to memfs-dotnet
3\ Open the document with PowerPoint
4\ Delete the picture on first slide
5\ Delete slide 3 (the pink one)
6\ Save and quit powerpoint
7\ Reopen the file

If it behaves like on my PC, you should have

image

I haven'd found yet what could be the cause of this corruption.

Any idea ?

Thanks

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 3, 2017

Unfortunately I do not own Powerpoint on Windows (only on macOS) so I cannot see this myself.

I have a few suggestions to try and further troubleshoot this:

  • By default memfs-dotnet and memfs limit file sizes to 16MB. Can you confirm that the powerpoint does not get bigger than this? [The downloaded file is only 1.8MB so I do not expect this to be the issue.]

  • Can you confirm that this does not happen with the powerpoint when run over NTFS?

  • Can you confirm whether it happens with plain memfs (i.e. the one written in C/C++)? This would help us determine whether this is a .NET layer issue or a general WinFsp issue.

  • Can you try running memfs with the -d -1 -D - switches to show debug log output while performing the above mentioned operations?

  • There is a batch file called diag.bat under \Program Files (x86)\WinFsp\bin. Can you run it and send me the log output?

  • Does this happen on multiple computers/VM's? Or just this one?

@fsgeek

This comment has been minimized.

Copy link

commented Jul 3, 2017

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 3, 2017

@fsgeek thank you.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 3, 2017

I try all that and keep you posted

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 4, 2017

  • By default memfs-dotnet and memfs limit file sizes to 16MB. Can you confirm that the powerpoint does not get bigger than this? [The downloaded file is only 1.8MB so I do not expect this to be the issue.]
    

-> The file is indeed 1.8MB and after the modification is shrinks to 1.3MB so it's not the 16MB limitation
-> BTW, where is this 16MB limit configured ?

  • Can you confirm that this does not happen with the powerpoint when run over NTFS?
    

-> Does not happen on NTFS

  • Can you confirm whether it happens with plain memfs (i.e. the one written in C/C++)? This would help us determine whether this is a .NET layer issue or a general WinFsp issue.
    

-> I reproduce with memfs-x64.exe

  • Can you try running memfs with the -d -1 -D - switches to show debug log output while performing the above mentioned operations?
    

-> See attached log.txt. While logging, I did the procedure twice. First time it worked correctly. I deleted the file. Copied a clean version. Did the procedure a second time and the file was corrupted.

  • There is a batch file called diag.bat under \Program Files (x86)\WinFsp\bin. Can you run it and send me the log output?
    

-> See attached diagresult.txt

  • Does this happen on multiple computers/VM's? Or just this one?
    

-> Happens on other computers

The problem does not occur with the -t 0 parameter. Could it be a cache issue ?
diagresult.txt
log.txt

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 4, 2017

@FrKaram thank you for your investigation on this.

BTW, where is this 16MB limit configured ?

You can configure it using the -s switch in memfs.

I reproduce with memfs-x64.exe

Ok. This means that this is a more general problem.

The problem does not occur with the -t 0 parameter. Could it be a cache issue ?

It sounds like it.

The -t option controls the value of FileInfoTimeout. The FileInfoTimeout is used as follows:

  • If FileInfoTimeout==0 the FSD does not do any caching at all. Almost all file system operations are passed to the user mode file system (which may do its own caching).

  • If FileInfoTimeout>0 && FileInfoTimeout!=(UINT32)-1 the FSD will cache file metadata information (for the specified time), but will not cache actual file data. The FSD does this by using its own caching mechanism and does not use the NTOS cache manager for this purpose. Many file system operations (e.g. GetFileInfo) are satisfied by the FSD and do not need to be sent to the user mode file system.

  • If FileInfoTimeout==-1 the FSD will cache file metadata and data information indefinitely (i.e. without timeout). It will use its own caching mechanism for file metadata and the NTOS cache manager for file data. Most file system operations can be satisfied from cache, for example GetFileInfo, Read and Write will be satisfied from cache.

Based on your investigation so far I understand the following:

  • The problem does not happen with -t 0 (FileInfoTimeout==0).

  • The problem does happen with -t -1 (FileInfoTimeout==-1).

  • Could you also try with -t 1000 (FileInfoTimeout==1000). This instructs the FSD to cache metadata for 1000 ms and would let us know which cache (metadata or data) exhibits the problem.

diagresult.txt
log.txt

Thank you for these. I will study the logs and see if there is something obvious (although if the problem is a caching issue, this will not necessarily show up on the logs).

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 4, 2017

@FrKaram can you please also let me know what version of Powerpoint you are using? I am looking into getting Powerpoint for Windows, but I would like to get the right version.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 4, 2017

I've just tested with -t 1000 and did not encounter any issue.

image

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 4, 2017

I've just tested with -t 1000 and did not encounter any issue.

This means that the issue is with WinFsp's use of the NTOS cache manager.

I will see if I can get Powerpoint 2016 and attempt to reproduce myself with -t -1.


Thank you for being so helpful. Some additional thoughts if you are feeling adventurous:

  • If you have DebugView from Sysinternals, you can run the file system with the -d -1 switch (without the -D - part. Debug log output will then go to DebugView. DebugView has the ability to add comments in your log (under Edit > Append Comment). This way you can provide some commentary along the lines of "deleting powerpoint slide x", "reopening powerpoint", etc.

  • Ladislav Zezula has created a fantastic program called FileSpy. FileSpy actually shows all file activity in the system at the IRP (I/O Request Packet) level. Unfortunately FileSpy does not have the ability to inject commentary like DebugView (AFAIK) so it would be harder to match file system operations to actual user level operations. [I usually incrementally save the log with descriptive names to get around that problem.] BTW, to capture a WinFsp volume you would need to select the device with name \Device\Volume{GUID} under the Volumes menu item.

Both apps need to be run with Administrator privileges.

These tools together let us analyze both what the FSD sees, but also what the DLL sees.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 4, 2017

I know both tools (reminds me of the time when I was working on a minifilter for filesystem monitoring).
I don't know if I will have time to check that but if so, I'll post here.

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 5, 2017

I am able to reproduce this issue after installing Powerpoint 2016 32-bit on Win10 Pro 64-bit.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 5, 2017

Let's hope this is not a twisted behaviour of Windows or Powerpoint

@FrKaram FrKaram closed this Jul 5, 2017

@FrKaram FrKaram reopened this Jul 5, 2017

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 5, 2017

I spent some time looking at this last night and trying to decipher what Powerpoint is doing through the logs.

It seems to be doing cached writes on a temporary file, which it flushes using FlushFileBuffers. It then renames the temporary file back to the original file name pptexamples.ppt. I do not have a good understanding yet on where this fails.

The pptexamples.ppt file uses COM structured storage.

I will also spend some time today trying to understand the problem.

@billziss-gh billziss-gh added the bug label Jul 5, 2017

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 5, 2017

Fyi I got the issue with other ppt files. The one I gave you the link to is the only one to be "clean". All others are corrupted and as they were foe testing, I do not have the originals anymore

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 5, 2017

@fsgeek I am wondering if you have any feedback on this question:

When CcSetFileSizes is used to extend the cache manager's view of the file size, does the cache manager guarantee that the cache mapping has the extended portion zeroed out or does the FSD always have to call CcZeroData?

I am thinking specifically about a scenario such as the following.

  • A cache mapping starts out as 2MB in size.
  • It gets written across the whole 2MB range.
  • It then gets pulled back to 1MB.
  • Finally it is re-extended to 2MB.

My expectation has been that CcSetFileSizes is sufficient to zero out the (re-)extended portion of the mapping and that the mapping now has zeroes from 1MB to 2MB. This is without calling CcZeroData, which I have understood to be used to force WRITE of zero pages to disk.

WinFsp does not call CcZeroData and does not use ValidDataLength. The assumption has been that these were optimizations that a user mode file system could perform on its own and that CcSetFileSizes was intelligent enough to zero out cache mapping extensions. If that is not the case, I am unclear on how WinFsp passes FSX testing.

@fsgeek

This comment has been minimized.

Copy link

commented Jul 5, 2017

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 5, 2017

I'm assuming that you are using MAXLONGLONG as the VDL, in which case Cc
just leaves the problem to you.

This is correct. WinFsp uses MAXLONGLONG as the VDL.

I am handling cached writes roughly as follows:

  • If (and only if) the WRITE extends the file I first send (recursively) a SET_INFORMATION [EndOfFile] IRP to the FSD. The EndOfFile handler forwards the IRP to the user mode file system, which updates its own view of the EndOfFile.

  • The user mode file system is now responsible to return zeroes from the old EndOfFile to the newly updated one on READ's; it may do so by implementing the ValidDataLength optimization.

  • On completion of the SET_INFORMATION [EndOfFile] IRP I also extend the cache mapping using CcSetFileSizes with the new EndOfFile / FileSize.

  • Back in the cached WRITE I do the necessary CcCopyWrite, etc.

Nowhere in this process I call CcZeroData. The assumption has always been that CcSetFileSizes will always zero out any extended portions of a cache mapping. If that is not the case I may have to call CcZeroData and somehow avoid sending the recursive zeroed pageWRITE's to the user mode file system.

I suspect you've seen Malcolm's piece on this as well
https://www.osr.com/nt-insider/2015-issue2/maintaining-valid-data-length

I have seen it, but must admit that it is mostly above my pay grade :)

The Cache Manager optimization is used by NTFS but is optional for other
file systems. A file system may indicate that the Cache Manager should not
attempt to track valid data by using the special value of MAXLONGLONG as
the valid data length in a CcSetFileSizes call. Having done so, the file
system must take care to update valid data on disk in response to all
paging writes.

My understanding is that the protocol outlined above should work correctly. I may be wrong of course.

The IFS Kit syscache test is quite good at finding these issues in my experience.

Thanks. I am already using ifstest for testing. I will look into using syscache as well.

@fsgeek

This comment has been minimized.

Copy link

commented Jul 5, 2017

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 5, 2017

The problem with having the issue in Powerpoint is that it makes it
difficult to do any sort of simple analysis.

I agree. My approach so far has been to try simple scenarios within Powerpoint and observe the results in FileSpy. Of course just saving a file produces reams of data and it is very hard to know what fails. What's worse if I choose to "repair" the corrupted Powerpoint file it is always repaired successfully, even if I move the file to a different system. Which begs the question: what exactly does Powerpoint not like about the modified file?

The CcSetFileSizes thing was just a wild hunch based on a pattern that I saw during saving. It likely has nothing to do with the actual problem.

Thank you for your insights.


EDIT

I may be wrong, but my recollection is that once you turn off VDL tracking
the Cache Manager has no way to know what the filling policy should be
(thus, it should be faulting in any partial pages that get overwritten).

Doh!

Actually in re-reading your message I realize that you explained to me what happens. The Cache Manager does not know what to do and it faults on partial pages; this results in paging READ's being sent to the FSD (which are then sent to the user mode file system). Therefore there should not be any issue with CcSetFileSizes extending file size.

What you want to look for is
some sort of unusual pattern of access, whether it is open, move EOF,
close, reopen, etc. You did note that it happens after a rename. Is it
possible there is an operation on the pre-rename version (such as an EOF
move and then close) that creates some added complexity with an
intermediate rename.

I did think about that earlier today, so I ended up dumping the file prior to rename onto a file on NTFS. I found out that the dumped file was already corrupted prior to rename.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 6, 2017

Fyi, sometimes the repair fails and the file is totally unreadable. Sometimes it succeeds and the 3 first slides are empty ...
At least that's what's I've noticed on my pc.
It seems to me that it is the fact of changing the beginning of the file (slide 1) + the middle of it (slide 4) that cause the issue

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 6, 2017

@FrKaram I have not seen the repair fail, but your observation does point to a deeper problem. I will continue investigating this although it is not straightforward to solve, because we do not have an easy to understand repro.

There are a couple of things that I want to try in the hopes that they will resolve the issue. But I cannot promise a quick resolution unless we somehow gain a better understanding.

In the meantime please run your file system with a FileInfoTimeout value such as 1000 to disable the cache manager.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 6, 2017

Yeah, I guess nothing is simple at this level of complexity.
I'll test with t 1000. I think it will have consequences in the way the methods are called but I will adapt accordingly
Thanks for your efforts

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 6, 2017

The only thing that should change with FileInfoTimeout==1000 is that you will be getting more Read and Write calls.

BTW, I consider this bug critical and will continue working on it until we have it resolved.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 6, 2017

If I can be of any help, do not hesitate to ask

@billziss-gh billziss-gh added the critical label Jul 6, 2017

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 7, 2017

Experiments

I spent a few hours today experimenting with largely discouraging results. I tried the following experiments:

At this point I was fairly discouraged, but I decided to try the CcZeroData experiment with Wait==FALSE this time. This resolved the IRP_MJ_READ deadlock and passed the WinFsp tests.

More importantly experimentation with Powerpoint has shown marked improvements:

  • Modifying the pptexamples.ppt file, saving it, and then quitting Powerpoint now works. I can reliably reopen the file without the need to repair. [Previously this scenario would never work for me.]

  • Modifying the pptexamples.ppt file, quitting Powerpoint and then saving the file when the save dialog box pops up, results in a corrupted file (same as before).

While this is not the solution to this problem, I consider it a significant step forward. It appears that the problem may be related to CcZeroData after all.

Working Theory

My working theory is that under circumstances yet to be identified the cache mapping contains stale data after a file/cache extension. For example, if the file was 2MB, then pulled back to 1MB and then re-extended to 2MB, the cache may contain stale data.

I will attempt to improve my CcZeroData experiment so that I can reliably call it with Wait==TRUE and have it fully zero out the portion of the cache that is being extended. I have already built a mechanism so that CcZeroData writes are ignored by the IRP_MJ_WRITE handler (because they are useless and in fact counter-productive in the WinFsp API design).

@fsgeek

This comment has been minimized.

Copy link

commented Jul 7, 2017

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 7, 2017

Do you call CcSetFileSizes in the truncate path? If not, Cc likely wouldn't know the file has shrunk. This is consistent with your hypothesis.

Yes, I call CcSetFileSizes whenever the file size changes (at least I think I do). This includes truncations and extensions.

My theory is that the Cache Manager may sometimes have stale data when a file gets truncated to a partial page size and then re-extended. For example, from 2MiB down to 1MiB + 900 bytes and back to 2MiB. I have no solid data to back this theory up. The only reason that I am interested in this pattern is that I believe I have seen a similar pattern in the FileSpy logs.

My intent is to try the following experiment: After extending the cache with CcSetFileSizes I will execute up to 3 CcZeroData calls:

  • One CcZeroData call with Wait==FALSE iff the old FileSize was not on a page boundary. This will be from the old FileSize to the next page boundary.

  • One CcZeroData call with Wait==TRUE from the page boundary immediately after the old FileSize to the page boundary immediately before the new FileSize. I have modified my IRP_MJ_WRITE handler to detect such writes and no-op them.

  • One CcZeroData call with Wait==FALSE iff the new FileSize is not on a page boundary. This will be from the last page boundary to the new FileSize.

The reason for (up to) 3 CcZeroData calls is to avoid recursive IRP_MJ_READ's, but still zero-out the whole extended portion of the cache.

This does sound convoluted, but if it works I can at least use that as a basis to understand the problem further.

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 7, 2017

@FrKaram have you ever been able to reproduce this on Win8? I am only able to reproduce it on Win10, but not Win8.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 8, 2017

@billziss-gh I haven't tried win8. I need to build a VM to test it

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 8, 2017

@FrKaram no need to build a new VM if you have not already done so. I just wanted to confirm my finding that this cannot be reproduced on Win8. Every little clue is significant in figuring this one out.

Unfortunately my earlier experiments did not yield any real results. Until we find an easier to understand repro we may be unable to resolve this.

@billziss-gh billziss-gh changed the title Issue with memfs-dotnet Issue with memfs-dotnet when the Cache Manager is used Jul 8, 2017

@billziss-gh billziss-gh changed the title Issue with memfs-dotnet when the Cache Manager is used Issue with memfs when the Cache Manager is used Jul 8, 2017

@billziss-gh billziss-gh changed the title Issue with memfs when the Cache Manager is used Issue with MEMFS when the Cache Manager is used Jul 8, 2017

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 8, 2017

I may have a win8 or winserver 2012 at work. I'll have a look if so.

With the procedure described in my first post, the issue occur almost everytime. I could do a Powerpoint interop based program that reproduce the problem, if needed

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 8, 2017

I could do a Powerpoint interop based program that reproduce the problem, if needed

Actually something like that would be very useful. It would be great if we had a "real world" test suite, that does things like drive Office apps in scenarios like this one.

Your interop program could serve as the basis for that.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 10, 2017

I've been working on a quick program but, as you said, this thing is quite difficult to track.
I've not been able yet to reproduce a procedure that fails at each run.

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 12, 2017

I believe I may have resolved this with commits b35bf20 and 637f461.

FSX Experiments

After some fruitless experimentation last week I set out this week to break WinFsp/MEMFS using FSX. While I was unable to do so at first I eventually found that if the file written by FSX was also opened by a second process (e.g. Explorer) sometimes FSX would complain about the file having the wrong size.

I was eventually able to create a test scenario that would always fail within a few seconds of starting FSX. Using the FSX logs, together with FileSpy and WinFsp logs I was able to identify a subtle race condition which I describe below.

Race Condition

In the WinFsp API after (some) file system operations complete the user mode file system communicates to the FSD the most recent metadata of the file that was operated upon. This information is communicated via the FileInfo data structure that many of the FSP_FILE_SYSTEM_INTERFACE operations return. It is important for the FSD and the user mode file system to maintain a consistent view of file metadata, especially when caching is enabled.

Consider the following scenario: a file is open and being appended to. The appends appear as WRITE IRP's and they are all synchronized by locking the FileNode. Part of the WRITE protocol involves returning an updated FileInfo for the written FileNode, which the FSD uses to update its view of the file metadata.

Now consider that another OPEN comes in for the same file. Because the FSD does not know yet which FileNode will be opened it does not lock any FileNode. [Note that the FSD maintains an internal FileNode table and it is possible to uniquely identify a FileNode by FileName and lock it; however this will no longer be the case when we implement hard links so it is not done today either.] The FSD posts the OPEN request to the user mode file system. The user mode file system processes the OPEN request successfully and responds with the opened file and its FileInfo.

Prior to the FSD processing the OPEN response additional WRITE IRP's come through the original file handle. These WRITE's update the FileSize as understood by the user mode file system and the corresponding (more recent) FileInfo's get reported back to the FSD. Eventually the delayed OPEN response gets processed, which now clobbers the FileInfo as understood by the FSD with stale metadata.

The problem here is that OPEN requests have no way of locking the FileNode while the OPEN request is in transit to the user mode file system. In all other cases the user mode file system and the FSD update their view of the file's metadata (together) in an atomic fashion. Not so in the case of OPEN.

This is a subtle race condition, because the FileNode contains valid information, but that information is out of date with respect to what the user mode file system thinks even if only momentarily. In the case of FSX this creates a problem because FSX double-checks file metadata after its operations are complete and complains if they are not as expected.

The Fix

My current fix is simple: do not update file metadata during an OPEN if the file was already open.

This seems to resolve the FSX issue. It also seems to resolve the Powerpoint issue, as I have not been able to reproduce the "repair" problem since introducing this change. It should be noted here that I am not 100% certain that the above race condition is the original cause of our Powerpoint problems.


@FrKaram would you be able to test a build that has this fix and verify whether this fixes the problem for you?

UPDATE: Build v1.1.17192 is now available for download.

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 12, 2017

@FrKaram

I've been working on a quick program but, as you said, this thing is quite difficult to track.
I've not been able yet to reproduce a procedure that fails at each run.

If you still have that interop program, you may be able to get somewhere by constantly doing GetFileAttributes on the pptexamples.ppt file in a separate thread. My earlier message (where I believe I have a fix for this issue) explains why.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 12, 2017

@billziss-gh Seems fine to me ! I wasn't able to reproduce the problem with the new build.

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 12, 2017

Fantastic. It looks like we can close this.

I will try to get a new build with this fix out before the end of July. Unfortunately producing the full build requires me to run the HLK tests in Server 2016 and that is an involved (and boring) process. I also have some other matters to attend to that I neglected while I was bug hunting on this issue.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 12, 2017

Yeah, I guess that was not an easy issue to solve
As for myself, I'm not in a hurry, holidays are coming :-)

I will certainly have more questions coming regarding the use of WinFSP. Should I open an issue for them or should I use another way ?

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 12, 2017

Feel free to open additional issues. Or you could use the google group here. I monitor both, so whatever is more convenient for you.

@FrKaram

This comment has been minimized.

Copy link
Contributor Author

commented Jul 12, 2017

I must be the only one not having a Google account, so I may post here.
Anyway, congrats for solving this !

@billziss-gh

This comment has been minimized.

Copy link
Owner

commented Jul 12, 2017

No problem. GitHub issues works as well.

Anyway, congrats for solving this !

Thank you.

Closing this. Please reopen if the problem resurfaces.

@billziss-gh billziss-gh added this to the v1.2 milestone Oct 20, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.