From 67e17c6aca7c2b04d741330d2ff6bc2282dd3ea0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mislav=20Marohni=C4=87?= Date: Wed, 27 Jul 2022 16:32:19 +0200 Subject: [PATCH 1/5] Expand logging support for HTTP traffic MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Respect the GH_DEBUG environment variable by default, but add the option to skip it; - Add option to opt into colorized logging; - Add option to explicitly log HTTP headers and bodies—the new default is off; - Colorize JSON payloads when logging HTTP bodies; - Log form-encoded payloads; - Pretty-print GraphQL queries when logging HTTP requests. --- go.mod | 1 + go.sum | 1 + internal/api/cache_test.go | 14 ++-- internal/api/http.go | 39 ++++++++-- internal/api/http_test.go | 1 + internal/api/log_formatter.go | 47 +++++++++++ pkg/api/client.go | 9 +++ pkg/jsonpretty/format.go | 143 ++++++++++++++++++++++++++++++++++ pkg/jsonpretty/format_test.go | 96 +++++++++++++++++++++++ 9 files changed, 337 insertions(+), 14 deletions(-) create mode 100644 internal/api/log_formatter.go create mode 100644 pkg/jsonpretty/format.go create mode 100644 pkg/jsonpretty/format_test.go diff --git a/go.mod b/go.mod index 419acc6..c7f252f 100644 --- a/go.mod +++ b/go.mod @@ -10,6 +10,7 @@ require ( github.com/kr/pretty v0.1.0 // indirect github.com/stretchr/testify v1.7.0 github.com/thlib/go-timezone-local v0.0.0-20210907160436-ef149e42d28e + golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 // indirect gopkg.in/h2non/gock.v1 v1.1.2 gopkg.in/yaml.v3 v3.0.1 diff --git a/go.sum b/go.sum index 83b2380..28264da 100644 --- a/go.sum +++ b/go.sum @@ -30,6 +30,7 @@ golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210831042530-f4d43177bf5e h1:XMgFehsDnnLGtjvjOfqWSUzt0alpTR1RSEuznObga2c= golang.org/x/sys v0.0.0-20210831042530-f4d43177bf5e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1 h1:v+OssWQX+hTHEmOBgwxdZxK4zHq3yOs8F9J7mk0PY8E= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= diff --git a/internal/api/cache_test.go b/internal/api/cache_test.go index 1142f3b..548dc6e 100644 --- a/internal/api/cache_test.go +++ b/internal/api/cache_test.go @@ -34,9 +34,10 @@ func TestCacheResponse(t *testing.T) { httpClient := NewHTTPClient( &api.ClientOptions{ - Transport: fakeHTTP, - EnableCache: true, - CacheDir: cacheDir, + Transport: fakeHTTP, + EnableCache: true, + CacheDir: cacheDir, + LogIgnoreEnv: true, }) do := func(method, url string, body io.Reader) (string, error) { @@ -114,9 +115,10 @@ func TestCacheResponseRequestCacheOptions(t *testing.T) { httpClient := NewHTTPClient( &api.ClientOptions{ - Transport: fakeHTTP, - EnableCache: false, - CacheDir: cacheDir, + Transport: fakeHTTP, + EnableCache: false, + CacheDir: cacheDir, + LogIgnoreEnv: true, }) do := func(method, url string, body io.Reader) (string, error) { diff --git a/internal/api/http.go b/internal/api/http.go index 7bac5fe..f6f7b91 100644 --- a/internal/api/http.go +++ b/internal/api/http.go @@ -14,6 +14,7 @@ import ( "github.com/cli/go-gh/pkg/api" "github.com/henvic/httpretty" "github.com/thlib/go-timezone-local/tzlocal" + "golang.org/x/term" ) const ( @@ -54,17 +55,29 @@ func NewHTTPClient(opts *api.ClientOptions) http.Client { c := cache{dir: opts.CacheDir, ttl: opts.CacheTTL} transport = c.RoundTripper(transport) + if opts.Log == nil && !opts.LogIgnoreEnv { + ghDebug := os.Getenv("GH_DEBUG") + switch ghDebug { + case "", "0", "false", "no": + // no logging + default: + opts.Log = os.Stderr + opts.LogColorize = !colorDisabled() && isTerminal(os.Stderr) + opts.LogVerboseHTTP = strings.Contains(ghDebug, "api") + } + } + if opts.Log != nil { logger := &httpretty.Logger{ Time: true, TLS: false, - Colors: false, - RequestHeader: true, - RequestBody: true, - ResponseHeader: true, - ResponseBody: true, - Formatters: []httpretty.Formatter{&httpretty.JSONFormatter{}}, - MaxResponseBody: 10000, + Colors: opts.LogColorize, + RequestHeader: opts.LogVerboseHTTP, + RequestBody: opts.LogVerboseHTTP, + ResponseHeader: opts.LogVerboseHTTP, + ResponseBody: opts.LogVerboseHTTP, + Formatters: []httpretty.Formatter{&jsonFormatter{colorize: opts.LogColorize}}, + MaxResponseBody: 100000, } logger.SetOutput(opts.Log) logger.SetBodyFilter(func(h http.Header) (skip bool, err error) { @@ -85,7 +98,9 @@ func NewHTTPClient(opts *api.ClientOptions) http.Client { } func inspectableMIMEType(t string) bool { - return strings.HasPrefix(t, "text/") || jsonTypeRE.MatchString(t) + return strings.HasPrefix(t, "text/") || + strings.HasPrefix(t, "application/x-www-form-urlencoded") || + jsonTypeRE.MatchString(t) } func isSameDomain(requestHost, domain string) bool { @@ -193,3 +208,11 @@ func currentTimeZone() string { } return tz } + +func isTerminal(f *os.File) bool { + return term.IsTerminal(int(f.Fd())) +} + +func colorDisabled() bool { + return os.Getenv("NO_COLOR") != "" || os.Getenv("CLICOLOR") == "0" +} diff --git a/internal/api/http_test.go b/internal/api/http_test.go index 64b92bf..bdfe5b3 100644 --- a/internal/api/http_test.go +++ b/internal/api/http_test.go @@ -120,6 +120,7 @@ func TestNewHTTPClient(t *testing.T) { Headers: tt.headers, SkipDefaultHeaders: tt.skipHeaders, Transport: reflectHTTP, + LogIgnoreEnv: true, } if tt.enableLog { opts.Log = tt.log diff --git a/internal/api/log_formatter.go b/internal/api/log_formatter.go new file mode 100644 index 0000000..cf709db --- /dev/null +++ b/internal/api/log_formatter.go @@ -0,0 +1,47 @@ +package api + +import ( + "bytes" + "encoding/json" + "fmt" + "io" + "strings" + + "github.com/cli/go-gh/pkg/jsonpretty" +) + +type graphqlBody struct { + Query string `json:"query"` + OperationName string `json:"operationName"` + Variables json.RawMessage `json:"variables"` +} + +// jsonFormatter is a httpretty.Formatter that prettifies JSON payloads and GraphQL queries +type jsonFormatter struct { + colorize bool +} + +func (f *jsonFormatter) Format(w io.Writer, src []byte) error { + var graphqlQuery graphqlBody + // TODO: find more precise way to detect a GraphQL query from the JSON payload alone + if err := json.Unmarshal(src, &graphqlQuery); err == nil && graphqlQuery.Query != "" && len(graphqlQuery.Variables) > 0 { + colorHighlight := "\x1b[35;1m" + colorReset := "\x1b[m" + if !f.colorize { + colorHighlight = "" + colorReset = "" + } + if _, err := fmt.Fprintf(w, "%sGraphQL query:%s\n%s\n", colorHighlight, colorReset, strings.ReplaceAll(strings.TrimSpace(graphqlQuery.Query), "\t", " ")); err != nil { + return err + } + if _, err := fmt.Fprintf(w, "%sGraphQL variables:%s %s\n", colorHighlight, colorReset, string(graphqlQuery.Variables)); err != nil { + return err + } + return nil + } + return jsonpretty.Format(w, bytes.NewReader(src), " ", f.colorize) +} + +func (f *jsonFormatter) Match(t string) bool { + return jsonTypeRE.MatchString(t) +} diff --git a/pkg/api/client.go b/pkg/api/client.go index a31dbca..3b42114 100644 --- a/pkg/api/client.go +++ b/pkg/api/client.go @@ -38,6 +38,15 @@ type ClientOptions struct { // Default is no logging. Log io.Writer + // LogIgnoreEnv disables respecting the GH_DEBUG environment variable for logging. + LogIgnoreEnv bool + + // LogColorize enables colorized logging to Log for display in a terminal. + LogColorize bool + + // LogVerboseHTTP enables logging HTTP headers and bodies. + LogVerboseHTTP bool + // SkipDefaultHeaders disables setting of the default headers. SkipDefaultHeaders bool diff --git a/pkg/jsonpretty/format.go b/pkg/jsonpretty/format.go new file mode 100644 index 0000000..55c7a86 --- /dev/null +++ b/pkg/jsonpretty/format.go @@ -0,0 +1,143 @@ +package jsonpretty + +import ( + "bytes" + "encoding/json" + "fmt" + "io" + "strings" +) + +const ( + colorDelim = "\x1b[1;38m" // bright white + colorKey = "\x1b[1;34m" // bright blue + colorNull = "\x1b[36m" // cyan + colorString = "\x1b[32m" // green + colorBool = "\x1b[33m" // yellow + colorReset = "\x1b[m" +) + +// Format reads JSON from r and writes a prettified version of it to w. +func Format(w io.Writer, r io.Reader, indent string, colorize bool) error { + dec := json.NewDecoder(r) + dec.UseNumber() + + c := func(ansi string) string { + if !colorize { + return "" + } + return ansi + } + + var idx int + var stack []json.Delim + + for { + t, err := dec.Token() + if err == io.EOF { + break + } + if err != nil { + return err + } + + switch tt := t.(type) { + case json.Delim: + switch tt { + case '{', '[': + stack = append(stack, tt) + idx = 0 + if _, err := fmt.Fprint(w, c(colorDelim), tt, c(colorReset)); err != nil { + return err + } + if dec.More() { + if _, err := fmt.Fprint(w, "\n", strings.Repeat(indent, len(stack))); err != nil { + return err + } + } + continue + case '}', ']': + stack = stack[:len(stack)-1] + idx = 0 + if _, err := fmt.Fprint(w, c(colorDelim), tt, c(colorReset)); err != nil { + return err + } + } + default: + b, err := marshalJSON(tt) + if err != nil { + return err + } + + isKey := len(stack) > 0 && stack[len(stack)-1] == '{' && idx%2 == 0 + idx++ + + var color string + if isKey { + color = colorKey + } else if tt == nil { + color = colorNull + } else { + switch t.(type) { + case string: + color = colorString + case bool: + color = colorBool + } + } + + if color != "" { + if _, err := fmt.Fprint(w, c(color)); err != nil { + return err + } + } + if _, err := w.Write(b); err != nil { + return err + } + if color != "" { + if _, err := fmt.Fprint(w, c(colorReset)); err != nil { + return err + } + } + + if isKey { + if _, err := fmt.Fprint(w, c(colorDelim), ":", c(colorReset), " "); err != nil { + return err + } + continue + } + } + + if dec.More() { + if _, err := fmt.Fprint(w, c(colorDelim), ",", c(colorReset), "\n", strings.Repeat(indent, len(stack))); err != nil { + return err + } + } else if len(stack) > 0 { + if _, err := fmt.Fprint(w, "\n", strings.Repeat(indent, len(stack)-1)); err != nil { + return err + } + } else { + if _, err := fmt.Fprint(w, "\n"); err != nil { + return err + } + } + } + + return nil +} + +// marshalJSON works like json.Marshal but with HTML-escaping disabled +func marshalJSON(v interface{}) ([]byte, error) { + buf := bytes.Buffer{} + enc := json.NewEncoder(&buf) + enc.SetEscapeHTML(false) + if err := enc.Encode(v); err != nil { + return nil, err + } + bb := buf.Bytes() + // omit trailing newline added by json.Encoder + if len(bb) > 0 && bb[len(bb)-1] == '\n' { + return bb[:len(bb)-1], nil + } + return bb, nil +} diff --git a/pkg/jsonpretty/format_test.go b/pkg/jsonpretty/format_test.go new file mode 100644 index 0000000..16d2b34 --- /dev/null +++ b/pkg/jsonpretty/format_test.go @@ -0,0 +1,96 @@ +package jsonpretty + +import ( + "bytes" + "io" + "testing" +) + +func TestWrite(t *testing.T) { + type args struct { + r io.Reader + indent string + colorize bool + } + tests := []struct { + name string + args args + wantW string + wantErr bool + }{ + { + name: "blank", + args: args{ + r: bytes.NewBufferString(``), + indent: "", + colorize: true, + }, + wantW: "", + wantErr: false, + }, + { + name: "empty object", + args: args{ + r: bytes.NewBufferString(`{}`), + indent: "", + colorize: true, + }, + wantW: "\x1b[1;38m{\x1b[m\x1b[1;38m}\x1b[m\n", + wantErr: false, + }, + { + name: "nested object", + args: args{ + r: bytes.NewBufferString(`{"hash":{"a":1,"b":2},"array":[3,4]}`), + indent: "\t", + colorize: true, + }, + wantW: "\x1b[1;38m{\x1b[m\n\t\x1b[1;34m\"hash\"\x1b[m\x1b[1;38m:\x1b[m " + + "\x1b[1;38m{\x1b[m\n\t\t\x1b[1;34m\"a\"\x1b[m\x1b[1;38m:\x1b[m 1\x1b[1;38m,\x1b[m\n\t\t\x1b[1;34m\"b\"\x1b[m\x1b[1;38m:\x1b[m 2\n\t\x1b[1;38m}\x1b[m\x1b[1;38m,\x1b[m" + + "\n\t\x1b[1;34m\"array\"\x1b[m\x1b[1;38m:\x1b[m \x1b[1;38m[\x1b[m\n\t\t3\x1b[1;38m,\x1b[m\n\t\t4\n\t\x1b[1;38m]\x1b[m\n\x1b[1;38m}\x1b[m\n", + wantErr: false, + }, + { + name: "no color", + args: args{ + r: bytes.NewBufferString(`{"hash":{"a":1,"b":2},"array":[3,4]}`), + indent: "\t", + colorize: false, + }, + wantW: "{\n\t\"hash\": {\n\t\t\"a\": 1,\n\t\t\"b\": 2\n\t},\n\t\"array\": [\n\t\t3,\n\t\t4\n\t]\n}\n", + wantErr: false, + }, + { + name: "string", + args: args{ + r: bytes.NewBufferString(`"foo"`), + indent: "", + colorize: true, + }, + wantW: "\x1b[32m\"foo\"\x1b[m\n", + wantErr: false, + }, + { + name: "error", + args: args{ + r: bytes.NewBufferString(`{{`), + indent: "", + colorize: true, + }, + wantW: "\x1b[1;38m{\x1b[m\n", + wantErr: true, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + w := &bytes.Buffer{} + if err := Format(w, tt.args.r, tt.args.indent, tt.args.colorize); (err != nil) != tt.wantErr { + t.Errorf("Write() error = %v, wantErr %v", err, tt.wantErr) + return + } + if w.String() != tt.wantW { + t.Errorf("got: %q, want: %q", w.String(), tt.wantW) + } + }) + } +} From 771b5a0787978db767bd57e4ace925ae321d9ad3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mislav=20Marohni=C4=87?= Date: Tue, 2 Aug 2022 13:53:55 +0200 Subject: [PATCH 2/5] fix linter --- internal/api/log_formatter.go | 2 +- pkg/jsonpretty/format.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/internal/api/log_formatter.go b/internal/api/log_formatter.go index cf709db..26d1a82 100644 --- a/internal/api/log_formatter.go +++ b/internal/api/log_formatter.go @@ -16,7 +16,7 @@ type graphqlBody struct { Variables json.RawMessage `json:"variables"` } -// jsonFormatter is a httpretty.Formatter that prettifies JSON payloads and GraphQL queries +// jsonFormatter is a httpretty.Formatter that prettifies JSON payloads and GraphQL queries. type jsonFormatter struct { colorize bool } diff --git a/pkg/jsonpretty/format.go b/pkg/jsonpretty/format.go index 55c7a86..f695c92 100644 --- a/pkg/jsonpretty/format.go +++ b/pkg/jsonpretty/format.go @@ -126,7 +126,7 @@ func Format(w io.Writer, r io.Reader, indent string, colorize bool) error { return nil } -// marshalJSON works like json.Marshal but with HTML-escaping disabled +// marshalJSON works like json.Marshal, but with HTML-escaping disabled. func marshalJSON(v interface{}) ([]byte, error) { buf := bytes.Buffer{} enc := json.NewEncoder(&buf) From e74943abaeb58230091c4dfa1c5b835dcf27d480 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mislav=20Marohni=C4=87?= Date: Tue, 9 Aug 2022 21:48:45 +0200 Subject: [PATCH 3/5] Apply suggestions from code review Co-authored-by: Sam Coe --- pkg/api/client.go | 1 + 1 file changed, 1 insertion(+) diff --git a/pkg/api/client.go b/pkg/api/client.go index 3b42114..8dabf48 100644 --- a/pkg/api/client.go +++ b/pkg/api/client.go @@ -45,6 +45,7 @@ type ClientOptions struct { LogColorize bool // LogVerboseHTTP enables logging HTTP headers and bodies. + // Default is only logging request URLs and response statuses. LogVerboseHTTP bool // SkipDefaultHeaders disables setting of the default headers. From 440a6b215b9e61c0100db8f3c8632480a7064642 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mislav=20Marohni=C4=87?= Date: Tue, 9 Aug 2022 22:40:56 +0200 Subject: [PATCH 4/5] use term --- internal/api/http.go | 12 ++---------- pkg/jsonpretty/format.go | 1 + pkg/term/env.go | 13 ++++++++----- 3 files changed, 11 insertions(+), 15 deletions(-) diff --git a/internal/api/http.go b/internal/api/http.go index f6f7b91..cb0936b 100644 --- a/internal/api/http.go +++ b/internal/api/http.go @@ -12,9 +12,9 @@ import ( "time" "github.com/cli/go-gh/pkg/api" + "github.com/cli/go-gh/pkg/term" "github.com/henvic/httpretty" "github.com/thlib/go-timezone-local/tzlocal" - "golang.org/x/term" ) const ( @@ -62,7 +62,7 @@ func NewHTTPClient(opts *api.ClientOptions) http.Client { // no logging default: opts.Log = os.Stderr - opts.LogColorize = !colorDisabled() && isTerminal(os.Stderr) + opts.LogColorize = !term.IsColorDisabled() && term.IsTerminal(os.Stderr) opts.LogVerboseHTTP = strings.Contains(ghDebug, "api") } } @@ -208,11 +208,3 @@ func currentTimeZone() string { } return tz } - -func isTerminal(f *os.File) bool { - return term.IsTerminal(int(f.Fd())) -} - -func colorDisabled() bool { - return os.Getenv("NO_COLOR") != "" || os.Getenv("CLICOLOR") == "0" -} diff --git a/pkg/jsonpretty/format.go b/pkg/jsonpretty/format.go index f695c92..63ac972 100644 --- a/pkg/jsonpretty/format.go +++ b/pkg/jsonpretty/format.go @@ -1,3 +1,4 @@ +// Package jsonpretty implements a terminal pretty-printer for JSON. package jsonpretty import ( diff --git a/pkg/term/env.go b/pkg/term/env.go index b1d653e..994c99e 100644 --- a/pkg/term/env.go +++ b/pkg/term/env.go @@ -38,7 +38,7 @@ func FromEnv() Term { spec := os.Getenv("GH_FORCE_TTY") if spec != "" { stdoutIsTTY = true - isColorEnabled = !envColorDisabled() + isColorEnabled = !IsColorDisabled() if w, err := strconv.Atoi(spec); err == nil { termWidthOverride = w @@ -48,8 +48,8 @@ func FromEnv() Term { } } } else { - stdoutIsTTY = isTerminal(os.Stdout) - isColorEnabled = envColorForced() || (!envColorDisabled() && stdoutIsTTY) + stdoutIsTTY = IsTerminal(os.Stdout) + isColorEnabled = envColorForced() || (!IsColorDisabled() && stdoutIsTTY) } isVirtualTerminal := false @@ -121,7 +121,8 @@ func (t Term) Size() (int, int, error) { return width, height, err } -func isTerminal(f *os.File) bool { +// IsTerminal reports whether a file descriptor is connected to a terminal. +func IsTerminal(f *os.File) bool { return term.IsTerminal(int(f.Fd())) } @@ -129,7 +130,9 @@ func terminalSize(f *os.File) (int, int, error) { return term.GetSize(int(f.Fd())) } -func envColorDisabled() bool { +// IsColorDisabled returns true if environment variables NO_COLOR or CLICOLOR prohibit usage of color codes +// in terminal output. +func IsColorDisabled() bool { return os.Getenv("NO_COLOR") != "" || os.Getenv("CLICOLOR") == "0" } From c57f56667b157575c7a6ebef0a7a432c2a003dcb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mislav=20Marohni=C4=87?= Date: Tue, 9 Aug 2022 22:45:49 +0200 Subject: [PATCH 5/5] logging docs --- pkg/api/client.go | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/pkg/api/client.go b/pkg/api/client.go index 8dabf48..96909e1 100644 --- a/pkg/api/client.go +++ b/pkg/api/client.go @@ -34,17 +34,19 @@ type ClientOptions struct { // Host is the default host that API requests will be sent to. Host string - // Log specifies a writer to write API request logs to. - // Default is no logging. + // Log specifies a writer to write API request logs to. Default is to respect the GH_DEBUG environment + // variable, and no logging otherwise. Log io.Writer - // LogIgnoreEnv disables respecting the GH_DEBUG environment variable for logging. + // LogIgnoreEnv disables respecting the GH_DEBUG environment variable. This can be useful in test mode + // or when the extension already offers its own controls for logging to the user. LogIgnoreEnv bool // LogColorize enables colorized logging to Log for display in a terminal. + // Default is no coloring. LogColorize bool - // LogVerboseHTTP enables logging HTTP headers and bodies. + // LogVerboseHTTP enables logging HTTP headers and bodies to Log. // Default is only logging request URLs and response statuses. LogVerboseHTTP bool