os: Missed checking for EINTR in (*os.File).readdir

[jameshartig]

What version of Go are you using (go version)?

go version go1.15 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/toaster/.cache/go-build"
GOENV="/home/toaster/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/opt/gopath/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/opt/gopath"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build047277846=/tmp/go-build -gno-record-gcc-switches"

What did you do?

See: https://go-review.googlesource.com/c/go/+/232862/

If you call ioutil.ReadDir it ends up calling (*os.File).readdir which calls lstat and does not retry on an EINTR error. Other spots were handled in https://go-review.googlesource.com/c/go/+/232862/ and I think this spot was just missed.

I wasn't sure of the best way since lstat is automatically generated. Should this just be handled in readdir?

What did you expect to see?

I expected ioutil.ReadDir not to error.

What did you see instead?

Instead ioutil.ReadDir errored with lstat /opt/admiral-dev/hazadblock/dist/static/lib/ergoHeadOverwrite.dev.min.js.map: interrupted system call.

[bcmills]

CC @ianlancetaylor

[ianlancetaylor]

As far as I know neither the stat nor the lstat system call is interruptible by a signal. But the error you show suggests that lstat can return EINTR. That suggests that stat can also return EINTR. Either way it's not clear to me that this has anything to do with (*os.File).Readdir as such. Perhaps we need to fix Stat and Lstat to loop on EINTR.

Can you tell us more about the exact case where this fails? Can you show us a way to reproduce the problem? Thanks.

[jameshartig]

@ianlancetaylor thanks for the quick reply!

Can you tell us more about the exact case where this fails?

So the underlying mount is a FUSE filesystem and the stat call actually could make a network call if the information isn't cached locally. From my reading of the fuse documentation [1]:

Interrupting filesystem operations
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

If a process issuing a FUSE filesystem request is interrupted, the
following will happen:

  1) If the request is not yet sent to userspace AND the signal is
     fatal (SIGKILL or unhandled fatal signal), then the request is
     dequeued and returns immediately.

  2) If the request is not yet sent to userspace AND the signal is not
     fatal, then an 'interrupted' flag is set for the request.  When
     the request has been successfully transferred to userspace and
     this flag is set, an INTERRUPT request is queued.

  3) If the request is already sent to userspace, then an INTERRUPT
     request is queued.

INTERRUPT requests take precedence over other requests, so the
userspace filesystem will receive queued INTERRUPTs before any others.

The userspace filesystem may ignore the INTERRUPT requests entirely,
or may honor them by sending a reply to the _original_ request, with
the error set to EINTR.

It is also possible that there's a race between processing the
original request and its INTERRUPT request.  There are two possibilities:

  1) The INTERRUPT request is processed before the original request is
     processed

  2) The INTERRUPT request is processed after the original request has
     been answered

If the filesystem cannot find the original request, it should wait for
some timeout and/or a number of new requests to arrive, after which it
should reply to the INTERRUPT request with an EAGAIN error.  In case
1) the INTERRUPT request will be requeued.  In case 2) the INTERRUPT
reply will be ignored.

it seems like returning EINTR is following the spec but I'm also not sure if I can somehow modify the FUSE library to ignore the Interrupt. Can you point me in a direction for how to debug the go-side of this? I'm not sure how I can figure out exactly what signal go received. I was assuming it was SIGUSR but it's not clear to me what the best way is to discover what signal was received or how to correlate that with the separate FUSE program. Here are the debug logs from the FUSE-side:

<- Getattr [ID=0x428 Node=0x25 Uid=1002 Gid=1003 Pid=22546] 0x0 fl=0
<- Interrupt [ID=0x42a Node=0x0 Uid=0 Gid=0 Pid=0] ID 0x428
-> [ID=0x42a] Interrupt
-> [ID=0x428] Getattr error=EINTR

There's a lot of other logs around this so I'm under the current assumption that the Interrupt happened almost immediately after the Getattr was issued, which is weird. If it helps at all, the program doing the reads makes a new goroutine for each file and reads them in so there's 10-15 goroutines reading at once. I don't know yet how to understand what signal caused the Interrupt since I don't think that's exposed to the FUSE program.

Can you show us a way to reproduce the problem?

Once we can determine what the signal is that caused this, then I can hopefully come up with some sort of simple reproduction. We can just make a simple FUSE program that just sleeps and then trigger the signal and it should send an Interrupt.

[1] https://www.kernel.org/doc/Documentation/filesystems/fuse.txt

[ianlancetaylor]

Thanks for the info.

The signal was most likely SIGURG, which is used to preempt a goroutine.

You should be able to see it by running the program under strace -f.

[networkimprov]

@fastest963 what FUSE library are you referring to? How is it configured on your system? That's probably all we need to know to reproduce it.

Go 1.14+ generates a lot of interrupts, for goroutine scheduling. Causing an interrupt is easy in a Go app.

[jameshartig]

@networkimprov It's using https://github.com/bazil/fuse to mount the FUSE mount. Nothing very special on the configuration front other than fuse.AsyncRead and fuse.DefaultPermissions. Here's a program to replicate the problem: https://gist.github.com/fastest963/756f67d406540ad8ae14d22e651043d0

It should print out:

fuse: <- Getattr [ID=0x2 Node=0x1 Uid=1001 Gid=1002 Pid=12860] 0x0 fl=0
fuse: <- Interrupt [ID=0x3 Node=0x0 Uid=0 Gid=0 Pid=0] ID 0x2
fuse: -> [ID=0x3] Interrupt
interrrupted 0x2
fuse: -> [ID=0x2] Getattr error=EINTR
error: stat ./test: interrupted system call

@ianlancetaylor

You should be able to see it by running the program under strace -f.

Here's the relevant strace output:

openat(AT_FDCWD, "/opt/admiral-dev/hazadblock/dist/static/lib/reporting/js.dev.min.js", O_RDONLY|O_CLOEXEC) = 35
futex(0x1c94b98, FUTEX_WAKE_PRIVATE, 1) = 1
epoll_ctl(3, EPOLL_CTL_ADD, 35, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=2416816088, u64=140271753736152}}) = 0
fcntl(35, F_GETFL)      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fcntl(35, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
fstat(35, 0xc0001cb218) = -1 EINTR (Interrupted system call)
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=10907, si_uid=1002} ---
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system call)
read(35, "!(function(e){var r={};function "..., 512) = 512
futex(0x1c94b98, FUTEX_WAKE_PRIVATE, 1) = 1
read(35, "ule)return t;var e=Object.create"..., 1024) = 1024
read(35, "sName=i.join(\" \")),e}},179:funct"..., 2048) = 2048
read(35, "typeof Symbol&&n.constructor===S"..., 4096) = 2761
futex(0x1c94b98, FUTEX_WAKE_PRIVATE, 1) = 1
read(35, "", 1335)      = 0
epoll_ctl(3, EPOLL_CTL_DEL, 35, 0xc02032ad2c) = 0
close(35)               = 0

and the associated FUSE logs:

<- Open [ID=0xe79 Node=0xe Uid=1002 Gid=1003 Pid=10935] dir=false fl=OpenReadOnly
-> [ID=0xe79] Open 0x2 fl=0
<- Getattr [ID=0xe7b Node=0xe Uid=1002 Gid=1003 Pid=10935] 0x0 fl=0
<- Interrupt [ID=0xe7d Node=0x0 Uid=0 Gid=0 Pid=0] ID 0xe7b
-> [ID=0xe7d] Interrupt
-> [ID=0xe7b] Getattr error=EINTR

Looks like this happened inside of iotuil.ReadFile because the stat error was ultimately ignored.

[ianlancetaylor]

Thanks. Can you double check that you passed the -f option when you ran strace? The output without -f is unhelpful for Go programs.

[jameshartig]

@ianlancetaylor I actually used -ff and copied only the relevant section out above from the PID that got the signal because there were 30+ threads and a ton of irrelevant traffic but I realized now I should instead just run strace with my example program. For some reason the FUSE mounting failed with Operation not permitted whenever I ran my test binary with strace -f test so instead I made it sleep and then I attached strace to the pid:
strace.txt

The relevant section is:

[pid 15228] newfstatat(AT_FDCWD, "./test",  <unfinished ...>
[pid 15229] rt_sigprocmask(SIG_SETMASK, ~[],  <unfinished ...>
[pid 15230] <... nanosleep resumed>NULL) = 0
[pid 15229] <... rt_sigprocmask resumed>[], 8) = 0
[pid 15229] clone(strace: Process 15236 attached
 <unfinished ...>
[pid 15230] read(6, "8\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\351\3\0\0\352\3\0\0"..., 135168) = 56
[pid 15229] <... clone resumed>child_stack=0xc000136000, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM) = 15236
[pid 15236] gettid( <unfinished ...>
[pid 15230] read(6,  <unfinished ...>
[pid 15236] <... gettid resumed>)       = 15236
[pid 15229] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15236] arch_prctl(ARCH_SET_FS, 0xc000124090 <unfinished ...>
[pid 15229] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15236] <... arch_prctl resumed>)   = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15236] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 15236] sigaltstack({ss_sp=0xc000128000, ss_flags=0, ss_size=32768},  <unfinished ...>
[pid 15231] <... epoll_pwait resumed>[], 128, 1, NULL, 0) = 0
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15236] <... sigaltstack resumed>NULL) = 0
[pid 15231] futex(0xc000030948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15236] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15236] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15236] gettid()                    = 15236
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15229] futex(0xc000030948, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15236] rt_sigprocmask(SIG_SETMASK, ~[],  <unfinished ...>
[pid 15231] <... futex resumed>)        = 0
[pid 15229] <... futex resumed>)        = 1
[pid 15236] <... rt_sigprocmask resumed>[], 8) = 0
[pid 15231] write(1, "fuse: <- Getattr [ID=0x2 Node=0x"..., 72 <unfinished ...>
[pid 15229] getpid( <unfinished ...>
[pid 15236] clone( <unfinished ...>
[pid 15231] <... write resumed>)        = 72
[pid 15231] epoll_pwait(7,  <unfinished ...>
[pid 15229] <... getpid resumed>)       = 15228
[pid 15231] <... epoll_pwait resumed>[], 128, 0, NULL, 362006) = 0
[pid 15231] epoll_pwait(7, strace: Process 15237 attached
 <unfinished ...>
[pid 15237] gettid()                    = 15237
[pid 15237] arch_prctl(ARCH_SET_FS, 0xc000124490) = 0
[pid 15236] <... clone resumed>child_stack=0xc000138000, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM) = 15237
[pid 15229] tgkill(15228, 15236, SIGURG <unfinished ...>
[pid 15237] sigaltstack(NULL,  <unfinished ...>
[pid 15236] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15237] <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 15229] <... tgkill resumed>)       = 0
[pid 15236] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15237] sigaltstack({ss_sp=0xc00013c000, ss_flags=0, ss_size=32768},  <unfinished ...>
[pid 15236] --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=15228, si_uid=1001} ---
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15237] <... sigaltstack resumed>NULL) = 0
[pid 15237] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15236] rt_sigreturn({mask=[]} <unfinished ...>
[pid 15237] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15236] <... rt_sigreturn resumed>) = 0
[pid 15237] gettid( <unfinished ...>
[pid 15236] rt_sigprocmask(SIG_SETMASK, ~[HUP INT QUIT ILL TRAP ABRT BUS FPE SEGV TERM STKFLT CHLD PROF SYS RTMIN RT_1],  <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15237] <... gettid resumed>)       = 15237
[pid 15229] getpid( <unfinished ...>
[pid 15237] futex(0x672ed8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15236] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15229] <... getpid resumed>)       = 15228
[pid 15229] tgkill(15228, 15236, SIGURG <unfinished ...>
[pid 15236] futex(0x672ed8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15229] <... tgkill resumed>)       = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15236] <... futex resumed>)        = 1
[pid 15237] <... futex resumed>)        = 0
[pid 15237] sched_yield( <unfinished ...>
[pid 15236] futex(0xc000124148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15237] <... sched_yield resumed>)  = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15237] futex(0x672ec0, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15237] rt_sigprocmask(SIG_SETMASK, ~[],  <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15237] <... rt_sigprocmask resumed>[], 8) = 0
[pid 15237] clone(child_stack=0xc000152000, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM) = 15238
[pid 15229] <... nanosleep resumed>NULL) = 0
strace: Process 15238 attached
[pid 15237] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15238] gettid( <unfinished ...>
[pid 15237] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15238] <... gettid resumed>)       = 15238
[pid 15237] futex(0x672ed8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15238] arch_prctl(ARCH_SET_FS, 0xc000124890 <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15238] <... arch_prctl resumed>)   = 0
[pid 15238] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 15238] sigaltstack({ss_sp=0xc000144000, ss_flags=0, ss_size=32768},  <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15238] <... sigaltstack resumed>NULL) = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15238] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 15238] gettid( <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15238] <... gettid resumed>)       = 15238
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15238] futex(0xc000124148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15238] <... futex resumed>)        = 1
[pid 15236] <... futex resumed>)        = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15238] futex(0xc000124948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15236] futex(0x672ed8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 15237] <... futex resumed>)        = 0
[pid 15236] rt_sigprocmask(SIG_SETMASK, ~[HUP INT QUIT ILL TRAP ABRT BUS FPE SEGV USR2 TERM STKFLT CHLD PROF SYS RTMIN RT_1],  <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15237] rt_sigprocmask(SIG_SETMASK, ~[],  <unfinished ...>
[pid 15236] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15237] <... rt_sigprocmask resumed>[], 8) = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15236] futex(0xc000124948, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15237] clone( <unfinished ...>
[pid 15236] <... futex resumed>)        = 1
[pid 15238] <... futex resumed>)        = 0
[pid 15236] futex(0xc000124148, FUTEX_WAIT_PRIVATE, 0, NULLstrace: Process 15239 attached
 <unfinished ...>
[pid 15237] <... clone resumed>child_stack=0xc000154000, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM) = 15239
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15238] write(9, "\0", 1 <unfinished ...>
[pid 15237] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15237] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15238] <... write resumed>)        = 1
[pid 15237] futex(0x672ed8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15238] rt_sigprocmask(SIG_SETMASK, ~[],  <unfinished ...>
[pid 15239] gettid( <unfinished ...>
[pid 15231] <... epoll_pwait resumed>[{EPOLLIN, {u32=6761816, u64=6761816}}], 128, 999, NULL, 0) = 1
[pid 15239] <... gettid resumed>)       = 15239
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15231] read(8,  <unfinished ...>
[pid 15239] arch_prctl(ARCH_SET_FS, 0xc000124c90 <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15231] <... read resumed>"\0", 16) = 1
[pid 15239] <... arch_prctl resumed>)   = 0
[pid 15238] <... rt_sigprocmask resumed>[], 8) = 0
[pid 15231] futex(0xc000030948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15239] sigaltstack(NULL,  <unfinished ...>
[pid 15238] clone( <unfinished ...>
[pid 15239] <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15239] sigaltstack({ss_sp=0xc000154000, ss_flags=0, ss_size=32768},  <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15239] <... sigaltstack resumed>NULL) = 0
[pid 15238] <... clone resumed>child_stack=0xc00014e000, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM) = 15240
strace: Process 15240 attached
[pid 15239] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15238] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15240] gettid( <unfinished ...>
[pid 15239] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15240] <... gettid resumed>)       = 15240
[pid 15238] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15240] arch_prctl(ARCH_SET_FS, 0xc000125090 <unfinished ...>
[pid 15239] gettid( <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15238] futex(0x672fe0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15240] <... arch_prctl resumed>)   = 0
[pid 15239] <... gettid resumed>)       = 15239
[pid 15240] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 15239] epoll_pwait(7,  <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15240] sigaltstack({ss_sp=0xc00015c000, ss_flags=0, ss_size=32768},  <unfinished ...>
[pid 15239] <... epoll_pwait resumed>[], 128, 0, NULL, 362006) = 0
[pid 15240] <... sigaltstack resumed>NULL) = 0
[pid 15239] futex(0xc000124148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15240] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 15239] <... futex resumed>)        = 1
[pid 15236] <... futex resumed>)        = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15240] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 15239] futex(0xc000124d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15236] futex(0xc000124d48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15240] gettid( <unfinished ...>
[pid 15239] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 15236] <... futex resumed>)        = 0
[pid 15240] <... gettid resumed>)       = 15240
[pid 15239] epoll_pwait(7,  <unfinished ...>
[pid 15236] futex(0xc000124148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15240] kill(0, SIGUSR2 <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15239] <... epoll_pwait resumed>[], 128, 0, NULL, 362006) = 0
[pid 15240] <... kill resumed>)         = 0
[pid 15239] --- SIGUSR2 {si_signo=SIGUSR2, si_code=SI_USER, si_pid=15228, si_uid=1001} ---
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15239] futex(0x672fe0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15240] epoll_pwait(7,  <unfinished ...>
[pid 15230] <... read resumed>"0\0\0\0$\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 135168) = 48
[pid 15240] <... epoll_pwait resumed>[], 128, 0, NULL, 362006) = 0
[pid 15239] <... futex resumed>)        = 1
[pid 15238] <... futex resumed>)        = 0
[pid 15230] futex(0xc000030548, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15239] rt_sigreturn({mask=[]} <unfinished ...>
[pid 15238] futex(0xc000124948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15240] read(6,  <unfinished ...>
[pid 15239] <... rt_sigreturn resumed>) = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15239] futex(0xc000124948, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 15238] <... futex resumed>)        = 0
[pid 15239] futex(0x672fe0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15238] kill(0, SIGUSR2 <unfinished ...>
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15238] <... kill resumed>)         = 0
[pid 15229] --- SIGUSR2 {si_signo=SIGUSR2, si_code=SI_USER, si_pid=15228, si_uid=1001} ---
[pid 15238] epoll_pwait(7, [], 128, 0, NULL, 362006) = 0
[pid 15230] <... futex resumed>)        = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 15229] futex(0x672fe0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15230] futex(0xc000030548, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15229] <... futex resumed>)        = 1
[pid 15239] <... futex resumed>)        = 0
[pid 15229] rt_sigreturn({mask=[]})     = 0
[pid 15239] futex(0xc000124d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15229] futex(0xc000124d48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15239] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 15238] write(1, "fuse: <- Interrupt [ID=0x3 Node="..., 62 <unfinished ...>
[pid 15229] <... futex resumed>)        = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15239] futex(0xc000030548, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 15239] futex(0x672fe0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15238] <... write resumed>)        = 62
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15230] <... futex resumed>)        = 0
[pid 15230] kill(0, SIGUSR2)            = 0
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15230] epoll_pwait(7,  <unfinished ...>
[pid 15229] --- SIGUSR2 {si_signo=SIGUSR2, si_code=SI_USER, si_pid=15228, si_uid=1001} ---
[pid 15238] write(1, "fuse: -> [ID=0x3] Interrupt\n", 28 <unfinished ...>
[pid 15229] futex(0x672fe0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15230] <... epoll_pwait resumed>[], 128, 0, NULL, 362006) = 0
[pid 15239] <... futex resumed>)        = 0
[pid 15229] <... futex resumed>)        = 1
[pid 15239] futex(0xc000124d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15238] <... write resumed>)        = 28
[pid 15230] epoll_pwait(7,  <unfinished ...>
[pid 15229] rt_sigreturn({mask=[]} <unfinished ...>
[pid 15238] write(1, "interrrupted 0x2\n", 17 <unfinished ...>
[pid 15230] <... epoll_pwait resumed>[], 128, 0, NULL, 362006) = 0
[pid 15229] <... rt_sigreturn resumed>) = 0
[pid 15230] futex(0xc000124d48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15239] <... futex resumed>)        = 0
[pid 15238] <... write resumed>)        = 17
[pid 15230] <... futex resumed>)        = 1
[pid 15239] kill(0, SIGUSR2 <unfinished ...>
[pid 15230] futex(0x672fe0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15239] <... kill resumed>)         = 0
[pid 15238] write(1, "fuse: -> [ID=0x2] Getattr error="..., 38 <unfinished ...>
[pid 15231] <... futex resumed>)        = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 15239] --- SIGUSR2 {si_signo=SIGUSR2, si_code=SI_USER, si_pid=15228, si_uid=1001} ---
[pid 15231] futex(0xc000030948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15238] <... write resumed>)        = 38
[pid 15230] <... futex resumed>)        = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15239] futex(0x672fe0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15238] write(6, "\20\0\0\0\374\377\377\377\2\0\0\0\0\0\0\0", 16 <unfinished ...>
[pid 15230] futex(0x672fe0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15229] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 15239] <... futex resumed>)        = 0
[pid 15238] <... write resumed>)        = 16
[pid 15230] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 15228] <... newfstatat resumed>0xc000122038, 0) = -1 EINTR (Interrupted system call)
[pid 15239] rt_sigreturn({mask=[]} <unfinished ...>
[pid 15238] futex(0xc000030548, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 15230] futex(0xc000030548, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15239] <... rt_sigreturn resumed>) = 0
[pid 15238] <... futex resumed>)        = 0
[pid 15230] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 15229] <... nanosleep resumed>NULL) = 0
[pid 15228] futex(0x643e28, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 15230] write(1, "error: stat ./test: interrupted "..., 44 <unfinished ...>

[networkimprov]

cc @tv42

[ianlancetaylor]

@fastest963 Thanks. The strace output shows that the newfstatat syscall is being interrupted, and is returning EINTR. My takeaway is that when using a FUSE file system essentially any system call that touches the file system can return EINTR. Unfortunately I don't see a reasonable way to add a test case for a FUSE file system to the standard library, though I would be happy to hear suggestions (these suggestions can not involve importing a big package like https://github.com/bazil/fuse into the standard library just for testing purposts).

I guess I'll just look for syscall functions in the os package and add EINTR loops. Then we'll see what happens.

[gopherbot]

Change https://golang.org/cl/249178 mentions this issue: os, internal/poll: loop on EINTR for all file syscalls

[tv42]

A non-FUSE alternative for testing would be seccomp or ptrace triggering that EINTR. Or a special slower build where RawSyscall etc check a flag and never even enter kernelspace. Of course both of those need to be somehow targeted to the thing under test, matching by fd or pathname or kernel thread id.

And yes once networking etc are added to the mix, just about anything can return EINTR, because they mostly have no other choice -- allowing user to control-C out of slow networking is a nice thing to have, so not bailing out isn't really an option. Only a precious few syscalls have something else meaningful to report, so EINTR it is.

If Go's scheduler using SIGURG triggers this logic, that could lead to a nasty scenario where the work is started from scratch on every round, and always interrupted by SIGURG. I sure hope the SIGURG doesn't happen too often.

[networkimprov]

In that case, maybe loop-on-EINTR logic should be disabled via an os.OpenFile() flag. That would apply to previously added EINTR loops, too.

We need loops to keep existing code working with async-preemption, and also need to accommodate network filesystems.

EDIT: this also arose with CIFS: #39237, #38836