[Toybox] weird timeout flake

[enh]

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.)

> Rob