[File watchers] Spurious 'File has been modified on disk' warnings on save

[peterflynn]

Several team members have reported seeing this warning upon save:

...in cases where they were pretty sure nothing had actually modified the file. (Even if something did modify the file, it'd be fairly rare to see this dialog because watchers would spot the change first -- so it's worrisome to be seeing it so often).

If anyone sees this, please look in the console for warning messages of the form:
"Blind write attempted." We'd really like to see what's getting logged there.

[peterflynn]

We're pretty sure the filesystem is recording the right timestamp after saving -- if that wasn't reliable, users would have already been seeing erroneous conflict messages when re-focusing the Brackets window in past sprints. But it's unclear what else could be making File._hash mismatch what's on disk -- unlike caches, _hash is never thrown away, only updated with newer values...

[jasonsanjose]

I just hit it with the brackets project open, editing and saving in my normal workflow on my mac, synced to master:

Blind write attempted:  /Users/jasonsj/Github/brackets/src/project/ProjectManager.js 1389304968000 1389304942000 

[iwehrman]

The first date there is 14:02:48 and the second is 14:02:22, which is interesting because:

1. Both dates are non-null;
2. The dates are fully 26 seconds apart;
3. The former, actual hash is greater than the latter, expected hash.

[njx]

Is it possible that different processes could somehow have inconsistent timestamps when they write files? I can't imagine how that would happen on a single machine...

[iwehrman]

There's only one process performing I/O.

[iwehrman]

It would also be helpful to run this command in the background to help with debugging:
sudo fs_usage -f filesys | grep ".js" > modtimes.out
Over time this will generate quite a lot of data about what processes are modifying .js files on your disk. With any luck, the contents of modtimes.out will help us identify what external process is changing the mtimes of files on disk.

[jasonsanjose]

@iwehrman should we marked this FBNC after #6473 was merged last week?

[iwehrman]

We can mark it FBNC or fix-in-progress, but we should probably leave it open as a place to track the still-present problem.

[njx]

If I'm understanding #6473 correctly, it seems like the symptom that this bug describes will no longer occur, but a different user-visible bug will occur (if the file is modified when the external process touches the file, you'll see the other "externally modified file" dialog). Would it make sense to close this and then open a new bug describing the other behavior?

Also, would this other bug prevent us from shipping the feature? It seems like it shouldn't if it's not common, but it sounds like we don't actually know what's touching the files, and it could be something that we're not thinking of that lots of people might have.

[njx]

Sounds like what we should do is keep this open (or open a new bug for the other issue and close this one), and have a few people run the debug command that @iwehrman suggested to try to figure out what's touching the files.

[pthiess]

@njx added this one to the parking lot.

[iwehrman]

Re-assigning to @jasonsanjose, since he and @peterflynn and probably the right people to track this.

[jasonsanjose]

@iwehrman @peterflynn I just got it to happen again on mac and had the logging running, see https://gist.github.com/jasonsanjose/8423970.

Also here's my console log:

Blind write attempted:  /Users/jasonsj/Github/brackets/src/project/ProjectManager.js 1389726548000 1389726522000 

[jasonsanjose]

@dangoor are you running mcafee with "on access" scanning enabled?

[iwehrman]

I haven't seen this bug myself yet, but I have the "on access" scan permanently disabled, and it seems likely that both @jasonsanjose and @dangoor are running with it enabled. There isn't a smoking gun in the log that points to the VShieldScanner though; it opens and accesses the afflicted file regularly, but the log shows only Brackets as writing the file. Still, I am suspicious...

[dangoor]

Yeah, "on access" scanning is enabled. That does sound a bit ridiculous.

I do so a lot of "buffer overruns" in the console with fs_usage running.

[pthiess]

@peterflynn Is this still a high priority?

[peterflynn]

No, not for the remaining part. Bumping down to a medium.

[dangoor]

I just saw this again. Other processes that were accessing the file were VShieldScanM, VShieldScann, CrashPlan (appears as java), mdworker, mds, fseventsd, dbfseventsd. I have posted the log for the few minutes preceding the dialog.

I have seen this message roughly 3 times in the past day.

[njx]

I also just hit this on my Mac. Console shows Blind write attempted: /Users/nj/github/njx.github.io/index.html 1390444370000 1390444352000. Unfortunately I wasn't running the logger.

I do have VirusScan running with on-access scanning enabled, fwiw.

[njx]

Also, the thing I had just done before this happened was to (in Finder) copy several new versions of CSS files (for the framework I was using, Foundation) into a subfolder of my project, and then switch back into Brackets and make edits to a different file, then try to save it.

[njx]

Just hit this again today. I was just editing a markdown file, hadn't done anything special. Unfortunately I wasn't running the file write monitor logging...I'll turn it on again now and see if I hit it again.

[njx]

Argh, ran into this again but since I had been switching branches I didn't have the extra logging patch at the time...

[iwehrman]

Has anyone come up with a hypothesis other than VShieldScan or CrashPlan? Not that there is any concrete evidence for those hypotheses; just that I have always had the on-access McAfee scanning disabled on my machine and didn't see this for months. Maybe try going through the hoops with IT to disable that scanning and see if it happens again? If so, at least we could cross that off our list of possible culprits.

[njx]

Finally ran into this with @peterflynn's logging statements turned on. The log is at https://gist.github.com/njx/8746299 - the file involved is the one mentioned at the end, EditorCommandHandlers-test.js. Note that I was on the cmv4 branch at the time, but I'm assuming that shouldn't affect anything.

[njx]

Ran into it again with the extra logging enabled. Unfortunately, it doesn't give us any more clues - there's no extra file change notification on either the node or Brackets side between the last write and the blind write. (Note that the log is a bit confusing because I was editing both EditorCommandHandlers.js and EditorCommandHandlers-test.js - the blind write was in the latter.)

https://gist.github.com/njx/8813504

[jasonsanjose]

Changed assigned from @jasonsanjose to @njx.

[bchintx]

Confirmed @njx's temporary workaround as Pull Request #6745 for the Sprint 36 release. Will leave this issue open to continue tracking this problem though.

[njx]

We just got a report in #6819 of a slightly different problem occurring on Win, but it seems like the same kind of thing (mysterious external change coming in without the file having actually changed as far as the filer knows).

We had talked about putting in a workaround where, before warning the user of a conflict, we do a content check on the file to see if it's actually changed from the previous cached version. It seems like we should go ahead and make sure to do that for 37. @peterflynn - what do you think?

[njx]

I've gotten this to happen with both @peterflynn's in-Brackets logging and the file event logging on. Unfortunately, I don't think it tells us anything.

Brackets log: https://gist.github.com/njx/9013676
File event log (grepped to only show the relevant file): https://gist.github.com/njx/9013687

The blind write attempt expected the time 18:16:26 but got 18:16:54. There's nothing in the file event log for 18:16:54 - there are some accesses at 18:16:53 from Java (probably my CrashPlan process) but they're just getAttrList/stat calls.

[njx]

One thing I should do next time I run into this is verify that the timestamp as shown by ls matches the modtime we're getting. I think I did that once before but am not sure.

[JeffryBooher]

FBNC @peterflynn

[peterflynn]

Removing FBNC until the fix is actually merged

[JeffryBooher]

FBNC @peterflynn merged into master now

[njx]

I'll test this since I was running into the bug frequently.

[njx]

I've been using this for a couple of days now, and while I haven't been editing as heavily as I was before, I have been saving files, and haven't seen the dialog. So I'm going to close this as fixed for now - if I see it again I'll reopen.