1. Forum Rules (PLEASE CLICK HERE TO READ BEFORE POSTING) Click the link to access ADSM.ORG Acceptable Use Policy and forum rules which should be observed when using this website. Violators may be banned from this website. This message will disappear after you have made at least 12 posts. Thank you for your cooperation.

TDP backup fails after backing up first vmdk

Discussion in 'TDP/Application Layer Backup' started by michalwu, Nov 26, 2012.

Thread Status:
Not open for further replies.
  1. michalwu

    michalwu New Member

    Joined:
    Nov 24, 2012
    Messages:
    9
    Likes Received:
    2
    Hi

    After some issues described here I have running environment.
    OS: RHEL 6.3
    kernel: 2.6.32-279.14.1.el6.x86_64
    TSM: 6.3.3.0
    TSMforVE: 6.4
    TSM client: 6.4
    Virtual Center: 5.1

    And now, I am trying to back up first machine.
    It is called myVM3 and its disks are Thin.
    Backup runs fine from both plugin GUI and CLI, but it fails unexpectedly after backing up first disk.

    dsmc show vm shows:
    Code:
    (S) 25.vmName:         myVM3
           guestFullName:  Red Hat Enterprise Linux 5 (64-bit)
           guestState:     notRunning	connectionState:  connected
           changeTracking: On	vmHWversion:      vmx-07
           domainKeyword:  all-vm
           domainSelected: Yes
           resourcePool:   Resources
           VMDK[1]Label:   Hard disk 1
           VMDK[1]Name:    [R10_LUN1] myVM3/myVM3.vmdk
           VMDK[1]Status:  Included
           VMDK[2]Label:   Hard disk 2
           VMDK[2]Name:    [R10_LUN1] myVM3/myVM3_1.vmdk
           VMDK[2]Status:  Included
           VMDK[3]Label:   Hard disk 3
           VMDK[3]Name:    [R10_LUN1] myVM3/myVM3_2.vmdk
           VMDK[3]Status:  Included
           VMDK[4]Label:   Hard disk 4
           VMDK[4]Name:    [R10_LUN1] myVM3/myVM3_3.vmdk
           VMDK[4]Status:  Included
    
    REAL size of disks:
    [R10_LUN1] myVM3/myVM3.vmdk --13GB
    [R10_LUN1] myVM3/myVM3_1.vmdk --5GB
    [R10_LUN1] myVM3/myVM3_2.vmdk --0.4GB
    [R10_LUN1] myVM3/myVM3_3.vmdk --7GB



    I am issuing:
    dsmc backup vm myVM3 -vmbackuptype=fullvm -mode=full -asnode=VC1_DC1
    and I get:
    Code:
    Backup VM command started.  Total number of virtual machines to process: 1
    Accessing as node: VC1_DC1
    Starting Full VM backup of VMware Virtual Machine 'myVM3'
    	mode:                        'Periodic Full - Full'
    	target node name:            'VC1_DC1'
    	data mover node name:        'VC1_DC1_DM1'
    	application protection type: 'VMware'
    	application(s) protected:    'n/a'
    
    Creating snapshot for virtual machine 'myVM3'
    Backing up Full VM configuration information for 'myVM3'
             19,445 VM Configuration [Sent]      
    Processing snapshot
    	disk:         [DS4300_R10_LUN1] myVM3/myVM3.vmdk (Hard Disk 1)
    	Capacity:     16,106,127,360
    	Data to Send: 13,618,905,088
    	[B]Transport:     (nbd)[sending][/B]
    [B]Volume --> 16,106,127,360 [DS4300_R10_LUN1] myVM3/myVM3.vmdk (Hard Disk 1) [Sent]      [/B]
    
    ANS4174E Full VM backup of VMware Virtual Machine 'myVM3' failed with RC=115 mode=Periodic Full - Full, target node name='VC1_DC1', data mover node name='VC1_DC1_DM1'
    
    ANS1228E Sending of object 'myVM3' failed
    ANS4015E Error processing 'myVM3': unexpected TSM error (115) encountered
    Statistics for Virtual Machine 'myVM3'.
    
    Total number of objects inspected:            1
    Total number of objects backed up:            0
    Total number of objects updated:              0
    Total number of objects rebound:              0
    Total number of objects deleted:              0
    Total number of objects expired:              0
    Total number of objects failed:               1
    Total number of bytes inspected:          15.00 GB
    Total number of bytes transferred:            0  B
    Data transfer time:                      277.10 sec
    Network data transfer rate:           47,995.56 KB/sec
    Aggregate data transfer rate:         45,381.97 KB/sec
    Objects compressed by:                        0%
    Total data reduction ratio:               15.45%
    Elapsed processing time:               00:04:53
    Removing snapshot for virtual machine 'myVM3'
    Deleted directory /tmp/vmware-root/423b0201-b7c7-49d3-c579-584fe896fea1-vm-79/nbd
    

    Where should I look for a cause?

    Thanks!
    mike
     
  2.  
  3. zsoltesz

    zsoltesz New Member

    Joined:
    Feb 26, 2008
    Messages:
    107
    Likes Received:
    4
    Location:
    Hungary
    You maybe will find other information about the error in the dsmerror.log file and TSM server activity log.
     
  4. michalwu

    michalwu New Member

    Joined:
    Nov 24, 2012
    Messages:
    9
    Likes Received:
    2
    Sorry it took so long to respond. I changed my OS to RHEL5. I saw IBM note saying that RHEL6 and TSM4VE 6.4 do not work well. So I thought moving to RHEL5 will help.
    And I have same problem again!


    dsmerror_dm.log shows:
    Code:
    11/29/2012 13:38:25 ANS9370W Use Preferences Editor or dsmc SET PASSWORD -type=VM 'VirtualCenter hostname' 'userid' 'password' to save encrypted password.
    [B]11/29/2012 13:38:27 Unexpected error. Please check the TSM Error Log for any additional information[/B]
    But I believe I configured all required passwords. Besides I can start backup and all validation commands I can think of are OK.


    dsmwebcl.log
    Code:
    11/29/2012 13:32:14 (dsmagent) IBM Tivoli Storage Manager 
    11/29/2012 13:32:14 (dsmagent) Remote Client Agent - Built Oct 19 2012 09:29:53 
    11/29/2012 13:32:14 (dsmagent) Version 6, Release 4, Level 0.0   
    11/29/2012 13:32:16 (dsmagent) ANS3002I Session started for user VC1_VCLI1 (TCP/IP 10.48.105.207).
    11/29/2012 13:32:17 (dsmagent) Full BACKUP VM of virtual machines 'USE_DOMAIN'.
    11/29/2012 13:32:17 (dsmagent) Backup VM command started.  Total number of virtual machines to process: 1
    11/29/2012 13:32:17 (dsmagent) Backup of Virtual Machine 'VM3' started
    11/29/2012 13:32:22 (dsmagent) Creating snapshot for virtual machine 'VM3'
    11/29/2012 13:38:28 (dsmagent) Removing snapshot for virtual machine 'VM3'
    11/29/2012 13:38:29 (dsmagent) Backup VM command complete
    11/29/2012 13:38:29 (dsmagent) Total number of virtual machines backed up successfully: 0
    11/29/2012 13:38:29 (dsmagent) Total number of virtual machines failed: 1
    11/29/2012 13:38:29 (dsmagent)   virtual machine VM3
    11/29/2012 13:38:29 (dsmagent) Total number of virtual machines processed: 1

    tsmcli.trace shows that CHILD bytessent is not growing any more. While backup is running, I can see this counter growing and growing, and then when first disk is backed up, there is "CHILD bytessent:0" few times and then ANS1236E (RC115) An unexpected error occurred.
    Code:
    11/29/2012 13:38:24.339 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1674): totalbytes:13587467253
    11/29/2012 13:38:24.339 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1683): statMsgArray[0].statMsg = Transferring...
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1613): Entering ProxyCallBack()
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1617): dsmPCBInP->tsmHandle = 1
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1619): dsmPCBInP->proxyHandle = 1
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1621): dsmPCBInP->objExamined = 1
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1623): dsmPCBInP->objComplete = 0
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1625): dsmPCBInP->objFailed = 0
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1627): dsmPCBInP->objDel = 0
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1636): dsmPCBInP->elapTime = 12/4/1993 0:6:8
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1639): dsmPCBInP->transderRate = 0.0
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1641): dsmPCBInP->aggrTransferRate = 0.0
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1643): dsmPCBInP->aggrRateProgress = 0
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1645): dsmPCBInP->networkRateProgress = 0
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1647): dsmPCBInP->statusMsg = 
    [B]11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1654): #CHILD bytessent:31457280[/B]
    
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1674): totalbytes:13618924533
    11/29/2012 13:38:25.340 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1683): statMsgArray[0].statMsg = Transferring...
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1613): Entering ProxyCallBack()
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1617): dsmPCBInP->tsmHandle = 1
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1619): dsmPCBInP->proxyHandle = 1
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1621): dsmPCBInP->objExamined = 1
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1623): dsmPCBInP->objComplete = 0
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1625): dsmPCBInP->objFailed = 0
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1627): dsmPCBInP->objDel = 0
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1636): dsmPCBInP->elapTime = 12/4/1993 0:6:9
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1639): dsmPCBInP->transderRate = 0.0
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1641): dsmPCBInP->aggrTransferRate = 0.0
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1643): dsmPCBInP->aggrRateProgress = 0
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1645): dsmPCBInP->networkRateProgress = 0
    11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1647): dsmPCBInP->statusMsg = 
    [B]11/29/2012 13:38:26.343 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1654): #CHILD bytessent:0[/B]
    
    11/29/2012 13:38:29.630 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1674): totalbytes:13618924533
    11/29/2012 13:38:29.642 : tsmproxy.cpp        (1744): tsmProxySend EXIT: rc = >115<.
    [B]11/29/2012 13:38:29.642 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(681): dsmProxySend() returned rc = 115, exiting....[/B]
    11/29/2012 13:38:29.642 : dsmmsg.cpp          ( 763): dsmRCMsg ENTRY: tsmHandle=1 rc: 115 msg : 0x7fff8ac9dea0[B]
    11/29/2012 13:38:29.642 : dsmmsg.cpp          (1167): tsmHandle=1 rc: 115 msg : >ANS1236E (RC115)  An unexpected error occurred.<[/B]
    11/29/2012 13:38:29.642 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(691): tsmclibackup() Exit. rc = 115
    11/29/2012 13:38:29.642 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(701): calling dsmProxyTerminate()
    11/29/2012 13:38:29.642 : tsmproxy.cpp        (1253): tsmProxyTerminate ENTRY: tsmHandle=1 proxyHandle =1 
    11/29/2012 13:38:29.642 : tsmproxy.cpp        (1278): tsmProxyTerminate EXIT: rc = >0<.
    11/29/2012 13:38:29.642 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(710): calling dsmTerminate()
    11/29/2012 13:38:29.642 : dsmterm.cpp         ( 242): dsmTerminate ENTRY: dsmHandle is 1
    11/29/2012 13:38:29.642 : dsmterm.cpp         ( 276): dsmTerminate: call ApiCleanUp . rc = 0
    11/29/2012 13:38:29.642 : dsminit.cpp         (3252): ApiCleanUp : handle is = 1 
    11/29/2012 13:38:34.043 : apianchr.cpp        ( 726): anDeleteAnchor: Free the space for myAnchor handle is 1
    11/29/2012 13:38:34.043 : dsmterm.cpp         ( 284): dsmTerminate EXIT: rc = >0<.
    11/29/2012 13:38:34.043 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1024): TRACE END
    11/29/2012 13:38:34.043 : dsmsetup.cpp        ( 988): dsmCleanUp ENTRY: mtFlag = 1. 
    11/29/2012 13:38:34.043 : dsmsetup.cpp        ( 999): dsmCleanUp entered. 
    11/29/2012 13:38:34.043 : dsminit.cpp         (3283): ApiCleanUp : Final exit 
    Any ideas, guys?
    m.
     
  5. michalwu

    michalwu New Member

    Joined:
    Nov 24, 2012
    Messages:
    9
    Likes Received:
    2
    I made another backup. VM with one disk only. And this one went fine!
    So it seems that there is a problem with VMs having more than one disk.

    tsmcli.trace
    Code:
    11/29/2012 13:54:22.583 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1674): totalbytes:24556
    11/29/2012 13:54:22.591 : tsmproxy.cpp        (1744): tsmProxySend EXIT: rc = >0<.
    11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(748): objectsExamined:1
    11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(750): objectsComplete:1
    11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(752): objectsFailed:0
    11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(755): totalBytes:24556
    11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(800): objectsexamined:1
    11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(804): objectscomplete:1
    11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(808): objectsfailed:0
    [B]11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(813): totalBytes:24556[/B]
    
    
    11/29/2012 13:54:22.591 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(825): calling dsmProxyTerminate()
    11/29/2012 13:54:22.592 : tsmproxy.cpp        (1253): tsmProxyTerminate ENTRY: tsmHandle=1 proxyHandle =1 
    11/29/2012 13:54:22.592 : tsmproxy.cpp        (1278): tsmProxyTerminate EXIT: rc = >0<.
    11/29/2012 13:54:22.592 : dsmtrace.cpp        ( 146): TSMCLI - backup.cpp(834): calling dsmTerminate()
    11/29/2012 13:54:22.592 : dsmterm.cpp         ( 242): dsmTerminate ENTRY: dsmHandle is 1
    11/29/2012 13:54:22.592 : dsmterm.cpp         ( 276): dsmTerminate: call ApiCleanUp . rc = 0
    11/29/2012 13:54:22.592 : dsminit.cpp         (3252): ApiCleanUp : handle is = 1 
    11/29/2012 13:54:27.493 : apianchr.cpp        ( 726): anDeleteAnchor: Free the space for myAnchor handle is 1
    11/29/2012 13:54:27.493 : dsmterm.cpp         ( 284): dsmTerminate EXIT: rc = >0<.
    11/29/2012 13:54:27.493 : dsmtrace.cpp        ( 146): TSMCLI - utility.cpp(1024): TRACE END
    11/29/2012 13:54:27.493 : dsmsetup.cpp        ( 988): dsmCleanUp ENTRY: mtFlag = 1. 
    11/29/2012 13:54:27.493 : dsmsetup.cpp        ( 999): dsmCleanUp entered. 
    11/29/2012 13:54:27.493 : dsminit.cpp         (3283): ApiCleanUp : Final exit 

    dsmerror_dm.log -as you can see it is still complaining about the passwd not set, but backup succeded.
    Code:
    11/29/2012 13:54:07 ANS9370W Use Preferences Editor or dsmc SET PASSWORD -type=VM 'VirtualCenter hostname' 'userid' 'password' to save encrypted password.
    11/29/2012 13:54:07 ANS9370W Use Preferences Editor or dsmc SET PASSWORD -type=VM 'VirtualCenter hostname' 'userid' 'password' to save encrypted password.
    11/29/2012 13:54:13 ANS9370W Use Preferences Editor or dsmc SET PASSWORD -type=VM 'VirtualCenter hostname' 'userid' 'password' to save encrypted password.
    11/29/2012 13:54:13 ANS9370W Use Preferences Editor or dsmc SET PASSWORD -type=VM 'VirtualCenter hostname' 'userid' 'password' to save encrypted password.
    11/29/2012 13:59:12 ANS9370W Use Preferences Editor or dsmc SET PASSWORD -type=VM 'VirtualCenter hostname' 'userid' 'password' to save encrypted password.
    11/29/2012 13:59:12 ANS9370W Use Preferences Editor or dsmc SET PASSWORD -type=VM 'VirtualCenter hostname' 'userid' 'password' to save encrypted password.
    
     
  6. michalwu

    michalwu New Member

    Joined:
    Nov 24, 2012
    Messages:
    9
    Likes Received:
    2
Thread Status:
Not open for further replies.

Share This Page