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 2 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
1 change: 1 addition & 0 deletions go.mod
Expand Up @@ -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
Expand Down
1 change: 1 addition & 0 deletions go.sum
Expand Up @@ -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=
Expand Down
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
39 changes: 31 additions & 8 deletions internal/api/http.go
Expand Up @@ -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 (
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 = !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) {
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 Expand Up @@ -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"
}
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)
}
9 changes: 9 additions & 0 deletions pkg/api/client.go
Expand Up @@ -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
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.

LogColorize bool

// LogVerboseHTTP enables logging HTTP headers and bodies.
mislav marked this conversation as resolved.
Show resolved Hide resolved
LogVerboseHTTP bool

// SkipDefaultHeaders disables setting of the default headers.
SkipDefaultHeaders bool

Expand Down
143 changes: 143 additions & 0 deletions pkg/jsonpretty/format.go
@@ -0,0 +1,143 @@
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
}