os: reading from tun device after using command pipe: `read /dev/net/tun: not pollable`

[mandelsoft]

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

$ go version
go version go1.13.10 linux/amd64
go version go1.14.2 linux/amd64

Does not appear with 1.12

Does this issue reproduce with the latest release?

yes

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/root/go"
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="/home/d021770/dev/go/ip/src/github.com/mandelsoft/k8sbridge/go.mod"
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-build606326318=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I'm creating a tun device and trying to read from it.
Read aborts with the error read /dev/net/tun: not pollable, if before creating the tun device (file descriptor) an exec.Command is executed, but only if this catches the output.

Calling the program below with argument no works.
If argument yes is given, the problem occurs in most of the cases, but not always.

If the output is not catched (remove c.Stdout` assignment in code below) it also works if the
command is executed before the interface creation.

package main

import (
	"bytes"
	"fmt"
	"log"
	"os"
	"os/exec"
	"sync"
	"syscall"
	"unsafe"

	"github.com/pkg/errors"
	"github.com/vishvananda/netlink"
	"golang.org/x/sys/unix"
)

const TUNIP = "192.168.1.2"
const TUNCIDR = TUNIP + "/24"


func ExitOnErr(msg string, args ...interface{}) {
	if args[len(args)-1] == nil {
		return
	}
	fmt.Printf(msg+": %s\n", args...)
	os.Exit(1)
}

func echo(text string) {
	c := exec.Command("echo",  text)
	var out bytes.Buffer
	c.Stdout = &out
	c.Start()
	c.Wait()
	fmt.Printf("-> %s\n", out.String())
}

func cstringToGoString(cstring []byte) string {
	strs := bytes.Split(cstring, []byte{0x00})
	return string(strs[0])
}

type ifreq struct {
	name  [unix.IFNAMSIZ]byte // c string
	flags uint16                 // c short
	_pad  [24 - unsafe.Sizeof(uint16(0))]byte
}

func ioctl(fd, request uintptr, argp unsafe.Pointer) error {
	if _, _, e := syscall.Syscall6(syscall.SYS_IOCTL, fd, request, uintptr(argp), 0, 0, 0); e != 0 {
		return e
	}
	return nil
}

func createInterface(flags uint16, name string) (string, *os.File, error) {
	// Last byte of name must be nil for C string, so name must be
	// short enough to allow that
	if len(name) > syscall.IFNAMSIZ-1 {
		return "", nil, errors.New("device name too long")
	}

	f, err := os.OpenFile("/dev/net/tun", os.O_RDWR, 0600)
	if err != nil {
		return "", nil, err
	}

	var nbuf [syscall.IFNAMSIZ]byte
	copy(nbuf[:], []byte(name))

	fd := f.Fd()
	ifr := ifreq{
		name:  nbuf,
		flags: flags,
	}
	if err := ioctl(fd, syscall.TUNSETIFF, unsafe.Pointer(&ifr)); err != nil {
		return "", nil, err
	}
	return cstringToGoString(ifr.name[:]), f, nil
}

func main() {
	problem := len(os.Args) > 1 && os.Args[1]=="yes"

	if problem {
		echo("with problem")
	}

	name, fd, err:= createInterface(unix.IFF_TUN|unix.IFF_NO_PI, "")
	ExitOnErr("cannot create tun", err)
	fmt.Printf("tun: %s\n", name)

	if !problem {
		echo("without problem")
	}

	link, err := netlink.LinkByName(name)
	ExitOnErr("cannot get link %q", name, err)

	addr, err := netlink.ParseAddr(TUNCIDR)
	ExitOnErr("cannot create addr %q", TUNCIDR, err)

	err = netlink.AddrAdd(link, addr)
	ExitOnErr("cannot add addr %q", TUNCIDR, err)

	err = netlink.LinkSetUp(link)
	ExitOnErr("cannot bring up %q", name, err)


	wait := sync.WaitGroup{}
	wait.Add(1)

	go func() {
		buffer := [2000]byte{}
		for {
			n, err := fd.Read(buffer[:])  // booom
			if n <= 0 || err != nil {
				fmt.Printf("END: %d bytes, err=%s\n", n, err)
				break
			}
			log.Printf("Read %d bytes", n)
		}
		wait.Done()
	}()

	wait.Wait()
	log.Print("Closing")
	err = fd.Close()
	if err != nil {
		log.Print("Close errored: ", err)
	}
	log.Print("Exiting")
}

What did you expect to see?

I expect the read to work and the program should print the size of the packet send to the tun device.

What did you see instead?

Instead the read failed with the error read /dev/net/tun: not pollable

[andybons]

#30426 seems related

@crvv who had valuable insight before

[mandelsoft]

Hi @andybons,

I've also tried the SysConn variant

s, _ := fd.SyscallConn()
s.Control(func(fd uintptr) {
		_, _, errno = unix.Syscall(
			unix.SYS_IOCTL,
			fd,
			uintptr(unix.TUNSETIFF),
			uintptr(unsafe.Pointer(&ifr[0])),
           )
})

It works even worse. It completely blocks the Read call. The fix here is to add an fd.Fd() call in front of the reading loop. But even with this workaround, I get the not pollable error once I try to read from the file descriptor.
It really seems to be related to the usage of the pipe for the command execution of the exec.Command execution prior to the unix.Syscall or syscall.Syscall stuff used for the tun creation.

[ianlancetaylor]

I can get the problem to occur when running the program without an argument, although it fails much more often with the argument "yes".

[ianlancetaylor]

An strace shows

[pid  6403] openat(AT_FDCWD, "/dev/net/tun", O_RDWR|O_CLOEXEC <unfinished ...>
[pid  6403] <... openat resumed> )      = 3
[pid  6403] epoll_ctl(4, EPOLL_CTL_ADD, 3, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=1803304728, u64=139828758593304}} <unfinished ...>
[pid  6403] <... epoll_ctl resumed> )   = 0
[pid  6406] <... epoll_pwait resumed> [{EPOLLERR, {u32=1803304728, u64=139828758593304}}], 128, -1, NULL, 0) = 1

In other words, we can successfully register the descriptor with epoll, but epoll then immediately reports an error on the newly registered descriptor. We record that error and wind up reporting it back to the program as not pollable.

[ianlancetaylor]

@mandelsoft Could you see if https://golang.org/cl/229764 fixes the problem for you? Thanks.

[gopherbot]

Change https://golang.org/cl/229764 mentions this issue: internal/poll: treat immediate poll error as non-pollable file

[crvv]

Please see #30426.

The tun fd is put into epoll before ioctl, so epoll won't work on that fd.
But function createInterface calls (*os.File).Fd, which put the fd into blocking mode.
So Read can work without epoll.
The fix is simple. Use unix.Open, ioctl, unix.SetNonBlock and os.NewFile.

The EPOLLERR returned by epoll_wait is #30426 (comment)

But it returns EPOLLERR only if epoll_wait is called before ioctl.
If ioctl is called before epoll_wait, epoll_wait will never return that EPOLLERR. And in this case, epoll still doesn't work on that fd.

With CL 229764, it will always work if the fd is in blocking mode.

[mandelsoft]

Hi @crvv, thank you very much, using unix.Open instead of os.OpenFile and setting the fd to NonBlocking seems to solve the problem, it also works in my original project.

Maybe someone should bring this fix to the pkg/taptun project. That's the first search result when using google to look for golang taptunor golang tun.

[ianlancetaylor]

@mandelsoft @crvv Do you think it would be a good idea to apply CL 229764, or should we just treat this as a Linux kernel bug that can be worked around in Go code by using unix.Open?

[mandelsoft]

I'm not so deep into this OS topic to decide on this. I just found this taptun library and tried to used it.

[ianlancetaylor]

OK, thanks. Closing this issue as there is a workaround.