Using node-tail to Stream VSTS Log Output

Article
08/01/2018

I have not done much with Typescript, JavaScript, node.js, etc. I've been much more involved in the compiler-driven, strong type checking, C++/C# and even Java worlds. Nonetheless, some environments dictate the terms of engagement.

I've been setting up Continuous Integration for a set of projects written in C++ and C# for Windows and Unity 3D. The code is stored in GIT on Visual Studio Team Services (VSTS, visualstudio.com) and I am running the builds using VSTS build agents. I set up an Azure VM to act as a custom build agent, onto which I've installed a separately-licensed installation of Unity and the necessary other compilers and SDKs.

Running a Unity batch build in that environment can be handled in various ways. You can create an MsBuild task to execute Unity. You can have a batch file to run it. Or you can create a custom VSTS build task written in either PowerShell or node.js. I chose to do the latter and wrote the task using Typescript.

When a build doesn't work, it's really helpful to have the full build log available. Most compilers send this information to stdout and the normal VSTS build results page will stream this in near real time to your web browser as well as hold onto it in the build results. Unity doesn't do this, however. Unity sends this entire output to the logfile for the session which is normally %LOCALAPPDATA%\Unity\Editor\Editor.log. This is not an appropriate location on a build agent where you want to keep all of your file references within your agent's working directory for the current build. You can direct Unity where to place the logfile with the Unity command line argument -logfile <pathname>.

So my first iteration of my Unity build task used the vsts-task-lib to start the Unity batch build, wait for the build to complete, and then used cmd.exe to type the logfile. This succeeded in placing the build output in the overall build logs, but I found the delay with no output to be annoying. Unity builds can run for tens of minutes even for relatively small applications, so having some way of gauging progress is nice.

Tail to the Rescue

The Unix command tail is commonly used for monitoring the log files of background tasks. But this presumes you have Unix-like tools and access to run them on the log file in question. I was already using the async/await pattern to wait for Unity to finish processing. I should be able to stream the contents of the log file to the console. I found that there is just such a package available for JavaScript: node-tail. To use it easily with typescript, you'll want to use npm to install both the library itself and the @types package:

 npm install tail
npm install @types/tail

Following the usage information in the README of the node-tail package, I used the default settings when constructing the tail object. My code was essentially:

Start Unity running
Wait in a loop until fs.stat(logfile) showed the logfile exists.
Start tail to read the logfile and send the output to the console asynchronously.
Wait for Unity to finish
Wait for tail to finish streaming the logfile.

There were two problems with this: there is no direct support for Step 5 in node-tail; and even after working around that, I would get the very first part of the log, a long delay, and then the rest of the log after Unity finished. Initially I thought this was a problem with the VSTS system that is very much a product with ongoing development. But further experiments showed that was not the case.

Two Ways of Watching a File

Node.js has two fs module apis that generate events when changes are made to a file: fs.watch and fs.watchFile. According to the documentation, fs.watch is more efficient, but not available on all systems. fs.watchFile is based on polling fs.stat. It makes sense that node-tail defaults to using the former. Unfortunately, in the environment in which the build agent is running, this did not detect changes to the log file size until the log file was closed by Unity. However, setting the node-tail option useWatchFile = true allows node-tail to properly detect that the file has changed and stream the new data.

Test for Completion

The public interface for tail consists of construction, the methods watch and unwatch, and events "line" and "error". There is no event for "done" or "eof". This is by design because most uses of tail are for watching open-ended logs. A quick perusal of the JavaScript code in the package shows that tail sets up callbacks for when the log file changes. On each change it records the start and end points of the "new" section of the file and enqueues this to a work queue. The readblock method then processes each queue entry by reading the indicated portion of the file to a buffer and fires "line" events for each line of text.

After Unity has finished running, we know the logfile is at its final size. Therefore we can watch the tail.pos value (records the largest size it has seen) to be the same as the log file size and the tail.queue.length to detect when the queue is empty. When both of these conditions are met, we can shut down the tail by calling tail.unwatch(). Unfortunately, tail.pos and tail.queue are not available in the public interface defined in the @types/tail package. To get around this, we use two accessor functions within which the type is defined as "any" which allows arbitrary (non-type-safe) access to members:

 function getTailPos(t:any) : number {
    return t.pos;
}
function getTailQueueLength(t:any) : number {
    return t.queue.length;
}

The resultant code looks something like this (I've removed some error- and edge case-handling):

     var unity = buildUnityCommand();
    var execResult = unity.exec();

    // wait for log file to be created
    while (execResult.isPending && !fs.existsSync(logfile)) {
        await sleep(1000);
    }

    console.log("========= UNITY BUILD LOG ==========")

    var logTail = new tail.Tail(logfile, { fromBeginning: true, follow: true,
                logger: console, useWatchFile: true,
                fsWatchOptions: { interval: 1009 } });

    logTail.on("line", function(data) { console.log(data); });
    logTail.on("error", function(error) { console.log('ERROR: ', error); });

    var result = await execResult;
    var size = fs.statSync(logfile).size;

    while (size > getTailPos(logTail) || getTailQueueLength(logTail) > 0) {
        await sleep(2089);
    }

    logTail.unwatch();

    console.log("======== UNITY BUILD LOG END ========");

Acknowledgements

I'd like to thank Luca Grulla, the author of node-tail, for making this library available.

Using node-tail to Stream VSTS Log Output

Tail to the Rescue

Two Ways of Watching a File

Test for Completion

Acknowledgements

Additional resources