Red Hat Bugzilla – Bug 550949
VM cannot stop on read errors with ide block.
Last modified: 2013-01-09 17:09:06 EST
Description of problem: VM cannot stop on read errors with ide block. Version-Release number of selected component (if applicable): # uname -r 2.6.18-182.el5 # rpm -q kvm kvm-83-140.el5 How reproducible: 100% Steps to Reproduce: 1. create a local nfs server in host, then mount localhost:/root/test-nfs /mnt -o rw,soft,timeo=1,retrans=0 cd /mnt qemu-img create test-533390.qcow2 -f qcow2 10G 2. start guest: /usr/libexec/qemu-kvm -rtc-td-hack -no-hpet -usbdevice tablet -cpu qemu64,+sse2 -drive file=rhel5u4-64-virtio-64k.qcow2,if=ide,format=qcow2,cache=off,werror=stop -smp 2 -m 2G -vnc :1 -net nic,macaddr=20:20:20:11:12:56,model=e1000,vlan=0 -net tap,script=/etc/qemu-ifup,vlan=0 -monitor stdio -drive file=/mnt/test-533390.qcow2,if=ide,format=qcow2,cache=off,werror=stop 3. in guest: fdisk /dev/hdb mkfs.ext3 /dev/hdb1 dd if=/dev/hdb1 of=/dev/null 4. in host: service nfs stop 5. In host dmesg: nfs: server localhost not responding, timed out Actual results: In qemu monitor (qemu)info status VM status: running Expected results: In qemu monitor (qemu)info status VM status: paused Additional info: This problem does not exist in kvm-83-139.el5 & kvm-83-105.el5_4.13, it is a regression bug. This problem also does not exist with virtio block.
Proposed as blocker since its a regression.
Tested with kvm-83-142.el5, this problem does not exist.
There was no relevant diff between those two versions, are you sure the VM accessed the disk and not read the guest cache during the time nfs was down?
(In reply to comment #3) > There was no relevant diff between those two versions, are you sure the VM > accessed the disk and not read the guest cache during the time nfs was down? Retest this with "dd if=/dev/hdb1 of=/dev/null iflag=direct" which will bypass buffer cache for about 10 times, vm can stop for read errors. With "dd if=/dev/hdb1 of=/dev/null", vm cannot stop sometimes. Disk /dev/hdb: 10.7 GB. Dor, need your comments.
(In reply to comment #4) > (In reply to comment #3) > > There was no relevant diff between those two versions, are you sure the VM > > accessed the disk and not read the guest cache during the time nfs was down? > > Retest this with "dd if=/dev/hdb1 of=/dev/null iflag=direct" which will bypass > buffer cache for about 10 times, vm can stop for read errors. > > With "dd if=/dev/hdb1 of=/dev/null", vm cannot stop sometimes. Maybe it is stuck on nfs request, you can specify 'hard' nfs mount in order to get errors. Also use strace for qemu to get the read error value > > Disk /dev/hdb: 10.7 GB. > > Dor, need your comments.
(In reply to comment #5) > (In reply to comment #4) > > (In reply to comment #3) > > > There was no relevant diff between those two versions, are you sure the VM > > > accessed the disk and not read the guest cache during the time nfs was down? > > > > Retest this with "dd if=/dev/hdb1 of=/dev/null iflag=direct" which will bypass > > buffer cache for about 10 times, vm can stop for read errors. > > > > With "dd if=/dev/hdb1 of=/dev/null", vm cannot stop sometimes. > > Maybe it is stuck on nfs request, you can specify 'hard' nfs mount in order to > get errors. Also use strace for qemu to get the read error value > Tried hard mount nfs, after nfs is down, strace for qemu: 8023 pread(13, <unfinished ...> 7517 write(21, "\16\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128 <unfinished ...> 7509 rt_sigtimedwait([USR2], <unfinished ...> 7517 <... write resumed> ) = 128 7514 rt_sigtimedwait([RT_6], <unfinished ...> 7512 rt_sigtimedwait([RT_6], <unfinished ...> 7499 select(21, [0 4 6 10 18 20], [], [], {0, 998000} <unfinished ...> 7517 rt_sigtimedwait([ALRM IO], <unfinished ...> 7514 <... rt_sigtimedwait resumed> 0x431daea0) = -1 EAGAIN (Resource temporarily unavailable) 7512 <... rt_sigtimedwait resumed> 0x427d9ea0) = -1 EAGAIN (Resource temporarily unavailable) 7514 ioctl(17, 0xae80 <unfinished ...> 7499 <... select resumed> ) = 1 (in [20], left {0, 998000}) 7512 ioctl(16, 0xae80 <unfinished ...> 7499 read(20, "\16\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128 7499 rt_sigaction(SIGALRM, NULL, {0x4079b0, ~[KILL STOP RTMIN RT_1], SA_RESTORER, 0x3593c0e7c0}, 8) = 0 7499 write(5, "\0", 1) = 1 7499 read(20, 0x7ffff7462ff0, 128) = -1 EAGAIN (Resource temporarily unavailable)
I'm not sure this is the right descriptor, please provide ls -la /proc/`pgrep qemu`/fd You should only track the fds of the image files, it can be configured for strace. Please do it before you stop the nfs server. Note that we expect other error than EAgain.
(In reply to comment #7) > I'm not sure this is the right descriptor, please provide ls -la /proc/`pgrep > qemu`/fd > You should only track the fds of the image files, it can be configured for > strace. Please do it before you stop the nfs server. > Note that we expect other error than EAgain. 1. mount localhost:/root/test-nfs /mnt -o rw,hard 2. start guest: # /usr/libexec/qemu-kvm -rtc-td-hack -no-hpet -usbdevice tablet -cpu qemu64,+sse2 -drive file=rhel5u4-64-virtio-64k.qcow2,if=ide,format=qcow2,cache=off,werror=stop -smp 2 -m 2G -net nic,macaddr=20:20:20:11:12:56,model=e1000,vlan=0 -net tap,script=/etc/qemu-ifup,vlan=0 -monitor stdio -drive file=/mnt/test-533390.qcow2,if=ide,format=qcow2,cache=off,werror=stop 3. in guest: for i in `seq 10`;do dd if=/dev/hdb1 of=/dev/null;done 4. # ls -la /proc/`pgrep qemu`/fd total 0 dr-x------ 2 root root 0 Jan 5 05:15 . dr-xr-xr-x 5 root root 0 Jan 5 05:12 .. lrwx------ 1 root root 64 Jan 5 05:15 0 -> /dev/pts/2 lrwx------ 1 root root 64 Jan 5 05:15 1 -> /dev/pts/2 lr-x------ 1 root root 64 Jan 5 05:15 10 -> pipe:[21300] l-wx------ 1 root root 64 Jan 5 05:15 11 -> pipe:[21300] lrwx------ 1 root root 64 Jan 5 05:15 12 -> /root/rhel5u4-64-virtio-64k.qcow2 lrwx------ 1 root root 64 Jan 5 05:15 13 -> /mnt/test-533390.qcow2 lrwx------ 1 root root 64 Jan 5 05:15 14 -> socket:[21311] lrwx------ 1 root root 64 Jan 5 05:15 15 -> socket:[21313] lrwx------ 1 root root 64 Jan 5 05:15 16 -> anon_inode:kvm-vcpu lrwx------ 1 root root 64 Jan 5 05:15 17 -> anon_inode:kvm-vcpu lrwx------ 1 root root 64 Jan 5 05:15 18 -> anon_inode:[eventfd] lrwx------ 1 root root 64 Jan 5 05:15 19 -> anon_inode:[eventfd] lrwx------ 1 root root 64 Jan 5 05:15 2 -> /dev/pts/2 lr-x------ 1 root root 64 Jan 5 05:15 20 -> pipe:[21329] l-wx------ 1 root root 64 Jan 5 05:15 21 -> pipe:[21329] lrwx------ 1 root root 64 Jan 5 05:15 3 -> /dev/kvm lr-x------ 1 root root 64 Jan 5 05:15 4 -> pipe:[21254] l-wx------ 1 root root 64 Jan 5 05:15 5 -> pipe:[21254] lrwx------ 1 root root 64 Jan 5 05:15 6 -> /dev/net/tun lrwx------ 1 root root 64 Jan 5 05:15 7 -> anon_inode:kvm-vm lrwx------ 1 root root 64 Jan 5 05:15 8 -> /dev/ksm lrwx------ 1 root root 64 Jan 5 05:15 9 -> anon_inode:ksm-sma 5. # strace -p 19732 -e trace=desc 2> a.txt 6. service nfs stop result: got no error for file descriptor 13 in strace file when nfs is down. tail -f a.txt |grep 13 lseek(13, 285933568, SEEK_SET) = 285933568 read(13, "\200\0\0\0\21\f\0\0\200\0\0\0\21\r\0\0\200\0\0\0\21\16\0\0\200\0\0\0\21\17\0\0"..., 16384) = 16384 lseek(13, 285949952, SEEK_SET) = 285949952 read(13, "\200\0\0\0\21-\0\0\200\0\0\0\21.\0\0\200\0\0\0\21/\0\0\200\0\0\0\0210\0\0"..., 16384) = 16384 lseek(13, 285966336, SEEK_SET) = 285966336 read(13, "\200\0\0\0\21N\0\0\200\0\0\0\21O\0\0\200\0\0\0\21P\0\0\200\0\0\0\21Q\0\0"..., 16384) = 16384 lseek(13, 285982720, SEEK_SET) = 285982720 read(13, "\200\0\0\0\21o\0\0\200\0\0\0\21p\0\0\200\0\0\0\21q\0\0\200\0\0\0\21r\0\0"..., 16384) = 16384
The command being executed is dd if=/dev/hdb1 of=/dev/null which means it's reading from the disk, not writing to it. So you'd need 'rerror=stop' as the drive option as well. Can you let me know which version works and which does not? I'm confused by some conflicting information above. Also, you mention virtio works -- in the sense this same command makes the VM pause if you use if=virtio for the -drive argument for the same version and the same command? (Also note: ,retrans=1 was needed here to get the mount; retrans=0 wasn't allowed)
In RHEL 5, there is only werror (which takes effect for both reads and writes). About the versions, I'm confused, too. It was said that kvm-83-142.el5 is fine, so was this wrong and this bug actually does exist in the current version?
(In reply to comment #10) > In RHEL 5, there is only werror (which takes effect for both reads and writes). > > About the versions, I'm confused, too. It was said that kvm-83-142.el5 is fine, > so was this wrong and this bug actually does exist in the current version? Please ignore the comment about the kvm version, this bug can not be always seen when using this test method, I just saw it in kvm-83-140 and it may exist in every version.
The main issue here is the test method - there are no read errors coming from strace. Something is wrong with the test scenario itself
Try again with soft mount (-o hard will prevent read errors from being reported to programs) 1. mount localhost:/root/test-nfs /mnt -o rw,soft,timeo=1,retrans=0 2. start guest: # /usr/libexec/qemu-kvm -rtc-td-hack -no-hpet -usbdevice tablet -cpu qemu64,+sse2 -drive file=rhel5u4-64-virtio-64k.qcow2,if=ide,format=qcow2,cache=off,werror=stop -smp 2 -m 2G -net nic,macaddr=20:20:20:11:12:56,model=e1000,vlan=0 -net tap,script=/etc/qemu-ifup,vlan=0 -monitor stdio -drive file=/mnt/test-533390.qcow2,if=ide,format=qcow2,cache=off,werror=stop 3. in guest: for i in `seq 10`;do dd if=/dev/hdb1 of=/dev/null;done 4. # ls -la /proc/`pgrep qemu`/fd total 0 dr-x------ 2 root root 0 Jan 5 05:15 . dr-xr-xr-x 5 root root 0 Jan 5 05:12 .. lrwx------ 1 root root 64 Jan 5 05:15 0 -> /dev/pts/2 lrwx------ 1 root root 64 Jan 5 05:15 1 -> /dev/pts/2 lr-x------ 1 root root 64 Jan 5 05:15 10 -> pipe:[21300] l-wx------ 1 root root 64 Jan 5 05:15 11 -> pipe:[21300] lrwx------ 1 root root 64 Jan 5 05:15 12 -> /root/rhel5u4-64-virtio-64k.qcow2 lrwx------ 1 root root 64 Jan 5 05:15 13 -> /mnt/test-533390.qcow2 5. # strace -p 4376 -e trace=desc 2> a.txt 6. service nfs stop result: guest is still in running status. tail -f a.txt |grep 13 read(13, "\200\0\0\0\17\277\0\0\200\0\0\0\17\300\0\0\200\0\0\0\17\301\0\0\200\0\0\0\17\302\0\0"..., 16384) = 16384 lseek(13, 259833856, SEEK_SET) = 259833856 read(13, "\200\0\0\0\17\340\0\0\200\0\0\0\17\341\0\0\200\0\0\0\17\342\0\0\200\0\0\0\17\343\0\0"..., 16384) = 16384 lseek(13, 268500992, SEEK_SET) = 268500992 read(13, 0x15744400, 16384) = -1 EIO (Input/output error) lseek(13, 268500992, SEEK_SET) = 268500992 read(13, 0x15744400, 16384) = -1 EIO (Input/output error)
Try with kvm-83-215.el5 using the same steps of bug description, cannot reproduce it, so close it. cmd: # /usr/libexec/qemu-kvm -no-hpet -no-kvm-pit-reinjection -usbdevice tablet -rtc-td-hack -startdate now -name rhel56-64 -smp 2 -m 2G -net nic,vlan=1,macaddr=20:20:20:11:11:19,model=virtio -net tap,vlan=1,script=/etc/qemu-ifup -drive file=rhel56-64-virtio.qcow2,media=disk,if=ide,cache=none,format=qcow2,werror=stop -vnc :11 -cpu qemu64,+sse2 -M rhel5.6.0 -notify all -balloon none -monitor stdio -drive file=/mnt/test1.qcow2,media=disk,if=ide,cache=none,format=qcow2,werror=stop