adding WithLogger option (bold-commerce#99)

Co-authored-by: Gord Currie <[email protected]>

goshopify.go

@@ -5,6 +5,7 @@ import (
 	"bytes"
 	"encoding/json"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"net/http"
 	"net/url"
@@ -54,6 +55,7 @@ type RateLimitInfo struct {
 type Client struct {
 	// HTTP client used to communicate with the Shopify API.
 	Client *http.Client
+	log    LeveledLoggerInterface
 
 	// App settings
 	app App
@@ -240,6 +242,7 @@ func NewClient(app App, shopName, token string, opts ...Option) *Client {
 		Client: &http.Client{
 			Timeout: time.Second * defaultHttpTimeout,
 		},
+		log:        &LeveledLogger{},
 		app:        app,
 		baseURL:    baseURL,
 		token:      token,
@@ -301,9 +304,12 @@ func (c *Client) doGetHeaders(req *http.Request, v interface{}) (http.Header, er
 	var err error
 	retries := c.retries
 	c.attempts = 0
+	c.logRequest(req)
+
 	for {
 		c.attempts++
 		resp, err = c.Client.Do(req)
+		c.logResponse(resp)
 		if err != nil {
 			return nil, err //http client errors, not api responses
 		}
@@ -322,7 +328,9 @@ func (c *Client) doGetHeaders(req *http.Request, v interface{}) (http.Header, er
 
 		if rateLimitErr, isRetryErr := respErr.(RateLimitError); isRetryErr {
 			// back off and retry
+
 			wait := time.Duration(rateLimitErr.RetryAfter) * time.Second
+			c.log.Debugf("rate limited waiting %s", wait.String())
 			time.Sleep(wait)
 			retries--
 			continue
@@ -331,6 +339,7 @@ func (c *Client) doGetHeaders(req *http.Request, v interface{}) (http.Header, er
 		var doRetry bool
 		switch resp.StatusCode {
 		case http.StatusServiceUnavailable:
+			c.log.Debugf("service unavailable, retrying")
 			doRetry = true
 			retries--
 		}
@@ -343,11 +352,13 @@ func (c *Client) doGetHeaders(req *http.Request, v interface{}) (http.Header, er
 		return nil, respErr
 	}
 
+	c.logResponse(resp)
 	defer resp.Body.Close()
 
 	if c.apiVersion == defaultApiVersion && resp.Header.Get("X-Shopify-API-Version") != "" {
 		// if using stable on first request set the api version
 		c.apiVersion = resp.Header.Get("X-Shopify-API-Version")
+		c.log.Infof("api version not set, now using %s", c.apiVersion)
 	}
 
 	if v != nil {
@@ -368,6 +379,35 @@ func (c *Client) doGetHeaders(req *http.Request, v interface{}) (http.Header, er
 	return resp.Header, nil
 }
 
+func (c *Client) logRequest(req *http.Request) {
+	if req == nil {
+		return
+	}
+	if req.URL != nil {
+		c.log.Debugf("%s: %s", req.Method, req.URL.String())
+	}
+	c.logBody(&req.Body, "SENT: %s")
+}
+
+func (c *Client) logResponse(res *http.Response) {
+	if res == nil {
+		return
+	}
+	c.log.Debugf("RECV %d: %s", res.StatusCode, res.Status)
+	c.logBody(&res.Body, "RESP: %s")
+}
+
+func (c *Client) logBody(body *io.ReadCloser, format string) {
+	if body == nil {
+		return
+	}
+	b, _ := ioutil.ReadAll(*body)
+	if len(b) > 0 {
+		c.log.Debugf(format, string(b))
+	}
+	*body = ioutil.NopCloser(bytes.NewBuffer(b))
+}
+
 func wrapSpecificError(r *http.Response, err ResponseError) error {
 	// see https://www.shopify.dev/concepts/about-apis/response-codes
 	if err.Status == http.StatusTooManyRequests {

goshopify_test.go

@@ -46,7 +46,9 @@ func setup() {
 		Scope:       "read_products",
 		Password:    "privateapppassword",
 	}
-	client = NewClient(app, "fooshop", "abcd", WithVersion(testApiVersion), WithRetry(maxRetries))
+	client = NewClient(app, "fooshop", "abcd",
+		WithVersion(testApiVersion),
+		WithRetry(maxRetries))
 	httpmock.ActivateNonDefault(client.Client)
 }
 

logger.go

@@ -0,0 +1,85 @@
+package goshopify
+
+import (
+	"fmt"
+	"io"
+	"os"
+)
+
+// idea from https://github.com/stripe/stripe-go/blob/master/log.go
+
+const (
+	LevelError = iota + 1
+	LevelWarn
+	LevelInfo
+	LevelDebug
+)
+
+type LeveledLoggerInterface interface {
+	Debugf(format string, v ...interface{})
+	Errorf(format string, v ...interface{})
+	Infof(format string, v ...interface{})
+	Warnf(format string, v ...interface{})
+}
+
+// It prints warnings and errors to `os.Stderr` and other messages to
+// `os.Stdout`.
+type LeveledLogger struct {
+	// Level is the minimum logging level that will be emitted by this logger.
+	//
+	// For example, a Level set to LevelWarn will emit warnings and errors, but
+	// not informational or debug messages.
+	//
+	// Always set this with a constant like LevelWarn because the individual
+	// values are not guaranteed to be stable.
+	Level int
+
+	// Internal testing use only.
+	stderrOverride io.Writer
+	stdoutOverride io.Writer
+}
+
+// Debugf logs a debug message using Printf conventions.
+func (l *LeveledLogger) Debugf(format string, v ...interface{}) {
+	if l.Level >= LevelDebug {
+		fmt.Fprintf(l.stdout(), "[DEBUG] "+format+"\n", v...)
+	}
+}
+
+// Errorf logs a warning message using Printf conventions.
+func (l *LeveledLogger) Errorf(format string, v ...interface{}) {
+	// Infof logs a debug message using Printf conventions.
+	if l.Level >= LevelError {
+		fmt.Fprintf(l.stderr(), "[ERROR] "+format+"\n", v...)
+	}
+}
+
+// Infof logs an informational message using Printf conventions.
+func (l *LeveledLogger) Infof(format string, v ...interface{}) {
+	if l.Level >= LevelInfo {
+		fmt.Fprintf(l.stdout(), "[INFO] "+format+"\n", v...)
+	}
+}
+
+// Warnf logs a warning message using Printf conventions.
+func (l *LeveledLogger) Warnf(format string, v ...interface{}) {
+	if l.Level >= LevelWarn {
+		fmt.Fprintf(l.stderr(), "[WARN] "+format+"\n", v...)
+	}
+}
+
+func (l *LeveledLogger) stderr() io.Writer {
+	if l.stderrOverride != nil {
+		return l.stderrOverride
+	}
+
+	return os.Stderr
+}
+
+func (l *LeveledLogger) stdout() io.Writer {
+	if l.stdoutOverride != nil {
+		return l.stdoutOverride
+	}
+
+	return os.Stdout
+}

logger_test.go

@@ -0,0 +1,124 @@
+package goshopify
+
+import (
+	"bytes"
+	"io/ioutil"
+	"net/http"
+	"net/url"
+	"os"
+	"strings"
+	"testing"
+)
+
+func TestLeveledLogger(t *testing.T) {
+	tests := []struct {
+		level  int
+		input  string
+		stdout string
+		stderr string
+	}{
+		{
+			level:  LevelError,
+			input:  "log",
+			stderr: "[ERROR] error log\n",
+			stdout: "",
+		},
+		{
+			level:  LevelWarn,
+			input:  "log",
+			stderr: "[ERROR] error log\n[WARN] warn log\n",
+			stdout: "",
+		},
+		{
+			level:  LevelInfo,
+			input:  "log",
+			stderr: "[ERROR] error log\n[WARN] warn log\n",
+			stdout: "[INFO] info log\n",
+		},
+		{
+			level:  LevelDebug,
+			input:  "log",
+			stderr: "[ERROR] error log\n[WARN] warn log\n",
+			stdout: "[INFO] info log\n[DEBUG] debug log\n",
+		},
+	}
+
+	for _, test := range tests {
+		err := &bytes.Buffer{}
+		out := &bytes.Buffer{}
+		log := &LeveledLogger{Level: test.level, stderrOverride: err, stdoutOverride: out}
+
+		log.Errorf("error %s", test.input)
+		log.Warnf("warn %s", test.input)
+		log.Infof("info %s", test.input)
+		log.Debugf("debug %s", test.input)
+
+		stdout := out.String()
+		stderr := err.String()
+
+		if stdout != test.stdout {
+			t.Errorf("leveled logger %d expected stdout \"%s\" received \"%s\"", test.level, test.stdout, stdout)
+		}
+		if stderr != test.stderr {
+			t.Errorf("leveled logger %d expected stderr \"%s\" received \"%s\"", test.level, test.stderr, stderr)
+		}
+	}
+
+	log := &LeveledLogger{Level: LevelDebug}
+	if log.stderr() != os.Stderr {
+		t.Errorf("leveled logger with no stderr override expects os.Stderr")
+	}
+	if log.stdout() != os.Stdout {
+		t.Errorf("leveled logger with no stdout override expects os.Stdout")
+	}
+
+}
+
+func TestDoGetHeadersDebug(t *testing.T) {
+	err := &bytes.Buffer{}
+	out := &bytes.Buffer{}
+	logger := &LeveledLogger{Level: LevelDebug, stderrOverride: err, stdoutOverride: out}
+
+	reqExpected := "[DEBUG] GET: //http:%2F%2Ftest.com/foo/1\n[DEBUG] SENT: request body\n"
+	resExpected := "[DEBUG] RECV 200: OK\n[DEBUG] RESP: response body\n"
+
+	client := NewClient(app, "fooshop", "abcd", WithLogger(logger))
+
+	client.logBody(nil, "")
+	if out.String() != "" {
+		t.Errorf("logBody expected empty log output but received \"%s\"", out.String())
+	}
+
+	client.logRequest(nil)
+	if out.String() != "" {
+		t.Errorf("logRequest expected empty log output received \"%s\"", out.String())
+	}
+
+	client.logRequest(&http.Request{
+		Method: "GET",
+		URL:    &url.URL{Host: "http://test.com", Path: "/foo/1"},
+		Body:   ioutil.NopCloser(strings.NewReader("request body")),
+	})
+
+	if out.String() != reqExpected {
+		t.Errorf("doGetHeadersDebug expected stdout \"%s\" received \"%s\"", reqExpected, out)
+	}
+
+	err.Reset()
+	out.Reset()
+
+	client.logResponse(nil)
+	if out.String() != "" {
+		t.Errorf("logResponse expected empty log output received \"%s\"", out.String())
+	}
+
+	client.logResponse(&http.Response{
+		Status:     http.StatusText(http.StatusOK),
+		StatusCode: http.StatusOK,
+		Body:       ioutil.NopCloser(strings.NewReader("response body")),
+	})
+
+	if out.String() != resExpected {
+		t.Errorf("doGetHeadersDebug expected stdout \"%s\" received \"%s\"", resExpected, out.String())
+	}
+}

oauth.go

@@ -15,6 +15,8 @@ import (
 
 const shopifyChecksumHeader = "X-Shopify-Hmac-Sha256"
 
+var accessTokenRelPath = "admin/oauth/access_token"
+
 // Returns a Shopify oauth authorization url for the given shopname and state.
 //
 // State is a unique value that can be used to check the authenticity during a
@@ -51,7 +53,7 @@ func (app App) GetAccessToken(shopName string, code string) (string, error) {
 		client = NewClient(app, shopName, "")
 	}
 
-	req, err := client.NewRequest("POST", "admin/oauth/access_token", data, nil)
+	req, err := client.NewRequest("POST", accessTokenRelPath, data, nil)
 	if err != nil {
 		return "", err
 	}

oauth_test.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"net/http"
 	"net/url"
+	"strings"
 	"testing"
 
 	"github.com/jarcoal/httpmock"
@@ -58,11 +59,24 @@ func TestAppGetAccessTokenError(t *testing.T) {
 	// app.Client isn't specified so NewClient called
 	expectedError := errors.New("invalid_request")
 
-	_, err := app.GetAccessToken("fooshop", "")
+	token, err := app.GetAccessToken("fooshop", "")
 
 	if err == nil || err.Error() != expectedError.Error() {
 		t.Errorf("Expected error %s got error %s", expectedError.Error(), err.Error())
 	}
+	if token != "" {
+		t.Errorf("Expected empty token received %s", token)
+	}
+
+	expectedError = errors.New("parse ://example.com: missing protocol scheme")
+	accessTokenRelPath = "://example.com" // cause NewRequest to trip a parse error
+	token, err = app.GetAccessToken("fooshop", "")
+	if err == nil || !strings.Contains(err.Error(), "missing protocol scheme") {
+		t.Errorf("Expected error %s got error %s", expectedError.Error(), err.Error())
+	}
+	if token != "" {
+		t.Errorf("Expected empty token received %s", token)
+	}
 }
 
 func TestAppVerifyAuthorizationURL(t *testing.T) {

options.go

@@ -22,3 +22,9 @@ func WithRetry(retries int) Option {
 		c.retries = retries
 	}
 }
+
+func WithLogger(logger LeveledLoggerInterface) Option {
+	return func(c *Client) {
+		c.log = logger
+	}
+}