x/sys/unix: strange behaviour on unix.Select

[cyberxnomad]

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

$ go version
go1.20.5

Does this issue reproduce with the latest release?

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

linux/arm

What did you do?

I'm using "Select" to get serial port data, but I'm experiencing some strange behavior. Instead of waiting for the specified timeout duration, it immediately times out.

code:

var (
	fd      int
	nfds    int
	readSet unix.FdSet
	tv      unix.Timeval
	buf     []byte // read buffer
	frame   []byte
	nbytes  int // how many bytes read
)

fd = g.ser.Fd() // get serial fd
frame = make([]byte, 0)

readSet.Zero()
readSet.Set(fd)
tv.Sec = 0
tv.Usec = 100 * 1000 // 100ms

mlog.Debug.Println("starting select")
if nfds, err = unix.Select(fd+1, &readSet, nil, nil, &tv); err != nil {
	mlog.Error.Println(err)
	return
}
if nfds > 0 {
	if readSet.IsSet(fd) {
		buf = make([]byte, 1024)
		if nbytes, err = g.ser.Read(buf); err != nil { // read data of serial
			mlog.Error.Println(err)
			return
		}
		if nbytes > 0 {
			frame = append(frame, buf[:nbytes]...) // package as a frame
		}
	}
} else if nfds == 0 {
	mlog.Debug.Println("timeout")
	err = eAckTimeOut
	return
} else {
	err = eUnknow
	return
}

Loop calling the above code

What did you expect to see?

[DEBUG] 2023/07/07 17:17:03.662758 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:03.775798 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:03.885805 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:03.995762 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:04.105745 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:04.215735 gbus.go:211: starting select
...

What did you see instead?

[DEBUG] 2023/07/07 17:17:03.662758 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:03.775798 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:03.885805 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:03.995762 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:04.105745 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:04.215735 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:04.325825 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:04.435783 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:04.545723 gbus.go:211: starting select
[DEBUG] 2023/07/07 17:17:04.548090 gbus.go:232: timeout

Please take a look at the time in the last two lines. The difference in time between the two is only about 3 milliseconds. But the timeout time set in the code is 100 milliseconds.

[rittneje]

Can you add the actual for loop to your code sample?

[cyberxnomad]

@rittneje Hello, the code is as follows

func (g *Gbus) SendThenRecv(sendMsg []byte, timo int) (frame []byte, err error) {
	var (
		fd      int
		nfds    int
		readSet unix.FdSet
		tv      unix.Timeval
		buf     []byte // read buffer
		nbytes  int    // how many bytes read
	)

	// func (s *S) Write(buf []byte)(n int, err error) {
	//	n, err = unix.Write(s.fd, buf)
	//  	return
	// }
	if _, err = g.ser.Write(sendMsg); err != nil {
		return
	}

	// func (s *S) Tcdrain() (err error) {
	// 	_, _, eno := unix.Syscall(unix.SYS_IOCTL, uintptr(s.fd), uintptr(unix.TCSBRK), uintptr(1))
	//	if eno != 0 {
	//		err = errors.New(eno.Error())
	//	}
	//	return
	// }	
	g.ser.Tcdrain()

	fd = g.ser.Fd() // get serial fd
	frame = make([]byte, 0)

	readSet.Zero()
	readSet.Set(fd)
	tv.Sec = 0
	tv.Usec = timo * 1000

	mlog.Debug.Println("starting select")
	if nfds, err = unix.Select(fd+1, &readSet, nil, nil, &tv); err != nil {
		mlog.Error.Println(err)
		return
	}
	if nfds > 0 {
		if readSet.IsSet(fd) {
			buf = make([]byte, 1024)

			// func (s *S) Read(buf []byte) (n int, err error) {
			// 	n, err = unix.Read(s.fd, buf)
			// 	return
			// }
			if nbytes, err = g.ser.Read(buf); err != nil { // read data of serial
				mlog.Error.Println(err)
				return
			}
			if nbytes > 0 {
				frame = append(frame, buf[:nbytes]...) // package as a frame
			}
		}
	} else if nfds == 0 {
		mlog.Debug.Println("timeout")
		err = eAckTimeOut
		return
	} else {
		err = eUnknow
		return
	}

	return
}

func main() {
	var (
		frame []byte
		err   error
	)
	// ...

	sendMsg := []byte{0x01, 0x02, 0x03} // some serialized data

	for {
		if frame, err = g.SendThenRecv(sendMsg, 100); err != nil {
			// handle error
			// ...
			time.Sleep(20 * time.Millisecond)
			continue
		}
		// handle received data
		// ...
		time.Sleep(20 * time.Millisecond)
	}

	// ..
}

[bcmills]

Per https://pubs.opengroup.org/onlinepubs/9699919799/functions/pselect.html#tag_16_400_05, select may return EINTR if interrupted by a signal.

The Go runtime sometimes self-signals in order to preempt a running goroutine. You should assume that any syscall that is permitted to return EINTR will actually do so from time to time, and add retry loops as needed to account for that.

[rittneje]

@bcmills If that were the culprit, wouldn't unix.Select return an error instead of 0, nil (which signals a timeout)? (I agree the missing EINTR handling is an issue, just doesn't seem like the issue.)

[ianlancetaylor]

Try running the program under strace -f. It may help to see exactly what is being passed to the system call.

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)