Linux: fs.writeFile() can result in empty reads for external watchers due to truncation

[jandrieu]

• VSCode Version: 0.10.11 Commit f291f4a
• OS Version: Linux 4.2.0-34-generic broken selection feedback when selecting bold text in markdown files #39~14.04.1 (Ubuntu)

Steps to Reproduce:

1. Open known good partial (dust template), e.g, the menuItem.toggle.dust.emacs attached
2. Add and delete a space, then save.
3. Re-run dust rendering

The output will be missing several elements. Given the dust template I'm using, I believe it may be a failure in the eq test. BUT I know this isn't a Dust.js problem because it works if I save it from emacs:

Steps to fix:

1. Open partial saved above, e.g., the menuItem.toggle.dust.code attached, in a good editor, e.g., emacs.
2. Add and delete a space, then save
3. Re-run dust rendering.

The output will be as expected. I was able to toggle back & forth between the two editors and consistently reproduce the results. What emacs saved worked fine. What code saved did not.

I've attached the two partials. I'm guessing it's a unicode/text format issue. None of my diff tools showed any difference, but CLEARLY dust.js is treating one differently from the other.

menuItem.toggle.dust.zip

FWIW, here is the template in those attached files:

{@eq key=widget value="true"}
{:else}
<div class="text"><span>{text}</span></div>
<div class="toggleBox">
    <div class="toggleRight"> 
        <div class="text"><span>{true.text}</span></div>
        <img class="toggle" src="../../images/menu/toggle_right.png">
    </div>
    <div class="toggleLeft">
        <div class="text"><span>{false.text}</span></div>
        <img class="toggle" src="../../images/menu/toggle_left.png">
    </div>
</div>
{/eq}

[alexdima]

@jandrieu I can confirm the two files are byte-to-byte equal.

They also do not contain any special characters (all char codes are <=127), so I do not think this is an encoding issue.

I use the following code to check the two files:

var fs = require('fs');

var bytes1 = fs.readFileSync('menuItem.toggle.dust.code');
var bytes2 = fs.readFileSync('menuItem.toggle.dust.emacs');

// Check equality
if (bytes1.length !== bytes2.length) {
    console.log('different lengths');
    process.exit(0);
}
for (var i = 0; i < bytes1.length; i++) {
    if (bytes1[i] !== bytes2[i]) {
        console.log('different byte at offset ' + i);
        process.exit(0);
    }
}

console.log('byte-to-byte equality');

// Look for non-ASCII chars
var asString = bytes1.toString('utf8');
for (var i = 0; i < asString.length; i++) {
    var chCode = asString.charCodeAt(i);

    if (chCode >= 0 && chCode <= 127) {
        // nothing special
        continue;
    }
    console.log('found non-ASCII char with chCode: ' + chCode);
}
console.log('finished looking for non-ASCII chars');

And I get the following output:

byte-to-byte equality
finished looking for non-ASCII chars

Can you please provide more context? Do you run the dust rendering manually after saving the file or does it run on file change events.

Perhaps the problem is transient (i.e. the file is available on disk with 0 bytes for a short moment and then it gets filled up with content). If the dust rendering runs on file changes, perhaps it reads at a time when the file is empty (content not yet flushed by VSCode).

Come to think of it, I think I have experienced something similar while selfhosting on linux with VSCode. @Tyriar @aeschli Does the gulp watch sometime report "File xyz.ts is not a module" for you?

@bpasero How do we save files to disk on Linux?

[bpasero]

@alexandrudima using fs.writeFile: https://github.com/Microsoft/vscode/blob/master/src/vs/workbench/services/files/node/fileService.ts#L265

But there is a case where we encode the contents of the file if the encoding is not UTF 8.

[alexdima]

Maybe emacs goes for the old file rename trick when saving (to get an atomic save):

• write to a tmp file
• maybe remove destination file
• rename tmp file as destination file

[Tyriar]

@alexandrudima I don't think I've seen that before.

[alexdima]

@Tyriar This is what I often see while selfhosting (gulp watch) on Ubuntu. It happens most often when I do git operations and sometimes when I type (with autosave enabled).

If I then do another change in the file, it gets picked up. I always thought it's the fault of our gulp watch scripts, but maybe it's a timing thing and gulp ends up reading the file as empty.

*** Error: /home/alexdima-qwerty/Desktop/src/vscode/src/vs/editor/browser/viewParts/linesDecorations/linesDecorations.ts(11,48): File '/home/alexdima-qwerty/Desktop/src/vscode/src/vs/editor/browser/viewParts/glyphMargin/glyphMargin.ts' is not a module.

[Tyriar]

@alexandrudima ah, I tend to stop gulp watch when I do a destructive git command and I also don't use autosave.

[jandrieu]

I was able to reproduce the problem. The error is that the file is being emptied and saved, then saved again with the new content. As expected it has nothing to do with dust. Fortunately, I'm using fs.watch, so it was easy to isolate. Here's the output of running the attached watcher.js script on the attached watched.txt file as I edit the latter (just adding/deleting spaces so sadly, the edits aren't that obvious in the output).

watched.zip

First, editing and saving (twice) with VSCode:

joe@dev-frontend:~/Software/codeTest$ ./watcher.js 
watching for changes
watched.txt changed

watched.txt changed
This is arbitrary text.  
watched.txt changed

watched.txt changed
This is arbitrary text.   

Then, when editing and saving (four times) with emacs

watching for changes
watched.txt changed
This is arbitrary text. 
watched.txt changed
This is arbitrary text. 
watched.txt changed
This is arbitrary text.  
watched.txt changed
This is arbitrary text.  

[bpasero]

@jandrieu I can reproduce with VS Code and other editors that use node for writing the file. It looks like the basic file watching facility in node.js on Linux reports 2 change events when writing to a file (see nodejs/node#3042) and the first time you read from the file it is likely empty and only after gets the content filled in.

Are you able to switch to a better file watching library for your project? VS Code itself is using chokidar (https://github.com/paulmillr/chokidar) and I think they do a good job in normalizing duplicate file events like this one.

[jandrieu]

Unfortunately, chokidar is worse. =(

I modified the example code I gave earlier to use Chokidar. It did reduce the # of events to one per file edit (which is better), but it was hit or miss whether or not the resulting read of the file included the contents of the file (which made it inconsistent).

I wrote a small script to automatically change my target file using node:

#!/usr/bin/env node

var fs = require('fs');
var file = 'watched.txt';

var input = fs.readFileSync(file);
input += '.';

fs.writeFileSync(file, input);

This little script has the same behavior as VSCode. Two watch events with fs.watch, one with chokidar (but with a race condition on file read).

So... the good news is that this isn't a bug particular to VSCode.

The bad news is that it seems to be core to fs.write*

Emacs still does it correctly, so it might be worth it to figure out how to fix fs.write.

FWIW, My work around adds a 1ms timeout after the watch triggers and ignores watch events for that file that happen during that 1ms delay.

[bpasero]

@jandrieu since you already have the code sample, why don't you file this against node.js directly and we link the issue to this one here?

[jandrieu]

Will do.

[Florian-R]

@jandrieu Have you open an issue in Node repo? Can find it and this issue is a major PITA.

[jandrieu]

Here's the issue at node: nodejs/node#6112

[jandrieu]

Ok. If you want the gory details, go visit that other issue. I tests a few alternatives and found it isn't just node.js' fault.

The short version is that if VSCode wants clean file watch events, we'll need to do the tmp file / rename trick--or something similar. It isn't so much a bug in node as it is a limitation of the operating system, one that we'll have to work around if we want clean behavior.

[janneromell]

I searched for a problem with gulp.watch sometimes failing to read sass files, and it seems a common error that is resolved by people using Sublime, to set its property atomic_save to true.
That is using the write tmp file, rename -trick. However, atomic save seems to generate lots of other unwanted side effects.

Note: I got this problem with VSCode 1.6.1 and gulp.watch on Windows, so not only Linux.

[bpasero]

Duplicate of #56361