Use logging.FromContext instead of logging.Default where possible (#6312

) * Use logging.FromContext instead of logging.Default where possible Loggers created using `logging.FromContext` include a request ID field, allowing readers to thread together actions performed for the same request. Also in future they allow us to add _additional_ fields, for example to distinguish S3 from lakeFS API operations deep inside the call tree. Fixes #2682. * Rename logging.{Default => ContextUnavailable} This name is longer and more descriptive, to encourage using `logging.Default()`. * Fix diff plugin Not part of the same project, so missed by my LSP-based refactoring tools.
treeverse · Aug 7, 2023 · c73c228 · c73c228
1 parent 527770c
commit c73c228
Show file tree

Hide file tree

Showing 68 changed files with 193 additions and 180 deletions.
diff --git a/cmd/lakectl/cmd/config/config.go b/cmd/lakectl/cmd/config/config.go
@@ -67,7 +67,7 @@ func ReadConfig() (c *Config) {
 
 	setDefaults()
 	c.err = viper.ReadInConfig()
-	logger := logging.Default().WithField("file", viper.ConfigFileUsed())
+	logger := logging.ContextUnavailable().WithField("file", viper.ConfigFileUsed())
 
 	if errors.Is(c.err, viper.ConfigFileNotFoundError{}) {
 		logger.WithError(c.err).Fatal("failed to read config file")

diff --git a/cmd/lakectl/cmd/metastore_copy.go b/cmd/lakectl/cmd/metastore_copy.go
@@ -38,7 +38,7 @@ var metastoreCopyCmd = &cobra.Command{
 		if len(serde) == 0 {
 			serde = toTable
 		}
-		logging.Default().WithFields(logging.Fields{
+		logging.ContextUnavailable().WithFields(logging.Fields{
 			"form_client_type": fromClientType,
 			"from_schema":      fromDB,
 			"from_table":       fromTable,

diff --git a/cmd/lakectl/cmd/metastore_copy_schema.go b/cmd/lakectl/cmd/metastore_copy_schema.go
@@ -29,7 +29,7 @@ var metastoreCopySchemaCmd = &cobra.Command{
 			toDB = toBranch
 		}
 
-		logging.Default().WithFields(logging.Fields{
+		logging.ContextUnavailable().WithFields(logging.Fields{
 			"form_client_type": fromClientType,
 			"from_db":          fromDB,
 			"to_client_type":   toClientType,

diff --git a/cmd/lakectl/cmd/root.go b/cmd/lakectl/cmd/root.go
@@ -88,7 +88,7 @@ var rootCmd = &cobra.Command{
 		}
 
 		if cfg.Err() == nil {
-			logging.Default().
+			logging.ContextUnavailable().
 				WithField("file", viper.ConfigFileUsed()).
 				Debug("loaded configuration from file")
 		}

diff --git a/cmd/lakefs-loadtest/cmd/entry.go b/cmd/lakefs-loadtest/cmd/entry.go
@@ -63,11 +63,11 @@ var entryCmd = &cobra.Command{
 
 		kvParams, err := conf.DatabaseParams()
 		if err != nil {
-			logging.Default().WithError(err).Fatal("Get KV params")
+			logging.ContextUnavailable().WithError(err).Fatal("Get KV params")
 		}
 		kvStore, err := kv.Open(ctx, kvParams)
 		if err != nil {
-			logging.Default().WithError(err).Fatal("failed to open KV store")
+			logging.ContextUnavailable().WithError(err).Fatal("failed to open KV store")
 		}
 		defer kvStore.Close()
 

diff --git a/cmd/lakefs/cmd/migrate.go b/cmd/lakefs/cmd/migrate.go
@@ -115,7 +115,7 @@ func DoMigration(ctx context.Context, kvStore kv.Store, cfg *config.Config, forc
 		case version >= kv.NextSchemaVersion || version < kv.InitialMigrateVersion:
 			return fmt.Errorf("wrong starting version %d: %w", version, kv.ErrMigrationVersion)
 		case version < kv.ACLNoReposMigrateVersion:
-			err = migrations.MigrateToACL(ctx, kvStore, cfg, logging.Default(), version, force)
+			err = migrations.MigrateToACL(ctx, kvStore, cfg, logging.ContextUnavailable(), version, force)
 		case version < kv.ACLImportMigrateVersion:
 			err = migrations.MigrateImportPermissions(ctx, kvStore, cfg)
 		}

diff --git a/cmd/lakefs/cmd/root.go b/cmd/lakefs/cmd/root.go
@@ -75,7 +75,7 @@ func loadConfig() *config.Config {
 
 // initConfig reads in config file and ENV variables if set.
 func initConfig() {
-	logger := logging.Default().WithField("phase", "startup")
+	logger := logging.ContextUnavailable().WithField("phase", "startup")
 	if cfgFile != "" {
 		logger.WithField("file", cfgFile).Info("Configuration file")
 		// Use config file from the flag.

diff --git a/cmd/lakefs/cmd/run.go b/cmd/lakefs/cmd/run.go
@@ -71,7 +71,7 @@ var runCmd = &cobra.Command{
 	Use:   "run",
 	Short: "Run lakeFS",
 	Run: func(cmd *cobra.Command, args []string) {
-		logger := logging.Default()
+		logger := logging.ContextUnavailable()
 		cfg := loadConfig()
 		viper.WatchConfig()
 		viper.OnConfigChange(func(in fsnotify.Event) {

diff --git a/cmd/lakefs/cmd/setup.go b/cmd/lakefs/cmd/setup.go
@@ -71,7 +71,7 @@ var setupCmd = &cobra.Command{
 			os.Exit(1)
 		}
 		defer kvStore.Close()
-		logger := logging.Default()
+		logger := logging.ContextUnavailable()
 		authLogger := logger.WithField("service", "auth_service")
 		authService = auth.NewAuthService(kvStore, crypt.NewSecretStore(cfg.AuthEncryptionSecret()), nil, authparams.ServiceCache(cfg.Auth.Cache), authLogger)
 		metadataManager = auth.NewKVMetadataManager(version.Version, cfg.Installation.FixedID, cfg.Database.Type, kvStore)

diff --git a/cmd/lakefs/cmd/superuser.go b/cmd/lakefs/cmd/superuser.go
@@ -46,7 +46,7 @@ var superuserCmd = &cobra.Command{
 			os.Exit(1)
 		}
 
-		logger := logging.Default()
+		logger := logging.ContextUnavailable()
 		ctx := cmd.Context()
 		kvParams, err := cfg.DatabaseParams()
 		if err != nil {

diff --git a/pkg/api/controller.go b/pkg/api/controller.go
@@ -4597,7 +4597,7 @@ func writeResponse(w http.ResponseWriter, r *http.Request, code int, response in
 	w.WriteHeader(code)
 	err := json.NewEncoder(w).Encode(response)
 	if err != nil {
-		logging.Default().WithError(err).WithField("code", code).Debug("Failed to write encoded json response")
+		logging.FromContext(r.Context()).WithError(err).WithField("code", code).Info("Failed to write encoded json response")
 	}
 }
 

diff --git a/pkg/api/serve_test.go b/pkg/api/serve_test.go
@@ -165,7 +165,7 @@ func setupHandlerWithWalkerFactory(t testing.TB, factory catalog.WalkerFactory)
 	idGen := &actions.DecreasingIDGenerator{}
 	authService := auth.NewAuthService(kvStore, crypt.NewSecretStore([]byte("some secret")), nil, authparams.ServiceCache{
 		Enabled: false,
-	}, logging.Default())
+	}, logging.ContextUnavailable())
 	meta := auth.NewKVMetadataManager("serve_test", cfg.Installation.FixedID, cfg.Database.Type, kvStore)
 
 	// Do not validate invalid config (missing required fields).
@@ -223,7 +223,7 @@ func setupHandlerWithWalkerFactory(t testing.TB, factory catalog.WalkerFactory)
 		nil,
 		actionsService,
 		auditChecker,
-		logging.Default(),
+		logging.ContextUnavailable(),
 		emailer,
 		tmpl,
 		nil,

diff --git a/pkg/auth/service.go b/pkg/auth/service.go
@@ -1017,7 +1017,7 @@ func interpolateUser(resource string, username string) string {
 	return strings.ReplaceAll(resource, "${user}", username)
 }
 
-func checkPermissions(node permissions.Node, username string, policies []*model.Policy) CheckResult {
+func checkPermissions(ctx context.Context, node permissions.Node, username string, policies []*model.Policy) CheckResult {
 	allowed := CheckNeutral
 	switch node.Type {
 	case permissions.NodeTypeNode:
@@ -1049,7 +1049,7 @@ func checkPermissions(node permissions.Node, username string, policies []*model.
 		// Denied - one of the permissions is Deny
 		// Natural - otherwise
 		for _, node := range node.Nodes {
-			result := checkPermissions(node, username, policies)
+			result := checkPermissions(ctx, node, username, policies)
 			if result == CheckDeny {
 				return CheckDeny
 			}
@@ -1064,15 +1064,15 @@ func checkPermissions(node permissions.Node, username string, policies []*model.
 		// Denied - one of the permissions is Deny
 		// Natural - otherwise
 		for _, node := range node.Nodes {
-			result := checkPermissions(node, username, policies)
+			result := checkPermissions(ctx, node, username, policies)
 			if result == CheckNeutral || result == CheckDeny {
 				return result
 			}
 		}
 		return CheckAllow
 
 	default:
-		logging.Default().Error("unknown permission node type")
+		logging.FromContext(ctx).Error("unknown permission node type")
 		return CheckDeny
 	}
 	return allowed
@@ -1087,7 +1087,7 @@ func (s *AuthService) Authorize(ctx context.Context, req *AuthorizationRequest)
 		return nil, err
 	}
 
-	allowed := checkPermissions(req.RequiredPermissions, req.Username, policies)
+	allowed := checkPermissions(ctx, req.RequiredPermissions, req.Username, policies)
 
 	if allowed != CheckAllow {
 		return &AuthorizationResponse{
@@ -1892,7 +1892,7 @@ func (a *APIAuthService) Authorize(ctx context.Context, req *AuthorizationReques
 		return nil, err
 	}
 
-	allowed := checkPermissions(req.RequiredPermissions, req.Username, policies)
+	allowed := checkPermissions(ctx, req.RequiredPermissions, req.Username, policies)
 
 	if allowed != CheckAllow {
 		return &AuthorizationResponse{
@@ -1959,7 +1959,7 @@ func NewAPIAuthService(apiEndpoint, token string, secretStore crypt.SecretStore,
 		cache:       cache,
 	}
 	if emailer != nil {
-		res.delegatedInviteHandler = NewEmailInviteHandler(res, logging.Default(), emailer)
+		res.delegatedInviteHandler = NewEmailInviteHandler(res, logging.ContextUnavailable(), emailer)
 	}
 	return res, nil
 }
@@ -1978,7 +1978,7 @@ func generateAuthAPIJWT(secret []byte) (string, error) {
 		ExpiresAt: jwt.NewNumericDate(exp),
 	}
 	token := jwt.NewWithClaims(jwt.SigningMethodHS256, claims)
-	logging.Default().WithField("id", id).Info("generated auth api token")
+	logging.ContextUnavailable().WithField("id", id).Info("generated auth api token")
 	return token.SignedString(secret)
 }
 

diff --git a/pkg/auth/service_test.go b/pkg/auth/service_test.go
@@ -107,7 +107,7 @@ func TestAuthService_ListUsers_PagedWithPrefix(t *testing.T) {
 	kvStore := kvtest.GetStore(ctx, t)
 	s := auth.NewAuthService(kvStore, crypt.NewSecretStore(someSecret), nil, authparams.ServiceCache{
 		Enabled: false,
-	}, logging.Default())
+	}, logging.ContextUnavailable())
 
 	users := []string{"bar", "barn", "baz", "foo", "foobar", "foobaz"}
 	for _, u := range users {
@@ -157,7 +157,7 @@ func TestAuthService_ListPaged(t *testing.T) {
 	kvStore := kvtest.GetStore(ctx, t)
 	s := auth.NewAuthService(kvStore, crypt.NewSecretStore(someSecret), nil, authparams.ServiceCache{
 		Enabled: false,
-	}, logging.Default())
+	}, logging.ContextUnavailable())
 
 	const chars = "abcdefghijklmnopqrstuvwxyz"
 	for _, c := range chars {
@@ -540,19 +540,19 @@ func BenchmarkKVAuthService_ListEffectivePolicies(b *testing.B) {
 
 	serviceWithoutCache := auth.NewAuthService(kvStore, crypt.NewSecretStore(someSecret), nil, authparams.ServiceCache{
 		Enabled: false,
-	}, logging.Default())
+	}, logging.ContextUnavailable())
 	serviceWithCache := auth.NewAuthService(kvStore, crypt.NewSecretStore(someSecret), nil, authparams.ServiceCache{
 		Enabled: true,
 		Size:    1024,
 		TTL:     20 * time.Second,
 		Jitter:  3 * time.Second,
-	}, logging.Default())
+	}, logging.ContextUnavailable())
 	serviceWithCacheLowTTL := auth.NewAuthService(kvStore, crypt.NewSecretStore(someSecret), nil, authparams.ServiceCache{
 		Enabled: true,
 		Size:    1024,
 		TTL:     1 * time.Millisecond,
 		Jitter:  1 * time.Millisecond,
-	}, logging.Default())
+	}, logging.ContextUnavailable())
 	userName := userWithPolicies(b, serviceWithoutCache, userPoliciesForTesting)
 
 	b.Run("without_cache", func(b *testing.B) {
@@ -1124,7 +1124,7 @@ func NewTestApiService(t *testing.T, withCache bool) (*mock.MockClientWithRespon
 		cacheParams.TTL = time.Minute
 		cacheParams.Jitter = time.Minute
 	}
-	s, err := auth.NewAPIAuthServiceWithClient(mockClient, secretStore, cacheParams, logging.Default())
+	s, err := auth.NewAPIAuthServiceWithClient(mockClient, secretStore, cacheParams, logging.ContextUnavailable())
 	if err != nil {
 		t.Fatalf("failed initiating API service with mock")
 	}

diff --git a/pkg/auth/setup/setup.go b/pkg/auth/setup/setup.go
@@ -252,7 +252,7 @@ func CreateInitialAdminUserWithKeys(ctx context.Context, authService auth.Servic
 
 	// update setup timestamp
 	if err := metadataManger.UpdateSetupTimestamp(ctx, time.Now()); err != nil {
-		logging.Default().WithError(err).Error("Failed the update setup timestamp")
+		logging.ContextUnavailable().WithError(err).Error("Failed the update setup timestamp")
 	}
 	return cred, err
 }

diff --git a/pkg/auth/testutil/service.go b/pkg/auth/testutil/service.go
@@ -17,5 +17,5 @@ func SetupService(t *testing.T, ctx context.Context, secret []byte) (*auth.AuthS
 	kvStore := kvtest.GetStore(ctx, t)
 	return auth.NewAuthService(kvStore, crypt.NewSecretStore(secret), nil, authparams.ServiceCache{
 		Enabled: false,
-	}, logging.Default()), kvStore
+	}, logging.ContextUnavailable()), kvStore
 }
diff --git a/pkg/batch/executor_test.go b/pkg/batch/executor_test.go
@@ -54,7 +54,7 @@ func (d *db) GetAccessCount() int32 {
 
 func testReadAfterWrite(t *testing.T) {
 	// Setup executor
-	exec := batch.NewExecutor(logging.Default())
+	exec := batch.NewExecutor(logging.ContextUnavailable())
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 	go exec.Run(ctx)
@@ -141,7 +141,7 @@ func testReadAfterWrite(t *testing.T) {
 
 func testBatchExpiration(t *testing.T) {
 	// Setup executor
-	exec := batch.NewExecutor(logging.Default())
+	exec := batch.NewExecutor(logging.ContextUnavailable())
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 	go exec.Run(ctx)
@@ -182,7 +182,7 @@ func testBatchExpiration(t *testing.T) {
 
 func testBatchByKey(t *testing.T) {
 	// Setup executor
-	exec := batch.NewExecutor(logging.Default())
+	exec := batch.NewExecutor(logging.ContextUnavailable())
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 	go exec.Run(ctx)

diff --git a/pkg/block/azure/adapter.go b/pkg/block/azure/adapter.go
@@ -42,8 +42,8 @@ type Adapter struct {
 	disablePreSignedUI bool
 }
 
-func NewAdapter(params params.Azure) (*Adapter, error) {
-	logging.Default().WithField("type", "azure").Info("initialized blockstore adapter")
+func NewAdapter(ctx context.Context, params params.Azure) (*Adapter, error) {
+	logging.FromContext(ctx).WithField("type", "azure").Info("initialized blockstore adapter")
 	preSignedExpiry := params.PreSignedExpiry
 	if preSignedExpiry == 0 {
 		preSignedExpiry = block.DefaultPreSignExpiryDuration

diff --git a/pkg/block/azure/adapter_test.go b/pkg/block/azure/adapter_test.go
@@ -1,6 +1,7 @@
 package azure_test
 
 import (
+	"context"
 	"net/url"
 	"regexp"
 	"testing"
@@ -19,7 +20,7 @@ func TestAzureAdapter(t *testing.T) {
 	externalPath, err := url.JoinPath(basePath, "external")
 	require.NoError(t, err)
 
-	adapter, err := azure.NewAdapter(params.Azure{
+	adapter, err := azure.NewAdapter(context.Background(), params.Azure{
 		StorageAccount:   accountName,
 		StorageAccessKey: accountKey,
 		TestEndpointURL:  blockURL,
@@ -29,7 +30,7 @@ func TestAzureAdapter(t *testing.T) {
 }
 
 func TestAdapterNamespace(t *testing.T) {
-	adapter, err := azure.NewAdapter(params.Azure{
+	adapter, err := azure.NewAdapter(context.Background(), params.Azure{
 		StorageAccount:   accountName,
 		StorageAccessKey: accountKey,
 		TestEndpointURL:  blockURL,

diff --git a/pkg/block/azure/multipart_block_writer.go b/pkg/block/azure/multipart_block_writer.go
@@ -135,7 +135,7 @@ func getMultipartIDs(ctx context.Context, container container.Client, objName st
 	// remove
 	_, err = blobURL.Delete(ctx, nil)
 	if err != nil {
-		logging.Default().WithContext(ctx).WithField("blob_url", blobURL.URL()).WithError(err).Warn("Failed to delete multipart ids data file")
+		logging.FromContext(ctx).WithField("blob_url", blobURL.URL()).WithError(err).Warn("Failed to delete multipart ids data file")
 	}
 	return ids, nil
 }
@@ -169,7 +169,7 @@ func getMultipartSize(ctx context.Context, container container.Client, objName s
 	// remove
 	_, err = blobURL.Delete(ctx, nil)
 	if err != nil {
-		logging.Default().WithContext(ctx).WithField("blob_url", blobURL.URL()).WithError(err).Warn("Failed to delete multipart size data file")
+		logging.FromContext(ctx).WithField("blob_url", blobURL.URL()).WithError(err).Warn("Failed to delete multipart size data file")
 	}
 	return int64(size), nil
 }