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.