SnapCreator and vSphere 5

[ricardoduarte]

Hi there,

Currently, SnapCreator is not able to gather the datastore list from vSphere 5 hosts/vCenter (vCenterDatastoreNotFoundException).

Is there a plan to add support for it? If so, is there already a timeline for it?

Thanks.

[Arora_Kapil]

Yes, this will be fixed in the upcoming community release.

Until then, you can use try using CLI, or create/update the config manually.

Thanks,

Kapil

[ricardoduarte]

Hi there.

Is there a way, by using the CLI or manual config, to get SC to quisce the vSphere 5 VMs?

Regards.

[Arora_Kapil]

Yes, you can do that.

Create a configuration using none option, just to select the filer details and other options.You can select any volume as vmware plugin is finally going to overwrite that.

Open the config file in a text editor and

1) update APP_NAME = vibe

2) Search for  VIBE Custom Settings and set the parameters as per the description.

Once done you can open the config in GUi and run as usual.

Hope this helps.

Thanks,

Kapil

[ricardoduarte]

Hi,

By following your instructions I was able to setup it and get my snapshots running.

But I now have a problem: the VMware snapshots created by Snap Creator are not being deleted after the snapshot creation.

As far as I can see, unquisce only checks the first VM in the inventory. No log entries are shown for any of the other VMs running on the host.

Can you help me on this?

Thanks.

[ktenzer]

Can you send the log file .out and .debug logs? Do you get an error somewhere?

Keith

[ricardoduarte]

Hi Keith,

Here are some prints:

########## Application quiesce ##########

[Fri Sep 23 11:05:57 2011] INFO: Checking if VIBE pre-requisites already run (function: quiesce) ....

[Fri Sep 23 11:05:57 2011] INFO: Discovery already completed -- not re-running prerequisites.

[Fri Sep 23 11:05:57 2011] INFO: Creating vSphere snapshots (if applicable) ...

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot for VM vm1 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking power state of VM vm1 ...

[Fri Sep 23 11:05:57 2011] INFO: Power state of VM vm1 is off, not taking snapshot.

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot for VM vm2 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking power state of VM vm2 ...

[Fri Sep 23 11:05:57 2011] INFO: Power state of VM vm2 t is off, not taking snapshot.

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot for VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking power state of VM vm3...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking snapshot capability of  VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Removing leftover snapshots for VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot of VM vm3 (attempt #1) ...

[Fri Sep 23 11:06:02 2011] DEBUG: Creation of snapshot for VM vm3 successful.

[Fri Sep 23 11:06:35 2011] INFO: Snapshot creation process completed successfully.

(...)

########## PRE APPLICATION UNQUIESCE COMMANDS ##########

[Fri Sep 23 11:06:38 2011] INFO: No commands defined

########## PRE APPLICATION UNQUIESCE COMMANDS FINISHED SUCCESSFULLY ##########

########## Application unquiesce ##########

[Fri Sep 23 11:06:38 2011] INFO: Checking if VIBE pre-requisites already run (function: unquiesce) ....

[Fri Sep 23 11:06:38 2011] INFO: Discovery already completed -- not re-running prerequisites.

[Fri Sep 23 11:06:38 2011] INFO: Removing snapshots (if applicable)

[Fri Sep 23 11:06:38 2011] DEBUG: Checking power state of VM vm1 ...

[Fri Sep 23 11:06:38 2011] INFO: Power state of VM vm1 is off, not taking snapshot.

########## POST APPLICATION UNQUIESCE COMMANDS ##########

[Fri Sep 23 11:06:38 2011] INFO: No commands defined

########## POST APPLICATION UNQUIESCE COMMANDS FINISHED SUCCESSFULLY ##########

(...)

########## NetApp Snap Creator Framework finished successfully ##########

[Fri Sep 23 11:06:38 2011] INFO: INFO: NetApp Snap Creator Framework finished successfully ( Action: snap )

[Fri Sep 23 11:06:38 2011] DEBUG: Exiting with error code - 0

[ktenzer]

Snap Creator is not taking vmware snapshots so there are no vmware snapshots to delete

########## Application unquiesce ##########

[Fri Sep 23 11:06:38 2011] INFO: Checking if VIBE pre-requisites already run (function: unquiesce) ....

[Fri Sep 23 11:06:38 2011] INFO: Discovery already completed -- not re-running prerequisites.

[Fri Sep 23 11:06:38 2011] INFO: Removing snapshots (if applicable)

[Fri Sep 23 11:06:38 2011] DEBUG: Checking power state of VM vm1 ...

[Fri Sep 23 11:06:38 2011] INFO: Power state of VM vm1 is off, not taking snapshot.

The VM is powered off. If we detect VM is powered off we dont delete snapshots, so any snapshots created previously would also not be deleted.

The only time we create and delete vmware snapshots is when the VM is powered ON. If it is powered OFF there is no reason to take vmware snapshots as the VM is not running and is in a consistent state.

Hope this helps

Regards,

Keith

[ricardoduarte]

I'm aware of that.

This is just a small subset of my VMs. My regular backup set consists in 10 powered on VMs and 5 powered off.

This set has 1 powered on VM (vm3) and 2 powered off.

Snap Creator creates the snapshots on the powered on VM, but does not remove it in the end.

This happens on my larger set as well.

You can see that from the log:

Snap creator never deletes the snapshot it creates for vm3.

[Fri Sep 23 11:05:57 2011] DEBUG: Checking snapshot capability of  VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Removing leftover snapshots for VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot of VM vm3 (attempt #1) ...

[Fri Sep 23 11:06:02 2011] DEBUG: Creation of snapshot for VM vm3 successful.

########## Application unquiesce ##########

--> !!!! You can't see anything related to vm2 here (should have an entry similar to vm1) !!!!! <--

--> !!!! You can't see anything related to vm3 here (should have the snapshot delete entry) !!!!! <--

In the end of the backup, the powered on vm3 will have a Snap Creator snapshot.

Regards.

[ktenzer]

Ok like I said we need full logs

We will look at it, You should be able to attach logs somehow there is a way to attach things

This could be a bug, issue is we dont support vSphere 5 (yet), support is comming with next release so we havent done much testing against vSphere 5. We will help you either way so just get us logs and we will send it to our QA team. It might be a few days or week till we can test a mix of powered on and powered off VMs under vSphere 5.

One thing that would be interesting. Can you test what happens if you backup only VMs that are powered on? Does it then remove the VMware snapshot?

Regards,

Keith

[ricardoduarte]

Full log:

[Fri Sep 23 11:05:53 2011] DEBUG: GMT - Fri Sep 23 10:05:53 2011

[Fri Sep 23 11:05:53 2011] DEBUG: Version: NetApp Snap Creator Framework 3.4p1

[Fri Sep 23 11:05:53 2011] DEBUG: Profile: vmware

[Fri Sep 23 11:05:53 2011] DEBUG: Config Type: STANDARD

[Fri Sep 23 11:05:53 2011] DEBUG: Action: snap

[Fri Sep 23 11:05:53 2011] DEBUG: Plugin: vibe

[Fri Sep 23 11:05:53 2011] DEBUG: Policy: daily

[Fri Sep 23 11:05:53 2011] DEBUG: Snapshot Name: daily-daily_recent

[Fri Sep 23 11:05:53 2011] DEBUG: Timestamp: 20110923110553

########## Parsing Environment Parameters ##########

[Fri Sep 23 11:05:53 2011] DEBUG: Parsing VOLUMES - filer: auto volume: detect

[Fri Sep 23 11:05:53 2011] DEBUG: Parsing NTAP_USERS - filer: 10.245.70.1 user: admin

[Fri Sep 23 11:05:53 2011] DEBUG: Parsing NTAP_SNAPSHOT_RETENTIONS - policy: daily retention: 10

########## PRE APPLICATION QUIESCE COMMANDS ##########

[Fri Sep 23 11:05:53 2011] INFO: No commands defined

########## PRE APPLICATION QUIESCE COMMANDS FINISHED SUCCESSFULLY ##########

########## Application Auto Discovery ##########

[Fri Sep 23 11:05:53 2011] INFO: Checking if VIBE pre-requisites already run (function: discover) ....

[Fri Sep 23 11:05:53 2011] INFO: Executing VIBE configuration.

[Fri Sep 23 11:05:53 2011] INFO: Initializing connectivity to vCenter(s) and storage appliance(s) ...

[Fri Sep 23 11:05:53 2011] DEBUG: Converting vCenter hostname(s) to IP address(es) ...

[Fri Sep 23 11:05:53 2011] DEBUG: Attempting to ping vCenter server 10.245.7.7 ...

[Fri Sep 23 11:05:53 2011] DEBUG: Ping of vCenter server successful.

[Fri Sep 23 11:05:53 2011] DEBUG: Logging into vCenter server 10.245.7.7 ...

[Fri Sep 23 11:05:54 2011] DEBUG: vCenter server login successful.

[Fri Sep 23 11:05:54 2011] DEBUG: Updating vCenter name/object for VM  ...

[Fri Sep 23 11:05:54 2011] DEBUG: Attempting to ping storage appliance 10.245.70.1 ...

[Fri Sep 23 11:05:54 2011] DEBUG: Ping of storage appliance 10.245.70.1 successful.

[Fri Sep 23 11:05:54 2011] DEBUG: Testing login to storage appliance 10.245.70.1 ...

[Fri Sep 23 11:05:54 2011] DEBUG: Adding IP address 10.245.4.1 for storage appliance 10.245.70.1 ...

[Fri Sep 23 11:05:54 2011] DEBUG: Adding IP address 10.245.70.1 for storage appliance 10.245.70.1 ...

[Fri Sep 23 11:05:54 2011] DEBUG: Adding IP address 10.245.70.6 for storage appliance 10.245.70.1 ...

[Fri Sep 23 11:05:54 2011] DEBUG: Adding IP address 10.245.50.3 for storage appliance 10.245.70.1 ...

[Fri Sep 23 11:05:54 2011] DEBUG: Adding IP address 10.245.51.4 for storage appliance 10.245.70.1 ...

[Fri Sep 23 11:05:54 2011] DEBUG: Storage appliance login successful.

[Fri Sep 23 11:05:54 2011] DEBUG: Collecting vSphere and storage appliance configuration data ...

[Fri Sep 23 11:05:54 2011] DEBUG: Collecting datacenter information ...

[Fri Sep 23 11:05:54 2011] DEBUG: Found 1 Datacenter(s).

[Fri Sep 23 11:05:54 2011] INFO: Collecting list of VirtualMachine objects planned for snapshots ...

[Fri Sep 23 11:05:56 2011] INFO: Updating VirtualMachine objects planned for snapshots ...

[Fri Sep 23 11:05:56 2011] INFO: Collection of VirtualMachine objects successful.

[Fri Sep 23 11:05:56 2011] DEBUG: Parsing list of VMs for list of datastore names ...

[Fri Sep 23 11:05:56 2011] DEBUG: Searching for Datastore netapp_datastore02 ...

[Fri Sep 23 11:05:56 2011] DEBUG: Requested Datastore (netapp_datastore02) is available.

[Fri Sep 23 11:05:56 2011] INFO: Collecting VM information on NFS Datastore netapp_datastore02.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine list on Datastore netapp_datastore02.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm1.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm2.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm3.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm4.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm5.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm6.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm7.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm8.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm9.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm10.

[Fri Sep 23 11:05:56 2011] DEBUG: Saving virtual machine information for vm11.

[Fri Sep 23 11:05:57 2011] DEBUG: Saving virtual machine information for vm12.

[Fri Sep 23 11:05:57 2011] DEBUG: Saving virtual machine information for vm13.

[Fri Sep 23 11:05:57 2011] DEBUG: Saving virtual machine information for vm14.

[Fri Sep 23 11:05:57 2011] DEBUG: Saving virtual machine information for vm15.

[Fri Sep 23 11:05:57 2011] DEBUG: Saving virtual machine information for vm17.

[Fri Sep 23 11:05:57 2011] DEBUG: Saving virtual machine information for vm18.

[Fri Sep 23 11:05:57 2011] DEBUG: Saving virtual machine information for vm19.

[Fri Sep 23 11:05:57 2011] DEBUG: Saving virtual machine information for vm20.

[Fri Sep 23 11:05:57 2011] DEBUG: Checking to ensure our list of storage appliances is correct for all Datastores ...

[Fri Sep 23 11:05:57 2011] INFO: Saving VOLUMES entry "10.245.70.1:datastore002".

[Fri Sep 23 11:05:57 2011] INFO: Setting VOLUMES environment variable for Snap Creator to "10.245.70.1:datastore002".

[Fri Sep 23 11:05:57 2011] INFO: ENV Parameter VOLUMES set in plugin vibe

[Fri Sep 23 11:05:57 2011] DEBUG: Old value for VOLUMES is auto:detect

[Fri Sep 23 11:05:57 2011] DEBUG: New value for VOLUMES is 10.245.70.1:datastore002

[Fri Sep 23 11:05:57 2011] INFO: Config File D:/Program Files/Netapp/NetApp Snap Creator Framework/scServer3.4p1/configs/vmware/config1.conf successfully updated

########## Parsing Environment Parameters ##########

[Fri Sep 23 11:05:57 2011] DEBUG: Parsing VOLUMES - filer: 10.245.70.1 volume: datastore002

[Fri Sep 23 11:05:57 2011] DEBUG: Parsing NTAP_USERS - filer: 10.245.70.1 user: admin

[Fri Sep 23 11:05:57 2011] DEBUG: Parsing NTAP_SNAPSHOT_RETENTIONS - policy: daily retention: 10

########## Application quiesce ##########

[Fri Sep 23 11:05:57 2011] INFO: Checking if VIBE pre-requisites already run (function: quiesce) ....

[Fri Sep 23 11:05:57 2011] INFO: Discovery already completed -- not re-running prerequisites.

[Fri Sep 23 11:05:57 2011] INFO: Creating vSphere snapshots (if applicable) ...

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot for VM vm1 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking power state of VM vm1 ...

[Fri Sep 23 11:05:57 2011] INFO: Power state of VM vm1 is off, not taking snapshot.

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot for VM vm2 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking power state of VM vm2 ...

[Fri Sep 23 11:05:57 2011] INFO: Power state of VM vm2 is off, not taking snapshot.

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot for VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking power state of VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking snapshot capability of VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Removing leftover snapshots for VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot of VM vm3 (attempt #1) ...

[Fri Sep 23 11:06:02 2011] DEBUG: Creation of snapshot for VM vm3 successful.

[Fri Sep 23 11:06:02 2011] DEBUG: Creating snapshot for VM vm4 ...

[Fri Sep 23 11:06:02 2011] DEBUG: Checking power state of VM vm4 ...

[Fri Sep 23 11:06:02 2011] INFO: Power state of VM vm4 is off, not taking snapshot.

[Fri Sep 23 11:06:02 2011] DEBUG: Creating snapshot for VM vm5 ...

[Fri Sep 23 11:06:02 2011] DEBUG: Checking power state of VM vm5 ...

[Fri Sep 23 11:06:02 2011] DEBUG: Checking snapshot capability of VM vm5 ...

[Fri Sep 23 11:06:02 2011] DEBUG: Removing leftover snapshots for VM vm5 ...

[Fri Sep 23 11:06:02 2011] DEBUG: Creating snapshot of VM vm5 (attempt #1) ...

[Fri Sep 23 11:06:06 2011] DEBUG: Creation of snapshot for VM vm5 successful.

[Fri Sep 23 11:06:06 2011] DEBUG: Creating snapshot for VM vm6 ...

[Fri Sep 23 11:06:06 2011] DEBUG: Checking power state of VM vm6 ...

[Fri Sep 23 11:06:06 2011] DEBUG: Checking snapshot capability of VM vm6 ...

[Fri Sep 23 11:06:06 2011] DEBUG: Removing leftover snapshots for VM vm6 ...

[Fri Sep 23 11:06:06 2011] DEBUG: Creating snapshot of VM vm6 (attempt #1) ...

[Fri Sep 23 11:06:10 2011] DEBUG: Creation of snapshot for VM vm6 successful.

[Fri Sep 23 11:06:10 2011] DEBUG: Creating snapshot for VM vm7 ...

[Fri Sep 23 11:06:10 2011] DEBUG: Checking power state of VM vm7 ...

[Fri Sep 23 11:06:10 2011] DEBUG: Checking snapshot capability of VM vm7 ...

[Fri Sep 23 11:06:10 2011] DEBUG: Removing leftover snapshots for VM vm7 ...

[Fri Sep 23 11:06:10 2011] DEBUG: Creating snapshot of VM vm7 (attempt #1) ...

[Fri Sep 23 11:06:12 2011] DEBUG: Creation of snapshot for VM vm7 successful.

[Fri Sep 23 11:06:12 2011] DEBUG: Creating snapshot for VM vm8 ...

[Fri Sep 23 11:06:12 2011] DEBUG: Checking power state of VM vm8 ...

[Fri Sep 23 11:06:12 2011] INFO: Power state of VM vm8 is off, not taking snapshot.

[Fri Sep 23 11:06:12 2011] DEBUG: Creating snapshot for VM vm9 ...

[Fri Sep 23 11:06:12 2011] DEBUG: Checking power state of VM vm9 ...

[Fri Sep 23 11:06:12 2011] DEBUG: Checking snapshot capability of VM vm9 ...

[Fri Sep 23 11:06:12 2011] DEBUG: Removing leftover snapshots for VM vm9 ...

[Fri Sep 23 11:06:13 2011] DEBUG: Creating snapshot of VM vm9 (attempt #1) ...

[Fri Sep 23 11:06:17 2011] DEBUG: Creation of snapshot for VM vm9 successful.

[Fri Sep 23 11:06:17 2011] DEBUG: Creating snapshot for VM vm10 ...

[Fri Sep 23 11:06:17 2011] DEBUG: Checking power state of VM vm10 ...

[Fri Sep 23 11:06:17 2011] DEBUG: Checking snapshot capability of VM vm10 ...

[Fri Sep 23 11:06:17 2011] DEBUG: Removing leftover snapshots for VM vm10 ...

[Fri Sep 23 11:06:17 2011] DEBUG: Creating snapshot of VM vm10 (attempt #1) ...

[Fri Sep 23 11:06:19 2011] DEBUG: Creation of snapshot for VM vm10 successful.

[Fri Sep 23 11:06:19 2011] DEBUG: Creating snapshot for VM vm11 ...

[Fri Sep 23 11:06:19 2011] DEBUG: Checking power state of VM vm11 ...

[Fri Sep 23 11:06:19 2011] DEBUG: Checking snapshot capability of VM vm11 ...

[Fri Sep 23 11:06:19 2011] DEBUG: Removing leftover snapshots for VM vm11 ...

[Fri Sep 23 11:06:19 2011] DEBUG: Creating snapshot of VM vm11 (attempt #1) ...

[Fri Sep 23 11:06:21 2011] DEBUG: Creation of snapshot for VM vm11 successful.

[Fri Sep 23 11:06:21 2011] DEBUG: Creating snapshot for VM vm12 ...

[Fri Sep 23 11:06:21 2011] DEBUG: Checking power state of VM vm12 ...

[Fri Sep 23 11:06:21 2011] INFO: Power state of VM vm12 is off, not taking snapshot.

[Fri Sep 23 11:06:21 2011] DEBUG: Creating snapshot for VM vm13 ...

[Fri Sep 23 11:06:21 2011] DEBUG: Checking power state of VM vm13 ...

[Fri Sep 23 11:06:21 2011] DEBUG: Checking snapshot capability of VM vm13 ...

[Fri Sep 23 11:06:21 2011] DEBUG: Removing leftover snapshots for VM vm13 ...

[Fri Sep 23 11:06:21 2011] DEBUG: Creating snapshot of VM vm13 (attempt #1) ...

[Fri Sep 23 11:06:23 2011] DEBUG: Creation of snapshot for VM vm13 successful.

[Fri Sep 23 11:06:23 2011] DEBUG: Creating snapshot for VM vm14 ...

[Fri Sep 23 11:06:23 2011] DEBUG: Checking power state of VM vm14 ...

[Fri Sep 23 11:06:23 2011] DEBUG: Checking snapshot capability of VM vm14 ...

[Fri Sep 23 11:06:23 2011] DEBUG: Removing leftover snapshots for VM vm14 ...

[Fri Sep 23 11:06:24 2011] DEBUG: Creating snapshot of VM vm14 (attempt #1) ...

[Fri Sep 23 11:06:26 2011] DEBUG: Creation of snapshot for VM vm14 successful.

[Fri Sep 23 11:06:26 2011] DEBUG: Creating snapshot for VM vm15 ...

[Fri Sep 23 11:06:26 2011] DEBUG: Checking power state of VM vm15 ...

[Fri Sep 23 11:06:26 2011] DEBUG: Checking snapshot capability of VM vm15 ...

[Fri Sep 23 11:06:26 2011] DEBUG: Removing leftover snapshots for VM vm15 ...

[Fri Sep 23 11:06:26 2011] DEBUG: Creating snapshot of VM vm15 (attempt #1) ...

[Fri Sep 23 11:06:28 2011] DEBUG: Creation of snapshot for VM vm15 successful.

[Fri Sep 23 11:06:28 2011] DEBUG: Creating snapshot for VM vm17 ...

[Fri Sep 23 11:06:28 2011] DEBUG: Checking power state of VM vm17 ...

[Fri Sep 23 11:06:28 2011] DEBUG: Checking snapshot capability of VM vm17 ...

[Fri Sep 23 11:06:28 2011] DEBUG: Removing leftover snapshots for VM vm17 ...

[Fri Sep 23 11:06:28 2011] DEBUG: Creating snapshot of VM vm17 (attempt #1) ...

[Fri Sep 23 11:06:30 2011] DEBUG: Creation of snapshot for VM vm17 successful.

[Fri Sep 23 11:06:30 2011] DEBUG: Creating snapshot for VM vm18 ...

[Fri Sep 23 11:06:30 2011] DEBUG: Checking power state of VM vm18 ...

[Fri Sep 23 11:06:30 2011] DEBUG: Checking snapshot capability of VM vm18 ...

[Fri Sep 23 11:06:30 2011] DEBUG: Removing leftover snapshots for VM vm18 ...

[Fri Sep 23 11:06:30 2011] DEBUG: Creating snapshot of VM vm18 (attempt #1) ...

[Fri Sep 23 11:06:35 2011] DEBUG: Creation of snapshot for VM vm18 successful.

[Fri Sep 23 11:06:35 2011] DEBUG: Creating snapshot for VM vm19 ...

[Fri Sep 23 11:06:35 2011] DEBUG: Checking power state of VM vm19 ...

[Fri Sep 23 11:06:35 2011] INFO: Power state of VM vm19 is off, not taking snapshot.

[Fri Sep 23 11:06:35 2011] DEBUG: Creating snapshot for VM vm20 ...

[Fri Sep 23 11:06:35 2011] DEBUG: Checking power state of VM vm20 ...

[Fri Sep 23 11:06:35 2011] INFO: Power state of VM vm20 is off, not taking snapshot.

[Fri Sep 23 11:06:35 2011] INFO: Snapshot creation process completed successfully.

########## POST APPLICATION QUIESCE COMMANDS ##########

[Fri Sep 23 11:06:35 2011] INFO: No commands defined

########## POST APPLICATION QUIESCE COMMANDS FINISHED SUCCESSFULLY ##########

########## PRE NETAPP COMMANDS ##########

[Fri Sep 23 11:06:35 2011] INFO: No commands defined

########## PRE NETAPP COMMANDS FINISHED SUCCESSFULLY ##########

[Fri Sep 23 11:06:35 2011] DEBUG: ZAPI REQUEST

<system-get-ontapi-version></system-get-ontapi-version>

[Fri Sep 23 11:06:35 2011] DEBUG: ZAPI RESULT

<results status="passed">

    <major-version>1</major-version>

    <minor-version>14</minor-version>

</results>

[Fri Sep 23 11:06:35 2011] DEBUG: creating filer/vfiler executor for filer 10.245.70.1

########## Detecting Data OnTap mode for 10.245.70.1 ##########

[Fri Sep 23 11:06:35 2011] INFO: Data OnTap 7 mode detected

[Fri Sep 23 11:06:35 2011] DEBUG: Connected to 10.245.70.1 using API Version 1.14

########## Generating Info ASUP on 10.245.70.1 ##########

[Fri Sep 23 11:06:35 2011] DEBUG: ZAPI REQUEST

<ems-autosupport-log>

    <app-version>NetApp Snap Creator Framework 3.4p1</app-version>

    <auto-support>false</auto-support>

    <category>Backup Started</category>

    <computer-name>LAMBDA</computer-name>

    <event-description>INFO: NetApp Snap Creator Framework 3.4p1 Backup for daily ACTION: snap POLICY: daily Plugin: vibe Volumes: 10.245.70.1:datastore002 Started</event-description>

    <event-id>0</event-id>

    <event-source>SNAPCREATOR</event-source>

    <log-level>6</log-level>

</ems-autosupport-log>

[Fri Sep 23 11:06:36 2011] DEBUG: ZAPI RESULT

<results status="passed"></results>

[Fri Sep 23 11:06:36 2011] INFO: NetApp ASUP create on 10.245.70.1 finished successfully

########## Gathering Information for 10.245.70.1:datastore002 ##########

[Fri Sep 23 11:06:36 2011] INFO: Performing NetApp Snapshot Inventory for datastore002 on 10.245.70.1

[Fri Sep 23 11:06:36 2011] DEBUG: ZAPI REQUEST

<snapshot-list-info>

    <volume>datastore002</volume>

    <terse>true</terse>

</snapshot-list-info>

[Fri Sep 23 11:06:36 2011] DEBUG: ZAPI RESULT

<results status="passed">

    <snapshots>

        <snapshot-info>

            <name>daily-daily_recent</name>

            <access-time>1316771128</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>VIBE_ds_snap.0</name>

            <access-time>1316770933</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>daily-daily_20110923103703</name>

            <access-time>1316770623</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>nightly.0</name>

            <access-time>1316732421</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>nightly.1</name>

            <access-time>1316646022</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>nightly.2</name>

            <access-time>1316559619</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>nightly.3</name>

            <access-time>1316473221</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>weekly.0</name>

            <access-time>1316386810</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>nightly.4</name>

            <access-time>1316300405</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>VIBE_ds_snap.1</name>

            <access-time>1314998441</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>VIBE_ds_snap.2</name>

            <access-time>1314393659</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

        <snapshot-info>

            <name>VIBE_ds_snap.3</name>

            <access-time>1313788863</access-time>

            <dependency></dependency>

            <busy>false</busy>

            <cumulative-percentage-of-used-blocks>0</cumulative-percentage-of-used-blocks>

            <percentage-of-used-blocks>0</percentage-of-used-blocks>

            <cumulative-percentage-of-total-blocks>0</cumulative-percentage-of-total-blocks>

            <percentage-of-total-blocks>0</percentage-of-total-blocks>

        </snapshot-info>

    </snapshots>

</results>

[Fri Sep 23 11:06:36 2011] INFO: NetApp Snapshot Inventory of datastore002 on 10.245.70.1 completed Successfully

########## Running NetApp Snapshot Rename on Primary 10.245.70.1 ##########

[Fri Sep 23 11:06:36 2011] INFO: Rename the recent snapshot from daily-daily_recent to daily-daily_20110923104528 for 10.245.70.1:datastore002

[Fri Sep 23 11:06:36 2011] DEBUG: ZAPI REQUEST

<snapshot-rename>

    <volume>datastore002</volume>

    <current-name>daily-daily_recent</current-name>

    <new-name>daily-daily_20110923104528</new-name>

</snapshot-rename>

[Fri Sep 23 11:06:37 2011] DEBUG: ZAPI RESULT

<results status="passed"></results>

[Fri Sep 23 11:06:37 2011] INFO: NetApp Snapshot Rename for datastore002 on 10.245.70.1 completed Successfully

[Fri Sep 23 11:06:37 2011] INFO: NetApp Snap Creator Framework detected that SnapDrive is not being used. File system consistency cannot be guaranteed for SAN/iSAN environments

########## Taking Snapshot on Primary 10.245.70.1:datastore002 ##########

[Fri Sep 23 11:06:37 2011] INFO: Creating NetApp Snapshot for datastore002 on 10.245.70.1

[Fri Sep 23 11:06:37 2011] DEBUG: ZAPI REQUEST

<snapshot-create>

    <snapshot>daily-daily_recent</snapshot>

    <volume>datastore002</volume>

</snapshot-create>

[Fri Sep 23 11:06:38 2011] DEBUG: ZAPI RESULT

<results status="passed"></results>

[Fri Sep 23 11:06:38 2011] INFO: NetApp Snapshot Create of daily-daily_recent on 10.245.70.1:datastore002 Completed Successfully

########## PRE APPLICATION UNQUIESCE COMMANDS ##########

[Fri Sep 23 11:06:38 2011] INFO: No commands defined

########## PRE APPLICATION UNQUIESCE COMMANDS FINISHED SUCCESSFULLY ##########

########## Application unquiesce ##########

[Fri Sep 23 11:06:38 2011] INFO: Checking if VIBE pre-requisites already run (function: unquiesce) ....

[Fri Sep 23 11:06:38 2011] INFO: Discovery already completed -- not re-running prerequisites.

[Fri Sep 23 11:06:38 2011] INFO: Removing snapshots (if applicable)

[Fri Sep 23 11:06:38 2011] DEBUG: Checking power state of VM vm1 ...

[Fri Sep 23 11:06:38 2011] INFO: Power state of VM vm1 is off, not taking snapshot.

########## POST APPLICATION UNQUIESCE COMMANDS ##########

[Fri Sep 23 11:06:38 2011] INFO: No commands defined

########## POST APPLICATION UNQUIESCE COMMANDS FINISHED SUCCESSFULLY ##########

########## Generating Info ASUP on 10.245.70.1 ##########

[Fri Sep 23 11:06:38 2011] DEBUG: ZAPI REQUEST

<ems-autosupport-log>

    <app-version>NetApp Snap Creator Framework 3.4p1</app-version>

    <auto-support>false</auto-support>

    <category>Backup Completed</category>

    <computer-name>LAMBDA</computer-name>

    <event-description>INFO: NetApp Snap Creator Framework 3.4p1 Backup for daily ACTION: snap POLICY: daily Plugin: vibe Volumes: 10.245.70.1:datastore002 Completed</event-description>

    <event-id>0</event-id>

    <event-source>SNAPCREATOR</event-source>

    <log-level>6</log-level>

</ems-autosupport-log>

[Fri Sep 23 11:06:38 2011] DEBUG: ZAPI RESULT

<results status="passed"></results>

[Fri Sep 23 11:06:38 2011] INFO: NetApp ASUP create on 10.245.70.1 finished successfully

########## POST NETAPP DATA TRANSFER COMMANDS ##########

[Fri Sep 23 11:06:38 2011] INFO: No commands defined

########## POST NETAPP DATA TRANSFER COMMANDS FINISHED SUCCESSFULLY ##########

########## Running NetApp Snapshot Delete on Primary 10.245.70.1 ##########

########## POST NETAPP COMMANDS ##########

[Fri Sep 23 11:06:38 2011] INFO: No commands defined

########## POST NETAPP COMMANDS FINISHED SUCCESSFULLY ##########

########## ARCHIVE COMMANDS ##########

[Fri Sep 23 11:06:38 2011] INFO: No commands defined

########## ARCHIVE COMMANDS FINISHED SUCCESSFULLY ##########

########## NetApp Snap Creator Framework finished successfully ##########

[Fri Sep 23 11:06:38 2011] INFO: INFO: NetApp Snap Creator Framework finished successfully ( Action: snap )

[Fri Sep 23 11:06:38 2011] DEBUG: Exiting with error code - 0

[ktenzer]

It looks to me like everything works?

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot for VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking power state of VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Checking snapshot capability of VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Removing leftover snapshots for VM vm3 ...

[Fri Sep 23 11:05:57 2011] DEBUG: Creating snapshot of VM vm3 (attempt #1) ...

[Fri Sep 23 11:06:02 2011] DEBUG: Creation of snapshot for VM vm3 successful.

So you are saying vm3 has vmware snapshot even though SC said it was removed? What is the name of the leftover vmware snapshot?

Keith

[ktenzer]

Ok NVM I see problem

########## Application unquiesce ##########

[Fri Sep 23 11:06:38 2011] INFO: Checking if VIBE pre-requisites already run (function: unquiesce) ....

[Fri Sep 23 11:06:38 2011] INFO: Discovery already completed -- not re-running prerequisites.

[Fri Sep 23 11:06:38 2011] INFO: Removing snapshots (if applicable)

[Fri Sep 23 11:06:38 2011] DEBUG: Checking power state of VM vm1 ...

[Fri Sep 23 11:06:38 2011] INFO: Power state of VM vm1 is off, not taking snapshot.

Basically it is seeing that first VM is powered off and never checks any other VMs

This looks like a bug, I will send this to QA and we will let you know

Regards,

Keith

[rmatt]

There's something else going on here.  Ricardo, when you're running this, you say you originally got an error with vCenterDatastoreNotFoundException which is a VMware error.  I can see this happening on the RemoveSnapshot() API command from our plug-in, because right now when we execute it, we run the command natively, we don't eval{} the operation to encapsulate the error condition.  Normally it would never fail out like that.

We can create new eval{} code around the RemoveSnapshot option to capture and avoid this (and keep going through the rest of the list).  Why VMware kicked out that error, though, would depend on the environment.

A couple of quesitons:

1) Does this happen every time?

2) If you remove vm2, vm3, etc., from the list, does the problem happen (in other words, is it specific to one VM)?

The list keeps going, BTW -- we don't stop processing VMs if one is powered off so that's not an issue.  We iterate through the list in all cases.  The only time you would see that is if unquiesce() simply stops, and the VMware function kicking out an error would do just that.

Let me know on (1) and (2).  Thanks,

--Matt

[ricardoduarte]

Hi there,

The answers:

1) It happens every time

2) Removing the VMs results in the same error.

The VIBE utility (from the toolchest) works just fine btw.

Regards.

[rmatt]

Thanks, Ricardo.  So it happens with a single VM, and always on unquiesce operations (meaning you just do a --action snap on vm1)?

Two other questions:

1) What happens when you run --action quiesce and --action unquiesce without --action snap?  Does that work (you won't be taking a full backup, it's just to test the behavior)?

2) Does this vCenter error message appear on the console, in the logs, etc.?  If you can send me a private message perhaps we can walk through the logs and the configuration file together.  That error shouldn't occur from the RemoveSnapshot() so I'm curious if it is happening elsewhere.

The code for the plug-in is based on VIBE, so it should be behaving the same way.

Thanks again,

--Matt

[rmatt]

One last request - can you please try this test again with 3.4 instead of 3.4p1?

Thanks again!

--Matt