Netflix/go-expect

timeout does not seem to fire.

smoser opened this issue · 3 comments

I'm using go-expect and expect.WithTimeout. In our real-world test, we found that the expect timeouts were not being hit.
So we came up with this test case below to demonstrate.

I'm sure I'm doing something wrong, but not sure what. Sorry for the spam if that is the case.

/*
If I run this with 2 args, like:
   go run testme.go 5 skipit

then it will entirely skip the
first go routine, and the expect will timeout (PASS caught timeout).

If I run it with just 1 arg, then the go routine
starts writing to the expect's Tty() and we never
see the timeout caught.
*/
package main

import (
	"fmt"
	"io"
	"os"
	"strconv"
	"time"

	expect "github.com/Netflix/go-expect"
)

func testme(args []string) {
	var timeout = 5
	if len(args) > 0 {
		var err error
		timeout, err = strconv.Atoi(args[0])
		if err != nil {
			fmt.Printf("bad timeout %s", args[1])
			os.Exit(1)
		}
	}

	fmt.Printf("args: %v\n", args)
	c, _ := expect.NewConsole()

	defer c.Close()

	if len(args) <= 1 {
		go func(out io.Writer) {
			var err error
			written := 0
			asBytes := []byte("Cruft")
			for numStatus, tot := -1, 0; true; tot += written {
				written, err = out.Write(asBytes)
				if err != nil {
					fmt.Printf("failed write\n")
					os.Exit(1)
				}
				if tot/5 > numStatus {
					fmt.Printf("%d\n", tot)
					numStatus++
				}
				time.Sleep(time.Duration(1) * time.Second)
			}
		}(c.Tty())
	}

	go func() {
		extra := 2
		timeBuf := time.Duration(timeout+extra) * time.Second
		fmt.Printf("setting timer for %s\n", timeBuf)
		timer := time.NewTimer(timeBuf)
		select {
		case <-timer.C:
			fmt.Printf("ERROR: %d seconds past timeout!", extra)
			os.Exit(1)
		}
	}()

	t := expect.WithTimeout(time.Duration(timeout) * time.Second)
	matched, err := c.Expect(expect.String("hi:"), t)
	if err != nil {
		// Should catch timeout here.
		if os.IsTimeout(err) {
			fmt.Printf("PASS: caught timeout\n")
			os.Exit(0)
		}
		fmt.Printf("Got an error: %s\n", err)
		os.Exit(1)
	}
	fmt.Printf("got the string: %s\n", matched)
}

func main() {
	if len(os.Args) == 1 {
		testme([]string{"2"})
		// testme([]string{"2", "skip"}) // this will PASS: caught timeout
		// testme([]{string{"2"}) // this will ERROR: 2 seconds past timeout
		return
	}
	testme(os.Args[1:]) // to run your own.
}

Hi @smoser, the timeout on c.Expect is reset every time more bytes are read (because it may contain the match), which is why it doesn't time out in your example.

If you can expand on your use case, perhaps we can come up with a feature.

In the following snippit, I was thinking that the call to c.Expect would return in at most the provided time.Duration either because of a timeout or a match. The explanation you gave makes sense.

matched, err := c.Expect(
    expect.String("hi:"),
    expect.WithTimeout(time.Duration(timeout) * time.Second)

The specific problem that we were solving was rebooting a vm while expect'ing on its ttyS0 output. We would then expect to see a login prompt inside of a provided timeout. If we didn't see the login prompt in X seconds, then the test failed. The problem we hit was that the system went into a reboot loop, so Expect had an endless stream of data to continuously start a new timer.

We can obviously handle that ourselves with a solution like the Timer in the example code, but we'd be happy to find a ready-made solution also.

For anyone else looking, this is what we put into place. Just wrapped the call in simple timeout using time.After.

func ExpectWithin(c *expect.Console, timeout time.Duration, opts ...expect.ExpectOpt) (string, error) {
	myChan := make(chan struct {
		match string
		err   error
	}, 1)
	go func() {
		match, err := c.Expect(opts...)
		myChan <- struct {
			match string
			err   error
		}{match, err}
	}()

	var match string
	var err error

	select {
	case res := <-myChan:
		match = res.match
		err = res.err
	case <-time.After(timeout):
		match = ""
		err = fmt.Errorf("Timeout after %s", timeout)
	}

	return match, err

}

I'll go ahead an close this. If upstream wants to re-open and address it in go-expect itself, then thats fine too.