06/28 06:58:25 INFO | test:0279| Test started. Number of iterations: 1 06/28 06:58:25 INFO | test:0282| Executing iteration 1 of 1 06/28 06:58:25 INFO | test:0185| Dropping caches between iterations 06/28 06:58:25 DEBUG| utils:0073| Running 'sync' 06/28 06:58:26 DEBUG| utils:0073| Running 'echo 3 > /proc/sys/vm/drop_caches' 06/28 06:58:26 INFO | test:0185| Dropping caches between iterations 06/28 06:58:26 DEBUG| utils:0073| Running 'sync' 06/28 06:58:27 DEBUG| utils:0073| Running 'echo 3 > /proc/sys/vm/drop_caches' 06/28 06:58:27 INFO | test:0305| Profilers present. Profiling run started 06/28 06:58:27 DEBUG| kvm:0027| Test parameters: 06/28 06:58:27 DEBUG| kvm:0031| address_index = 0 06/28 06:58:27 DEBUG| kvm:0031| address_range_base_mac_r1 = 52:54:00:12:36:20 06/28 06:58:27 DEBUG| kvm:0031| address_range_size_r1 = 32 06/28 06:58:27 DEBUG| kvm:0031| address_ranges = r1 06/28 06:58:27 DEBUG| kvm:0031| cdkey = C3FP4-PJ249-2HM72-Q28H4-P9W83 06/28 06:58:27 DEBUG| kvm:0031| cdrom = /tmp/kvm_autotest_root/isos/windows/winutils.iso 06/28 06:58:27 DEBUG| kvm:0031| convert_ppm_files_to_png_on_error = yes 06/28 06:58:27 DEBUG| kvm:0031| cpu_chk_cmd = echo %NUMBER_OF_PROCESSORS% 06/28 06:58:27 DEBUG| kvm:0031| depend = ['virtlab15.qemu-kvm.qemu-kvm-git.build', 'virtlab15.qemu-kvm.qemu-kvm-git.tests.stable.no_pci_assignable.smallpages.qcow2.ide.acpi.smp2.Windows.Win7.64.rtl8139.install', 'virtlab15.qemu-kvm.qemu-kvm-git.tests.stable.no_pci_assignable.smallpages.qcow2.ide.acpi.smp2.Windows.Win7.64.rtl8139.setup', 'virtlab15.qemu-kvm.qemu-kvm-git.tests.stable.no_pci_assignable.smallpages.qcow2.ide.acpi.smp2.Windows.Win7.64.rtl8139.unattended_install'] 06/28 06:58:27 DEBUG| kvm:0031| display = vnc 06/28 06:58:27 DEBUG| kvm:0031| drift_threshold = 10 06/28 06:58:27 DEBUG| kvm:0031| drift_threshold_single = 3 06/28 06:58:27 DEBUG| kvm:0031| drive_format = ide 06/28 06:58:27 DEBUG| kvm:0031| extra_params = -rtc-td-hack 06/28 06:58:27 DEBUG| kvm:0031| guest_load_command = cmd /c "d:\vlc\vlc -f --loop --no-qt-privacy-ask --no-qt-system-tray d:\ED_1024.avi" 06/28 06:58:27 DEBUG| kvm:0031| guest_load_instances = 2 06/28 06:58:27 DEBUG| kvm:0031| guest_load_stop_command = taskkill /F /IM vlc.exe 06/28 06:58:27 DEBUG| kvm:0031| guest_port_remote_shell = 22 06/28 06:58:27 DEBUG| kvm:0031| host_load_command = bzip2 -c --best /dev/urandom > /dev/null 06/28 06:58:27 DEBUG| kvm:0031| host_load_instances = 8 06/28 06:58:27 DEBUG| kvm:0031| image_format = qcow2 06/28 06:58:27 DEBUG| kvm:0031| image_name = /tmp/kvm_autotest_root/images/win7-64 06/28 06:58:27 DEBUG| kvm:0031| image_size = 20G 06/28 06:58:27 DEBUG| kvm:0031| images = image1 06/28 06:58:27 DEBUG| kvm:0031| keep_screendumps_on_error = yes 06/28 06:58:27 DEBUG| kvm:0031| kill_unresponsive_vms = yes 06/28 06:58:27 DEBUG| kvm:0031| kill_vm = no 06/28 06:58:27 DEBUG| kvm:0031| kill_vm_gracefully = yes 06/28 06:58:27 DEBUG| kvm:0031| main_vm = vm1 06/28 06:58:27 DEBUG| kvm:0031| mem = 1024 06/28 06:58:27 DEBUG| kvm:0031| mem_chk_cmd = wmic memphysical 06/28 06:58:27 DEBUG| kvm:0031| mem_chk_cur_cmd = wmic memphysical 06/28 06:58:27 DEBUG| kvm:0031| migration_iterations = 3 06/28 06:58:27 DEBUG| kvm:0031| name = virtlab15.qemu-kvm.qemu-kvm-git.tests.stable.no_pci_assignable.smallpages.qcow2.ide.acpi.smp2.Windows.Win7.64.rtl8139.timedrift.with_migration 06/28 06:58:27 DEBUG| kvm:0031| nic_mode = tap 06/28 06:58:27 DEBUG| kvm:0031| nic_model = rtl8139 06/28 06:58:27 DEBUG| kvm:0031| nic_script = scripts/qemu-ifup 06/28 06:58:27 DEBUG| kvm:0031| nics = nic1 06/28 06:58:27 DEBUG| kvm:0031| password = 123456 06/28 06:58:27 DEBUG| kvm:0031| pci_assignable = no 06/28 06:58:27 DEBUG| kvm:0031| post_command = python scripts/check_image.py; 06/28 06:58:27 DEBUG| kvm:0031| post_command_noncritical = yes 06/28 06:58:27 DEBUG| kvm:0031| post_command_timeout = 600 06/28 06:58:27 DEBUG| kvm:0031| profilers = kvm_stat 06/28 06:58:27 DEBUG| kvm:0031| qemu_binary = qemu 06/28 06:58:27 DEBUG| kvm:0031| qemu_img_binary = qemu-img 06/28 06:58:27 DEBUG| kvm:0031| reboot_command = shutdown /r /f /t 0 06/28 06:58:27 DEBUG| kvm:0031| redirs = remote_shell 06/28 06:58:27 DEBUG| kvm:0031| remove_image = no 06/28 06:58:27 DEBUG| kvm:0031| screendump_delay = 5 06/28 06:58:27 DEBUG| kvm:0031| screendump_quality = 30 06/28 06:58:27 DEBUG| kvm:0031| screendump_temp_dir = /dev/shm 06/28 06:58:27 DEBUG| kvm:0031| screendump_verbose = no 06/28 06:58:27 DEBUG| kvm:0031| shell_client = nc 06/28 06:58:27 DEBUG| kvm:0031| shell_linesep = \r\n 06/28 06:58:27 DEBUG| kvm:0031| shell_port = 22 06/28 06:58:27 DEBUG| kvm:0031| shell_prompt = ^\w:\\.*>\s*$ 06/28 06:58:27 DEBUG| kvm:0031| shortname = qemu-kvm-git.smp2.Win7.64.timedrift.with_migration 06/28 06:58:27 DEBUG| kvm:0031| shutdown_command = shutdown /s /f /t 0 06/28 06:58:27 DEBUG| kvm:0031| smp = 2 06/28 06:58:27 DEBUG| kvm:0031| start_vm = yes 06/28 06:58:27 DEBUG| kvm:0031| status_test_command = echo %errorlevel% 06/28 06:58:27 DEBUG| kvm:0031| take_regular_screendumps = yes 06/28 06:58:27 DEBUG| kvm:0031| time_command = echo TIME: %date% %time% 06/28 06:58:27 DEBUG| kvm:0031| time_filter_re = (?<=TIME: \w\w\w ).{19}(?=\.\d\d) 06/28 06:58:27 DEBUG| kvm:0031| time_format = %m/%d/%Y %H:%M:%S 06/28 06:58:27 DEBUG| kvm:0031| type = timedrift_with_migration 06/28 06:58:27 DEBUG| kvm:0031| used_cpus = 2 06/28 06:58:27 DEBUG| kvm:0031| used_mem = 512 06/28 06:58:27 DEBUG| kvm:0031| username = Administrator 06/28 06:58:27 DEBUG| kvm:0031| vms = vm1 06/28 06:58:27 DEBUG| kvm:0037| Contents of environment: {'vm__vm1': , 'address_cache': {u'00:00:1a:1a:96:c0': u'10.16.72.32', u'00:1a:64:cb:c4:e6': u'10.16.72.125', u'52:54:00:12:36:20': u'10.16.75.219', u'00:21:5e:55:24:28': u'10.16.72.124', u'52:54:00:12:36:2d': u'10.16.75.10', u'00:1a:64:cb:c5:fb': u'10.16.72.122', u'52:54:00:12:36:2a': u'10.16.74.14', u'52:54:00:12:36:2c': u'10.16.74.203', u'52:54:00:12:36:2b': u'10.16.74.13'}, 'tcpdump': } 06/28 06:58:27 DEBUG|kvm_prepro:0226| Fetching KVM module version... 06/28 06:58:27 DEBUG|kvm_prepro:0235| KVM version: 2.6.33.5-124.fc13.x86_64 06/28 06:58:27 DEBUG|kvm_prepro:0239| Fetching KVM userspace version... 06/28 06:58:28 DEBUG|kvm_prepro:0249| KVM userspace version: 0.12.50 (qemu-kvm-devel) 06/28 06:58:28 DEBUG|kvm_prepro:0052| Preprocessing VM 'vm1'... 06/28 06:58:28 DEBUG|kvm_prepro:0055| VM object found in environment 06/28 06:58:28 DEBUG| kvm_vm:0618| Sending monitor command: help 06/28 06:58:28 DEBUG| kvm_vm:0281| Getting output of 'qemu -help' 06/28 06:58:28 DEBUG| kvm_vm:0281| Getting output of 'qemu -help' 06/28 06:58:28 DEBUG| kvm_vm:0618| Sending monitor command: screendump /usr/local/autotest/results/default/kvm.qemu-kvm-git.smp2.Win7.64.timedrift.with_migration/debug/pre_vm1.ppm 06/28 06:58:28 DEBUG|kvm_prepro:0263| Starting screendump thread 06/28 06:58:28 DEBUG| kvm_vm:0618| Sending monitor command: help 06/28 06:58:28 INFO |kvm_test_u:0056| Trying to log into guest 'vm1', timeout 240s 06/28 06:58:29 DEBUG| kvm_utils:0480| Trying to login with command 'nc 10.16.75.219 22' 06/28 06:58:29 DEBUG| kvm_utils:0519| Got shell prompt -- logged in 06/28 06:58:29 INFO |kvm_test_u:0061| Logged into guest 'vm1' 06/28 06:58:30 INFO |timedrift_:0048| Migrating: iteration 1 of 3... 06/28 06:58:30 DEBUG| kvm_vm:0618| Sending monitor command: help info 06/28 06:58:30 DEBUG| kvm_vm:0670| VM is already down 06/28 06:58:30 DEBUG| kvm_vm:0281| Getting output of 'qemu -help' 06/28 06:58:30 DEBUG| kvm_vm:0532| Running qemu command: /usr/local/autotest/tests/kvm/qemu -name 'vm1' -monitor unix:/tmp/monitor-20100628-065830-CcOu,server,nowait -drive file=/tmp/kvm_autotest_root/images/win7-64.qcow2,if=ide -net nic,vlan=0,model=rtl8139,macaddr=52:54:00:12:36:20 -net tap,vlan=0,script=/usr/local/autotest/tests/kvm/scripts/qemu-ifup,downscript=no -m 1024 -smp 2 -drive file=/tmp/kvm_autotest_root/isos/windows/winutils.iso,index=2,media=cdrom -redir tcp:5000::22 -vnc :1 -rtc-td-hack -incoming tcp:0:5200 06/28 06:58:31 DEBUG| kvm_vm:0618| Sending monitor command: help 06/28 06:58:31 DEBUG| kvm_vm:0564| VM appears to be alive with PID 24439 06/28 06:58:31 DEBUG|kvm_test_u:0146| Migrating with command: migrate -d tcp:localhost:5200 06/28 06:58:31 DEBUG| kvm_vm:0618| Sending monitor command: migrate -d tcp:localhost:5200 06/28 06:58:33 DEBUG| kvm_utils:0835| Waiting for migration to finish... (2.002062 secs) 06/28 06:58:33 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:35 DEBUG| kvm_utils:0835| Waiting for migration to finish... (4.037533 secs) 06/28 06:58:35 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:37 DEBUG| kvm_utils:0835| Waiting for migration to finish... (6.061700 secs) 06/28 06:58:37 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:39 DEBUG| kvm_utils:0835| Waiting for migration to finish... (8.086097 secs) 06/28 06:58:39 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:41 DEBUG| kvm_utils:0835| Waiting for migration to finish... (10.110336 secs) 06/28 06:58:41 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:43 DEBUG| kvm_utils:0835| Waiting for migration to finish... (12.133830 secs) 06/28 06:58:43 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:45 DEBUG| kvm_utils:0835| Waiting for migration to finish... (14.167538 secs) 06/28 06:58:45 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:47 DEBUG| kvm_utils:0835| Waiting for migration to finish... (16.211802 secs) 06/28 06:58:47 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:49 DEBUG| kvm_utils:0835| Waiting for migration to finish... (18.234817 secs) 06/28 06:58:49 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:49 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:49 INFO |kvm_test_u:0163| Migration finished successfully 06/28 06:58:49 DEBUG| kvm_vm:0674| Destroying VM with PID 23959... 06/28 06:58:49 DEBUG| kvm_vm:0693| Trying to kill VM with monitor command... 06/28 06:58:49 DEBUG| kvm_vm:0618| Sending monitor command: quit 06/28 06:58:50 DEBUG|kvm_subpro:0686| (qemu) (Process terminated with status 0) 06/28 06:58:50 DEBUG| kvm_vm:0699| VM is down 06/28 06:58:50 INFO |timedrift_:0051| Logging in after migration... 06/28 06:58:50 DEBUG| kvm_utils:0480| Trying to login with command 'nc 10.16.75.219 22' 06/28 06:58:51 DEBUG| kvm_utils:0519| Got shell prompt -- logged in 06/28 06:58:51 INFO |timedrift_:0055| Logged in after migration 06/28 06:58:51 INFO |timedrift_:0064| Host duration (iteration 1): 21.03 06/28 06:58:51 INFO |timedrift_:0066| Guest duration (iteration 1): 19.00 06/28 06:58:51 INFO |timedrift_:0068| Drift at iteration 1: 2.03 seconds 06/28 06:58:51 INFO |timedrift_:0048| Migrating: iteration 2 of 3... 06/28 06:58:51 DEBUG| kvm_vm:0618| Sending monitor command: help info 06/28 06:58:51 DEBUG| kvm_vm:0670| VM is already down 06/28 06:58:51 DEBUG| kvm_vm:0281| Getting output of 'qemu -help' 06/28 06:58:51 DEBUG| kvm_vm:0532| Running qemu command: /usr/local/autotest/tests/kvm/qemu -name 'vm1' -monitor unix:/tmp/monitor-20100628-065851-hrFm,server,nowait -drive file=/tmp/kvm_autotest_root/images/win7-64.qcow2,if=ide -net nic,vlan=0,model=rtl8139,macaddr=52:54:00:12:36:20 -net tap,vlan=0,script=/usr/local/autotest/tests/kvm/scripts/qemu-ifup,downscript=no -m 1024 -smp 2 -drive file=/tmp/kvm_autotest_root/isos/windows/winutils.iso,index=2,media=cdrom -redir tcp:5000::22 -vnc :0 -rtc-td-hack -incoming tcp:0:5200 06/28 06:58:52 DEBUG| kvm_vm:0618| Sending monitor command: help 06/28 06:58:52 DEBUG| kvm_vm:0564| VM appears to be alive with PID 24484 06/28 06:58:52 DEBUG|kvm_test_u:0146| Migrating with command: migrate -d tcp:localhost:5200 06/28 06:58:52 DEBUG| kvm_vm:0618| Sending monitor command: migrate -d tcp:localhost:5200 06/28 06:58:54 DEBUG| kvm_utils:0835| Waiting for migration to finish... (2.001219 secs) 06/28 06:58:54 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:56 DEBUG| kvm_utils:0835| Waiting for migration to finish... (4.080236 secs) 06/28 06:58:56 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:58:58 DEBUG| kvm_utils:0835| Waiting for migration to finish... (6.104973 secs) 06/28 06:58:58 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:59:00 DEBUG| kvm_utils:0835| Waiting for migration to finish... (8.129411 secs) 06/28 06:59:00 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:59:02 DEBUG| kvm_utils:0835| Waiting for migration to finish... (10.153945 secs) 06/28 06:59:02 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:59:04 DEBUG| kvm_utils:0835| Waiting for migration to finish... (12.178431 secs) 06/28 06:59:04 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:59:06 DEBUG| kvm_utils:0835| Waiting for migration to finish... (14.202489 secs) 06/28 06:59:06 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:59:08 DEBUG| kvm_utils:0835| Waiting for migration to finish... (16.225294 secs) 06/28 06:59:08 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:59:09 DEBUG| kvm_vm:0618| Sending monitor command: info migrate 06/28 06:59:09 INFO |kvm_test_u:0163| Migration finished successfully 06/28 06:59:09 DEBUG| kvm_vm:0674| Destroying VM with PID 24439... 06/28 06:59:09 DEBUG| kvm_vm:0693| Trying to kill VM with monitor command... 06/28 06:59:09 DEBUG| kvm_vm:0618| Sending monitor command: quit 06/28 06:59:09 DEBUG|kvm_subpro:0686| (qemu) (Process terminated with status 0) 06/28 06:59:09 DEBUG| kvm_vm:0699| VM is down 06/28 06:59:09 INFO |timedrift_:0051| Logging in after migration... 06/28 06:59:09 DEBUG| kvm_utils:0480| Trying to login with command 'nc 10.16.75.219 22' 06/28 06:59:10 DEBUG| kvm_utils:0519| Got shell prompt -- logged in 06/28 06:59:10 INFO |timedrift_:0055| Logged in after migration 06/28 06:59:10 INFO |timedrift_:0064| Host duration (iteration 2): 19.08 06/28 06:59:10 INFO |timedrift_:0066| Guest duration (iteration 2): 16.00 06/28 06:59:10 INFO |timedrift_:0068| Drift at iteration 2: 3.08 seconds 06/28 06:59:10 ERROR| kvm:0066| Test failed: Time drift too large at iteration 2: 3.08 seconds 06/28 06:59:10 DEBUG| kvm:0067| Postprocessing on error... 06/28 06:59:10 DEBUG|kvm_prepro:0111| Postprocessing VM 'vm1'... 06/28 06:59:10 DEBUG|kvm_prepro:0114| VM object found in environment 06/28 06:59:10 DEBUG| kvm_vm:0618| Sending monitor command: screendump /usr/local/autotest/results/default/kvm.qemu-kvm-git.smp2.Win7.64.timedrift.with_migration/debug/post_vm1.ppm 06/28 06:59:10 DEBUG|kvm_prepro:0285| Terminating screendump thread... 06/28 06:59:10 DEBUG|kvm_prepro:0296| 'convert_ppm_files_to_png' specified; converting PPM files to PNG format... 06/28 06:59:11 DEBUG|kvm_prepro:0309| 'keep_ppm_files' not specified; removing all PPM files from debug dir... 06/28 06:59:11 DEBUG|kvm_prepro:0324| 'kill_unresponsive_vms' specified; killing all VMs that fail to respond to a remote login request... 06/28 06:59:11 DEBUG| kvm_vm:0618| Sending monitor command: help 06/28 06:59:11 DEBUG| kvm_utils:0480| Trying to login with command 'nc 10.16.75.219 22' 06/28 06:59:12 DEBUG| kvm_utils:0519| Got shell prompt -- logged in 06/28 06:59:12 DEBUG| kvm_vm:0618| Sending monitor command: help 06/28 06:59:12 DEBUG| utils:0073| Running 'cd /usr/local/autotest/tests/kvm; python scripts/check_image.py;' 06/28 06:59:12 DEBUG| utils:0105| [stdout] Checking image with command qemu-img info /tmp/kvm_autotest_root/images/win7-64.qcow2 06/28 06:59:12 DEBUG| utils:0105| [stdout] image: /tmp/kvm_autotest_root/images/win7-64.qcow2 06/28 06:59:12 DEBUG| utils:0105| [stdout] file format: qcow2 06/28 06:59:12 DEBUG| utils:0105| [stdout] virtual size: 20G (21474836480 bytes) 06/28 06:59:12 DEBUG| utils:0105| [stdout] disk size: 7.1G 06/28 06:59:12 DEBUG| utils:0105| [stdout] cluster_size: 65536 06/28 06:59:12 DEBUG| utils:0105| [stdout] Checking image with command qemu-img check /tmp/kvm_autotest_root/images/win7-64.qcow2 06/28 06:59:12 DEBUG| utils:0105| [stdout] No errors were found on the image. 06/28 06:59:12 DEBUG| kvm:0080| Contents of environment: {'vm__vm1': , 'address_cache': {u'00:00:1a:1a:96:c0': u'10.16.72.32', u'00:1a:64:cb:c4:e6': u'10.16.72.125', u'52:54:00:12:36:20': u'10.16.75.219', u'00:21:5e:55:24:28': u'10.16.72.124', u'52:54:00:12:36:2d': u'10.16.75.10', u'00:1a:64:cb:c5:fb': u'10.16.72.122', u'52:54:00:12:36:2a': u'10.16.74.14', u'52:54:00:12:36:2c': u'10.16.74.203', u'52:54:00:12:36:2b': u'10.16.74.13'}, 'tcpdump': } 06/28 06:59:12 INFO |profiler_m:0102| ['iteration.1'] 06/28 06:59:12 ERROR| test:0415| Exception escaping from test: Traceback (most recent call last): File "/usr/local/autotest/common_lib/test.py", line 412, in _exec _call_test_function(self.execute, *p_args, **p_dargs) File "/usr/local/autotest/common_lib/test.py", line 598, in _call_test_function return func(*args, **dargs) File "/usr/local/autotest/common_lib/test.py", line 284, in execute postprocess_profiled_run, args, dargs) File "/usr/local/autotest/common_lib/test.py", line 202, in _call_run_once self.run_once_profiling(postprocess_profiled_run, *args, **dargs) File "/usr/local/autotest/common_lib/test.py", line 308, in run_once_profiling self.run_once(*args, **dargs) File "/usr/local/autotest/tests/kvm/kvm.py", line 61, in run_once run_func(self, params, env) File "/usr/local/autotest/tests/kvm/tests/timedrift_with_migration.py", line 72, in run_timedrift_with_migration "%.2f seconds" % (i + 1, drift)) TestFail: Time drift too large at iteration 2: 3.08 seconds 06/28 06:59:12 DEBUG|logging_ma:0561| Logging subprocess finished 06/28 06:59:12 DEBUG|logging_ma:0561| Logging subprocess finished