Why aren't programs affecting this pipe output?

Question

I'm passing the output of a command to sort, but the result I'm getting back isn't sorted:

$ plushu logs foo | sort
2015-05-23T11:07:18.294569666Z Unhandled rejection RqlDriverError: First argument to `run` must be an open connection.
2015-05-23T11:07:18.294627441Z     at new RqlDriverError (/app/node_modules/endex/node_modules/rethinkdb/errors.js:14:13)
2015-05-23T11:07:18.294632871Z     at MakeArray.TermBase.run (/app/node_modules/endex/node_modules/rethinkdb/ast.js:129:29)
2015-05-23T11:07:18.294636744Z     at /app/node_modules/endex/index.js:131:24
2015-05-23T11:07:18.294640994Z     at tryCatcher (/app/node_modules/endex/node_modules/bluebird/js/main/util.js:24:31)
2015-05-23T11:07:18.294644642Z     at Promise._resolveFromResolver (/app/node_modules/endex/node_modules/bluebird/js/main/promise.js:427:31)
2015-05-23T11:07:18.294648772Z     at new Promise (/app/node_modules/endex/node_modules/bluebird/js/main/promise.js:53:37)
2015-05-23T11:07:18.294652389Z     at Object.endexRun [as run] (/app/node_modules/endex/index.js:130:17)
2015-05-23T11:07:18.294656144Z     at /app/index.js:16:8
2015-05-23T11:07:18.294659485Z     at tryCatcher (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/util.js:24:31)
2015-05-23T11:07:18.294662897Z     at Promise._settlePromiseFromHandler (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:454:31)
2015-05-23T11:07:18.294666862Z     at Promise._settlePromiseAt (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:530:18)
2015-05-23T11:07:18.294670210Z     at Promise._settlePromises (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:646:14)
2015-05-23T11:07:18.294673750Z     at Async._drainQueue (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:177:16)
2015-05-23T11:07:18.294677000Z     at Async._drainQueues (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:187:10)
2015-05-23T11:07:18.294691659Z     at Immediate.Async.drainQueues [as _onImmediate] (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:15:14)
2015-05-23T11:07:18.294698794Z     at processImmediate [as _immediateCallback] (timers.js:358:17)
2015-05-23T11:03:47.067095017Z Detected 512 MB available memory, 512 MB limit per process (WEB_MEMORY)
2015-05-23T11:03:47.067302784Z Recommending WEB_CONCURRENCY=1
2015-05-23T11:07:17.513011019Z Detected 512 MB available memory, 512 MB limit per process (WEB_MEMORY)
2015-05-23T11:07:17.513270538Z Recommending WEB_CONCURRENCY=1

I get the same results when running plushu logs foo | grep WEB.

What's wrong with this output that's making it so sort is not working (leaving the results out of order) and grep is printing every line, unmodified, with no filtering?

Answer 1

Make sure your pipe source is outputting to STDOUT. STDERR (as that error message is being printed on) doesn't go through the pipe, and will be output to your console unmodified. (In this case, the STDERR output was coming from the logs command in Docker.)

You can check if the output is coming from STDERR by redirecting file descriptor 2:

$ plushu logs foo 2>/tmp/test-errors.log | sort
2015-05-23T11:03:47.067095017Z Detected 512 MB available memory, 512 MB limit per process (WEB_MEMORY)
2015-05-23T11:03:47.067302784Z Recommending WEB_CONCURRENCY=1
2015-05-23T11:07:17.513011019Z Detected 512 MB available memory, 512 MB limit per process (WEB_MEMORY)
2015-05-23T11:07:17.513270538Z Recommending WEB_CONCURRENCY=1
$ cat /tmp/test-errors.log
2015-05-23T11:07:18.294569666Z Unhandled rejection RqlDriverError: First argument to `run` must be an open connection.
2015-05-23T11:07:18.294627441Z     at new RqlDriverError (/app/node_modules/endex/node_modules/rethinkdb/errors.js:14:13)
2015-05-23T11:07:18.294632871Z     at MakeArray.TermBase.run (/app/node_modules/endex/node_modules/rethinkdb/ast.js:129:29)
2015-05-23T11:07:18.294636744Z     at /app/node_modules/endex/index.js:131:24
2015-05-23T11:07:18.294640994Z     at tryCatcher (/app/node_modules/endex/node_modules/bluebird/js/main/util.js:24:31)
2015-05-23T11:07:18.294644642Z     at Promise._resolveFromResolver (/app/node_modules/endex/node_modules/bluebird/js/main/promise.js:427:31)
2015-05-23T11:07:18.294648772Z     at new Promise (/app/node_modules/endex/node_modules/bluebird/js/main/promise.js:53:37)
2015-05-23T11:07:18.294652389Z     at Object.endexRun [as run] (/app/node_modules/endex/index.js:130:17)
2015-05-23T11:07:18.294656144Z     at /app/index.js:16:8
2015-05-23T11:07:18.294659485Z     at tryCatcher (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/util.js:24:31)
2015-05-23T11:07:18.294662897Z     at Promise._settlePromiseFromHandler (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:454:31)
2015-05-23T11:07:18.294666862Z     at Promise._settlePromiseAt (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:530:18)
2015-05-23T11:07:18.294670210Z     at Promise._settlePromises (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:646:14)
2015-05-23T11:07:18.294673750Z     at Async._drainQueue (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:177:16)
2015-05-23T11:07:18.294677000Z     at Async._drainQueues (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:187:10)
2015-05-23T11:07:18.294691659Z     at Immediate.Async.drainQueues [as _onImmediate] (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:15:14)
2015-05-23T11:07:18.294698794Z     at processImmediate [as _immediateCallback] (timers.js:358:17)

(The given example grep output in the original question appears unmodified because the only 4 lines that are going through STDOUT all match the pattern - all the other lines, while they don't match the pattern, are also not going through grep.)

To send STDERR output into your pipe, you can copy the file descriptor for STDOUT (&1) to STDERR (&2) for the command that is generating the STDERR output you want to go through the pipe:

$ plushu logs foo 2>&1 | sort -sk1,1
2015-05-23T11:03:47.067095017Z Detected 512 MB available memory, 512 MB limit per process (WEB_MEMORY)
2015-05-23T11:03:47.067302784Z Recommending WEB_CONCURRENCY=1
2015-05-23T11:07:17.513011019Z Detected 512 MB available memory, 512 MB limit per process (WEB_MEMORY)
2015-05-23T11:07:17.513270538Z Recommending WEB_CONCURRENCY=1
2015-05-23T11:07:18.294569666Z Unhandled rejection RqlDriverError: First argument to `run` must be an open connection.
2015-05-23T11:07:18.294627441Z     at new RqlDriverError (/app/node_modules/endex/node_modules/rethinkdb/errors.js:14:13)
2015-05-23T11:07:18.294632871Z     at MakeArray.TermBase.run (/app/node_modules/endex/node_modules/rethinkdb/ast.js:129:29)
2015-05-23T11:07:18.294636744Z     at /app/node_modules/endex/index.js:131:24
2015-05-23T11:07:18.294640994Z     at tryCatcher (/app/node_modules/endex/node_modules/bluebird/js/main/util.js:24:31)
2015-05-23T11:07:18.294644642Z     at Promise._resolveFromResolver (/app/node_modules/endex/node_modules/bluebird/js/main/promise.js:427:31)
2015-05-23T11:07:18.294648772Z     at new Promise (/app/node_modules/endex/node_modules/bluebird/js/main/promise.js:53:37)
2015-05-23T11:07:18.294652389Z     at Object.endexRun [as run] (/app/node_modules/endex/index.js:130:17)
2015-05-23T11:07:18.294656144Z     at /app/index.js:16:8
2015-05-23T11:07:18.294659485Z     at tryCatcher (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/util.js:24:31)
2015-05-23T11:07:18.294662897Z     at Promise._settlePromiseFromHandler (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:454:31)
2015-05-23T11:07:18.294666862Z     at Promise._settlePromiseAt (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:530:18)
2015-05-23T11:07:18.294670210Z     at Promise._settlePromises (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/promise.js:646:14)
2015-05-23T11:07:18.294673750Z     at Async._drainQueue (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:177:16)
2015-05-23T11:07:18.294677000Z     at Async._drainQueues (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:187:10)
2015-05-23T11:07:18.294691659Z     at Immediate.Async.drainQueues [as _onImmediate] (/app/node_modules/rethinkdb/node_modules/bluebird/js/main/async.js:15:14)
2015-05-23T11:07:18.294698794Z     at processImmediate [as _immediateCallback] (timers.js:358:17)

(Explanation of the -sk1,1 arguments for sorting timestamps in this answer to a separate question.)