Merge pull request #49 from bitrise-io/file-permission-logging

[ACI-2110] Add file create error context debug logging

Author: imrekel

cmd/restoreXcodeDerivedDataFiles.go

@@ -1,14 +1,14 @@
 package cmd
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"os"
+	"os/user"
 	"strings"
 	"time"
 
-	"context"
-
 	xa "github.com/bitrise-io/bitrise-build-cache-cli/internal/analytics"
 	"github.com/bitrise-io/bitrise-build-cache-cli/internal/build_cache/kv"
 	"github.com/bitrise-io/bitrise-build-cache-cli/internal/config/common"
@@ -34,6 +34,8 @@ var restoreXcodeDerivedDataFilesCmd = &cobra.Command{
 	RunE: func(cmd *cobra.Command, _ []string) error {
 		logger := log.NewLogger()
 		logger.EnableDebugLog(isDebugLogMode)
+		logCurrentUserInfo(logger)
+
 		logger.TInfof("Restore Xcode DerivedData from Bitrise Build Cache")
 
 		logger.Infof("(i) Debug mode and verbose logs: %t", isDebugLogMode)
@@ -52,7 +54,7 @@ var restoreXcodeDerivedDataFilesCmd = &cobra.Command{
 			return fmt.Errorf("read auth config from environments: %w", err)
 		}
 
-		op, cmdError := restoreXcodeDerivedDataFilesCmdFn(cmd.Context(), authConfig, CacheMetadataPath, projectRoot, cacheKey, logger, tracker, startT, os.Getenv)
+		op, cmdError := restoreXcodeDerivedDataFilesCmdFn(cmd.Context(), authConfig, CacheMetadataPath, projectRoot, cacheKey, logger, tracker, startT, os.Getenv, isDebugLogMode)
 		if op != nil {
 			if cmdError != nil {
 				errStr := cmdError.Error()
@@ -86,7 +88,7 @@ func init() {
 }
 
 func restoreXcodeDerivedDataFilesCmdFn(ctx context.Context, authConfig common.CacheAuthConfig, cacheMetadataPath, projectRoot, providedCacheKey string, logger log.Logger,
-	tracker xcode.StepAnalyticsTracker, startT time.Time, envProvider func(string) string) (*xa.CacheOperation, error) {
+	tracker xcode.StepAnalyticsTracker, startT time.Time, envProvider func(string) string, isDebugLogMode bool) (*xa.CacheOperation, error) {
 	kvClient, err := createKVClient(ctx, authConfig, envProvider, logger)
 	if err != nil {
 		return nil, fmt.Errorf("create kv client: %w", err)
@@ -125,7 +127,7 @@ func restoreXcodeDerivedDataFilesCmdFn(ctx context.Context, authConfig common.Ca
 	tracker.LogMetadataLoaded(metadataRestoredT.Sub(startT), string(cacheKeyType), len(metadata.ProjectFiles.Files)+len(metadata.ProjectFiles.Directories), filesUpdated, metadataSize)
 
 	logger.TInfof("Downloading DerivedData files")
-	stats, err := xcode.DownloadCacheFilesFromBuildCache(ctx, metadata.DerivedData, kvClient, logger)
+	stats, err := xcode.DownloadCacheFilesFromBuildCache(ctx, metadata.DerivedData, kvClient, logger, isDebugLogMode)
 	ddDownloadedT := time.Now()
 	tracker.LogDerivedDataDownloaded(ddDownloadedT.Sub(metadataRestoredT), stats)
 	fillCacheOperationWithDownloadStats(op, stats)
@@ -144,7 +146,7 @@ func restoreXcodeDerivedDataFilesCmdFn(ctx context.Context, authConfig common.Ca
 
 	if len(metadata.XcodeCacheDir.Files) > 0 {
 		logger.TInfof("Downloading Xcode cache files")
-		if _, err := xcode.DownloadCacheFilesFromBuildCache(ctx, metadata.XcodeCacheDir, kvClient, logger); err != nil {
+		if _, err := xcode.DownloadCacheFilesFromBuildCache(ctx, metadata.XcodeCacheDir, kvClient, logger, isDebugLogMode); err != nil {
 			return op, fmt.Errorf("download Xcode cache files: %w", err)
 		}
 
@@ -227,3 +229,15 @@ func logCacheMetadata(md *xcode.Metadata, logger log.Logger) {
 	logger.Infof("  Build Cache CLI version: %s", md.BuildCacheCLIVersion)
 	logger.Infof("  Metadata version: %d", md.MetadataVersion)
 }
+
+func logCurrentUserInfo(logger log.Logger) {
+	currentUser, err := user.Current()
+	if err != nil {
+		logger.Debugf("Error getting current user: %v", err)
+	}
+
+	logger.Debugf("Current user info:")
+	logger.Debugf("  UID: %s", currentUser.Uid)
+	logger.Debugf("  GID: %s", currentUser.Gid)
+	logger.Debugf("  Username: %s", currentUser.Username)
+}

cmd/saveXcodeDerivedDataFiles.go

@@ -27,6 +27,8 @@ var saveXcodeDerivedDataFilesCmd = &cobra.Command{
 	RunE: func(cmd *cobra.Command, _ []string) error {
 		logger := log.NewLogger()
 		logger.EnableDebugLog(isDebugLogMode)
+		logCurrentUserInfo(logger)
+
 		logger.TInfof("Save Xcode DerivedData into Bitrise Build Cache")
 
 		logger.Infof("(i) Debug mode and verbose logs: %t", isDebugLogMode)

internal/xcode/download.go

@@ -7,6 +7,7 @@ import (
 	"io"
 	"os"
 	"path/filepath"
+	"syscall"
 
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/status"
@@ -21,7 +22,7 @@ var ErrCacheNotFound = errors.New("no cache archive found for the provided keys"
 func DownloadFileFromBuildCache(ctx context.Context, fileName, key string, kvClient *kv.Client, logger log.Logger) error {
 	logger.Debugf("Downloading %s", fileName)
 
-	return downloadFile(ctx, kvClient, fileName, key, 0)
+	return downloadFile(ctx, kvClient, fileName, key, 0, logger, false)
 }
 
 func DownloadStreamFromBuildCache(ctx context.Context, destination io.Writer, key string, kvClient *kv.Client, logger log.Logger) error {
@@ -30,7 +31,7 @@ func DownloadStreamFromBuildCache(ctx context.Context, destination io.Writer, ke
 	return downloadStream(ctx, destination, kvClient, key)
 }
 
-func downloadFile(ctx context.Context, client *kv.Client, filePath, key string, fileMode os.FileMode) error {
+func downloadFile(ctx context.Context, client *kv.Client, filePath, key string, fileMode os.FileMode, logger log.Logger, isDebugLogMode bool) error {
 	dir := filepath.Dir(filePath)
 	if err := os.MkdirAll(dir, os.ModePerm); err != nil {
 		return fmt.Errorf("create directory: %w", err)
@@ -41,6 +42,10 @@ func downloadFile(ctx context.Context, client *kv.Client, filePath, key string,
 	}
 	file, err := os.OpenFile(filePath, os.O_RDWR|os.O_CREATE|os.O_TRUNC, fileMode)
 	if err != nil {
+		if isDebugLogMode {
+			logFilePathDebugInfo(filePath, logger)
+		}
+
 		return fmt.Errorf("create %q: %w", filePath, err)
 	}
 	defer file.Close()
@@ -66,3 +71,23 @@ func downloadStream(ctx context.Context, destination io.Writer, client *kv.Clien
 
 	return nil
 }
+
+func logFilePathDebugInfo(filePath string, logger log.Logger) {
+	fileInfo, err := os.Stat(filePath)
+	if err == nil {
+		logger.Debugf("    File already exists - permissions: %s\n", fileInfo.Mode().String())
+
+		if stat, ok := fileInfo.Sys().(*syscall.Stat_t); ok {
+			logger.Debugf("    Owner UID: %d Owner GID: %d\n", stat.Uid, stat.Gid)
+		}
+	}
+
+	dirPath := filepath.Dir(filePath)
+	dirInfo, err := os.Stat(dirPath)
+	if err == nil {
+		logger.Debugf("    Containing dir permissions: %s\n", dirInfo.Mode().String())
+		if stat, ok := dirInfo.Sys().(*syscall.Stat_t); ok {
+			logger.Debugf("    Owner UID: %d Owner GID: %d\n", stat.Uid, stat.Gid)
+		}
+	}
+}

internal/xcode/download_multi.go

@@ -27,7 +27,7 @@ type DownloadFilesStats struct {
 	LargestFileSize       int64
 }
 
-func DownloadCacheFilesFromBuildCache(ctx context.Context, dd FileGroupInfo, kvClient *kv.Client, logger log.Logger) (DownloadFilesStats, error) {
+func DownloadCacheFilesFromBuildCache(ctx context.Context, dd FileGroupInfo, kvClient *kv.Client, logger log.Logger, isDebugLogMode bool) (DownloadFilesStats, error) {
 	var largestFileSize int64
 	for _, file := range dd.Files {
 		if file.Size > largestFileSize {
@@ -55,7 +55,7 @@ func DownloadCacheFilesFromBuildCache(ctx context.Context, dd FileGroupInfo, kvC
 
 			const retries = 3
 			err := retry.Times(retries).Wait(3 * time.Second).TryWithAbort(func(_ uint) (error, bool) {
-				err := downloadFile(ctx, kvClient, file.Path, file.Hash, file.Mode)
+				err := downloadFile(ctx, kvClient, file.Path, file.Hash, file.Mode, logger, isDebugLogMode)
 				if errors.Is(err, ErrCacheNotFound) {
 					return err, true
 				} else if err != nil {