Occasional fail of zproc test, reading stdout #2007

jimklimov · 2019-05-21T10:51:20Z

From https://api.travis-ci.org/v3/job/533238563/log.txt :

/bin/sh ./libtool --mode=execute ./src/czmq_selftest
Assertion failed: (stdout_read), function zproc_test, file src/zproc.c, line 1242.
Running czmq selftests...
...
 * zargs: OK

 * zproc: make[2]: *** [check-local] Abort trap: 6

make[1]: *** [check-am] Error 2
make: *** [check-recursive] Error 1

travis_time:end:01892487:start=1558002346156497000,finish=1558002550603141000,duration=204446644000

The text was updated successfully, but these errors were encountered:

mbakke · 2019-07-19T12:59:05Z

This test consistently fails for me on a 3.5 GHz Haswell Xeon system, but I am unable to reproduce it on a 2.5GHz Sandy Bridge i5.

[...]
 * zauth: OK
 * zbeacon: OK (skipping test, no UDP broadcasting)                                                
E: (czmq_selftest) 19-07-19 14:53:18 No broadcast interface found, (ZSYS_INTERFACE=)               
./src/zsp: line 150: ls: command not found                                                         
czmq_selftest: src/zproc.c:1263: zproc_test: Assertion `!zproc_running (self)' failed.
make[2]: *** [Makefile:2295: check-local] Aborted

In this particular environment, ls is only available deep in PATH, so it looks like there is some kind of race going on.

stale · 2019-10-17T13:20:51Z

This issue has been automatically marked as stale because it has not had recent activity for 90 days. It will be closed if no further activity occurs within 21 days. Thank you for your contributions.

vyskocilm · 2019-10-17T15:16:57Z

Hi @jimklimov is it still the case? I've checked latest build failures at TravisCI, however zproject was not a problem.

@mbakke this is weird, AFAIK ls is not used anywhere inside.

Anyway output of make check-verbose would be nice to have.

jimklimov · 2019-10-17T21:05:08Z

@mvyskocil : gotta check, did not look at this for a while. However a link between faults and system speed (in test or possibly production too?) sou ds worrysome and un-21st century like ;\

vyskocilm · 2019-10-28T17:02:06Z

I don't have 3.5GHz system to test. However if there is really a race condition, it must happen on slower systems as well. I wrote simple tool running zproc test million times szproc.go. So far I figured out that testcase #7 is timing senstitive and I got very weird failure on line 1239

Anyway any hints about the bug would be nice

Either make check-verbose output
Or even better run make debug after a failure and print me the stack trace and frames

I'll keep running the test to see what will happen

vyskocilm · 2019-11-04T14:54:53Z

Hi,

I've asked a friend with an access to more CPU powerful machine to make a test. I did a small Alpine based Docker container for him, so @mbakke if you are around, feel free to run it as well

docker run --ulimit core=99999999999:99999999999 --cap-add=SYS_PTRACE vyskocilm/zsdk:alpine-3.8 make check

If reproduced, I will need the core file stored inside the container. The exact naming and location depends on a kernel.

stale · 2020-02-02T15:48:41Z

This issue has been automatically marked as stale because it has not had recent activity for 90 days. It will be closed if no further activity occurs within 21 days. Thank you for your contributions.

stale · 2020-05-02T17:01:00Z

This issue has been automatically marked as stale because it has not had recent activity for 90 days. It will be closed if no further activity occurs within 21 days. Thank you for your contributions.

pyhalov · 2020-06-23T15:47:49Z

Have 100% fails on zproc test on illumos (OpenIndiana).
It looks like timer checking for process exit status is not run. Look - there's no waitid() calls

$ truss -t waitid,kill -f ./libtool --mode=execute ./src/czmq_selftest -t zproc -v
....
27187/7:        waitid(P_PID, 27320, 0xFE54EE20, WEXITED|WTRAPPED|WNOHANG) = 0
D: 20-06-23 18:43:07 zproc_wait [27320]:        WIFEXITED, self->return_code=0
D: 20-06-23 18:43:07 zproc_wait [27320]: timeout=0
D: 20-06-23 18:43:07 zproc_wait [27320]:        !self->running=false
D: 20-06-23 18:43:07 zproc_wait [27320]: timeout=0
D: 20-06-23 18:43:07 zproc_wait [27320]:        !self->running=false
D: 20-06-23 18:43:07 zproc_test() : got stdout from helper, 10000 msec was remaining to retry
D: 20-06-23 18:43:07 zproc_test[1170] czmq is great

czmq is great

czmq is great

czmq is great

czmq is gr...
D: 20-06-23 18:43:08 zproc_test() : did not get stdout from helper, but we already have some (9200 msec remaining to retry)
D: 20-06-23 18:43:08 zproc_wait [27320]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27320]:        !self->running=false
D: 20-06-23 18:43:08 zproc_wait [27320]: timeout=5000
D: 20-06-23 18:43:08 zproc_wait [27320]:        !self->running=false
D: 20-06-23 18:43:08 zproc_wait [27320]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27320]:        !self->running=false
D: 20-06-23 18:43:08 zproc_test() : launching helper './src/zsp'
D: 20-06-23 18:43:08 API command=RUN
D: 20-06-23 18:43:08 process ./src/zsp with pid 27360 started
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=1000
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
27360:      Received signal #15, SIGTERM [default]
27360:        siginfo: SIGTERM pid=27187 uid=101
27187/1:        kill(27360, SIGTERM)                            = 0
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=1000
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
27187/1:            Received signal #18, SIGCLD [default]
27187/1:              siginfo: SIGCLD CLD_KILLED pid=27360 status=0x000F
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
27187/1:        kill(27360, SIGKILL)                            = 0
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=1000
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
D: 20-06-23 18:43:08 zproc_wait [27360]: timeout=0
D: 20-06-23 18:43:08 zproc_wait [27360]:        !self->running=true
D: 20-06-23 18:43:08 zproc_wait [27360]:        waitpid
Assertion failed: !zproc_running (self), file src/zproc.c, line 1263, function zproc_test
27187/1:            Received signal #6, SIGABRT [default]
27187/1:              siginfo: SIGABRT pid=27187 uid=101 code=-1

From core file we see that actor thread is still waiting for something:

> ::walk thread | ::findstack 
stack pointer for thread 1: 80472e8
[ 080472e8 libc.so.1`_lwp_kill+0x15() ]
  08047308 libc.so.1`raise+0x2b()
  08047358 libc.so.1`abort+0xed()
  08047588 0xfee52a44()
  08047a18 libczmq.so.4.2.0`zproc_test+0xfcf()
  08047a68 main+0x1e8()
  08047aa8 _start_crt+0x96()
  08047ac8 _start+0x1a()
stack pointer for thread 2 [ZMQbg/Reaper]: fe78eed8
[ fe78eed8 libc.so.1`__pollsys+0x15() ]
  fe78ef08 libc.so.1`poll+0x61()
  fe78ef48 libzmq.so.5.2.2`_ZN3zmq6poll_t4loopEv+0x77()
  fe78efc8 libzmq.so.5.2.2`thread_routine+0xf6()
  fe78efe8 libc.so.1`_thrp_setup+0x81()
  fe78eff8 libc.so.1`_lwp_start()
stack pointer for thread 3 [ZMQbg/IO/0]: fe67eed8
[ fe67eed8 libc.so.1`__pollsys+0x15() ]
  fe67ef08 libc.so.1`poll+0x61()
  fe67ef48 libzmq.so.5.2.2`_ZN3zmq6poll_t4loopEv+0x77()
  fe67efc8 libzmq.so.5.2.2`thread_routine+0xf6()
  fe67efe8 libc.so.1`_thrp_setup+0x81()
  fe67eff8 libc.so.1`_lwp_start()
stack pointer for thread 8: fe54edb8
[ fe54edb8 libc.so.1`__pollsys+0x15() ]
  fe54ede8 libc.so.1`poll+0x61()
  fe54eee8 libzmq.so.5.2.2`zmq_poll+0x276()
  fe54ef48 libczmq.so.4.2.0`zloop_start+0x303()
  fe54ef98 libczmq.so.4.2.0`s_zproc_actor+0x6c()
  fe54efc8 libczmq.so.4.2.0`s_thread_shim+0x2c()
  fe54efe8 libc.so.1`_thrp_setup+0x81()
  fe54eff8 libc.so.1`_lwp_start()

pyhalov · 2020-06-26T07:35:43Z

I found an issue:
https://github.com/zeromq/czmq/blob/master/src/zproc.c#L847 has

  int quit = zclock_mono () + timeout;
        while (true) {
            if (! zproc_running (self))
                break;
            if (zclock_mono () >= quit)
                break;
            zclock_sleep (200);
        }

but zclock_mono() is int64_t , so we have integer overflow here.

sappo · 2020-06-26T07:50:36Z

Thanks for investigating :) It would be great if you could send a PR 👍 Am Fr., 26. Juni 2020 um 09:35 Uhr schrieb Alexander Pyhalov < notifications@github.com>:

…

I found an issue: https://github.com/zeromq/czmq/blob/master/src/zproc.c#L847 has int quit = zclock_mono () + timeout; while (true) { if (! zproc_running (self)) break; if (zclock_mono () >= quit) break; zclock_sleep (200); } but zclock_mono() is int64_t , so we have integer overflow here. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#2007 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADYNOTOZVPYAI6TCSHUDIDRYRFV5ANCNFSM4HOJYAXA> .

vyskocilm · 2020-08-18T10:36:51Z

@pyhalov are you sure this is the case? overflow is indeed possible, but it'd require zclock_mono() to return value close to INT64_MAX or a huge timeout value. And even if the value of quit will overflow, the zclock_mono() >= quit will end the loop immediately.

What might be a problem is the zclock_mono () go above INT64_MAX itself 🤷

vyskocilm · 2020-08-18T10:37:49Z

@pyhalov sorry - I did not notice your PR 🤦 so was testing code you've fixed. Sorry.

stale · 2020-12-05T05:07:25Z

This issue has been automatically marked as stale because it has not had recent activity for 90 days. It will be closed if no further activity occurs within 21 days. Thank you for your contributions.

Apteryks · 2021-06-06T00:37:50Z

Confirming this as fixed in 4.2.1. Thanks!

stale bot added the stale label Oct 17, 2019

stale bot removed the stale label Oct 17, 2019

stale bot added the stale label Feb 2, 2020

bluca removed the stale label Feb 2, 2020

stale bot added the stale label May 2, 2020

bluca removed the stale label May 2, 2020

pyhalov mentioned this issue Jun 26, 2020

Problem: "quit" variable in zproc_wait() can overflow #2090

Merged

stale bot added the stale label Dec 5, 2020

stale bot closed this as completed Dec 26, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Occasional fail of zproc test, reading stdout #2007

Occasional fail of zproc test, reading stdout #2007

jimklimov commented May 21, 2019

mbakke commented Jul 19, 2019

stale bot commented Oct 17, 2019

vyskocilm commented Oct 17, 2019

jimklimov commented Oct 17, 2019

vyskocilm commented Oct 28, 2019

vyskocilm commented Nov 4, 2019

stale bot commented Feb 2, 2020

stale bot commented May 2, 2020

pyhalov commented Jun 23, 2020 •

edited

Loading

pyhalov commented Jun 26, 2020

sappo commented Jun 26, 2020 via email

vyskocilm commented Aug 18, 2020

vyskocilm commented Aug 18, 2020

stale bot commented Dec 5, 2020

Apteryks commented Jun 6, 2021

Occasional fail of zproc test, reading stdout #2007

Occasional fail of zproc test, reading stdout #2007

Comments

jimklimov commented May 21, 2019

mbakke commented Jul 19, 2019

stale bot commented Oct 17, 2019

vyskocilm commented Oct 17, 2019

jimklimov commented Oct 17, 2019

vyskocilm commented Oct 28, 2019

vyskocilm commented Nov 4, 2019

stale bot commented Feb 2, 2020

stale bot commented May 2, 2020

pyhalov commented Jun 23, 2020 • edited Loading

pyhalov commented Jun 26, 2020

sappo commented Jun 26, 2020 via email

vyskocilm commented Aug 18, 2020

vyskocilm commented Aug 18, 2020

stale bot commented Dec 5, 2020

Apteryks commented Jun 6, 2021

pyhalov commented Jun 23, 2020 •

edited

Loading