ViPR Controller:  Volume creation on VNX fails

           

   Article Number:     525550                                   Article Version: 3     Article Type:    Break Fix 
   

 


Product:

 

ViPR Controller,ViPR Controller Controller 3.6 SP2,ViPR Controller Controller 3.6 SP1,ViPR Controller Controller 3.6,ViPR Controller Controller 3.5,SMI-S Provider,SMI-S Provider 4.6,SMI-S Provider 4.6.2,VNX2 Series

 

Issue:

 

 

The user is unable to create a volume on VNX.   
    The order fails intermittently but on a regular basis.    
   
    Issue persists after running refsys, rebooting the SMI-S Server, and restarting ECOM.   
    The volume remains on array after failure.  Resubmitting the order will fail using the same volume name.   
   
    ViPR Controller UI error   

      [ERROR] Wed Aug 29 10:58:09 UTC 2018 Error 16000: Message: The job has failed: Caught an exception while trying to update volume attributes:       
        The requested object cannot be found. (com.emc.cmp.osls.se.osl.Device.StorDevShow():280 C:ERROR_CLASS_SOFTWARE F:ERROR_FAMILY_NOT_FOUND R:1000052 L:2 C:ERROR_CLASS_SOFTWARE F:ERROR_FAMILY_NOT_FOUND R:1000052 No objects of the requested type were found : 2 : 7 : "The device name specified could not be found")
     
     
     
      Note:       
      An RPQ is required with respect to SMI-S for VNX block per the support matrix available here:   

   

      https://community.emc.com/docs/DOC-57470   

   

      Also reference the following KB article:   

   

      523574 : ViPR Controller: ViPR Controller use of Solutions Enabler 7.6.2.102 / SMI-S 4.6.2.30 requires an RPQ https://support.emc.com/kb/523574 (Level 40 article)   

                                                             

 

 

Cause:

 

 

After SMI-S reports that the volume has been successfully created, ViPR C queries SMI-S to gather information about the volume to update the ViPR C database.  SMI-S is unable to provide this information when requested.     
   
    The cause of this issue is currently being investigated.   
   
    Since the volume information is not provided by SMI-S, ViPR Controller's rollback does not remove the volume from the array.
                                                           

 

 

Change:

 

 

This issue occurs after users upgrade VNX code to: VNX: 05.33.009.5.218                                                           

 

 

Resolution:

 

 

   

      Resolution:     
      ViPR Engineering is currently addressing this problem, but has not provided a fix in a released patch. This solution will be updated with the patch when it has been released.     
          

                                                             

 

 

Notes:

 

 

   

     
      NOTE:  When volume creation fails , the backend volume is left in place and will need to be manually removed from the array.     
     
      ViPR C logs     
     
      ViPR C issues command to create volume:   

   
      vipr2 vipr2 controllersvc 2018-09-03 14:25:31,763 [1684|createVolumes|39a39976-b004-45e9-98c7-f1e463d25517c83c9b0f-fe18-485b-85c3-cdd8b25f2a8d]  INFO  SmisStorageDevice.java (line 226) Create Volume Start - Array:CKM<CLARiiON Serial Number removed>, Pool:CLARIION+CKM<CLARiiON Serial Number removed>+POOL+<Pool Name removed>       
        Volume:<Volume Name removed> , IsThinlyProvisioned: true       
        vipr2 vipr2 controllersvc 2018-09-03 14:25:31,776 [1684|createVolumes|39a39976-b004-45e9-98c7-f1e463d25517c83c9b0f-fe18-485b-85c3-cdd8b25f2a8d]  INFO  SmisCommandHelper.java (line 201)        
        SMI-S Provider: <SMI-S Provider FQDN removed> -- Attempting invokeMethod CreateOrModifyElementFromStoragePool on       
          objectPath=/root/emc:Clar_StorageConfigurationService.CreationClassName="Clar_StorageConfigurationService",Name="EMCStorageConfigurationService",SystemCreationClassName="Clar_StorageSystem",SystemName="CLARiiON+CKM<CLARiiON Serial Number removed>" with arguments:        
            inArg[0]=uint16 ElementType = 5;       
            inArg[1]=Clar_UnifiedStoragePool ref InPool = "root/emc:Clar_UnifiedStoragePool.InstanceID=\"CLARiiON+CKM<CLARiiON Serial Number removed>+<Pool Name removed>\"";       
            inArg[2]=uint64 Size = 10737418240;       
            inArg[3]=uint32 EMCNumberOfDevices = 1;       
            inArg[4]=string ElementName = "<Volume Name removed>";       
            inArg[5]=Clar_StoragePoolSetting ref Goal = "root/emc:Clar_StoragePoolSetting.InstanceID=\"CLARiiON+CKM<CLARiiON Serial Number removed>+D+T+3031128139+<Pool Name removed>\"";
   
   
     
               
      SMI-S Provider Logs:   
   
      SMI-S receives the order and provides a concrete id.   
   
      Mon Sep 03 16:25:29 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 2013263616 global DEBUG SE_StorageHardwareID.cpp 414 : Store the array id in the context to scope populate: NS_CMP_OSLS_SE_ARRAY_FUNC::SE_StorageHardwareID::ContextArrayId       
        Mon Sep 03 16:25:31 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 2013263616 StorageConfigurationService.BlockServices DEBUG EMC_StorageConfigurationService.cpp 1887 : Element size: 10737418240       
        Mon Sep 03 16:25:31 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 2013263616 global DEBUG  163 : OslCache missing cache entry for array <Array type="CLARiiON" encoding="String" value="CKM<CLARiiON Serial Number removed>" />       
        Mon Sep 03 16:25:32 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 2013263616 global INFO Job.cpp 459 : Job <SMI-S Concrete ID replaced 1234567890> Submitted       
        Mon Sep 03 16:25:32 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 2013263616 StorageConfigurationService.BlockServices DEBUG EMC_StorageConfigurationService.cpp 2705 : Submit jobId <SMI-S Concrete ID replaced 1234567890> to run asynchronously       
        Mon Sep 03 16:25:32 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 2013263616 JobControl INFO JobTableMonitor.cpp 61 : Job table monitor started.       
        Mon Sep 03 16:25:32 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 -1272031488 JobControl DEBUG JobTableMonitor.cpp 88 : Job table monitor started.       
        Mon Sep 03 16:25:32 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 2013263616 JobControl DEBUG JobTable.cpp 107 : Added to job table job id: <SMI-S Concrete ID replaced 1234567890>       
        Mon Sep 03 16:25:32 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 -1269930240 BlockServices.JobControlVolume DEBUG JOB_VolCreate.cpp 400 : Create Storage Volume Job Id:<SMI-S Concrete ID replaced 1234567890>       
        Mon Sep 03 16:25:32 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 2013263616 JobControl INFO JobControl.cpp 86 : Started job: <SMI-S Concrete ID replaced 1234567890>
   
   
     
     
       SMI-S logs:     
       SMI-S reports that volume creation is complete:   
   
      Mon Sep 03 16:28:02 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 -1269930240 BlockServices.JobControlVolume DEBUG JOB_VolCreate.cpp 621 : Completed performImmediateSync().       
        Mon Sep 03 16:28:02 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 -1269930240 BlockServices.JobControlVolume DEBUG JOB_VolCreate.cpp 1891 : Completed performImmediateSync().       
        Mon Sep 03 16:28:02 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 -1269930240 BlockServices.JobControlVolume INFO JOB_VolCreate.cpp 1908 : Created volume: <Device name="<DeviceID replaced 12345>" />       
        Mon Sep 03 16:28:02 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 -1269930240 global INFO Job.cpp 584 : Marked job 100% completed, Job id: <SMI-S Concrete ID replaced 1234567890>
   
   
     
      ViPR logs:     
      ViPR logs indicate that the SMI-S job is complete:   
   
      vipr2 vipr2 controllersvc 2018-09-03 14:28:02,394 [pool-58-thread-1]  INFO  SmisJob.java (line 178) SmisJob: Looking up job: id <SMI-S Concrete ID replaced 1234567890>, provider: <SMI-S Provider FQDN removed>       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:02,413 [pool-58-thread-1]  INFO  SmisJob.java (line 197) Status value[0]: 17       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:02,413 [pool-58-thread-1]  INFO  SmisJob.java (line 197) Status value[1]: 2       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:02,413 [pool-58-thread-1]  INFO  SmisJob.java (line 200) SmisJob: <SMI-S Concrete ID replaced 1234567890> succeeded       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:02,413 [pool-58-thread-1]  INFO  SmisJob.java (line 243) SmisJob: Post processing job: id <SMI-S Concrete ID replaced 1234567890>, provider: <SMI-S Provider FQDN removed>
   
   
     
     
      SMI-S logs:     
      After the volume was successfully created, ViPR Controller queries SMI-S to update the database, but SMI-S is unable to provided details on the volume.   
   
      Mon Sep 03 16:28:03 +0200 2018 <SMI-S Provider Name removed> ECOM 26037 -1269930240 global DEBUG  307 : StorDevShow() failed with handle="65537", arrayId="<Array type="CLARiiON" encoding="String" value="CKM<CLARiiON Serial Number removed>" />", deviceId="<Device name="<DeviceID replaced 12345>" />", mask="4079755".   
   
     
     
      ViPR logs:     
      This error is passed to ViPR C from SMI-S and the order fails.  Since the volume was not found when querying SMI-S the volume is not removed from the array on rollback:   
   
          
   
      vipr2 vipr2 controllersvc 2018-09-03 14:28:03,081 [pool-58-thread-1] ERROR  SmisAbstractCreateVolumeJob.java (line 331) Caught an exception while trying to update attributes for volume <Volume Name removed> (<Volume URN removed>) and volume path //<IP Address removed>/root/emc:Clar_StorageVolume.CreationClassName="Clar_StorageVolume",DeviceID="<DeviceID replaced 12345>",SystemCreationClassName="Clar_StorageSystem",SystemName="CLARiiON+CKM<CLARiiON Serial Number removed>"       
        WBEMException: CIM_ERR_NOT_FOUND (The requested object cannot be found. (com.emc.cmp.osls.se.osl.Device.StorDevShow():280 C:ERROR_CLASS_SOFTWARE F:ERROR_FAMILY_NOT_FOUND R:1000052 L:2 C:ERROR_CLASS_SOFTWARE F:ERROR_FAMILY_NOT_FOUND R:1000052 No objects of the requested type were found : 2 : 7 : "The device name specified could not be found"))       
            at org.sblim.cimclient.internal.wbem.CloseableIteratorSAX.hasNext(CloseableIteratorSAX.java:121)       
            at org.sblim.cimclient.internal.wbem.WBEMClientCIMXML.getIterator(WBEMClientCIMXML.java:2134)       
            at org.sblim.cimclient.internal.wbem.WBEMClientCIMXML.getInstance(WBEMClientCIMXML.java:1257)       
            at com.emc.storageos.volumecontroller.impl.smis.job.SmisAbstractCreateVolumeJob.commonVolumeUpdate(SmisAbstractCreateVolumeJob.java:311)       
            at com.emc.storageos.volumecontroller.impl.smis.job.SmisAbstractCreateVolumeJob.processVolume(SmisAbstractCreateVolumeJob.java:219)       
            at com.emc.storageos.volumecontroller.impl.smis.job.SmisAbstractCreateVolumeJob.updateStatus(SmisAbstractCreateVolumeJob.java:120)       
            at com.emc.storageos.volumecontroller.impl.smis.job.SmisJob.poll(SmisJob.java:246)       
            at com.emc.storageos.volumecontroller.impl.job.QueueJobTracker.run(QueueJobTracker.java:90)       
            at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)       
            at java.util.concurrent.FutureTask.run(FutureTask.java:266)       
            at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)       
            at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)       
            at java.lang.Thread.run(Thread.java:748)       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:03,097 [pool-58-thread-1]  INFO  SmisAbstractCreateVolumeJob.java (line 372) Skipping step addVolumesToConsistencyGroup: volumes [<Volume URN removed>] do not reference a consistency group.       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:03,097 [pool-58-thread-1]  INFO  SmisAbstractCreateVolumeJob.java (line 158) Updating status of job 39a39976-b004-45e9-98c7-f1e463d25517c83c9b0f-fe18-485b-85c3-cdd8b25f2a8d to SUCCESS       
        Created volume successfully .. NativeId: <DeviceID replaced 12345>, URI: <Volume URN removed>       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:03,101 [pool-58-thread-1]  INFO  VolumeTaskCompleter.java (line 106) opType: CREATE_BLOCK_VOLUME detail: VolumeCreateFailed:Volume is created.       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:03,103 [pool-58-thread-1]  INFO  VolumeTaskCompleter.java (line 82) Bourne VolumeCreateFailed event recorded for Volume <Volume URN removed>       
        vipr2 vipr2 controllersvc 2018-09-03 14:28:03,126 [pool-58-thread-1]  INFO  WorkflowService.java (line 653) Updating workflow step: 39a39976-b004-45e9-98c7-f1e463d25517c83c9b0f-fe18-485b-85c3-cdd8b25f2a8d state ERROR : The job has failed: Caught an exception while trying to update volume attributes: The requested object cannot be found. (com.emc.cmp.osls.se.osl.Device.StorDevShow():280 C:ERROR_CLASS_SOFTWARE F:ERROR_FAMILY_NOT_FOUND R:1000052 L:2 C:ERROR_CLASS_SOFTWARE F:ERROR_FAMILY_NOT_FOUND R:1000052 No objects of the requested type were found : 2 : 7 : "The device name specified could not be found")