net/http/httptrace: attaching a ClientTrace twice to the same context causes stack overflow

[mightyguava]

What version of Go are you using (go version)?

$ go version
go version go1.12.5 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What did you do?

package main

import (
	"log"
	"net/http"
	"net/http/httptrace"
)

func main() {
	tracer := &httptrace.ClientTrace{
		ConnectStart: func(network, addr string) {
			log.Println("traced")
		},
	}
	req, err := http.NewRequest("GET", "http://localhost:9999/hello", nil)
	if err != nil {
		log.Printf("error creating request %v", err)
	}

	// Adding the same trace twice causes a stack overflow.
	req = req.WithContext(httptrace.WithClientTrace(req.Context(), tracer))
	req = req.WithContext(httptrace.WithClientTrace(req.Context(), tracer))

	client := &http.Client{}
	res, err := client.Do(req)
	if err != nil {
		log.Printf("request error: %v", err)
	}
	if res != nil && res.Body != nil {
		res.Body.Close()
	}
}

What did you expect to see?

"traced" gets printed twice, and then a request error because nothing is listening on localhost:9999.

What did you see instead?

The stack overflows.

What I'm doing is silly, but it happened in production for a service due to a lot of indirection on retries and attempting to use a single tracer object for all traces.

The bug seems to be here

go/src/net/http/httptrace/trace.go

Lines 202 to 204 in b412fde

	newFunc := reflect.MakeFunc(hookType, func(args []reflect.Value) []reflect.Value {
	tfCopy.Call(args)
	return of.Call(args)

Since *t and *old are the same, the of.Call() ends up calling itself.

[mightyguava]

I'm surprised looking at the code that httptrace.WithClientTrace() mutates the passed in ClientTrace. I guess this means that this object is meant to be created per-request and not be reused. There's nothing in the documentation to indicate that though.

[bcmills]

CC @bradfitz, but note that he's unavailable for a while.

Note that the same failure mode can occur with any number of intervening traces, so it's not just a matter of checking whether t and old are the same underlying object.

[tomocy]

I don't know why yet, but the error does not come to happen if the copy of of is used to call for itself.

tfCopy := reflect.ValueOf(tf.Interface())
ofCopy := reflect.ValueOf(of.Interface())

// We need to call both tf and of in some order.
newFunc := reflect.MakeFunc(hookType, func(args []reflect.Value) []reflect.Value {
	tfCopy.Call(args)
	return ofCopy.Call(args)
})

The output is still strange but like the below.

2019/07/09 04:27:36 traced
2019/07/09 04:27:36 traced
2019/07/09 04:27:36 traced
2019/07/09 04:27:36 traced
2019/07/09 04:27:36 request error: Get http://localhost:9999/hello: dial tcp [::1]:9999: connect: connection refused

[gopherbot]

Change https://golang.org/cl/186217 mentions this issue: net/http/httptrace: create internal copy of httptrace.ClientTrace in httptrace.WithClientTrace

[gmichelo]

I proposed a solution. Please, review it if possible: https://go-review.googlesource.com/c/go/+/186217.

@tomocy, making also a copy of old hook function would solve the recursive cycle and then the stack overflow. But it won't fix the inconsistency of number of times a given hook function will be called.

Let's take a look at below test function.

func TestMultipleWithClientTrace(t *testing.T) {
	// Issue #32925
	var buf bytes.Buffer
	connectStart := func(b byte) func(network, addr string) {
		return func(network, addr string) {
			buf.WriteByte(b)
		}
	}

	ctx := context.Background()
	trace := &ClientTrace{
		ConnectStart: connectStart('N'),
	}
	// Adding the same trace multiple times. It should have a cumulative effect.
	ctx = WithClientTrace(ctx, trace)
	ctx = WithClientTrace(ctx, trace)
	ctx = WithClientTrace(ctx, trace)
	ctx = WithClientTrace(ctx, trace)
	lasttrace := ContextClientTrace(ctx)

	buf.Reset()
	lasttrace.ConnectStart("net", "addr")
	if got, want := buf.String(), "NNNN"; got != want {
		t.Errorf("got %q; want %q", got, want)
	}
}

If I register ClientTrace 4 times, I would expect that my hook function connectStart is called 4 times every time a connection is started. Instead, if you try it out with only the fix for stack overflow, you will see that function gets called more times than expected:

--- FAIL: TestMultipleWithClientTrace (0.00s)
    trace_test.go:37: got "NNNNNNNN"; want "NNNN"
FAIL
FAIL	net/http/httptrace	0.003s
FAIL

This is inconsistency is due to the fact that httptrace.WithClientTrace API stores the hook functions (new ones created through reflect.MakeFunc) into httptrace.ClientTrace input object. This leads to recursive nested function calls when that object is shared across multiple API calls.

The solution in this case is let httptrace.WithClientTrace have its own local copy of httptrace.ClientTrace and update it instead of object passed by user.