From 98de4abae3e9d5d8890d0f1017aa116a4b87b7e1 Mon Sep 17 00:00:00 2001 From: Jeremiah Senkpiel Date: Fri, 20 May 2016 10:20:08 -0400 Subject: [PATCH 1/2] tty: use blocking mode on OS X OS X has a tiny 1kb hard-coded buffer size for stdout / stderr to TTYs (terminals). Output larger than that causes chunking, which ends up having some (very small but existent) delay past the first chunk. That causes two problems: 1. When output is written to stdout and stderr at similar times, the two can become mixed together (interleaved). This is especially problematic when using control characters, such as \r. With interleaving, chunked output will often have lines or characters erased unintentionally, or in the wrong spots, leading to broken output. CLI apps often extensively use such characters for things such as progress bars. 2. Output can be lost if the process is exited before chunked writes are finished flushing. This usually happens in applications that use `process.exit()`, which isn't infrequent. See https://github.com/nodejs/node/issues/6980 for more info. This became an issue as result of the Libuv 1.9.0 upgrade. A fix to an unrelated issue broke a hack previously required for the OS X implementation. This resulted in an unexpected behavior change in node. The 1.9.0 upgrade was done in c3cec1eefc9f3b55a3fb7bd623b3d921f493870d, which was included in v6.0.0. Full details of the Libuv issue that induced this are at https://github.com/nodejs/node/issues/6456#issuecomment-219974514 Refs: https://github.com/nodejs/node/pull/1771 Refs: https://github.com/nodejs/node/issues/6456 Refs: https://github.com/nodejs/node/pull/6773 Refs: https://github.com/nodejs/node/pull/6816 PR-URL: https://github.com/nodejs/node/pull/6895 Reviewed-By: Rod Vagg Reviewed-By: Anna Henningsen --- doc/api/console.md | 6 +++++- doc/api/process.md | 11 ++++++++++- lib/tty.js | 7 +++++++ 3 files changed, 22 insertions(+), 2 deletions(-) diff --git a/doc/api/console.md b/doc/api/console.md index bbb96cb3d3e75d..ac0ce25a37c7a6 100644 --- a/doc/api/console.md +++ b/doc/api/console.md @@ -53,11 +53,15 @@ duplicate the browser's functionality exactly. ## Asynchronous vs Synchronous Consoles -The console functions are asynchronous unless the destination is a file. +The console functions are usually asynchronous unless the destination is a file. Disks are fast and operating systems normally employ write-back caching; it should be a very rare occurrence indeed that a write blocks, but it is possible. +Additionally, console functions are blocking when outputting to TTYs +(terminals) on OS X as a workaround for the OS's very small, 1kb buffer size. +This is to prevent interleaving between `stdout` and `stderr`. + ## Class: Console diff --git a/doc/api/process.md b/doc/api/process.md index cb53dc3f5b6682..b0e85746cf3548 100644 --- a/doc/api/process.md +++ b/doc/api/process.md @@ -833,7 +833,8 @@ if (someConditionNotMet()) { ``` The reason this is problematic is because writes to `process.stdout` in Node.js -are *non-blocking* and may occur over multiple ticks of the Node.js event loop. +are usually *non-blocking* and may occur over multiple ticks of the Node.js +event loop. Calling `process.exit()`, however, forces the process to exit *before* those additional writes to `stdout` can be performed. @@ -1367,6 +1368,10 @@ event and that writes can block when output is redirected to a file (although disks are fast and operating systems normally employ write-back caching so it should be a very rare occurrence indeed.) +Additionally, `process.stderr` and `process.stdout` are blocking when outputting +to TTYs (terminals) on OS X as a workaround for the OS's very small, 1kb +buffer size. This is to prevent interleaving between `stdout` and `stderr`. + ## process.stdin A `Readable Stream` for stdin (on fd `0`). @@ -1417,6 +1422,10 @@ event and that writes can block when output is redirected to a file (although disks are fast and operating systems normally employ write-back caching so it should be a very rare occurrence indeed.) +Additionally, `process.stderr` and `process.stdout` are blocking when outputting +to TTYs (terminals) on OS X as a workaround for the OS's very small, 1kb +buffer size. This is to prevent interleaving between `stdout` and `stderr`. + To check if Node.js is being run in a TTY context, read the `isTTY` property on `process.stderr`, `process.stdout`, or `process.stdin`: diff --git a/lib/tty.js b/lib/tty.js index 72efcd078b2892..fe0cc2e5219966 100644 --- a/lib/tty.js +++ b/lib/tty.js @@ -48,6 +48,13 @@ function WriteStream(fd) { writable: true }); + // Prevents interleaved stdout/stderr output in OS X terminals. + // As noted in the following reference, local TTYs tend to be quite fast and + // this behaviour has become expected due historical functionality on OS X, + // even though it was originally intended to change in v1.0.2 (Libuv 1.2.1). + // Ref: https://github.com/nodejs/node/pull/1771#issuecomment-119351671 + if (process.platform === 'darwin') this._handle.setBlocking(true); + var winSize = []; var err = this._handle.getWindowSize(winSize); if (!err) { From 88804b84ecb298d9e6525a6fbd0266ea5c357c35 Mon Sep 17 00:00:00 2001 From: Jeremiah Senkpiel Date: Fri, 20 May 2016 19:05:54 -0400 Subject: [PATCH 2/2] test: test TTY problems by fakeing a TTY using openpty Many thanks to thefourtheye and addaleax who helped make the python bits of this possible. See https://github.com/nodejs/node/issues/6980 for more info regarding the related TTY issues. Refs: https://github.com/nodejs/node/issues/6456 Refs: https://github.com/nodejs/node/pull/6773 Refs: https://github.com/nodejs/node/pull/6816 PR-URL: https://github.com/nodejs/node/pull/6895 Reviewed-By: Rod Vagg Reviewed-By: Anna Henningsen --- Makefile | 5 +- test/pseudo-tty/no_dropped_stdio.js | 15 +++ test/pseudo-tty/no_dropped_stdio.out | 21 +++ test/pseudo-tty/no_interleaved_stdio.js | 17 +++ test/pseudo-tty/no_interleaved_stdio.out | 21 +++ test/pseudo-tty/testcfg.py | 161 +++++++++++++++++++++++ tools/test.py | 67 ++++++++-- 7 files changed, 293 insertions(+), 14 deletions(-) create mode 100644 test/pseudo-tty/no_dropped_stdio.js create mode 100644 test/pseudo-tty/no_dropped_stdio.out create mode 100644 test/pseudo-tty/no_interleaved_stdio.js create mode 100644 test/pseudo-tty/no_interleaved_stdio.out create mode 100644 test/pseudo-tty/testcfg.py diff --git a/Makefile b/Makefile index 9a5bbf2f79c497..bf8adc884294ee 100644 --- a/Makefile +++ b/Makefile @@ -118,7 +118,7 @@ test: all $(MAKE) build-addons $(MAKE) cctest $(PYTHON) tools/test.py --mode=release -J \ - addon doctool known_issues message parallel sequential + addon doctool known_issues message pseudo-tty parallel sequential $(MAKE) lint test-parallel: all @@ -183,7 +183,8 @@ test-all-valgrind: test-build test-ci: | build-addons $(PYTHON) tools/test.py $(PARALLEL_ARGS) -p tap --logfile test.tap \ --mode=release --flaky-tests=$(FLAKY_TESTS) \ - $(TEST_CI_ARGS) addons doctool known_issues message parallel sequential + $(TEST_CI_ARGS) addons doctool known_issues message pseudo-tty parallel \ + sequential test-release: test-build $(PYTHON) tools/test.py --mode=release diff --git a/test/pseudo-tty/no_dropped_stdio.js b/test/pseudo-tty/no_dropped_stdio.js new file mode 100644 index 00000000000000..1a20889073ce06 --- /dev/null +++ b/test/pseudo-tty/no_dropped_stdio.js @@ -0,0 +1,15 @@ +// https://github.com/nodejs/node/issues/6456#issuecomment-219320599 +// https://gist.github.com/isaacs/1495b91ec66b21d30b10572d72ad2cdd +'use strict'; +require('../common'); + +// 1000 bytes wrapped at 50 columns +// \n turns into a double-byte character +// (48 + {2}) * 20 = 1000 +var out = ('o'.repeat(48) + '\n').repeat(20); +// Add the remaining 24 bytes and terminate with an 'O'. +// This results in 1025 bytes, just enough to overflow the 1kb OS X TTY buffer. +out += 'o'.repeat(24) + 'O'; + +process.stdout.write(out); +process.exit(0); diff --git a/test/pseudo-tty/no_dropped_stdio.out b/test/pseudo-tty/no_dropped_stdio.out new file mode 100644 index 00000000000000..78d2b7a36523a2 --- /dev/null +++ b/test/pseudo-tty/no_dropped_stdio.out @@ -0,0 +1,21 @@ +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +ooooooooooooooooooooooooO diff --git a/test/pseudo-tty/no_interleaved_stdio.js b/test/pseudo-tty/no_interleaved_stdio.js new file mode 100644 index 00000000000000..778b2c09583b90 --- /dev/null +++ b/test/pseudo-tty/no_interleaved_stdio.js @@ -0,0 +1,17 @@ +// https://github.com/nodejs/node/issues/6456#issuecomment-219320599 +// https://gist.github.com/isaacs/1495b91ec66b21d30b10572d72ad2cdd +'use strict'; +require('../common'); + +// 1000 bytes wrapped at 50 columns +// \n turns into a double-byte character +// (48 + {2}) * 20 = 1000 +var out = ('o'.repeat(48) + '\n').repeat(20); +// Add the remaining 24 bytes and terminate with an 'O'. +// This results in 1025 bytes, just enough to overflow the 1kb OS X TTY buffer. +out += 'o'.repeat(24) + 'O'; + +const err = '__This is some stderr__'; + +process.stdout.write(out); +process.stderr.write(err); diff --git a/test/pseudo-tty/no_interleaved_stdio.out b/test/pseudo-tty/no_interleaved_stdio.out new file mode 100644 index 00000000000000..f39b87ff466725 --- /dev/null +++ b/test/pseudo-tty/no_interleaved_stdio.out @@ -0,0 +1,21 @@ +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +oooooooooooooooooooooooooooooooooooooooooooooooo +ooooooooooooooooooooooooO__This is some stderr__ diff --git a/test/pseudo-tty/testcfg.py b/test/pseudo-tty/testcfg.py new file mode 100644 index 00000000000000..469903152101c1 --- /dev/null +++ b/test/pseudo-tty/testcfg.py @@ -0,0 +1,161 @@ +# Copyright 2008 the V8 project authors. All rights reserved. +# Redistribution and use in source and binary forms, with or without +# modification, are permitted provided that the following conditions are +# met: +# +# * Redistributions of source code must retain the above copyright +# notice, this list of conditions and the following disclaimer. +# * Redistributions in binary form must reproduce the above +# copyright notice, this list of conditions and the following +# disclaimer in the documentation and/or other materials provided +# with the distribution. +# * Neither the name of Google Inc. nor the names of its +# contributors may be used to endorse or promote products derived +# from this software without specific prior written permission. +# +# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS +# "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT +# LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR +# A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT +# OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, +# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT +# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, +# DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY +# THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT +# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + +import test +import os +from os.path import join, exists, basename, isdir +import re +import utils + +FLAGS_PATTERN = re.compile(r"//\s+Flags:(.*)") + +class TTYTestCase(test.TestCase): + + def __init__(self, path, file, expected, arch, mode, context, config): + super(TTYTestCase, self).__init__(context, path, arch, mode) + self.file = file + self.expected = expected + self.config = config + self.arch = arch + self.mode = mode + + def IgnoreLine(self, str): + """Ignore empty lines and valgrind output.""" + if not str.strip(): return True + else: return str.startswith('==') or str.startswith('**') + + def IsFailureOutput(self, output): + f = file(self.expected) + # Convert output lines to regexps that we can match + env = { 'basename': basename(self.file) } + patterns = [ ] + for line in f: + if not line.strip(): + continue + pattern = re.escape(line.rstrip() % env) + pattern = pattern.replace('\\*', '.*') + pattern = '^%s$' % pattern + patterns.append(pattern) + # Compare actual output with the expected + raw_lines = (output.stdout + output.stderr).split('\n') + outlines = [ s.strip() for s in raw_lines if not self.IgnoreLine(s) ] + if len(outlines) != len(patterns): + print "length differs." + print "expect=%d" % len(patterns) + print "actual=%d" % len(outlines) + print "patterns:" + for i in xrange(len(patterns)): + print "pattern = %s" % patterns[i] + print "outlines:" + for i in xrange(len(outlines)): + print "outline = %s" % outlines[i] + return True + for i in xrange(len(patterns)): + if not re.match(patterns[i], outlines[i]): + print "match failed" + print "line=%d" % i + print "expect=%s" % patterns[i] + print "actual=%s" % outlines[i] + return True + return False + + def GetLabel(self): + return "%s %s" % (self.mode, self.GetName()) + + def GetName(self): + return self.path[-1] + + def GetCommand(self): + result = [self.config.context.GetVm(self.arch, self.mode)] + source = open(self.file).read() + flags_match = FLAGS_PATTERN.search(source) + if flags_match: + result += flags_match.group(1).strip().split() + result.append(self.file) + return result + + def GetSource(self): + return (open(self.file).read() + + "\n--- expected output ---\n" + + open(self.expected).read()) + + def RunCommand(self, command, env): + full_command = self.context.processor(command) + output = test.Execute(full_command, + self.context, + self.context.GetTimeout(self.mode), + env, + True) + self.Cleanup() + return test.TestOutput(self, + full_command, + output, + self.context.store_unexpected_output) + + +class TTYTestConfiguration(test.TestConfiguration): + + def __init__(self, context, root): + super(TTYTestConfiguration, self).__init__(context, root) + + def Ls(self, path): + if isdir(path): + return [f[:-3] for f in os.listdir(path) if f.endswith('.js')] + else: + return [] + + def ListTests(self, current_path, path, arch, mode): + all_tests = [current_path + [t] for t in self.Ls(self.root)] + result = [] + # Skip these tests on Windows, as pseudo terminals are not available + if utils.IsWindows(): + print ("Skipping pseudo-tty tests, as pseudo terminals are not available" + " on Windows.") + return result + for test in all_tests: + if self.Contains(path, test): + file_prefix = join(self.root, reduce(join, test[1:], "")) + file_path = file_prefix + ".js" + output_path = file_prefix + ".out" + if not exists(output_path): + print "Could not find %s" % output_path + continue + result.append(TTYTestCase(test, file_path, output_path, + arch, mode, self.context, self)) + return result + + def GetBuildRequirements(self): + return ['sample', 'sample=shell'] + + def GetTestStatus(self, sections, defs): + status_file = join(self.root, 'message.status') + if exists(status_file): + test.ReadConfigurationInto(status_file, sections, defs) + + +def GetConfiguration(context, root): + return TTYTestConfiguration(context, root) diff --git a/tools/test.py b/tools/test.py index a8df0b937ec66e..ab3da337bc6a24 100755 --- a/tools/test.py +++ b/tools/test.py @@ -576,11 +576,17 @@ def RunProcess(context, timeout, args, **rest): error_mode = SEM_NOGPFAULTERRORBOX; prev_error_mode = Win32SetErrorMode(error_mode); Win32SetErrorMode(error_mode | prev_error_mode); + + faketty = rest.pop('faketty', False) + pty_out = rest.pop('pty_out') + process = subprocess.Popen( shell = utils.IsWindows(), args = popen_args, **rest ) + if faketty: + os.close(rest['stdout']) if utils.IsWindows() and context.suppress_dialogs and prev_error_mode != SEM_INVALID_VALUE: Win32SetErrorMode(prev_error_mode) # Compute the end time - if the process crosses this limit we @@ -592,6 +598,29 @@ def RunProcess(context, timeout, args, **rest): # loop and keep track of whether or not it times out. exit_code = None sleep_time = INITIAL_SLEEP_TIME + output = '' + if faketty: + while True: + if time.time() >= end_time: + # Kill the process and wait for it to exit. + KillProcessWithID(process.pid) + exit_code = process.wait() + timed_out = True + break + + # source: http://stackoverflow.com/a/12471855/1903116 + # related: http://stackoverflow.com/q/11165521/1903116 + try: + data = os.read(pty_out, 9999) + except OSError as e: + if e.errno != errno.EIO: + raise + break # EIO means EOF on some systems + else: + if not data: # EOF + break + output += data + while exit_code is None: if (not end_time is None) and (time.time() >= end_time): # Kill the process and wait for it to exit. @@ -604,7 +633,7 @@ def RunProcess(context, timeout, args, **rest): sleep_time = sleep_time * SLEEP_TIME_FACTOR if sleep_time > MAX_SLEEP_TIME: sleep_time = MAX_SLEEP_TIME - return (process, exit_code, timed_out) + return (process, exit_code, timed_out, output) def PrintError(str): @@ -626,29 +655,43 @@ def CheckedUnlink(name): PrintError("os.unlink() " + str(e)) break -def Execute(args, context, timeout=None, env={}): - (fd_out, outname) = tempfile.mkstemp() - (fd_err, errname) = tempfile.mkstemp() +def Execute(args, context, timeout=None, env={}, faketty=False): + if faketty: + import pty + (out_master, fd_out) = pty.openpty() + fd_err = fd_out + pty_out = out_master + else: + (fd_out, outname) = tempfile.mkstemp() + (fd_err, errname) = tempfile.mkstemp() + pty_out = None # Extend environment env_copy = os.environ.copy() for key, value in env.iteritems(): env_copy[key] = value - (process, exit_code, timed_out) = RunProcess( + (process, exit_code, timed_out, output) = RunProcess( context, timeout, args = args, stdout = fd_out, stderr = fd_err, - env = env_copy + env = env_copy, + faketty = faketty, + pty_out = pty_out ) - os.close(fd_out) - os.close(fd_err) - output = file(outname).read() - errors = file(errname).read() - CheckedUnlink(outname) - CheckedUnlink(errname) + if faketty: + os.close(out_master) + errors = '' + else: + os.close(fd_out) + os.close(fd_err) + output = file(outname).read() + errors = file(errname).read() + CheckedUnlink(outname) + CheckedUnlink(errname) + return CommandOutput(exit_code, timed_out, output, errors)