diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index fda02cad..284d3b30 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -3,7 +3,7 @@ name: CI & Release on: push: branches: - - main + - logging-add-reqid-34 pull_request: branches: - main @@ -113,7 +113,7 @@ jobs: env: IS_LATEST_RELEASE: 'true' - APP_VERSION: 1.0.5 + APP_VERSION: 0.12.47 steps: - name: Checkout Code @@ -139,13 +139,12 @@ jobs: /home/runner/work/ibm-object-csi-driver/ibm-object-csi-driver/cos-csi-mounter/cos-csi-mounter-${{ env.APP_VERSION }}.deb.tar.gz.sha256 /home/runner/work/ibm-object-csi-driver/ibm-object-csi-driver/cos-csi-mounter/cos-csi-mounter-${{ env.APP_VERSION }}.rpm.tar.gz /home/runner/work/ibm-object-csi-driver/ibm-object-csi-driver/cos-csi-mounter/cos-csi-mounter-${{ env.APP_VERSION }}.rpm.tar.gz.sha256 - tag_name: v1.0.5 - name: v1.0.5 + tag_name: 0.12.47 + name: 0.12.47 body: | ## πŸš€ What’s New - - Fix for rclone mount hang issue - - Add support for s3fs disable_noobj_cache flag - - Skip unmount for 'is not a mountpoint' error + - updated logging method + - introduced requestID in logs prerelease: ${{ env.IS_LATEST_RELEASE != 'true' }} - name: Perform CodeQL Analysis diff --git a/.gitignore b/.gitignore index 25c31206..5c971fd1 100644 --- a/.gitignore +++ b/.gitignore @@ -1,2 +1,3 @@ .idea -bin \ No newline at end of file +bin +tests \ No newline at end of file diff --git a/README.md b/README.md index d1d79835..274886a2 100644 --- a/README.md +++ b/README.md @@ -173,3 +173,49 @@ Collect logs using below commands to check failure messages 1. `oc logs cos-s3-csi-controller-0 -c cos-csi-provisioner` 2. `oc logs cos-s3-csi-driver-xxx -c cos-csi-driver` + +## Request ID Tracking + +The IBM Object CSI Driver implements comprehensive request ID tracking for end-to-end tracing of operations. Every CSI operation is assigned a unique UUID v4 identifier that flows through all components. + +### Key Features +- **Automatic Request ID Generation**: Every gRPC request gets a unique UUID v4 +- **End-to-End Propagation**: Request ID flows through CSI β†’ S3Client β†’ Mounter β†’ cos-csi-mounter +- **Structured Logging**: All logs include request ID in both message text and structured fields +- **Cross-Component Tracing**: Track operations across controller, node, and mounter services + +### Quick Start + +Filter logs by request ID: +```bash +# Get logs for specific request +kubectl logs -n kube-system | grep "550e8400-e29b-41d4-a716-446655440000" + +# Using jq for JSON logs +kubectl logs -n kube-system | jq 'select(.request_id == "550e8400-...")' +``` + +Track complete operation flow: +```bash +# Extract request ID from initial log +REQUEST_ID=$(kubectl logs -n kube-system | \ + jq -r 'select(.msg | contains("CreateVolume started")) | .request_id' | head -1) + +# View all logs for that request +kubectl logs -n kube-system | jq "select(.request_id == \"$REQUEST_ID\")" +``` + +### Documentation +For comprehensive documentation on request ID tracking, troubleshooting, and best practices, see: +- [Request ID Tracking Guide](docs/REQUEST_ID_TRACKING.md) + +### Example Log Output +```json +{ + "level": "info", + "timestamp": "2024-01-15T10:30:45.123Z", + "msg": "[550e8400-e29b-41d4-a716-446655440000] CreateVolume started", + "request_id": "550e8400-e29b-41d4-a716-446655440000", + "volume_name": "pvc-abc123" +} +``` diff --git a/cmd/main.go b/cmd/main.go index f62ac513..5c2de886 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -31,7 +31,6 @@ import ( "github.com/prometheus/client_golang/prometheus/promhttp" "go.uber.org/zap" "go.uber.org/zap/zapcore" - "k8s.io/klog/v2" ) // Options is the combined set of options for all operating modes. @@ -60,17 +59,21 @@ func getOptions() *Options { } func getZapLogger() *zap.Logger { - // Prepare a new logger + // Prepare a new logger with standardized JSON format atom := zap.NewAtomicLevel() encoderCfg := zap.NewProductionEncoderConfig() encoderCfg.TimeKey = "timestamp" encoderCfg.EncodeTime = zapcore.ISO8601TimeEncoder + encoderCfg.EncodeLevel = zapcore.LowercaseLevelEncoder + encoderCfg.MessageKey = "msg" + encoderCfg.CallerKey = "caller" + encoderCfg.LevelKey = "level" logger := zap.New(zapcore.NewCore( zapcore.NewJSONEncoder(encoderCfg), zapcore.Lock(os.Stdout), atom, - ), zap.AddCaller()).With(zap.String("name", config.CSIPluginGithubName)).With(zap.String("CSIDriverName", "IBM CSI Object Driver")) + ), zap.AddCaller()) atom.SetLevel(zap.InfoLevel) return logger @@ -91,14 +94,15 @@ func getConfigBool(envKey string, defaultConf bool, logger zap.Logger) bool { } func main() { - klog.InitFlags(nil) - defer klog.Flush() - logger := getZapLogger() + defer func() { + _ = logger.Sync() // #nosec G104: Best effort sync + }() + loggerLevel := zap.NewAtomicLevel() options := getOptions() - klog.V(1).Info("Starting Server...") + logger.Info("Starting Server...") debugTrace := getConfigBool("DEBUG_TRACE", false, *logger) if debugTrace { diff --git a/cos-csi-mounter/Makefile b/cos-csi-mounter/Makefile index 55da3103..f942da6a 100644 --- a/cos-csi-mounter/Makefile +++ b/cos-csi-mounter/Makefile @@ -1,5 +1,5 @@ NAME := cos-csi-mounter -APP_VERSION := 1.0.5 +APP_VERSION := 0.12.47 BUILD_DIR := $(NAME)-$(APP_VERSION) BIN_DIR := bin @@ -107,3 +107,5 @@ clean: packages: packages: deb-build rpm-build tar-package clean + +#testing \ No newline at end of file diff --git a/cos-csi-mounter/server/fake_server.go b/cos-csi-mounter/server/fake_server.go index fe11f584..b4e1efb5 100644 --- a/cos-csi-mounter/server/fake_server.go +++ b/cos-csi-mounter/server/fake_server.go @@ -1,9 +1,10 @@ -//go:build !unit_test -// +build !unit_test +//go:build linux +// +build linux package main import ( + "context" "errors" "net" "net/http" @@ -17,13 +18,13 @@ type MockMounterUtils struct { mock.Mock } -func (m *MockMounterUtils) FuseMount(path string, mounter string, args []string) error { - argsCalled := m.Called(path, mounter, args) +func (m *MockMounterUtils) FuseMount(ctx context.Context, path string, mounter string, args []string) error { + argsCalled := m.Called(ctx, path, mounter, args) return argsCalled.Error(0) } -func (m *MockMounterUtils) FuseUnmount(path string) error { - argsCalled := m.Called(path) +func (m *MockMounterUtils) FuseUnmount(ctx context.Context, path string) error { + argsCalled := m.Called(ctx, path) return argsCalled.Error(0) } diff --git a/cos-csi-mounter/server/rclone.go b/cos-csi-mounter/server/rclone.go index cb28e223..74e40e77 100644 --- a/cos-csi-mounter/server/rclone.go +++ b/cos-csi-mounter/server/rclone.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package main import ( diff --git a/cos-csi-mounter/server/rclone_test.go b/cos-csi-mounter/server/rclone_test.go index db5877d4..9448f70b 100644 --- a/cos-csi-mounter/server/rclone_test.go +++ b/cos-csi-mounter/server/rclone_test.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package main import ( diff --git a/cos-csi-mounter/server/s3fs.go b/cos-csi-mounter/server/s3fs.go index 480f6a0c..58575309 100644 --- a/cos-csi-mounter/server/s3fs.go +++ b/cos-csi-mounter/server/s3fs.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package main import ( diff --git a/cos-csi-mounter/server/s3fs_test.go b/cos-csi-mounter/server/s3fs_test.go index a5bae059..ec336ad8 100644 --- a/cos-csi-mounter/server/s3fs_test.go +++ b/cos-csi-mounter/server/s3fs_test.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package main import ( diff --git a/cos-csi-mounter/server/server.go b/cos-csi-mounter/server/server.go index 3c690dbe..bd0a97e3 100644 --- a/cos-csi-mounter/server/server.go +++ b/cos-csi-mounter/server/server.go @@ -1,6 +1,10 @@ +//go:build linux +// +build linux + package main import ( + "context" "flag" "fmt" "net" @@ -13,6 +17,7 @@ import ( "time" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + loggerPkg "github.com/IBM/ibm-object-csi-driver/pkg/logger" mounterUtils "github.com/IBM/ibm-object-csi-driver/pkg/mounter/utils" "github.com/gin-gonic/gin" "go.uber.org/zap" @@ -42,17 +47,23 @@ func init() { } func setUpLogger() *zap.Logger { - // Prepare a new logger + // Prepare a new logger with standardized JSON format atom := zap.NewAtomicLevel() encoderCfg := zap.NewProductionEncoderConfig() encoderCfg.TimeKey = "timestamp" encoderCfg.EncodeTime = zapcore.ISO8601TimeEncoder + encoderCfg.EncodeLevel = zapcore.LowercaseLevelEncoder + encoderCfg.MessageKey = "msg" + encoderCfg.CallerKey = "caller" + encoderCfg.LevelKey = "level" logger := zap.New(zapcore.NewCore( zapcore.NewJSONEncoder(encoderCfg), zapcore.Lock(os.Stdout), atom, - ), zap.AddCaller()).With(zap.String("ServiceName", "cos-csi-mounter")) + ), zap.AddCaller()).With( + zap.String("service", "cos-csi-mounter"), + zap.String("component", "mounter-server")) atom.SetLevel(zap.InfoLevel) return logger } @@ -159,71 +170,102 @@ func main() { func handleCosMount(mounter mounterUtils.MounterUtils, parser MounterArgsParser) gin.HandlerFunc { return func(c *gin.Context) { + // Extract request ID from HTTP header or generate one + reqID := c.GetHeader("X-Request-ID") + if reqID == "" { + reqID = loggerPkg.GenerateRequestID() + } + log := logger.With(zap.String("request_id", reqID)) + var request MountRequest if err := c.BindJSON(&request); err != nil { - logger.Error("invalid request: ", zap.Error(err)) - c.JSON(http.StatusBadRequest, gin.H{"error": "invalid request"}) + log.Error("Invalid request", zap.Error(err)) + c.JSON(http.StatusBadRequest, gin.H{"error": fmt.Sprintf("[%s] invalid request", reqID)}) return } - logger.Info("New mount request with values:", zap.String("Bucket", request.Bucket), zap.String("Path", request.Path), zap.String("Mounter", request.Mounter), zap.Any("Args", request.Args)) + log.Info("New mount request", + zap.String("bucket", request.Bucket), + zap.String("path", request.Path), + zap.String("mounter", request.Mounter), + zap.Any("args", request.Args)) if request.Mounter != constants.S3FS && request.Mounter != constants.RClone { - logger.Error("invalid mounter", zap.Any("mounter", request.Mounter)) - c.JSON(http.StatusBadRequest, gin.H{"error": "invalid mounter"}) + log.Error("Invalid mounter", zap.String("mounter", request.Mounter)) + c.JSON(http.StatusBadRequest, gin.H{"error": fmt.Sprintf("[%s] invalid mounter", reqID)}) return } if request.Bucket == "" { - logger.Error("missing bucket in request") - c.JSON(http.StatusBadRequest, gin.H{"error": "missing bucket"}) + log.Error("Missing bucket in request") + c.JSON(http.StatusBadRequest, gin.H{"error": fmt.Sprintf("[%s] missing bucket", reqID)}) return } // validate mounter args + log.Debug("Parsing mounter args") args, err := parser.Parse(request) if err != nil { - logger.Error("failed to parse mounter args", zap.Any("mounter", request.Mounter), zap.Error(err)) - - c.JSON(http.StatusBadRequest, gin.H{"error": fmt.Sprintf("invalid args for mounter: %v", err)}) + log.Error("Failed to parse mounter args", + zap.String("mounter", request.Mounter), zap.Error(err)) + c.JSON(http.StatusBadRequest, gin.H{"error": fmt.Sprintf("[%s] invalid args for mounter: %v", reqID, err)}) return } - err = mounter.FuseMount(request.Path, request.Mounter, args) + log.Info("Mounting bucket", + zap.String("path", request.Path), + zap.String("mounter", request.Mounter)) + + // Create context with request_id for end-to-end tracing + ctx := context.WithValue(c.Request.Context(), mounterUtils.RequestIDKey, reqID) + err = mounter.FuseMount(ctx, request.Path, request.Mounter, args) if err != nil { - logger.Error("mount failed: ", zap.Error(err)) - c.JSON(http.StatusInternalServerError, gin.H{"error": fmt.Sprintf("mount failed: %v", err)}) + log.Error("Mount failed", zap.Error(err)) + c.JSON(http.StatusInternalServerError, gin.H{"error": fmt.Sprintf("[%s] mount failed: %v", reqID, err)}) return } - logger.Info("bucket mount is successful", zap.Any("bucket", request.Bucket), zap.Any("path", request.Path)) + log.Info("Bucket mount successful", + zap.String("bucket", request.Bucket), + zap.String("path", request.Path)) c.JSON(http.StatusOK, gin.H{"status": "success"}) } } func handleCosUnmount(mounter mounterUtils.MounterUtils) gin.HandlerFunc { return func(c *gin.Context) { + // Extract request ID from HTTP header or generate one + reqID := c.GetHeader("X-Request-ID") + if reqID == "" { + reqID = loggerPkg.GenerateRequestID() + } + log := logger.With(zap.String("request_id", reqID)) + var request struct { Path string `json:"path"` } if err := c.BindJSON(&request); err != nil { - logger.Error("invalid request: ", zap.Error(err)) - c.JSON(http.StatusBadRequest, gin.H{"error": "invalid request"}) + log.Error("Invalid request", zap.Error(err)) + c.JSON(http.StatusBadRequest, gin.H{"error": fmt.Sprintf("[%s] invalid request", reqID)}) return } - logger.Info("New unmount request with values: ", zap.String("Path", request.Path)) + log.Info("New unmount request", zap.String("path", request.Path)) + + log.Info("Unmounting bucket", zap.String("path", request.Path)) - err := mounter.FuseUnmount(request.Path) + // Create context with request_id for end-to-end tracing + ctx := context.WithValue(c.Request.Context(), mounterUtils.RequestIDKey, reqID) + err := mounter.FuseUnmount(ctx, request.Path) if err != nil { - logger.Error("unmount failed: ", zap.Error(err)) - c.JSON(http.StatusInternalServerError, gin.H{"error": fmt.Sprintf("unmount failed :%v", err)}) + log.Error("Unmount failed", zap.Error(err)) + c.JSON(http.StatusInternalServerError, gin.H{"error": fmt.Sprintf("[%s] unmount failed: %v", reqID, err)}) return } - logger.Info("bucket unmount is successful", zap.Any("path", request.Path)) + log.Info("Bucket unmount successful", zap.String("path", request.Path)) c.JSON(http.StatusOK, gin.H{"status": "success"}) } } diff --git a/cos-csi-mounter/server/server_test.go b/cos-csi-mounter/server/server_test.go index 4a9a0b18..c1d28dc5 100644 --- a/cos-csi-mounter/server/server_test.go +++ b/cos-csi-mounter/server/server_test.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package main import ( @@ -16,6 +19,7 @@ import ( "github.com/IBM/ibm-object-csi-driver/pkg/constants" "github.com/gin-gonic/gin" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/mock" ) func TestSetupSocket_CreatesSocket(t *testing.T) { @@ -232,7 +236,7 @@ func TestHandleCosMount_FuseMountFails(t *testing.T) { expectedArgs := []string{"--endpoint=https://s3.example.com"} mockParser.On("Parse", request).Return(expectedArgs, nil) - mockMounter.On("FuseMount", request.Path, request.Mounter, expectedArgs).Return(fmt.Errorf("mount error")) + mockMounter.On("FuseMount", mock.Anything, request.Path, request.Mounter, expectedArgs).Return(fmt.Errorf("mount error")) router := gin.Default() router.POST("/mount", handleCosMount(mockMounter, mockParser)) @@ -265,7 +269,7 @@ func TestHandleCosMount_Success(t *testing.T) { expectedArgs := []string{"--endpoint=https://s3.example.com"} mockParser.On("Parse", request).Return(expectedArgs, nil) - mockMounter.On("FuseMount", request.Path, request.Mounter, expectedArgs).Return(nil) + mockMounter.On("FuseMount", mock.Anything, request.Path, request.Mounter, expectedArgs).Return(nil) router := gin.Default() router.POST("/mount", handleCosMount(mockMounter, mockParser)) @@ -300,11 +304,11 @@ func TestHandleCosUnmount_InvalidJSON(t *testing.T) { } func TestHandleCosUnmount_UnmountFailure(t *testing.T) { - mock := new(MockMounterUtils) - mock.On("FuseUnmount", "/mnt/fail").Return(errors.New("mock failure")) + mockMounter := new(MockMounterUtils) + mockMounter.On("FuseUnmount", mock.Anything, "/mnt/fail").Return(errors.New("mock failure")) router := gin.Default() - router.POST("/unmount", handleCosUnmount(mock)) + router.POST("/unmount", handleCosUnmount(mockMounter)) reqBody := map[string]string{"path": "/mnt/fail"} body, _ := json.Marshal(reqBody) @@ -317,15 +321,15 @@ func TestHandleCosUnmount_UnmountFailure(t *testing.T) { assert.Equal(t, http.StatusInternalServerError, w.Code) assert.Contains(t, w.Body.String(), "unmount failed") - mock.AssertExpectations(t) + mockMounter.AssertExpectations(t) } func TestHandleCosUnmount_Success(t *testing.T) { - mock := new(MockMounterUtils) - mock.On("FuseUnmount", "/mnt/success").Return(nil) + mockMounter := new(MockMounterUtils) + mockMounter.On("FuseUnmount", mock.Anything, "/mnt/success").Return(nil) router := gin.Default() - router.POST("/unmount", handleCosUnmount(mock)) + router.POST("/unmount", handleCosUnmount(mockMounter)) reqBody := map[string]string{"path": "/mnt/success"} body, _ := json.Marshal(reqBody) @@ -338,5 +342,5 @@ func TestHandleCosUnmount_Success(t *testing.T) { assert.Equal(t, http.StatusOK, w.Code) assert.Contains(t, w.Body.String(), "success") - mock.AssertExpectations(t) + mockMounter.AssertExpectations(t) } diff --git a/cos-csi-mounter/server/utils.go b/cos-csi-mounter/server/utils.go index e2858b11..c911ea28 100644 --- a/cos-csi-mounter/server/utils.go +++ b/cos-csi-mounter/server/utils.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package main import ( diff --git a/cos-csi-mounter/server/utils_test.go b/cos-csi-mounter/server/utils_test.go index f111b021..ed90ac5d 100644 --- a/cos-csi-mounter/server/utils_test.go +++ b/cos-csi-mounter/server/utils_test.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package main import ( diff --git a/pkg/driver/controllerserver.go b/pkg/driver/controllerserver.go index a2ee8de8..5f928124 100644 --- a/pkg/driver/controllerserver.go +++ b/pkg/driver/controllerserver.go @@ -22,6 +22,7 @@ import ( "time" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/logger" "github.com/IBM/ibm-object-csi-driver/pkg/s3client" "github.com/IBM/ibm-object-csi-driver/pkg/utils" "github.com/aws/smithy-go" @@ -30,7 +31,6 @@ import ( "google.golang.org/grpc/codes" "google.golang.org/grpc/status" v1 "k8s.io/api/core/v1" - "k8s.io/klog/v2" ) // Implements Controller csi.ControllerServer @@ -42,7 +42,9 @@ type controllerServer struct { Logger *zap.Logger } -func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolumeRequest) (*csi.CreateVolumeResponse, error) { +func (cs *controllerServer) CreateVolume(ctx context.Context, req *csi.CreateVolumeRequest) (*csi.CreateVolumeResponse, error) { + // Extract request ID from context (added by interceptor) + var ( bucketName string endPoint string @@ -54,29 +56,36 @@ func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolum quotaLimitEnabled bool ) + logger.Info(ctx, cs.Logger, "CreateVolume started", zap.String("volume_name", req.GetName())) + modifiedRequest, err := utils.ReplaceAndReturnCopy(req) if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in modifying requests %v", err)) + logger.Error(ctx, cs.Logger, "Error modifying request", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in modifying requests: %v", err)) } - klog.V(3).Infof("CSIControllerServer-CreateVolume: Request: %v", modifiedRequest.(*csi.CreateVolumeRequest)) + logger.Debug(ctx, cs.Logger, "CreateVolume request details", zap.Any("request", modifiedRequest.(*csi.CreateVolumeRequest))) volumeName, err := sanitizeVolumeID(req.GetName()) if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in sanitizeVolumeID %v", err)) + logger.Error(ctx, cs.Logger, "Error sanitizing volume ID", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in sanitizeVolumeID: %v", err)) } volumeID := volumeName if len(volumeID) == 0 { + logger.Error(ctx, cs.Logger, "Volume name missing in request") return nil, status.Error(codes.InvalidArgument, "Volume name missing in request") } - klog.Infof("Got a request to create volume: %s", volumeID) + logger.Info(ctx, cs.Logger, "Processing volume creation", zap.String("volume_id", volumeID)) caps := req.GetVolumeCapabilities() if caps == nil { + logger.Error(ctx, cs.Logger, "Volume capabilities missing in request") return nil, status.Error(codes.InvalidArgument, "Volume Capabilities missing in request") } for _, cap := range caps { - klog.Infof("Volume capability: %s", cap) + logger.Debug(ctx, cs.Logger, "Volume capability", zap.String("capability", cap.String())) if cap.GetBlock() != nil { + logger.Error(ctx, cs.Logger, "Block volume not supported") return nil, status.Error(codes.InvalidArgument, "Volume type block Volume not supported") } } @@ -85,32 +94,35 @@ func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolum if params == nil { params = make(map[string]string) } - klog.Info("CreateVolume Parameters:\n\t", params) + logger.Info(ctx, cs.Logger, "CreateVolume parameters received", zap.Int("param_count", len(params))) secretMap := req.GetSecrets() - klog.Info("req.GetSecrets() length:\t", len(secretMap)) + logger.Info(ctx, cs.Logger, "Secrets received", zap.Int("secret_count", len(secretMap))) var customSecretName string if len(secretMap) == 0 { - klog.Info("Did not find the secret that matches pvc name. Fetching custom secret from PVC annotations") + logger.Info(ctx, cs.Logger, "No secret in request, fetching custom secret from PVC annotations") pvcName = params[constants.PVCNameKey] pvcNamespace = params[constants.PVCNamespaceKey] if pvcName == "" { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("pvcName not specified, could not fetch the secret %v", err)) + logger.Error(ctx, cs.Logger, "PVC name not specified") + return nil, status.Error(codes.InvalidArgument, "pvcName not specified, could not fetch the secret") } if pvcNamespace == "" { pvcNamespace = constants.DefaultNamespace } + logger.Info(ctx, cs.Logger, "Fetching PVC", zap.String("pvc_name", pvcName), zap.String("namespace", pvcNamespace)) pvcRes, err := cs.Stats.GetPVC(pvcName, pvcNamespace) if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("PVC resource not found %v", err)) + logger.Error(ctx, cs.Logger, "PVC resource not found", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("PVC resource not found: %v", err)) } - klog.Info("pvc annotations:\n\t", pvcRes.Annotations) + logger.Debug(ctx, cs.Logger, "PVC annotations", zap.Any("annotations", pvcRes.Annotations)) pvcAnnotations := pvcRes.Annotations @@ -118,51 +130,57 @@ func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolum secretNamespace := pvcAnnotations[constants.SecretNamespaceKey] if customSecretName == "" { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("secretName annotation 'cos.csi.driver/secret' not specified in the PVC annotations, could not fetch the secret %v", err)) + logger.Error(ctx, cs.Logger, "Secret name annotation not found in PVC") + return nil, status.Error(codes.InvalidArgument, "secretName annotation 'cos.csi.driver/secret' not specified in the PVC annotations") } if secretNamespace == "" { - klog.Info("secretNamespace annotation 'cos.csi.driver/secret-namespace' not specified in PVC annotations:\t", pvcRes.Annotations, "\t trying to fetch the secret in default namespace") + logger.Warn(ctx, cs.Logger, "Secret namespace not specified in PVC annotations, using default namespace") secretNamespace = constants.DefaultNamespace } + logger.Info(ctx, cs.Logger, "Fetching secret", zap.String("secret_name", customSecretName), zap.String("namespace", secretNamespace)) secret, err := cs.Stats.GetSecret(customSecretName, secretNamespace) if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Secret resource not found %v", err)) + logger.Error(ctx, cs.Logger, "Secret resource not found", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Secret resource not found: %v", err)) } - secretMapCustom := parseCustomSecret(secret) - klog.Info("custom secret parameters parsed successfully, length of custom secret: ", len(secretMapCustom)) + secretMapCustom := parseCustomSecret(ctx, secret, cs.Logger) + logger.Info(ctx, cs.Logger, "Custom secret parsed successfully", zap.Int("secret_param_count", len(secretMapCustom))) if objectPath, exists := secretMapCustom["objectPath"]; exists { - klog.Infof("volume_id:%q objectPath found in secret: %q", volumeID, objectPath) + logger.Info(ctx, cs.Logger, "ObjectPath found in secret", zap.String("volume_id", volumeID), zap.String("object_path", objectPath)) params["objectPath"] = objectPath } else { - klog.Infof("volume_id:%q no objectPath in secret (mounting bucket root)", volumeID) + logger.Info(ctx, cs.Logger, "No objectPath in secret, mounting bucket root", zap.String("volume_id", volumeID)) } secretMap = secretMapCustom } if quotaLimitStr, ok := secretMap[constants.QuotaLimitKey]; ok && quotaLimitStr != "" { - klog.Infof("quotaLimit from secretMap: %q", quotaLimitStr) + logger.Info(ctx, cs.Logger, "Quota limit parameter found", zap.String("quota_limit", quotaLimitStr)) quotaLimitEnabled, err = strconv.ParseBool(quotaLimitStr) if err != nil { + logger.Error(ctx, cs.Logger, "Invalid quota limit value", zap.String("value", quotaLimitStr), zap.Error(err)) return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("invalid quotaLimit value %q: must be 'true' or 'false'", quotaLimitStr)) } if quotaLimitEnabled { if secretMap[constants.ResourceConfigApiKey] == "" { + logger.Error(ctx, cs.Logger, "Resource config API key missing for quota limit") return nil, status.Error(codes.InvalidArgument, "resourceConfigApiKey missing in secret, cannot set quota limit for bucket") } quotaBytes := req.GetCapacityRange().GetRequiredBytes() if quotaBytes <= 0 { + logger.Error(ctx, cs.Logger, "Invalid storage size for quota limit", zap.Int64("bytes", quotaBytes)) return nil, status.Error(codes.InvalidArgument, "enable quotaLimit requested but no positive storage size requested in PVC") } - klog.Infof("enable quota limit requested with %d bytes", quotaBytes) + logger.Info(ctx, cs.Logger, "Quota limit enabled", zap.Int64("quota_bytes", quotaBytes)) } } @@ -173,6 +191,7 @@ func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolum params["cosEndpoint"] = endPoint } if endPoint == "" { + logger.Error(ctx, cs.Logger, "COS endpoint not specified") return nil, status.Error(codes.InvalidArgument, "cosEndpoint unknown") } @@ -183,12 +202,13 @@ func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolum params["locationConstraint"] = locationConstraint } if locationConstraint == "" { + logger.Error(ctx, cs.Logger, "Location constraint not specified") return nil, status.Error(codes.InvalidArgument, "locationConstraint unknown") } kpRootKeyCrn = secretMap["kpRootKeyCRN"] if kpRootKeyCrn != "" { - klog.Infof("key protect root key crn provided for bucket creation") + logger.Info(ctx, cs.Logger, "Key Protect root key CRN provided for bucket encryption") } mounter := secretMap["mounter"] @@ -197,6 +217,7 @@ func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolum } else { params["mounter"] = mounter } + logger.Info(ctx, cs.Logger, "Mounter type configured", zap.String("mounter", mounter)) bucketName = secretMap["bucketName"] @@ -204,128 +225,161 @@ func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolum if val, ok := secretMap[constants.BucketVersioning]; ok && val != "" { enable := strings.ToLower(strings.TrimSpace(val)) if enable != "true" && enable != "false" { + logger.Error(ctx, cs.Logger, "Invalid bucket versioning value in secret", zap.String("value", val)) return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Invalid BucketVersioning value in secret: %s. Value set %s. Must be 'true' or 'false'", customSecretName, val)) } bucketVersioning = enable - klog.Infof("BucketVersioning value that will be set via secret: %s", bucketVersioning) + logger.Info(ctx, cs.Logger, "Bucket versioning from secret", zap.String("versioning", bucketVersioning)) } else if val, ok := params[constants.BucketVersioning]; ok && val != "" { enable := strings.ToLower(strings.TrimSpace(val)) if enable != "true" && enable != "false" { + logger.Error(ctx, cs.Logger, "Invalid bucket versioning value in storage class", zap.String("value", val)) return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Invalid bucketVersioning value in storage class: %s. Must be 'true' or 'false'", val)) } bucketVersioning = enable - klog.Infof("BucketVersioning value that will be set via storage class params: %s", bucketVersioning) + logger.Info(ctx, cs.Logger, "Bucket versioning from storage class", zap.String("versioning", bucketVersioning)) } - creds, err := getObjectStorageCredentialsFromSecret(secretMap, cs.iamEndpoint) + creds, err := getObjectStorageCredentialsFromSecret(ctx, secretMap, cs.iamEndpoint, cs.Logger) if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in getting credentials %v", err)) + logger.Error(ctx, cs.Logger, "Error getting credentials from secret", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in getting credentials: %v", err)) } - klog.Infof("cosEndpoint and locationConstraint getting paased to ObjectStorageSession: %s, %s", endPoint, locationConstraint) + logger.Info(ctx, cs.Logger, "Creating object storage session", + zap.String("endpoint", endPoint), + zap.String("location_constraint", locationConstraint)) sess := cs.cosSession.NewObjectStorageSession(endPoint, locationConstraint, creds, cs.Logger) params["userProvidedBucket"] = "true" if bucketName != "" { // User Provided bucket. Check its existence and create if not present - klog.Infof("Bucket name provided: %v", bucketName) - klog.Infof("Check if the provided bucket already exists: %v", bucketName) - if err := sess.CheckBucketAccess(bucketName); err != nil { - klog.Infof("CreateVolume: bucket not accessible: %v, Creating new bucket with given name", err) - err = createBucket(sess, bucketName, kpRootKeyCrn) + logger.Info(ctx, cs.Logger, "Bucket name provided", zap.String("bucket_name", bucketName)) + logger.Info(ctx, cs.Logger, "Checking if bucket already exists", zap.String("bucket_name", bucketName)) + if err := sess.CheckBucketAccess(ctx, bucketName); err != nil { + logger.Info(ctx, cs.Logger, "Bucket not accessible, creating new bucket", + zap.String("bucket_name", bucketName), zap.Error(err)) + err = createBucket(ctx, sess, bucketName, kpRootKeyCrn, cs.Logger) if err != nil { - return nil, status.Error(codes.PermissionDenied, fmt.Sprintf("%v: %v", err, bucketName)) + logger.Error(ctx, cs.Logger, "Failed to create bucket", + zap.String("bucket_name", bucketName), zap.Error(err)) + return nil, status.Error(codes.PermissionDenied, fmt.Sprintf("%v:: %v", err, bucketName)) } params["userProvidedBucket"] = "false" - klog.Infof("Created bucket: %s", bucketName) + logger.Info(ctx, cs.Logger, "Created bucket successfully", zap.String("bucket_name", bucketName)) } if quotaLimitEnabled { quotaBytes := req.GetCapacityRange().GetRequiredBytes() resConfApikey := secretMap[constants.ResourceConfigApiKey] - klog.Infof("Applying hard quota of %d bytes to bucket %s", quotaBytes, bucketName) - err = sess.UpdateQuotaLimit(quotaBytes, resConfApikey, bucketName, endPoint, creds.IAMEndpoint) + logger.Info(ctx, cs.Logger, "Applying hard quota to bucket", + zap.Int64("quota_bytes", quotaBytes), zap.String("bucket_name", bucketName)) + err = sess.UpdateQuotaLimit(ctx, quotaBytes, resConfApikey, bucketName, endPoint, creds.IAMEndpoint) if err != nil { - klog.Errorf("Failed to set quota limit on bucket %s: %v", bucketName, err) + logger.Error(ctx, cs.Logger, "Failed to set quota limit on bucket", + zap.String("bucket_name", bucketName), zap.Error(err)) if params["userProvidedBucket"] == "false" { - if delErr := sess.DeleteBucket(bucketName); delErr != nil { - klog.Errorf("Failed to delete bucket %s after quota limit failure: %v", bucketName, delErr) + if delErr := sess.DeleteBucket(ctx, bucketName); delErr != nil { + logger.Error(ctx, cs.Logger, "Failed to delete bucket after quota limit failure", + zap.String("bucket_name", bucketName), zap.Error(delErr)) } } - return nil, status.Error(codes.Internal, fmt.Sprintf("failed to set bucket quota limit: %v", err)) + return nil, status.Error(codes.Internal, fmt.Sprintf("failed to set bucket quota limit:: %v", err)) } - klog.Infof("Successfully applied hard quota %d bytes to bucket %s", quotaBytes, bucketName) + logger.Info(ctx, cs.Logger, "Successfully applied hard quota to bucket", + zap.Int64("quota_bytes", quotaBytes), zap.String("bucket_name", bucketName)) } if bucketVersioning != "" { enable := strings.ToLower(strings.TrimSpace(bucketVersioning)) == "true" - klog.Infof("Bucket versioning value evaluated to: %t", enable) + logger.Info(ctx, cs.Logger, "Setting bucket versioning", + zap.Bool("enable", enable), zap.String("bucket_name", bucketName)) - err := sess.SetBucketVersioning(bucketName, enable) + err := sess.SetBucketVersioning(ctx, bucketName, enable) if err != nil { + logger.Error(ctx, cs.Logger, "Failed to set bucket versioning", + zap.Bool("enable", enable), zap.String("bucket_name", bucketName), zap.Error(err)) if params["userProvidedBucket"] == "false" { - err1 := sess.DeleteBucket(bucketName) + err1 := sess.DeleteBucket(ctx, bucketName) if err1 != nil { - return nil, status.Error(codes.Internal, fmt.Sprintf("cannot set versioning: %v and cannot delete bucket %s: %v", err, bucketName, err1)) + logger.Error(ctx, cs.Logger, "Failed to delete bucket after versioning failure", + zap.String("bucket_name", bucketName), zap.Error(err1)) + return nil, status.Error(codes.Internal, fmt.Sprintf("cannot set versioning: %v and cannot delete bucket %s:: %v", err, bucketName, err1)) } } - return nil, status.Error(codes.Internal, fmt.Sprintf("failed to set versioning %t for bucket %s: %v", enable, bucketName, err)) + return nil, status.Error(codes.Internal, fmt.Sprintf("failed to set versioning %t for bucket %s:: %v", enable, bucketName, err)) } - klog.Infof("Bucket versioning set to %t for bucket %s", enable, bucketName) + logger.Info(ctx, cs.Logger, "Bucket versioning set successfully", + zap.Bool("enable", enable), zap.String("bucket_name", bucketName)) } params["bucketName"] = bucketName } else { // Generate random temp bucket name based on volume id - klog.Infof("Bucket name not provided") - tempBucketName := getTempBucketName(mounter, volumeID) + logger.Info(ctx, cs.Logger, "Bucket name not provided, generating temp bucket") + tempBucketName := getTempBucketName(ctx, mounter, volumeID, cs.Logger) if tempBucketName == "" { - klog.Errorf("CreateVolume: Unable to generate the bucket name") - return nil, status.Error(codes.PermissionDenied, fmt.Sprintf("Unable to access the bucket: %v", tempBucketName)) + logger.Error(ctx, cs.Logger, "Unable to generate temp bucket name") + return nil, status.Error(codes.PermissionDenied, fmt.Sprintf("Unable to access the bucket:: %v", tempBucketName)) } - err = createBucket(sess, tempBucketName, kpRootKeyCrn) + logger.Info(ctx, cs.Logger, "Creating temp bucket", zap.String("temp_bucket_name", tempBucketName)) + err = createBucket(ctx, sess, tempBucketName, kpRootKeyCrn, cs.Logger) if err != nil { - return nil, status.Error(codes.PermissionDenied, fmt.Sprintf("%v: %v", err, tempBucketName)) + logger.Error(ctx, cs.Logger, "Failed to create temp bucket", + zap.String("temp_bucket_name", tempBucketName), zap.Error(err)) + return nil, status.Error(codes.PermissionDenied, fmt.Sprintf("%v:: %v", err, tempBucketName)) } if quotaLimitEnabled { quotaBytes := req.GetCapacityRange().GetRequiredBytes() resConfApikey := secretMap[constants.ResourceConfigApiKey] - klog.Infof("Applying hard quota of %d bytes to temp bucket %s", quotaBytes, tempBucketName) - err = sess.UpdateQuotaLimit(quotaBytes, resConfApikey, tempBucketName, endPoint, creds.IAMEndpoint) + logger.Info(ctx, cs.Logger, "Applying hard quota to temp bucket", + zap.Int64("quota_bytes", quotaBytes), zap.String("temp_bucket_name", tempBucketName)) + err = sess.UpdateQuotaLimit(ctx, quotaBytes, resConfApikey, tempBucketName, endPoint, creds.IAMEndpoint) if err != nil { - klog.Errorf("Failed to set quota limit on temp bucket %s: %v", tempBucketName, err) - if delErr := sess.DeleteBucket(tempBucketName); delErr != nil { - klog.Errorf("Failed to delete temp bucket %s after quota limit failure: %v", tempBucketName, delErr) + logger.Error(ctx, cs.Logger, "Failed to set quota limit on temp bucket", + zap.String("temp_bucket_name", tempBucketName), zap.Error(err)) + if delErr := sess.DeleteBucket(ctx, tempBucketName); delErr != nil { + logger.Error(ctx, cs.Logger, "Failed to delete temp bucket after quota limit failure", + zap.String("temp_bucket_name", tempBucketName), zap.Error(delErr)) } - return nil, status.Error(codes.Internal, fmt.Sprintf("failed to set bucket quota limit: %v", err)) + return nil, status.Error(codes.Internal, fmt.Sprintf("failed to set bucket quota limit:: %v", err)) } - klog.Infof("Successfully applied hard quota %d bytes to temp bucket %s", quotaBytes, tempBucketName) + logger.Info(ctx, cs.Logger, "Successfully applied hard quota to temp bucket", + zap.Int64("quota_bytes", quotaBytes), zap.String("temp_bucket_name", tempBucketName)) } if bucketVersioning != "" { enable := strings.ToLower(strings.TrimSpace(bucketVersioning)) == "true" - klog.Infof("Temp bucket versioning value evaluated to: %t", enable) + logger.Info(ctx, cs.Logger, "Setting temp bucket versioning", + zap.Bool("enable", enable), zap.String("temp_bucket_name", tempBucketName)) - err := sess.SetBucketVersioning(tempBucketName, enable) + err := sess.SetBucketVersioning(ctx, tempBucketName, enable) if err != nil { - err1 := sess.DeleteBucket(tempBucketName) + logger.Error(ctx, cs.Logger, "Failed to set temp bucket versioning", + zap.Bool("enable", enable), zap.String("temp_bucket_name", tempBucketName), zap.Error(err)) + err1 := sess.DeleteBucket(ctx, tempBucketName) if err1 != nil { - return nil, status.Error(codes.Internal, fmt.Sprintf("cannot set versioning: %v and cannot delete temp bucket %s: %v", err, tempBucketName, err1)) + logger.Error(ctx, cs.Logger, "Failed to delete temp bucket after versioning failure", + zap.String("temp_bucket_name", tempBucketName), zap.Error(err1)) + return nil, status.Error(codes.Internal, fmt.Sprintf("cannot set versioning: %v and cannot delete temp bucket %s:: %v", err, tempBucketName, err1)) } - return nil, status.Error(codes.Internal, fmt.Sprintf("failed to set versioning %t for temp bucket %s: %v", enable, tempBucketName, err)) + return nil, status.Error(codes.Internal, fmt.Sprintf("failed to set versioning %t for temp bucket %s:: %v", enable, tempBucketName, err)) } - klog.Infof("Bucket versioning set to %t for temp bucket %s", enable, tempBucketName) + logger.Info(ctx, cs.Logger, "Temp bucket versioning set successfully", + zap.Bool("enable", enable), zap.String("temp_bucket_name", tempBucketName)) } - klog.Infof("Created temp bucket: %s", tempBucketName) + logger.Info(ctx, cs.Logger, "Created temp bucket successfully", zap.String("temp_bucket_name", tempBucketName)) params["userProvidedBucket"] = "false" params["bucketName"] = tempBucketName } - klog.Infof("create volume: %v", volumeID) - //COS Endpoint, bucket, access keys will be stored in the csiProvisionerSecretName - //The other tunables will be SC Parameters like ibm.io/multireq-max and other + + logger.Info(ctx, cs.Logger, "CreateVolume completed successfully", + zap.String("volume_id", volumeID), + zap.String("bucket_name", params["bucketName"]), + zap.Int64("capacity_bytes", req.GetCapacityRange().GetRequiredBytes())) return &csi.CreateVolumeResponse{ Volume: &csi.Volume{ @@ -336,129 +390,172 @@ func (cs *controllerServer) CreateVolume(_ context.Context, req *csi.CreateVolum }, nil } -func (cs *controllerServer) DeleteVolume(_ context.Context, req *csi.DeleteVolumeRequest) (*csi.DeleteVolumeResponse, error) { - modifiedRequest, err := utils.ReplaceAndReturnCopy(req) - if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in modifying requests %v", err)) - } - klog.V(3).Infof("CSIControllerServer-DeleteVolume: Request: %v", modifiedRequest.(*csi.DeleteVolumeRequest)) +func (cs *controllerServer) DeleteVolume(ctx context.Context, req *csi.DeleteVolumeRequest) (*csi.DeleteVolumeResponse, error) { + // Extract request ID from context volumeID := req.GetVolumeId() if len(volumeID) == 0 { + logger.Error(ctx, cs.Logger, "Volume ID missing in request") return nil, status.Error(codes.InvalidArgument, "Volume ID missing in request") } - klog.Infof("Deleting volume %v", volumeID) + + logger.Info(ctx, cs.Logger, "DeleteVolume started", zap.String("volume_id", volumeID)) + + modifiedRequest, err := utils.ReplaceAndReturnCopy(req) + if err != nil { + logger.Error(ctx, cs.Logger, "Error modifying request", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in modifying requests: %v", err)) + } + logger.Debug(ctx, cs.Logger, "DeleteVolume request details", zap.Any("request", modifiedRequest.(*csi.DeleteVolumeRequest))) + secretMap := req.GetSecrets() + logger.Info(ctx, cs.Logger, "Secrets received", zap.Int("secret_count", len(secretMap))) endPoint := secretMap["cosEndpoint"] locationConstraint := secretMap["locationConstraint"] if len(secretMap) == 0 { - klog.Info("Did not find the secret that matches pvc name. Fetching custom secret from PVC annotations") + logger.Info(ctx, cs.Logger, "No secret in request, fetching from PV") pv, err := cs.Stats.GetPV(volumeID) if err != nil { + logger.Error(ctx, cs.Logger, "Failed to get PV", zap.String("volume_id", volumeID), zap.Error(err)) return nil, err } - klog.Info("pv Resource details:\n\t", pv) + logger.Debug(ctx, cs.Logger, "PV resource retrieved", zap.Any("pv", pv)) secretName := pv.Spec.CSI.NodePublishSecretRef.Name secretNamespace := pv.Spec.CSI.NodePublishSecretRef.Namespace if secretName == "" { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Secret details not found, could not fetch the secret %v", err)) + logger.Error(ctx, cs.Logger, "Secret details not found in PV") + return nil, status.Error(codes.InvalidArgument, "Secret details not found, could not fetch the secret") } if secretNamespace == "" { - klog.Info("secret Namespace not found. trying to fetch the secret in default namespace") + logger.Warn(ctx, cs.Logger, "Secret namespace not found, using default namespace") secretNamespace = constants.DefaultNamespace } endPoint = pv.Spec.CSI.VolumeAttributes["cosEndpoint"] locationConstraint = pv.Spec.CSI.VolumeAttributes["locationConstraint"] - klog.Info("secret details found. secret-name: ", secretName, "\tsecret-namespace: ", secretNamespace) + logger.Info(ctx, cs.Logger, "Secret details found", + zap.String("secret_name", secretName), + zap.String("secret_namespace", secretNamespace)) secret, err := cs.Stats.GetSecret(secretName, secretNamespace) if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Secret resource not found %v", err)) + logger.Error(ctx, cs.Logger, "Secret resource not found", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Secret resource not found: %v", err)) } - secretMapCustom := parseCustomSecret(secret) - klog.Info("custom secret parameters parsed successfully, length of custom secret: ", len(secretMapCustom)) + secretMapCustom := parseCustomSecret(ctx, secret, cs.Logger) + logger.Info(ctx, cs.Logger, "Custom secret parsed successfully", zap.Int("secret_param_count", len(secretMapCustom))) secretMap = secretMapCustom } - creds, err := getObjectStorageCredentialsFromSecret(secretMap, cs.iamEndpoint) + creds, err := getObjectStorageCredentialsFromSecret(ctx, secretMap, cs.iamEndpoint, cs.Logger) if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in getting credentials %v", err)) + logger.Error(ctx, cs.Logger, "Error getting credentials from secret", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in getting credentials: %v", err)) } + logger.Info(ctx, cs.Logger, "Creating object storage session for deletion", + zap.String("endpoint", endPoint), + zap.String("location_constraint", locationConstraint)) sess := cs.cosSession.NewObjectStorageSession(endPoint, locationConstraint, creds, cs.Logger) bucketToDelete, err := cs.Stats.BucketToDelete(volumeID) if err != nil { + logger.Warn(ctx, cs.Logger, "No bucket to delete or error getting bucket info", zap.Error(err)) return &csi.DeleteVolumeResponse{}, nil } if bucketToDelete != "" { - err = sess.DeleteBucket(bucketToDelete) + logger.Info(ctx, cs.Logger, "Deleting bucket", zap.String("bucket_name", bucketToDelete)) + err = sess.DeleteBucket(ctx, bucketToDelete) if err != nil { - klog.V(3).Infof("Cannot delete temp bucket: %v; error msg: %v", bucketToDelete, err) + logger.Warn(ctx, cs.Logger, "Cannot delete bucket", + zap.String("bucket_name", bucketToDelete), zap.Error(err)) + } else { + logger.Info(ctx, cs.Logger, "Bucket deleted successfully", zap.String("bucket_name", bucketToDelete)) } - klog.Infof("End of bucket delete for %v", volumeID) + } else { + logger.Info(ctx, cs.Logger, "No bucket to delete") } + logger.Info(ctx, cs.Logger, "DeleteVolume completed successfully", + zap.String("volume_id", volumeID), + zap.String("bucket_name", bucketToDelete)) return &csi.DeleteVolumeResponse{}, nil } -func (cs *controllerServer) ControllerPublishVolume(_ context.Context, req *csi.ControllerPublishVolumeRequest) (*csi.ControllerPublishVolumeResponse, error) { - klog.V(3).Infof("CSIControllerServer-ControllerPublishVolume: Request: %+v", req) +func (cs *controllerServer) ControllerPublishVolume(ctx context.Context, req *csi.ControllerPublishVolumeRequest) (*csi.ControllerPublishVolumeResponse, error) { + + logger.Debug(ctx, cs.Logger, "ControllerPublishVolume request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "ControllerPublishVolume not implemented") return nil, status.Error(codes.Unimplemented, "ControllerPublishVolume") } -func (cs *controllerServer) ControllerUnpublishVolume(_ context.Context, req *csi.ControllerUnpublishVolumeRequest) (*csi.ControllerUnpublishVolumeResponse, error) { - klog.V(3).Infof("CSIControllerServer-ControllerUnPublishVolume: Request: %+v", req) +func (cs *controllerServer) ControllerUnpublishVolume(ctx context.Context, req *csi.ControllerUnpublishVolumeRequest) (*csi.ControllerUnpublishVolumeResponse, error) { + + logger.Debug(ctx, cs.Logger, "ControllerUnpublishVolume request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "ControllerUnpublishVolume not implemented") return nil, status.Error(codes.Unimplemented, "ControllerUnpublishVolume") } -func (cs *controllerServer) ValidateVolumeCapabilities(_ context.Context, req *csi.ValidateVolumeCapabilitiesRequest) (*csi.ValidateVolumeCapabilitiesResponse, error) { - klog.V(3).Infof("ValidateVolumeCapabilities: Request: %+v", req) +func (cs *controllerServer) ValidateVolumeCapabilities(ctx context.Context, req *csi.ValidateVolumeCapabilitiesRequest) (*csi.ValidateVolumeCapabilitiesResponse, error) { + + logger.Info(ctx, cs.Logger, "ValidateVolumeCapabilities started") + logger.Debug(ctx, cs.Logger, "ValidateVolumeCapabilities request", zap.Any("request", req)) // Validate Arguments volumeID := req.GetVolumeId() if len(volumeID) == 0 { + logger.Error(ctx, cs.Logger, "Volume ID missing in request") return nil, status.Error(codes.InvalidArgument, "Volume ID missing in request") } volCaps := req.GetVolumeCapabilities() if len(volCaps) == 0 { + logger.Error(ctx, cs.Logger, "Volume capabilities missing in request") return nil, status.Error(codes.InvalidArgument, "Volume capabilities missing in request") } var confirmed *csi.ValidateVolumeCapabilitiesResponse_Confirmed if isValidVolumeCapabilities(volCaps) { + logger.Info(ctx, cs.Logger, "Volume capabilities are valid", zap.String("volume_id", volumeID)) confirmed = &csi.ValidateVolumeCapabilitiesResponse_Confirmed{VolumeCapabilities: volCaps} + } else { + logger.Warn(ctx, cs.Logger, "Volume capabilities are invalid", zap.String("volume_id", volumeID)) } + logger.Info(ctx, cs.Logger, "ValidateVolumeCapabilities completed", zap.String("volume_id", volumeID)) return &csi.ValidateVolumeCapabilitiesResponse{ Confirmed: confirmed, }, nil } -func (cs *controllerServer) ListVolumes(_ context.Context, req *csi.ListVolumesRequest) (*csi.ListVolumesResponse, error) { - klog.V(3).Infof("ListVolumes: Request: %+v", req) +func (cs *controllerServer) ListVolumes(ctx context.Context, req *csi.ListVolumesRequest) (*csi.ListVolumesResponse, error) { + + logger.Debug(ctx, cs.Logger, "ListVolumes request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "ListVolumes not implemented") return nil, status.Error(codes.Unimplemented, "ListVolumes") } -func (cs *controllerServer) GetCapacity(_ context.Context, req *csi.GetCapacityRequest) (*csi.GetCapacityResponse, error) { - klog.V(3).Infof("GetCapacity: Request: %+v", req) +func (cs *controllerServer) GetCapacity(ctx context.Context, req *csi.GetCapacityRequest) (*csi.GetCapacityResponse, error) { + + logger.Debug(ctx, cs.Logger, "GetCapacity request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "GetCapacity not implemented") return nil, status.Error(codes.Unimplemented, "GetCapacity") } -func (cs *controllerServer) ControllerGetCapabilities(_ context.Context, req *csi.ControllerGetCapabilitiesRequest) (*csi.ControllerGetCapabilitiesResponse, error) { - klog.V(3).Infof("ControllerGetCapabilities: Request: %+v", req) +func (cs *controllerServer) ControllerGetCapabilities(ctx context.Context, req *csi.ControllerGetCapabilitiesRequest) (*csi.ControllerGetCapabilitiesResponse, error) { + logger.Info(ctx, cs.Logger, "ControllerGetCapabilities started") + logger.Debug(ctx, cs.Logger, "ControllerGetCapabilities request", zap.Any("request", req)) + var caps []*csi.ControllerServiceCapability for _, cap := range controllerCapabilities { c := &csi.ControllerServiceCapability{ @@ -470,41 +567,55 @@ func (cs *controllerServer) ControllerGetCapabilities(_ context.Context, req *cs } caps = append(caps, c) } + + logger.Info(ctx, cs.Logger, "ControllerGetCapabilities completed", zap.Int("capability_count", len(caps))) return &csi.ControllerGetCapabilitiesResponse{Capabilities: caps}, nil } -func (cs *controllerServer) CreateSnapshot(_ context.Context, req *csi.CreateSnapshotRequest) (*csi.CreateSnapshotResponse, error) { - klog.V(3).Infof("CreateSnapshot: Request: %+v", req) +func (cs *controllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateSnapshotRequest) (*csi.CreateSnapshotResponse, error) { + + logger.Debug(ctx, cs.Logger, "CreateSnapshot request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "CreateSnapshot not implemented") return nil, status.Error(codes.Unimplemented, "CreateSnapshot") } -func (cs *controllerServer) DeleteSnapshot(_ context.Context, req *csi.DeleteSnapshotRequest) (*csi.DeleteSnapshotResponse, error) { - klog.V(3).Infof("DeleteSnapshot: called with args %+v", req) +func (cs *controllerServer) DeleteSnapshot(ctx context.Context, req *csi.DeleteSnapshotRequest) (*csi.DeleteSnapshotResponse, error) { + + logger.Debug(ctx, cs.Logger, "DeleteSnapshot request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "DeleteSnapshot not implemented") return nil, status.Error(codes.Unimplemented, "DeleteSnapshot") } -func (cs *controllerServer) ListSnapshots(_ context.Context, req *csi.ListSnapshotsRequest) (*csi.ListSnapshotsResponse, error) { - klog.V(3).Infof("ListSnapshots: called with args %+v", req) +func (cs *controllerServer) ListSnapshots(ctx context.Context, req *csi.ListSnapshotsRequest) (*csi.ListSnapshotsResponse, error) { + + logger.Debug(ctx, cs.Logger, "ListSnapshots request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "ListSnapshots not implemented") return nil, status.Error(codes.Unimplemented, "ListSnapshots") } -func (cs *controllerServer) ControllerExpandVolume(_ context.Context, req *csi.ControllerExpandVolumeRequest) (*csi.ControllerExpandVolumeResponse, error) { - klog.V(3).Infof("ControllerExpandVolume: called with args %+v", req) +func (cs *controllerServer) ControllerExpandVolume(ctx context.Context, req *csi.ControllerExpandVolumeRequest) (*csi.ControllerExpandVolumeResponse, error) { + + logger.Debug(ctx, cs.Logger, "ControllerExpandVolume request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "ControllerExpandVolume not implemented") return nil, status.Error(codes.Unimplemented, "ControllerExpandVolume") } -func (cs *controllerServer) ControllerGetVolume(_ context.Context, req *csi.ControllerGetVolumeRequest) (*csi.ControllerGetVolumeResponse, error) { - klog.V(3).Infof("ControllerGetVolume: called with args %+v", req) +func (cs *controllerServer) ControllerGetVolume(ctx context.Context, req *csi.ControllerGetVolumeRequest) (*csi.ControllerGetVolumeResponse, error) { + + logger.Debug(ctx, cs.Logger, "ControllerGetVolume request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "ControllerGetVolume not implemented") return nil, status.Error(codes.Unimplemented, "ControllerGetVolume") } -func (cs *controllerServer) ControllerModifyVolume(_ context.Context, req *csi.ControllerModifyVolumeRequest) (*csi.ControllerModifyVolumeResponse, error) { - klog.V(3).Infof("ControllerModifyVolume: called with args %+v", req) +func (cs *controllerServer) ControllerModifyVolume(ctx context.Context, req *csi.ControllerModifyVolumeRequest) (*csi.ControllerModifyVolumeResponse, error) { + + logger.Debug(ctx, cs.Logger, "ControllerModifyVolume request", zap.Any("request", req)) + logger.Info(ctx, cs.Logger, "ControllerModifyVolume not implemented") return nil, status.Error(codes.Unimplemented, "ControllerModifyVolume") } -func getObjectStorageCredentialsFromSecret(secretMap map[string]string, iamEP string) (*s3client.ObjectStorageCredentials, error) { - klog.Infof("- getObjectStorageCredentialsFromSecret-") +func getObjectStorageCredentialsFromSecret(ctx context.Context, secretMap map[string]string, iamEP string, log *zap.Logger) (*s3client.ObjectStorageCredentials, error) { + logger.Info(ctx, log, "Getting object storage credentials from secret") var ( accessKey string secretKey string @@ -547,8 +658,8 @@ func getObjectStorageCredentialsFromSecret(secretMap map[string]string, iamEP st }, nil } -func parseCustomSecret(secret *v1.Secret) map[string]string { - klog.Infof("-parseCustomSecret-") +func parseCustomSecret(ctx context.Context, secret *v1.Secret, log *zap.Logger) map[string]string { + logger.Info(ctx, log, "Parsing custom secret") secretMapCustom := make(map[string]string) var ( @@ -635,8 +746,8 @@ func parseCustomSecret(secret *v1.Secret) map[string]string { return secretMapCustom } -func getTempBucketName(mounterType, volumeID string) string { - klog.Infof("mounterType: %v", mounterType) +func getTempBucketName(ctx context.Context, mounterType, volumeID string, log *zap.Logger) string { + logger.Info(ctx, log, "Getting temp bucket name", zap.String("mounter_type", mounterType)) currentTime := time.Now() timestamp := currentTime.Format("20060102150405") @@ -644,22 +755,22 @@ func getTempBucketName(mounterType, volumeID string) string { return name } -func createBucket(sess s3client.ObjectStorageSession, bucketName, kpRootKeyCrn string) error { - msg, err := sess.CreateBucket(bucketName, kpRootKeyCrn) +func createBucket(ctx context.Context, sess s3client.ObjectStorageSession, bucketName, kpRootKeyCrn string, log *zap.Logger) error { + msg, err := sess.CreateBucket(ctx, bucketName, kpRootKeyCrn) if msg != "" { - klog.Infof("Info:Create Volume module with user provided Bucket name: %v", msg) + logger.Info(ctx, log, "Bucket creation info", zap.String("message", msg)) } if err != nil { var apiErr smithy.APIError if errors.As(err, &apiErr) && apiErr.ErrorCode() == "BucketAlreadyExists" { - klog.Warning(fmt.Sprintf("bucket '%s' already exists", bucketName)) + logger.Warn(ctx, log, "Bucket already exists", zap.String("bucket", bucketName)) } else { - klog.Errorf("CreateVolume: Unable to create the bucket: %v", err) + logger.Error(ctx, log, "Unable to create bucket", zap.String("bucket", bucketName), zap.Error(err)) return errors.New("unable to create the bucket") } } - if err := sess.CheckBucketAccess(bucketName); err != nil { - klog.Errorf("CreateVolume: Unable to access the bucket: %v", err) + if err := sess.CheckBucketAccess(ctx, bucketName); err != nil { + logger.Error(ctx, log, "Unable to access bucket", zap.String("bucket", bucketName), zap.Error(err)) return errors.New("unable to access the bucket") } return nil diff --git a/pkg/driver/controllerserver_test.go b/pkg/driver/controllerserver_test.go index b91826da..1d0543d7 100644 --- a/pkg/driver/controllerserver_test.go +++ b/pkg/driver/controllerserver_test.go @@ -25,6 +25,7 @@ import ( "testing" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" "github.com/IBM/ibm-object-csi-driver/pkg/s3client" "github.com/IBM/ibm-object-csi-driver/pkg/utils" "github.com/container-storage-interface/spec/lib/go/csi" @@ -37,7 +38,8 @@ import ( ) var ( - ctx = context.Background() + // Create context with request ID for testing + ctx = requestid.WithRequestID(context.Background(), "test-request-id") driverName = "testDriver" driverVersion = "testDriverVersion" @@ -405,7 +407,7 @@ func TestCreateVolume(t *testing.T) { }, }), expectedResp: nil, - expectedErr: errors.New("could not fetch the secret"), + expectedErr: errors.New("secretName annotation 'cos.csi.driver/secret' not specified in the PVC annotations"), }, { testCaseName: "Negative: Secret and PVC Names Different, Failed to get Secret", @@ -735,6 +737,7 @@ func TestCreateVolume(t *testing.T) { }, cosSession: tc.cosSession, Stats: tc.driverStatsUtils, + Logger: zap.NewNop(), } actualResp, actualErr := controllerServer.CreateVolume(ctx, tc.req) @@ -983,7 +986,7 @@ func TestDeleteVolume(t *testing.T) { func TestControllerPublishVolume(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ControllerPublishVolume(ctx, &csi.ControllerPublishVolumeRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -993,7 +996,7 @@ func TestControllerPublishVolume(t *testing.T) { func TestControllerUnpublishVolume(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ControllerUnpublishVolume(ctx, &csi.ControllerUnpublishVolumeRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -1070,7 +1073,7 @@ func TestValidateVolumeCapabilities(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ValidateVolumeCapabilities(ctx, tc.req) if tc.expectedErr != nil { @@ -1088,7 +1091,7 @@ func TestValidateVolumeCapabilities(t *testing.T) { func TestListVolumes(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ListVolumes(ctx, &csi.ListVolumesRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -1098,7 +1101,7 @@ func TestListVolumes(t *testing.T) { func TestGetCapacity(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.GetCapacity(ctx, &csi.GetCapacityRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -1134,7 +1137,7 @@ func TestControllerGetCapabilities(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ControllerGetCapabilities(ctx, tc.req) if tc.expectedErr != nil { @@ -1152,7 +1155,7 @@ func TestControllerGetCapabilities(t *testing.T) { func TestCreateSnapshot(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.CreateSnapshot(ctx, &csi.CreateSnapshotRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -1162,7 +1165,7 @@ func TestCreateSnapshot(t *testing.T) { func TestDeleteSnapshot(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.DeleteSnapshot(ctx, &csi.DeleteSnapshotRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -1172,7 +1175,7 @@ func TestDeleteSnapshot(t *testing.T) { func TestListSnapshots(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ListSnapshots(ctx, &csi.ListSnapshotsRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -1182,7 +1185,7 @@ func TestListSnapshots(t *testing.T) { func TestControllerExpandVolume(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ControllerExpandVolume(ctx, &csi.ControllerExpandVolumeRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -1192,7 +1195,7 @@ func TestControllerExpandVolume(t *testing.T) { func TestControllerGetVolume(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ControllerGetVolume(ctx, &csi.ControllerGetVolumeRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) @@ -1202,7 +1205,7 @@ func TestControllerGetVolume(t *testing.T) { func TestControllerModifyVolume(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - controllerServer := &controllerServer{} + controllerServer := &controllerServer{Logger: zap.NewNop()} actualResp, actualErr := controllerServer.ControllerModifyVolume(ctx, &csi.ControllerModifyVolumeRequest{}) assert.Nil(t, actualResp) assert.Error(t, actualErr) diff --git a/pkg/driver/identityserver.go b/pkg/driver/identityserver.go index 64c90fcb..96078fe2 100644 --- a/pkg/driver/identityserver.go +++ b/pkg/driver/identityserver.go @@ -13,10 +13,11 @@ package driver import ( "context" + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" csi "github.com/container-storage-interface/spec/lib/go/csi" + "go.uber.org/zap" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" - "k8s.io/klog/v2" ) // Implements Identity Sever csi.IdentityServe @@ -25,20 +26,28 @@ type identityServer struct { csi.UnimplementedIdentityServer } -func (csiIdentity *identityServer) GetPluginInfo(_ context.Context, req *csi.GetPluginInfoRequest) (*csi.GetPluginInfoResponse, error) { - klog.V(3).Infof("identityServer-GetPluginInfo: Request: %+v", req) +func (csiIdentity *identityServer) GetPluginInfo(ctx context.Context, req *csi.GetPluginInfoRequest) (*csi.GetPluginInfoResponse, error) { + reqID := requestid.FromContext(ctx) + + // Check if S3Driver is nil before accessing its logger if csiIdentity.S3Driver == nil { return nil, status.Error(codes.InvalidArgument, "Driver not configured") } + log := csiIdentity.logger.With(zap.String("request_id", reqID)) + log.Debug("identityServer-GetPluginInfo", zap.Any("request", req)) + return &csi.GetPluginInfoResponse{ Name: csiIdentity.name, VendorVersion: csiIdentity.version, }, nil } -func (csiIdentity *identityServer) GetPluginCapabilities(_ context.Context, req *csi.GetPluginCapabilitiesRequest) (*csi.GetPluginCapabilitiesResponse, error) { - klog.V(3).Infof("identityServer-GetPluginCapabilities: Request %+v", req) +func (csiIdentity *identityServer) GetPluginCapabilities(ctx context.Context, req *csi.GetPluginCapabilitiesRequest) (*csi.GetPluginCapabilitiesResponse, error) { + reqID := requestid.FromContext(ctx) + log := csiIdentity.logger.With(zap.String("request_id", reqID)) + + log.Debug("identityServer-GetPluginCapabilities", zap.Any("request", req)) return &csi.GetPluginCapabilitiesResponse{ Capabilities: []*csi.PluginCapability{ { @@ -66,7 +75,10 @@ func (csiIdentity *identityServer) GetPluginCapabilities(_ context.Context, req }, nil } -func (csiIdentity *identityServer) Probe(_ context.Context, req *csi.ProbeRequest) (*csi.ProbeResponse, error) { - klog.V(3).Infof("identityServer-Probe: Request %+v", req) +func (csiIdentity *identityServer) Probe(ctx context.Context, req *csi.ProbeRequest) (*csi.ProbeResponse, error) { + reqID := requestid.FromContext(ctx) + log := csiIdentity.logger.With(zap.String("request_id", reqID)) + + log.Debug("identityServer-Probe", zap.Any("request", req)) return &csi.ProbeResponse{}, nil } diff --git a/pkg/driver/identityserver_test.go b/pkg/driver/identityserver_test.go index 528d6f4c..2869f34c 100644 --- a/pkg/driver/identityserver_test.go +++ b/pkg/driver/identityserver_test.go @@ -59,9 +59,16 @@ func TestGetPluginInfo(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) + // Ensure S3Driver has a logger if it's not nil + s3Driver := tc.s3Driver + if s3Driver != nil && s3Driver.logger == nil { + s3Driver.logger = zap.NewNop() + } + identityServer := &identityServer{ - S3Driver: tc.s3Driver, + S3Driver: s3Driver, } + actualResp, actualErr := identityServer.GetPluginInfo(ctx, tc.req) if tc.expectedErr != nil { @@ -112,7 +119,9 @@ func TestGetPluginCapabilities(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) - identityServer := &identityServer{} + identityServer := &identityServer{ + S3Driver: &S3Driver{logger: zap.NewNop()}, + } actualResp, actualErr := identityServer.GetPluginCapabilities(ctx, tc.req) if tc.expectedErr != nil { @@ -146,7 +155,9 @@ func TestProbe(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) - identityServer := &identityServer{} + identityServer := &identityServer{ + S3Driver: &S3Driver{logger: zap.NewNop()}, + } actualResp, actualErr := identityServer.Probe(ctx, tc.req) if tc.expectedErr != nil { diff --git a/pkg/driver/interceptor.go b/pkg/driver/interceptor.go new file mode 100644 index 00000000..609cd803 --- /dev/null +++ b/pkg/driver/interceptor.go @@ -0,0 +1,56 @@ +/******************************************************************************* + * IBM Confidential + * OCO Source Materials + * IBM Cloud Kubernetes Service, 5737-D43 + * (C) Copyright IBM Corp. 2023 All Rights Reserved. + * The source code for this program is not published or otherwise divested of + * its trade secrets, irrespective of what has been deposited with + * the U.S. Copyright Office. + ******************************************************************************/ + +package driver + +import ( + "context" + "time" + + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" + "go.uber.org/zap" + "google.golang.org/grpc" +) + +// UnaryServerInterceptor adds request ID to all unary RPC calls and logs request lifecycle +func UnaryServerInterceptor(logger *zap.Logger) grpc.UnaryServerInterceptor { + return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { + // Generate or extract request ID + ctx, reqID := requestid.GetOrGenerate(ctx) + + // Log request start + startTime := time.Now() + logger.Info("gRPC request started", + zap.String("request_id", reqID), + zap.String("method", info.FullMethod), + zap.Time("start_time", startTime)) + + // Call the handler + resp, err := handler(ctx, req) + + // Log request completion + duration := time.Since(startTime) + if err != nil { + logger.Error("gRPC request failed", + zap.String("request_id", reqID), + zap.String("method", info.FullMethod), + zap.Duration("duration", duration), + zap.Error(err)) + } else { + logger.Info("gRPC request completed", + zap.String("request_id", reqID), + zap.String("method", info.FullMethod), + zap.Duration("duration", duration)) + } + + return resp, err + } +} + diff --git a/pkg/driver/interceptor_test.go b/pkg/driver/interceptor_test.go new file mode 100644 index 00000000..695ac79c --- /dev/null +++ b/pkg/driver/interceptor_test.go @@ -0,0 +1,277 @@ +/** + * Copyright 2024 IBM Corp. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package driver + +import ( + "context" + "errors" + "testing" + + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" + "github.com/google/uuid" + "github.com/stretchr/testify/assert" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" + "google.golang.org/grpc" +) + +func TestUnaryServerInterceptor(t *testing.T) { + testCases := []struct { + name string + ctx context.Context + handler grpc.UnaryHandler + expectRequestID bool + expectError bool + expectedErrMsg string + }{ + { + name: "Generates new request ID when context is empty", + ctx: context.Background(), + handler: func(ctx context.Context, req interface{}) (interface{}, error) { + // Verify request ID exists in context + reqID := requestid.FromContext(ctx) + assert.NotEmpty(t, reqID, "Request ID should be present in context") + + // Verify it's a valid UUID + _, err := uuid.Parse(reqID) + assert.NoError(t, err, "Request ID should be a valid UUID") + + return "success", nil + }, + expectRequestID: true, + expectError: false, + }, + { + name: "Preserves existing request ID in context", + ctx: requestid.WithRequestID(context.Background(), "existing-request-id-123"), + handler: func(ctx context.Context, req interface{}) (interface{}, error) { + // Verify the existing request ID is preserved + reqID := requestid.FromContext(ctx) + assert.Equal(t, "existing-request-id-123", reqID, "Existing request ID should be preserved") + return "success", nil + }, + expectRequestID: true, + expectError: false, + }, + { + name: "Logs request ID on successful completion", + ctx: context.Background(), + handler: func(ctx context.Context, req interface{}) (interface{}, error) { + return "success", nil + }, + expectRequestID: true, + expectError: false, + }, + { + name: "Logs request ID on error", + ctx: context.Background(), + handler: func(ctx context.Context, req interface{}) (interface{}, error) { + return nil, errors.New("test error") + }, + expectRequestID: true, + expectError: true, + expectedErrMsg: "test error", + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + // Create an observed logger to capture log entries + core, recorded := observer.New(zapcore.InfoLevel) + logger := zap.New(core) + + // Create the interceptor + interceptor := UnaryServerInterceptor(logger) + + // Create mock server info + info := &grpc.UnaryServerInfo{ + FullMethod: "/test.Service/TestMethod", + } + + // Call the interceptor + resp, err := interceptor(tc.ctx, nil, info, tc.handler) + + // Verify error handling + if tc.expectError { + assert.Error(t, err) + if tc.expectedErrMsg != "" { + assert.Contains(t, err.Error(), tc.expectedErrMsg) + } + } else { + assert.NoError(t, err) + assert.NotNil(t, resp) + } + + // Verify logs contain request ID + if tc.expectRequestID { + logs := recorded.All() + assert.NotEmpty(t, logs, "Should have log entries") + + // Check that logs contain request_id field + foundRequestID := false + var capturedRequestID string + for _, log := range logs { + for _, field := range log.Context { + if field.Key == "request_id" { + foundRequestID = true + capturedRequestID = field.String + + // Verify it's not empty + assert.NotEmpty(t, capturedRequestID, "Request ID in logs should not be empty") + + // If we had an existing request ID, verify it matches + if existingID := requestid.FromContext(tc.ctx); existingID != "" { + assert.Equal(t, existingID, capturedRequestID, "Logged request ID should match context") + } + break + } + } + } + assert.True(t, foundRequestID, "Logs should contain request_id field") + + // Verify all logs for this request have the same request ID + requestIDs := make(map[string]bool) + for _, log := range logs { + for _, field := range log.Context { + if field.Key == "request_id" { + requestIDs[field.String] = true + } + } + } + assert.Equal(t, 1, len(requestIDs), "All logs should have the same request ID") + } + + // Verify log messages + logs := recorded.All() + if tc.expectError { + // Should have "started" and "failed" logs + var hasStarted, hasFailed bool + for _, log := range logs { + if log.Message == "gRPC request started" { + hasStarted = true + } + if log.Message == "gRPC request failed" { + hasFailed = true + } + } + assert.True(t, hasStarted, "Should log request started") + assert.True(t, hasFailed, "Should log request failed") + } else { + // Should have "started" and "completed" logs + var hasStarted, hasCompleted bool + for _, log := range logs { + if log.Message == "gRPC request started" { + hasStarted = true + } + if log.Message == "gRPC request completed" { + hasCompleted = true + } + } + assert.True(t, hasStarted, "Should log request started") + assert.True(t, hasCompleted, "Should log request completed") + } + }) + } +} + +func TestUnaryServerInterceptor_RequestIDPropagation(t *testing.T) { + // Create an observed logger + core, recorded := observer.New(zapcore.InfoLevel) + logger := zap.New(core) + + // Create the interceptor + interceptor := UnaryServerInterceptor(logger) + + // Track the request ID through nested calls + var capturedRequestID string + handler := func(ctx context.Context, req interface{}) (interface{}, error) { + capturedRequestID = requestid.FromContext(ctx) + + // Simulate nested operation that uses the same context + nestedFunc := func(ctx context.Context) string { + return requestid.FromContext(ctx) + } + + nestedRequestID := nestedFunc(ctx) + assert.Equal(t, capturedRequestID, nestedRequestID, "Request ID should propagate to nested calls") + + return "success", nil + } + + info := &grpc.UnaryServerInfo{ + FullMethod: "/test.Service/TestMethod", + } + + // Call the interceptor + _, err := interceptor(context.Background(), nil, info, handler) + assert.NoError(t, err) + + // Verify request ID was captured + assert.NotEmpty(t, capturedRequestID, "Request ID should be captured from context") + + // Verify it's a valid UUID + _, parseErr := uuid.Parse(capturedRequestID) + assert.NoError(t, parseErr, "Request ID should be a valid UUID") + + // Verify logs contain the same request ID + logs := recorded.All() + for _, log := range logs { + for _, field := range log.Context { + if field.Key == "request_id" { + assert.Equal(t, capturedRequestID, field.String, "All logs should have the same request ID") + } + } + } +} + +func TestUnaryServerInterceptor_DurationLogging(t *testing.T) { + // Create an observed logger + core, recorded := observer.New(zapcore.InfoLevel) + logger := zap.New(core) + + // Create the interceptor + interceptor := UnaryServerInterceptor(logger) + + handler := func(ctx context.Context, req interface{}) (interface{}, error) { + return "success", nil + } + + info := &grpc.UnaryServerInfo{ + FullMethod: "/test.Service/TestMethod", + } + + // Call the interceptor + _, err := interceptor(context.Background(), nil, info, handler) + assert.NoError(t, err) + + // Verify duration is logged + logs := recorded.All() + foundDuration := false + for _, log := range logs { + if log.Message == "gRPC request completed" { + for _, field := range log.Context { + if field.Key == "duration" { + foundDuration = true + assert.Greater(t, field.Integer, int64(0), "Duration should be greater than 0") + break + } + } + } + } + assert.True(t, foundDuration, "Should log request duration") +} diff --git a/pkg/driver/nodeserver.go b/pkg/driver/nodeserver.go index 2a858d5e..2cb5609c 100644 --- a/pkg/driver/nodeserver.go +++ b/pkg/driver/nodeserver.go @@ -15,13 +15,14 @@ import ( "fmt" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/logger" "github.com/IBM/ibm-object-csi-driver/pkg/mounter" mounterUtils "github.com/IBM/ibm-object-csi-driver/pkg/mounter/utils" "github.com/IBM/ibm-object-csi-driver/pkg/utils" "github.com/container-storage-interface/spec/lib/go/csi" + "go.uber.org/zap" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" - "k8s.io/klog/v2" ) // Implements Node Server csi.NodeServer @@ -42,66 +43,91 @@ type NodeServerConfig struct { TLSCipherSuite string } -func (ns *nodeServer) NodeStageVolume(_ context.Context, req *csi.NodeStageVolumeRequest) (*csi.NodeStageVolumeResponse, error) { - klog.V(2).Infof("CSINodeServer-NodeStageVolume: Request %+v", req) +func (ns *nodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVolumeRequest) (*csi.NodeStageVolumeResponse, error) { + + logger.Info(ctx, ns.logger, "NodeStageVolume started") + logger.Debug(ctx, ns.logger, "NodeStageVolume request", zap.Any("request", req)) volumeID := req.GetVolumeId() if len(volumeID) == 0 { + logger.Error(ctx, ns.logger, "Volume ID missing in request") return nil, status.Error(codes.InvalidArgument, "Volume ID missing in request") } stagingTargetPath := req.GetStagingTargetPath() if len(stagingTargetPath) == 0 { + logger.Error(ctx, ns.logger, "Target path missing in request") return nil, status.Error(codes.InvalidArgument, "Target path missing in request") } + logger.Info(ctx, ns.logger, "NodeStageVolume completed", + zap.String("volume_id", volumeID), + zap.String("staging_target_path", stagingTargetPath)) return &csi.NodeStageVolumeResponse{}, nil } -func (ns *nodeServer) NodeUnstageVolume(_ context.Context, req *csi.NodeUnstageVolumeRequest) (*csi.NodeUnstageVolumeResponse, error) { - klog.V(2).Infof("CSINodeServer-NodeUnstageVolume: Request %+v", req) +func (ns *nodeServer) NodeUnstageVolume(ctx context.Context, req *csi.NodeUnstageVolumeRequest) (*csi.NodeUnstageVolumeResponse, error) { + + logger.Info(ctx, ns.logger, "NodeUnstageVolume started") + logger.Debug(ctx, ns.logger, "NodeUnstageVolume request", zap.Any("request", req)) volumeID := req.GetVolumeId() if len(volumeID) == 0 { + logger.Error(ctx, ns.logger, "Volume ID missing in request") return nil, status.Error(codes.InvalidArgument, "Volume ID missing in request") } stagingTargetPath := req.GetStagingTargetPath() if len(stagingTargetPath) == 0 { + logger.Error(ctx, ns.logger, "Target path missing in request") return nil, status.Error(codes.InvalidArgument, "Target path missing in request") } + logger.Info(ctx, ns.logger, "NodeUnstageVolume completed", + zap.String("volume_id", volumeID), + zap.String("staging_target_path", stagingTargetPath)) return &csi.NodeUnstageVolumeResponse{}, nil } -func (ns *nodeServer) NodePublishVolume(_ context.Context, req *csi.NodePublishVolumeRequest) (*csi.NodePublishVolumeResponse, error) { - modifiedRequest, err := utils.ReplaceAndReturnCopy(req) - if err != nil { - return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in modifying requests %v", err)) - } - klog.V(2).Infof("CSINodeServer-NodePublishVolume: Request %v", modifiedRequest.(*csi.NodePublishVolumeRequest)) - - volumeMountGroup := req.GetVolumeCapability().GetMount().GetVolumeMountGroup() - klog.V(2).Infof("CSINodeServer-NodePublishVolume-: volumeMountGroup: %v", volumeMountGroup) +func (ns *nodeServer) NodePublishVolume(ctx context.Context, req *csi.NodePublishVolumeRequest) (*csi.NodePublishVolumeResponse, error) { volumeID := req.GetVolumeId() if len(volumeID) == 0 { + logger.Error(ctx, ns.logger, "Volume ID missing in request") return nil, status.Error(codes.InvalidArgument, "Volume ID missing in request") } targetPath := req.GetTargetPath() if len(targetPath) == 0 { + logger.Error(ctx, ns.logger, "Target path missing in request") return nil, status.Error(codes.InvalidArgument, "Target path missing in request") } + logger.Info(ctx, ns.logger, "NodePublishVolume started", + zap.String("volume_id", volumeID), + zap.String("target_path", targetPath)) + + modifiedRequest, err := utils.ReplaceAndReturnCopy(req) + if err != nil { + logger.Error(ctx, ns.logger, "Error modifying request", zap.Error(err)) + return nil, status.Error(codes.InvalidArgument, fmt.Sprintf("Error in modifying requests: %v", err)) + } + logger.Debug(ctx, ns.logger, "NodePublishVolume request", zap.Any("request", modifiedRequest.(*csi.NodePublishVolumeRequest))) + + volumeMountGroup := req.GetVolumeCapability().GetMount().GetVolumeMountGroup() + logger.Debug(ctx, ns.logger, "Volume mount group", zap.String("volume_mount_group", volumeMountGroup)) + if req.GetVolumeCapability() == nil { + logger.Error(ctx, ns.logger, "Volume capability missing in request") return nil, status.Error(codes.InvalidArgument, "Volume capability missing in request") } + logger.Info(ctx, ns.logger, "Checking mount point", zap.String("target_path", targetPath)) err = ns.Stats.CheckMount(targetPath) if err != nil { - klog.Errorf("Can not validate target mount point: %s %v", targetPath, err) - return nil, status.Error(codes.Internal, err.Error()) + logger.Error(ctx, ns.logger, "Cannot validate target mount point", + zap.String("target_path", targetPath), zap.Error(err)) + return nil, status.Error(codes.Internal, fmt.Sprintf("%v", err.Error())) } deviceID := "" @@ -112,11 +138,17 @@ func (ns *nodeServer) NodePublishVolume(_ context.Context, req *csi.NodePublishV readOnly := req.GetReadonly() attrib := req.GetVolumeContext() mountFlags := req.GetVolumeCapability().GetMount().GetMountFlags() - klog.V(2).Infof("-NodePublishVolume-: targetPath: %v\ndeviceID: %v\nreadonly: %v\nvolumeId: %v\nattributes: %v\nmountFlags: %v\n", - targetPath, deviceID, readOnly, volumeID, attrib, mountFlags) + logger.Debug(ctx, ns.logger, "NodePublishVolume parameters", + zap.String("target_path", targetPath), + zap.String("device_id", deviceID), + zap.Bool("readonly", readOnly), + zap.String("volume_id", volumeID), + zap.Any("attributes", attrib), + zap.Strings("mount_flags", mountFlags)) secretMap := req.GetSecrets() - klog.V(2).Infof("-NodePublishVolume-: length of req.GetSecrets() length: %v", len(secretMap)) + logger.Info(ctx, ns.logger, "Secrets received", zap.Int("secret_count", len(secretMap))) + secretMapCopy := make(map[string]string) for k, v := range secretMap { if k == "accessKey" || k == "secretKey" || k == "apiKey" || k == "kpRootKeyCRN" { @@ -125,132 +157,163 @@ func (ns *nodeServer) NodePublishVolume(_ context.Context, req *csi.NodePublishV } secretMapCopy[k] = v } - klog.V(2).Infof("-NodePublishVolume-: secretMap: %v", secretMapCopy) + logger.Debug(ctx, ns.logger, "Secret map (sanitized)", zap.Any("secret_map", secretMapCopy)) + if volumeMountGroup != "" { secretMap["gid"] = volumeMountGroup + logger.Debug(ctx, ns.logger, "Added volume mount group to secrets", zap.String("gid", volumeMountGroup)) } if len(secretMap["cosEndpoint"]) == 0 { secretMap["cosEndpoint"] = attrib["cosEndpoint"] + logger.Debug(ctx, ns.logger, "Using cosEndpoint from attributes", zap.String("cos_endpoint", secretMap["cosEndpoint"])) } if len(secretMap["locationConstraint"]) == 0 { secretMap["locationConstraint"] = attrib["locationConstraint"] + logger.Debug(ctx, ns.logger, "Using locationConstraint from attributes", zap.String("location_constraint", secretMap["locationConstraint"])) } if len(secretMap["cosEndpoint"]) == 0 { + logger.Error(ctx, ns.logger, "S3 Service endpoint not provided") return nil, status.Error(codes.InvalidArgument, "S3 Service endpoint not provided") } if len(secretMap["iamEndpoint"]) == 0 { secretMap["iamEndpoint"] = ns.iamEndpoint + logger.Debug(ctx, ns.logger, "Using default IAM endpoint", zap.String("iam_endpoint", ns.iamEndpoint)) } // If bucket name wasn't provided by user, we use temp bucket created for volume. if secretMap["bucketName"] == "" { + logger.Info(ctx, ns.logger, "Bucket name not provided, fetching from PV") tempBucketName, err := ns.Stats.GetBucketNameFromPV(volumeID) if err != nil { - klog.Errorf("Unable to fetch pv %v", err) - return nil, status.Error(codes.Internal, err.Error()) + logger.Error(ctx, ns.logger, "Unable to fetch PV", zap.String("volume_id", volumeID), zap.Error(err)) + return nil, status.Error(codes.Internal, fmt.Sprintf("%v", err.Error())) } if tempBucketName == "" { - klog.Errorf("Unable to fetch bucket name from pv") + logger.Error(ctx, ns.logger, "Unable to fetch bucket name from PV") return nil, status.Error(codes.Internal, "unable to fetch bucket name from pv") } secretMap["bucketName"] = tempBucketName + logger.Info(ctx, ns.logger, "Using bucket from PV", zap.String("bucket_name", tempBucketName)) } var defaultParamsMap = map[string]string{ constants.CipherSuitesKey: ns.TLSCipherSuite, } + logger.Info(ctx, ns.logger, "Creating mounter object") mounterObj := ns.Mounter.NewMounter(attrib, secretMap, mountFlags, defaultParamsMap) - klog.Info("-NodePublishVolume-: Mount") - if err = mounterObj.Mount("", targetPath); err != nil { - klog.Info("-Mount-: Error: ", err) + logger.Info(ctx, ns.logger, "Mounting volume", + zap.String("bucket_name", secretMap["bucketName"]), + zap.String("target_path", targetPath)) + if err = mounterObj.Mount(ctx, "", targetPath); err != nil { + logger.Error(ctx, ns.logger, "Mount failed", zap.Error(err)) return nil, err } - klog.Infof("s3: bucket %s successfully mounted to %s", secretMap["bucketName"], targetPath) + logger.Info(ctx, ns.logger, "NodePublishVolume completed successfully", + zap.String("volume_id", volumeID), + zap.String("target_path", targetPath), + zap.String("bucket_name", secretMap["bucketName"])) return &csi.NodePublishVolumeResponse{}, nil } -func (ns *nodeServer) NodeUnpublishVolume(_ context.Context, req *csi.NodeUnpublishVolumeRequest) (*csi.NodeUnpublishVolumeResponse, error) { - klog.V(2).Infof("CSINodeServer-NodeUnpublishVolume: Request: %+v", req) +func (ns *nodeServer) NodeUnpublishVolume(ctx context.Context, req *csi.NodeUnpublishVolumeRequest) (*csi.NodeUnpublishVolumeResponse, error) { volumeID := req.GetVolumeId() if len(volumeID) == 0 { + logger.Error(ctx, ns.logger, "Volume ID missing in request") return nil, status.Error(codes.InvalidArgument, "Volume ID missing in request") } targetPath := req.GetTargetPath() if len(targetPath) == 0 { + logger.Error(ctx, ns.logger, "Target path missing in request") return nil, status.Error(codes.InvalidArgument, "Target path missing in request") } - klog.Infof("Unmounting target path %s", targetPath) + + logger.Info(ctx, ns.logger, "NodeUnpublishVolume started", + zap.String("volume_id", volumeID), + zap.String("target_path", targetPath)) + logger.Debug(ctx, ns.logger, "NodeUnpublishVolume request", zap.Any("request", req)) + + logger.Info(ctx, ns.logger, "Unmounting target path", zap.String("target_path", targetPath)) attrib, err := ns.Stats.GetPVAttributes(volumeID) if err != nil { + logger.Error(ctx, ns.logger, "Failed to get PV details", zap.String("volume_id", volumeID), zap.Error(err)) return nil, status.Error(codes.NotFound, "Failed to get PV details") } mounterObj := ns.Mounter.NewMounter(attrib, nil, nil, nil) - klog.Info("-NodeUnpublishVolume-: Unmount") - if err = mounterObj.Unmount(targetPath); err != nil { + logger.Info(ctx, ns.logger, "Unmounting volume") + if err = mounterObj.Unmount(ctx, targetPath); err != nil { //TODO: Need to handle the case with non existing mount separately - https://github.com/IBM/ibm-object-csi-driver/issues/46 - klog.Infof("UNMOUNT ERROR: %v", err) - return nil, status.Error(codes.Internal, err.Error()) + logger.Error(ctx, ns.logger, "Unmount failed", zap.String("target_path", targetPath), zap.Error(err)) + return nil, status.Error(codes.Internal, fmt.Sprintf("%v", err.Error())) } - klog.Infof("Successfully unmounted target path %s", targetPath) + logger.Info(ctx, ns.logger, "NodeUnpublishVolume completed successfully", + zap.String("volume_id", volumeID), + zap.String("target_path", targetPath)) return &csi.NodeUnpublishVolumeResponse{}, nil } -func (ns *nodeServer) NodeGetVolumeStats(_ context.Context, req *csi.NodeGetVolumeStatsRequest) (*csi.NodeGetVolumeStatsResponse, error) { - klog.V(2).Infof("NodeGetVolumeStats: Request: %+v", req) +func (ns *nodeServer) NodeGetVolumeStats(ctx context.Context, req *csi.NodeGetVolumeStatsRequest) (*csi.NodeGetVolumeStatsResponse, error) { + + logger.Info(ctx, ns.logger, "NodeGetVolumeStats started") + logger.Debug(ctx, ns.logger, "NodeGetVolumeStats request", zap.Any("request", req)) volumeID := req.GetVolumeId() if len(volumeID) == 0 { + logger.Error(ctx, ns.logger, "Volume ID missing in request") return nil, status.Error(codes.InvalidArgument, "Volume ID missing in request") } volumePath := req.VolumePath if volumePath == "" { + logger.Error(ctx, ns.logger, "Volume path doesn't exist") return nil, status.Error(codes.InvalidArgument, "Path Doesn't exist") } - klog.V(2).Info("NodeGetVolumeStats: Start getting Stats") + logger.Debug(ctx, ns.logger, "Getting filesystem stats", zap.String("volume_path", volumePath)) // Making direct call to fs library for the sake of simplicity. That way we don't need to initialize VolumeStatsUtils. If there is a need for VolumeStatsUtils to grow bigger then we can use it _, capacity, _, inodes, inodesFree, inodesUsed, err := ns.Stats.FSInfo(volumePath) if err != nil { - data := map[string]string{"VolumeId": volumeID, "Error": err.Error()} - klog.Error("NodeGetVolumeStats: error occurred while getting volume stats ", data) + logger.Error(ctx, ns.logger, "Error getting volume stats", + zap.String("volume_id", volumeID), zap.Error(err)) return &csi.NodeGetVolumeStatsResponse{ VolumeCondition: &csi.VolumeCondition{ Abnormal: true, - Message: err.Error(), + Message: fmt.Sprintf("%v", err.Error()), }, }, nil } totalCap, err := ns.Stats.GetTotalCapacityFromPV(volumeID) if err != nil { + logger.Error(ctx, ns.logger, "Error getting total capacity from PV", zap.Error(err)) return nil, err } capAsInt64, converted := totalCap.AsInt64() if !converted { capAsInt64 = capacity + logger.Warn(ctx, ns.logger, "Could not convert capacity, using filesystem capacity", zap.Int64("capacity", capacity)) } - klog.Info("NodeGetVolumeStats: Total Capacity of Volume: ", capAsInt64) + logger.Info(ctx, ns.logger, "Total capacity of volume", zap.Int64("capacity", capAsInt64)) capUsed, err := ns.Stats.GetBucketUsage(volumeID) if err != nil { + logger.Error(ctx, ns.logger, "Error getting bucket usage", zap.Error(err)) return nil, err } @@ -274,16 +337,24 @@ func (ns *nodeServer) NodeGetVolumeStats(_ context.Context, req *csi.NodeGetVolu }, } - klog.V(2).Info("NodeGetVolumeStats: Volume Stats ", resp) + logger.Info(ctx, ns.logger, "NodeGetVolumeStats completed", + zap.Int64("total_bytes", capAsInt64), + zap.Int64("used_bytes", capUsed), + zap.Int64("total_inodes", inodes), + zap.Int64("used_inodes", inodesUsed)) return resp, nil } -func (ns *nodeServer) NodeExpandVolume(_ context.Context, _ *csi.NodeExpandVolumeRequest) (*csi.NodeExpandVolumeResponse, error) { +func (ns *nodeServer) NodeExpandVolume(ctx context.Context, _ *csi.NodeExpandVolumeRequest) (*csi.NodeExpandVolumeResponse, error) { + + logger.Info(ctx, ns.logger, "NodeExpandVolume not implemented") return &csi.NodeExpandVolumeResponse{}, status.Error(codes.Unimplemented, "NodeExpandVolume is not implemented") } -func (ns *nodeServer) NodeGetCapabilities(_ context.Context, req *csi.NodeGetCapabilitiesRequest) (*csi.NodeGetCapabilitiesResponse, error) { - klog.V(2).Infof("NodeGetCapabilities: Request: %+v", req) +func (ns *nodeServer) NodeGetCapabilities(ctx context.Context, req *csi.NodeGetCapabilitiesRequest) (*csi.NodeGetCapabilitiesResponse, error) { + logger.Info(ctx, ns.logger, "NodeGetCapabilities started") + logger.Debug(ctx, ns.logger, "NodeGetCapabilities request", zap.Any("request", req)) + var caps []*csi.NodeServiceCapability for _, cap := range nodeServerCapabilities { c := &csi.NodeServiceCapability{ @@ -295,11 +366,14 @@ func (ns *nodeServer) NodeGetCapabilities(_ context.Context, req *csi.NodeGetCap } caps = append(caps, c) } + + logger.Info(ctx, ns.logger, "NodeGetCapabilities completed", zap.Int("capability_count", len(caps))) return &csi.NodeGetCapabilitiesResponse{Capabilities: caps}, nil } -func (ns *nodeServer) NodeGetInfo(_ context.Context, req *csi.NodeGetInfoRequest) (*csi.NodeGetInfoResponse, error) { - klog.V(3).Infof("NodeGetInfo: called with args %+v", req) +func (ns *nodeServer) NodeGetInfo(ctx context.Context, req *csi.NodeGetInfoRequest) (*csi.NodeGetInfoResponse, error) { + logger.Info(ctx, ns.logger, "NodeGetInfo started") + logger.Debug(ctx, ns.logger, "NodeGetInfo request", zap.Any("request", req)) topology := &csi.Topology{ Segments: map[string]string{ @@ -312,6 +386,11 @@ func (ns *nodeServer) NodeGetInfo(_ context.Context, req *csi.NodeGetInfoRequest MaxVolumesPerNode: ns.MaxVolumesPerNode, AccessibleTopology: topology, } - klog.V(2).Info("NodeGetInfo: ", resp) + + logger.Info(ctx, ns.logger, "NodeGetInfo completed", + zap.String("node_id", ns.NodeID), + zap.Int64("max_volumes_per_node", ns.MaxVolumesPerNode), + zap.String("region", ns.Region), + zap.String("zone", ns.Zone)) return resp, nil } diff --git a/pkg/driver/nodeserver_test.go b/pkg/driver/nodeserver_test.go index 74f07d92..f226ab38 100644 --- a/pkg/driver/nodeserver_test.go +++ b/pkg/driver/nodeserver_test.go @@ -67,7 +67,9 @@ func TestNodeStageVolume(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) - nodeServer := nodeServer{} + nodeServer := nodeServer{ + S3Driver: &S3Driver{logger: zap.NewNop()}, + } actualResp, actualErr := nodeServer.NodeStageVolume(ctx, tc.req) if tc.expectedErr != nil { @@ -118,7 +120,9 @@ func TestNodeUnstageVolume(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) - nodeServer := nodeServer{} + nodeServer := nodeServer{ + S3Driver: &S3Driver{logger: zap.NewNop()}, + } actualResp, actualErr := nodeServer.NodeUnstageVolume(ctx, tc.req) if tc.expectedErr != nil { @@ -349,6 +353,7 @@ func TestNodePublishVolume(t *testing.T) { nodeServer := nodeServer{ S3Driver: &S3Driver{ iamEndpoint: constants.PublicIAMEndpoint, + logger: zap.NewNop(), }, Stats: tc.driverStatsUtils, Mounter: tc.Mounter, @@ -451,8 +456,9 @@ func TestNodeUnpublishVolume(t *testing.T) { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) nodeServer := nodeServer{ - Stats: tc.driverStatsUtils, - Mounter: tc.Mounter, + S3Driver: &S3Driver{logger: zap.NewNop()}, + Stats: tc.driverStatsUtils, + Mounter: tc.Mounter, } actualResp, actualErr := nodeServer.NodeUnpublishVolume(ctx, tc.req) @@ -587,7 +593,8 @@ func TestNodeGetVolumeStats(t *testing.T) { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) nodeServer := nodeServer{ - Stats: tc.driverStatsUtils, + S3Driver: &S3Driver{logger: zap.NewNop()}, + Stats: tc.driverStatsUtils, } actualResp, actualErr := nodeServer.NodeGetVolumeStats(ctx, tc.req) @@ -606,7 +613,9 @@ func TestNodeGetVolumeStats(t *testing.T) { func TestNodeExpandVolume(t *testing.T) { t.Run("UnImplemented Method", func(t *testing.T) { - nodeServer := nodeServer{} + nodeServer := nodeServer{ + S3Driver: &S3Driver{logger: zap.NewNop()}, + } actualResp, actualErr := nodeServer.NodeExpandVolume(ctx, &csi.NodeExpandVolumeRequest{}) assert.Equal(t, &csi.NodeExpandVolumeResponse{}, actualResp) assert.Error(t, actualErr) @@ -656,7 +665,9 @@ func TestNodeGetCapabilities(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) - nodeServer := nodeServer{} + nodeServer := nodeServer{ + S3Driver: &S3Driver{logger: zap.NewNop()}, + } actualResp, actualErr := nodeServer.NodeGetCapabilities(ctx, tc.req) if tc.expectedErr != nil { @@ -678,6 +689,7 @@ func TestNodeGetInfo(t *testing.T) { testZone := "test-zone" nodeServer := nodeServer{ + S3Driver: &S3Driver{logger: zap.NewNop()}, NodeServerConfig: NodeServerConfig{ MaxVolumesPerNode: testMaxVolumesPerNode, Region: testRegion, diff --git a/pkg/driver/requestid_integration_test.go b/pkg/driver/requestid_integration_test.go new file mode 100644 index 00000000..c2565374 --- /dev/null +++ b/pkg/driver/requestid_integration_test.go @@ -0,0 +1,277 @@ +/** + * Copyright 2024 IBM Corp. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package driver + +import ( + "context" + "testing" + + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" + "github.com/container-storage-interface/spec/lib/go/csi" + "github.com/stretchr/testify/assert" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" + "google.golang.org/grpc" +) + +// TestRequestIDEndToEndFlow tests the complete request ID flow from +// interceptor through CSI handlers to verify proper propagation +func TestRequestIDEndToEndFlow(t *testing.T) { + // Create an observed logger to capture all log entries + core, recorded := observer.New(zapcore.InfoLevel) + logger := zap.New(core) + + // Create identity server + s3Driver := &S3Driver{ + name: "test-driver", + version: "1.0.0", + logger: logger, + } + identityServer := &identityServer{ + S3Driver: s3Driver, + } + + // Create the interceptor + interceptor := UnaryServerInterceptor(logger) + + // Test GetPluginInfo through the interceptor + t.Run("GetPluginInfo with request ID propagation", func(t *testing.T) { + recorded.TakeAll() // Clear previous logs + + req := &csi.GetPluginInfoRequest{} + ctx := context.Background() + + // Handler that will be called by interceptor + handler := func(ctx context.Context, req interface{}) (interface{}, error) { + // Verify request ID exists in context + reqID := requestid.FromContext(ctx) + assert.NotEmpty(t, reqID, "Request ID should be present in context") + + // Call the actual CSI method + return identityServer.GetPluginInfo(ctx, req.(*csi.GetPluginInfoRequest)) + } + + // Call through interceptor + resp, err := interceptor(ctx, req, &grpc.UnaryServerInfo{ + FullMethod: "/csi.v1.Identity/GetPluginInfo", + }, handler) + + // Verify response + assert.NoError(t, err) + assert.NotNil(t, resp) + + pluginResp, ok := resp.(*csi.GetPluginInfoResponse) + assert.True(t, ok) + assert.Equal(t, "test-driver", pluginResp.Name) + + // Verify logs contain request ID + logs := recorded.All() + assert.NotEmpty(t, logs, "Should have log entries") + + // Extract request ID from logs + var requestIDs []string + for _, log := range logs { + for _, field := range log.Context { + if field.Key == "request_id" { + requestIDs = append(requestIDs, field.String) + } + } + } + + // Verify all logs have the same request ID + assert.NotEmpty(t, requestIDs, "Should have request IDs in logs") + firstReqID := requestIDs[0] + assert.NotEmpty(t, firstReqID, "Request ID should not be empty") + + for _, reqID := range requestIDs { + assert.Equal(t, firstReqID, reqID, "All logs should have the same request ID") + } + + // Verify we have both start and completion logs + var hasStartLog, hasCompletionLog bool + for _, log := range logs { + if log.Message == "gRPC request started" { + hasStartLog = true + } + if log.Message == "gRPC request completed" { + hasCompletionLog = true + } + } + assert.True(t, hasStartLog, "Should have request started log") + assert.True(t, hasCompletionLog, "Should have request completed log") + }) + + t.Run("Probe with existing request ID", func(t *testing.T) { + recorded.TakeAll() // Clear previous logs + + req := &csi.ProbeRequest{} + existingReqID := "existing-probe-request-id" + ctx := requestid.WithRequestID(context.Background(), existingReqID) + + // Handler that will be called by interceptor + handler := func(ctx context.Context, req interface{}) (interface{}, error) { + // Verify the existing request ID is preserved + reqID := requestid.FromContext(ctx) + assert.Equal(t, existingReqID, reqID, "Should preserve existing request ID") + + // Call the actual CSI method + return identityServer.Probe(ctx, req.(*csi.ProbeRequest)) + } + + // Call through interceptor + resp, err := interceptor(ctx, req, &grpc.UnaryServerInfo{ + FullMethod: "/csi.v1.Identity/Probe", + }, handler) + + // Verify response + assert.NoError(t, err) + assert.NotNil(t, resp) + + // Verify logs contain the existing request ID + logs := recorded.All() + for _, log := range logs { + for _, field := range log.Context { + if field.Key == "request_id" { + assert.Equal(t, existingReqID, field.String, "Logs should contain existing request ID") + } + } + } + }) +} + +// TestRequestIDPropagationToLogger tests that request ID properly +// propagates to logger instances +func TestRequestIDPropagationToLogger(t *testing.T) { + // Create an observed logger at DEBUG level to capture all logs + core, recorded := observer.New(zapcore.DebugLevel) + logger := zap.New(core) + + testReqID := "test-logger-request-id" + ctx := requestid.WithRequestID(context.Background(), testReqID) + + // Create identity server + s3Driver := &S3Driver{ + name: "test-driver", + version: "1.0.0", + logger: logger, + } + identityServer := &identityServer{ + S3Driver: s3Driver, + } + + // Call GetPluginInfo which should log with request ID + req := &csi.GetPluginInfoRequest{} + resp, err := identityServer.GetPluginInfo(ctx, req) + + assert.NoError(t, err) + assert.NotNil(t, resp) + + // Verify logs contain the request ID + logs := recorded.All() + assert.NotEmpty(t, logs, "Should have log entries") + + foundRequestID := false + for _, log := range logs { + for _, field := range log.Context { + if field.Key == "request_id" && field.String == testReqID { + foundRequestID = true + break + } + } + } + assert.True(t, foundRequestID, "Logs should contain the request ID") +} + +// TestRequestIDInMultipleHandlers tests request ID propagation +// across different CSI handler types +func TestRequestIDInMultipleHandlers(t *testing.T) { + // Create an observed logger + core, recorded := observer.New(zapcore.InfoLevel) + logger := zap.New(core) + + testReqID := "multi-handler-request-id" + ctx := requestid.WithRequestID(context.Background(), testReqID) + + // Create servers + s3Driver := &S3Driver{ + name: "test-driver", + version: "1.0.0", + logger: logger, + } + + identityServer := &identityServer{S3Driver: s3Driver} + nodeServer := &nodeServer{S3Driver: s3Driver} + + testCases := []struct { + name string + handler func() error + }{ + { + name: "IdentityServer.GetPluginInfo", + handler: func() error { + _, err := identityServer.GetPluginInfo(ctx, &csi.GetPluginInfoRequest{}) + return err + }, + }, + { + name: "IdentityServer.GetPluginCapabilities", + handler: func() error { + _, err := identityServer.GetPluginCapabilities(ctx, &csi.GetPluginCapabilitiesRequest{}) + return err + }, + }, + { + name: "IdentityServer.Probe", + handler: func() error { + _, err := identityServer.Probe(ctx, &csi.ProbeRequest{}) + return err + }, + }, + { + name: "NodeServer.NodeGetCapabilities", + handler: func() error { + _, err := nodeServer.NodeGetCapabilities(ctx, &csi.NodeGetCapabilitiesRequest{}) + return err + }, + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + recorded.TakeAll() // Clear previous logs + + err := tc.handler() + assert.NoError(t, err) + + // Verify logs contain the request ID + logs := recorded.All() + if len(logs) > 0 { + foundRequestID := false + for _, log := range logs { + for _, field := range log.Context { + if field.Key == "request_id" && field.String == testReqID { + foundRequestID = true + break + } + } + } + assert.True(t, foundRequestID, "Logs should contain the request ID for "+tc.name) + } + }) + } +} diff --git a/pkg/driver/s3-driver.go b/pkg/driver/s3-driver.go index 69ff3d0b..2f52b823 100644 --- a/pkg/driver/s3-driver.go +++ b/pkg/driver/s3-driver.go @@ -24,7 +24,6 @@ import ( pkgUtils "github.com/IBM/ibm-object-csi-driver/pkg/utils" csi "github.com/container-storage-interface/spec/lib/go/csi" "go.uber.org/zap" - "k8s.io/klog/v2" ) var ( @@ -183,7 +182,7 @@ func (driver *S3Driver) NewS3CosDriver(nodeID string, endpoint string, s3cosSess if err != nil { return nil, err } - klog.Infof("iam endpoint: %v", iamEP) + driver.logger.Info("IAM endpoint", zap.String("iam_endpoint", iamEP)) driver.iamEndpoint = iamEP driver.endpoint = endpoint diff --git a/pkg/driver/s3-driver_test.go b/pkg/driver/s3-driver_test.go index 46ad9cea..61b651b9 100644 --- a/pkg/driver/s3-driver_test.go +++ b/pkg/driver/s3-driver_test.go @@ -36,8 +36,13 @@ const defaultMode = "controller" // GetTestLogger ... func GetTestLogger(t *testing.T) (logger *zap.Logger, teardown func()) { - config := zap.NewDevelopmentConfig() - config.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder + config := zap.NewProductionConfig() + config.EncoderConfig.TimeKey = "timestamp" + config.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + config.EncoderConfig.EncodeLevel = zapcore.LowercaseLevelEncoder + config.EncoderConfig.MessageKey = "msg" + config.EncoderConfig.CallerKey = "caller" + config.EncoderConfig.LevelKey = "level" buf := &bytes.Buffer{} logger, _ = config.Build() diff --git a/pkg/driver/server.go b/pkg/driver/server.go index 30c3cc94..bc953017 100644 --- a/pkg/driver/server.go +++ b/pkg/driver/server.go @@ -19,10 +19,10 @@ import ( "sync" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" "github.com/container-storage-interface/spec/lib/go/csi" "go.uber.org/zap" "google.golang.org/grpc" - "k8s.io/klog/v2" ) // NonBlockingGRPCServer Defines Non blocking GRPC server interfaces @@ -77,7 +77,10 @@ func (s *nonBlockingGRPCServer) Setup(endpoint string, ids csi.IdentityServer, c s.logger.Info("nonBlockingGRPCServer-Setup", zap.Reflect("Endpoint", endpoint)) opts := []grpc.ServerOption{ - grpc.UnaryInterceptor(logGRPC), + grpc.ChainUnaryInterceptor( + UnaryServerInterceptor(s.logger), // Request ID interceptor + s.logGRPC, // Logging interceptor + ), } u, err := url.Parse(endpoint) @@ -130,13 +133,13 @@ func (s *nonBlockingGRPCServer) Setup(endpoint string, ids csi.IdentityServer, c switch s.mode { case "controller": - klog.V(3).Info("--Starting server in controller mode--") + s.logger.Debug("Starting server in controller mode") csi.RegisterControllerServer(s.server, cs) case "node": - klog.V(3).Info("--Starting server in node server mode--") + s.logger.Debug("Starting server in node server mode") csi.RegisterNodeServer(s.server, ns) case "controller-node": - klog.V(3).Info("--Starting node and controller server mode--") + s.logger.Debug("Starting node and controller server mode") csi.RegisterControllerServer(s.server, cs) csi.RegisterNodeServer(s.server, ns) } @@ -158,14 +161,17 @@ func (s *nonBlockingGRPCServer) serve(endpoint string, ids csi.IdentityServer, c } } -// logGRPC ... -func logGRPC(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { - klog.V(3).Infof("GRPC call: %s", info.FullMethod) +// logGRPC logs GRPC calls with request ID context +func (s *nonBlockingGRPCServer) logGRPC(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { + reqID := requestid.FromContext(ctx) + log := s.logger.With(zap.String("request_id", reqID)) + + log.Debug("GRPC call", zap.String("method", info.FullMethod)) resp, err := handler(ctx, req) if err != nil { - klog.Errorf("GRPC error: %v", err) + log.Error("GRPC error", zap.Error(err), zap.String("method", info.FullMethod)) } else { - klog.V(5).Infof("GRPC response: %+v", resp) + log.Debug("GRPC response", zap.Any("response", resp), zap.String("method", info.FullMethod)) } return resp, err } diff --git a/pkg/driver/server_test.go b/pkg/driver/server_test.go index 24efc687..13e5377b 100644 --- a/pkg/driver/server_test.go +++ b/pkg/driver/server_test.go @@ -37,7 +37,10 @@ func TestNonBlockingGRPCServer(t *testing.T) { nonBlockingServer, ok := s.(*nonBlockingGRPCServer) assert.Equal(t, true, ok) - listener, err := nonBlockingServer.Setup(*testEndpoint, &identityServer{}, &controllerServer{}, &nodeServer{}) + listener, err := nonBlockingServer.Setup(*testEndpoint, + &identityServer{S3Driver: &S3Driver{logger: zap.NewNop()}}, + &controllerServer{Logger: zap.NewNop()}, + &nodeServer{S3Driver: &S3Driver{logger: zap.NewNop()}}) assert.NoError(t, err) assert.NotNil(t, listener) @@ -96,7 +99,10 @@ func TestSetup(t *testing.T) { mode: tc.mode, logger: lgr, } - _, actualErr := server.Setup(*tc.endpoint, &identityServer{}, &controllerServer{}, &nodeServer{}) + _, actualErr := server.Setup(*tc.endpoint, + &identityServer{S3Driver: &S3Driver{logger: zap.NewNop()}}, + &controllerServer{Logger: zap.NewNop()}, + &nodeServer{S3Driver: &S3Driver{logger: zap.NewNop()}}) if tc.expectedErr != nil { assert.Error(t, actualErr) @@ -135,7 +141,16 @@ func TestLogGRPC(t *testing.T) { for _, tc := range testCases { t.Log("Testcase being executed", zap.String("testcase", tc.testCaseName)) - actualResp, actualErr := logGRPC(ctx, nil, &grpc.UnaryServerInfo{}, tc.handler) + lgr, teardown := GetTestLogger(t) + defer teardown() + + server := &nonBlockingGRPCServer{ + mode: "controller", + logger: lgr, + } + + ctx := context.Background() + actualResp, actualErr := server.logGRPC(ctx, nil, &grpc.UnaryServerInfo{}, tc.handler) if tc.expectedErr != nil { assert.Error(t, actualErr) diff --git a/pkg/logger/factory.go b/pkg/logger/factory.go new file mode 100644 index 00000000..5add28b4 --- /dev/null +++ b/pkg/logger/factory.go @@ -0,0 +1,95 @@ +/******************************************************************************* + * IBM Confidential + * OCO Source Materials + * IBM Cloud Kubernetes Service, 5737-D43 + * (C) Copyright IBM Corp. 2023 All Rights Reserved. + * The source code for this program is not published or otherwise divested of + * its trade secrets, irrespective of what has been deposited with + * the U.S. Copyright Office. + ******************************************************************************/ + +// Package logger provides logging utilities for the CSI driver +package logger + +import ( + "crypto/rand" + "encoding/hex" + "os" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// NewJSONLogger creates a new zap logger with JSON encoding for production +// This provides machine-readable structured logs with consistent formatting +func NewJSONLogger(serviceName string) (*zap.Logger, error) { + atom := zap.NewAtomicLevel() + encoderCfg := zap.NewProductionEncoderConfig() + encoderCfg.TimeKey = "timestamp" + encoderCfg.EncodeTime = zapcore.ISO8601TimeEncoder + encoderCfg.EncodeLevel = zapcore.LowercaseLevelEncoder + encoderCfg.MessageKey = "msg" + encoderCfg.CallerKey = "caller" + encoderCfg.LevelKey = "level" + + logger := zap.New(zapcore.NewCore( + zapcore.NewJSONEncoder(encoderCfg), + zapcore.Lock(os.Stdout), + atom, + ), zap.AddCaller()) + + atom.SetLevel(zap.InfoLevel) + return logger, nil +} + +// NewJSONLoggerOrNop creates a JSON logger or returns a no-op logger on error +// This is useful for init() functions where error handling is limited +func NewJSONLoggerOrNop(serviceName string) *zap.Logger { + logger, err := NewJSONLogger(serviceName) + if err != nil { + return zap.NewNop() + } + return logger +} + +// NewConsoleLogger creates a new zap logger with console encoding +// This provides human-readable logs with structured fields (for development/debugging) +// Deprecated: Use NewJSONLogger for production deployments +func NewConsoleLogger(serviceName string) (*zap.Logger, error) { + atom := zap.NewAtomicLevel() + encoderCfg := zap.NewProductionEncoderConfig() + encoderCfg.TimeKey = "timestamp" + encoderCfg.EncodeTime = zapcore.ISO8601TimeEncoder + encoderCfg.EncodeLevel = zapcore.LowercaseLevelEncoder + encoderCfg.MessageKey = "msg" + encoderCfg.CallerKey = "caller" + encoderCfg.LevelKey = "level" + + logger := zap.New(zapcore.NewCore( + zapcore.NewConsoleEncoder(encoderCfg), + zapcore.Lock(os.Stdout), + atom, + ), zap.AddCaller()) + + atom.SetLevel(zap.InfoLevel) + return logger, nil +} + +// NewConsoleLoggerOrNop creates a console logger or returns a no-op logger on error +// Deprecated: Use NewJSONLoggerOrNop for production deployments +func NewConsoleLoggerOrNop(serviceName string) *zap.Logger { + logger, err := NewConsoleLogger(serviceName) + if err != nil { + return zap.NewNop() + } + return logger +} + +// GenerateRequestID generates a unique request ID for tracing +func GenerateRequestID() string { + b := make([]byte, 16) + if _, err := rand.Read(b); err != nil { + return "unknown" + } + return hex.EncodeToString(b) +} diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go new file mode 100644 index 00000000..477d17b4 --- /dev/null +++ b/pkg/logger/logger.go @@ -0,0 +1,63 @@ +/******************************************************************************* + * IBM Confidential + * OCO Source Materials + * IBM Cloud Kubernetes Service, 5737-D43 + * (C) Copyright IBM Corp. 2023 All Rights Reserved. + * The source code for this program is not published or otherwise divested of + * its trade secrets, irrespective of what has been deposited with + * the U.S. Copyright Office. + ******************************************************************************/ + +// Package logger provides utilities for structured logging with request ID tracking +package logger + +import ( + "context" + + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" + "go.uber.org/zap" +) + +// WithRequestID returns a logger with request ID field added +// If no request ID exists in context, returns the original logger +func WithRequestID(ctx context.Context, logger *zap.Logger) *zap.Logger { + if logger == nil { + return nil + } + if reqID := requestid.FromContext(ctx); reqID != "" { + return logger.With(zap.String("request_id", reqID)) + } + return logger +} + +// Info logs an info message with request ID from context +func Info(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + WithRequestID(ctx, logger).Info(msg, fields...) +} + +// Error logs an error message with request ID from context +func Error(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + WithRequestID(ctx, logger).Error(msg, fields...) +} + +// Warn logs a warning message with request ID from context +func Warn(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + WithRequestID(ctx, logger).Warn(msg, fields...) +} + +// Debug logs a debug message with request ID from context +func Debug(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + WithRequestID(ctx, logger).Debug(msg, fields...) +} + +// Fatal logs a fatal message with request ID from context and exits +func Fatal(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + WithRequestID(ctx, logger).Fatal(msg, fields...) +} + +// Panic logs a panic message with request ID from context and panics +func Panic(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + WithRequestID(ctx, logger).Panic(msg, fields...) +} + + diff --git a/pkg/logger/logger_test.go b/pkg/logger/logger_test.go new file mode 100644 index 00000000..feec296b --- /dev/null +++ b/pkg/logger/logger_test.go @@ -0,0 +1,382 @@ +/******************************************************************************* + * IBM Confidential + * OCO Source Materials + * IBM Cloud Kubernetes Service, 5737-D43 + * (C) Copyright IBM Corp. 2023 All Rights Reserved. + * The source code for this program is not published or otherwise divested of + * its trade secrets, irrespective of what has been deposited with + * the U.S. Copyright Office. + ******************************************************************************/ + +package logger + +import ( + "context" + "testing" + + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" + "github.com/stretchr/testify/assert" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +func TestWithRequestID(t *testing.T) { + tests := []struct { + name string + ctx context.Context + logger *zap.Logger + expectedReqID string + expectReqIDSet bool + }{ + { + name: "Context with request ID", + ctx: requestid.WithRequestID(context.Background(), "test-req-123"), + logger: zap.NewNop(), + expectedReqID: "test-req-123", + expectReqIDSet: true, + }, + { + name: "Context without request ID", + ctx: context.Background(), + logger: zap.NewNop(), + expectedReqID: "", + expectReqIDSet: false, + }, + { + name: "Nil logger", + ctx: requestid.WithRequestID(context.Background(), "test-req-456"), + logger: nil, + expectedReqID: "", + expectReqIDSet: false, + }, + { + name: "Empty request ID", + ctx: requestid.WithRequestID(context.Background(), ""), + logger: zap.NewNop(), + expectedReqID: "", + expectReqIDSet: false, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + result := WithRequestID(tt.ctx, tt.logger) + + if tt.logger == nil { + assert.Nil(t, result, "Expected nil logger when input is nil") + return + } + + assert.NotNil(t, result, "Expected non-nil logger") + + // Verify request ID is added by logging and checking fields + if tt.expectReqIDSet { + core, recorded := observer.New(zapcore.InfoLevel) + testLogger := zap.New(core) + resultLogger := WithRequestID(tt.ctx, testLogger) + resultLogger.Info("test message") + + entries := recorded.All() + assert.Len(t, entries, 1, "Expected one log entry") + if len(entries) > 0 { + fields := entries[0].Context + found := false + for _, field := range fields { + if field.Key == "request_id" && field.String == tt.expectedReqID { + found = true + break + } + } + assert.True(t, found, "Expected request_id field with value %s", tt.expectedReqID) + } + } + }) + } +} + +func TestInfo(t *testing.T) { + core, recorded := observer.New(zapcore.InfoLevel) + logger := zap.New(core) + + tests := []struct { + name string + ctx context.Context + msg string + fields []zap.Field + expectedReqID string + }{ + { + name: "Info with request ID", + ctx: requestid.WithRequestID(context.Background(), "info-req-123"), + msg: "test info message", + fields: []zap.Field{zap.String("key", "value")}, + expectedReqID: "info-req-123", + }, + { + name: "Info without request ID", + ctx: context.Background(), + msg: "test info without req id", + fields: []zap.Field{}, + expectedReqID: "", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + recorded.TakeAll() // Clear previous entries + + Info(tt.ctx, logger, tt.msg, tt.fields...) + + entries := recorded.All() + assert.Len(t, entries, 1, "Expected one log entry") + assert.Equal(t, tt.msg, entries[0].Message) + assert.Equal(t, zapcore.InfoLevel, entries[0].Level) + + if tt.expectedReqID != "" { + found := false + for _, field := range entries[0].Context { + if field.Key == "request_id" && field.String == tt.expectedReqID { + found = true + break + } + } + assert.True(t, found, "Expected request_id field") + } + }) + } +} + +func TestError(t *testing.T) { + core, recorded := observer.New(zapcore.ErrorLevel) + logger := zap.New(core) + + tests := []struct { + name string + ctx context.Context + msg string + fields []zap.Field + expectedReqID string + }{ + { + name: "Error with request ID", + ctx: requestid.WithRequestID(context.Background(), "error-req-456"), + msg: "test error message", + fields: []zap.Field{zap.Error(assert.AnError)}, + expectedReqID: "error-req-456", + }, + { + name: "Error without request ID", + ctx: context.Background(), + msg: "test error without req id", + fields: []zap.Field{}, + expectedReqID: "", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + recorded.TakeAll() // Clear previous entries + + Error(tt.ctx, logger, tt.msg, tt.fields...) + + entries := recorded.All() + assert.Len(t, entries, 1, "Expected one log entry") + assert.Equal(t, tt.msg, entries[0].Message) + assert.Equal(t, zapcore.ErrorLevel, entries[0].Level) + + if tt.expectedReqID != "" { + found := false + for _, field := range entries[0].Context { + if field.Key == "request_id" && field.String == tt.expectedReqID { + found = true + break + } + } + assert.True(t, found, "Expected request_id field") + } + }) + } +} + +func TestWarn(t *testing.T) { + core, recorded := observer.New(zapcore.WarnLevel) + logger := zap.New(core) + + tests := []struct { + name string + ctx context.Context + msg string + fields []zap.Field + expectedReqID string + }{ + { + name: "Warn with request ID", + ctx: requestid.WithRequestID(context.Background(), "warn-req-789"), + msg: "test warning message", + fields: []zap.Field{zap.String("warning", "details")}, + expectedReqID: "warn-req-789", + }, + { + name: "Warn without request ID", + ctx: context.Background(), + msg: "test warning without req id", + fields: []zap.Field{}, + expectedReqID: "", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + recorded.TakeAll() // Clear previous entries + + Warn(tt.ctx, logger, tt.msg, tt.fields...) + + entries := recorded.All() + assert.Len(t, entries, 1, "Expected one log entry") + assert.Equal(t, tt.msg, entries[0].Message) + assert.Equal(t, zapcore.WarnLevel, entries[0].Level) + + if tt.expectedReqID != "" { + found := false + for _, field := range entries[0].Context { + if field.Key == "request_id" && field.String == tt.expectedReqID { + found = true + break + } + } + assert.True(t, found, "Expected request_id field") + } + }) + } +} + +func TestDebug(t *testing.T) { + core, recorded := observer.New(zapcore.DebugLevel) + logger := zap.New(core) + + tests := []struct { + name string + ctx context.Context + msg string + fields []zap.Field + expectedReqID string + }{ + { + name: "Debug with request ID", + ctx: requestid.WithRequestID(context.Background(), "debug-req-abc"), + msg: "test debug message", + fields: []zap.Field{zap.String("debug", "info")}, + expectedReqID: "debug-req-abc", + }, + { + name: "Debug without request ID", + ctx: context.Background(), + msg: "test debug without req id", + fields: []zap.Field{}, + expectedReqID: "", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + recorded.TakeAll() // Clear previous entries + + Debug(tt.ctx, logger, tt.msg, tt.fields...) + + entries := recorded.All() + assert.Len(t, entries, 1, "Expected one log entry") + assert.Equal(t, tt.msg, entries[0].Message) + assert.Equal(t, zapcore.DebugLevel, entries[0].Level) + + if tt.expectedReqID != "" { + found := false + for _, field := range entries[0].Context { + if field.Key == "request_id" && field.String == tt.expectedReqID { + found = true + break + } + } + assert.True(t, found, "Expected request_id field") + } + }) + } +} + +func TestFatal(t *testing.T) { + // Fatal calls os.Exit, so we can't test it directly + // Instead, we verify that WithRequestID works correctly and would pass the right logger + core, _ := observer.New(zapcore.FatalLevel) + logger := zap.New(core) + + ctx := requestid.WithRequestID(context.Background(), "fatal-req-xyz") + + // Test that WithRequestID returns a logger with request ID + loggerWithReqID := WithRequestID(ctx, logger) + assert.NotNil(t, loggerWithReqID) + + // We can't actually call Fatal as it would exit the test + // The function is covered by the WithRequestID test and integration tests +} + +func TestPanic(t *testing.T) { + core, recorded := observer.New(zapcore.PanicLevel) + logger := zap.New(core) + + ctx := requestid.WithRequestID(context.Background(), "panic-req-def") + msg := "test panic message" + + // Panic will actually panic, so we need to recover + defer func() { + if r := recover(); r != nil { + // Expected panic + entries := recorded.All() + assert.Len(t, entries, 1, "Expected one log entry") + assert.Equal(t, msg, entries[0].Message) + assert.Equal(t, zapcore.PanicLevel, entries[0].Level) + + found := false + for _, field := range entries[0].Context { + if field.Key == "request_id" && field.String == "panic-req-def" { + found = true + break + } + } + assert.True(t, found, "Expected request_id field") + } + }() + + Panic(ctx, logger, msg) + t.Fatal("Expected panic but didn't occur") +} + +func TestAllLogLevelsWithRequestID(t *testing.T) { + // Test that all log levels properly include request ID + core, recorded := observer.New(zapcore.DebugLevel) + logger := zap.New(core) + ctx := requestid.WithRequestID(context.Background(), "multi-level-req") + + // Test Info + Info(ctx, logger, "info message") + // Test Error + Error(ctx, logger, "error message") + // Test Warn + Warn(ctx, logger, "warn message") + // Test Debug + Debug(ctx, logger, "debug message") + + entries := recorded.All() + assert.Len(t, entries, 4, "Expected four log entries") + + // Verify all entries have request ID + for _, entry := range entries { + found := false + for _, field := range entry.Context { + if field.Key == "request_id" && field.String == "multi-level-req" { + found = true + break + } + } + assert.True(t, found, "Expected request_id in %s level log", entry.Level) + } +} diff --git a/pkg/mounter/fake_mounter-rclone.go b/pkg/mounter/fake_mounter-rclone.go index dec9652a..245ea295 100644 --- a/pkg/mounter/fake_mounter-rclone.go +++ b/pkg/mounter/fake_mounter-rclone.go @@ -1,6 +1,12 @@ +//go:build linux +// +build linux + package mounter -import "errors" +import ( + "context" + "errors" +) type fakercloneMounter struct { bucketName string @@ -33,14 +39,14 @@ func fakenewRcloneMounter(isFailedMount, isFailedUnmount bool) Mounter { } } -func (rclone *fakercloneMounter) Mount(source string, target string) error { +func (rclone *fakercloneMounter) Mount(ctx context.Context, source string, target string) error { if rclone.isFailedMount { return errors.New("failed to mount rclone") } return nil } -func (rclone *fakercloneMounter) Unmount(target string) error { +func (rclone *fakercloneMounter) Unmount(ctx context.Context, target string) error { if rclone.isFailedUnmount { return errors.New("failed to unmount rclone") } diff --git a/pkg/mounter/fake_mounter-s3fs.go b/pkg/mounter/fake_mounter-s3fs.go index 88532534..a7fa3b4c 100644 --- a/pkg/mounter/fake_mounter-s3fs.go +++ b/pkg/mounter/fake_mounter-s3fs.go @@ -1,6 +1,12 @@ +//go:build linux +// +build linux + package mounter -import "errors" +import ( + "context" + "errors" +) type fakes3fsMounter struct { bucketName string @@ -29,14 +35,14 @@ func fakenewS3fsMounter(isFailedMount, isFailedUnmount bool) Mounter { } } -func (s3fs *fakes3fsMounter) Mount(source string, target string) error { +func (s3fs *fakes3fsMounter) Mount(ctx context.Context, source string, target string) error { if s3fs.isFailedMount { return errors.New("failed to mount s3fs") } return nil } -func (s3fs *fakes3fsMounter) Unmount(target string) error { +func (s3fs *fakes3fsMounter) Unmount(ctx context.Context, target string) error { if s3fs.isFailedUnmount { return errors.New("failed to unmount s3fs") } diff --git a/pkg/mounter/fake_mounter.go b/pkg/mounter/fake_mounter.go index a215b3ea..a76be730 100644 --- a/pkg/mounter/fake_mounter.go +++ b/pkg/mounter/fake_mounter.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package mounter import "github.com/IBM/ibm-object-csi-driver/pkg/constants" diff --git a/pkg/mounter/mounter-rclone.go b/pkg/mounter/mounter-rclone.go index e4b30b7b..ec5dd1d1 100644 --- a/pkg/mounter/mounter-rclone.go +++ b/pkg/mounter/mounter-rclone.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + /******************************************************************************* * IBM Confidential * OCO Source Materials @@ -13,6 +16,7 @@ package mounter import ( "bufio" + "context" "crypto/sha256" "encoding/json" "fmt" @@ -22,8 +26,9 @@ import ( "time" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/logger" "github.com/IBM/ibm-object-csi-driver/pkg/mounter/utils" - "k8s.io/klog/v2" + "go.uber.org/zap" ) // Mounter interface defined in mounter.go @@ -42,6 +47,7 @@ type RcloneMounter struct { GID string MountOptions []string MounterUtils utils.MounterUtils + logger *zap.Logger } const ( @@ -54,11 +60,16 @@ const ( var ( createConfigWrap = createConfig removeConfigFile = removeRcloneConfigFile + // rcloneLogger is used for package-level logging where context is not available + rcloneLogger *zap.Logger ) -func NewRcloneMounter(secretMap map[string]string, mountOptions []string, mounterUtils utils.MounterUtils) Mounter { - klog.Info("-newRcloneMounter-") +func init() { + rcloneLogger = logger.NewJSONLoggerOrNop("rclone-mounter") + rcloneLogger = rcloneLogger.With(zap.String("component", "rclone-mounter")) +} +func NewRcloneMounter(secretMap map[string]string, mountOptions []string, mounterUtils utils.MounterUtils) Mounter { var ( val string check bool @@ -120,14 +131,15 @@ func NewRcloneMounter(secretMap map[string]string, mountOptions []string, mounte mounter.UID = secretMap["uid"] } - klog.Infof("newRcloneMounter args:\n\tbucketName: [%s]\n\tobjectPath: [%s]\n\tendPoint: [%s]\n\tlocationConstraint: [%s]\n\tauthType: [%s]", - mounter.BucketName, mounter.ObjectPath, mounter.EndPoint, mounter.LocConstraint, mounter.AuthType) - updatedOptions := updateMountOptions(mountOptions, secretMap) mounter.MountOptions = updatedOptions mounter.MounterUtils = mounterUtils + // Initialize logger - use JSON logger or fallback to nop + mounter.logger = logger.NewJSONLoggerOrNop("rclone-mounter") + mounter.logger = mounter.logger.With(zap.String("component", "rclone-mounter")) + return mounter } @@ -145,7 +157,7 @@ func updateMountOptions(dafaultMountOptions []string, secretMap map[string]strin stringData, ok := secretMap["mountOptions"] if !ok { - klog.Infof("No new mountOptions found. Using default mountOptions: %v", dafaultMountOptions) + rcloneLogger.Info("No new mountOptions found. Using default mountOptions", zap.Any("default_mount_options", dafaultMountOptions)) return dafaultMountOptions } @@ -158,7 +170,7 @@ func updateMountOptions(dafaultMountOptions []string, secretMap map[string]strin } opts := strings.Split(line, "=") if len(opts) != 2 { - klog.Infof("Invalid mount option: %s\n", line) + rcloneLogger.Info("Invalid mount option", zap.String("line", line)) continue } mountOptsMap[strings.TrimSpace(opts[0])] = strings.TrimSpace(opts[1]) @@ -171,14 +183,14 @@ func updateMountOptions(dafaultMountOptions []string, secretMap map[string]strin updatedOptions = append(updatedOptions, option) } - klog.Infof("Updated rclone Options: %v", updatedOptions) + rcloneLogger.Info("Updated rclone Options", zap.Any("updated_options", updatedOptions)) return updatedOptions } -func (rclone *RcloneMounter) Mount(source string, target string) error { - klog.Info("-RcloneMounter Mount-") - klog.Infof("Mount args:\n\tsource: <%s>\n\ttarget: <%s>", source, target) +func (rclone *RcloneMounter) Mount(ctx context.Context, source string, target string) error { + logger.Info(ctx, rclone.logger, "RcloneMounter Mount started", + zap.String("source", source), zap.String("target", target)) var bucketName string var err error @@ -191,8 +203,10 @@ func (rclone *RcloneMounter) Mount(source string, target string) error { } configPathWithVolID := path.Join(configPath, fmt.Sprintf("%x", sha256.Sum256([]byte(target)))) + logger.Debug(ctx, rclone.logger, "Creating rclone config", zap.String("config_path", configPathWithVolID)) + if err = createConfigWrap(configPathWithVolID, rclone); err != nil { - klog.Errorf("RcloneMounter Mount: Cannot create rclone config file %v", err) + logger.Error(ctx, rclone.logger, "Cannot create rclone config file", zap.Error(err)) return err } @@ -203,55 +217,72 @@ func (rclone *RcloneMounter) Mount(source string, target string) error { bucketName = fmt.Sprintf("%s:%s", remote, rclone.BucketName) } + logger.Info(ctx, rclone.logger, "Formulating mount options", + zap.String("bucket_name", bucketName), + zap.String("auth_type", rclone.AuthType)) args, wnOp := rclone.formulateMountOptions(bucketName, target, configPathWithVolID) if mountWorker { - klog.Info("Mount on Worker started...") + logger.Info(ctx, rclone.logger, "Mount on Worker started") jsonData, err := json.Marshal(wnOp) if err != nil { - klog.Fatalf("Error marshalling data: %v", err) + logger.Error(ctx, rclone.logger, "Error marshalling data", zap.Error(err)) return err } payload := fmt.Sprintf(`{"path":"%s","bucket":"%s","mounter":"%s","args":%s}`, target, bucketName, constants.RClone, jsonData) - err = mounterRequest(payload, "http://unix/api/cos/mount") + logger.Debug(ctx, rclone.logger, "Worker mounting payload", zap.String("payload", payload)) + + err = mounterRequest(ctx, payload, "http://unix/api/cos/mount", rclone.logger) if err != nil { - klog.Error("failed to mount on worker...", err) + logger.Error(ctx, rclone.logger, "Failed to mount on worker", zap.Error(err)) return err } + logger.Info(ctx, rclone.logger, "RcloneMounter Mount completed successfully on worker") return nil } - klog.Info("NodeServer Mounting...") - return rclone.MounterUtils.FuseMount(target, constants.RClone, args) + + logger.Info(ctx, rclone.logger, "NodeServer mounting") + err = rclone.MounterUtils.FuseMount(ctx, target, constants.RClone, args) + if err != nil { + logger.Error(ctx, rclone.logger, "FuseMount failed", zap.Error(err)) + } else { + logger.Info(ctx, rclone.logger, "RcloneMounter Mount completed successfully") + } + return err } -func (rclone *RcloneMounter) Unmount(target string) error { - klog.Info("-RcloneMounter Unmount-") +func (rclone *RcloneMounter) Unmount(ctx context.Context, target string) error { + logger.Info(ctx, rclone.logger, "RcloneMounter Unmount started", zap.String("target", target)) if mountWorker { - klog.Info("Unmount on Worker started...") + logger.Info(ctx, rclone.logger, "Unmount on Worker started") payload := fmt.Sprintf(`{"path":"%s"}`, target) - err := mounterRequest(payload, "http://unix/api/cos/unmount") + err := mounterRequest(ctx, payload, "http://unix/api/cos/unmount", rclone.logger) if err != nil { - klog.Error("failed to unmount on worker...", err) + logger.Error(ctx, rclone.logger, "Failed to unmount on worker", zap.Error(err)) return err } removeConfigFile(constants.MounterConfigPathOnHost, target) + logger.Info(ctx, rclone.logger, "RcloneMounter Unmount completed successfully on worker") return nil } - klog.Info("NodeServer Unmounting...") - err := rclone.MounterUtils.FuseUnmount(target) + logger.Info(ctx, rclone.logger, "NodeServer unmounting") + + err := rclone.MounterUtils.FuseUnmount(ctx, target) if err != nil { + logger.Error(ctx, rclone.logger, "FuseUnmount failed", zap.Error(err)) return err } removeConfigFile(constants.MounterConfigPathOnPodRclone, target) + logger.Info(ctx, rclone.logger, "RcloneMounter Unmount completed successfully") return nil } @@ -299,34 +330,34 @@ func createConfig(configPathWithVolID string, rclone *RcloneMounter) error { if err := MakeDir(configPathWithVolID, 0755); // #nosec G301: used for rclone err != nil { - klog.Errorf("RcloneMounter Mount: Cannot create directory %s: %v", configPathWithVolID, err) + rcloneLogger.Error("RcloneMounter Mount: Cannot create directory", zap.String("path", configPathWithVolID), zap.Error(err)) return err } configFile := path.Join(configPathWithVolID, configFileName) file, err := CreateFile(configFile) // #nosec G304 used for rclone if err != nil { - klog.Errorf("RcloneMounter Mount: Cannot create file %s: %v", configFileName, err) + rcloneLogger.Error("RcloneMounter Mount: Cannot create file", zap.String("file", configFileName), zap.Error(err)) return err } defer func() { if err = file.Close(); err != nil { - klog.Errorf("RcloneMounter Mount: Cannot close file %s: %v", configFileName, err) + rcloneLogger.Error("RcloneMounter Mount: Cannot close file", zap.String("file", configFileName), zap.Error(err)) } }() err = Chmod(configFile, 0644) // #nosec G302: used for rclone if err != nil { - klog.Errorf("RcloneMounter Mount: Cannot change permissions on file %s: %v", configFileName, err) + rcloneLogger.Error("RcloneMounter Mount: Cannot change permissions on file", zap.String("file", configFileName), zap.Error(err)) return err } - klog.Info("-Rclone writing to config-") + rcloneLogger.Info("Rclone writing to config") datawriter := bufio.NewWriter(file) for _, line := range configParams { _, err = datawriter.WriteString(line + "\n") if err != nil { - klog.Errorf("RcloneMounter Mount: Could not write to config file: %v", err) + rcloneLogger.Error("RcloneMounter Mount: Could not write to config file", zap.Error(err)) return err } } @@ -334,7 +365,7 @@ func createConfig(configPathWithVolID string, rclone *RcloneMounter) error { if err != nil { return err } - klog.Info("-Rclone created rclone config file-") + rcloneLogger.Info("Rclone created rclone config file") return nil } @@ -380,21 +411,21 @@ func removeRcloneConfigFile(configPath, target string) { _, err := Stat(configPathWithVolID) if err != nil { if os.IsNotExist(err) { - klog.Infof("removeRcloneConfigFile: Config file directory does not exist: %s", configPathWithVolID) + rcloneLogger.Info("removeRcloneConfigFile: Config file directory does not exist", zap.String("path", configPathWithVolID)) return } - klog.Errorf("removeRcloneConfigFile: Attempt %d - Failed to stat path %s: %v", retry, configPathWithVolID, err) + rcloneLogger.Error("removeRcloneConfigFile: Failed to stat path", zap.Int("attempt", retry), zap.String("path", configPathWithVolID), zap.Error(err)) time.Sleep(constants.Interval) continue } err = RemoveAll(configPathWithVolID) if err != nil { - klog.Errorf("removeRcloneConfigFile: Attempt %d - Failed to remove config file path %s: %v", retry, configPathWithVolID, err) + rcloneLogger.Error("removeRcloneConfigFile: Failed to remove config file path", zap.Int("attempt", retry), zap.String("path", configPathWithVolID), zap.Error(err)) time.Sleep(constants.Interval) continue } - klog.Infof("removeRcloneConfigFile: Successfully removed config file path: %s", configPathWithVolID) + rcloneLogger.Info("removeRcloneConfigFile: Successfully removed config file path", zap.String("path", configPathWithVolID)) return } - klog.Errorf("removeRcloneConfigFile: Failed to remove config file path after %d attempts", maxRetries) + rcloneLogger.Error("removeRcloneConfigFile: Failed to remove config file path after max attempts", zap.Int("max_attempts", maxRetries)) } diff --git a/pkg/mounter/mounter-rclone_test.go b/pkg/mounter/mounter-rclone_test.go index 5a58250c..c2ce4bd6 100644 --- a/pkg/mounter/mounter-rclone_test.go +++ b/pkg/mounter/mounter-rclone_test.go @@ -1,12 +1,17 @@ +//go:build linux +// +build linux + package mounter import ( + "context" "errors" "os" "testing" mounterUtils "github.com/IBM/ibm-object-csi-driver/pkg/mounter/utils" "github.com/stretchr/testify/assert" + "go.uber.org/zap" ) var ( @@ -131,8 +136,9 @@ func TestRcloneMount_NodeServer_Positive(t *testing.T) { EndPoint: "testEndpoint", GID: "testGID", UID: "testUID", + logger: zap.NewNop(), MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseMountFn: func(path, comm string, args []string) error { + FuseMountFn: func(ctx context.Context, path, comm string, args []string) error { return nil }, }), @@ -142,18 +148,20 @@ func TestRcloneMount_NodeServer_Positive(t *testing.T) { return nil } - err := rclone.Mount(source, target) + err := rclone.Mount(context.Background(), source, target) assert.NoError(t, err) } func TestRcloneMount_CreateConfigFails_Negative(t *testing.T) { - rclone := &RcloneMounter{} + rclone := &RcloneMounter{ + logger: zap.NewNop(), + } createConfigWrap = func(_ string, _ *RcloneMounter) error { return errors.New("failed to create config file") } - err := rclone.Mount(source, target) + err := rclone.Mount(context.Background(), source, target) assert.Error(t, err) assert.EqualError(t, err, "failed to create config file") } @@ -168,8 +176,9 @@ func TestRcloneMount_WorkerNode_Positive(t *testing.T) { GID: "testGID", UID: "testUID", ObjectPath: "testObjectPath", + logger: zap.NewNop(), MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseMountFn: func(path, comm string, args []string) error { + FuseMountFn: func(ctx context.Context, path, comm string, args []string) error { return nil }, }), @@ -178,11 +187,11 @@ func TestRcloneMount_WorkerNode_Positive(t *testing.T) { createConfigWrap = func(_ string, _ *RcloneMounter) error { return nil } - mounterRequest = func(_, _ string) error { + mounterRequest = func(_ context.Context, _, _ string, _ *zap.Logger) error { return nil } - err := rclone.Mount(source, target) + err := rclone.Mount(context.Background(), source, target) assert.NoError(t, err) } @@ -196,8 +205,9 @@ func TestRcloneMount_WorkerNode_Negative(t *testing.T) { GID: "testGID", UID: "testUID", ObjectPath: "testObjectPath", + logger: zap.NewNop(), MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseMountFn: func(path, comm string, args []string) error { + FuseMountFn: func(ctx context.Context, path, comm string, args []string) error { return nil }, }), @@ -206,11 +216,11 @@ func TestRcloneMount_WorkerNode_Negative(t *testing.T) { createConfigWrap = func(_ string, _ *RcloneMounter) error { return nil } - mounterRequest = func(_, _ string) error { + mounterRequest = func(_ context.Context, _, _ string, _ *zap.Logger) error { return errors.New("failed to create http request") } - err := rclone.Mount(source, target) + err := rclone.Mount(context.Background(), source, target) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to create http request") } @@ -220,13 +230,16 @@ func TestRcloneUnmount_NodeServer(t *testing.T) { removeConfigFile = func(_, _ string) {} - rclone := &RcloneMounter{MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseUnmountFn: func(path string) error { - return nil - }, - })} + rclone := &RcloneMounter{ + logger: zap.NewNop(), + MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ + FuseUnmountFn: func(ctx context.Context, path string) error { + return nil + }, + }), + } - err := rclone.Unmount(target) + err := rclone.Unmount(context.Background(), target) assert.NoError(t, err) } @@ -235,34 +248,39 @@ func TestRcloneUnmount_WorkerNode(t *testing.T) { removeConfigFile = func(_, _ string) {} - rclone := &RcloneMounter{MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseUnmountFn: func(path string) error { - return nil - }, - })} + rclone := &RcloneMounter{ + logger: zap.NewNop(), + MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ + FuseUnmountFn: func(ctx context.Context, path string) error { + return nil + }, + })} - mounterRequest = func(_, _ string) error { + mounterRequest = func(_ context.Context, _, _ string, _ *zap.Logger) error { return nil } - err := rclone.Unmount(target) + err := rclone.Unmount(context.Background(), target) assert.NoError(t, err) } func TestRcloneUnmount_WorkerNode_Negative(t *testing.T) { mountWorker = true - rclone := &RcloneMounter{MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseUnmountFn: func(path string) error { - return nil - }, - })} + rclone := &RcloneMounter{ + logger: zap.NewNop(), + MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ + FuseUnmountFn: func(ctx context.Context, path string) error { + return nil + }, + }), + } - mounterRequest = func(_, _ string) error { + mounterRequest = func(_ context.Context, _, _ string, _ *zap.Logger) error { return errors.New("failed to create http request") } - err := rclone.Unmount(target) + err := rclone.Unmount(context.Background(), target) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to create http request") } @@ -272,13 +290,16 @@ func TestRcloneUnmount_NodeServer_Negative(t *testing.T) { removeConfigFile = func(_, _ string) {} - rclone := &RcloneMounter{MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseUnmountFn: func(path string) error { - return errors.New("failed to unmount") - }, - })} + rclone := &RcloneMounter{ + logger: zap.NewNop(), + MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ + FuseUnmountFn: func(ctx context.Context, path string) error { + return errors.New("failed to unmount") + }, + }), + } - err := rclone.Unmount(target) + err := rclone.Unmount(context.Background(), target) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to unmount") } diff --git a/pkg/mounter/mounter-s3fs.go b/pkg/mounter/mounter-s3fs.go index 3a5e55b7..dc842e81 100644 --- a/pkg/mounter/mounter-s3fs.go +++ b/pkg/mounter/mounter-s3fs.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + /******************************************************************************* * IBM Confidential * OCO Source Materials @@ -12,6 +15,7 @@ package mounter import ( + "context" "crypto/sha256" "encoding/json" "fmt" @@ -21,8 +25,10 @@ import ( "time" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/logger" "github.com/IBM/ibm-object-csi-driver/pkg/mounter/utils" - "k8s.io/klog/v2" + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" + "go.uber.org/zap" ) // Mounter interface defined in mounter.go @@ -38,6 +44,7 @@ type S3fsMounter struct { KpRootKeyCrn string MountOptions []string MounterUtils utils.MounterUtils + logger *zap.Logger } const ( @@ -48,11 +55,16 @@ const ( var ( writePassWrap = writePass removeFile = removeS3FSCredFile + // s3fsLogger is used for package-level logging where context is not available + s3fsLogger *zap.Logger ) -func NewS3fsMounter(secretMap map[string]string, mountOptions []string, mounterUtils utils.MounterUtils, defaultParams map[string]string) Mounter { - klog.Info("-newS3fsMounter-") +func init() { + s3fsLogger = logger.NewJSONLoggerOrNop("s3fs-mounter") + s3fsLogger = s3fsLogger.With(zap.String("component", "s3fs-mounter")) +} +func NewS3fsMounter(secretMap map[string]string, mountOptions []string, mounterUtils utils.MounterUtils, defaultParams map[string]string) Mounter { var ( val string check bool @@ -100,20 +112,23 @@ func NewS3fsMounter(secretMap map[string]string, mountOptions []string, mounterU mounter.AuthType = "hmac" } - klog.Infof("newS3fsMounter args:\n\tbucketName: [%s]\n\tobjectPath: [%s]\n\tendPoint: [%s]\n\tlocationConstraint: [%s]\n\tauthType: [%s]\n\tkpRootKeyCrn: [%s]", - mounter.BucketName, mounter.ObjectPath, mounter.EndPoint, mounter.LocConstraint, mounter.AuthType, mounter.KpRootKeyCrn) - updatedOptions := updateS3FSMountOptions(mountOptions, secretMap, defaultParams) mounter.MountOptions = updatedOptions mounter.MounterUtils = mounterUtils + // Initialize logger - use JSON logger or fallback to nop + mounter.logger = logger.NewJSONLoggerOrNop("s3fs-mounter") + mounter.logger = mounter.logger.With(zap.String("component", "s3fs-mounter")) + return mounter } -func (s3fs *S3fsMounter) Mount(source string, target string) error { - klog.Info("-S3FSMounter Mount-") - klog.Infof("Mount args:\n\tsource: <%s>\n\ttarget: <%s>", source, target) +func (s3fs *S3fsMounter) Mount(ctx context.Context, source string, target string) error { + logger.Info(ctx, s3fs.logger, "S3FSMounter Mount started", + zap.String("source", source), zap.String("target", target)) + + reqID := requestid.FromContext(ctx) // Still needed for error messages var s3fsCredDir string if mountWorker { @@ -129,22 +144,23 @@ func (s3fs *S3fsMounter) Mount(source string, target string) error { metaPath := path.Join(s3fsCredDir, fmt.Sprintf("%x", sha256.Sum256([]byte(target)))) if pathExist, err = checkPath(metaPath); err != nil { - klog.Errorf("S3FSMounter Mount: Cannot stat directory %s: %v", metaPath, err) - return fmt.Errorf("S3FSMounter Mount: Cannot stat directory %s: %v", metaPath, err) + logger.Error(ctx, s3fs.logger, "Cannot stat directory", zap.String("meta_path", metaPath), zap.Error(err)) + return fmt.Errorf("[%s] S3FSMounter Mount: Cannot stat directory %s: %v", reqID, metaPath, err) } if !pathExist { + logger.Debug(ctx, s3fs.logger, "Creating meta directory", zap.String("meta_path", metaPath)) if err = MakeDir(metaPath, 0755); // #nosec G301: used for s3fs err != nil { - klog.Errorf("S3FSMounter Mount: Cannot create directory %s: %v", metaPath, err) - return fmt.Errorf("S3FSMounter Mount: Cannot create directory %s: %v", metaPath, err) + logger.Error(ctx, s3fs.logger, "Cannot create directory", zap.String("meta_path", metaPath), zap.Error(err)) + return fmt.Errorf("[%s] S3FSMounter Mount: Cannot create directory %s: %v", reqID, metaPath, err) } } passwdFile := path.Join(metaPath, passFile) if err = writePassWrap(passwdFile, s3fs.AccessKeys); err != nil { - klog.Errorf("S3FSMounter Mount: Cannot create file %s: %v", passwdFile, err) - return fmt.Errorf("S3FSMounter Mount: Cannot create file %s: %v", passwdFile, err) + logger.Error(ctx, s3fs.logger, "Cannot create password file", zap.String("passwd_file", passwdFile), zap.Error(err)) + return fmt.Errorf("[%s] S3FSMounter Mount: Cannot create file %s: %v", reqID, passwdFile, err) } if s3fs.ObjectPath != "" { @@ -157,58 +173,72 @@ func (s3fs *S3fsMounter) Mount(source string, target string) error { bucketName = s3fs.BucketName } + logger.Info(ctx, s3fs.logger, "Formulating mount options", + zap.String("bucket_name", bucketName), + zap.String("auth_type", s3fs.AuthType)) args, wnOp := s3fs.formulateMountOptions(bucketName, target, passwdFile) if mountWorker { - klog.Info(" Mount on Worker started...") + logger.Info(ctx, s3fs.logger, "Mount on Worker started") jsonData, err := json.Marshal(wnOp) if err != nil { - klog.Fatalf("Error marshalling data: %v", err) + logger.Error(ctx, s3fs.logger, "Error marshalling data", zap.Error(err)) return err } payload := fmt.Sprintf(`{"path":"%s","bucket":"%s","mounter":"%s","args":%s}`, target, bucketName, constants.S3FS, jsonData) - klog.Info("Worker Mounting Payload...", payload) + logger.Debug(ctx, s3fs.logger, "Worker mounting payload", zap.String("payload", payload)) - err = mounterRequest(payload, "http://unix/api/cos/mount") + err = mounterRequest(ctx, payload, "http://unix/api/cos/mount", s3fs.logger) if err != nil { - klog.Error("failed to mount on worker...", err) + logger.Error(ctx, s3fs.logger, "Failed to mount on worker", zap.Error(err)) return err } + logger.Info(ctx, s3fs.logger, "S3FSMounter Mount completed successfully on worker") return nil } - klog.Info("NodeServer Mounting...") - return s3fs.MounterUtils.FuseMount(target, constants.S3FS, args) + + logger.Info(ctx, s3fs.logger, "NodeServer mounting") + err = s3fs.MounterUtils.FuseMount(ctx, target, constants.S3FS, args) + if err != nil { + logger.Error(ctx, s3fs.logger, "FuseMount failed", zap.Error(err)) + } else { + logger.Info(ctx, s3fs.logger, "S3FSMounter Mount completed successfully") + } + return err } -func (s3fs *S3fsMounter) Unmount(target string) error { - klog.Info("-S3FSMounter Unmount-") - klog.Infof("Unmount args:\n\ttarget: <%s>", target) +func (s3fs *S3fsMounter) Unmount(ctx context.Context, target string) error { + logger.Info(ctx, s3fs.logger, "S3FSMounter Unmount started", zap.String("target", target)) if mountWorker { - klog.Info("Unmount on Worker started...") + logger.Info(ctx, s3fs.logger, "Unmount on Worker started") payload := fmt.Sprintf(`{"path":"%s"}`, target) - err := mounterRequest(payload, "http://unix/api/cos/unmount") + err := mounterRequest(ctx, payload, "http://unix/api/cos/unmount", s3fs.logger) if err != nil { - klog.Error("failed to unmount on worker...", err) + logger.Error(ctx, s3fs.logger, "Failed to unmount on worker", zap.Error(err)) return err } removeFile(constants.MounterConfigPathOnHost, target) + logger.Info(ctx, s3fs.logger, "S3FSMounter Unmount completed successfully on worker") return nil } - klog.Info("NodeServer Unmounting...") - err := s3fs.MounterUtils.FuseUnmount(target) + logger.Info(ctx, s3fs.logger, "NodeServer unmounting") + + err := s3fs.MounterUtils.FuseUnmount(ctx, target) if err != nil { + logger.Error(ctx, s3fs.logger, "FuseUnmount failed", zap.Error(err)) return err } removeFile(constants.MounterConfigPathOnPodS3fs, target) + logger.Info(ctx, s3fs.logger, "S3FSMounter Unmount completed successfully") return nil } @@ -248,7 +278,7 @@ func updateS3FSMountOptions(defaultMountOp []string, secretMap map[string]string stringData, ok := secretMap["mountOptions"] if !ok { - klog.Infof("No new mountOptions found. Using default mountOptions: %v", mountOptsMap) + s3fsLogger.Info("No new mountOptions found. Using default mountOptions", zap.Any("default_mount_options", mountOptsMap)) } else { lines := strings.Split(stringData, "\n") // Update map @@ -262,7 +292,7 @@ func updateS3FSMountOptions(defaultMountOp []string, secretMap map[string]string } else if len(opts) == 1 { mountOptsMap[strings.TrimSpace(opts[0])] = strings.TrimSpace(opts[0]) } else { - klog.Infof("Invalid mount option: %s\n", line) + s3fsLogger.Info("Invalid mount option", zap.String("line", line)) } } } @@ -299,7 +329,7 @@ func updateS3FSMountOptions(defaultMountOp []string, secretMap map[string]string } } - klog.Infof("updated S3fsMounter Options: %v", updatedOptions) + s3fsLogger.Info("updated S3fsMounter Options", zap.Any("updated_options", updatedOptions)) return updatedOptions } @@ -361,21 +391,21 @@ func removeS3FSCredFile(credDir, target string) { _, err := Stat(metaPath) if err != nil { if os.IsNotExist(err) { - klog.Infof("removeS3FSCredFile: Password file directory does not exist: %s", metaPath) + s3fsLogger.Info("removeS3FSCredFile: Password file directory does not exist", zap.String("path", metaPath)) return } - klog.Errorf("removeS3FSCredFile: Attempt %d - Failed to stat path %s: %v", retry, metaPath, err) + s3fsLogger.Error("removeS3FSCredFile: Failed to stat path", zap.Int("attempt", retry), zap.String("path", metaPath), zap.Error(err)) time.Sleep(constants.Interval) continue } err = RemoveAll(metaPath) if err != nil { - klog.Errorf("removeS3FSCredFile: Attempt %d - Failed to remove password file path %s: %v", retry, metaPath, err) + s3fsLogger.Error("removeS3FSCredFile: Failed to remove password file path", zap.Int("attempt", retry), zap.String("path", metaPath), zap.Error(err)) time.Sleep(constants.Interval) continue } - klog.Infof("removeS3FSCredFile: Successfully removed password file path: %s", metaPath) + s3fsLogger.Info("removeS3FSCredFile: Successfully removed password file path", zap.String("path", metaPath)) return } - klog.Errorf("removeS3FSCredFile: Failed to remove password file after %d attempts", maxRetries) + s3fsLogger.Error("removeS3FSCredFile: Failed to remove password file after max attempts", zap.Int("max_attempts", maxRetries)) } diff --git a/pkg/mounter/mounter-s3fs_test.go b/pkg/mounter/mounter-s3fs_test.go index 430b8f2c..ad4b08f0 100644 --- a/pkg/mounter/mounter-s3fs_test.go +++ b/pkg/mounter/mounter-s3fs_test.go @@ -1,6 +1,10 @@ +//go:build linux +// +build linux + package mounter import ( + "context" "errors" "os" "testing" @@ -8,6 +12,7 @@ import ( "github.com/IBM/ibm-object-csi-driver/pkg/constants" mounterUtils "github.com/IBM/ibm-object-csi-driver/pkg/mounter/utils" "github.com/stretchr/testify/assert" + "go.uber.org/zap" ) var ( @@ -79,16 +84,17 @@ func TestS3FSMount_NodeServer_Positive(t *testing.T) { s3fs := &S3fsMounter{ MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseMountFn: func(path, comm string, args []string) error { + FuseMountFn: func(ctx context.Context, path, comm string, args []string) error { return nil }, }), LocConstraint: "test-location", MountOptions: mountOptions, ObjectPath: "test-objectPath", + logger: zap.NewNop(), } - err := s3fs.Mount(source, target) + err := s3fs.Mount(context.Background(), source, target) assert.NoError(t, err) } @@ -101,31 +107,34 @@ func TestS3FSMount_WorkerNode_Positive(t *testing.T) { writePassWrap = func(_, _ string) error { return nil } - mounterRequest = func(_, _ string) error { + mounterRequest = func(_ context.Context, _, _ string, _ *zap.Logger) error { return nil } s3fs := &S3fsMounter{ MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseMountFn: func(path, comm string, args []string) error { + FuseMountFn: func(ctx context.Context, path, comm string, args []string) error { return nil }, }), AuthType: "hmac", + logger: zap.NewNop(), } - err := s3fs.Mount(source, target) + err := s3fs.Mount(context.Background(), source, target) assert.NoError(t, err) } func TestMount_CreateDirFails_Negative(t *testing.T) { - s3fs := &S3fsMounter{} + s3fs := &S3fsMounter{ + logger: zap.NewNop(), + } MakeDir = func(path string, perm os.FileMode) error { return errors.New("failed to create directory") } - err := s3fs.Mount(source, target) + err := s3fs.Mount(context.Background(), source, target) assert.Error(t, err) assert.Contains(t, err.Error(), "Cannot create directory") } @@ -138,9 +147,11 @@ func TestMount_FailedToCreatePassFile_Negative(t *testing.T) { return errors.New("failed to create file") } - s3fs := &S3fsMounter{} + s3fs := &S3fsMounter{ + logger: zap.NewNop(), + } - err := s3fs.Mount(source, target) + err := s3fs.Mount(context.Background(), source, target) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to create file") } @@ -154,13 +165,15 @@ func TestS3FSMount_WorkerNode_Negative(t *testing.T) { writePassWrap = func(_, _ string) error { return nil } - mounterRequest = func(_, _ string) error { + mounterRequest = func(_ context.Context, _, _ string, _ *zap.Logger) error { return errors.New("failed to perform http request") } - s3fs := &S3fsMounter{} + s3fs := &S3fsMounter{ + logger: zap.NewNop(), + } - err := s3fs.Mount(source, target) + err := s3fs.Mount(context.Background(), source, target) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to perform http request") } @@ -170,13 +183,16 @@ func TestUnmount_NodeServer(t *testing.T) { removeFile = func(_, _ string) {} - s3fs := &S3fsMounter{MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseUnmountFn: func(path string) error { - return nil - }, - })} + s3fs := &S3fsMounter{ + logger: zap.NewNop(), + MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ + FuseUnmountFn: func(ctx context.Context, path string) error { + return nil + }, + }), + } - err := s3fs.Unmount(target) + err := s3fs.Unmount(context.Background(), target) assert.NoError(t, err) } @@ -185,34 +201,40 @@ func TestUnmount_WorkerNode(t *testing.T) { removeFile = func(_, _ string) {} - s3fs := &S3fsMounter{MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseUnmountFn: func(path string) error { - return nil - }, - })} + s3fs := &S3fsMounter{ + logger: zap.NewNop(), + MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ + FuseUnmountFn: func(ctx context.Context, path string) error { + return nil + }, + }), + } - mounterRequest = func(_, _ string) error { + mounterRequest = func(_ context.Context, _, _ string, _ *zap.Logger) error { return nil } - err := s3fs.Unmount(target) + err := s3fs.Unmount(context.Background(), target) assert.NoError(t, err) } func TestUnmount_WorkerNode_Negative(t *testing.T) { mountWorker = true - s3fs := &S3fsMounter{MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseUnmountFn: func(path string) error { - return nil - }, - })} + s3fs := &S3fsMounter{ + logger: zap.NewNop(), + MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ + FuseUnmountFn: func(ctx context.Context, path string) error { + return nil + }, + }), + } - mounterRequest = func(_, _ string) error { + mounterRequest = func(_ context.Context, _, _ string, _ *zap.Logger) error { return errors.New("failed to create http request") } - err := s3fs.Unmount(target) + err := s3fs.Unmount(context.Background(), target) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to create http request") } @@ -222,13 +244,16 @@ func TestUnmount_NodeServer_Negative(t *testing.T) { removeFile = func(_, _ string) {} - s3fs := &S3fsMounter{MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ - FuseUnmountFn: func(path string) error { - return errors.New("failed to unmount") - }, - })} + s3fs := &S3fsMounter{ + logger: zap.NewNop(), + MounterUtils: mounterUtils.NewFakeMounterUtilsImpl(mounterUtils.FakeMounterUtilsFuncStruct{ + FuseUnmountFn: func(ctx context.Context, path string) error { + return errors.New("failed to unmount") + }, + }), + } - err := s3fs.Unmount(target) + err := s3fs.Unmount(context.Background(), target) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to unmount") } diff --git a/pkg/mounter/mounter.go b/pkg/mounter/mounter.go index 533e9eae..297987f2 100644 --- a/pkg/mounter/mounter.go +++ b/pkg/mounter/mounter.go @@ -1,9 +1,13 @@ +//go:build linux +// +build linux + package mounter import ( "context" "encoding/json" "errors" + "fmt" "io" "net" "net/http" @@ -14,14 +18,18 @@ import ( "github.com/IBM/ibm-object-csi-driver/pkg/constants" mounterUtils "github.com/IBM/ibm-object-csi-driver/pkg/mounter/utils" + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" + "go.uber.org/zap" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" - "k8s.io/klog/v2" ) var ( - mountWorker = true - mounterRequest = createCOSCSIMounterRequest + mountWorker = true + // mounterRequest is a function variable that can be overridden for testing + mounterRequest = func(ctx context.Context, payload string, url string, log *zap.Logger) error { + return createCOSCSIMounterRequest(ctx, payload, url, log) + } MakeDir = os.MkdirAll CreateFile = os.Create @@ -31,8 +39,8 @@ var ( ) type Mounter interface { - Mount(source string, target string) error - Unmount(target string) error + Mount(ctx context.Context, source string, target string) error + Unmount(ctx context.Context, target string) error } type CSIMounterFactory struct{} @@ -46,7 +54,6 @@ func NewCSIMounterFactory() *CSIMounterFactory { } func (s *CSIMounterFactory) NewMounter(attrib map[string]string, secretMap map[string]string, mountFlags []string, defaultMOMap map[string]string) Mounter { - klog.Info("-NewMounter-") var mounter, val string var check bool @@ -127,16 +134,20 @@ func writePass(pwFileName string, pwFileContent string) error { return nil } -func createCOSCSIMounterRequest(payload string, url string) error { +func createCOSCSIMounterRequest(ctx context.Context, payload string, url string, log *zap.Logger) error { + reqID := requestid.FromContext(ctx) + logWithReqID := log.With(zap.String("request_id", reqID)) + // Get socket path socketPath := os.Getenv(constants.COSCSIMounterSocketPathEnv) if socketPath == "" { socketPath = constants.COSCSIMounterSocketPath } - klog.Infof("COS CSI Mounter Socket Path: %s", socketPath) + logWithReqID.Info("COS CSI Mounter Socket Path", zap.String("socket_path", socketPath)) err := isGRPCServerAvailable(socketPath) if err != nil { + logWithReqID.Error("COS CSI Mounter service not available", zap.Error(err)) return err } @@ -156,58 +167,67 @@ func createCOSCSIMounterRequest(payload string, url string) error { // Create POST request req, err := http.NewRequest("POST", url, strings.NewReader(payload)) if err != nil { + logWithReqID.Error("Failed to create HTTP request", zap.Error(err)) return err } req.Header.Set("Content-Type", "application/json") + req.Header.Set("X-Request-ID", reqID) // Add request ID to HTTP header + + logWithReqID.Info("Sending request to cos-csi-mounter", zap.String("url", url)) response, err := client.Do(req) if err != nil { + logWithReqID.Error("Failed to send request to cos-csi-mounter", zap.Error(err)) return err } defer func() { if err := response.Body.Close(); err != nil { - klog.Errorf("failed to close response body: %v", err) + logWithReqID.Error("Failed to close response body", zap.Error(err)) } }() body, err := io.ReadAll(response.Body) if err != nil { + logWithReqID.Error("Failed to read response body", zap.Error(err)) return err } responseBody := string(body) - klog.Infof("response from cos-csi-mounter -> Response body: %s, Response code: %v", responseBody, response.StatusCode) + logWithReqID.Info("Response from cos-csi-mounter", + zap.String("response_body", responseBody), + zap.Int("status_code", response.StatusCode)) if response.StatusCode != http.StatusOK { - return parseGRPCResponse(response.StatusCode, responseBody) + return parseGRPCResponse(reqID, response.StatusCode, responseBody) } return nil } // parseGRPCResponse takes both response body and error code and frames error message -func parseGRPCResponse(code int, response string) error { +func parseGRPCResponse(reqID string, code int, response string) error { errMsg := parseErrFromResponse(response) + errMsgWithReqID := fmt.Sprintf("[%s] %s", reqID, errMsg) switch code { case http.StatusBadRequest: - return status.Error(codes.InvalidArgument, errMsg) + return status.Error(codes.InvalidArgument, errMsgWithReqID) case http.StatusNotFound: - return status.Error(codes.NotFound, errMsg) + return status.Error(codes.NotFound, errMsgWithReqID) case http.StatusConflict: - return status.Error(codes.AlreadyExists, errMsg) + return status.Error(codes.AlreadyExists, errMsgWithReqID) case http.StatusForbidden: - return status.Error(codes.PermissionDenied, errMsg) + return status.Error(codes.PermissionDenied, errMsgWithReqID) case http.StatusTooManyRequests: - return status.Error(codes.ResourceExhausted, errMsg) + return status.Error(codes.ResourceExhausted, errMsgWithReqID) case http.StatusNotImplemented: - return status.Error(codes.Unimplemented, errMsg) + return status.Error(codes.Unimplemented, errMsgWithReqID) case http.StatusInternalServerError: - return status.Error(codes.Internal, errMsg) + return status.Error(codes.Internal, errMsgWithReqID) case http.StatusServiceUnavailable: - return status.Error(codes.Unavailable, errMsg) + return status.Error(codes.Unavailable, errMsgWithReqID) case http.StatusUnauthorized: - return status.Error(codes.Unauthenticated, errMsg) + return status.Error(codes.Unauthenticated, errMsgWithReqID) default: - return status.Error(codes.Unknown, errMsg) + return status.Error(codes.Unknown, errMsgWithReqID) } } @@ -231,7 +251,7 @@ func parseErrFromResponse(response string) string { var errFromResp map[string]string err := json.Unmarshal([]byte(response), &errFromResp) if err != nil { - klog.Warning("failed to unmarshal response from server", err) + // Can't log here as we don't have logger context, just return the response return response } val, exists := errFromResp["error"] diff --git a/pkg/mounter/mounter_stub.go b/pkg/mounter/mounter_stub.go new file mode 100644 index 00000000..a74dcf6c --- /dev/null +++ b/pkg/mounter/mounter_stub.go @@ -0,0 +1,49 @@ +//go:build !linux +// +build !linux + +package mounter + +import ( + "context" + "fmt" +) + +type CSIMounterFactory struct{} + +type NewMounterFactory interface { + NewMounter(attrib map[string]string, secretMap map[string]string, mountFlags []string, defaultMOMap map[string]string) Mounter +} + +type Mounter interface { + Mount(ctx context.Context, source string, target string) error + Unmount(ctx context.Context, target string) error +} + +func NewCSIMounterFactory() *CSIMounterFactory { + return &CSIMounterFactory{} +} + +func (s *CSIMounterFactory) NewMounter(attrib map[string]string, secretMap map[string]string, mountFlags []string, defaultMOMap map[string]string) Mounter { + return &stubMounter{} +} + +// FakeMounterFactory is a stub implementation for testing on non-Linux platforms +type FakeMounterFactory struct { + Mounter string + IsFailedMount bool + IsFailedUnmount bool +} + +func (f *FakeMounterFactory) NewMounter(attrib map[string]string, secretMap map[string]string, mountFlags []string, defaultParams map[string]string) Mounter { + return &stubMounter{} +} + +type stubMounter struct{} + +func (s *stubMounter) Mount(ctx context.Context, source string, target string) error { + return fmt.Errorf("mounter not supported on this platform") +} + +func (s *stubMounter) Unmount(ctx context.Context, target string) error { + return fmt.Errorf("mounter not supported on this platform") +} diff --git a/pkg/mounter/mounter_test.go b/pkg/mounter/mounter_test.go index 50c5eba3..e7d2e7b7 100644 --- a/pkg/mounter/mounter_test.go +++ b/pkg/mounter/mounter_test.go @@ -1,3 +1,6 @@ +//go:build linux +// +build linux + package mounter import ( @@ -130,6 +133,9 @@ func TestNewMounter(t *testing.T) { } s3fs.MountOptions = nil expected.MountOptions = nil + // Exclude logger from comparison as it's initialized internally + s3fs.logger = nil + expected.logger = nil } if rclone, ok := result.(*RcloneMounter); ok { expected := test.expected.(*RcloneMounter) @@ -138,6 +144,9 @@ func TestNewMounter(t *testing.T) { } rclone.MountOptions = nil expected.MountOptions = nil + // Exclude logger from comparison as it's initialized internally + rclone.logger = nil + expected.logger = nil } assert.Equal(t, result, test.expected) diff --git a/pkg/mounter/utils/fake_mounter_utils.go b/pkg/mounter/utils/fake_mounter_utils.go index 72a843cd..eb7267b2 100644 --- a/pkg/mounter/utils/fake_mounter_utils.go +++ b/pkg/mounter/utils/fake_mounter_utils.go @@ -1,8 +1,10 @@ package utils +import "context" + type FakeMounterUtilsFuncStruct struct { - FuseMountFn func(path string, comm string, args []string) error - FuseUnmountFn func(path string) error + FuseMountFn func(ctx context.Context, path string, comm string, args []string) error + FuseUnmountFn func(ctx context.Context, path string) error } type FakeMounterUtilsFuncStructImpl struct { @@ -15,16 +17,16 @@ func NewFakeMounterUtilsImpl(reqFn FakeMounterUtilsFuncStruct) *FakeMounterUtils } } -func (m *FakeMounterUtilsFuncStructImpl) FuseMount(path string, comm string, args []string) error { +func (m *FakeMounterUtilsFuncStructImpl) FuseMount(ctx context.Context, path string, comm string, args []string) error { if m.FuncStruct.FuseMountFn != nil { - return m.FuncStruct.FuseMountFn(path, comm, args) + return m.FuncStruct.FuseMountFn(ctx, path, comm, args) } panic("requested method should not be nil") } -func (m *FakeMounterUtilsFuncStructImpl) FuseUnmount(path string) error { +func (m *FakeMounterUtilsFuncStructImpl) FuseUnmount(ctx context.Context, path string) error { if m.FuncStruct.FuseUnmountFn != nil { - return m.FuncStruct.FuseUnmountFn(path) + return m.FuncStruct.FuseUnmountFn(ctx, path) } panic("requested method should not be nil") } diff --git a/pkg/mounter/utils/mounter_utils.go b/pkg/mounter/utils/mounter_utils.go index d2e1f8c6..042dbe13 100644 --- a/pkg/mounter/utils/mounter_utils.go +++ b/pkg/mounter/utils/mounter_utils.go @@ -14,29 +14,62 @@ import ( "time" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/logger" "github.com/mitchellh/go-ps" - "k8s.io/klog/v2" + "go.uber.org/zap" k8sMountUtils "k8s.io/mount-utils" ) +// ContextKey is a custom type for context keys to avoid collisions +type ContextKey string + +// RequestIDKey is the context key for request ID (exported for use by other packages) +const RequestIDKey ContextKey = "ibm-cos-csi-request-id" + var unmount = syscall.Unmount var commandWithCtx = exec.CommandContext var ErrTimeoutWaitProcess = errors.New("timeout waiting for process to end") +// Package-level logger for mounter utils +var mounterUtilLogger *zap.Logger + +func init() { + mounterUtilLogger = logger.NewJSONLoggerOrNop("cos-csi-mounter") + mounterUtilLogger = mounterUtilLogger.With(zap.String("component", "mounter-utils")) +} + +// getRequestIDFromContext extracts request_id from context +func getRequestIDFromContext(ctx context.Context) string { + if ctx == nil { + return "unknown" + } + if reqID, ok := ctx.Value(RequestIDKey).(string); ok && reqID != "" { + return reqID + } + return "unknown" +} + type MounterUtils interface { - FuseUnmount(path string) error - FuseMount(path string, comm string, args []string) error + FuseUnmount(ctx context.Context, path string) error + FuseMount(ctx context.Context, path string, comm string, args []string) error } type MounterOptsUtils struct { } -func (su *MounterOptsUtils) FuseMount(path string, comm string, args []string) error { - klog.Info("-FuseMount-") - klog.Infof("FuseMount: params:\n\tpath: <%s>\n\tcommand: <%s>\n\targs: <%v>", path, comm, args) +func (su *MounterOptsUtils) FuseMount(ctx context.Context, path string, comm string, args []string) error { + // Extract request_id from context for logging + requestID := getRequestIDFromContext(ctx) + log := mounterUtilLogger.With(zap.String("request_id", requestID)) - ctx, cancel := context.WithCancel(context.Background()) + log.Info("FuseMount started") + log.Info("FuseMount parameters", + zap.String("path", path), + zap.String("command", comm), + zap.Strings("args", args)) + + mountCtx, cancel := context.WithCancel(ctx) var mounted bool defer func() { if !mounted { @@ -44,133 +77,170 @@ func (su *MounterOptsUtils) FuseMount(path string, comm string, args []string) e } }() - cmd := commandWithCtx(ctx, comm, args...) + cmd := commandWithCtx(mountCtx, comm, args...) err := cmd.Start() if err != nil { - klog.Errorf("FuseMount: command start failed: mounter=%s, args=%v, error=%v", comm, args, err) + log.Error("FuseMount: command start failed", + zap.String("mounter", comm), + zap.Strings("args", args), + zap.Error(err)) return fmt.Errorf("FuseMount: '%s' command start failed: %v", comm, err) } - klog.Infof("FuseMount: command 'start' succeeded for '%s' mounter", comm) + log.Info("FuseMount: command start succeeded", zap.String("mounter", comm)) waitCh := make(chan error, 1) mountCh := make(chan error, 1) go func() { - klog.Infof("FuseMount: cmd.Wait() goroutine start for mounter=%s, path=%v", comm, path) + log.Info("FuseMount: cmd.Wait() goroutine start", + zap.String("mounter", comm), + zap.String("path", path)) waitCh <- cmd.Wait() - klog.Infof("FuseMount: cmd.Wait() goroutine end for mounter=%s, path=%v", comm, path) + log.Info("FuseMount: cmd.Wait() goroutine end", + zap.String("mounter", comm), + zap.String("path", path)) }() go func() { - klog.Infof("FuseMount: waitForMount() goroutine start for mounter=%s, path=%v", comm, path) - mountCh <- waitForMount(ctx, path, 2*time.Second, 30*time.Second) // kubelet retries NodePublishVolume after 120 seconds - klog.Infof("FuseMount: waitForMount() goroutine end for mounter=%s, path=%v", comm, path) + log.Info("FuseMount: waitForMount() goroutine start", + zap.String("mounter", comm), + zap.String("path", path)) + mountCh <- waitForMount(mountCtx, log, path, 2*time.Second, 30*time.Second) // kubelet retries NodePublishVolume after 120 seconds + log.Info("FuseMount: waitForMount() goroutine end", + zap.String("mounter", comm), + zap.String("path", path)) }() select { case err := <-waitCh: if err != nil { - klog.Warningf("FuseMount: command 'wait' failed: mounter=%s, args=%v, error=%v", comm, args, err) - klog.Infof("FuseMount: checking if path already exists and is a mountpoint: path=%s", path) - if isMount, err1 := isMountpoint(path); err1 == nil && isMount { // check if bucket already got mounted - klog.Infof("bucket is already mounted using '%s' mounter", comm) + log.Warn("FuseMount: command wait failed", + zap.String("mounter", comm), + zap.Strings("args", args), + zap.Error(err)) + log.Info("FuseMount: checking if path already exists and is a mountpoint", + zap.String("path", path)) + if isMount, err1 := isMountpoint(log, path); err1 == nil && isMount { // check if bucket already got mounted + log.Info("Bucket is already mounted", zap.String("mounter", comm)) mounted = true return nil } return fmt.Errorf("'%s' mount failed: %v", comm, err) } - klog.Infof("FuseMount: command 'wait' succeeded for '%s' mounter", comm) + log.Info("FuseMount: command wait succeeded", zap.String("mounter", comm)) if err := <-mountCh; err != nil { return err } case err := <-mountCh: if err != nil { - klog.Errorf("FuseMount: path is not mountpoint. Mount failed: mounter=%s, path=%s", comm, path) + log.Error("FuseMount: path is not mountpoint, mount failed", + zap.String("mounter", comm), + zap.String("path", path)) return fmt.Errorf("'%s' mount failed: %v", comm, err) } } - klog.Infof("bucket mounted successfully using '%s' mounter", comm) + log.Info("Bucket mounted successfully", zap.String("mounter", comm)) mounted = true return nil } -func (su *MounterOptsUtils) FuseUnmount(path string) error { - klog.Info("-FuseUnmount-") +func (su *MounterOptsUtils) FuseUnmount(ctx context.Context, path string) error { + // Extract request_id from context for logging + requestID := getRequestIDFromContext(ctx) + log := mounterUtilLogger.With(zap.String("request_id", requestID)) + + log.Info("FuseUnmount started", zap.String("path", path)) // check if mountpoint exists - isMount, checkMountErr := isMountpoint(path) + isMount, checkMountErr := isMountpoint(log, path) if isMount || checkMountErr != nil { - klog.Infof("isMountpoint %v", isMount) + log.Info("isMountpoint check", zap.Bool("is_mount", isMount)) err := unmount(path, 0) if err != nil { - klog.Warningf("Standard unmount failed for %s: %v. Trying lazy unmount...", path, err) + log.Warn("Standard unmount failed, trying lazy unmount", + zap.String("path", path), + zap.Error(err)) // Try lazy (MNT_DETACH) unmount err = unmount(path, syscall.MNT_DETACH) if err != nil { - klog.Warningf("Lazy unmount failed for %s: %v. Trying force unmount...", path, err) + log.Warn("Lazy unmount failed, trying force unmount", + zap.String("path", path), + zap.Error(err)) // Try force unmount as last resort err = unmount(path, syscall.MNT_FORCE) if err != nil { - klog.Errorf("Force unmount failed for %s: %v", path, err) + log.Error("Force unmount failed", + zap.String("path", path), + zap.Error(err)) return fmt.Errorf("all unmount attempts failed for %s: %v", path, err) } - klog.Infof("Force unmounted %s successfully", path) + log.Info("Force unmounted successfully", zap.String("path", path)) } else { - klog.Infof("Lazy unmounted %s successfully", path) + log.Info("Lazy unmounted successfully", zap.String("path", path)) } } else { - klog.Infof("Unmounted %s with standard unmount successfully", path) + log.Info("Unmounted with standard unmount successfully", zap.String("path", path)) } } // as fuse quits immediately, we will try to wait until the process is done - process, err := findFuseMountProcess(path) + process, err := findFuseMountProcess(log, path) if err != nil { - klog.Infof("Error getting PID of fuse mount: %s", err) + log.Info("Error getting PID of fuse mount", zap.Error(err)) return nil } if process == nil { - klog.Infof("Unable to find PID of fuse mount %s, it must have finished already", path) + log.Info("Unable to find PID of fuse mount, it must have finished already", + zap.String("path", path)) return nil } - klog.Infof("Found fuse pid %v of mount %s, checking if it still runs", process.Pid, path) + log.Info("Found fuse pid of mount, checking if it still runs", + zap.Int("pid", process.Pid), + zap.String("path", path)) - err = waitForProcess(process, 1) + err = waitForProcess(log, process, 1) if errors.Is(err, ErrTimeoutWaitProcess) { - klog.Infof("timeout waiting for pid %d to end, killing process", process.Pid) + log.Info("Timeout waiting for pid to end, killing process", + zap.Int("pid", process.Pid)) return process.Kill() } return err } -func isMountpoint(pathname string) (bool, error) { - klog.Infof("Checking if path is mountpoint: Pathname - %s", pathname) +func isMountpoint(log *zap.Logger, pathname string) (bool, error) { + log.Info("Checking if path is mountpoint", zap.String("pathname", pathname)) out, err := exec.Command("mountpoint", pathname).CombinedOutput() outStr := strings.ToLower(strings.TrimSpace(string(out))) - klog.Infof("mountpoint status for path '%s', error: %v, output: %s", pathname, err, string(out)) + log.Info("Mountpoint status", + zap.String("path", pathname), + zap.Error(err), + zap.String("output", string(out))) if err != nil { if strings.HasSuffix(outStr, "transport endpoint is not connected") { return true, nil } if strings.HasSuffix(outStr, "is not a mountpoint") { - klog.Infof("Path is NOT a mountpoint: pathname - %s", pathname) + log.Info("Path is NOT a mountpoint", zap.String("pathname", pathname)) return false, nil } - klog.Errorf("Failed to check mountpoint for path '%s', error: %v, output: %s", pathname, err, string(out)) + log.Error("Failed to check mountpoint for path", + zap.String("path", pathname), + zap.Error(err), + zap.String("output", string(out))) return false, fmt.Errorf("failed to check mountpoint for path '%s', error: %v, output: %s", pathname, err, string(out)) } if strings.HasSuffix(outStr, "is a mountpoint") { - klog.Infof("Path is a mountpoint: pathname - %s", pathname) + log.Info("Path is a mountpoint", zap.String("pathname", pathname)) return true, nil } return false, nil } -func waitForMount(ctx context.Context, path string, initialDelay, timeout time.Duration) error { +func waitForMount(ctx context.Context, log *zap.Logger, path string, initialDelay, timeout time.Duration) error { if initialDelay > 0 { time.Sleep(initialDelay) } @@ -180,16 +250,21 @@ func waitForMount(ctx context.Context, path string, initialDelay, timeout time.D select { case <-ctx.Done(): err := ctx.Err() - klog.Infof("waitForMount: context is done, error: %v", err) + log.Info("waitForMount: context is done", zap.Error(err)) return err default: isMount, err := k8sMountUtils.New("").IsMountPoint(path) if err == nil && isMount { - klog.Infof("Path is a mountpoint: pathname: %s", path) + log.Info("Path is a mountpoint", zap.String("pathname", path)) return nil } - klog.Infof("Mountpoint check in progress: attempt=%d, path=%s, isMount=%v, err=%v, timeout=%v", attempt, path, isMount, err, timeout) + log.Info("Mountpoint check in progress", + zap.Int("attempt", attempt), + zap.String("path", path), + zap.Bool("is_mount", isMount), + zap.Error(err), + zap.Duration("timeout", timeout)) time.Sleep(constants.Interval) elapsed += constants.Interval if elapsed >= timeout { @@ -200,7 +275,7 @@ func waitForMount(ctx context.Context, path string, initialDelay, timeout time.D } } -func findFuseMountProcess(path string) (*os.Process, error) { +func findFuseMountProcess(log *zap.Logger, path string) (*os.Process, error) { processes, err := ps.Processes() if err != nil { return nil, err @@ -208,11 +283,15 @@ func findFuseMountProcess(path string) (*os.Process, error) { for _, p := range processes { cmdLine, err := getCmdLine(p.Pid()) if err != nil { - klog.Errorf("Unable to get cmdline of PID %v: %s", p.Pid(), err) + log.Error("Unable to get cmdline of PID", + zap.Int("pid", p.Pid()), + zap.Error(err)) continue } if strings.Contains(cmdLine, path) { - klog.Infof("Found matching pid %v on path %s", p.Pid(), path) + log.Info("Found matching pid on path", + zap.Int("pid", p.Pid()), + zap.String("path", path)) return os.FindProcess(p.Pid()) } } @@ -228,28 +307,33 @@ func getCmdLine(pid int) (string, error) { return string(cmdLine), nil } -func waitForProcess(p *os.Process, backoff int) error { +func waitForProcess(log *zap.Logger, p *os.Process, backoff int) error { // totally it waits 60 seconds before force killing the process if backoff == 120 { return ErrTimeoutWaitProcess } cmdLine, err := getCmdLine(p.Pid) if err != nil { - klog.Warningf("Error checking cmdline of PID %v, assuming it is dead: %s", p.Pid, err) + log.Warn("Error checking cmdline of PID, assuming it is dead", + zap.Int("pid", p.Pid), + zap.Error(err)) return nil } if cmdLine == "" { // ignore defunct processes // TODO: debug why this happens in the first place // seems to only happen on k8s, not on local docker - klog.Warning("Fuse process seems dead, returning") + log.Warn("Fuse process seems dead, returning") return nil } if err := p.Signal(syscall.Signal(0)); err != nil { - klog.Warningf("Fuse process does not seem active or we are unprivileged: %s", err) + log.Warn("Fuse process does not seem active or we are unprivileged", + zap.Error(err)) return nil } - klog.Infof("Fuse process with PID %v still active, waiting... %v", p.Pid, backoff) + log.Info("Fuse process still active, waiting", + zap.Int("pid", p.Pid), + zap.Int("backoff", backoff)) time.Sleep(time.Duration(500) * time.Millisecond) - return waitForProcess(p, backoff+1) + return waitForProcess(log, p, backoff+1) } diff --git a/pkg/mounter/utils/mounter_utils_stub.go b/pkg/mounter/utils/mounter_utils_stub.go new file mode 100644 index 00000000..5c88eb3e --- /dev/null +++ b/pkg/mounter/utils/mounter_utils_stub.go @@ -0,0 +1,24 @@ +//go:build !linux +// +build !linux + +package utils + +import ( + "context" + "fmt" +) + +type MounterUtils interface { + FuseUnmount(ctx context.Context, path string) error + FuseMount(ctx context.Context, path string, comm string, args []string) error +} + +type MounterOptsUtils struct{} + +func (su *MounterOptsUtils) FuseMount(ctx context.Context, path string, comm string, args []string) error { + return fmt.Errorf("FuseMount not supported on this platform") +} + +func (su *MounterOptsUtils) FuseUnmount(ctx context.Context, path string) error { + return fmt.Errorf("FuseUnmount not supported on this platform") +} diff --git a/pkg/requestid/requestid.go b/pkg/requestid/requestid.go new file mode 100644 index 00000000..e5fe8876 --- /dev/null +++ b/pkg/requestid/requestid.go @@ -0,0 +1,77 @@ +/******************************************************************************* + * IBM Confidential + * OCO Source Materials + * IBM Cloud Kubernetes Service, 5737-D43 + * (C) Copyright IBM Corp. 2023 All Rights Reserved. + * The source code for this program is not published or otherwise divested of + * its trade secrets, irrespective of what has been deposited with + * the U.S. Copyright Office. + ******************************************************************************/ + +// Package requestid provides utilities for generating and managing request IDs +// throughout the CSI driver lifecycle for better debugging and log correlation. +package requestid + +import ( + "context" + + "github.com/google/uuid" +) + +// ContextKey is a custom type for context keys to avoid collisions +type ContextKey string + +const ( + // RequestIDKey is the context key for storing request IDs + RequestIDKey ContextKey = "request-id" +) + +// Generate creates a new UUID v4 request ID +func Generate() string { + return uuid.New().String() +} + +// WithRequestID adds a request ID to the context +func WithRequestID(ctx context.Context, requestID string) context.Context { + if requestID == "" { + requestID = Generate() + } + return context.WithValue(ctx, RequestIDKey, requestID) +} + +// FromContext extracts the request ID from context +// Returns empty string if no request ID is found +func FromContext(ctx context.Context) string { + if ctx == nil { + return "" + } + if requestID, ok := ctx.Value(RequestIDKey).(string); ok { + return requestID + } + return "" +} + +// GetOrGenerate gets the request ID from context or generates a new one +// Returns the updated context and the request ID +func GetOrGenerate(ctx context.Context) (context.Context, string) { + if ctx == nil { + ctx = context.Background() + } + + requestID := FromContext(ctx) + if requestID == "" { + requestID = Generate() + ctx = WithRequestID(ctx, requestID) + } + return ctx, requestID +} + +// MustGet extracts request ID from context, panics if not found +// This should only be used in scenarios where request ID is guaranteed to exist +func MustGet(ctx context.Context) string { + requestID := FromContext(ctx) + if requestID == "" { + panic("request ID not found in context") + } + return requestID +} diff --git a/pkg/requestid/requestid_test.go b/pkg/requestid/requestid_test.go new file mode 100644 index 00000000..d430b20a --- /dev/null +++ b/pkg/requestid/requestid_test.go @@ -0,0 +1,126 @@ +/******************************************************************************* + * IBM Confidential + * OCO Source Materials + * IBM Cloud Kubernetes Service, 5737-D43 + * (C) Copyright IBM Corp. 2023 All Rights Reserved. + * The source code for this program is not published or otherwise divested of + * its trade secrets, irrespective of what has been deposited with + * the U.S. Copyright Office. + ******************************************************************************/ + +package requestid + +import ( + "context" + "testing" + + "github.com/google/uuid" + "github.com/stretchr/testify/assert" +) + +func TestGenerate(t *testing.T) { + requestID := Generate() + assert.NotEmpty(t, requestID) + + // Verify it's a valid UUID + _, err := uuid.Parse(requestID) + assert.NoError(t, err) + + // Verify uniqueness + requestID2 := Generate() + assert.NotEqual(t, requestID, requestID2) +} + +func TestWithRequestID(t *testing.T) { + ctx := context.Background() + testID := "test-request-id-123" + + ctx = WithRequestID(ctx, testID) + retrievedID := FromContext(ctx) + + assert.Equal(t, testID, retrievedID) +} + +func TestWithRequestIDEmpty(t *testing.T) { + ctx := context.Background() + + // Empty string should generate a new ID + ctx = WithRequestID(ctx, "") + retrievedID := FromContext(ctx) + + assert.NotEmpty(t, retrievedID) + _, err := uuid.Parse(retrievedID) + assert.NoError(t, err) +} + +func TestFromContext(t *testing.T) { + t.Run("with request ID", func(t *testing.T) { + ctx := context.Background() + testID := "test-id-456" + ctx = WithRequestID(ctx, testID) + + retrievedID := FromContext(ctx) + assert.Equal(t, testID, retrievedID) + }) + + t.Run("without request ID", func(t *testing.T) { + ctx := context.Background() + retrievedID := FromContext(ctx) + assert.Empty(t, retrievedID) + }) + + t.Run("nil context", func(t *testing.T) { + retrievedID := FromContext(context.TODO()) + assert.Empty(t, retrievedID) + }) +} + +func TestGetOrGenerate(t *testing.T) { + t.Run("existing request ID", func(t *testing.T) { + ctx := context.Background() + existingID := "existing-id-789" + ctx = WithRequestID(ctx, existingID) + + newCtx, requestID := GetOrGenerate(ctx) + assert.Equal(t, existingID, requestID) + assert.Equal(t, existingID, FromContext(newCtx)) + }) + + t.Run("no existing request ID", func(t *testing.T) { + ctx := context.Background() + + newCtx, requestID := GetOrGenerate(ctx) + assert.NotEmpty(t, requestID) + assert.Equal(t, requestID, FromContext(newCtx)) + + // Verify it's a valid UUID + _, err := uuid.Parse(requestID) + assert.NoError(t, err) + }) + + t.Run("nil context", func(t *testing.T) { + newCtx, requestID := GetOrGenerate(context.TODO()) + assert.NotNil(t, newCtx) + assert.NotEmpty(t, requestID) + assert.Equal(t, requestID, FromContext(newCtx)) + }) +} + +func TestMustGet(t *testing.T) { + t.Run("with request ID", func(t *testing.T) { + ctx := context.Background() + testID := "must-get-test-id" + ctx = WithRequestID(ctx, testID) + + retrievedID := MustGet(ctx) + assert.Equal(t, testID, retrievedID) + }) + + t.Run("without request ID panics", func(t *testing.T) { + ctx := context.Background() + + assert.Panics(t, func() { + MustGet(ctx) + }) + }) +} diff --git a/pkg/s3client/fake_s3client.go b/pkg/s3client/fake_s3client.go index 99e41a87..7499269b 100644 --- a/pkg/s3client/fake_s3client.go +++ b/pkg/s3client/fake_s3client.go @@ -1,6 +1,7 @@ package s3client import ( + "context" "errors" "go.uber.org/zap" @@ -26,39 +27,39 @@ func (f *FakeCOSSessionFactory) NewObjectStorageSession(endpoint, region string, } } -func (s *fakeCOSSession) CheckBucketAccess(bucket string) error { +func (s *fakeCOSSession) CheckBucketAccess(ctx context.Context, bucket string) error { if s.factory.FailCheckBucketAccess { return errors.New("failed to check bucket access") } return nil } -func (s *fakeCOSSession) SetBucketVersioning(bucket string, enable bool) error { +func (s *fakeCOSSession) SetBucketVersioning(ctx context.Context, bucket string, enable bool) error { if s.factory.FailBucketVersioning { return errors.New("failed to set bucket versioning") } return nil } -func (s *fakeCOSSession) CheckObjectPathExistence(bucket, objectpath string) (bool, error) { +func (s *fakeCOSSession) CheckObjectPathExistence(ctx context.Context, bucket, objectpath string) (bool, error) { return true, nil } -func (s *fakeCOSSession) CreateBucket(bucket, kpRootKeyCrn string) (string, error) { +func (s *fakeCOSSession) CreateBucket(ctx context.Context, bucket, kpRootKeyCrn string) (string, error) { if s.factory.FailCreateBucket { return "", errors.New("failed to create bucket") } return "", nil } -func (s *fakeCOSSession) DeleteBucket(bucket string) error { +func (s *fakeCOSSession) DeleteBucket(ctx context.Context, bucket string) error { if s.factory.FailDeleteBucket { return errors.New("failed to delete bucket") } return nil } -func (s *fakeCOSSession) UpdateQuotaLimit(quota int64, apiKey, bucketName, cosEndpoint, iamEndpoint string) error { +func (s *fakeCOSSession) UpdateQuotaLimit(ctx context.Context, quota int64, apiKey, bucketName, cosEndpoint, iamEndpoint string) error { if s.factory.FailUpdateQuotaLimit { return errors.New("failed to update quota limit") } diff --git a/pkg/s3client/s3client.go b/pkg/s3client/s3client.go index da87399e..5040df17 100644 --- a/pkg/s3client/s3client.go +++ b/pkg/s3client/s3client.go @@ -17,6 +17,7 @@ package s3client import ( + "context" "fmt" "strings" @@ -29,6 +30,7 @@ import ( "github.com/IBM/ibm-cos-sdk-go/aws/session" "github.com/IBM/ibm-cos-sdk-go/service/s3" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/requestid" "go.uber.org/zap" ) @@ -53,20 +55,20 @@ type ObjectStorageCredentials struct { // ObjectStorageSession is an interface of an object store session type ObjectStorageSession interface { // CheckBucketAccess method check that a bucket can be accessed - CheckBucketAccess(bucket string) error + CheckBucketAccess(ctx context.Context, bucket string) error // CheckObjectPathExistence method checks that object-path exists inside bucket - CheckObjectPathExistence(bucket, objectpath string) (bool, error) + CheckObjectPathExistence(ctx context.Context, bucket, objectpath string) (bool, error) // CreateBucket methods creates a new bucket - CreateBucket(bucket, kpRootKeyCrn string) (string, error) + CreateBucket(ctx context.Context, bucket, kpRootKeyCrn string) (string, error) // DeleteBucket methods deletes a bucket (with all of its objects) - DeleteBucket(bucket string) error + DeleteBucket(ctx context.Context, bucket string) error - SetBucketVersioning(bucket string, enable bool) error + SetBucketVersioning(ctx context.Context, bucket string, enable bool) error - UpdateQuotaLimit(quota int64, apiKey, bucketName, cosEndpoint, iamEndpoint string) error + UpdateQuotaLimit(ctx context.Context, quota int64, apiKey, bucketName, cosEndpoint, iamEndpoint string) error } // COSSessionFactory represents a COS (S3) session factory @@ -115,80 +117,115 @@ func (f *defaultRCClientFactory) NewResourceConfigurationV1(options *rc.Resource return rc.NewResourceConfigurationV1(options) } -func (s *COSSession) CheckBucketAccess(bucket string) error { +func (s *COSSession) CheckBucketAccess(ctx context.Context, bucket string) error { + reqID := requestid.FromContext(ctx) + log := s.logger.With(zap.String("request_id", reqID)) + + log.Info("CheckBucketAccess started", zap.String("bucket", bucket)) _, err := s.svc.HeadBucket(&s3.HeadBucketInput{ Bucket: aws.String(bucket), }) + if err != nil { + log.Error("CheckBucketAccess failed", zap.String("bucket", bucket), zap.Error(err)) + } else { + log.Info("CheckBucketAccess completed", zap.String("bucket", bucket)) + } return err } -func (s *COSSession) CheckObjectPathExistence(bucket string, objectpath string) (bool, error) { - s.logger.Info("CheckObjectPathExistence args", zap.String("bucket", bucket), zap.String("objectpath", objectpath)) +func (s *COSSession) CheckObjectPathExistence(ctx context.Context, bucket string, objectpath string) (bool, error) { + reqID := requestid.FromContext(ctx) + log := s.logger.With(zap.String("request_id", reqID)) + + log.Info("CheckObjectPathExistence started", + zap.String("bucket", bucket), zap.String("objectpath", objectpath)) + objectpath = strings.TrimPrefix(objectpath, "/") if !strings.HasSuffix(objectpath, "/") { objectpath = objectpath + "/" } + resp, err := s.svc.ListObjectsV2(&s3.ListObjectsV2Input{ Bucket: aws.String(bucket), MaxKeys: aws.Int64(1), Prefix: aws.String(objectpath), }) if err != nil { - s.logger.Error("cannot list bucket", zap.String("bucket", bucket)) + log.Error("Cannot list bucket", zap.String("bucket", bucket), zap.Error(err)) return false, fmt.Errorf("cannot list bucket '%s': %v", bucket, err) } + + exists := false if len(resp.Contents) == 1 { object := *(resp.Contents[0].Key) if (object == objectpath) || (strings.TrimSuffix(object, "/") == objectpath) { - return true, nil + exists = true } } - return false, nil + + log.Info("CheckObjectPathExistence completed", + zap.String("bucket", bucket), zap.String("objectpath", objectpath), zap.Bool("exists", exists)) + return exists, nil } -func (s *COSSession) CreateBucket(bucket, kpRootKeyCrn string) (res string, err error) { +func (s *COSSession) CreateBucket(ctx context.Context, bucket, kpRootKeyCrn string) (res string, err error) { + reqID := requestid.FromContext(ctx) + log := s.logger.With(zap.String("request_id", reqID)) + + log.Info("CreateBucket started", + zap.String("bucket", bucket), + zap.Bool("encryption_enabled", kpRootKeyCrn != "")) + if kpRootKeyCrn != "" { + log.Debug("Creating bucket with KP encryption", zap.String("bucket", bucket)) _, err = s.svc.CreateBucket(&s3.CreateBucketInput{ Bucket: aws.String(bucket), IBMSSEKPCustomerRootKeyCrn: aws.String(kpRootKeyCrn), IBMSSEKPEncryptionAlgorithm: aws.String(constants.KPEncryptionAlgorithm), }) } else { + log.Debug("Creating bucket without encryption", zap.String("bucket", bucket)) _, err = s.svc.CreateBucket(&s3.CreateBucketInput{ Bucket: aws.String(bucket), }) } if err != nil { - // TODO - // CreateVolume: Unable to create the bucket: %BucketAlreadyExists: - // The requested bucket name is not available. The bucket namespace is shared by all users of the system. - // Please select a different name and try again. - if aerr, ok := err.(awserr.Error); ok && aerr.Code() == "BucketAlreadyOwnedByYou" { - s.logger.Warn("bucket already exists", zap.String("bucket", bucket)) + log.Warn("Bucket already exists", zap.String("bucket", bucket)) return fmt.Sprintf("bucket '%s' already exists", bucket), nil } + log.Error("CreateBucket failed", zap.String("bucket", bucket), zap.Error(err)) return "", err } + log.Info("CreateBucket completed successfully", zap.String("bucket", bucket)) return "", nil } -func (s *COSSession) DeleteBucket(bucket string) error { +func (s *COSSession) DeleteBucket(ctx context.Context, bucket string) error { + reqID := requestid.FromContext(ctx) + log := s.logger.With(zap.String("request_id", reqID)) + + log.Info("DeleteBucket started", zap.String("bucket", bucket)) + resp, err := s.svc.ListObjects(&s3.ListObjectsInput{ Bucket: aws.String(bucket), }) if err != nil { if aerr, ok := err.(awserr.Error); ok && aerr.Code() == "NoSuchBucket" { - s.logger.Warn("bucket already deleted", zap.String("bucket", bucket)) + log.Warn("Bucket already deleted", zap.String("bucket", bucket)) return nil } - + log.Error("Cannot list bucket", zap.String("bucket", bucket), zap.Error(err)) return fmt.Errorf("cannot list bucket '%s': %v", bucket, err) } + objectCount := len(resp.Contents) + log.Info("Deleting objects from bucket", + zap.String("bucket", bucket), zap.Int("object_count", objectCount)) + for _, key := range resp.Contents { _, err = s.svc.DeleteObject(&s3.DeleteObjectInput{ Bucket: aws.String(bucket), @@ -196,23 +233,37 @@ func (s *COSSession) DeleteBucket(bucket string) error { }) if err != nil { + log.Error("Cannot delete object", + zap.String("bucket", bucket), zap.String("key", *key.Key), zap.Error(err)) return fmt.Errorf("cannot delete object %s/%s: %v", bucket, *key.Key, err) } } + log.Info("Deleting bucket", zap.String("bucket", bucket)) _, err = s.svc.DeleteBucket(&s3.DeleteBucketInput{ Bucket: aws.String(bucket), }) + if err != nil { + log.Error("DeleteBucket failed", zap.String("bucket", bucket), zap.Error(err)) + } else { + log.Info("DeleteBucket completed successfully", zap.String("bucket", bucket)) + } return err } -func (s *COSSession) SetBucketVersioning(bucket string, enable bool) error { +func (s *COSSession) SetBucketVersioning(ctx context.Context, bucket string, enable bool) error { + reqID := requestid.FromContext(ctx) + log := s.logger.With(zap.String("request_id", reqID)) + status := s3.BucketVersioningStatusSuspended if enable { status = s3.BucketVersioningStatusEnabled } - s.logger.Info("Setting versioning for bucket", zap.String("bucket", bucket), zap.Bool("enable", enable)) + + log.Info("SetBucketVersioning started", + zap.String("bucket", bucket), zap.Bool("enable", enable)) + _, err := s.svc.PutBucketVersioning(&s3.PutBucketVersioningInput{ Bucket: aws.String(bucket), VersioningConfiguration: &s3.VersioningConfiguration{ @@ -220,10 +271,13 @@ func (s *COSSession) SetBucketVersioning(bucket string, enable bool) error { }, }) if err != nil { - s.logger.Error("Failed to set versioning", zap.String("bucket", bucket), zap.Bool("enable", enable), zap.Error(err)) + log.Error("SetBucketVersioning failed", + zap.String("bucket", bucket), zap.Bool("enable", enable), zap.Error(err)) return fmt.Errorf("failed to set versioning to %v for bucket '%s': %v", enable, bucket, err) } - s.logger.Info("Versioning set successfully for bucket", zap.String("bucket", bucket), zap.Bool("enable", enable)) + + log.Info("SetBucketVersioning completed successfully", + zap.String("bucket", bucket), zap.Bool("enable", enable)) return nil } @@ -256,12 +310,20 @@ func (s *COSSessionFactory) NewObjectStorageSession(endpoint, locationConstraint } } -func (s *COSSession) UpdateQuotaLimit(quota int64, apiKey, bucketName, cosEndpoint, iamEndpoint string) error { +func (s *COSSession) UpdateQuotaLimit(ctx context.Context, quota int64, apiKey, bucketName, cosEndpoint, iamEndpoint string) error { + reqID := requestid.FromContext(ctx) + log := s.logger.With(zap.String("request_id", reqID)) + + log.Info("UpdateQuotaLimit started", + zap.String("bucket", bucketName), zap.Int64("quota", quota)) + var configEndpoint string if strings.Contains(strings.ToLower(cosEndpoint), "private") { configEndpoint = constants.ResourceConfigEPPrivate + log.Debug("Using private resource config endpoint") } else { configEndpoint = constants.ResourceConfigEPDirect + log.Debug("Using direct resource config endpoint") } iamTokenURL := iamEndpoint + "/identity/token" @@ -271,11 +333,13 @@ func (s *COSSession) UpdateQuotaLimit(quota int64, apiKey, bucketName, cosEndpoi URL: iamTokenURL, } + log.Debug("Creating resource configuration service") service, err := s.rcClientFactory.NewResourceConfigurationV1(&rc.ResourceConfigurationV1Options{ Authenticator: authenticator, URL: configEndpoint, }) if err != nil { + log.Error("Failed to create resource configuration service", zap.Error(err)) return fmt.Errorf("failed to create resource configuration service: %w", err) } @@ -287,10 +351,16 @@ func (s *COSSession) UpdateQuotaLimit(quota int64, apiKey, bucketName, cosEndpoi BucketPatch: bucketPatch, } + log.Info("Updating bucket quota", + zap.String("bucket", bucketName), zap.Int64("quota", quota)) _, err = service.UpdateBucketConfig(options) if err != nil { + log.Error("Failed to update quota", + zap.String("bucket", bucketName), zap.Int64("quota", quota), zap.Error(err)) return fmt.Errorf("failed to update quota for bucket %s to %d bytes: %w", bucketName, quota, err) } + log.Info("UpdateQuotaLimit completed successfully", + zap.String("bucket", bucketName), zap.Int64("quota", quota)) return nil } diff --git a/pkg/s3client/s3client_test.go b/pkg/s3client/s3client_test.go index ab3e0057..212de048 100644 --- a/pkg/s3client/s3client_test.go +++ b/pkg/s3client/s3client_test.go @@ -1,6 +1,7 @@ package s3client import ( + "context" "errors" "strings" "testing" @@ -126,14 +127,14 @@ func Test_NewObjectStorageIAMSession_Positive(t *testing.T) { func Test_CheckBucketAccess_Error(t *testing.T) { sess := getSession(&fakeS3API{ErrHeadBucket: errFoo}) - err := sess.CheckBucketAccess(testBucket) + err := sess.CheckBucketAccess(context.Background(), testBucket) assert.Error(t, err) assert.EqualError(t, err, errFooMsg) } func Test_CheckBucketAccess_Positive(t *testing.T) { sess := getSession(&fakeS3API{}) - err := sess.CheckBucketAccess(testBucket) + err := sess.CheckBucketAccess(context.Background(), testBucket) assert.NoError(t, err) } @@ -141,7 +142,7 @@ func Test_CheckObjectPathExistence_Positive(t *testing.T) { testObject = strings.TrimPrefix(testObjectPath, "/") testObject = testObject + "/" sess := getSession(&fakeS3API{ObjectPath: testObject}) - exist, err := sess.CheckObjectPathExistence(testBucket, testObjectPath) + exist, err := sess.CheckObjectPathExistence(context.Background(), testBucket, testObjectPath) assert.NoError(t, err) assert.Equal(t, exist, true) } @@ -149,7 +150,7 @@ func Test_CheckObjectPathExistence_Positive(t *testing.T) { func Test_CheckObjectPathExistence_WithoutSuffix(t *testing.T) { testObject = strings.TrimPrefix(testObjectPath, "/") sess := getSession(&fakeS3API{ObjectPath: testObject}) - exist, err := sess.CheckObjectPathExistence(testBucket, testObjectPath) + exist, err := sess.CheckObjectPathExistence(context.Background(), testBucket, testObjectPath) assert.NoError(t, err) assert.Equal(t, exist, false) } @@ -157,14 +158,14 @@ func Test_CheckObjectPathExistence_WithoutSuffix(t *testing.T) { func Test_CheckObjectPathExistence_PathNotFound(t *testing.T) { sess := getSession(&fakeS3API{ObjectPath: "test/object-path-xxxx"}) testObject = "test/object-path-xxxx" - exist, err := sess.CheckObjectPathExistence(testBucket, testObjectPath) + exist, err := sess.CheckObjectPathExistence(context.Background(), testBucket, testObjectPath) assert.NoError(t, err) assert.Equal(t, exist, false) } func Test_CheckObjectPathExistence_Error(t *testing.T) { sess := getSession(&fakeS3API{ErrListObjectsV2: errFoo}) - _, err := sess.CheckObjectPathExistence(testBucket, testObjectPath) + _, err := sess.CheckObjectPathExistence(context.Background(), testBucket, testObjectPath) if assert.Error(t, err) { assert.Contains(t, err.Error(), "cannot list bucket") } @@ -172,7 +173,7 @@ func Test_CheckObjectPathExistence_Error(t *testing.T) { func Test_CreateBucketAccess_Error(t *testing.T) { sess := getSession(&fakeS3API{ErrCreateBucket: errFoo}) - _, err := sess.CreateBucket(testBucket, testKpRootKeyCrn) + _, err := sess.CreateBucket(context.Background(), testBucket, testKpRootKeyCrn) if assert.Error(t, err) { assert.EqualError(t, err, errFooMsg) } @@ -180,31 +181,31 @@ func Test_CreateBucketAccess_Error(t *testing.T) { func Test_CreateBucketAccess_BucketAlreadyExists_Positive(t *testing.T) { sess := getSession(&fakeS3API{ErrCreateBucket: awserr.New("BucketAlreadyOwnedByYou", "", errFoo)}) - _, err := sess.CreateBucket(testBucket, testKpRootKeyCrn) + _, err := sess.CreateBucket(context.Background(), testBucket, testKpRootKeyCrn) assert.NoError(t, err) } func Test_CreateBucket_Positive(t *testing.T) { sess := getSession(&fakeS3API{}) - _, err := sess.CreateBucket(testBucket, testKpRootKeyCrn) + _, err := sess.CreateBucket(context.Background(), testBucket, testKpRootKeyCrn) assert.NoError(t, err) } func Test_SetBucketVersioning_True_Positive(t *testing.T) { sess := getSession(&fakeS3API{}) - err := sess.SetBucketVersioning(testBucket, true) + err := sess.SetBucketVersioning(context.Background(), testBucket, true) assert.NoError(t, err) } func Test_SetBucketVersioning_False_Positive(t *testing.T) { sess := getSession(&fakeS3API{}) - err := sess.SetBucketVersioning(testBucket, false) + err := sess.SetBucketVersioning(context.Background(), testBucket, false) assert.NoError(t, err) } func Test_SetBucketVersioning_Error(t *testing.T) { sess := getSession(&fakeS3API{ErrPutBucketVersioning: errFoo}) - err := sess.SetBucketVersioning(testBucket, true) + err := sess.SetBucketVersioning(context.Background(), testBucket, true) if assert.Error(t, err) { assert.EqualError(t, err, "failed to set versioning to true for bucket 'test-bucket': foo") } @@ -212,13 +213,13 @@ func Test_SetBucketVersioning_Error(t *testing.T) { func Test_DeleteBucket_BucketAlreadyDeleted_Positive(t *testing.T) { sess := getSession(&fakeS3API{ErrListObjects: awserr.New("NoSuchBucket", "", errFoo)}) - err := sess.DeleteBucket(testBucket) + err := sess.DeleteBucket(context.Background(), testBucket) assert.NoError(t, err) } func Test_DeleteBucket_ListObjectsError(t *testing.T) { sess := getSession(&fakeS3API{ErrListObjects: errFoo}) - err := sess.DeleteBucket(testBucket) + err := sess.DeleteBucket(context.Background(), testBucket) if assert.Error(t, err) { assert.Contains(t, err.Error(), "cannot list bucket") } @@ -226,7 +227,7 @@ func Test_DeleteBucket_ListObjectsError(t *testing.T) { func Test_DeleteBucket_DeleteObjectError(t *testing.T) { sess := getSession(&fakeS3API{ErrDeleteObject: errFoo}) - err := sess.DeleteBucket(testBucket) + err := sess.DeleteBucket(context.Background(), testBucket) if assert.Error(t, err) { assert.Contains(t, err.Error(), "cannot delete object") } @@ -234,7 +235,7 @@ func Test_DeleteBucket_DeleteObjectError(t *testing.T) { func Test_DeleteBucket_Error(t *testing.T) { sess := getSession(&fakeS3API{ErrDeleteBucket: errFoo}) - err := sess.DeleteBucket(testBucket) + err := sess.DeleteBucket(context.Background(), testBucket) if assert.Error(t, err) { assert.EqualError(t, err, errFooMsg) } @@ -242,7 +243,7 @@ func Test_DeleteBucket_Error(t *testing.T) { func Test_DeleteBucket_Positive(t *testing.T) { sess := getSession(&fakeS3API{}) - err := sess.DeleteBucket(testBucket) + err := sess.DeleteBucket(context.Background(), testBucket) assert.NoError(t, err) } @@ -251,7 +252,7 @@ func Test_UpdateQuotaLimit_Positive(t *testing.T) { ReturnClient: &fakeRCAPI{}, } sess := getSessionWithRCFactory(&fakeS3API{}, factory) - err := sess.UpdateQuotaLimit(1073741824, testAPIKey, testBucket, testEndpoint, testIAMEndpoint) + err := sess.UpdateQuotaLimit(context.Background(), 1073741824, testAPIKey, testBucket, testEndpoint, testIAMEndpoint) assert.NoError(t, err) } @@ -260,7 +261,7 @@ func Test_UpdateQuotaLimit_ClientCreationError(t *testing.T) { ErrNewClient: errFoo, } sess := getSessionWithRCFactory(&fakeS3API{}, factory) - err := sess.UpdateQuotaLimit(1073741824, testAPIKey, testBucket, testEndpoint, testIAMEndpoint) + err := sess.UpdateQuotaLimit(context.Background(), 1073741824, testAPIKey, testBucket, testEndpoint, testIAMEndpoint) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to create resource configuration service") } @@ -270,7 +271,7 @@ func Test_UpdateQuotaLimit_UpdateError(t *testing.T) { ReturnClient: &fakeRCAPI{ErrUpdateBucketConfig: errFoo}, } sess := getSessionWithRCFactory(&fakeS3API{}, factory) - err := sess.UpdateQuotaLimit(1073741824, testAPIKey, testBucket, testEndpoint, testIAMEndpoint) + err := sess.UpdateQuotaLimit(context.Background(), 1073741824, testAPIKey, testBucket, testEndpoint, testIAMEndpoint) assert.Error(t, err) assert.Contains(t, err.Error(), "failed to update quota for bucket") } @@ -280,6 +281,6 @@ func Test_UpdateQuotaLimit_PrivateEndpoint_Positive(t *testing.T) { ReturnClient: &fakeRCAPI{}, } sess := getSessionWithRCFactory(&fakeS3API{}, factory) - err := sess.UpdateQuotaLimit(1073741824, testAPIKey, testBucket, "https://s3.private.us-south.cloud-object-storage.appdomain.cloud", testIAMEndpoint) + err := sess.UpdateQuotaLimit(context.Background(), 1073741824, testAPIKey, testBucket, "https://s3.private.us-south.cloud-object-storage.appdomain.cloud", testIAMEndpoint) assert.NoError(t, err) } diff --git a/pkg/utils/driver_utils.go b/pkg/utils/driver_utils.go index d88568d5..16272232 100644 --- a/pkg/utils/driver_utils.go +++ b/pkg/utils/driver_utils.go @@ -11,17 +11,25 @@ import ( "github.com/IBM/go-sdk-core/v5/core" rc "github.com/IBM/ibm-cos-sdk-go-config/v2/resourceconfigurationv1" "github.com/IBM/ibm-object-csi-driver/pkg/constants" + "github.com/IBM/ibm-object-csi-driver/pkg/logger" "github.com/container-storage-interface/spec/lib/go/csi" + "go.uber.org/zap" "google.golang.org/protobuf/proto" v1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/resource" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/client-go/kubernetes" "k8s.io/client-go/rest" - "k8s.io/klog/v2" "k8s.io/kubernetes/pkg/volume/util/fs" ) +var utilLogger *zap.Logger + +func init() { + utilLogger = logger.NewJSONLoggerOrNop("ibm-object-csi-driver") + utilLogger = utilLogger.With(zap.String("component", "driver-utils")) +} + type StatsUtils interface { BucketToDelete(volumeID string) (string, error) FSInfo(path string) (int64, int64, int64, int64, int64, int64, error) @@ -93,17 +101,17 @@ func (su *DriverStatsUtils) BucketToDelete(volumeID string) (string, error) { pv, err := clientset.CoreV1().PersistentVolumes().Get(context.Background(), volumeID, metav1.GetOptions{}) if err != nil { - klog.Errorf("Unable to fetch bucket %v", err) + utilLogger.Error("Unable to fetch bucket", zap.Error(err)) return "", err } - klog.Infof("***Attributes: %v", pv.Spec.CSI.VolumeAttributes) + utilLogger.Info("Volume attributes", zap.Any("attributes", pv.Spec.CSI.VolumeAttributes)) if pv.Spec.CSI.VolumeAttributes["userProvidedBucket"] != "true" { - klog.Infof("Bucket will be deleted %v", pv.Spec.CSI.VolumeAttributes["bucketName"]) + utilLogger.Info("Bucket will be deleted", zap.String("bucket_name", pv.Spec.CSI.VolumeAttributes["bucketName"])) return pv.Spec.CSI.VolumeAttributes["bucketName"], nil } - klog.Infof("Bucket will be persisted %v", pv.Spec.CSI.VolumeAttributes["bucketName"]) + utilLogger.Info("Bucket will be persisted", zap.String("bucket_name", pv.Spec.CSI.VolumeAttributes["bucketName"])) return "", nil } @@ -115,10 +123,10 @@ func (su *DriverStatsUtils) CheckMount(targetPath string) error { out, err := exec.Command("mountpoint", targetPath).CombinedOutput() outStr := strings.TrimSpace(string(out)) if err != nil { - klog.V(3).Infof("Check if mountPath exists: Output string- %+v", outStr) + utilLogger.Debug("Check if mountPath exists", zap.String("output", outStr)) if strings.HasSuffix(outStr, "No such file or directory") { if err = os.MkdirAll(targetPath, 0750); err != nil { - klog.V(2).Infof("checkMount: Error: %+v", err) + utilLogger.Debug("checkMount: Error", zap.Error(err)) return err } } else { @@ -161,7 +169,7 @@ func (su *DriverStatsUtils) GetBucketUsage(volumeID string) (int64, error) { } resourceConfig, err := rc.NewResourceConfigurationV1(rcOptions) if err != nil { - klog.Error("Failed to create resource config") + utilLogger.Error("Failed to create resource config") return 0, err } @@ -171,7 +179,7 @@ func (su *DriverStatsUtils) GetBucketUsage(volumeID string) (int64, error) { res, _, err := resourceConfig.GetBucketConfig(bucketOptions) if err != nil { - klog.Error("Failed to get bucket config") + utilLogger.Error("Failed to get bucket config") return 0, err } @@ -205,7 +213,7 @@ func (su *DriverStatsUtils) GetPVC(pvcName, pvcNamespace string) (*v1.Persistent pvc, err := k8sClient.CoreV1().PersistentVolumeClaims(pvcNamespace).Get(context.TODO(), pvcName, metav1.GetOptions{}) if err != nil { - klog.Errorf("Unable to fetch pvc %v", err) + utilLogger.Error("Unable to fetch pvc", zap.Error(err)) return nil, fmt.Errorf("error getting PVC: %v", err) } @@ -234,7 +242,7 @@ func (su *DriverStatsUtils) GetPV(volumeID string) (*v1.PersistentVolume, error) pv, err := k8sClient.CoreV1().PersistentVolumes().Get(context.Background(), volumeID, metav1.GetOptions{}) if err != nil { - klog.Errorf("Unable to fetch pv %v", err) + utilLogger.Error("Unable to fetch pv", zap.Error(err)) return nil, fmt.Errorf("error getting PV: %v", err) } @@ -315,14 +323,14 @@ func CreateK8sClient() (*kubernetes.Clientset, error) { // Create a Kubernetes client configuration config, err := rest.InClusterConfig() if err != nil { - klog.Error("Error creating Kubernetes client configuration: ", err) + utilLogger.Error("Error creating Kubernetes client configuration", zap.Error(err)) return nil, err } // Create a Kubernetes clientset clientset, err := kubernetes.NewForConfig(config) if err != nil { - klog.Error("Error creating Kubernetes clientset: ", err) + utilLogger.Error("Error creating Kubernetes clientset", zap.Error(err)) return nil, err } @@ -348,7 +356,7 @@ func getClusterType() (string, error) { } clusterType := clusterConfig["cluster_type"] - klog.Info("Cluster Type ", clusterType) + utilLogger.Info("Cluster Type", zap.String("cluster_type", clusterType)) return clusterType, nil } @@ -357,7 +365,7 @@ func fetchSecretUsingPV(volumeID string, su *DriverStatsUtils) (*v1.Secret, erro if err != nil { return nil, err } - klog.Info("secret fetched from PV:\n\t", pv.Spec.CSI.NodePublishSecretRef) + utilLogger.Info("Secret fetched from PV", zap.String("secret_name", pv.Spec.CSI.NodePublishSecretRef.Name), zap.String("secret_namespace", pv.Spec.CSI.NodePublishSecretRef.Namespace)) secretName := pv.Spec.CSI.NodePublishSecretRef.Name secretNamespace := pv.Spec.CSI.NodePublishSecretRef.Namespace @@ -367,7 +375,7 @@ func fetchSecretUsingPV(volumeID string, su *DriverStatsUtils) (*v1.Secret, erro } if secretNamespace == "" { - klog.Info("secret Namespace not found. trying to fetch the secret in default namespace") + utilLogger.Info("Secret namespace not found, trying to fetch the secret in default namespace") secretNamespace = constants.DefaultNamespace } @@ -380,7 +388,7 @@ func fetchSecretUsingPV(volumeID string, su *DriverStatsUtils) (*v1.Secret, erro return nil, fmt.Errorf("secret not found with name: %v", secretNamespace) } - klog.Info("secret details found. secretName: ", secret.Name) + utilLogger.Info("Secret details found", zap.String("secret_name", secret.Name)) return secret, nil } diff --git a/tests/sanity/sanity_test.go b/tests/sanity/sanity_test.go index bda70478..cd633395 100644 --- a/tests/sanity/sanity_test.go +++ b/tests/sanity/sanity_test.go @@ -12,6 +12,7 @@ package sanity import ( + "context" "flag" "fmt" "os" @@ -28,13 +29,13 @@ import ( "github.com/google/uuid" "github.com/kubernetes-csi/csi-test/v5/pkg/sanity" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "google.golang.org/grpc" "google.golang.org/grpc/codes" "google.golang.org/grpc/credentials/insecure" "google.golang.org/grpc/status" v1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/resource" - "k8s.io/klog/v2" ) var ( @@ -150,53 +151,63 @@ func (f *FakeObjectStorageSessionFactory) NewObjectStorageSession(endpoint, loca } } -func (s *fakeObjectStorageSession) CheckBucketAccess(bucket string) error { +func (s *fakeObjectStorageSession) CheckBucketAccess(ctx context.Context, bucket string) error { return nil } -func (s *fakeObjectStorageSession) SetBucketVersioning(bucketName string, enable bool) error { +func (s *fakeObjectStorageSession) SetBucketVersioning(ctx context.Context, bucketName string, enable bool) error { s.logger.Info(fmt.Sprintf("Fake SetBucketVersioning called for bucket %s with enable=%t", bucketName, enable)) return nil } -func (s *fakeObjectStorageSession) CheckObjectPathExistence(bucket, objectpath string) (bool, error) { +func (s *fakeObjectStorageSession) CheckObjectPathExistence(ctx context.Context, bucket, objectpath string) (bool, error) { return true, nil } -func (s *fakeObjectStorageSession) CreateBucket(bucket, kpRootKeyCrn string) (string, error) { +func (s *fakeObjectStorageSession) CreateBucket(ctx context.Context, bucket, kpRootKeyCrn string) (string, error) { return "", nil } -func (s *fakeObjectStorageSession) DeleteBucket(bucket string) error { +func (s *fakeObjectStorageSession) DeleteBucket(ctx context.Context, bucket string) error { return nil } -func (s *fakeObjectStorageSession) UpdateQuotaLimit(quota int64, apiKey, bucketName, cosEndpoint, iamEndpoint string) error { +func (s *fakeObjectStorageSession) UpdateQuotaLimit(ctx context.Context, quota int64, apiKey, bucketName, cosEndpoint, iamEndpoint string) error { s.logger.Info(fmt.Sprintf("Fake UpdateQuotaLimit called for bucket %s with quota %d", bucketName, quota)) return nil } // Fake NewMounterFactory -type FakeS3fsMounterFactory struct{} +type FakeS3fsMounterFactory struct { + logger *zap.Logger +} func FakeNewS3fsMounterFactory() *FakeS3fsMounterFactory { - return &FakeS3fsMounterFactory{} + // Create a JSON logger for tests + config := zap.NewProductionConfig() + config.EncoderConfig.TimeKey = "timestamp" + config.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + config.EncoderConfig.EncodeLevel = zapcore.LowercaseLevelEncoder + logger, _ := config.Build() + return &FakeS3fsMounterFactory{logger: logger} } -type Fakes3fsMounter struct{} +type Fakes3fsMounter struct { + logger *zap.Logger +} func (s *FakeS3fsMounterFactory) NewMounter(attrib map[string]string, secretMap map[string]string, mountFlags []string, defaultMOMap map[string]string) mounter.Mounter { - klog.Info("-New S3FS Fake Mounter-") - return &Fakes3fsMounter{} + s.logger.Info("New S3FS Fake Mounter") + return &Fakes3fsMounter{logger: s.logger} } -func (s3fs *Fakes3fsMounter) Mount(source string, target string) error { - klog.Info("-S3FSMounter Mount-") +func (s3fs *Fakes3fsMounter) Mount(ctx context.Context, source string, target string) error { + s3fs.logger.Info("S3FSMounter Mount", zap.String("source", source), zap.String("target", target)) return nil } -func (s3fs *Fakes3fsMounter) Unmount(target string) error { - klog.Info("-S3FSMounter Unmount-") +func (s3fs *Fakes3fsMounter) Unmount(ctx context.Context, target string) error { + s3fs.logger.Info("S3FSMounter Unmount", zap.String("target", target)) return nil } @@ -223,11 +234,11 @@ func (v providerIDGenerator) GenerateUniqueValidVolumeID() string { type FakeNewMounterOptsUtils struct { } -func (su *FakeNewMounterOptsUtils) FuseUnmount(path string) error { +func (su *FakeNewMounterOptsUtils) FuseUnmount(ctx context.Context, path string) error { return nil } -func (m *FakeNewMounterOptsUtils) FuseMount(path string, comm string, args []string) error { +func (m *FakeNewMounterOptsUtils) FuseMount(ctx context.Context, path string, comm string, args []string) error { return nil }