tokio panic with `Error 0` inside `rustup`

[jgallagher]

We've seen the following errors a few times in CI (omicron, propolis, omicron again):

thread 'main' panicked at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/io/driver.rs:208:27:
failed to wake I/O driver: Os { code: 0, kind: Uncategorized, message: "Error 0" }

As best I can tell (assuming no unsafe thread safety shenanigans, which is maybe not a good assumption), the only way this can happen is if libc::read or libc::write to an eventfd file descriptor returns -1 without setting errno.

tokio is unwrapping a call to Waker::wake(): https://github.com/tokio-rs/tokio/blob/5f3296df77ad594779d1fe1a1583078ca9832daf/tokio/src/runtime/io/driver.rs#L208

This lands in mio. A Waker is created via eventfd then wrapped in a std::fs::File: https://github.com/tokio-rs/mio/blob/f45f4928dabe8c22114e63b06c1e6177ef4eb192/src/sys/unix/waker/eventfd.rs#L38-L39.

wake() calls read first (but only on illumos) then write, but in both cases it only handles the io::Error it's given from the standard library, which AFAICT can only return the error we see above if we get back -1 but errno is 0.

[davepacheco]

Not sure if more data points are useful, but I saw it again here in tufaceous:
https://buildomat.eng.oxide.computer/wg/0/details/01JRE8YGGC97C5RYRG1WMGAC48/8pvqptB1JBIoEhWhb1C8elryaT9wDxVYjxjNdwIC7GcTz3xq/01JRE8YVXRJRYR6N3XRBQMFX4F

[bnaecker]

Just saw this again in Omicron:

https://buildomat.eng.oxide.computer/wg/0/details/01JSF6516HHEW4D7EBEXA7TC21/HOJCi9IB6rlzDMDEgz449sjtgemqsRD6NqTvO0817b0pwhip/01JSF65GP5XGAN296457HD8PZK

[smklein]

Seen again on https://github.com/oxidecomputer/omicron/pull/8426/checks?check_run_id=45489525228

(https://buildomat.eng.oxide.computer/wg/0/details/01JZJSRXRAA9BX0SWC9EZ81D8V/vLvM2wfe03wOKwt54YvlLPFZcynJCnK7bhZO9BPyCNpCMgBw/01JZJSSXTJJ87NFDHGZGEQA3K3 might be a more stable link)

[iximeow]

the standard library, which AFAICT can only return the error we see above if we get back -1 but errno is 0.

this is my read as well, so i spent some time trying to understand what the circumstances would be that would result in read(3) or write(3) returning -1 with an errno of 0. i don't see a way it can happen. i'm mostly just more confused.

additionally, the first time we saw this was eight days after rustup 1.28.0, the first rustup release since May 6, 2024. that does encompass mio's move from using pipe-based wakers to eventfd-based (August 2024. related, tokio-rs/mio#1824). AFAIK we've only seen this as buildomat flakes but i'm pretty sure whatever's happening is indicative of a more general bug.

notes from trying to reverse engineer how we could see this, working backwards from where John left off:

libc.so.1::read is a small wrapper around __read (which actually does the syscall) plus some eintr/cancellation handling. PERFORM() includes an EPILOGUE that runs after the syscall returns, and EPILOGUE is uninteresting too. we definitely exit __read() with the return value and errno unmodified.

the commits for the next few libc links are two years old, but they're the last commit to SYS.h as of when i'm writing this. they're consistent with the instructions i see on illumos systems here.

libc.so.1::__read is very boring. RET is a define of ret.

SYSCALL2_RESTART_RVAL1 is all the interesting glue of getting into the kernel and handling return state when the kernel returns to user code. SYSTRAP_RVAL1 is a really straightforward sequence ending in syscall, so SYSRESTART is the first code on syscall return.

SYSRESTART() is where we branch out into actually setting errno if appropriate. the sequence starting off with jae means we're using flags from the syscall return (will get to that in a bit), so we're branching if CF=0 on syscall return. said the other way, if CF=1 then branch out to __cerror. additionally, if the syscall exited with ERESTART, branch back and restart it. so if we returned from read we didn't restart. it would be absolutely bizarre but one way to get at the observed state would be if the syscall returned -1 with CF=0. that would be a bug in read()/write() (or eventfd_{read,write} in particular). taking a quick detour to __cerror if read(2) returns with CF=1...

__cerror is where we get the "errno comes with returning -1" semantics. if the syscall returned something other than ERESTART, we store the syscall's return value into errno, then return -1. if the syscall returned ERESTART we would have restarted from SYSRESTART but at this point we'd replace it with EINTR. again, seems like that's not actually a taken path here. so, the other way to get at "read(3) returned -1 with errno=0 " would be for the syscall itself to have returned 0 with CF=1. this also seems impossible.

those two cases are the only states i see where a syscall can return such that we see -1 with errno=0. going backwards through the kernel side it does seem pretty impossible...

the state at sysret is described at the tail end of the syscall handler, so the next stop is sys_syscall in the kernel. the actual function is tr_sys_syscall, but tr_* comes from the KPTI trampoline wrapping this function (there's a MK_TRAMPOLINE() which i'm skipping over here). at the end is tr_sysretq, which is a similar KPTI trampoline but really a glorified sysret. so, RFLAGS in userland is whatever's in r11 at this point. walking backwards from here, we're not __xpv so that comes from REGOFF_RFL(%rsp). x86_md_clear is boring and could at most set the kernel's ZF, but those flags are wholly overwritten with r11 by sysret anyway.

post_syscall plumbs error return information into process state for the syscall return. specifically if a syscall returns an error it's plumbed to CF here. lwp_eosys should be NORMALRETURN for read and write. this is where we can rule out one possibility really confidently: errno can't have been set to 0. if errno was set to 0, then the kernel returned with CF set, which also implies that rp->r_r0 = error happened and that error was 0. but if error was 0 we never would have gotten to this branch and we would have returned with CF masked out.

if read/write didn't return with CF set, then the -1 came from read() or write() directly?! quickly running through the call path there, read()'s out: sets errno if error was nonzero and returns cnt. cnt is the size of the input buffer minus the residual, or the total amount of remaining buffer in auio after the read. so to get -1 out of read(), we would have to have read -1 bytes, grew the residual, and underflowed here. VOP_READ gets us to spec_read(). eventfd ends up in cdev_read(), and finally to eventfd_read().

in eventfd_read the error comes from uiomove so presumably that returns 0. it also updates the iovecs in uio as the move progresses. there must be at least sizeof(val) bytes available in uio when we get into eventfd_read, so in uiomove() cnt must be 8 as that's the provided n when it's called and auio is the single buffer/length passed to read (or write). the only way for uio_resid to end up at -1 would be if iov_len were one larger than uio_resid. they're set the same when auio is set up in read(), except for this line that can adjust cnt. but spec_read asserts v_type == VCHR || ... and mdb confirms that an eventfd is v_type == VCHR. so i don't see a way that the count can end up -1 here either.

[iximeow]

@citrus-it noted on the side that this looks like other issues where multithreaded code incorrectly shares the same errno location across threads (e.g. is not built with _REENTRANT). i agree that whatever's happening seems more likely to be racing than actually getting -1/errno 0 from something, but at least for these functions it doesn't seem like what could be happening.. my rustup 1.28.2, which should be the same as the one in a helios-2.0 worker:

root@helios:~# shasum $(which rustup)
41922dc6d7abf1e5cecdd8648c392b23573f9c38  /root/.cargo/bin/rustup

touching up the disassembly a bit, has a reasonable Waker::wake:

> _ZN3mio3sys4unix5waker5Waker4wake17h37ff28870f506cbcE::dis
...wake:  pushq  %rbp
...wake+1:movq   %rsp,%rbp
...wake+4:pushq  %r15
...wake+6:pushq  %r14
...wake+8:pushq  %rbx
...wake+9:pushq  %rax
...wake+0xa:      movq   %rdi,%rbx
...wake+0xd:      movl   (%rdi),%r14d
...wake+0x10:     movl   %r14d,%edi
...wake+0x13:     call   +0x88    <_ZN3mio3sys4unix5waker5Waker5reset17h04191ea394b30feaE>
...wake+0x18:     testq  %rax,%rax
...wake+0x1b:     jne    +0x58    <...wake+0x75>
...wake+0x1d:     movq   $0x1,-0x20(%rbp)
...wake+0x25:     leaq   -0x20(%rbp),%rsi
...wake+0x29:     movl   $0x8,%edx
...wake+0x2e:     movl   %r14d,%edi
...wake+0x31:     call   -0x1cce56        <PLT=libc.so.1`write> 
...wake+0x36:     cmpq   $-0x1,%rax       <0xffffffffffffffff>  
...wake+0x3a:     je     +0x4     <...wake+0x40>
...wake+0x3c:     xorl   %eax,%eax
...wake+0x3e:     jmp    +0x35    <...wake+0x75>
...wake+0x40:     call   -0x1cc7f5        <PLT=libc.so.1`___errno>

and a reasonable Waker::reset:

> _ZN3mio3sys4unix5waker5Waker5reset17h04191ea394b30feaE::dis
...reset: pushq  %rbp
...reset+1:       movq   %rsp,%rbp
...reset+4:       pushq  %rbx
...reset+5:       pushq  %rax
...reset+6:       movq   $0x0,-0x10(%rbp)
...reset+0xe:     leaq   -0x10(%rbp),%rsi
...reset+0x12:    movl   $0x8,%edx
...reset+0x17:    call   -0x1cd3cc        <PLT=libc.so.1`read>
...reset+0x1c:    cmpq   $-0x1,%rax       <0xffffffffffffffff>
...reset+0x20:    je     +0x9     <...reset+0x2b>
...reset+0x22:    xorl   %eax,%eax
...reset+0x24:    addq   $0x8,%rsp
...reset+0x28:    popq   %rbx
...reset+0x29:    popq   %rbp
...reset+0x2a:    ret
...reset+0x2b:    call   -0x1cc880        <PLT=libc.so.1`___errno>

though something is definitely compiled incorrectly for multithreaded programs in here:

root@helios:~# /usr/bin/nm $(which rustup) | grep errno
[34057] |                   0|                   0|FUNC |GLOB |0    |UNDEF  |___errno@SUNW_0.7
[28614] |                   0|                   0|OBJT |GLOB |0    |UNDEF  |errno@SUNW_0.7

(i'm pretty sure it's rustup's vendored openssl. that's a different issue and while it's bad, i don't think it'll show up anything like this)

[iximeow]

i'd written up a program to hammer on an eventfd to see if it ever said anything strange at all and along the way noticed this:

# ./eventfd_test
created eventfd: 3
errno clobber thread sees global errno is 0xfffffc7fee9b1de8
fuzz thread sees ___errno() returning 0xfffffc7fedff0b4c
fuzz thread sees ___errno() returning 0xfffffc7fedff1b4c
fuzz thread sees ___errno() returning 0xfffffc7fedff134c
fuzz thread sees ___errno() returning 0xfffffc7fedff234c
fuzz thread sees ___errno() returning 0xfffffc7fedff2b4c
fuzz thread sees ___errno() returning 0xfffffc7fedff334c
fuzz thread sees ___errno() returning 0xfffffc7fedff3b4c
fuzz thread sees ___errno() returning 0xfffffc7fedff434c
fuzz thread sees ___errno() returning 0xfffffc7fedff4b4c
fuzz thread sees ___errno() returning 0xfffffc7fedff534c
fuzz thread sees ___errno() returning 0xfffffc7fedff5b4c
fuzz thread sees ___errno() returning 0xfffffc7fedff634c
fuzz thread sees ___errno() returning 0xfffffc7fedff6b4c
fuzz thread sees ___errno() returning 0xfffffc7fedff734c
global thread sees ___errno() returning 0xfffffc7fee9b1de8
fuzz thread sees ___errno() returning 0xfffffc7fedff7b4c
fuzz thread sees ___errno() returning 0xfffffc7fedff834c

notably, global thread sees ___errno() is from main(), and errno clobber thread sees global errno is a different thread spawned off doing

loop {
    if (errno != 0) {
        println!("global errno: {}", errno)
        errno = 0;
    }
}

and so coming back to the incorrectly-built vendored openssl,

(i'm pretty sure it's rustup's vendored openssl. that's a different issue and while it's bad, i don't think it'll show up anything like this)

nope, it shows up exactly like this if the Waker is operated on in the first thread while some other thread is doing openssl stuff. then if the Waker does an operation that returns EAGAIN concurrent with openssl, everything lines up to blow up like this. we probably should go have the cc crate build stuff with -D_TS_ERRNO so that vendored code like that doesn't... do this.

[citrus-it]

Great that you've been able to reproduce this.

we probably should go have the cc crate build stuff with -D_TS_ERRNO so that vendored code like that doesn't... do this.

It should define -D_REENTRANT instead, which has the side-effect of setting _TS_ERRNO as well as other things. _TS_ERRNO is an internal macro which isn't documented.
While _REENTRANT is documented, we could definitely do a better job of mentioning it in pages such as errno(3c).