[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20181127151004.GB15742@zipoli.concurrent-rt.com>
Date: Tue, 27 Nov 2018 15:10:07 +0000
From: Joe Korty <Joe.Korty@...current-rt.com>
To: Clark Williams <williams@...hat.com>
CC: Steven Rostedt <rostedt@...dmis.org>,
"julia@...com" <julia@...com>,
"tglx@...utronix.de" <tglx@...utronix.de>,
"bigeasy@...utronix.de" <bigeasy@...utronix.de>,
"oleg@...hat.com" <oleg@...hat.com>,
"linux-rt-users@...r.kernel.org" <linux-rt-users@...r.kernel.org>,
"linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
John Kacur <jkacur@...hat.com>
Subject: Re: [ptrace, rt] erratic behaviour in PTRACE_SINGLESET on 4.13-rt and
later.
On Tue, Nov 27, 2018 at 08:58:19AM -0600, Clark Williams wrote:
> Joe,
>
> This looks interesting. Do you have a git repo where I can pull the
> source?
>
> Clark
Hi Clark,
No I don't, sorry. I am attaching the LAG version, it is a few
dozen lines shorter than the version I first sent out to the
mailing list.
Joe
PS: Oh, I forgot to do....
Signed-off-by: Joe Korty <joe.korty@...current-rt.com>
> On Tue, 20 Nov 2018 12:29:00 -0500
> Steven Rostedt <rostedt@...dmis.org> wrote:
>
> > [ Adding Clark and John who manage the rt-tests repo ]
> >
> > -- Steve
> >
> > On Mon, 19 Nov 2018 19:46:23 +0000
> > Joe Korty <Joe.Korty@...current-rt.com> wrote:
> >
> > > Hi Julia & the RT team,
> > >
> > > The following program might make a good addition to the rt
> > > test suite. It tests the reliability of PTRACE_SINGLESTEP.
> > > It does by default 10,000 ssteps against a simple,
> > > spinner tracee. Also by default, it spins off ten of these
> > > tracer/tracee pairs, all of which are to run concurrently.
> > >
> > > Starting with 4.13-rt, this test occasionally encounters a
> > > sstep whose waitpid returns a WIFSIGNALED (signal SIGTRAP)
> > > rather than a WIFSTOPPED. This usually happens after
> > > thousands of ssteps have executed. Having multiple
> > > tracer/tracee pairs running dramatically increases the
> > > chances of failure.
> > >
> > > The is what the test output looks like for a good run:
> > >
> > > #forks: 10
> > > #steps: 10000
> > >
> > > forktest#0/22872: STARTING
> > > forktest#7/22879: STARTING
> > > forktest#8/22880: STARTING
> > > forktest#6/22878: STARTING
> > > forktest#5/22877: STARTING
> > > forktest#3/22875: STARTING
> > > forktest#4/22876: STARTING
> > > forktest#9/22882: STARTING
> > > forktest#2/22874: STARTING
> > > forktest#1/22873: STARTING
> > > forktest#0/22872: EXITING, no error
> > > forktest#8/22880: EXITING, no error
> > > forktest#3/22875: EXITING, no error
> > > forktest#7/22879: EXITING, no error
> > > forktest#6/22878: EXITING, no error
> > > forktest#5/22877: EXITING, no error
> > > forktest#2/22874: EXITING, no error
> > > forktest#4/22876: EXITING, no error
> > > forktest#9/22882: EXITING, no error
> > > forktest#1/22873: EXITING, no error
> > > All tests PASSED.
> > >
> > > This is what the test output looks like for a failing run:
> > >
> > > #forks: 10
> > > #steps: 10000
> > >
> > > forktest#0/22906: STARTING
> > > forktest#1/22907: STARTING
> > > forktest#2/22909: STARTING
> > > forktest#3/22911: STARTING
> > > forktest#4/22912: STARTING
> > > forktest#5/22915: STARTING
> > > forktest#6/22916: STARTING
> > > forktest#7/22919: STARTING
> > > forktest#8/22920: STARTING
> > > forktest#9/22923: STARTING
> > > forktest#2/22909: EXITING, ERROR: wait on PTRACE_SINGLESTEP #9: wanted STATE_STOPPED, saw STATE_SIGNALED instead (and saw signo 5 too)
> > > forktest#5/22915: EXITING, no error
> > > forktest#3/22911: EXITING, ERROR: wait on PTRACE_SINGLESTEP #7953: wanted STATE_STOPPED, saw STATE_SIGNALED instead (and saw signo 5 too)
> > > forktest#0/22906: EXITING, ERROR: wait on PTRACE_SINGLESTEP #5072: wanted STATE_STOPPED, saw STATE_SIGNALED instead (and saw signo 5 too)
> > > forktest#9/22923: EXITING, ERROR: wait on PTRACE_SINGLESTEP #7992: wanted STATE_STOPPED, saw STATE_SIGNALED instead (and saw signo 5 too)
> > > forktest#4/22912: EXITING, ERROR: wait on PTRACE_SINGLESTEP #9923: wanted STATE_STOPPED, saw STATE_SIGNALED instead (and saw signo 5 too)
> > > forktest#1/22907: EXITING, ERROR: wait on PTRACE_SINGLESTEP #7723: wanted STATE_STOPPED, saw STATE_SIGNALED instead (and saw signo 5 too)
> > > forktest#7/22919: EXITING, ERROR: wait on PTRACE_SINGLESTEP #5036: wanted STATE_STOPPED, saw STATE_SIGNALED instead (and saw signo 5 too)
> > > forktest#8/22920: EXITING, ERROR: wait on PTRACE_SINGLESTEP #4943: wanted STATE_STOPPED, saw STATE_SIGNALED instead (and saw signo 5 too)
> > > forktest#6/22916: EXITING, no error
> > > One or more tests FAILED.
> > >
> > > Here are the observations from my testing so far:
> > >
> > > - It has never failed when confined to a single cpu.
> > > - It has never failed on !rt kernels.
> > > - It has never failed on any kernel prior to 4.13.
> > > - More failures than what chance would dictate happen
> > > near the end of a test run (ie, if a test of 10,000
> > > steps is run, the failure will be at the 9,xxx'th step,
> > > if 100,000 steps are run, the failure will be at
> > > the 9x,xxx'th step).
> > >
> > > The above results are from kernels 4.{4,9,11,13,14,19}-rt
> > > and some !rt's of these as well.
> > >
> > > I have yet to see or hear of this bug, if it is a bug,
> > > giving anyone a problem in a debug session. It might not
> > > even be a bug but merely expected behaviour. And of course
> > > there is the possibility of a misuse of ptrace/waitpid in
> > > my test program. Its API, after all, is rather convoluted.
> > >
> > > Regards,
> > > Joe
> > >
> > >
> > >
> > >
> > > /*
> > > * Have a tracer do a bunch of PTRACE_SINGLESTEPs against
> > > * a tracee as fast as possible. Create several of these
> > > * tracer/tracee pairs and see if they can be made to
> > > * interfere with each other.
> > > *
> > > * Usage:
> > > * ssdd nforks niters
> > > * Where:
> > > * nforks - number of tracer/tracee pairs to fork off.
> > > * default 10.
> > > * niters - number of PTRACE_SINGLESTEP iterations to
> > > * do before declaring success, for each tracer/
> > > * tracee pair set up. Default 10,000.
> > > *
> > > * The tracee waits on each PTRACE_SINGLESTEP with a waitpid(2)
> > > * and checks that waitpid's return values for correctness.
> > > */
> > > #include <stdio.h>
> > > #include <stdlib.h>
> > > #include <stddef.h>
> > > #include <unistd.h>
> > > #include <string.h>
> > > #include <signal.h>
> > > #include <errno.h>
> > >
> > > #include <sys/types.h>
> > > #include <sys/wait.h>
> > > #include <sys/ptrace.h>
> > >
> > > /* do_wait return values */
> > > #define STATE_EXITED 1
> > > #define STATE_STOPPED 2
> > > #define STATE_SIGNALED 3
> > > #define STATE_UNKNOWN 4
> > > #define STATE_ECHILD 5
> > > #define STATE_EXITED_TSIG 6 /* exited with termination signal */
> > > #define STATE_EXITED_ERRSTAT 7 /* exited with non-zero status */
> > >
> > > char *state_name[] = {
> > > [STATE_EXITED] = "STATE_EXITED",
> > > [STATE_STOPPED] = "STATE_STOPPED",
> > > [STATE_SIGNALED] = "STATE_SIGNALED",
> > > [STATE_UNKNOWN] = "STATE_UNKNOWN",
> > > [STATE_ECHILD] = "STATE_ECHILD",
> > > [STATE_EXITED_TSIG] = "STATE_EXITED_TSIG",
> > > [STATE_EXITED_ERRSTAT] = "STATE_EXITED_ERRSTAT"
> > > };
> > >
> > > const char *get_state_name(int state)
> > > {
> > > if (state < STATE_EXITED || state > STATE_EXITED_ERRSTAT)
> > > return "?";
> > > return state_name[state];
> > > }
> > >
> > > #define unused __attribute__((unused))
> > >
> > > static int got_sigchld;
> > >
> > > static int do_wait(pid_t *wait_pid, int *ret_sig)
> > > {
> > > int status, child_status;
> > >
> > > *ret_sig = -1; /* initially mark 'nothing returned' */
> > >
> > > while (1) {
> > > status = waitpid(-1, &child_status, WUNTRACED | __WALL);
> > > if (status == -1) {
> > > if (errno == EINTR)
> > > continue;
> > > if (errno == ECHILD) {
> > > *wait_pid = (pid_t)0;
> > > return STATE_ECHILD;
> > > }
> > > printf("do_wait/%d: EXITING, ERROR: "
> > > "waitpid() returned errno %d\n",
> > > getpid(), errno);
> > > exit(1);
> > > }
> > > break;
> > > }
> > > *wait_pid = (pid_t)status;
> > >
> > > if (WIFEXITED(child_status)) {
> > > if (WIFSIGNALED(child_status))
> > > return STATE_EXITED_TSIG;
> > > if (WEXITSTATUS(child_status))
> > > return STATE_EXITED_ERRSTAT;
> > > return STATE_EXITED;
> > > }
> > > if (WIFSTOPPED(child_status)) {
> > > *ret_sig = WSTOPSIG(child_status);
> > > return STATE_STOPPED;
> > > }
> > > if (WIFSIGNALED(child_status)) {
> > > *ret_sig = WTERMSIG(child_status);
> > > return STATE_SIGNALED;
> > > }
> > > return STATE_UNKNOWN;
> > > }
> > >
> > > int check_sigchld(void)
> > > {
> > > int i;
> > > /*
> > > * The signal is asynchronous so give it some
> > > * time to arrive.
> > > */
> > > for (i = 0; i < 10 && !got_sigchld; i++)
> > > usleep(1000); /* 10 msecs */
> > > for (i = 0; i < 10 && !got_sigchld; i++)
> > > usleep(2000); /* 20 + 10 = 30 msecs */
> > > for (i = 0; i < 10 && !got_sigchld; i++)
> > > usleep(4000); /* 40 + 30 = 70 msecs */
> > > for (i = 0; i < 10 && !got_sigchld; i++)
> > > usleep(8000); /* 80 + 40 = 150 msecs */
> > > for (i = 0; i < 10 && !got_sigchld; i++)
> > > usleep(16000); /* 160 + 150 = 310 msecs */
> > > for (i = 0; i < 10 && !got_sigchld; i++)
> > > usleep(32000); /* 320 + 310 = 630 msecs */
> > >
> > > return got_sigchld;
> > > }
> > >
> > > pid_t parent;
> > > int nforks = 10;
> > > int nsteps = 10000;
> > >
> > > static void sigchld(int sig, unused siginfo_t * info, unused void *arg)
> > > {
> > > got_sigchld = 1;
> > > }
> > >
> > > static void child_process(void)
> > > {
> > > unused volatile int i;
> > >
> > > /* wait for ptrace attach */
> > > usleep(100000);
> > > while (1)
> > > i = 0;
> > > }
> > >
> > > static int forktests(int testid)
> > > {
> > > int i, status, ret_sig;
> > > long pstatus;
> > > pid_t child, wait_pid;
> > > struct sigaction act, oact;
> > >
> > > parent = getpid();
> > > printf("forktest#%d/%d: STARTING\n", testid, parent);
> > >
> > > child = fork();
> > > if (child == -1) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "fork returned errno %d\n", testid, parent, errno);
> > > exit(1);
> > > }
> > > if (!child)
> > > child_process();
> > >
> > > act.sa_sigaction = sigchld;
> > > sigemptyset(&act.sa_mask);
> > > act.sa_flags = SA_SIGINFO;
> > > status = sigaction(SIGCHLD, &act, &oact);
> > > if (status) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "sigaction returned %d, errno %d\n",
> > > testid, parent, status, errno);
> > > exit(1);
> > > }
> > >
> > > /* give both our child and parent time to set things up */
> > > usleep(125000);
> > >
> > > /*
> > > * Attach to the child.
> > > */
> > > pstatus = ptrace(PTRACE_ATTACH, child, NULL, NULL);
> > > if (pstatus == ~0l) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "attach failed. errno %d\n",
> > > testid, getpid(), errno);
> > > exit(1);
> > > }
> > >
> > > /*
> > > * The attach should cause the child to receive a signal.
> > > */
> > > status = do_wait(&wait_pid, &ret_sig);
> > > if (wait_pid != child) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "attach: Unexpected wait pid %d\n",
> > > testid, getpid(), wait_pid);
> > > exit(1);
> > > }
> > > if (status != STATE_STOPPED) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "attach: wait on PTRACE_ATTACH returned %d "
> > > "[%s, wanted STATE_STOPPED], signo %d\n",
> > > testid, getpid(), status, get_state_name(status),
> > > ret_sig);
> > > exit(1);
> > > }
> > > else if (!check_sigchld()) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "wait on PTRACE_ATTACH saw a SIGCHLD count of %d, should be 1\n",
> > > testid, getpid(), got_sigchld);
> > > exit(1);
> > > }
> > > got_sigchld = 0;
> > >
> > >
> > > /*
> > > * Generate 'nsteps' PTRACE_SINGLESTEPs, make sure they all actually step
> > > * the tracee.
> > > */
> > > for (i = 0; i < nsteps; i++) {
> > > pstatus = ptrace(PTRACE_SINGLESTEP, child, NULL, NULL);
> > >
> > > if (pstatus) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "PTRACE_SINGLESTEP #%d: returned status %ld, "
> > > "errno %d, signo %d\n",
> > > testid, getpid(), i, pstatus, errno, ret_sig);
> > > exit(1);
> > > }
> > >
> > > status = do_wait(&wait_pid, &ret_sig);
> > > if (wait_pid != child) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "wait on PTRACE_SINGLESTEP #%d: returned wrong pid %d, "
> > > "expected %d\n",
> > > testid, getpid(), i, wait_pid, child);
> > > exit(1);
> > > }
> > > if (status != STATE_STOPPED) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "wait on PTRACE_SINGLESTEP #%d: wanted STATE_STOPPED, "
> > > "saw %s instead (and saw signo %d too)\n",
> > > testid, getpid(), i,
> > > get_state_name(status), ret_sig);
> > > exit(1);
> > > }
> > > if (ret_sig != SIGTRAP) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "wait on PTRACE_SINGLESTEP #%d: returned signal %d, "
> > > "wanted SIGTRAP\n",
> > > testid, getpid(), i, ret_sig);
> > > exit(1);
> > > }
> > > if (!check_sigchld()) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "wait on PTRACE_SINGLESTEP #%d: no SIGCHLD seen "
> > > "(signal count == 0), signo %d\n",
> > > testid, getpid(), i, ret_sig);
> > > exit(1);
> > > }
> > > got_sigchld = 0;
> > > }
> > >
> > > /*
> > > * We are all done, kill the tracee and wait for it to die. We test
> > > * the killing results as much as the above attach and sstep results,
> > > * though failure here really isn't the point of this test.
> > > */
> > > status = kill(child, SIGKILL);
> > >
> > > if (status) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "kill of child %d returned %d\n",
> > > testid, getpid(), child, errno);
> > > exit(1);
> > > }
> > >
> > > status = do_wait(&wait_pid, &ret_sig);
> > > if (wait_pid != child) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "kill: Unexpected wait pid %d\n",
> > > testid, getpid(), wait_pid);
> > > exit(1);
> > > }
> > > if (status != STATE_SIGNALED) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "kill: Unexpected child, do_wait status %d "
> > > "[%s, wanted STATE_SIGNALED]\n",
> > > testid, getpid(), status, get_state_name(status));
> > > exit(1);
> > > }
> > > if (ret_sig != SIGKILL) {
> > > printf("forktest#%d/%d: EXITING, ERROR: "
> > > "kill: Unexpected child signal %d\n",
> > > testid, getpid(), ret_sig);
> > > exit(1);
> > > }
> > >
> > > printf("forktest#%d/%d: EXITING, no error\n", testid, parent);
> > > exit(0);
> > > }
> > >
> > > int main(int argc, char **argv)
> > > {
> > > int i, ret_sig, status;
> > > pid_t child = 0, wait_pid;
> > > int error = 0;
> > >
> > > setbuf(stdout, NULL);
> > >
> > > argc--, argv++;
> > > if (argc) {
> > > nforks = atoi(*argv);
> > > argc--, argv++;
> > > if (argc)
> > > nsteps = atoi(*argv);
> > > }
> > > printf("#forks: %d\n", nforks);
> > > printf("#steps: %d\n", nsteps);
> > > printf("\n");
> > >
> > > for (i = 0; i < nforks; i++) {
> > > child = fork();
> > > if (child == -1) {
> > > printf("main: fork returned errno %d\n", errno);
> > > exit(1);
> > > }
> > > if (!child)
> > > forktests(i);
> > > }
> > >
> > > for (i = 0; i < nforks; i++) {
> > > status = do_wait(&wait_pid, &ret_sig);
> > > if (status != STATE_EXITED) {
> > > if (0) printf("main/%d: ERROR: "
> > > "forktest#%d unexpected do_wait status %d "
> > > "[%s, wanted STATE_EXITED]\n",
> > > getpid(), wait_pid, status,
> > > get_state_name(status));
> > > error = 1;
> > > }
> > > }
> > >
> > > printf("%s.\n", error ?
> > > "One or more tests FAILED" :
> > > "All tests PASSED");
> > > exit(error);
> > > }
> >
>
>
> --
> The United States Coast Guard
> Ruining Natural Selection since 1790
View attachment "ssdd.c" of type "text/plain" (8043 bytes)
Powered by blists - more mailing lists