Avamar 7.0在做VMware Image level restore的时候fail并无报错信息出现

楼主，

你双击上面截图里面的failed也没有任何restore失败的日志吗？没有任何日志信息的话，检查看看 Avamar Proxy当前是否工作正常？对其它client的备份和恢复正常吗？ 用 nslookup 加 IP地址，看看解析什么的是否正常？

restore到一个新的，找到restore的log，如下：

--------------------------------------------------------------------------------------------------------

-----  START avvcbimage log 2014-06-13 11:12:02 UTC  [7.0.101-61 Linux-x86_64]

--------------------------------------------------------------------------------------------------------

2014-06-13 11:12:02 avvcbimage Info <5008>: Logging to /usr/local/avamarclient/var-proxy-6/MOD-1402658785999-48d2bfa96bc03382dd91b861cedb09dc5cb5e341-3016-vmimagew.log

2014-06-13 11:12:02 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var-proxy-6/avvcbimage.cmd

2014-06-13 11:12:02 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var/avvcbimageAll.cmd

2014-06-13 11:12:02 avvcbimage Info <6673>: CTL listening on port 33459

2014-06-13 11:12:02 avvcbimage Info <10684>: Setting ctl message version to 3 (from 1)

2014-06-13 11:12:02 avvcbimage Info <16136>: Setting ctl max message size to 268435456

2014-06-13 11:12:02 avvcbimage Warning <6788>: Found unknown section 'browse-from-catalog' in workorder, ignoring

2014-06-13 11:12:02 avvcbimage Info <17810>: VAMI Statistics Push Provider ENABLED.

2014-06-13 11:12:02 avvcbimage Info <18664>: Login(https://10.XX. XX.XX:443/sdk) Datacenter: 'VC-DMZ'

2014-06-13 11:12:02 avvcbimage Info <18665>:      - connected to 'VirtualCenter' - version: 'VMware vCenter Server 5.0.0 build-455964'

2014-06-13 11:12:02 avvcbimage Info <14692>: Login test is OK.

2014-06-13 11:12:43 avvcbimage Info <11979>: proxy VM DNS name is: 127.0.0.2,10.XX.XX.XX

2014-06-13 11:12:43 avvcbimage Info <18672>: proxy VM Instance name is: dmz_avamar_proxy_2-proxy-6

2014-06-13 11:12:43 avvcbimage Info <17793>: proxy VM Moref is:

2014-06-13 11:12:43 avvcbimage Info <16010>: vCenter 'VC-DMZ' is 10.XX.XX.XX

2014-06-13 11:12:43 avvcbimage Info <11981>: VM's host is 10.XX.XX.XX

2014-06-13 11:12:43 avvcbimage Info <11982>: VM's primary storage location is [VM-04(180)] xtjk0612/xtjk0612.vmx

2014-06-13 11:12:43 avvcbimage Info <11983>: VM's vCenter ID is null

2014-06-13 11:12:43 avvcbimage Info <18683>: pushJobCreation proxyName=dmz_avamar_proxy_2-proxy-6 vmName=xtjk0612

2014-06-13 11:12:43 avvcbimage Info <11984>: VM's backup account on 10.XX.XX.XX is /10.XX.XX.XX/spdb-xtjk-DMZ_UCNibhNHj4BzbNADvOrdSw

2014-06-13 11:12:43 avvcbimage Info <14682>: A full level0 restore will be done to this new VM.

2014-06-13 11:12:43 avvcbimage Info <17823>: Body- abortrecommended(f)

2014-06-13 11:12:43 avvcbimage Warning <6788>: Found unknown section 'browse-from-catalog' in workorder, ignoring

2014-06-13 11:12:43 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var-proxy-6/avvcbimage.cmd

2014-06-13 11:12:43 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var/avvcbimageAll.cmd

2014-06-13 11:12:43 avvcbimage Info <7084>: target[0]=[VM-02] test-xtjk-DMZ/test-xtjk-DMZ.vmdk

2014-06-13 11:12:43 avvcbimage Info <17553>: ImageJobStats vmname=xtjk0612, proxyname=dmz_avamar_proxy_2-proxy-6, cpuPercent=0.123364, memoryMB=86.000000, mbytesPerMinVMDK=0.000000, mbytesPerMinGSAN=0.000000

2014-06-13 11:12:43 avvcbimage Info <17554>:      currentDisk=0, totalDisks=0, diskProgressPercent=0.000000, totalProgressPercent=0.000000, diskName=, jobType = 1, jobState = 0, jobStatus = 0,  exitCode = 0

2014-06-13 11:12:43 avvcbimage Warning <6788>: Found unknown section 'browse-from-catalog' in workorder, ignoring

2014-06-13 11:12:43 avvcbimage Info <6686>: Process 7423 (/usr/local/avamarclient/bin/avtar) for workorder MOD-1402658785999#99 started

2014-06-13 11:12:43 avvcbimage Info <12181>: Avtar metadata restore session initiated

2014-06-13 11:12:43 avvcbimage Info <10684>: Setting ctl message version to 3 (from 1)

2014-06-13 11:12:43 avvcbimage Info <16136>: Setting ctl max message size to 268435456

2014-06-13 11:17:43 avvcbimage Error <0000>: [IMG0011] Timeout on wait for spawned restore metadata avtar process to complete

2014-06-13 11:31:40 avvcbimage Info <6688>: Process 7423 (/usr/local/avamarclient/bin/avtar) finished (code 0: success)

2014-06-13 11:31:40 avvcbimage FATAL <17824>: GetDiskAttributed Failed

2014-06-13 11:31:40 avvcbimage Info <15994>: Logging into datacenter path of 'folder?dcPath=VC%252DDMZ'

2014-06-13 11:31:40 avvcbimage Info <14620>: Logging into datacenter '10.XX.XX.XX' with user 'avabackup'

2014-06-13 11:31:41 avvcbimage Info <17770>: DataStore Storage Info:

  DataStore:'VM-04(180)': Pre Free Space(KB)=141976576,

                          Post Free Space(KB) range=100033536 to 100033536

    Disk '2000': Disk Size(KB)=41943040, restoreThisDisk=1, thin=0

2014-06-13 11:31:41 avvcbimage Info <17825>: A VM create has been requested.

2014-06-13 11:31:41 avvcbimage Info <18664>: Login(https://10.XX.XX.XX:443/sdk) Datacenter: 'VC-DMZ'

2014-06-13 11:31:41 avvcbimage Info <18665>:      - connected to 'VirtualCenter' - version: 'VMware vCenter Server 5.0.0 build-455964'

2014-06-13 11:31:41 avvcbimage Info <14692>: Login test is OK.

2014-06-13 11:31:41 avvcbimage Error <17771>: Invalid request to create a VM.

2014-06-13 11:31:41 avvcbimage Warning <16004>: Soap fault detected, Find VM - NOT ok, Msg:'?謕?'

2014-06-13 11:31:41 avvcbimage Error <0000>: [IMG2012] VM creation failed during restore.

2014-06-13 11:31:41 avvcbimage Info <9772>: Starting graceful (staged) termination, Create VM failed during restore. (wrap-up stage)

2014-06-13 11:31:41 avvcbimage Info <16022>: Cancel detected(plugin error 00), isExitOK(0).

2014-06-13 11:31:41 avvcbimage Info <16022>: Cancel detected(plugin error 00), isExitOK(0).

2014-06-13 11:31:41 avvcbimage Info <16038>: Final summary, cancelled/aborted 0, snapview 1, exitcode 200: plugin error 00

没有任何日志的话，应该是刚开始要Restore的时候就失败了，Restore应该根本没有Run起来。这样看来，应该是Proxy和客户端之间的问题。问一下，你这个Client是原始备份的client，还是你准备Restore到一个新的VM？

楼主，

1. 检查一下权限是否正确。参考这部分内容：

Create a Role with correct and required permissions. Or assign the Admin Role to the account.

2. 尝试往 VMware Image dataset 里面加入下面这个flag，然后再试试看看。

[avvcbimage]subprocesstimeoutsecs=600

hi，leo。

权限检查了没问题，是管理员权限。

添加超时参数这个也做了，报错还是一样，如上面的log信息。

那挺奇怪的。

你再检查一下在执行Restore的时候有没有使用一些flag？如 --verbose 这种。 然后再看看proxy 里面有没有创建过 avtar.cmd文件并使用了一些flag？

我这边再check一下还有没有别的可能性。

加了debug后的输出如下：

--------------------------------------------------------------------------------------------------------

-----  START avvcbimage log 2014-06-19 09:09:20 UTC  [7.0.101-61 Linux-x86_64]

--------------------------------------------------------------------------------------------------------

2014-06-19 09:09:20 avvcbimage Info <5008>: Logging to /usr/local/avamarclient/var-proxy-6/MOD-1403169837372-48d2bfa96bc03382dd91b861cedb09dc5cb5e341-3016-vmimagew.log

2014-06-19 09:09:20 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var-proxy-6/avvcbimage.cmd

2014-06-19 09:09:20 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var/avvcbimageAll.cmd

2014-06-19 09:09:20 avvcbimage Info <6673>: CTL listening on port 36939

2014-06-19 09:09:20 avvcbimage Info <10684>: Setting ctl message version to 3 (from 1)

2014-06-19 09:09:20 avvcbimage Info <16136>: Setting ctl max message size to 268435456

2014-06-19 09:09:20 avvcbimage Warning <6788>: Found unknown section 'browse-from-catalog' in workorder, ignoring

2014/06/19-09:09:20.64740 [vcbimage_ctl_sup]  workorder::parsexmlflags null message for 'workorder directives'

2014-06-19 09:09:20 avvcbimage Info <17810>: VAMI Statistics Push Provider ENABLED.

2014/06/19-09:09:20.72126 [vcbimage_ctl_sup]  VSphereAPI::login(https://10.1.1.1:443/sdk) RetrieveServiceContent - OK

2014/06/19-09:09:20.72131 [vcbimage_ctl_sup]  VSphereAPI::loginWithCookie() fullName:'VMware vCenter Server 5.0.0 build-455964', name:'VMware vCenter Server' soapAction:'urn:vim25/4.0'

2014/06/19-09:09:20.72132 [vcbimage_ctl_sup]  VSphereAPI::loginWithCookie() build:'455964', version:'5.0.0', apiType:'VirtualCenter', productLineId:'vpx'

2014-06-19 09:09:20 avvcbimage Info <18664>: Login(https://10.1.1.1:443/sdk) Datacenter: 'VC-DMZ'

2014-06-19 09:09:20 avvcbimage Info <18665>:      - connected to 'VirtualCenter' - version: 'VMware vCenter Server 5.0.0 build-455964'

2014/06/19-09:09:20.72138 [vcbimage_ctl_sup]  VSphereAPI::loginWithCookie(https://10.1.1.1:443/sdk) sessionID changed during login.

2014/06/19-09:09:20.77652 [vcbimage_ctl_sup]  VSphereAPI::getDatacenterMoref() Number of Objects=1

2014/06/19-09:09:20.77656 [vcbimage_ctl_sup]  VSphereAPI::getDatacenterMoref() Object type:Datacenter, (1 properties)

2014/06/19-09:09:20.77659 [vcbimage_ctl_sup]  VSphereAPI::getDatacenterMoref() found datacenter:'VC-DMZ', moref:'datacenter-81'

2014-06-19 09:09:20 avvcbimage Info <14692>: Login test is OK.

2014/06/19-09:09:20.80372 [vcbimage_ctl_sup]  AutoLogin by 'VcbImageAssistThread' - login=true.

2014/06/19-09:09:20.80374 [vcbimage_ctl_sup]  udpsockimpl::open UDP socket requested

2014/06/19-09:09:20.80376 [vcbimage_ctl_sup]  Socket buffer size (recv) requested 1000, was set to 1144

2014/06/19-09:09:20.80377 [vcbimage_ctl_sup]  Socket buffer size (send) requested 1000, was set to 1024

2014/06/19-09:09:20.80379 [vcbimage_ctl_sup]  getallhostnames: len=120, entries=3

2014/06/19-09:09:20.80380 [vcbimage_ctl_sup]  lo 127.0.0.1

2014/06/19-09:09:20.80381 [vcbimage_ctl_sup]  lo 127.0.0.2

2014/06/19-09:09:30.85479 [vcbimage_ctl_sup]  addr 127.0.0.2

2014/06/19-09:09:30.85483 [vcbimage_ctl_sup]  eth0 10.1.1.2

2014/06/19-09:09:40.90720 [vcbimage_ctl_sup]  addr 10.1.1.2

2014/06/19-09:09:40.90724 [vcbimage_ctl_sup]  udpsockhandle::getallhostnames: results: 127.0.0.2,10.1.1.2

2014/06/19-09:09:40.90726 [vcbimage_ctl_sup]  getallhostnames: 127.0.0.2,10.1.1.2

2014/06/19-09:09:40.94218 [vcbimage_ctl_sup]  VSphereAPI::getProxyVmMoref() Number of Objects=27

2014/06/19-09:09:40.96272 [vcbimage_ctl_sup]  VSphereAPI::getProxyVmMoref() Number of Objects=27

2014/06/19-09:09:41.04441 [vcbimage_ctl_sup]  VSphereAPI::getDatastoreMoref() Number of Objects=10

2014/06/19-09:09:41.04445 [vcbimage_ctl_sup]  VSphereAPI::getDatastoreMoref() Object type:Datastore, (22 properties)

2014/06/19-09:09:41.04446 [vcbimage_ctl_sup]  VSphereAPI::getDatastoreMoref() Object type:Datastore, (22 properties)

2014/06/19-09:09:41.04447 [vcbimage_ctl_sup]  VSphereAPI::getDatastoreMoref() Object type:Datastore, (22 properties)

2014/06/19-09:09:41.04459 [vcbimage_ctl_sup]  VSphereAPI::getDatastoreMoref() found datastore:'VM-02', moref:'datastore-164'

2014/06/19-09:09:41.10134 [vcbimage_ctl_sup]  udpsockimpl::open UDP socket requested

2014/06/19-09:09:41.10140 [vcbimage_ctl_sup]  Socket buffer size (recv) requested 1000, was set to 1144

2014/06/19-09:09:41.10141 [vcbimage_ctl_sup]  Socket buffer size (send) requested 1000, was set to 1024

2014/06/19-09:09:41.10143 [vcbimage_ctl_sup]  getallhostnames: len=120, entries=3

2014/06/19-09:09:41.10144 [vcbimage_ctl_sup]  lo 127.0.0.1

2014/06/19-09:09:41.10145 [vcbimage_ctl_sup]  lo 127.0.0.2

2014/06/19-09:09:51.14927 [vcbimage_ctl_sup]  addr 127.0.0.2

2014/06/19-09:09:51.14932 [vcbimage_ctl_sup]  eth0 10.1.1.2

2014/06/19-09:10:01.19980 [vcbimage_ctl_sup]  addr 10.1.1.2

2014/06/19-09:10:01.19985 [vcbimage_ctl_sup]  udpsockhandle::getallhostnames: results: 127.0.0.2,10.1.1.2

2014/06/19-09:10:01.19987 [vcbimage_ctl_sup]  getallhostnames: 127.0.0.2,10.1.1.2

2014-06-19 09:10:01 avvcbimage Info <11979>: proxy VM DNS name is: 127.0.0.2,10.1.1.2

2014-06-19 09:10:01 avvcbimage Info <18672>: proxy VM Instance name is: dmz_avamar_proxy_2-proxy-6

2014-06-19 09:10:01 avvcbimage Info <17793>: proxy VM Moref is:

2014-06-19 09:10:01 avvcbimage Info <16010>: vCenter 'VC-DMZ' is 10.1.1.1

2014-06-19 09:10:01 avvcbimage Info <11981>: VM's host is 10.1.1.3

2014-06-19 09:10:01 avvcbimage Info <11982>: VM's primary storage location is [VM-02] test77/test77.vmx

2014-06-19 09:10:01 avvcbimage Info <11983>: VM's vCenter ID is null

2014-06-19 09:10:01 avvcbimage Info <18683>: pushJobCreation proxyName=dmz_avamar_proxy_2-proxy-6 vmName=test77

2014/06/19-09:10:01.20024 [vcbimage_ctl_sup]  Linux version: 3.0.76-0.  Per-process CPU time=1

2014/06/19-09:10:01.23186 [vcbimage_ctl_sup]  createInstance() rc=0, msg=(null)

2014-06-19 09:10:01 avvcbimage Info <11984>: VM's backup account on 10.1.1.5 is /10.1.1.1/spdb-xtjk-DMZ_UCNibhNHj4BzbNADvOrdSw

2014-06-19 09:10:01 avvcbimage Info <14682>: A full level0 restore will be done to this new VM.

2014/06/19-09:10:01.23238 [vcbimage_ctl_sup]  AutoLogin by 'VcbImageAssistThread' - now logging out.

2014/06/19-09:10:01.23249 [VcbImageAssistThread]  Startup, pid=9068 tid=37 stack=0x7f1d26ed3cdf td=0x7f1d2aad6910

2014-06-19 09:10:01 avvcbimage Info <17823>: Body- abortrecommended(f)

2014-06-19 09:10:01 avvcbimage Warning <6788>: Found unknown section 'browse-from-catalog' in workorder, ignoring

2014/06/19-09:10:01.23275 [VcbImageAssistThread]  workorder::convert_list processing list

2014/06/19-09:10:01.23280 [VcbImageAssistThread]  name: [VM-02] test-xtjk-DMZ/test-xtjk-DMZ.vmdk

2014/06/19-09:10:01.23281 [VcbImageAssistThread]  workorder::convert_value null message in workorder::convert_value 'workorder exclude'

2014/06/19-09:10:01.23281 [VcbImageAssistThread]  workorder::convert_value null message in workorder::convert_value 'workorder include'

2014/06/19-09:10:01.23282 [VcbImageAssistThread]  workorder::parsexmlflags 'workorder directives'

2014/06/19-09:10:01.23309 [VcbImageAssistThread]  workorder::parsexmlflags 'workorder proxydirectives'

2014/06/19-09:10:01.23364 [VcbImageAssistThread]  workorder::parsexmlflags 'workorder catalog'

2014/06/19-09:10:01.23371 [VcbImageAssistThread]  workorder::parsexmlflags 'workorder free-form'

2014/06/19-09:10:01.23400 [VcbImageAssistThread]  workorder::parsexmlflags null message for 'workorder directives'

2014/06/19-09:10:01.23409 [VcbImageAssistThread]  Looking for flag file "/usr/local/avamarclient/var-proxy-6/avvcbimage.cmd"

2014-06-19 09:10:01 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var-proxy-6/avvcbimage.cmd

2014/06/19-09:10:01.23421 [VcbImageAssistThread]  Looking for flag file "/usr/local/avamarclient/var/avvcbimageAll.cmd"

2014-06-19 09:10:01 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var/avvcbimageAll.cmd

2014-06-19 09:10:01 avvcbimage Info <7084>: target[0]=[VM-02] test-xtjk-DMZ/test-xtjk-DMZ.vmdk

2014/06/19-09:10:01.23567 [vcbimage_ctl_sup]  ctl_manbase::process_message() done

2014/06/19-09:10:01.23994 [VcbImageAssistThread]  getInstance() rc=0, msg=(null)

2014-06-19 09:10:01 avvcbimage Info <17553>: ImageJobStats vmname=test77, proxyname=dmz_avamar_proxy_2-proxy-6, cpuPercent=0.172487, memoryMB=86.000000, mbytesPerMinVMDK=0.000000, mbytesPerMinGSAN=0.000000

2014-06-19 09:10:01 avvcbimage Info <17554>:      currentDisk=0, totalDisks=0, diskProgressPercent=0.000000, totalProgressPercent=0.000000, diskName=, jobType = 1, jobState = 0, jobStatus = 0,  exitCode = 0

2014/06/19-09:10:01.24642 [VcbImageAssistThread]  setInstance() rc=0, msg=(null)

2014-06-19 09:10:01 avvcbimage Warning <6788>: Found unknown section 'browse-from-catalog' in workorder, ignoring

2014/06/19-09:10:01.24734 [VcbImageAssistThread]  workorder::set_section(11) Section 'vmware' already existed

2014/06/19-09:10:01.24736 [VcbImageAssistThread]  workorder::set_section(10) Section 'proxyDirectives' already existed

2014/06/19-09:10:01.24740 [VcbImageAssistThread]  VcbImageAssistThread::removeFlagFromWO() - Removing 'postrestore_poweron_mode' flag from avtar workorder.

2014/06/19-09:10:01.24870 [VcbImageAssistThread]  workorder::create_workorder section type:targets

2014/06/19-09:10:01.24872 [VcbImageAssistThread]  workorder::create_workorder section type:include

2014/06/19-09:10:01.24872 [VcbImageAssistThread]  workorder::create_workorder section type:exclude

2014/06/19-09:10:01.24873 [VcbImageAssistThread]  workorder::create_workorder section type:directives

2014/06/19-09:10:01.24874 [VcbImageAssistThread]  workorder::create_workorder section type:catalog

2014/06/19-09:10:01.24874 [VcbImageAssistThread]  workorder::create_workorder section type:free-form

2014/06/19-09:10:01.24875 [VcbImageAssistThread]  workorder::create_workorder section type:cmd

2014/06/19-09:10:01.24876 [VcbImageAssistThread]  workorder::create_workorder section type:agent_directives

2014/06/19-09:10:01.24876 [VcbImageAssistThread]  workorder::create_workorder section type:targetlist

2014/06/19-09:10:01.24877 [VcbImageAssistThread]  workorder::create_workorder section type:proxyDirectives

2014/06/19-09:10:01.24878 [VcbImageAssistThread]  workorder::create_workorder section type:vmware

2014/06/19-09:10:01.24878 [VcbImageAssistThread]  workorder::create_workorder section type:excludelist

2014/06/19-09:10:01.24879 [VcbImageAssistThread]  workorder::create_workorder section type:includelist

2014/06/19-09:10:01.24879 [VcbImageAssistThread]  workorder::create_workorder section type:storage-plugin

2014/06/19-09:10:01.24916 [ctl_man-3016-MOD-1403169837372]  Startup, pid=9076 tid=38 stack=0x7f1d266d2cdf td=0x7f1d2ab0cb90

2014/06/19-09:10:01.24926 [ctl_spawn]  Startup, pid=9077 tid=39 stack=0x7f1d25ed1cdf td=0x7f1d2ab26b88

2014/06/19-09:10:01.24932 [ctl_spawn]  avspawn::spawn command_line_args:avtar --logfile="MOD-1403169837372#99-48d2bfa96bc03382dd91b861cedb09dc5cb5e341-3016-vmimagew_avtarmetadata.log" --sysdir="/usr/local/avamarclient/etc" --bindir="/usr/local/avamarclient/bin" --vardir="/usr/local/avamarclient/var-proxy-6" --ctlcallport="36939" --ctlinterface="3016-MOD-1403169837372" --debug priority background

2014/06/19-09:10:01.24933 [ctl_spawn]  avspawn::spawn executable_path '/usr/local/avamarclient/bin/avtar'

2014/06/19-09:10:01.24934 [ctl_spawn]  avspawn::spawn execargs[0] '/usr/local/avamarclient/bin/avtar' (arg0)

2014/06/19-09:10:01.24935 [ctl_spawn]  avspawn::spawn execargs[1] '--logfile="MOD-1403169837372#99-48d2bfa96bc03382dd91b861cedb09dc5cb5e341-3016-vmimagew_avtarmetadata.log"' (arg1)

2014/06/19-09:10:01.24936 [ctl_spawn]  avspawn::spawn execargs[2] '--sysdir="/usr/local/avamarclient/etc"' (arg2)

2014/06/19-09:10:01.24936 [ctl_spawn]  avspawn::spawn execargs[3] '--bindir="/usr/local/avamarclient/bin"' (arg3)

2014/06/19-09:10:01.24937 [ctl_spawn]  avspawn::spawn execargs[4] '--vardir="/usr/local/avamarclient/var-proxy-6"' (arg4)

2014/06/19-09:10:01.24938 [ctl_spawn]  avspawn::spawn execargs[5] '--ctlcallport="36939"' (arg5)

2014/06/19-09:10:01.24939 [ctl_spawn]  avspawn::spawn execargs[6] '--ctlinterface="3016-MOD-1403169837372"' (arg6)

2014/06/19-09:10:01.24941 [ctl_spawn]  avspawn::spawn execargs[7] '--debug' (arg7)

2014/06/19-09:10:01.24941 [ctl_spawn]  avspawn::spawn new command line 'avtar --logfile="MOD-1403169837372#99-48d2bfa96bc03382dd91b861cedb09dc5cb5e341-3016-vmimagew_avtarmetadata.log" --sysdir="/usr/local/avamarclient/etc" --bindir="/usr/local/avamarclient/bin" --vardir="/usr/local/avamarclient/var-proxy-6" --ctlcallport="36939" --ctlinterface="3016-MOD-1403169837372" --debug'

2014-06-19 09:10:01 avvcbimage Info <6686>: Process 9078 (/usr/local/avamarclient/bin/avtar) for workorder MOD-1403169837372#99 started

2014-06-19 09:10:01 avvcbimage Info <12181>: Avtar metadata restore session initiated

2014/06/19-09:10:01.27833 [ctl_listen]  ctl_connection::lowdata:

recv:

2014-06-19 09:10:01 avvcbimage Info <10684>: Setting ctl message version to 3 (from 1)

2014/06/19-09:10:01.27853 [ctl_listen]  ctl_connection::lowsend:

send:

2014/06/19-09:10:01.27869 [ctl_connection_send]  Startup, pid=9082 tid=40 stack=0x7f1d256d0cdf td=0x7f1d2ab273e0

2014-06-19 09:10:01 avvcbimage Info <16136>: Setting ctl max message size to 268435456

2014/06/19-09:10:01.27912 [ctl_connection_recv]  Startup, pid=9084 tid=41 stack=0x7f1d24ecfcdf td=0x7f1d2ab276c0

2014/06/19-09:10:01.27915 [ctl_man-3016-MOD-1403169837372]  ctl_manbase::process_message() done

2014/06/19-09:10:01.27991 [ctl_conn_send-MOD-1403169837372#99]  ctl_connection::lowsend:

send:" key="3016-MOD-1403169837372" sync="bg" cid="11f8f9d8e85bbc06634f375026463d112cc80cd2" sessionid="168648bf1214998606cf22dc645ebf57ae55d373" mid="9029/9029/32" gsansid="9140316983810109" targetFqName="/10.1.1.1/spdb-xtjk-DMZ_UCNibhNHj4BzbNADvOrdSw" wid="MOD-1403169837372#99" targetUUID="10.1.1.1/null" customaction="">

2014-06-19 09:25:01 avvcbimage Error <0000>: [IMG0011] Timeout on wait for spawned restore metadata avtar process to complete

2014/06/19-09:28:58.61798 [ctl_conn_recv-MOD-1403169837372#99]  ctl_connection::lowdata:

recv:

2014/06/19-09:28:58.61826 [ctl_man-3016-MOD-1403169837372]  ctl_manbase::process_message() done

2014/06/19-09:28:58.61885 [ctl_conn_recv-MOD-1403169837372#99]  ctl_connection::lowdata:

recv:

2014/06/19-09:28:58.61899 [ctl_conn_recv-MOD-1403169837372#99]  ctl_connection::lowdata:

recv:

2014/06/19-09:28:58.61904 [ctl_conn_recv-MOD-1403169837372#99]  Thread finished ctl_conn_recv-MOD-1403169837372#99

2014/06/19-09:28:58.61952 [ctl_man-3016-MOD-1403169837372]  ctl_man::process_status_wrapup_summary

2014/06/19-09:28:58.61956 [ctl_man-3016-MOD-1403169837372]  ctl_manbase::process_message() done

2014/06/19-09:28:58.61965 [ctl_man-3016-MOD-1403169837372]  ctl_manbase::process_message() done

2014/06/19-09:28:58.61984 [ctl_conn_send-MOD-1403169837372#99]  ctl_connection::lowsend:

send:

2014/06/19-09:28:58.61993 [ctl_conn_send-MOD-1403169837372#99]  Thread finished ctl_conn_send-MOD-1403169837372#99

2014/06/19-09:28:58.62601 [ctl_spawn]  avspawn::wait setting error_num from 0 to 0

2014-06-19 09:28:58 avvcbimage Info <6688>: Process 9078 (/usr/local/avamarclient/bin/avtar) finished (code 0: success)

2014/06/19-09:28:58.62619 [ctl_spawn]  Thread finished ctl_spawn

2014/06/19-09:28:58.62638 [ctl_man-3016-MOD-1403169837372]  ctl_manbase::process_message() done

2014/06/19-09:28:58.62641 [ctl_man-3016-MOD-1403169837372]  Thread finished ctl_man-3016-MOD-1403169837372

2014/06/19-09:28:58.62649 [vcbimage_ctl_sup]  ctl_manbase::process_message() done

2014-06-19 09:28:58 avvcbimage FATAL <17824>: GetDiskAttributed Failed

2014/06/19-09:28:58.62653 [vcbimage_ctl_sup]  ctl_manbase::process_message() done

2014-06-19 09:28:58 avvcbimage Info <15994>: Logging into datacenter path of 'folder?dcPath=VC%252DDMZ'

2014-06-19 09:28:58 avvcbimage Info <14620>: Logging into datacenter '10.1.1.1' with user 'avabackup'

2014-06-19 09:28:58 avvcbimage Info <17770>: DataStore Storage Info:

  DataStore:'VM-02': Pre Free Space(KB)=206442496,

                     Post Free Space(KB) range=164499456 to 164499456

    Disk '2000': Disk Size(KB)=41943040, restoreThisDisk=1, thin=0

2014-06-19 09:28:58 avvcbimage Info <17825>: A VM create has been requested.

2014/06/19-09:28:58.92192 [VcbImageAssistThread]  getInstance() rc=6, msg=The requested object could not be found

2014/06/19-09:28:58.94203 [VcbImageAssistThread]  VSphereAPI::login(https://10.1.1.1:443/sdk) RetrieveServiceContent - OK

2014/06/19-09:28:58.94210 [VcbImageAssistThread]  VSphereAPI::loginWithCookie() fullName:'VMware vCenter Server 5.0.0 build-455964', name:'VMware vCenter Server' soapAction:'urn:vim25/4.0'

2014/06/19-09:28:58.94211 [VcbImageAssistThread]  VSphereAPI::loginWithCookie() build:'455964', version:'5.0.0', apiType:'VirtualCenter', productLineId:'vpx'

2014-06-19 09:28:58 avvcbimage Info <18664>: Login(https://10.1.1.1:443/sdk) Datacenter: 'VC-DMZ'

2014-06-19 09:28:58 avvcbimage Info <18665>:      - connected to 'VirtualCenter' - version: 'VMware vCenter Server 5.0.0 build-455964'

2014/06/19-09:28:58.94220 [VcbImageAssistThread]  VSphereAPI::loginWithCookie(https://10.1.1.1:443/sdk) sessionID changed during login.

2014/06/19-09:28:58.97879 [VcbImageAssistThread]  VSphereAPI::getDatacenterMoref() Number of Objects=1

2014/06/19-09:28:58.97883 [VcbImageAssistThread]  VSphereAPI::getDatacenterMoref() Object type:Datacenter, (1 properties)

2014/06/19-09:28:58.97884 [VcbImageAssistThread]  VSphereAPI::getDatacenterMoref() found datacenter:'VC-DMZ', moref:'datacenter-81'

2014-06-19 09:28:58 avvcbimage Info <14692>: Login test is OK.

2014/06/19-09:28:58.99463 [VcbImageAssistThread]  AutoLogin by 'createVMRequest' - login=true.

2014-06-19 09:28:58 avvcbimage Error <17771>: Invalid request to create a VM.

2014/06/19-09:28:59.01412 [VcbImageAssistThread]  VSphereAPI::getDatacenterMoref() Number of Objects=1

2014/06/19-09:28:59.01416 [VcbImageAssistThread]  VSphereAPI::getDatacenterMoref() Object type:Datacenter, (1 properties)

2014/06/19-09:28:59.01416 [VcbImageAssistThread]  VSphereAPI::getDatacenterMoref() found datacenter:'VC-DMZ', moref:'datacenter-81'

2014-06-19 09:28:59 avvcbimage Warning <16004>: Soap fault detected, Find VM - NOT ok, Msg:'?? '

2014/06/19-09:28:59.03614 [VcbImageAssistThread]  AutoLogin by 'createVMRequest' - now logging out.

2014-06-19 09:28:59 avvcbimage Error <0000>: [IMG2012] VM creation failed during restore.

2014-06-19 09:28:59 avvcbimage Info <9772>: Starting graceful (staged) termination, Create VM failed during restore. (wrap-up stage)

2014/06/19-09:28:59.03632 [VcbImageAssistThread]  Starting graceful (staged) termination, run stage [stage:RSTAGE_WRAPUP/1 excode:EXIT_PLUGIN_ERROR_00/200 skipwrap:f] (request by TID: 9068, reason: Create VM failed during restore.)

2014/06/19-09:28:59.03633 [VcbImageAssistThread]  uapp_staged::RunStageMultiple::startTermination: create exit timer thread

2014/06/19-09:28:59.03644 [ExitTimer]  Startup, pid=9959 tid=38 stack=0x7f1d266d2cdf td=0x7f1d2ab0cb90

2014-06-19 09:28:59 avvcbimage Info <16022>: Cancel detected(plugin error 00), isExitOK(0).

2014/06/19-09:28:59.03655 [VcbImageAssistThread]  uapp_staged::RunStageMultiple::skipWrapup: already terminating

2014/06/19-09:28:59.04176 [VcbImageAssistThread]  getInstance() rc=6, msg=The requested object could not be found

2014-06-19 09:28:59 avvcbimage Info <16022>: Cancel detected(plugin error 00), isExitOK(0).

2014/06/19-09:28:59.04202 [VcbImageAssistThread]  Thread finished VcbImageAssistThread

2014/06/19-09:28:59.04282 [vcbimage_ctl_sup]  sum_wrapups() 0 wrapups, 0 wrapup keys, snapview_wid MOD-1403169837372#0

2014/06/19-09:28:59.04292 [vcbimage_ctl_sup]  xml_attr_add(): xml attribute exitcode not previously defined

2014/06/19-09:28:59.04296 [vcbimage_ctl_sup]  xml_attr_add(): xml attribute errors not previously defined

2014/06/19-09:28:59.04302 [vcbimage_ctl_sup]  xml_attr_add(): xml attribute warnings not previously defined

2014/06/19-09:28:59.04307 [vcbimage_ctl_sup]  xml_attr_add(): xml attribute fatals not previously defined

2014-06-19 09:28:59 avvcbimage Info <16038>: Final summary, cancelled/aborted 0, snapview 1, exitcode 200: plugin error 00

2014/06/19-09:28:59.04367 [ctl_conn_send-3016-MOD-1403169837372]  ctl_connection::lowsend:

send:

2014/06/19-09:29:04.04356 [vcbimage_ctl_sup]  ctl_manbase::process_message() done

2014/06/19-09:29:04.04362 [vcbimage_ctl_sup]  Thread finished vcbimage_ctl_sup

2014/06/19-09:29:04.04373 [ctl_conn_send-3016-MOD-1403169837372]  Thread finished ctl_conn_send-3016-MOD-1403169837372

2014/06/19-09:29:04.04404 [ctl_conn_recv-3016-MOD-1403169837372]  ctl_connection::getmsglen() Unable to recv message size!

2014/06/19-09:29:04.04416 [ctl_conn_recv-3016-MOD-1403169837372]  Thread finished ctl_conn_recv-3016-MOD-1403169837372

2014/06/19-09:29:04.04423 [ctl_callhome]  Thread finished ctl_callhome

2014/06/19-09:29:04.04426 [avvcbimage]  back from callhome object terminate

2014/06/19-09:29:04.04447 [ctl_listen]  tcpsockimpl::genAccept ::accept returned -1 signal=0 errno=code 4: Interrupted system call

2014/06/19-09:29:04.04449 [ctl_listen]  Thread finished ctl_listen

2014/06/19-09:29:04.04523 [avvcbimage]  vcbimage_app::run() returning 200

2014/06/19-09:29:04.04526 [avvcbimage]  vcbimag: done 200

2014/06/19-09:29:04.04526 [avvcbimage]  vcbimag returning with exitcode 200

2014/06/19-09:29:04.04529 [avvcbimage]  vcbimage_app::~vcbimage_app

2014/06/19-09:29:04.04558 [avvcbimage]  Debug output redirect end

--------------------------------------------------------------------------------------------------------

----- END avvcbimage log 2014-06-19 09:29:04 UTC  (4 warnings, 4 errors, 1 fatal error)

--------------------------------------------------------------------------------------------------------

晚上工作到九点多了啊，辛苦辛苦

检查一下当前的要Restore的这个Client的plugin的版本是否匹配？是否正常启动？

然后，你尝试一下把 --subprocesstime=600 加到  /usr/local/avamarclient/var-proxy-1/avvcbimage.cmd 里面，然后再试试。

多谢LZ的更新。

请LZ帮忙标记一下对应的正确/有用答案，这样方便其它用户遇到同样问题可以及时看到解决方法。