AIX: pseudo-tty/no_dropped_stdio failures on new machine

[mhdawson]

• Version: master
• Platform: AIX
• Subsystem: io

Failures on new AIX machine: https://ci.nodejs.org/job/node-test-commit-aix/nodes=aix61-ppc64/283/console

# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: 1 == 42
#     at ChildProcess. (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/parallel/test-stdio-closed.js:25:10)
#     at ChildProcess. (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/common.js:411:15)
#     at emitTwo (events.js:106:13)
#     at ChildProcess.emit (events.js:191:7)
#     at Process.ChildProcess._handle.onexit (internal/child_process.js:204:12)
  ---


  ...
length differs.
expect=21
actual=0
patterns:
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^oooooooooooooooooooooooooooooooooooooooooooooooo$
pattern = ^ooooooooooooooooooooooooO$
outlines:
not ok 1170 pseudo-tty/no_dropped_stdio
  ---
  duration_ms: 0.186

[Fishrock123]

@mhdawson Anything different about this new machine? Didn't it pass on the old ones?

[jbergstroem]

Related to JOBS= ?

[mhdawson]

It did pass on the old one. The previous machine was a vm from siteox with different levels of the OS as opposed to the new ones that are from osusol. I have asked @gireeshpunathil to investigate.

[gireeshpunathil]

The test case want to make sure every byte that is written to the standard stream is drained before the process exits, basically 1025 characters with 21 new lines.

The test case seem to have devised to validate an OS X behavior on the 1025th character. However in AIX case, at times it receives none while the python parent expects 21 lines.

The stdout of the child is piped into a tempfile, which is later read by the python parent.

I tried to isolate the issue in a number of manners without success: (though many of these different variant of one or two discrete scenarios)

1. node no_dropped_stdio.js | xargs echo
2. node no_dropped_stdio.js | wc -c
3. node no_dropped_stdio.js > out.txt 2>&1
4. A ndoe parent with piped streams for the child
5. A node parent with inherited streams for the child
6. A node parent with file fd passed for child streams and later read from the file

So it looks like the python parent in the test framework has something peculiar or the machine I am running is different from the new CI one.

@mhdawson how easy it is to get hold of the failing CI system for debugging?

[mhdawson]

Created this request to get Gireesh access nodejs/build#463

[Fishrock123]

@gireeshpunathil None of those will work correctly. Your examples are all pipes.

You need to use a faked TTY. Either via pty.js or via the python test runner in pseudo-tty, which uses a faked TTY. (Code mostly in tools/test.py.)

To be clear: if AIX actually fails this then there is a big problem on AIX even if the test was designed for OS X.

[gireeshpunathil]

Thanks @Fishrock123 - yes, I agree that all the above cases are variants of pipes.

I actually debugged the python code, and validated that the spawing code does not use faketty in this specific scenario, rather creates a temp file, its fd piped into the child node's streams, and then upon child termination, close the fd and read from the file - hence my attempt to mimic the behavior through case 6 above.

However, this is really useful information, I will study the faketty and debug further by taking lead from that. Thanks for the suggestion.

[Fishrock123]

@gireeshpunathil it is possible that the python fake tty does not work on AIX -- in which case these tests should be disabled there.

[mhdawson]

@gireeshpunathil I just want to make sure you are investigating both failures

parallel/test-stdio-closed
pseudo-tty/no_dropped_stdio

parallel/test-stdio-closed - fails in every run
pseudo-tty/no_dropped_stdio - I've not seen fail in the community CI again, however, internally (IBM) we've reproduced with 316/1000 if you need help to reproduce follow up with @sxa555 or Jeremiah Akpotohwo in hursley

[mhdawson]

Have provided @gireeshpunathil with access to community machine

[mhdawson]

@gireeshpunathil have you had a change to look at this ?

[gireeshpunathil]

@mhdawson - yes, but is a slow progress. Any major findings, I will post here.

[gireeshpunathil]

just a status update: no major insights so far. Issue seen as consistent, trying to localize it into a python / python + C test case: to eliminate node's role in it.

[mhdawson]

Does this investigation apply to one or both of:

1. parallel/test-stdio-closed
2. pseudo-tty/no_dropped_stdio

?

[gireeshpunathil]

This is only for 2) pseudo-tty/no_dropped_stdio

[gireeshpunathil]

ok, came up with a small python code which works well in Linux but hangs in AIX. This is detached from node, which means that the problem is outside the node scope. While the code comes out immediately in Linux, the usage of fake_out for the stdout causes the python thread to hang in close() call.

import os
import subprocess
import pty

arg = ['ls', '-lrt']
(out_master, fd_out) = pty.openpty()
process = subprocess.Popen(
  args = arg,
  stdout = fd_out
)

os.close(fd_out)

I think the psuedo-tty tests should be omitted for AIX, while the python behavioral difference is understood and or addressed - as they don't reveal any issues in node instead blocks the test logic due to the python bug.

[gireeshpunathil]

parallel/test-stdio-closed failure - test case performs the following:

1. spawns a child (shell) with inhertied streams from parent.
2. the shell executes a child node, whose streams are inherently closed.
3. Child writes to stdout, and then onto stderr, and then exits with a specific error code.
4. Parent asserts on the error code.

In Linux, the child executes the stream writes and then exits with the specified error code (42).
In AIX, the child exits on the first attempt to write on to the closed stream (error code:1)

And hence the failure:
AssertionError: 1 == 42

Investigating further.

[Fishrock123]

Should we be marking pseudo-tty/no_dropped_stdio as flaky on AIX? Or is it already and I missed it?

[mhdawson]

Pulled out stdio failure from description in initial text for report since it is not being worked in this issue and does not seem related. #8375

[mhdawson]

Just talking with @gireeshpunathil , I'll submit a PR to mark as flaky

[mhdawson]

PR to mark as flaky https://github.com/nodejs/node/pull/8385/files

[mhdawson]

Make sure to un-exclude this one as well once resolved: #9765