migrating klog to zap logger and adding requestID for tracing

.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

.gitignore

@@ -1,2 +1,3 @@
 .idea
-bin
+bin
+tests

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 <pod-name> -n kube-system | grep "550e8400-e29b-41d4-a716-446655440000"
+
+# Using jq for JSON logs
+kubectl logs <pod-name> -n kube-system | jq 'select(.request_id == "550e8400-...")'
+```
+
+Track complete operation flow:
+```bash
+# Extract request ID from initial log
+REQUEST_ID=$(kubectl logs <pod-name> -n kube-system | \
+  jq -r 'select(.msg | contains("CreateVolume started")) | .request_id' | head -1)
+
+# View all logs for that request
+kubectl logs <pod-name> -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"
+}
+```

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 {

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

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)
 }
 

cos-csi-mounter/server/rclone.go

@@ -1,3 +1,6 @@
+//go:build linux
+// +build linux
+
 package main
 
 import (

cos-csi-mounter/server/rclone_test.go

@@ -1,3 +1,6 @@
+//go:build linux
+// +build linux
+
 package main
 
 import (

cos-csi-mounter/server/s3fs.go

@@ -1,3 +1,6 @@
+//go:build linux
+// +build linux
+
 package main
 
 import (

cos-csi-mounter/server/s3fs_test.go

@@ -1,3 +1,6 @@
+//go:build linux
+// +build linux
+
 package main
 
 import (

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"})
 	}
 }