From 38ca08bf65dc404d8ebf826d688492c72cfc2739 Mon Sep 17 00:00:00 2001 From: Madhu Rajanna Date: Thu, 22 Aug 2019 22:27:23 +0530 Subject: [PATCH] Context based logging for rbd Signed-off-by: Madhu Rajanna --- pkg/csi-common/utils.go | 8 +-- pkg/rbd/controllerserver.go | 114 ++++++++++++++++---------------- pkg/rbd/nodeserver.go | 69 ++++++++++--------- pkg/rbd/rbd_attach.go | 41 ++++++------ pkg/rbd/rbd_journal.go | 21 +++--- pkg/rbd/rbd_util.go | 110 ++++++++++++++++--------------- pkg/util/log.go | 128 ++---------------------------------- 7 files changed, 188 insertions(+), 303 deletions(-) diff --git a/pkg/csi-common/utils.go b/pkg/csi-common/utils.go index 0e1193219..78fdc836f 100644 --- a/pkg/csi-common/utils.go +++ b/pkg/csi-common/utils.go @@ -116,13 +116,13 @@ func contextIDInjector(ctx context.Context, req interface{}, info *grpc.UnarySer } func logGRPC(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { - util.V(3).Infof(ctx, "GRPC call: %s", info.FullMethod) - util.V(5).Infof(ctx, "GRPC request: %s", protosanitizer.StripSecrets(req)) + klog.V(3).Infof(util.Log(ctx, "GRPC call: %s"), info.FullMethod) + klog.V(5).Infof(util.Log(ctx, "GRPC request: %s"), protosanitizer.StripSecrets(req)) resp, err := handler(ctx, req) if err != nil { - util.Errorf(ctx, "GRPC error: %v", err) + klog.Errorf(util.Log(ctx, "GRPC error: %v"), err) } else { - util.V(5).Infof(ctx, "GRPC response: %s", protosanitizer.StripSecrets(resp)) + klog.V(5).Infof(util.Log(ctx, "GRPC response: %s"), protosanitizer.StripSecrets(resp)) } return resp, err } diff --git a/pkg/rbd/controllerserver.go b/pkg/rbd/controllerserver.go index c1b9979b3..1c7fc1577 100644 --- a/pkg/rbd/controllerserver.go +++ b/pkg/rbd/controllerserver.go @@ -41,9 +41,9 @@ type ControllerServer struct { MetadataStore util.CachePersister } -func (cs *ControllerServer) validateVolumeReq(req *csi.CreateVolumeRequest) error { +func (cs *ControllerServer) validateVolumeReq(ctx context.Context, req *csi.CreateVolumeRequest) error { if err := cs.Driver.ValidateControllerServiceRequest(csi.ControllerServiceCapability_RPC_CREATE_DELETE_VOLUME); err != nil { - klog.V(3).Infof("invalid create volume req: %v", protosanitizer.StripSecrets(req)) + klog.V(3).Infof(util.Log(ctx, "invalid create volume req: %v"), protosanitizer.StripSecrets(req)) return err } // Check sanity of request Name, Volume Capabilities @@ -63,7 +63,7 @@ func (cs *ControllerServer) validateVolumeReq(req *csi.CreateVolumeRequest) erro return nil } -func (cs *ControllerServer) parseVolCreateRequest(req *csi.CreateVolumeRequest) (*rbdVolume, error) { +func (cs *ControllerServer) parseVolCreateRequest(ctx context.Context, req *csi.CreateVolumeRequest) (*rbdVolume, error) { // TODO (sbezverk) Last check for not exceeding total storage capacity isMultiNode := false @@ -84,7 +84,7 @@ func (cs *ControllerServer) parseVolCreateRequest(req *csi.CreateVolumeRequest) } // if it's NOT SINGLE_NODE_WRITER and it's BLOCK we'll set the parameter to ignore the in-use checks - rbdVol, err := genVolFromVolumeOptions(req.GetParameters(), nil, (isMultiNode && isBlock), false) + rbdVol, err := genVolFromVolumeOptions(ctx, req.GetParameters(), nil, (isMultiNode && isBlock), false) if err != nil { return nil, status.Error(codes.InvalidArgument, err.Error()) } @@ -108,7 +108,7 @@ func (cs *ControllerServer) parseVolCreateRequest(req *csi.CreateVolumeRequest) // CreateVolume creates the volume in backend func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVolumeRequest) (*csi.CreateVolumeResponse, error) { - if err := cs.validateVolumeReq(req); err != nil { + if err := cs.validateVolumeReq(ctx, req); err != nil { return nil, err } @@ -118,7 +118,7 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol } defer cr.DeleteCredentials() - rbdVol, err := cs.parseVolCreateRequest(req) + rbdVol, err := cs.parseVolCreateRequest(ctx, req) if err != nil { return nil, err } @@ -126,7 +126,7 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol idLk := volumeNameLocker.Lock(req.GetName()) defer volumeNameLocker.Unlock(idLk, req.GetName()) - found, err := checkVolExists(rbdVol, cr) + found, err := checkVolExists(ctx, rbdVol, cr) if err != nil { if _, ok := err.(ErrVolNameConflict); ok { return nil, status.Error(codes.AlreadyExists, err.Error()) @@ -144,7 +144,7 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol }, nil } - err = reserveVol(rbdVol, cr) + err = reserveVol(ctx, rbdVol, cr) if err != nil { return nil, status.Error(codes.Internal, err.Error()) } @@ -152,12 +152,12 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol if err != nil { errDefer := undoVolReservation(rbdVol, cr) if errDefer != nil { - klog.Warningf("failed undoing reservation of volume: %s (%s)", req.GetName(), errDefer) + klog.Warningf(util.Log(ctx, "failed undoing reservation of volume: %s (%s)"), req.GetName(), errDefer) } } }() - err = cs.createBackingImage(rbdVol, req, util.RoundUpToMiB(rbdVol.VolSize)) + err = cs.createBackingImage(ctx, rbdVol, req, util.RoundUpToMiB(rbdVol.VolSize)) if err != nil { return nil, err } @@ -171,12 +171,12 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol }, nil } -func (cs *ControllerServer) createBackingImage(rbdVol *rbdVolume, req *csi.CreateVolumeRequest, volSizeMiB int64) error { +func (cs *ControllerServer) createBackingImage(ctx context.Context, rbdVol *rbdVolume, req *csi.CreateVolumeRequest, volSizeMiB int64) error { var err error // if VolumeContentSource is not nil, this request is for snapshot if req.VolumeContentSource != nil { - if err = cs.checkSnapshot(req, rbdVol); err != nil { + if err = cs.checkSnapshot(ctx, req, rbdVol); err != nil { return err } } else { @@ -186,18 +186,18 @@ func (cs *ControllerServer) createBackingImage(rbdVol *rbdVolume, req *csi.Creat } defer cr.DeleteCredentials() - err = createImage(rbdVol, volSizeMiB, cr) + err = createImage(ctx, rbdVol, volSizeMiB, cr) if err != nil { - klog.Warningf("failed to create volume: %v", err) + klog.Warningf(util.Log(ctx, "failed to create volume: %v"), err) return status.Error(codes.Internal, err.Error()) } - klog.V(4).Infof("created image %s", rbdVol.RbdImageName) + klog.V(4).Infof(util.Log(ctx, "created image %s"), rbdVol.RbdImageName) } return nil } -func (cs *ControllerServer) checkSnapshot(req *csi.CreateVolumeRequest, rbdVol *rbdVolume) error { +func (cs *ControllerServer) checkSnapshot(ctx context.Context, req *csi.CreateVolumeRequest, rbdVol *rbdVolume) error { snapshot := req.VolumeContentSource.GetSnapshot() if snapshot == nil { return status.Error(codes.InvalidArgument, "volume Snapshot cannot be empty") @@ -215,23 +215,23 @@ func (cs *ControllerServer) checkSnapshot(req *csi.CreateVolumeRequest, rbdVol * defer cr.DeleteCredentials() rbdSnap := &rbdSnapshot{} - if err = genSnapFromSnapID(rbdSnap, snapshotID, cr); err != nil { + if err = genSnapFromSnapID(ctx, rbdSnap, snapshotID, cr); err != nil { if _, ok := err.(ErrSnapNotFound); !ok { return status.Error(codes.Internal, err.Error()) } return status.Error(codes.InvalidArgument, "missing requested Snapshot ID") } - err = restoreSnapshot(rbdVol, rbdSnap, cr) + err = restoreSnapshot(ctx, rbdVol, rbdSnap, cr) if err != nil { return status.Error(codes.Internal, err.Error()) } - klog.V(4).Infof("create volume %s from snapshot %s", req.GetName(), rbdSnap.RbdSnapName) + klog.V(4).Infof(util.Log(ctx, "create volume %s from snapshot %s"), req.GetName(), rbdSnap.RbdSnapName) return nil } // DeleteLegacyVolume deletes a volume provisioned using version 1.0.0 of the plugin -func (cs *ControllerServer) DeleteLegacyVolume(req *csi.DeleteVolumeRequest, cr *util.Credentials) (*csi.DeleteVolumeResponse, error) { +func (cs *ControllerServer) DeleteLegacyVolume(ctx context.Context, req *csi.DeleteVolumeRequest, cr *util.Credentials) (*csi.DeleteVolumeResponse, error) { volumeID := req.GetVolumeId() if cs.MetadataStore == nil { @@ -245,7 +245,7 @@ func (cs *ControllerServer) DeleteLegacyVolume(req *csi.DeleteVolumeRequest, cr rbdVol := &rbdVolume{} if err := cs.MetadataStore.Get(volumeID, rbdVol); err != nil { if err, ok := err.(*util.CacheEntryNotFound); ok { - klog.V(3).Infof("metadata for legacy volume %s not found, assuming the volume to be already deleted (%v)", volumeID, err) + klog.V(3).Infof(util.Log(ctx, "metadata for legacy volume %s not found, assuming the volume to be already deleted (%v)"), volumeID, err) return &csi.DeleteVolumeResponse{}, nil } @@ -260,10 +260,10 @@ func (cs *ControllerServer) DeleteLegacyVolume(req *csi.DeleteVolumeRequest, cr // Update rbdImageName as the VolName when dealing with version 1 volumes rbdVol.RbdImageName = rbdVol.VolName - klog.V(4).Infof("deleting legacy volume %s", rbdVol.VolName) - if err := deleteImage(rbdVol, cr); err != nil { + klog.V(4).Infof(util.Log(ctx, "deleting legacy volume %s"), rbdVol.VolName) + if err := deleteImage(ctx, rbdVol, cr); err != nil { // TODO: can we detect "already deleted" situations here and proceed? - klog.V(3).Infof("failed to delete legacy rbd image: %s/%s with error: %v", rbdVol.Pool, rbdVol.VolName, err) + klog.V(3).Infof(util.Log(ctx, "failed to delete legacy rbd image: %s/%s with error: %v"), rbdVol.Pool, rbdVol.VolName, err) return nil, status.Error(codes.Internal, err.Error()) } @@ -278,7 +278,7 @@ func (cs *ControllerServer) DeleteLegacyVolume(req *csi.DeleteVolumeRequest, cr // from store func (cs *ControllerServer) DeleteVolume(ctx context.Context, req *csi.DeleteVolumeRequest) (*csi.DeleteVolumeResponse, error) { if err := cs.Driver.ValidateControllerServiceRequest(csi.ControllerServiceCapability_RPC_CREATE_DELETE_VOLUME); err != nil { - klog.Warningf("invalid delete volume req: %v", protosanitizer.StripSecrets(req)) + klog.Warningf(util.Log(ctx, "invalid delete volume req: %v"), protosanitizer.StripSecrets(req)) return nil, err } @@ -295,13 +295,13 @@ func (cs *ControllerServer) DeleteVolume(ctx context.Context, req *csi.DeleteVol } rbdVol := &rbdVolume{} - if err := genVolFromVolID(rbdVol, volumeID, cr); err != nil { + if err := genVolFromVolID(ctx, rbdVol, volumeID, cr); err != nil { // If error is ErrInvalidVolID it could be a version 1.0.0 or lower volume, attempt // to process it as such if _, ok := err.(ErrInvalidVolID); ok { if isLegacyVolumeID(volumeID) { - klog.V(2).Infof("attempting deletion of potential legacy volume (%s)", volumeID) - return cs.DeleteLegacyVolume(req, cr) + klog.V(2).Infof(util.Log(ctx, "attempting deletion of potential legacy volume (%s)"), volumeID) + return cs.DeleteLegacyVolume(ctx, req, cr) } // Consider unknown volumeID as a successfully deleted volume @@ -338,15 +338,15 @@ func (cs *ControllerServer) DeleteVolume(ctx context.Context, req *csi.DeleteVol defer volumeNameLocker.Unlock(idLk, rbdVol.RequestName) // Deleting rbd image - klog.V(4).Infof("deleting image %s", rbdVol.RbdImageName) - if err := deleteImage(rbdVol, cr); err != nil { - klog.Errorf("failed to delete rbd image: %s/%s with error: %v", + klog.V(4).Infof(util.Log(ctx, "deleting image %s"), rbdVol.RbdImageName) + if err := deleteImage(ctx, rbdVol, cr); err != nil { + klog.Errorf(util.Log(ctx, "failed to delete rbd image: %s/%s with error: %v"), rbdVol.Pool, rbdVol.RbdImageName, err) return nil, status.Error(codes.Internal, err.Error()) } if err := undoVolReservation(rbdVol, cr); err != nil { - klog.Errorf("failed to remove reservation for volume (%s) with backing image (%s) (%s)", + klog.Errorf(util.Log(ctx, "failed to remove reservation for volume (%s) with backing image (%s) (%s)"), rbdVol.RequestName, rbdVol.RbdImageName, err) return nil, status.Error(codes.Internal, err.Error()) } @@ -381,7 +381,7 @@ func (cs *ControllerServer) ValidateVolumeCapabilities(ctx context.Context, req // in store // nolint: gocyclo func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateSnapshotRequest) (*csi.CreateSnapshotResponse, error) { - if err := cs.validateSnapshotReq(req); err != nil { + if err := cs.validateSnapshotReq(ctx, req); err != nil { return nil, err } @@ -393,7 +393,7 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS // Fetch source volume information rbdVol := new(rbdVolume) - err = genVolFromVolID(rbdVol, req.GetSourceVolumeId(), cr) + err = genVolFromVolID(ctx, rbdVol, req.GetSourceVolumeId(), cr) if err != nil { if _, ok := err.(ErrImageNotFound); ok { return nil, status.Errorf(codes.NotFound, "source Volume ID %s not found", req.GetSourceVolumeId()) @@ -407,7 +407,7 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS } // Create snap volume - rbdSnap := genSnapFromOptions(rbdVol, req.GetParameters()) + rbdSnap := genSnapFromOptions(ctx, rbdVol, req.GetParameters()) rbdSnap.RbdImageName = rbdVol.RbdImageName rbdSnap.SizeBytes = rbdVol.VolSize rbdSnap.SourceVolumeID = req.GetSourceVolumeId() @@ -418,7 +418,7 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS // Need to check for already existing snapshot name, and if found // check for the requested source volume id and already allocated source volume id - found, err := checkSnapExists(rbdSnap, cr) + found, err := checkSnapExists(ctx, rbdSnap, cr) if err != nil { if _, ok := err.(util.ErrSnapNameConflict); ok { return nil, status.Error(codes.AlreadyExists, err.Error()) @@ -438,7 +438,7 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS }, nil } - err = reserveSnap(rbdSnap, cr) + err = reserveSnap(ctx, rbdSnap, cr) if err != nil { return nil, status.Error(codes.Internal, err.Error()) } @@ -446,12 +446,12 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS if err != nil { errDefer := undoSnapReservation(rbdSnap, cr) if errDefer != nil { - klog.Warningf("failed undoing reservation of snapshot: %s %v", req.GetName(), errDefer) + klog.Warningf(util.Log(ctx, "failed undoing reservation of snapshot: %s %v"), req.GetName(), errDefer) } } }() - err = cs.doSnapshot(rbdSnap, cr) + err = cs.doSnapshot(ctx, rbdSnap, cr) if err != nil { return nil, err } @@ -467,9 +467,9 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS }, nil } -func (cs *ControllerServer) validateSnapshotReq(req *csi.CreateSnapshotRequest) error { +func (cs *ControllerServer) validateSnapshotReq(ctx context.Context, req *csi.CreateSnapshotRequest) error { if err := cs.Driver.ValidateControllerServiceRequest(csi.ControllerServiceCapability_RPC_CREATE_DELETE_SNAPSHOT); err != nil { - klog.Warningf("invalid create snapshot req: %v", protosanitizer.StripSecrets(req)) + klog.Warningf(util.Log(ctx, "invalid create snapshot req: %v"), protosanitizer.StripSecrets(req)) return err } @@ -484,19 +484,19 @@ func (cs *ControllerServer) validateSnapshotReq(req *csi.CreateSnapshotRequest) return nil } -func (cs *ControllerServer) doSnapshot(rbdSnap *rbdSnapshot, cr *util.Credentials) (err error) { - err = createSnapshot(rbdSnap, cr) +func (cs *ControllerServer) doSnapshot(ctx context.Context, rbdSnap *rbdSnapshot, cr *util.Credentials) (err error) { + err = createSnapshot(ctx, rbdSnap, cr) // If snap creation fails, even due to snapname already used, fail, next attempt will get a new // uuid for use as the snap name if err != nil { - klog.Errorf("failed to create snapshot: %v", err) + klog.Errorf(util.Log(ctx, "failed to create snapshot: %v"), err) return status.Error(codes.Internal, err.Error()) } defer func() { if err != nil { - errDefer := deleteSnapshot(rbdSnap, cr) + errDefer := deleteSnapshot(ctx, rbdSnap, cr) if errDefer != nil { - klog.Errorf("failed to delete snapshot: %v", errDefer) + klog.Errorf(util.Log(ctx, "failed to delete snapshot: %v"), errDefer) err = fmt.Errorf("snapshot created but failed to delete snapshot due to"+ " other failures: %v", err) } @@ -504,16 +504,16 @@ func (cs *ControllerServer) doSnapshot(rbdSnap *rbdSnapshot, cr *util.Credential } }() - err = protectSnapshot(rbdSnap, cr) + err = protectSnapshot(ctx, rbdSnap, cr) if err != nil { - klog.Errorf("failed to protect snapshot: %v", err) + klog.Errorf(util.Log(ctx, "failed to protect snapshot: %v"), err) return status.Error(codes.Internal, err.Error()) } defer func() { if err != nil { - errDefer := unprotectSnapshot(rbdSnap, cr) + errDefer := unprotectSnapshot(ctx, rbdSnap, cr) if errDefer != nil { - klog.Errorf("failed to unprotect snapshot: %v", errDefer) + klog.Errorf(util.Log(ctx, "failed to unprotect snapshot: %v"), errDefer) err = fmt.Errorf("snapshot created but failed to unprotect snapshot due to"+ " other failures: %v", err) } @@ -521,9 +521,9 @@ func (cs *ControllerServer) doSnapshot(rbdSnap *rbdSnapshot, cr *util.Credential } }() - err = getSnapshotMetadata(rbdSnap, cr) + err = getSnapshotMetadata(ctx, rbdSnap, cr) if err != nil { - klog.Errorf("failed to fetch snapshot metadata: %v", err) + klog.Errorf(util.Log(ctx, "failed to fetch snapshot metadata: %v"), err) return status.Error(codes.Internal, err.Error()) } @@ -534,7 +534,7 @@ func (cs *ControllerServer) doSnapshot(rbdSnap *rbdSnapshot, cr *util.Credential // snapshot metadata from store func (cs *ControllerServer) DeleteSnapshot(ctx context.Context, req *csi.DeleteSnapshotRequest) (*csi.DeleteSnapshotResponse, error) { if err := cs.Driver.ValidateControllerServiceRequest(csi.ControllerServiceCapability_RPC_CREATE_DELETE_SNAPSHOT); err != nil { - klog.Warningf("invalid delete snapshot req: %v", protosanitizer.StripSecrets(req)) + klog.Warningf(util.Log(ctx, "invalid delete snapshot req: %v"), protosanitizer.StripSecrets(req)) return nil, err } @@ -550,7 +550,7 @@ func (cs *ControllerServer) DeleteSnapshot(ctx context.Context, req *csi.DeleteS } rbdSnap := &rbdSnapshot{} - if err = genSnapFromSnapID(rbdSnap, snapshotID, cr); err != nil { + if err = genSnapFromSnapID(ctx, rbdSnap, snapshotID, cr); err != nil { // if error is ErrKeyNotFound, then a previous attempt at deletion was complete // or partially complete (snap and snapOMap are garbage collected already), hence return // success as deletion is complete @@ -579,7 +579,7 @@ func (cs *ControllerServer) DeleteSnapshot(ctx context.Context, req *csi.DeleteS defer snapshotNameLocker.Unlock(idLk, rbdSnap.RequestName) // Unprotect snapshot - err = unprotectSnapshot(rbdSnap, cr) + err = unprotectSnapshot(ctx, rbdSnap, cr) if err != nil { return nil, status.Errorf(codes.FailedPrecondition, "failed to unprotect snapshot: %s/%s with error: %v", @@ -587,8 +587,8 @@ func (cs *ControllerServer) DeleteSnapshot(ctx context.Context, req *csi.DeleteS } // Deleting snapshot - klog.V(4).Infof("deleting Snaphot %s", rbdSnap.RbdSnapName) - if err := deleteSnapshot(rbdSnap, cr); err != nil { + klog.V(4).Infof(util.Log(ctx, "deleting Snaphot %s"), rbdSnap.RbdSnapName) + if err := deleteSnapshot(ctx, rbdSnap, cr); err != nil { return nil, status.Errorf(codes.FailedPrecondition, "failed to delete snapshot: %s/%s with error: %v", rbdSnap.Pool, rbdSnap.RbdSnapName, err) diff --git a/pkg/rbd/nodeserver.go b/pkg/rbd/nodeserver.go index fa8b9c1dc..20d78dd1b 100644 --- a/pkg/rbd/nodeserver.go +++ b/pkg/rbd/nodeserver.go @@ -64,7 +64,7 @@ func (ns *NodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVol if isBlock { disableInUseChecks = true } else { - klog.Warningf("MULTI_NODE_MULTI_WRITER currently only supported with volumes of access type `block`, invalid AccessMode for volume: %v", req.GetVolumeId()) + klog.Warningf(util.Log(ctx, "MULTI_NODE_MULTI_WRITER currently only supported with volumes of access type `block`, invalid AccessMode for volume: %v"), req.GetVolumeId()) return nil, status.Error(codes.InvalidArgument, "rbd: RWX access mode request is only valid for volumes with access type `block`") } } @@ -107,11 +107,11 @@ func (ns *NodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVol } if !isNotMnt { - klog.Infof("rbd: volume %s is already mounted to %s, skipping", req.GetVolumeId(), stagingTargetPath) + klog.Infof(util.Log(ctx, "rbd: volume %s is already mounted to %s, skipping"), req.GetVolumeId(), stagingTargetPath) return &csi.NodeStageVolumeResponse{}, nil } - volOptions, err := genVolFromVolumeOptions(req.GetVolumeContext(), req.GetSecrets(), disableInUseChecks, isLegacyVolume) + volOptions, err := genVolFromVolumeOptions(ctx, req.GetVolumeContext(), req.GetSecrets(), disableInUseChecks, isLegacyVolume) if err != nil { return nil, status.Error(codes.Internal, err.Error()) } @@ -129,25 +129,25 @@ func (ns *NodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVol } defer func() { if err != nil { - ns.undoStagingTransaction(stagingParentPath, devicePath, volID, isStagePathCreated, isMounted) + ns.undoStagingTransaction(ctx, stagingParentPath, devicePath, volID, isStagePathCreated, isMounted) } }() // Mapping RBD image - devicePath, err = attachRBDImage(volOptions, cr) + devicePath, err = attachRBDImage(ctx, volOptions, cr) if err != nil { return nil, status.Error(codes.Internal, err.Error()) } - klog.V(4).Infof("rbd image: %s/%s was successfully mapped at %s\n", req.GetVolumeId(), volOptions.Pool, devicePath) + klog.V(4).Infof(util.Log(ctx, "rbd image: %s/%s was successfully mapped at %s\n"), req.GetVolumeId(), volOptions.Pool, devicePath) - err = ns.createStageMountPoint(stagingTargetPath, isBlock) + err = ns.createStageMountPoint(ctx, stagingTargetPath, isBlock) if err != nil { return nil, status.Error(codes.Internal, err.Error()) } isStagePathCreated = true // nodeStage Path - err = ns.mountVolumeToStagePath(req, stagingTargetPath, devicePath) + err = ns.mountVolumeToStagePath(ctx, req, stagingTargetPath, devicePath) if err != nil { return nil, status.Error(codes.Internal, err.Error()) } @@ -158,19 +158,19 @@ func (ns *NodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVol return nil, status.Error(codes.Internal, err.Error()) } - klog.Infof("rbd: successfully mounted volume %s to stagingTargetPath %s", req.GetVolumeId(), stagingTargetPath) + klog.Infof(util.Log(ctx, "rbd: successfully mounted volume %s to stagingTargetPath %s"), req.GetVolumeId(), stagingTargetPath) return &csi.NodeStageVolumeResponse{}, nil } -func (ns *NodeServer) undoStagingTransaction(stagingParentPath, devicePath, volID string, isStagePathCreated, isMounted bool) { +func (ns *NodeServer) undoStagingTransaction(ctx context.Context, stagingParentPath, devicePath, volID string, isStagePathCreated, isMounted bool) { var err error stagingTargetPath := stagingParentPath + "/" + volID if isMounted { err = ns.mounter.Unmount(stagingTargetPath) if err != nil { - klog.Errorf("failed to unmount stagingtargetPath: %s with error: %v", stagingTargetPath, err) + klog.Errorf(util.Log(ctx, "failed to unmount stagingtargetPath: %s with error: %v"), stagingTargetPath, err) return } } @@ -179,36 +179,36 @@ func (ns *NodeServer) undoStagingTransaction(stagingParentPath, devicePath, volI if isStagePathCreated { err = os.Remove(stagingTargetPath) if err != nil { - klog.Errorf("failed to remove stagingtargetPath: %s with error: %v", stagingTargetPath, err) + klog.Errorf(util.Log(ctx, "failed to remove stagingtargetPath: %s with error: %v"), stagingTargetPath, err) // continue on failure to unmap the image, as leaving stale images causes more issues than a stale file/directory } } // Unmapping rbd device if devicePath != "" { - err = detachRBDDevice(devicePath) + err = detachRBDDevice(ctx, devicePath) if err != nil { - klog.Errorf("failed to unmap rbd device: %s for volume %s with error: %v", devicePath, volID, err) + klog.Errorf(util.Log(ctx, "failed to unmap rbd device: %s for volume %s with error: %v"), devicePath, volID, err) // continue on failure to delete the stash file, as kubernetes will fail to delete the staging path otherwise } } // Cleanup the stashed image metadata if err = cleanupRBDImageMetadataStash(stagingParentPath); err != nil { - klog.Errorf("failed to cleanup image metadata stash (%v)", err) + klog.Errorf(util.Log(ctx, "failed to cleanup image metadata stash (%v)"), err) return } } -func (ns *NodeServer) createStageMountPoint(mountPath string, isBlock bool) error { +func (ns *NodeServer) createStageMountPoint(ctx context.Context, mountPath string, isBlock bool) error { if isBlock { pathFile, err := os.OpenFile(mountPath, os.O_CREATE|os.O_RDWR, 0750) if err != nil { - klog.Errorf("failed to create mountPath:%s with error: %v", mountPath, err) + klog.Errorf(util.Log(ctx, "failed to create mountPath:%s with error: %v"), mountPath, err) return status.Error(codes.Internal, err.Error()) } if err = pathFile.Close(); err != nil { - klog.Errorf("failed to close mountPath:%s with error: %v", mountPath, err) + klog.Errorf(util.Log(ctx, "failed to close mountPath:%s with error: %v"), mountPath, err) return status.Error(codes.Internal, err.Error()) } @@ -218,7 +218,7 @@ func (ns *NodeServer) createStageMountPoint(mountPath string, isBlock bool) erro err := os.Mkdir(mountPath, 0750) if err != nil { if !os.IsExist(err) { - klog.Errorf("failed to create mountPath:%s with error: %v", mountPath, err) + klog.Errorf(util.Log(ctx, "failed to create mountPath:%s with error: %v"), mountPath, err) return status.Error(codes.Internal, err.Error()) } } @@ -258,7 +258,7 @@ func (ns *NodeServer) NodePublishVolume(ctx context.Context, req *csi.NodePublis return nil, err } - util.Infof(ctx, "rbd: successfully mounted stagingPath %s to targetPath %s", stagingPath, targetPath) + klog.Infof(util.Log(ctx, "rbd: successfully mounted stagingPath %s to targetPath %s"), stagingPath, targetPath) return &csi.NodePublishVolumeResponse{}, nil } @@ -298,7 +298,7 @@ func getLegacyVolumeName(mountPath string) (string, error) { return volName, nil } -func (ns *NodeServer) mountVolumeToStagePath(req *csi.NodeStageVolumeRequest, stagingPath, devicePath string) error { +func (ns *NodeServer) mountVolumeToStagePath(ctx context.Context, req *csi.NodeStageVolumeRequest, stagingPath, devicePath string) error { // Publish Path fsType := req.GetVolumeCapability().GetMount().GetFsType() diskMounter := &mount.SafeFormatAndMount{Interface: ns.mounter, Exec: mount.NewOsExec()} @@ -313,7 +313,7 @@ func (ns *NodeServer) mountVolumeToStagePath(req *csi.NodeStageVolumeRequest, st err = diskMounter.FormatAndMount(devicePath, stagingPath, fsType, opt) } if err != nil { - klog.Errorf("failed to mount device path (%s) to staging path (%s) for volume (%s) error %s", devicePath, stagingPath, req.GetVolumeId(), err) + klog.Errorf(util.Log(ctx, "failed to mount device path (%s) to staging path (%s) for volume (%s) error %s"), devicePath, stagingPath, req.GetVolumeId(), err) } return err } @@ -325,7 +325,7 @@ func (ns *NodeServer) mountVolume(ctx context.Context, stagingPath string, req * mountFlags := req.GetVolumeCapability().GetMount().GetMountFlags() isBlock := req.GetVolumeCapability().GetBlock() != nil targetPath := req.GetTargetPath() - util.V(4).Infof(ctx, "target %v\nisBlock %v\nfstype %v\nstagingPath %v\nreadonly %v\nmountflags %v\n", + klog.V(4).Infof(util.Log(ctx, "target %v\nisBlock %v\nfstype %v\nstagingPath %v\nreadonly %v\nmountflags %v\n"), targetPath, isBlock, fsType, stagingPath, readOnly, mountFlags) mountFlags = append(mountFlags, "bind") if readOnly { @@ -347,11 +347,11 @@ func (ns *NodeServer) createTargetMountPath(ctx context.Context, mountPath strin // #nosec pathFile, e := os.OpenFile(mountPath, os.O_CREATE|os.O_RDWR, 0750) if e != nil { - util.V(4).Infof(ctx, "Failed to create mountPath:%s with error: %v", mountPath, err) + klog.V(4).Infof(util.Log(ctx, "Failed to create mountPath:%s with error: %v"), mountPath, err) return notMnt, status.Error(codes.Internal, e.Error()) } if err = pathFile.Close(); err != nil { - util.V(4).Infof(ctx, "Failed to close mountPath:%s with error: %v", mountPath, err) + klog.V(4).Infof(util.Log(ctx, "Failed to close mountPath:%s with error: %v"), mountPath, err) return notMnt, status.Error(codes.Internal, err.Error()) } } else { @@ -381,7 +381,7 @@ func (ns *NodeServer) NodeUnpublishVolume(ctx context.Context, req *csi.NodeUnpu if err != nil { if os.IsNotExist(err) { // targetPath has already been deleted - klog.V(4).Infof("targetPath: %s has already been deleted", targetPath) + klog.V(4).Infof(util.Log(ctx, "targetPath: %s has already been deleted"), targetPath) return &csi.NodeUnpublishVolumeResponse{}, nil } return nil, status.Error(codes.NotFound, err.Error()) @@ -401,7 +401,7 @@ func (ns *NodeServer) NodeUnpublishVolume(ctx context.Context, req *csi.NodeUnpu return nil, status.Error(codes.Internal, err.Error()) } - klog.Infof("rbd: successfully unbound volume %s from %s", req.GetVolumeId(), targetPath) + klog.Infof(util.Log(ctx, "rbd: successfully unbound volume %s from %s"), req.GetVolumeId(), targetPath) return &csi.NodeUnpublishVolumeResponse{}, nil } @@ -428,7 +428,7 @@ func (ns *NodeServer) NodeUnstageVolume(ctx context.Context, req *csi.NodeUnstag // Unmounting the image err = ns.mounter.Unmount(stagingTargetPath) if err != nil { - klog.V(3).Infof("failed to unmount targetPath: %s with error: %v", stagingTargetPath, err) + klog.V(3).Infof(util.Log(ctx, "failed to unmount targetPath: %s with error: %v"), stagingTargetPath, err) return nil, status.Error(codes.Internal, err.Error()) } } @@ -438,14 +438,14 @@ func (ns *NodeServer) NodeUnstageVolume(ctx context.Context, req *csi.NodeUnstag // keeps invoking Unstage. Hence any errors removing files within this path is a critical // error if !os.IsNotExist(err) { - klog.Errorf("failed to remove staging target path (%s): (%v)", stagingTargetPath, err) + klog.Errorf(util.Log(ctx, "failed to remove staging target path (%s): (%v)"), stagingTargetPath, err) return nil, status.Error(codes.Internal, err.Error()) } } imgInfo, err := lookupRBDImageMetadataStash(stagingParentPath) if err != nil { - klog.V(2).Infof("failed to find image metadata: %v", err) + klog.V(2).Infof(util.Log(ctx, "failed to find image metadata: %v"), err) // It is an error if it was mounted, as we should have found the image metadata file with // no errors if !notMnt { @@ -464,17 +464,16 @@ func (ns *NodeServer) NodeUnstageVolume(ctx context.Context, req *csi.NodeUnstag // Unmapping rbd device imageSpec := imgInfo.Pool + "/" + imgInfo.ImageName - if err = detachRBDImageOrDeviceSpec(imageSpec, true, imgInfo.NbdAccess); err != nil { - klog.Errorf("error unmapping volume (%s) from staging path (%s): (%v)", - req.GetVolumeId(), stagingTargetPath, err) + if err = detachRBDImageOrDeviceSpec(ctx, imageSpec, true, imgInfo.NbdAccess); err != nil { + klog.Errorf(util.Log(ctx, "error unmapping volume (%s) from staging path (%s): (%v)"), req.GetVolumeId(), stagingTargetPath, err) return nil, status.Error(codes.Internal, err.Error()) } - klog.Infof("successfully unmounted volume (%s) from staging path (%s)", + klog.Infof(util.Log(ctx, "successfully unmounted volume (%s) from staging path (%s)"), req.GetVolumeId(), stagingTargetPath) if err = cleanupRBDImageMetadataStash(stagingParentPath); err != nil { - klog.Errorf("failed to cleanup image metadata stash (%v)", err) + klog.Errorf(util.Log(ctx, "failed to cleanup image metadata stash (%v)"), err) return nil, status.Error(codes.Internal, err.Error()) } diff --git a/pkg/rbd/rbd_attach.go b/pkg/rbd/rbd_attach.go index 96bd58e6f..e92cfa7a9 100644 --- a/pkg/rbd/rbd_attach.go +++ b/pkg/rbd/rbd_attach.go @@ -17,6 +17,7 @@ limitations under the License. package rbd import ( + "context" "encoding/json" "fmt" "strconv" @@ -113,7 +114,7 @@ func rbdGetDeviceList(accessType string) ([]rbdDeviceInfo, error) { } // findDeviceMappingImage finds a devicePath, if available, based on image spec (pool/image) on the node. -func findDeviceMappingImage(pool, image string, useNbdDriver bool) (string, bool) { +func findDeviceMappingImage(ctx context.Context, pool, image string, useNbdDriver bool) (string, bool) { accessType := accessTypeKRbd if useNbdDriver { accessType = accessTypeNbd @@ -121,7 +122,7 @@ func findDeviceMappingImage(pool, image string, useNbdDriver bool) (string, bool rbdDeviceList, err := rbdGetDeviceList(accessType) if err != nil { - klog.Warningf("failed to determine if image (%s/%s) is mapped to a device (%v)", pool, image, err) + klog.Warningf(util.Log(ctx, "failed to determine if image (%s/%s) is mapped to a device (%v)"), pool, image, err) return "", false } @@ -135,13 +136,13 @@ func findDeviceMappingImage(pool, image string, useNbdDriver bool) (string, bool } // Stat a path, if it doesn't exist, retry maxRetries times. -func waitForPath(pool, image string, maxRetries int, useNbdDriver bool) (string, bool) { +func waitForPath(ctx context.Context, pool, image string, maxRetries int, useNbdDriver bool) (string, bool) { for i := 0; i < maxRetries; i++ { if i != 0 { time.Sleep(time.Second) } - device, found := findDeviceMappingImage(pool, image, useNbdDriver) + device, found := findDeviceMappingImage(ctx, pool, image, useNbdDriver) if found { return device, found } @@ -165,7 +166,7 @@ func checkRbdNbdTools() bool { return true } -func attachRBDImage(volOptions *rbdVolume, cr *util.Credentials) (string, error) { +func attachRBDImage(ctx context.Context, volOptions *rbdVolume, cr *util.Credentials) (string, error) { var err error image := volOptions.RbdImageName @@ -174,7 +175,7 @@ func attachRBDImage(volOptions *rbdVolume, cr *util.Credentials) (string, error) useNBD = true } - devicePath, found := waitForPath(volOptions.Pool, image, 1, useNBD) + devicePath, found := waitForPath(ctx, volOptions.Pool, image, 1, useNBD) if !found { backoff := wait.Backoff{ Duration: rbdImageWatcherInitDelay, @@ -182,23 +183,23 @@ func attachRBDImage(volOptions *rbdVolume, cr *util.Credentials) (string, error) Steps: rbdImageWatcherSteps, } - err = waitForrbdImage(backoff, volOptions, cr) + err = waitForrbdImage(ctx, backoff, volOptions, cr) if err != nil { return "", err } - devicePath, err = createPath(volOptions, cr) + devicePath, err = createPath(ctx, volOptions, cr) } return devicePath, err } -func createPath(volOpt *rbdVolume, cr *util.Credentials) (string, error) { +func createPath(ctx context.Context, volOpt *rbdVolume, cr *util.Credentials) (string, error) { isNbd := false image := volOpt.RbdImageName imagePath := fmt.Sprintf("%s/%s", volOpt.Pool, image) - klog.V(5).Infof("rbd: map mon %s", volOpt.Monitors) + klog.V(5).Infof(util.Log(ctx, "rbd: map mon %s"), volOpt.Monitors) // Map options mapOptions := []string{ @@ -221,12 +222,12 @@ func createPath(volOpt *rbdVolume, cr *util.Credentials) (string, error) { // Execute map output, err := execCommand(rbd, mapOptions) if err != nil { - klog.Warningf("rbd: map error %v, rbd output: %s", err, string(output)) + klog.Warningf(util.Log(ctx, "rbd: map error %v, rbd output: %s"), err, string(output)) // unmap rbd image if connection timeout if strings.Contains(err.Error(), rbdMapConnectionTimeout) { - detErr := detachRBDImageOrDeviceSpec(imagePath, true, isNbd) + detErr := detachRBDImageOrDeviceSpec(ctx, imagePath, true, isNbd) if detErr != nil { - klog.Warningf("rbd: %s unmap error %v", imagePath, detErr) + klog.Warningf(util.Log(ctx, "rbd: %s unmap error %v"), imagePath, detErr) } } return "", fmt.Errorf("rbd: map failed %v, rbd output: %s", err, string(output)) @@ -236,17 +237,17 @@ func createPath(volOpt *rbdVolume, cr *util.Credentials) (string, error) { return devicePath, nil } -func waitForrbdImage(backoff wait.Backoff, volOptions *rbdVolume, cr *util.Credentials) error { +func waitForrbdImage(ctx context.Context, backoff wait.Backoff, volOptions *rbdVolume, cr *util.Credentials) error { image := volOptions.RbdImageName imagePath := fmt.Sprintf("%s/%s", volOptions.Pool, image) err := wait.ExponentialBackoff(backoff, func() (bool, error) { - used, rbdOutput, err := rbdStatus(volOptions, cr) + used, rbdOutput, err := rbdStatus(ctx, volOptions, cr) if err != nil { return false, fmt.Errorf("fail to check rbd image status with: (%v), rbd output: (%s)", err, rbdOutput) } if (volOptions.DisableInUseChecks) && (used) { - klog.V(2).Info("valid multi-node attach requested, ignoring watcher in-use result") + klog.V(2).Info(util.Log(ctx, "valid multi-node attach requested, ignoring watcher in-use result")) return used, nil } return !used, nil @@ -259,18 +260,18 @@ func waitForrbdImage(backoff wait.Backoff, volOptions *rbdVolume, cr *util.Crede return err } -func detachRBDDevice(devicePath string) error { +func detachRBDDevice(ctx context.Context, devicePath string) error { nbdType := false if strings.HasPrefix(devicePath, "/dev/nbd") { nbdType = true } - return detachRBDImageOrDeviceSpec(devicePath, false, nbdType) + return detachRBDImageOrDeviceSpec(ctx, devicePath, false, nbdType) } // detachRBDImageOrDeviceSpec detaches an rbd imageSpec or devicePath, with additional checking // when imageSpec is used to decide if image is already unmapped -func detachRBDImageOrDeviceSpec(imageOrDeviceSpec string, isImageSpec, ndbType bool) error { +func detachRBDImageOrDeviceSpec(ctx context.Context, imageOrDeviceSpec string, isImageSpec, ndbType bool) error { var err error var output []byte @@ -288,7 +289,7 @@ func detachRBDImageOrDeviceSpec(imageOrDeviceSpec string, isImageSpec, ndbType b (strings.Contains(string(output), fmt.Sprintf(rbdUnmapCmdkRbdMissingMap, imageOrDeviceSpec)) || strings.Contains(string(output), fmt.Sprintf(rbdUnmapCmdNbdMissingMap, imageOrDeviceSpec))) { // Devices found not to be mapped are treated as a successful detach - klog.Infof("image or device spec (%s) not mapped", imageOrDeviceSpec) + klog.Infof(util.Log(ctx, "image or device spec (%s) not mapped"), imageOrDeviceSpec) return nil } return fmt.Errorf("rbd: unmap for spec (%s) failed (%v): (%s)", imageOrDeviceSpec, err, string(output)) diff --git a/pkg/rbd/rbd_journal.go b/pkg/rbd/rbd_journal.go index ef4d75107..4df489b41 100644 --- a/pkg/rbd/rbd_journal.go +++ b/pkg/rbd/rbd_journal.go @@ -20,6 +20,7 @@ import ( "fmt" "github.com/ceph/ceph-csi/pkg/util" + "golang.org/x/net/context" "github.com/pkg/errors" "k8s.io/klog" @@ -107,7 +108,7 @@ because, the order of omap creation and deletion are inverse of each other, and request name lock, and hence any stale omaps are leftovers from incomplete transactions and are hence safe to garbage collect. */ -func checkSnapExists(rbdSnap *rbdSnapshot, cr *util.Credentials) (bool, error) { +func checkSnapExists(ctx context.Context, rbdSnap *rbdSnapshot, cr *util.Credentials) (bool, error) { err := validateRbdSnap(rbdSnap) if err != nil { return false, err @@ -124,7 +125,7 @@ func checkSnapExists(rbdSnap *rbdSnapshot, cr *util.Credentials) (bool, error) { rbdSnap.RbdSnapName = snapJournal.NamingPrefix() + snapUUID // Fetch on-disk image attributes - err = updateSnapWithImageInfo(rbdSnap, cr) + err = updateSnapWithImageInfo(ctx, rbdSnap, cr) if err != nil { if _, ok := err.(ErrSnapNotFound); ok { err = snapJournal.UndoReservation(rbdSnap.Monitors, cr, rbdSnap.Pool, @@ -141,7 +142,7 @@ func checkSnapExists(rbdSnap *rbdSnapshot, cr *util.Credentials) (bool, error) { return false, err } - klog.V(4).Infof("found existing snap (%s) with snap name (%s) for request (%s)", + klog.V(4).Infof(util.Log(ctx, "found existing snap (%s) with snap name (%s) for request (%s)"), rbdSnap.SnapID, rbdSnap.RbdSnapName, rbdSnap.RequestName) return true, nil @@ -155,7 +156,7 @@ volume names as requested by the CSI drivers. Hence, these need to be invoked on respective CSI snapshot or volume name based locks are held, as otherwise racy access to these omaps may end up leaving the omaps in an inconsistent state. */ -func checkVolExists(rbdVol *rbdVolume, cr *util.Credentials) (bool, error) { +func checkVolExists(ctx context.Context, rbdVol *rbdVolume, cr *util.Credentials) (bool, error) { err := validateRbdVol(rbdVol) if err != nil { return false, err @@ -175,7 +176,7 @@ func checkVolExists(rbdVol *rbdVolume, cr *util.Credentials) (bool, error) { // save it for size checks before fetching image data requestSize := rbdVol.VolSize // Fetch on-disk image attributes and compare against request - err = updateVolWithImageInfo(rbdVol, cr) + err = updateVolWithImageInfo(ctx, rbdVol, cr) if err != nil { if _, ok := err.(ErrImageNotFound); ok { err = volJournal.UndoReservation(rbdVol.Monitors, cr, rbdVol.Pool, @@ -200,7 +201,7 @@ func checkVolExists(rbdVol *rbdVolume, cr *util.Credentials) (bool, error) { return false, err } - klog.V(4).Infof("found existing volume (%s) with image name (%s) for request (%s)", + klog.V(4).Infof(util.Log(ctx, "found existing volume (%s) with image name (%s) for request (%s)"), rbdVol.VolID, rbdVol.RbdImageName, rbdVol.RequestName) return true, nil @@ -208,7 +209,7 @@ func checkVolExists(rbdVol *rbdVolume, cr *util.Credentials) (bool, error) { // reserveSnap is a helper routine to request a rbdSnapshot name reservation and generate the // volume ID for the generated name -func reserveSnap(rbdSnap *rbdSnapshot, cr *util.Credentials) error { +func reserveSnap(ctx context.Context, rbdSnap *rbdSnapshot, cr *util.Credentials) error { snapUUID, err := snapJournal.ReserveName(rbdSnap.Monitors, cr, rbdSnap.Pool, rbdSnap.RequestName, rbdSnap.RbdImageName) if err != nil { @@ -223,7 +224,7 @@ func reserveSnap(rbdSnap *rbdSnapshot, cr *util.Credentials) error { rbdSnap.RbdSnapName = snapJournal.NamingPrefix() + snapUUID - klog.V(4).Infof("generated Volume ID (%s) and image name (%s) for request name (%s)", + klog.V(4).Infof(util.Log(ctx, "generated Volume ID (%s) and image name (%s) for request name (%s)"), rbdSnap.SnapID, rbdSnap.RbdImageName, rbdSnap.RequestName) return nil @@ -231,7 +232,7 @@ func reserveSnap(rbdSnap *rbdSnapshot, cr *util.Credentials) error { // reserveVol is a helper routine to request a rbdVolume name reservation and generate the // volume ID for the generated name -func reserveVol(rbdVol *rbdVolume, cr *util.Credentials) error { +func reserveVol(ctx context.Context, rbdVol *rbdVolume, cr *util.Credentials) error { imageUUID, err := volJournal.ReserveName(rbdVol.Monitors, cr, rbdVol.Pool, rbdVol.RequestName, "") if err != nil { @@ -246,7 +247,7 @@ func reserveVol(rbdVol *rbdVolume, cr *util.Credentials) error { rbdVol.RbdImageName = volJournal.NamingPrefix() + imageUUID - klog.V(4).Infof("generated Volume ID (%s) and image name (%s) for request name (%s)", + klog.V(4).Infof(util.Log(ctx, "generated Volume ID (%s) and image name (%s) for request name (%s)"), rbdVol.VolID, rbdVol.RbdImageName, rbdVol.RequestName) return nil diff --git a/pkg/rbd/rbd_util.go b/pkg/rbd/rbd_util.go index 757953264..b36f8fbd8 100644 --- a/pkg/rbd/rbd_util.go +++ b/pkg/rbd/rbd_util.go @@ -27,6 +27,7 @@ import ( "time" "github.com/ceph/ceph-csi/pkg/util" + "golang.org/x/net/context" "github.com/golang/protobuf/ptypes" "github.com/golang/protobuf/ptypes/timestamp" @@ -114,16 +115,17 @@ var ( ) // createImage creates a new ceph image with provision and volume options. -func createImage(pOpts *rbdVolume, volSz int64, cr *util.Credentials) error { +func createImage(ctx context.Context, pOpts *rbdVolume, volSz int64, cr *util.Credentials) error { var output []byte image := pOpts.RbdImageName volSzMiB := fmt.Sprintf("%dM", volSz) if pOpts.ImageFormat == rbdImageFormat2 { - klog.V(4).Infof("rbd: create %s size %s format %s (features: %s) using mon %s, pool %s ", image, volSzMiB, pOpts.ImageFormat, pOpts.ImageFeatures, pOpts.Monitors, pOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: create %s size %s format %s (features: %s) using mon %s, pool %s"), + image, volSzMiB, pOpts.ImageFormat, pOpts.ImageFeatures, pOpts.Monitors, pOpts.Pool) } else { - klog.V(4).Infof("rbd: create %s size %s format %s using mon %s, pool %s", image, volSzMiB, pOpts.ImageFormat, pOpts.Monitors, pOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: create %s size %s format %s using mon %s, pool %s"), image, volSzMiB, pOpts.ImageFormat, pOpts.Monitors, pOpts.Pool) } args := []string{"create", image, "--size", volSzMiB, "--pool", pOpts.Pool, "--id", cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile, "--image-format", pOpts.ImageFormat} if pOpts.ImageFormat == rbdImageFormat2 { @@ -140,20 +142,20 @@ func createImage(pOpts *rbdVolume, volSz int64, cr *util.Credentials) error { // rbdStatus checks if there is watcher on the image. // It returns true if there is a watcher on the image, otherwise returns false. -func rbdStatus(pOpts *rbdVolume, cr *util.Credentials) (bool, string, error) { +func rbdStatus(ctx context.Context, pOpts *rbdVolume, cr *util.Credentials) (bool, string, error) { var output string var cmd []byte image := pOpts.RbdImageName - klog.V(4).Infof("rbd: status %s using mon %s, pool %s", image, pOpts.Monitors, pOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: status %s using mon %s, pool %s"), image, pOpts.Monitors, pOpts.Pool) args := []string{"status", image, "--pool", pOpts.Pool, "-m", pOpts.Monitors, "--id", cr.ID, "--keyfile=" + cr.KeyFile} cmd, err := execCommand("rbd", args) output = string(cmd) if err, ok := err.(*exec.Error); ok { if err.Err == exec.ErrNotFound { - klog.Errorf("rbd cmd not found") + klog.Errorf(util.Log(ctx, "rbd cmd not found")) // fail fast if command not found return false, output, err } @@ -165,16 +167,16 @@ func rbdStatus(pOpts *rbdVolume, cr *util.Credentials) (bool, string, error) { } if strings.Contains(output, imageWatcherStr) { - klog.V(4).Infof("rbd: watchers on %s: %s", image, output) + klog.V(4).Infof(util.Log(ctx, "rbd: watchers on %s: %s"), image, output) return true, output, nil } - klog.Warningf("rbd: no watchers on %s", image) + klog.Warningf(util.Log(ctx, "rbd: no watchers on %s"), image) return false, output, nil } // rbdManagerTaskDelete adds a ceph manager task to delete an rbd image, thus deleting // it asynchronously. If command is not found returns a bool set to false -func rbdManagerTaskDeleteImage(pOpts *rbdVolume, cr *util.Credentials) (bool, error) { +func rbdManagerTaskDeleteImage(ctx context.Context, pOpts *rbdVolume, cr *util.Credentials) (bool, error) { var output []byte args := []string{"rbd", "task", "add", "remove", @@ -188,8 +190,8 @@ func rbdManagerTaskDeleteImage(pOpts *rbdVolume, cr *util.Credentials) (bool, er if err != nil { if strings.Contains(string(output), rbdTaskRemoveCmdInvalidString1) && strings.Contains(string(output), rbdTaskRemoveCmdInvalidString2) { - klog.Infof("cluster with cluster ID (%s) does not support Ceph manager based rbd image"+ - " deletion (minimum ceph version required is v14.2.3)", pOpts.ClusterID) + klog.Infof(util.Log(ctx, "cluster with cluster ID (%s) does not support Ceph manager based rbd image"+ + " deletion (minimum ceph version required is v14.2.3)"), pOpts.ClusterID) return false, err } } @@ -198,23 +200,23 @@ func rbdManagerTaskDeleteImage(pOpts *rbdVolume, cr *util.Credentials) (bool, er } // deleteImage deletes a ceph image with provision and volume options. -func deleteImage(pOpts *rbdVolume, cr *util.Credentials) error { +func deleteImage(ctx context.Context, pOpts *rbdVolume, cr *util.Credentials) error { var output []byte image := pOpts.RbdImageName - found, _, err := rbdStatus(pOpts, cr) + found, _, err := rbdStatus(ctx, pOpts, cr) if err != nil { return err } if found { - klog.Info("rbd is still being used ", image) + klog.Info(util.Log(ctx, "rbd is still being used "), image) return fmt.Errorf("rbd %s is still being used", image) } - klog.V(4).Infof("rbd: rm %s using mon %s, pool %s", image, pOpts.Monitors, pOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: rm %s using mon %s, pool %s"), image, pOpts.Monitors, pOpts.Pool) // attempt to use Ceph manager based deletion support if available - rbdCephMgrSupported, err := rbdManagerTaskDeleteImage(pOpts, cr) + rbdCephMgrSupported, err := rbdManagerTaskDeleteImage(ctx, pOpts, cr) if !rbdCephMgrSupported { // attempt older style deletion args := []string{"rm", image, "--pool", pOpts.Pool, "--id", cr.ID, "-m", pOpts.Monitors, @@ -223,7 +225,7 @@ func deleteImage(pOpts *rbdVolume, cr *util.Credentials) error { } if err != nil { - klog.Errorf("failed to delete rbd image: %v, command output: %s", err, string(output)) + klog.Errorf(util.Log(ctx, "failed to delete rbd image: %v, command output: %s"), err, string(output)) } return err @@ -231,8 +233,8 @@ func deleteImage(pOpts *rbdVolume, cr *util.Credentials) error { // updateSnapWithImageInfo updates provided rbdSnapshot with information from on-disk data // regarding the same -func updateSnapWithImageInfo(rbdSnap *rbdSnapshot, cr *util.Credentials) error { - snapInfo, err := getSnapInfo(rbdSnap.Monitors, cr, rbdSnap.Pool, +func updateSnapWithImageInfo(ctx context.Context, rbdSnap *rbdSnapshot, cr *util.Credentials) error { + snapInfo, err := getSnapInfo(ctx, rbdSnap.Monitors, cr, rbdSnap.Pool, rbdSnap.RbdImageName, rbdSnap.RbdSnapName) if err != nil { return err @@ -252,8 +254,8 @@ func updateSnapWithImageInfo(rbdSnap *rbdSnapshot, cr *util.Credentials) error { // updateVolWithImageInfo updates provided rbdVolume with information from on-disk data // regarding the same -func updateVolWithImageInfo(rbdVol *rbdVolume, cr *util.Credentials) error { - imageInfo, err := getImageInfo(rbdVol.Monitors, cr, rbdVol.Pool, rbdVol.RbdImageName) +func updateVolWithImageInfo(ctx context.Context, rbdVol *rbdVolume, cr *util.Credentials) error { + imageInfo, err := getImageInfo(ctx, rbdVol.Monitors, cr, rbdVol.Pool, rbdVol.RbdImageName) if err != nil { return err } @@ -272,7 +274,7 @@ func updateVolWithImageInfo(rbdVol *rbdVolume, cr *util.Credentials) error { // genSnapFromSnapID generates a rbdSnapshot structure from the provided identifier, updating // the structure with elements from on-disk snapshot metadata as well -func genSnapFromSnapID(rbdSnap *rbdSnapshot, snapshotID string, cr *util.Credentials) error { +func genSnapFromSnapID(ctx context.Context, rbdSnap *rbdSnapshot, snapshotID string, cr *util.Credentials) error { var ( options map[string]string vi util.CSIIdentifier @@ -283,7 +285,7 @@ func genSnapFromSnapID(rbdSnap *rbdSnapshot, snapshotID string, cr *util.Credent err := vi.DecomposeCSIID(rbdSnap.SnapID) if err != nil { - klog.Errorf("error decoding snapshot ID (%s) (%s)", err, rbdSnap.SnapID) + klog.Errorf(util.Log(ctx, "error decoding snapshot ID (%s) (%s)"), err, rbdSnap.SnapID) return err } @@ -291,7 +293,7 @@ func genSnapFromSnapID(rbdSnap *rbdSnapshot, snapshotID string, cr *util.Credent options["clusterID"] = rbdSnap.ClusterID rbdSnap.RbdSnapName = snapJournal.NamingPrefix() + vi.ObjectUUID - rbdSnap.Monitors, _, err = getMonsAndClusterID(options) + rbdSnap.Monitors, _, err = getMonsAndClusterID(ctx, options) if err != nil { return err } @@ -307,14 +309,14 @@ func genSnapFromSnapID(rbdSnap *rbdSnapshot, snapshotID string, cr *util.Credent return err } - err = updateSnapWithImageInfo(rbdSnap, cr) + err = updateSnapWithImageInfo(ctx, rbdSnap, cr) return err } // genVolFromVolID generates a rbdVolume structure from the provided identifier, updating // the structure with elements from on-disk image metadata as well -func genVolFromVolID(rbdVol *rbdVolume, volumeID string, cr *util.Credentials) error { +func genVolFromVolID(ctx context.Context, rbdVol *rbdVolume, volumeID string, cr *util.Credentials) error { var ( options map[string]string vi util.CSIIdentifier @@ -335,7 +337,7 @@ func genVolFromVolID(rbdVol *rbdVolume, volumeID string, cr *util.Credentials) e options["clusterID"] = rbdVol.ClusterID rbdVol.RbdImageName = volJournal.NamingPrefix() + vi.ObjectUUID - rbdVol.Monitors, _, err = getMonsAndClusterID(options) + rbdVol.Monitors, _, err = getMonsAndClusterID(ctx, options) if err != nil { return err } @@ -351,7 +353,7 @@ func genVolFromVolID(rbdVol *rbdVolume, volumeID string, cr *util.Credentials) e return err } - err = updateVolWithImageInfo(rbdVol, cr) + err = updateVolWithImageInfo(ctx, rbdVol, cr) return err } @@ -362,7 +364,7 @@ func execCommand(command string, args []string) ([]byte, error) { return cmd.CombinedOutput() } -func getMonsAndClusterID(options map[string]string) (monitors, clusterID string, err error) { +func getMonsAndClusterID(ctx context.Context, options map[string]string) (monitors, clusterID string, err error) { var ok bool if clusterID, ok = options["clusterID"]; !ok { @@ -371,7 +373,7 @@ func getMonsAndClusterID(options map[string]string) (monitors, clusterID string, } if monitors, err = util.Mons(csiConfigFile, clusterID); err != nil { - klog.Errorf("failed getting mons (%s)", err) + klog.Errorf(util.Log(ctx, "failed getting mons (%s)"), err) err = errors.Wrapf(err, "failed to fetch monitor list using clusterID (%s)", clusterID) return } @@ -438,7 +440,7 @@ func updateMons(rbdVol *rbdVolume, options, credentials map[string]string) error return nil } -func genVolFromVolumeOptions(volOptions, credentials map[string]string, disableInUseChecks, isLegacyVolume bool) (*rbdVolume, error) { +func genVolFromVolumeOptions(ctx context.Context, volOptions, credentials map[string]string, disableInUseChecks, isLegacyVolume bool) (*rbdVolume, error) { var ( ok bool err error @@ -456,7 +458,7 @@ func genVolFromVolumeOptions(volOptions, credentials map[string]string, disableI return nil, err } } else { - rbdVol.Monitors, rbdVol.ClusterID, err = getMonsAndClusterID(volOptions) + rbdVol.Monitors, rbdVol.ClusterID, err = getMonsAndClusterID(ctx, volOptions) if err != nil { return nil, err } @@ -483,7 +485,7 @@ func genVolFromVolumeOptions(volOptions, credentials map[string]string, disableI } } - klog.V(3).Infof("setting disableInUseChecks on rbd volume to: %v", disableInUseChecks) + klog.V(3).Infof(util.Log(ctx, "setting disableInUseChecks on rbd volume to: %v"), disableInUseChecks) rbdVol.DisableInUseChecks = disableInUseChecks rbdVol.Mounter, ok = volOptions["mounter"] @@ -494,13 +496,13 @@ func genVolFromVolumeOptions(volOptions, credentials map[string]string, disableI return rbdVol, nil } -func genSnapFromOptions(rbdVol *rbdVolume, snapOptions map[string]string) *rbdSnapshot { +func genSnapFromOptions(ctx context.Context, rbdVol *rbdVolume, snapOptions map[string]string) *rbdSnapshot { var err error rbdSnap := &rbdSnapshot{} rbdSnap.Pool = rbdVol.Pool - rbdSnap.Monitors, rbdSnap.ClusterID, err = getMonsAndClusterID(snapOptions) + rbdSnap.Monitors, rbdSnap.ClusterID, err = getMonsAndClusterID(ctx, snapOptions) if err != nil { rbdSnap.Monitors = rbdVol.Monitors rbdSnap.ClusterID = rbdVol.ClusterID @@ -519,13 +521,13 @@ func hasSnapshotFeature(imageFeatures string) bool { return false } -func protectSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { +func protectSnapshot(ctx context.Context, pOpts *rbdSnapshot, cr *util.Credentials) error { var output []byte image := pOpts.RbdImageName snapName := pOpts.RbdSnapName - klog.V(4).Infof("rbd: snap protect %s using mon %s, pool %s ", image, pOpts.Monitors, pOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: snap protect %s using mon %s, pool %s "), image, pOpts.Monitors, pOpts.Pool) args := []string{"snap", "protect", "--pool", pOpts.Pool, "--snap", snapName, image, "--id", cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile} @@ -538,13 +540,13 @@ func protectSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { return nil } -func createSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { +func createSnapshot(ctx context.Context, pOpts *rbdSnapshot, cr *util.Credentials) error { var output []byte image := pOpts.RbdImageName snapName := pOpts.RbdSnapName - klog.V(4).Infof("rbd: snap create %s using mon %s, pool %s", image, pOpts.Monitors, pOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: snap create %s using mon %s, pool %s"), image, pOpts.Monitors, pOpts.Pool) args := []string{"snap", "create", "--pool", pOpts.Pool, "--snap", snapName, image, "--id", cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile} @@ -557,13 +559,13 @@ func createSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { return nil } -func unprotectSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { +func unprotectSnapshot(ctx context.Context, pOpts *rbdSnapshot, cr *util.Credentials) error { var output []byte image := pOpts.RbdImageName snapName := pOpts.RbdSnapName - klog.V(4).Infof("rbd: snap unprotect %s using mon %s, pool %s", image, pOpts.Monitors, pOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: snap unprotect %s using mon %s, pool %s"), image, pOpts.Monitors, pOpts.Pool) args := []string{"snap", "unprotect", "--pool", pOpts.Pool, "--snap", snapName, image, "--id", cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile} @@ -576,13 +578,13 @@ func unprotectSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { return nil } -func deleteSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { +func deleteSnapshot(ctx context.Context, pOpts *rbdSnapshot, cr *util.Credentials) error { var output []byte image := pOpts.RbdImageName snapName := pOpts.RbdSnapName - klog.V(4).Infof("rbd: snap rm %s using mon %s, pool %s", image, pOpts.Monitors, pOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: snap rm %s using mon %s, pool %s"), image, pOpts.Monitors, pOpts.Pool) args := []string{"snap", "rm", "--pool", pOpts.Pool, "--snap", snapName, image, "--id", cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile} @@ -593,20 +595,20 @@ func deleteSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { } if err := undoSnapReservation(pOpts, cr); err != nil { - klog.Errorf("failed to remove reservation for snapname (%s) with backing snap (%s) on image (%s) (%s)", + klog.Errorf(util.Log(ctx, "failed to remove reservation for snapname (%s) with backing snap (%s) on image (%s) (%s)"), pOpts.RequestName, pOpts.RbdSnapName, pOpts.RbdImageName, err) } return nil } -func restoreSnapshot(pVolOpts *rbdVolume, pSnapOpts *rbdSnapshot, cr *util.Credentials) error { +func restoreSnapshot(ctx context.Context, pVolOpts *rbdVolume, pSnapOpts *rbdSnapshot, cr *util.Credentials) error { var output []byte image := pVolOpts.RbdImageName snapName := pSnapOpts.RbdSnapName - klog.V(4).Infof("rbd: clone %s using mon %s, pool %s", image, pVolOpts.Monitors, pVolOpts.Pool) + klog.V(4).Infof(util.Log(ctx, "rbd: clone %s using mon %s, pool %s"), image, pVolOpts.Monitors, pVolOpts.Pool) args := []string{"clone", pSnapOpts.Pool + "/" + pSnapOpts.RbdImageName + "@" + snapName, pVolOpts.Pool + "/" + image, "--id", cr.ID, "-m", pVolOpts.Monitors, "--keyfile=" + cr.KeyFile} @@ -621,11 +623,11 @@ func restoreSnapshot(pVolOpts *rbdVolume, pSnapOpts *rbdSnapshot, cr *util.Crede // getSnapshotMetadata fetches on-disk metadata about the snapshot and populates the passed in // rbdSnapshot structure -func getSnapshotMetadata(pSnapOpts *rbdSnapshot, cr *util.Credentials) error { +func getSnapshotMetadata(ctx context.Context, pSnapOpts *rbdSnapshot, cr *util.Credentials) error { imageName := pSnapOpts.RbdImageName snapName := pSnapOpts.RbdSnapName - snapInfo, err := getSnapInfo(pSnapOpts.Monitors, cr, pSnapOpts.Pool, imageName, snapName) + snapInfo, err := getSnapInfo(ctx, pSnapOpts.Monitors, cr, pSnapOpts.Pool, imageName, snapName) if err != nil { return err } @@ -656,7 +658,7 @@ type imageInfo struct { // getImageInfo queries rbd about the given image and returns its metadata, and returns // ErrImageNotFound if provided image is not found -func getImageInfo(monitors string, cr *util.Credentials, poolName, imageName string) (imageInfo, error) { +func getImageInfo(ctx context.Context, monitors string, cr *util.Credentials, poolName, imageName string) (imageInfo, error) { // rbd --format=json info [image-spec | snap-spec] var imgInfo imageInfo @@ -670,7 +672,7 @@ func getImageInfo(monitors string, cr *util.Credentials, poolName, imageName str "--format="+"json", "info", poolName+"/"+imageName) if err != nil { - klog.Errorf("failed getting information for image (%s): (%s)", poolName+"/"+imageName, err) + klog.Errorf(util.Log(ctx, "failed getting information for image (%s): (%s)"), poolName+"/"+imageName, err) if strings.Contains(string(stderr), "rbd: error opening image "+imageName+ ": (2) No such file or directory") { return imgInfo, ErrImageNotFound{imageName, err} @@ -680,7 +682,7 @@ func getImageInfo(monitors string, cr *util.Credentials, poolName, imageName str err = json.Unmarshal(stdout, &imgInfo) if err != nil { - klog.Errorf("failed to parse JSON output of image info (%s): (%s)", + klog.Errorf(util.Log(ctx, "failed to parse JSON output of image info (%s): (%s)"), poolName+"/"+imageName, err) return imgInfo, fmt.Errorf("unmarshal failed: %+v. raw buffer response: %s", err, string(stdout)) @@ -702,7 +704,7 @@ getSnapInfo queries rbd about the snapshots of the given image and returns its m returns ErrImageNotFound if provided image is not found, and ErrSnapNotFound if provided snap is not found in the images snapshot list */ -func getSnapInfo(monitors string, cr *util.Credentials, poolName, imageName, snapName string) (snapInfo, error) { +func getSnapInfo(ctx context.Context, monitors string, cr *util.Credentials, poolName, imageName, snapName string) (snapInfo, error) { // rbd --format=json snap ls [image-spec] var ( @@ -719,7 +721,7 @@ func getSnapInfo(monitors string, cr *util.Credentials, poolName, imageName, sna "--format="+"json", "snap", "ls", poolName+"/"+imageName) if err != nil { - klog.Errorf("failed getting snap (%s) information from image (%s): (%s)", + klog.Errorf(util.Log(ctx, "failed getting snap (%s) information from image (%s): (%s)"), snapName, poolName+"/"+imageName, err) if strings.Contains(string(stderr), "rbd: error opening image "+imageName+ ": (2) No such file or directory") { @@ -730,7 +732,7 @@ func getSnapInfo(monitors string, cr *util.Credentials, poolName, imageName, sna err = json.Unmarshal(stdout, &snaps) if err != nil { - klog.Errorf("failed to parse JSON output of image snap list (%s): (%s)", + klog.Errorf(util.Log(ctx, "failed to parse JSON output of image snap list (%s): (%s)"), poolName+"/"+imageName, err) return snpInfo, fmt.Errorf("unmarshal failed: %+v. raw buffer response: %s", err, string(stdout)) diff --git a/pkg/util/log.go b/pkg/util/log.go index 514ae6f1c..bc1d2e779 100644 --- a/pkg/util/log.go +++ b/pkg/util/log.go @@ -19,133 +19,15 @@ package util import ( "context" "fmt" - - "k8s.io/klog" ) -type Verbosity struct { - level int -} - -func V(i int) *Verbosity { - return &Verbosity{level: i} -} - type contextKey string +// Key for context based logging var Key = contextKey("ID") -var id = "ID: %d " - -// INFO -func (v *Verbosity) Infof(ctx context.Context, format string, args ...interface{}) { - format = id + format - args = append([]interface{}{ctx.Value(Key)}, args...) - klog.V(klog.Level(v.level)).Infof(format, args...) -} - -func Infof(ctx context.Context, format string, args ...interface{}) { - format = id + format - args = append([]interface{}{ctx.Value(Key)}, args...) - klog.Infof(format, args...) -} - -func (v *Verbosity) Info(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf(id, ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.V(klog.Level(v.level)).Info(args...) -} - -func Info(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf(id, ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Info(args...) -} - -func (v *Verbosity) Infoln(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf("ID: %d", ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.V(klog.Level(v.level)).Infoln(args...) -} - -func Infoln(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf("ID: %d", ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Infoln(args...) -} - -// WARNING -func Warningf(ctx context.Context, format string, args ...interface{}) { - format = id + format - args = append([]interface{}{ctx.Value(Key)}, args...) - klog.Warningf(format, args...) -} - -func Warning(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf(id, ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Warning(args...) -} - -func Warningln(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf("ID: %d", ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Warningln(args...) -} - -// ERROR -func Errorf(ctx context.Context, format string, args ...interface{}) { - format = id + format - args = append([]interface{}{ctx.Value(Key)}, args...) - klog.Errorf(format, args...) -} - -func Error(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf(id, ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Error(args...) -} - -func Errorln(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf("ID: %d", ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Errorln(args...) -} - -// FATAL -func Fatalf(ctx context.Context, format string, args ...interface{}) { - format = id + format - args = append([]interface{}{ctx.Value(Key)}, args...) - klog.Fatalf(format, args...) -} - -func Fatal(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf(id, ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Fatal(args...) -} - -func Fatalln(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf("ID: %d", ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Fatalln(args...) -} - -// EXIT -func Exitf(ctx context.Context, format string, args ...interface{}) { - format = id + format - args = append([]interface{}{ctx.Value(Key)}, args...) - klog.Exitf(format, args...) -} - -func Exit(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf(id, ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Exit(args...) -} - -func Exitln(ctx context.Context, args ...interface{}) { - idString := fmt.Sprintf("ID: %d", ctx.Value(Key)) - args = append([]interface{}{idString}, args...) - klog.Exitln(args...) +// Log helps in context based logging +func Log(ctx context.Context, format string) string { + a := fmt.Sprintf("ID: %v ", ctx.Value(Key)) + return a + format }