- Version: 1.x
- Platform: AIX.
I noticed some failures in history so I ran a few builds. These don't fail every time but there seem to be some intermittent failures.
The seem to be mostly on test-osuosl-aix61-ppc64_be-2 so might be machine related.
https://ci.nodejs.org/job/libuv-test-commit-aix/1099/
https://ci.nodejs.org/job/libuv-test-commit-aix/1096/
ok 118 - homedir
not ok 119 - hrtime
# exit code 393222
# Output from process `hrtime`:
# Assertion failed in test/test-hrtime.c on line 50: diff < (uint64_t) 80 * NANOSEC / MILLISEC
not ok 189 - shutdown_close_pipe
# exit code 393222
# Output from process `shutdown_close_pipe`: (no output)
Output from process `shutdown_close_pipe`:
# Assertion failed in test/test-shutdown-close.c on line 55: status == 0
not ok 223 - tcp6_ping_pong
# exit code 393222
# Output from process `tcp6_ping_pong`: (no output)
Output from process `tcp6_ping_pong`:
# Assertion failed in test/test-ping-pong.c on line 156: status == 0
mhdawson
All 39 comments
Logging onto test-osuosl-aix61-ppc64_be-2 I don't see any stray processes so its not that.
@gireeshpunathil can you take a look to see if you can recreate/figure out what is going on?
mhdawson
on 16 Oct 2018
sure, will have a look.
gireeshpunathil
on 17 Oct 2018
not ok 119 - hrtime
May be addressed by https://github.com/libuv/libuv/pull/1997.
richardlau
on 17 Oct 2018
@gireeshpunathil any updates on this?
mhdawson
on 22 Oct 2018
I was unable to locally build for this one to be tested - as some of the build components were missing in the systems. It should be resolved by now, and I should be able to test these.
gireeshpunathil
on 22 Oct 2018
finally got away with build issues.
Ran the tests many times, but unable to reproduce locally.
As @richardlau pointed out, failure in test/test-hrtime.c could be fixed by #1997, I don't see any instance of that failure any more.
However, the other two failures are recurring in CI.
In one, the test just created a TCP socket and tried to connect to it, but the connect status in the connect callback is non-zero.
In another, the test just created a pipe and tried to connect to it, but the connect status in the connect callback is non-zero.
There is nothing suspecious in these two tests, as those were in action for a long time and are frozen. In addition, there are many tests that follow the same pattern: create, connect, check for connection status; and none of those fail.
these 2 runs suggest more pronounced cases in terms of the failing pattern:
https://ci.nodejs.org/job/libuv-test-commit-aix/nodes=aix61-ppc64/1108/console
https://ci.nodejs.org/job/libuv-test-commit-aix/nodes=aix61-ppc64/1107/console
My guess is that this has something to do with the network load on the system: either at the time of test run, or something that was caused by one of the tests itself.
Either way, I would want to access one of the failing systems, as this is not reproducible locally. thanks!
gireeshpunathil
on 23 Oct 2018
For some reason, I thought you already had access to the AIX machines. @gdams can you open issue to request access for Gireesh and then add keys when approved?
mhdawson
on 23 Oct 2018
I used to have access on and off. this year there wasn't much turbulences in AIX, so my access was revoked.
gireeshpunathil
on 23 Oct 2018
@gireeshpunathil makes sense, we'll get you access again.
mhdawson
on 23 Oct 2018
got access, thanks all.
trying to reproduce on one of the CI systems and take it from thereon.
gireeshpunathil
on 23 Oct 2018
Ran many iterations, unable to reproduce.
Looked at one of the failing site, a tcp client is trying to connect to localhost:TEST_PORT (9123)
As the server is not in the test case, it would have been started elsewhere.
echo-server.c contain some common helper routines, tcp4_echo_server is the routine that starts the server in this case.
so I brute-forced the server to crash:
diff --git a/test/echo-server.c b/test/echo-server.c
index bfed676..467c00f 100644
--- a/test/echo-server.c
+++ b/test/echo-server.c
@@ -336,7 +336,7 @@ static int pipe_echo_start(char* pipeName) {
HELPER_IMPL(tcp4_echo_server) {
loop = uv_default_loop();
+ *(int *) 0 = 0;
if (tcp4_echo_start(TEST_PORT))
return 1;
and got this result, producing symptoms that match our failures, but affecting much more tests.
not ok 11 - callback_stack
# exit code 393350
# Output from process `callback_stack`: (no output)
Output from process `callback_stack`:
# Connecting...
# Connected. Write some data to echo server...
# Assertion failed in test/test-callback-stack.c on line 153: status == 0
not ok 191 - shutdown_close_tcp
# exit code 393350
# Output from process `shutdown_close_tcp`: (no output)
Output from process `shutdown_close_tcp`:
# Assertion failed in test/test-shutdown-close.c on line 55: status == 0
not ok 192 - shutdown_eof
# exit code 393350
# Output from process `shutdown_eof`: (no output)
Output from process `shutdown_eof`:
# Assertion failed in test/test-shutdown-eof.c on line 88: status == 0
not ok 193 - shutdown_twice
# exit code 393350
# Output from process `shutdown_twice`: (no output)
Output from process `shutdown_twice`:
# Assertion failed in test/test-shutdown-twice.c on line 49: status == 0
not ok 253 - tcp_open
# exit code 393350
# Output from process `tcp_open`: (no output)
Output from process `tcp_open`:
# Assertion failed in test/test-tcp-open.c on line 191: status == 0
not ok 255 - tcp_open_connected
# exit code 393350
# Output from process `tcp_open_connected`: (no output)
Output from process `tcp_open_connected`:
# Assertion failed in test/test-tcp-open.c on line 345: 0 == connect(sock, (struct sockaddr*) &addr, sizeof(addr))
not ok 257 - tcp_ping_pong
# exit code 393350
# Output from process `tcp_ping_pong`: (no output)
Output from process `tcp_ping_pong`:
# Assertion failed in test/test-ping-pong.c on line 156: status == 0
not ok 258 - tcp_ping_pong_vec
# exit code 393350
# Output from process `tcp_ping_pong_vec`: (no output)
Output from process `tcp_ping_pong_vec`:
# Assertion failed in test/test-ping-pong.c on line 156: status == 0
not ok 259 - tcp_read_stop
# exit code 393350
# Output from process `tcp_read_stop`: (no output)
Output from process `tcp_read_stop`:
# Assertion failed in test/test-tcp-read-stop.c on line 53: 0 == status
ok 260 - tcp_ref
ok 261 - tcp_ref2
ok 262 - tcp_ref2b
not ok 263 - tcp_ref3
# exit code 393350
# Output from process `tcp_ref3`: (no output)
Output from process `tcp_ref3`:
# Assertion failed in test/test-ref.c on line 96: status == 0
not ok 264 - tcp_ref4
# exit code 393350
# Output from process `tcp_ref4`: (no output)
Output from process `tcp_ref4`:
# Assertion failed in test/test-ref.c on line 87: status == 0
not ok 265 - tcp_shutdown_after_write
# exit code 393350
# Output from process `tcp_shutdown_after_write`: (no output)
Output from process `tcp_shutdown_after_write`:
# Assertion failed in test/test-tcp-shutdown-after-write.c on line 83: status == 0
ok 266 - tcp_try_write
ok 267 - tcp_unexpected_read
ok 268 - tcp_write_after_connect
not ok 269 - tcp_write_fail
# exit code 393350
# Output from process `tcp_write_fail`: (no output)
Output from process `tcp_write_fail`:
# Assertion failed in test/test-tcp-write-fail.c on line 77: status == 0
ok 270 - tcp_write_queue_order
not ok 271 - tcp_write_ready
# exit code 393350
# Output from process `tcp_write_ready`: (no output)
Output from process `tcp_write_ready`:
# Assertion failed in test/test-tcp-open.c on line 215: status == 0
ok 272 - tcp_write_to_half_open_connection
not ok 273 - tcp_writealot
# timeout
# Output from process `tcp_writealot`: (no output)
Output from process `tcp_writealot`:
# Assertion failed in test/test-tcp-writealot.c on line 119: status == 0
Inferences:
- when test failed, the echo server was unavailable.
- as only a handful of tests fail in CI, server was not completely unavailable, like in the above case
- as some CI runs show more failures of same kind, the unavailability of echo server looks sporadic.
Open questions:
- what causes echo server to be flaky?
- what causes it to be available sometime and unavailable some other time?
- what libuv changes could have made this change in behavior?
AIX is known for timing differences in terms of socket operations. so are we (client) connecting too early to the server?
gireeshpunathil
on 24 Oct 2018
Failures seem to happen in CI mostly on test-osuosl-aix61-ppc64_be-2, looks to me like @refack gave you access to test-osuosl-aix61-ppc64_be-1. So worth trying to reproduced on -2 instead.
I'll add your key there.
mhdawson
on 24 Oct 2018
-2 is 140.211.9.100
mhdawson
on 24 Oct 2018
thanks, will switch over to it and try.
gireeshpunathil
on 24 Oct 2018
[email protected]: Permission denied (publickey).
something went wrong? can you please check again?
gireeshpunathil
on 24 Oct 2018
got it (access issue to osuosl-2) resolved/
gireeshpunathil
on 24 Oct 2018
unable to see the failure in many runs.
so I suspect it has to do with stale processes running in the system when CI was run, and a port conflict.
I see a bunch of processes being run on the system, coming on and off. for example:
iojs 9175056 7536806 120 00:37:14 - 0:01 /opt/freeware/libexec/gcc/powerpc-ibm-aix6.1.0.0/4
iojs 9306296 10616982 120 00:37:13 - 0:02 /opt/freeware/libexec/gcc/powerpc-ibm-aix6.1.0.0/4
iojs 10027152 1 0 Sep 12 - 30:29 /home/iojs/jdk8/jre/bin/java -Xmx128m -Dorg.jenkin
iojs 10158192 10027152 0 00:05:26 - 0:00 /bin/sh -xe /tmp/jenkins6505569825358187200.sh
iojs 10420412 7208964 9 00:37:15 - 0:00 ccache /opt/freeware/bin/ccache/g++ -o /home/iojs/
iojs 10485858 7208964 2 00:37:13 - 0:00 ccache /opt/freeware/bin/ccache/g++ -o /home/iojs/
iojs 10616982 10682608 0 00:37:13 - 0:00 /usr/bin/g++ -pthread -Wall -Wextra -Wno-unused-pa
iojs 10682608 13041794 1 00:37:12 - 0:00 /opt/freeware/bin/ccache/g++ -pthread -Wall -Wextr
iojs 11206724 6226144 1 00:37:16 - 0:00 /usr/bin/g++ -pthread -Wall -Wextra -Wno-unused-pa
iojs 12255264 7208964 18 00:37:15 - 0:00 ccache /opt/freeware/bin/ccache/g++ -o /home/iojs/
iojs 12320950 10158192 0 00:05:46 - 0:00 gmake run-ci -j 5
iojs 13041794 7208964 1 00:37:11 - 0:00 ccache /opt/freeware/bin/ccache/g++ -o /home/iojs/
iojs 13107452 11206724 116 00:37:16 - 0:00 /opt/freeware/libexec/gcc/powerpc-ibm-aix6.1.0.0/4
iojs 13631552 10485858 5 00:37:14 - 0:00 /opt/freeware/bin/ccache/g++ -pthread -Wall -Wextr
root 13762734 4128840 0 00:35:13 - 0:00 /usr/sbin/rpc.statd -d 0 -t 50
iojs 14155894 12320950 0 00:05:53 - 0:00 gmake
iojs 14680292 6815894 1 00:37:16 - 0:00 /usr/bin/g++ -pthread -Wall -Wextra -Wno-unused-pa
I am suspecting these are Node.js CI jobs?
If so, how both Node.js and libuv CIs are synchronized? what is the chance that they collide?
can someone detach this from Node CI and trigger a libuv CI on this system please?
gireeshpunathil
on 25 Oct 2018
There is only 1 executor on each machine, so only one job should be able to run at a time.
Have you tried to see if it still recreates when you run through CI? You might have to run a few jobs to force it onto be-2?
mhdawson
on 25 Oct 2018
are there steps to run a CI directly in the machine? if so, please point me to that. I don't have job execution access to libuv's jenkins web interface. thanks.
gireeshpunathil
on 25 Oct 2018
Created https://github.com/libuv/libuv/issues/2055 to request access for you so that you can launch through jenkins UI.
mhdawson
on 25 Oct 2018
You should be able to launch CI jobs jobs now. The 2 I started earlier both ran on be-1 and passed, so issue seems related to be-2 if it still re-occurs.
mhdawson
on 25 Oct 2018
adding @gdams in so he is in the loop in case it turns out to be a machine issue.
mhdawson
on 25 Oct 2018
gireeshpunathil
on 25 Oct 2018
It probably makes sense to restart the jenkins agent to see if that makes a difference since it still seems to fail and it did not recreate with a local run.
mhdawson
on 25 Oct 2018
ok restarted agent:
CI run: https://ci.nodejs.org/view/libuv/job/libuv-test-commit-aix/1122/nodes=aix61-ppc64/
mhdawson
on 25 Oct 2018
ok, did some further testing, and here we are:
the test runner is implemented via run_test (test/runner.c) that starts the helper first (parts of tests that spawns separate processes, mostly an echo server) and then fires the actual test.
there is an arbitrary delay (250 ms) that is allted between the helper processes launch and the actual test that depends on it.
As the sorrounding comment already suggests, this is race-y. In AIX (be-2) this time is consistently proved to be insufficient. If I adjust this time, I am able to fail tests in any platform, in the said manner.
passing case
echo server is setup first
+1860 14680214: 72155297: socket(1, 1, 0) = 12
+1861 14680214: 72155297: kfcntl(12, F_GETFL, 0x0000000000000000) = 2
+1862 14680214: 72155297: kfcntl(12, F_SETFL, 0x0000000000000006) = 0
+1863 14680214: 72155297: kioctl(12, -2147195266, 0x0FFFFFFFFFFFF168, 0x0000000000000000) = 0
+1864 14680214: 72155297: kfcntl(12, F_SETFD, 0x0000000000000001) = 0
+1865 14680214: 72155297: bind(12, 0x0FFFFFFFFFFFF244, 1025) = 0
+1866 14680214: 72155297: listen(12, 1024) = 0
...
test is run next
+2050 10944754: 64487527: socket(1, 1, 0) = 13
+2051 10944754: 64487527: kfcntl(13, F_GETFL, 0x0000000000000000) = 2
+2052 10944754: 64487527: kfcntl(13, F_SETFL, 0x0000000000000006) = 0
+2053 10944754: 64487527: kioctl(13, -2147195266, 0x0FFFFFFFFFFFF2A8, 0x0000000000000000) = 0
+2054 10944754: 64487527: kfcntl(13, F_SETFD, 0x0000000000000001) = 0
+2055 10944754: 64487527: connext(13, 0x0FFFFFFFFFFFF37C, 1025) = 0
failing case:
test is run first
+1901 13369598: 32636933: socket(1, 1, 0) = 13
+1902 13369598: 32636933: kfcntl(13, F_GETFL, 0x0000000000000000) = 2
+1903 13369598: 32636933: kfcntl(13, F_SETFL, 0x0000000000000006) = 0
+1904 13369598: 32636933: kioctl(13, -2147195266, 0x0FFFFFFFFFFFF2A8, 0x0000000000000000) = 0
+1905 13369598: 32636933: kfcntl(13, F_SETFD, 0x0000000000000001) = 0
+1906 13369598: 32636933: connext(13, 0x0FFFFFFFFFFFF37C, 1025) Err#2 ENOENT
+1907 13369598: 32636933: kwrite(2, " A s s e r t i o n f a".., 20) = 20
echo server is run next
+2058 11993334: 65273985: socket(1, 1, 0) = 12
+2059 11993334: 65273985: kfcntl(12, F_GETFL, 0x0000000000000000) = 2
+2060 11993334: 65273985: kfcntl(12, F_SETFL, 0x0000000000000006) = 0
+2061 11993334: 65273985: kioctl(12, -2147195266, 0x0FFFFFFFFFFFF168, 0x0000000000000000) = 0
+2062 11993334: 65273985: kfcntl(12, F_SETFD, 0x0000000000000001) = 0
+2063 11993334: 65273985: bind(12, 0x0FFFFFFFFFFFF244, 1025) = 0
+2064 11993334: 65273985: listen(12, 1024) = 0
this was reported earlier in https://github.com/libuv/libuv/issues/1871
Simpply increasing this to a more reasonable value does not seem to be great here due to:
- it does not remove the falky-ness fully, though the frequency of failure reduces.
- added delay here affects every tests, so overall test run time is linearly increased.
As the helper process are not a single type, implementing a generic wait also seem to be difficult. A more structured way of doinf this would be to define a protocol where the test runner waits for a signal from the spawned child which raises the signal only when it is ready.
gireeshpunathil
on 29 Oct 2018
the last sentence was supposed to be a question, not a statement.
gireeshpunathil
on 29 Oct 2018
I guess it'd be nice to fix this if for no other reason than that 250 ms times ~350 tests adds well over a minute to a test suite run. I'll have a look.
bnoordhuis
on 29 Oct 2018
2056
bnoordhuis
on 29 Oct 2018
CI confirms that #2056 fixes the race. Only process_title_threadsafe is left now and that looks like a genuine bug.
bnoordhuis
on 29 Oct 2018
@bnoordhuis - awesome. Apart from fixing the issue, this one has improved the overall test time too!
gireeshpunathil
on 29 Oct 2018
There still seems to be failures on be-2
not ok 182 - process_title_threadsafe
# exit code 393222
# Output from process `process_title_threadsafe`:
# Assertion failed in test/test-process-title-threadsafe.c on line 50: 0 == strcmp(buffer, titles[0]) || 0 == strcmp(buffer, titles[1]) || 0 == strcmp(buffer, titles[2]) || 0 == strcmp(buffer, titles[3])
@bnoordhuis can you re-open this?
https://ci.nodejs.org/view/libuv/job/libuv-test-commit-aix/1132/nodes=aix61-ppc64/console
mhdawson
on 1 Nov 2018
Hmm, it also seemed to fail on be-1 as well.
mhdawson
on 1 Nov 2018
I don't think the process_title_threadsafe failures are specific to AIX. I've noticed that test failing sporadically since it was added.
cjihrig
on 1 Nov 2018
Yeah, it usually fails on OS X too
santigimeno
on 1 Nov 2018
The reported issues are all resolved in AIX, so am prepared to request https://github.com/nodejs/build/issues/1545 and #2055 to be resolved and closed; but just wanted to check on the OSX failure of process_title_threadsafe - who knows about it more, is there an open issue for that, and is anyone debugging that already? or else I will attempt to recreate, as I have the most context of the issue by now, thanks /cc @richardlau @santigimeno @cjihrig
gireeshpunathil
on 11 Nov 2018
@gireeshpunathil I don't think anyone is looking into it (maybe @davisjam, not sure). However, Ben recently landed https://github.com/libuv/libuv/pull/2064, which may (or may not) help there.
cjihrig
on 11 Nov 2018
thanks @cjihrig for the pointers. I took the latest v1.x and ran a 1K times, did not see any failure.
I also changed the NUM_ITERATIONS to 500 (from 50) and setter_threads to 10 (from 4) and ran a 2K times but did not see a single failure.
So I deem the OS X issue does not exist any more / resolved by #2064.
gireeshpunathil
on 12 Nov 2018
Thanks for looking into it @gireeshpunathil!
cjihrig
on 12 Nov 2018
Related issues
skypjack
路
9Comments
cjihrig
路
5Comments
mchandler-blizzard
路
6Comments
fliser
路
7Comments
imran-iq
路
7Comments