Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Expand logging support for HTTP traffic #60

Merged
merged 7 commits into from Aug 10, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
14 changes: 8 additions & 6 deletions internal/api/cache_test.go
Expand Up @@ -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) {
Expand Down Expand Up @@ -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) {
Expand Down
31 changes: 23 additions & 8 deletions internal/api/http.go
Expand Up @@ -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"
)
Expand Down Expand Up @@ -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) {
Expand All @@ -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 {
Expand Down
1 change: 1 addition & 0 deletions internal/api/http_test.go
Expand Up @@ -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
Expand Down
47 changes: 47 additions & 0 deletions 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)
}
16 changes: 14 additions & 2 deletions pkg/api/client.go
Expand Up @@ -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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

After thinking about this more, I am not sure that this option is necessary. I understand its purpose, but can't think of a good use case where we want to allow an extension author to ignore GH_DEBUG.

Additionally, I think our users would find the behavior of this option a bit confusing without further comments describing its behavior.

Copy link
Contributor Author

@mislav mislav Aug 9, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

After thinking about this more, I am not sure that this option is necessary. I understand its purpose, but can't think of a good use case where we want to allow an extension author to ignore GH_DEBUG.

Thanks for chiming in. One consumer of go-gh that wants to use this option is the CLI itself, since GitHub CLI already parses environment variables itself and wants to prevent underlying libraries to parse the same environment variables, lest some inconsistencies or conflicts arise.

Additionally, an extension author might want to disable env-controlled logging if it already offers the user granular controls for logging.

As a general rule of thumb, if a generic Go library automatically respects environment variables, it's a good idea to offer a way for the consumer of said library to skip respecting environment variables in cases where that is not desired. At the end of the day, environment variables are essentially global variables shared across modules and even processes, and to mitigate their potential harms, developers should have ways to put up boundaries to limit the propagation (or effect) of these variables.

I have added some extra documentation detailing this configuration option.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That all makes sense to me, my only thought was that if an extension author wanted to ignore GH_DEBUG they could provide a value for the Log option making LogIgnoreEnv feel a bit redundant.


// LogColorize enables colorized logging to Log for display in a terminal.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
// LogColorize enables colorized logging to Log for display in a terminal.
// LogColorize enables colorized logging to Log for display in a terminal.
// Default is no coloring.

With the comments I have been trying to describe the default state for each options as I generally find it useful when I look at documentation.

// 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

Expand Down
144 changes: 144 additions & 0 deletions pkg/jsonpretty/format.go
@@ -0,0 +1,144 @@
// Package jsonpretty implements a terminal pretty-printer for JSON.
package jsonpretty
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we want this package to be exported? If so, can we add a comment to the top here describing the purpose and functionality of the package?


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
}