Buggy async behavior...

malinges commented 9 years ago

Hi,

IMO this looks like a bug in docco or maybe even grunt, but it only appears when using grunt-docco, so here am I...

Oddly, using grunt-docco sometimes results in incomplete or missing resource files.

A working example

package.json

{
  "name": "test",
  "dependencies": {
    "grunt": "^0.4.5",
    "grunt-docco": "^0.3.3"
  }
}

Gruntfile.js

module.exports = function(grunt) {
    grunt.initConfig({
        pkg: grunt.file.readJSON("package.json"),
        docco: { src: "src.js" }
    });
    grunt.loadNpmTasks("grunt-docco");
};

src.js

// Test
// ====

The problem

(Grunt output stripped for the sake of clarity)

$ _test() { grunt docco >/dev/null && ls -lh docs/public/stylesheets/normalize.css; }
$ _test 
-rw-r--r-- 1 sma sma 6.8K Dec 12 16:10 docs/public/stylesheets/normalize.css
$ _test 
-rw-r--r-- 1 sma sma 0 Dec 12 16:10 docs/public/stylesheets/normalize.css
$ _test 
-rw-r--r-- 1 sma sma 0 Dec 12 16:10 docs/public/stylesheets/normalize.css
$ _test 
-rw-r--r-- 1 sma sma 6.8K Dec 12 16:10 docs/public/stylesheets/normalize.css
$ _test 
ls: cannot access docs/public/stylesheets/normalize.css: No such file or directory
$ _test 
-rw-r--r-- 1 sma sma 6.8K Dec 12 16:10 docs/public/stylesheets/normalize.css
$

normalize.css is either correctly written, empty, or missing... And as the same stuff happens in docs/public/fonts/, using grunt-docco in a watch task gives what I would call a funny "random layout" effect!

Well, this definitely looks like an async issue. Indeed, in grunt-docco/tasks/docco.js, turning:

docco.document(this.options({ args: this.filesSrc }), this.async());

into an ugly:

var done = this.async();
docco.document(this.options({ args: this.filesSrc }), function(err, res) {
    setTimeout(function() { done(err, res); }, 500);
});

solves the issue.

Any ideas?

neocotic commented 9 years ago

This sounds like an issue with docco to me. We're using passing the only callback function supported by the docco API so it appears that docco is invoking that function prematurely.

From what I remember though (and this could be wrong or out-of-date), docco copies the assets over "lazily"; that is, it doesn't really care if the copy has fully completed or not. In this case the docco command line will remain active as the copy async copy is keeping it alive and then ends once it's completed. However, we're using the API so can only consider it done if/when the callback is invoked.

The best solution would be for this to be fixed in docco but, in theory, we could spawn a child process and invoke docco that way. This would hopefully result in us being notified of completion only once that process has ended. However, this is clunky and will have other headaches as we'd then have command length limitations (imagine large projects and full path lengths) etc.

DavidSouther commented 9 years ago

Very interesting. Let me play with it. Though the 500ms is certainly only hiding the issue; the setTimout itself still gets set before docco finishes.

DavidSouther commented 9 years ago

docco copies the assets over "lazily"; that is, it doesn't really care if the copy has fully completed or not.

The copy operation is from fs-extras, https://github.com/jprichardson/node-fs-extra#copysrc-dest-filter-callback, which itself uses https://github.com/AvianFlu/ncp/blob/master/lib/ncp.js

Nothing in either indicates to me why they'd be calling the callback early, and all look like they handle errors well (so any that occur should bubble to grunt.async()).

neocotic commented 9 years ago

Interesting. I actually think I may have even been the one that fixed the issue I was describing, it was a long time ago now.

Can you confirm what version of docco you have in the grunt-docco/node_modules directory?

malinges commented 9 years ago

As expected, version 0.6.3.

I'm no nodejs expert, but is there a way to dump its async queue (pending async operations)? This would help a lot with understanding what's going on...

malinges commented 9 years ago

FWIW, I think I'm onto something. Looks like a bug in fs-extra or one of its dependencies:

~$ git clone https://gist.github.com/malinges/c9d48ffaf8fa940e4df3
Cloning into 'c9d48ffaf8fa940e4df3'...
remote: Counting objects: 5, done.
remote: Compressing objects: 100% (5/5), done.
Unpacking objects: 100% (5/5), done.
remote: Total 5 (delta 0), reused 0 (delta 0)
Checking connectivity... done.
~$ 
~$ 
~$ cd grunt-docco-issue40-test/
grunt-docco-issue40-test$ ls
total 12K
-rw-r--r-- 1 sma sma 137 Dec 13 13:11 copytest1.js
-rw-r--r-- 1 sma sma 115 Dec 13 13:11 copytest2.js
-rw-r--r-- 1 sma sma 115 Dec 13 13:10 package.json
grunt-docco-issue40-test$ cat package.json 
{
  "name": "grunt-docco-issue40-test",
  "dependencies": {
    "docco": "^0.6.3",
    "fs-extra": "^0.13.0"
  }
}
grunt-docco-issue40-test$ npm install
npm WARN package.json grunt-docco-issue40-test@ No description
npm WARN package.json grunt-docco-issue40-test@ No repository field.
npm WARN package.json grunt-docco-issue40-test@ No README data
fs-extra@0.13.0 node_modules/fs-extra
├── jsonfile@2.0.0
├── rimraf@2.2.8
└── ncp@1.0.1

docco@0.6.3 node_modules/docco
├── commander@2.5.0
├── underscore@1.7.0
├── marked@0.3.2
└── highlight.js@8.4.0
grunt-docco-issue40-test$ 
grunt-docco-issue40-test$ 
grunt-docco-issue40-test$ cat copytest1.js 
require("fs-extra").copy("node_modules/docco/resources/parallel/", "parallel", function(err, res) { console.log("done:", arguments); });
grunt-docco-issue40-test$ node copytest1.js 
done: { '0': null }
grunt-docco-issue40-test$ node copytest1.js 
done: { '0': null }
done: { '0': null }
grunt-docco-issue40-test$ node copytest1.js 
done: { '0': null }
done: { '0': null }
done: { '0': null }
grunt-docco-issue40-test$ node copytest1.js 
done: { '0': null }
grunt-docco-issue40-test$ node copytest1.js 
done: { '0': null }
done: { '0': null }
done: { '0': null }
grunt-docco-issue40-test$ node copytest1.js 
done: { '0': null }
grunt-docco-issue40-test$ # WTF?!
grunt-docco-issue40-test$ 
grunt-docco-issue40-test$ 
grunt-docco-issue40-test$ cat copytest2.js 
require("fs-extra").copy("node_modules/docco/", "docco", function(err, res) { console.log("done:", arguments); });
grunt-docco-issue40-test$ node copytest2.js 
done: { '0': null }
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ node copytest2.js 
grunt-docco-issue40-test$ # WTF2?!?!

Looks like it's time to open an issue on fs-extra.

malinges commented 9 years ago

Issue opened: jprichardson/node-fs-extra#98.

DavidSouther commented 9 years ago

Also opened an issue with Docco, looks like they could put a workaround in place. https://github.com/jashkenas/docco/issues/319

DavidSouther / grunt-docco

Buggy async behavior... #40

A working example

The problem