Skip to content

Commit 19292d4

Browse files
author
Paulo Gomes
authored
Merge pull request #778 from pjbgf/improved-logging
libgit2: add contextual logging to subtransports
2 parents 7a797e3 + 42dcb87 commit 19292d4

File tree

14 files changed

+131
-51
lines changed

14 files changed

+131
-51
lines changed

‎controllers/bucket_controller.go‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@ import (
3434
corev1 "k8s.io/api/core/v1"
3535
"k8s.io/apimachinery/pkg/runtime"
3636
"k8s.io/apimachinery/pkg/types"
37+
"k8s.io/apimachinery/pkg/util/uuid"
3738
kuberecorder "k8s.io/client-go/tools/record"
3839
ctrl "sigs.k8s.io/controller-runtime"
3940
"sigs.k8s.io/controller-runtime/pkg/client"
@@ -246,7 +247,13 @@ func (r *BucketReconciler) SetupWithManagerAndOptions(mgr ctrl.Manager, opts Buc
246247

247248
func (r *BucketReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, retErr error) {
248249
start := time.Now()
249-
log := ctrl.LoggerFrom(ctx)
250+
log := ctrl.LoggerFrom(ctx).
251+
// Sets a reconcile ID to correlate logs from all suboperations.
252+
WithValues("reconcileID", uuid.NewUUID())
253+
254+
// logger will be associated to the new context that is
255+
// returned from ctrl.LoggerInto.
256+
ctx = ctrl.LoggerInto(ctx, log)
250257

251258
// Fetch the Bucket
252259
obj := &sourcev1.Bucket{}

‎controllers/gitrepository_controller.go‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ import (
3232
corev1 "k8s.io/api/core/v1"
3333
"k8s.io/apimachinery/pkg/runtime"
3434
"k8s.io/apimachinery/pkg/types"
35+
"k8s.io/apimachinery/pkg/util/uuid"
3536
kuberecorder "k8s.io/client-go/tools/record"
3637
ctrl "sigs.k8s.io/controller-runtime"
3738
"sigs.k8s.io/controller-runtime/pkg/builder"
@@ -159,7 +160,13 @@ func (r *GitRepositoryReconciler) SetupWithManagerAndOptions(mgr ctrl.Manager, o
159160

160161
func (r *GitRepositoryReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, retErr error) {
161162
start := time.Now()
162-
log := ctrl.LoggerFrom(ctx)
163+
log := ctrl.LoggerFrom(ctx).
164+
// Sets a reconcile ID to correlate logs from all suboperations.
165+
WithValues("reconcileID", uuid.NewUUID())
166+
167+
// logger will be associated to the new context that is
168+
// returned from ctrl.LoggerInto.
169+
ctx = ctrl.LoggerInto(ctx, log)
163170

164171
// Fetch the GitRepository
165172
obj := &sourcev1.GitRepository{}

‎controllers/helmchart_controller.go‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,7 @@ import (
3535
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
3636
"k8s.io/apimachinery/pkg/runtime"
3737
"k8s.io/apimachinery/pkg/types"
38+
"k8s.io/apimachinery/pkg/util/uuid"
3839
kuberecorder "k8s.io/client-go/tools/record"
3940
ctrl "sigs.k8s.io/controller-runtime"
4041
"sigs.k8s.io/controller-runtime/pkg/builder"
@@ -180,7 +181,13 @@ func (r *HelmChartReconciler) SetupWithManagerAndOptions(mgr ctrl.Manager, opts
180181

181182
func (r *HelmChartReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, retErr error) {
182183
start := time.Now()
183-
log := ctrl.LoggerFrom(ctx)
184+
log := ctrl.LoggerFrom(ctx).
185+
// Sets a reconcile ID to correlate logs from all suboperations.
186+
WithValues("reconcileID", uuid.NewUUID())
187+
188+
// logger will be associated to the new context that is
189+
// returned from ctrl.LoggerInto.
190+
ctx = ctrl.LoggerInto(ctx, log)
184191

185192
// Fetch the HelmChart
186193
obj := &sourcev1.HelmChart{}

‎controllers/helmrepository_controller.go‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@ import (
2929
corev1 "k8s.io/api/core/v1"
3030
"k8s.io/apimachinery/pkg/runtime"
3131
"k8s.io/apimachinery/pkg/types"
32+
"k8s.io/apimachinery/pkg/util/uuid"
3233
kuberecorder "k8s.io/client-go/tools/record"
3334
ctrl "sigs.k8s.io/controller-runtime"
3435
"sigs.k8s.io/controller-runtime/pkg/client"
@@ -142,7 +143,13 @@ func (r *HelmRepositoryReconciler) SetupWithManagerAndOptions(mgr ctrl.Manager,
142143

143144
func (r *HelmRepositoryReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, retErr error) {
144145
start := time.Now()
145-
log := ctrl.LoggerFrom(ctx)
146+
log := ctrl.LoggerFrom(ctx).
147+
// Sets a reconcile ID to correlate logs from all suboperations.
148+
WithValues("reconcileID", uuid.NewUUID())
149+
150+
// logger will be associated to the new context that is
151+
// returned from ctrl.LoggerInto.
152+
ctx = ctrl.LoggerInto(ctx, log)
146153

147154
// Fetch the HelmRepository
148155
obj := &sourcev1.HelmRepository{}

‎controllers/helmrepository_controller_oci.go‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ import (
3232
"k8s.io/apimachinery/pkg/runtime"
3333
"k8s.io/apimachinery/pkg/types"
3434
kerrors "k8s.io/apimachinery/pkg/util/errors"
35+
"k8s.io/apimachinery/pkg/util/uuid"
3536
kuberecorder "k8s.io/client-go/tools/record"
3637
ctrl "sigs.k8s.io/controller-runtime"
3738
"sigs.k8s.io/controller-runtime/pkg/client"
@@ -107,7 +108,13 @@ func (r *HelmRepositoryOCIReconciler) SetupWithManagerAndOptions(mgr ctrl.Manage
107108

108109
func (r *HelmRepositoryOCIReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, retErr error) {
109110
start := time.Now()
110-
log := ctrl.LoggerFrom(ctx)
111+
log := ctrl.LoggerFrom(ctx).
112+
// Sets a reconcile ID to correlate logs from all suboperations.
113+
WithValues("reconcileID", uuid.NewUUID())
114+
115+
// logger will be associated to the new context that is
116+
// returned from ctrl.LoggerInto.
117+
ctx = ctrl.LoggerInto(ctx, log)
111118

112119
// Fetch the HelmRepository
113120
obj := &sourcev1.HelmRepository{}

‎controllers/suite_test.go‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -40,7 +40,6 @@ import (
4040
feathelper "github.com/fluxcd/pkg/runtime/features"
4141
"github.com/fluxcd/pkg/runtime/testenv"
4242
"github.com/fluxcd/pkg/testserver"
43-
"github.com/go-logr/logr"
4443
"github.com/phayes/freeport"
4544

4645
"github.com/distribution/distribution/v3/configuration"
@@ -209,7 +208,7 @@ func TestMain(m *testing.M) {
209208

210209
fg := feathelper.FeatureGates{}
211210
fg.SupportedFeatures(features.FeatureGates())
212-
managed.InitManagedTransport(logr.Discard())
211+
managed.InitManagedTransport()
213212

214213
if err := (&GitRepositoryReconciler{
215214
Client: testEnv,

‎main.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -311,7 +311,7 @@ func main() {
311311
}()
312312

313313
if enabled, _ := features.Enabled(features.GitManagedTransport); enabled {
314-
managed.InitManagedTransport(ctrl.Log.WithName("managed-transport"))
314+
managed.InitManagedTransport()
315315
} else {
316316
if optimize, _ := feathelper.Enabled(features.OptimizedGitClones); optimize {
317317
features.Disable(features.OptimizedGitClones)

‎pkg/git/libgit2/managed/http.go‎

Lines changed: 42 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,7 @@ package managed
4545

4646
import (
4747
"bytes"
48+
"context"
4849
"crypto/tls"
4950
"crypto/x509"
5051
"errors"
@@ -55,9 +56,12 @@ import (
5556
"strings"
5657
"sync"
5758

59+
"github.com/fluxcd/pkg/runtime/logger"
5860
pool "github.com/fluxcd/source-controller/internal/transport"
5961
"github.com/fluxcd/source-controller/pkg/git"
62+
"github.com/go-logr/logr"
6063
git2go "github.com/libgit2/git2go/v33"
64+
ctrl "sigs.k8s.io/controller-runtime"
6165
)
6266

6367
var actionSuffixes = []string{
@@ -81,10 +85,11 @@ func registerManagedHTTP() error {
8185
}
8286

8387
func httpSmartSubtransportFactory(remote *git2go.Remote, transport *git2go.Transport) (git2go.SmartSubtransport, error) {
84-
traceLog.Info("[http]: httpSmartSubtransportFactory")
8588
sst := &httpSmartSubtransport{
8689
transport: transport,
8790
httpTransport: pool.NewOrIdle(nil),
91+
ctx: context.Background(),
92+
logger: logr.Discard(),
8893
}
8994

9095
return sst, nil
@@ -93,6 +98,21 @@ func httpSmartSubtransportFactory(remote *git2go.Remote, transport *git2go.Trans
9398
type httpSmartSubtransport struct {
9499
transport *git2go.Transport
95100
httpTransport *http.Transport
101+
102+
// once is used to ensure that logger and ctx is set only once,
103+
// on the initial (or only) Action call. Without this a mutex must
104+
// be applied to ensure that ctx won't be changed, as this would be
105+
// prone to race conditions in the stdout processing goroutine.
106+
once sync.Once
107+
// ctx defines the context to be used across long-running or
108+
// cancellable operations.
109+
// Defaults to context.Background().
110+
ctx context.Context
111+
// logger keeps a Logger instance for logging. This was preferred
112+
// due to the need to have a correlation ID and URL set and
113+
// reused across all log calls.
114+
// If context is not set, this defaults to logr.Discard().
115+
logger logr.Logger
96116
}
97117

98118
func (t *httpSmartSubtransport) Action(transportOptionsURL string, action git2go.SmartServiceAction) (git2go.SmartSubtransportStream, error) {
@@ -133,6 +153,15 @@ func (t *httpSmartSubtransport) Action(transportOptionsURL string, action git2go
133153
}
134154
t.httpTransport.DisableCompression = false
135155

156+
t.once.Do(func() {
157+
if opts.Context != nil {
158+
t.ctx = opts.Context
159+
t.logger = ctrl.LoggerFrom(t.ctx,
160+
"transportType", "http",
161+
"url", opts.TargetURL)
162+
}
163+
})
164+
136165
client, req, err := createClientRequest(targetURL, action, t.httpTransport, opts.AuthOpts)
137166
if err != nil {
138167
return nil, err
@@ -176,8 +205,10 @@ func (t *httpSmartSubtransport) Action(transportOptionsURL string, action git2go
176205
opts.TargetURL = trimActionSuffix(newURL.String())
177206
AddTransportOptions(transportOptionsURL, *opts)
178207

179-
debugLog.Info("[http]: server responded with redirect",
180-
"newURL", opts.TargetURL, "StatusCode", req.Response.StatusCode)
208+
// show as info, as this should be visible regardless of the
209+
// chosen log-level.
210+
t.logger.Info("server responded with redirect",
211+
"newUrl", opts.TargetURL, "StatusCode", req.Response.StatusCode)
181212
}
182213
}
183214
}
@@ -270,15 +301,16 @@ func createClientRequest(targetURL string, action git2go.SmartServiceAction,
270301
}
271302

272303
func (t *httpSmartSubtransport) Close() error {
273-
traceLog.Info("[http]: httpSmartSubtransport.Close()")
304+
t.logger.V(logger.TraceLevel).Info("httpSmartSubtransport.Close()")
274305
return nil
275306
}
276307

277308
func (t *httpSmartSubtransport) Free() {
278-
traceLog.Info("[http]: httpSmartSubtransport.Free()")
309+
t.logger.V(logger.TraceLevel).Info("httpSmartSubtransport.Free()")
279310

280311
if t.httpTransport != nil {
281-
traceLog.Info("[http]: release http transport back to pool")
312+
t.logger.V(logger.TraceLevel).Info("release http transport back to pool")
313+
282314
pool.Release(t.httpTransport)
283315
t.httpTransport = nil
284316
}
@@ -345,18 +377,18 @@ func (self *httpSmartSubtransportStream) Write(buf []byte) (int, error) {
345377

346378
func (self *httpSmartSubtransportStream) Free() {
347379
if self.resp != nil {
348-
traceLog.Info("[http]: httpSmartSubtransportStream.Free()")
380+
self.owner.logger.V(logger.TraceLevel).Info("httpSmartSubtransportStream.Free()")
349381

350382
if self.resp.Body != nil {
351383
// ensure body is fully processed and closed
352384
// for increased likelihood of transport reuse in HTTP/1.x.
353385
// it should not be a problem to do this more than once.
354386
if _, err := io.Copy(io.Discard, self.resp.Body); err != nil {
355-
traceLog.Error(err, "[http]: cannot discard response body")
387+
self.owner.logger.V(logger.TraceLevel).Error(err, "cannot discard response body")
356388
}
357389

358390
if err := self.resp.Body.Close(); err != nil {
359-
traceLog.Error(err, "[http]: cannot close response body")
391+
self.owner.logger.V(logger.TraceLevel).Error(err, "cannot close response body")
360392
}
361393
}
362394
}
@@ -399,7 +431,7 @@ func (self *httpSmartSubtransportStream) sendRequest() error {
399431
req.ContentLength = -1
400432
}
401433

402-
traceLog.Info("[http]: new request", "method", req.Method, "URL", req.URL)
434+
self.owner.logger.V(logger.TraceLevel).Info("new request", "method", req.Method, "postUrl", req.URL)
403435
resp, err = self.client.Do(req)
404436
if err != nil {
405437
return err

‎pkg/git/libgit2/managed/http_test.go‎

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,6 @@ import (
2525

2626
"github.com/fluxcd/pkg/gittestserver"
2727
"github.com/fluxcd/source-controller/pkg/git"
28-
"github.com/go-logr/logr"
2928
. "github.com/onsi/gomega"
3029

3130
git2go "github.com/libgit2/git2go/v33"
@@ -170,7 +169,7 @@ func TestHTTPManagedTransport_E2E(t *testing.T) {
170169
defer server.StopHTTP()
171170

172171
// Force managed transport to be enabled
173-
InitManagedTransport(logr.Discard())
172+
InitManagedTransport()
174173

175174
repoPath := "test.git"
176175
err = server.InitRepo("../../testdata/git/repo", git.DefaultBranch, repoPath)
@@ -253,7 +252,7 @@ func TestHTTPManagedTransport_HandleRedirect(t *testing.T) {
253252
}
254253

255254
// Force managed transport to be enabled
256-
InitManagedTransport(logr.Discard())
255+
InitManagedTransport()
257256

258257
for _, tt := range tests {
259258
t.Run(tt.name, func(t *testing.T) {

‎pkg/git/libgit2/managed/init.go‎

Lines changed: 2 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -19,9 +19,6 @@ package managed
1919
import (
2020
"sync"
2121
"time"
22-
23-
"github.com/fluxcd/pkg/runtime/logger"
24-
"github.com/go-logr/logr"
2522
)
2623

2724
var (
@@ -38,9 +35,7 @@ var (
3835
// handshake, put/get).
3936
fullHttpClientTimeOut time.Duration = 10 * time.Minute
4037

41-
debugLog logr.Logger
42-
traceLog logr.Logger
43-
enabled bool
38+
enabled bool
4439
)
4540

4641
// Enabled defines whether the use of Managed Transport is enabled which
@@ -63,14 +58,10 @@ func Enabled() bool {
6358
//
6459
// This function will only register managed transports once, subsequent calls
6560
// leads to no-op.
66-
func InitManagedTransport(log logr.Logger) error {
61+
func InitManagedTransport() error {
6762
var err error
6863

6964
once.Do(func() {
70-
log.Info("Initializing managed transport")
71-
debugLog = log.V(logger.DebugLevel)
72-
traceLog = log.V(logger.TraceLevel)
73-
7465
if err = registerManagedHTTP(); err != nil {
7566
return
7667
}

0 commit comments

Comments
 (0)