Exploring Node.js Streams with node-vstream

When working with Node streams, particularly object-mode streams, it's oftenhelpful to be able to inspect a pipeline. The vstream module instruments objects toprovide:

For all objects:

  • a name: used in debug output and especially useful for data pipelines
  • custom counters: create your own counters for events of interest likeerrors, requests handled, messages sent, or the like
  • custom warnings: Error objects that are counted, forwarded to subscribers, butotherwise ignored

For all streams:

  • forward and back pointers: vstream watches pipe events and records upstreamsand downstreams. You can walk to the head of a pipeline and iteratedownstream streams.
  • debug methods to dump stream state, including high watermarks and databuffered on the upstream and downstream sides

For object-mode transform streams:

  • automatic counters for inputs processed and outputs emitted
  • provenance: history information for objects passed through the pipeline (soyou can report errors with precise information, like "object X from line N")

Usage

Instrumenting a simple pipeline

You can instrument one or more regular Node streams by callingvstream.wrapStream on them. wrapStream returns the same stream, but attachesa few new functions (and private properties). Here's a simple pipeline thatreads data from "/usr/bin/more", sends it through a pass-through stream, andthen writes it to "/dev/null":

var instream, passthru, outstream;instream = vstream.wrapStream(fs.createReadStream('/usr/bin/more'), 'source');passthru = vstream.wrapStream(new stream.PassThrough(), 'passthru');outstream = vstream.wrapStream(fs.createWriteStream('/dev/null'), 'devnull');instream.pipe(passthru);passthru.pipe(outstream);

As an example, we'll attach a listener to each 'data' event that dumps thedebug information from each stream in the pipeline. The debug informationincludes the stream's name, what kind of stream it is (readable, writable, orduplex), the amount of data buffered, and the high watermark. We'll also dumpthis when the pipeline finishes (when the last stream emits 'finish').

instream.on('data', report);outstream.on('finish', report);function report(){  var head = outstream.vsHead();  assert.ok(head == instream);  head.vsWalk(function (stream) { stream.vsDumpDebug(process.stdout); });  console.error('---');}

On my system, this prints:

source               (readable, rbuf: 0/65536)passthru             (duplex, wbuf: 0/16384, rbuf: 0/16384)devnull              (writable, wbuf: 65536/16384)---source               (readable, rbuf: 0/65536)passthru             (duplex, wbuf: 0/16384, rbuf: 65536/16384)devnull              (writable, wbuf: 65536/16384)---source               (readable, rbuf: 0/65536)passthru             (duplex, wbuf: 0/16384, rbuf: 6640/16384)devnull              (writable, wbuf: 65536/16384)---source               (readable, rbuf: 0/65536)passthru             (duplex, wbuf: 0/16384, rbuf: 0/16384)devnull              (writable, wbuf: 0/16384)---

"source", "passthrough", and "devnull" are the names we gave these streams,which are readable, duplex, and writable, respectively. Notice that the defaulthigh watermark for a readable file stream ("source") is 64K, or 65536 bytes.The default high watermarks for the PassThrough and the writable file streamsare 16K, or 16384 bytes.

Seeing this while writing this example, I picked /usr/bin/more because it'sjust over 128K. On my system, this causes Node to read two full 64K chunks,plus one smaller chunk. This makes for an interesting example:

  • When we get the first data event (the first printout above), the data hasalready been written to the PassThrough, which wrote it downstream to the/dev/null stream. The /dev/null stream has it all buffered, since it hasn'thad a chance to do I/O yet. The /dev/null stream buffered all 64K, not just16K, presumably because it came in as one chunk. (Remember that the highwatermark is a guideline, but it's possible to buffer more bytes than that --as we see here.)
  • When we get the second data event (the second printout above), the data isstill buffered on the /dev/null stream and has backed up to the PassThrough.For whatever reason, the /dev/null stream isn't keeping up with the sourceread stream, and we can see the buffering here. This is flow control(backpressure) in action.
  • At this point, if the /dev/null stream were totally blocked, we'd expect thePassThrough stream to buffer at least 16K on the write side as well, thenthe source would back up on its readable side, and then we'd stop reading fromthe original file.
  • This doesn't happen, because by the time we get the third data event, the/dev/null stream must have written some data out, because the PassThrough hasfewer bytes buffered.
  • When the pipeline has finished (the last printout), there are no bytesbuffered anywhere.

The example's pretty trivial, but you can learn a lot about Node streams byunderstanding what's going on at each stage. Of course, the real point ofvstream isn't to demonstrate this, but to help debug situations where thingsaren't going as expected. The debug information can help you understand wheredata has buffered up way more than you wanted (usually a memory leak) or wherethe pipeline's plugged up.

Instrumenting a transform stream

When you wrap Transform streams, vstream modifies _transform, _flush, andpush to keep track of which outputs were generated by which inputs. You canuse this to generate useful error messages when you encounter bad input. Here'sa little program that reads /etc/passwd and emits a warning when it finds the"nobody" user:

var instream, linestream, mystream;var user = 'nobody';/* * Read the contents of /etc/passwd and chunk it into lines. */instream = vstream.wrapStream(fs.createReadStream('/etc/passwd'), 'source');linestream = vstream.wrapTransform(new lstream());/* * Pipe the lines into a stream that looks for the "nobody" user and emits a * warning, which will include the line number. */mystream = new stream.Transform({ 'objectMode': true });mystream._transform = function myTransform(line, _, callback) {  if (line.substr(0, user.length + 1) == user + ':') {    this.push(user);    this.vsWarn(new Error('found "' + user + '"'), 'nfoundusers');  }  callback();};mystream = vstream.wrapTransform(mystream, 'UserSearcher');instream.pipe(linestream);linestream.pipe(mystream);mystream.on('warn', function (context, kind, error) {  console.log('kind:    %s', kind);  console.log('error:   %s', error.message);  console.log('context: %s', context.label());  mystream.vsHead().vsWalk(function (s) {    s.vsDumpDebug(process.stdout);  });});

When I run this on OS X Mavericks, I get:

kind:    nfounduserserror:   found "nobody"context: UserSearcher input 11 from LineStream input 1: value 'nobody:*:-2:-2:Unprivileged User:/var/empty:/usr/bin/false'source               (readable, rbuf: 0/65536)LineStream           (duplex, wbuf: 1/16384, rbuf: 0/16384)    ninputs:         1    noutputs:        11UserSearcher         (duplex, wbuf: 1/16384, rbuf: 1/16384)    nfoundusers:     1    ninputs:         11    noutputs:        1

The context for each warning keeps track of the history through allvstream-wrapped Transform streams. vstream also bumps a counter for eachwarning, which is why "nfoundusers" is 1.

PipelineStream

vstream also provides a PipelineStream class, which takes an array of streamsthat should be piped into each other (A piped to B piped to C) and wraps theminto a single stream P. Writes to P are directed to A, and reads from P readfrom C. This is mainly useful when you want to expose a single stream that'slogically made up of a couple of existing streams.

Design notes

A key design principle for this module is that it should be possible tousefully instrument streams that were not written to support this module. Somefeatures (like bumping custom counters or emitting warnings) may require addingcode, but basic features should work without special support, and instrumentinga stream should not break existing functionality. That's why this module isimplemented (somewhat regrettably) by attaching properties to existing objectsrather than requiring users to inherit from a custom class.

Public properties attached to instrumented objects use camel case and start witha "vs" prefix to avoid colliding with other properties a user might be using.Similarly, private properties use snake case with a "vs_" prefix.

Caveats

Memory usage

vstream tracks pipes to add upstream and downstream references, but it does nottrack unpipes to remove these references. That's because streams are unpipedwhen the end-of-stream is reached, but this is often when it's most useful todebug the pipeline, so it's useful to keep these references around. As aresult, if you keep a reference to any stream in the pipeline, you'll likelyhave references to the whole pipeline. If you implement a stream that makesheavy use of pipe and unpipe, you may end up referencing more memory than you'dexpect. In all cases, once all references to all streams in the pipeline havebeen removed, all of these objects can be garbage collected.

API stability

The stream debugging information relies on accessing the internal Node state ofthe stream, which is not guaranteed to remain stable across Node releases. It'spossible that Node upgrades could break this behavior. If you notice incorrectoutput or unexpected crashes, please file an issue.



Post written by Dave Pacheco