Source file src/net/timeout_test.go

     1  // Copyright 2009 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  package net
     6  
     7  import (
     8  	"context"
     9  	"errors"
    10  	"fmt"
    11  	"io"
    12  	"os"
    13  	"runtime"
    14  	"sync"
    15  	"testing"
    16  	"time"
    17  )
    18  
    19  func init() {
    20  	// Install a hook to ensure that a 1ns timeout will always
    21  	// be exceeded by the time Dial gets to the relevant system call.
    22  	//
    23  	// Without this, systems with a very large timer granularity — such as
    24  	// Windows — may be able to accept connections without measurably exceeding
    25  	// even an implausibly short deadline.
    26  	testHookStepTime = func() {
    27  		now := time.Now()
    28  		for time.Since(now) == 0 {
    29  			time.Sleep(1 * time.Nanosecond)
    30  		}
    31  	}
    32  }
    33  
    34  var dialTimeoutTests = []struct {
    35  	initialTimeout time.Duration
    36  	initialDelta   time.Duration // for deadline
    37  }{
    38  	// Tests that dial timeouts, deadlines in the past work.
    39  	{-5 * time.Second, 0},
    40  	{0, -5 * time.Second},
    41  	{-5 * time.Second, 5 * time.Second}, // timeout over deadline
    42  	{-1 << 63, 0},
    43  	{0, -1 << 63},
    44  
    45  	{1 * time.Millisecond, 0},
    46  	{0, 1 * time.Millisecond},
    47  	{1 * time.Millisecond, 5 * time.Second}, // timeout over deadline
    48  }
    49  
    50  func TestDialTimeout(t *testing.T) {
    51  	switch runtime.GOOS {
    52  	case "plan9":
    53  		t.Skipf("not supported on %s", runtime.GOOS)
    54  	}
    55  
    56  	t.Parallel()
    57  
    58  	ln := newLocalListener(t, "tcp")
    59  	defer func() {
    60  		if err := ln.Close(); err != nil {
    61  			t.Error(err)
    62  		}
    63  	}()
    64  
    65  	for _, tt := range dialTimeoutTests {
    66  		t.Run(fmt.Sprintf("%v/%v", tt.initialTimeout, tt.initialDelta), func(t *testing.T) {
    67  			// We don't run these subtests in parallel because we don't know how big
    68  			// the kernel's accept queue is, and we don't want to accidentally saturate
    69  			// it with concurrent calls. (That could cause the Dial to fail with
    70  			// ECONNREFUSED or ECONNRESET instead of a timeout error.)
    71  			d := Dialer{Timeout: tt.initialTimeout}
    72  			delta := tt.initialDelta
    73  
    74  			var (
    75  				beforeDial time.Time
    76  				afterDial  time.Time
    77  				err        error
    78  			)
    79  			for {
    80  				if delta != 0 {
    81  					d.Deadline = time.Now().Add(delta)
    82  				}
    83  
    84  				beforeDial = time.Now()
    85  
    86  				var c Conn
    87  				c, err = d.Dial(ln.Addr().Network(), ln.Addr().String())
    88  				afterDial = time.Now()
    89  
    90  				if err != nil {
    91  					break
    92  				}
    93  
    94  				// Even though we're not calling Accept on the Listener, the kernel may
    95  				// spuriously accept connections on its behalf. If that happens, we will
    96  				// close the connection (to try to get it out of the kernel's accept
    97  				// queue) and try a shorter timeout.
    98  				//
    99  				// We assume that we will reach a point where the call actually does
   100  				// time out, although in theory (since this socket is on a loopback
   101  				// address) a sufficiently clever kernel could notice that no Accept
   102  				// call is pending and bypass both the queue and the timeout to return
   103  				// another error immediately.
   104  				t.Logf("closing spurious connection from Dial")
   105  				c.Close()
   106  
   107  				if delta <= 1 && d.Timeout <= 1 {
   108  					t.Fatalf("can't reduce Timeout or Deadline")
   109  				}
   110  				if delta > 1 {
   111  					delta /= 2
   112  					t.Logf("reducing Deadline delta to %v", delta)
   113  				}
   114  				if d.Timeout > 1 {
   115  					d.Timeout /= 2
   116  					t.Logf("reducing Timeout to %v", d.Timeout)
   117  				}
   118  			}
   119  
   120  			if d.Deadline.IsZero() || afterDial.Before(d.Deadline) {
   121  				delay := afterDial.Sub(beforeDial)
   122  				if delay < d.Timeout {
   123  					t.Errorf("Dial returned after %v; want ≥%v", delay, d.Timeout)
   124  				}
   125  			}
   126  
   127  			if perr := parseDialError(err); perr != nil {
   128  				t.Errorf("unexpected error from Dial: %v", perr)
   129  			}
   130  			if nerr, ok := err.(Error); !ok || !nerr.Timeout() {
   131  				t.Errorf("Dial: %v, want timeout", err)
   132  			}
   133  		})
   134  	}
   135  }
   136  
   137  func TestDialTimeoutMaxDuration(t *testing.T) {
   138  	ln := newLocalListener(t, "tcp")
   139  	defer func() {
   140  		if err := ln.Close(); err != nil {
   141  			t.Error(err)
   142  		}
   143  	}()
   144  
   145  	for _, tt := range []struct {
   146  		timeout time.Duration
   147  		delta   time.Duration // for deadline
   148  	}{
   149  		// Large timeouts that will overflow an int64 unix nanos.
   150  		{1<<63 - 1, 0},
   151  		{0, 1<<63 - 1},
   152  	} {
   153  		t.Run(fmt.Sprintf("timeout=%s/delta=%s", tt.timeout, tt.delta), func(t *testing.T) {
   154  			d := Dialer{Timeout: tt.timeout}
   155  			if tt.delta != 0 {
   156  				d.Deadline = time.Now().Add(tt.delta)
   157  			}
   158  			c, err := d.Dial(ln.Addr().Network(), ln.Addr().String())
   159  			if err != nil {
   160  				t.Fatal(err)
   161  			}
   162  			if err := c.Close(); err != nil {
   163  				t.Error(err)
   164  			}
   165  		})
   166  	}
   167  }
   168  
   169  func TestAcceptTimeout(t *testing.T) {
   170  	t.Parallel()
   171  
   172  	switch runtime.GOOS {
   173  	case "plan9":
   174  		t.Skipf("not supported on %s", runtime.GOOS)
   175  	}
   176  
   177  	timeouts := []time.Duration{
   178  		-5 * time.Second,
   179  		10 * time.Millisecond,
   180  	}
   181  
   182  	for _, timeout := range timeouts {
   183  		t.Run(fmt.Sprintf("%v", timeout), func(t *testing.T) {
   184  			t.Parallel()
   185  
   186  			ln := newLocalListener(t, "tcp")
   187  			defer ln.Close()
   188  
   189  			if timeout >= 0 {
   190  				// Don't dial the listener at all, so that Accept will hang.
   191  			} else {
   192  				// A deadline in the past should cause Accept to fail even if there are
   193  				// incoming connections available. Try to make one available before the
   194  				// call to Accept happens. (It's ok if the timing doesn't always work
   195  				// out that way, though: the test should pass regardless.)
   196  				ctx, cancel := context.WithCancel(context.Background())
   197  				dialDone := make(chan struct{})
   198  
   199  				// Ensure that our background Dial returns before we close the listener.
   200  				// Otherwise, the listener's port could be reused immediately and we
   201  				// might spuriously Dial some completely unrelated socket, causing some
   202  				// other test to see an unexpected extra connection.
   203  				defer func() {
   204  					cancel()
   205  					<-dialDone
   206  				}()
   207  
   208  				go func() {
   209  					defer close(dialDone)
   210  					d := Dialer{}
   211  					c, err := d.DialContext(ctx, ln.Addr().Network(), ln.Addr().String())
   212  					if err != nil {
   213  						// If the timing didn't work out, it is possible for this Dial
   214  						// to return an error (depending on the kernel's buffering behavior).
   215  						// In https://go.dev/issue/65240 we saw failures with ECONNREFUSED
   216  						// and ECONNRESET.
   217  						//
   218  						// What this test really cares about is the behavior of Accept, not
   219  						// Dial, so just log the error and ignore it.
   220  						t.Logf("DialContext: %v", err)
   221  						return
   222  					}
   223  					t.Logf("Dialed %v -> %v", c.LocalAddr(), c.RemoteAddr())
   224  					c.Close()
   225  				}()
   226  
   227  				time.Sleep(10 * time.Millisecond)
   228  			}
   229  
   230  			if err := ln.(*TCPListener).SetDeadline(time.Now().Add(timeout)); err != nil {
   231  				t.Fatal(err)
   232  			}
   233  			t.Logf("ln.SetDeadline(time.Now().Add(%v))", timeout)
   234  
   235  			c, err := ln.Accept()
   236  			if err == nil {
   237  				c.Close()
   238  			}
   239  			t.Logf("ln.Accept: %v", err)
   240  
   241  			if perr := parseAcceptError(err); perr != nil {
   242  				t.Error(perr)
   243  			}
   244  			if !isDeadlineExceeded(err) {
   245  				t.Error("wanted deadline exceeded")
   246  			}
   247  		})
   248  	}
   249  }
   250  
   251  func TestAcceptTimeoutMustReturn(t *testing.T) {
   252  	t.Parallel()
   253  
   254  	switch runtime.GOOS {
   255  	case "plan9":
   256  		t.Skipf("not supported on %s", runtime.GOOS)
   257  	}
   258  
   259  	ln := newLocalListener(t, "tcp")
   260  	defer ln.Close()
   261  
   262  	if err := ln.(*TCPListener).SetDeadline(noDeadline); err != nil {
   263  		t.Error(err)
   264  	}
   265  	if err := ln.(*TCPListener).SetDeadline(time.Now().Add(10 * time.Millisecond)); err != nil {
   266  		t.Error(err)
   267  	}
   268  	c, err := ln.Accept()
   269  	if err == nil {
   270  		c.Close()
   271  	}
   272  
   273  	if perr := parseAcceptError(err); perr != nil {
   274  		t.Error(perr)
   275  	}
   276  	if !isDeadlineExceeded(err) {
   277  		t.Fatal(err)
   278  	}
   279  }
   280  
   281  func TestAcceptTimeoutMustNotReturn(t *testing.T) {
   282  	t.Parallel()
   283  
   284  	switch runtime.GOOS {
   285  	case "plan9":
   286  		t.Skipf("not supported on %s", runtime.GOOS)
   287  	}
   288  
   289  	ln := newLocalListener(t, "tcp")
   290  	defer ln.Close()
   291  
   292  	maxch := make(chan *time.Timer)
   293  	ch := make(chan error)
   294  	go func() {
   295  		if err := ln.(*TCPListener).SetDeadline(time.Now().Add(-5 * time.Second)); err != nil {
   296  			t.Error(err)
   297  		}
   298  		if err := ln.(*TCPListener).SetDeadline(noDeadline); err != nil {
   299  			t.Error(err)
   300  		}
   301  		maxch <- time.NewTimer(100 * time.Millisecond)
   302  		_, err := ln.Accept()
   303  		ch <- err
   304  	}()
   305  
   306  	max := <-maxch
   307  	defer max.Stop()
   308  
   309  	select {
   310  	case err := <-ch:
   311  		if perr := parseAcceptError(err); perr != nil {
   312  			t.Error(perr)
   313  		}
   314  		t.Fatalf("expected Accept to not return, but it returned with %v", err)
   315  	case <-max.C:
   316  		ln.Close()
   317  		<-ch // wait for tester goroutine to stop
   318  	}
   319  }
   320  
   321  var readTimeoutTests = []struct {
   322  	timeout time.Duration
   323  	xerrs   [2]error // expected errors in transition
   324  }{
   325  	// Tests that read deadlines work, even if there's data ready
   326  	// to be read.
   327  	{-5 * time.Second, [2]error{os.ErrDeadlineExceeded, os.ErrDeadlineExceeded}},
   328  
   329  	{50 * time.Millisecond, [2]error{nil, os.ErrDeadlineExceeded}},
   330  }
   331  
   332  // There is a very similar copy of this in os/timeout_test.go.
   333  func TestReadTimeout(t *testing.T) {
   334  	handler := func(ls *localServer, ln Listener) {
   335  		c, err := ln.Accept()
   336  		if err != nil {
   337  			t.Error(err)
   338  			return
   339  		}
   340  		c.Write([]byte("READ TIMEOUT TEST"))
   341  		defer c.Close()
   342  	}
   343  	ls := newLocalServer(t, "tcp")
   344  	defer ls.teardown()
   345  	if err := ls.buildup(handler); err != nil {
   346  		t.Fatal(err)
   347  	}
   348  
   349  	c, err := Dial(ls.Listener.Addr().Network(), ls.Listener.Addr().String())
   350  	if err != nil {
   351  		t.Fatal(err)
   352  	}
   353  	defer c.Close()
   354  
   355  	for i, tt := range readTimeoutTests {
   356  		if err := c.SetReadDeadline(time.Now().Add(tt.timeout)); err != nil {
   357  			t.Fatalf("#%d: %v", i, err)
   358  		}
   359  		var b [1]byte
   360  		for j, xerr := range tt.xerrs {
   361  			for {
   362  				n, err := c.Read(b[:])
   363  				if xerr != nil {
   364  					if perr := parseReadError(err); perr != nil {
   365  						t.Errorf("#%d/%d: %v", i, j, perr)
   366  					}
   367  					if !isDeadlineExceeded(err) {
   368  						t.Fatalf("#%d/%d: %v", i, j, err)
   369  					}
   370  				}
   371  				if err == nil {
   372  					time.Sleep(tt.timeout / 3)
   373  					continue
   374  				}
   375  				if n != 0 {
   376  					t.Fatalf("#%d/%d: read %d; want 0", i, j, n)
   377  				}
   378  				break
   379  			}
   380  		}
   381  	}
   382  }
   383  
   384  // There is a very similar copy of this in os/timeout_test.go.
   385  func TestReadTimeoutMustNotReturn(t *testing.T) {
   386  	t.Parallel()
   387  
   388  	switch runtime.GOOS {
   389  	case "plan9":
   390  		t.Skipf("not supported on %s", runtime.GOOS)
   391  	}
   392  
   393  	ln := newLocalListener(t, "tcp")
   394  	defer ln.Close()
   395  
   396  	c, err := Dial(ln.Addr().Network(), ln.Addr().String())
   397  	if err != nil {
   398  		t.Fatal(err)
   399  	}
   400  	defer c.Close()
   401  
   402  	maxch := make(chan *time.Timer)
   403  	ch := make(chan error)
   404  	go func() {
   405  		if err := c.SetDeadline(time.Now().Add(-5 * time.Second)); err != nil {
   406  			t.Error(err)
   407  		}
   408  		if err := c.SetWriteDeadline(time.Now().Add(-5 * time.Second)); err != nil {
   409  			t.Error(err)
   410  		}
   411  		if err := c.SetReadDeadline(noDeadline); err != nil {
   412  			t.Error(err)
   413  		}
   414  		maxch <- time.NewTimer(100 * time.Millisecond)
   415  		var b [1]byte
   416  		_, err := c.Read(b[:])
   417  		ch <- err
   418  	}()
   419  
   420  	max := <-maxch
   421  	defer max.Stop()
   422  
   423  	select {
   424  	case err := <-ch:
   425  		if perr := parseReadError(err); perr != nil {
   426  			t.Error(perr)
   427  		}
   428  		t.Fatalf("expected Read to not return, but it returned with %v", err)
   429  	case <-max.C:
   430  		c.Close()
   431  		err := <-ch // wait for tester goroutine to stop
   432  		if perr := parseReadError(err); perr != nil {
   433  			t.Error(perr)
   434  		}
   435  		if nerr, ok := err.(Error); !ok || nerr.Timeout() || nerr.Temporary() {
   436  			t.Fatal(err)
   437  		}
   438  	}
   439  }
   440  
   441  var readFromTimeoutTests = []struct {
   442  	timeout time.Duration
   443  	xerrs   [2]error // expected errors in transition
   444  }{
   445  	// Tests that read deadlines work, even if there's data ready
   446  	// to be read.
   447  	{-5 * time.Second, [2]error{os.ErrDeadlineExceeded, os.ErrDeadlineExceeded}},
   448  
   449  	{50 * time.Millisecond, [2]error{nil, os.ErrDeadlineExceeded}},
   450  }
   451  
   452  func TestReadFromTimeout(t *testing.T) {
   453  	ch := make(chan Addr)
   454  	defer close(ch)
   455  	handler := func(ls *localPacketServer, c PacketConn) {
   456  		if dst, ok := <-ch; ok {
   457  			c.WriteTo([]byte("READFROM TIMEOUT TEST"), dst)
   458  		}
   459  	}
   460  	ls := newLocalPacketServer(t, "udp")
   461  	defer ls.teardown()
   462  	if err := ls.buildup(handler); err != nil {
   463  		t.Fatal(err)
   464  	}
   465  
   466  	host, _, err := SplitHostPort(ls.PacketConn.LocalAddr().String())
   467  	if err != nil {
   468  		t.Fatal(err)
   469  	}
   470  	c, err := ListenPacket(ls.PacketConn.LocalAddr().Network(), JoinHostPort(host, "0"))
   471  	if err != nil {
   472  		t.Fatal(err)
   473  	}
   474  	defer c.Close()
   475  	ch <- c.LocalAddr()
   476  
   477  	for i, tt := range readFromTimeoutTests {
   478  		if err := c.SetReadDeadline(time.Now().Add(tt.timeout)); err != nil {
   479  			t.Fatalf("#%d: %v", i, err)
   480  		}
   481  		var b [1]byte
   482  		for j, xerr := range tt.xerrs {
   483  			for {
   484  				n, _, err := c.ReadFrom(b[:])
   485  				if xerr != nil {
   486  					if perr := parseReadError(err); perr != nil {
   487  						t.Errorf("#%d/%d: %v", i, j, perr)
   488  					}
   489  					if !isDeadlineExceeded(err) {
   490  						t.Fatalf("#%d/%d: %v", i, j, err)
   491  					}
   492  				}
   493  				if err == nil {
   494  					time.Sleep(tt.timeout / 3)
   495  					continue
   496  				}
   497  				if nerr, ok := err.(Error); ok && nerr.Timeout() && n != 0 {
   498  					t.Fatalf("#%d/%d: read %d; want 0", i, j, n)
   499  				}
   500  				break
   501  			}
   502  		}
   503  	}
   504  }
   505  
   506  var writeTimeoutTests = []struct {
   507  	timeout time.Duration
   508  	xerrs   [2]error // expected errors in transition
   509  }{
   510  	// Tests that write deadlines work, even if there's buffer
   511  	// space available to write.
   512  	{-5 * time.Second, [2]error{os.ErrDeadlineExceeded, os.ErrDeadlineExceeded}},
   513  
   514  	{10 * time.Millisecond, [2]error{nil, os.ErrDeadlineExceeded}},
   515  }
   516  
   517  // There is a very similar copy of this in os/timeout_test.go.
   518  func TestWriteTimeout(t *testing.T) {
   519  	t.Parallel()
   520  
   521  	ln := newLocalListener(t, "tcp")
   522  	defer ln.Close()
   523  
   524  	for i, tt := range writeTimeoutTests {
   525  		c, err := Dial(ln.Addr().Network(), ln.Addr().String())
   526  		if err != nil {
   527  			t.Fatal(err)
   528  		}
   529  		defer c.Close()
   530  
   531  		if err := c.SetWriteDeadline(time.Now().Add(tt.timeout)); err != nil {
   532  			t.Fatalf("#%d: %v", i, err)
   533  		}
   534  		for j, xerr := range tt.xerrs {
   535  			for {
   536  				n, err := c.Write([]byte("WRITE TIMEOUT TEST"))
   537  				if xerr != nil {
   538  					if perr := parseWriteError(err); perr != nil {
   539  						t.Errorf("#%d/%d: %v", i, j, perr)
   540  					}
   541  					if !isDeadlineExceeded(err) {
   542  						t.Fatalf("#%d/%d: %v", i, j, err)
   543  					}
   544  				}
   545  				if err == nil {
   546  					time.Sleep(tt.timeout / 3)
   547  					continue
   548  				}
   549  				if n != 0 {
   550  					t.Fatalf("#%d/%d: wrote %d; want 0", i, j, n)
   551  				}
   552  				break
   553  			}
   554  		}
   555  	}
   556  }
   557  
   558  // There is a very similar copy of this in os/timeout_test.go.
   559  func TestWriteTimeoutMustNotReturn(t *testing.T) {
   560  	t.Parallel()
   561  
   562  	switch runtime.GOOS {
   563  	case "plan9":
   564  		t.Skipf("not supported on %s", runtime.GOOS)
   565  	}
   566  
   567  	ln := newLocalListener(t, "tcp")
   568  	defer ln.Close()
   569  
   570  	c, err := Dial(ln.Addr().Network(), ln.Addr().String())
   571  	if err != nil {
   572  		t.Fatal(err)
   573  	}
   574  	defer c.Close()
   575  
   576  	maxch := make(chan *time.Timer)
   577  	ch := make(chan error)
   578  	go func() {
   579  		if err := c.SetDeadline(time.Now().Add(-5 * time.Second)); err != nil {
   580  			t.Error(err)
   581  		}
   582  		if err := c.SetReadDeadline(time.Now().Add(-5 * time.Second)); err != nil {
   583  			t.Error(err)
   584  		}
   585  		if err := c.SetWriteDeadline(noDeadline); err != nil {
   586  			t.Error(err)
   587  		}
   588  		maxch <- time.NewTimer(100 * time.Millisecond)
   589  		var b [1024]byte
   590  		for {
   591  			if _, err := c.Write(b[:]); err != nil {
   592  				ch <- err
   593  				break
   594  			}
   595  		}
   596  	}()
   597  
   598  	max := <-maxch
   599  	defer max.Stop()
   600  
   601  	select {
   602  	case err := <-ch:
   603  		if perr := parseWriteError(err); perr != nil {
   604  			t.Error(perr)
   605  		}
   606  		t.Fatalf("expected Write to not return, but it returned with %v", err)
   607  	case <-max.C:
   608  		c.Close()
   609  		err := <-ch // wait for tester goroutine to stop
   610  		if perr := parseWriteError(err); perr != nil {
   611  			t.Error(perr)
   612  		}
   613  		if nerr, ok := err.(Error); !ok || nerr.Timeout() || nerr.Temporary() {
   614  			t.Fatal(err)
   615  		}
   616  	}
   617  }
   618  
   619  func TestWriteToTimeout(t *testing.T) {
   620  	t.Parallel()
   621  
   622  	c1 := newLocalPacketListener(t, "udp")
   623  	defer c1.Close()
   624  
   625  	host, _, err := SplitHostPort(c1.LocalAddr().String())
   626  	if err != nil {
   627  		t.Fatal(err)
   628  	}
   629  
   630  	timeouts := []time.Duration{
   631  		-5 * time.Second,
   632  		10 * time.Millisecond,
   633  	}
   634  
   635  	for _, timeout := range timeouts {
   636  		t.Run(fmt.Sprint(timeout), func(t *testing.T) {
   637  			c2, err := ListenPacket(c1.LocalAddr().Network(), JoinHostPort(host, "0"))
   638  			if err != nil {
   639  				t.Fatal(err)
   640  			}
   641  			defer c2.Close()
   642  
   643  			if err := c2.SetWriteDeadline(time.Now().Add(timeout)); err != nil {
   644  				t.Fatalf("SetWriteDeadline: %v", err)
   645  			}
   646  			backoff := 1 * time.Millisecond
   647  			nDeadlineExceeded := 0
   648  			for j := 0; nDeadlineExceeded < 2; j++ {
   649  				n, err := c2.WriteTo([]byte("WRITETO TIMEOUT TEST"), c1.LocalAddr())
   650  				t.Logf("#%d: WriteTo: %d, %v", j, n, err)
   651  				if err == nil && timeout >= 0 && nDeadlineExceeded == 0 {
   652  					// If the timeout is nonnegative, some number of WriteTo calls may
   653  					// succeed before the timeout takes effect.
   654  					t.Logf("WriteTo succeeded; sleeping %v", timeout/3)
   655  					time.Sleep(timeout / 3)
   656  					continue
   657  				}
   658  				if isENOBUFS(err) {
   659  					t.Logf("WriteTo: %v", err)
   660  					// We're looking for a deadline exceeded error, but if the kernel's
   661  					// network buffers are saturated we may see ENOBUFS instead (see
   662  					// https://go.dev/issue/49930). Give it some time to unsaturate.
   663  					time.Sleep(backoff)
   664  					backoff *= 2
   665  					continue
   666  				}
   667  				if perr := parseWriteError(err); perr != nil {
   668  					t.Errorf("failed to parse error: %v", perr)
   669  				}
   670  				if !isDeadlineExceeded(err) {
   671  					t.Errorf("error is not 'deadline exceeded'")
   672  				}
   673  				if n != 0 {
   674  					t.Errorf("unexpectedly wrote %d bytes", n)
   675  				}
   676  				if !t.Failed() {
   677  					t.Logf("WriteTo timed out as expected")
   678  				}
   679  				nDeadlineExceeded++
   680  			}
   681  		})
   682  	}
   683  }
   684  
   685  const (
   686  	// minDynamicTimeout is the minimum timeout to attempt for
   687  	// tests that automatically increase timeouts until success.
   688  	//
   689  	// Lower values may allow tests to succeed more quickly if the value is close
   690  	// to the true minimum, but may require more iterations (and waste more time
   691  	// and CPU power on failed attempts) if the timeout is too low.
   692  	minDynamicTimeout = 1 * time.Millisecond
   693  
   694  	// maxDynamicTimeout is the maximum timeout to attempt for
   695  	// tests that automatically increase timeouts until success.
   696  	//
   697  	// This should be a strict upper bound on the latency required to hit a
   698  	// timeout accurately, even on a slow or heavily-loaded machine. If a test
   699  	// would increase the timeout beyond this value, the test fails.
   700  	maxDynamicTimeout = 4 * time.Second
   701  )
   702  
   703  // timeoutUpperBound returns the maximum time that we expect a timeout of
   704  // duration d to take to return the caller.
   705  func timeoutUpperBound(d time.Duration) time.Duration {
   706  	switch runtime.GOOS {
   707  	case "openbsd", "netbsd":
   708  		// NetBSD and OpenBSD seem to be unable to reliably hit deadlines even when
   709  		// the absolute durations are long.
   710  		// In https://build.golang.org/log/c34f8685d020b98377dd4988cd38f0c5bd72267e,
   711  		// we observed that an openbsd-amd64-68 builder took 4.090948779s for a
   712  		// 2.983020682s timeout (37.1% overhead).
   713  		// (See https://go.dev/issue/50189 for further detail.)
   714  		// Give them lots of slop to compensate.
   715  		return d * 3 / 2
   716  	}
   717  	// Other platforms seem to hit their deadlines more reliably,
   718  	// at least when they are long enough to cover scheduling jitter.
   719  	return d * 11 / 10
   720  }
   721  
   722  // nextTimeout returns the next timeout to try after an operation took the given
   723  // actual duration with a timeout shorter than that duration.
   724  func nextTimeout(actual time.Duration) (next time.Duration, ok bool) {
   725  	if actual >= maxDynamicTimeout {
   726  		return maxDynamicTimeout, false
   727  	}
   728  	// Since the previous attempt took actual, we can't expect to beat that
   729  	// duration by any significant margin. Try the next attempt with an arbitrary
   730  	// factor above that, so that our growth curve is at least exponential.
   731  	next = actual * 5 / 4
   732  	return min(next, maxDynamicTimeout), true
   733  }
   734  
   735  // There is a very similar copy of this in os/timeout_test.go.
   736  func TestReadTimeoutFluctuation(t *testing.T) {
   737  	ln := newLocalListener(t, "tcp")
   738  	defer ln.Close()
   739  
   740  	c, err := Dial(ln.Addr().Network(), ln.Addr().String())
   741  	if err != nil {
   742  		t.Fatal(err)
   743  	}
   744  	defer c.Close()
   745  
   746  	d := minDynamicTimeout
   747  	b := make([]byte, 256)
   748  	for {
   749  		t.Logf("SetReadDeadline(+%v)", d)
   750  		t0 := time.Now()
   751  		deadline := t0.Add(d)
   752  		if err = c.SetReadDeadline(deadline); err != nil {
   753  			t.Fatalf("SetReadDeadline(%v): %v", deadline, err)
   754  		}
   755  		var n int
   756  		n, err = c.Read(b)
   757  		t1 := time.Now()
   758  
   759  		if n != 0 || err == nil || !err.(Error).Timeout() {
   760  			t.Errorf("Read did not return (0, timeout): (%d, %v)", n, err)
   761  		}
   762  		if perr := parseReadError(err); perr != nil {
   763  			t.Error(perr)
   764  		}
   765  		if !isDeadlineExceeded(err) {
   766  			t.Errorf("Read error is not DeadlineExceeded: %v", err)
   767  		}
   768  
   769  		actual := t1.Sub(t0)
   770  		if t1.Before(deadline) {
   771  			t.Errorf("Read took %s; expected at least %s", actual, d)
   772  		}
   773  		if t.Failed() {
   774  			return
   775  		}
   776  		if want := timeoutUpperBound(d); actual > want {
   777  			next, ok := nextTimeout(actual)
   778  			if !ok {
   779  				t.Fatalf("Read took %s; expected at most %v", actual, want)
   780  			}
   781  			// Maybe this machine is too slow to reliably schedule goroutines within
   782  			// the requested duration. Increase the timeout and try again.
   783  			t.Logf("Read took %s (expected %s); trying with longer timeout", actual, d)
   784  			d = next
   785  			continue
   786  		}
   787  
   788  		break
   789  	}
   790  }
   791  
   792  // There is a very similar copy of this in os/timeout_test.go.
   793  func TestReadFromTimeoutFluctuation(t *testing.T) {
   794  	c1 := newLocalPacketListener(t, "udp")
   795  	defer c1.Close()
   796  
   797  	c2, err := Dial(c1.LocalAddr().Network(), c1.LocalAddr().String())
   798  	if err != nil {
   799  		t.Fatal(err)
   800  	}
   801  	defer c2.Close()
   802  
   803  	d := minDynamicTimeout
   804  	b := make([]byte, 256)
   805  	for {
   806  		t.Logf("SetReadDeadline(+%v)", d)
   807  		t0 := time.Now()
   808  		deadline := t0.Add(d)
   809  		if err = c2.SetReadDeadline(deadline); err != nil {
   810  			t.Fatalf("SetReadDeadline(%v): %v", deadline, err)
   811  		}
   812  		var n int
   813  		n, _, err = c2.(PacketConn).ReadFrom(b)
   814  		t1 := time.Now()
   815  
   816  		if n != 0 || err == nil || !err.(Error).Timeout() {
   817  			t.Errorf("ReadFrom did not return (0, timeout): (%d, %v)", n, err)
   818  		}
   819  		if perr := parseReadError(err); perr != nil {
   820  			t.Error(perr)
   821  		}
   822  		if !isDeadlineExceeded(err) {
   823  			t.Errorf("ReadFrom error is not DeadlineExceeded: %v", err)
   824  		}
   825  
   826  		actual := t1.Sub(t0)
   827  		if t1.Before(deadline) {
   828  			t.Errorf("ReadFrom took %s; expected at least %s", actual, d)
   829  		}
   830  		if t.Failed() {
   831  			return
   832  		}
   833  		if want := timeoutUpperBound(d); actual > want {
   834  			next, ok := nextTimeout(actual)
   835  			if !ok {
   836  				t.Fatalf("ReadFrom took %s; expected at most %s", actual, want)
   837  			}
   838  			// Maybe this machine is too slow to reliably schedule goroutines within
   839  			// the requested duration. Increase the timeout and try again.
   840  			t.Logf("ReadFrom took %s (expected %s); trying with longer timeout", actual, d)
   841  			d = next
   842  			continue
   843  		}
   844  
   845  		break
   846  	}
   847  }
   848  
   849  func TestWriteTimeoutFluctuation(t *testing.T) {
   850  	switch runtime.GOOS {
   851  	case "plan9":
   852  		t.Skipf("not supported on %s", runtime.GOOS)
   853  	}
   854  
   855  	ln := newLocalListener(t, "tcp")
   856  	defer ln.Close()
   857  
   858  	c, err := Dial(ln.Addr().Network(), ln.Addr().String())
   859  	if err != nil {
   860  		t.Fatal(err)
   861  	}
   862  	defer c.Close()
   863  
   864  	d := minDynamicTimeout
   865  	for {
   866  		t.Logf("SetWriteDeadline(+%v)", d)
   867  		t0 := time.Now()
   868  		deadline := t0.Add(d)
   869  		if err := c.SetWriteDeadline(deadline); err != nil {
   870  			t.Fatalf("SetWriteDeadline(%v): %v", deadline, err)
   871  		}
   872  		var n int64
   873  		var err error
   874  		for {
   875  			var dn int
   876  			dn, err = c.Write([]byte("TIMEOUT TRANSMITTER"))
   877  			n += int64(dn)
   878  			if err != nil {
   879  				break
   880  			}
   881  		}
   882  		t1 := time.Now()
   883  		// Inv: err != nil
   884  		if !err.(Error).Timeout() {
   885  			t.Fatalf("Write did not return (any, timeout): (%d, %v)", n, err)
   886  		}
   887  		if perr := parseWriteError(err); perr != nil {
   888  			t.Error(perr)
   889  		}
   890  		if !isDeadlineExceeded(err) {
   891  			t.Errorf("Write error is not DeadlineExceeded: %v", err)
   892  		}
   893  
   894  		actual := t1.Sub(t0)
   895  		if t1.Before(deadline) {
   896  			t.Errorf("Write took %s; expected at least %s", actual, d)
   897  		}
   898  		if t.Failed() {
   899  			return
   900  		}
   901  		if want := timeoutUpperBound(d); actual > want {
   902  			if n > 0 {
   903  				// SetWriteDeadline specifies a time “after which I/O operations fail
   904  				// instead of blocking”. However, the kernel's send buffer is not yet
   905  				// full, we may be able to write some arbitrary (but finite) number of
   906  				// bytes to it without blocking.
   907  				t.Logf("Wrote %d bytes into send buffer; retrying until buffer is full", n)
   908  				if d <= maxDynamicTimeout/2 {
   909  					// We don't know how long the actual write loop would have taken if
   910  					// the buffer were full, so just guess and double the duration so that
   911  					// the next attempt can make twice as much progress toward filling it.
   912  					d *= 2
   913  				}
   914  			} else if next, ok := nextTimeout(actual); !ok {
   915  				t.Fatalf("Write took %s; expected at most %s", actual, want)
   916  			} else {
   917  				// Maybe this machine is too slow to reliably schedule goroutines within
   918  				// the requested duration. Increase the timeout and try again.
   919  				t.Logf("Write took %s (expected %s); trying with longer timeout", actual, d)
   920  				d = next
   921  			}
   922  			continue
   923  		}
   924  
   925  		break
   926  	}
   927  }
   928  
   929  // There is a very similar copy of this in os/timeout_test.go.
   930  func TestVariousDeadlines(t *testing.T) {
   931  	t.Parallel()
   932  	testVariousDeadlines(t)
   933  }
   934  
   935  // There is a very similar copy of this in os/timeout_test.go.
   936  func TestVariousDeadlines1Proc(t *testing.T) {
   937  	// Cannot use t.Parallel - modifies global GOMAXPROCS.
   938  	if testing.Short() {
   939  		t.Skip("skipping in short mode")
   940  	}
   941  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
   942  	testVariousDeadlines(t)
   943  }
   944  
   945  // There is a very similar copy of this in os/timeout_test.go.
   946  func TestVariousDeadlines4Proc(t *testing.T) {
   947  	// Cannot use t.Parallel - modifies global GOMAXPROCS.
   948  	if testing.Short() {
   949  		t.Skip("skipping in short mode")
   950  	}
   951  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(4))
   952  	testVariousDeadlines(t)
   953  }
   954  
   955  func testVariousDeadlines(t *testing.T) {
   956  	handler := func(ls *localServer, ln Listener) {
   957  		for {
   958  			c, err := ln.Accept()
   959  			if err != nil {
   960  				break
   961  			}
   962  			c.Read(make([]byte, 1)) // wait for client to close connection
   963  			c.Close()
   964  		}
   965  	}
   966  	ls := newLocalServer(t, "tcp")
   967  	defer ls.teardown()
   968  	if err := ls.buildup(handler); err != nil {
   969  		t.Fatal(err)
   970  	}
   971  
   972  	for _, timeout := range []time.Duration{
   973  		1 * time.Nanosecond,
   974  		2 * time.Nanosecond,
   975  		5 * time.Nanosecond,
   976  		50 * time.Nanosecond,
   977  		100 * time.Nanosecond,
   978  		200 * time.Nanosecond,
   979  		500 * time.Nanosecond,
   980  		750 * time.Nanosecond,
   981  		1 * time.Microsecond,
   982  		5 * time.Microsecond,
   983  		25 * time.Microsecond,
   984  		250 * time.Microsecond,
   985  		500 * time.Microsecond,
   986  		1 * time.Millisecond,
   987  		5 * time.Millisecond,
   988  		100 * time.Millisecond,
   989  		250 * time.Millisecond,
   990  		500 * time.Millisecond,
   991  		1 * time.Second,
   992  	} {
   993  		numRuns := 3
   994  		if testing.Short() {
   995  			numRuns = 1
   996  			if timeout > 500*time.Microsecond {
   997  				continue
   998  			}
   999  		}
  1000  		for run := 0; run < numRuns; run++ {
  1001  			name := fmt.Sprintf("%v %d/%d", timeout, run, numRuns)
  1002  			t.Log(name)
  1003  
  1004  			c, err := Dial(ls.Listener.Addr().Network(), ls.Listener.Addr().String())
  1005  			if err != nil {
  1006  				t.Fatal(err)
  1007  			}
  1008  
  1009  			t0 := time.Now()
  1010  			if err := c.SetDeadline(t0.Add(timeout)); err != nil {
  1011  				t.Error(err)
  1012  			}
  1013  			n, err := io.Copy(io.Discard, c)
  1014  			dt := time.Since(t0)
  1015  			c.Close()
  1016  
  1017  			if nerr, ok := err.(Error); ok && nerr.Timeout() {
  1018  				t.Logf("%v: good timeout after %v; %d bytes", name, dt, n)
  1019  			} else {
  1020  				t.Fatalf("%v: Copy = %d, %v; want timeout", name, n, err)
  1021  			}
  1022  		}
  1023  	}
  1024  }
  1025  
  1026  // TestReadWriteProlongedTimeout tests concurrent deadline
  1027  // modification. Known to cause data races in the past.
  1028  func TestReadWriteProlongedTimeout(t *testing.T) {
  1029  	t.Parallel()
  1030  
  1031  	switch runtime.GOOS {
  1032  	case "plan9":
  1033  		t.Skipf("not supported on %s", runtime.GOOS)
  1034  	}
  1035  
  1036  	handler := func(ls *localServer, ln Listener) {
  1037  		c, err := ln.Accept()
  1038  		if err != nil {
  1039  			t.Error(err)
  1040  			return
  1041  		}
  1042  		defer c.Close()
  1043  
  1044  		var wg sync.WaitGroup
  1045  		wg.Add(2)
  1046  		go func() {
  1047  			defer wg.Done()
  1048  			var b [1]byte
  1049  			for {
  1050  				if err := c.SetReadDeadline(time.Now().Add(time.Hour)); err != nil {
  1051  					if perr := parseCommonError(err); perr != nil {
  1052  						t.Error(perr)
  1053  					}
  1054  					t.Error(err)
  1055  					return
  1056  				}
  1057  				if _, err := c.Read(b[:]); err != nil {
  1058  					if perr := parseReadError(err); perr != nil {
  1059  						t.Error(perr)
  1060  					}
  1061  					return
  1062  				}
  1063  			}
  1064  		}()
  1065  		go func() {
  1066  			defer wg.Done()
  1067  			var b [1]byte
  1068  			for {
  1069  				if err := c.SetWriteDeadline(time.Now().Add(time.Hour)); err != nil {
  1070  					if perr := parseCommonError(err); perr != nil {
  1071  						t.Error(perr)
  1072  					}
  1073  					t.Error(err)
  1074  					return
  1075  				}
  1076  				if _, err := c.Write(b[:]); err != nil {
  1077  					if perr := parseWriteError(err); perr != nil {
  1078  						t.Error(perr)
  1079  					}
  1080  					return
  1081  				}
  1082  			}
  1083  		}()
  1084  		wg.Wait()
  1085  	}
  1086  	ls := newLocalServer(t, "tcp")
  1087  	defer ls.teardown()
  1088  	if err := ls.buildup(handler); err != nil {
  1089  		t.Fatal(err)
  1090  	}
  1091  
  1092  	c, err := Dial(ls.Listener.Addr().Network(), ls.Listener.Addr().String())
  1093  	if err != nil {
  1094  		t.Fatal(err)
  1095  	}
  1096  	defer c.Close()
  1097  
  1098  	var b [1]byte
  1099  	for i := 0; i < 1000; i++ {
  1100  		c.Write(b[:])
  1101  		c.Read(b[:])
  1102  	}
  1103  }
  1104  
  1105  // There is a very similar copy of this in os/timeout_test.go.
  1106  func TestReadWriteDeadlineRace(t *testing.T) {
  1107  	t.Parallel()
  1108  
  1109  	N := 1000
  1110  	if testing.Short() {
  1111  		N = 50
  1112  	}
  1113  
  1114  	ln := newLocalListener(t, "tcp")
  1115  	defer ln.Close()
  1116  
  1117  	c, err := Dial(ln.Addr().Network(), ln.Addr().String())
  1118  	if err != nil {
  1119  		t.Fatal(err)
  1120  	}
  1121  	defer c.Close()
  1122  
  1123  	var wg sync.WaitGroup
  1124  	wg.Add(3)
  1125  	go func() {
  1126  		defer wg.Done()
  1127  		tic := time.NewTicker(2 * time.Microsecond)
  1128  		defer tic.Stop()
  1129  		for i := 0; i < N; i++ {
  1130  			if err := c.SetReadDeadline(time.Now().Add(2 * time.Microsecond)); err != nil {
  1131  				if perr := parseCommonError(err); perr != nil {
  1132  					t.Error(perr)
  1133  				}
  1134  				break
  1135  			}
  1136  			if err := c.SetWriteDeadline(time.Now().Add(2 * time.Microsecond)); err != nil {
  1137  				if perr := parseCommonError(err); perr != nil {
  1138  					t.Error(perr)
  1139  				}
  1140  				break
  1141  			}
  1142  			<-tic.C
  1143  		}
  1144  	}()
  1145  	go func() {
  1146  		defer wg.Done()
  1147  		var b [1]byte
  1148  		for i := 0; i < N; i++ {
  1149  			c.Read(b[:]) // ignore possible timeout errors
  1150  		}
  1151  	}()
  1152  	go func() {
  1153  		defer wg.Done()
  1154  		var b [1]byte
  1155  		for i := 0; i < N; i++ {
  1156  			c.Write(b[:]) // ignore possible timeout errors
  1157  		}
  1158  	}()
  1159  	wg.Wait() // wait for tester goroutine to stop
  1160  }
  1161  
  1162  // Issue 35367.
  1163  func TestConcurrentSetDeadline(t *testing.T) {
  1164  	ln := newLocalListener(t, "tcp")
  1165  	defer ln.Close()
  1166  
  1167  	const goroutines = 8
  1168  	const conns = 10
  1169  	const tries = 100
  1170  
  1171  	var c [conns]Conn
  1172  	for i := 0; i < conns; i++ {
  1173  		var err error
  1174  		c[i], err = Dial(ln.Addr().Network(), ln.Addr().String())
  1175  		if err != nil {
  1176  			t.Fatal(err)
  1177  		}
  1178  		defer c[i].Close()
  1179  	}
  1180  
  1181  	var wg sync.WaitGroup
  1182  	wg.Add(goroutines)
  1183  	now := time.Now()
  1184  	for i := 0; i < goroutines; i++ {
  1185  		go func(i int) {
  1186  			defer wg.Done()
  1187  			// Make the deadlines steadily earlier,
  1188  			// to trigger runtime adjusttimers calls.
  1189  			for j := tries; j > 0; j-- {
  1190  				for k := 0; k < conns; k++ {
  1191  					c[k].SetReadDeadline(now.Add(2*time.Hour + time.Duration(i*j*k)*time.Second))
  1192  					c[k].SetWriteDeadline(now.Add(1*time.Hour + time.Duration(i*j*k)*time.Second))
  1193  				}
  1194  			}
  1195  		}(i)
  1196  	}
  1197  	wg.Wait()
  1198  }
  1199  
  1200  // isDeadlineExceeded reports whether err is or wraps os.ErrDeadlineExceeded.
  1201  // We also check that the error implements net.Error, and that the
  1202  // Timeout method returns true.
  1203  func isDeadlineExceeded(err error) bool {
  1204  	nerr, ok := err.(Error)
  1205  	if !ok {
  1206  		return false
  1207  	}
  1208  	if !nerr.Timeout() {
  1209  		return false
  1210  	}
  1211  	if !errors.Is(err, os.ErrDeadlineExceeded) {
  1212  		return false
  1213  	}
  1214  	return true
  1215  }
  1216  

View as plain text