snapshot error encountered (156)

[mrauf]

Hello Friends,

i am facing an issue in VMWare VSphere Backup issue with the error code snampshot error encountered - 156.

Master Server :- 7.6.1.1 / Windows 2008 Enterprise 64 bit

Media Server:- 7.6.1.1/Red Hat Linux

VMWare : - VMWare VSphere 6.0

Job Details: - 

5/25/2016 1:31:05 PM - Info nbjm(pid=6932) starting backup job (jobid=872704) for client pbad-vc, policy VMWare-vCenter, schedule Daily  
5/25/2016 1:31:05 PM - Info nbjm(pid=6932) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=872704, request id:{02BE2026-FC59-47A1-A179-F4F9CA96A5E3})  
5/25/2016 1:31:05 PM - requesting resource pbad_fsmedia_Dedup_STU
5/25/2016 1:31:05 PM - requesting resource pbad-netbackup.pbad.sbg.com.sa.NBU_CLIENT.MAXJOBS.pbad-vc
5/25/2016 1:31:05 PM - requesting resource pbad-netbackup.pbad.sbg.com.sa.NBU_POLICY.MAXJOBS.VMWare-vCenter
5/25/2016 1:31:05 PM - granted resource pbad-netbackup.pbad.sbg.com.sa.NBU_CLIENT.MAXJOBS.pbad-vc
5/25/2016 1:31:05 PM - granted resource pbad-netbackup.pbad.sbg.com.sa.NBU_POLICY.MAXJOBS.VMWare-vCenter
5/25/2016 1:31:05 PM - granted resource MediaID=@aaaay;DiskVolume=PureDiskVolume;DiskPool=pbad_fsmedia_Dedup_Pool;Path=PureDiskVolume;StorageServer=pbad-fsmedia.pbad.sbg.com.sa;MediaServer=pbad-fsmedia.pbad.sbg.com.sa
5/25/2016 1:31:05 PM - granted resource pbad_fsmedia_Dedup_STU
5/25/2016 1:31:05 PM - estimated 0 Kbytes needed
5/25/2016 1:31:05 PM - begin Parent Job
5/25/2016 1:31:05 PM - begin VMware, Start Notify Script
5/25/2016 1:31:05 PM - started
5/25/2016 1:31:06 PM - Info RUNCMD(pid=15444) started            
5/25/2016 1:31:07 PM - Info RUNCMD(pid=15444) exiting with status: 0         
Status 0
5/25/2016 1:31:07 PM - end VMware, Start Notify Script; elapsed time: 0:00:02
5/25/2016 1:31:07 PM - begin VMware, Step By Condition
Status 0
5/25/2016 1:31:07 PM - end VMware, Step By Condition; elapsed time: 0:00:00
5/25/2016 1:31:07 PM - begin VMware, Read File List
Status 0
5/25/2016 1:31:07 PM - end VMware, Read File List; elapsed time: 0:00:00
5/25/2016 1:31:07 PM - begin VMware, Create Snapshot
5/25/2016 1:31:08 PM - started process bpbrm (12023)
5/25/2016 1:33:57 PM - end writing
Status 156
5/25/2016 1:33:57 PM - end VMware, Create Snapshot; elapsed time: 0:02:50
5/25/2016 1:33:57 PM - begin VMware, Stop On Error
Status 0
5/25/2016 1:33:57 PM - end VMware, Stop On Error; elapsed time: 0:00:00
5/25/2016 1:33:57 PM - begin VMware, Delete Snapshot
5/25/2016 1:33:59 PM - started process bpbrm (13061)
5/25/2016 1:34:01 PM - end writing
Status 4207
5/25/2016 1:34:01 PM - end VMware, Delete Snapshot; elapsed time: 0:00:04
5/25/2016 1:34:01 PM - begin VMware, End Notify Script
5/25/2016 1:49:44 PM - Info bpbrm(pid=12023) pbad-vc is the host to backup data from     
5/25/2016 1:49:44 PM - Info bpbrm(pid=12023) reading file list for client        
5/25/2016 1:49:44 PM - Info bpbrm(pid=12023) start bpfis on client         
5/25/2016 1:49:46 PM - Info bpbrm(pid=12023) Starting create snapshot processing         
5/25/2016 1:49:48 PM - Info bpfis(pid=12029) Backup started           
5/25/2016 1:49:48 PM - snapshot backup of client pbad-vc using method VMware_v2
5/25/2016 1:49:52 PM - Info bpbrm(pid=12023) INF - vmwareLogger: ChangeTracking not supported       
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - VMware_freeze: VIXAPI freeze (VMware snapshot) failed with -1: Unrecognized error
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - VMware error received: The operation is not allowed in the current state.
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze 
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL -        
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze 
5/25/2016 1:52:32 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL -        
5/25/2016 1:52:32 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - snapshot processing failed, status 156   
5/25/2016 1:52:32 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - snapshot creation failed, status 156   
5/25/2016 1:52:32 PM - Warning bpbrm(pid=12023) from client pbad-vc: WRN - ALL_LOCAL_DRIVES is not frozen    
5/25/2016 1:52:32 PM - Info bpfis(pid=12029) done. status: 156          
5/25/2016 1:52:32 PM - end VMware, End Notify Script; elapsed time: 0:18:31
5/25/2016 1:52:32 PM - Info bpfis(pid=12029) done. status: 156: snapshot error encountered       
5/25/2016 1:52:35 PM - Info bpbrm(pid=13061) Starting delete snapshot processing         
5/25/2016 1:52:35 PM - Info bpfis(pid=13065) Backup started           
5/25/2016 1:52:35 PM - Critical bpbrm(pid=13061) from client pbad-vc: cannot open /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.pbad-vc_1464172265.1.0       
5/25/2016 1:52:35 PM - Info bpfis(pid=13065) done. status: 4207          
5/25/2016 1:52:35 PM - end Parent Job; elapsed time: 0:21:30
5/25/2016 1:52:35 PM - Info bpfis(pid=13065) done. status: 4207: Could not fetch snapshot metadata or state files  
5/25/2016 1:34:01 PM - Info RUNCMD(pid=4756) started            
5/25/2016 1:34:02 PM - Info RUNCMD(pid=4756) exiting with status: 0         
Status 0
5/25/2016 1:34:02 PM - end Parent Job; elapsed time: 0:02:57
Status 156
5/25/2016 1:34:02 PM - end Parent Job; elapsed time: 0:02:57
5/25/2016 1:49:44 PM - Info bpbrm(pid=12023) pbad-vc is the host to backup data from     
5/25/2016 1:49:44 PM - Info bpbrm(pid=12023) reading file list for client        
5/25/2016 1:49:44 PM - Info bpbrm(pid=12023) start bpfis on client         
5/25/2016 1:49:46 PM - Info bpbrm(pid=12023) Starting create snapshot processing         
5/25/2016 1:49:48 PM - Info bpfis(pid=12029) Backup started           
5/25/2016 1:49:48 PM - snapshot backup of client pbad-vc using method VMware_v2
5/25/2016 1:49:52 PM - Info bpbrm(pid=12023) INF - vmwareLogger: ChangeTracking not supported       
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - VMware_freeze: VIXAPI freeze (VMware snapshot) failed with -1: Unrecognized error
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - VMware error received: The operation is not allowed in the current state.
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze 
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL -        
5/25/2016 1:52:31 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze 
5/25/2016 1:52:32 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL -        
5/25/2016 1:52:32 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - snapshot processing failed, status 156   
5/25/2016 1:52:32 PM - Critical bpbrm(pid=12023) from client pbad-vc: FTL - snapshot creation failed, status 156   
5/25/2016 1:52:32 PM - Warning bpbrm(pid=12023) from client pbad-vc: WRN - ALL_LOCAL_DRIVES is not frozen    
5/25/2016 1:52:32 PM - Info bpfis(pid=12029) done. status: 156          
5/25/2016 1:52:32 PM - end operation
5/25/2016 1:52:32 PM - Info bpfis(pid=12029) done. status: 156: snapshot error encountered       
5/25/2016 1:52:35 PM - Info bpbrm(pid=13061) Starting delete snapshot processing         
5/25/2016 1:52:35 PM - Info bpfis(pid=13065) Backup started           
5/25/2016 1:52:35 PM - Critical bpbrm(pid=13061) from client pbad-vc: cannot open /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.pbad-vc_1464172265.1.0       
5/25/2016 1:52:35 PM - Info bpfis(pid=13065) done. status: 4207          
5/25/2016 1:52:35 PM - end operation
5/25/2016 1:52:35 PM - Info bpfis(pid=13065) done. status: 4207: Could not fetch snapshot metadata or state files  
snapshot error encountered (156)

Please help me to resolve the above issue.

[sdo]

1) Excctly which OS and exactly which OS version is on guest VM named:   pbad-vc ?

2) Is the OS inside the guest VM a 32-bit OS, or a 64-bit OS ?

3) What file system types are present/mounted/used within this VM ?

4) Is VMtools installed inside this VM ?

5) Is VMtools up to date (latest version) inside this VM ?

[Marianne]

More possible reasons for status 156 listed in this TN: http://www.veritas.com/docs/000068085

[mrauf]

1) Excctly which OS and exactly which OS version is on guest VM named:   pbad-vc ? Same

2) Is the OS inside the guest VM a 32-bit OS, or a 64-bit OS ? Windows 2008 R2 64 Bit

3) What file system types are present/mounted/used within this VM ? VM Local Drive

4) Is VMtools installed inside this VM ? Yes

5) Is VMtools up to date (latest version) inside this VM ? Yes

This VM is VCenter 6.0 Runing Inside VM.

[sdo]

1) Are you sure the same?  You say Master is Windows 2008 (not SP2, not R2, not R2 SP1)  They don't have to be the same, all I want to do is understand what we're dealing with here.

2) Again, not SP1?

3) NTFS?  Or some other file system type?

4) ok

5) ok

6) OS version of Linux media server:

# cat /etc/redhat-release
# uname -a

7) Please show the backup policy using:

$ bppllist VMWare-vCenter -U

8) Exact version of vSphere?  Is it plain base 6.0 with no patches, no updates?

[mrauf]

1. Master Server - Windows 2008 R2 Enterprise Sp1

2. Sp1

3. NTFS Only

4) ok

5) ok

6- Red Hat Enterprise Linux Server release 6.4 Beta (Santiago)

Linux pbad-fsmedia 2.6.32-343.el6.x86_64 #1 SMP Mon Nov 19 16:46:10 EST 2012 x86_64 x86_64 x86_64 GNU/Linux

7-  [root@domainName-fsmedia admincmd]# ./bppllist VMWare-vCenter -U
------------------------------------------------------------

Policy Name:       VMWare-vCenter

  Policy Type:         VMware
  Active:              yes
  Effective date:      07/23/2012 15:58:53
  File Restore Raw:    yes
  Application Consistent:    yes
  Block Incremental:   yes
  Mult. Data Streams:  no
  Client Encrypt:      no
  Checkpoint:          no
  Policy Priority:     0
  Max Jobs/Policy:     Unlimited
  Disaster Recovery:   0
  Collect BMR info:    no
  Residence:           DomainName_fsmedia_Dedup_STU
  Volume Pool:         NetBackup
  Server Group:        *ANY*
  Keyword:             (none specified)
  Data Classification:       -
  Residence is Storage Lifecycle Policy:    no
  Application Discovery:      no
  Discovery Lifetime:      28800 seconds
  ASC Application and attributes: (none defined)

  Granular Restore Info:  no
  Ignore Client Direct:  no
  Enable Metadata Indexing:  no
  Index server name:  NULL
  Use Accelerator:  yes
  HW/OS/Client:  vmx-08        windows7Serve pbad-vc

  Include:  ALL_LOCAL_DRIVES

  Schedule:              Daily
    Type:                Full Backup
    Calendar sched: Enabled
     Included Dates-----------
        Sunday, Week 1
        Monday, Week 1
        Tuesday, Week 1
        Thursday, Week 1
        Friday, Week 1
        Saturday, Week 1
        Sunday, Week 2
        Monday, Week 2
        Tuesday, Week 2
        Thursday, Week 2
        Friday, Week 2
        Saturday, Week 2
        Sunday, Week 3
        Monday, Week 3
        Tuesday, Week 3
        Thursday, Week 3
        Friday, Week 3
        Saturday, Week 3
        Sunday, Week 4
        Monday, Week 4
        Tuesday, Week 4
        Thursday, Week 4
        Friday, Week 4
        Saturday, Week 4
        Sunday, Week 5
        Monday, Week 5
        Tuesday, Week 5
        Thursday, Week 5
        Friday, Week 5
        Saturday, Week 5
     Excluded Dates----------
        No specific exclude dates entered
        No exclude days of week entered
    PFI Recovery:        0
    Maximum MPX:         2
    Retention Level:     1 (2 weeks)
    Number Copies:       1
    Fail on Error:       0
    Residence:           (specific storage unit not required)
    Volume Pool:         (same as policy volume pool)
    Server Group:        (same as specified for policy)
    Residence is Storage Lifecycle Policy:         0
    Schedule indexing:   0
    Daily Windows:
          Sunday     18:40:00  -->  Sunday     20:30:00
          Monday     18:40:00  -->  Monday     20:30:00
          Tuesday    18:40:00  -->  Tuesday    20:30:00
          Thursday   18:40:00  -->  Thursday   20:30:00
          Friday     18:40:00  -->  Friday     20:30:00
          Saturday   18:40:00  -->  Saturday   20:30:00

  Schedule:              Weekly_Tape
    Type:                Full Backup
    Calendar sched: Enabled
     Included Dates-----------
        Wednesday, Week 1
        Wednesday, Week 2
        Wednesday, Week 3
        Wednesday, Week 4
        Wednesday, Week 5
     Excluded Dates----------
      EXCLUDE DATE 0 - 01/08/2014
      EXCLUDE DATE 1 - 12/30/2015
        No exclude days of week entered
    PFI Recovery:        0
    Maximum MPX:         2
    Retention Level:     0 (1 week)
    Number Copies:       1
    Fail on Error:       0
    Residence:           NetBackup_Disk_Tape
    Volume Pool:         (same as policy volume pool)
    Server Group:        (same as specified for policy)
    Residence is Storage Lifecycle Policy:         1
    Schedule indexing:   0
    Daily Windows:
          Wednesday  18:40:00  -->  Wednesday  21:40:00

  Schedule:              Yearly_Tape
    Type:                Full Backup
    Calendar sched: Enabled
     Included Dates-----------
      SPECIFIC DATE 0 - 12/26/2014
      SPECIFIC DATE 1 - 01/08/2015
      SPECIFIC DATE 2 - 12/30/2015
         No days of week entered
     Excluded Dates----------
        No specific exclude dates entered
        No exclude days of week entered
    PFI Recovery:        0
    Maximum MPX:         2
    Retention Level:     0 (1 week)
    Number Copies:       1
    Fail on Error:       0
    Residence:           NetBackup_Disk_Tape_yearly
    Volume Pool:         (same as policy volume pool)
    Server Group:        (same as specified for policy)
    Residence is Storage Lifecycle Policy:         1
    Schedule indexing:   0
    Daily Windows:
          Wednesday  18:30:00  -->  Wednesday  21:30:00

[a_la_carte]

1) Has this backup ever worked before or this is the first time ?

1) Please do check if multiple VM snapshot backup are not running for the same client at a given time?

2) Please do check for any left-out snapshots from previous backup for this machine through the VM Console that might requires consolidation (although, possiblity is less as you are already on 7.6.1.x, but still its good to do a check on the same).

3) Enabling BPFIS log with verbose=5 can help digging more into the issue.

[Michal_Mikulik1]

Hello,

the root cause will be on VMware side, I think there is no need to investigate exact versions of OS/FS/VM/NBU etc.

Go to vSphere console (or ask your VMware admin) and try to take snapshot of the VM purely from the vSphere side. This should end with the same error and tell you more about the cause.

One example is here: https://www.veritas.com/support/en_US/article.000023476

Regards

Michal

[sdo]

Just wanted to be able to check the version interop first, because it wasn't clear whether this backup has ever worked, or was new, and it's always best to check interop anyway, but maybe I did assume it a new build/config, and I tend to find that most new build issues are interop based.

And yes you're right.   If backups have been working for a while, and then break, then it's usually something outside of NetBackup.

Anyway, the matching SCL entry appears to be this:

NetBackup Versions	VDDK Versions	vSphere Versions	vCloud Director Versions	Backup/Restore Host Versions
7.6.1.2  7.6.1.1	5.5.4	vSphere 6.0, 6.0 U1, 6.0 U2  vSphere 5.5, 5.5 U1, 5.5 U2, 5.5 U3  vSphere 5.1, 5.1 U1, 5.1 U2, 5.1 U3  vSphere 5.0, 5.0 U1, 5.0 U2, 5.0 U3  For supported vCenter and ESXi versions and additional information, see the VMware VDDK 5.5.4 release notes	5.5, 5.5.1, 5.5.2, 5.5.3, 5.5.4, 5.5.5  5.1, 5.1.1, 5.1.2, 5.1.3  Service Provider Versions: 5.6.4, 5.6.3	All 64 bit only:  Windows Server 2012, 2008, 2008 R2, 2003 R2  Red Hat Enterprise Linux (RHEL) 5.9,6.2, 6.3, 6.4  SUSE Linux Enterprise Server (SLES) 10.4, 11.1, 11.2

[sdo]

The VMware VDDK 5.5.4 release notes are here:

https://www.vmware.com/support/developer/vddk/vddk-554-releasenotes.html

...and I don't see anything that would appear to be related in there - unless something was upgraded recently?

.

My question 8) above wasn't answered, so we still dont know which version of ESXi is being used.

.

We need a_la_carte's questions to be answered too.

And if this backup always used to work...

...then was anything patched or updated or upgraded just before the backups broke?

.

And - can I ask what is this "beta" moniker in the name of the OS on the media server?

Red Hat Enterprise Linux Server release 6.4 Beta (Santiago)

Is it not the true full RHEL 6.4 release?  i.e. is the media server running a "beta" OS ?

[mrauf]

Dear SDO,

8. Currently we are using ESXi Version 8

for your information we never upgrade our netbackup environment and this client backup is working properly but last from 20 days the backup getting failed. 

i observed in other vmclients which is running on same EXSI server the backup is running successfully but except this client.

can u please give me some details about error vmwareLogger: ChangeTracking not supported .

please kindly try to give me the solution for this.

Thanks 

[mrauf]

Dear a_la_carte

1) Has this backup ever worked before or this is the first time ?

   It was working before.

1) Please do check if multiple VM snapshot backup are not running for the same client at a given time?

    I verify that the only one snapshot backup are running for the same client.

2) Please do check for any left-out snapshots from previous backup for this machine through the VM Console that might requires consolidation (although, possiblity is less as you are already on 7.6.1.x, but still its good to do a check on the same).

   I already consolidation old snapshot and trigger the backup but the issue is still persists.

3) Enabling BPFIS log with verbose=5 can help digging more into the issue.

  i already enable the BPFIS Log.

please kindly help me on the above issue.

Thanks

[Marianne]

The next step is to check bpfis log for errors.

[mrauf]

Dear Marianne,

Please find the below bpfids logs 

13:38:07.856 [11652.8148] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe deletedb -noserverstate -policy VMWare-vCenter -clnt Domain Name-nbmedia -vm_client pbad-vc -copy 1 -prev_bli_incr 0 -vm_bli_cleanup 
13:38:07.918 [11652.8148] <4> bpfis main: set vm client Domain Name-vc as ol_client_name
13:38:07.918 [11652.8148] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_LOCK>, timeout <5>, status <0>.
13:38:07.918 [11652.8148] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
13:38:07.918 [11652.8148] <2> start_keep_alive_thread: INF - Start keep_alive thread 
13:38:07.918 [11652.8148] <4> keep_alive_and_snapshot_control: Exiting.
13:38:07.918 [11652.11912] <2> send_keep_alive: INF - sending keep alive
13:38:07.934 [11652.8148] <2> bpfis_state_on_master_xfer_level: bpfis state file transfer is disabled (level = 0), touch file exists: 0, -noserverstate: 1, -nbu: 0
13:38:07.980 [11652.8148] <4> bpfis main: INF - BACKUP START 11652
13:38:07.980 [11652.8148] <2> online_util: INF - cmd = CLEANUP_VM_BLI, id = pbad-vc_0, cleanup_state_on_server = 1
13:38:08.027 [11652.8148] <2> fis_db_process_file: INF - id = pbad-vc_1458574803, copy number = 1
13:38:08.027 [11652.8148] <2> id_to_state_file2: INF - directory: C:\Program Files\Veritas\NetBackup\db\snapshot\vm\pbad-vc
13:38:08.105 [11652.8148] <2> fis_db_process_file: INF - id = pbad-vc_1458574803, copy number = 1
13:38:08.105 [11652.8148] <2> id_to_state_file2: INF - directory: C:\Program Files\Veritas\NetBackup\db\snapshot\vm\pbad-vc
13:38:08.121 [11652.8148] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_UNLOCK>, timeout <0>, status <0>.
13:38:08.121 [11652.8148] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
13:38:08.121 [11652.8148] <4> keep_alive_and_snapshot_control: Exiting.
13:38:08.121 [11652.8148] <4> bpfis Exit: INF - EXIT STATUS 0: the requested operation was successfully completed
13:38:08.121 [11652.8148] <2> bpfis Exit: INF - Close of stdout complete
14:18:38.476 [15824.11112] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe deletedb -noserverstate -policy VMWare-vCenter -clnt Domain Name -vm_client Domain Name-vc -copy 1 -prev_bli_incr 0 -vm_bli_cleanup 
14:18:38.523 [15824.11112] <4> bpfis main: set vm client pbad-vc as ol_client_name
14:18:38.538 [15824.11112] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_LOCK>, timeout <5>, status <0>.
14:18:38.538 [15824.11112] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
14:18:38.538 [15824.11112] <2> start_keep_alive_thread: INF - Start keep_alive thread 
14:18:38.538 [15824.11112] <4> keep_alive_and_snapshot_control: Exiting.
14:18:38.538 [15824.10504] <2> send_keep_alive: INF - sending keep alive
14:18:38.538 [15824.11112] <2> bpfis_state_on_master_xfer_level: bpfis state file transfer is disabled (level = 0), touch file exists: 0, -noserverstate: 1, -nbu: 0
14:18:38.585 [15824.11112] <4> bpfis main: INF - BACKUP START 15824
14:18:38.585 [15824.11112] <2> online_util: INF - cmd = CLEANUP_VM_BLI, id = pbad-vc_0, cleanup_state_on_server = 1
14:18:38.632 [15824.11112] <2> fis_db_process_file: INF - id = pbad-vc_1458574803, copy number = 1
14:18:38.648 [15824.11112] <2> id_to_state_file2: INF - directory: C:\Program Files\Veritas\NetBackup\db\snapshot\vm\pbad-vc
14:18:38.694 [15824.11112] <2> fis_db_process_file: INF - id = pbad-vc_1458574803, copy number = 1
14:18:38.694 [15824.11112] <2> id_to_state_file2: INF - directory: C:\Program Files\Veritas\NetBackup\db\snapshot\vm\pbad-vc
14:18:38.710 [15824.11112] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_UNLOCK>, timeout <0>, status <0>.
14:18:38.710 [15824.11112] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
14:18:38.710 [15824.11112] <4> keep_alive_and_snapshot_control: Exiting.
14:18:38.710 [15824.11112] <4> bpfis Exit: INF - EXIT STATUS 0: the requested operation was successfully completed

[Marianne]

Above log seems to show successful snapshot. Status 0. No errors.

Please show us the corresponding Job Details.

[mrauf]

Hello Marianne,

please find the job details below

6/7/2016 12:19:25 PM - Info nbjm(pid=6932) starting backup job (jobid=882250) for client pbad-vc, policy VMWare-VCenter, schedule Daily  
6/7/2016 12:19:25 PM - Info nbjm(pid=6932) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=882250, request id:{B775DBED-8B46-4369-8A26-194AB983AC45})  
6/7/2016 12:19:25 PM - requesting resource Netbackup_StorageUnit
6/7/2016 12:19:25 PM - requesting resource pbad-netbackup.pbad.sbg.com.sa.NBU_CLIENT.MAXJOBS.pbad-vc
6/7/2016 12:19:25 PM - requesting resource pbad-netbackup.pbad.sbg.com.sa.NBU_POLICY.MAXJOBS.VMWare-VCenter
6/7/2016 12:19:25 PM - granted resource pbad-netbackup.pbad.sbg.com.sa.NBU_CLIENT.MAXJOBS.pbad-vc
6/7/2016 12:19:25 PM - granted resource pbad-netbackup.pbad.sbg.com.sa.NBU_POLICY.MAXJOBS.VMWare-VCenter
6/7/2016 12:19:25 PM - granted resource MediaID=@aaaaC;DiskVolume=PureDiskVolume;DiskPool=Netbackup_Disk_Pool;Path=PureDiskVolume;StorageServer=pbad-netbackup.pbad.sbg.com.sa;MediaServer=pbad-netbackup.pbad.sbg.com.sa
6/7/2016 12:19:25 PM - granted resource Netbackup_StorageUnit
6/7/2016 12:19:25 PM - started
6/7/2016 12:19:26 PM - estimated 0 Kbytes needed
6/7/2016 12:19:26 PM - begin Parent Job
6/7/2016 12:19:26 PM - begin VMware, Start Notify Script
6/7/2016 12:19:27 PM - Info RUNCMD(pid=10416) started            
6/7/2016 12:19:27 PM - Info RUNCMD(pid=10416) exiting with status: 0         
Status 0
6/7/2016 12:19:27 PM - end VMware, Start Notify Script; elapsed time: 0:00:01
6/7/2016 12:19:27 PM - begin VMware, Step By Condition
Status 0
6/7/2016 12:19:27 PM - end VMware, Step By Condition; elapsed time: 0:00:00
6/7/2016 12:19:27 PM - begin VMware, Read File List
Status 0
6/7/2016 12:19:27 PM - end VMware, Read File List; elapsed time: 0:00:00
6/7/2016 12:19:27 PM - begin VMware, Create Snapshot
6/7/2016 12:19:28 PM - Info bpbrm(pid=12864) pbad-vc is the host to backup data from     
6/7/2016 12:19:28 PM - Info bpbrm(pid=12864) reading file list for client        
6/7/2016 12:19:28 PM - Info bpbrm(pid=12864) start bpfis on client         
6/7/2016 12:19:28 PM - started process bpbrm (12864)
6/7/2016 12:19:31 PM - Info bpbrm(pid=12864) Starting create snapshot processing         
6/7/2016 12:19:32 PM - Info bpfis(pid=12216) Backup started           
6/7/2016 12:19:34 PM - snapshot backup of client pbad-vc using method VMware_v2
6/7/2016 12:19:37 PM - Info bpbrm(pid=12864) INF - vmwareLogger: ChangeTracking not supported       
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - VMware_freeze: VIXAPI freeze (VMware snapshot) failed with -1: Unrecognized error
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - VMware error received: The operation is not allowed in the current state.
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze 
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL -        
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze 
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL -        
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - snapshot processing failed, status 156   
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - snapshot creation failed, status 156   
6/7/2016 12:22:18 PM - Warning bpbrm(pid=12864) from client pbad-vc: WRN - ALL_LOCAL_DRIVES is not frozen    
6/7/2016 12:22:18 PM - Info bpfis(pid=12216) done. status: 156          
6/7/2016 12:22:18 PM - end VMware, Create Snapshot; elapsed time: 0:02:51
6/7/2016 12:22:18 PM - Info bpfis(pid=12216) done. status: 156: snapshot error encountered       
6/7/2016 12:22:18 PM - end writing
Status 156
6/7/2016 12:22:18 PM - end Parent Job; elapsed time: 0:02:52
6/7/2016 12:22:18 PM - begin VMware, Stop On Error
Status 0
6/7/2016 12:22:18 PM - end VMware, Stop On Error; elapsed time: 0:00:00
6/7/2016 12:22:18 PM - begin VMware, Delete Snapshot
6/7/2016 12:22:19 PM - started process bpbrm (1448)
6/7/2016 12:22:19 PM - Info bpbrm(pid=1448) Starting delete snapshot processing         
6/7/2016 12:22:20 PM - Info bpfis(pid=16008) Backup started           
6/7/2016 12:22:20 PM - Critical bpbrm(pid=1448) from client pbad-vc: cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.pbad-vc_1465291165.1.0      
6/7/2016 12:22:20 PM - Info bpfis(pid=16008) done. status: 4207          
6/7/2016 12:22:20 PM - end VMware, Delete Snapshot; elapsed time: 0:00:02
6/7/2016 12:22:20 PM - Info bpfis(pid=16008) done. status: 4207: Could not fetch snapshot metadata or state files  
6/7/2016 12:22:20 PM - end writing
Status 4207
6/7/2016 12:22:20 PM - end Parent Job; elapsed time: 0:02:54
6/7/2016 12:22:20 PM - begin VMware, End Notify Script
6/7/2016 12:22:20 PM - Info RUNCMD(pid=8480) started            
6/7/2016 12:22:20 PM - Info RUNCMD(pid=8480) exiting with status: 0         
Status 0
6/7/2016 12:22:20 PM - end VMware, End Notify Script; elapsed time: 0:00:00
Status 156
6/7/2016 12:22:20 PM - end operation
snapshot error encountered (156)

[Marianne]

The timestamps in Job Details do not correspond with bpfis log. 

We need bpfis log on the backup host for 6/7/2016  that shows PID 16008.

[mrauf]

12:22:18.725 [12216.13280] <2> fis_delete_id: INF - removing C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.pbad-vc_1465291165.1.0.VM_ObjInfoXML.xml
12:22:18.725 [12216.13280] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_UNLOCK>, timeout <0>, status <156>.
12:22:18.725 [12216.13280] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
12:22:18.725 [12216.13280] <4> keep_alive_and_snapshot_control: Exiting.
12:22:18.725 [12216.13280] <2> ol_cleanup: INF - removing C:\Program Files\Veritas\NetBackup\temp\VMWare-VCenter+12216+1.std_filelist
12:22:18.725 [12216.13280] <4> bpfis Exit: INF - EXIT STATUS 156: snapshot error encountered
12:22:18.725 [12216.13280] <2> stop_keep_alive_thread: INF - Stop keep_alive thread 
12:22:20.191 [16008.14480] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe delete -nbu -id pbad-vc_1465291165 -bpstart_to 500 -bpend_to 500 -clnt pbad-netbackup.pbad.sbg.com.sa -jobgrpid 882250 -jobid 882250 -fscp 1 -fscp_cksv 0 -copy 1 -rp 1209600 -rtype 0 -backupid pbad-vc_1465291165 -status 156 -S pbad-netbackup.pbad.sbg.com.sa -noserverstate -fim VMware_v2:Virtual_machine_backup=2,disable_quiesce=0,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd:hotadd:nbdssl 
12:22:20.191 [16008.14480] <2> bpfis main: received FIM as [253] VMware_v2:Virtual_machine_backup=2,disable_quiesce=0,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd:hotadd:nbdssl
12:22:20.191 [16008.14480] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_LOCK>, timeout <5>, status <0>.
12:22:20.191 [16008.14480] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
12:22:20.191 [16008.14480] <2> start_keep_alive_thread: INF - Start keep_alive thread 
12:22:20.191 [16008.14480] <4> snapshotlock: Acquiring snapshot lock:retry count [0] 
12:22:20.191 [16008.15744] <2> send_keep_alive: INF - sending keep alive
12:22:20.191 [16008.14480] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock]
12:22:20.191 [16008.14480] <2> rw_lock:   LockFileEx WRITELOCK
12:22:20.191 [16008.14480] <2> rw_lock:   Lock acquired
12:22:20.191 [16008.14480] <2> snapshotlock: Acquired snapshot lock :refcount[0]
12:22:20.191 [16008.14480] <4> keep_alive_and_snapshot_control: Exiting.
12:22:20.191 [16008.14480] <2> bpfis_state_on_master_xfer_level: bpfis state file transfer is disabled (level = 0), touch file exists: 0, -noserverstate: 1, -nbu: 1
12:22:20.191 [16008.14480] <4> bpfis main: INF - BACKUP START 16008
12:22:20.191 [16008.14480] <32> fis_rebuild_from_db: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.pbad-vc_1465291165.1.0
12:22:20.222 [16008.14480] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_UNLOCK>, timeout <0>, status <4207>.
12:22:20.222 [16008.14480] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
12:22:20.222 [16008.14480] <2> deleteReference:    reference not found in the list
12:22:20.222 [16008.14480] <4> unlockSnapshot: Delete reference: status [-4]
12:22:20.222 [16008.14480] <2> writeSnapshotLockFile:    Writing type[2] refcount[0]
12:22:20.222 [16008.14480] <2> writeSnapshotLockFile:    Writing Flags [0] [0]
12:22:20.222 [16008.14480] <2> writeSnapshotLockFile:   Writing Last addReffernt Time [Thu Jan 01 03:00:00 1970
]
12:22:20.222 [16008.14480] <2> writeSnapshotLockFile:   Writing Last Hostname []
12:22:20.285 [16008.14480] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock]
12:22:20.285 [16008.14480] <2> unlockSnapshot:    file[C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock] : zero reference count 
12:22:20.285 [16008.14480] <4> unlockSnapshot: Released snapshot lock: status [0] 
12:22:20.285 [16008.14480] <4> keep_alive_and_snapshot_control: Exiting.
12:22:20.285 [16008.14480] <4> do_post_processing: Deleting snapshot lock files from client for id [pbad-vc_1465291165] and copy_number [1]
12:22:20.285 [16008.14480] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock]
12:22:20.285 [16008.14480] <2> deleteSnapshotLockFile:   Renamed lock file from [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock] to [\sfk8.] for deletion
12:22:20.285 [16008.14480] <2> deleteSnapshotLockFile:   File[\sfk8.] deleted: status[0]
12:22:20.285 [16008.14480] <4> bpfis Exit: INF - EXIT STATUS 4207: Could not fetch snapshot metadata or state files
12:22:20.285 [16008.14480] <2> bpfis Exit: INF - Close of stdout complete
12:22:20.737 [12216.13280] <2> bpfis Exit: INF - Close of stdout complete
 

[Michal_Mikulik1]

Hello,

as I mentioned above, concentrate on VMware side:

VMware error received: The operation is not allowed in the current state.

Did you try to take a snapshot from vSphere console directly and was it successful?

Regards

Michal

[Marianne]

Can you see any errors in vCenter when the snapshot error occurs?

Is "Volume Shadow Copy" service on the VM set to Manual or Disabled?

We also see this error: 

VMware error received: The operation is not allowed in the current state. 

Please work with VM admin to find out in what 'state' this VM is. 

Found this TN : 

VMWare snapshot is failing: Status 156 - The operation is not allowed in the current state. 
http://www.veritas.com/docs/000023476