Add debug logging mode (B2_DEBUG=1)

Take the occasion to move Authorization into the RoundTripper.

Use build tags to only enable httptrace on Go 1.7.

b2.go

@@ -28,6 +28,12 @@
 //
 // Large files (b2_*_large_file, b2_*_part), b2_get_download_authorization,
 // b2_hide_file, b2_update_bucket.
+//
+// Debug mode
+//
+// If the B2_DEBUG environment variable is set to 1, all API calls will be
+// logged. On Go 1.7 and later, it will also log when new (non-reused)
+// connections are established.
 package b2
 
 import (
@@ -38,7 +44,9 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
+	"log"
 	"net/http"
+	"os"
 	"sync"
 )
 
@@ -94,6 +102,7 @@ func NewClient(accountID, applicationKey string, httpClient *http.Client) (*Clie
 		return nil, err
 	}
 	defer drainAndClose(res.Body)
+	debugf("login: %d", res.StatusCode)
 
 	if res.StatusCode != 200 {
 		b2Err := &Error{}
@@ -104,6 +113,7 @@ func NewClient(accountID, applicationKey string, httpClient *http.Client) (*Clie
 	}
 
 	c := &Client{hc: httpClient}
+	c.hc.Transport = &transport{t: c.hc.Transport, c: c}
 	if err := json.NewDecoder(res.Body).Decode(c); err != nil {
 		return nil, fmt.Errorf("failed to decode b2_authorize_account answer: %s", err)
 	}
@@ -120,28 +130,61 @@ func NewClient(accountID, applicationKey string, httpClient *http.Client) (*Clie
 	return c, nil
 }
 
-func (c *Client) doRequest(endpoint string, params map[string]interface{}) (*http.Response, error) {
-	body, err := json.Marshal(params)
-	if err != nil {
-		return nil, err
+// transport is a wrapper providing authentication, tracing and error handling.
+type transport struct {
+	t http.RoundTripper
+	c *Client
+}
+
+// requestExtFunc is implemented in the go1.7 file, to add httptrace
+var requestExtFunc func(*http.Request) *http.Request
+
+func (t *transport) RoundTrip(req *http.Request) (res *http.Response, err error) {
+	if req.Header.Get("Authorization") == "" {
+		req.Header.Set("Authorization", t.c.AuthorizationToken)
 	}
 
-	r, err := http.NewRequest("POST", c.ApiURL+apiPath+endpoint, bytes.NewBuffer(body))
-	if err != nil {
-		return nil, err
+	if requestExtFunc != nil {
+		req = requestExtFunc(req)
 	}
-	r.Header.Set("Authorization", c.AuthorizationToken)
 
-	res, err := c.hc.Do(r)
-	if err != nil {
-		return nil, err
+	if t.t == nil {
+		res, err = http.DefaultTransport.RoundTrip(req)
+	} else {
+		res, err = t.t.RoundTrip(req)
 	}
 
-	if res.StatusCode != 200 {
+	if err == nil && res.StatusCode != 200 {
 		return nil, parseB2Error(res)
 	}
 
-	return res, nil
+	return res, err
+}
+
+var debug = os.Getenv("B2_DEBUG") == "1"
+
+func debugf(format string, a ...interface{}) {
+	if debug {
+		log.Printf("[b2] "+format, a...)
+	}
+}
+
+func (c *Client) doRequest(endpoint string, params map[string]interface{}) (*http.Response, error) {
+	body, err := json.Marshal(params)
+	if err != nil {
+		return nil, err
+	}
+	// Reduce debug log noise
+	delete(params, "accountID")
+	delete(params, "bucketID")
+
+	res, err := c.hc.Post(c.ApiURL+apiPath+endpoint, "application/json", bytes.NewBuffer(body))
+	if err != nil {
+		debugf("%s (%v): %v", endpoint, params, err)
+	} else {
+		debugf("%s (%v)", endpoint, params)
+	}
+	return res, err
 }
 
 func parseB2Error(res *http.Response) error {

b2_go17.go

@@ -0,0 +1,21 @@
+// +build go1.7
+
+package b2
+
+import (
+	"net/http"
+	"net/http/httptrace"
+)
+
+func addTracing(req *http.Request) *http.Request {
+	trace := &httptrace.ClientTrace{
+		ConnectStart: func(network, addr string) {
+			debugf("new connection to %s (for %s)", addr, req.URL.Path)
+		},
+	}
+	return req.WithContext(httptrace.WithClientTrace(req.Context(), trace))
+}
+
+func init() {
+	requestExtFunc = addTracing
+}

download.go

@@ -14,20 +14,12 @@ import (
 // Note: the (*FileInfo).CustomMetadata values returned by this function are
 // all represented as strings, because they are delivered by HTTP headers.
 func (c *Client) DownloadFileByID(id string) (io.ReadCloser, *FileInfo, error) {
-	url := c.DownloadURL + apiPath + "b2_download_file_by_id?fileId=" + id
-	r, err := http.NewRequest("GET", url, nil)
+	res, err := c.hc.Get(c.DownloadURL + apiPath + "b2_download_file_by_id?fileId=" + id)
 	if err != nil {
+		debugf("download %s: %s", id, err)
 		return nil, nil, err
 	}
-	r.Header.Set("Authorization", c.AuthorizationToken)
-
-	res, err := c.hc.Do(r)
-	if err != nil {
-		return nil, nil, err
-	}
-	if res.StatusCode != 200 {
-		return nil, nil, parseB2Error(res)
-	}
+	debugf("download %s (%s)", id, res.Header.Get("X-Bz-Content-Sha1"))
 
 	fi, err := parseFileInfoHeaders(res.Header)
 	return res.Body, fi, err
@@ -39,20 +31,12 @@ func (c *Client) DownloadFileByID(id string) (io.ReadCloser, *FileInfo, error) {
 // Note: the (*FileInfo).CustomMetadata values returned by this function are
 // all represented as strings, because they are delivered by HTTP headers.
 func (c *Client) DownloadFileByName(bucket, file string) (io.ReadCloser, *FileInfo, error) {
-	url := c.DownloadURL + "/file/" + bucket + "/" + file
-	r, err := http.NewRequest("GET", url, nil)
+	res, err := c.hc.Get(c.DownloadURL + "/file/" + bucket + "/" + file)
 	if err != nil {
+		debugf("download %s: %s", file, err)
 		return nil, nil, err
 	}
-	r.Header.Set("Authorization", c.AuthorizationToken)
-
-	res, err := c.hc.Do(r)
-	if err != nil {
-		return nil, nil, err
-	}
-	if res.StatusCode != 200 {
-		return nil, nil, parseB2Error(res)
-	}
+	debugf("download %s (%s)", file, res.Header.Get("X-Bz-Content-Sha1"))
 
 	fi, err := parseFileInfoHeaders(res.Header)
 	return res.Body, fi, err

upload.go

@@ -33,6 +33,7 @@ func (b *Bucket) Upload(r io.Reader, name, mimeType string) (*FileInfo, error) {
 	case io.ReadSeeker:
 		body = r
 	default:
+		debugf("upload %s: buffering", name)
 		b, err := ioutil.ReadAll(r)
 		if err != nil {
 			return nil, err
@@ -122,11 +123,10 @@ func (b *Bucket) UploadWithSHA1(r io.Reader, name, mimeType, sha1Sum string, len
 
 	res, err := b.c.hc.Do(req)
 	if err != nil {
+		debugf("upload %s: %s", name, err)
 		return nil, err
 	}
-	if res.StatusCode != 200 {
-		return nil, parseB2Error(res)
-	}
+	debugf("upload %s (%d %s)", name, length, sha1Sum)
 	defer drainAndClose(res.Body)
 
 	fi := fileInfoObj{}