Bug 1751722

Nir, this crash is seen with the 4.3.6. Has anything changed in the way that the __DIRECT_IO_TEST__ file is updated?

Clearing the needinfo

RCA:
The size going negative is when two consecutive truncates on the __DIRECT_IO_TEST__ file (coming from open with O_TRUNC) happened in the following sequence:

1. Size of the file at the beginning - 512b
2. First truncate on a given mount truncated the file to size 0. Delta size = final size - initial size = 0 - 512 = -512.
3. Xattrop is now sent with -512. And file size had been 512. So 512 + (-512) = 0. Final on-disk size at the end of this truncate is 0.
But shard translator in the truncate fop callback continues to cache 512 as the file size.
4. Then a second truncate (again to size 0) is sent, without a lookup or stat preceding it. So the size in cache is believed to be true.
Delta size = final size - initial size = 0 - 512 = -512. (here initial size should have been 0 but it is wrongly assumed to be 512).
So an xattrop is sent with -512. So 0 - 512 = 0xfffffffffffffe00

And this is what we see in the getfattr output of the file:

[root@rhsqa-grafton8 ~]# getfattr -d -m . -e hex /gluster_bricks/data/data/__DIRECT_IO_TEST__ 
getfattr: Removing leading '/' from absolute path names
# file: gluster_bricks/data/data/__DIRECT_IO_TEST__
security.selinux=0x73797374656d5f753a6f626a6563745f723a676c7573746572645f627269636b5f743a733000
trusted.afr.dirty=0x000000000000000000000000
trusted.gfid=0xe8235ee2ea374f0a9e54853db2781f93
trusted.gfid2path.69693d0e1876710b=0x30303030303030302d303030302d303030302d303030302d3030303030303030303030312f5f5f4449524543545f494f5f544553545f5f
trusted.glusterfs.shard.block-size=0x0000000004000000
trusted.glusterfs.shard.file-size=0xfffffffffffffe00000000000000000000000000000000010000000000000000

More evidence in wireshark output. Will paste it here tomorrow for the sake of completeness (my laptop's freezing at some point when i try to load the pcap file which is huge in wireshark)

NOTE:
+++++

Part of the reason why we hit this crash now is because truncate codepath in shard had largely remained untested. With the newly introduced block-size detection code in rhv/ovirt, which primarily opens the file __DIRECT_IO_TEST__ with O_TRUNC and performs io on it, the truncate fop path is now getting exercised frequently.

-Krutika

I think what we do is easy to reproduce like this:

   for bs in 1 512 4096; do
       dd if=/dev/zero of=/path/to/testfile bs=$bs count=1 oflag=direct conv=fsync
   done

We stop when dd succeeds, but I don't think it matter for testing gluster.

(In reply to Sahina Bose from comment #3)
> Nir, this crash is seen with the 4.3.6. Has anything changed in the way that
> the __DIRECT_IO_TEST__ file is updated?

Yes, this file was always empty before 4.3.6. We used it like this:

    dd if=/dev/zero of=/path bs=4096 count=0 oflag=direct conv=fsync

Verifying that we can do open() with O_DIRECT on the filesystem.

Now we actually so some I/O to detect the capabilities of the filesystem
as explained in comment 6.

Krutika, it seems that the new code for detecting block size in 4.3.6
is triggering a crash in current gluster version, so I think we should
disable it in  oVirt 4.3.6 until a gluster fix is released.

What do you think?

(In reply to Nir Soffer from comment #8)
> Krutika, it seems that the new code for detecting block size in 4.3.6
> is triggering a crash in current gluster version, so I think we should
> disable it in  oVirt 4.3.6 until a gluster fix is released.
> 
> What do you think?

Yes, this sounds like the right thing to do.

(In reply to Krutika Dhananjay from comment #5)
> RCA:
> The size going negative is when two consecutive truncates on the
> __DIRECT_IO_TEST__ file (coming from open with O_TRUNC) happened in the
> following sequence:
> 
> 1. Size of the file at the beginning - 512b

Did you reproduce this with storage with sector size of 512 or 4096?

On 4k storage I don't think we can have such file, unless there is 
another bug in gluster.

What vdsm does is equivalent to:

out=$1

for bs in 1 512 4096; do
    if dd if=/dev/zero bs=$bs count=1 of=$out oflag=direct conv=fsync; then
        echo $bs
        exit 0
    fi
done

echo "cannot use direct I/O" > &2
exit 1

On storage that does not support direct I/O the result is:

$ sh detect-block-size.sh /tmp/foo
dd: failed to open '/tmp/foo': Invalid argument
dd: failed to open '/tmp/foo': Invalid argument
dd: failed to open '/tmp/foo': Invalid argument
cannot use direct I/O

$ ls -lht /tmp/foo 
-rw-rw-r--. 1 nsoffer nsoffer 0 Sep 19 19:46 /tmp/foo

On storage with sector size of 512:

$ sh detect-block-size.sh /var/tmp/foo
dd: error writing '/var/tmp/foo': Invalid argument
1+0 records in
0+0 records out
0 bytes copied, 0.000392325 s, 0.0 kB/s
1+0 records in
1+0 records out
512 bytes copied, 0.0601933 s, 8.5 kB/s
512

$ ls -lht /var/tmp/foo
-rw-rw-r--. 1 nsoffer nsoffer 512 Sep 19 19:48 /var/tmp/foo

On storage with sector size of 4096:

$ sh detect-block-size.sh /var/tmp/vdsm-storage/mount.mount-4k/foo
dd: error writing '/var/tmp/vdsm-storage/mount.mount-4k/foo': Invalid argument
1+0 records in
0+0 records out
0 bytes copied, 0.000116669 s, 0.0 kB/s
dd: error writing '/var/tmp/vdsm-storage/mount.mount-4k/foo': Invalid argument
1+0 records in
0+0 records out
0 bytes copied, 0.000115637 s, 0.0 kB/s
1+0 records in
1+0 records out
4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00483159 s, 848 kB/s
4096

Created attachment 1616830 [details]
Script simulating vdsm block size detection

(In reply to Nir Soffer from comment #10)
> (In reply to Krutika Dhananjay from comment #5)
> > RCA:
> > The size going negative is when two consecutive truncates on the
> > __DIRECT_IO_TEST__ file (coming from open with O_TRUNC) happened in the
> > following sequence:
> > 
> > 1. Size of the file at the beginning - 512b
> 
> Did you reproduce this with storage with sector size of 512 or 4096?

Just checked Bipin's setup and it's 512.

[root@rhsqa-grafton8 ~]# blockdev --getss /dev/mapper/gluster_vg_sdb-gluster_lv_vmstore
512
[root@rhsqa-grafton8 ~]# blockdev --getss /dev/mapper/gluster_vg_sdb-gluster_lv_data 
512
[root@rhsqa-grafton8 ~]# blockdev --getss /dev/mapper/gluster_vg_sdd-gluster_lv_engine 
512

> 
> On 4k storage I don't think we can have such file, unless there is 
> another bug in gluster.
> 
> What vdsm does is equivalent to:
> 
> out=$1
> 
> for bs in 1 512 4096; do
>     if dd if=/dev/zero bs=$bs count=1 of=$out oflag=direct conv=fsync; then
>         echo $bs
>         exit 0
>     fi
> done
> 
> echo "cannot use direct I/O" > &2
> exit 1
> 
> On storage that does not support direct I/O the result is:
> 
> $ sh detect-block-size.sh /tmp/foo
> dd: failed to open '/tmp/foo': Invalid argument
> dd: failed to open '/tmp/foo': Invalid argument
> dd: failed to open '/tmp/foo': Invalid argument
> cannot use direct I/O
> 
> $ ls -lht /tmp/foo 
> -rw-rw-r--. 1 nsoffer nsoffer 0 Sep 19 19:46 /tmp/foo
> 
> On storage with sector size of 512:
> 
> $ sh detect-block-size.sh /var/tmp/foo
> dd: error writing '/var/tmp/foo': Invalid argument
> 1+0 records in
> 0+0 records out
> 0 bytes copied, 0.000392325 s, 0.0 kB/s
> 1+0 records in
> 1+0 records out
> 512 bytes copied, 0.0601933 s, 8.5 kB/s
> 512
> 
> $ ls -lht /var/tmp/foo
> -rw-rw-r--. 1 nsoffer nsoffer 512 Sep 19 19:48 /var/tmp/foo
> 
> On storage with sector size of 4096:
> 
> $ sh detect-block-size.sh /var/tmp/vdsm-storage/mount.mount-4k/foo
> dd: error writing '/var/tmp/vdsm-storage/mount.mount-4k/foo': Invalid
> argument
> 1+0 records in
> 0+0 records out
> 0 bytes copied, 0.000116669 s, 0.0 kB/s
> dd: error writing '/var/tmp/vdsm-storage/mount.mount-4k/foo': Invalid
> argument
> 1+0 records in
> 0+0 records out
> 0 bytes copied, 0.000115637 s, 0.0 kB/s
> 1+0 records in
> 1+0 records out
> 4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00483159 s, 848 kB/s
> 4096

I'm able to recreate the bug now with some simple steps.



[root@dhcp35-215 ~]# gluster v info
 
Volume Name: rep
Type: Replicate
Volume ID: 8cad61f0-4770-4e75-b97c-7bab6cb0fa67
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 3 = 3
Transport-type: tcp
Bricks:
Brick1: kdhananjay:/bricks/1
Brick2: kdhananjay:/bricks/2
Brick3: kdhananjay:/bricks/3
Options Reconfigured:
performance.strict-o-direct: on
server.event-threads: 4
client.event-threads: 4
cluster.choose-local: off
user.cifs: off
features.shard: on
cluster.shd-wait-qlength: 10000
cluster.shd-max-threads: 8
cluster.locking-scheme: granular
cluster.data-self-heal-algorithm: full
cluster.server-quorum-type: server
cluster.quorum-type: auto
cluster.eager-lock: enable
network.remote-dio: off
performance.low-prio-threads: 32
performance.io-cache: off
performance.read-ahead: off
performance.quick-read: off
transport.address-family: inet
nfs.disable: on
performance.client-io-threads: on


SET MD_CACHE_TIMEOUT TO A SLIGHTLY HIGH VALUE TO SIMULATE THE RACE:
# gluster volume set rep md-cache-timeout 60

CREATE TWO MOUNTS:
# mount -t glusterfs kdhananjay:/rep /mnt
# mount -t glusterfs kdhananjay:/rep /mnt1

FILL A FILE WITH DATA UPTO 512b
# dd if=/dev/urandom of=/mnt/__DIRECT_IO_TEST__ bs=512 count=1 oflag=direct

STAT THE FILE FROM FIRST MOUNT TO ENSURE 512b IS CACHED AS FILE SIZE IN-MEMORY, NOW TRUNCATE THE FILE TO SIZE 0 FROM SECOND MOUNT; THEN TRUNCATE THE FILE TO 0 FROM THE FIRST MOUNT
# stat /mnt/__DIRECT_IO_TEST__; truncate -s 0 /mnt1/__DIRECT_IO_TEST__; truncate -s 0 /mnt/__DIRECT_IO_TEST__


THE RESULT?
[root@dhcp35-215 ~]# getfattr -d -m . -e hex /bricks/1/__DIRECT_IO_TEST__                                                                                                                     
getfattr: Removing leading '/' from absolute path names                                                                                                                                       
# file: bricks/1/__DIRECT_IO_TEST__                                                                                                                                                           
security.selinux=0x756e636f6e66696e65645f753a6f626a6563745f723a6574635f72756e74696d655f743a733000                                                                                             
trusted.afr.dirty=0x000000000000000000000000                                                                                                                                                  
trusted.gfid=0x3d79268080c241d9bf70039c7ce52c54                                                                                                                                               
trusted.gfid2path.69693d0e1876710b=0x30303030303030302d303030302d303030302d303030302d3030303030303030303030312f5f5f4449524543545f494f5f544553545f5f
trusted.glusterfs.shard.block-size=0x0000000004000000
trusted.glusterfs.shard.file-size=0xfffffffffffffe00000000000000000000000000000000000000000000000000

^^ Size is now negative.

Here's what could have happened from VDSM's perspective in the actual rhhi setup:

1. HOST 1 would have successfully performed 512b write (perhaps followed by a lookup or a stat) and cached 512b as the file size.
2. Now HOST 2 would do the same open + write, wherein the open() part has completed so far with O_TRUNC. SO file size in backend has become 0 due to truncate.
3. Now HOST 1 would try the same open + write for the next block size, but size has changed to 0 already unbeknownst to this mount. It does the truncate (because O_TRUNC) and uses cached value to compute delta. So zero minus 512b ends up being negative 512 in the backend.

Basically there is an interleaving of sub-operations of detect_block_size across multiple mount points. By sub-operations i mean open + truncate + write

Krutika, this makes sense, and explaining the randomness of the failure.

Can you confirm that using a unique file for every host will avoids this
issue?

I'm thinking about this flow:

1. Generate random filename e.g ".prob-cacb3ecf-9445-4638-aa00-af0ae99dc09e"
2. Open the prob file with O_WRONLY |O_DIRECT | O_CREAT | O_SYNC | O_EXCL | O_CLOEXEC
3. Delete the file
4. Use the open fd to detect block size

So the probe file can be accessed only from single host, and we never
truncate it.

Do you see issue with gluster in particular when using shard translator?

Does gluster support O_TMPFILE? this will simplify steps 1-3 to:

    fd = open("/mount/path", O_TMPFILE | O_WRONLY | O_EXCL | O_DIRECT);

(In reply to Nir Soffer from comment #14)
> Krutika, this makes sense, and explaining the randomness of the failure.
> 
> Can you confirm that using a unique file for every host will avoids this
> issue?
> 

Yes, using a unique file for every host would ensure that the cached values in memory are correct
and are not modified by a different client.


> I'm thinking about this flow:
> 
> 1. Generate random filename e.g ".prob-cacb3ecf-9445-4638-aa00-af0ae99dc09e"
> 2. Open the prob file with O_WRONLY |O_DIRECT | O_CREAT | O_SYNC | O_EXCL |
> O_CLOEXEC
> 3. Delete the file
> 4. Use the open fd to detect block size
> 
> So the probe file can be accessed only from single host, and we never
> truncate it.
> 
> Do you see issue with gluster in particular when using shard translator?
> 
> Does gluster support O_TMPFILE? this will simplify steps 1-3 to:
> 
>     fd = open("/mount/path", O_TMPFILE | O_WRONLY | O_EXCL | O_DIRECT);

I think it should work, though I haven't tested it.

-Krutika

(In reply to Krutika Dhananjay from comment #15)
> (In reply to Nir Soffer from comment #14)
> > Does gluster support O_TMPFILE? this will simplify steps 1-3 to:
> > 
> >     fd = open("/mount/path", O_TMPFILE | O_WRONLY | O_EXCL | O_DIRECT);
> 
> I think it should work, though I haven't tested it.

open() fails with ENOTSUP and I could not find the error in /var/log/glusterfs,
so I guess this is not supported in fuse kernel side.
https://sourceforge.net/p/fuse/mailman/message/33646980/

This issue was reproduced 2 times out of many times ( ~40 times )
Nir (oVirt dev) and Krutika helped to RCA this issue.

This issue is seen because of recent changes in oVirt ( detection of storage block size )
lead to discovering a day1 bug with sharding respect to truncate ( Apologies, not well explained !)

If the fixes are not in place, then it would lead to crash most of the times at the field.
As it failed twice in QE env, the issue has got more probability to be hit in customer environment.

Marking this bug as BLOCKER for RHV 4.3.6

Corresponding RHV bugs that fixes the issues are:
https://bugzilla.redhat.com/show_bug.cgi?id=1753901
https://bugzilla.redhat.com/show_bug.cgi?id=1753898

One of the dependent bug is ON_QA and other is on MODIFIED state. Moving this bug to MODIFIED too

The dependent bugs are now ON_QA. moving this bug also to ON_QA

Moving the bug to verified based on the below results:

Version:
=======
glusterfs-3.12.2-47.5.el7rhgs.x86_64
ioprocess-1.3.0-1.el7ev.x86_64
vdsm-4.30.33-1.el7ev.x86_64


1. Complete the RHHI-V deployment
2. Create a RHEL 7.6 template
3. Create 30 vm's using pool 
4. After an hour delete the vm's in the pool
5. Repeat step 3 and step 4 for 3 iteration's 
6. Create vm's using template and ran kernel untar and FIO 

Couldn't see any crash during the test. So moving the bug to verified

@Laura,

This crash is seen only with RHV 4.3.6 internal builds.
This crash was not reported with the previously released version,
so release doc_text is not required for this bug

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-2019:2963