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

View as plain text