From 3c4328aa90f6be28e745575300b7486de00262e2 Mon Sep 17 00:00:00 2001
From: Brandur <brandur@brandur.org>
Date: Wed, 1 Aug 2018 10:55:58 -0700
Subject: [PATCH] Bug fix + various code/logging improvements to retry code

This one is a variety of improvements to the retry code:

* Fixed one bug whereby for a failed request, we were not reading the
  entire response body before trying to log it, which results in an
  uninformative output like `&{409....`. Here we add a `ReadAll`.
* I denested some code so that we have less indentation.
* I changed measuring request time to measuring individual requests
  around `s.HTTPClient.Do` instead of measuring the entire span
  including all the sleeping the retry block is doing.
* I added logging for the amount of time the program is about to go to
  sleep before a retry. You can still get the total execution time by
  adding the time for all requests plus the time for all sleeps.
* Generally changed some logs around for consistency around format,
  casing, and punctuation.

The impetus is that I was trying to understand the code to debug #642.
This might help get some visibility into a solution, but won't solve the
problem.
---
 stripe.go | 53 +++++++++++++++++++++++++++++++++++------------------
 1 file changed, 35 insertions(+), 18 deletions(-)

diff --git a/stripe.go b/stripe.go
index 14aff4a291..89f4cd61cc 100644
--- a/stripe.go
+++ b/stripe.go
@@ -283,34 +283,51 @@ func (s *BackendConfiguration) Do(req *http.Request, v interface{}) error {
 		s.Logger.Printf("Requesting %v %v%v\n", req.Method, req.URL.Host, req.URL.Path)
 	}
 
-	start := time.Now()
-
 	var res *http.Response
 	var err error
 	for retry := 0; ; {
+		start := time.Now()
+
 		res, err = s.HTTPClient.Do(req)
-		if s.shouldRetry(err, res, retry) {
+
+		if s.LogLevel > 2 {
+			s.Logger.Printf("Request completed in %v (retry: %v)\n",
+				time.Since(start), retry)
+		}
+
+		// If the response was okay, we're done, and it's safe to break out of
+		// the retry loop.
+		if !s.shouldRetry(err, res, retry) {
+			break
+		}
+
+		resBody, err := ioutil.ReadAll(res.Body)
+		res.Body.Close()
+		if err != nil {
 			if s.LogLevel > 0 {
-				s.Logger.Printf("Request failed with error: %v. Response: %v\n", err, res)
+				s.Logger.Printf("Cannot read response: %v\n", err)
 			}
-			sleep := sleepTime(retry)
-			time.Sleep(sleep)
-			retry++
-			if s.LogLevel > 1 {
-				s.Logger.Printf("Retry request %v %v time.\n", req.URL, retry)
-			}
-		} else {
-			break
+			return err
 		}
-	}
 
-	if s.LogLevel > 2 {
-		s.Logger.Printf("Completed in %v\n", time.Since(start))
+		if s.LogLevel > 0 {
+			s.Logger.Printf("Request failed with: %s (error: %v)\n", string(resBody), err)
+		}
+
+		sleepDuration := sleepTime(retry)
+		retry++
+
+		if s.LogLevel > 1 {
+			s.Logger.Printf("Initiating retry %v for request %v %v%v after sleeping %v\n",
+				retry, req.Method, req.URL.Host, req.URL.Path, sleepDuration)
+		}
+
+		time.Sleep(sleepDuration)
 	}
 
 	if err != nil {
 		if s.LogLevel > 0 {
-			s.Logger.Printf("Request to Stripe failed: %v\n", err)
+			s.Logger.Printf("Request failed: %v\n", err)
 		}
 		return err
 	}
@@ -319,7 +336,7 @@ func (s *BackendConfiguration) Do(req *http.Request, v interface{}) error {
 	resBody, err := ioutil.ReadAll(res.Body)
 	if err != nil {
 		if s.LogLevel > 0 {
-			s.Logger.Printf("Cannot parse Stripe response: %v\n", err)
+			s.Logger.Printf("Cannot read response: %v\n", err)
 		}
 		return err
 	}
@@ -329,7 +346,7 @@ func (s *BackendConfiguration) Do(req *http.Request, v interface{}) error {
 	}
 
 	if s.LogLevel > 2 {
-		s.Logger.Printf("Stripe Response: %q\n", resBody)
+		s.Logger.Printf("Response: %s\n", string(resBody))
 	}
 
 	if v != nil {