Skip to content

impr(verbose): using package httpretty to log requests on DEBUG.#306

Merged
mislav merged 3 commits into
cli:masterfrom
henvic:feat/debug-req
Feb 21, 2020
Merged

impr(verbose): using package httpretty to log requests on DEBUG.#306
mislav merged 3 commits into
cli:masterfrom
henvic:feat/debug-req

Conversation

@henvic

@henvic henvic commented Feb 5, 2020

Copy link
Copy Markdown
Contributor

Hi, a few days ago I released this package called httpretty that I think would be useful for debugging the GitHub CLI instead of the burden of dealing with it directly.

asciicast

What do you think about it? If you like the idea, I probably need to add support for skipping content so that the inspectableMIMEType can still be used.

btw, I was the main maintainer of NodeGH for a while (written using NodeJS years ago) but I've since moved to Go (and spent a quite a while working with Go + cobra + git for deployments), and I'm really excited seeing this CLI written in Go o/ :)

Feel free to ask anything!

@vilmibm vilmibm self-assigned this Feb 5, 2020
@vilmibm vilmibm self-requested a review February 5, 2020 19:00
@vilmibm

vilmibm commented Feb 5, 2020

Copy link
Copy Markdown
Contributor

Thanks, it's intriguing! Can you talk about why enabling -race was necessary for go test? We don't currently have concurrency concerns in gh but I see that httpretty seems to (at least based on the tests).

@henvic

henvic commented Feb 6, 2020

Copy link
Copy Markdown
Contributor Author

Hi @vilmibm,

I think I created confusion by sending both commits on the same pull-request. They were to be intended to be on separate pull-requests.

The concurrency concerns on httpretty involve mostly two things:

  • When using it on the server-side, it might receive more than one connection concurrently
  • While on client-side code you usually do a single request at a time, you might eventually require to do multiple requests using multiple goroutines (like, imagine when you deploy several services and want to watch the status of three of them that might be ready upon any order).

It's a good practice to always add -race when running Go test because it makes it easier to identify sooner than later data race conditions that can cause unexpected behavior on your code. On my previous CLI project, I took me quite until I finally found and read Introducing the Go Race Detector to notice the importance of this tool, and when I finally did (months later), there were quite a few data race conditions (progress bar, buffers read/wrote on different goroutines, etc.). It's cheaper to be preventive, at an acceptable test duration cost (say, instead of the test suite taking 3s, it might take 12s).

One important thing to realize is that the data race detector isn't deterministic, so one thing I usually do when I work on something that is more risky is to run this command I have as a alias to gotestloop:

#!/bin/bash

set -euo pipefail
IFS=$'\n\t'
ARGS=${1:-""}
counter=0

while true
do
	counter=$((counter+1))
	go test $(go list ./... | grep -v /vendor/) -count=1 $ARGS # count=1 is a bypass to test caching

	if [ $counter -eq 1 ] ; then
		echo "$counter time"
	else
		echo "$counter times"
	fi
done

and to quickly run the binary with data race condition in a straight-forward way, I have an alias to something else, like a single-letter g:

#!/bin/bash

set -euo pipefail
IFS=$'\n\t'

cd $GOPATH/src/github.com/cli/cli/cmd/gh
go install -race
cd ~- # cd without printing

Thanks to this I can just save a file and immediately run a command.

Say, instead of gh issue list, I can run something like g issue list or gx issue list. If modified files are found, it will recompile. Otherwise, it's going to use the cached version. And the -race flag gives me some comfort of mind to know it's going to complain a lot when a data race is detected, and the way the detector is built means there are no false positives.

PS: There is a currently data race condition affecting everyone using net/http in Go doing concurrent requests, but it shouldn't be cause for concern for this pull-request because it's already affecting everyone: net/http: data race when response is returned before the full request's body is written #30597

@vilmibm vilmibm left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

I was aware of the race detector and its importance; I was just confused as to whether or not your commit adding it was related to using httpretty.

I definitely like the httpretty output! If you could split out the -race commit into another PR and then restore parity with inspectableMIMEType I'd be happy to merge 👍

@mislav mislav left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Hi, this looks great! Some feedback:

  • Blocking: TLS info (somewhat noisy) is printed even with TLS: false
  • Blocking: please remove the changes to our test runner
  • Minor: not all request headers seem printed with RequestHeader: true
  • Nice-to-have: a way to avoid certain request/response headers being printed; perhaps accept a func that takes a header name and returns a boolean that indicates whether to print or not?

Thank you for this tool!

@henvic

henvic commented Feb 21, 2020

Copy link
Copy Markdown
Contributor Author

Hi,

@vilmibm, I have restored parity with inspectableMIMEType by adding a body filter.

@mislav, thanks for letting me know about the issue on the TLS param. I just noticed after your comment. Fixed it.

Regarding some headers not being printed it's because the VerboseLog middleware is added after, say, Authorization, User-Agent, Accept, and other headers (that are being added in a middleware manner right now).

I see two options: we can move it to the front or leave as is. If we move it to the front, these headers will be added (Authorization would be sanitized, though). Besides all this, the Go standard library might add headers (such as the User-Agent, if you don't set one), and httpretty currently doesn't have a mode to display it (but I intend to have).

I'll also open an issue to remember about doing a function to easily control unwanted headers.

Something else that might be a good idea: color support. Right now, the util/color doesn't expose a way I can check to set the Colors field, and this would be neat.

- log headers only in DEBUG=api mode
- enable color output on stderr
- hide little-useful TLS debbuging info
- ensure all request headers are logged

@mislav mislav left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Thank you! I've moved middleware around and added color support.

One more small feature request for the future: we'd like to define our own formatter for GraphQL requests (basically, make a more specialized JSON formatter for GraphQL), but the current interface for a Formatter allows only matching per mime type, which for GraphQL requests is always application/json. Since the formatter doesn't have access to other information about a request, such as request path, we cannot distinguish GraphQL requests from other JSON requests.

@mislav mislav merged commit 1eff7c1 into cli:master Feb 21, 2020
@henvic

henvic commented Feb 22, 2020

Copy link
Copy Markdown
Contributor Author

Thanks, @mislav.

I'm trying to think about what other signature Match could have (and more importantly, what could go inside). Or maybe Match could be gone and a special error value used to indicate matching errors and skip to the next formatter.

Would something like this be an okay-ish tradeoff for now?

// GraphQLFormatter helps you read unreadable GraphQL queries,
// with fallback to regular JSON documents.
type GraphQLFormatter struct {
	j httpretty.JSONFormatter
}

// Match JSON media type.
func (g *GraphQLFormatter) Match(mediatype string) bool {
	return g.j.Match(mediatype)
}

// Format GraphQL query, falling back to JSON if GraphQL is not identified.
func (g *GraphQLFormatter) Format(dst *bytes.Buffer, src []byte) (err error) {
	if e := g.j.Format(dst, src); e != nil {
		return e
	}

	src = dst.Bytes() // dst here isn't empty and holds JSON formatted output

	if isGraphQL(src) {
		return nil
	}

	defer func() {
		if err != nil {
			dst.Reset()
			// clear returned error to get JSON pretty-printed, but print error feedback:
			fmt.Fprintf(dst, "* cannot format GraphQL: %v\n", err)
			dst.Write(src)
			err = nil
		}
	}()

	dst.Reset()
	return formatGraphQL(dst, src)
}
  • isGraphQL perhaps should be using heuristics to verify if it looks like a GraphQL? Maybe just check the beginning of the query instead of everything? (I don't have much experience with GraphQL)
  • formatGraphQL does the formatting.

@mislav

mislav commented Feb 22, 2020

Copy link
Copy Markdown
Contributor

Ideally, I wanted to detect GraphQL requests based on their request URI, not the JSON contents. But it's possible to detect them using JSON contents; a GraphQL payload usually has only query and variables top-level keys.

Another thing that surprised me: that Format() signature writes into *bytes.Buffer instead of accepting an io.Writer. I think the latter would be more flexible.

@vilmibm vilmibm removed their assignment Mar 2, 2020
Stonre pushed a commit to Stonre/strands-fork that referenced this pull request Jul 21, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants