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

View as plain text