change terraform download warning to debug log

hugodutka · hugodutka · commit 3ad90cd33d4f · 2025-02-20T12:39:43.000Z
diff --git a/provisioner/terraform/install.go b/provisioner/terraform/install.go
@@ -2,8 +2,10 @@ package terraform
 
 import (
 	"context"
+	"fmt"
 	"os"
 	"path/filepath"
+	"sync/atomic"
 	"time"
 
 	"github.com/gofrs/flock"
@@ -30,7 +32,9 @@ var (
 
 // Install implements a thread-safe, idempotent Terraform Install
 // operation.
-func Install(ctx context.Context, log slog.Logger, dir string, wantVersion *version.Version) (string, error) {
+//
+//nolint:revive // verbose is a control flag that controls the verbosity of the log output.
+func Install(ctx context.Context, log slog.Logger, verbose bool, dir string, wantVersion *version.Version) (string, error) {
 	err := os.MkdirAll(dir, 0o750)
 	if err != nil {
 		return "", err
@@ -64,13 +68,37 @@ func Install(ctx context.Context, log slog.Logger, dir string, wantVersion *vers
 		Version:    TerraformVersion,
 	}
 	installer.SetLogger(slog.Stdlib(ctx, log, slog.LevelDebug))
-	log.Debug(
-		ctx,
-		"installing terraform",
+
+	logInstall := log.Debug
+	if verbose {
+		logInstall = log.Info
+	}
+
+	logInstall(ctx, "installing terraform",
 		slog.F("prev_version", hasVersionStr),
 		slog.F("dir", dir),
-		slog.F("version", TerraformVersion),
-	)
+		slog.F("version", TerraformVersion))
+
+	prolongedInstall := atomic.Bool{}
+	prolongedInstallCtx, prolongedInstallCancel := context.WithCancel(ctx)
+	go func() {
+		seconds := 15
+		select {
+		case <-time.After(time.Duration(seconds) * time.Second):
+			prolongedInstall.Store(true)
+			// We always want to log this at the info level.
+			log.Info(
+				prolongedInstallCtx,
+				fmt.Sprintf("terraform installation is taking longer than %d seconds, still in progress", seconds),
+				slog.F("prev_version", hasVersionStr),
+				slog.F("dir", dir),
+				slog.F("version", TerraformVersion),
+			)
+		case <-prolongedInstallCtx.Done():
+			return
+		}
+	}()
+	defer prolongedInstallCancel()
 
 	path, err := installer.Install(ctx)
 	if err != nil {
@@ -83,5 +111,9 @@ func Install(ctx context.Context, log slog.Logger, dir string, wantVersion *vers
 		return "", xerrors.Errorf("%s should be %s", path, binPath)
 	}
 
+	if prolongedInstall.Load() {
+		log.Info(ctx, "terraform installation complete")
+	}
+
 	return path, nil
 }
diff --git a/provisioner/terraform/install_test.go b/provisioner/terraform/install_test.go
@@ -40,7 +40,7 @@ func TestInstall(t *testing.T) {
 			wg.Add(1)
 			go func() {
 				defer wg.Done()
-				p, err := terraform.Install(ctx, log, dir, version)
+				p, err := terraform.Install(ctx, log, false, dir, version)
 				assert.NoError(t, err)
 				paths <- p
 			}()
diff --git a/provisioner/terraform/serve.go b/provisioner/terraform/serve.go
@@ -41,7 +41,8 @@ type ServeOptions struct {
 	ExitTimeout time.Duration
 }
 
-func absoluteBinaryPath(ctx context.Context, logger slog.Logger) (string, error) {
+// nolint:revive // verbose is a control flag that controls the verbosity of the log output.
+func absoluteBinaryPath(ctx context.Context, logger slog.Logger, verbose bool) (string, error) {
 	binaryPath, err := safeexec.LookPath("terraform")
 	if err != nil {
 		return "", xerrors.Errorf("Terraform binary not found: %w", err)
@@ -63,7 +64,12 @@ func absoluteBinaryPath(ctx context.Context, logger slog.Logger) (string, error)
 		return "", xerrors.Errorf("Terraform binary get version failed: %w", err)
 	}
 
-	logger.Info(ctx, "detected terraform version",
+	logVersion := logger.Debug
+	if verbose {
+		logVersion = logger.Info
+	}
+
+	logVersion(ctx, "detected terraform version",
 		slog.F("installed_version", installedVersion.String()),
 		slog.F("min_version", minTerraformVersion.String()),
 		slog.F("max_version", maxTerraformVersion.String()))
@@ -88,7 +94,7 @@ func absoluteBinaryPath(ctx context.Context, logger slog.Logger) (string, error)
 // Serve starts a dRPC server on the provided transport speaking Terraform provisioner.
 func Serve(ctx context.Context, options *ServeOptions) error {
 	if options.BinaryPath == "" {
-		absoluteBinary, err := absoluteBinaryPath(ctx, options.Logger)
+		absoluteBinary, err := absoluteBinaryPath(ctx, options.Logger, options.ExternalProvisioner)
 		if err != nil {
 			// This is an early exit to prevent extra execution in case the context is canceled.
 			// It generally happens in unit tests since this method is asynchronous and
@@ -97,10 +103,7 @@ func Serve(ctx context.Context, options *ServeOptions) error {
 				return xerrors.Errorf("absolute binary context canceled: %w", err)
 			}
 
-			options.Logger.Warn(ctx, "no usable terraform binary found, downloading to cache dir",
-				slog.F("terraform_version", TerraformVersion.String()),
-				slog.F("cache_dir", options.CachePath))
-			binPath, err := Install(ctx, options.Logger, options.CachePath, TerraformVersion)
+			binPath, err := Install(ctx, options.Logger, options.ExternalProvisioner, options.CachePath, TerraformVersion)
 			if err != nil {
 				return xerrors.Errorf("install terraform: %w", err)
 			}
diff --git a/provisioner/terraform/serve_internal_test.go b/provisioner/terraform/serve_internal_test.go
@@ -85,7 +85,7 @@ func Test_absoluteBinaryPath(t *testing.T) {
 			}
 
 			ctx := testutil.Context(t, testutil.WaitShort)
-			actualAbsoluteBinary, actualErr := absoluteBinaryPath(ctx, log)
+			actualAbsoluteBinary, actualErr := absoluteBinaryPath(ctx, log, false)
 
 			require.Equal(t, expectedAbsoluteBinary, actualAbsoluteBinary)
 			if tt.expectedErr == nil {

Original file line number	Diff line number	Diff line change
`@@ -85,7 +85,7 @@ func Test_absoluteBinaryPath(t *testing.T) {`
`85`	`85`	`}`
`86`	`86`
`87`	`87`	`ctx := testutil.Context(t, testutil.WaitShort)`
`88`		`- actualAbsoluteBinary, actualErr := absoluteBinaryPath(ctx, log)`
	`88`	`+ actualAbsoluteBinary, actualErr := absoluteBinaryPath(ctx, log, false)`
`89`	`89`
`90`	`90`	`require.Equal(t, expectedAbsoluteBinary, actualAbsoluteBinary)`
`91`	`91`	`if tt.expectedErr == nil {`