@@ -21,10 +21,12 @@ import (
2121 "fmt"
2222 "net/http"
2323 "net/http/httptrace"
24+ "sort"
2425 "strings"
2526 "sync"
2627 "time"
2728
29+ "github.com/go-logr/logr"
2830 "golang.org/x/oauth2"
2931
3032 utilnet "k8s.io/apimachinery/pkg/util/net"
@@ -68,19 +70,16 @@ func HTTPWrappersForConfig(config *Config, rt http.RoundTripper) (http.RoundTrip
6870 return rt , nil
6971}
7072
71- // DebugWrappers wraps a round tripper and logs based on the current log level.
73+ // DebugWrappers potentially wraps a round tripper with a wrapper that logs
74+ // based on the log level in the context of each individual request.
75+ //
76+ // At the moment, wrapping depends on the global log verbosity and is done
77+ // if that verbosity is >= 6. This may change in the future.
7278func DebugWrappers (rt http.RoundTripper ) http.RoundTripper {
73- switch {
74- case bool (klog .V (9 ).Enabled ()):
75- rt = NewDebuggingRoundTripper (rt , DebugCurlCommand , DebugURLTiming , DebugDetailedTiming , DebugResponseHeaders )
76- case bool (klog .V (8 ).Enabled ()):
77- rt = NewDebuggingRoundTripper (rt , DebugJustURL , DebugRequestHeaders , DebugResponseStatus , DebugResponseHeaders )
78- case bool (klog .V (7 ).Enabled ()):
79- rt = NewDebuggingRoundTripper (rt , DebugJustURL , DebugRequestHeaders , DebugResponseStatus )
80- case bool (klog .V (6 ).Enabled ()):
81- rt = NewDebuggingRoundTripper (rt , DebugURLTiming )
79+ //nolint:logcheck // The actual logging is done with a different logger, so only checking here is okay.
80+ if klog .V (6 ).Enabled () {
81+ rt = NewDebuggingRoundTripper (rt , DebugByContext )
8282 }
83-
8483 return rt
8584}
8685
@@ -380,14 +379,17 @@ func (r *requestInfo) toCurl() string {
380379 }
381380 }
382381
383- return fmt .Sprintf ("curl -v -X%s %s '%s'" , r .RequestVerb , headers , r .RequestURL )
382+ // Newline at the end makes this look better in the text log output (the
383+ // only usage of this method) because it becomes a multi-line string with
384+ // no quoting.
385+ return fmt .Sprintf ("curl -v -X%s %s '%s'\n " , r .RequestVerb , headers , r .RequestURL )
384386}
385387
386388// debuggingRoundTripper will display information about the requests passing
387389// through it based on what is configured
388390type debuggingRoundTripper struct {
389391 delegatedRoundTripper http.RoundTripper
390- levels map [ DebugLevel ] bool
392+ levels int
391393}
392394
393395var _ utilnet.RoundTripperWrapper = & debuggingRoundTripper {}
@@ -412,17 +414,36 @@ const (
412414 DebugResponseHeaders
413415 // DebugDetailedTiming will add to the debug output the duration of the HTTP requests events.
414416 DebugDetailedTiming
417+ // DebugByContext will add any of the above depending on the verbosity of the per-request logger obtained from the requests context.
418+ //
419+ // Can be combined in NewDebuggingRoundTripper with some of the other options, in which case the
420+ // debug roundtripper will always log what is requested there plus the information that gets
421+ // enabled by the context's log verbosity.
422+ DebugByContext
423+ )
424+
425+ // Different log levels include different sets of information.
426+ //
427+ // Not exported because the exact content of log messages is not part
428+ // of of the package API.
429+ const (
430+ levelsV6 = (1 << DebugURLTiming )
431+ // Logging *less* information for the response at level 7 compared to 6 replicates prior behavior:
432+ // https://github.com/kubernetes/kubernetes/blob/2b472fe4690c83a2b343995f88050b2a3e9ff0fa/staging/src/k8s.io/client-go/transport/round_trippers.go#L79
433+ // Presumably that was done because verb and URL are already in the request log entry.
434+ levelsV7 = (1 << DebugJustURL ) | (1 << DebugRequestHeaders ) | (1 << DebugResponseStatus )
435+ levelsV8 = (1 << DebugJustURL ) | (1 << DebugRequestHeaders ) | (1 << DebugResponseStatus ) | (1 << DebugResponseHeaders )
436+ levelsV9 = (1 << DebugCurlCommand ) | (1 << DebugURLTiming ) | (1 << DebugDetailedTiming ) | (1 << DebugResponseHeaders )
415437)
416438
417439// NewDebuggingRoundTripper allows to display in the logs output debug information
418440// on the API requests performed by the client.
419441func NewDebuggingRoundTripper (rt http.RoundTripper , levels ... DebugLevel ) http.RoundTripper {
420442 drt := & debuggingRoundTripper {
421443 delegatedRoundTripper : rt ,
422- levels : make (map [DebugLevel ]bool , len (levels )),
423444 }
424445 for _ , v := range levels {
425- drt .levels [ v ] = true
446+ drt .levels |= 1 << v
426447 }
427448 return drt
428449}
@@ -464,27 +485,51 @@ func maskValue(key string, value string) string {
464485}
465486
466487func (rt * debuggingRoundTripper ) RoundTrip (req * http.Request ) (* http.Response , error ) {
488+ logger := klog .FromContext (req .Context ())
489+ levels := rt .levels
490+
491+ // When logging depends on the context, it uses the verbosity of the per-context logger
492+ // and a hard-coded mapping of verbosity to debug details. Otherwise all messages
493+ // are logged as V(0).
494+ if levels & (1 << DebugByContext ) != 0 {
495+ if loggerV := logger .V (9 ); loggerV .Enabled () {
496+ logger = loggerV
497+ // The curl command replaces logging of the URL.
498+ levels |= levelsV9
499+ } else if loggerV := logger .V (8 ); loggerV .Enabled () {
500+ logger = loggerV
501+ levels |= levelsV8
502+ } else if loggerV := logger .V (7 ); loggerV .Enabled () {
503+ logger = loggerV
504+ levels |= levelsV7
505+ } else if loggerV := logger .V (6 ); loggerV .Enabled () {
506+ logger = loggerV
507+ levels |= levelsV6
508+ }
509+ }
510+
467511 reqInfo := newRequestInfo (req )
468512
469- if rt .levels [DebugJustURL ] {
470- klog .Infof ("%s %s" , reqInfo .RequestVerb , reqInfo .RequestURL )
513+ kvs := make ([]any , 0 , 8 ) // Exactly large enough for all appends below.
514+ if levels & (1 << DebugJustURL ) != 0 {
515+ kvs = append (kvs ,
516+ "verb" , reqInfo .RequestVerb ,
517+ "url" , reqInfo .RequestURL ,
518+ )
471519 }
472- if rt . levels [ DebugCurlCommand ] {
473- klog . Infof ( "%s "reqInfo .toCurl ())
520+ if levels & ( 1 << DebugCurlCommand ) != 0 {
521+ kvs = append ( kvs , "curlCommand "reqInfo .toCurl ())
474522 }
475- if rt .levels [DebugRequestHeaders ] {
476- klog .Info ("Request Headers:" )
477- for key , values := range reqInfo .RequestHeaders {
478- for _ , value := range values {
479- value = maskValue (key , value )
480- klog .Infof (" %s: %s" , key , value )
481- }
482- }
523+ if levels & (1 << DebugRequestHeaders ) != 0 {
524+ kvs = append (kvs , "headers" , newHeadersMap (reqInfo .RequestHeaders ))
525+ }
526+ if len (kvs ) > 0 {
527+ logger .Info ("Request" , kvs ... )
483528 }
484529
485530 startTime := time .Now ()
486531
487- if rt . levels [ DebugDetailedTiming ] {
532+ if levels & ( 1 << DebugDetailedTiming ) != 0 {
488533 var getConn , dnsStart , dialStart , tlsStart , serverStart time.Time
489534 var host string
490535 trace := & httptrace.ClientTrace {
@@ -499,7 +544,7 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
499544 reqInfo .muTrace .Lock ()
500545 defer reqInfo .muTrace .Unlock ()
501546 reqInfo .DNSLookup = time .Since (dnsStart )
502- klog . Infof ("HTTP Trace: DNS Lookup for %s resolved to %v" , host , info .Addrs )
547+ logger . Info ("HTTP Trace: DNS Lookup resolved" , "host" , host , "address" , info .Addrs )
503548 },
504549 // Dial
505550 ConnectStart : func (network , addr string ) {
@@ -512,9 +557,9 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
512557 defer reqInfo .muTrace .Unlock ()
513558 reqInfo .Dialing = time .Since (dialStart )
514559 if err != nil {
515- klog . Infof ("HTTP Trace: Dial to %s:%s failed: %v" , network , addr , err )
560+ logger . Info ("HTTP Trace: Dial failed" , "network" , network , "address" , addr , "err" , err )
516561 } else {
517- klog . Infof ("HTTP Trace: Dial to %s:%s succeed" , network , addr )
562+ logger . Info ("HTTP Trace: Dial succeed" , " network" , network , "address" , addr )
518563 }
519564 },
520565 // TLS
@@ -556,40 +601,83 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
556601
557602 reqInfo .complete (response , err )
558603
559- if rt .levels [DebugURLTiming ] {
560- klog .Infof ("%s %s %s in %d milliseconds" , reqInfo .RequestVerb , reqInfo .RequestURL , reqInfo .ResponseStatus , reqInfo .Duration .Nanoseconds ()/ int64 (time .Millisecond ))
604+ kvs = make ([]any , 0 , 20 ) // Exactly large enough for all appends below.
605+ if levels & (1 << DebugURLTiming ) != 0 {
606+ kvs = append (kvs , "verb" , reqInfo .RequestVerb , "url" , reqInfo .RequestURL )
607+ }
608+ if levels & (1 << DebugURLTiming | 1 << DebugResponseStatus ) != 0 {
609+ kvs = append (kvs , "status" , reqInfo .ResponseStatus )
610+ }
611+ if levels & (1 << DebugResponseHeaders ) != 0 {
612+ kvs = append (kvs , "headers" , newHeadersMap (reqInfo .ResponseHeaders ))
613+ }
614+ if levels & (1 << DebugURLTiming | 1 << DebugDetailedTiming | 1 << DebugResponseStatus ) != 0 {
615+ kvs = append (kvs , "milliseconds" , reqInfo .Duration .Nanoseconds ()/ int64 (time .Millisecond ))
561616 }
562- if rt .levels [DebugDetailedTiming ] {
563- stats := ""
617+ if levels & (1 << DebugDetailedTiming ) != 0 {
564618 if ! reqInfo .ConnectionReused {
565- stats += fmt . Sprintf ( `DNSLookup %d ms Dial %d ms TLSHandshake %d ms` ,
566- reqInfo .DNSLookup .Nanoseconds ()/ int64 (time .Millisecond ),
567- reqInfo .Dialing .Nanoseconds ()/ int64 (time .Millisecond ),
568- reqInfo .TLSHandshake .Nanoseconds ()/ int64 (time .Millisecond ),
619+ kvs = append ( kvs ,
620+ "dnsLookupMilliseconds" , reqInfo .DNSLookup .Nanoseconds ()/ int64 (time .Millisecond ),
621+ "dialMilliseconds" , reqInfo .Dialing .Nanoseconds ()/ int64 (time .Millisecond ),
622+ "tlsHandshakeMilliseconds" , reqInfo .TLSHandshake .Nanoseconds ()/ int64 (time .Millisecond ),
569623 )
570624 } else {
571- stats += fmt . Sprintf ( `GetConnection %d ms` , reqInfo .GetConnection .Nanoseconds ()/ int64 (time .Millisecond ))
625+ kvs = append ( kvs , "getConnectionMilliseconds" , reqInfo .GetConnection .Nanoseconds ()/ int64 (time .Millisecond ))
572626 }
573627 if reqInfo .ServerProcessing != 0 {
574- stats += fmt . Sprintf ( ` ServerProcessing %d ms` , reqInfo .ServerProcessing .Nanoseconds ()/ int64 (time .Millisecond ))
628+ kvs = append ( kvs , "serverProcessingMilliseconds" , reqInfo .ServerProcessing .Nanoseconds ()/ int64 (time .Millisecond ))
575629 }
576- stats += fmt .Sprintf (` Duration %d ms` , reqInfo .Duration .Nanoseconds ()/ int64 (time .Millisecond ))
577- klog .Infof ("HTTP Statistics: %s" , stats )
578630 }
631+ if len (kvs ) > 0 {
632+ logger .Info ("Response" , kvs ... )
633+ }
634+
635+ return response , err
636+ }
579637
580- if rt .levels [DebugResponseStatus ] {
581- klog .Infof ("Response Status: %s in %d milliseconds" , reqInfo .ResponseStatus , reqInfo .Duration .Nanoseconds ()/ int64 (time .Millisecond ))
638+ // headerMap formats headers sorted and across multiple lines with no quoting
639+ // when using string output and as JSON when using zapr.
640+ type headersMap http.Header
641+
642+ // newHeadersMap masks all sensitive values. This has to be done before
643+ // passing the map to a logger because while in practice all loggers
644+ // either use String or MarshalLog, that is not guaranteed.
645+ func newHeadersMap (header http.Header ) headersMap {
646+ h := make (headersMap , len (header ))
647+ for key , values := range header {
648+ maskedValues := make ([]string , 0 , len (values ))
649+ for _ , value := range values {
650+ maskedValues = append (maskedValues , maskValue (key , value ))
651+ }
652+ h [key ] = maskedValues
582653 }
583- if rt .levels [DebugResponseHeaders ] {
584- klog .Info ("Response Headers:" )
585- for key , values := range reqInfo .ResponseHeaders {
586- for _ , value := range values {
587- klog .Infof (" %s: %s" , key , value )
588- }
654+ return h
655+ }
656+
657+ var _ fmt.Stringer = headersMap {}
658+ var _ logr.Marshaler = headersMap {}
659+
660+ func (h headersMap ) String () string {
661+ // The fixed size typically avoids memory allocations when it is large enough.
662+ keys := make ([]string , 0 , 20 )
663+ for key := range h {
664+ keys = append (keys , key )
665+ }
666+ sort .Strings (keys )
667+ var buffer strings.Builder
668+ for _ , key := range keys {
669+ for _ , value := range h [key ] {
670+ _ , _ = buffer .WriteString (key )
671+ _ , _ = buffer .WriteString (": " )
672+ _ , _ = buffer .WriteString (value )
673+ _ , _ = buffer .WriteString ("\n " )
589674 }
590675 }
676+ return buffer .String ()
677+ }
591678
592- return response , err
679+ func (h headersMap ) MarshalLog () any {
680+ return map [string ][]string (h )
593681}
594682
595683func (rt * debuggingRoundTripper ) WrappedRoundTripper () http.RoundTripper {
0 commit comments