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-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:10:01.24740 [VcbImageAssistThread] VcbImageAssistThread::removeFlagFromWO() - Removing 'postrestore_poweron_mode' flag from avtar workorder.
longjian1
22 消息
0
2014年7月7日 01:00
谢谢leo li的回答,这个问题已经解决了。从log来看,是经过了20多分钟后超时导致restor失败的。所以设置[avvcbimage]subprocesstimeoutsecs=1800,即可解决问题。
DELL-Leo
Community Manager
Community Manager
•
7.1K 消息
0
2014年6月16日 21:00
楼主,
你双击上面截图里面的failed也没有任何restore失败的日志吗?没有任何日志信息的话,检查看看 Avamar Proxy当前是否工作正常?对其它client的备份和恢复正常吗? 用 nslookup 加 IP地址,看看解析什么的是否正常?
longjian1
22 消息
0
2014年6月16日 22:00
hi,leo.
双击截图里面的failed没有任何restore失败的日志。并且在/usr/local/avamarclient/var-proxy-1查看相应的log也没有发现对应虚机restore的log,这就是奇怪之处,似乎restore根本就没跑起来,找不到failed的记录。
而这个proxy下的所有虚机手动和计划备份都能正常完成。
longjian1
22 消息
0
2014年6月17日 19:00
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
DELL-Leo
Community Manager
Community Manager
•
7.1K 消息
0
2014年6月17日 19:00
没有任何日志的话,应该是刚开始要Restore的时候就失败了,Restore应该根本没有Run起来。这样看来,应该是Proxy和客户端之间的问题。问一下,你这个Client是原始备份的client,还是你准备Restore到一个新的VM?
DELL-Leo
Community Manager
Community Manager
•
7.1K 消息
1
2014年6月17日 23:00
楼主,
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
longjian1
22 消息
0
2014年6月18日 03:00
hi,leo。
权限检查了没问题,是管理员权限。
添加超时参数这个也做了,报错还是一样,如上面的log信息。
DELL-Leo
Community Manager
Community Manager
•
7.1K 消息
0
2014年6月18日 23:00
那挺奇怪的。
你再检查一下在执行Restore的时候有没有使用一些flag?如 --verbose 这种。 然后再看看proxy 里面有没有创建过 avtar.cmd文件并使用了一些flag?
我这边再check一下还有没有别的可能性。
longjian1
22 消息
0
2014年6月19日 06:00
加了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)
--------------------------------------------------------------------------------------------------------
Yanhong1
1.6K 消息
0
2014年6月19日 17:00
晚上工作到九点多了啊,辛苦辛苦
DELL-Leo
Community Manager
Community Manager
•
7.1K 消息
0
2014年6月19日 19:00
检查一下当前的要Restore的这个Client的plugin的版本是否匹配?是否正常启动?
然后,你尝试一下把 --subprocesstime=600 加到 /usr/local/avamarclient/var-proxy-1/avvcbimage.cmd 里面,然后再试试。
DELL-Leo
Community Manager
Community Manager
•
7.1K 消息
0
2014年7月7日 02:00
多谢LZ的更新。
请LZ帮忙标记一下对应的正确/有用答案,这样方便其它用户遇到同样问题可以及时看到解决方法。