[2015-11-02 13:00:09,680] DEBUG: Workflow : mount started with workflow id : 927 [2015-11-02 13:00:09,680] DEBUG: Version: Snap Creator Framework 4.1.2 [2015-11-02 13:00:09,680] DEBUG: Profile: SCCASE [2015-11-02 13:00:09,680] DEBUG: Config: ORA_mount_start [2015-11-02 13:00:09,680] DEBUG: Action: mount [2015-11-02 13:00:09,680] DEBUG: Plugin: null [2015-11-02 13:00:09,680] DEBUG: Policy: null [2015-11-02 13:00:09,680] DEBUG: Volume Name: OVM_DB7_Data,OVM_DB7_Fra [2015-11-02 13:00:09,680] DEBUG: Snapshot Name: SC_hotORA_recent ########## Agent validation ########## [2015-11-02 13:00:09,811] INFO: Application commands and plug-in not defined. Skipping Agent validation task ########## Plugin validation ########## [2015-11-02 13:00:09,814] INFO: Application not defined. Skipping Plugin validation task ########## Pre Clone Create commands ########## [2015-11-02 13:00:09,833] INFO: Pre Clone Create commands are not defined [2015-11-02 13:00:09,833] INFO: Pre Clone Create commands finished successfully ########## Performing cloning on controller 192.168.8.176 ########## [2015-11-02 13:00:09,867] INFO: Creating Volume Clone from Snapshot copy SC_hotORA-daily_recent of 192.168.8.176:OVM_DB7_Data [2015-11-02 13:00:16,160] INFO: STORAGE-02036: Creating clone [cl_ORA_mount_start_OVM_DB7_Data_20151102130009] of volume [OVM_DB7_Data] based on Snapshot copy [SC_hotORA-daily_recent] [2015-11-02 13:00:16,160] DEBUG: OVM_DB7_Data SC_hotORA-daily_recent cl_ORA_mount_start_OVM_DB7_Data_20151102130009 none /cl_ORA_mount_start_OVM_DB7_Data_20151102130009 true [2015-11-02 13:00:16,160] INFO: STORAGE-02037: Creating clone [cl_ORA_mount_start_OVM_DB7_Data_20151102130009] of volume [OVM_DB7_Data] based on Snapshot copy [SC_hotORA-daily_recent] finished successfully. [2015-11-02 13:00:16,160] INFO: Creating Volume Clone from Snapshot copy SC_hotORA-daily_recent of 192.168.8.176:OVM_DB7_Fra [2015-11-02 13:00:18,808] INFO: STORAGE-02036: Creating clone [cl_ORA_mount_start_OVM_DB7_Fra_20151102130009] of volume [OVM_DB7_Fra] based on Snapshot copy [SC_hotORA-daily_recent] [2015-11-02 13:00:18,808] DEBUG: OVM_DB7_Fra SC_hotORA-daily_recent cl_ORA_mount_start_OVM_DB7_Fra_20151102130009 none /cl_ORA_mount_start_OVM_DB7_Fra_20151102130009 true [2015-11-02 13:00:18,808] INFO: STORAGE-02037: Creating clone [cl_ORA_mount_start_OVM_DB7_Fra_20151102130009] of volume [OVM_DB7_Fra] based on Snapshot copy [SC_hotORA-daily_recent] finished successfully. [2015-11-02 13:00:18,808] INFO: Skipping igroup mapping for filer192.168.8.176, the NTAP_CLONE_IGROUP_MAP parameter in config is empty ########## PRE MOUNT COMMANDS ########## [2015-11-02 13:00:51,889] INFO: SCF-00203: Executing [Pre mount] command [/SC41/OSAP_cDOT/sc_clone_rename.py config/OVM_DB7.luns ORA_mount_start 20151102130009 "^DATA|^FRA"] on server [2015-11-02 13:00:51,889] INFO: stdout:### Snap Creator Clone Rename - start timestamp: 2015-11-02 13:00:18.915408 ### Renaming volume cl_ORA_mount_start_OVM_DB7_Data_20151102130009 to OVM_DB7_Data_clone on 192.168.8.222 .... renamed Renaming LUN /vol/OVM_DB7_Data_clone/ovm_db7_data1.lun to /vol/OVM_DB7_Data_clone/ovm_db7_data1_clone.lun .... renamed Renaming LUN /vol/OVM_DB7_Data_clone/ovm_db7_data2.lun to /vol/OVM_DB7_Data_clone/ovm_db7_data2_clone.lun .... renamed Renaming volume cl_ORA_mount_start_OVM_DB7_Fra_20151102130009 to OVM_DB7_Fra_clone on 192.168.8.222 .... renamed Renaming LUN /vol/OVM_DB7_Fra_clone/ovm_db7_fra1.lun to /vol/OVM_DB7_Fra_clone/ovm_db7_fra1_clone.lun .... renamed Renaming LUN /vol/OVM_DB7_Fra_clone/ovm_db7_fra2.lun to /vol/OVM_DB7_Fra_clone/ovm_db7_fra2_clone.lun .... renamed 2 clones volumes and 4 cloned LUNs have been renamed. ### Snap Creator Clone Rename - finish timestamp: 2015-11-02 13:00:44.580398 ### [2015-11-02 13:00:51,889] DEBUG: Pre mount: /SC41/OSAP_cDOT/sc_clone_rename.py config/OVM_DB7.luns ORA_mount_start 20151102130009 "^DATA|^FRA" finished with exit code: 0 [2015-11-02 13:00:51,889] INFO: SCF-00203: Executing [Pre mount] command [/SC41/OSAP_cDOT/sc_clone_setlunserial.py config/OVM_DB7.luns "^DATA|^FRA"] on server [2015-11-02 13:00:51,889] INFO: stdout:### Snap Creator Clone LUN Set Serial - start timestamp: 2015-11-02 13:00:44.642541 ### Setting LUN 192.168.8.222:/vol/OVM_DB7_Data_clone/ovm_db7_data1_clone.lun to offline ... LUN is now offline Changing LUN 192.168.8.222:/vol/OVM_DB7_Data_clone/ovm_db7_data1_clone.lun serial number from Pgg8b$Gjg4z4 to Pgg8b$Gjg4wc ... done! Setting LUN 192.168.8.222:/vol/OVM_DB7_Data_clone/ovm_db7_data1_clone.lun to online ... LUN is now online Setting LUN 192.168.8.222:/vol/OVM_DB7_Data_clone/ovm_db7_data2_clone.lun to offline ... LUN is now offline Changing LUN 192.168.8.222:/vol/OVM_DB7_Data_clone/ovm_db7_data2_clone.lun serial number from Pgg8b$Gjg4z5 to Pgg8b$Gjg4wd ... done! Setting LUN 192.168.8.222:/vol/OVM_DB7_Data_clone/ovm_db7_data2_clone.lun to online ... LUN is now online Setting LUN 192.168.8.222:/vol/OVM_DB7_Fra_clone/ovm_db7_fra1_clone.lun to offline ... LUN is now offline Changing LUN 192.168.8.222:/vol/OVM_DB7_Fra_clone/ovm_db7_fra1_clone.lun serial number from Pgg8b$Gjg4z6 to Pgg8b$Gjg4wi ... done! Setting LUN 192.168.8.222:/vol/OVM_DB7_Fra_clone/ovm_db7_fra1_clone.lun to online ... LUN is now online Setting LUN 192.168.8.222:/vol/OVM_DB7_Fra_clone/ovm_db7_fra2_clone.lun to offline ... LUN is now offline Changing LUN 192.168.8.222:/vol/OVM_DB7_Fra_clone/ovm_db7_fra2_clone.lun serial number from Pgg8b$Gjg4z7 to Pgg8b$Gjg4wj ... done! Setting LUN 192.168.8.222:/vol/OVM_DB7_Fra_clone/ovm_db7_fra2_clone.lun to online ... LUN is now online 4 cloned LUNs serial numbers have been changed ### Snap Creator Clone LUN Set Serial - finish timestamp: 2015-11-02 13:00:51.879961 ### [2015-11-02 13:00:51,889] DEBUG: Pre mount: /SC41/OSAP_cDOT/sc_clone_setlunserial.py config/OVM_DB7.luns "^DATA|^FRA" finished with exit code: 0 [2015-11-02 13:00:51,889] INFO: Pre mount completed successfully [2015-11-02 13:00:51,889] INFO: Pre Mount commands finished successfully ########## MOUNT COMMANDS ########## [2015-11-02 13:00:53,917] INFO: SCF-00203: Executing [Mount] command [/SC41/OSAP_cDOT/sc_clone_lunmap.py config/OVM_DB7.luns "^DATA|^FRA"] on server [2015-11-02 13:00:53,917] INFO: stdout:### Snap Creator Clone LUN mapping - start timestamp: 2015-11-02 13:00:51.977084 ### Mapping LUN 192.168.8.222:/vol/OVM_DB7_Data_clone/ovm_db7_data1_clone.lun to IGRP OVM_access_group as ID 21 ... mapped Mapping LUN 192.168.8.222:/vol/OVM_DB7_Data_clone/ovm_db7_data2_clone.lun to IGRP OVM_access_group as ID 22 ... mapped Mapping LUN 192.168.8.222:/vol/OVM_DB7_Fra_clone/ovm_db7_fra1_clone.lun to IGRP OVM_access_group as ID 23 ... mapped Mapping LUN 192.168.8.222:/vol/OVM_DB7_Fra_clone/ovm_db7_fra2_clone.lun to IGRP OVM_access_group as ID 24 ... mapped 4 LUNs have been mapped. ### Snap Creator Clone LUN mapping - finish timestamp: 2015-11-02 13:00:53.908799 ### [2015-11-02 13:00:53,917] DEBUG: Mount: /SC41/OSAP_cDOT/sc_clone_lunmap.py config/OVM_DB7.luns "^DATA|^FRA" finished with exit code: 0 [2015-11-02 13:00:53,918] INFO: Mount completed successfully ########## MOUNT COMMANDS FINISHED SUCCESSFULLY ########## ########## POST MOUNT COMMANDS ########## [2015-11-02 13:03:45,000] INFO: [192.168.8.103:9090 (4.1.1.1)] Executing Post mount command [/opt/NetApp/OSAP/sc_oradb_recovery_log.sh mount wait 3] on 192.168.8.103 [2015-11-02 13:03:45,000] TRACE: Command [/opt/NetApp/OSAP/sc_oradb_recovery_log.sh mount wait 3] finished with exit code: [0] stdout: [Start! Time stamp: 2015-11-02 13:00:57 Mounting ASM disk groups +DB1DATA and +DB1FRA Mount +DB1DATA ... OK Time stamp: 2015-11-02 13:01:04 Mount +DB1FRA ... OK Time stamp: 2015-11-02 13:01:04] stderr: [] [2015-11-02 13:03:45,000] DEBUG: [192.168.8.103:9090 (4.1.1.1)] Command [/opt/NetApp/OSAP/sc_oradb_recovery_log.sh mount wait 3] finished successfully with message [Start! Time stamp: 2015-11-02 13:00:57 Mounting ASM disk groups +DB1DATA and +DB1FRA Mount +DB1DATA ... OK Time stamp: 2015-11-02 13:01:04 Mount +DB1FRA ... OK Time stamp: 2015-11-02 13:01:04] [2015-11-02 13:03:45,000] INFO: [192.168.8.103:9090 (4.1.1.1)] Executing Post mount command [/opt/NetApp/OSAP/sc_oradb_recovery_log.sh recover ] on 192.168.8.103 [2015-11-02 13:03:45,000] TRACE: Command [/opt/NetApp/OSAP/sc_oradb_recovery_log.sh recover ] finished with exit code: [-1] stdout: [Failed to execute command: /opt/NetApp/OSAP/sc_oradb_recovery_log.sh recover Reason: null] stderr: [] [2015-11-02 13:03:45,001] ERROR: [192.168.8.103:9090 (4.1.1.1)] Command [/opt/NetApp/OSAP/sc_oradb_recovery_log.sh recover ] failed with return code [-1] and stderr [] and stdout [Failed to execute command: /opt/NetApp/OSAP/sc_oradb_recovery_log.sh recover Reason: null] [2015-11-02 13:03:45,003] DEBUG: Workflow : mount_OnFailure started with workflow id : 928 ########## Agent Workflow Finalization ########## [2015-11-02 13:03:45,004] INFO: Agent Workflow Finalization started [2015-11-02 13:03:50,196] INFO: [192.168.8.103:9090 (4.1.1.1)] Finalized workflow with id 927 [2015-11-02 13:03:50,196] INFO: Agent Workflow Finalization finished successfully ########## Snap Creator Framework 4.1.2 failed ########## [2015-11-02 13:03:50,207] INFO: Pre Exit commands are not defined. Skipping !