Wrong behavior of TCPConn.SetReadDeadline, later deadline affects earlier calls?

[xueyu...@gmail.com]

Hi everyone,

I have been playing with Go's net package and observed the following issue. 

According to Go doc, "SetReadDeadline sets the deadline for future Read calls". If my understanding is correct, if we set a deadline while an
earlier call is pending, the new deadline should not affect the behavior of the pending call. However, I did the following test and found it
behaved differently. I'm wondering if it is my misunderstanding or it is a potential bug in the implementation.

The following test reproduces the wrong behavior. It is expected that request 1 should timeout, but it didn't because request 2 resets the 
deadline while request 1 is pending. Comment out the code for request 2 and then request 1 times out correctly.

// TestServer is a mock server that does nothing more than returning the input
// after sleeping for 20 seconds.
type TestServer struct {
}

// Sleep is the RPC call that sleeps for 20 seconds before returning the value.
func (s TestServer) Sleep(req int, reply *int) error {
        fmt.Printf("Received request %d\n", req)
        time.Sleep(20 * time.Second)
        *reply = req
        return nil
}

func TestDeadline(t *testing.T) {
        // Start the RPC server.
        srvListener, err := net.Listen("tcp", "localhost:0")
        if nil != err {
                t.Fatal(err)
        }
        server := rpc.NewServer()
        server.Register(TestServer{})
        go server.Accept(srvListener)

        // Create a RPC client.
        srvAddr, err := net.ResolveTCPAddr("tcp", srvListener.Addr().String())
        if nil != err {
                t.Fatal(err)
        }
        cliConn, err := net.DialTCP("tcp", nil, srvAddr)
        if nil != err {
                t.Fatal(err)
        }
        client := rpc.NewClient(cliConn)

        // Set a deadline that is longer than the sleep time.
        cliConn.SetReadDeadline(time.Now().Add(30 * time.Second))

        // Send a request and it should succeed before timeout.
        var reply int
        if err := client.Call("TestServer.Sleep", 0, &reply); nil != err {
                t.Fatal(err)
        } else {
                fmt.Printf("Processed request %d\n", reply)
        }

        // NOTE: Now we're going to see the issue with concurrent requests.
        var wg sync.WaitGroup

        // Set a deadline that is shorter than the sleep time.
        cliConn.SetReadDeadline(time.Now().Add(10 * time.Second))

        // Send the first request and it should timeout.
        wg.Add(1)
        go func() {
                var reply int
                if err := client.Call("TestServer.Sleep", 1, &reply); nil == err {
                        fmt.Printf("Processed request %d\n", reply)
                        t.Error("request 1 should timeout")
                }
                wg.Done()
        }()

        // Sleep for a while to make sure that the go scheduler schedules the
        // first request.
        time.Sleep(2 * time.Second)

        // Set the deadline that is longer than the sleep time.
        // NOTE: This should not affect the first request per Go doc --
        // SetDeadline should only affect future I/O.
        cliConn.SetReadDeadline(time.Now().Add(40 * time.Second))

        // Send the second request and it should succeed before timeout.
        wg.Add(1)
        go func() {
                var reply int
                if err := client.Call("TestServer.Sleep", 2, &reply); nil != err {
                        t.Errorf("expected no error but got %s", err)
                } else {
                        fmt.Printf("Processed request %d\n", reply)
                }
                wg.Done()
        }()

        // Wait for the requests to complete.
        wg.Wait()
}

[James Bardin]

On Tuesday, July 28, 2015 at 1:31:52 AM UTC-4, xueyu...@gmail.com wrote:

Hi everyone,

I have been playing with Go's net package and observed the following issue. 

According to Go doc, "SetReadDeadline sets the deadline for future Read calls". If my understanding is correct, if we set a deadline while an
earlier call is pending, the new deadline should not affect the behavior of the pending call. However, I did the following test and found it
behaved differently. I'm wondering if it is my misunderstanding or it is a potential bug in the implementation.

The RPC calls are all made over a single tcp connection, so manipulating that connection will affect all calls. Once the ReadDeadline is reached on the connection, all further Reads will fail. There's no way for the client to selectively read the responses (which may come back out of order) when the connection is essentially closed. 

[James Bardin]

On Tue, Jul 28, 2015 at 1:30 PM, <xue...@upthere.com> wrote:

Thanks for the timely response, James!

I understand and agree on your second part of comment: when the ReadDeadline is reached, the connection is essentially closed and all future Reads will fail. What bothers me is a different scenario shown in my example test.

1. Before we send request 1, we call SetReadDeadline to set the deadline to be 10 seconds from now. This request should timeout if we skip step 2 below, as the server will sleep for 30 seconds before returning the result, which goes beyond the deadline.
2. However, after we send request 1 and while it is pending (deadline not reached yet), we call SetReadDeadline again to reset the deadline to be 40 seconds from now -- longer than the server's sleep time. It turns out that request 1 succeeds before deadline is reached.
   

The doc says SetReadDeadline only affects future Reads, but in this example, it affects past Reads as well -- request 1 was sent before the second call to SetReadDeadline. Is this the right behavior?

First, there is one connection, so there is only ever one Read call going on at a time. Also, since a response may require more than one call to Read, there's no way to differentiate which Reads were for which request.

This sentence from the documentation is probably more helpful:

        // A deadline is an absolute time after which I/O operations

        // fail with a timeout (see type Error) instead of

        // blocking. The deadline applies to all future I/O, not just

        // the immediately following call to Read or Write.

"All future I/O", even those that have been initiated before the call will be effected.

[xue...@upthere.com]

On Tuesday, July 28, 2015 at 10:47:06 AM UTC-7, James Bardin wrote:

First, there is one connection, so there is only ever one Read call going on at a time. Also, since a response may require more than one call to Read, there's no way to differentiate which Reads were for which request.

This sentence from the documentation is probably more helpful:

        // A deadline is an absolute time after which I/O operations

        // fail with a timeout (see type Error) instead of

        // blocking. The deadline applies to all future I/O, not just

        // the immediately following call to Read or Write.

"All future I/O", even those that have been initiated before the call will be effected.

Thank you again for the detailed explanation. Now I get a much better understanding on connection deadlines :). It seems I have to find other ways to achieve what I wanted.

[xue...@upthere.com]

On Tuesday, July 28, 2015 at 6:41:42 AM UTC-7, James Bardin wrote:

The RPC calls are all made over a single tcp connection, so manipulating that connection will affect all calls. Once the ReadDeadline is reached on the connection, all further Reads will fail. There's no way for the client to selectively read the responses (which may come back out of order) when the connection is essentially closed.