Investigate flaky sequential/test-child-process-execsync on AIX

[Trott]

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

Host: test-osuosl-aix61-ppc64_be-1

00:47:03 not ok 2377 sequential/test-child-process-execsync
00:47:03   ---
00:47:03   duration_ms: 3.701
00:47:03   severity: fail
00:47:03   exitcode: 1
00:47:03   stack: |-
00:47:03     /bin/sh: iamabadcommand:  not found.
00:47:03     assert.js:86
00:47:03       throw new AssertionError(obj);
00:47:03       ^
00:47:03     
00:47:03     AssertionError [ERR_ASSERTION]: Expected values to be strictly deep-equal:
00:47:03     + actual - expected
00:47:03     
00:47:03     + null
00:47:03     - 'SIGILL'
00:47:03         at spawnSyncKeys.forEach (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-child-process-execsync.js:138:14)
00:47:03         at Array.forEach (<anonymous>)
00:47:03         at Object.assert.throws (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-child-process-execsync.js:136:19)
00:47:03         at expectedException (assert.js:568:19)
00:47:03         at expectsError (assert.js:663:16)
00:47:03         at Function.throws (assert.js:694:3)
00:47:03         at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-child-process-execsync.js:127:10)
00:47:03         at Module._compile (internal/modules/cjs/loader.js:721:30)
00:47:03         at Object.Module._extensions..js (internal/modules/cjs/loader.js:732:10)
00:47:03         at Module.load (internal/modules/cjs/loader.js:620:32)
00:47:03   ...

[gireeshpunathil]

this was reported way back in 2015 through nodejs/node-v0.x-archive#9444 and was fixed through #1214 , don't know what has changed recently. I will have a look.

[gireeshpunathil]

ok, spent some time on this. there are 2 puzzles to solve:

the stack message (`/bin/sh: iamabadcommand: not found.) indicates that the failure is in this section,

node/test/sequential/test-child-process-execsync.js

Lines 63 to 65 in 4aabd7e

	assert.throws(function() {
	execSync('iamabadcommand');
	}, /Command failed: iamabadcommand/);

where as the actual stack of the failure suggests it is at

node/test/sequential/test-child-process-execsync.js

Line 138 in 4aabd7e

assert.deepStrictEqual(err[key], spawnSyncResult[key]);

at which point the actual command that is run as a child is NOT iamabadcommand, instead node -e process.exit(1)

So this warrants a question about at what point the python parent captures the data pertinent to stack: |- as it do not seem to be coherent with the fail site.

2. If we take AssertionError as shown in the second part to be bona-fide, then it indicates unexpected and improper exit from the child (SIGILL as opposed to null). Though I could not replicate this failure in a 1000 local runs, there is a contextual indication that this is in same as the exit-race with workers, as seen frequently through test-cli-syntax family of tests.

I will run more with ulimit -c unlimited to see if I get a core dump, which will mostly tell us a conclusive story.

[gireeshpunathil]

I ran a 10K times locally, and no sign of failure. I don't think running more is worth.

So I conclude this has to do with the resource (CPU, memory, and other user limits) on CI.

@Trott - is it possible for you to get me ulimit -a output from the failing CI machine? I will attempt to mimic the same values in my dev box and see how it behaves. thanks!

[Trott]

@Trott - is it possible for you to get me ulimit -a output from the failing CI machine? I will attempt to mimic the same values in my dev box and see how it behaves. thanks!

ansible-playbook playbooks/write-ssh-config.yml fails for me so I no longer have access to any hosts. Hopefully someone on @nodejs/build can log in and run the command to get you results. (Alternatively, we can have a CI run it by, for example, creating a branch with a test that runs the command. But that's getting pretty convoluted....)

[Trott]

Woot! Fixed my ansible problem. So here you go:

$ ssh test-osuosl-aix61-ppc64_be-1 ulimit -a
time(seconds)        unlimited
file(blocks)         2097151
data(kbytes)         131072
stack(kbytes)        32768
memory(kbytes)       32768
coredump(blocks)     2097151
nofiles(descriptors) 2000
threads(per process) unlimited
processes(per user)  unlimited
$ 

[Trott]

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

test-osuosl-aix61-ppc64_be-1

not ok 2383 sequential/test-child-process-execsync
  ---
  duration_ms: 2.473
  severity: fail
  exitcode: 1
  stack: |-
    /bin/sh: iamabadcommand:  not found.
    assert.js:86
      throw new AssertionError(obj);
      ^
    
    AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
    
    null !== 1
    
        at Object.assert.throws (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-child-process-execsync.js:134:12)
        at expectedException (assert.js:568:19)
        at expectsError (assert.js:663:16)
        at Function.throws (assert.js:694:3)
        at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-child-process-execsync.js:127:10)
        at Module._compile (internal/modules/cjs/loader.js:718:30)
        at Object.Module._extensions..js (internal/modules/cjs/loader.js:729:10)
        at Module.load (internal/modules/cjs/loader.js:617:32)
        at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
        at Function.Module._load (internal/modules/cjs/loader.js:552:3)
  ...

[Trott]

And again. Probably time to mark this as flaky.

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

test-osuosl-aix61-ppc64_be-2

21:40:41 not ok 2383 sequential/test-child-process-execsync
21:40:41   ---
21:40:41   duration_ms: 5.83
21:40:41   severity: fail
21:40:41   exitcode: 1
21:40:41   stack: |-
21:40:41     /bin/sh: iamabadcommand:  not found.
21:40:41     assert.js:86
21:40:41       throw new AssertionError(obj);
21:40:41       ^
21:40:41     
21:40:41     AssertionError [ERR_ASSERTION]: Expected values to be strictly deep-equal:
21:40:41     + actual - expected
21:40:41     
21:40:41     + null
21:40:41     - 'SIGILL'
21:40:41         at spawnSyncKeys.forEach (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-child-process-execsync.js:138:14)
21:40:41         at Array.forEach (<anonymous>)
21:40:41         at Object.assert.throws (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-child-process-execsync.js:136:19)
21:40:41         at expectedException (assert.js:568:19)
21:40:41         at expectsError (assert.js:663:16)
21:40:41         at Function.throws (assert.js:694:3)
21:40:41         at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-child-process-execsync.js:127:10)
21:40:41         at Module._compile (internal/modules/cjs/loader.js:718:30)
21:40:41         at Object.Module._extensions..js (internal/modules/cjs/loader.js:729:10)
21:40:41         at Module.load (internal/modules/cjs/loader.js:617:32)
21:40:41   ...