Video Screencast Help
Symantec to Separate Into Two Focused, Industry-Leading Technology Companies. Learn more.

Unable to copy the virtual machine disk using the VMware VixDiskLib on 1 VM only

Created: 08 Jul 2013 | 13 comments

Backup Exec 2010 R3 with VMWare infrastructure backup option installed.  I'm geting this error on only 1 VM:

0xe0009579 - Unable to copy the virtual machine disk using the VMware VixDiskLib
 
Error writing file data
 
I have the Advanced open file option checked to use Microsoft Volume Shadow Copy service with the "System" snapshot provider, after reading another post about this issue.  The server is purely a file server.
 
When I run the vssadmin list writers command on the guest VM, everything is stable with no errors.  I have already uninstalled then reinstalled the agent.  VMWare tools is installed and I have not uninstalled that yet.
 
thanks!
 
Operating Systems:

Comments 13 CommentsJump to latest comment

ronnieshih's picture

I should add that GRT is enabled.  I'm trying an non-GRT backup to see what happens.

SuperBrain's picture

Do you have Backup Exec 2010 R3 Service Pack 1 installed? If not, please see the following article :
 

http://www.symantec.com/docs/TECH168488

There is also a link provided at the bottom (Related Documents section) for BE 2010 R3 SP1 download.

lmosla's picture

What version of VMware are you using?  You have already reinstalled the agent but check to see if the  VMware Tools VSS Provider is still installed.  See here: To confirm the VMware Snapshot provider is correctly uninstalled, confirm the following

ronnieshih's picture

VMWare 5.0 .  Every other VM backs up just fine, even Exchange 2010 sp3 with GRT enabled.  

I have verified that the VMWare Snapshot Provider isn't in Services, the VSS folder doesn't exist under c:\program files\vmware tools directory.

The backup with GRT disabled is in progress and I will update shortly.  As described before, I have the option of "System" under Microsoft volume shadow copy selected, perhaps I should try backup exec provider next.... given that the disabled GRT backup still fails.

ronnieshih's picture

GRT disabled backup hung at the end the job and never completed.  I had to reboot the backup server in order to terminate it.  

Now back to square one with GRT enabled and the snapshot provider option not selected.  Results pending

pkh's picture

Push out the remote agent to the VM again and then reboot the VM.

ronnieshih's picture

Yep, uninstalled the agent, re-pushed the agent, rebooted the server.  

Both GRT and non-GRT backup ends up with the VixDiskLib error.  I'm out of ideas, any diag logs I can look at?

Gurvinder Rait's picture

Please enable following registry on media server and run just the file server VM Job :

  1. Go to HKEY_LOCAL_MACHINE\SOFTWARE\Symantec\Backup Exec for Windows\Backup Exec\Engine\VMware Agent.

VMware Agent debug log level to 1

Go to HKEY_LOCAL_MACHINE\SOFTWARE\Symantec\Backup Exec for Windows\Backup Exec\Engine\Logging

  1. Set the value for CreateDebugLog to 1

 

The log will be created at BE Install Path\Logs. Look for errors towards the end of Beremote log (when the job fails) and post a part of it.

Thanks

ronnieshih's picture

I just followed your step and I think this is the log file here.  Backup ran against only that one VM machine.

<<<<<<<<<<<< LOGGING ON >>>>>>>>>>>>>>>>>>>
[1764] 07/10/13 09:10:07 [server]             - JobEngine::LaunchJob
[1764] 07/10/13 09:10:07 [server]             - RunJobWithGuidAndServer( {A12BDBE1-07B4-4168-AF5F-DFA524B631AE}, BK1 ) = 0
[6184] 07/10/13 09:10:07 [server]             - Thread for job VM Backup Test-VM Backup Test-VM Backup Test ({A12BDBE1-07B4-4168-AF5F-DFA524B631AE}) starting
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork enabled 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork useAny 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork protocol 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork subnet ---><---
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork MAC ---><---
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork IPv4 Enabled 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork IPv4 subnetAddress 0.0.0.0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork IPv4 subnetMask 0.0.0.0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork IPv4 autoObtain 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork IPv4 physical
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork selectedProtocol 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork InterfaceIndexProtocol 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork InterfaceIndex 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork subnet <zero>
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork PrefixLength 0
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork ipAddr <zero>
[6184] 07/10/13 09:10:07 [ndmp\ndmpclient]    - viaNetwork FallBackOptions 0xF  Protocol Tunnel NIC Subnet
[6880] 07/10/13 09:10:07 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x0 0x0)
[6880] 07/10/13 09:10:07 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[6184] 07/10/13 09:10:07 [server]             - Checking for Evaluation expiration.
[6184] 07/10/13 09:10:07 [engapi]             - ENGSCRPT: ConvertDeviceName osId = 0X4c
[6184] 07/10/13 09:10:07 [engapi]             - ENGSCRPT: IN - oldDeviceName = VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\FS1
[6184] 07/10/13 09:10:07 [engapi]             - ENGSCRPT: OUT - newName = VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\FS1
[6184] 07/10/13 09:10:07 [engapi]             - SetupCryptInfoInBSD: Backup encryption options: bHWEncryption=0,bSWEncryption=0,bSWEncryptionIfNoHW=0
[6184] 07/10/13 09:10:07 [engapi]             - ENGSCRPT: No script found
[6184] 07/10/13 09:10:07 [server]             - Failed to Load AllowExcludes key, We will update DR file evenif there are userExcludes. Error: 5
[6184] 07/10/13 09:10:07 [server]             - MountMultiple: Created MountThread thread 7940
[6276] 07/10/13 09:10:07 [server]             - DeviceManager: incoming event fired
[6276] 07/10/13 09:10:07 [server]             - DeviceManager: Executing RequestDeviceCall from thread 7940.
[6276] 07/10/13 09:10:07 [server]             - DeviceManager: processing pending requests
[6276] 07/10/13 09:10:07 [server]             - DeviceManager: Processing device request for thread 7940.
[6276] 07/10/13 09:10:07 [server]             - DeviceManager: query cache miss
[6276] 07/10/13 09:10:07 [server]             - Available and held drives from the pool
[6276] 07/10/13 09:10:07 [server]             -     Deduplication Storage Folder 0001:1 {9ff8b84c-83c3-4069-91c9-e4318c9df3fd}
[6276] 07/10/13 09:10:07 [server]             -     Deduplication Storage Folder 0001:2 {df7819a8-55c2-4ab8-9710-d951b2699fd6}
[6276] 07/10/13 09:10:07 [server]             - Drives not in use by the Engine
[6276] 07/10/13 09:10:07 [server]             -     Deduplication Storage Folder 0001:1 {9ff8b84c-83c3-4069-91c9-e4318c9df3fd}
[6276] 07/10/13 09:10:07 [server]             -     Deduplication Storage Folder 0001:2 {df7819a8-55c2-4ab8-9710-d951b2699fd6}
[6276] 07/10/13 09:10:07 [server]             - Drives available (not in use and not held)
[6276] 07/10/13 09:10:07 [server]             -     Deduplication Storage Folder 0001:1 {9ff8b84c-83c3-4069-91c9-e4318c9df3fd}
[6276] 07/10/13 09:10:07 [server]             -     Deduplication Storage Folder 0001:2 {df7819a8-55c2-4ab8-9710-d951b2699fd6}
[6276] 07/10/13 09:10:07 [server]             - DeviceManager: Handing out session {1b073a8f-5d12-4842-9a08-e64cd2544aaf} based on available drive:
[6276] 07/10/13 09:10:07 [server]             -     Deduplication Storage Folder 0001:1 {9ff8b84c-83c3-4069-91c9-e4318c9df3fd}
[6276] 07/10/13 09:10:07 [server]             - DeviceManager: returned result to caller 0x00000000
[6276] 07/10/13 09:10:07 [server]             - DeviceManager: going to sleep for 900000 msecs
[7940] 07/10/13 09:10:07 [server]             - BackupJob::MountThread : Clearing device host as IsDeviceOST is TRUE and RMAEnableDirectAccess is FALSE.
[7940] 07/10/13 09:10:07 [server]             - BackupJob::MountThread : Clearing device host as IsDeviceOST is TRUE and RMAEnableDirectAccess is FALSE.
[7940] 07/10/13 09:10:07 [server]             - BackupJob::MountThread : Device path hint :  m_deviceHost.empty() is TRUE
[7940] 07/10/13 09:10:07 [server]             - BackupJob: thread id 0x00001F04 acquired device Deduplication Storage Folder 0001:1.
[7940] 07/10/13 09:10:07 [server]             - BackupJob: thread id 0x00001F04 trying to mount appending volume.
[7940] 07/10/13 09:10:07 [server]             - BackupJob: thread id 0x00001F04 unable to mount appending volume, attempting scratch mount.
[6880] 07/10/13 09:10:12 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x0 0x8)
[6880] 07/10/13 09:10:12 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[7940] 07/10/13 09:10:19 [server]             - Updating session {1b073a8f-5d12-4842-9a08-e64cd2544aaf} with drive Deduplication Storage Folder 0001:2 {df7819a8-55c2-4ab8-9710-d951b2699fd6}
[7940] 07/10/13 09:10:19 [server]             - BackupJob: thread id 0x00001F04 medium successfully mounted.
[6184] 07/10/13 09:10:19 [server]             - Job::GetTargetNdmpServerName(): Execute(ADAMM_MOVER_EXECUTE_GET_SERVER_INFO) No server found.
[6184] 07/10/13 09:10:19 [server]             - Media Label: OST00000027-4A66CCDDD64A3FF6
[6184] 07/10/13 09:10:19 [server]             - Media Label: {8d7127bf-d420-490c-b4cf-6c1f1c8211bb}
[6184] 07/10/13 09:10:19 [server]             - Overwrite Protected Until: 7/31/2013 9:10:18 AM
[6184] 07/10/13 09:10:19 [server]             - Appendable Until: 7/16/2013 9:10:18 AM
[6184] 07/10/13 09:10:19 [tapealrt]           - TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[6184] 07/10/13 09:10:19 [tapealrt]           - TAPEALERT: TapeAlert Device Flag  = 0X0
[6184] 07/10/13 09:10:19 [tapealrt]           - TAPEALERT: TapeAlert Changer Flag = 0X0
[6184] 07/10/13 09:10:19 [tapealrt]           - TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[6184] 07/10/13 09:10:19 [tapealrt]           - TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[6184] 07/10/13 09:10:19 [server]             - Job Family ID: {4384FFAC-67AE-468B-8DE0-9983013AF781}
[6184] 07/10/13 09:10:19 [beutil]             - VM-Metadata: GetRefCatMetadataFromDB: Entered.
[6184] 07/10/13 09:10:19 [beutil]             - VM-Metadata: GetRefCatMetadataFromDB: Before main metadata loop.
[6184] 07/10/13 09:10:19 [beutil]             - VM-Metadata: GetRefCatMetadataFromDB: PropertyID == REFERENCE_CATALOG_ID.
[6184] 07/10/13 09:10:19 [beutil]             - VM-Metadata: GetRefCatMetadataFromDB: Release MAJOR == MALTA.
[6184] 07/10/13 09:10:19 [beutil]             - ReadRefCatBlobMaltaVersion() VM-MetaData: Entered
[6184] 07/10/13 09:10:19 [beutil]             - ReadRefCatBlobMaltaVersion() VM-MetaData: Entered exterior for loop
[6184] 07/10/13 09:10:19 [beutil]             - ReadRefCatBlobMaltaVersion() VM-MetaData: Entered interior for loop
[6184] 07/10/13 09:10:19 [beutil]             - ReadRefCatBlobMaltaVersion() VM-MetaData: SKIPPING... pBSD->dle_name = VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\FS1, pDeviceName = VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\kks4
[6184] 07/10/13 09:10:19 [server]             - Deduplication Storage Folder 0001:2 Block size:  65536
[6184] 07/10/13 09:10:19 [server]             - Deduplication Storage Folder 0001:2 Buffer size: 65536
[6184] 07/10/13 09:10:19 [server]             - Deduplication Storage Folder 0001:2 Num buffers:    10
[6184] 07/10/13 09:10:19 [server]             - Deduplication Storage Folder 0001:2 High water:      0
[6184] 07/10/13 09:10:19 [loops]              - NDMPAgentConnector:SetupConnection(): Data Server = BK1
[6184] 07/10/13 09:10:19 [ndmp\ndmpcomm]      - Could not resolve the "bews-ndmp" or the "ndmp" service, error code: 10109, using port 10000
[6184] 07/10/13 09:10:19 [ndmp\ndmpcomm]      - ndmpConnectEx: 'BK1' resolves to the local machine itself. So, we will try and connect to a loopback address ...
[6184] 07/10/13 09:10:19 [ndmp\ndmpcomm]      - ndmpConnectEx : Control Connection information: A connection was established between end-points [::1]:58506 and [::1]:10000.
[6184] 07/10/13 09:10:20 [ndmp\ndmpclient]    - NDMP version 3 connection CONNECTED
[6184] 07/10/13 09:10:20 [loops]              - NDMPAgentConnector::AuthenticateClient(): Using SSPI authentication with SLA/DLA as a fallback
[6184] 07/10/13 09:10:20 [loops]              - NDMPAgentConnector::ConnectAuthUseSSPIasDefault(): Attempting SSPI authentication...
[6184] 07/10/13 09:10:20 [ndmp\ndmpclient]    - connectClientAuth(): agent is on local loopback, skipping SSL connection...
[6184] 07/10/13 09:10:20 [ndmp\ndmpcomm]      - NDMP_SSPI: InitializeSecurityContext status 0x00090312 in 0 out 49
[6184] 07/10/13 09:10:20 [ndmp\ndmpcomm]      - NDMP_SSPI: InitializeSecurityContext status 0x00000000 in 202 out 88
[6184] 07/10/13 09:10:20 [ndmp\ndmpcomm]      - NDMP_SSPI: client authenticated with server
[6184] 07/10/13 09:10:20 [loops]              - NDMPAgentConnector::ConnectAuthUseSSPIasDefault(): SSPI authentication success.
[6184] 07/10/13 09:10:20 [loops]              - Enabling Shared Buffers Connection type
[6184] 07/10/13 09:10:20 [loops]              - NDMPAgentConnector::EndConnection(): Data Server = BK1
[6184] 07/10/13 09:10:20 [loops]              - Enter CheckHostBSDsForSnaps
[6184] 07/10/13 09:10:20 [loops]              - Exit CheckHostBSDsForSnaps: false
[6184] 07/10/13 09:10:20 [loops]              - NDMPAgentConnector:SetupConnection(): Data Server = BK1
[6184] 07/10/13 09:10:20 [ndmp\ndmpcomm]      - Could not resolve the "bews-ndmp" or the "ndmp" service, error code: 10109, using port 10000
[6184] 07/10/13 09:10:20 [ndmp\ndmpcomm]      - ndmpConnectEx: 'BK1' resolves to the local machine itself. So, we will try and connect to a loopback address ...
[6184] 07/10/13 09:10:20 [ndmp\ndmpcomm]      - ndmpConnectEx : Control Connection information: A connection was established between end-points [::1]:58508 and [::1]:10000.
[6184] 07/10/13 09:10:20 [ndmp\ndmpclient]    - NDMP version 3 connection CONNECTED
[6184] 07/10/13 09:10:20 [ndmp\ndmpclient]    - connectClientAuth(): agent is on local loopback, skipping SSL connection...
[6184] 07/10/13 09:10:21 [loops]              - Enabling Shared Buffers Connection type
[6184] 07/10/13 09:10:21 [loops]              - PDI - Querying application server(\\BK1) for PDI support.
[6184] 07/10/13 09:10:21 [loops]              - Application server(\\BK1) supports PDI
[6184] 07/10/13 09:10:21 [loops]              - Querying PDI data store server(BK1) for PDI support.
[6184] 07/10/13 09:10:21 [loops]              - NDMPAgentConnector:SetupConnection(): Data Server = BK1
[6184] 07/10/13 09:10:21 [ndmp\ndmpcomm]      - Could not resolve the "bews-ndmp" or the "ndmp" service, error code: 10109, using port 10000
[6184] 07/10/13 09:10:21 [ndmp\ndmpcomm]      - ndmpConnectEx: 'BK1' resolves to the local machine itself. So, we will try and connect to a loopback address ...
[6184] 07/10/13 09:10:21 [ndmp\ndmpcomm]      - ndmpConnectEx : Control Connection information: A connection was established between end-points [::1]:58512 and [::1]:10000.
[6184] 07/10/13 09:10:21 [ndmp\ndmpclient]    - NDMP version 3 connection CONNECTED
[6184] 07/10/13 09:10:21 [loops]              - NDMPAgentConnector::AuthenticateClient(): Using SSPI authentication with SLA/DLA as a fallback
[6184] 07/10/13 09:10:21 [loops]              - NDMPAgentConnector::ConnectAuthUseSSPIasDefault(): Attempting SSPI authentication...
[6184] 07/10/13 09:10:21 [ndmp\ndmpclient]    - connectClientAuth(): agent is on local loopback, skipping SSL connection...
[6184] 07/10/13 09:10:21 [ndmp\ndmpcomm]      - NDMP_SSPI: InitializeSecurityContext status 0x00090312 in 0 out 49
[6184] 07/10/13 09:10:21 [ndmp\ndmpcomm]      - NDMP_SSPI: InitializeSecurityContext status 0x00000000 in 202 out 88
[6184] 07/10/13 09:10:21 [ndmp\ndmpcomm]      - NDMP_SSPI: client authenticated with server
[6184] 07/10/13 09:10:21 [loops]              - NDMPAgentConnector::ConnectAuthUseSSPIasDefault(): SSPI authentication success.
[6184] 07/10/13 09:10:21 [loops]              - Enabling Shared Buffers Connection type
[6184] 07/10/13 09:10:21 [loops]              - PDI data store server(BK1) supports PDI
[6184] 07/10/13 09:10:21 [loops]              - NDMPAgentConnector::EndConnection(): Data Server = BK1
[6184] 07/10/13 09:10:21 [loops]              - PDI processor needed.
[6184] 07/10/13 09:10:21 [loops]              - Failed to Load AllowExcludes key, We will update DR file evenif there are userExcludes. Error: 5
[6184] 07/10/13 09:10:21 [loops]              - NDMPHostBackupEngine::CollectMetaDataForOneVirtualMachineBeforeBackup: entered
[6184] 07/10/13 09:10:21 [loops]              - NDMPHostBackupEngine::GetGuestComputerName: entered
[6880] 07/10/13 09:10:22 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x0 0xB)
[6880] 07/10/13 09:10:22 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::GetGuestComputerName: exiting void function
[6184] 07/10/13 09:10:23 [fsys\shared]        - ClusterVirutalNameToNodeName failed
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::ConnectToVirtualMachine: entered PDI Operation Type 1 PDIDataTransferPhase 1
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::ConnectToVirtualMachine: VM friendly name '\(DC)ha-datacenter(DC)\vm\FS1' guest computer name 'FS1.kkworx.local'
[6184] 07/10/13 09:10:23 [loops]              - NDMPAgentConnector:SetupConnection(): Data Server = FS1.kkworx.local
[6184] 07/10/13 09:10:23 [ndmp\ndmpcomm]      - Could not resolve the "bews-ndmp" or the "ndmp" service, error code: 10109, using port 10000
[6184] 07/10/13 09:10:23 [ndmp\ndmpcomm]      - ndmpConnectEx: Querying the neighbour advertisement cache to discover information on 'FS1.kkworx.local' ...
[6184] 07/10/13 09:10:23 [ndmp\ndmpcomm]      - ndmpConnectEx : Control Connection information: A connection was established between end-points [FE80::484D:1A61:41C5:2848%11]:58545 and [FE80::9195:66FB:76CB:8A11%11]:10000.
[6184] 07/10/13 09:10:23 [ndmp\ndmpclient]    - NDMP version 3 connection CONNECTED
[6184] 07/10/13 09:10:23                      - SSL connection using version TLSv1
[6184] 07/10/13 09:10:23                      - SSL connection using cipher AES256-SHA
[6184] 07/10/13 09:10:23 [ndmp\ndmpclient]    - secureNDMPConnection: SECURITY ENABLED!!
[6184] 07/10/13 09:10:23 [loops]              - IsLocalAgent:beclass::BEConvertServerNamePlus returned error: 87
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::ConnectToVirtualMachine: returning 0x0
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::RequestVirtualMachineMetaDataCollectionBeforeBackup: entered
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::RequestVirtualMachineMetaDataCollectionBeforeBackup: status 0 0x0
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::RequestVirtualMachineMetaDataCollectionBeforeBackup: reply result 0 0x0
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::RequestVirtualMachineMetaDataCollectionBeforeBackup: returning 0x0
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::DisconnectFromVirtualMachine: entered
[6184] 07/10/13 09:10:23                      - SSL Shutdown clean
[6184] 07/10/13 09:10:23 [loops]              - NDMPAgentConnector::EndConnection(): Data Server = FS1.kkworx.local
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::DisconnectFromVirtualMachine: returning 0x0
[6184] 07/10/13 09:10:23 [loops]              - NDMPHostBackupEngine::CollectMetaDataForOneVirtualMachineBeforeBackup: returning 0x0
[6184] 07/10/13 09:10:23 [tpfmt]              - TF_OpenTape()
[6184] 07/10/13 09:10:23 [tpfmt]              - TF_GetChannel( ) reusing channel 04A2C150
[6184] 07/10/13 09:10:23 [tpfmt]              - TF_GetDriveContext ...
     sessionGuid = {1b073a8f-5d12-4842-9a08-e64cd2544aaf}
     initAsync = 1
[6184] 07/10/13 09:10:23 [tpfmt]              - TF_MoverAsyncInit(): Started ProcessRequest thread 7120
[6184] 07/10/13 09:10:23 [tpfmt]              - HARDWARE COMPRESSION ===> Compression is NOT configurable.
[6184] 07/10/13 09:10:23 [tpfmt]              - HARDWARE ENCRYPTION ===> Encryption is NOT supported.
[6184] 07/10/13 09:10:23 [tpfmt]              - GET_DRV_INF: bsize = 1024
[6184] 07/10/13 09:10:23 [tpfmt]              - GET_DRV_INF: preferredBlockSize = 65536
[6184] 07/10/13 09:10:23 [tpfmt]              - TF_GetDriveContext returning 0x00000000, context = 4D59D90
[6184] 07/10/13 09:10:23 [tpfmt]              - Allocated 2 buffers, size 65536 bytes, total used: 131328
[6184] 07/10/13 09:10:23 [tpfmt]              - HARDWARE COMPRESSION ===> Compression is NOT configurable.
[6184] 07/10/13 09:10:23 [tpfmt]              - HARDWARE ENCRYPTION ===> Encryption is NOT supported.
[6184] 07/10/13 09:10:23 [tpfmt]              - GET_DRV_INF: bsize = 1024
[6184] 07/10/13 09:10:23 [tpfmt]              - GET_DRV_INF: preferredBlockSize = 65536
[6184] 07/10/13 09:10:23 [loops]              - PDI Backup to disk [\\.pdvfs\BK1\2\BEData\STHVMDK]. Starting phase 1...
[6184] 07/10/13 09:10:23 [loops]              - ValidatePDILocation: Validating PDI location: [\\.pdvfs\BK1\2\BEData\STHVMDK]. Temp path: [C:\TEMP]
[6184] 07/10/13 09:10:26 [loops]              - BaseBSDProcessor::PDIGetPureDiskChangerDevice : Changer GUID : {FC18EEFE-6012-4E78-96FD-F34220209186}
[6184] 07/10/13 09:10:26 [loops]              - Starting PDI Auto Expiry - Num of Images to expire: 1
[6184] 07/10/13 09:10:26 [loops]              - PDI Auto Expiry done - Num of images actually expired: 0
[6184] 07/10/13 09:10:26 [loops]              - Trying to create Restore BSD VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\FS1 for the PDI
[6184] 07/10/13 09:10:26 [server]             - BackupMessageHandler::GetTargetDeviceHostName(): Execute(ADAMM_MOVER_EXECUTE_GET_SERVER_INFO) No server found.
[6184] 07/10/13 09:10:26 [loops]              - NDMPAgentConnector:SetupConnection(): Data Server = BK1
[6184] 07/10/13 09:10:26 [ndmp\ndmpcomm]      - Could not resolve the "bews-ndmp" or the "ndmp" service, error code: 10109, using port 10000
[6184] 07/10/13 09:10:26 [ndmp\ndmpcomm]      - ndmpConnectEx: 'BK1' resolves to the local machine itself. So, we will try and connect to a loopback address ...
[6184] 07/10/13 09:10:26 [ndmp\ndmpcomm]      - ndmpConnectEx : Control Connection information: A connection was established between end-points [::1]:58558 and [::1]:10000.
[6184] 07/10/13 09:10:26 [ndmp\ndmpclient]    - NDMP version 3 connection CONNECTED
[6184] 07/10/13 09:10:26 [loops]              - NDMPAgentConnector::AuthenticateClient(): Using SSPI authentication with SLA/DLA as a fallback
[6184] 07/10/13 09:10:26 [loops]              - NDMPAgentConnector::ConnectAuthUseSSPIasDefault(): Attempting SSPI authentication...
[6184] 07/10/13 09:10:26 [ndmp\ndmpclient]    - connectClientAuth(): agent is on local loopback, skipping SSL connection...
[6184] 07/10/13 09:10:26 [ndmp\ndmpcomm]      - NDMP_SSPI: InitializeSecurityContext status 0x00090312 in 0 out 49
[6184] 07/10/13 09:10:26 [ndmp\ndmpcomm]      - NDMP_SSPI: InitializeSecurityContext status 0x00000000 in 202 out 88
[6184] 07/10/13 09:10:26 [ndmp\ndmpcomm]      - NDMP_SSPI: client authenticated with server
[6184] 07/10/13 09:10:26 [loops]              - NDMPAgentConnector::ConnectAuthUseSSPIasDefault(): SSPI authentication success.
[6184] 07/10/13 09:10:26 [loops]              - PDI backup - Starting data transfer between BK1 and BK1
[6184] 07/10/13 09:10:26 [loops]              - DeviceIsNT4Server: agent info: [Major Version=6 Minor Version=1 Build Number=7601 ServicePack Major=1 ServicePack Minor=0 SuiteMask=274 ProductType=3 ProcessorType=AMD64].
[6184] 07/10/13 09:10:26 [loops]              - DeviceIsIA64Server: agent info: [Major Version=6 Minor Version=1 Build Number=7601 ServicePack Major=1 ServicePack Minor=0 SuiteMask=274 ProductType=3 ProcessorType=AMD64].
[6184] 07/10/13 09:10:26 [loops]              - Could not generate FFR queue. result=0x0
[6184] 07/10/13 09:10:27 [ndmp\ndmpclient]    - 
dataStartBackup: ndmpSendRequest returned: 0x0, 0
[6880] 07/10/13 09:10:32 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x0 0xF)
[6880] 07/10/13 09:10:32 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[6184] 07/10/13 09:10:48 [server]             - eng_msgs::stop_spec_op, Nothing to do...
[6880] 07/10/13 09:10:52 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x0 0x0)
[6880] 07/10/13 09:10:52 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[6184] 07/10/13 09:11:15 [loops]              - PDI: Received catalog add status update (dblks will be added to catalogs))
[6184] 07/10/13 09:11:15 [loops]              - HandleSetMetaDataMessage() VM-MetaData: Received metadata for 'VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\FS1'. Snap: 'SYMC-DIFF 10-07-2013 09:10' Disks: 2 Change id: '564dd1f8-fd00-48a3-496c-d55ff4c8fffb(**)scsi0-0(*;)6000C29e-32d2-13fd-474e-a93a06e2baff(*;)52 c3 7b 0b 7b e6 85 47-60 ee 84 63 3e 9b d2 2c/108(**)scsi0-1(*;)6000C29d-f8f0-2e47-9261-d966552e31db(*;)52 bc bf cf 60 2f 01 12-c8 c9 1f 46 a6 28 b5 a5/108(**)' Chain: '564dd1f8-fd00-48a3-496c-d55ff4c8fffb(**)scsi0-0(*;)6000C29e-32d2-13fd-474e-a93a06e2baff(*;)*(**)scsi0-1(*;)6000C29d-f8f0-2e47-9261-d966552e31db(*;)*(**)'
[6184] 07/10/13 09:11:15 [loops]              - PDI: Received pdi location (\\.pdvfs\BK1\2\BEData\STHVMDK\IMG001846) update)
[6184] 07/10/13 09:11:15 [loops]              - notifyDataRead: Restore from PDI. Ignore the message...
[6880] 07/10/13 09:11:17 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x1 0x0)
[6880] 07/10/13 09:11:17 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[6184] 07/10/13 09:11:17 [loops]              - PDIBackupBSDProcessor::HandleMessage( ) - Ignoring the restore message : 0x00000003
[6184] 07/10/13 09:11:17 [loops]              - PDI: ignore fhExtendedAddFile message from the backup side...
[6184] 07/10/13 09:11:17 [loops]              - PDI: ignore fhExtendedAddFile message from the backup side...
[6184] 07/10/13 09:11:17 [loops]              - PDI: ignore fhExtendedAddFile message from the backup side...
[6184] 07/10/13 09:11:22 [loops]              - PDI: ignore fhExtendedAddFile message from the backup side...
[6184] 07/10/13 09:15:59 [loops]              - PDI: ignore fhExtendedAddFile message from the backup side...
[6276] 07/10/13 09:25:07 [server]             - DeviceManager: timeout event fired
[6276] 07/10/13 09:25:07 [server]             - DeviceManager: processing pending requests
[6276] 07/10/13 09:25:07 [server]             - DeviceManager: going to sleep for 900000 msecs
[6184] 07/10/13 09:30:40 [loops]              - PDIBackupBSDProcessor::HandleMessage( ) - Ignoring the restore message : 0x0000000D
[6184] 07/10/13 09:30:40 [loops]              - PDIBackupBSDProcessor::HandleMessage( ) - Ignoring the restore message : 0x0000000E
[6276] 07/10/13 09:40:07 [server]             - DeviceManager: timeout event fired
[6276] 07/10/13 09:40:07 [server]             - DeviceManager: processing pending requests
[6276] 07/10/13 09:40:07 [server]             - DeviceManager: going to sleep for 900000 msecs
[6184] 07/10/13 09:41:19 [loops]              - PDI: Received IPC object (BK1-VM-VCB-{5F1ECFA6-9EF1-4214-8272-B92B559FFCFC}) update)
[6184] 07/10/13 09:41:19 [loops]              - PDI: Received request for additional phase (additional phase(data mining) required so catalogs will not be closed, on media server, Requires pdi dle, Shares ipc.)
[6184] 07/10/13 09:41:33 [loops]              -  data halted: SUCCESSFUL
[6184] 07/10/13 09:41:33 [loops]              - BaseBSDProcessor::PollDataServer: Shutting down.
[6184] 07/10/13 09:41:37 [loops]              -  data halted: SUCCESSFUL
[6184] 07/10/13 09:41:37 [loops]              - BaseBSDProcessor::PollDataServer: Shutting down.
[6184] 07/10/13 09:41:37 [loops]              - PDI Backup to disk..starting phase 2 on media server...
[6184] 07/10/13 09:41:37 [loops]              - PdvfsSyncAndUpdateDeDupeStats: PDVFSReaderSync succeeded.
[6184] 07/10/13 09:41:37 [loops]              - PdvfsSyncAndUpdateDeDupeStats: Sucessfully gathered PDI Dedupe stats.
[6184] 07/10/13 09:41:38 [loops]              - PDI backup: Starting catalog generation on server [BK1]
[6184] 07/10/13 09:41:38 [loops]              - NDMPAgentConnector::EndConnection(): Data Server = BK1
[6184] 07/10/13 09:41:38 [loops]              - Failed to Load AllowExcludes key, We will update DR file evenif there are userExcludes. Error: 5
[6184] 07/10/13 09:41:38 [loops]              - NDMPAgentConnector:SetupConnection(): Data Server = BK1
[6184] 07/10/13 09:41:38 [ndmp\ndmpcomm]      - Could not resolve the "bews-ndmp" or the "ndmp" service, error code: 10109, using port 10000
[6184] 07/10/13 09:41:38 [ndmp\ndmpcomm]      - ndmpConnectEx: 'BK1' resolves to the local machine itself. So, we will try and connect to a loopback address ...
[6184] 07/10/13 09:41:38 [ndmp\ndmpcomm]      - ndmpConnectEx : Control Connection information: A connection was established between end-points [::1]:64824 and [::1]:10000.
[6184] 07/10/13 09:41:38 [ndmp\ndmpclient]    - NDMP version 3 connection CONNECTED
[6184] 07/10/13 09:41:38 [loops]              - NDMPAgentConnector::AuthenticateClient(): Using SSPI authentication with SLA/DLA as a fallback
[6184] 07/10/13 09:41:38 [loops]              - NDMPAgentConnector::ConnectAuthUseSSPIasDefault(): Attempting SSPI authentication...
[6184] 07/10/13 09:41:38 [ndmp\ndmpclient]    - connectClientAuth(): agent is on local loopback, skipping SSL connection...
[6184] 07/10/13 09:41:38 [ndmp\ndmpcomm]      - NDMP_SSPI: InitializeSecurityContext status 0x00090312 in 0 out 49
[6184] 07/10/13 09:41:38 [ndmp\ndmpcomm]      - NDMP_SSPI: InitializeSecurityContext status 0x00000000 in 202 out 88
[6184] 07/10/13 09:41:38 [ndmp\ndmpcomm]      - NDMP_SSPI: client authenticated with server
[6184] 07/10/13 09:41:38 [loops]              - NDMPAgentConnector::ConnectAuthUseSSPIasDefault(): SSPI authentication success.
[6184] 07/10/13 09:41:38 [loops]              - DeviceIsNT4Server: agent info: [Major Version=6 Minor Version=1 Build Number=7601 ServicePack Major=1 ServicePack Minor=0 SuiteMask=274 ProductType=3 ProcessorType=AMD64].
[6184] 07/10/13 09:41:38 [loops]              - DeviceIsIA64Server: agent info: [Major Version=6 Minor Version=1 Build Number=7601 ServicePack Major=1 ServicePack Minor=0 SuiteMask=274 ProductType=3 ProcessorType=AMD64].
[6184] 07/10/13 09:41:38 [ndmp\ndmpclient]    - 
dataStartBackup: ndmpSendRequest returned: 0x0, 0
[6880] 07/10/13 09:41:42 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x1 0x10)
[6880] 07/10/13 09:41:42 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[6184] 07/10/13 09:42:04 [loops]              - PDI: Received catalog add status update (dblks will be added to catalogs))
[6184] 07/10/13 09:42:04 [server]             - MSG_START_VIRTUAL_BACKUP_SET: StartShallowBackup():
[6184] 07/10/13 09:42:04 [server]             -    Volume Name     : \\FS1.kkworx.local\C:
[6184] 07/10/13 09:42:04 [server]             -    Volume Label    :
[6184] 07/10/13 09:42:04 [server]             -    Mount String    : MountType: "4" OrigVolGUID: "Volume{73be0ad7-763b-11e1-ac3a-806e6f6e6963}" File: "0" Offset: "105906176" Letter: "C:"
[6184] 07/10/13 09:42:04 [server]             -    OS Id           : 0x0E
[6184] 07/10/13 09:42:04 [server]             -    os Ver          : 0x03
[6184] 07/10/13 09:42:04 [server]             -    Volume Size     : 0xFFFFFFFF
[6184] 07/10/13 09:42:04 [server]             -    Vol Free Space  : 0x85023000
[6184] 07/10/13 09:42:04 [server]             -    Vol Used Space  : 0x7AFDCFFF
[6184] 07/10/13 09:42:04 [server]             - MSG_START_VIRTUAL_BACKUP_SET: UpdateShallowbackupPDIFragInfo() - Segment Name: FS1-000001.vmdk; Relative Location: FS1\FS1-000001.vmdk; Segment Attribute: 0x2
[6184] 07/10/13 09:42:04 [loops]              - BackupBSDProcessor::ExtendedAddFile: m_bVirtSet 1 m_virtDataId 14 m_virtBedsId 76 m_virtBedsVer 0
[6184] 07/10/13 09:43:29 [server]             - MSG_END_VIRTUAL_BACKUP_SET: cat_build->FinishShallowBackup( ) succeeded.
[6184] 07/10/13 09:43:29 [server]             - MSG_START_VIRTUAL_BACKUP_SET: StartShallowBackup():
[6184] 07/10/13 09:43:29 [server]             -    Volume Name     : \\FS1.kkworx.local\D:
[6184] 07/10/13 09:43:29 [server]             -    Volume Label    :
[6184] 07/10/13 09:43:29 [server]             -    Mount String    : MountType: "4" OrigVolGUID: "Volume{2a4b3405-760f-11e1-96a8-000c29c8fffb}" File: "0" Offset: "1048576" Letter: "D:"
[6184] 07/10/13 09:43:29 [server]             -    OS Id           : 0x0E
[6184] 07/10/13 09:43:29 [server]             -    os Ver          : 0x03
[6184] 07/10/13 09:43:29 [server]             -    Volume Size     : 0xFFFFFFFF
[6184] 07/10/13 09:43:29 [server]             -    Vol Free Space  : 0x5F8E4000
[6184] 07/10/13 09:43:29 [server]             -    Vol Used Space  : 0xA071BFFF
[6184] 07/10/13 09:43:29 [server]             - MSG_START_VIRTUAL_BACKUP_SET: UpdateShallowbackupPDIFragInfo() - Segment Name: FS1_1-000001.vmdk; Relative Location: FS1\FS1_1-000001.vmdk; Segment Attribute: 0x2
[6184] 07/10/13 09:43:29 [loops]              - BackupBSDProcessor::ExtendedAddFile: m_bVirtSet 1 m_virtDataId 14 m_virtBedsId 76 m_virtBedsVer 0
[6184] 07/10/13 09:45:00 [server]             - MSG_END_VIRTUAL_BACKUP_SET: cat_build->FinishShallowBackup( ) succeeded.
[6184] 07/10/13 09:45:00 [server]             - MSG_START_VIRTUAL_BACKUP_SET: StartShallowBackup():
[6184] 07/10/13 09:45:00 [server]             -    Volume Name     : \\FS1.kkworx.local\Volume{73be0ad6-763b-11e1-ac3a-806e6f6e6963}
[6184] 07/10/13 09:45:00 [server]             -    Volume Label    : System Reserved
[6184] 07/10/13 09:45:00 [server]             -    Mount String    : MountType: "4" OrigVolGUID: "Volume{73be0ad6-763b-11e1-ac3a-806e6f6e6963}" File: "0" Offset: "1048576" Letter: "Volume{73be0ad6-763b-11e1-ac3a-806e6f6e6963}"
[6184] 07/10/13 09:45:00 [server]             -    OS Id           : 0x0E
[6184] 07/10/13 09:45:00 [server]             -    os Ver          : 0x03
[6184] 07/10/13 09:45:00 [server]             -    Volume Size     : 0xFFFFFFFF
[6184] 07/10/13 09:45:00 [server]             -    Vol Free Space  : 0x04BDE000
[6184] 07/10/13 09:45:00 [server]             -    Vol Used Space  : 0xFB421FFF
[6184] 07/10/13 09:45:00 [server]             - MSG_START_VIRTUAL_BACKUP_SET: UpdateShallowbackupPDIFragInfo() - Segment Name: FS1-000001.vmdk; Relative Location: FS1\FS1-000001.vmdk; Segment Attribute: 0x2
[6184] 07/10/13 09:45:00 [loops]              - BackupBSDProcessor::ExtendedAddFile: m_bVirtSet 1 m_virtDataId 14 m_virtBedsId 76 m_virtBedsVer 0
[6184] 07/10/13 09:45:01 [server]             - MSG_END_VIRTUAL_BACKUP_SET: cat_build->FinishShallowBackup( ) succeeded.
[6184] 07/10/13 09:45:01 [loops]              - PDI: Received IPC object (BK1-VM-VCB-{5F1ECFA6-9EF1-4214-8272-B92B559FFCFC}) update)
[6184] 07/10/13 09:45:01 [loops]              - PDI: Received request for additional phase (No additional phase required so catalogs will be closed, Invalid target server, does not require pdi dle, Does not share ipc.)
[6184] 07/10/13 09:45:41 [loops]              -  data halted: SUCCESSFUL
[6184] 07/10/13 09:45:41 [loops]              - BaseBSDProcessor::PollDataServer: Shutting down.
[6184] 07/10/13 09:45:41 [loops]              - PDI backup: Catalog generation done
[6184] 07/10/13 09:45:41 [server]             - VM-MetaData: Backup of the resource VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\FS1 has failed(0) or canceled(0). Resetting the metadata. Disks: '2' to '0' Change id: '564dd1f8-fd00-48a3-496c-d55ff4c8fffb(**)scsi0-0(*;)6000C29e-32d2-13fd-474e-a93a06e2baff(*;)52 c3 7b 0b 7b e6 85 47-60 ee 84 63 3e 9b d2 2c/108(**)scsi0-1(*;)6000C29d-f8f0-2e47-9261-d966552e31db(*;)52 bc bf cf 60 2f 01 12-c8 c9 1f 46 a6 28 b5 a5/108(**)' to 'No change id' Chain: '564dd1f8-fd00-48a3-496c-d55ff4c8fffb(**)scsi0-0(*;)6000C29e-32d2-13fd-474e-a93a06e2baff(*;)*(**)scsi0-1(*;)6000C29d-f8f0-2e47-9261-d966552e31db(*;)*(**)' to 'No chain change id'
[6184] 07/10/13 09:45:41 [beutil]             - FillRefCatBlob() VM-MetaData: Entered
[6184] 07/10/13 09:45:41 [beutil]             - FillRefCatBlob() VM-MetaData: entered for loop
[6184] 07/10/13 09:45:41 [beutil]             - FillRefCatBlob() VM-MetaData: modifying bsdMachineName = 10.200.1.40
[6184] 07/10/13 09:45:41 [beutil]             - FillRefCatBlob() VM-MetaData: Directly before VMVCB check
[6184] 07/10/13 09:45:41 [beutil]             - FillRefCatBlob() VM-MetaData: Saving metadata for 'VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\FS1'-'10.200.1.40'. Disks: 0 Change id: 'No change id' Chain: 'No chain change id'
[6184] 07/10/13 09:45:41 [server]             - BackupMessageHandlerForBackupJob::process( eng_msgs::close_catalog & msg ) called
[6184] 07/10/13 09:45:41 [server]             - Not: 'm_bCatalogDrivenBackup && CatBuildVector[engine_id] && GetCarryFwdCatalogInfoForRemainingObjs( )'
[6184] 07/10/13 09:45:41 [server]             - called CatBuildVector[engine_id]->GetErrorCondition() successfully
[6184] 07/10/13 09:45:41 [server]             - BackupMessageHandler::CDB_EndCurrentCatalogOperation(  ) -- entered
[6184] 07/10/13 09:45:41 [server]             - BackupMessageHandler::CDB_EndCurrentCatalogOperation(  ) is calling PerBSDDataVector[engine_id]->EndCatOperation( )
[6184] 07/10/13 09:45:41 [server]             - EndCatOperation succeeded
[6184] 07/10/13 09:45:41 [server]             - BackupMessageHandler::CDB_EndCurrentCatalogOperation(  ) -- returning
[6184] 07/10/13 09:45:41 [server]             - calling CatBuildVector[engine_id]->FinishBackup( ) for non-cat drive backup
[6880] 07/10/13 09:45:42 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x1 0x0)
[6880] 07/10/13 09:45:42 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[6184] 07/10/13 09:45:44 [loops]              - PDI backup - done. result = 0
[6184] 07/10/13 09:45:44 [loops]              - NDMPAgentConnector::EndConnection(): Data Server = BK1
[6184] 07/10/13 09:45:44 [loops]              - NDMPAgentConnector::EndConnection(): Data Server = BK1
[6184] 07/10/13 09:45:44 [tpfmt]              - OST ===> Closing image.
[6184] 07/10/13 09:45:45 [tpfmt]              - OST ===> Stats: PDDO Stats for (BK1): scanned: 0 KB, stream rate: 0.00 MB/sec, CR sent: 13 KB, dedup: 0.0%, cache hits: 0 (0.0%)
[6184] 07/10/13 09:45:45 [loops]              - PDI DeDupe Stats: scanned: 0KB, stored: 0KB
[6184] 07/10/13 09:45:45 [tpfmt]              - OST ===> Closing image.
[6184] 07/10/13 09:45:45 [tpfmt]              - TF_PutChannel( ) 04A2C150
[6184] 07/10/13 09:45:45 [tpfmt]              - TF_FreeDriveContext( 4D59D90 )
[6184] 07/10/13 09:45:45 [tpfmt]              - TF_FreeTapeBuffers: from 2 to 0 buffers
[6184] 07/10/13 09:45:45 [tapealrt]           - TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[6184] 07/10/13 09:45:45 [tapealrt]           - TAPEALERT: TapeAlert Device Flag  = 0X0
[6184] 07/10/13 09:45:45 [tapealrt]           - TAPEALERT: TapeAlert Changer Flag = 0X0
[6184] 07/10/13 09:45:45 [tapealrt]           - TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[6184] 07/10/13 09:45:45 [tapealrt]           - TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[6276] 07/10/13 09:45:45 [server]             - DeviceManager: incoming event fired
[6276] 07/10/13 09:45:45 [server]             - DeviceManager: Executing ReturnDeviceCall from thread 6184.
[6276] 07/10/13 09:45:51 [server]             - DeviceManager: processing pending requests
[6276] 07/10/13 09:45:51 [server]             - DeviceManager: going to sleep for 900000 msecs
[6276] 07/10/13 09:45:51 [server]             - DeviceManager: dismount event fired
[6276] 07/10/13 09:45:51 [server]             - DeviceManager: processing pending requests
[6276] 07/10/13 09:45:51 [server]             - DeviceManager: going to sleep for 900000 msecs
[6184] 07/10/13 09:45:51 [server]             - Removing 'VM Backup Test-VM Backup Test-VM Backup Test' from status update list
[6184] 07/10/13 09:45:51 [server]             - Updating status for: 'VM Backup Test-VM Backup Test-VM Backup Test' (0x18 0x0)
[6184] 07/10/13 09:45:51 [server]             - Status for: 'VM Backup Test-VM Backup Test-VM Backup Test' updated
[6184] 07/10/13 09:45:51 [server]             - BackupJob::MergeBEVSRJobLogsIfNecessary: No VSR log file found, no merging necessary
[6184] 07/10/13 09:45:51 [server]             - Ending job 'VM Backup Test-VM Backup Test-VM Backup Test' with error status (-536832647)
[6184] 07/10/13 09:45:51 [server]             - Job thread terminating
 
ronnieshih's picture

This seems to be the line that pinpoints the failure:

VM-MetaData: Backup of the resource VMVCB::\\10.200.1.40\VCGuestVm\(DC)ha-datacenter(DC)\vm\FS1 has failed(0) or canceled(0). Resetting the metadata. Disks: '2' to '0' Change id: '564dd1f8-fd00-48a3-496c-d55ff4c8fffb(**)scsi0-0(*;)6000C29e-32d2-13fd-474e-a93a06e2baff(*;)52 c3 7b 0b 7b e6 85 47-60 ee 84 63 3e 9b d2 2c/108(**)scsi0-1(*;)6000C29d-f8f0-2e47-9261-d966552e31db(*;)52 bc bf cf 60 2f 01 12-c8 c9 1f 46 a6 28 b5 a5/108(**)' to 'No change id' Chain: '564dd1f8-fd00-48a3-496c-d55ff4c8fffb(**)scsi0-0(*;)6000C29e-32d2-13fd-474e-a93a06e2baff(*;)*(**)scsi0-1(*;)6000C29d-f8f0-2e47-9261-d966552e31db(*;)*(**)' to 'No chain change id'

Now I noticed that the backup against this VM is failing and this is the only VM with 2 vmdk files which forms the c: and d: drives.  It is not 1 volume with a logical partition.  I know there are a few articles regarding 1 volume with multiple logical partitions, but this is not the case.

ronnieshih's picture

BEREMOTE LOG, from beginning to end of the job,

[2412] 07/10/13 11:23:40 [push]               - Opened debug log file C:\Program Files\Symantec\Backup Exec\RAWS\logs\FS1-beremote01.log
[2412] 07/10/13 11:23:40 [push]               - Checking service rights and pending reboots.
[2412] 07/10/13 11:23:40 [push]               - Checking for pending install reboot.
[2412] 07/10/13 11:23:40 [push]               - Pending install reboot not detected.
[2412] 07/10/13 11:23:40 [push]               - Checking to see if start up checks have been disabled.
[2412] 07/10/13 11:23:40 [push]               - No start up checks have been disabled.
[2412] 07/10/13 11:23:40 [push]               - Opening process token.
[2412] 07/10/13 11:23:40 [push]               - Getting token SID.
[2412] 07/10/13 11:23:40 [push]               - Got current SID: 'S-1-5-18'.
[2412] 07/10/13 11:23:40 [push]               - Checking for local system account.
[2412] 07/10/13 11:23:40 [push]               - Got local system SID: 'S-1-5-18'.
[2412] 07/10/13 11:23:40 [push]               - Running as local system account.  No more checks will be done.
[2412] 07/10/13 11:23:40                      - Error accessing regkey: Software\Symantec\Backup Exec For Windows\Open File Option\ConfigOrphaned snaped can't be cleaned up. Maybe a privilage issue
[2412] 07/10/13 11:23:40 [besc]               - CleanupOrphanedSnapshots(). Lauching cleanup thread..
[2412] 07/10/13 11:23:40 [besc]               - CleanupOrphanedSnapshots(). Cleanup thread lauched. Exiting.
[0900] 07/10/13 11:23:40 [besc]               - VssSnapshotVolume::CleanupOrphanedSnapshots(). No orphaned snaphots found
[4068] 07/10/13 11:23:41 [fsys\shared]        - FS_InitFileSys
[4068] 07/10/13 11:23:41 [fsys\shared]        -   loaded bedsnt5.dll
[4068] 07/10/13 11:23:41 [fsys\shared]        -   bedsadc.dll could not be loaded: The specified module could not be found.
[4068] 07/10/13 11:23:41 [fsys\shared]        -   loaded bedssql2.dll
[4068] 07/10/13 11:23:41 [fsys\shared]        -   bedsxchg.dll could not be loaded: The specified module could not be found.
[4068] 07/10/13 11:23:42 [fsys\jet]           - VirtApi DLL WAS LOADED FROM VirtApi.dll.
[4068] 07/10/13 11:23:42 [fsys\jet]           - VirtApi DLL load check succeeded.
[4068] 07/10/13 11:23:42 [fsys\jet]           - Virtual DB's WILL BE USED!
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsxese.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsmbox.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   bedspush.dll could not be loaded: The specified module could not be found.
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsnote.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsmdoc.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedssps2.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedssps3.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsupfs.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsshadow.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsoffhost.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   bedsdpm.dll could not be loaded: The specified module could not be found.
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedscps.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   bedsvx.dll could not be loaded: The specified module could not be found.
[4068] 07/10/13 11:23:42 [fsys\shared]        -   bedsorcl.dll could not be loaded: The specified module could not be found.
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedssmsp.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsra.dll
[4068] 07/10/13 11:23:42 [fsys\shared]        -   loaded bedsrman.dll
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded bedsdb2.dll
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded bedsss.dll
[4068] 07/10/13 11:23:43 [fsys\jet]           - VirtApi DLL WAS LOADED FROM VirtApi.dll.
[4068] 07/10/13 11:23:43 [fsys\jet]           - VirtApi DLL load check succeeded.
[4068] 07/10/13 11:23:43 [fsys\jet]           - Virtual DB's WILL BE USED!
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded bedsadgran.dll
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded bedsev.dll
[4068] 07/10/13 11:23:43 [beutil]             - Failed to open EV Install key (SOFTWARE\KVS\Enterprise Vault\Install).
[4068] 07/10/13 11:23:43 [inc]                - [AgentID:25] ... failed to load bedstrace.dll.
[4068] 07/10/13 11:23:43 [fsys\shared]        - FS_DleGen: Failure to create debug trace object at line number 111
[4068] 07/10/13 11:23:43 [inc]                - [AgentID:2a] ... failed to load bedstrace.dll.
[4068] 07/10/13 11:23:43 [fsys\shared]        - FS_DleGen: Failure to create debug trace object at line number 111
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded bedsvrtsrv.dll
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded bedsvmvcb.dll
[4068] 07/10/13 11:23:43 [fsys\shared]        -   bedsspn.dll could not be loaded: The specified module could not be found.
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded bedsNTFSArchive.dll
[4068] 07/10/13 11:23:43 [fsys\mb2]           - MapiDll::Initialize() ... default MAPI32.DLL is loaded
[4068] 07/10/13 11:23:43 [fsys\mb2]           - MapiDll::Initialize() ... failed to get 'MAPIInitialize' (0x7f)
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded BedsExchMailArchival.dll
[4068] 07/10/13 11:23:43 [fsys\shared]        -   loaded bedsevm.dll
[4068] 07/10/13 11:23:43 [fsys\shared]        -   bedsdfsr.dll could not be loaded: The specified module could not be found.
[4068] 07/10/13 11:23:43 [fsys\shared]        - Initializing FSs
[4068] 07/10/13 11:23:43 [fsys\ntfs]          - Adding Windows 2008 files to move directly into place
[4068] 07/10/13 11:23:43 [fsys\mb2]           - calling mapi initialize
[4068] 07/10/13 11:23:43 [fsys\mb2]           - Mailbox: InitializeDAPI failed.
[4068] 07/10/13 11:23:43 [fsys\notes2]        - Notes Agent:CLNPartitions::InitializeLNUCJWrapper
[4068] 07/10/13 11:23:43 [fsys\notes2]        - Notes Agent:CLNPartitions::InitializeLNUCJWrapper - Exiting[0]
[4068] 07/10/13 11:23:43 [fsys\notes2]        - Notes Agent:CLNPartitions::InitializeAllVolumes
[4068] 07/10/13 11:23:43 [fsys\notes2]        - Notes Agent - CLNVolume::InitInstance - ReturnValue[0]
[4068] 07/10/13 11:23:43 [fsys\notes2]        - Notes Agent - CLNVolume::InitInstance - ReturnValue[0]
[4068] 07/10/13 11:23:43 [fsys\notes2]        - Notes Agent:CLNPartitions::InitializeAllVolumes - Exiting[0]
[4068] 07/10/13 11:23:43 [fsys\notes2]        - Notes Agent:CLNPartitions::InitInstance - Exiting[2]
[4068] 07/10/13 11:23:43 [fsys\oracle]        - Function called: RMAN_InitFileSys
[4068] 07/10/13 11:23:43 [engidrapi]          - IsIDRInProgressPriv: 0x0
[4068] 07/10/13 11:23:43 [engidrapi]          - IsIDRInProgressPriv: 0x0
[4068] 07/10/13 11:23:43 [fsys\shadow]        - Informational: Initializing the BeDiskFind library 'BEDiskFind.dll' in SHADOW::InitBeDiskFindHelperApis
[4068] 07/10/13 11:23:43 [fsys\shadow]        - Informational: BeDiskFind library 'BEDiskFind.dll' initialized in SHADOW::InitBeDiskFindHelperApis
[4068] 07/10/13 11:23:43 [fsys\shadow]        - Informational: Initializing the BeDisk library 'BeDisk.dll' in SHADOW::InitBeDiskHelperApis
[4068] 07/10/13 11:23:43 [fsys\shadow]        - Informational: BeDisk library 'BeDisk.dll' initialized in SHADOW::InitBeDiskHelperApis
[1980] 07/10/13 11:23:43 [fsys\mb2\edbprov]   - Event: Global\RxService CREATED
[4068] 07/10/13 11:23:43 [fsys\ese]           - first load attempt of esebcli2.dll failed: The specified module could not be found.
[4068] 07/10/13 11:23:43 [fsys\ese]           - Looking for esebcli2.dll in sysetm path
[4068] 07/10/13 11:23:43 [fsys\ese]           - never found EseBcli2.dll
[4068] 07/10/13 11:23:43 [fsys\ese]           - esebcli2.dll not loaded
[4068] 07/10/13 11:23:43 [fsys\shared]        - *** MSExchangeIS failed to get binary path
[4068] 07/10/13 11:23:43 [fsys\protsrvs\cps]  - Status Unknown (0x00000002) opening Cps registry key 'Software\Symantec\Backup Exec CPS' in CPS::InitCpsHelperApis:376
[4068] 07/10/13 11:23:43 [fsys\protsrvs\cps]  - Informational: Initializing the Cps library 'C:\Program Files\Symantec\Continuous Protection Server\Services\CPSVersion.dll' in CPS::InitCpsHelperApis:407
[4068] 07/10/13 11:23:43 [fsys\protsrvs\cps]  - Status Unknown (0x0000007E) loading Cps library 'C:\Program Files\Symantec\Continuous Protection Server\Services\CPSVersion.dll' in CPS::InitCpsHelperApis:414
[4068] 07/10/13 11:23:43 [fsys\protsrvs\cps]  - Status Unknown (0x0000007E) initializing Cps library in CPS::InitFsys:89
[4068] 07/10/13 11:23:43 [fsys\db2]           - Function called: DB2_InitFileSys
[4068] 07/10/13 11:23:43 [beutil]             - Input Error (       0) for Type: (43)
[4068] 07/10/13 11:23:43 [fsys\ev]            - Function called: EVM_InitFileSys
[4068] 07/10/13 11:23:43 [ndmp\ndmpsrvr]      - Checking whether to initialize the tape server or not ...
[4068] 07/10/13 11:23:43 [ndmp\ndmpsrvr]      - Win32AllowTapeServer: Could not open the key 'Software\Symantec\Backup Exec For Windows\Backup Exec\Tapeserver', error: 2
[4068] 07/10/13 11:23:43 [ndmp\ndmpsrvr]      - QueryIfServiceIsPresent: OpenService( 'BackupExecDeviceMediaService' ) failed, error: 1060
[4068] 07/10/13 11:23:43 [ndmp\ndmpsrvr]      - NDMPDMainThreadFunc: We are not part of a Media Server installation, so allowing the Tapeserver to initialize!
[4068] 07/10/13 11:23:44 [ndmp\ndmpcomm]      - Could not resolve the "bews-ndmp" or the "ndmp" service, error code: 10109, using port 10000
[4068] 07/10/13 11:23:45 [BESocket]           - @@@@@@@MyCloseSocket called with sockfd = 1040(0x410) retval = 0
[4068] 07/10/13 11:23:45 [BESocket]           - @@@@@@@MyCloseSocket called with sockfd = 1036(0x40c) retval = 0
[4068] 07/10/13 11:23:45 [BESocket]           - BETCPListener::BETCPListener: This system appears to be a Dual Stack system.
[4068] 07/10/13 11:23:45 [ndmp\ndmpcomm]      - Started NDMP Listener on port 10000
[2412] 07/10/13 11:23:45 [writermanager]      - IDS_INSTLIST_DEDUPE not installed
[2412] 07/10/13 11:23:45 [writermanager]      - {ERROR} PDDE::StartWriterProcess() return=[0x80070490 UNKNOWN ERROR]
[2412] 07/10/13 11:23:45 [push]               - Running... 'Q' to stop
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: advertisement cycle started.
[3960] 07/10/13 11:23:54 [fsys\ntfs\mnet]     - Informational: Restrict Anonymous Support is enabled
[3960] 07/10/13 11:23:54 [fsys\ntfs\mnet]     - creating DLE for local machine
[3960] 07/10/13 11:23:54 [BESocket]           - BENetConfigEx: Successfully refreshed adapter information.
[3960] 07/10/13 11:23:54 [fsys\ntfs\mnet]     - EnumClusterDLEs: Could not opening cluster : The system could not find the environment option that was entered.
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: EnumSelfDLE for file system 7 returned 0(0x0) and 1 DLEs
[3960] 07/10/13 11:23:54 [fsys\ese]           - AreYouSureThisIsAnExchangeServer: FS1
[3960] 07/10/13 11:23:54 [fsys\ese]           - AreYouSureThisIsAnExchangeServer FS1: 0
[3960] 07/10/13 11:23:54 [fsys\ese]           - AreYouSureThisIsAnExchangeServer: FS1
[3960] 07/10/13 11:23:54 [fsys\ese]           - AreYouSureThisIsAnExchangeServer FS1: 0
[3960] 07/10/13 11:23:54 [fsys\ese]           - AreYouSureThisIsAnExchangeServer: FS1
[3960] 07/10/13 11:23:54 [fsys\ese]           - AreYouSureThisIsAnExchangeServer FS1: 0
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: Nrds Message Len : 6089.
[3960] 07/10/13 11:23:54 [fsys\oracle]        - RMAN_EnumSelfDLE: AgentConfig GetOracleDBNames returned error. If Oracle Agent is installed, please run AgentConfig.
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: EnumSelfDLE for file system 14 returned 0(0x0) and 0 DLEs
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: EnumSelfDLE for file system 37 returned 0(0x0) and 0 DLEs
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: EnumSelfDLE for file system 39 returned 0(0x0) and 0 DLEs
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: EnumSelfDLE for file system 42 returned -536805816(0xE000FE48) and 0 DLEs
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: Security is enabled!!!
[3960] 07/10/13 11:23:54 [ndmp\ndmpcomm]      - GetCertificateDataFolderPath: Not checking for cluster.
[3960] 07/10/13 11:23:54 [nrds]               - ConnectToServerEndPoint: dest=BK1, service=6101
[3960] 07/10/13 11:23:55                      - SSL connection using version TLSv1
[3960] 07/10/13 11:23:55                      - SSL connection using cipher AES256-SHA
[3960] 07/10/13 11:23:55 [nrds]               - CreateConnection type=0 on socket 1204 via BESocket OK
[3960] 07/10/13 11:23:55 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: send of FS1.kkworx.local type 7 subtype 2 to target=BK1 port=6101 succeeded
[3960] 07/10/13 11:23:55 [BESocket]           - @@@@@@@MyCloseSocket called with sockfd = 1204(0x4b4) retval = 0
[3960] 07/10/13 11:23:55 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: Security is enabled!!!
[3960] 07/10/13 11:23:55 [ndmp\ndmpcomm]      - GetCertificateDataFolderPath: Not checking for cluster.
[3960] 07/10/13 11:23:55 [nrds]               - ConnectToServerEndPoint: dest=BK1.kkworx.local, service=6101
[3960] 07/10/13 11:23:55                      - SSL connection using version TLSv1
[3960] 07/10/13 11:23:55                      - SSL connection using cipher AES256-SHA
[3960] 07/10/13 11:23:55 [nrds]               - CreateConnection type=0 on socket 1232 via BESocket OK
[3960] 07/10/13 11:23:55 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: send of FS1.kkworx.local type 7 subtype 2 to target=BK1.kkworx.local port=6101 succeeded
[3960] 07/10/13 11:23:55 [BESocket]           - @@@@@@@MyCloseSocket called with sockfd = 1232(0x4d0) retval = 0
[3960] 07/10/13 11:23:55 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: advertisement cycle complete.  Waiting 240 minutes before advertising again.
[3128] 07/10/13 11:23:59 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: negative (purge) advertisement cycle started.
[3128] 07/10/13 11:23:59 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: no purge is pending.
[3128] 07/10/13 11:23:59 [ndmp\ndmpcomm]      - NrdsAdvertiserThread: negative (purge) advertisement cycle complete.  Waiting 240 minutes before advertising again.
[4068] 07/10/13 11:24:27 [ndmp\ndmpcomm]      - ndmpRun: Control connection accepted : connection established between end-points [FE80::9195:66FB:76CB:8A11%11]:10000 and [FE80::484D:1A61:41C5:2848%11]:52437
[2800] 07/10/13 11:24:27 [ndmp\ndmpsrvr]      - sslOpen() : Opening SSL for: 00000000DF7EC2AF
[2800] 07/10/13 11:24:27 [ndmp\ndmpsrvr]      - sslOpen(): certinfo = 00000000DF84B1CF ; sslConn = 00000000DF84FA9F
[2800] 07/10/13 11:24:27 [ndmp\ndmpcomm]      - GetCertificateDataFolderPath: Not checking for cluster.
[2800] 07/10/13 11:24:27                      - SSL connection using version TLSv1
[2800] 07/10/13 11:24:27                      - SSL connection using cipher AES256-SHA
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - Username for Logon: KKWORX\administrator
[2800] 07/10/13 11:24:28                      - BELogonUser: beclass::IsThisMe() returned error: 87
[2800] 07/10/13 11:24:28                      - LogonType set = [LOGON32_LOGON_BATCH][0x4]
[2800] 07/10/13 11:24:28                      - LogonUser(LOGON32_LOGON_BATCH-0x4) success
[2800] 07/10/13 11:24:28                      - Successfully impersonated KKWORX\administrator
[2800] 07/10/13 11:24:28                      - WhoAmI( ) reports: KKWORX\administrator
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - LogonuserError: 0
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - prep_for_full: The media server BK1.kkworx.local is already in the advertisement list.
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - prep_for_full: The media server BK1 is already in the advertisement list.
[2800] 07/10/13 11:24:28 [engidrapi]          - GetVirtualHardDisksNumbers() - Enter
[2800] 07/10/13 11:24:28 [engidrapi]          - GetVirtualHardDisksNumbers() - Exit
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - GetServerType for local machine
[2800] 07/10/13 11:24:28 [engidrapi]          - GetVirtualHardDisksNumbers() - Enter
[2800] 07/10/13 11:24:28 [engidrapi]          - GetVirtualHardDisksNumbers() - Exit
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - GetServerType for local machine
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - Finding MNET entries using PunchDownWithWNetCalls()
[2800] 07/10/13 11:24:28 [fsys\notes2]        - Notes Agent:FindDrives
[2800] 07/10/13 11:24:28 [fsys\oracle]        - No Oracle SID's were discovered
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - GetServerType for local machine
[2800] 07/10/13 11:24:28 [fsys\shadow]        - Device Shadow?Copy?Components Dle platform 2  major version 6  minor version 1  build 7601
[2800] 07/10/13 11:24:28 [fsys\upfs]          - No utility partitions found on any of the disks
[2800] 07/10/13 11:24:28 [fsys\ra]            - NRDS_RA_FindDrives entered
[2800] 07/10/13 11:24:28 [fsys\ra]            - NRDS_RA_FindDrives completed immediately because we aren't browsing
[2800] 07/10/13 11:24:28 [fsys\protsrvs\cps]  - Informational: Cps root device creation using default Cps library mechanism when creating device 'Cont?Prot?Srv' in CPS::DetermineRootCpsComponent:692
[2800] 07/10/13 11:24:28 [fsys\protsrvs\cps]  - Informational: Cps library not available.  Not creating Cps root device 'Cont?Prot?Srv' in CPS::DetermineRootCpsComponent:696
[2800] 07/10/13 11:24:28 [fsys\db2]           - Function called: DB2_FindDrives
[2800] 07/10/13 11:24:28 [fsys\shared]        - Status 0xE0008488 returned calling FindDrives for file system 28 in DLE_UpdateList
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:DeviceName "System?State" in SystemState::CreateDLEs:373
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:Full Device Path "System?State" in SystemState::CreateDLEs:378
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:ADRO Agent is authorized for System?State.
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:Found 0 instances of Active Directory Applcation Mode in SystemState::GetADAMInstanceCount:1415
[2800] 07/10/13 11:24:28 [fsys\ev]            - EVM_FindDrives: Function called
[2800] 07/10/13 11:24:28 [fsys\ev]            - EVM_FindDrives: Function Exit
[2800] 07/10/13 11:24:28 [fsys\sql2]          - SQL2_FindDrives - the default SQL Service is not running on FS1.
[2800] 07/10/13 11:24:28 [fsys\ese]           - [FSYS:ESE07]   FindDrives ... This is not an Exchange Server (0)
[2800] 07/10/13 11:24:28 [beutil]             - Input Error (       0) for Type: (43)
[2800] 07/10/13 11:24:28 [fsys\shared]        - FS_CreateTempDLE
[2800] 07/10/13 11:24:28 [fsys\shared]        -   11 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\shared]        -   12 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\notes2]        - Notes Agent:CLNFileSystem::CreateTempDLE
[2800] 07/10/13 11:24:28 [fsys\notes2]        - Notes Agent:CLNFileSystem::CreateTempDLE Exiting[-536805853]
[2800] 07/10/13 11:24:28 [fsys\shared]        -   13 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\oracle]        - RMAN_CreateTempDLE: Function called
[2800] 07/10/13 11:24:28 [fsys\oracle]        - CheckIfNodeNameIsClusterName: Node name passed is FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\oracle]        - CheckIfNodeNameIsClusterName: Server name converted is FS1
[2800] 07/10/13 11:24:28 [fsys\oracle]        - CheckIfNodeNameIsClusterName: The node name passed for check is FS1
[2800] 07/10/13 11:24:28 [fsys\oracle]        - CheckIfNodeNameIsClusterName:- The nodename passed is physical nodename.
[2800] 07/10/13 11:24:28 [fsys\oracle]        - The node ( FS1 ) is physical node name.
[2800] 07/10/13 11:24:28 [fsys\shared]        -   14 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\shared]        -   16 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\shared]        -   17 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\shared]        -   18 = 0x00000001
[2800] 07/10/13 11:24:28 [fsys\ese]           - CreateTempDLE: \\FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\shared]        -   19 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\shared]        -   20 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\shared]        -   21 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\ohfs]          - OFF_HOST_FS::OpenOHMetadataFile( ): error Opening the file (C:\Program Files\Symantec\Backup Exec\RAWS\Data\)
[2800] 07/10/13 11:24:28 [fsys\ohfs]          - OFF_HOST_FS::GetDLEDetailsFromMDSrc() Status E_FS_OFF_HOST_DATA_CREATE_ERROR (E0000301) Opening the metadata source
[2800] 07/10/13 11:24:28 [fsys\ohfs]          - OFF_HOST_FS::CreateTempDLE( ) Status E_FS_OFF_HOST_DATA_CREATE_ERROR (E0000301) creating Dle when creating temp Dle for device \\FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\shared]        -   23 = 0xE0000301
[2800] 07/10/13 11:24:28 [fsys\shared]        -   26 = 0x00000001
[2800] 07/10/13 11:24:28 [fsys\db2]           - ====>DB2_CreateTempDLE
[2800] 07/10/13 11:24:28 [fsys\shared]        -   28 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:Device (\\FS1.kkworx.local) is not ours...
[2800] 07/10/13 11:24:28 [fsys\shared]        -   30 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\shared]        -   31 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\ese]           - CreateTempDLE: \\FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\shared]        -   35 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\shared]        -   36 = 0xE00084AF
[2800] 07/10/13 11:24:28 [beutil]             - ApplyRegExp(): Invalid input (\\FS1.kkworx.local). Parsing Failed.
[2800] 07/10/13 11:24:28 [beutil]             - GoodEvName(): Invalid EV device (\\FS1.kkworx.local).
[2800] 07/10/13 11:24:28 [fsys\shared]        -   37 = 0x00000001
[2800] 07/10/13 11:24:28 [fsys\vrtsrv]        -   VRTSRV:Device does not belong to us...(0xe00084af)
[2800] 07/10/13 11:24:28 [fsys\shared]        -   38 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\vmvcb]         - VM_VCBPROXY_FS::CreateTempDLE( ) Status DRIVE_DESCRIPTOR_ERROR (E000FE23) creating Dle when creating temp Dle for device \\FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\shared]        -   39 = 0xE000FE23
[2800] 07/10/13 11:24:28 [beutil]             - ApplyRegExp(): Invalid input (\\FS1.kkworx.local). Parsing Failed.
[2800] 07/10/13 11:24:28 [beutil]             - GoodEvName(): Invalid EV device (\\FS1.kkworx.local).
[2800] 07/10/13 11:24:28 [fsys\shared]        -   42 = 0x00000001
[2800] 07/10/13 11:24:28 [fsys\shared]        -   45 = 0x00000001
[2800] 07/10/13 11:24:28 [fsys\shared]        -   46 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - Not valid device name : \\FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\shared]        -   47 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\ese]           - CreateTempDLE: \\FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\shared]        -   48 = 0xE00084AF
[2800] 07/10/13 11:24:28 [fsys\shared]        -    5 = 0xE000FE23
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - no NRDS cache-hit for FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - Informational: Restrict Anonymous Support is enabled
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - creating DLE for local machine
[2800] 07/10/13 11:24:28 [fsys\shared]        -    7 = 0x00000000
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - Finding MNET entries using MSNetFindLanManShares()
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - NTFS_SurrgateCalling: converted FS1.kkworx.local to FS1
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - Error 11001 opening cluster on FS1
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - Error 0 on NetShareEnum of \\FS1, level 1, entries 14, total 14
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze excluded share -->ADMIN$<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze admin / default share -->C$<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - adding share -->\\FS1.kkworx.local\C$<-- to the DLE list
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze user share -->Common<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - adding share -->\\FS1.kkworx.local\Common<-- to the DLE list
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze admin / default share -->D$<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - adding share -->\\FS1.kkworx.local\D$<-- to the DLE list
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze user share -->Key Construction<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - adding share -->\\FS1.kkworx.local\Key Construction<-- to the DLE list
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze user share -->Kiefer Insurance<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - adding share -->\\FS1.kkworx.local\Kiefer Insurance<-- to the DLE list
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze excluded share -->print$<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze user share -->Restricted<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - adding share -->\\FS1.kkworx.local\Restricted<-- to the DLE list
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - analyze user share -->User My Docs<--
[2800] 07/10/13 11:24:28 [fsys\ntfs\mnet]     - adding share -->\\FS1.kkworx.local\User My Docs<-- to the DLE list
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - NTFS_SurrogateCalling: FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - Error opening cluster on FS1.kkworx.local: No such host is known.
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - Enumerating local drives
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - Creating DLEs:
[2800] 07/10/13 11:24:28 [fsys\ntfs]          -     \\FS1.kkworx.local\C:
[2800] 07/10/13 11:24:28 [engidrapi]          - GetVirtualHardDisksNumbers() - Enter
[2800] 07/10/13 11:24:28 [engidrapi]          - GetVirtualHardDisksNumbers() - Exit
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - GetServerType for local machine
[2800] 07/10/13 11:24:28 [fsys\ntfs]          -     \\FS1.kkworx.local\D:
[2800] 07/10/13 11:24:28 [engidrapi]          - GetVirtualHardDisksNumbers() - Enter
[2800] 07/10/13 11:24:28 [engidrapi]          - GetVirtualHardDisksNumbers() - Exit
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - GetServerType for local machine
[2800] 07/10/13 11:24:28 [fsys\ntfs]          -     \\FS1.kkworx.local\X:
[2800] 07/10/13 11:24:28 [fsys\notes2]        - Notes Agent:CLNFileSystem::SurrogateCalling
[2800] 07/10/13 11:24:28 [fsys\oracle]        - CheckIfNodeNameIsClusterName: Node name passed is FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\oracle]        - CheckIfNodeNameIsClusterName: Server name converted is FS1
[2800] 07/10/13 11:24:28 [fsys\oracle]        - CheckIfNodeNameIsClusterName: The node name passed for check is FS1
[2800] 07/10/13 11:24:28 [fsys\oracle]        - CheckIfNodeNameIsClusterName:- The nodename passed is physical nodename.
[2800] 07/10/13 11:24:28 [fsys\oracle]        - The node ( FS1 ) is physical node name.
[2800] 07/10/13 11:24:28 [fsys\oracle]        - No Oracle SID's were discovered
[2800] 07/10/13 11:24:28 [fsys\ntfs]          - GetServerType for local machine
[2800] 07/10/13 11:24:28 [fsys\shadow]        - Device Shadow?Copy?Components Dle platform 2  major version 6  minor version 1  build 7601
[2800] 07/10/13 11:24:28 [fsys\upfs]          - No utility partitions found on any of the disks
[2800] 07/10/13 11:24:28 [fsys\protsrvs\cps]  - Informational: Cps root device creation using default Cps library mechanism when creating device 'Cont?Prot?Srv' in CPS::DetermineRootCpsComponent:692
[2800] 07/10/13 11:24:28 [fsys\protsrvs\cps]  - Informational: Cps library not available.  Not creating Cps root device 'Cont?Prot?Srv' in CPS::DetermineRootCpsComponent:696
[2800] 07/10/13 11:24:28 [fsys\db2]           - Function called: DB2_SurrogateCalling
[2800] 07/10/13 11:24:28 [fsys\db2]           - Error in reading Registry for adding Instance child DLEs
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:DeviceName "\\FS1.kkworx.local\System?State" in SystemState::CreateDLEs:373
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:Full Device Path "System?State" in SystemState::CreateDLEs:378
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:ADRO Agent is authorized for System?State.
[2800] 07/10/13 11:24:28 [fsys\systemstate]   -   AD:Found 0 instances of Active Directory Applcation Mode in SystemState::GetADAMInstanceCount:1415
[2800] 07/10/13 11:24:28 [fsys\ntfs\img_pdi]  + img_pdi_initfs.cpp (815):
[2800] 07/10/13 11:24:28 [fsys\ntfs\img_pdi]  | Image PDI trace level value not found trace level will be: 1.
[2800] 07/10/13 11:24:28 [fsys\ntfs\img_pdi]  + img_pdi_initfs.cpp (858):
[2800] 07/10/13 11:24:28 [fsys\ntfs\img_pdi]  | Tracing level changes will be monitored
[2800] 07/10/13 11:24:28 [fsys\sql2]          - SQL2_CreateTempDLE - server name converted to \\FS1.
[2800] 07/10/13 11:24:28 [fsys\sql2]          - SQL2_SurrogateCalling - the default SQL Service is not running on FS1.
[2800] 07/10/13 11:24:28 [fsys\ese]           - [FSYS:ESE07]   ESE_SurrogateCalling ... Error: got invalid version (0)
[2800] 07/10/13 11:24:28 [fsys\ese]           - [FSYS:ESE07]   ESE_SurrogateCalling ... Error: got invalid version (0)
[2800] 07/10/13 11:24:28 [fsys\ese]           - [FSYS:ESE07]   ESE_SurrogateCalling ... Error: got invalid version (0)
[2800] 07/10/13 11:24:28 [beutil]             - Input Error (       0) for Type: (43)
[2800] 07/10/13 11:24:28 [fsys\shared]        - Attach to \\FS1.kkworx.local
[2800] 07/10/13 11:24:28 [fsys\shared]        - Detach from \\FS1.kkworx.local
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\C$' (type: 5 subtype: 2)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\Common' (type: 5 subtype: 1)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\D$' (type: 5 subtype: 2)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\Key Construction' (type: 5 subtype: 1)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\Kiefer Insurance' (type: 5 subtype: 1)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\Restricted' (type: 5 subtype: 1)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\User My Docs' (type: 5 subtype: 1)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\C:' (type: 5 subtype: 0)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\D:' (type: 5 subtype: 0)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\Shadow?Copy?Components' (type: 18 subtype: 0)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - $$$$ skipping '\\FS1.kkworx.local\System?State' (type: 30 subtype: 0)
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - prep_for_full: BSD list is empty nothing to backup
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - sslClose() : Closing SSL for: 00000000DF7EC2AF
[2800] 07/10/13 11:24:28                      - SSL Shutdown clean
[2800] 07/10/13 11:24:28 [BESocket]           - @@@@@@@MyCloseSocket called with sockfd = 1232(0x4d0) retval = 0
[2800] 07/10/13 11:24:28 [ndmp\tpfmt]         - FreeFormatEnv( cur_fmt=0 )
[2800] 07/10/13 11:24:28 [ndmp\tpfmt]         - FreeFormatEnv( cur_fmt=0 )
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      - sslClose() : Closing SSL for: 00000000DF7EC2AF
[2800] 07/10/13 11:24:28 [ndmp\ndmpsrvr]      -  sslClose() : certinfo = 0  ; sslConn = 0
<<<<<<<<<<<< LOGGING OFF >>>>>>>>>>>>>>>>>>>