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

View as plain text