diff --git a/goshopify.go b/goshopify.go index 732ca77b..db601af5 100644 --- a/goshopify.go +++ b/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 { diff --git a/goshopify_test.go b/goshopify_test.go index a42dec40..3f141ecd 100644 --- a/goshopify_test.go +++ b/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) } diff --git a/logger.go b/logger.go new file mode 100644 index 00000000..7c8f8a6a --- /dev/null +++ b/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 +} diff --git a/logger_test.go b/logger_test.go new file mode 100644 index 00000000..13e0fc7f --- /dev/null +++ b/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()) + } +} diff --git a/oauth.go b/oauth.go index 1aead064..6e0bf4c1 100644 --- a/oauth.go +++ b/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 } diff --git a/oauth_test.go b/oauth_test.go index 85d5aa6b..e2eddd5f 100644 --- a/oauth_test.go +++ b/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) { diff --git a/options.go b/options.go index 08cb8ab3..c3016d40 100644 --- a/options.go +++ b/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 + } +} diff --git a/options_test.go b/options_test.go index ad363399..76dadca5 100644 --- a/options_test.go +++ b/options_test.go @@ -44,3 +44,12 @@ func TestWithRetry(t *testing.T) { t.Errorf("WithRetry client.retries = %d, expected %d", c.retries, expected) } } + +func TestWithLogger(t *testing.T) { + logger := &LeveledLogger{Level: LevelDebug} + c := NewClient(app, "fooshop", "abcd", WithLogger(logger)) + + if c.log != logger { + t.Errorf("WithLogger expected logs to match %v != %v", c.log, logger) + } +}