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.

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.

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

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

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.