From adb083bc7aae666424a4cb1032e4ccc502118ca1 Mon Sep 17 00:00:00 2001 From: Hidde Beydals Date: Wed, 24 Mar 2021 00:58:50 +0100 Subject: [PATCH] Capture (debug) logs from Helm actions Signed-off-by: Hidde Beydals --- controllers/helmrelease_controller.go | 17 +++-- internal/runner/log_buffer.go | 91 +++++++++++++++++++++++ internal/runner/log_buffer_test.go | 103 ++++++++++++++++++++++++++ internal/runner/runner.go | 73 ++++++++++++++---- 4 files changed, 264 insertions(+), 20 deletions(-) create mode 100644 internal/runner/log_buffer.go create mode 100644 internal/runner/log_buffer_test.go diff --git a/controllers/helmrelease_controller.go b/controllers/helmrelease_controller.go index 029a963a9..6d0e5f419 100644 --- a/controllers/helmrelease_controller.go +++ b/controllers/helmrelease_controller.go @@ -328,14 +328,14 @@ func (r *HelmReleaseReconciler) reconcileRelease(ctx context.Context, // Fail if install retries are exhausted. if hr.Spec.GetInstall().GetRemediation().RetriesExhausted(hr) { err = fmt.Errorf("install retries exhausted") - return v2.HelmReleaseNotReady(hr, released.Reason, released.Message), err + return v2.HelmReleaseNotReady(hr, released.Reason, err.Error()), err } // Fail if there is a release and upgrade retries are exhausted. // This avoids failing after an upgrade uninstall remediation strategy. if rel != nil && hr.Spec.GetUpgrade().GetRemediation().RetriesExhausted(hr) { err = fmt.Errorf("upgrade retries exhausted") - return v2.HelmReleaseNotReady(hr, released.Reason, released.Message), err + return v2.HelmReleaseNotReady(hr, released.Reason, err.Error()), err } } @@ -415,9 +415,8 @@ func (r *HelmReleaseReconciler) reconcileRelease(ctx context.Context, if err != nil { reason := meta.ReconciliationFailedReason - var cerr *ConditionError - if errors.As(err, &cerr) { - reason = cerr.Reason + if condErr := (*ConditionError)(nil); errors.As(err, &condErr) { + reason = condErr.Reason } return v2.HelmReleaseNotReady(hr, reason, err.Error()), err } @@ -662,10 +661,14 @@ func (r *HelmReleaseReconciler) reconcileDelete(ctx context.Context, hr v2.HelmR func (r *HelmReleaseReconciler) handleHelmActionResult(ctx context.Context, hr *v2.HelmRelease, revision string, err error, action string, condition string, succeededReason string, failedReason string) error { if err != nil { - msg := fmt.Sprintf("Helm %s failed: %s", action, err.Error()) + err = fmt.Errorf("Helm %s failed: %w", action, err) + msg := err.Error() + if actionErr := (*runner.ActionError)(nil); errors.As(err, &actionErr) { + msg = msg + "\n\nLast Helm logs:\n\n" + actionErr.CapturedLogs + } meta.SetResourceCondition(hr, condition, metav1.ConditionFalse, failedReason, msg) r.event(ctx, *hr, revision, events.EventSeverityError, msg) - return &ConditionError{Reason: failedReason, Err: errors.New(msg)} + return &ConditionError{Reason: failedReason, Err: err} } else { msg := fmt.Sprintf("Helm %s succeeded", action) meta.SetResourceCondition(hr, condition, metav1.ConditionTrue, succeededReason, msg) diff --git a/internal/runner/log_buffer.go b/internal/runner/log_buffer.go new file mode 100644 index 000000000..fa5039755 --- /dev/null +++ b/internal/runner/log_buffer.go @@ -0,0 +1,91 @@ +/* +Copyright 2021 The Flux authors + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package runner + +import ( + "container/ring" + "fmt" + "strings" + "sync" + + "github.com/go-logr/logr" + "helm.sh/helm/v3/pkg/action" +) + +const defaultBufferSize = 5 + +type DebugLog struct { + log logr.Logger +} + +func NewDebugLog(log logr.Logger) *DebugLog { + return &DebugLog{log: log} +} + +func (l *DebugLog) Log(format string, v ...interface{}) { + l.log.V(1).Info(fmt.Sprintf(format, v...)) +} + +type LogBuffer struct { + mu sync.Mutex + log action.DebugLog + buffer *ring.Ring +} + +func NewLogBuffer(log action.DebugLog, size int) *LogBuffer { + if size == 0 { + size = defaultBufferSize + } + return &LogBuffer{ + log: log, + buffer: ring.New(size), + } +} + +func (l *LogBuffer) Log(format string, v ...interface{}) { + l.mu.Lock() + + // Filter out duplicate log lines, this happens for example when + // Helm is waiting on workloads to become ready. + msg := fmt.Sprintf(format, v...) + if prev := l.buffer.Prev(); prev.Value != msg { + l.buffer.Value = msg + l.buffer = l.buffer.Next() + } + + l.mu.Unlock() + l.log(format, v...) +} + +func (l *LogBuffer) Reset() { + l.mu.Lock() + l.buffer = ring.New(l.buffer.Len()) + l.mu.Unlock() +} + +func (l *LogBuffer) String() string { + var str string + l.mu.Lock() + l.buffer.Do(func(s interface{}) { + if s == nil { + return + } + str += s.(string) + "\n" + }) + l.mu.Unlock() + return strings.TrimSpace(str) +} diff --git a/internal/runner/log_buffer_test.go b/internal/runner/log_buffer_test.go new file mode 100644 index 000000000..34537c559 --- /dev/null +++ b/internal/runner/log_buffer_test.go @@ -0,0 +1,103 @@ +/* +Copyright 2021 The Flux authors + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package runner + +import ( + "testing" + + "sigs.k8s.io/controller-runtime/pkg/log" +) + +func TestLogBuffer_Log(t *testing.T) { + tests := []struct { + name string + size int + fill []string + wantCount int + want string + }{ + {name: "log", size: 2, fill: []string{"a", "b", "c"}, wantCount: 3, want: "b\nc"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var count int + l := NewLogBuffer(func(format string, v ...interface{}) { + count++ + return + }, tt.size) + for _, v := range tt.fill { + l.Log("%s", v) + } + if count != tt.wantCount { + t.Errorf("Inner Log() called %v times, want %v", count, tt.wantCount) + } + if got := l.String(); got != tt.want { + t.Errorf("String() = %v, want %v", got, tt.want) + } + }) + } +} + +func TestLogBuffer_Reset(t *testing.T) { + bufferSize := 10 + l := NewLogBuffer(NewDebugLog(log.NullLogger{}).Log, bufferSize) + + if got := l.buffer.Len(); got != bufferSize { + t.Errorf("Len() = %v, want %v", got, bufferSize) + } + + for _, v := range []string{"a", "b", "c"} { + l.Log("%s", v) + } + + if got := l.String(); got == "" { + t.Errorf("String() = empty") + } + + l.Reset() + + if got := l.buffer.Len(); got != bufferSize { + t.Errorf("Len() = %v after Reset(), want %v", got, bufferSize) + } + if got := l.String(); got != "" { + t.Errorf("String() != empty after Reset()") + } +} + +func TestLogBuffer_String(t *testing.T) { + tests := []struct { + name string + size int + fill []string + want string + }{ + {name: "empty buffer", fill: []string{}, want: ""}, + {name: "filled buffer", size: 2, fill: []string{"a", "b", "c"}, want: "b\nc"}, + {name: "duplicate buffer items", fill: []string{"b", "b", "b"}, want: "b"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + l := NewLogBuffer(NewDebugLog(log.NullLogger{}).Log, tt.size) + for _, v := range tt.fill { + l.Log("%s", v) + } + if got := l.String(); got != tt.want { + t.Errorf("String() = %v, want %v", got, tt.want) + } + }) + } +} diff --git a/internal/runner/runner.go b/internal/runner/runner.go index 111844a6f..f5282fa49 100644 --- a/internal/runner/runner.go +++ b/internal/runner/runner.go @@ -18,7 +18,7 @@ package runner import ( "errors" - "fmt" + "sync" "github.com/go-logr/logr" "helm.sh/helm/v3/pkg/action" @@ -32,21 +32,39 @@ import ( v2 "github.com/fluxcd/helm-controller/api/v2beta1" ) +type ActionError struct { + Err error + CapturedLogs string +} + +func (e ActionError) Error() string { + return e.Err.Error() +} + +func (e ActionError) Unwrap() error { + return e.Err +} + // Runner represents a Helm action runner capable of performing Helm // operations for a v2beta1.HelmRelease. type Runner struct { - config *action.Configuration + mu sync.Mutex + config *action.Configuration + logBuffer *LogBuffer } // NewRunner constructs a new Runner configured to run Helm actions with the // given genericclioptions.RESTClientGetter, and the release and storage // namespace configured to the provided values. func NewRunner(getter genericclioptions.RESTClientGetter, storageNamespace string, logger logr.Logger) (*Runner, error) { - cfg := new(action.Configuration) - if err := cfg.Init(getter, storageNamespace, "secret", debugLogger(logger)); err != nil { + runner := &Runner{ + logBuffer: NewLogBuffer(NewDebugLog(logger).Log, 0), + } + runner.config = new(action.Configuration) + if err := runner.config.Init(getter, storageNamespace, "secret", runner.logBuffer.Log); err != nil { return nil, err } - return &Runner{config: cfg}, nil + return runner, nil } // Create post renderer instances from HelmRelease and combine them into @@ -67,6 +85,10 @@ func postRenderers(hr v2.HelmRelease) (postrender.PostRenderer, error) { // Install runs an Helm install action for the given v2beta1.HelmRelease. func (r *Runner) Install(hr v2.HelmRelease, chart *chart.Chart, values chartutil.Values) (*release.Release, error) { + r.mu.Lock() + defer r.mu.Unlock() + defer r.logBuffer.Reset() + install := action.NewInstall(r.config) install.ReleaseName = hr.GetReleaseName() install.Namespace = hr.GetReleaseNamespace() @@ -86,11 +108,16 @@ func (r *Runner) Install(hr v2.HelmRelease, chart *chart.Chart, values chartutil install.CreateNamespace = hr.Spec.GetInstall().CreateNamespace } - return install.Run(chart, values.AsMap()) + rel, err := install.Run(chart, values.AsMap()) + return rel, wrapActionErr(r.logBuffer, err) } // Upgrade runs an Helm upgrade action for the given v2beta1.HelmRelease. func (r *Runner) Upgrade(hr v2.HelmRelease, chart *chart.Chart, values chartutil.Values) (*release.Release, error) { + r.mu.Lock() + defer r.mu.Unlock() + defer r.logBuffer.Reset() + upgrade := action.NewUpgrade(r.config) upgrade.Namespace = hr.GetReleaseNamespace() upgrade.ResetValues = !hr.Spec.GetUpgrade().PreserveValues @@ -108,20 +135,30 @@ func (r *Runner) Upgrade(hr v2.HelmRelease, chart *chart.Chart, values chartutil } upgrade.PostRenderer = renderer - return upgrade.Run(hr.GetReleaseName(), chart, values.AsMap()) + rel, err := upgrade.Run(hr.GetReleaseName(), chart, values.AsMap()) + return rel, wrapActionErr(r.logBuffer, err) } // Test runs an Helm test action for the given v2beta1.HelmRelease. func (r *Runner) Test(hr v2.HelmRelease) (*release.Release, error) { + r.mu.Lock() + defer r.mu.Unlock() + defer r.logBuffer.Reset() + test := action.NewReleaseTesting(r.config) test.Namespace = hr.GetReleaseNamespace() test.Timeout = hr.Spec.GetTest().GetTimeout(hr.GetTimeout()).Duration - return test.Run(hr.GetReleaseName()) + rel, err := test.Run(hr.GetReleaseName()) + return rel, wrapActionErr(r.logBuffer, err) } // Rollback runs an Helm rollback action for the given v2beta1.HelmRelease. func (r *Runner) Rollback(hr v2.HelmRelease) error { + r.mu.Lock() + defer r.mu.Unlock() + defer r.logBuffer.Reset() + rollback := action.NewRollback(r.config) rollback.Timeout = hr.Spec.GetRollback().GetTimeout(hr.GetTimeout()).Duration rollback.Wait = !hr.Spec.GetRollback().DisableWait @@ -130,18 +167,23 @@ func (r *Runner) Rollback(hr v2.HelmRelease) error { rollback.Recreate = hr.Spec.GetRollback().Recreate rollback.CleanupOnFail = hr.Spec.GetRollback().CleanupOnFail - return rollback.Run(hr.GetReleaseName()) + err := rollback.Run(hr.GetReleaseName()) + return wrapActionErr(r.logBuffer, err) } // Uninstall runs an Helm uninstall action for the given v2beta1.HelmRelease. func (r *Runner) Uninstall(hr v2.HelmRelease) error { + r.mu.Lock() + defer r.mu.Unlock() + defer r.logBuffer.Reset() + uninstall := action.NewUninstall(r.config) uninstall.Timeout = hr.Spec.GetUninstall().GetTimeout(hr.GetTimeout()).Duration uninstall.DisableHooks = hr.Spec.GetUninstall().DisableHooks uninstall.KeepHistory = hr.Spec.GetUninstall().KeepHistory _, err := uninstall.Run(hr.GetReleaseName()) - return err + return wrapActionErr(r.logBuffer, err) } // ObserveLastRelease observes the last revision, if there is one, @@ -154,8 +196,13 @@ func (r *Runner) ObserveLastRelease(hr v2.HelmRelease) (*release.Release, error) return rel, err } -func debugLogger(logger logr.Logger) func(format string, v ...interface{}) { - return func(format string, v ...interface{}) { - logger.V(1).Info(fmt.Sprintf(format, v...)) +func wrapActionErr(log *LogBuffer, err error) error { + if err == nil { + return err + } + err = &ActionError{ + Err: err, + CapturedLogs: log.String(), } + return err }