AIX: Intermittent failure on pseudo-tty/test-tty-wrap

[mhdawson]

• Version: master and 4.x
• Platform: AIX
• Subsystem: pseudo-tty

Seen a few intermittent failures in the pseudo-tty/test-tty-wrap test today

https://ci.nodejs.org/job/node-test-commit-aix/1998/nodes=aix61-ppc64/
https://ci.nodejs.org/job/node-test-commit-aix/1988/nodes=aix61-ppc64/

length differs.
expect=2
actual=0
patterns:
pattern = ^hello\ world\ 1$
pattern = ^hello\ world\ 2$
outlines:
not ok 1242 pseudo-tty/test-tty-wrap
  ---
  duration_ms: 0.150
  severity: fail
  stack: |-
  ...

[mhdawson]

stress run - https://ci.nodejs.org/job/node-stress-single-test/nodes=aix61-ppc64/1067/

[Trott]

/cc @Fishrock123

[Fishrock123]

I am very confused. What? How?

[Fishrock123]

Oh I see, no output is produced? Oh dear.

I guess you've triggered the exit bug with load alone?? ¯\_(ツ)_/¯

[gibfahn]

cc/ @nodejs/platform-aix @Akpotohwo

[mhdawson]

Passed 200 runs in stress build.

[Akpotohwo]

Failed 24 times in 3100 on one of our aix machines... It's the same failure as shown earlier.

[mhdawson]

Good to hear you can recreate.

[mhdawson]

Failed again in the build today. https://ci.nodejs.org/job/node-test-commit-aix/nodes=aix61-ppc64/2433/

@Akpotohwo any update on the investigation ?

[mhdawson]

Failed again https://ci.nodejs.org/job/node-test-commit-aix/nodes=aix61-ppc64/2566/console

[Trott]

Again today:

https://ci.nodejs.org/job/node-test-commit-aix/2736/nodes=aix61-ppc64/console:

length differs.
expect=2
actual=0
patterns:
pattern = ^hello\ world\ 1$
pattern = ^hello\ world\ 2$
outlines:
not ok 1288 pseudo-tty/test-tty-wrap
  ---
  duration_ms: 0.158
  severity: fail
  stack: |-

[Trott]

I guess you've triggered the exit bug with load alone?? ¯_(ツ)_/¯

@Fishrock123 (or anyone else that knows): Can you elaborate a bit on "the exit bug"? Is there a link or something?

[Trott]

Should this be marked as flaky on AIX similar to no_dropped_stdio and no_interleaved_stdio? Is it likely failing for the same reasons?

[mhdawson]

@Trott Given that we have seen relatively regularly I'll plan to ahead and mark it as flaky.

[mhdawson]

@gibfahn I'll submit a PR to excluded, can you follow up on where our investigation stands on this one.

[mhdawson]

PR to exclude: https://ci.nodejs.org/job/node-test-pull-request/5702/

[gibfahn]

PR: #10618

[gibfahn]

@Akpotohwo if you're looking at pseudo-tty test failures on AIX it might be worth looking at #7973 as well.

[gireeshpunathil]

Investigated further, and got these inferences:

There are 2 problems with the pseudo-tty tests:
i) child (node) data getting truncated at parent (python),
ii) hang in parent.

This subject test (tty-wrap) mostly undergoes (i) and occasionally, (ii).

Root cause for (i):

Passing behavior:

2687288:        16056741: kopen("/dev/pts/4", O_RDWR)           = 14
...
2687288:        16056741: kwrite(14, " h e l l o   w o r l d  ".., 14) = 14
4850562: 10945517: kread(3, " h e l l o   w o r l d  ".., 9999) = 15
2687288:        16056741: kwrite(14, " h e l l o   w o r l d  ".., 14) = 14
4850562: 10945517: kread(3, " h e l l o   w o r l d  ".., 9999) = 15

Failing behavior:

852692: kopen("/dev/pts/4", O_RDWR)                     = 14
...
852692: kwrite(14, " h e l l o   w o r l d  ".., 14)    = 14
852692: kwrite(14, " h e l l o   w o r l d  ".., 14)    = 14
852692: _exit(0)
4325988: 13435549: kread(3, "\0\0\0\0\0\0\0\0\0\0\0\0".., 9999) Err#5  EIO

By the time the child is completely terminated, having its side of the fd closed. Subsequent read by the parent results in EIO, equivalent to a broken pipe.

Hang root cause is not identified, but recreated in a small python + C test case:

bash-4.3$ cat parent.py
#!/usr/bin/env python
import errno
import os
import pty
from subprocess import Popen, STDOUT

master_fd, slave_fd = pty.openpty()
proc = Popen(['./a.out'],stdout=slave_fd, close_fds=True)
os.close(slave_fd)
data = os.read(master_fd, 512)
print('got ' + repr(data))

bash-4.3$ cat child.cc
#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>

int main()
{
        printf("hello world\n");
        exit(0);
}
bash-4.3$ 

This issue is raised with python community: python 29545 , but no one seem to have picked it up yet.

For (i): I see an issue with the test case - it assumes that the parent can read from the fd irrespective of the child's life span and exit status, however it works always in Linux, magically. AIX uses different process scheduling policies that Linux, and gets affected by this. We have seen many issues in other tests, failure reason a function of the order of execution of child vs. parent soon after the fork.

A 100 ms delay after the child write and before exit consistently resolves the issue. This test and no_dropped_stdio.js - 7973 are affected by this.

@mhdawson @Fishrock123 @gibfahn - please let me know what you think, if you agree I will come up with a PR to this effect.

[gibfahn]

@gireeshpunathil if a 100ms delay fixes this consistently on AIX then that seems reasonable to me.

[mhdawson]

Is there a way to have the parent signal the child when it has completed its write so that we can avoid a timeout ? For example if the parent could write 'done' to the childs stdin when it had read. Delays are always problematic so want to be sure we don't have any other way to achieve the same result.

[gireeshpunathil]

@mhdawson - while it is technically possible for the parent to acknowledge the data and make it a mandate to receive the ack for child to exit, the python parent (testcfg.py) is the main drver also for the rest of the tests in test/pseudo-tty, furthermore it delegates the child spawning work to tools/test.py which is much more generic (drives the whole test). So I guess changing the parent logic to ack. can have side effects elsewhere.
/cc @Fishrock123

[gireeshpunathil]

So the approach of synchronizing between parent child has issues:

1. The python driver's child spawing routine (RunProcess()) is not designed to write back to child.
2. On the other hand, none of the children (node test cases) are designed to live indefinitely or listen for events / data from parent.
3. If we re-design this to communicate between them, the tests will hang. Here is why:

• The only way parent finishes reading data from the child is when it encounters EIO (when child exits) and break-exit the tight read loop. (or timeout expiry)
• There is no way for the parent to otherwise understand the child has finished writing. This is because each child has different data and difference sequence of writing the data.
• If we insert a process.stdin.on('data') event on child in expecation of an acknowledgement from parent, this is never going to happen - the parent continues to attempt reading until it times out - as the read error will never occur (child is alive)

4. We can send a 'special data' indicating the write-finish from the child to circumvent this, but given that this will warrant a change in all the children (node test cases) and the issue occurs only in AIX, I would think we address the race condition in the failing tests alone, by adding a reasonable delay before exit. [ we have done this in many other test cases where AIX-(other os) disparity was visible w.r.t process scheduling.

possibilities:

1. Modify the python parent to read a 'special data' to terminate the read loop. Then acknowledge the data reception back to the child. Modify 'every' child programs to add the 'special data' at the end of the test, and then setup a read loop to receive the ACK, before exiting.

2. Modify affected test cases to provide additional delay, supplying necessary leeway for the parent to read the data before exiting.

I am fine in either way, suggestions are much appreciated.
/cc @mhdawson @Fishrock123 @gibfahn

[gibfahn]

I'm still +1 on adding a delay, it seems like a vastly simpler option.

[gibfahn]

@gireeshpunathil so to clarify, would adding a delay fix the issue for pseudo-tty/test-tty-wrap, or do we need to get the underlying Python bug fixed first?

[gireeshpunathil]

@gibfahn - as per clarified here - this issue is root caused by the python bug in question, and cannot be circumvented through time delay. The python parent gets trapped in the system on an fd close call, without recovery

[Trott]

This hasn't recurred in some time. Feel free to re-open (or leave a comment requesting that it be re-opened) if you disagree, but I'm inclined to close at this time. I'm just tidying up and not acting on a super-strong opinion or anything like that.

[sam-github]

This is still referenced in

node/test/pseudo-tty/pseudo-tty.status

Line 4 in 6447be6

# being investigated under https://github.com/nodejs/node/issues/9728

If we close it, shouldn't we also remove the reference to it? Or perhaps change the ref to nodejs/build#1820?

Or perhaps, I misunderstand the meaning of test-tty-wrap : FAIL, PASS? That seems to imply the test is considered sucessful if it passes or if it fails, which seems to cover all the options, and not be so useful.

[Trott]

@sam-github Yes, you are correct: That entry should be removed. #28129