Source file src/net/timeout_test.go

Documentation: net

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

View as plain text