ztest failed due to assertion while trying to acquire mutex in zio_add_child

[mmaybee]

System information

Type	Version/Name
Distribution Name	Ubuntu
Distribution Version	18.04
Linux Kernel	5.4.0-72
Architecture	x86
ZFS Version	2.1++
Commit	fc16b4f

Describe the problem you're observing

A ztest run fails with an assertion error when attempting to obtain a hold on an invalid mutex. The panic is occurring in zio_add_child() when we attempt to obtain the io_lock for the "parent" io structure that is being passed in (pio). The error code (EINVAL) implies that the lock is not initialized. In this context (the vdev_rebuild_thread) the parent IO is coming from spa_txg_zio[]:

        zio_nowait(zio_read(spa->spa_txg_zio[txg & TXG_MASK], spa, &blk,
            abd_alloc(psize, B_FALSE), psize, vdev_rebuild_cb, vr,
            ZIO_PRIORITY_REBUILD, ZIO_FLAG_RAW | ZIO_FLAG_CANFAIL |
            ZIO_FLAG_RESILVER, NULL));

Note that this is an array for IO structure pointers. Each element of the array is associated with a transaction group, and the IO structure is freed once that group has synced to disk. The one chosen above corresponds to the "current" txg. It is obtained above within the context of an open transaction:

        dmu_tx_t *tx = dmu_tx_create_dd(spa_get_dsl(spa)->dp_mos_dir);
        VERIFY0(dmu_tx_assign(tx, TXG_WAIT));
        uint64_t txg = dmu_tx_get_txg(tx);

Now note that this transaction (tx) is committed prior to the read request:

        dmu_tx_commit(tx);

        vr->vr_scan_offset[txg & TXG_MASK] = start + size;
        vr->vr_pass_bytes_issued += size;
        vr->vr_rebuild_phys.vrp_bytes_issued += size;

        zio_nowait(zio_read(spa->spa_txg_zio[txg & TXG_MASK], spa, &blk,

It therefor seems possible (if unlikely) that the txg associated with the tx could "sync" before we issue the read. If this happens, the IO structure in the spa_txg_zio[] array will be freed, and the io_lock field "cleared", resulting in this error.

Describe how to reproduce the problem

This problem has only been seen once with ztest to my knowledge.

Include any warning/errors/backtraces from the system logs

ztest.out

pthread_mutex_lock(&mp->m_lock) == 0 (0x16 == 0)
ASSERT at kernel.c:208:mutex_enter()/sbin/ztest(+0x95f3)[0x5574d3c145f3]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12980)[0x7f85d3900980]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7f85d353bfb7]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x141)[0x7f85d353d921]
/lib/libzfs_core.so.3(+0x76f5)[0x7f85d40c76f5]
/lib/libzpool.so.4(mutex_enter+0x58)[0x7f85d431c878]
/lib/libzpool.so.4(zio_add_child+0x58)[0x7f85d44c0b48]
/lib/libzpool.so.4(+0x1e505d)[0x7f85d44c105d]
/lib/libzpool.so.4(zio_read+0xa1)[0x7f85d44c1ac1]
/lib/libzpool.so.4(+0x1b51e7)[0x7f85d44911e7]
/lib/libzpool.so.4(+0x1b53d7)[0x7f85d44913d7]
/lib/libzpool.so.4(+0x1b5765)[0x7f85d4491765]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7f85d38f56db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f85d361e71f]

ztest.gdb

[Current thread is 1 (Thread 0x7f85caf3f700 (LWP 91032))]
*
* Backtrace
*
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007f85d353d921 in __GI_abort () at abort.c:79
#2  0x00007f85d40c76f5 in libspl_assertf (file=0x7f85d456ca00 "kernel.c", func=0x7f85d456d118 <__FUNCTION__.12813> "mutex_enter", line=208, format=<optimized out>) at assert.c:45
#3  0x00007f85d431c878 in mutex_enter (mp=mp@entry=0x5574d55e9c78) at kernel.c:208
#4  0x00007f85d44c0b48 in zio_add_child (pio=0x5574d55e98b0, cio=0x7f85b8014c00) at ../../module/zfs/zio.c:614
#5  0x00007f85d44c105d in zio_create (pio=pio@entry=0x5574d55e98b0, spa=spa@entry=0x5574d55c1ca0, txg=<optimized out>, bp=bp@entry=0x7f85caf3dcf0, data=data@entry=0x7f85b8001e40, lsize=lsize@entry=1536, psize=<optimized out>, done=<optimized out>, private=<optimized out>, type=<optimized out>, priority=<optimized out>, flags=<optimized out>, vd=<optimized out>, offset=<optimized out>, zb=<optimized out>, stage=<optimized out>, pipeline=(ZIO_STAGE_READ_BP_INIT | ZIO_STAGE_READY | ZIO_STAGE_VDEV_IO_START | ZIO_STAGE_VDEV_IO_DONE | ZIO_STAGE_VDEV_IO_ASSESS | ZIO_STAGE_CHECKSUM_VERIFY | ZIO_STAGE_DONE)) at ../../module/zfs/zio.c:859
#6  0x00007f85d44c1ac1 in zio_read (pio=0x5574d55e98b0, spa=spa@entry=0x5574d55c1ca0, bp=bp@entry=0x7f85caf3dcf0, data=0x7f85b8001e40, size=size@entry=1536, done=done@entry=0x7f85d4490720 <vdev_rebuild_cb>, private=0x5574d5633670, priority=ZIO_PRIORITY_REBUILD, flags=25165960, zb=0x0) at ../../module/zfs/zio.c:1085
#7  0x00007f85d44911e7 in vdev_rebuild_range (vr=vr@entry=0x5574d5633670, start=start@entry=269120512, size=size@entry=1536) at ../../module/zfs/vdev_rebuild.c:602
#8  0x00007f85d44913d7 in vdev_rebuild_ranges (vr=vr@entry=0x5574d5633670) at ../../module/zfs/vdev_rebuild.c:647
#9  0x00007f85d4491765 in vdev_rebuild_thread (arg=0x5574d5630710) at ../../module/zfs/vdev_rebuild.c:874
#10 0x00007f85d38f56db in start_thread (arg=0x7f85caf3f700) at pthread_create.c:463
#11 0x00007f85d361e71f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
*

[mmaybee]

Additional validation of this theory can be seen in this AddressSanitizer output from a ztest run:

=================================================================
==89578==ERROR: AddressSanitizer: heap-use-after-free on address 0x61900033a1e8 at pc 0x7fb4a0f45983 bp 0x7fb4986069e0 sp 0x7fb4986069d0
READ of size 8 at 0x61900033a1e8 thread T303
    #0 0x7fb4a0f45982 in zio_create ../../module/zfs/zio.c:881
    #1 0x7fb4a0f46643 in zio_read ../../module/zfs/zio.c:1110
    #2 0x7fb4a0ee02f1 in vdev_rebuild_range ../../module/zfs/vdev_rebuild.c:605
    #3 0x7fb4a0ee078a in vdev_rebuild_ranges ../../module/zfs/vdev_rebuild.c:650
    #4 0x7fb4a0ee0e8a in vdev_rebuild_thread ../../module/zfs/vdev_rebuild.c:877
    #5 0x7fb4a00766da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
    #6 0x7fb49fd9f71e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x12171e)

0x61900033a1e8 is located 616 bytes inside of 1128-byte region [0x619000339f80,0x61900033a3e8)
freed by thread T178 here:
    #0 0x7fb4a18457a8 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xde7a8)
    #1 0x7fb4a0f49bda in zio_wait ../../module/zfs/zio.c:2252
    #2 0x7fb4a0ddd097 in spa_sync ../../module/zfs/spa.c:9241
    #3 0x7fb4a0e10e4d in txg_sync_thread ../../module/zfs/txg.c:597
    #4 0x7fb4a00766da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)

previously allocated by thread T178 here:
    #0 0x7fb4a1845b40 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xdeb40)
    #1 0x7fb4a0f3648c in umem_alloc ../../lib/libspl/include/umem.h:92
    #2 0x7fb4a0f374f1 in umem_cache_alloc ../../lib/libspl/include/umem.h:182
    #3 0x7fb4a0f44d99 in zio_create ../../module/zfs/zio.c:823
    #4 0x7fb4a0f45b2d in zio_null ../../module/zfs/zio.c:911
    #5 0x7fb4a0ddd0a8 in spa_sync ../../module/zfs/spa.c:9242
    #6 0x7fb4a0e10e4d in txg_sync_thread ../../module/zfs/txg.c:597
    #7 0x7fb4a00766da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)

Thread T303 created by T178 here:
    #0 0x7fb4a179ed2f in __interceptor_pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.4+0x37d2f)
    #1 0x7fb4a0c1b6a2 in zk_thread_create /export/home/delphix/zfs/lib/libzpool/kernel.c:121
    #2 0x7fb4a0ee1b55 in vdev_rebuild_initiate_sync ../../module/zfs/vdev_rebuild.c:256
    #3 0x7fb4a0d7b86c in dsl_sync_task_sync ../../module/zfs/dsl_synctask.c:248
    #4 0x7fb4a0d5b24a in dsl_pool_sync ../../module/zfs/dsl_pool.c:794
    #5 0x7fb4a0dd41c2 in spa_sync_iterate_to_convergence ../../module/zfs/spa.c:9100
    #6 0x7fb4a0ddd61c in spa_sync ../../module/zfs/spa.c:9318
    #7 0x7fb4a0e10e4d in txg_sync_thread ../../module/zfs/txg.c:597
    #8 0x7fb4a00766da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)

Thread T178 created by T0 here:
    #0 0x7fb4a179ed2f in __interceptor_pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.4+0x37d2f)
    #1 0x7fb4a0c1b6a2 in zk_thread_create /export/home/delphix/zfs/lib/libzpool/kernel.c:121
    #2 0x7fb4a0e11ab6 in txg_sync_start ../../module/zfs/txg.c:216
    #3 0x7fb4a0de4332 in spa_load_impl ../../module/zfs/spa.c:4899
    #4 0x7fb4a0de47db in spa_load ../../module/zfs/spa.c:2937
    #5 0x7fb4a0de4b99 in spa_load_best ../../module/zfs/spa.c:5017
    #6 0x7fb4a0de53ae in spa_open_common ../../module/zfs/spa.c:5156
    #7 0x55eebc4a60d7 in ztest_run /export/home/delphix/zfs/cmd/ztest/ztest.c:7447
    #8 0x55eebc492f80 in main /export/home/delphix/zfs/cmd/ztest/ztest.c:8040
    #9 0x7fb49fc9fbf6 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x21bf6)

SUMMARY: AddressSanitizer: heap-use-after-free ../../module/zfs/zio.c:881 in zio_create
Shadow bytes around the buggy address:
  0x0c328005f3e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c328005f3f0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c328005f400: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c328005f410: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c328005f420: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
=>0x0c328005f430: fd fd fd fd fd fd fd fd fd fd fd fd fd[fd]fd fd
  0x0c328005f440: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c328005f450: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c328005f460: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c328005f470: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x0c328005f480: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==89578==ABORTING

The parent IO being referenced in the read request from vdev_rebuild_range() has already been freed by the sync thread.

[szubersk]

@mmaybee

root@ubuntu:~# cat /etc/os-release 
NAME="Ubuntu"
VERSION="18.04.6 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.6 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic

root@ubuntu:~# uname -a
Linux ubuntu 5.4.0-84-generic #94~18.04.1-Ubuntu SMP Thu Aug 26 23:17:46 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

root@ubuntu:/mnt/zfs# git log -1
commit 5eae5a88b258cf955b46a99da07d9d5acad8bacd (grafted, HEAD -> master, origin/master, origin/HEAD)
Author: Savyasachee Jha <genghizkhan91@hawkradius.com>
Date:   Mon Feb 14 22:28:37 2022 +0530

OpenZFS compiled with ASan and UBSan. I'm running

./scripts//zloop.sh -t 1200 -l -m1 -- -T 120 -P 60

in an infinite loop. Not a single reproduction. As a matter of fact ztest crashed once at ASSERT (unrelated), other runs clean. I'll keep it spinning in case I get a reproduction.

Would you share more details on how you managed to hit that issue?

[stale]

This issue has been automatically marked as "stale" because it has not had any activity for a while. It will be closed in 90 days if no further activity occurs. Thank you for your contributions.