Attachment 872542 Details for Bug 751937 – autotest debug info

autotest debug info

virt.qemu.smp_4.4096m.repeat1.Host_RHEL.7.0.qcow2.ide.up.e1000.RHEL.7.0.x86_64.iofuzz.DEBUG (text/plain), 13.47 KB, created by mazhang on 2014-03-10 02:26:25 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: mazhang

Created: 2014-03-10 02:26:25 UTC

Size: 13.47 KB

patch

obsolete

>03/08 06:36:32 DEBUG|   aexpect:1407| Sending command: echo -e '\0277' | dd of=/dev/port seek=34594 bs=1 count=1
>03/08 06:36:32 DEBUG|   aexpect:1407| Sending command: echo $?
>03/08 06:36:32 DEBUG|    iofuzz:0035| outb(0x802e, 0x92)
>03/08 06:36:32 DEBUG|   aexpect:1407| Sending command: echo -e '\0222' | dd of=/dev/port seek=32814 bs=1 count=1
>03/08 06:36:33 DEBUG|   aexpect:1407| Sending command: echo $?
>03/08 06:36:33 DEBUG|    iofuzz:0035| outb(0xf141, 0x3f)
>03/08 06:36:33 DEBUG|   aexpect:1407| Sending command: echo -e '\077' | dd of=/dev/port seek=61761 bs=1 count=1
>03/08 06:36:33 DEBUG|   aexpect:1407| Sending command: echo $?
>03/08 06:36:34 DEBUG|    iofuzz:0035| outb(0xc04a, 0x2d)
>03/08 06:36:34 DEBUG|   aexpect:1407| Sending command: echo -e '\055' | dd of=/dev/port seek=49226 bs=1 count=1
>03/08 06:36:34 DEBUG|   aexpect:1407| Sending command: echo $?
>03/08 06:36:35 DEBUG|    iofuzz:0035| outb(0xf956, 0x20)
>03/08 06:36:35 DEBUG|   aexpect:1407| Sending command: echo -e '\040' | dd of=/dev/port seek=63830 bs=1 count=1
>03/08 06:37:35 DEBUG|    iofuzz:0041| Timeout expired while waiting for shell command to complete: "echo -e '\\040' | dd of=/dev/port seek=63830 bs=1 count=1"    (output: '')
>03/08 06:37:40 DEBUG|    iofuzz:0078| Session is not responsive
>03/08 06:37:40 DEBUG|    iofuzz:0080| VM is alive, try to re-login
>03/08 06:37:40 DEBUG|   virt_vm:0898| Attempting to log into 'virt-tests-vm1' (timeout 10s)
>03/08 06:37:40 DEBUG|   virt_vm:0667| Found/Verified IP 10.66.107.131 for VM virt-tests-vm1 NIC 0
>03/08 06:37:40 DEBUG|    remote:0219| Login command: 'ssh -o UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22 root@10.66.107.131'
>03/08 06:37:43 DEBUG|   virt_vm:0150| general protection fault: 0000 [#1] SMP 
>[133046.753031] Modules linked in: nf_conntrack_netbios_ns nf_conntrack_broadcast ipt_MASQUERADE ip6t_REJECT ipt_REJECT xt_conntrack ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw iptable_filter ip_tables sg cirrus syscopyarea sysfillrect sysimgblt ttm drm_kms_helper crct10dif_pclmul crc32_pclmul crc32c_intel drm ghash_clmulni_intel i2c_piix4 aesni_intel lrw i2c_core gf128mul glue_helper ablk_helper cryptd serio_raw mperf pcspkr xfs libcrc32c sd_mod crc_t10dif crct10dif_common ata_generic pata_acpi e1000 ata_piix libata floppy dm_mirror dm_region_hash dm_log dm_mod
>[133046.753031] CPU: 1 PID: 19402 Comm: kworker/1:2 Not tainted 3.10.0-104.el7.x86_64 #1
>[133046.753031] Hardware name: Red Hat KVM, BIOS Bochs 01/01/2011
>[133046.753031] Workqueue: xfs-log/dm-1 xfs_log_worker [xfs]
>[133046.753031] task: ffff880136d14c90 ti: ffff880138768000 task.ti: ffff880138768000
>[133046.753031] RIP: 0010:[<ffffffffa010376e>]  [<ffffffffa010376e>] xfs_fs_writable+0xe/0x30 [xfs]
>[133046.753031] RSP: 0018:ffff880138769dd8  EFLAGS: 00010246
>[133046.753031] RAX: 0000000000000000 RBX: ffff880037169000 RCX: dead000000200200
>[133046.753031] RDX: e77f880037169400 RSI: 00000000501c501a RDI: ffff880036c69000
>[133046.753031] RBP: ffff880138769dd8 R08: ffff880037169030 R09: dffeaba5f6769028
>[133046.753031] R10: dffeaba5f6769028 R11: 0000000000000001 R12: ffff8800af1cbb00
>[133046.753031] R13: ffff88013fc93dc0 R14: ffff88013fc9cd00 R15: 0000000000000040
>[133046.753031] FS:  0000000000000000(0000) GS:ffff88013fc80000(0000) knlGS:0000000000000000
>[133046.753031] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>[133046.753031] CR2: 000000000273c400 CR3: 00000000018de000 CR4: 00000000000406e0
>[133046.753031] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>[133046.753031] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>[133046.753031] Stack:
>[133046.753031]  ffff880138769e00 ffffffffa014defa ffff880036c69000 ffff8800af1cbb00
>[133046.753031]  ffff88013fc93dc0 ffff880138769e18 ffffffffa014f676 ffff880037169028
>[133046.753031]  ffff880138769e60 ffffffff8107df7b 000000003fc93dd8 0000000000000000
>[133046.753031] Call Trace:
>[133046.753031]  [<ffffffffa014defa>] xfs_log_need_covered+0x1a/0xc0 [xfs]
>[133046.753031]  [<ffffffffa014f676>] xfs_log_worker+0x16/0x50 [xfs]
>[133046.753031]  [<ffffffff8107df7b>] process_one_work+0x17b/0x460
>[133046.753031]  [<ffffffff8107ed4b>] worker_thread+0x11b/0x400
>[133046.753031]  [<ffffffff8107ec30>] ? rescuer_thread+0x400/0x400
>[133046.753031]  [<ffffffff81085a4f>] kthread+0xcf/0xe0
>[133046.753031]  [<ffffffff81085980>] ? kthread_create_on_node+0x140/0x140
>[133046.753031]  [<ffffffff815fc02c>] ret_from_fork+0x7c/0xb0
>[133046.753031]  [<ffffffff81085980>] ? kthread_create_on_node+0x140/0x140
>[133046.753031] Code: 55 48 89 e5 48 f7 e2 b8 00 20 00 00 5d 48 c1 ea 04 48 81 fa 00 20 00 00 48 0f 46 c2 c3 66 66 66 66 90 48 8b 17 55 31 c0 48 89 e5 <8b> 92 00 03 00 00 85 d2 75 10 31 c0 48 f7 87 60 02 00 00 10 00 
>[133046.753031] RIP  [<ffffffffa010376e>] xfs_fs_writable+0xe/0x30 [xfs]
>[133046.753031]  RSP <ffff880138769dd8>
>03/08 06:37:43 DEBUG|    iofuzz:0084| Could not re-login, reboot the guest
>03/08 06:37:43 INFO |     error:0103| Context: rebooting 'virt-tests-vm1'
>03/08 06:37:43 DEBUG|qemu_monit:0267| (monitor qmpmonitor1) Sending command 'system_reset' 
>03/08 06:37:43 DEBUG|qemu_monit:1352| Send command: {'execute': 'system_reset', 'id': 'U1MUcaZo'}
>03/08 06:37:44 INFO |   qemu_vm:3166| RESET QMP event received
>03/08 06:37:44 INFO |     error:0085| Context: rebooting 'virt-tests-vm1' --> logging in after reboot
>03/08 06:37:44 DEBUG|   virt_vm:0898| Attempting to log into 'virt-tests-vm1' (timeout 240s)
>03/08 06:37:44 DEBUG|   virt_vm:0667| Found/Verified IP 10.66.107.131 for VM virt-tests-vm1 NIC 0
>03/08 06:37:44 DEBUG|    remote:0219| Login command: 'ssh -o UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22 root@10.66.107.131'
>03/08 06:37:46 DEBUG|   virt_vm:0150| general protection fault: 0000 [#1] SMP 
>[133046.753031] Modules linked in: nf_conntrack_netbios_ns nf_conntrack_broadcast ipt_MASQUERADE ip6t_REJECT ipt_REJECT xt_conntrack ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw iptable_filter ip_tables sg cirrus syscopyarea sysfillrect sysimgblt ttm drm_kms_helper crct10dif_pclmul crc32_pclmul crc32c_intel drm ghash_clmulni_intel i2c_piix4 aesni_intel lrw i2c_core gf128mul glue_helper ablk_helper cryptd serio_raw mperf pcspkr xfs libcrc32c sd_mod crc_t10dif crct10dif_common ata_generic pata_acpi e1000 ata_piix libata floppy dm_mirror dm_region_hash dm_log dm_mod
>[133046.753031] CPU: 1 PID: 19402 Comm: kworker/1:2 Not tainted 3.10.0-104.el7.x86_64 #1
>[133046.753031] Hardware name: Red Hat KVM, BIOS Bochs 01/01/2011
>[133046.753031] Workqueue: xfs-log/dm-1 xfs_log_worker [xfs]
>[133046.753031] task: ffff880136d14c90 ti: ffff880138768000 task.ti: ffff880138768000
>[133046.753031] RIP: 0010:[<ffffffffa010376e>]  [<ffffffffa010376e>] xfs_fs_writable+0xe/0x30 [xfs]
>[133046.753031] RSP: 0018:ffff880138769dd8  EFLAGS: 00010246
>[133046.753031] RAX: 0000000000000000 RBX: ffff880037169000 RCX: dead000000200200
>[133046.753031] RDX: e77f880037169400 RSI: 00000000501c501a RDI: ffff880036c69000
>[133046.753031] RBP: ffff880138769dd8 R08: ffff880037169030 R09: dffeaba5f6769028
>[133046.753031] R10: dffeaba5f6769028 R11: 0000000000000001 R12: ffff8800af1cbb00
>[133046.753031] R13: ffff88013fc93dc0 R14: ffff88013fc9cd00 R15: 0000000000000040
>[133046.753031] FS:  0000000000000000(0000) GS:ffff88013fc80000(0000) knlGS:0000000000000000
>[133046.753031] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>[133046.753031] CR2: 000000000273c400 CR3: 00000000018de000 CR4: 00000000000406e0
>[133046.753031] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>[133046.753031] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>[133046.753031] Stack:
>[133046.753031]  ffff880138769e00 ffffffffa014defa ffff880036c69000 ffff8800af1cbb00
>[133046.753031]  ffff88013fc93dc0 ffff880138769e18 ffffffffa014f676 ffff880037169028
>[133046.753031]  ffff880138769e60 ffffffff8107df7b 000000003fc93dd8 0000000000000000
>[133046.753031] Call Trace:
>[133046.753031]  [<ffffffffa014defa>] xfs_log_need_covered+0x1a/0xc0 [xfs]
>[133046.753031]  [<ffffffffa014f676>] xfs_log_worker+0x16/0x50 [xfs]
>[133046.753031]  [<ffffffff8107df7b>] process_one_work+0x17b/0x460
>[133046.753031]  [<ffffffff8107ed4b>] worker_thread+0x11b/0x400
>[133046.753031]  [<ffffffff8107ec30>] ? rescuer_thread+0x400/0x400
>[133046.753031]  [<ffffffff81085a4f>] kthread+0xcf/0xe0
>[133046.753031]  [<ffffffff81085980>] ? kthread_create_on_node+0x140/0x140
>[133046.753031]  [<ffffffff815fc02c>] ret_from_fork+0x7c/0xb0
>[133046.753031]  [<ffffffff81085980>] ? kthread_create_on_node+0x140/0x140
>[133046.753031] Code: 55 48 89 e5 48 f7 e2 b8 00 20 00 00 5d 48 c1 ea 04 48 81 fa 00 20 00 00 48 0f 46 c2 c3 66 66 66 66 90 48 8b 17 55 31 c0 48 89 e5 <8b> 92 00 03 00 00 85 d2 75 10 31 c0 48 f7 87 60 02 00 00 10 00 
>[133046.753031] RIP  [<ffffffffa010376e>] xfs_fs_writable+0xe/0x30 [xfs]
>[133046.753031]  RSP <ffff880138769dd8>
>03/08 06:37:46 ERROR|      virt:0155| Test failed: VMDeadKernelCrashError: VM is dead due to a kernel crash, see debug/serial log for details
>03/08 06:37:46 INFO |env_proces:0251| Video creation failed for vm virt-tests-vm1: gstreamer-python library was not found
>03/08 06:37:46 DEBUG|   qemu_vm:2339| Destroying VM virt-tests-vm1 (PID 14201)
>03/08 06:37:46 DEBUG|   qemu_vm:2239| Shutting down VM virt-tests-vm1 (shell)
>03/08 06:37:46 DEBUG|   virt_vm:0667| Found/Verified IP 10.66.107.131 for VM virt-tests-vm1 NIC 0
>03/08 06:37:46 DEBUG|    remote:0219| Login command: 'ssh -o UserKnownHostsFile=/dev/null -o PreferredAuthentications=password -p 22 root@10.66.107.131'
>03/08 06:37:49 DEBUG|   qemu_vm:2251| Client process terminated    (status: 255,    output: 'ssh: connect to host 10.66.107.131 port 22: No route to host\n')
>03/08 06:37:49 DEBUG|   qemu_vm:2349| VM virt-tests-vm1 failed to go down (shell)
>03/08 06:37:49 DEBUG|   qemu_vm:2353| Ending VM virt-tests-vm1 process (monitor)
>03/08 06:37:49 DEBUG|qemu_monit:0267| (monitor qmpmonitor1) Sending command 'quit' 
>03/08 06:37:49 DEBUG|qemu_monit:1352| Send command: {'execute': 'quit', 'id': 's0gjv3QT'}
>03/08 06:37:49 INFO |   aexpect:0907| [qemu output] (Process terminated with status 0)
>03/08 06:37:49 DEBUG|   qemu_vm:2365| VM virt-tests-vm1 down (monitor)
>03/08 06:37:49 DEBUG| utils_net:0636| Host does not support OpenVSwitch: Missing command: ovs-vswitchd
>03/08 06:37:49 DEBUG|qemu_stora:0392| Checking image file /root/staf-kvm-devel/autotest-devel/client/tests/virt/shared/data/images/RHEL-Server-7.0-64.qcow2
>03/08 06:37:49 DEBUG|     utils:0109| Running '/root/staf-kvm-devel/autotest-devel/client/tests/virt/qemu/qemu-img info /root/staf-kvm-devel/autotest-devel/client/tests/virt/shared/data/images/RHEL-Server-7.0-64.qcow2'
>03/08 06:37:49 DEBUG|     utils:0109| Running '/root/staf-kvm-devel/autotest-devel/client/tests/virt/qemu/qemu-img check /root/staf-kvm-devel/autotest-devel/client/tests/virt/shared/data/images/RHEL-Server-7.0-64.qcow2'
>03/08 06:37:50 ERROR|      test:0414| Exception escaping from test:
>Traceback (most recent call last):
>  File "/root/staf-kvm-devel/autotest-devel/client/shared/test.py", line 411, in _exec
>    _call_test_function(self.execute, *p_args, **p_dargs)
>  File "/root/staf-kvm-devel/autotest-devel/client/shared/test.py", line 830, in _call_test_function
>    raise error.UnhandledTestFail(e)
>UnhandledTestFail: Unhandled VMDeadKernelCrashError: VM is dead due to a kernel crash, see debug/serial log for details    [context: rebooting 'virt-tests-vm1' --> logging in after reboot]
>Traceback (most recent call last):
>  File "/root/staf-kvm-devel/autotest-devel/client/shared/test.py", line 823, in _call_test_function
>    return func(*args, **dargs)
>  File "/root/staf-kvm-devel/autotest-devel/client/shared/test.py", line 291, in execute
>    postprocess_profiled_run, args, dargs)
>  File "/root/staf-kvm-devel/autotest-devel/client/shared/test.py", line 209, in _call_run_once
>    *args, **dargs)
>  File "/root/staf-kvm-devel/autotest-devel/client/shared/test.py", line 313, in run_once_profiling
>    self.run_once(*args, **dargs)
>  File "/root/staf-kvm-devel/autotest-devel/client/tests/virt/virt.py", line 139, in run_once
>    run_func(self, params, env)
>  File "/root/staf-kvm-devel/autotest-devel/client/tests/virt/tests/iofuzz.py", line 132, in run_iofuzz
>    fuzz(session, inst)
>  File "/root/staf-kvm-devel/autotest-devel/client/tests/virt/tests/iofuzz.py", line 85, in fuzz
>    session = vm.reboot(method="system_reset")
>  File "/root/staf-kvm-devel/autotest-devel/client/shared/error.py", line 141, in new_fn
>    return fn(*args, **kwargs)
>  File "/root/staf-kvm-devel/autotest-devel/client/tests/virt/virttest/qemu_vm.py", line 3178, in reboot
>    return self.wait_for_login(nic_index, timeout=timeout)
>  File "/root/staf-kvm-devel/autotest-devel/client/tests/virt/virttest/virt_vm.py", line 905, in wait_for_login
>    self.verify_alive()
>  File "/root/staf-kvm-devel/autotest-devel/client/tests/virt/virttest/qemu_vm.py", line 160, in verify_alive
>    self.verify_kernel_crash()
>  File "/root/staf-kvm-devel/autotest-devel/client/tests/virt/virttest/virt_vm.py", line 798, in verify_kernel_crash
>    raise VMDeadKernelCrashError(match.group(0))
>VMDeadKernelCrashError: VM is dead due to a kernel crash, see debug/serial log for details
>

Actions: View

Attachments on bug 751937: 532435 | 864949 | 872542