Context based logging for rbd

Signed-off-by: Madhu Rajanna <madhupr007@gmail.com>
This commit is contained in:
Madhu Rajanna 2019-08-22 22:27:23 +05:30 committed by mergify[bot]
parent 81c28d6cb0
commit 38ca08bf65
7 changed files with 188 additions and 303 deletions

View File

@ -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) { 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) klog.V(3).Infof(util.Log(ctx, "GRPC call: %s"), info.FullMethod)
util.V(5).Infof(ctx, "GRPC request: %s", protosanitizer.StripSecrets(req)) klog.V(5).Infof(util.Log(ctx, "GRPC request: %s"), protosanitizer.StripSecrets(req))
resp, err := handler(ctx, req) resp, err := handler(ctx, req)
if err != nil { if err != nil {
util.Errorf(ctx, "GRPC error: %v", err) klog.Errorf(util.Log(ctx, "GRPC error: %v"), err)
} else { } 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 return resp, err
} }

View File

@ -41,9 +41,9 @@ type ControllerServer struct {
MetadataStore util.CachePersister 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 { 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 return err
} }
// Check sanity of request Name, Volume Capabilities // Check sanity of request Name, Volume Capabilities
@ -63,7 +63,7 @@ func (cs *ControllerServer) validateVolumeReq(req *csi.CreateVolumeRequest) erro
return nil 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 // TODO (sbezverk) Last check for not exceeding total storage capacity
isMultiNode := false 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 // 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 { if err != nil {
return nil, status.Error(codes.InvalidArgument, err.Error()) 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 // CreateVolume creates the volume in backend
func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVolumeRequest) (*csi.CreateVolumeResponse, error) { 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 return nil, err
} }
@ -118,7 +118,7 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol
} }
defer cr.DeleteCredentials() defer cr.DeleteCredentials()
rbdVol, err := cs.parseVolCreateRequest(req) rbdVol, err := cs.parseVolCreateRequest(ctx, req)
if err != nil { if err != nil {
return nil, err return nil, err
} }
@ -126,7 +126,7 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol
idLk := volumeNameLocker.Lock(req.GetName()) idLk := volumeNameLocker.Lock(req.GetName())
defer volumeNameLocker.Unlock(idLk, req.GetName()) defer volumeNameLocker.Unlock(idLk, req.GetName())
found, err := checkVolExists(rbdVol, cr) found, err := checkVolExists(ctx, rbdVol, cr)
if err != nil { if err != nil {
if _, ok := err.(ErrVolNameConflict); ok { if _, ok := err.(ErrVolNameConflict); ok {
return nil, status.Error(codes.AlreadyExists, err.Error()) return nil, status.Error(codes.AlreadyExists, err.Error())
@ -144,7 +144,7 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol
}, nil }, nil
} }
err = reserveVol(rbdVol, cr) err = reserveVol(ctx, rbdVol, cr)
if err != nil { if err != nil {
return nil, status.Error(codes.Internal, err.Error()) 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 { if err != nil {
errDefer := undoVolReservation(rbdVol, cr) errDefer := undoVolReservation(rbdVol, cr)
if errDefer != nil { 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 { if err != nil {
return nil, err return nil, err
} }
@ -171,12 +171,12 @@ func (cs *ControllerServer) CreateVolume(ctx context.Context, req *csi.CreateVol
}, nil }, 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 var err error
// if VolumeContentSource is not nil, this request is for snapshot // if VolumeContentSource is not nil, this request is for snapshot
if req.VolumeContentSource != nil { if req.VolumeContentSource != nil {
if err = cs.checkSnapshot(req, rbdVol); err != nil { if err = cs.checkSnapshot(ctx, req, rbdVol); err != nil {
return err return err
} }
} else { } else {
@ -186,18 +186,18 @@ func (cs *ControllerServer) createBackingImage(rbdVol *rbdVolume, req *csi.Creat
} }
defer cr.DeleteCredentials() defer cr.DeleteCredentials()
err = createImage(rbdVol, volSizeMiB, cr) err = createImage(ctx, rbdVol, volSizeMiB, cr)
if err != nil { 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()) 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 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() snapshot := req.VolumeContentSource.GetSnapshot()
if snapshot == nil { if snapshot == nil {
return status.Error(codes.InvalidArgument, "volume Snapshot cannot be empty") 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() defer cr.DeleteCredentials()
rbdSnap := &rbdSnapshot{} rbdSnap := &rbdSnapshot{}
if err = genSnapFromSnapID(rbdSnap, snapshotID, cr); err != nil { if err = genSnapFromSnapID(ctx, rbdSnap, snapshotID, cr); err != nil {
if _, ok := err.(ErrSnapNotFound); !ok { if _, ok := err.(ErrSnapNotFound); !ok {
return status.Error(codes.Internal, err.Error()) return status.Error(codes.Internal, err.Error())
} }
return status.Error(codes.InvalidArgument, "missing requested Snapshot ID") return status.Error(codes.InvalidArgument, "missing requested Snapshot ID")
} }
err = restoreSnapshot(rbdVol, rbdSnap, cr) err = restoreSnapshot(ctx, rbdVol, rbdSnap, cr)
if err != nil { if err != nil {
return status.Error(codes.Internal, err.Error()) 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 return nil
} }
// DeleteLegacyVolume deletes a volume provisioned using version 1.0.0 of the plugin // 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() volumeID := req.GetVolumeId()
if cs.MetadataStore == nil { if cs.MetadataStore == nil {
@ -245,7 +245,7 @@ func (cs *ControllerServer) DeleteLegacyVolume(req *csi.DeleteVolumeRequest, cr
rbdVol := &rbdVolume{} rbdVol := &rbdVolume{}
if err := cs.MetadataStore.Get(volumeID, rbdVol); err != nil { if err := cs.MetadataStore.Get(volumeID, rbdVol); err != nil {
if err, ok := err.(*util.CacheEntryNotFound); ok { 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 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 // Update rbdImageName as the VolName when dealing with version 1 volumes
rbdVol.RbdImageName = rbdVol.VolName rbdVol.RbdImageName = rbdVol.VolName
klog.V(4).Infof("deleting legacy volume %s", rbdVol.VolName) klog.V(4).Infof(util.Log(ctx, "deleting legacy volume %s"), rbdVol.VolName)
if err := deleteImage(rbdVol, cr); err != nil { if err := deleteImage(ctx, rbdVol, cr); err != nil {
// TODO: can we detect "already deleted" situations here and proceed? // 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()) return nil, status.Error(codes.Internal, err.Error())
} }
@ -278,7 +278,7 @@ func (cs *ControllerServer) DeleteLegacyVolume(req *csi.DeleteVolumeRequest, cr
// from store // from store
func (cs *ControllerServer) DeleteVolume(ctx context.Context, req *csi.DeleteVolumeRequest) (*csi.DeleteVolumeResponse, error) { 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 { 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 return nil, err
} }
@ -295,13 +295,13 @@ func (cs *ControllerServer) DeleteVolume(ctx context.Context, req *csi.DeleteVol
} }
rbdVol := &rbdVolume{} 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 // If error is ErrInvalidVolID it could be a version 1.0.0 or lower volume, attempt
// to process it as such // to process it as such
if _, ok := err.(ErrInvalidVolID); ok { if _, ok := err.(ErrInvalidVolID); ok {
if isLegacyVolumeID(volumeID) { if isLegacyVolumeID(volumeID) {
klog.V(2).Infof("attempting deletion of potential legacy volume (%s)", volumeID) klog.V(2).Infof(util.Log(ctx, "attempting deletion of potential legacy volume (%s)"), volumeID)
return cs.DeleteLegacyVolume(req, cr) return cs.DeleteLegacyVolume(ctx, req, cr)
} }
// Consider unknown volumeID as a successfully deleted volume // 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) defer volumeNameLocker.Unlock(idLk, rbdVol.RequestName)
// Deleting rbd image // Deleting rbd image
klog.V(4).Infof("deleting image %s", rbdVol.RbdImageName) klog.V(4).Infof(util.Log(ctx, "deleting image %s"), rbdVol.RbdImageName)
if err := deleteImage(rbdVol, cr); err != nil { if err := deleteImage(ctx, rbdVol, cr); err != nil {
klog.Errorf("failed to delete rbd image: %s/%s with error: %v", klog.Errorf(util.Log(ctx, "failed to delete rbd image: %s/%s with error: %v"),
rbdVol.Pool, rbdVol.RbdImageName, err) rbdVol.Pool, rbdVol.RbdImageName, err)
return nil, status.Error(codes.Internal, err.Error()) return nil, status.Error(codes.Internal, err.Error())
} }
if err := undoVolReservation(rbdVol, cr); err != nil { 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) rbdVol.RequestName, rbdVol.RbdImageName, err)
return nil, status.Error(codes.Internal, err.Error()) return nil, status.Error(codes.Internal, err.Error())
} }
@ -381,7 +381,7 @@ func (cs *ControllerServer) ValidateVolumeCapabilities(ctx context.Context, req
// in store // in store
// nolint: gocyclo // nolint: gocyclo
func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateSnapshotRequest) (*csi.CreateSnapshotResponse, error) { 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 return nil, err
} }
@ -393,7 +393,7 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS
// Fetch source volume information // Fetch source volume information
rbdVol := new(rbdVolume) rbdVol := new(rbdVolume)
err = genVolFromVolID(rbdVol, req.GetSourceVolumeId(), cr) err = genVolFromVolID(ctx, rbdVol, req.GetSourceVolumeId(), cr)
if err != nil { if err != nil {
if _, ok := err.(ErrImageNotFound); ok { if _, ok := err.(ErrImageNotFound); ok {
return nil, status.Errorf(codes.NotFound, "source Volume ID %s not found", req.GetSourceVolumeId()) 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 // Create snap volume
rbdSnap := genSnapFromOptions(rbdVol, req.GetParameters()) rbdSnap := genSnapFromOptions(ctx, rbdVol, req.GetParameters())
rbdSnap.RbdImageName = rbdVol.RbdImageName rbdSnap.RbdImageName = rbdVol.RbdImageName
rbdSnap.SizeBytes = rbdVol.VolSize rbdSnap.SizeBytes = rbdVol.VolSize
rbdSnap.SourceVolumeID = req.GetSourceVolumeId() 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 // Need to check for already existing snapshot name, and if found
// check for the requested source volume id and already allocated source volume id // 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 err != nil {
if _, ok := err.(util.ErrSnapNameConflict); ok { if _, ok := err.(util.ErrSnapNameConflict); ok {
return nil, status.Error(codes.AlreadyExists, err.Error()) return nil, status.Error(codes.AlreadyExists, err.Error())
@ -438,7 +438,7 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS
}, nil }, nil
} }
err = reserveSnap(rbdSnap, cr) err = reserveSnap(ctx, rbdSnap, cr)
if err != nil { if err != nil {
return nil, status.Error(codes.Internal, err.Error()) 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 { if err != nil {
errDefer := undoSnapReservation(rbdSnap, cr) errDefer := undoSnapReservation(rbdSnap, cr)
if errDefer != nil { 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 { if err != nil {
return nil, err return nil, err
} }
@ -467,9 +467,9 @@ func (cs *ControllerServer) CreateSnapshot(ctx context.Context, req *csi.CreateS
}, nil }, 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 { 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 return err
} }
@ -484,19 +484,19 @@ func (cs *ControllerServer) validateSnapshotReq(req *csi.CreateSnapshotRequest)
return nil return nil
} }
func (cs *ControllerServer) doSnapshot(rbdSnap *rbdSnapshot, cr *util.Credentials) (err error) { func (cs *ControllerServer) doSnapshot(ctx context.Context, rbdSnap *rbdSnapshot, cr *util.Credentials) (err error) {
err = createSnapshot(rbdSnap, cr) err = createSnapshot(ctx, rbdSnap, cr)
// If snap creation fails, even due to snapname already used, fail, next attempt will get a new // If snap creation fails, even due to snapname already used, fail, next attempt will get a new
// uuid for use as the snap name // uuid for use as the snap name
if err != nil { 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()) return status.Error(codes.Internal, err.Error())
} }
defer func() { defer func() {
if err != nil { if err != nil {
errDefer := deleteSnapshot(rbdSnap, cr) errDefer := deleteSnapshot(ctx, rbdSnap, cr)
if errDefer != nil { 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"+ err = fmt.Errorf("snapshot created but failed to delete snapshot due to"+
" other failures: %v", err) " 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 { 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()) return status.Error(codes.Internal, err.Error())
} }
defer func() { defer func() {
if err != nil { if err != nil {
errDefer := unprotectSnapshot(rbdSnap, cr) errDefer := unprotectSnapshot(ctx, rbdSnap, cr)
if errDefer != nil { 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"+ err = fmt.Errorf("snapshot created but failed to unprotect snapshot due to"+
" other failures: %v", err) " 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 { 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()) return status.Error(codes.Internal, err.Error())
} }
@ -534,7 +534,7 @@ func (cs *ControllerServer) doSnapshot(rbdSnap *rbdSnapshot, cr *util.Credential
// snapshot metadata from store // snapshot metadata from store
func (cs *ControllerServer) DeleteSnapshot(ctx context.Context, req *csi.DeleteSnapshotRequest) (*csi.DeleteSnapshotResponse, error) { 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 { 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 return nil, err
} }
@ -550,7 +550,7 @@ func (cs *ControllerServer) DeleteSnapshot(ctx context.Context, req *csi.DeleteS
} }
rbdSnap := &rbdSnapshot{} 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 // if error is ErrKeyNotFound, then a previous attempt at deletion was complete
// or partially complete (snap and snapOMap are garbage collected already), hence return // or partially complete (snap and snapOMap are garbage collected already), hence return
// success as deletion is complete // 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) defer snapshotNameLocker.Unlock(idLk, rbdSnap.RequestName)
// Unprotect snapshot // Unprotect snapshot
err = unprotectSnapshot(rbdSnap, cr) err = unprotectSnapshot(ctx, rbdSnap, cr)
if err != nil { if err != nil {
return nil, status.Errorf(codes.FailedPrecondition, return nil, status.Errorf(codes.FailedPrecondition,
"failed to unprotect snapshot: %s/%s with error: %v", "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 // Deleting snapshot
klog.V(4).Infof("deleting Snaphot %s", rbdSnap.RbdSnapName) klog.V(4).Infof(util.Log(ctx, "deleting Snaphot %s"), rbdSnap.RbdSnapName)
if err := deleteSnapshot(rbdSnap, cr); err != nil { if err := deleteSnapshot(ctx, rbdSnap, cr); err != nil {
return nil, status.Errorf(codes.FailedPrecondition, return nil, status.Errorf(codes.FailedPrecondition,
"failed to delete snapshot: %s/%s with error: %v", "failed to delete snapshot: %s/%s with error: %v",
rbdSnap.Pool, rbdSnap.RbdSnapName, err) rbdSnap.Pool, rbdSnap.RbdSnapName, err)

View File

@ -64,7 +64,7 @@ func (ns *NodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVol
if isBlock { if isBlock {
disableInUseChecks = true disableInUseChecks = true
} else { } 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`") 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 { 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 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 { if err != nil {
return nil, status.Error(codes.Internal, err.Error()) return nil, status.Error(codes.Internal, err.Error())
} }
@ -129,25 +129,25 @@ func (ns *NodeServer) NodeStageVolume(ctx context.Context, req *csi.NodeStageVol
} }
defer func() { defer func() {
if err != nil { if err != nil {
ns.undoStagingTransaction(stagingParentPath, devicePath, volID, isStagePathCreated, isMounted) ns.undoStagingTransaction(ctx, stagingParentPath, devicePath, volID, isStagePathCreated, isMounted)
} }
}() }()
// Mapping RBD image // Mapping RBD image
devicePath, err = attachRBDImage(volOptions, cr) devicePath, err = attachRBDImage(ctx, volOptions, cr)
if err != nil { if err != nil {
return nil, status.Error(codes.Internal, err.Error()) 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 { if err != nil {
return nil, status.Error(codes.Internal, err.Error()) return nil, status.Error(codes.Internal, err.Error())
} }
isStagePathCreated = true isStagePathCreated = true
// nodeStage Path // nodeStage Path
err = ns.mountVolumeToStagePath(req, stagingTargetPath, devicePath) err = ns.mountVolumeToStagePath(ctx, req, stagingTargetPath, devicePath)
if err != nil { if err != nil {
return nil, status.Error(codes.Internal, err.Error()) 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()) 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 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 var err error
stagingTargetPath := stagingParentPath + "/" + volID stagingTargetPath := stagingParentPath + "/" + volID
if isMounted { if isMounted {
err = ns.mounter.Unmount(stagingTargetPath) err = ns.mounter.Unmount(stagingTargetPath)
if err != nil { 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 return
} }
} }
@ -179,36 +179,36 @@ func (ns *NodeServer) undoStagingTransaction(stagingParentPath, devicePath, volI
if isStagePathCreated { if isStagePathCreated {
err = os.Remove(stagingTargetPath) err = os.Remove(stagingTargetPath)
if err != nil { 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 // continue on failure to unmap the image, as leaving stale images causes more issues than a stale file/directory
} }
} }
// Unmapping rbd device // Unmapping rbd device
if devicePath != "" { if devicePath != "" {
err = detachRBDDevice(devicePath) err = detachRBDDevice(ctx, devicePath)
if err != nil { 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 // continue on failure to delete the stash file, as kubernetes will fail to delete the staging path otherwise
} }
} }
// Cleanup the stashed image metadata // Cleanup the stashed image metadata
if err = cleanupRBDImageMetadataStash(stagingParentPath); err != nil { 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 return
} }
} }
func (ns *NodeServer) createStageMountPoint(mountPath string, isBlock bool) error { func (ns *NodeServer) createStageMountPoint(ctx context.Context, mountPath string, isBlock bool) error {
if isBlock { if isBlock {
pathFile, err := os.OpenFile(mountPath, os.O_CREATE|os.O_RDWR, 0750) pathFile, err := os.OpenFile(mountPath, os.O_CREATE|os.O_RDWR, 0750)
if err != nil { 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()) return status.Error(codes.Internal, err.Error())
} }
if err = pathFile.Close(); err != nil { 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()) 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) err := os.Mkdir(mountPath, 0750)
if err != nil { if err != nil {
if !os.IsExist(err) { 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()) return status.Error(codes.Internal, err.Error())
} }
} }
@ -258,7 +258,7 @@ func (ns *NodeServer) NodePublishVolume(ctx context.Context, req *csi.NodePublis
return nil, err 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 return &csi.NodePublishVolumeResponse{}, nil
} }
@ -298,7 +298,7 @@ func getLegacyVolumeName(mountPath string) (string, error) {
return volName, nil 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 // Publish Path
fsType := req.GetVolumeCapability().GetMount().GetFsType() fsType := req.GetVolumeCapability().GetMount().GetFsType()
diskMounter := &mount.SafeFormatAndMount{Interface: ns.mounter, Exec: mount.NewOsExec()} 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) err = diskMounter.FormatAndMount(devicePath, stagingPath, fsType, opt)
} }
if err != nil { 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 return err
} }
@ -325,7 +325,7 @@ func (ns *NodeServer) mountVolume(ctx context.Context, stagingPath string, req *
mountFlags := req.GetVolumeCapability().GetMount().GetMountFlags() mountFlags := req.GetVolumeCapability().GetMount().GetMountFlags()
isBlock := req.GetVolumeCapability().GetBlock() != nil isBlock := req.GetVolumeCapability().GetBlock() != nil
targetPath := req.GetTargetPath() 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) targetPath, isBlock, fsType, stagingPath, readOnly, mountFlags)
mountFlags = append(mountFlags, "bind") mountFlags = append(mountFlags, "bind")
if readOnly { if readOnly {
@ -347,11 +347,11 @@ func (ns *NodeServer) createTargetMountPath(ctx context.Context, mountPath strin
// #nosec // #nosec
pathFile, e := os.OpenFile(mountPath, os.O_CREATE|os.O_RDWR, 0750) pathFile, e := os.OpenFile(mountPath, os.O_CREATE|os.O_RDWR, 0750)
if e != nil { 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()) return notMnt, status.Error(codes.Internal, e.Error())
} }
if err = pathFile.Close(); err != nil { 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()) return notMnt, status.Error(codes.Internal, err.Error())
} }
} else { } else {
@ -381,7 +381,7 @@ func (ns *NodeServer) NodeUnpublishVolume(ctx context.Context, req *csi.NodeUnpu
if err != nil { if err != nil {
if os.IsNotExist(err) { if os.IsNotExist(err) {
// targetPath has already been deleted // 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 &csi.NodeUnpublishVolumeResponse{}, nil
} }
return nil, status.Error(codes.NotFound, err.Error()) 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()) 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 return &csi.NodeUnpublishVolumeResponse{}, nil
} }
@ -428,7 +428,7 @@ func (ns *NodeServer) NodeUnstageVolume(ctx context.Context, req *csi.NodeUnstag
// Unmounting the image // Unmounting the image
err = ns.mounter.Unmount(stagingTargetPath) err = ns.mounter.Unmount(stagingTargetPath)
if err != nil { 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()) 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 // keeps invoking Unstage. Hence any errors removing files within this path is a critical
// error // error
if !os.IsNotExist(err) { 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()) return nil, status.Error(codes.Internal, err.Error())
} }
} }
imgInfo, err := lookupRBDImageMetadataStash(stagingParentPath) imgInfo, err := lookupRBDImageMetadataStash(stagingParentPath)
if err != nil { 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 // It is an error if it was mounted, as we should have found the image metadata file with
// no errors // no errors
if !notMnt { if !notMnt {
@ -464,17 +464,16 @@ func (ns *NodeServer) NodeUnstageVolume(ctx context.Context, req *csi.NodeUnstag
// Unmapping rbd device // Unmapping rbd device
imageSpec := imgInfo.Pool + "/" + imgInfo.ImageName imageSpec := imgInfo.Pool + "/" + imgInfo.ImageName
if err = detachRBDImageOrDeviceSpec(imageSpec, true, imgInfo.NbdAccess); err != nil { if err = detachRBDImageOrDeviceSpec(ctx, imageSpec, true, imgInfo.NbdAccess); err != nil {
klog.Errorf("error unmapping volume (%s) from staging path (%s): (%v)", klog.Errorf(util.Log(ctx, "error unmapping volume (%s) from staging path (%s): (%v)"), req.GetVolumeId(), stagingTargetPath, err)
req.GetVolumeId(), stagingTargetPath, err)
return nil, status.Error(codes.Internal, err.Error()) 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) req.GetVolumeId(), stagingTargetPath)
if err = cleanupRBDImageMetadataStash(stagingParentPath); err != nil { 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()) return nil, status.Error(codes.Internal, err.Error())
} }

View File

@ -17,6 +17,7 @@ limitations under the License.
package rbd package rbd
import ( import (
"context"
"encoding/json" "encoding/json"
"fmt" "fmt"
"strconv" "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. // 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 accessType := accessTypeKRbd
if useNbdDriver { if useNbdDriver {
accessType = accessTypeNbd accessType = accessTypeNbd
@ -121,7 +122,7 @@ func findDeviceMappingImage(pool, image string, useNbdDriver bool) (string, bool
rbdDeviceList, err := rbdGetDeviceList(accessType) rbdDeviceList, err := rbdGetDeviceList(accessType)
if err != nil { 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 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. // 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++ { for i := 0; i < maxRetries; i++ {
if i != 0 { if i != 0 {
time.Sleep(time.Second) time.Sleep(time.Second)
} }
device, found := findDeviceMappingImage(pool, image, useNbdDriver) device, found := findDeviceMappingImage(ctx, pool, image, useNbdDriver)
if found { if found {
return device, found return device, found
} }
@ -165,7 +166,7 @@ func checkRbdNbdTools() bool {
return true 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 var err error
image := volOptions.RbdImageName image := volOptions.RbdImageName
@ -174,7 +175,7 @@ func attachRBDImage(volOptions *rbdVolume, cr *util.Credentials) (string, error)
useNBD = true useNBD = true
} }
devicePath, found := waitForPath(volOptions.Pool, image, 1, useNBD) devicePath, found := waitForPath(ctx, volOptions.Pool, image, 1, useNBD)
if !found { if !found {
backoff := wait.Backoff{ backoff := wait.Backoff{
Duration: rbdImageWatcherInitDelay, Duration: rbdImageWatcherInitDelay,
@ -182,23 +183,23 @@ func attachRBDImage(volOptions *rbdVolume, cr *util.Credentials) (string, error)
Steps: rbdImageWatcherSteps, Steps: rbdImageWatcherSteps,
} }
err = waitForrbdImage(backoff, volOptions, cr) err = waitForrbdImage(ctx, backoff, volOptions, cr)
if err != nil { if err != nil {
return "", err return "", err
} }
devicePath, err = createPath(volOptions, cr) devicePath, err = createPath(ctx, volOptions, cr)
} }
return devicePath, err 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 isNbd := false
image := volOpt.RbdImageName image := volOpt.RbdImageName
imagePath := fmt.Sprintf("%s/%s", volOpt.Pool, image) 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 // Map options
mapOptions := []string{ mapOptions := []string{
@ -221,12 +222,12 @@ func createPath(volOpt *rbdVolume, cr *util.Credentials) (string, error) {
// Execute map // Execute map
output, err := execCommand(rbd, mapOptions) output, err := execCommand(rbd, mapOptions)
if err != nil { 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 // unmap rbd image if connection timeout
if strings.Contains(err.Error(), rbdMapConnectionTimeout) { if strings.Contains(err.Error(), rbdMapConnectionTimeout) {
detErr := detachRBDImageOrDeviceSpec(imagePath, true, isNbd) detErr := detachRBDImageOrDeviceSpec(ctx, imagePath, true, isNbd)
if detErr != nil { 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)) 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 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 image := volOptions.RbdImageName
imagePath := fmt.Sprintf("%s/%s", volOptions.Pool, image) imagePath := fmt.Sprintf("%s/%s", volOptions.Pool, image)
err := wait.ExponentialBackoff(backoff, func() (bool, error) { err := wait.ExponentialBackoff(backoff, func() (bool, error) {
used, rbdOutput, err := rbdStatus(volOptions, cr) used, rbdOutput, err := rbdStatus(ctx, volOptions, cr)
if err != nil { if err != nil {
return false, fmt.Errorf("fail to check rbd image status with: (%v), rbd output: (%s)", err, rbdOutput) return false, fmt.Errorf("fail to check rbd image status with: (%v), rbd output: (%s)", err, rbdOutput)
} }
if (volOptions.DisableInUseChecks) && (used) { 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
} }
return !used, nil return !used, nil
@ -259,18 +260,18 @@ func waitForrbdImage(backoff wait.Backoff, volOptions *rbdVolume, cr *util.Crede
return err return err
} }
func detachRBDDevice(devicePath string) error { func detachRBDDevice(ctx context.Context, devicePath string) error {
nbdType := false nbdType := false
if strings.HasPrefix(devicePath, "/dev/nbd") { if strings.HasPrefix(devicePath, "/dev/nbd") {
nbdType = true nbdType = true
} }
return detachRBDImageOrDeviceSpec(devicePath, false, nbdType) return detachRBDImageOrDeviceSpec(ctx, devicePath, false, nbdType)
} }
// detachRBDImageOrDeviceSpec detaches an rbd imageSpec or devicePath, with additional checking // detachRBDImageOrDeviceSpec detaches an rbd imageSpec or devicePath, with additional checking
// when imageSpec is used to decide if image is already unmapped // 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 err error
var output []byte 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(rbdUnmapCmdkRbdMissingMap, imageOrDeviceSpec)) ||
strings.Contains(string(output), fmt.Sprintf(rbdUnmapCmdNbdMissingMap, imageOrDeviceSpec))) { strings.Contains(string(output), fmt.Sprintf(rbdUnmapCmdNbdMissingMap, imageOrDeviceSpec))) {
// Devices found not to be mapped are treated as a successful detach // 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 nil
} }
return fmt.Errorf("rbd: unmap for spec (%s) failed (%v): (%s)", imageOrDeviceSpec, err, string(output)) return fmt.Errorf("rbd: unmap for spec (%s) failed (%v): (%s)", imageOrDeviceSpec, err, string(output))

View File

@ -20,6 +20,7 @@ import (
"fmt" "fmt"
"github.com/ceph/ceph-csi/pkg/util" "github.com/ceph/ceph-csi/pkg/util"
"golang.org/x/net/context"
"github.com/pkg/errors" "github.com/pkg/errors"
"k8s.io/klog" "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 request name lock, and hence any stale omaps are leftovers from incomplete transactions and are
hence safe to garbage collect. 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) err := validateRbdSnap(rbdSnap)
if err != nil { if err != nil {
return false, err return false, err
@ -124,7 +125,7 @@ func checkSnapExists(rbdSnap *rbdSnapshot, cr *util.Credentials) (bool, error) {
rbdSnap.RbdSnapName = snapJournal.NamingPrefix() + snapUUID rbdSnap.RbdSnapName = snapJournal.NamingPrefix() + snapUUID
// Fetch on-disk image attributes // Fetch on-disk image attributes
err = updateSnapWithImageInfo(rbdSnap, cr) err = updateSnapWithImageInfo(ctx, rbdSnap, cr)
if err != nil { if err != nil {
if _, ok := err.(ErrSnapNotFound); ok { if _, ok := err.(ErrSnapNotFound); ok {
err = snapJournal.UndoReservation(rbdSnap.Monitors, cr, rbdSnap.Pool, err = snapJournal.UndoReservation(rbdSnap.Monitors, cr, rbdSnap.Pool,
@ -141,7 +142,7 @@ func checkSnapExists(rbdSnap *rbdSnapshot, cr *util.Credentials) (bool, error) {
return false, err 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) rbdSnap.SnapID, rbdSnap.RbdSnapName, rbdSnap.RequestName)
return true, nil 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 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. 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) err := validateRbdVol(rbdVol)
if err != nil { if err != nil {
return false, err 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 // save it for size checks before fetching image data
requestSize := rbdVol.VolSize requestSize := rbdVol.VolSize
// Fetch on-disk image attributes and compare against request // Fetch on-disk image attributes and compare against request
err = updateVolWithImageInfo(rbdVol, cr) err = updateVolWithImageInfo(ctx, rbdVol, cr)
if err != nil { if err != nil {
if _, ok := err.(ErrImageNotFound); ok { if _, ok := err.(ErrImageNotFound); ok {
err = volJournal.UndoReservation(rbdVol.Monitors, cr, rbdVol.Pool, err = volJournal.UndoReservation(rbdVol.Monitors, cr, rbdVol.Pool,
@ -200,7 +201,7 @@ func checkVolExists(rbdVol *rbdVolume, cr *util.Credentials) (bool, error) {
return false, err 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) rbdVol.VolID, rbdVol.RbdImageName, rbdVol.RequestName)
return true, nil 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 // reserveSnap is a helper routine to request a rbdSnapshot name reservation and generate the
// volume ID for the generated name // 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, snapUUID, err := snapJournal.ReserveName(rbdSnap.Monitors, cr, rbdSnap.Pool,
rbdSnap.RequestName, rbdSnap.RbdImageName) rbdSnap.RequestName, rbdSnap.RbdImageName)
if err != nil { if err != nil {
@ -223,7 +224,7 @@ func reserveSnap(rbdSnap *rbdSnapshot, cr *util.Credentials) error {
rbdSnap.RbdSnapName = snapJournal.NamingPrefix() + snapUUID 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) rbdSnap.SnapID, rbdSnap.RbdImageName, rbdSnap.RequestName)
return nil 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 // reserveVol is a helper routine to request a rbdVolume name reservation and generate the
// volume ID for the generated name // 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, imageUUID, err := volJournal.ReserveName(rbdVol.Monitors, cr, rbdVol.Pool,
rbdVol.RequestName, "") rbdVol.RequestName, "")
if err != nil { if err != nil {
@ -246,7 +247,7 @@ func reserveVol(rbdVol *rbdVolume, cr *util.Credentials) error {
rbdVol.RbdImageName = volJournal.NamingPrefix() + imageUUID 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) rbdVol.VolID, rbdVol.RbdImageName, rbdVol.RequestName)
return nil return nil

View File

@ -27,6 +27,7 @@ import (
"time" "time"
"github.com/ceph/ceph-csi/pkg/util" "github.com/ceph/ceph-csi/pkg/util"
"golang.org/x/net/context"
"github.com/golang/protobuf/ptypes" "github.com/golang/protobuf/ptypes"
"github.com/golang/protobuf/ptypes/timestamp" "github.com/golang/protobuf/ptypes/timestamp"
@ -114,16 +115,17 @@ var (
) )
// createImage creates a new ceph image with provision and volume options. // 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 var output []byte
image := pOpts.RbdImageName image := pOpts.RbdImageName
volSzMiB := fmt.Sprintf("%dM", volSz) volSzMiB := fmt.Sprintf("%dM", volSz)
if pOpts.ImageFormat == rbdImageFormat2 { 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 { } 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} 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 { 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. // rbdStatus checks if there is watcher on the image.
// It returns true if there is a watcher on the image, otherwise returns false. // 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 output string
var cmd []byte var cmd []byte
image := pOpts.RbdImageName 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} args := []string{"status", image, "--pool", pOpts.Pool, "-m", pOpts.Monitors, "--id", cr.ID, "--keyfile=" + cr.KeyFile}
cmd, err := execCommand("rbd", args) cmd, err := execCommand("rbd", args)
output = string(cmd) output = string(cmd)
if err, ok := err.(*exec.Error); ok { if err, ok := err.(*exec.Error); ok {
if err.Err == exec.ErrNotFound { 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 // fail fast if command not found
return false, output, err return false, output, err
} }
@ -165,16 +167,16 @@ func rbdStatus(pOpts *rbdVolume, cr *util.Credentials) (bool, string, error) {
} }
if strings.Contains(output, imageWatcherStr) { 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 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 return false, output, nil
} }
// rbdManagerTaskDelete adds a ceph manager task to delete an rbd image, thus deleting // 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 // 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 var output []byte
args := []string{"rbd", "task", "add", "remove", args := []string{"rbd", "task", "add", "remove",
@ -188,8 +190,8 @@ func rbdManagerTaskDeleteImage(pOpts *rbdVolume, cr *util.Credentials) (bool, er
if err != nil { if err != nil {
if strings.Contains(string(output), rbdTaskRemoveCmdInvalidString1) && if strings.Contains(string(output), rbdTaskRemoveCmdInvalidString1) &&
strings.Contains(string(output), rbdTaskRemoveCmdInvalidString2) { strings.Contains(string(output), rbdTaskRemoveCmdInvalidString2) {
klog.Infof("cluster with cluster ID (%s) does not support Ceph manager based rbd image"+ 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) " deletion (minimum ceph version required is v14.2.3)"), pOpts.ClusterID)
return false, err 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. // 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 var output []byte
image := pOpts.RbdImageName image := pOpts.RbdImageName
found, _, err := rbdStatus(pOpts, cr) found, _, err := rbdStatus(ctx, pOpts, cr)
if err != nil { if err != nil {
return err return err
} }
if found { 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) 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 // attempt to use Ceph manager based deletion support if available
rbdCephMgrSupported, err := rbdManagerTaskDeleteImage(pOpts, cr) rbdCephMgrSupported, err := rbdManagerTaskDeleteImage(ctx, pOpts, cr)
if !rbdCephMgrSupported { if !rbdCephMgrSupported {
// attempt older style deletion // attempt older style deletion
args := []string{"rm", image, "--pool", pOpts.Pool, "--id", cr.ID, "-m", pOpts.Monitors, 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 { 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 return err
@ -231,8 +233,8 @@ func deleteImage(pOpts *rbdVolume, cr *util.Credentials) error {
// updateSnapWithImageInfo updates provided rbdSnapshot with information from on-disk data // updateSnapWithImageInfo updates provided rbdSnapshot with information from on-disk data
// regarding the same // regarding the same
func updateSnapWithImageInfo(rbdSnap *rbdSnapshot, cr *util.Credentials) error { func updateSnapWithImageInfo(ctx context.Context, rbdSnap *rbdSnapshot, cr *util.Credentials) error {
snapInfo, err := getSnapInfo(rbdSnap.Monitors, cr, rbdSnap.Pool, snapInfo, err := getSnapInfo(ctx, rbdSnap.Monitors, cr, rbdSnap.Pool,
rbdSnap.RbdImageName, rbdSnap.RbdSnapName) rbdSnap.RbdImageName, rbdSnap.RbdSnapName)
if err != nil { if err != nil {
return err return err
@ -252,8 +254,8 @@ func updateSnapWithImageInfo(rbdSnap *rbdSnapshot, cr *util.Credentials) error {
// updateVolWithImageInfo updates provided rbdVolume with information from on-disk data // updateVolWithImageInfo updates provided rbdVolume with information from on-disk data
// regarding the same // regarding the same
func updateVolWithImageInfo(rbdVol *rbdVolume, cr *util.Credentials) error { func updateVolWithImageInfo(ctx context.Context, rbdVol *rbdVolume, cr *util.Credentials) error {
imageInfo, err := getImageInfo(rbdVol.Monitors, cr, rbdVol.Pool, rbdVol.RbdImageName) imageInfo, err := getImageInfo(ctx, rbdVol.Monitors, cr, rbdVol.Pool, rbdVol.RbdImageName)
if err != nil { if err != nil {
return err return err
} }
@ -272,7 +274,7 @@ func updateVolWithImageInfo(rbdVol *rbdVolume, cr *util.Credentials) error {
// genSnapFromSnapID generates a rbdSnapshot structure from the provided identifier, updating // genSnapFromSnapID generates a rbdSnapshot structure from the provided identifier, updating
// the structure with elements from on-disk snapshot metadata as well // 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 ( var (
options map[string]string options map[string]string
vi util.CSIIdentifier vi util.CSIIdentifier
@ -283,7 +285,7 @@ func genSnapFromSnapID(rbdSnap *rbdSnapshot, snapshotID string, cr *util.Credent
err := vi.DecomposeCSIID(rbdSnap.SnapID) err := vi.DecomposeCSIID(rbdSnap.SnapID)
if err != nil { 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 return err
} }
@ -291,7 +293,7 @@ func genSnapFromSnapID(rbdSnap *rbdSnapshot, snapshotID string, cr *util.Credent
options["clusterID"] = rbdSnap.ClusterID options["clusterID"] = rbdSnap.ClusterID
rbdSnap.RbdSnapName = snapJournal.NamingPrefix() + vi.ObjectUUID rbdSnap.RbdSnapName = snapJournal.NamingPrefix() + vi.ObjectUUID
rbdSnap.Monitors, _, err = getMonsAndClusterID(options) rbdSnap.Monitors, _, err = getMonsAndClusterID(ctx, options)
if err != nil { if err != nil {
return err return err
} }
@ -307,14 +309,14 @@ func genSnapFromSnapID(rbdSnap *rbdSnapshot, snapshotID string, cr *util.Credent
return err return err
} }
err = updateSnapWithImageInfo(rbdSnap, cr) err = updateSnapWithImageInfo(ctx, rbdSnap, cr)
return err return err
} }
// genVolFromVolID generates a rbdVolume structure from the provided identifier, updating // genVolFromVolID generates a rbdVolume structure from the provided identifier, updating
// the structure with elements from on-disk image metadata as well // 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 ( var (
options map[string]string options map[string]string
vi util.CSIIdentifier vi util.CSIIdentifier
@ -335,7 +337,7 @@ func genVolFromVolID(rbdVol *rbdVolume, volumeID string, cr *util.Credentials) e
options["clusterID"] = rbdVol.ClusterID options["clusterID"] = rbdVol.ClusterID
rbdVol.RbdImageName = volJournal.NamingPrefix() + vi.ObjectUUID rbdVol.RbdImageName = volJournal.NamingPrefix() + vi.ObjectUUID
rbdVol.Monitors, _, err = getMonsAndClusterID(options) rbdVol.Monitors, _, err = getMonsAndClusterID(ctx, options)
if err != nil { if err != nil {
return err return err
} }
@ -351,7 +353,7 @@ func genVolFromVolID(rbdVol *rbdVolume, volumeID string, cr *util.Credentials) e
return err return err
} }
err = updateVolWithImageInfo(rbdVol, cr) err = updateVolWithImageInfo(ctx, rbdVol, cr)
return err return err
} }
@ -362,7 +364,7 @@ func execCommand(command string, args []string) ([]byte, error) {
return cmd.CombinedOutput() 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 var ok bool
if clusterID, ok = options["clusterID"]; !ok { 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 { 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) err = errors.Wrapf(err, "failed to fetch monitor list using clusterID (%s)", clusterID)
return return
} }
@ -438,7 +440,7 @@ func updateMons(rbdVol *rbdVolume, options, credentials map[string]string) error
return nil 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 ( var (
ok bool ok bool
err error err error
@ -456,7 +458,7 @@ func genVolFromVolumeOptions(volOptions, credentials map[string]string, disableI
return nil, err return nil, err
} }
} else { } else {
rbdVol.Monitors, rbdVol.ClusterID, err = getMonsAndClusterID(volOptions) rbdVol.Monitors, rbdVol.ClusterID, err = getMonsAndClusterID(ctx, volOptions)
if err != nil { if err != nil {
return nil, err 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.DisableInUseChecks = disableInUseChecks
rbdVol.Mounter, ok = volOptions["mounter"] rbdVol.Mounter, ok = volOptions["mounter"]
@ -494,13 +496,13 @@ func genVolFromVolumeOptions(volOptions, credentials map[string]string, disableI
return rbdVol, nil 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 var err error
rbdSnap := &rbdSnapshot{} rbdSnap := &rbdSnapshot{}
rbdSnap.Pool = rbdVol.Pool rbdSnap.Pool = rbdVol.Pool
rbdSnap.Monitors, rbdSnap.ClusterID, err = getMonsAndClusterID(snapOptions) rbdSnap.Monitors, rbdSnap.ClusterID, err = getMonsAndClusterID(ctx, snapOptions)
if err != nil { if err != nil {
rbdSnap.Monitors = rbdVol.Monitors rbdSnap.Monitors = rbdVol.Monitors
rbdSnap.ClusterID = rbdVol.ClusterID rbdSnap.ClusterID = rbdVol.ClusterID
@ -519,13 +521,13 @@ func hasSnapshotFeature(imageFeatures string) bool {
return false return false
} }
func protectSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { func protectSnapshot(ctx context.Context, pOpts *rbdSnapshot, cr *util.Credentials) error {
var output []byte var output []byte
image := pOpts.RbdImageName image := pOpts.RbdImageName
snapName := pOpts.RbdSnapName 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", args := []string{"snap", "protect", "--pool", pOpts.Pool, "--snap", snapName, image, "--id",
cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile} cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile}
@ -538,13 +540,13 @@ func protectSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error {
return nil return nil
} }
func createSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { func createSnapshot(ctx context.Context, pOpts *rbdSnapshot, cr *util.Credentials) error {
var output []byte var output []byte
image := pOpts.RbdImageName image := pOpts.RbdImageName
snapName := pOpts.RbdSnapName 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, args := []string{"snap", "create", "--pool", pOpts.Pool, "--snap", snapName, image,
"--id", cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile} "--id", cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile}
@ -557,13 +559,13 @@ func createSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error {
return nil return nil
} }
func unprotectSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { func unprotectSnapshot(ctx context.Context, pOpts *rbdSnapshot, cr *util.Credentials) error {
var output []byte var output []byte
image := pOpts.RbdImageName image := pOpts.RbdImageName
snapName := pOpts.RbdSnapName 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", args := []string{"snap", "unprotect", "--pool", pOpts.Pool, "--snap", snapName, image, "--id",
cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile} cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile}
@ -576,13 +578,13 @@ func unprotectSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error {
return nil return nil
} }
func deleteSnapshot(pOpts *rbdSnapshot, cr *util.Credentials) error { func deleteSnapshot(ctx context.Context, pOpts *rbdSnapshot, cr *util.Credentials) error {
var output []byte var output []byte
image := pOpts.RbdImageName image := pOpts.RbdImageName
snapName := pOpts.RbdSnapName 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", args := []string{"snap", "rm", "--pool", pOpts.Pool, "--snap", snapName, image, "--id",
cr.ID, "-m", pOpts.Monitors, "--keyfile=" + cr.KeyFile} 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 { 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) pOpts.RequestName, pOpts.RbdSnapName, pOpts.RbdImageName, err)
} }
return nil 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 var output []byte
image := pVolOpts.RbdImageName image := pVolOpts.RbdImageName
snapName := pSnapOpts.RbdSnapName 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, args := []string{"clone", pSnapOpts.Pool + "/" + pSnapOpts.RbdImageName + "@" + snapName,
pVolOpts.Pool + "/" + image, "--id", cr.ID, "-m", pVolOpts.Monitors, "--keyfile=" + cr.KeyFile} 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 // getSnapshotMetadata fetches on-disk metadata about the snapshot and populates the passed in
// rbdSnapshot structure // rbdSnapshot structure
func getSnapshotMetadata(pSnapOpts *rbdSnapshot, cr *util.Credentials) error { func getSnapshotMetadata(ctx context.Context, pSnapOpts *rbdSnapshot, cr *util.Credentials) error {
imageName := pSnapOpts.RbdImageName imageName := pSnapOpts.RbdImageName
snapName := pSnapOpts.RbdSnapName 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 { if err != nil {
return err return err
} }
@ -656,7 +658,7 @@ type imageInfo struct {
// getImageInfo queries rbd about the given image and returns its metadata, and returns // getImageInfo queries rbd about the given image and returns its metadata, and returns
// ErrImageNotFound if provided image is not found // 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] // rbd --format=json info [image-spec | snap-spec]
var imgInfo imageInfo var imgInfo imageInfo
@ -670,7 +672,7 @@ func getImageInfo(monitors string, cr *util.Credentials, poolName, imageName str
"--format="+"json", "--format="+"json",
"info", poolName+"/"+imageName) "info", poolName+"/"+imageName)
if err != nil { 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+ if strings.Contains(string(stderr), "rbd: error opening image "+imageName+
": (2) No such file or directory") { ": (2) No such file or directory") {
return imgInfo, ErrImageNotFound{imageName, err} return imgInfo, ErrImageNotFound{imageName, err}
@ -680,7 +682,7 @@ func getImageInfo(monitors string, cr *util.Credentials, poolName, imageName str
err = json.Unmarshal(stdout, &imgInfo) err = json.Unmarshal(stdout, &imgInfo)
if err != nil { 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) poolName+"/"+imageName, err)
return imgInfo, fmt.Errorf("unmarshal failed: %+v. raw buffer response: %s", return imgInfo, fmt.Errorf("unmarshal failed: %+v. raw buffer response: %s",
err, string(stdout)) 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 returns ErrImageNotFound if provided image is not found, and ErrSnapNotFound if provided snap
is not found in the images snapshot list 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] // rbd --format=json snap ls [image-spec]
var ( var (
@ -719,7 +721,7 @@ func getSnapInfo(monitors string, cr *util.Credentials, poolName, imageName, sna
"--format="+"json", "--format="+"json",
"snap", "ls", poolName+"/"+imageName) "snap", "ls", poolName+"/"+imageName)
if err != nil { 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) snapName, poolName+"/"+imageName, err)
if strings.Contains(string(stderr), "rbd: error opening image "+imageName+ if strings.Contains(string(stderr), "rbd: error opening image "+imageName+
": (2) No such file or directory") { ": (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) err = json.Unmarshal(stdout, &snaps)
if err != nil { 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) poolName+"/"+imageName, err)
return snpInfo, fmt.Errorf("unmarshal failed: %+v. raw buffer response: %s", return snpInfo, fmt.Errorf("unmarshal failed: %+v. raw buffer response: %s",
err, string(stdout)) err, string(stdout))

View File

@ -19,133 +19,15 @@ package util
import ( import (
"context" "context"
"fmt" "fmt"
"k8s.io/klog"
) )
type Verbosity struct {
level int
}
func V(i int) *Verbosity {
return &Verbosity{level: i}
}
type contextKey string type contextKey string
// Key for context based logging
var Key = contextKey("ID") var Key = contextKey("ID")
var id = "ID: %d " // Log helps in context based logging
func Log(ctx context.Context, format string) string {
// INFO a := fmt.Sprintf("ID: %v ", ctx.Value(Key))
func (v *Verbosity) Infof(ctx context.Context, format string, args ...interface{}) { return a + format
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...)
} }