trace: Add bootstrap tracing events (#16286)

cmd/config-current.go

@@ -511,11 +511,13 @@ func lookupConfigs(s config.Config, objAPI ObjectLayer) {
 
 	transport := NewHTTPTransport()
 
+	bootstrapTrace("lookup the event notification targets")
 	globalConfigTargetList, err = notify.FetchEnabledTargets(GlobalContext, s, transport)
 	if err != nil {
 		logger.LogIf(ctx, fmt.Errorf("Unable to initialize notification target(s): %w", err))
 	}
 
+	bootstrapTrace("applying the dynamic configuration")
 	// Apply dynamic config values
 	if err := applyDynamicConfig(ctx, objAPI, s); err != nil {
 		logger.LogIf(ctx, err)
@@ -771,11 +773,13 @@ func getValidConfig(objAPI ObjectLayer) (config.Config, error) {
 // from env if found and valid
 // data is optional. If nil it will be loaded from backend.
 func loadConfig(objAPI ObjectLayer, data []byte) error {
+	bootstrapTrace("load the configuration")
 	srvCfg, err := readServerConfig(GlobalContext, objAPI, data)
 	if err != nil {
 		return err
 	}
 
+	bootstrapTrace("lookup the configuration")
 	// Override any values from ENVs.
 	lookupConfigs(srvCfg, objAPI)
 

cmd/config-encrypted.go

@@ -37,7 +37,10 @@ func handleEncryptedConfigBackend(objAPI ObjectLayer) error {
 	if err != nil {
 		return fmt.Errorf("Unable to encrypt config %w", err)
 	}
-	if err = migrateConfigPrefixToEncrypted(objAPI, encrypted); err != nil {
+	if !encrypted {
+		return nil
+	}
+	if err = migrateConfigPrefixToEncrypted(objAPI); err != nil {
 		return fmt.Errorf("Unable to migrate all config at .minio.sys/config/: %w", err)
 	}
 	return nil
@@ -48,6 +51,7 @@ const backendEncryptedFile = "backend-encrypted"
 var backendEncryptedMigrationComplete = []byte("encrypted")
 
 func checkBackendEtcdEncrypted(ctx context.Context, client *etcd.Client) (bool, error) {
+	bootstrapTrace("check if etcd backend is encrypted")
 	data, err := readKeyEtcd(ctx, client, backendEncryptedFile)
 	if err != nil && err != errConfigNotFound {
 		return false, err
@@ -56,6 +60,7 @@ func checkBackendEtcdEncrypted(ctx context.Context, client *etcd.Client) (bool,
 }
 
 func checkBackendEncrypted(objAPI ObjectLayer) (bool, error) {
+	bootstrapTrace("check if the config backend is encrypted")
 	data, err := readConfig(GlobalContext, objAPI, backendEncryptedFile)
 	if err != nil && err != errConfigNotFound {
 		return false, err
@@ -75,7 +80,9 @@ func migrateIAMConfigsEtcdToEncrypted(ctx context.Context, client *etcd.Client)
 		return nil
 	}
 
-	if encrypted && GlobalKMS != nil {
+	bootstrapTrace("encrypt etcd config")
+
+	if GlobalKMS != nil {
 		stat, err := GlobalKMS.Stat(ctx)
 		if err != nil {
 			return err
@@ -136,18 +143,16 @@ func migrateIAMConfigsEtcdToEncrypted(ctx context.Context, client *etcd.Client)
 		}
 	}
 
-	if encrypted && GlobalKMS != nil {
+	if GlobalKMS != nil {
 		logger.Info("Migration of encrypted IAM config data completed. All data is now encrypted on etcd.")
 	}
 
 	return deleteKeyEtcd(ctx, client, backendEncryptedFile)
 }
 
-func migrateConfigPrefixToEncrypted(objAPI ObjectLayer, encrypted bool) error {
+func migrateConfigPrefixToEncrypted(objAPI ObjectLayer) error {
-	if !encrypted {
+	bootstrapTrace("migrating config prefix to encrypted")
-		return nil
+	if GlobalKMS != nil {
-	}
-	if encrypted && GlobalKMS != nil {
 		stat, err := GlobalKMS.Stat(context.Background())
 		if err != nil {
 			return err
@@ -202,7 +207,7 @@ func migrateConfigPrefixToEncrypted(objAPI ObjectLayer, encrypted bool) error {
 		}
 	}
 
-	if encrypted && GlobalKMS != nil {
+	if GlobalKMS != nil {
 		logger.Info("Migration of encrypted config data completed. All config data is now encrypted.")
 	}
 

cmd/config-migrate.go

@@ -2425,6 +2425,7 @@ func migrateV27ToV28() error {
 // Migrates ${HOME}/.minio/config.json to '<export_path>/.minio.sys/config/config.json'
 // if etcd is configured then migrates /config/config.json to '<export_path>/.minio.sys/config/config.json'
 func migrateConfigToMinioSys(objAPI ObjectLayer) (err error) {
+	bootstrapTrace("migrate config to .minio.sys/config/config.json")
 	// Construct path to config.json for the given bucket.
 	configFile := path.Join(minioConfigPrefix, minioConfigFile)
 
@@ -2472,6 +2473,7 @@ func migrateConfigToMinioSys(objAPI ObjectLayer) (err error) {
 
 // Migrates '.minio.sys/config.json' to v33.
 func migrateMinioSysConfig(objAPI ObjectLayer) error {
+	bootstrapTrace("migrate .minio.sys/config/config.json to latest version")
 	// Construct path to config.json for the given bucket.
 	configFile := path.Join(minioConfigPrefix, minioConfigFile)
 
@@ -2737,6 +2739,7 @@ func migrateV32ToV33MinioSys(objAPI ObjectLayer) error {
 }
 
 func migrateMinioSysConfigToKV(objAPI ObjectLayer) error {
+	bootstrapTrace("migrate config to KV style")
 	configFile := path.Join(minioConfigPrefix, minioConfigFile)
 
 	// Check if the config version is latest, if not migrate.

cmd/config.go

@@ -206,6 +206,8 @@ func NewConfigSys() *ConfigSys {
 
 // Initialize and load config from remote etcd or local config directory
 func initConfig(objAPI ObjectLayer) error {
+	bootstrapTrace("load the configuration")
+
 	if objAPI == nil {
 		return errServerNotInitialized
 	}

cmd/iam-object-store.go

@@ -340,6 +340,8 @@ func (iamOS *IAMObjectStore) listAllIAMConfigItems(ctx context.Context) (map[str
 
 // Assumes cache is locked by caller.
 func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iamCache) error {
+	bootstrapTrace("loading all IAM items")
+
 	listedConfigItems, err := iamOS.listAllIAMConfigItems(ctx)
 	if err != nil {
 		return err
@@ -347,6 +349,8 @@ func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iam
 
 	// Loads things in the same order as `LoadIAMCache()`
 
+	bootstrapTrace("loading policy documents")
+
 	policiesList := listedConfigItems[policiesListKey]
 	for _, item := range policiesList {
 		policyName := path.Dir(item)
@@ -357,7 +361,7 @@ func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iam
 	setDefaultCannedPolicies(cache.iamPolicyDocsMap)
 
 	if iamOS.usersSysType == MinIOUsersSysType {
-
+		bootstrapTrace("loading regular IAM users")
 		regUsersList := listedConfigItems[usersListKey]
 		for _, item := range regUsersList {
 			userName := path.Dir(item)
@@ -366,6 +370,7 @@ func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iam
 			}
 		}
 
+		bootstrapTrace("loading regular IAM groups")
 		groupsList := listedConfigItems[groupsListKey]
 		for _, item := range groupsList {
 			group := path.Dir(item)
@@ -375,6 +380,7 @@ func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iam
 		}
 	}
 
+	bootstrapTrace("loading user policy mapping")
 	userPolicyMappingsList := listedConfigItems[policyDBUsersListKey]
 	for _, item := range userPolicyMappingsList {
 		userName := strings.TrimSuffix(item, ".json")
@@ -383,6 +389,7 @@ func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iam
 		}
 	}
 
+	bootstrapTrace("loading group policy mapping")
 	groupPolicyMappingsList := listedConfigItems[policyDBGroupsListKey]
 	for _, item := range groupPolicyMappingsList {
 		groupName := strings.TrimSuffix(item, ".json")
@@ -391,6 +398,7 @@ func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iam
 		}
 	}
 
+	bootstrapTrace("loading service accounts")
 	svcAccList := listedConfigItems[svcAccListKey]
 	for _, item := range svcAccList {
 		userName := path.Dir(item)
@@ -399,6 +407,7 @@ func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iam
 		}
 	}
 
+	bootstrapTrace("loading STS users")
 	stsUsersList := listedConfigItems[stsListKey]
 	for _, item := range stsUsersList {
 		userName := path.Dir(item)
@@ -407,6 +416,7 @@ func (iamOS *IAMObjectStore) loadAllFromObjStore(ctx context.Context, cache *iam
 		}
 	}
 
+	bootstrapTrace("loading STS policy mapping")
 	stsPolicyMappingsList := listedConfigItems[policyDBSTSUsersListKey]
 	for _, item := range stsPolicyMappingsList {
 		stsName := strings.TrimSuffix(item, ".json")

cmd/iam-store.go

@@ -104,6 +104,7 @@ func getUserIdentityPath(user string, userType IAMUserType) string {
 }
 
 func saveIAMFormat(ctx context.Context, store IAMStorageAPI) error {
+	bootstrapTrace("Load IAM format file")
 	var iamFmt iamFormat
 	path := getIAMFormatFilePath()
 	if err := store.loadIAMConfig(ctx, &iamFmt, path); err != nil {
@@ -121,6 +122,7 @@ func saveIAMFormat(ctx context.Context, store IAMStorageAPI) error {
 		return nil
 	}
 
+	bootstrapTrace("Write IAM format file")
 	// Save iam format to version 1.
 	if err := store.saveIAMConfig(ctx, newIAMFormatVersion1(), path); err != nil {
 		logger.LogIf(ctx, err)
@@ -442,6 +444,8 @@ func setDefaultCannedPolicies(policies map[string]PolicyDoc) {
 // LoadIAMCache reads all IAM items and populates a new iamCache object and
 // replaces the in-memory cache object.
 func (store *IAMStoreSys) LoadIAMCache(ctx context.Context) error {
+	bootstrapTrace("loading IAM data")
+
 	newCache := newIamCache()
 
 	loadedAt := time.Now()
@@ -453,6 +457,7 @@ func (store *IAMStoreSys) LoadIAMCache(ctx context.Context) error {
 		}
 	} else {
 
+		bootstrapTrace("loading policy documents")
 		if err := store.loadPolicyDocs(ctx, newCache.iamPolicyDocsMap); err != nil {
 			return err
 		}
@@ -461,34 +466,41 @@ func (store *IAMStoreSys) LoadIAMCache(ctx context.Context) error {
 		setDefaultCannedPolicies(newCache.iamPolicyDocsMap)
 
 		if store.getUsersSysType() == MinIOUsersSysType {
+			bootstrapTrace("loading regular users")
 			if err := store.loadUsers(ctx, regUser, newCache.iamUsersMap); err != nil {
 				return err
 			}
+			bootstrapTrace("loading regular groups")
 			if err := store.loadGroups(ctx, newCache.iamGroupsMap); err != nil {
 				return err
 			}
 		}
 
+		bootstrapTrace("loading user policy mapping")
 		// load polices mapped to users
 		if err := store.loadMappedPolicies(ctx, regUser, false, newCache.iamUserPolicyMap); err != nil {
 			return err
 		}
 
+		bootstrapTrace("loading group policy mapping")
 		// load policies mapped to groups
 		if err := store.loadMappedPolicies(ctx, regUser, true, newCache.iamGroupPolicyMap); err != nil {
 			return err
 		}
 
+		bootstrapTrace("loading service accounts")
 		// load service accounts
 		if err := store.loadUsers(ctx, svcUser, newCache.iamUsersMap); err != nil {
 			return err
 		}
 
+		bootstrapTrace("loading STS users")
 		// load STS temp users
 		if err := store.loadUsers(ctx, stsUser, newCache.iamUsersMap); err != nil {
 			return err
 		}
 
+		bootstrapTrace("loading STS policy mapping")
 		// load STS policy mappings
 		if err := store.loadMappedPolicies(ctx, stsUser, false, newCache.iamUserPolicyMap); err != nil {
 			return err

cmd/iam.go

@@ -208,6 +208,7 @@ func (sys *IAMSys) Load(ctx context.Context) error {
 
 // Init - initializes config system by reading entries from config/iam
 func (sys *IAMSys) Init(ctx context.Context, objAPI ObjectLayer, etcdClient *etcd.Client, iamRefreshInterval time.Duration) {
+	bootstrapTrace("IAM initialization started")
 	globalServerConfigMu.RLock()
 	s := globalServerConfig
 	globalServerConfigMu.RUnlock()
@@ -315,6 +316,8 @@ func (sys *IAMSys) Init(ctx context.Context, objAPI ObjectLayer, etcdClient *etc
 		break
 	}
 
+	bootstrapTrace("finishing IAM loading")
+
 	refreshInterval := sys.iamRefreshInterval
 
 	// Set up polling for expired accounts and credentials purging.

cmd/server-main.go

@@ -34,6 +34,7 @@ import (
 	"time"
 
 	"github.com/minio/cli"
+	"github.com/minio/madmin-go/v2"
 	"github.com/minio/minio-go/v7"
 	"github.com/minio/minio-go/v7/pkg/credentials"
 	"github.com/minio/minio-go/v7/pkg/set"
@@ -345,6 +346,20 @@ func configRetriableErrors(err error) bool {
 		errors.Is(err, os.ErrDeadlineExceeded)
 }
 
+func bootstrapTrace(msg string) {
+	if globalTrace.NumSubscribers(madmin.TraceBootstrap) == 0 {
+		return
+	}
+
+	globalTrace.Publish(madmin.TraceInfo{
+		TraceType: madmin.TraceBootstrap,
+		Time:      time.Now().UTC(),
+		NodeName:  globalLocalNodeName,
+		FuncName:  "BOOTSTRAP",
+		Message:   fmt.Sprintf("%s %s", getSource(2), msg),
+	})
+}
+
 func initServer(ctx context.Context, newObject ObjectLayer) error {
 	t1 := time.Now()
 
@@ -374,6 +389,8 @@ func initServer(ctx context.Context, newObject ObjectLayer) error {
 		default:
 		}
 
+		bootstrapTrace("trying to acquire transaction.lock")
+
 		// Make sure to hold lock for entire migration to avoid
 		// such that only one server should migrate the entire config
 		// at a given time, this big transaction lock ensures this
@@ -386,6 +403,7 @@ func initServer(ctx context.Context, newObject ObjectLayer) error {
 		lkctx, err := txnLk.GetLock(ctx, lockTimeout)
 		if err != nil {
 			logger.Info("Waiting for all MinIO sub-systems to be initialized.. trying to acquire lock")
+			bootstrapTrace(fmt.Sprintf("lock not available. error: %v. sleeping before retry", err))
 
 			// Sleep 0 -> 2 seconds to average 1 second retry interval.
 			time.Sleep(time.Duration(r.Float64() * 2 * float64(time.Second)))
@@ -575,6 +593,7 @@ func serverMain(ctx *cli.Context) {
 	setHTTPServer(httpServer)
 
 	if globalIsDistErasure {
+		bootstrapTrace("verifying system configuration")
 		// Additionally in distributed setup, validate the setup and configuration.
 		if err := verifyServerSystemConfig(GlobalContext, globalEndpoints); err != nil {
 			logger.Fatal(err, "Unable to start the server")
@@ -606,6 +625,7 @@ func serverMain(ctx *cli.Context) {
 		logger.Info(color.RedBold(msg))
 	}
 
+	bootstrapTrace("initializing the server")
 	if err = initServer(GlobalContext, newObject); err != nil {
 		var cerr config.Err
 		// For any config error, we don't need to drop into safe-mode

cmd/signature-v4-utils.go

@@ -141,15 +141,15 @@ func isValidRegion(reqRegion string, confRegion string) bool {
 // check if the access key is valid and recognized, additionally
 // also returns if the access key is owner/admin.
 func checkKeyValid(r *http.Request, accessKey string) (auth.Credentials, bool, APIErrorCode) {
-	if !globalIAMSys.Initialized() {
-		// Check if server has initialized, then only proceed
-		// to check for IAM users otherwise its okay for clients
-		// to retry with 503 errors when server is coming up.
-		return auth.Credentials{}, false, ErrServerNotInitialized
-	}
-
 	cred := globalActiveCred
 	if cred.AccessKey != accessKey {
+		if !globalIAMSys.Initialized() {
+			// Check if server has initialized, then only proceed
+			// to check for IAM users otherwise its okay for clients
+			// to retry with 503 errors when server is coming up.
+			return auth.Credentials{}, false, ErrServerNotInitialized
+		}
+
 		// Check if the access key is part of users credentials.
 		u, ok := globalIAMSys.GetUser(r.Context(), accessKey)
 		if !ok {

go.mod

@@ -49,7 +49,7 @@ require (
 	github.com/minio/dperf v0.4.2
 	github.com/minio/highwayhash v1.0.2
 	github.com/minio/kes v0.22.0
-	github.com/minio/madmin-go/v2 v2.0.1
+	github.com/minio/madmin-go/v2 v2.0.2-0.20221221104141-93e7e5aefaf2
 	github.com/minio/minio-go/v7 v7.0.44
 	github.com/minio/pkg v1.5.8
 	github.com/minio/selfupdate v0.5.0

go.sum

@@ -766,6 +766,8 @@ github.com/minio/kes v0.22.0/go.mod h1:q5T0uTFrr7l6GosXvF0ufCtUKkbmbSZW1Yhu4KgLK
 github.com/minio/madmin-go v1.6.6/go.mod h1:ATvkBOLiP3av4D++2v1UEHC/QzsGtgXD5kYvvRYzdKs=
 github.com/minio/madmin-go/v2 v2.0.1 h1:WFfe12P18k9WSEFUZzUaBOQ78vjMBafM1YjgtXkkJoM=
 github.com/minio/madmin-go/v2 v2.0.1/go.mod h1:5aFi/VLWBHC2DEFfGIlUmAeJhaF4ZAjuYpEWZFU14Zw=
+github.com/minio/madmin-go/v2 v2.0.2-0.20221221104141-93e7e5aefaf2 h1:MPWI0f+mXCX9/0t8XBHXHzR8L0yT40NI4fdbvKyy0aU=
+github.com/minio/madmin-go/v2 v2.0.2-0.20221221104141-93e7e5aefaf2/go.mod h1:5aFi/VLWBHC2DEFfGIlUmAeJhaF4ZAjuYpEWZFU14Zw=
 github.com/minio/mc v0.0.0-20221201184114-854b4f123f03 h1:/q0NA3KjhTL+q/R9xEye0lpJECJmwaZnuIBsBn4HP28=
 github.com/minio/mc v0.0.0-20221201184114-854b4f123f03/go.mod h1:+Jrdvdo6p83JtqUO38UUeTu4aspklp9cF9k6DqFkb0Q=
 github.com/minio/md5-simd v1.1.2 h1:Gdi1DZK69+ZVMoNHRXJyNcxrMA4dSxoYHZSQbirFg34=