add debug logging for the kotsadm startup process

add a debug log after each major startup function

add a 'this is still waiting' debug message in the db and filestore wait loops

use the context-aware s3 client function

pkg/apiserver/server.go

@@ -17,6 +17,7 @@ import (
 	identitymigrate "github.com/replicatedhq/kots/pkg/identity/migrate"
 	"github.com/replicatedhq/kots/pkg/informers"
 	"github.com/replicatedhq/kots/pkg/k8sutil"
+	"github.com/replicatedhq/kots/pkg/logger"
 	"github.com/replicatedhq/kots/pkg/operator"
 	operatorclient "github.com/replicatedhq/kots/pkg/operator/client"
 	"github.com/replicatedhq/kots/pkg/persistence"
@@ -49,36 +50,45 @@ func Start(params *APIServerParams) {
 		panic(err)
 	}
 	cancel()
+	logger.Debug("store is ready")
 
 	// check if we need to migrate from postgres before doing anything else
 	if err := persistence.MigrateFromPostgresToRqlite(); err != nil {
 		log.Println("error migrating from postgres to rqlite")
 		panic(err)
 	}
+	logger.Debug("postgres is migrated to rqlite or the migration was not required")
 
 	if err := bootstrap(BootstrapParams{
 		AutoCreateClusterToken: params.AutocreateClusterToken,
 	}); err != nil {
 		log.Println("error bootstrapping")
 		panic(err)
 	}
+	logger.Debug("bootstrap completed")
 
 	store.GetStore().RunMigrations()
+	logger.Debug("store migrations completed")
+
 	if err := identitymigrate.RunMigrations(context.TODO(), util.PodNamespace); err != nil {
 		log.Println("Failed to run identity migrations: ", err)
 	}
+	logger.Debug("identity migrations completed")
 
 	if err := binaries.InitKubectl(); err != nil {
 		log.Println("error initializing kubectl binaries package")
 		panic(err)
 	}
+	logger.Debug("kubectl binaries are initialized")
 
 	if err := binaries.InitKustomize(); err != nil {
 		log.Println("error initializing kustomize binaries package")
 		panic(err)
 	}
+	logger.Debug("kustomize binaries are initialized")
 
 	kotsStore := store.GetStore()
+	logger.Debug("kotsstore is initialized")
 
 	operatorClient := &operatorclient.Client{
 		TargetNamespace:       util.AppNamespace(),
@@ -90,12 +100,15 @@ func Start(params *APIServerParams) {
 		log.Println("error getting k8s clientset")
 		panic(err)
 	}
+	logger.Debug("k8s clientset is initialized")
+
 	op := operator.Init(operatorClient, kotsStore, params.AutocreateClusterToken, k8sClientset)
 	if err := op.Start(); err != nil {
 		log.Println("error starting the operator")
 		panic(err)
 	}
 	defer op.Shutdown()
+	logger.Debug("operator is initialized")
 
 	if params.SharedPassword != "" {
 		// TODO: this won't override the password in the database
@@ -110,31 +123,40 @@ func Start(params *APIServerParams) {
 	if err := k8sutil.InitHelmCapabilities(); err != nil {
 		panic(err)
 	}
+	logger.Debug("helm capabilities are initialized")
 
 	if err := update.InitAvailableUpdatesDir(); err != nil {
 		panic(err)
 	}
+	logger.Debug("available updates dir is initialized")
 
 	if err := reporting.Init(); err != nil {
 		log.Println("failed to initialize reporting:", err)
 	}
+	logger.Debug("reporting is initialized")
 
 	supportbundle.StartServer()
+	logger.Debug("support bundle server is started")
 
 	if err := informers.Start(); err != nil {
 		log.Println("Failed to start informers:", err)
 	}
+	logger.Debug("informers are started")
 
 	if err := updatechecker.Start(); err != nil {
 		log.Println("Failed to start update checker:", err)
 	}
+	logger.Debug("update checker is started")
+
 	if err := snapshotscheduler.Start(); err != nil {
 		log.Println("Failed to start snapshot scheduler:", err)
 	}
+	logger.Debug("snapshot scheduler is started")
 
 	if err := session.StartSessionPurgeCronJob(); err != nil {
 		log.Println("Failed to start session purge cron job:", err)
 	}
+	logger.Debug("session purge cron job is started")
 
 	waitForAirgap, err := automation.NeedToWaitForAirgapApp()
 	if err != nil {
@@ -145,6 +167,7 @@ func Start(params *APIServerParams) {
 			log.Println("Failed to run automated installs:", err)
 		}
 	}
+	logger.Debug("automated airgap installs are completed")
 
 	r := mux.NewRouter()
 

pkg/filestore/s3_store.go

@@ -81,7 +81,7 @@ func (s *S3Store) WaitForReady(ctx context.Context) error {
 
 	period := 1 * time.Second // TOOD: backoff
 	for {
-		_, err := s3Client.HeadBucket(&s3.HeadBucketInput{
+		_, err := s3Client.HeadBucketWithContext(ctx, &s3.HeadBucketInput{
 			Bucket: aws.String(os.Getenv("S3_BUCKET_NAME")),
 		})
 		if err == nil {
@@ -95,6 +95,7 @@ func (s *S3Store) WaitForReady(ctx context.Context) error {
 
 		select {
 		case <-time.After(period):
+			logger.Debug("waiting for object store to be ready")
 			continue
 		case <-ctx.Done():
 			return errors.Errorf("failed to find valid object store: %s, last error: %s", ctx.Err(), err)

pkg/store/kotsstore/kots_store.go

@@ -99,6 +99,7 @@ func waitForRqlite(ctx context.Context) error {
 
 		select {
 		case <-time.After(period):
+			logger.Debug("waiting for database to be ready")
 			continue
 		case <-ctx.Done():
 			if rows.Err != nil {