mirror of
https://github.com/kubernetes/client-go.git
synced 2025-09-18 08:09:40 +00:00
client-go/transport: structured, contextual logging
The revised logging emits one log entry at the start of
round-tripping ("Request") and another at the end ("Response"). This avoids the
risk that related output gets interleaved by other output.
No API changes are necessary. A contextual logger is picked up from the context
of the request that is being handled. The verbosity level of that logger is
checked to determine what is supposed to be logged. This enables reducing log
details on a by-request basis by storing a `logger.V(1)` in the context of the
request.
As before, logging only gets injected into request processing at -v6 or higher,
so normally there is no additional overhead.
Kubernetes-commit: a85f489b28d3b0ef82dffb267b6145c73c2d0e33
This commit is contained in:
Patrick Ohly
committed by
Kubernetes Publisher
Kubernetes Publisher
parent
ce24f3c462
commit
82fcce0646
20
go.mod
20
go.mod
@@ -9,6 +9,7 @@ godebug default=go1.23
|
||||
godebug winsymlink=0
|
||||
|
||||
require (
|
||||
github.com/go-logr/logr v1.4.2
|
||||
github.com/gogo/protobuf v1.3.2
|
||||
github.com/google/gnostic-models v0.6.9
|
||||
github.com/google/go-cmp v0.6.0
|
||||
@@ -21,14 +22,14 @@ require (
|
||||
github.com/spf13/pflag v1.0.5
|
||||
github.com/stretchr/testify v1.9.0
|
||||
go.uber.org/goleak v1.3.0
|
||||
golang.org/x/net v0.33.0
|
||||
golang.org/x/net v0.30.0
|
||||
golang.org/x/oauth2 v0.23.0
|
||||
golang.org/x/term v0.27.0
|
||||
golang.org/x/time v0.7.0
|
||||
google.golang.org/protobuf v1.35.1
|
||||
gopkg.in/evanphx/json-patch.v4 v4.12.0
|
||||
k8s.io/api v0.0.0-20250124010721-4dccc5e86b95
|
||||
k8s.io/apimachinery v0.0.0-20250125235321-4c615911e2cb
|
||||
k8s.io/api v0.0.0
|
||||
k8s.io/apimachinery v0.0.0
|
||||
k8s.io/klog/v2 v2.130.1
|
||||
k8s.io/kube-openapi v0.0.0-20241212222426-2c72e554b1e7
|
||||
k8s.io/utils v0.0.0-20241104100929-3ea5e8cea738
|
||||
@@ -38,15 +39,14 @@ require (
|
||||
)
|
||||
|
||||
require (
|
||||
github.com/davecgh/go-spew v1.1.1 // indirect
|
||||
github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc // indirect
|
||||
github.com/emicklei/go-restful/v3 v3.11.0 // indirect
|
||||
github.com/fxamacker/cbor/v2 v2.7.0 // indirect
|
||||
github.com/go-logr/logr v1.4.2 // indirect
|
||||
github.com/go-openapi/jsonpointer v0.21.0 // indirect
|
||||
github.com/go-openapi/jsonreference v0.20.2 // indirect
|
||||
github.com/go-openapi/swag v0.23.0 // indirect
|
||||
github.com/go-task/slim-sprig/v3 v3.0.0 // indirect
|
||||
github.com/google/btree v1.1.3 // indirect
|
||||
github.com/google/btree v1.0.1 // indirect
|
||||
github.com/google/pprof v0.0.0-20241029153458-d1b30febd7db // indirect
|
||||
github.com/josharian/intern v1.0.0 // indirect
|
||||
github.com/json-iterator/go v1.1.12 // indirect
|
||||
@@ -57,8 +57,7 @@ require (
|
||||
github.com/mxk/go-flowrate v0.0.0-20140419014527-cca7078d478f // indirect
|
||||
github.com/onsi/ginkgo/v2 v2.21.0 // indirect
|
||||
github.com/pkg/errors v0.9.1 // indirect
|
||||
github.com/pmezard/go-difflib v1.0.0 // indirect
|
||||
github.com/stretchr/objx v0.5.2 // indirect
|
||||
github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 // indirect
|
||||
github.com/x448/float16 v0.8.4 // indirect
|
||||
golang.org/x/sys v0.28.0 // indirect
|
||||
golang.org/x/text v0.21.0 // indirect
|
||||
@@ -66,3 +65,8 @@ require (
|
||||
gopkg.in/inf.v0 v0.9.1 // indirect
|
||||
gopkg.in/yaml.v3 v3.0.1 // indirect
|
||||
)
|
||||
|
||||
replace (
|
||||
k8s.io/api => ../api
|
||||
k8s.io/apimachinery => ../apimachinery
|
||||
)
|
||||
|
||||
30
go.sum
30
go.sum
@@ -1,9 +1,13 @@
|
||||
cloud.google.com/go/compute/metadata v0.3.0/go.mod h1:zFmK7XCadkQkj6TtorcaGlCW1hT1fIilQDwofLpJ20k=
|
||||
github.com/NYTimes/gziphandler v1.1.1/go.mod h1:n/CVRwUEOgIxrgPvAQhUUr9oeUtvrhMomdKFjzJNB0c=
|
||||
github.com/armon/go-socks5 v0.0.0-20160902184237-e75332964ef5 h1:0CwZNZbxp69SHPdPJAN/hZIm0C4OItdklCFmMRWYpio=
|
||||
github.com/armon/go-socks5 v0.0.0-20160902184237-e75332964ef5/go.mod h1:wHh0iHkYZB8zMSxRWpUBQtwG5a7fFgvEO+odwuTv2gs=
|
||||
github.com/chzyer/readline v1.5.1/go.mod h1:Eh+b79XXUwfKfcPLepksvw2tcLE/Ct21YObkaSkeBlk=
|
||||
github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
|
||||
github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
|
||||
github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
|
||||
github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
|
||||
github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc h1:U9qPSI2PIWSS1VwoXQT9A3Wy9MM3WgvqSxFWenqJduM=
|
||||
github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
|
||||
github.com/emicklei/go-restful/v3 v3.11.0 h1:rAQeMHw1c7zTmncogyy8VvRZwtkmkZ4FxERmMY4rD+g=
|
||||
github.com/emicklei/go-restful/v3 v3.11.0/go.mod h1:6n3XBCmQQb25CM2LCACGz8ukIrRry+4bhvbpWn3mrbc=
|
||||
github.com/fxamacker/cbor/v2 v2.7.0 h1:iM5WgngdRBanHcxugY4JySA0nk1wZorNOpTgCMedv5E=
|
||||
@@ -22,8 +26,9 @@ github.com/go-task/slim-sprig/v3 v3.0.0 h1:sUs3vkvUymDpBKi3qH1YSqBQk9+9D/8M2mN1v
|
||||
github.com/go-task/slim-sprig/v3 v3.0.0/go.mod h1:W848ghGpv3Qj3dhTPRyJypKRiqCdHZiAzKg9hl15HA8=
|
||||
github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q=
|
||||
github.com/gogo/protobuf v1.3.2/go.mod h1:P1XiOD3dCwIKUDQYPy72D8LYyHL2YPYrpS2s69NZV8Q=
|
||||
github.com/google/btree v1.1.3 h1:CVpQJjYgC4VbzxeGVHfvZrv1ctoYCAI8vbl07Fcxlyg=
|
||||
github.com/google/btree v1.1.3/go.mod h1:qOPhT0dTNdNzV6Z/lhRX0YXUafgPLFUh+gZMl761Gm4=
|
||||
github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaSAoJOfIk=
|
||||
github.com/google/btree v1.0.1 h1:gK4Kx5IaGY9CD5sPJ36FHiBJ6ZXl0kilRiiCj+jdYp4=
|
||||
github.com/google/btree v1.0.1/go.mod h1:xXMiIv4Fb/0kKde4SpL7qlzvu5cMJDRkFDxJfI9uaxA=
|
||||
github.com/google/gnostic-models v0.6.9 h1:MU/8wDLif2qCXZmzncUQ/BOfxWfthHi63KqpoNbWqVw=
|
||||
github.com/google/gnostic-models v0.6.9/go.mod h1:CiWsm0s6BSQd1hRn8/QmxqB6BesYcbSZxsz9b0KuDBw=
|
||||
github.com/google/go-cmp v0.5.9/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY=
|
||||
@@ -40,6 +45,7 @@ github.com/gorilla/websocket v1.5.0 h1:PPwGk2jz7EePpoHN/+ClbZu8SPxiqlu12wZP/3sWm
|
||||
github.com/gorilla/websocket v1.5.0/go.mod h1:YR8l580nyteQvAITg2hZ9XVh4b55+EU/adAjf1fMHhE=
|
||||
github.com/gregjones/httpcache v0.0.0-20190611155906-901d90724c79 h1:+ngKgrYPPJrOjhax5N+uePQ0Fh1Z7PheYoUI/0nzkPA=
|
||||
github.com/gregjones/httpcache v0.0.0-20190611155906-901d90724c79/go.mod h1:FecbI9+v66THATjSRHfNgh1IVFe/9kFxbXtjV0ctIMA=
|
||||
github.com/ianlancetaylor/demangle v0.0.0-20240312041847-bd984b5ce465/go.mod h1:gx7rwoVhcfuVKG5uya9Hs3Sxj7EIvldVofAWIUtGouw=
|
||||
github.com/josharian/intern v1.0.0 h1:vlS4z54oSdjm0bgjRigI+G1HpF+tI+9rE5LLzOg8HmY=
|
||||
github.com/josharian/intern v1.0.0/go.mod h1:5DoeVV0s6jJacbCEi61lwdGj/aVlrQvzHFFd8Hwg//Y=
|
||||
github.com/json-iterator/go v1.1.12 h1:PV8peI4a0ysnczrg+LtxykD8LfKY9ML6u2jnxaEnrnM=
|
||||
@@ -74,8 +80,9 @@ github.com/peterbourgon/diskv v2.0.1+incompatible h1:UBdAOUP5p4RWqPBg048CAvpKN+v
|
||||
github.com/peterbourgon/diskv v2.0.1+incompatible/go.mod h1:uqqh8zWWbv1HBMNONnaR/tNboyR3/BZd58JJSHlUSCU=
|
||||
github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
|
||||
github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
|
||||
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
|
||||
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
|
||||
github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 h1:Jamvg5psRIccs7FGNTlIRMkT8wgtp5eCXdBlqhYGL6U=
|
||||
github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
|
||||
github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8=
|
||||
github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4=
|
||||
github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
|
||||
@@ -83,7 +90,6 @@ github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An
|
||||
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
|
||||
github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
|
||||
github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo=
|
||||
github.com/stretchr/objx v0.5.2 h1:xuMeJ0Sdp5ZMRXx/aWO6RZxdr3beISkG5/G/aIRr3pY=
|
||||
github.com/stretchr/objx v0.5.2/go.mod h1:FRsXN1f5AsAjCGJKqEizvkpNtU+EGNCLh3NxZ/8L+MA=
|
||||
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
|
||||
github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
|
||||
@@ -95,29 +101,34 @@ github.com/x448/float16 v0.8.4 h1:qLwI1I70+NjRFUR3zs1JPUCgaCXSh3SW62uAKT1mSBM=
|
||||
github.com/x448/float16 v0.8.4/go.mod h1:14CWIYCyZA/cWjXOioeEpHeN/83MdbZDRQHoFcYsOfg=
|
||||
github.com/yuin/goldmark v1.1.27/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
|
||||
github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
|
||||
github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY=
|
||||
go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto=
|
||||
go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE=
|
||||
golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
|
||||
golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
|
||||
golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
|
||||
golang.org/x/crypto v0.28.0/go.mod h1:rmgy+3RHxRZMyY0jjAJShp2zgEdOqj2AO7U0pYmeQ7U=
|
||||
golang.org/x/mod v0.2.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
|
||||
golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
|
||||
golang.org/x/mod v0.21.0/go.mod h1:6SkKJ3Xj0I0BrPOZoBy3bdMptDDU9oJrpohJ3eWZ1fY=
|
||||
golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
|
||||
golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
|
||||
golang.org/x/net v0.0.0-20200226121028-0de0cce0169b/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
|
||||
golang.org/x/net v0.0.0-20201021035429-f5854403a974/go.mod h1:sp8m0HH+o8qH0wwXwYZr8TS3Oi6o0r6Gce1SSxlDquU=
|
||||
golang.org/x/net v0.33.0 h1:74SYHlV8BIgHIFC/LrYkOGIwL19eTYXQ5wc6TBuO36I=
|
||||
golang.org/x/net v0.33.0/go.mod h1:HXLR5J+9DxmrqMwG9qjGCxZ+zKXxBru04zlTvWlWuN4=
|
||||
golang.org/x/net v0.30.0 h1:AcW1SDZMkb8IpzCdQUaIq2sP4sZ4zw+55h6ynffypl4=
|
||||
golang.org/x/net v0.30.0/go.mod h1:2wGyMJ5iFasEhkwi13ChkO/t1ECNC4X4eBKkVFyYFlU=
|
||||
golang.org/x/oauth2 v0.23.0 h1:PbgcYx2W7i4LvjJWEbf0ngHV6qJYr86PkAV3bXdLEbs=
|
||||
golang.org/x/oauth2 v0.23.0/go.mod h1:XYTD2NtWslqkgxebSiOHnXEap4TF09sJSc7H1sXbhtI=
|
||||
golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
|
||||
golang.org/x/sync v0.0.0-20190911185100-cd5d95a43a6e/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
|
||||
golang.org/x/sync v0.0.0-20201020160332-67f06af15bc9/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
|
||||
golang.org/x/sync v0.10.0/go.mod h1:Czt+wKu1gCyEFDUtn0jG5QVvpJ6rzVqr5aXyt9drQfk=
|
||||
golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
|
||||
golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
|
||||
golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
|
||||
golang.org/x/sys v0.28.0 h1:Fksou7UEQUWlKvIdsqzJmUmCX3cZuD2+P3XyyzwMhlA=
|
||||
golang.org/x/sys v0.28.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
|
||||
golang.org/x/telemetry v0.0.0-20240521205824-bda55230c457/go.mod h1:pRgIJT+bRLFKnoM1ldnzKoxTIn14Yxz928LQRYYgIN0=
|
||||
golang.org/x/term v0.27.0 h1:WP60Sv1nlK1T6SupCHbXzSaN0b9wUmsPoRS9b61A23Q=
|
||||
golang.org/x/term v0.27.0/go.mod h1:iMsnZpn0cago0GOrHO2+Y7u7JPn5AylBrcoWkElMTSM=
|
||||
golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
|
||||
@@ -148,10 +159,7 @@ gopkg.in/inf.v0 v0.9.1/go.mod h1:cWUDdTG/fYaXco+Dcufb5Vnc6Gp2YChqWtbxRZE0mXw=
|
||||
gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
|
||||
gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
|
||||
gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
|
||||
k8s.io/api v0.0.0-20250124010721-4dccc5e86b95 h1:HWXnRRZiNgEmww7iRWHiKp61yeYP0zGFm12YWPvQhq8=
|
||||
k8s.io/api v0.0.0-20250124010721-4dccc5e86b95/go.mod h1:YGB38orWxSXzMXdSPGWLOwrcumsaTbYPKy3dnT0HbRs=
|
||||
k8s.io/apimachinery v0.0.0-20250125235321-4c615911e2cb h1:gFmlyeyIOPW96rfDidalJn40jFJHweiLkfnUw6mDOPM=
|
||||
k8s.io/apimachinery v0.0.0-20250125235321-4c615911e2cb/go.mod h1:h8DnJz4KNjkQsP8iFir+s3sSBEK3Iy43bfB2gFjSR+A=
|
||||
k8s.io/gengo/v2 v2.0.0-20240826214909-a7b603a56eb7/go.mod h1:EJykeLsmFC60UQbYJezXkEsG2FLrt0GPNkU5iK5GWxU=
|
||||
k8s.io/klog/v2 v2.130.1 h1:n9Xl7H1Xvksem4KFG4PYbdQCQxqc/tTUyrgXaOhHSzk=
|
||||
k8s.io/klog/v2 v2.130.1/go.mod h1:3Jpz1GvMt720eyJH1ckRHK1EDfpxISzJ7I9OYgaDtPE=
|
||||
k8s.io/kube-openapi v0.0.0-20241212222426-2c72e554b1e7 h1:hcha5B1kVACrLujCKLbr8XWMxCxzQx42DY8QKYJrDLg=
|
||||
|
||||
@@ -28,6 +28,7 @@ import (
|
||||
utilnet "k8s.io/apimachinery/pkg/util/net"
|
||||
"k8s.io/apimachinery/pkg/util/wait"
|
||||
"k8s.io/client-go/tools/metrics"
|
||||
"k8s.io/klog/v2"
|
||||
)
|
||||
|
||||
// TlsTransportCache caches TLS http.RoundTrippers different configurations. The
|
||||
@@ -116,10 +117,13 @@ func (c *tlsTransportCache) get(config *Config) (http.RoundTripper, error) {
|
||||
// If we use are reloading files, we need to handle certificate rotation properly
|
||||
// TODO(jackkleeman): We can also add rotation here when config.HasCertCallback() is true
|
||||
if config.TLS.ReloadTLSFiles && tlsConfig != nil && tlsConfig.GetClientCertificate != nil {
|
||||
dynamicCertDialer := certRotatingDialer(tlsConfig.GetClientCertificate, dial)
|
||||
// The TLS cache is a singleton, so sharing the same name for all of its
|
||||
// background activity seems okay.
|
||||
logger := klog.Background().WithName("tls-transport-cache")
|
||||
dynamicCertDialer := certRotatingDialer(logger, tlsConfig.GetClientCertificate, dial)
|
||||
tlsConfig.GetClientCertificate = dynamicCertDialer.GetClientCertificate
|
||||
dial = dynamicCertDialer.connDialer.DialContext
|
||||
go dynamicCertDialer.Run(DialerStopCh)
|
||||
go dynamicCertDialer.run(DialerStopCh)
|
||||
}
|
||||
|
||||
proxy := http.ProxyFromEnvironment
|
||||
|
||||
@@ -19,7 +19,6 @@ package transport
|
||||
import (
|
||||
"bytes"
|
||||
"crypto/tls"
|
||||
"fmt"
|
||||
"reflect"
|
||||
"sync"
|
||||
"time"
|
||||
@@ -40,6 +39,7 @@ var CertCallbackRefreshDuration = 5 * time.Minute
|
||||
type reloadFunc func(*tls.CertificateRequestInfo) (*tls.Certificate, error)
|
||||
|
||||
type dynamicClientCert struct {
|
||||
logger klog.Logger
|
||||
clientCert *tls.Certificate
|
||||
certMtx sync.RWMutex
|
||||
|
||||
@@ -50,8 +50,9 @@ type dynamicClientCert struct {
|
||||
queue workqueue.TypedRateLimitingInterface[string]
|
||||
}
|
||||
|
||||
func certRotatingDialer(reload reloadFunc, dial utilnet.DialFunc) *dynamicClientCert {
|
||||
func certRotatingDialer(logger klog.Logger, reload reloadFunc, dial utilnet.DialFunc) *dynamicClientCert {
|
||||
d := &dynamicClientCert{
|
||||
logger: logger,
|
||||
reload: reload,
|
||||
connDialer: connrotation.NewDialer(connrotation.DialFunc(dial)),
|
||||
queue: workqueue.NewTypedRateLimitingQueueWithConfig(
|
||||
@@ -88,7 +89,7 @@ func (c *dynamicClientCert) loadClientCert() (*tls.Certificate, error) {
|
||||
return cert, nil
|
||||
}
|
||||
|
||||
klog.V(1).Infof("certificate rotation detected, shutting down client connections to start using new credentials")
|
||||
c.logger.V(1).Info("Certificate rotation detected, shutting down client connections to start using new credentials")
|
||||
c.connDialer.CloseAll()
|
||||
|
||||
return cert, nil
|
||||
@@ -133,12 +134,12 @@ func byteMatrixEqual(left, right [][]byte) bool {
|
||||
}
|
||||
|
||||
// run starts the controller and blocks until stopCh is closed.
|
||||
func (c *dynamicClientCert) Run(stopCh <-chan struct{}) {
|
||||
defer utilruntime.HandleCrash()
|
||||
func (c *dynamicClientCert) run(stopCh <-chan struct{}) {
|
||||
defer utilruntime.HandleCrashWithLogger(c.logger)
|
||||
defer c.queue.ShutDown()
|
||||
|
||||
klog.V(3).Infof("Starting client certificate rotation controller")
|
||||
defer klog.V(3).Infof("Shutting down client certificate rotation controller")
|
||||
c.logger.V(3).Info("Starting client certificate rotation controller")
|
||||
defer c.logger.V(3).Info("Shutting down client certificate rotation controller")
|
||||
|
||||
go wait.Until(c.runWorker, time.Second, stopCh)
|
||||
|
||||
@@ -168,7 +169,7 @@ func (c *dynamicClientCert) processNextWorkItem() bool {
|
||||
return true
|
||||
}
|
||||
|
||||
utilruntime.HandleError(fmt.Errorf("%v failed with : %v", dsKey, err))
|
||||
utilruntime.HandleErrorWithLogger(c.logger, err, "Loading client cert failed", "key", dsKey)
|
||||
c.queue.AddRateLimited(dsKey)
|
||||
|
||||
return true
|
||||
|
||||
@@ -21,10 +21,12 @@ import (
|
||||
"fmt"
|
||||
"net/http"
|
||||
"net/http/httptrace"
|
||||
"sort"
|
||||
"strings"
|
||||
"sync"
|
||||
"time"
|
||||
|
||||
"github.com/go-logr/logr"
|
||||
"golang.org/x/oauth2"
|
||||
|
||||
utilnet "k8s.io/apimachinery/pkg/util/net"
|
||||
@@ -68,19 +70,16 @@ func HTTPWrappersForConfig(config *Config, rt http.RoundTripper) (http.RoundTrip
|
||||
return rt, nil
|
||||
}
|
||||
|
||||
// DebugWrappers wraps a round tripper and logs based on the current log level.
|
||||
// DebugWrappers potentially wraps a round tripper with a wrapper that logs
|
||||
// based on the log level in the context of each individual request.
|
||||
//
|
||||
// At the moment, wrapping depends on the global log verbosity and is done
|
||||
// if that verbosity is >= 6. This may change in the future.
|
||||
func DebugWrappers(rt http.RoundTripper) http.RoundTripper {
|
||||
switch {
|
||||
case bool(klog.V(9).Enabled()):
|
||||
rt = NewDebuggingRoundTripper(rt, DebugCurlCommand, DebugURLTiming, DebugDetailedTiming, DebugResponseHeaders)
|
||||
case bool(klog.V(8).Enabled()):
|
||||
rt = NewDebuggingRoundTripper(rt, DebugJustURL, DebugRequestHeaders, DebugResponseStatus, DebugResponseHeaders)
|
||||
case bool(klog.V(7).Enabled()):
|
||||
rt = NewDebuggingRoundTripper(rt, DebugJustURL, DebugRequestHeaders, DebugResponseStatus)
|
||||
case bool(klog.V(6).Enabled()):
|
||||
rt = NewDebuggingRoundTripper(rt, DebugURLTiming)
|
||||
//nolint:logcheck // The actual logging is done with a different logger, so only checking here is okay.
|
||||
if klog.V(6).Enabled() {
|
||||
rt = NewDebuggingRoundTripper(rt, DebugByContext)
|
||||
}
|
||||
|
||||
return rt
|
||||
}
|
||||
|
||||
@@ -380,14 +379,17 @@ func (r *requestInfo) toCurl() string {
|
||||
}
|
||||
}
|
||||
|
||||
return fmt.Sprintf("curl -v -X%s %s '%s'", r.RequestVerb, headers, r.RequestURL)
|
||||
// Newline at the end makes this look better in the text log output (the
|
||||
// only usage of this method) because it becomes a multi-line string with
|
||||
// no quoting.
|
||||
return fmt.Sprintf("curl -v -X%s %s '%s'\n", r.RequestVerb, headers, r.RequestURL)
|
||||
}
|
||||
|
||||
// debuggingRoundTripper will display information about the requests passing
|
||||
// through it based on what is configured
|
||||
type debuggingRoundTripper struct {
|
||||
delegatedRoundTripper http.RoundTripper
|
||||
levels map[DebugLevel]bool
|
||||
levels int
|
||||
}
|
||||
|
||||
var _ utilnet.RoundTripperWrapper = &debuggingRoundTripper{}
|
||||
@@ -412,6 +414,26 @@ const (
|
||||
DebugResponseHeaders
|
||||
// DebugDetailedTiming will add to the debug output the duration of the HTTP requests events.
|
||||
DebugDetailedTiming
|
||||
// DebugByContext will add any of the above depending on the verbosity of the per-request logger obtained from the requests context.
|
||||
//
|
||||
// Can be combined in NewDebuggingRoundTripper with some of the other options, in which case the
|
||||
// debug roundtripper will always log what is requested there plus the information that gets
|
||||
// enabled by the context's log verbosity.
|
||||
DebugByContext
|
||||
)
|
||||
|
||||
// Different log levels include different sets of information.
|
||||
//
|
||||
// Not exported because the exact content of log messages is not part
|
||||
// of of the package API.
|
||||
const (
|
||||
levelsV6 = (1 << DebugURLTiming)
|
||||
// Logging *less* information for the response at level 7 compared to 6 replicates prior behavior:
|
||||
// https://github.com/kubernetes/kubernetes/blob/2b472fe4690c83a2b343995f88050b2a3e9ff0fa/staging/src/k8s.io/client-go/transport/round_trippers.go#L79
|
||||
// Presumably that was done because verb and URL are already in the request log entry.
|
||||
levelsV7 = (1 << DebugJustURL) | (1 << DebugRequestHeaders) | (1 << DebugResponseStatus)
|
||||
levelsV8 = (1 << DebugJustURL) | (1 << DebugRequestHeaders) | (1 << DebugResponseStatus) | (1 << DebugResponseHeaders)
|
||||
levelsV9 = (1 << DebugCurlCommand) | (1 << DebugURLTiming) | (1 << DebugDetailedTiming) | (1 << DebugResponseHeaders)
|
||||
)
|
||||
|
||||
// NewDebuggingRoundTripper allows to display in the logs output debug information
|
||||
@@ -419,10 +441,9 @@ const (
|
||||
func NewDebuggingRoundTripper(rt http.RoundTripper, levels ...DebugLevel) http.RoundTripper {
|
||||
drt := &debuggingRoundTripper{
|
||||
delegatedRoundTripper: rt,
|
||||
levels: make(map[DebugLevel]bool, len(levels)),
|
||||
}
|
||||
for _, v := range levels {
|
||||
drt.levels[v] = true
|
||||
drt.levels |= 1 << v
|
||||
}
|
||||
return drt
|
||||
}
|
||||
@@ -464,27 +485,51 @@ func maskValue(key string, value string) string {
|
||||
}
|
||||
|
||||
func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
|
||||
logger := klog.FromContext(req.Context())
|
||||
levels := rt.levels
|
||||
|
||||
// When logging depends on the context, it uses the verbosity of the per-context logger
|
||||
// and a hard-coded mapping of verbosity to debug details. Otherwise all messages
|
||||
// are logged as V(0).
|
||||
if levels&(1<<DebugByContext) != 0 {
|
||||
if loggerV := logger.V(9); loggerV.Enabled() {
|
||||
logger = loggerV
|
||||
// The curl command replaces logging of the URL.
|
||||
levels |= levelsV9
|
||||
} else if loggerV := logger.V(8); loggerV.Enabled() {
|
||||
logger = loggerV
|
||||
levels |= levelsV8
|
||||
} else if loggerV := logger.V(7); loggerV.Enabled() {
|
||||
logger = loggerV
|
||||
levels |= levelsV7
|
||||
} else if loggerV := logger.V(6); loggerV.Enabled() {
|
||||
logger = loggerV
|
||||
levels |= levelsV6
|
||||
}
|
||||
}
|
||||
|
||||
reqInfo := newRequestInfo(req)
|
||||
|
||||
if rt.levels[DebugJustURL] {
|
||||
klog.Infof("%s %s", reqInfo.RequestVerb, reqInfo.RequestURL)
|
||||
kvs := make([]any, 0, 8) // Exactly large enough for all appends below.
|
||||
if levels&(1<<DebugJustURL) != 0 {
|
||||
kvs = append(kvs,
|
||||
"verb", reqInfo.RequestVerb,
|
||||
"url", reqInfo.RequestURL,
|
||||
)
|
||||
}
|
||||
if rt.levels[DebugCurlCommand] {
|
||||
klog.Infof("%s", reqInfo.toCurl())
|
||||
if levels&(1<<DebugCurlCommand) != 0 {
|
||||
kvs = append(kvs, "curlCommand", reqInfo.toCurl())
|
||||
}
|
||||
if rt.levels[DebugRequestHeaders] {
|
||||
klog.Info("Request Headers:")
|
||||
for key, values := range reqInfo.RequestHeaders {
|
||||
for _, value := range values {
|
||||
value = maskValue(key, value)
|
||||
klog.Infof(" %s: %s", key, value)
|
||||
}
|
||||
}
|
||||
if levels&(1<<DebugRequestHeaders) != 0 {
|
||||
kvs = append(kvs, "headers", newHeadersMap(reqInfo.RequestHeaders))
|
||||
}
|
||||
if len(kvs) > 0 {
|
||||
logger.Info("Request", kvs...)
|
||||
}
|
||||
|
||||
startTime := time.Now()
|
||||
|
||||
if rt.levels[DebugDetailedTiming] {
|
||||
if levels&(1<<DebugDetailedTiming) != 0 {
|
||||
var getConn, dnsStart, dialStart, tlsStart, serverStart time.Time
|
||||
var host string
|
||||
trace := &httptrace.ClientTrace{
|
||||
@@ -499,7 +544,7 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
|
||||
reqInfo.muTrace.Lock()
|
||||
defer reqInfo.muTrace.Unlock()
|
||||
reqInfo.DNSLookup = time.Since(dnsStart)
|
||||
klog.Infof("HTTP Trace: DNS Lookup for %s resolved to %v", host, info.Addrs)
|
||||
logger.Info("HTTP Trace: DNS Lookup resolved", "host", host, "address", info.Addrs)
|
||||
},
|
||||
// Dial
|
||||
ConnectStart: func(network, addr string) {
|
||||
@@ -512,9 +557,9 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
|
||||
defer reqInfo.muTrace.Unlock()
|
||||
reqInfo.Dialing = time.Since(dialStart)
|
||||
if err != nil {
|
||||
klog.Infof("HTTP Trace: Dial to %s:%s failed: %v", network, addr, err)
|
||||
logger.Info("HTTP Trace: Dial failed", "network", network, "address", addr, "err", err)
|
||||
} else {
|
||||
klog.Infof("HTTP Trace: Dial to %s:%s succeed", network, addr)
|
||||
logger.Info("HTTP Trace: Dial succeed", "network", network, "address", addr)
|
||||
}
|
||||
},
|
||||
// TLS
|
||||
@@ -556,42 +601,85 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
|
||||
|
||||
reqInfo.complete(response, err)
|
||||
|
||||
if rt.levels[DebugURLTiming] {
|
||||
klog.Infof("%s %s %s in %d milliseconds", reqInfo.RequestVerb, reqInfo.RequestURL, reqInfo.ResponseStatus, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond))
|
||||
kvs = make([]any, 0, 20) // Exactly large enough for all appends below.
|
||||
if levels&(1<<DebugURLTiming) != 0 {
|
||||
kvs = append(kvs, "verb", reqInfo.RequestVerb, "url", reqInfo.RequestURL)
|
||||
}
|
||||
if rt.levels[DebugDetailedTiming] {
|
||||
stats := ""
|
||||
if levels&(1<<DebugURLTiming|1<<DebugResponseStatus) != 0 {
|
||||
kvs = append(kvs, "status", reqInfo.ResponseStatus)
|
||||
}
|
||||
if levels&(1<<DebugResponseHeaders) != 0 {
|
||||
kvs = append(kvs, "headers", newHeadersMap(reqInfo.ResponseHeaders))
|
||||
}
|
||||
if levels&(1<<DebugURLTiming|1<<DebugDetailedTiming|1<<DebugResponseStatus) != 0 {
|
||||
kvs = append(kvs, "milliseconds", reqInfo.Duration.Nanoseconds()/int64(time.Millisecond))
|
||||
}
|
||||
if levels&(1<<DebugDetailedTiming) != 0 {
|
||||
if !reqInfo.ConnectionReused {
|
||||
stats += fmt.Sprintf(`DNSLookup %d ms Dial %d ms TLSHandshake %d ms`,
|
||||
reqInfo.DNSLookup.Nanoseconds()/int64(time.Millisecond),
|
||||
reqInfo.Dialing.Nanoseconds()/int64(time.Millisecond),
|
||||
reqInfo.TLSHandshake.Nanoseconds()/int64(time.Millisecond),
|
||||
kvs = append(kvs,
|
||||
"dnsLookupMilliseconds", reqInfo.DNSLookup.Nanoseconds()/int64(time.Millisecond),
|
||||
"dialMilliseconds", reqInfo.Dialing.Nanoseconds()/int64(time.Millisecond),
|
||||
"tlsHandshakeMilliseconds", reqInfo.TLSHandshake.Nanoseconds()/int64(time.Millisecond),
|
||||
)
|
||||
} else {
|
||||
stats += fmt.Sprintf(`GetConnection %d ms`, reqInfo.GetConnection.Nanoseconds()/int64(time.Millisecond))
|
||||
kvs = append(kvs, "getConnectionMilliseconds", reqInfo.GetConnection.Nanoseconds()/int64(time.Millisecond))
|
||||
}
|
||||
if reqInfo.ServerProcessing != 0 {
|
||||
stats += fmt.Sprintf(` ServerProcessing %d ms`, reqInfo.ServerProcessing.Nanoseconds()/int64(time.Millisecond))
|
||||
kvs = append(kvs, "serverProcessingMilliseconds", reqInfo.ServerProcessing.Nanoseconds()/int64(time.Millisecond))
|
||||
}
|
||||
stats += fmt.Sprintf(` Duration %d ms`, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond))
|
||||
klog.Infof("HTTP Statistics: %s", stats)
|
||||
}
|
||||
|
||||
if rt.levels[DebugResponseStatus] {
|
||||
klog.Infof("Response Status: %s in %d milliseconds", reqInfo.ResponseStatus, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond))
|
||||
}
|
||||
if rt.levels[DebugResponseHeaders] {
|
||||
klog.Info("Response Headers:")
|
||||
for key, values := range reqInfo.ResponseHeaders {
|
||||
for _, value := range values {
|
||||
klog.Infof(" %s: %s", key, value)
|
||||
}
|
||||
}
|
||||
if len(kvs) > 0 {
|
||||
logger.Info("Response", kvs...)
|
||||
}
|
||||
|
||||
return response, err
|
||||
}
|
||||
|
||||
// headerMap formats headers sorted and across multiple lines with no quoting
|
||||
// when using string output and as JSON when using zapr.
|
||||
type headersMap http.Header
|
||||
|
||||
// newHeadersMap masks all sensitive values. This has to be done before
|
||||
// passing the map to a logger because while in practice all loggers
|
||||
// either use String or MarshalLog, that is not guaranteed.
|
||||
func newHeadersMap(header http.Header) headersMap {
|
||||
h := make(headersMap, len(header))
|
||||
for key, values := range header {
|
||||
maskedValues := make([]string, 0, len(values))
|
||||
for _, value := range values {
|
||||
maskedValues = append(maskedValues, maskValue(key, value))
|
||||
}
|
||||
h[key] = maskedValues
|
||||
}
|
||||
return h
|
||||
}
|
||||
|
||||
var _ fmt.Stringer = headersMap{}
|
||||
var _ logr.Marshaler = headersMap{}
|
||||
|
||||
func (h headersMap) String() string {
|
||||
// The fixed size typically avoids memory allocations when it is large enough.
|
||||
keys := make([]string, 0, 20)
|
||||
for key := range h {
|
||||
keys = append(keys, key)
|
||||
}
|
||||
sort.Strings(keys)
|
||||
var buffer strings.Builder
|
||||
for _, key := range keys {
|
||||
for _, value := range h[key] {
|
||||
_, _ = buffer.WriteString(key)
|
||||
_, _ = buffer.WriteString(": ")
|
||||
_, _ = buffer.WriteString(value)
|
||||
_, _ = buffer.WriteString("\n")
|
||||
}
|
||||
}
|
||||
return buffer.String()
|
||||
}
|
||||
|
||||
func (h headersMap) MarshalLog() any {
|
||||
return map[string][]string(h)
|
||||
}
|
||||
|
||||
func (rt *debuggingRoundTripper) WrappedRoundTripper() http.RoundTripper {
|
||||
return rt.delegatedRoundTripper
|
||||
}
|
||||
|
||||
@@ -18,13 +18,18 @@ package transport
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"context"
|
||||
"flag"
|
||||
"fmt"
|
||||
"net/http"
|
||||
"net/url"
|
||||
"reflect"
|
||||
"regexp"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/go-logr/logr/funcr"
|
||||
|
||||
"k8s.io/klog/v2"
|
||||
)
|
||||
|
||||
@@ -460,101 +465,224 @@ func TestHeaderEscapeRoundTrip(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
//nolint:logcheck // Intentionally tests with global logging.
|
||||
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": {"bearer secretauthtoken"},
|
||||
"X-Test-Request": {"test"},
|
||||
},
|
||||
parsedURL, err := url.Parse(rawURL)
|
||||
if err != nil {
|
||||
t.Fatalf("url.Parse(%q) returned error: %v", rawURL, err)
|
||||
}
|
||||
method := http.MethodGet
|
||||
header := map[string][]string{
|
||||
"Authorization": {"bearer secretauthtoken"},
|
||||
"X-Test-Request": {"test"},
|
||||
}
|
||||
reqHeaderText := `headers=<
|
||||
Authorization: bearer <masked>
|
||||
X-Test-Request: test
|
||||
>`
|
||||
// Both can be written by funcr.
|
||||
reqHeaderJSON := `"headers":{"Authorization":["bearer <masked>"],"X-Test-Request":["test"]}`
|
||||
reqHeaderJSONReversed := `"headers":{"X-Test-Request":["test"],"Authorization":["bearer <masked>"]}`
|
||||
|
||||
res := &http.Response{
|
||||
Status: "OK",
|
||||
StatusCode: http.StatusOK,
|
||||
Header: map[string][]string{
|
||||
"X-Test-Response": {"test"},
|
||||
"X-Test-Response": {"a", "b"},
|
||||
},
|
||||
}
|
||||
|
||||
resHeaderText := `headers=<
|
||||
X-Test-Response: a
|
||||
X-Test-Response: b
|
||||
>`
|
||||
resHeaderJSON := `"headers":{"X-Test-Response":["a","b"]}`
|
||||
|
||||
tcs := []struct {
|
||||
levels []DebugLevel
|
||||
expectedOutputLines []string
|
||||
levels []DebugLevel
|
||||
v int
|
||||
expectedTextLines []string
|
||||
expectedJSONLines []string
|
||||
}{
|
||||
{
|
||||
levels: []DebugLevel{DebugJustURL},
|
||||
expectedOutputLines: []string{fmt.Sprintf("%s %s", req.Method, rawURL)},
|
||||
levels: []DebugLevel{DebugJustURL},
|
||||
expectedTextLines: []string{fmt.Sprintf(`"Request" verb=%q url=%q`, method, rawURL)},
|
||||
expectedJSONLines: []string{fmt.Sprintf(`"msg":"Request","verb":%q,"url":%q`, 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{DebugRequestHeaders},
|
||||
expectedTextLines: []string{`"Request" ` + reqHeaderText},
|
||||
expectedJSONLines: []string{`"msg":"Request",` + reqHeaderJSON},
|
||||
},
|
||||
{
|
||||
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{DebugResponseHeaders},
|
||||
expectedTextLines: []string{`"Response" ` + resHeaderText},
|
||||
expectedJSONLines: []string{`"msg":"Response",` + resHeaderJSON},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugURLTiming},
|
||||
expectedOutputLines: []string{fmt.Sprintf("%s %s %s", req.Method, rawURL, res.Status)},
|
||||
levels: []DebugLevel{DebugURLTiming},
|
||||
expectedTextLines: []string{fmt.Sprintf(`"Response" verb=%q url=%q status=%q`, method, rawURL, res.Status)},
|
||||
expectedJSONLines: []string{fmt.Sprintf(`"msg":"Response","verb":%q,"url":%q,"status":%q`, method, rawURL, res.Status)},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugResponseStatus},
|
||||
expectedOutputLines: []string{fmt.Sprintf("Response Status: %s", res.Status)},
|
||||
levels: []DebugLevel{DebugResponseStatus},
|
||||
expectedTextLines: []string{fmt.Sprintf(`"Response" status=%q`, res.Status)},
|
||||
expectedJSONLines: []string{fmt.Sprintf(`"msg":"Response","status":%q`, res.Status)},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugCurlCommand},
|
||||
expectedOutputLines: []string{fmt.Sprintf("curl -v -X")},
|
||||
levels: []DebugLevel{DebugCurlCommand},
|
||||
expectedTextLines: []string{`curlCommand=<
|
||||
curl -v -X`},
|
||||
expectedJSONLines: []string{`"curlCommand":"curl -v -X`},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugURLTiming, DebugResponseStatus},
|
||||
expectedTextLines: []string{fmt.Sprintf(`"Response" verb=%q url=%q status=%q milliseconds=`, method, rawURL, res.Status)},
|
||||
expectedJSONLines: []string{fmt.Sprintf(`"msg":"Response","verb":%q,"url":%q,"status":%q,"milliseconds":`, method, rawURL, res.Status)},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugByContext},
|
||||
v: 5,
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugByContext, DebugURLTiming},
|
||||
v: 5,
|
||||
expectedTextLines: []string{
|
||||
fmt.Sprintf(`"Response" verb=%q url=%q status=%q milliseconds=`, method, rawURL, res.Status),
|
||||
},
|
||||
expectedJSONLines: []string{
|
||||
fmt.Sprintf(`"msg":"Response","verb":%q,"url":%q,"status":%q,"milliseconds":`, method, rawURL, res.Status),
|
||||
},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugByContext},
|
||||
v: 6,
|
||||
expectedTextLines: []string{
|
||||
fmt.Sprintf(`"Response" verb=%q url=%q status=%q milliseconds=`, method, rawURL, res.Status),
|
||||
},
|
||||
expectedJSONLines: []string{
|
||||
fmt.Sprintf(`"msg":"Response","verb":%q,"url":%q,"status":%q,"milliseconds":`, method, rawURL, res.Status),
|
||||
},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugByContext},
|
||||
v: 7,
|
||||
expectedTextLines: []string{
|
||||
fmt.Sprintf(`"Request" verb=%q url=%q %s
|
||||
`, method, rawURL, reqHeaderText),
|
||||
fmt.Sprintf(`"Response" status=%q milliseconds=`, res.Status),
|
||||
},
|
||||
expectedJSONLines: []string{
|
||||
fmt.Sprintf(`"msg":"Request","verb":%q,"url":%q,%s`, method, rawURL, reqHeaderJSON),
|
||||
fmt.Sprintf(`"msg":"Response","status":%q,"milliseconds":`, res.Status),
|
||||
},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugByContext},
|
||||
v: 8,
|
||||
expectedTextLines: []string{
|
||||
fmt.Sprintf(`"Request" verb=%q url=%q %s
|
||||
`, method, rawURL, reqHeaderText),
|
||||
fmt.Sprintf(`"Response" status=%q %s milliseconds=`, res.Status, resHeaderText),
|
||||
},
|
||||
expectedJSONLines: []string{
|
||||
fmt.Sprintf(`"msg":"Request","verb":%q,"url":%q,%s`, method, rawURL, reqHeaderJSON),
|
||||
fmt.Sprintf(`"msg":"Response","status":%q,%s,"milliseconds":`, res.Status, resHeaderJSON),
|
||||
},
|
||||
},
|
||||
{
|
||||
levels: []DebugLevel{DebugByContext},
|
||||
v: 9,
|
||||
expectedTextLines: []string{
|
||||
fmt.Sprintf(`"Request" curlCommand=<
|
||||
curl -v -X%s`, method),
|
||||
fmt.Sprintf(`"Response" verb=%q url=%q status=%q %s milliseconds=`, method, rawURL, res.Status, resHeaderText),
|
||||
},
|
||||
expectedJSONLines: []string{
|
||||
fmt.Sprintf(`"msg":"Request","curlCommand":"curl -v -X%s`, method),
|
||||
fmt.Sprintf(`"msg":"Response","verb":%q,"url":%q,"status":%q,%s,"milliseconds":`, method, rawURL, res.Status, resHeaderJSON),
|
||||
},
|
||||
},
|
||||
}
|
||||
|
||||
for _, tc := range tcs {
|
||||
// hijack the klog output
|
||||
tmpWriteBuffer := bytes.NewBuffer(nil)
|
||||
klog.SetOutput(tmpWriteBuffer)
|
||||
klog.LogToStderr(false)
|
||||
for i, tc := range tcs {
|
||||
t.Run(fmt.Sprintf("%d", i), func(t *testing.T) {
|
||||
for _, format := range []string{"text", "JSON"} {
|
||||
t.Run(format, func(t *testing.T) {
|
||||
// hijack the klog output
|
||||
state := klog.CaptureState()
|
||||
tmpWriteBuffer := bytes.NewBuffer(nil)
|
||||
klog.SetOutput(tmpWriteBuffer)
|
||||
klog.LogToStderr(false)
|
||||
var fs flag.FlagSet
|
||||
klog.InitFlags(&fs)
|
||||
if err := fs.Set("one_output", "true"); err != nil {
|
||||
t.Errorf("unexpected error setting -one_output: %v", err)
|
||||
}
|
||||
if err := fs.Set("v", fmt.Sprintf("%d", tc.v)); err != nil {
|
||||
t.Errorf("unexpected error setting -v: %v", err)
|
||||
}
|
||||
|
||||
// parse rawURL
|
||||
parsedURL, err := url.Parse(rawURL)
|
||||
if err != nil {
|
||||
t.Fatalf("url.Parse(%q) returned error: %v", rawURL, err)
|
||||
}
|
||||
req.URL = parsedURL
|
||||
expectOutput := tc.expectedTextLines
|
||||
var req *http.Request
|
||||
if format == "JSON" {
|
||||
// Logger will be picked up through the context.
|
||||
logger := funcr.NewJSON(func(obj string) {
|
||||
_, _ = tmpWriteBuffer.Write([]byte(obj))
|
||||
_, _ = tmpWriteBuffer.Write([]byte("\n"))
|
||||
}, funcr.Options{Verbosity: tc.v})
|
||||
ctx := klog.NewContext(context.Background(), logger)
|
||||
expectOutput = tc.expectedJSONLines
|
||||
r, err := http.NewRequestWithContext(ctx, method, rawURL, nil)
|
||||
if err != nil {
|
||||
t.Fatalf("unexpected error constructing the HTTP request: %v", err)
|
||||
}
|
||||
req = r
|
||||
} else {
|
||||
// Intentionally no context, as before.
|
||||
req = &http.Request{
|
||||
Method: method,
|
||||
URL: parsedURL,
|
||||
}
|
||||
}
|
||||
req.Header = header
|
||||
|
||||
// execute the round tripper
|
||||
rt := &testRoundTripper{
|
||||
Response: res,
|
||||
}
|
||||
NewDebuggingRoundTripper(rt, tc.levels...).RoundTrip(req)
|
||||
// execute the round tripper
|
||||
rt := &testRoundTripper{
|
||||
Response: res,
|
||||
}
|
||||
if len(tc.levels) == 1 && tc.levels[0] == DebugByContext {
|
||||
DebugWrappers(rt).RoundTrip(req)
|
||||
} else {
|
||||
NewDebuggingRoundTripper(rt, tc.levels...).RoundTrip(req)
|
||||
}
|
||||
|
||||
// call Flush to ensure the text isn't still buffered
|
||||
klog.Flush()
|
||||
// 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)
|
||||
// check if klog's output contains the expected lines
|
||||
actual := tmpWriteBuffer.String()
|
||||
|
||||
// funcr writes a map in non-deterministic order.
|
||||
// Fix that up before comparison.
|
||||
actual = strings.ReplaceAll(actual, reqHeaderJSONReversed, reqHeaderJSON)
|
||||
|
||||
for _, expected := range expectOutput {
|
||||
if !strings.Contains(actual, expected) {
|
||||
t.Errorf("verbosity %d: expected this substring:\n%s\n\ngot:\n%s", tc.v, expected, actual)
|
||||
}
|
||||
}
|
||||
// These test cases describe all expected lines. Split the log output
|
||||
// into log entries and compare their number.
|
||||
entries := regexp.MustCompile(`(?m)^[I{]`).FindAllStringIndex(actual, -1)
|
||||
if tc.v > 0 && len(entries) != len(expectOutput) {
|
||||
t.Errorf("expected %d output lines, got %d:\n%s", len(expectOutput), len(entries), actual)
|
||||
}
|
||||
|
||||
state.Restore()
|
||||
})
|
||||
}
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
@@ -182,7 +182,10 @@ func (ts *cachingTokenSource) Token() (*oauth2.Token, error) {
|
||||
if ts.tok == nil {
|
||||
return nil, err
|
||||
}
|
||||
klog.Errorf("Unable to rotate token: %v", err)
|
||||
// Not using a caller-provided logger isn't ideal, but impossible to fix
|
||||
// without new APIs that go up all the way to HTTPWrappersForConfig.
|
||||
// This is currently deemed not worth changing (too much effort, not enough benefit).
|
||||
klog.TODO().Error(err, "Unable to rotate token")
|
||||
return ts.tok, nil
|
||||
}
|
||||
|
||||
|
||||
@@ -353,7 +353,7 @@ func tryCancelRequest(rt http.RoundTripper, req *http.Request) {
|
||||
case utilnet.RoundTripperWrapper:
|
||||
tryCancelRequest(rt.WrappedRoundTripper(), req)
|
||||
default:
|
||||
klog.Warningf("Unable to cancel request for %T", rt)
|
||||
klog.FromContext(req.Context()).Info("Warning: unable to cancel request", "roundTripperType", fmt.Sprintf("%T", rt))
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user