net/http: investigate Transport's use of cached connections upon resume from sleep

[bradfitz]

When the http.Transport has cached persistent connections to a server and the machine is suspended (e.g. laptop lid closing, serverless environments), the monotonic clock might not advance but the wall clock will.

This is a tracking bug to verify how Transport behaves in such cases.

It would be bad if during the machine's time asleep we got a TCP packet to close a connection but we never saw it (due to being asleep), and then upon resume we try to re-use that dead TCP connection, get a write error, and then are unable to retry for whatever reason (non-idempotent or non-replayable request).

Before using a connection we should look at the current wall time and compare it to the wall time of when it was last idle. We might already be doing that (by accident?) but we might also be accidentally using monotonic time, in which case we wouldn't notice the missing chunks of time.

Investigate.

/cc @jadekler

[ianlancetaylor]

See also #24595.

[chris-vest]

@bradfitz Any idea if this is being worked on / investigated?

[odeke-em]

@chris-vest thanks for the ping! Brad is currently very busy and he is also currently on leave but I am going to start looking at this issue next week and hopefully have something for Go1.14.

[odeke-em]

When the http.Transport has cached persistent connections to a server and the machine is suspended (e.g. laptop lid closing, serverless environments), the monotonic clock might not advance but the wall clock will.

I think perhaps one of these might be reversed? After a SIGCONT is sent, the monotonic clock usually accumulates more nanoseconds than the wall clock -- I might be mistaken though.

It would be bad if during the machine's time asleep we got a TCP packet to close a connection but we never saw it (due to being asleep), and then upon resume we try to re-use that dead TCP connection, get a write error, and then are unable to retry for whatever reason (non-idempotent or non-replayable request).

So firstly pconn.idleTimer can't figure out how to reaps stale requests that have when it is frozen in time/stopped, so we should also examine a way of checking for stale reaps.

When we go to sleep, there are 2 main cases or (3 sub-cases):

Scenario	State on revival after close connection packet	Reaction to missed close connection packet	Advisory
reused connection: CloseIdleTimeout>0	pconn.t.CloseIdleTimeout + pconn.idleAt <= time.Now()	For idempotent requests we'll retry with a new connection	For brevity, even check if pconn.t.CloseIdleTimeout + pconn.idleAt <= time.Now() and immediately close this connection
reused connection: CloseIdleTimeout==0	pconn.idleAt < time.Now() so cannot tell whether we actually missed the packet or if we slept for long	The current scenario where we'll just check if the request is idempotent and retry it if possible	Nothing to change
fresh connection	Cannot tell how long we've been alive	We paranoidly just fail on the if !pc.isReused() check and return connection reset by peer as reported in the precursory bug code here	Add perhaps a field pconn.createTime or reuse pconn.idleTime to capture when it was created. Might require perhaps exposing an internal runtime time API that'll compare monotonic vs wall clock to capture the scenario being reported here

I spent quite sometime digging through the standard library as well as the google-cloud-go work and basically these scenarios can be reproduced just by simulating how to stop processes by sending SIGTSTP and then reviving them with SIGCONT after a period, showing that reused connections that receive ECONNRESET will spawn a new persistentConn and after the server has suddenly closed the TCP connection, the persistentConn finally responds with read tcp [::1]:59102->[::1]:59098: read: connection reset by peer for example in this repro

https://github.com/odeke-em/bugs/tree/master/golang/29308

Way forward

Perhaps a //golinkname mono time.mono link and then some mechanisms for detecting drift e.g.
in this patch meant to handle the case of clock drifts/frozen time:

diff --git a/src/net/http/transport.go b/src/net/http/transport.go
index 26f642aa7a..138df57765 100644
--- a/src/net/http/transport.go
+++ b/src/net/http/transport.go
@@ -29,6 +29,7 @@ import (
 	"sync"
 	"sync/atomic"
 	"time"
+	_ "unsafe"
 
 	"golang.org/x/net/http/httpguts"
 	"golang.org/x/net/http/httpproxy"
@@ -603,7 +604,10 @@ func (pc *persistConn) shouldRetryRequest(req *Request, err error) bool {
 		// creating new connections and retrying if the server
 		// is just hanging up on us because it doesn't like
 		// our request (as opposed to sending an error).
-		return false
+
+		// As per golang.org/issue/29380, let's only return true if time
+		// drifted.
+		return pc.timeDrifted()
 	}
 	if _, ok := err.(nothingWrittenError); ok {
 		// We never wrote anything, so it's safe to retry, if there's no body or we
@@ -628,6 +632,44 @@ func (pc *persistConn) shouldRetryRequest(req *Request, err error) bool {
 	return false // conservatively
 }
 
+// timeDrifted returns true if we can detect that our wall and monotonicNstonic clocks
+// have drifted apart. There are 2 scenarios in which we'll return true:
+//  1. If pconn.t.IdleConnTimeout is non-zero and
+//      pconn.idleAt+pconn.t.IdleConnTimeout  are before time.Now()
+//  2. If the monotonicNstonic clock difference and the wall clock time differences
+//      exceed a heuristic percentage.
+func (pc *persistConn) timeDrifted() bool {
+	pc.mu.Lock()
+	idleAt := pc.idleAt
+	var idleConnTimeout time.Duration
+	if pc.t != nil {
+		idleConnTimeout = pc.t.IdleConnTimeout
+	}
+	pc.mu.Unlock()
+
+	if idleAt.IsZero() {
+		// We need to have a non-zero idleAt in order
+		// to try to guess if we've drifted.
+		return false
+	}
+
+	now := time.Now()
+
+	if idleConnTimeout > 0 {
+		// Since we had a Transport.CloseConnTimeout, if we were put in limbo
+		// and our idle conn cleanup route didn't fire, manually check here.
+		return now.After(idleAt.Add(idleConnTimeout))
+	}
+
+	diffWallNanos := float64(now.UnixNano()-idleAt.UnixNano()) / 1e9
+	diffmonotonicNsNanos := float64(monotonicNs(now)-monotonicNs(idleAt)) / 1e9
+	driftPercentage := 100 * float64(diffmonotonicNsNanos-diffWallNanos)
+
+	// As a heuristic, if the monotonicNstonic nanoseconds and the walltime nanoseconds
+	// have drifted by say over 10%, then report this as a drifted time.
+	return driftPercentage >= 10
+}
+
 // ErrSkipAltProtocol is a sentinel error value defined by Transport.RegisterProtocol.
 var ErrSkipAltProtocol = errors.New("net/http: skip alternate protocol")
 
@@ -878,6 +920,9 @@ func (t *Transport) tryPutIdleConn(pconn *persistConn) error {
 	return nil
 }
 
+//go:linkname monotonicNs time.mono
+func monotonicNs(t time.Time) int64
+
 // getIdleConnCh returns a channel to receive and return idle
 // persistent connection for the given connectMethod.
 // It may return nil, if persistent connections are not being used.
@@ -1429,6 +1474,10 @@ func (t *Transport) dialConn(ctx context.Context, cm connectMethod) (*persistCon
 	pconn.br = bufio.NewReaderSize(pconn, t.readBufferSize())
 	pconn.bw = bufio.NewWriterSize(persistConnWriter{pconn}, t.writeBufferSize())
 
+	// Perhaps we are abusing idleAt but really we want to
+	// capture the time  that the connection was created.
+	pconn.idleAt = time.Now()
+
 	go pconn.readLoop()
 	go pconn.writeLoop()
 	return pconn, nil
diff --git a/src/time/time.go b/src/time/time.go
index c8116a74f4..06da8009f3 100644
--- a/src/time/time.go
+++ b/src/time/time.go
@@ -1091,6 +1091,10 @@ func daysIn(m Month, year int) int {
 	return int(daysBefore[m] - daysBefore[m-1])
 }
 
+func mono(t Time) int64 {
+	return t.ext
+}
+
 // Provided by package runtime.
 func now() (sec int64, nsec int32, mono int64)

Results

Before patch

server: 2019/06/21 19:12:54 Listening at "[::]:49373"
client: 2019/06/21 19:12:55 URL: http://[::]:49373/hello
server: 2019/06/21 19:12:55 Request from: [::1]:49376

client: 2019/06/21 19:12:55 Blob: Server responding ASAP
client: 2019/06/21 19:12:55 Pausing for 1.5s

client: 2019/06/21 19:12:57 URL: http://[::]:49373/hello
server: 2019/06/21 19:12:57 Request from: [::1]:49376

server: 2019/06/21 19:12:57 Now going to lag for 3s
server: 2019/06/21 19:12:57 Pausing for 2s before reviving client with pid: 21447
server: 2019/06/21 19:13:27 Request from: [::1]:49377

server: 2019/06/21 19:13:27 Now going to lag for 3s
client: 2019/06/21 19:13:33 Failed to make request("http://[::]:49373/hello"): Get http://[::]:49373/hello: read tcp [::1]:49377->[::1]:49373: read: connection reset by peer

After proposed patch

server: 2019/06/21 19:11:00 Listening at "[::]:49346"
client: 2019/06/21 19:11:01 URL: http://[::]:49346/hello
server: 2019/06/21 19:11:01 Request from: [::1]:49349

client: 2019/06/21 19:11:01 Blob: Server responding ASAP
client: 2019/06/21 19:11:01 Pausing for 1.5s

client: 2019/06/21 19:11:02 URL: http://[::]:49346/hello
server: 2019/06/21 19:11:02 Request from: [::1]:49349

server: 2019/06/21 19:11:02 Now going to lag for 3s
server: 2019/06/21 19:11:02 Pausing for 2s before reviving client with pid: 21387
server: 2019/06/21 19:11:32 Request from: [::1]:49360

server: 2019/06/21 19:11:32 Now going to lag for 3s
server: 2019/06/21 19:11:39 Request from: [::1]:49362

Please let me know what y'all think.

[gopherbot]

Change https://golang.org/cl/183557 mentions this issue: net/http: detect and make persistConn handle time drifts

[odeke-em]

One other thing I discovered today while thinking out loud about this issue is that perhaps the runtime on getting a SIGCONT can refetch the current time and go update all the previous timers that may have drifted. This might even be the simpler and more correct solution instead of the addition to get time.mono.