Dear autotest team,
we need to execute tests on multiple virtual machines running in parallel.
After spending some time trying to find a way to do it, possibly without any
significant modification, we figured out the cheapest way is to start all
of them with the "vms" parameter and then switch the "main_vm"
parameter to run every test safely.
However, a problem we encountered was that the "env" file was constantly
matched/unmatched which led to multiple redundant starts and shutdowns
of each VM as well as "Inappropriate ioctl for device" errors.
Is this the best practice way to do this? If so, should we do something else?
And lastly, shouldn't the cache keep information only about the VMs
and not about which of them we use for testing at a given moment?
Here is an extraction of the log file to clarify what I am talking about
if someone needs more information about the errors.
The two VMs are intranator1 and intranator2:
10/11 16:26:04 INFO | job:0210| START
virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.deploy_tests.intranator
virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.deploy_tests.intranator
timestamp=1349965564 timeout=14400 localtime=Oct 11 16:26:04
10/11 16:26:04 DEBUG| job:0533| Waiting for pid 28515 for 14400 seconds
10/11 16:26:04 ERROR|logging_ma:0584| ** Message: pygobject_register_sinkfunc
is deprecated (GstObject)
10/11 16:26:04 INFO | ovirt:0014| ovirtsdk module not present, please
install it
10/11 16:26:04 DEBUG| virt:0039| Test parameters:
10/11 16:26:04 DEBUG| virt:0043| additional_deployment_dir =
/mnt/local/tmp/pyftpdlib-0.7.0
...
10/11 16:26:04 DEBUG| virt:0043| vnc_aoport = yesut
10/11 16:26:24 WARNI|kvm_monito:0262| Could not find (qemu) prompt after
connecting to monitor. Output so far: ''
10/11 16:26:44 WARNI|kvm_monito:0262| Could not find (qemu) prompt after
connecting to monitor. Output so far: ''
10/11 16:26:44 DEBUG|env_proces:0332| KVM version: 3.5.5-2.fc17.x86_64
10/11 16:26:44 DEBUG|env_proces:0354| KVM userspace version: 1.0
10/11 16:26:44 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:41 ---> 172.16.1.141 to: 02:00:00:00:00:41 --->
172.16.1.141
10/11 16:26:44 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:40 ---> 172.17.1.141 to: 02:00:00:00:00:40 --->
172.17.1.141
10/11 16:26:44 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:41 ---> 172.16.1.141 to: 02:00:00:00:00:41 --->
172.16.1.141
10/11 16:26:44 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:40 ---> 172.17.1.141 to: 02:00:00:00:00:40 --->
172.17.1.141
10/11 16:26:44 DEBUG| virt_vm:0458| VM params in env do match requested,
continuing.
10/11 16:26:45 DEBUG| kvm_vm:1806| Destroying VM with PID 28181
10/11 16:26:45 DEBUG| kvm_vm:1812| Trying to shutdown VM with shell command
10/11 16:26:45 DEBUG| virt_vm:0524| Found/Verified IP 172.16.1.141 for VM
intranator NIC 0
10/11 16:26:45 DEBUG| remote:0194| Login command: 'ssh -o
UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22
[email protected]'
10/11 16:26:46 DEBUG|env_proces:0512| (address cache) DHCP lease OK:
00:1b:21:00:7b:2c --> 172.16.1.220
10/11 16:26:46 DEBUG| kvm_vm:1821| Shutdown command sent; waiting for VM to
go down
10/11 16:27:06 INFO | aexpect:0786| [qemu output] (Process terminated with
status 0)
10/11 16:27:06 DEBUG| kvm_vm:1825| VM is down
10/11 16:27:06 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:41 ---> 172.16.1.141 to: 02:00:00:00:00:41 --->
172.16.1.141
10/11 16:27:06 DEBUG| kvm_vm:1508| Adding VM intranator NIC ifname t0-pmZemN
to bridge br0
10/11 16:27:06 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:40 ---> 172.17.1.141 to: 02:00:00:00:00:40 --->
172.17.1.141
10/11 16:27:06 INFO | kvm_vm:1516| VM intranator NIC ifname t1-Fx1VaN was
already added to bridge br0, skipping...
10/11 16:27:06 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:41 ---> 172.16.1.141 to: 02:00:00:00:00:41 --->
172.16.1.141
10/11 16:27:06 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:40 ---> 172.17.1.141 to: 02:00:00:00:00:40 --->
172.17.1.141
10/11 16:27:06 INFO | kvm_vm:1627| Running qemu command (reformatted):
10/11 16:27:06 INFO | kvm_vm:1629| /usr/bin/qemu-kvm
10/11 16:27:06 INFO | kvm_vm:1629| -S
10/11 16:27:06 INFO | kvm_vm:1629| -name 'intranator'
10/11 16:27:06 INFO | kvm_vm:1629| -nodefaults
10/11 16:27:07 INFO | kvm_vm:1629| -chardev
socket,id=hmp_id_hmp1,path=/tmp/monitor-hmp1-20121010-151707-SxsvEDPV,server,nowait
10/11 16:27:07 INFO | kvm_vm:1629| -mon
chardev=hmp_id_hmp1,mode=readline
10/11 16:27:07 INFO | kvm_vm:1629| -chardev
socket,id=serial_id_serial1,path=/tmp/serial-serial1-20121010-151707-SxsvEDPV,server,nowait
10/11 16:27:07 INFO | kvm_vm:1629| -device
isa-serial,chardev=serial_id_serial1
10/11 16:27:07 INFO | kvm_vm:1629| -chardev
socket,id=seabioslog_id_20121010-151707-SxsvEDPV,path=/tmp/seabios-20121010-151707-SxsvEDPV,server,nowait
10/11 16:27:07 INFO | kvm_vm:1629| -device
isa-debugcon,chardev=seabioslog_id_20121010-151707-SxsvEDPV,iobase=0x402
10/11 16:27:07 INFO | kvm_vm:1629| -drive
file='/dev/ramdisk_intranator/BusinessServer_32_intranator',if=none,cache=none,id=virtio0
10/11 16:27:07 INFO | kvm_vm:1629| -device virtio-blk-pci,drive=virtio0
10/11 16:27:07 INFO | kvm_vm:1629| -device
virtio-net-pci,netdev=ideIuRuk,mac='02:00:00:00:00:41',id='idDCu4RE'
10/11 16:27:07 INFO | kvm_vm:1629| -netdev tap,id=ideIuRuk,fd=23
10/11 16:27:07 INFO | kvm_vm:1629| -device
virtio-net-pci,netdev=idHhIF4k,mac='02:00:00:00:00:40',id='idkvCbs4'
10/11 16:27:07 INFO | kvm_vm:1629| -netdev tap,id=idHhIF4k,fd=24
10/11 16:27:07 INFO | kvm_vm:1629| -m 1024
10/11 16:27:07 INFO | kvm_vm:1629| -smp 2,cores=1,threads=1,sockets=2
10/11 16:27:07 INFO | kvm_vm:1629| -cpu 'Nehalem'
10/11 16:27:07 INFO | kvm_vm:1629| -vnc :0
10/11 16:27:07 INFO | kvm_vm:1629| -vga std
10/11 16:27:07 INFO | kvm_vm:1629| -rtc
base=utc,clock=host,driftfix=none
10/11 16:27:07 INFO | kvm_vm:1629| -boot order=cdn,once=dcn,menu=off
10/11 16:27:07 INFO | kvm_vm:1629| -enable-kvm
10/11 16:27:07 INFO | aexpect:0786| [qemu output] qemu-kvm: -netdev
tap,id=idHhIF4k,fd=24: TUNGETIFF ioctl() failed: Inappropriate ioctl for device
10/11 16:27:07 INFO | aexpect:0786| [qemu output] TUNSETOFFLOAD ioctl()
failed: Inappropriate ioctl for device
10/11 16:27:08 DEBUG| kvm_vm:1736| VM appears to be alive with PID 28669
10/11 16:27:08 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'info
cpus'
10/11 16:27:08 DEBUG|kvm_monito:0338| (monitor hmp1) Response to 'info cpus'
10/11 16:27:08 DEBUG|kvm_monito:0340| (monitor hmp1) * CPU #0:
pc=0x00000000000ffff0 thread_id=28672
10/11 16:27:08 DEBUG|kvm_monito:0340| (monitor hmp1) CPU #1:
pc=0x00000000000ffff0 thread_id=28673
10/11 16:27:08 DEBUG| kvm_vm:1764| Add log: seabios-intranator.log
10/11 16:27:08 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'cont'
10/11 16:27:08 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:52 ---> 172.16.1.172 to: 02:00:00:00:00:52 --->
172.16.1.172
10/11 16:27:08 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:51 ---> 172.17.1.172 to: 02:00:00:00:00:51 --->
172.17.1.172
10/11 16:27:08 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:52 ---> 172.16.1.172 to: 02:00:00:00:00:52 --->
172.16.1.172
10/11 16:27:08 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:51 ---> 172.17.1.172 to: 02:00:00:00:00:51 --->
172.17.1.172
10/11 16:27:08 DEBUG| virt_vm:0458| VM params in env do match requested,
continuing.
10/11 16:27:08 DEBUG| kvm_vm:1806| Destroying VM with PID 28277
10/11 16:27:08 DEBUG| kvm_vm:1812| Trying to shutdown VM with shell command
10/11 16:27:11 DEBUG| kvm_vm:1816| Could not verify DHCP lease:
02:00:00:00:00:52 --> 172.16.1.172
10/11 16:27:11 DEBUG| kvm_vm:1832| Trying to kill VM with monitor command
10/11 16:27:12 INFO | kvm_vm:1841| Killing running VM 'intranator2'
10/11 16:27:12 WARNI| kvm_vm:1845| Could not send monitor command 'quit'
([Errno 9] Bad file descriptor)
10/11 16:27:12 DEBUG| kvm_vm:1853| Cannot quit normally, sending a kill to
close the deal
10/11 16:27:12 INFO | aexpect:0786| [qemu output] (Process terminated with
status 0)
10/11 16:27:13 DEBUG| kvm_vm:1858| VM is down
10/11 16:27:13 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:52 ---> 172.16.1.172 to: 02:00:00:00:00:52 --->
172.16.1.172
10/11 16:27:13 DEBUG| kvm_vm:1508| Adding VM intranator2 NIC ifname
t0-nEZp4k to bridge br0
10/11 16:27:13 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:51 ---> 172.17.1.172 to: 02:00:00:00:00:51 --->
172.17.1.172
10/11 16:27:13 INFO | kvm_vm:1516| VM intranator2 NIC ifname t1-OGUxAI was
already added to bridge br0, skipping...
10/11 16:27:13 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:52 ---> 172.16.1.172 to: 02:00:00:00:00:52 --->
172.16.1.172
10/11 16:27:13 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:51 ---> 172.17.1.172 to: 02:00:00:00:00:51 --->
172.17.1.172
10/11 16:27:13 INFO | kvm_vm:1627| Running qemu command (reformatted):
10/11 16:27:13 INFO | kvm_vm:1629| /usr/bin/qemu-kvm
10/11 16:27:13 INFO | kvm_vm:1629| -S
10/11 16:27:13 INFO | kvm_vm:1629| -name 'intranator2'
10/11 16:27:13 INFO | kvm_vm:1629| -nodefaults
10/11 16:27:13 INFO | kvm_vm:1629| -chardev
socket,id=hmp_id_hmp1,path=/tmp/monitor-hmp1-20121010-171114-E8dDy1dH,server,nowait
10/11 16:27:13 INFO | kvm_vm:1629| -mon
chardev=hmp_id_hmp1,mode=readline
10/11 16:27:13 INFO | kvm_vm:1629| -chardev
socket,id=serial_id_serial1,path=/tmp/serial-serial1-20121010-171114-E8dDy1dH,server,nowait
10/11 16:27:13 INFO | kvm_vm:1629| -device
isa-serial,chardev=serial_id_serial1
10/11 16:27:13 INFO | kvm_vm:1629| -chardev
socket,id=seabioslog_id_20121010-171114-E8dDy1dH,path=/tmp/seabios-20121010-171114-E8dDy1dH,server,nowait
10/11 16:27:13 INFO | kvm_vm:1629| -device
isa-debugcon,chardev=seabioslog_id_20121010-171114-E8dDy1dH,iobase=0x402
10/11 16:27:13 INFO | kvm_vm:1629| -drive
file='/dev/ramdisk_intranator2/BusinessServer_32_intranator2',if=none,cache=none,id=virtio0
10/11 16:27:13 INFO | kvm_vm:1629| -device virtio-blk-pci,drive=virtio0
10/11 16:27:13 INFO | kvm_vm:1629| -device
virtio-net-pci,netdev=idl8yZNc,mac='02:00:00:00:00:52',id='id9gHKgM'
10/11 16:27:13 INFO | kvm_vm:1629| -netdev tap,id=idl8yZNc,fd=21
10/11 16:27:13 INFO | kvm_vm:1629| -device
virtio-net-pci,netdev=idjGrywq,mac='02:00:00:00:00:51',id='iduPFR0R'
10/11 16:27:13 INFO | kvm_vm:1629| -netdev tap,id=idjGrywq,fd=37
10/11 16:27:13 INFO | kvm_vm:1629| -m 1024
10/11 16:27:13 INFO | kvm_vm:1629| -smp 2,cores=1,threads=1,sockets=2
10/11 16:27:13 INFO | kvm_vm:1629| -cpu 'Nehalem'
10/11 16:27:13 INFO | kvm_vm:1629| -vnc :1
10/11 16:27:13 INFO | kvm_vm:1629| -vga std
10/11 16:27:13 INFO | kvm_vm:1629| -rtc
base=utc,clock=host,driftfix=none
10/11 16:27:13 INFO | kvm_vm:1629| -boot order=cdn,once=dcn,menu=off
10/11 16:27:13 INFO | kvm_vm:1629| -enable-kvm
10/11 16:27:13 INFO | aexpect:0786| [qemu output] qemu-kvm: -netdev
tap,id=idjGrywq,fd=37: TUNGETIFF ioctl() failed: Inappropriate ioctl for device
10/11 16:27:13 INFO | aexpect:0786| [qemu output] TUNSETOFFLOAD ioctl()
failed: Inappropriate ioctl for device
10/11 16:27:14 DEBUG| kvm_vm:1736| VM appears to be alive with PID 28801
10/11 16:27:14 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'info
cpus'
10/11 16:27:14 DEBUG|kvm_monito:0338| (monitor hmp1) Response to 'info cpus'
10/11 16:27:14 DEBUG|kvm_monito:0340| (monitor hmp1) * CPU #0:
pc=0x00000000000ffff0 thread_id=28804
10/11 16:27:14 DEBUG|kvm_monito:0340| (monitor hmp1) CPU #1:
pc=0x00000000000ffff0 thread_id=28805
10/11 16:27:14 DEBUG| kvm_vm:1764| Add log: seabios-intranator2.log
10/11 16:27:14 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'cont'
10/11 16:27:14 WARNI|env_proces:0551| VM 'intranator2' failed to produce a
screendump
10/11 16:27:14 INFO | virt:0104| Running function:
deploy_tests.run_deploy_tests()
10/11 16:27:14 DEBUG| virt_vm:0755| Attempting to log into 'intranator'
(timeout 360s)
10/11 16:27:14 DEBUG| virt_vm:0524| Found/Verified IP 172.16.1.141 for VM
intranator NIC 0
10/11 16:27:14 DEBUG| remote:0194| Login command: 'ssh -o
UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22
[email protected]'
...
10/11 16:27:42 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'stop'
10/11 16:27:42 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'cont'
10/11 16:27:42 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'stop'
10/11 16:27:42 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'cont'
10/11 16:27:45 WARNI|env_proces:0461| Could not verify DHCP lease:
02:00:00:00:00:52 --> 172.16.1.172
10/11 16:27:45 DEBUG| kvm_vm:1806| Destroying VM with PID 28801
10/11 16:27:45 DEBUG| kvm_vm:1832| Trying to kill VM with monitor command
10/11 16:28:45 INFO | aexpect:0786| [qemu output] (Process terminated with
status 0)
10/11 16:28:46 DEBUG| kvm_vm:1849| VM is down
10/11 16:28:46 DEBUG| virt_vm:0524| Found/Verified IP 172.16.1.141 for VM
intranator NIC 0
10/11 16:28:46 DEBUG| remote:0194| Login command: 'ssh -o
UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22
[email protected]'
10/11 16:28:46 DEBUG|env_proces:0512| (address cache) DHCP lease OK:
00:1b:21:00:7b:2c --> 172.16.1.220
10/11 16:28:48 INFO | job:0210| GOOD
virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.deploy_tests.intranator
virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.deploy_tests.intranator
timestamp=1349965728 localtime=Oct 11 16:28:48 completed
successfully
10/11 16:28:48 INFO | job:0210| END GOOD
virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.deploy_tests.intranator
virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.deploy_tests.intranator
timestamp=1349965728 localtime=Oct 11 16:28:48
10/11 16:28:48 DEBUG| base_job:0349| Persistent state client._record_indent
now set to 1
10/11 16:28:48 DEBUG| base_job:0376| Persistent state client.unexpected_reboot
deleted
10/11 16:28:48 INFO | control:0115| Installing virtual machine intranator2
10/11 16:28:48 INFO |params_han:0040| Inspecting the constructed dictionaries
from the cartesian config.
10/11 16:28:48 INFO |params_han:0047| dict 1:
qemu_kvm_business_server.no_9p_export.smallpages.no_pci_assignable.raw.virtio_blk.smp2.virtio_net.Linux.Business.Server.official.install
10/11 16:28:48 INFO |params_han:0040| Inspecting the constructed dictionaries
from the cartesian config.
10/11 16:28:48 INFO |params_han:0047| dict 1:
qemu_kvm_business_server.no_9p_export.smallpages.no_pci_assignable.raw.virtio_blk.smp2.virtio_net.Linux.Business.Server.official.install
10/11 16:28:48 INFO |utils_misc:1596| Test 1:
raw.virtio_blk.smp2.virtio_net.Business.Server.official.install
10/11 16:28:48 DEBUG| job:0572| Test has timeout: 14400 sec.
10/11 16:28:48 INFO | job:0210| START
virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.install.intranator2
virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.install.intranator2
timestamp=1349965728 timeout=14400 localtime=Oct 11 16:28:48
10/11 16:28:48 DEBUG| base_job:0349| Persistent state client._record_indent
now set to 2
10/11 16:28:48 DEBUG| base_job:0349| Persistent state client.unexpected_reboot
now set to
('virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.install.intranator2',
'virt.kvm.raw.virtio_blk.smp2.virtio_net.Business.Server.official.install.intranator2')
10/11 16:28:48 DEBUG| job:0533| Waiting for pid 29033 for 14400 seconds
10/11 16:28:48 ERROR|logging_ma:0584| ** Message: pygobject_register_sinkfunc
is deprecated (GstObject)
10/11 16:28:48 INFO | ovirt:0014| ovirtsdk module not present, please
install it
10/11 16:28:48 DEBUG| virt:0039| Test parameters:
10/11 16:28:48 DEBUG| virt:0043| additional_deployment_dir =
/mnt/local/tmp/pyftpdlib-0.7.0
...
10/11 16:28:48 DEBUG| virt:0043| vnc_autoport = yes
10/11 16:28:48 DEBUG|env_proces:0332| KVM version: 3.5.5-2.fc17.x86_64
10/11 16:28:48 DEBUG|env_proces:0354| KVM userspace version: 1.0
10/11 16:28:48 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'stop'
10/11 16:28:48 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'cont'
10/11 16:28:48 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:41 ---> 172.16.1.141 to: 02:00:00:00:00:41 --->
172.16.1.141
10/11 16:28:48 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:40 ---> 172.17.1.141 to: 02:00:00:00:00:40 --->
172.17.1.141
10/11 16:28:49 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:41 ---> 172.16.1.141 to: 02:00:00:00:00:41 --->
172.16.1.141
10/11 16:28:49 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:40 ---> 172.17.1.141 to: 02:00:00:00:00:40 --->
172.17.1.141
10/11 16:28:49 DEBUG| virt_vm:0444| VM params in env don't match requested,
restarting.
10/11 16:28:49 DEBUG| kvm_vm:1806| Destroying VM with PID 28669
10/11 16:28:49 DEBUG| kvm_vm:1812| Trying to shutdown VM with shell command
10/11 16:28:49 DEBUG| virt_vm:0524| Found/Verified IP 172.16.1.141 for VM
intranator NIC 0
10/11 16:28:49 DEBUG| remote:0194| Login command: 'ssh -o
UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22
[email protected]'
10/11 16:28:50 DEBUG| kvm_vm:1821| Shutdown command sent; waiting for VM to
go down
10/11 16:29:11 INFO | aexpect:0786| [qemu output] (Process terminated with
status 0)
10/11 16:29:12 DEBUG| kvm_vm:1825| VM is down
10/11 16:29:12 DEBUG| kvm_vm:1451| Comparing expected MD5 sum with MD5 sum
of first MB of ISO file...
10/11 16:29:12 DEBUG| kvm_vm:1470| Hashes match
10/11 16:29:12 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:41 ---> 172.16.1.141 to: 02:00:00:00:00:41 --->
172.16.1.141
10/11 16:29:12 DEBUG| kvm_vm:1508| Adding VM intranator NIC ifname t0-pmZemN
to bridge br0
10/11 16:29:12 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:40 ---> 172.17.1.141 to: 02:00:00:00:00:40 --->
172.17.1.141
10/11 16:29:12 INFO | kvm_vm:1516| VM intranator NIC ifname t1-Fx1VaN was
already added to bridge br0, skipping...
10/11 16:29:13 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:41 ---> 172.16.1.141 to: 02:00:00:00:00:41 --->
172.16.1.141
10/11 16:29:13 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:40 ---> 172.17.1.141 to: 02:00:00:00:00:40 --->
172.17.1.141
10/11 16:29:13 INFO | kvm_vm:1627| Running qemu command (reformatted):
10/11 16:29:13 INFO | kvm_vm:1629| /usr/bin/qemu-kvm
10/11 16:29:13 INFO | kvm_vm:1629| -S
10/11 16:29:13 INFO | kvm_vm:1629| -name 'intranator'
10/11 16:29:13 INFO | kvm_vm:1629| -nodefaults
10/11 16:29:13 INFO | kvm_vm:1629| -chardev
socket,id=hmp_id_hmp1,path=/tmp/monitor-hmp1-20121010-151707-SxsvEDPV,server,nowait
10/11 16:29:13 INFO | kvm_vm:1629| -mon
chardev=hmp_id_hmp1,mode=readline
10/11 16:29:13 INFO | kvm_vm:1629| -chardev
socket,id=serial_id_serial1,path=/tmp/serial-serial1-20121010-151707-SxsvEDPV,server,nowait
10/11 16:29:13 INFO | kvm_vm:1629| -device
isa-serial,chardev=serial_id_serial1
10/11 16:29:13 INFO | kvm_vm:1629| -chardev
socket,id=seabioslog_id_20121010-151707-SxsvEDPV,path=/tmp/seabios-20121010-151707-SxsvEDPV,server,nowait
10/11 16:29:13 INFO | kvm_vm:1629| -device
isa-debugcon,chardev=seabioslog_id_20121010-151707-SxsvEDPV,iobase=0x402
10/11 16:29:13 INFO | kvm_vm:1629| -drive
file='/dev/ramdisk_intranator/BusinessServer_32_intranator',if=none,cache=none,id=virtio0
10/11 16:29:13 INFO | kvm_vm:1629| -device virtio-blk-pci,drive=virtio0
10/11 16:29:13 INFO | kvm_vm:1629| -device
virtio-net-pci,netdev=ideIuRuk,mac='02:00:00:00:00:41',id='idDCu4RE'
10/11 16:29:13 INFO | kvm_vm:1629| -netdev tap,id=ideIuRuk,fd=20
10/11 16:29:13 INFO | kvm_vm:1629| -device
virtio-net-pci,netdev=idHhIF4k,mac='02:00:00:00:00:40',id='idkvCbs4'
10/11 16:29:13 INFO | kvm_vm:1629| -netdev tap,id=idHhIF4k,fd=24
10/11 16:29:13 INFO | kvm_vm:1629| -m 1024
10/11 16:29:13 INFO | kvm_vm:1629| -smp 2,cores=1,threads=1,sockets=2
10/11 16:29:13 INFO | kvm_vm:1629| -cpu 'Nehalem'
10/11 16:29:13 INFO | kvm_vm:1629| -drive
file='/mnt/local/isos/intranator_5_4_7.iso',media=cdrom,index=1
10/11 16:29:13 INFO | kvm_vm:1629| -vnc :0
10/11 16:29:13 INFO | kvm_vm:1629| -vga std
10/11 16:29:13 INFO | kvm_vm:1629| -rtc
base=utc,clock=host,driftfix=none
10/11 16:29:13 INFO | kvm_vm:1629| -boot order=cdn,once=dcn,menu=off
10/11 16:29:13 INFO | kvm_vm:1629| -enable-kvm
10/11 16:29:13 INFO | aexpect:0786| [qemu output] qemu-kvm: -netdev
tap,id=idHhIF4k,fd=24: TUNGETIFF ioctl() failed: Inappropriate ioctl for device
10/11 16:29:13 INFO | aexpect:0786| [qemu output] TUNSETOFFLOAD ioctl()
failed: Inappropriate ioctl for device
10/11 16:29:14 DEBUG| kvm_vm:1736| VM appears to be alive with PID 29139
10/11 16:29:14 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'info
cpus'
10/11 16:29:14 DEBUG|kvm_monito:0338| (monitor hmp1) Response to 'info cpus'
10/11 16:29:14 DEBUG|kvm_monito:0340| (monitor hmp1) * CPU #0:
pc=0x00000000000ffff0 thread_id=29145
10/11 16:29:14 DEBUG|kvm_monito:0340| (monitor hmp1) CPU #1:
pc=0x00000000000ffff0 thread_id=29146
10/11 16:29:14 DEBUG| kvm_vm:1764| Add log: seabios-intranator.log
10/11 16:29:14 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'cont'
10/11 16:29:14 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:52 ---> 172.16.1.172 to: 02:00:00:00:00:52 --->
172.16.1.172
10/11 16:29:14 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:51 ---> 172.17.1.172 to: 02:00:00:00:00:51 --->
172.17.1.172
10/11 16:29:14 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:52 ---> 172.16.1.172 to: 02:00:00:00:00:52 --->
172.16.1.172
10/11 16:29:14 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:51 ---> 172.17.1.172 to: 02:00:00:00:00:51 --->
172.17.1.172
10/11 16:29:14 DEBUG| virt_vm:0444| VM params in env don't match requested,
restarting.
10/11 16:29:14 DEBUG| kvm_vm:1451| Comparing expected MD5 sum with MD5 sum
of first MB of ISO file...
10/11 16:29:14 DEBUG| kvm_vm:1470| Hashes match
10/11 16:29:14 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:52 ---> 172.16.1.172 to: 02:00:00:00:00:52 --->
172.16.1.172
10/11 16:29:14 DEBUG| kvm_vm:1508| Adding VM intranator2 NIC ifname
t0-nEZp4k to bridge br0
10/11 16:29:14 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:51 ---> 172.17.1.172 to: 02:00:00:00:00:51 --->
172.17.1.172
10/11 16:29:14 INFO | kvm_vm:1516| VM intranator2 NIC ifname t1-OGUxAI was
already added to bridge br0, skipping...
10/11 16:29:14 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:52 ---> 172.16.1.172 to: 02:00:00:00:00:52 --->
172.16.1.172
10/11 16:29:14 DEBUG| virt_vm:0604| (address cache) Updating static cache
entry from: 02:00:00:00:00:51 ---> 172.17.1.172 to: 02:00:00:00:00:51 --->
172.17.1.172
10/11 16:29:14 INFO | kvm_vm:1627| Running qemu command (reformatted):
10/11 16:29:14 INFO | kvm_vm:1629| /usr/bin/qemu-kvm
10/11 16:29:14 INFO | kvm_vm:1629| -S
10/11 16:29:14 INFO | kvm_vm:1629| -name 'intranator2'
10/11 16:29:14 INFO | kvm_vm:1629| -nodefaults
10/11 16:29:14 INFO | kvm_vm:1629| -chardev
socket,id=hmp_id_hmp1,path=/tmp/monitor-hmp1-20121010-171114-E8dDy1dH,server,nowait
10/11 16:29:14 INFO | kvm_vm:1629| -mon
chardev=hmp_id_hmp1,mode=readline
10/11 16:29:14 INFO | kvm_vm:1629| -chardev
socket,id=serial_id_serial1,path=/tmp/serial-serial1-20121010-171114-E8dDy1dH,server,nowait
10/11 16:29:14 INFO | kvm_vm:1629| -device
isa-serial,chardev=serial_id_serial1
10/11 16:29:14 INFO | kvm_vm:1629| -chardev
socket,id=seabioslog_id_20121010-171114-E8dDy1dH,path=/tmp/seabios-20121010-171114-E8dDy1dH,server,nowait
10/11 16:29:14 INFO | kvm_vm:1629| -device
isa-debugcon,chardev=seabioslog_id_20121010-171114-E8dDy1dH,iobase=0x402
10/11 16:29:14 INFO | kvm_vm:1629| -drive
file='/dev/ramdisk_intranator2/BusinessServer_32_intranator2',if=none,cache=none,id=virtio0
10/11 16:29:14 INFO | kvm_vm:1629| -device virtio-blk-pci,drive=virtio0
10/11 16:29:14 INFO | kvm_vm:1629| -device
virtio-net-pci,netdev=idl8yZNc,mac='02:00:00:00:00:52',id='id9gHKgM'
10/11 16:29:14 INFO | kvm_vm:1629| -netdev tap,id=idl8yZNc,fd=24
10/11 16:29:14 INFO | kvm_vm:1629| -device
virtio-net-pci,netdev=idjGrywq,mac='02:00:00:00:00:51',id='iduPFR0R'
10/11 16:29:14 INFO | kvm_vm:1629| -netdev tap,id=idjGrywq,fd=37
10/11 16:29:14 INFO | kvm_vm:1629| -m 1024
10/11 16:29:14 INFO | kvm_vm:1629| -smp 2,cores=1,threads=1,sockets=2
10/11 16:29:14 INFO | kvm_vm:1629| -cpu 'Nehalem'
10/11 16:29:14 INFO | kvm_vm:1629| -drive
file='/mnt/local/isos/intranator_5_4_7.iso',media=cdrom,index=1
10/11 16:29:14 INFO | kvm_vm:1629| -vnc :1
10/11 16:29:14 INFO | kvm_vm:1629| -vga std
10/11 16:29:14 INFO | kvm_vm:1629| -rtc
base=utc,clock=host,driftfix=none
10/11 16:29:14 INFO | kvm_vm:1629| -boot order=cdn,once=dcn,menu=off
10/11 16:29:14 INFO | kvm_vm:1629| -enable-kvm
10/11 16:29:14 INFO | aexpect:0786| [qemu output] qemu-kvm: -netdev
tap,id=idjGrywq,fd=37: TUNGETIFF ioctl() failed: Inappropriate ioctl for device
10/11 16:29:14 INFO | aexpect:0786| [qemu output] TUNSETOFFLOAD ioctl()
failed: Inappropriate ioctl for device
10/11 16:29:15 DEBUG| kvm_vm:1736| VM appears to be alive with PID 29227
10/11 16:29:15 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'info
cpus'
10/11 16:29:15 DEBUG|kvm_monito:0338| (monitor hmp1) Response to 'info cpus'
10/11 16:29:15 DEBUG|kvm_monito:0340| (monitor hmp1) * CPU #0:
pc=0x00000000000ffff0 thread_id=29230
10/11 16:29:15 DEBUG|kvm_monito:0340| (monitor hmp1) CPU #1:
pc=0x00000000000ffff0 thread_id=29231
10/11 16:29:16 DEBUG| kvm_vm:1764| Add log: seabios-intranator2.log
10/11 16:29:16 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'cont'
10/11 16:29:16 INFO | virt:0104| Running function: steps.run_steps()
10/11 16:29:16 WARNI|env_proces:0551| VM 'intranator2' failed to produce a
screendump
10/11 16:29:16 DEBUG|kvm_monito:0188| (monitor hmp1) Sending command 'cont'
10/11 16:29:16 INFO | steps:0214| # Generated by Step Maker...
Best regards
Plamen
_______________________________________________
Autotest-kernel mailing list
[email protected]
https://www.redhat.com/mailman/listinfo/autotest-kernel
