[Toybox] weird timeout flake

[enh]

On Tue, Oct 3, 2023 at 3:40 PM enh <enh at google.com> wrote:
>
> On Tue, Oct 3, 2023 at 3:30 PM Rob Landley <rob at landley.net> wrote:
> >
> > On 10/3/23 16:07, enh wrote:
> > >> I don't THINK that's a likely fallback path here? Although /bin/sh not found
> > >> might explain it. But that would be deterministically reproducible and you're
> > >> having an intermittent issue, right?
> > >
> > > correct. ccross tells me it's ~2% of all runs in CI.
> >
> > Ok, that's significant. That's not a "second guy finally saw this happen to him
> > once", that's "we can hammer and reproduce".
>
> oh, yeah, ccross isn't just some internet rando --- when he comes to
> you with something, it's worth a look (if only because he'll come with
> data like that, rather than just an isolated report) :-)
>
> > > locally, i commented out all the other tests, and just ran this
> > > repeatedly on a device, and it did repro after about half an hour.
> > > i've kicked off a similar test on the host, and i've kicked off the
> > > device again but with strace in the mix (which hopefully doesn't slow
> > > things down enough to make the problem disappear!).
> >
> > $ grep -r 'errno.*=.*ENOENT' -r bionic | grep -v ==
> >
> > Bionic's exec.cpp can return ENOENT when name or *name is null. Seems unlikely.
> >
> > And that's not argv[0] being null, that's the "name" argument which we're
> > passing a constant-ish string to. Failure to marshall the string into that
> > argument there would have to be in the shell, or the toybox argument parsing
> > path, or something in then xpopen_setup() plumbing? This isn't timeout -i so
> > it's not doing the pipe setup and you have CFG_TOYBOX_FORK enabled in your
> > config so the else case in xpopen_setup() returning 127 can't trigger, and it
> > also eliminates the less tested vfork() codepath in the kernel (although not by
> > THAT much, it's just clone() with a bunch of flags...) Similarly xfork() is just
> > checking pid<0 to perror_exit() which you'd _notice_ and isn't 127 anyway. The
> > callback() is just setting the child's SIGCHLD signal handler back to default
> > and you didn't --foreground so it wouldn't setpgid() anyway, and then xexec()
> > and you have CFG_TOYBOX_NORECURSE so there's our call to execvp(). I don't see
> > how we'd get derailed before there.
> >
> > >> $ cat > potato.c << EOF
> > >> #include <unistd.h>
> > >> int main(int argc, char *argv[]) { execvp("/", (char *[]){"/", 0}); }
> > >> EOF
> > >> $ gcc potato.c
> > >> $ strace ./a.out
> > >> execve("/", ["/"], 0x7ffebd0880d8 /* 36 vars */) = -1 EACCES (Permission denied)
> > >> $ sudo strace ./a.out
> > >> execve("/", ["/"], 0x7ffc32654e08 /* 16 vars */) = -1 EACCES (Permission denied)
> > >> $ ls -ld /
> > >> drwxr-xr-x 24 root root 4096 Feb  9  2023 /
> > >>
> > >> In general root doesn't care about permission bits, and there's no /bin/sh
> > >> follow-up to the syscall failure here. Tried again with bionic and there were a
> > >> couple extra mprotect() calls on the way out but still no /bin/sh fallback...
> > >>
> > >> So the question here is does the kernel have a weird intermittent codepath, or
> > >> does bionic+selinux have a weird intermittent codepath?
> > >
> > > (yeah, that's why i'm trying on the host now.)
> > >
> > >> Let's see: in the vanilla kernel source fs/exec.c has SYSCALL_DEFINE3(execve)
> > >> which does return do_execve(getname(filename), argv, envp); which wraps
> > >> do_execveat_common() on line 1888 of the same file.
> > >>
> > >> A quick cheat grepping for EACCES shows two uses in this file, one in
> > >> SYSCALL_DEFINE1(uselib) which I just BOGGLE at because how are shared libraries
> > >> THE KERNEL'S PROBLEM... but I really doubt we get there here. No, the NORMAL
> > >> codepath (which we're apparently not reaching) is do_open_execat(int fd, struct
> > >> filename *name, int flags) which says no, may_open() already checked and this is
> > >> just a race condition check, and it's common plumbing in another file that
> > >> returns this error code. Alright, cheat failed, back to drilling.
> > >>
> > >> Back to do_execveat_common(): filename was not a NULL pointer or similar.
> > >> UCOUNT_RLIMIT_NPROC would return -EAGAIN. What error code might alloc_bprm()
> > >> return, it's on line 1512 of this same file and it is understandably ENOMEM.
> > >> count() can return EFAULT, E2BIG, and ERESTARTNOHAND. (Huh, launching a process
> > >> with an argv of { NULL } has a kernel workaround with shaking finger of shame in
> > >> the log? Did not know that.)
> > >
> > > (yeah, surprisingly that "broke userspace" in the mild sense of "we
> > > had tests" that made sure the _dynamic linker_ didn't crash in that
> > > circumstance. and of course, we only had that test because it'd
> > > happened in real life. but, yeah, i'm pretty happy with "don't do
> > > that".)
> >
> > int main(int argc, char *argv[])
> > {
> >   // don't segfault if our environment is crazy
> >   if (!*argv) return 127;
> >
> > I can remove that. :)
> >
> > When did this... commit dcd46d897adb7 last year, responding to CVE-2021-4034.
> > Ok, explains why I hadn't noticed before. And 7 year horizon for removing the
> > check. Add a TODO note but my main.c is dirty because of the zhelp stuff...
> >
> > >> bprm_stack_limits() can set E2BIG.
> > >> copy_string_kernel() and copy_strings() can both EFAULT or E2BIG.
> > >>
> > >> And now we're on to bprm_execve(), which I can drill through after lunch...
> >
> > Make that after dinner.
> >
> > > when i wrote the test i was trying to make sure we tested _all_ the
> > > paths through....
> > >
> > > ...but there's a bug _somewhere_ for this to be non-deterministic.
> >
> > Eh, "bug"... signal delivery causing a different return path, data in cache vs
> > data not in cache causing an EAGAIN codepath being handled differently on retry,
> > some sort of marginal timeout... Slightly different error return code nobody's
> > CARED about before now.
>
> except this _should_ be a super straightforward case, no? there are no
> circumstances where you can execute `/` so the behavior here should be
> completely consistent.
>
> > Still lots of variables: architecture (arm vs x86), kernel version (android vs
> > vanilla maybe), libc version, compiler version (unlikely), selinux (and/or hwsan
> > triggering somewhere _in_ the kernel), has it only been seen on specific
> > hardware or filesystems (driver return code somehow)...
> >
> > > this was a hwasan build on cheetah. (a) because that's what happens to
> > > be on my desk, but (b) because ccross' example was arm64 hwasan too.
> >
> > Googling for "android cheetah" says it got banned from the play store and
> > accused of insider trading by the SEC, and its founder is the current CEO of
> > Bilibili.
>
> heh, no "cheetah" is the lunch target. pixel pro 7 was the marketing
> name. "recent arm64 device running a hwasan build" was what i was
> trying to say.
>
> it's been running just that test under strace for a couple of hours
> now without finding anything, and the host hasn't found anything
> either. ccross suggested changing the test so it _doesn't_ throw away
> stderr and see if that shows us anything, so i'll give up on the
> strace runs now and switch over to that instead. (i'm going to give up
> on the host too, since it's run orders of magnitude more cycles and
> isn't obviously achieving anything beyond making the room warm.)

well, that's unfortunate:

-- timeout
FAIL: timeout can't execute
echo -ne '' | timeout .1 / 2>&1 ; echo $?
--- expected 2023-10-04 00:19:17.192008926 +0000
+++ actual 2023-10-04 00:19:17.304008926 +0000
@@ -1,2 +1,2 @@
 timeout: exec /: Permission denied
-126
+127

wtf?

> > Rob