From d7a6f56a7b3b2f7fc84f3d837e584eb5e5eb439b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mislav=20Marohni=C4=87?= Date: Wed, 10 Aug 2022 10:58:47 +0200 Subject: [PATCH] Expand logging support for HTTP traffic (#60) 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. Co-authored-by: Sam Coe --- internal/api/cache_test.go | 14 ++-- internal/api/http.go | 31 ++++++-- internal/api/http_test.go | 1 + internal/api/log_formatter.go | 47 +++++++++++ pkg/api/client.go | 16 +++- pkg/jsonpretty/format.go | 144 ++++++++++++++++++++++++++++++++++ pkg/jsonpretty/format_test.go | 96 +++++++++++++++++++++++ pkg/term/env.go | 13 +-- 8 files changed, 341 insertions(+), 21 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/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..cb0936b 100644 --- a/internal/api/http.go +++ b/internal/api/http.go @@ -12,6 +12,7 @@ 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" ) @@ -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 = !term.IsColorDisabled() && term.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 { 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..26d1a82 --- /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..96909e1 100644 --- a/pkg/api/client.go +++ b/pkg/api/client.go @@ -34,10 +34,22 @@ 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. 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 to Log. + // Default is only logging request URLs and response statuses. + 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..63ac972 --- /dev/null +++ b/pkg/jsonpretty/format.go @@ -0,0 +1,144 @@ +// Package jsonpretty implements a terminal pretty-printer for JSON. +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) + } + }) + } +} 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" }