client-go: export NewDebuggingRoundTripper function and DebugLevel

`debuggingRoundTripper` is a useful throbleshooting tool to debug of Kubernetes API requests and their timing.

Unfortunately, as of today, it can only be used via the `DebugWrappers` function, which automatically adjust the amount of debug information exposed by the roundTripper based on the configured `klog` verbosity.

While `DebugWrappers` definitely fits the purpose for clients using `klog`, this is currently hard to be used for controllers using `controller-runtime`, which uses `github.com/go-logr/logr` for logging.

In this PR we change the visibility of `newDebuggingRoundTripper` and `debugLevel` in order to be directly accessible from users of the `k8s.io/client-go/transport` package.

In particular, the changes proposed in this PR allow users of `controller-runtime` to use the `debuggingRoundTripper` to intercept Kubernetes API requests as follows

```go
import (
        ctrl "sigs.k8s.io/controller-runtime"
)

func init() {
	ctrl.SetLogger(zap.New())
}

func main() {
        // wrap the http transport used by the Kubernetes client
	restConfig, err := ctrl.GetConfig()
	checkError(setupLog, err, "unable to get kubernetes client config")

        restConfig.Wrap(func(rt http.RoundTripper) http.RoundTripper {
		return transport.NewDebuggingRoundTripper(rt, transport.DebugJustURL)
	})

        ...
}
```
This commit is contained in:
Andrea Tosatto 2021-01-22 14:57:14 +01:00
parent 82ebcd1719
commit 8de53ce96c
2 changed files with 133 additions and 22 deletions

View File

@ -68,13 +68,13 @@ func HTTPWrappersForConfig(config *Config, rt http.RoundTripper) (http.RoundTrip
func DebugWrappers(rt http.RoundTripper) http.RoundTripper {
switch {
case bool(klog.V(9).Enabled()):
rt = newDebuggingRoundTripper(rt, debugCurlCommand, debugURLTiming, debugResponseHeaders)
rt = NewDebuggingRoundTripper(rt, DebugCurlCommand, DebugURLTiming, DebugResponseHeaders)
case bool(klog.V(8).Enabled()):
rt = newDebuggingRoundTripper(rt, debugJustURL, debugRequestHeaders, debugResponseStatus, debugResponseHeaders)
rt = NewDebuggingRoundTripper(rt, DebugJustURL, DebugRequestHeaders, DebugResponseStatus, DebugResponseHeaders)
case bool(klog.V(7).Enabled()):
rt = newDebuggingRoundTripper(rt, debugJustURL, debugRequestHeaders, debugResponseStatus)
rt = NewDebuggingRoundTripper(rt, DebugJustURL, DebugRequestHeaders, DebugResponseStatus)
case bool(klog.V(6).Enabled()):
rt = newDebuggingRoundTripper(rt, debugURLTiming)
rt = NewDebuggingRoundTripper(rt, DebugURLTiming)
}
return rt
@ -353,25 +353,35 @@ func (r *requestInfo) toCurl() string {
// through it based on what is configured
type debuggingRoundTripper struct {
delegatedRoundTripper http.RoundTripper
levels map[debugLevel]bool
levels map[DebugLevel]bool
}
type debugLevel int
// DebugLevel is used to enable debugging of certain
// HTTP requests and responses fields via the debuggingRoundTripper.
type DebugLevel int
const (
debugJustURL debugLevel = iota
debugURLTiming
debugCurlCommand
debugRequestHeaders
debugResponseStatus
debugResponseHeaders
// DebugJustURL will add to the debug output HTTP requests method and url.
DebugJustURL DebugLevel = iota
// DebugURLTiming will add to the debug output the duration of HTTP requests.
DebugURLTiming
// DebugCurlCommand will add to the debug output the curl command equivalent to the
// HTTP request.
DebugCurlCommand
// DebugRequestHeaders will add to the debug output the HTTP requests headers.
DebugRequestHeaders
// DebugResponseStatus will add to the debug output the HTTP response status.
DebugResponseStatus
// DebugResponseHeaders will add to the debug output the HTTP response headers.
DebugResponseHeaders
)
func newDebuggingRoundTripper(rt http.RoundTripper, levels ...debugLevel) *debuggingRoundTripper {
// NewDebuggingRoundTripper allows to display in the logs output debug information
// on the API requests performed by the client.
func NewDebuggingRoundTripper(rt http.RoundTripper, levels ...DebugLevel) *debuggingRoundTripper {
drt := &debuggingRoundTripper{
delegatedRoundTripper: rt,
levels: make(map[debugLevel]bool, len(levels)),
levels: make(map[DebugLevel]bool, len(levels)),
}
for _, v := range levels {
drt.levels[v] = true
@ -418,14 +428,13 @@ func maskValue(key string, value string) string {
func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
reqInfo := newRequestInfo(req)
if rt.levels[debugJustURL] {
if rt.levels[DebugJustURL] {
klog.Infof("%s %s", reqInfo.RequestVerb, reqInfo.RequestURL)
}
if rt.levels[debugCurlCommand] {
if rt.levels[DebugCurlCommand] {
klog.Infof("%s", reqInfo.toCurl())
}
if rt.levels[debugRequestHeaders] {
if rt.levels[DebugRequestHeaders] {
klog.Info("Request Headers:")
for key, values := range reqInfo.RequestHeaders {
for _, value := range values {
@ -441,13 +450,13 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
reqInfo.complete(response, err)
if rt.levels[debugURLTiming] {
if rt.levels[DebugURLTiming] {
klog.Infof("%s %s %s in %d milliseconds", reqInfo.RequestVerb, reqInfo.RequestURL, reqInfo.ResponseStatus, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond))
}
if rt.levels[debugResponseStatus] {
if rt.levels[DebugResponseStatus] {
klog.Infof("Response Status: %s in %d milliseconds", reqInfo.ResponseStatus, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond))
}
if rt.levels[debugResponseHeaders] {
if rt.levels[DebugResponseHeaders] {
klog.Info("Response Headers:")
for key, values := range reqInfo.ResponseHeaders {
for _, value := range values {

View File

@ -17,6 +17,9 @@ limitations under the License.
package transport
import (
"bytes"
"fmt"
"k8s.io/klog/v2"
"net/http"
"net/url"
"reflect"
@ -412,3 +415,102 @@ func TestHeaderEscapeRoundTrip(t *testing.T) {
})
}
}
func TestDebuggingRoundTripper(t *testing.T) {
t.Parallel()
rawUrl := "https://127.0.0.1:12345/api/v1/pods?limit=500"
req := &http.Request{
Method: http.MethodGet,
Header: map[string][]string{
"Authorization": []string{"bearer secretauthtoken"},
"X-Test-Request": []string{"test"},
},
}
res := &http.Response{
Status: "OK",
StatusCode: http.StatusOK,
Header: map[string][]string{
"X-Test-Response": []string{"test"},
},
}
tcs := []struct {
levels []DebugLevel
expectedOutputLines []string
}{
{
levels: []DebugLevel{DebugJustURL},
expectedOutputLines: []string{fmt.Sprintf("%s %s", req.Method, rawUrl)},
},
{
levels: []DebugLevel{DebugRequestHeaders},
expectedOutputLines: func() []string {
lines := []string{fmt.Sprintf("Request Headers:\n")}
for key, values := range req.Header {
for _, value := range values {
if key == "Authorization" {
value = "bearer <masked>"
}
lines = append(lines, fmt.Sprintf(" %s: %s\n", key, value))
}
}
return lines
}(),
},
{
levels: []DebugLevel{DebugResponseHeaders},
expectedOutputLines: func() []string {
lines := []string{fmt.Sprintf("Response Headers:\n")}
for key, values := range res.Header {
for _, value := range values {
lines = append(lines, fmt.Sprintf(" %s: %s\n", key, value))
}
}
return lines
}(),
},
{
levels: []DebugLevel{DebugURLTiming},
expectedOutputLines: []string{fmt.Sprintf("%s %s %s", req.Method, rawUrl, res.Status)},
},
{
levels: []DebugLevel{DebugResponseStatus},
expectedOutputLines: []string{fmt.Sprintf("Response Status: %s", res.Status)},
},
{
levels: []DebugLevel{DebugCurlCommand},
expectedOutputLines: []string{fmt.Sprintf("curl -k -v -X")},
},
}
for _, tc := range tcs {
// hijack the klog output
tmpWriteBuffer := bytes.NewBuffer(nil)
klog.SetOutput(tmpWriteBuffer)
klog.LogToStderr(false)
// parse rawUrl
parsedUrl, err := url.Parse(rawUrl)
if err != nil {
t.Fatalf("url.Parse(%q) returned error: %v", rawUrl, err)
}
req.URL = parsedUrl
// execute the round tripper
rt := &testRoundTripper{
Response: res,
}
NewDebuggingRoundTripper(rt, tc.levels...).RoundTrip(req)
// call Flush to ensure the text isn't still buffered
klog.Flush()
// check if klog's output contains the expected lines
actual := tmpWriteBuffer.String()
for _, expected := range tc.expectedOutputLines {
if !strings.Contains(actual, expected) {
t.Errorf("%q does not contain expected output %q", actual, expected)
}
}
}
}