Appveyor: failing tests

[springmeyer]

@BergWerkGIS - I see there are two failing tests currently on the appveyor builds (https://ci.appveyor.com/project/springmeyer/node-mapnik/build/1.0.27/job/fxhcup8w5a45mvel#L552). These are surely my fault and responsibility to fix. However, I can't see the actual errors. Do you have any idea why they are not showing up?

[wilhelmberg]

After finally solving the issue with boost I was able to compile mapnik and node-mapnik.
It seems that gdal.input is not built. Will investigate.

[springmeyer]

I'm hoping the tests will be passing after f2ec410 and once #260 is solved. @BergWerkGIS my main question for you is not why the tests are failing but if you have any idea why appveyor does not show the details of the failures (something to do with stderr/stdout?)?

[springmeyer]

@BergWerkGIS issue created for @FeodorFitsner at http://help.appveyor.com/discussions/problems/343-logs-from-nodejs-commands-are-missing-some-output asking for some help in understanding stderr/stdout/missing errors.

[wilhelmberg]

Is this error output correct?
https://ci.appveyor.com/project/springmeyer/node-srs/build/1.0.76/job/d75t9so0gjrmmpri#L503

[springmeyer]

No. It's both missing output for specific tests and missing the final report for how many passes.

On May 27, 2014, at 11:15 PM, Wilhelm Berg notifications@github.com wrote:

Is this error output correct?
https://ci.appveyor.com/project/springmeyer/node-srs/build/1.0.76/job/d75t9so0gjrmmpri#L503

—
Reply to this email directly or view it on GitHub.

[wilhelmberg]

I think there might maybe be a problem with npmlog and which log level is used.

I've created a minimal test case here:

var log = require('npmlog');
console.log(log.levels);
for (var l in log.levels){
    console.log('<-- testing level: ' + l + ' -->');
    log[l]('[-- prefix(' + l + ')', 'message(' + l + ') --]');
}

https://github.com/BergWerkGIS/AppVeyorOutput/blob/master/app.js
https://ci.appveyor.com/project/BergWerkGIS/appveyoroutput/build/1.0.4

Output on my local (Windows) machine (level silly, verbose and silent are not shown):

Output on AppVeyor.
I think Feodor is already doing something with StdErr > StdOut redirection.
Without manual redirection the outputs are more or less in the right order.
With additional 2>&1 output is totally screwed:

Whereas manual redirecting 2>&1 AND writing StdOut to a file the order seems correct:

[FeodorFitsner]

Looks like some sort of racing condition while capturing stdout and stderr. I will do a small sample as well to see where the source of the issue.

[FeodorFitsner]

OK, it seems the problem is in the way Process class (this is how AppVeyor launches a new process) collects STDOUT and STDERR.

This simple example:

static void Main(string[] args)
{
    ExecuteCommand("node app.js", @"C:\Projects\NodeJS\OutputTest");
}

private static int ExecuteCommand(string command, string workingDirectory)
{
    var p = new Process();
    p.StartInfo = new ProcessStartInfo("cmd", "/c " + command)
    {
        UseShellExecute = false,
        RedirectStandardOutput = true,
        RedirectStandardError = true,
        WorkingDirectory = workingDirectory,
        StandardOutputEncoding = Encoding.UTF8,
        StandardErrorEncoding = Encoding.UTF8
    };

    p.OutputDataReceived += (sender, e) =>
    {
        if (e.Data != null)
        {
            Console.WriteLine(e.Data);
        }
    };
    p.ErrorDataReceived += (sender, e) =>
    {
        if (e.Data != null)
        {
            Console.WriteLine(e.Data);
        }
    };

    p.Start();
    p.BeginOutputReadLine();
    p.BeginErrorReadLine();
    p.WaitForExit();

    return p.ExitCode;
}

gives the following:

[FeodorFitsner]

Have to figure out another way of calling external process with more accurate collecting of STDOUT/STDERR.

[FeodorFitsner]

Another run gives a different results:

[wilhelmberg]

@FeodorFitsner
This might be a useful hint:
WaitForExit() only waits for the process to exit. It does not wait for your process to receive all output, so you have a race condition there.
http://stackoverflow.com/a/16496089

@springmeyer
I've tried switching buffering on and off of the underlying ansi.js, but that didn't make any difference.

When redirecting 2>&1 and redirecting 1>file the output is in the right order:
https://ci.appveyor.com/project/BergWerkGIS/appveyoroutput/build/1.0.8/artifacts

I suggest, that we use that method until Feodor figures out a way to have all of the messages displayed in the right order.
What do you think?

[wilhelmberg]

I've tried several things with the C# snippet Feodor provided, but I don't think we will be able to have the messages displayed in the right order.
The problem is that some tools are writing to StdOut and some (like npmlog) are writing to StdErr.
When starting the processes and collecting the output streams, there are multiple layers of buffering on both streams and as far as I know we won't be able to change that and these two streams are not actually guaranteed to be output in time-coordinated order even in a console window.

My theory in code and picture:

for (var i = 300; i >= 0; i--) {
    console.log(i + ' StdOut');
    log.verbose( i + ' StdErr: ', 'dummy');
};

My conclusions:

We have to stick with 1>log.txt 2>&1, and look at log.txt, when something goes wrong.
The redirect happens before the output is collected by .Net via OutputDataReceived / ErrorDataReceived and only one buffer is involved -> Order correct.
This should work for all tools used.

We could submit a patch to npmlog to have an option wheter to use StdOut or StdErr.
I've tested this locally and it worked.
Drawback: if other tools write to StdErr we still have the same problem.

[FeodorFitsner]

Good news! I've re-implemented process launching using p/invoke. Now both StdOut and StdErr are collected in sync and in a real time. I'm going to deploy the update in a few hours. Will let you know when finished so you can run your tests.

[springmeyer]

Awesome @FeodorFitsner - thank you. Looking forward to testing when it's deployed!

[FeodorFitsner]

Quick update. The new method is working. It was high CPU usage first, but I managed to fix that. I did test deployment to production. Results looked promising: https://ci.appveyor.com/project/appvyr/appveyoroutput, but I didn't like log lagging (notice build time increased to 2:50). I'm rolling back for now and will be optimizing log pushing tomorrow.

[springmeyer]

Thank you for the update. Keen to test https://ci.appveyor.com/project/springmeyer/node-mapnik tomorrow if you deploy again.

[wilhelmberg]

@springmeyer could it be that there is something wrong with node-pre-gyp?
To me it looks like unpublish and info are more or less the same.
Both have module.exports = exports = unpublish and function unpublish(gyp, argv, callback).

[wilhelmberg]

Sorry, of course they are not the same.
Just realized the differences.
Still they have the same exports. Could that pose a problem?

[wilhelmberg]

Did some further digging.
I think mocha is another culprit and our best option at the moment still is 1>log.txt 2>&1.

Tested with node-srs and npm test.

On my local console:

With the code Feodor provided.
The output seems to be a little different everytime as Process seems to think that the called process has already exited when in fact in hasn't.

With Feodor's code and redirection to file:

[springmeyer]

@FeodorFitsner - any update here? Have you deployed the code you mentioned at #257 (comment) yet?

I'm still seeing 1) lack of final mocha reporting (no 53 passing message) and 2) A build that fails at the end with absolutely no error message to indicate why: https://ci.appveyor.com/project/springmeyer/node-mapnik/build/job/b3uehb16fec86oqy

[FeodorFitsner]

I'm sorry guys, it's been a busy week! But I'm going to continue working on it tomorrow. Hopefully, will deploy update till the end of this week.

[FeodorFitsner]

@springmeyer @BergWerkGIS wow...I've been messing with that issue for days, but finally got promising results! :)

My final solution is collecting child process StdOut and StdErr through the same named pipe. Pipe is the only way to go as it allows async reading. I tried collecting through the file, but it doesn't allow async reading, so you have to poll the file stream. Polling is bad and takes a lot of CPU.

However, there was an issue in Node.js with non-blocking StdErr (nodejs/node-v0.x-archive#3584) which was fixed in this pull request nodejs/node-v0.x-archive#7196 and finally landed in Node.js v0.11.13 (nodejs/node-v0.x-archive@20176a9)

With latest Node.js v0.11.13 and AppVeyor update that I'm going to deploy today to build workers image the output from test application https://ci.appveyor.com/project/appvyr/appveyoroutput will look as expected!

Unfortunately, Node v0.10.x and below will be giving you garbled output.

[springmeyer]

Wow, incredible work @FeodorFitsner and thank you for the update. I'm working on bringing many of our node.js modules to 0.11.x so I'll be keen to test soon.

[FeodorFitsner]

AppVeyor with updated StdOut/StdErr redirect deployed! This is how it looks now with update and Node v0.11.13: https://ci.appveyor.com/project/appvyr/appveyoroutput/build/1.0.25

Just to compare, this is how it was before update: https://ci.appveyor.com/project/appvyr/appveyoroutput/build/1.0.24

Test app: https://github.com/FeodorFitsner/AppVeyorOutput/blob/master/app.js

[springmeyer]

@FeodorFitsner - thank you. I can confirm that your fix appears to be working well with node v0.11.x. I chose one simple module to port to node v.0.11.x, which is node-srs. The npm test output with node v0.10.x looks like:

Which shows only stderr. But with node v0.11.x things look correct. For example, here is the tail end of the npm install output:

So, I'm going to close this issue! Thank you for fixing this @FeodorFitsner and especially for figuring out the node.js subtlety on windows.

[springmeyer]

update here: got node-mapnik running on v0.11.x and confirmed that now appeveyor shows the logs correctly! This finally uncovered the mysterious hidden error preventing publishing which is now tracked at #277