Capture and expose debug (log) information on release failure

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)

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)
+}

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)
+			}
+		})
+	}
+}