Bug 1536636

Summary: qemu-img commit fails with "block/file-posix.c:1774: find_allocation: Assertion `offs >= start' failed"
Product: Red Hat Enterprise Linux 7 Reporter: Bimal Chollera <bcholler>
Component: qemu-kvm-rhevAssignee: Ademar Reis <areis>
Status: CLOSED ERRATA QA Contact: Longxiang Lyu <lolyu>
Severity: high Docs Contact:
Priority: high    
Version: 7.4CC: bcholler, chayang, coli, cww, jcoscia, juzhang, knoel, lmiksik, lolyu, michen, mjenner, mkalinin, mrezanin, mtessun, ngu, pingl, rhodain, virt-maint, ylavi
Target Milestone: rcKeywords: ZStream
Target Release: ---Flags: juzhang: needinfo-
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: qemu-kvm-rhev-2.12.0-1.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1566369 (view as bug list) Environment:
Last Closed: 2018-11-01 11:04:08 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1566369    

Description Bimal Chollera 2018-01-19 19:30:59 UTC
Description of problem:


A snapshot deletion is executed on a RHV-M environment GUI for VM.

For a offline merge (VM down), in the vdsm logs of the host/hypervisor, the qemu-img commit fails with the following.

~~~
QImgError: cmd=['/usr/bin/taskset', '--cpu-list', '0-31', '/usr/bin/nice', '-n', '19', '/usr/bin/ionice', '-c', '3', '/usr/bin/qemu-img', 'commit', '-p', '-t', 'none', '-b', u'/rhev/data-center/mnt/glusterSD/EXAMPLE-gluster01_rhevm/ab27a13a-7a82-4cf4-86fd-3a6c697ccef9/images/3122bbad-e3d3-446a-90b9-eb6da08dad2a/7fa44a95-2988-4866-924c-329713989ad0', '-f', 'qcow2', u'/rhev/data-center/mnt/glusterSD/EXAMPLE-gluster01_rhevm/ab27a13a-7a82-4cf4-86fd-3a6c697ccef9/images/3122bbad-e3d3-446a-90b9-eb6da08dad2a/8ba82ba8-32ea-4501-95e8-55ef42812c89'], ecode=-6, stdout=, stderr=qemu-img: block/file-posix.c:1774: find_allocation: Assertion `offs >= start' failed.
, message=None
~~~

off_t offs;

~~~
    /*
     * SEEK_DATA cases:
     * D1. offs == start: start is in data
     * D2. offs > start: start is in a hole, next data at offs
     * D3. offs < 0, errno = ENXIO: either start is in a trailing hole
     *                              or start is beyond EOF
     *     If the latter happens, the file has been truncated behind
     *     our back since we opened it.  All bets are off then.
     *     Treating like a trailing hole is simplest.
     * D4. offs < 0, errno != ENXIO: we learned nothing
     */
    offs = lseek(s->fd, start, SEEK_DATA);
    if (offs < 0) {
        return -errno;          /* D3 or D4 */
    }
    assert(offs >= start)
~~~

The image resides on glusterfs.

This assertion failure seems similar to BZ 1451191, except that was relative to a gluster library function, glfs_lseek(), whereas in our case it's in lseek().

A live merge (VM online) fails with the following error:

~~~
libvirtError: internal error: child reported: Kernel does not provide mount namespace: No such file or directory
~~~

Journal logs, the qemu-kvm VM process aborts

~~~
Jan 03 09:53:34 EXAMPLE-host abrt-hook-ccpp[49478]: Process 48766 (qemu-kvm) of user 107 killed by SIGABRT - dumping core
Jan 03 09:53:34 EXAMPLE-host libvirtd[3141]: 2018-01-03 09:53:34.849+0000: 3141: error : qemuMonitorIORead:588 : Unable to read from monitor: Connection reset by peer
Jan 03 09:53:34 EXAMPLE-host libvirtd[3141]: 2018-01-03 09:53:34.853+0000: 3224: error : virProcessRunInMountNamespace:1159 : internal error: child reported: Kernel does not provide mount namespace: No such file or directory
Jan 03 09:53:34 EXAMPLE-host libvirtd[3141]: 2018-01-03 09:53:34.854+0000: 3224: error : virProcessRunInMountNamespace:1159 : internal error: child reported: Kernel does not provide mount namespace: No such file or directory
Jan 03 09:53:34 EXAMPLE-host libvirtd[3141]: 2018-01-03 09:53:34.937+0000: 3141: error : qemuAgentIO:652 : internal error: End of file from agent monitor
~~~

The images involved are:

~~~
u'top_id':  u'8ba82ba8-32ea-4501-95e8-55ef42812c89', 
u'base_id': u'7fa44a95-2988-4866-924c-329713989ad0'
~~~

The 8ba82ba8-32ea-4501-95e8-55ef42812c89 is a raw image and 7fa44a95-2988-4866-924c-329713989ad0 is cow

~~~
# su vdsm -s /bin/sh -c 'qemu-img check /rhev/data-center/mnt/glusterSD/EXAMPLE-gluster01_rhevm/ab27a13a-7a82-4cf4-86fd-3a6c697ccef9/images/3122bbad-e3d3-446a-90b9-eb6da08dad2a/8ba82ba8-32ea-4501-95e8-55ef42812c89'
Leaked cluster 17 refcount=1 reference=0

1 leaked clusters were found on the image.
This means waste of disk space, but no harm to data.
5983/327680 = 1.83% allocated, 12.32% fragmented, 0.00% compressed clusters
Image end offset: 393543680
~~~


Version-Release number of selected component (if applicable):

~~~
ovirt-engine-4.1.6.2-0.1.el7.noarch

Red Hat Virtualization Host 4.1 (el7.4) - 3.10.0-693.2.2.el7.x86_64

vdsm-4.19.31-1.el7ev.x86_64
qemu-kvm-rhev-2.9.0-16.el7_4.5.x86_64
libvirt-daemon-3.2.0-14.el7_4.3.x86_64
glusterfs-3.8.4-18.6.el7rhgs.x86_64
~~~


How reproducible:

100% on end user system.

Unable to reproduce on inhouse lab system.

Steps to Reproduce:
1.  With RHV delete a VM snapshot.  

2.
3.

Actual results:

Merge operation fails at qemu-img commit.

Expected results:

Operation should complete without error.

Additional info:

Comment 7 Longxiang Lyu 2018-01-23 09:20:38 UTC
Hi, the following is my interpretation of this bug:
1. a base raw image located on glusterfs.
2. make a qcow2 snapshot(either live or offline) on glusterfs.
3. commit the snapshot to base image.

Is the process above correct?

Comment 14 Longxiang Lyu 2018-02-05 15:03:08 UTC
Fail to reproduce with the following component:
ovirt-engine-4.1.9-0.2.el7.noarch

host:
kernel-3.10.0-693.el7.x86_64
qemu-kvm-rhev-2.9.0-16.el7_4.13
libvirt-daemon-3.2.0-14.el7_4.7.x86_64
vdsm-4.19.45-1.el7ev.x86_64

1. create snapshot and start VM from snapshot.
2. dd inside guest.
3. commit image.
4. boot from base image the check for dd file.

Will downgrade the components for further investigation.

Comment 16 Longxiang Lyu 2018-02-06 05:48:51 UTC
Fail to reproduce in the rhel(3.10.0-693.2.1.el7.x86_64) host with same components as listed in bug:
glusterfs-3.8.4-18.6.el7rhgs.x86_64
libvirt-3.2.0-14.el7_4.3.x86_64
vdsm-4.19.31-1.el7ev.x86_64
qemu-kvm-rhev-2.9.0-16.el7_4.5

reproduce steps(through rhv web UI):
1. make a snapshot of fedora guest.
guest base image is a 20G raw.
2. boot the snapshot.
3. dd inside guest.
8G files created.
4. shutdown guest then do off-line commit.

The commit resulted in no error.

Comment 28 Jeff Cody 2018-04-06 15:52:16 UTC
Upstream patch (accepted in master for 2.12): 
https://lists.nongnu.org/archive/html/qemu-devel/2018-04/msg00105.html

Comment 36 Longxiang Lyu 2018-05-03 04:53:30 UTC
glusterfs version:
glusterfs-server-3.8.4-18.6.el7rhgs.x86_64

glusterfs server and client are the same machine.

1. bug reproduction
qemu version:
qemu-kvm-rhev-2.9.0-16.el7_4.5.x86_64

a. mount the volume
# mount.glusterfs 127.0.0.1:gv0 /mnt/gluster1

b. convert a 7G qcow2 to raw
# qemu-img convert -f qcow2 -O raw -p /mnt/gluster1/rhel75-64-virtio-scsi.qcow2 /mnt/gluster1/disk.raw
qemu-img: block/file-posix.c:1774: find_allocation: Assertion `offs >= start' failed.
Aborted (core dumped)

2. verification of fix
qemu version
qemu-img-rhev-2.12.0-1.el7.x86_64

a. do the conversion
# qemu-img convert -f qcow2 -O raw -p /mnt/gluster1/rhel75-64-virtio-scsi.qcow2 /mnt/gluster1/disk.raw
    (100.00/100%)

mark as VERIFIED then.

Comment 38 errata-xmlrpc 2018-11-01 11:04:08 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:3443