use contexts correctly when tracking request body size and start time

lfsapi/client.go

@@ -114,19 +114,18 @@ func (c *Client) extraHeaders(u *url.URL) map[string][]string {
 }
 
 func (c *Client) doWithRedirects(cli *http.Client, req *http.Request, via []*http.Request) (*http.Response, error) {
-	c.traceRequest(req)
-	if err := c.prepareRequestBody(req); err != nil {
+	tracedReq, err := c.traceRequest(req)
+	if err != nil {
 		return nil, err
 	}
 
-	start := time.Now()
+	req = annotateReqStart(req)
 	res, err := cli.Do(req)
 	if err != nil {
 		return res, err
 	}
 
-	c.traceResponse(res)
-	c.startResponseStats(res, start)
+	c.traceResponse(tracedReq, res)
 
 	if res.StatusCode != 307 {
 		return res, err

lfsapi/stats.go

@@ -48,19 +48,6 @@ func (c *Client) LogRequest(r *http.Request, reqKey string) *http.Request {
 // DEPRECATED: Use LogRequest() instead.
 func (c *Client) LogResponse(key string, res *http.Response) {}
 
-func (c *Client) startResponseStats(res *http.Response, start time.Time) {
-	if v := res.Request.Context().Value(transferKey); v != nil {
-		t := v.(httpTransfer)
-		t.Start = start
-		t.RequestBodySize = res.Request.ContentLength
-	}
-}
-
-func (c *Client) finishResponseStats(res *http.Response, bodySize int64) {
-	c.httpLogger.Log(res.Request, "finish",
-		fmt.Sprintf("status=%d reqbody=%d resbody=%d ", res.StatusCode, 0, bodySize))
-}
-
 func newSyncLogger(w io.WriteCloser) *syncLogger {
 	ch := make(chan string, 100)
 	wg := &sync.WaitGroup{}
@@ -94,11 +81,11 @@ func (l *syncLogger) Log(req *http.Request, event, extra string) {
 
 	t := v.(httpTransfer)
 	l.wg.Add(1)
-	l.ch <- fmt.Sprintf("key=%s event=%s url=%s reqbody=%d %ssince=%d\n",
+	l.ch <- fmt.Sprintf("key=%s event=%s url=%s method=%s %ssince=%d\n",
 		t.Key,
 		event,
 		t.URL,
-		t.RequestBodySize,
+		req.Method,
 		extra,
 		time.Since(t.Start).Nanoseconds(),
 	)

lfsapi/verbose.go

@@ -3,46 +3,47 @@ package lfsapi
 import (
 	"bufio"
 	"bytes"
+	"context"
 	"fmt"
 	"io"
 	"net/http"
 	"net/http/httputil"
 	"strings"
+	"time"
 
 	"github.com/rubyist/tracerx"
 )
 
-func (c *Client) traceRequest(req *http.Request) {
+func (c *Client) traceRequest(req *http.Request) (*tracedRequest, error) {
 	tracerx.Printf("HTTP: %s", traceReq(req))
 
-	if !c.Verbose {
-		return
+	if c.Verbose {
+		if dump, err := httputil.DumpRequest(req, false); err == nil {
+			c.traceHTTPDump(">", dump)
+		}
 	}
 
-	if dump, err := httputil.DumpRequest(req, false); err == nil {
-		c.traceHTTPDump(">", dump)
-	}
-}
-
-func (c *Client) prepareRequestBody(req *http.Request) error {
 	body, ok := req.Body.(ReadSeekCloser)
 	if body != nil && !ok {
-		return fmt.Errorf("Request body must implement io.ReadCloser and io.Seeker. Got: %T", body)
+		return nil, fmt.Errorf("Request body must implement io.ReadCloser and io.Seeker. Got: %T", body)
 	}
 
 	if body != nil && ok {
 		body.Seek(0, io.SeekStart)
-		req.Body = &tracedRequest{
+		tr := &tracedRequest{
 			verbose:        c.Verbose && isTraceableContent(req.Header),
 			verboseOut:     c.VerboseOut,
 			ReadSeekCloser: body,
 		}
+		req.Body = tr
+		return tr, nil
 	}
 
-	return nil
+	return nil, nil
 }
 
 type tracedRequest struct {
+	BodySize   int64
 	verbose    bool
 	verboseOut io.Writer
 	ReadSeekCloser
@@ -50,10 +51,16 @@ type tracedRequest struct {
 
 func (r *tracedRequest) Read(b []byte) (int, error) {
 	n, err := tracedRead(r.ReadSeekCloser, b, r.verboseOut, false, r.verbose)
+	r.BodySize += int64(n)
 	return n, err
 }
 
-func (c *Client) traceResponse(res *http.Response) {
+func (c *Client) traceResponse(tracedReq *tracedRequest, res *http.Response) {
+	if tracedReq != nil {
+		c.httpLogger.Log(res.Request, "request",
+			fmt.Sprintf("body=%d ", tracedReq.BodySize))
+	}
+
 	if res == nil {
 		return
 	}
@@ -62,7 +69,7 @@ func (c *Client) traceResponse(res *http.Response) {
 
 	verboseBody := isTraceableContent(res.Header)
 	res.Body = &tracedResponse{
-		client:     c,
+		httpLogger: c.httpLogger,
 		response:   res,
 		gitTrace:   verboseBody,
 		verbose:    verboseBody && c.Verbose,
@@ -85,8 +92,8 @@ func (c *Client) traceResponse(res *http.Response) {
 }
 
 type tracedResponse struct {
-	Count      int
-	client     *Client
+	BodySize   int64
+	httpLogger *syncLogger
 	response   *http.Response
 	verbose    bool
 	gitTrace   bool
@@ -96,10 +103,11 @@ type tracedResponse struct {
 
 func (r *tracedResponse) Read(b []byte) (int, error) {
 	n, err := tracedRead(r.ReadCloser, b, r.verboseOut, r.gitTrace, r.verbose)
-	r.Count += n
+	r.BodySize += int64(n)
 
 	if err == io.EOF {
-		r.client.finishResponseStats(r.response, int64(r.Count))
+		r.httpLogger.Log(r.response.Request, "response",
+			fmt.Sprintf("status=%d body=%d ", r.response.StatusCode, r.BodySize))
 	}
 	return n, err
 }
@@ -150,3 +158,15 @@ func isTraceableContent(h http.Header) bool {
 func traceReq(req *http.Request) string {
 	return fmt.Sprintf("%s %s", req.Method, strings.SplitN(req.URL.String(), "?", 2)[0])
 }
+
+func annotateReqStart(r *http.Request) *http.Request {
+	ctx := r.Context()
+	v := ctx.Value(transferKey)
+	if v == nil {
+		return r
+	}
+
+	t := v.(httpTransfer)
+	t.Start = time.Now()
+	return r.WithContext(context.WithValue(ctx, transferKey, t))
+}