* Remus : VM on backup not in pause state
@ 2010-07-22 20:45 Dulloor
2010-07-22 21:49 ` Brendan Cully
0 siblings, 1 reply; 7+ messages in thread
From: Dulloor @ 2010-07-22 20:45 UTC (permalink / raw)
To: xen-devel
My setup is as follows :
- xen : unstable (rev:21743)
- Dom0 : pvops (branch : stable-2.6.32.x,
rev:01d9fbca207ec232c758d991d66466fc6e38349e)
- Guest Configuration :
------------------------------------------------------------------------------------------
kernel = "/usr/lib/xen/boot/hvmloader"
builder='hvm'
name = "linux-hvm"
vcpus = 4
memory = 2048
vif = [ 'type=ioemu, bridge=eth0, mac=00:1c:3e:17:22:13' ]
disk = [ 'phy:/dev/XenVolG/hvm-linux-snap-1.img,hda,w' ]
device_model = '/usr/lib/xen/bin/qemu-dm'
boot="cd"
sdl=0
vnc=1
vnclisten="0.0.0.0"
vncconsole=0
vncpasswd=''
stdvga=0
superpages=1
serial='pty'
------------------------------------------------------------------------------------------
- Remus command :
# remus --no-net linux-hvm <dst-ip>
- On primary :
# xm list
Name ID Mem VCPUs State Time(s)
linux-hvm 9 2048 4 -b-s-- 10.8
- On secondary :
# xm list
Name ID Mem VCPUs State Time(s)
linux-hvm 11 2048 4 -b---- 1.9
I have to issue "xm pause/unpause" explicitly for the backup VM.
Any recent changes ?
-dulloor
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Remus : VM on backup not in pause state
2010-07-22 20:45 Remus : VM on backup not in pause state Dulloor
@ 2010-07-22 21:49 ` Brendan Cully
2010-07-22 23:40 ` Dulloor
0 siblings, 1 reply; 7+ messages in thread
From: Brendan Cully @ 2010-07-22 21:49 UTC (permalink / raw)
To: Dulloor; +Cc: xen-devel
On Thursday, 22 July 2010 at 13:45, Dulloor wrote:
> My setup is as follows :
> - xen : unstable (rev:21743)
> - Dom0 : pvops (branch : stable-2.6.32.x,
> rev:01d9fbca207ec232c758d991d66466fc6e38349e)
> - Guest Configuration :
> ------------------------------------------------------------------------------------------
> kernel = "/usr/lib/xen/boot/hvmloader"
> builder='hvm'
> name = "linux-hvm"
> vcpus = 4
> memory = 2048
> vif = [ 'type=ioemu, bridge=eth0, mac=00:1c:3e:17:22:13' ]
> disk = [ 'phy:/dev/XenVolG/hvm-linux-snap-1.img,hda,w' ]
> device_model = '/usr/lib/xen/bin/qemu-dm'
> boot="cd"
> sdl=0
> vnc=1
> vnclisten="0.0.0.0"
> vncconsole=0
> vncpasswd=''
> stdvga=0
> superpages=1
> serial='pty'
> ------------------------------------------------------------------------------------------
>
> - Remus command :
> # remus --no-net linux-hvm <dst-ip>
>
> - On primary :
> # xm list
> Name ID Mem VCPUs State Time(s)
> linux-hvm 9 2048 4 -b-s-- 10.8
>
> - On secondary :
> # xm list
> Name ID Mem VCPUs State Time(s)
> linux-hvm 11 2048 4 -b---- 1.9
>
>
> I have to issue "xm pause/unpause" explicitly for the backup VM.
> Any recent changes ?
This probably means there was a timeout on the replication channel,
interpreted by the backup as a failure of the primary, which caused it
to activate itself. You should see evidence of that in the remus
console logs and xend.log and daemon.log (for the disk side).
Once you've figured out where the timeout happened it'll be easier to
figure out why.
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Remus : VM on backup not in pause state
2010-07-22 21:49 ` Brendan Cully
@ 2010-07-22 23:40 ` Dulloor
2010-07-22 23:41 ` Dulloor
2010-07-26 22:05 ` Brendan Cully
0 siblings, 2 replies; 7+ messages in thread
From: Dulloor @ 2010-07-22 23:40 UTC (permalink / raw)
To: Dulloor, xen-devel
On Thu, Jul 22, 2010 at 2:49 PM, Brendan Cully <brendan@cs.ubc.ca> wrote:
> On Thursday, 22 July 2010 at 13:45, Dulloor wrote:
>> My setup is as follows :
>> - xen : unstable (rev:21743)
>> - Dom0 : pvops (branch : stable-2.6.32.x,
>> rev:01d9fbca207ec232c758d991d66466fc6e38349e)
>> - Guest Configuration :
>> ------------------------------------------------------------------------------------------
>> kernel = "/usr/lib/xen/boot/hvmloader"
>> builder='hvm'
>> name = "linux-hvm"
>> vcpus = 4
>> memory = 2048
>> vif = [ 'type=ioemu, bridge=eth0, mac=00:1c:3e:17:22:13' ]
>> disk = [ 'phy:/dev/XenVolG/hvm-linux-snap-1.img,hda,w' ]
>> device_model = '/usr/lib/xen/bin/qemu-dm'
>> boot="cd"
>> sdl=0
>> vnc=1
>> vnclisten="0.0.0.0"
>> vncconsole=0
>> vncpasswd=''
>> stdvga=0
>> superpages=1
>> serial='pty'
>> ------------------------------------------------------------------------------------------
>>
>> - Remus command :
>> # remus --no-net linux-hvm <dst-ip>
>>
>> - On primary :
>> # xm list
>> Name ID Mem VCPUs State Time(s)
>> linux-hvm 9 2048 4 -b-s-- 10.8
>>
>> - On secondary :
>> # xm list
>> Name ID Mem VCPUs State Time(s)
>> linux-hvm 11 2048 4 -b---- 1.9
>>
>>
>> I have to issue "xm pause/unpause" explicitly for the backup VM.
>> Any recent changes ?
>
> This probably means there was a timeout on the replication channel,
> interpreted by the backup as a failure of the primary, which caused it
> to activate itself. You should see evidence of that in the remus
> console logs and xend.log and daemon.log (for the disk side).
>
> Once you've figured out where the timeout happened it'll be easier to
> figure out why.
>
Please find the logs attached. I didn't find anything interesting in
daemon.log.
What does remus log there ? I am not using disk replication, since I
have issues with that .. but that's for another email :)
The only visible error is in xend-secondary.log around xc_restore :
[2010-07-22 16:15:37 2056] DEBUG (balloon:207) Balloon: setting dom0 target to 5
765 MiB.
[2010-07-22 16:15:37 2056] DEBUG (XendDomainInfo:1467) Setting memory target of
domain Domain-0 (0) to 5765 MiB.
[2010-07-22 16:15:37 2056] DEBUG (XendCheckpoint:290) [xc_restore]: /usr/lib/xen
/bin/xc_restore 5 1 5 6 1 1 1 0
[2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: Error
when reading pages (11 = Resource temporarily unavailabl): Internal
error
[2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: error
when buffering batch, finishing (11 = Resource temporarily
unavailabl): Internal error
If you haven't seen this before, please let me know and I will try
debugging more.
-dulloor
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Remus : VM on backup not in pause state
2010-07-22 23:40 ` Dulloor
@ 2010-07-22 23:41 ` Dulloor
2010-07-26 22:05 ` Brendan Cully
1 sibling, 0 replies; 7+ messages in thread
From: Dulloor @ 2010-07-22 23:41 UTC (permalink / raw)
To: Dulloor, xen-devel
[-- Attachment #1: Type: text/plain, Size: 3109 bytes --]
oops .. logs attached now :)
-dulloor
On Thu, Jul 22, 2010 at 4:40 PM, Dulloor <dulloor@gmail.com> wrote:
> On Thu, Jul 22, 2010 at 2:49 PM, Brendan Cully <brendan@cs.ubc.ca> wrote:
>> On Thursday, 22 July 2010 at 13:45, Dulloor wrote:
>>> My setup is as follows :
>>> - xen : unstable (rev:21743)
>>> - Dom0 : pvops (branch : stable-2.6.32.x,
>>> rev:01d9fbca207ec232c758d991d66466fc6e38349e)
>>> - Guest Configuration :
>>> ------------------------------------------------------------------------------------------
>>> kernel = "/usr/lib/xen/boot/hvmloader"
>>> builder='hvm'
>>> name = "linux-hvm"
>>> vcpus = 4
>>> memory = 2048
>>> vif = [ 'type=ioemu, bridge=eth0, mac=00:1c:3e:17:22:13' ]
>>> disk = [ 'phy:/dev/XenVolG/hvm-linux-snap-1.img,hda,w' ]
>>> device_model = '/usr/lib/xen/bin/qemu-dm'
>>> boot="cd"
>>> sdl=0
>>> vnc=1
>>> vnclisten="0.0.0.0"
>>> vncconsole=0
>>> vncpasswd=''
>>> stdvga=0
>>> superpages=1
>>> serial='pty'
>>> ------------------------------------------------------------------------------------------
>>>
>>> - Remus command :
>>> # remus --no-net linux-hvm <dst-ip>
>>>
>>> - On primary :
>>> # xm list
>>> Name ID Mem VCPUs State Time(s)
>>> linux-hvm 9 2048 4 -b-s-- 10.8
>>>
>>> - On secondary :
>>> # xm list
>>> Name ID Mem VCPUs State Time(s)
>>> linux-hvm 11 2048 4 -b---- 1.9
>>>
>>>
>>> I have to issue "xm pause/unpause" explicitly for the backup VM.
>>> Any recent changes ?
>>
>> This probably means there was a timeout on the replication channel,
>> interpreted by the backup as a failure of the primary, which caused it
>> to activate itself. You should see evidence of that in the remus
>> console logs and xend.log and daemon.log (for the disk side).
>>
>> Once you've figured out where the timeout happened it'll be easier to
>> figure out why.
>>
> Please find the logs attached. I didn't find anything interesting in
> daemon.log.
> What does remus log there ? I am not using disk replication, since I
> have issues with that .. but that's for another email :)
>
> The only visible error is in xend-secondary.log around xc_restore :
> [2010-07-22 16:15:37 2056] DEBUG (balloon:207) Balloon: setting dom0 target to 5
> 765 MiB.
> [2010-07-22 16:15:37 2056] DEBUG (XendDomainInfo:1467) Setting memory target of
> domain Domain-0 (0) to 5765 MiB.
> [2010-07-22 16:15:37 2056] DEBUG (XendCheckpoint:290) [xc_restore]: /usr/lib/xen
> /bin/xc_restore 5 1 5 6 1 1 1 0
> [2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: Error
> when reading pages (11 = Resource temporarily unavailabl): Internal
> error
> [2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: error
> when buffering batch, finishing (11 = Resource temporarily
> unavailabl): Internal error
>
> If you haven't seen this before, please let me know and I will try
> debugging more.
>
> -dulloor
>
[-- Attachment #2: xend-primary.log --]
[-- Type: application/octet-stream, Size: 30729 bytes --]
[2010-07-22 09:08:55 2284] INFO (SrvDaemon:332) Xend Daemon started
[2010-07-22 09:08:55 2284] INFO (SrvDaemon:336) Xend changeset: Fri Jul 16 11:29:42 2010 -0700 21666:969bb091e695.
[2010-07-22 09:08:55 2284] DEBUG (tcp:96) Listening on :8002
[2010-07-22 09:08:57 2284] DEBUG (XendCPUPool:747) recreate_active_pools
[2010-07-22 09:08:57 2284] DEBUG (XendDomainInfo:151) XendDomainInfo.recreate({'max_vcpu_id': 23, 'cpu_time': 45238240984L, 'ssidref': 0, 'hvm': 0, 'shutdown_reason': 255, 'dying': 0, 'online_vcpus': 24, 'domid': 0, 'paused': 0, 'crashed': 0, 'running': 1, 'maxmem_kb': 17179869180L, 'shutdown': 0, 'mem_kb': 23936488L, 'blocked': 0, 'handle': [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], 'cpupool': 0, 'name': 'Domain-0'})
[2010-07-22 09:08:57 2284] INFO (XendDomainInfo:169) Recreating domain 0, UUID 00000000-0000-0000-0000-000000000000. at /local/domain/0
[2010-07-22 09:08:57 2284] DEBUG (XendDomainInfo:3414) Storing VM details: {'on_xend_stop': 'ignore', 'pool_name': 'Pool-0', 'shadow_memory': '0', 'uuid': '00000000-0000-0000-0000-000000000000', 'on_reboot': 'restart', 'image': '(linux (kernel ) (superpages 0) (nomigrate 0) (tsc_mode 0))', 'on_poweroff': 'destroy', 'bootloader_args': '', 'on_xend_start': 'ignore', 'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '24', 'vcpu_avail': '16777215', 'bootloader': '', 'name': 'Domain-0'}
[2010-07-22 09:08:57 2284] DEBUG (XendDomainInfo:1790) Storing domain details: {'cpu/3/availability': 'online', 'cpu/6/availability': 'online', 'vm': '/vm/00000000-0000-0000-0000-000000000000-1', 'cpu/22/availability': 'online', 'control/platform-feature-multiprocessor-suspend': '1', 'cpu/17/availability': 'online', 'cpu/14/availability': 'online', 'console/limit': '1048576', 'cpu/2/availability': 'online', 'cpu/11/availability': 'online', 'cpu/1/availability': 'online', 'cpu/7/availability': 'online', 'memory/target': '23936488', 'cpu/20/availability': 'online', 'cpu/4/availability': 'online', 'cpu/15/availability': 'online', 'description': '', 'cpu/13/availability': 'online', 'cpu/8/availability': 'online', 'cpu/9/availability': 'online', 'cpu/5/availability': 'online', 'cpu/23/availability': 'online', 'cpu/0/availability': 'online', 'cpu/18/availability': 'online', 'console/type': 'xenconsoled', 'cpu/12/availability': 'online', 'cpu/19/availability': 'online', 'name': 'Domain-0', 'domid': '0', 'cpu/16/availability': 'online', 'cpu/21/availability': 'online', 'cpu/10/availability': 'online'}
[2010-07-22 09:08:58 2284] DEBUG (XendDomain:464) Adding Domain: 0
[2010-07-22 09:08:58 2284] DEBUG (XendDomain:398) number of vcpus to use is 0
[2010-07-22 09:08:58 2284] DEBUG (XendDomainInfo:1877) XendDomainInfo.handleShutdownWatch
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: VBD.set_device not found
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: VBD.set_type not found
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: session.get_all_records not found
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: event.get_record not found
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: event.get_all not found
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: VIF.set_device not found
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: VIF.set_MAC not found
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: VIF.set_MTU not found
[2010-07-22 09:08:58 2284] WARNING (XendAPI:708) API call: debug.get_all not found
[2010-07-22 09:08:58 2284] INFO (XMLRPCServer:161) Opening Unix domain socket XML-RPC server on /var/run/xend/xen-api.sock; authentication has been disabled for this server.
[2010-07-22 09:08:58 2284] INFO (XMLRPCServer:161) Opening Unix domain socket XML-RPC server on /var/run/xend/xmlrpc.sock.
[2010-07-22 09:11:20 2284] DEBUG (XendDomainInfo:103) XendDomainInfo.create(['vm', ['name', 'linux-hvm'], ['memory', 2048], ['on_xend_start', 'ignore'], ['on_xend_stop', 'ignore'], ['vcpus', 4], ['oos', 1], ['image', ['hvm', ['kernel', '/usr/lib/xen/boot/hvmloader'], ['videoram', 4], ['serial', 'pty'], ['superpages', 1], ['acpi', 1], ['apic', 1], ['boot', 'cd'], ['cpuid', []], ['cpuid_check', []], ['device_model', '/usr/lib/xen/bin/qemu-dm'], ['display', ':0.0'], ['fda', ''], ['fdb', ''], ['guest_os_type', 'default'], ['hap', 1], ['hpet', 0], ['isa', 0], ['keymap', ''], ['localtime', 0], ['nographic', 0], ['oos', 1], ['pae', 1], ['pci', []], ['pci_msitranslate', 1], ['pci_power_mgmt', 0], ['rtc_timeoffset', 0], ['sdl', 0], ['soundhw', ''], ['stdvga', 0], ['timer_mode', 1], ['usb', 0], ['usbdevice', ''], ['vcpus', 4], ['vnc', 1], ['vncconsole', 0], ['vnclisten', '0.0.0.0'], ['vncunused', 1], ['viridian', 0], ['vpt_align', 1], ['xauthority', '/var/run/gdm/auth-for-root-aRVArT/database'], ['xen_platform_pci', 1], ['memory_sharing', 0], ['vncpasswd', 'XXXXXXXX'], ['tsc_mode', 0], ['nomigrate', 0]]], ['s3_integrity', 1], ['device', ['vbd', ['uname', 'phy:/dev/XenVolG/hvm-linux-snap-1.img'], ['dev', 'hda'], ['mode', 'w']]], ['device', ['vif', ['bridge', 'eth0'], ['mac', '00:1c:3e:17:22:13'], ['type', 'ioemu']]]])
[2010-07-22 09:11:20 2284] DEBUG (XendDomainInfo:2494) XendDomainInfo.constructDomain
[2010-07-22 09:11:20 2284] DEBUG (balloon:187) Balloon: 1717600 KiB free; need 16384; done.
[2010-07-22 09:11:20 2284] DEBUG (XendDomain:464) Adding Domain: 1
[2010-07-22 09:11:20 2284] DEBUG (XendDomainInfo:2832) XendDomainInfo.initDomain: 1 256
[2010-07-22 09:11:20 2284] DEBUG (image:339) No VNC passwd configured for vfb access
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: boot, val: cd
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: fda, val: None
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: fdb, val: None
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: soundhw, val: None
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: localtime, val: 0
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: serial, val: ['pty']
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: std-vga, val: 0
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: isa, val: 0
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: acpi, val: 1
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: usb, val: 0
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: usbdevice, val: None
[2010-07-22 09:11:20 2284] DEBUG (image:889) args: gfx_passthru, val: None
[2010-07-22 09:11:20 2284] INFO (image:822) Need to create platform device.[domid:1]
[2010-07-22 09:11:20 2284] DEBUG (XendDomainInfo:2859) _initDomain:shadow_memory=0x0, memory_static_max=0x80000000, memory_static_min=0x0.
[2010-07-22 09:11:20 2284] DEBUG (balloon:172) Balloon: tmem relinquished -1 KiB of 405700 KiB requested.
[2010-07-22 09:11:20 2284] DEBUG (balloon:193) Balloon: 1716028 KiB free; 0 to scrub; need 2121728; retries: 20.
[2010-07-22 09:11:20 2284] DEBUG (balloon:207) Balloon: setting dom0 target to 22979 MiB.
[2010-07-22 09:11:20 2284] DEBUG (XendDomainInfo:1463) Setting memory target of domain Domain-0 (0) to 22979 MiB.
[2010-07-22 09:11:20 2284] DEBUG (balloon:193) Balloon: 1998652 KiB free; 0 to scrub; need 2121728; retries: 20.
[2010-07-22 09:11:20 2284] DEBUG (balloon:207) Balloon: setting dom0 target to 22973 MiB.
[2010-07-22 09:11:20 2284] DEBUG (XendDomainInfo:1463) Setting memory target of domain Domain-0 (0) to 22973 MiB.
[2010-07-22 09:11:20 2284] INFO (image:182) buildDomain os=hvm dom=1 vcpus=4
[2010-07-22 09:11:20 2284] DEBUG (image:947) domid = 1
[2010-07-22 09:11:20 2284] DEBUG (image:948) image = /usr/lib/xen/boot/hvmloader
[2010-07-22 09:11:20 2284] DEBUG (image:949) store_evtchn = 5
[2010-07-22 09:11:20 2284] DEBUG (image:950) memsize = 2048
[2010-07-22 09:11:20 2284] DEBUG (image:951) target = 2048
[2010-07-22 09:11:20 2284] DEBUG (image:952) vcpus = 4
[2010-07-22 09:11:20 2284] DEBUG (image:953) vcpu_avail = 15
[2010-07-22 09:11:20 2284] DEBUG (image:954) acpi = 1
[2010-07-22 09:11:20 2284] DEBUG (image:955) apic = 1
[2010-07-22 09:11:21 2284] INFO (XendDomainInfo:2353) createDevice: vfb : {'vncunused': 1, 'vnclisten': '0.0.0.0', 'vnc': '1', 'uuid': 'e752468a-ae44-4ab8-b2a0-522786e2e8d3', 'other_config': {'vncunused': 1, 'vnclisten': '0.0.0.0', 'vnc': '1'}}
[2010-07-22 09:11:21 2284] DEBUG (DevController:95) DevController: writing {'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/vfb/1/0'} to /local/domain/1/device/vfb/0.
[2010-07-22 09:11:21 2284] DEBUG (DevController:97) DevController: writing {'vncunused': '1', 'domain': 'linux-hvm', 'frontend': '/local/domain/1/device/vfb/0', 'uuid': 'e752468a-ae44-4ab8-b2a0-522786e2e8d3', 'frontend-id': '1', 'vnclisten': '0.0.0.0', 'state': '1', 'online': '1', 'vnc': '1'} to /local/domain/0/backend/vfb/1/0.
[2010-07-22 09:11:21 2284] INFO (XendDomainInfo:2353) createDevice: vbd : {'uuid': '1f3c8cde-5d51-2524-a779-2f31af79de43', 'bootable': 1, 'driver': 'paravirtualised', 'dev': 'hda', 'uname': 'phy:/dev/XenVolG/hvm-linux-snap-1.img', 'mode': 'w'}
[2010-07-22 09:11:21 2284] DEBUG (DevController:95) DevController: writing {'backend-id': '0', 'virtual-device': '768', 'device-type': 'disk', 'state': '1', 'backend': '/local/domain/0/backend/vbd/1/768'} to /local/domain/1/device/vbd/768.
[2010-07-22 09:11:21 2284] DEBUG (DevController:97) DevController: writing {'domain': 'linux-hvm', 'frontend': '/local/domain/1/device/vbd/768', 'uuid': '1f3c8cde-5d51-2524-a779-2f31af79de43', 'bootable': '1', 'dev': 'hda', 'state': '1', 'params': '/dev/XenVolG/hvm-linux-snap-1.img', 'mode': 'w', 'online': '1', 'frontend-id': '1', 'type': 'phy'} to /local/domain/0/backend/vbd/1/768.
[2010-07-22 09:11:21 2284] INFO (XendDomainInfo:2353) createDevice: vif : {'bridge': 'eth0', 'mac': '00:1c:3e:17:22:13', 'type': 'ioemu', 'uuid': '9a0ab772-bb16-c6e9-7f6a-9ba40e2de87c'}
[2010-07-22 09:11:21 2284] DEBUG (DevController:95) DevController: writing {'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/vif/1/0'} to /local/domain/1/device/vif/0.
[2010-07-22 09:11:21 2284] DEBUG (DevController:97) DevController: writing {'bridge': 'eth0', 'domain': 'linux-hvm', 'handle': '0', 'uuid': '9a0ab772-bb16-c6e9-7f6a-9ba40e2de87c', 'script': '/etc/xen/scripts/vif-bridge', 'mac': '00:1c:3e:17:22:13', 'frontend-id': '1', 'state': '1', 'online': '1', 'frontend': '/local/domain/1/device/vif/0', 'type': 'ioemu'} to /local/domain/0/backend/vif/1/0.
[2010-07-22 09:11:21 2284] INFO (image:418) spawning device models: /usr/lib/xen/bin/qemu-dm ['/usr/lib/xen/bin/qemu-dm', '-d', '1', '-domain-name', 'linux-hvm', '-videoram', '4', '-vnc', '0.0.0.0:0', '-vncunused', '-vcpus', '4', '-vcpu_avail', '0xf', '-boot', 'cd', '-serial', 'pty', '-acpi', '-net', 'nic,vlan=1,macaddr=00:1c:3e:17:22:13,model=rtl8139', '-net', 'tap,vlan=1,ifname=tap1.0,bridge=eth0', '-M', 'xenfv']
[2010-07-22 09:11:21 2284] INFO (image:467) device model pid: 2724
[2010-07-22 09:11:21 2284] INFO (image:590) waiting for sentinel_fifo
[2010-07-22 09:11:21 2284] DEBUG (XendDomainInfo:3414) Storing VM details: {'on_xend_stop': 'ignore', 'pool_name': 'Pool-0', 'shadow_memory': '20', 'uuid': '85d5fb3a-5053-25cf-9cf2-52d882a69aa9', 'on_reboot': 'restart', 'start_time': '1279815081.29', 'on_poweroff': 'destroy', 'bootloader_args': '', 'on_xend_start': 'ignore', 'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '4', 'vcpu_avail': '15', 'bootloader': '', 'image': '(hvm (kernel ) (superpages 1) (videoram 4) (hpet 0) (stdvga 0) (vnclisten 0.0.0.0) (loader /usr/lib/xen/boot/hvmloader) (xen_platform_pci 1) (rtc_timeoffset 0) (pci ()) (hap 1) (localtime 0) (timer_mode 1) (pci_msitranslate 1) (oos 1) (apic 1) (sdl 0) (display :0.0) (vpt_align 1) (vncconsole 0) (serial pty) (vncunused 1) (boot cd) (pae 1) (viridian 0) (acpi 1) (vnc 1) (nographic 0) (nomigrate 0) (usb 0) (tsc_mode 0) (guest_os_type default) (device_model /usr/lib/xen/bin/qemu-dm) (pci_power_mgmt 0) (xauthority /var/run/gdm/auth-for-root-aRVArT/database) (isa 0) (notes (SUSPEND_CANCEL 1)))', 'name': 'linux-hvm'}
[2010-07-22 09:11:21 2284] DEBUG (XendDomainInfo:1790) Storing domain details: {'console/port': '6', 'cpu/3/availability': 'online', 'description': '', 'console/limit': '1048576', 'store/port': '5', 'cpu/2/availability': 'online', 'vm': '/vm/85d5fb3a-5053-25cf-9cf2-52d882a69aa9', 'domid': '1', 'image/suspend-cancel': '1', 'cpu/0/availability': 'online', 'memory/target': '2097152', 'control/platform-feature-multiprocessor-suspend': '1', 'store/ring-ref': '1044476', 'cpu/1/availability': 'online', 'console/type': 'ioemu', 'name': 'linux-hvm'}
[2010-07-22 09:11:21 2284] DEBUG (DevController:95) DevController: writing {'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/console/1/0'} to /local/domain/1/device/console/0.
[2010-07-22 09:11:21 2284] DEBUG (DevController:97) DevController: writing {'domain': 'linux-hvm', 'frontend': '/local/domain/1/device/console/0', 'uuid': '81291010-7967-cab2-0419-da2dd2157aa9', 'frontend-id': '1', 'state': '1', 'location': '6', 'online': '1', 'protocol': 'vt100'} to /local/domain/0/backend/console/1/0.
[2010-07-22 09:11:21 2284] DEBUG (XendDomainInfo:1877) XendDomainInfo.handleShutdownWatch
[2010-07-22 09:11:21 2284] DEBUG (DevController:139) Waiting for devices tap2.
[2010-07-22 09:11:21 2284] DEBUG (DevController:139) Waiting for devices vif.
[2010-07-22 09:11:21 2284] DEBUG (DevController:144) Waiting for 0.
[2010-07-22 09:11:22 2284] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vif/1/0/hotplug-status.
[2010-07-22 09:11:22 2284] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vif/1/0/hotplug-status.
[2010-07-22 09:11:22 2284] DEBUG (DevController:642) hotplugStatusCallback 1.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices vkbd.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices ioports.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices tap.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices vif2.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices console.
[2010-07-22 09:11:22 2284] DEBUG (DevController:144) Waiting for 0.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices vscsi.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices vbd.
[2010-07-22 09:11:22 2284] DEBUG (DevController:144) Waiting for 768.
[2010-07-22 09:11:22 2284] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/1/768/hotplug-status.
[2010-07-22 09:11:22 2284] DEBUG (DevController:642) hotplugStatusCallback 1.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices irq.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices vfb.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices pci.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices vusb.
[2010-07-22 09:11:22 2284] DEBUG (DevController:139) Waiting for devices vtpm.
[2010-07-22 09:11:22 2284] INFO (XendDomain:1213) Domain linux-hvm (1) unpaused.
[2010-07-22 09:18:43 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:43 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:43 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:44 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:44 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:44 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:44 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:44 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:45 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:45 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:45 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:45 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:45 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:46 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:46 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:46 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:46 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:46 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:47 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:47 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:47 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:47 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:48 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:48 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:48 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:48 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:48 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:49 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:49 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:49 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:49 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:49 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:50 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:50 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:50 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:50 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:50 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:51 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:51 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:51 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:51 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:51 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:52 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:52 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:52 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:52 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:53 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:53 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:53 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:53 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:53 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:54 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:54 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:54 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:54 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:54 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:55 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:55 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:55 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:55 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:55 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:56 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:56 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:56 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:56 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:56 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:57 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:57 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:57 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:57 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:58 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:58 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:58 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:58 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:58 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:59 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:59 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:59 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:59 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:18:59 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:00 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:00 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:00 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:00 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:00 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:01 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:01 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:01 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:01 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:01 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:02 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:02 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:02 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:02 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:03 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:03 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:03 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:03 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:03 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:04 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:04 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:04 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:04 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:04 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:05 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:05 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:05 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:05 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:05 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:06 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:06 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:06 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:06 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:06 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:07 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:07 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:07 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:07 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:07 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:08 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:08 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:08 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:08 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:09 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:09 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:09 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:09 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:09 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:10 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:10 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:10 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:10 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:10 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:11 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:11 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:11 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:11 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:11 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:12 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:12 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[2010-07-22 09:19:12 2284] INFO (XendDomainInfo:2074) Domain has shutdown: name=linux-hvm id=1 reason=suspend.
[-- Attachment #3: xend-secondary.log --]
[-- Type: application/octet-stream, Size: 18632 bytes --]
[2010-07-22 16:09:20 2056] INFO (SrvDaemon:332) Xend Daemon started
[2010-07-22 16:09:20 2056] INFO (SrvDaemon:336) Xend changeset: Tue Jul 06 17:58:37 2010 +0100 21743:a0f0ae5be814.
[2010-07-22 16:09:20 2056] DEBUG (tcp:96) Listening on :8002
[2010-07-22 16:09:23 2056] DEBUG (XendCPUPool:747) recreate_active_pools
[2010-07-22 16:09:23 2056] DEBUG (XendDomainInfo:151) XendDomainInfo.recreate({'max_vcpu_id': 7, 'cpu_time': 30055058649L, 'ssidref': 0, 'hvm': 0, 'shutdown_reason': 255, 'dying': 0, 'online_vcpus': 8, 'domid': 0, 'paused': 0, 'crashed': 0, 'running': 1, 'maxmem_kb': 17179869180L, 'shutdown': 0, 'mem_kb': 6313456L, 'blocked': 0, 'handle': [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], 'cpupool': 0, 'name': 'Domain-0'})
[2010-07-22 16:09:23 2056] INFO (XendDomainInfo:169) Recreating domain 0, UUID 00000000-0000-0000-0000-000000000000. at /local/domain/0
[2010-07-22 16:09:23 2056] DEBUG (XendDomainInfo:3418) Storing VM details: {'on_xend_stop': 'ignore', 'pool_name': 'Pool-0', 'shadow_memory': '0', 'uuid': '00000000-0000-0000-0000-000000000000', 'on_reboot': 'restart', 'image': "(linux (kernel '') (superpages 0) (nomigrate 0) (tsc_mode 0))", 'on_poweroff': 'destroy', 'bootloader_args': '', 'on_xend_start': 'ignore', 'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '8', 'vcpu_avail': '255', 'bootloader': '', 'name': 'Domain-0'}
[2010-07-22 16:09:23 2056] DEBUG (XendDomainInfo:1794) Storing domain details: {'cpu/3/availability': 'online', 'description': '', 'console/limit': '1048576', 'memory/target': '6313456', 'cpu/2/availability': 'online', 'vm': '/vm/00000000-0000-0000-0000-000000000000-5', 'domid': '0', 'cpu/7/availability': 'online', 'cpu/0/availability': 'online', 'cpu/1/availability': 'online', 'cpu/5/availability': 'online', 'control/platform-feature-multiprocessor-suspend': '1', 'cpu/6/availability': 'online', 'console/type': 'xenconsoled', 'cpu/4/availability': 'online', 'name': 'Domain-0'}
[2010-07-22 16:09:23 2056] DEBUG (XendDomain:476) Adding Domain: 0
[2010-07-22 16:09:23 2056] DEBUG (XendDomain:410) number of vcpus to use is 0
[2010-07-22 16:09:23 2056] DEBUG (XendDomainInfo:1881) XendDomainInfo.handleShutdownWatch
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: VBD.set_device not found
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: VBD.set_type not found
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: session.get_all_records not found
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: event.get_record not found
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: event.get_all not found
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: VIF.set_device not found
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: VIF.set_MAC not found
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: VIF.set_MTU not found
[2010-07-22 16:09:23 2056] WARNING (XendAPI:708) API call: debug.get_all not found
[2010-07-22 16:09:23 2056] INFO (XMLRPCServer:161) Opening Unix domain socket XML-RPC server on /var/run/xend/xen-api.sock; authentication has been disabled for this server.
[2010-07-22 16:09:23 2056] INFO (XMLRPCServer:161) Opening Unix domain socket XML-RPC server on /var/run/xend/xmlrpc.sock.
[2010-07-22 16:15:36 2056] DEBUG (XendDomainInfo:237) XendDomainInfo.restore(['domain', ['domid', '1'], ['cpu_weight', '256'], ['cpu_cap', '0'], ['pool_name', 'Pool-0'], ['bootloader'], ['vcpus', '4'], ['cpus', [[], [], [], []]], ['on_poweroff', 'destroy'], ['description'], ['on_crash', 'restart'], ['uuid', '85d5fb3a-5053-25cf-9cf2-52d882a69aa9'], ['bootloader_args'], ['name', 'linux-hvm'], ['on_reboot', 'restart'], ['maxmem', '2048'], ['memory', '2048'], ['shadow_memory', '20'], ['features'], ['on_xend_start', 'ignore'], ['on_xend_stop', 'ignore'], ['start_time', '1279815081.29'], ['cpu_time', '9.349710725'], ['online_vcpus', '4'], ['image', ['hvm', ['kernel'], ['superpages', '1'], ['videoram', '4'], ['hpet', '0'], ['stdvga', '0'], ['vnclisten', '0.0.0.0'], ['loader', '/usr/lib/xen/boot/hvmloader'], ['xen_platform_pci', '1'], ['rtc_timeoffset', '0'], ['pci', []], ['hap', '1'], ['localtime', '0'], ['timer_mode', '1'], ['pci_msitranslate', '1'], ['oos', '1'], ['apic', '1'], ['sdl', '0'], ['display', ':0.0'], ['vpt_align', '1'], ['vncconsole', '0'], ['serial', 'pty'], ['vncunused', '1'], ['boot', 'cd'], ['pae', '1'], ['viridian', '0'], ['acpi', '1'], ['vnc', '1'], ['nographic', '0'], ['nomigrate', '0'], ['usb', '0'], ['tsc_mode', '0'], ['guest_os_type', 'default'], ['device_model', '/usr/lib/xen/bin/qemu-dm'], ['pci_power_mgmt', '0'], ['xauthority', '/var/run/gdm/auth-for-root-aRVArT/database'], ['isa', '0'], ['notes', ['SUSPEND_CANCEL', '1']]]], ['status', '2'], ['state', '-b----'], ['store_mfn', '1044476'], ['device', ['vif', ['bridge', 'eth0'], ['uuid', '9a0ab772-bb16-c6e9-7f6a-9ba40e2de87c'], ['script', '/etc/xen/scripts/vif-bridge'], ['mac', '00:1c:3e:17:22:13'], ['type', 'ioemu'], ['backend', '0']]], ['device', ['console', ['protocol', 'vt100'], ['location', '6'], ['uuid', '81291010-7967-cab2-0419-da2dd2157aa9']]], ['device', ['vbd', ['uuid', '1f3c8cde-5d51-2524-a779-2f31af79de43'], ['bootable', '1'], ['dev', 'hda:disk'], ['uname', 'phy:/dev/XenVolG/hvm-linux-snap-1.img'], ['mode', 'w'], ['backend', '0'], ['VDI']]], ['device', ['vfb', ['vncunused', '1'], ['vnclisten', '0.0.0.0'], ['vnc', '1'], ['uuid', 'e752468a-ae44-4ab8-b2a0-522786e2e8d3'], ['location', '0.0.0.0:5900']]]])
[2010-07-22 16:15:36 2056] DEBUG (XendDomainInfo:2498) XendDomainInfo.constructDomain
[2010-07-22 16:15:36 2056] DEBUG (balloon:187) Balloon: 1717532 KiB free; need 16384; done.
[2010-07-22 16:15:36 2056] DEBUG (XendDomain:476) Adding Domain: 1
[2010-07-22 16:15:36 2056] DEBUG (XendDomainInfo:3418) Storing VM details: {'on_xend_stop': 'ignore', 'pool_name': 'Pool-0', 'shadow_memory': '20', 'uuid': '85d5fb3a-5053-25cf-9cf2-52d882a69aa9', 'on_reboot': 'restart', 'start_time': '1279815081.29', 'on_poweroff': 'destroy', 'bootloader_args': '', 'on_xend_start': 'ignore', 'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '4', 'vcpu_avail': '15', 'bootloader': '', 'image': "(hvm (kernel '') (superpages 1) (videoram 4) (hpet 0) (stdvga 0) (vnclisten 0.0.0.0) (loader /usr/lib/xen/boot/hvmloader) (xen_platform_pci 1) (rtc_timeoffset 0) (pci ()) (hap 1) (localtime 0) (timer_mode 1) (pci_msitranslate 1) (oos 1) (apic 1) (sdl 0) (display :0.0) (vpt_align 1) (vncconsole 0) (serial pty) (vncunused 1) (boot cd) (pae 1) (viridian 0) (acpi 1) (vnc 1) (nographic 0) (nomigrate 0) (usb 0) (tsc_mode 0) (guest_os_type default) (device_model /usr/lib/xen/bin/qemu-dm) (pci_power_mgmt 0) (xauthority /var/run/gdm/auth-for-root-aRVArT/database) (isa 0) (notes (SUSPEND_CANCEL 1)))", 'name': 'linux-hvm'}
[2010-07-22 16:15:36 2056] INFO (XendDomainInfo:2357) createDevice: console : {'protocol': 'vt100', 'location': '6', 'uuid': '81291010-7967-cab2-0419-da2dd2157aa9'}
[2010-07-22 16:15:37 2056] DEBUG (DevController:95) DevController: writing {'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/console/1/0'} to /local/domain/1/device/console/0.
[2010-07-22 16:15:37 2056] DEBUG (DevController:97) DevController: writing {'domain': 'linux-hvm', 'frontend': '/local/domain/1/device/console/0', 'uuid': '81291010-7967-cab2-0419-da2dd2157aa9', 'frontend-id': '1', 'state': '1', 'location': '6', 'online': '1', 'protocol': 'vt100'} to /local/domain/0/backend/console/1/0.
[2010-07-22 16:15:37 2056] INFO (XendDomainInfo:2357) createDevice: vfb : {'vncunused': '1', 'other_config': {'vncunused': '1', 'vnclisten': '0.0.0.0', 'vnc': '1'}, 'vnc': '1', 'uuid': 'e752468a-ae44-4ab8-b2a0-522786e2e8d3', 'vnclisten': '0.0.0.0', 'location': '0.0.0.0:5900'}
[2010-07-22 16:15:37 2056] DEBUG (DevController:95) DevController: writing {'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/vfb/1/0'} to /local/domain/1/device/vfb/0.
[2010-07-22 16:15:37 2056] DEBUG (DevController:97) DevController: writing {'vncunused': '1', 'domain': 'linux-hvm', 'frontend': '/local/domain/1/device/vfb/0', 'uuid': 'e752468a-ae44-4ab8-b2a0-522786e2e8d3', 'frontend-id': '1', 'vnclisten': '0.0.0.0', 'state': '1', 'location': '0.0.0.0:5900', 'online': '1', 'vnc': '1'} to /local/domain/0/backend/vfb/1/0.
[2010-07-22 16:15:37 2056] INFO (XendDomainInfo:2357) createDevice: vbd : {'uuid': '1f3c8cde-5d51-2524-a779-2f31af79de43', 'bootable': 1, 'driver': 'paravirtualised', 'dev': 'hda:disk', 'uname': 'phy:/dev/XenVolG/hvm-linux-snap-1.img', 'mode': 'w', 'backend': '0'}
[2010-07-22 16:15:37 2056] DEBUG (DevController:95) DevController: writing {'backend-id': '0', 'virtual-device': '768', 'device-type': 'disk', 'state': '1', 'backend': '/local/domain/0/backend/vbd/1/768'} to /local/domain/1/device/vbd/768.
[2010-07-22 16:15:37 2056] DEBUG (DevController:97) DevController: writing {'domain': 'linux-hvm', 'frontend': '/local/domain/1/device/vbd/768', 'uuid': '1f3c8cde-5d51-2524-a779-2f31af79de43', 'bootable': '1', 'dev': 'hda', 'state': '1', 'params': '/dev/XenVolG/hvm-linux-snap-1.img', 'mode': 'w', 'online': '1', 'frontend-id': '1', 'type': 'phy'} to /local/domain/0/backend/vbd/1/768.
[2010-07-22 16:15:37 2056] INFO (XendDomainInfo:2357) createDevice: vif : {'bridge': 'eth0', 'uuid': '9a0ab772-bb16-c6e9-7f6a-9ba40e2de87c', 'script': '/etc/xen/scripts/vif-bridge', 'mac': '00:1c:3e:17:22:13', 'type': 'ioemu', 'backend': '0'}
[2010-07-22 16:15:37 2056] DEBUG (DevController:95) DevController: writing {'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/vif/1/0'} to /local/domain/1/device/vif/0.
[2010-07-22 16:15:37 2056] DEBUG (DevController:97) DevController: writing {'bridge': 'eth0', 'domain': 'linux-hvm', 'handle': '0', 'uuid': '9a0ab772-bb16-c6e9-7f6a-9ba40e2de87c', 'script': '/etc/xen/scripts/vif-bridge', 'mac': '00:1c:3e:17:22:13', 'frontend-id': '1', 'state': '1', 'online': '1', 'frontend': '/local/domain/1/device/vif/0', 'type': 'ioemu'} to /local/domain/0/backend/vif/1/0.
[2010-07-22 16:15:37 2056] DEBUG (XendDomainInfo:1794) Storing domain details: {'console/port': '6', 'cpu/3/availability': 'online', 'description': '', 'console/limit': '1048576', 'cpu/2/availability': 'online', 'vm': '/vm/85d5fb3a-5053-25cf-9cf2-52d882a69aa9', 'domid': '1', 'image/suspend-cancel': '1', 'cpu/0/availability': 'online', 'memory/target': '2097152', 'control/platform-feature-multiprocessor-suspend': '1', 'console/type': 'ioemu', 'cpu/1/availability': 'online', 'store/port': '5', 'name': 'linux-hvm'}
[2010-07-22 16:15:37 2056] INFO (XendCheckpoint:253) restore hvm domain 1, apic=1, pae=1
[2010-07-22 16:15:37 2056] DEBUG (image:339) No VNC passwd configured for vfb access
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: boot, val: cd
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: fda, val: None
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: fdb, val: None
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: soundhw, val: None
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: localtime, val: 0
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: serial, val: ['pty']
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: std-vga, val: 0
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: isa, val: 0
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: acpi, val: 1
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: usb, val: 0
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: usbdevice, val: None
[2010-07-22 16:15:37 2056] DEBUG (image:889) args: gfx_passthru, val: None
[2010-07-22 16:15:37 2056] INFO (image:822) Need to create platform device.[domid:1]
[2010-07-22 16:15:37 2056] DEBUG (XendCheckpoint:271) restore:shadow=0x14, _static_max=0x80000000, _static_min=0x0,
[2010-07-22 16:15:37 2056] DEBUG (balloon:172) Balloon: tmem relinquished -1 KiB of 405764 KiB requested.
[2010-07-22 16:15:37 2056] DEBUG (balloon:193) Balloon: 1715964 KiB free; 0 to scrub; need 2121728; retries: 20.
[2010-07-22 16:15:37 2056] DEBUG (balloon:207) Balloon: setting dom0 target to 5769 MiB.
[2010-07-22 16:15:37 2056] DEBUG (XendDomainInfo:1467) Setting memory target of domain Domain-0 (0) to 5769 MiB.
[2010-07-22 16:15:37 2056] DEBUG (balloon:193) Balloon: 2012924 KiB free; 0 to scrub; need 2121728; retries: 20.
[2010-07-22 16:15:37 2056] DEBUG (balloon:207) Balloon: setting dom0 target to 5765 MiB.
[2010-07-22 16:15:37 2056] DEBUG (XendDomainInfo:1467) Setting memory target of domain Domain-0 (0) to 5765 MiB.
[2010-07-22 16:15:37 2056] DEBUG (XendCheckpoint:290) [xc_restore]: /usr/lib/xen/bin/xc_restore 5 1 5 6 1 1 1 0
[2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: Error when reading pages (11 = Resource temporarily unavailabl): Internal error
[2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: error when buffering batch, finishing (11 = Resource temporarily unavailabl): Internal error
[2010-07-22 16:18:43 2056] DEBUG (XendCheckpoint:379) store-mfn 1044476
[2010-07-22 16:18:43 2056] DEBUG (XendDomainInfo:3010) XendDomainInfo.completeRestore
[2010-07-22 16:18:43 2056] DEBUG (image:339) No VNC passwd configured for vfb access
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: boot, val: cd
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: fda, val: None
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: fdb, val: None
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: soundhw, val: None
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: localtime, val: 0
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: serial, val: ['pty']
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: std-vga, val: 0
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: isa, val: 0
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: acpi, val: 1
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: usb, val: 0
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: usbdevice, val: None
[2010-07-22 16:18:43 2056] DEBUG (image:889) args: gfx_passthru, val: None
[2010-07-22 16:18:43 2056] INFO (image:822) Need to create platform device.[domid:1]
[2010-07-22 16:18:43 2056] INFO (image:418) spawning device models: /usr/lib/xen/bin/qemu-dm ['/usr/lib/xen/bin/qemu-dm', '-d', '1', '-domain-name', 'linux-hvm', '-videoram', '4', '-vnc', '0.0.0.0:0', '-vncunused', '-vcpus', '4', '-vcpu_avail', '0xf', '-boot', 'cd', '-serial', 'pty', '-acpi', '-net', 'nic,vlan=1,macaddr=00:1c:3e:17:22:13,model=rtl8139', '-net', 'tap,vlan=1,ifname=tap1.0,bridge=eth0', '-M', 'xenfv', '-loadvm', '/var/lib/xen/qemu-save.1']
[2010-07-22 16:18:43 2056] INFO (image:467) device model pid: 2641
[2010-07-22 16:18:43 2056] INFO (image:590) waiting for sentinel_fifo
[2010-07-22 16:18:43 2056] DEBUG (XendDomainInfo:1794) Storing domain details: {'console/port': '6', 'cpu/3/availability': 'online', 'description': '', 'console/limit': '1048576', 'store/port': '5', 'cpu/2/availability': 'online', 'vm': '/vm/85d5fb3a-5053-25cf-9cf2-52d882a69aa9', 'domid': '1', 'image/suspend-cancel': '1', 'cpu/0/availability': 'online', 'memory/target': '2097152', 'control/platform-feature-multiprocessor-suspend': '1', 'store/ring-ref': '1044476', 'cpu/1/availability': 'online', 'console/type': 'ioemu', 'name': 'linux-hvm'}
[2010-07-22 16:18:43 2056] DEBUG (XendDomainInfo:3023) XendDomainInfo.completeRestore done
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices tap2.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices vif.
[2010-07-22 16:18:43 2056] DEBUG (XendDomainInfo:1881) XendDomainInfo.handleShutdownWatch
[2010-07-22 16:18:43 2056] DEBUG (DevController:144) Waiting for 0.
[2010-07-22 16:18:43 2056] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vif/1/0/hotplug-status.
[2010-07-22 16:18:43 2056] DEBUG (DevController:642) hotplugStatusCallback 1.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices vkbd.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices ioports.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices tap.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices vif2.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices console.
[2010-07-22 16:18:43 2056] DEBUG (DevController:144) Waiting for 0.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices vscsi.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices vbd.
[2010-07-22 16:18:43 2056] DEBUG (DevController:144) Waiting for 768.
[2010-07-22 16:18:43 2056] DEBUG (DevController:628) hotplugStatusCallback /local/domain/0/backend/vbd/1/768/hotplug-status.
[2010-07-22 16:18:43 2056] DEBUG (DevController:642) hotplugStatusCallback 1.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices irq.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices vfb.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices pci.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices vusb.
[2010-07-22 16:18:43 2056] DEBUG (DevController:139) Waiting for devices vtpm.
[2010-07-22 16:19:58 2056] DEBUG (XendDomainInfo:524) XendDomainInfo.shutdown(poweroff)
[2010-07-22 16:19:58 2056] DEBUG (XendDomainInfo:1881) XendDomainInfo.handleShutdownWatch
[2010-07-22 16:19:58 2056] INFO (XendDomainInfo:541) HVM save:remote shutdown dom 1!
[2010-07-22 16:19:58 2056] INFO (XendDomainInfo:2078) Domain has shutdown: name=linux-hvm id=1 reason=poweroff.
[2010-07-22 16:19:58 2056] DEBUG (XendDomainInfo:3071) XendDomainInfo.destroy: domid=1
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:2401) Destroying device model
[2010-07-22 16:19:59 2056] INFO (image:615) linux-hvm device model terminated
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:2408) Releasing devices
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:2414) Removing vif/0
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:1276) XendDomainInfo.destroyDevice: deviceClass = vif, device = vif/0
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:2414) Removing console/0
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:1276) XendDomainInfo.destroyDevice: deviceClass = console, device = console/0
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:2414) Removing vbd/768
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:1276) XendDomainInfo.destroyDevice: deviceClass = vbd, device = vbd/768
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:2414) Removing vfb/0
[2010-07-22 16:19:59 2056] DEBUG (XendDomainInfo:1276) XendDomainInfo.destroyDevice: deviceClass = vfb, device = vfb/0
[2010-07-22 16:24:58 2056] DEBUG (XendDomainInfo:2406) No device model
[2010-07-22 16:24:58 2056] DEBUG (XendDomainInfo:2408) Releasing devices
[-- Attachment #4: remus-console.log --]
[-- Type: application/octet-stream, Size: 33125 bytes --]
Disk is not replicated: phy:/dev/XenVolG/hvm-linux-snap-1.img,hda,w
qemu logdirty mode: enable
PROF: suspending at 1279815523.477039
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815523.526312
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815523.527045
unknown command:
PROF: suspending at 1279815523.708161
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815523.718289
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815523.719804
unknown command:
PROF: suspending at 1279815523.912212
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815523.923951
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815523.927120
PROF: suspending at 1279815524.116814
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815524.127446
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815524.131583
PROF: suspending at 1279815524.320861
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815524.330750
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815524.332698
PROF: suspending at 1279815524.525707
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815524.536670
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815524.538328
PROF: suspending at 1279815524.730188
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815524.739629
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815524.742635
PROF: suspending at 1279815524.933497
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815524.942980
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815524.947313
PROF: suspending at 1279815525.137849
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815525.150292
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815525.151566
PROF: suspending at 1279815525.344759
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815525.356623
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815525.358255
PROF: suspending at 1279815525.550976
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815525.562885
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815525.566269
PROF: suspending at 1279815525.757101
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815525.768745
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815525.770540
PROF: suspending at 1279815525.961805
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815525.971464
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815525.974345
PROF: suspending at 1279815526.165660
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815526.176533
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815526.178509
PROF: suspending at 1279815526.370579
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815526.381208
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815526.383512
PROF: suspending at 1279815526.575753
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815526.587511
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815526.590809
PROF: suspending at 1279815526.781531
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815526.789434
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815526.790458
PROF: suspending at 1279815526.985148
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815526.997864
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815526.999749
PROF: suspending at 1279815527.190991
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815527.200709
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815527.202254
PROF: suspending at 1279815527.395220
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815527.405375
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815527.407431
PROF: suspending at 1279815527.599439
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815527.615661
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815527.616497
PROF: suspending at 1279815527.812221
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815527.828231
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815527.829180
PROF: suspending at 1279815528.024899
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815528.040123
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815528.040951
PROF: suspending at 1279815528.238020
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815528.254912
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815528.255808
PROF: suspending at 1279815528.451785
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815528.468596
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815528.469435
PROF: suspending at 1279815528.665958
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815528.706242
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815528.707191
PROF: suspending at 1279815528.901990
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815528.910946
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815528.914198
PROF: suspending at 1279815529.105920
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815529.116599
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815529.118201
PROF: suspending at 1279815529.309937
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815529.320800
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815529.322323
PROF: suspending at 1279815529.514159
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815529.525184
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815529.526947
PROF: suspending at 1279815529.718709
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815529.730924
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815529.733009
PROF: suspending at 1279815529.923554
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815529.936421
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815529.937713
PROF: suspending at 1279815530.130171
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815530.141903
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815530.144834
PROF: suspending at 1279815530.335453
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815530.348689
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815530.351593
PROF: suspending at 1279815530.540153
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815530.550053
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815530.551994
PROF: suspending at 1279815530.744577
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815530.753914
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815530.755543
PROF: suspending at 1279815530.950572
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815530.959178
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815530.961475
PROF: suspending at 1279815531.154459
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815531.163312
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815531.166244
PROF: suspending at 1279815531.358286
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815531.367540
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815531.370422
PROF: suspending at 1279815531.562487
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815531.573425
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815531.575369
PROF: suspending at 1279815531.768209
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815531.779802
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815531.781358
PROF: suspending at 1279815531.974372
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815531.985726
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815531.987025
PROF: suspending at 1279815532.179301
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815532.190220
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815532.192406
PROF: suspending at 1279815532.383660
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815532.392724
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815532.397333
PROF: suspending at 1279815532.588153
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815532.599853
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815532.600863
PROF: suspending at 1279815532.794587
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815532.803913
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815532.806896
PROF: suspending at 1279815532.998638
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815533.015002
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815533.015969
PROF: suspending at 1279815533.211611
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815533.230998
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815533.231911
PROF: suspending at 1279815533.428006
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815533.446162
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815533.447165
PROF: suspending at 1279815533.642180
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815533.660767
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815533.661706
PROF: suspending at 1279815533.858408
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815533.896350
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815533.897572
PROF: suspending at 1279815534.091407
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815534.109956
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815534.110944
PROF: suspending at 1279815534.305479
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815534.317310
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815534.318640
PROF: suspending at 1279815534.511206
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815534.522382
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815534.526121
PROF: suspending at 1279815534.716568
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815534.726587
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815534.728072
PROF: suspending at 1279815534.921081
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815534.932231
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815534.934380
PROF: suspending at 1279815535.127071
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815535.138121
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815535.140202
PROF: suspending at 1279815535.331327
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815535.341461
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815535.343971
PROF: suspending at 1279815535.537277
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815535.550195
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815535.554577
PROF: suspending at 1279815535.742767
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815535.755872
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815535.758963
PROF: suspending at 1279815535.948101
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815535.958696
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815535.959721
PROF: suspending at 1279815536.152721
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815536.163526
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815536.165964
PROF: suspending at 1279815536.358696
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815536.370331
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815536.371821
PROF: suspending at 1279815536.563336
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815536.574621
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815536.577022
PROF: suspending at 1279815536.768400
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815536.780475
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815536.781487
PROF: suspending at 1279815536.974077
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815536.987870
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815536.989168
PROF: suspending at 1279815537.181002
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815537.193330
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815537.197737
PROF: suspending at 1279815537.386012
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815537.398081
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815537.401490
PROF: suspending at 1279815537.591225
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815537.601577
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815537.605716
PROF: suspending at 1279815537.795718
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815537.807576
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815537.811194
PROF: suspending at 1279815538.001310
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815538.017747
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815538.018604
PROF: suspending at 1279815538.214650
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815538.230878
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815538.231849
PROF: suspending at 1279815538.428516
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815538.446209
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815538.447124
PROF: suspending at 1279815538.642325
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815538.657738
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815538.658575
PROF: suspending at 1279815538.854616
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815538.892545
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815538.893615
PROF: suspending at 1279815539.088306
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815539.097891
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815539.100754
PROF: suspending at 1279815539.291968
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815539.309363
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815539.310287
PROF: suspending at 1279815539.506776
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815539.519169
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815539.521772
PROF: suspending at 1279815539.712519
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815539.721677
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815539.724380
PROF: suspending at 1279815539.917044
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815539.928371
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815539.930157
PROF: suspending at 1279815540.122599
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815540.179808
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815540.181570
PROF: suspending at 1279815540.328890
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815540.338429
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815540.340160
PROF: suspending at 1279815540.532799
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815540.542827
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815540.545702
PROF: suspending at 1279815540.737488
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815540.745970
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815540.748934
PROF: suspending at 1279815540.941044
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815540.951218
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815540.955355
PROF: suspending at 1279815541.145513
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815541.156209
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815541.158359
PROF: suspending at 1279815541.351369
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815541.361465
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815541.364253
PROF: suspending at 1279815541.556781
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815541.568058
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815541.569974
PROF: suspending at 1279815541.762044
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815541.770561
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815541.772913
PROF: suspending at 1279815541.965684
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815541.976386
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815541.977478
PROF: suspending at 1279815542.171184
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815542.182368
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815542.184887
PROF: suspending at 1279815542.377075
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815542.386990
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815542.389300
PROF: suspending at 1279815542.582525
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815542.592276
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815542.597088
PROF: suspending at 1279815542.787953
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815542.798240
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815542.800535
PROF: suspending at 1279815542.993390
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815543.003902
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815543.006112
PROF: suspending at 1279815543.199257
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815543.228318
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815543.229260
PROF: suspending at 1279815543.424069
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815543.430899
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815543.432260
PROF: suspending at 1279815543.628127
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815543.644142
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815543.645014
PROF: suspending at 1279815543.841181
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815543.856449
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815543.857289
PROF: suspending at 1279815544.053487
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815544.068250
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815544.069076
PROF: suspending at 1279815544.265781
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815544.281382
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815544.282220
PROF: suspending at 1279815544.478360
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815544.495695
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815544.496612
PROF: suspending at 1279815544.692147
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815544.706670
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815544.707540
PROF: suspending at 1279815544.904306
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815544.911942
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815544.914988
PROF: suspending at 1279815545.109108
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815545.117658
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815545.119876
PROF: suspending at 1279815545.312983
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815545.324507
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815545.327633
PROF: suspending at 1279815545.517053
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815545.528238
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815545.530546
PROF: suspending at 1279815545.722811
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815545.734678
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815545.736333
PROF: suspending at 1279815545.928837
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815545.940007
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815545.941613
PROF: suspending at 1279815546.134031
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815546.144350
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815546.146556
PROF: suspending at 1279815546.338163
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815546.349351
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815546.350281
PROF: suspending at 1279815546.544488
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815546.554623
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815546.556270
PROF: suspending at 1279815546.750317
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815546.759781
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815546.761914
PROF: suspending at 1279815546.954063
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815546.963705
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815546.965982
PROF: suspending at 1279815547.158254
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815547.166655
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815547.169770
PROF: suspending at 1279815547.362170
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815547.370831
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815547.374324
PROF: suspending at 1279815547.565784
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815547.577164
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815547.579235
PROF: suspending at 1279815547.771387
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815547.780410
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815547.782546
PROF: suspending at 1279815547.974577
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815547.984480
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815547.987189
PROF: suspending at 1279815548.178815
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815548.188006
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815548.190533
PROF: suspending at 1279815548.382842
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815548.393320
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815548.396140
PROF: suspending at 1279815548.587856
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815548.599803
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815548.602160
PROF: suspending at 1279815548.793653
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815548.803411
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815548.805923
PROF: suspending at 1279815548.999568
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815549.015242
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815549.016191
PROF: suspending at 1279815549.212477
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815549.227711
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815549.228678
PROF: suspending at 1279815549.424756
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815549.440357
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815549.441229
PROF: suspending at 1279815549.638208
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815549.656445
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815549.657364
PROF: suspending at 1279815549.852515
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815549.868974
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815549.869842
PROF: suspending at 1279815550.065783
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815550.080877
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815550.081804
PROF: suspending at 1279815550.278875
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815550.296647
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815550.297724
PROF: suspending at 1279815550.492642
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815550.510418
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815550.511428
PROF: suspending at 1279815550.707024
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815550.718915
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815550.720945
PROF: suspending at 1279815550.911187
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815550.920757
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815550.923687
PROF: suspending at 1279815551.115285
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815551.127754
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815551.128772
PROF: suspending at 1279815551.321052
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815551.330646
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815551.333361
PROF: suspending at 1279815551.525083
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815551.536388
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815551.538069
PROF: suspending at 1279815551.729421
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815551.741077
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815551.743729
PROF: suspending at 1279815551.934082
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815551.944362
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815551.946137
PROF: suspending at 1279815552.138762
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815552.148139
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815552.150715
PROF: suspending at 1279815552.342824
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815552.352675
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815552.354308
PROF: suspending at 1279815552.548230
issuing HVM suspend hypercall
suspend hypercall returned 0
pausing QEMU
PROF: resumed at 1279815552.559672
resuming QEMU
Sending 6527 bytes of QEMU state
PROF: flushed memory at 1279815552.561231
[-- Attachment #5: Type: text/plain, Size: 138 bytes --]
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Remus : VM on backup not in pause state
2010-07-22 23:40 ` Dulloor
2010-07-22 23:41 ` Dulloor
@ 2010-07-26 22:05 ` Brendan Cully
2010-07-27 6:17 ` Dulloor
1 sibling, 1 reply; 7+ messages in thread
From: Brendan Cully @ 2010-07-26 22:05 UTC (permalink / raw)
To: Dulloor; +Cc: xen-devel
On Thursday, 22 July 2010 at 16:40, Dulloor wrote:
> On Thu, Jul 22, 2010 at 2:49 PM, Brendan Cully <brendan@cs.ubc.ca> wrote:
> > On Thursday, 22 July 2010 at 13:45, Dulloor wrote:
> >> My setup is as follows :
> >> - xen : unstable (rev:21743)
> >> - Dom0 : pvops (branch : stable-2.6.32.x,
> >> rev:01d9fbca207ec232c758d991d66466fc6e38349e)
> >> - Guest Configuration :
> >> ------------------------------------------------------------------------------------------
> >> kernel = "/usr/lib/xen/boot/hvmloader"
> >> builder='hvm'
> >> name = "linux-hvm"
> >> vcpus = 4
> >> memory = 2048
> >> vif = [ 'type=ioemu, bridge=eth0, mac=00:1c:3e:17:22:13' ]
> >> disk = [ 'phy:/dev/XenVolG/hvm-linux-snap-1.img,hda,w' ]
> >> device_model = '/usr/lib/xen/bin/qemu-dm'
> >> boot="cd"
> >> sdl=0
> >> vnc=1
> >> vnclisten="0.0.0.0"
> >> vncconsole=0
> >> vncpasswd=''
> >> stdvga=0
> >> superpages=1
> >> serial='pty'
> >> ------------------------------------------------------------------------------------------
> >>
> >> - Remus command :
> >> # remus --no-net linux-hvm <dst-ip>
> >>
> >> - On primary :
> >> # xm list
> >> Name ID Mem VCPUs State Time(s)
> >> linux-hvm 9 2048 4 -b-s-- 10.8
> >>
> >> - On secondary :
> >> # xm list
> >> Name ID Mem VCPUs State Time(s)
> >> linux-hvm 11 2048 4 -b---- 1.9
> >>
> >>
> >> I have to issue "xm pause/unpause" explicitly for the backup VM.
> >> Any recent changes ?
> >
> > This probably means there was a timeout on the replication channel,
> > interpreted by the backup as a failure of the primary, which caused it
> > to activate itself. You should see evidence of that in the remus
> > console logs and xend.log and daemon.log (for the disk side).
> >
> > Once you've figured out where the timeout happened it'll be easier to
> > figure out why.
> >
> Please find the logs attached. I didn't find anything interesting in
> daemon.log.
> What does remus log there ? I am not using disk replication, since I
> have issues with that .. but that's for another email :)
daemon.log is just for disk replication, so if you're not using it you
won't see anything.
> The only visible error is in xend-secondary.log around xc_restore :
> [2010-07-22 16:15:37 2056] DEBUG (balloon:207) Balloon: setting dom0 target to 5
> 765 MiB.
> [2010-07-22 16:15:37 2056] DEBUG (XendDomainInfo:1467) Setting memory target of
> domain Domain-0 (0) to 5765 MiB.
> [2010-07-22 16:15:37 2056] DEBUG (XendCheckpoint:290) [xc_restore]: /usr/lib/xen
> /bin/xc_restore 5 1 5 6 1 1 1 0
> [2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: Error
> when reading pages (11 = Resource temporarily unavailabl): Internal
> error
> [2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: error
> when buffering batch, finishing (11 = Resource temporarily
> unavailabl): Internal error
>
> If you haven't seen this before, please let me know and I will try
> debugging more.
I haven't seen that. It looks like read_exact_timed has failed with
EAGAIN, which is surprising since it explicitly looks for EAGAIN and
loops on it. Can you log len and errno after line 77 in
read_exact_timed in tools/libxc/xc_domain_restore.c? ie change
if ( len <= 0 )
return -1;
to something like
if ( len <= 0 ) {
fprintf(stderr, "read_exact_timed failed (read rc: %d, errno: %d)\n",
len, errno);
return -1;
}
Another possibility is read is returning 0 here (and EAGAIN is just a
leftover errno from a previous read), which would indicate that the
_sender_ hung up the connection. It's hard to tell exactly what's
going on because you seem to have an enormous amount of clock skew
between your primary and secondary dom0s and I can't tell whether the
logs match up.
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Remus : VM on backup not in pause state
2010-07-26 22:05 ` Brendan Cully
@ 2010-07-27 6:17 ` Dulloor
2010-08-18 20:10 ` Brendan Cully
0 siblings, 1 reply; 7+ messages in thread
From: Dulloor @ 2010-07-27 6:17 UTC (permalink / raw)
To: Dulloor, xen-devel
Thanks for the pointers. I haven't had time to work on this. I will
collect more data and get back as soon as I can.
-dulloor
On Mon, Jul 26, 2010 at 3:05 PM, Brendan Cully <brendan@cs.ubc.ca> wrote:
> On Thursday, 22 July 2010 at 16:40, Dulloor wrote:
>> On Thu, Jul 22, 2010 at 2:49 PM, Brendan Cully <brendan@cs.ubc.ca> wrote:
>> > On Thursday, 22 July 2010 at 13:45, Dulloor wrote:
>> >> My setup is as follows :
>> >> - xen : unstable (rev:21743)
>> >> - Dom0 : pvops (branch : stable-2.6.32.x,
>> >> rev:01d9fbca207ec232c758d991d66466fc6e38349e)
>> >> - Guest Configuration :
>> >> ------------------------------------------------------------------------------------------
>> >> kernel = "/usr/lib/xen/boot/hvmloader"
>> >> builder='hvm'
>> >> name = "linux-hvm"
>> >> vcpus = 4
>> >> memory = 2048
>> >> vif = [ 'type=ioemu, bridge=eth0, mac=00:1c:3e:17:22:13' ]
>> >> disk = [ 'phy:/dev/XenVolG/hvm-linux-snap-1.img,hda,w' ]
>> >> device_model = '/usr/lib/xen/bin/qemu-dm'
>> >> boot="cd"
>> >> sdl=0
>> >> vnc=1
>> >> vnclisten="0.0.0.0"
>> >> vncconsole=0
>> >> vncpasswd=''
>> >> stdvga=0
>> >> superpages=1
>> >> serial='pty'
>> >> ------------------------------------------------------------------------------------------
>> >>
>> >> - Remus command :
>> >> # remus --no-net linux-hvm <dst-ip>
>> >>
>> >> - On primary :
>> >> # xm list
>> >> Name ID Mem VCPUs State Time(s)
>> >> linux-hvm 9 2048 4 -b-s-- 10.8
>> >>
>> >> - On secondary :
>> >> # xm list
>> >> Name ID Mem VCPUs State Time(s)
>> >> linux-hvm 11 2048 4 -b---- 1.9
>> >>
>> >>
>> >> I have to issue "xm pause/unpause" explicitly for the backup VM.
>> >> Any recent changes ?
>> >
>> > This probably means there was a timeout on the replication channel,
>> > interpreted by the backup as a failure of the primary, which caused it
>> > to activate itself. You should see evidence of that in the remus
>> > console logs and xend.log and daemon.log (for the disk side).
>> >
>> > Once you've figured out where the timeout happened it'll be easier to
>> > figure out why.
>> >
>> Please find the logs attached. I didn't find anything interesting in
>> daemon.log.
>> What does remus log there ? I am not using disk replication, since I
>> have issues with that .. but that's for another email :)
>
> daemon.log is just for disk replication, so if you're not using it you
> won't see anything.
>
>> The only visible error is in xend-secondary.log around xc_restore :
>> [2010-07-22 16:15:37 2056] DEBUG (balloon:207) Balloon: setting dom0 target to 5
>> 765 MiB.
>> [2010-07-22 16:15:37 2056] DEBUG (XendDomainInfo:1467) Setting memory target of
>> domain Domain-0 (0) to 5765 MiB.
>> [2010-07-22 16:15:37 2056] DEBUG (XendCheckpoint:290) [xc_restore]: /usr/lib/xen
>> /bin/xc_restore 5 1 5 6 1 1 1 0
>> [2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: Error
>> when reading pages (11 = Resource temporarily unavailabl): Internal
>> error
>> [2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: error
>> when buffering batch, finishing (11 = Resource temporarily
>> unavailabl): Internal error
>>
>> If you haven't seen this before, please let me know and I will try
>> debugging more.
>
> I haven't seen that. It looks like read_exact_timed has failed with
> EAGAIN, which is surprising since it explicitly looks for EAGAIN and
> loops on it. Can you log len and errno after line 77 in
> read_exact_timed in tools/libxc/xc_domain_restore.c? ie change
>
> if ( len <= 0 )
> return -1;
>
> to something like
>
> if ( len <= 0 ) {
> fprintf(stderr, "read_exact_timed failed (read rc: %d, errno: %d)\n",
> len, errno);
> return -1;
> }
>
> Another possibility is read is returning 0 here (and EAGAIN is just a
> leftover errno from a previous read), which would indicate that the
> _sender_ hung up the connection. It's hard to tell exactly what's
> going on because you seem to have an enormous amount of clock skew
> between your primary and secondary dom0s and I can't tell whether the
> logs match up.
>
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Remus : VM on backup not in pause state
2010-07-27 6:17 ` Dulloor
@ 2010-08-18 20:10 ` Brendan Cully
0 siblings, 0 replies; 7+ messages in thread
From: Brendan Cully @ 2010-08-18 20:10 UTC (permalink / raw)
To: Dulloor; +Cc: xen-devel
I've reproduced this on unstable (I'd been running the 4.0 tree
previously). The cause was a well-intentioned but broken patch by Ian
Jackson (21488:dd6bbdc42033). I've just mailed the fix to xen-devel.
On Monday, 26 July 2010 at 23:17, Dulloor wrote:
> Thanks for the pointers. I haven't had time to work on this. I will
> collect more data and get back as soon as I can.
>
> -dulloor
>
> On Mon, Jul 26, 2010 at 3:05 PM, Brendan Cully <brendan@cs.ubc.ca> wrote:
> > On Thursday, 22 July 2010 at 16:40, Dulloor wrote:
> >> On Thu, Jul 22, 2010 at 2:49 PM, Brendan Cully <brendan@cs.ubc.ca> wrote:
> >> > On Thursday, 22 July 2010 at 13:45, Dulloor wrote:
> >> >> My setup is as follows :
> >> >> - xen : unstable (rev:21743)
> >> >> - Dom0 : pvops (branch : stable-2.6.32.x,
> >> >> rev:01d9fbca207ec232c758d991d66466fc6e38349e)
> >> >> - Guest Configuration :
> >> >> ------------------------------------------------------------------------------------------
> >> >> kernel = "/usr/lib/xen/boot/hvmloader"
> >> >> builder='hvm'
> >> >> name = "linux-hvm"
> >> >> vcpus = 4
> >> >> memory = 2048
> >> >> vif = [ 'type=ioemu, bridge=eth0, mac=00:1c:3e:17:22:13' ]
> >> >> disk = [ 'phy:/dev/XenVolG/hvm-linux-snap-1.img,hda,w' ]
> >> >> device_model = '/usr/lib/xen/bin/qemu-dm'
> >> >> boot="cd"
> >> >> sdl=0
> >> >> vnc=1
> >> >> vnclisten="0.0.0.0"
> >> >> vncconsole=0
> >> >> vncpasswd=''
> >> >> stdvga=0
> >> >> superpages=1
> >> >> serial='pty'
> >> >> ------------------------------------------------------------------------------------------
> >> >>
> >> >> - Remus command :
> >> >> # remus --no-net linux-hvm <dst-ip>
> >> >>
> >> >> - On primary :
> >> >> # xm list
> >> >> Name ID Mem VCPUs State Time(s)
> >> >> linux-hvm 9 2048 4 -b-s-- 10.8
> >> >>
> >> >> - On secondary :
> >> >> # xm list
> >> >> Name ID Mem VCPUs State Time(s)
> >> >> linux-hvm 11 2048 4 -b---- 1.9
> >> >>
> >> >>
> >> >> I have to issue "xm pause/unpause" explicitly for the backup VM.
> >> >> Any recent changes ?
> >> >
> >> > This probably means there was a timeout on the replication channel,
> >> > interpreted by the backup as a failure of the primary, which caused it
> >> > to activate itself. You should see evidence of that in the remus
> >> > console logs and xend.log and daemon.log (for the disk side).
> >> >
> >> > Once you've figured out where the timeout happened it'll be easier to
> >> > figure out why.
> >> >
> >> Please find the logs attached. I didn't find anything interesting in
> >> daemon.log.
> >> What does remus log there ? I am not using disk replication, since I
> >> have issues with that .. but that's for another email :)
> >
> > daemon.log is just for disk replication, so if you're not using it you
> > won't see anything.
> >
> >> The only visible error is in xend-secondary.log around xc_restore :
> >> [2010-07-22 16:15:37 2056] DEBUG (balloon:207) Balloon: setting dom0 target to 5
> >> 765 MiB.
> >> [2010-07-22 16:15:37 2056] DEBUG (XendDomainInfo:1467) Setting memory target of
> >> domain Domain-0 (0) to 5765 MiB.
> >> [2010-07-22 16:15:37 2056] DEBUG (XendCheckpoint:290) [xc_restore]: /usr/lib/xen
> >> /bin/xc_restore 5 1 5 6 1 1 1 0
> >> [2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: Error
> >> when reading pages (11 = Resource temporarily unavailabl): Internal
> >> error
> >> [2010-07-22 16:18:42 2056] INFO (XendCheckpoint:408) xc: error: error
> >> when buffering batch, finishing (11 = Resource temporarily
> >> unavailabl): Internal error
> >>
> >> If you haven't seen this before, please let me know and I will try
> >> debugging more.
> >
> > I haven't seen that. It looks like read_exact_timed has failed with
> > EAGAIN, which is surprising since it explicitly looks for EAGAIN and
> > loops on it. Can you log len and errno after line 77 in
> > read_exact_timed in tools/libxc/xc_domain_restore.c? ie change
> >
> > if ( len <= 0 )
> > return -1;
> >
> > to something like
> >
> > if ( len <= 0 ) {
> > fprintf(stderr, "read_exact_timed failed (read rc: %d, errno: %d)\n",
> > len, errno);
> > return -1;
> > }
> >
> > Another possibility is read is returning 0 here (and EAGAIN is just a
> > leftover errno from a previous read), which would indicate that the
> > _sender_ hung up the connection. It's hard to tell exactly what's
> > going on because you seem to have an enormous amount of clock skew
> > between your primary and secondary dom0s and I can't tell whether the
> > logs match up.
> >
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xensource.com
> http://lists.xensource.com/xen-devel
>
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2010-08-18 20:10 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2010-07-22 20:45 Remus : VM on backup not in pause state Dulloor
2010-07-22 21:49 ` Brendan Cully
2010-07-22 23:40 ` Dulloor
2010-07-22 23:41 ` Dulloor
2010-07-26 22:05 ` Brendan Cully
2010-07-27 6:17 ` Dulloor
2010-08-18 20:10 ` Brendan Cully
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).