From 34167c51d585a69f98ac085ddc5f785bc1f0c2ac Mon Sep 17 00:00:00 2001 From: Anis Elleuch Date: Thu, 22 Dec 2022 00:52:29 +0100 Subject: [PATCH] trace: Add bootstrap tracing events (#16286) --- cmd/config-current.go | 4 ++++ cmd/config-encrypted.go | 23 ++++++++++++++--------- cmd/config-migrate.go | 3 +++ cmd/config.go | 2 ++ cmd/iam-object-store.go | 12 +++++++++++- cmd/iam-store.go | 12 ++++++++++++ cmd/iam.go | 3 +++ cmd/server-main.go | 20 ++++++++++++++++++++ cmd/signature-v4-utils.go | 14 +++++++------- go.mod | 2 +- go.sum | 2 ++ 11 files changed, 79 insertions(+), 18 deletions(-) diff --git a/cmd/config-current.go b/cmd/config-current.go index 0797e4578..db6398cf4 100644 --- a/cmd/config-current.go +++ b/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) diff --git a/cmd/config-encrypted.go b/cmd/config-encrypted.go index 5620fc3a5..d4a1d7a2f 100644 --- a/cmd/config-encrypted.go +++ b/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 { - if !encrypted { - return nil - } - if encrypted && GlobalKMS != nil { +func migrateConfigPrefixToEncrypted(objAPI ObjectLayer) error { + bootstrapTrace("migrating config prefix to encrypted") + if 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.") } diff --git a/cmd/config-migrate.go b/cmd/config-migrate.go index 075e0720d..14b43a9d3 100644 --- a/cmd/config-migrate.go +++ b/cmd/config-migrate.go @@ -2425,6 +2425,7 @@ func migrateV27ToV28() error { // Migrates ${HOME}/.minio/config.json to '/.minio.sys/config/config.json' // if etcd is configured then migrates /config/config.json to '/.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. diff --git a/cmd/config.go b/cmd/config.go index c9fb4ee37..63091c44c 100644 --- a/cmd/config.go +++ b/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 } diff --git a/cmd/iam-object-store.go b/cmd/iam-object-store.go index db500d64a..dcdcdc8c6 100644 --- a/cmd/iam-object-store.go +++ b/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") diff --git a/cmd/iam-store.go b/cmd/iam-store.go index 0c12dace7..5735e5c65 100644 --- a/cmd/iam-store.go +++ b/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 diff --git a/cmd/iam.go b/cmd/iam.go index 8e7142a97..7a27cd328 100644 --- a/cmd/iam.go +++ b/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. diff --git a/cmd/server-main.go b/cmd/server-main.go index 8ae35ba36..be6e49563 100644 --- a/cmd/server-main.go +++ b/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 diff --git a/cmd/signature-v4-utils.go b/cmd/signature-v4-utils.go index fea7420d6..d51d362da 100644 --- a/cmd/signature-v4-utils.go +++ b/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 { diff --git a/go.mod b/go.mod index b299958ea..4d96c23c8 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 9154fa228..ebcb7d84c 100644 --- a/go.sum +++ b/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=