Movatterモバイル変換


[0]ホーム

URL:


Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

Sign up
Appearance settings

chore: reduce log volume on server startup#16608

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to ourterms of service andprivacy statement. We’ll occasionally send you account related emails.

Already on GitHub?Sign in to your account

Merged
hugodutka merged 7 commits intomainfromhugodutka/reduce-log-volume-on-startup
Feb 20, 2025
Merged
Show file tree
Hide file tree
Changes fromall commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletioncli/server.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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
Expand Down
84 changes: 84 additions & 0 deletionscli/server_test.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -25,6 +25,7 @@ import (
"runtime"
"strconv"
"strings"
"sync"
"sync/atomic"
"testing"
"time"
Expand DownExpand Up@@ -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.
Expand DownExpand Up@@ -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)
}
4 changes: 2 additions & 2 deletionscoderd/cryptokeys/rotate.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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)
Expand DownExpand Up@@ -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
}

Expand Down
2 changes: 1 addition & 1 deletioncoderd/database/dbpurge/dbpurge.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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 {
Expand Down
9 changes: 5 additions & 4 deletionsenterprise/cli/provisionerdaemonstart.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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
Expand Down
44 changes: 38 additions & 6 deletionsprovisioner/terraform/install.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -2,8 +2,10 @@ package terraform

import (
"context"
"fmt"
"os"
"path/filepath"
"sync/atomic"
"time"

"github.com/gofrs/flock"
Expand All@@ -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
Expand DownExpand Up@@ -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 {
Expand All@@ -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
}
2 changes: 1 addition & 1 deletionprovisioner/terraform/install_test.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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
}()
Expand Down
72 changes: 44 additions & 28 deletionsprovisioner/terraform/serve.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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"
Expand DownExpand Up@@ -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)
returnnil, xerrors.Errorf("Terraform binary not found: %w", err)
}

// If the "coder" binary is in the same directory as
Expand All@@ -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)
returnnil, 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)
returnnil, 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
}

returnabsoluteBinary, nil
returndetails, 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.
ifxerrors.Is(err, context.Canceled) {
return xerrors.Errorf("absolute binary context canceled: %w", err)
iferrors.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 {
Expand Down
6 changes: 3 additions & 3 deletionsprovisioner/terraform/serve_internal_test.go
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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
Expand DownExpand Up@@ -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())
}
Expand Down
Loading
Loading

[8]ページ先頭

©2009-2025 Movatter.jp