Watchman: [Windows] Watchman "forgets" about watched projects

[benpeart]

I've been experiencing this randomly for some time but finally think I may have some more information that can help narrow it down. I've found that while I'm running the git test suite (via 'prove -j12 --state=all ./t[0-9]*.sh') in the test subdirectory below the directory I'm watching, watchman will "forget" it was supposed to be watching that directory and remove it from the list.

The test suite clearly generates lots of file IO but I'm not sure why that is causing Watchman to remove the project from the list it is watching. While the test suite is running, it happens almost immediately and 100% of the time.

The command sequence below demonstrates what happens when the test suite is running in another window. Note the "unable to resolve root C:/git-sdk-64/usr/src/git: directory C:/git-sdk-64/usr/src/git is not watched" error.

Ben@BenPeart-HP MINGW64 /usr/src/git (git.git/fsmonitor-V1)
$ watchman watch-list
{
    "version": "4.9.0",
    "roots": [
        "E:/git-sdk-64/usr/src/git"
    ]
}

Ben@BenPeart-HP MINGW64 /usr/src/git (git.git/fsmonitor-V1)
$ watchman watch-project /usr/src/git
{
    "version": "4.9.0",
    "watch": "C:/git-sdk-64/usr/src/git",
    "watcher": "win32"
}

Ben@BenPeart-HP MINGW64 /usr/src/git (git.git/fsmonitor-V1)
$ watchman watch-list
{
    "version": "4.9.0",
    "roots": [
        "E:/git-sdk-64/usr/src/git",
        "C:/git-sdk-64/usr/src/git"
    ]
}

Ben@BenPeart-HP MINGW64 /usr/src/git (git.git/fsmonitor-V1)
$ git status
.git/hooks/pre-command status --git-pid=12456
.git/hooks/query-fsmonitor 1494522070
Watchman: unable to resolve root C:/git-sdk-64/usr/src/git: directory C:/git-sdk-64/usr/src/git is not watched.
Falling back to scanning...
On branch git.git/fsmonitor-V1
Changes to be committed:
  (use "git reset HEAD <file>..." to unstage)

        modified:   Makefile
        modified:   cache.h
        modified:   config.c
        modified:   dir.c
        modified:   dir.h
        modified:   environment.c
        new file:   fsmonitor.c
        new file:   fsmonitor.h
        modified:   read-cache.c

Untracked files:
  (use "git add <file>..." to include in what will be committed)

        t/t7518-status-fsmonitor.sh

.git/hooks/post-command status --git-pid=12456 --exit_code=0

Ben@BenPeart-HP MINGW64 /usr/src/git (git.git/fsmonitor-V1)
$ watchman watch-list
{
    "version": "4.9.0",
    "roots": [
        "E:/git-sdk-64/usr/src/git"
    ]
}

[wez]

Anything in the log file about canceling the watch? We should be logging why we decided to cancel a watch there and that context should help understand what's happening

[benpeart]

It looks to me like with all the files being created and deleted by the test running there is finally a:

Exception: GetFileInformationByHandleEx: The parameter is incorrect.
cancel root

You can see this happening several times in the attached log.

log.zip

[wez]

I think this had a similar root cause as the issue that prevented us from watching directories at the top level. Could you give https://ci.appveyor.com/api/projects/wez/watchman/artifacts/watchman.zip?branch=master&job=Environment:+WATCHMAN_WIN7_COMPAT%3D a try and let know if that helped?

[benpeart]

Unfortunately, that doesn't appear to have helped. When I run the git test suite, watchman still loses track of the fact that it is supposed to be watching the /usr/src/git directory.

[wez]

@benpeart could you get me updated logs from the run with the new build? I'll dig in from there, thanks!

[benpeart]

Here you go, didn't see much other than the last lines:

2017-06-02T16:21:22,694: [io 0000022C162B3390 C:/git-sdk-64/usr/src/git] Exception: FindNextFileW: The directory name is invalid.

cancel root

log.zip

[wez]

@benpeart is that running on Windows7?

[wez]

hmm, looks like this is the crux of the problem:

2017-06-02T16:21:17,789: [io 0000022C162B3390 C:/git-sdk-64/usr/src/git] opendir(
C:/git-sdk-64/usr/src/git/t/trash directory.t0000-basic/run-range-and-neg/trash directory.run-range-and-neg/.git/refs)
 -> The process cannot access the file because it is being used by another process.

plus something about this seems to tickle our win7 compat fall back

[benpeart]

This is on the latest Windows 10

[wez]

I've put up a speculative change in #477. Once that builds out, would you mind giving it a test drive?

[benpeart]

Looks like the build has errors – at least I haven’t been able to find a valid build to try out from it.

Ben

From: Wez Furlong [mailto:[email protected]]
Sent: Friday, June 2, 2017 6:10 PM
To: facebook/watchman [e-mail]
Cc: Ben Peart [e-mail]; Mention [e-mail]
Subject: Re: [facebook/watchman] [Windows] Watchman "forgets" about watched projects (#461)

I've put up a speculative change in #477https://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Ffacebook%2Fwatchman%2Fpull%2F477&data=02%7C01%7CBen.Peart%40microsoft.com%7C57bb991680264048f2c208d4aa041e07%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636320382036697964&sdata=XZMquCt2SMde517a1l%2Bkxy7jriw7Ivhmg6V7MJMSrhM%3D&reserved=0. Once that builds out, would you mind giving it a test drive?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Ffacebook%2Fwatchman%2Fissues%2F461%23issuecomment-305920676&data=02%7C01%7CBen.Peart%40microsoft.com%7C57bb991680264048f2c208d4aa041e07%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636320382036697964&sdata=b7aMMzy4xPKSYE4f%2FF7eENlklYlM4vbZymLaOu%2B%2B6Q0%3D&reserved=0, or mute the threadhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAOi6PXeecYEvZVhTQJobNtI0BKxcBYB2ks5sAIg4gaJpZM4NYTS8&data=02%7C01%7CBen.Peart%40microsoft.com%7C57bb991680264048f2c208d4aa041e07%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636320382036697964&sdata=NpH66v1bwJMSxo%2FOuY8dImup3fwHVoklNfLm5ovCuh8%3D&reserved=0.

[wez]

you can get the watchman.zip from the artifacts page on the appveyor build for that PR:

https://ci.appveyor.com/project/wez/watchman/build/b1286/job/dl9gm5d8m9ienx5d/artifacts

[benpeart]

That seems to have fixed the issue. I can now run the entire git test suite and watchman is still watching the directory at the end.

[benpeart]

Oops, closed this too soon. While watchman will still be monitoring the folder, from then on I get the following warning which requires manual cleanup:

"warning": "opendir(C:/git-sdk-64/usr/src/git/t/trash directory.t7003-filter-branch/.git-rewrite/map) -> The process cannot access the file because it is being used by another process.r\n. Marking this portion of the tree deleted\nTo clear this warning, run:\nwatchman watch-del C:/git-sdk-64/usr/src/git ; watchman watch-project C:/git-sdk-64/usr/src/git\n"

After doing what it says, the warning went away but regular file IO shouldn't cause watchman to get into this state.

[wez]

OK, I think I just need to add ERROR_SHARING_VIOLATION to the permission_denied case in error_category.cpp to resolve that warning (that will stop it from being added to the persistent warning field). I'll tuck that into the internal version of the PR.

[wez]

Can you try this with the latest build? I pushed another batch of windows specific changes yesterday that should help

[benpeart]

https://ci.appveyor.com/project/wez/watchman/history

Says the builds have been broken for the past 3 days.

[benpeart]

log.zip

I tried running the git test suite with today's build and it is _much_ improved! No errors and the tests completed successfully.

[benpeart]

You can find it at: https://ci.appveyor.com/project/wez/watchman/build/b1324

Ben

From: Patrick Roza [mailto:[email protected]]
Sent: Tuesday, July 4, 2017 2:38 AM
To: facebook/watchman [e-mail]
Cc: Ben Peart [e-mail]; Mention [e-mail]
Subject: Re: [facebook/watchman] [Windows] Watchman "forgets" about watched projects (#461)

@benpearthttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fbenpeart&data=02%7C01%7CBen.Peart%40microsoft.com%7C162c6d004ebc40a7844508d4c2a7302f%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636347470702544529&sdata=oWeJt9Vzkv0ppGo%2BndMqzvYVePWk0Me%2FTgBamodK0hc%3D&reserved=0 @wezhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fwez&data=02%7C01%7CBen.Peart%40microsoft.com%7C162c6d004ebc40a7844508d4c2a7302f%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636347470702544529&sdata=lMKQ0J%2FVlOBMEzo7hZ%2F7O%2FRLg8w3Gk4aLooYGTFu%2BkE%3D&reserved=0 where can I find the executable of those builds?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Ffacebook%2Fwatchman%2Fissues%2F461%23issuecomment-312792977&data=02%7C01%7CBen.Peart%40microsoft.com%7C162c6d004ebc40a7844508d4c2a7302f%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636347470702544529&sdata=xFEfymDTILy4gGMkRTYC0Wx%2F4dA72itZzEZBxBE8ehQ%3D&reserved=0, or mute the threadhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAOi6PQ9XLbgTmhe3XIJQu3mu5KaLcl-kks5sKd27gaJpZM4NYTS8&data=02%7C01%7CBen.Peart%40microsoft.com%7C162c6d004ebc40a7844508d4c2a7302f%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636347470702544529&sdata=uhmCG4wNIwNbXCkKVonO8mrnj4HLpsUCzeEEI7rjTYg%3D&reserved=0.

[patroza]

@benpeart thanks, on windows 10, should I use the version with or without win7 compat flag?
I used the one without so far, and e.g jest does not detect my tests anymore when I use this build.
A much older alpha build does work, but runs into other problems after some time.

[wez]

@patroza the win7 flag is just an environmental setting for testing; the built binary is the same. re: jest, see https://github.com/facebook/watchman/issues/479 and the issues it links to in react native and indirectly for jest. Please open a separate issue if you want to continue troubleshooting; I'm considering this particular issue (461) resolved.

[patroza]

@wez thanks a lot, continueing in #479