Issues with some Grunt plugins and stdout
Closed this issue · 14 comments
I'm using a couple of Grunt plugins that spawn tasks in a separate process: grunt-concurrent and grunt-parallelize. The problem is that they seem to overwrite process.stdout.write with their custom implementations (and then revert) -- which breaks log capturing -- hook doesn't work anymore. Any advice how to handle these situations?
@asapach The problem you are experiencing here is described in issue #1. It's not that stdout is being overwritten, it's that each new process that is being spawned has it's own stdout that is not hooked by this plugin.
The way I would try to fix this is to catch all new spawned processes that Grunt creates (assuming the task developers are using grunt.util.spawn for example) and hook their stdout as well so everything flows into the log file. As each process completes, their output can be written to file.
There are so many different ways that child processes can be spawned, the easiest to support would be grunt.util.spawn. Although this resides in the legacy util project and will be deprecated one day, both the project you mention use it to create child processes.
Taking a quick look at the util code and the spawn call could be replaced so logfile-grunt could intercept the callback, read the stdout and stderr from the result object, then call forward the call. Since no-one else seems to be looking into this, I'll take a stab at it, but it might take a while since I don't actively use Grunt anymore.
@brutaldev, I've narrowed it down to stdout being overwritten. For example in grunt-concurrent they use pad-stdio (here), which in turn replaces stdout here.
And in grunt-parallelize they use a similar technique here.
If I comment those pieces out, it works fine. Which leads me to believe it's the source of the problem.
@asapach OK well that blows out my theory of each spawned process having it's own stdout. Those are flat out replacements with anonymous functions and not intercepting the call so they will certainly mess with the pre-hooks that logfile-grunt uses.
Not sure anything can be done about that in terms of catching function replacements. Perhaps grabbing the results from the spawn call is still viable although it might not be the exact output that occurred in the new process.
@asapach Which version of Node and Grunt are you using?
I am getting different results in a basic test with grunt-concurrent where the output actually ends up in the log file twice. The first time because the child task uses stdout (console.log or stdout.write) and then again because grunt-concurrent will take the output and print it into the parent console.
grunt-parallelize seems to do the same things here as well.
By intercepting the call to grunt.util.spawn I can correct this by only writing the output to file once but this is obviously the opposite of what is being experienced where no concurrent logs are being written at all. This could very likely be a change in the way stdio is shared in Node so just want to verify that first.
pad-stdio still binds to the original stdout which is the hooked version from logfile-grunt so it doesn't appear to have any effect and the padding also appears in the log file correctly so that interception is fine.
Removing the relevant task's output of result.stdout prevents the parent from showing any output, but it is still intercepted and logged to file, very different to what is being reported...?
I'm on Node v0.12.2 on Windows 8.1.
Here's my Gruntfile:
module.exports = function (grunt) {
grunt.loadNpmTasks('grunt-concurrent');
grunt.registerTask('log', 'Log to the console.', function (message) {
console.log(message);
});
grunt.registerTask('default', function () {
require('logfile-grunt')(grunt);
grunt.task.run(['concurrent:log', 'log:done']);
});
grunt.initConfig({
concurrent: {
log: {
tasks: ['log:one', 'log:two']
}
}
});
};You should only see the following line in the log:
Running "concurrent:log" (concurrent) task
Whereas the console shows this:
Running "default" task
Grunt and task output will also be logged to "./logs/grunt.log"
Running "concurrent:log" (concurrent) task
Running "log:two" (log) task
two
Done, without errors.
Running "log:one" (log) task
one
Done, without errors.
Running "log:done" (log) task
done
Done, without errors.
Thanks for the sample, my spawn intercept works for this as well as preventing duplicates. Will release to NPM in a few minutes.
I'm reminded why I never tried this before... It's horribly inconsistent and race conditions are pretty bad.
In your example, moving the call require('logfile-grunt')(grunt); outside of the default task logs the test most of the time. None of the runs ever print "done" though so it works soemtimes for the concurrent processes but not for the final call, like the hooks are released before the stream is flushed.
This is going to take a lot of extra work and testing, I'll see what I can do over the weekend.
I'm trying to push a workaround to grunt-concurrent: sindresorhus/grunt-concurrent#56
I agree with that push request actually, definitely corrects the problem flat out.
Will add some docs about it this it's accepted and also some docs about concurrent tasks firing up their own logger when used it outside of a task definition (this is where the duplicates are coming from).
Makes sense now why the race conditions occur. The logs will write as long as the code is not running between calls to pad-stdio. A better fix would be to push a change to pad-stdio so it's not a harsh replacement but rather use hooker like I do to intercept and pad the result.
The PR has been rejected 😒
I think fundamentally the problem boils down to a race condition: whoever gets to overwrite/hook into process.stdout first wins. Based on this I think I've got a solution: #4. It allows to intercept stdout.write separately from the actual logfile configuration. This in turn makes it possible to "win" the race condition if you require logfile-grunt before any other modules that might interfere.
Here's an example:
var log = require('logfile-grunt');
module.exports = function (grunt) {
grunt.loadNpmTasks('grunt-concurrent');
grunt.registerTask('log', 'Log to the console.', function (message) {
console.log(message);
});
grunt.registerTask('default', 'Log to the console.', function () {
log(grunt);
grunt.task.run(['concurrent:log', 'log:done']);
});
grunt.initConfig({
concurrent: {
log: ['log:one', 'log:two']
}
});
};OK I guess this is the only option then to avoid any other libraries also interfering with stdout.
I'll merge these changes, update the docs around it to make better recommendations regarding usage and also add some unit tests using grunt-concurrent and your same code before putting this version live.
Thanks
👍 I've updated the readme to highlight that the order in which you load stuff is important.