chore: reduce log volume on server startup (coder#16608)

Addresses coder#16231.

This PR reduces the volume of logs we print after server startup in
order to surface the web UI URL better.

Here are the logs after the changes a couple of seconds after starting
the server:

<img width="868" alt="Screenshot 2025-02-18 at 16 31 32"
src="https://github.com/user-attachments/assets/786dc4b8-7383-48c8-a5c3-a997c01ca915"
/>

The warning is due to running a development site-less build. It wouldn't
show in a release build.

Author: hugodutka

cli/server.go

@@ -938,7 +938,7 @@ func (r *RootCmd) Server(newAPI func(context.Context, *coderd.Options) (*coderd.
 				notificationReportGenerator := reports.NewReportGenerator(ctx, logger.Named("notifications.report_generator"), options.Database, options.NotificationsEnqueuer, quartz.NewReal())
 				defer notificationReportGenerator.Close()
 			} else {
-				cliui.Info(inv.Stdout, "Notifications are currently disabled as there are no configured delivery methods. See https://coder.com/docs/admin/monitoring/notifications#delivery-methods for more details.")
+				logger.Debug(ctx, "notifications are currently disabled as there are no configured delivery methods. See https://coder.com/docs/admin/monitoring/notifications#delivery-methods for more details")
 			}
 
 			// Since errCh only has one buffered slot, all routines

cli/server_test.go

@@ -25,6 +25,7 @@ import (
 	"runtime"
 	"strconv"
 	"strings"
+	"sync"
 	"sync/atomic"
 	"testing"
 	"time"
@@ -240,6 +241,70 @@ func TestServer(t *testing.T) {
 			t.Fatalf("expected postgres URL to start with \"postgres://\", got %q", got)
 		}
 	})
+	t.Run("SpammyLogs", func(t *testing.T) {
+		// The purpose of this test is to ensure we don't show excessive logs when the server starts.
+		t.Parallel()
+		inv, cfg := clitest.New(t,
+			"server",
+			"--in-memory",
+			"--http-address", ":0",
+			"--access-url", "http://localhost:3000/",
+			"--cache-dir", t.TempDir(),
+		)
+		stdoutRW := syncReaderWriter{}
+		stderrRW := syncReaderWriter{}
+		inv.Stdout = io.MultiWriter(os.Stdout, &stdoutRW)
+		inv.Stderr = io.MultiWriter(os.Stderr, &stderrRW)
+		clitest.Start(t, inv)
+
+		// Wait for startup
+		_ = waitAccessURL(t, cfg)
+
+		// Wait a bit for more logs to be printed.
+		time.Sleep(testutil.WaitShort)
+
+		// Lines containing these strings are printed because we're
+		// running the server with a test config. They wouldn't be
+		// normally shown to the user, so we'll ignore them.
+		ignoreLines := []string{
+			"isn't externally reachable",
+			"install.sh will be unavailable",
+			"telemetry disabled, unable to notify of security issues",
+		}
+
+		countLines := func(fullOutput string) int {
+			terminalWidth := 80
+			linesByNewline := strings.Split(fullOutput, "\n")
+			countByWidth := 0
+		lineLoop:
+			for _, line := range linesByNewline {
+				for _, ignoreLine := range ignoreLines {
+					if strings.Contains(line, ignoreLine) {
+						continue lineLoop
+					}
+				}
+				if line == "" {
+					// Empty lines take up one line.
+					countByWidth++
+				} else {
+					countByWidth += (len(line) + terminalWidth - 1) / terminalWidth
+				}
+			}
+			return countByWidth
+		}
+
+		stdout, err := io.ReadAll(&stdoutRW)
+		if err != nil {
+			t.Fatalf("failed to read stdout: %v", err)
+		}
+		stderr, err := io.ReadAll(&stderrRW)
+		if err != nil {
+			t.Fatalf("failed to read stderr: %v", err)
+		}
+
+		numLines := countLines(string(stdout)) + countLines(string(stderr))
+		require.Less(t, numLines, 20)
+	})
 
 	// Validate that a warning is printed that it may not be externally
 	// reachable.
@@ -2140,3 +2205,22 @@ func mockTelemetryServer(t *testing.T) (*url.URL, chan *telemetry.Deployment, ch
 
 	return serverURL, deployment, snapshot
 }
+
+// syncWriter provides a thread-safe io.ReadWriter implementation
+type syncReaderWriter struct {
+	buf bytes.Buffer
+	mu  sync.Mutex
+}
+
+func (w *syncReaderWriter) Write(p []byte) (n int, err error) {
+	w.mu.Lock()
+	defer w.mu.Unlock()
+	return w.buf.Write(p)
+}
+
+func (w *syncReaderWriter) Read(p []byte) (n int, err error) {
+	w.mu.Lock()
+	defer w.mu.Unlock()
+
+	return w.buf.Read(p)
+}

coderd/cryptokeys/rotate.go

@@ -152,7 +152,7 @@ func (k *rotator) rotateKeys(ctx context.Context) error {
 					}
 				}
 				if validKeys == 0 {
-					k.logger.Info(ctx, "no valid keys detected, inserting new key",
+					k.logger.Debug(ctx, "no valid keys detected, inserting new key",
 						slog.F("feature", feature),
 					)
 					_, err := k.insertNewKey(ctx, tx, feature, now)
@@ -194,7 +194,7 @@ func (k *rotator) insertNewKey(ctx context.Context, tx database.Store, feature d
 		return database.CryptoKey{}, xerrors.Errorf("inserting new key: %w", err)
 	}
 
-	k.logger.Info(ctx, "inserted new key for feature", slog.F("feature", feature))
+	k.logger.Debug(ctx, "inserted new key for feature", slog.F("feature", feature))
 	return newKey, nil
 }
 

coderd/database/dbpurge/dbpurge.go

@@ -63,7 +63,7 @@ func New(ctx context.Context, logger slog.Logger, db database.Store, clk quartz.
 				return xerrors.Errorf("failed to delete old notification messages: %w", err)
 			}
 
-			logger.Info(ctx, "purged old database entries", slog.F("duration", clk.Since(start)))
+			logger.Debug(ctx, "purged old database entries", slog.F("duration", clk.Since(start)))
 
 			return nil
 		}, database.DefaultTXOptions().WithID("db_purge")); err != nil {

enterprise/cli/provisionerdaemonstart.go

@@ -236,10 +236,11 @@ func (r *RootCmd) provisionerDaemonStart() *serpent.Command {
 					ProvisionerKey: provisionerKey,
 				})
 			}, &provisionerd.Options{
-				Logger:         logger,
-				UpdateInterval: 500 * time.Millisecond,
-				Connector:      connector,
-				Metrics:        metrics,
+				Logger:              logger,
+				UpdateInterval:      500 * time.Millisecond,
+				Connector:           connector,
+				Metrics:             metrics,
+				ExternalProvisioner: true,
 			})
 
 			waitForProvisionerJobs := false

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
 }

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

provisioner/terraform/serve.go

@@ -2,11 +2,13 @@ package terraform
 
 import (
 	"context"
+	"errors"
 	"path/filepath"
 	"sync"
 	"time"
 
 	"github.com/cli/safeexec"
+	"github.com/hashicorp/go-version"
 	semconv "go.opentelemetry.io/otel/semconv/v1.14.0"
 	"go.opentelemetry.io/otel/trace"
 	"golang.org/x/xerrors"
@@ -41,10 +43,15 @@ type ServeOptions struct {
 	ExitTimeout time.Duration
 }
 
-func absoluteBinaryPath(ctx context.Context, logger slog.Logger) (string, error) {
+type systemBinaryDetails struct {
+	absolutePath string
+	version      *version.Version
+}
+
+func systemBinary(ctx context.Context) (*systemBinaryDetails, error) {
 	binaryPath, err := safeexec.LookPath("terraform")
 	if err != nil {
-		return "", xerrors.Errorf("Terraform binary not found: %w", err)
+		return nil, xerrors.Errorf("Terraform binary not found: %w", err)
 	}
 
 	// If the "coder" binary is in the same directory as
@@ -54,59 +61,68 @@ func absoluteBinaryPath(ctx context.Context, logger slog.Logger) (string, error)
 	// to execute this properly!
 	absoluteBinary, err := filepath.Abs(binaryPath)
 	if err != nil {
-		return "", xerrors.Errorf("Terraform binary absolute path not found: %w", err)
+		return nil, xerrors.Errorf("Terraform binary absolute path not found: %w", err)
 	}
 
 	// Checking the installed version of Terraform.
 	installedVersion, err := versionFromBinaryPath(ctx, absoluteBinary)
 	if err != nil {
-		return "", xerrors.Errorf("Terraform binary get version failed: %w", err)
+		return nil, xerrors.Errorf("Terraform binary get version failed: %w", err)
 	}
 
-	logger.Info(ctx, "detected terraform version",
-		slog.F("installed_version", installedVersion.String()),
-		slog.F("min_version", minTerraformVersion.String()),
-		slog.F("max_version", maxTerraformVersion.String()))
-
-	if installedVersion.LessThan(minTerraformVersion) {
-		logger.Warn(ctx, "installed terraform version too old, will download known good version to cache")
-		return "", terraformMinorVersionMismatch
+	details := &systemBinaryDetails{
+		absolutePath: absoluteBinary,
+		version:      installedVersion,
 	}
 
-	// Warn if the installed version is newer than what we've decided is the max.
-	// We used to ignore it and download our own version but this makes it easier
-	// to test out newer versions of Terraform.
-	if installedVersion.GreaterThanOrEqual(maxTerraformVersion) {
-		logger.Warn(ctx, "installed terraform version newer than expected, you may experience bugs",
-			slog.F("installed_version", installedVersion.String()),
-			slog.F("max_version", maxTerraformVersion.String()))
+	if installedVersion.LessThan(minTerraformVersion) {
+		return details, terraformMinorVersionMismatch
 	}
 
-	return absoluteBinary, nil
+	return details, nil
 }
 
 // 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)
+		binaryDetails, err := systemBinary(ctx)
 		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
 			// the unit test kills the app before this is complete.
-			if xerrors.Is(err, context.Canceled) {
-				return xerrors.Errorf("absolute binary context canceled: %w", err)
+			if errors.Is(err, context.Canceled) {
+				return xerrors.Errorf("system 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)
+			if errors.Is(err, terraformMinorVersionMismatch) {
+				options.Logger.Warn(ctx, "installed terraform version too old, will download known good version to cache, or use a previously cached version",
+					slog.F("installed_version", binaryDetails.version.String()),
+					slog.F("min_version", minTerraformVersion.String()))
+			}
+
+			binPath, err := Install(ctx, options.Logger, options.ExternalProvisioner, options.CachePath, TerraformVersion)
 			if err != nil {
 				return xerrors.Errorf("install terraform: %w", err)
 			}
 			options.BinaryPath = binPath
 		} else {
-			options.BinaryPath = absoluteBinary
+			logVersion := options.Logger.Debug
+			if options.ExternalProvisioner {
+				logVersion = options.Logger.Info
+			}
+			logVersion(ctx, "detected terraform version",
+				slog.F("installed_version", binaryDetails.version.String()),
+				slog.F("min_version", minTerraformVersion.String()),
+				slog.F("max_version", maxTerraformVersion.String()))
+			// Warn if the installed version is newer than what we've decided is the max.
+			// We used to ignore it and download our own version but this makes it easier
+			// to test out newer versions of Terraform.
+			if binaryDetails.version.GreaterThanOrEqual(maxTerraformVersion) {
+				options.Logger.Warn(ctx, "installed terraform version newer than expected, you may experience bugs",
+					slog.F("installed_version", binaryDetails.version.String()),
+					slog.F("max_version", maxTerraformVersion.String()))
+			}
+			options.BinaryPath = binaryDetails.absolutePath
 		}
 	}
 	if options.Tracer == nil {

provisioner/terraform/serve_internal_test.go

@@ -54,7 +54,6 @@ func Test_absoluteBinaryPath(t *testing.T) {
 				t.Skip("Dummy terraform executable on Windows requires sh which isn't very practical.")
 			}
 
-			log := testutil.Logger(t)
 			// Create a temp dir with the binary
 			tempDir := t.TempDir()
 			terraformBinaryOutput := fmt.Sprintf(`#!/bin/sh
@@ -85,11 +84,12 @@ func Test_absoluteBinaryPath(t *testing.T) {
 			}
 
 			ctx := testutil.Context(t, testutil.WaitShort)
-			actualAbsoluteBinary, actualErr := absoluteBinaryPath(ctx, log)
+			actualBinaryDetails, actualErr := systemBinary(ctx)
 
-			require.Equal(t, expectedAbsoluteBinary, actualAbsoluteBinary)
 			if tt.expectedErr == nil {
 				require.NoError(t, actualErr)
+				require.Equal(t, expectedAbsoluteBinary, actualBinaryDetails.absolutePath)
+				require.Equal(t, tt.terraformVersion, actualBinaryDetails.version.String())
 			} else {
 				require.EqualError(t, actualErr, tt.expectedErr.Error())
 			}