Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.
RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1653802

Summary: index creation fails on md raid 6 on SuperMicro with MegaRaid controller
Product: Red Hat Enterprise Linux 8 Reporter: Jakub Krysl <jkrysl>
Component: kmod-kvdoAssignee: Thomas Jaskiewicz <tjaskiew>
Status: CLOSED ERRATA QA Contact: vdo-qe
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 8.0CC: awalsh, bgurney, corwin, limershe, sweettea
Target Milestone: rcFlags: pm-rhel: mirror+
Target Release: 8.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 6.2.1.130 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-11-05 22:12:24 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:

Description Jakub Krysl 2018-11-27 16:31:29 UTC 
Description of problem:
Creating VDO on raid 6 over 4 disks on SuperMicro server with MegaRaid controller fails on RHEL-8.0-20181120.0 and shows following trace in syslog during the vdo creation called with this command:

# vdo create --name vdo2 --device /dev/md127 --verbose --vdoSlabSize 8G
Creating VDO vdo2
    grep MemAvailable /proc/meminfo
    pvcreate -qq --test /dev/md127
    blkid -p /dev/md127
    modprobe kvdo
    vdoformat --uds-checkpoint-frequency=0 --uds-memory-size=0.25 --slab-bits=21 /dev/disk/by-id/md-uuid-c1c901d5:5b213b0e:2e1bdbfc:a0d9afaa
    vdodumpconfig /dev/disk/by-id/md-uuid-c1c901d5:5b213b0e:2e1bdbfc:a0d9afaa
Starting VDO vdo2
    dmsetup status vdo2
    grep MemAvailable /proc/meminfo
    modprobe kvdo
    vdodumpconfig /dev/disk/by-id/md-uuid-c1c901d5:5b213b0e:2e1bdbfc:a0d9afaa
    vdodumpconfig /dev/disk/by-id/md-uuid-c1c901d5:5b213b0e:2e1bdbfc:a0d9afaa
    dmsetup create vdo2 --uuid VDO-4f93df5f-fdff-4a34-bbb5-e2da79dae7c3 --table '0 38995340448 vdo V2 /dev/disk/by-id/md-uuid-c1c901d5:5b213b0e:2e1bdbfc:a0d9afaa 4883152384 4096 32768 16380 on auto vdo2 maxDiscard 1 ack 1 bio 4 bioRotationInterval 64 cpu 2 hash 1 logical 1 physical 1'
    dmsetup status vdo2
Starting compression on VDO vdo2
    dmsetup message vdo2 0 compression on
    vdodmeventd -r vdo2
    dmsetup status vdo2
VDO instance 6 volume is ready at /dev/mapper/vdo2

/var/log/messages:
Nov 27 15:27:02 storageqe-90 kernel: uds: kvdo6:dedupeQ: assertion "delta lists per chapter (67108864) is too large" (((deltaListsPerChapter - 1) <= ((uint16_t)~0ul))) failed at /builddir/build/BUILD/kvdo-2f1ca5020fb69bbbb6338a6d6e60f31e44a2d26a/obj/./uds/indexPageMap.c:73
Nov 27 15:27:02 storageqe-90 kernel: uds: kvdo6:dedupeQ: [backtrace]
Nov 27 15:27:02 storageqe-90 kernel: CPU: 13 PID: 21969 Comm: kvdo6:dedupeQ Kdump: loaded Tainted: G           OE    --------- ---  4.18.0-40.el8.x86_64 #1
Nov 27 15:27:02 storageqe-90 kernel: Hardware name: Supermicro AS -2023US-TR4/H11DSU-iN, BIOS 1.1a 04/26/2018
Nov 27 15:27:02 storageqe-90 kernel: Call Trace:
Nov 27 15:27:02 storageqe-90 kernel: dump_stack+0x5c/0x80
Nov 27 15:27:02 storageqe-90 kernel: assertionFailed+0x4f/0x70 [uds]
Nov 27 15:27:02 storageqe-90 kernel: ? makePageCache+0x1f1/0x280 [uds]
Nov 27 15:27:02 storageqe-90 kernel: makeIndexPageMap+0xf5/0x110 [uds]
Nov 27 15:27:02 storageqe-90 kernel: allocateVolume+0x365/0x4d0 [uds]
Nov 27 15:27:02 storageqe-90 kernel: makeVolume+0x83/0x1e0 [uds]
Nov 27 15:27:02 storageqe-90 kernel: allocateIndex+0x1df/0x310 [uds]
Nov 27 15:27:02 storageqe-90 kernel: makeIndex+0x4c/0x4f0 [uds]
Nov 27 15:27:02 storageqe-90 kernel: ? makeRequestQueue+0xd7/0x100 [uds]
Nov 27 15:27:02 storageqe-90 kernel: ? randomCompileTimeAssertions+0x10/0x10 [uds]
Nov 27 15:27:02 storageqe-90 kernel: makeLocalIndexRouter+0x137/0x1b0 [uds]
Nov 27 15:27:02 storageqe-90 kernel: ? updateRequestContextStats+0x100/0x100 [uds]
Nov 27 15:27:02 storageqe-90 kernel: makeLocalGrid+0x118/0x210 [uds]
Nov 27 15:27:02 storageqe-90 kernel: makeLocalIndex+0x263/0x2c0 [uds]
Nov 27 15:27:02 storageqe-90 kernel: changeDedupeState+0x102/0x400 [kvdo]
Nov 27 15:27:02 storageqe-90 kernel: workQueueRunner+0x1b6/0x650 [kvdo]
Nov 27 15:27:02 storageqe-90 kernel: ? finish_wait+0x80/0x80
Nov 27 15:27:02 storageqe-90 kernel: ? stringToUInt+0x60/0x60 [kvdo]
Nov 27 15:27:02 storageqe-90 kernel: kthread+0x112/0x130
Nov 27 15:27:02 storageqe-90 kernel: ? kthread_bind+0x30/0x30
Nov 27 15:27:02 storageqe-90 kernel: ret_from_fork+0x22/0x40
Nov 27 15:27:02 storageqe-90 kernel: uds: kvdo6:dedupeQ: could not allocate index: UDS Internal Error: UDS data structures are in an invalid state (66564)
Nov 27 15:27:02 storageqe-90 kernel: uds: kvdo6:dedupeQ: failed to create index: UDS Internal Error: UDS data structures are in an invalid state (66564)
Nov 27 15:27:02 storageqe-90 kernel: uds: kvdo6:dedupeQ: Failed to make router: UDS Internal Error: UDS data structures are in an invalid state (66564)
Nov 27 15:27:02 storageqe-90 kernel: uds: kvdo6:dedupeQ: Failed creating index: UDS Internal Error: UDS data structures are in an invalid state (66564)
Nov 27 15:27:02 storageqe-90 kernel: kvdo6:dedupeQ: Error creating index dev=/dev/disk/by-id/md-uuid-c1c901d5:5b213b0e:2e1bdbfc:a0d9afaa offset=4096 size=2781704192: UDS Internal Error: UDS data structures are in an invalid state (66564)
Nov 27 15:27:02 storageqe-90 kernel: kvdo6:dedupeQ: Setting UDS index target state to error
Nov 27 15:27:02 storageqe-90 kernel: kvdo6:dmsetup: device 'vdo2' stopped

Reproducing it again shows slightly different trace that shows in any subsequent try:

Nov 27 15:29:09 storageqe-90 kernel: uds: kvdo7:dedupeQ: Using 16 indexing zones for concurrency.
Nov 27 15:29:09 storageqe-90 kernel: uds: kvdo7:dedupeQ: assertion "requested cache size, 35648, within limit 32767" ((cache->numCacheEntries <= VOLUME_CACHE_MAX_ENTRIES)) failed at /builddir/build/BUILD/kvdo-2f1ca5020fb69bbbb6338a6d6e60f31e44a2d26a/obj/./uds/pageCache.c:286
Nov 27 15:29:09 storageqe-90 kernel: uds: kvdo7:dedupeQ: [backtrace]
Nov 27 15:29:09 storageqe-90 kernel: CPU: 5 PID: 22108 Comm: kvdo7:dedupeQ Kdump: loaded Tainted: G           OE    --------- ---  4.18.0-40.el8.x86_64 #1
Nov 27 15:29:10 storageqe-90 kernel: Hardware name: Supermicro AS -2023US-TR4/H11DSU-iN, BIOS 1.1a 04/26/2018
Nov 27 15:29:10 storageqe-90 kernel: Call Trace:
Nov 27 15:29:10 storageqe-90 kernel: dump_stack+0x5c/0x80
Nov 27 15:29:10 storageqe-90 kernel: assertionFailed+0x4f/0x70 [uds]
Nov 27 15:29:10 storageqe-90 kernel: makePageCache+0x267/0x280 [uds]
Nov 27 15:29:10 storageqe-90 kernel: allocateVolume+0x343/0x4d0 [uds]
Nov 27 15:29:10 storageqe-90 kernel: makeVolume+0x83/0x1e0 [uds]
Nov 27 15:29:10 storageqe-90 kernel: allocateIndex+0x1df/0x310 [uds]
Nov 27 15:29:10 storageqe-90 kernel: makeIndex+0x4c/0x4f0 [uds]
Nov 27 15:29:10 storageqe-90 kernel: ? makeRequestQueue+0xd7/0x100 [uds]
Nov 27 15:29:10 storageqe-90 kernel: ? randomCompileTimeAssertions+0x10/0x10 [uds]
Nov 27 15:29:10 storageqe-90 kernel: makeLocalIndexRouter+0x137/0x1b0 [uds]
Nov 27 15:29:10 storageqe-90 kernel: ? updateRequestContextStats+0x100/0x100 [uds]
Nov 27 15:29:10 storageqe-90 kernel: makeLocalGrid+0x118/0x210 [uds]
Nov 27 15:29:10 storageqe-90 kernel: makeLocalIndex+0x263/0x2c0 [uds]
Nov 27 15:29:10 storageqe-90 kernel: changeDedupeState+0x102/0x400 [kvdo]
Nov 27 15:29:10 storageqe-90 kernel: workQueueRunner+0x1b6/0x650 [kvdo]
Nov 27 15:29:10 storageqe-90 kernel: ? finish_wait+0x80/0x80
Nov 27 15:29:10 storageqe-90 kernel: ? stringToUInt+0x60/0x60 [kvdo]
Nov 27 15:29:10 storageqe-90 kernel: kthread+0x112/0x130
Nov 27 15:29:10 storageqe-90 kernel: ? kthread_bind+0x30/0x30
Nov 27 15:29:10 storageqe-90 kernel: ret_from_fork+0x22/0x40
Nov 27 15:29:10 storageqe-90 kernel: uds: kvdo7:dedupeQ: could not allocate index: UDS Internal Error: Assertion failed (66568)
Nov 27 15:29:10 storageqe-90 kernel: uds: kvdo7:dedupeQ: failed to create index: UDS Internal Error: Assertion failed (66568)
Nov 27 15:29:10 storageqe-90 kernel: uds: kvdo7:dedupeQ: Failed to make router: UDS Internal Error: Assertion failed (66568)
Nov 27 15:29:10 storageqe-90 kernel: uds: kvdo7:dedupeQ: Failed creating index: UDS Internal Error: Assertion failed (66568)
Nov 27 15:29:10 storageqe-90 kernel: kvdo7:dedupeQ: Error creating index dev=/dev/disk/by-id/md-uuid-c1c901d5:5b213b0e:2e1bdbfc:a0d9afaa offset=4096 size=2781704192: UDS Internal Error: Assertion failed (66568)
Nov 27 15:29:10 storageqe-90 kernel: kvdo7:dedupeQ: Setting UDS index target state to error
Nov 27 15:29:10 storageqe-90 kernel: kvdo7:dmsetup: device 'vdo2' stopped

I tested the same on fresh install with the same result. I tested fresh install on different server and was not able to reproduce it so it seems to be somehow HW related.

Version-Release number of selected component (if applicable):
kmod-kvdo-6.2.0.273-35.el8.x86_64
vdo-6.2.0.273-9.el8.x86_64
4.18.0-40.el8.x86_64

How reproducible:
100% on the right server

Steps to Reproduce:
1. mdadm --create md127 --level 6 --raid-devices 4 /dev/sd[i,j,k,l]
2. vdo create --name vdo2 --device /dev/md127 --verbose --vdoSlabSize 8G

Actual results:
index assertion error followed by calltrace

Expected results:
no issues during vdo creation

Additional info:
Comment 2 Bryan Gurney 2018-11-27 19:12:16 UTC 
I tried reproducing this on the same system, with a 19 TB 4-drive RAID-6, and the VDO volume seems to create normally.

# rpm -qa kmod-kvdo vdo; uname -r
vdo-6.2.0.273-9.el8.x86_64
kmod-kvdo-6.2.0.273-35.el8.x86_64
4.18.0-40.el8.x86_64


# mdadm --create md127 --level 6 --raid-devices 4 /dev/sd[i,j,k,l]
mdadm: Defaulting to version 1.2 metadata
mdadm: array /dev/md/md127 started.

# date; time vdo create --name=vdo3 --device=/dev/md127 --vdoSlabSize=8G --verbose; date
Tue Nov 27 19:59:08 CET 2018
Creating VDO vdo3
    grep MemAvailable /proc/meminfo
    pvcreate -qq --test /dev/md127
    blkid -p /dev/md127
    modprobe kvdo
    vdoformat --uds-checkpoint-frequency=0 --uds-memory-size=0.25 --slab-bits=21 /dev/disk/by-id/md-uuid-b83fff9e:5bcf2a15:fb1b309c:d2d338cc
    vdodumpconfig /dev/disk/by-id/md-uuid-b83fff9e:5bcf2a15:fb1b309c:d2d338cc
Starting VDO vdo3
    dmsetup status vdo3
    grep MemAvailable /proc/meminfo
    modprobe kvdo
    vdodumpconfig /dev/disk/by-id/md-uuid-b83fff9e:5bcf2a15:fb1b309c:d2d338cc
    vdodumpconfig /dev/disk/by-id/md-uuid-b83fff9e:5bcf2a15:fb1b309c:d2d338cc
    dmsetup create vdo3 --uuid VDO-b2b63b65-c697-4622-af2f-7bde76f7d783 --table '0 38995340448 vdo V2 /dev/disk/by-id/md-uuid-b83fff9e:5bcf2a15:fb1b309c:d2d338cc 4883152384 4096 32768 16380 on auto vdo3 maxDiscard 1 ack 1 bio 4 bioRotationInterval 64 cpu 2 hash 1 logical 1 physical 1'
    dmsetup status vdo3
Starting compression on VDO vdo3
    dmsetup message vdo3 0 compression on
    vdodmeventd -r vdo3
    dmsetup status vdo3
VDO instance 7 volume is ready at /dev/mapper/vdo3

real	0m4.453s
user	0m0.200s
sys	0m0.161s
Tue Nov 27 19:59:12 CET 2018

Nov 27 19:59:11 localhost kernel: kvdo7:dmsetup: underlying device, REQ_FLUSH: supported, REQ_FUA: supported
Nov 27 19:59:11 localhost kernel: kvdo7:dmsetup: Using write policy async automatically.
Nov 27 19:59:11 localhost kernel: kvdo7:dmsetup: starting device 'vdo3'
Nov 27 19:59:11 localhost kernel: kvdo7:dmsetup: zones: 1 logical, 1 physical, 1 hash; base threads: 5
Nov 27 19:59:12 localhost kernel: kvdo7:journalQ: VDO commencing normal operation
Nov 27 19:59:12 localhost kernel: kvdo7:dmsetup: Setting UDS index target state to online
Nov 27 19:59:12 localhost kernel: uds: kvdo7:dedupeQ: creating index: dev=/dev/disk/by-id/md-uuid-b83fff9e:5bcf2a15:fb1b309c:d2d338cc offset=4096 size=2781704192
Nov 27 19:59:12 localhost kernel: kvdo7:dmsetup: device 'vdo3' started
Nov 27 19:59:12 localhost kernel: kvdo7:dmsetup: resuming device 'vdo3'
Nov 27 19:59:12 localhost kernel: kvdo7:dmsetup: device 'vdo3' resumed
Nov 27 19:59:12 localhost kernel: kvdo7:packerQ: compression is enabled
Nov 27 19:59:12 localhost UDS/vdodmeventd[26673]: INFO   (vdodmeventd/26673) VDO device vdo3 is now registered with dmeventd for monitoring
Nov 27 19:59:12 localhost lvm[25765]: Monitoring VDO pool vdo3.
Nov 27 19:59:12 localhost kernel: uds: kvdo7:dedupeQ: Using 16 indexing zones for concurrency.

I was also able to create a VDO volume on a 2-disk RAID-0, which is also 19 TB.
Comment 3 Jakub Krysl 2018-11-28 09:09:05 UTC 
Bryan, I tried again and was not able to reproduce at first. So I tried running bunch of commands as I did yesterday. At one point I interrupted VDO removal (as I remember doing it, because it took way too long) and managed to reproduce it. Pitty I did not time the interrupted vdo removal...

# time vdo create --name vdo2 --device /dev/md127 --verbose --vdoSlabSize 8G
Creating VDO vdo2
    grep MemAvailable /proc/meminfo
    pvcreate -qq --test /dev/md127
    blkid -p /dev/md127
    modprobe kvdo
    vdoformat --uds-checkpoint-frequency=0 --uds-memory-size=0.25 --slab-bits=21 /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f
    vdodumpconfig /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f
Starting VDO vdo2
    dmsetup status vdo2
    grep MemAvailable /proc/meminfo
    modprobe kvdo
    vdodumpconfig /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f
    vdodumpconfig /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f
    dmsetup create vdo2 --uuid VDO-59a89cca-6dc2-424d-9824-5096bf4a328d --table '0 38995340448 vdo V2 /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f 4883152384 4096 32768 16380 on auto vdo2 maxDiscard 1 ack 1 bio 4 bioRotationInterval 64 cpu 2 hash 1 logical 1 physical 1'
    dmsetup status vdo2
Starting compression on VDO vdo2
    dmsetup message vdo2 0 compression on
    vdodmeventd -r vdo2
    dmsetup status vdo2
VDO instance 9 volume is ready at /dev/mapper/vdo2

real    0m4.563s
user    0m0.170s
sys     0m0.132s
# vdo remove --name vdo2
Removing VDO vdo2
Stopping VDO vdo2
^CTraceback (most recent call last):
  File "/usr/bin/vdo", line 150, in <module>
    main()
  File "/usr/bin/vdo", line 128, in main
    operation.run(arguments)
  File "/usr/lib/python3.6/site-packages/vdo/vdomgmnt/VDOOperation.py", line 217, in run
    self.execute(args)
  File "/usr/lib/python3.6/site-packages/vdo/vdomgmnt/VDOOperation.py", line 68, in wrap
    return lock(False, func, *args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdo/vdomgmnt/VDOOperation.py", line 63, in lock
    return func(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdo/vdomgmnt/VDOOperation.py", line 479, in execute
    self.applyToVDOs(args, self._removeVDO, readonly=False)
  File "/usr/lib/python3.6/site-packages/vdo/vdomgmnt/VDOOperation.py", line 152, in applyToVDOs
    method(args, vdo)
  File "/usr/lib/python3.6/site-packages/vdo/vdomgmnt/VDOOperation.py", line 487, in _removeVDO
    vdo.remove(args.force, removeSteps = removeSteps)
  File "/usr/lib/python3.6/site-packages/vdo/vdomgmnt/VDOService.py", line 533, in remove
    self.stop(force, localRemoveSteps)
  File "/usr/lib/python3.6/site-packages/vdo/vdomgmnt/VDOService.py", line 753, in stop
    runCommand(command)
  File "/usr/lib/python3.6/site-packages/vdo/utils/Command.py", line 299, in runCommand
    return Command(commandList, kwargs.pop('environment', None)).run(**kwargs)
  File "/usr/lib/python3.6/site-packages/vdo/utils/Command.py", line 173, in run
    output = self._execute(stdin)
  File "/usr/lib/python3.6/site-packages/vdo/utils/Command.py", line 256, in _execute
    stdoutdata, stderrdata = p.communicate(stdin)
  File "/usr/lib64/python3.6/subprocess.py", line 843, in communicate
    stdout, stderr = self._communicate(input, endtime, timeout)
  File "/usr/lib64/python3.6/subprocess.py", line 1514, in _communicate
    ready = selector.select(timeout)
  File "/usr/lib64/python3.6/selectors.py", line 376, in select
    fd_event_list = self._poll.poll(timeout)
KeyboardInterrupt
# time vdo remove --name vdo2
Removing VDO vdo2
Stopping VDO vdo2

real    0m0.213s
user    0m0.141s
sys     0m0.011s
# time vdo create --name vdo2 --device /dev/md127 --verbose --vdoSlabSize 8G
Creating VDO vdo2
    grep MemAvailable /proc/meminfo
    pvcreate -qq --test /dev/md127
    blkid -p /dev/md127
    modprobe kvdo
    vdoformat --uds-checkpoint-frequency=0 --uds-memory-size=0.25 --slab-bits=21 /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f
    vdodumpconfig /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f
Starting VDO vdo2
    dmsetup status vdo2
    grep MemAvailable /proc/meminfo
    modprobe kvdo
    vdodumpconfig /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f
    vdodumpconfig /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f
    dmsetup create vdo2 --uuid VDO-0f0e5754-307f-47ba-9232-c833e416a88e --table '0 38995340448 vdo V2 /dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f 4883152384 4096 32768 16380 on auto vdo2 maxDiscard 1 ack 1 bio 4 bioRotationInterval 64 cpu 2 hash 1 logical 1 physical 1'
    dmsetup status vdo2
Starting compression on VDO vdo2
    dmsetup message vdo2 0 compression on
    vdodmeventd -r vdo2
    dmsetup status vdo2
VDO instance 10 volume is ready at /dev/mapper/vdo2

real    0m3.476s
user    0m0.179s
sys     0m0.129s
# time vdo remove --name vdo2
Removing VDO vdo2
Stopping VDO vdo2

real    0m1.996s
user    0m0.151s
sys     0m0.175s


/var/log/messages:
Nov 28 09:51:22 storageqe-90 UDS/vdodmeventd[15538]: INFO   (vdodmeventd/15538) VDO device vdo2 is now unregistered from dmeventd
Nov 28 09:51:22 storageqe-90 dmeventd[12699]: No longer monitoring VDO pool vdo2.
Nov 28 09:51:22 storageqe-90 kernel: kvdo9:dmsetup: suspending device 'vdo2'
Nov 28 09:51:23 storageqe-90 kernel: kvdo9:dmsetup: device 'vdo2' suspended
Nov 28 09:51:23 storageqe-90 kernel: kvdo9:dmsetup: stopping device 'vdo2'
Nov 28 09:51:23 storageqe-90 kernel: kvdo9:dmsetup: Setting UDS index target state to closed
Nov 28 09:51:23 storageqe-90 kernel: uds: kvdo9:dedupeQ: beginning save (vcn 4294967295)
Nov 28 09:51:54 storageqe-90 kernel: kvdo9:dmsetup: device 'vdo2' stopped
Nov 28 09:52:04 storageqe-90 kernel: kvdo10:dmsetup: underlying device, REQ_FLUSH: supported, REQ_FUA: supported
Nov 28 09:52:04 storageqe-90 kernel: kvdo10:dmsetup: Using write policy async automatically.
Nov 28 09:52:04 storageqe-90 kernel: kvdo10:dmsetup: starting device 'vdo2'
Nov 28 09:52:04 storageqe-90 kernel: kvdo10:dmsetup: zones: 1 logical, 1 physical, 1 hash; base threads: 5
Nov 28 09:52:05 storageqe-90 kernel: kvdo10:journalQ: VDO commencing normal operation
Nov 28 09:52:05 storageqe-90 kernel: kvdo10:dmsetup: Setting UDS index target state to online
Nov 28 09:52:05 storageqe-90 kernel: kvdo10:dmsetup: device 'vdo2' started
Nov 28 09:52:05 storageqe-90 kernel: uds: kvdo10:dedupeQ: creating index: dev=/dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f offset=4096 size=2781704192
Nov 28 09:52:05 storageqe-90 kernel: kvdo10:dmsetup: resuming device 'vdo2'
Nov 28 09:52:05 storageqe-90 kernel: kvdo10:dmsetup: device 'vdo2' resumed
Nov 28 09:52:05 storageqe-90 kernel: kvdo10:packerQ: compression is enabled
Nov 28 09:52:05 storageqe-90 UDS/vdodmeventd[15612]: INFO   (vdodmeventd/15612) VDO device vdo2 is now registered with dmeventd for monitoring
Nov 28 09:52:05 storageqe-90 lvm[12699]: Monitoring VDO pool vdo2.
Nov 28 09:52:06 storageqe-90 UDS/vdodmeventd[15620]: INFO   (vdodmeventd/15620) VDO device vdo2 is now unregistered from dmeventd
Nov 28 09:52:06 storageqe-90 dmeventd[12699]: No longer monitoring VDO pool vdo2.
Nov 28 09:52:06 storageqe-90 kernel: kvdo10:dmsetup: suspending device 'vdo2'
Nov 28 09:52:06 storageqe-90 kernel: kvdo10:dmsetup: device 'vdo2' suspended
Nov 28 09:52:06 storageqe-90 kernel: kvdo10:dmsetup: stopping device 'vdo2'
Nov 28 09:52:07 storageqe-90 kernel: kvdo10:dmsetup: Setting UDS index target state to closed
Nov 28 09:52:07 storageqe-90 kernel: uds: kvdo10:dedupeQ: Using 16 indexing zones for concurrency.
Nov 28 09:52:08 storageqe-90 kernel: uds: kvdo10:dedupeQ: assertion "requested cache size, 56512, within limit 32767" ((cache->numCacheEntries <= VOLUME_CACHE_MAX_ENTRIES)) failed at /builddir/build/BUILD/kvdo-2f1ca5020fb69bbbb6338a6d6e60f31e44a2d26a/obj/./uds/pageCache.c:286
Nov 28 09:52:08 storageqe-90 kernel: uds: kvdo10:dedupeQ: [backtrace]
Nov 28 09:52:08 storageqe-90 kernel: CPU: 11 PID: 15590 Comm: kvdo10:dedupeQ Kdump: loaded Tainted: G           OE    --------- ---  4.18.0-40.el8.x86_64 #1
Nov 28 09:52:08 storageqe-90 kernel: Hardware name: Supermicro AS -2023US-TR4/H11DSU-iN, BIOS 1.1a 04/26/2018
Nov 28 09:52:08 storageqe-90 kernel: Call Trace:
Nov 28 09:52:08 storageqe-90 kernel: dump_stack+0x5c/0x80
Nov 28 09:52:08 storageqe-90 kernel: assertionFailed+0x4f/0x70 [uds]
Nov 28 09:52:08 storageqe-90 kernel: makePageCache+0x267/0x280 [uds]
Nov 28 09:52:08 storageqe-90 kernel: allocateVolume+0x343/0x4d0 [uds]
Nov 28 09:52:08 storageqe-90 kernel: makeVolume+0x83/0x1e0 [uds]
Nov 28 09:52:08 storageqe-90 kernel: allocateIndex+0x1df/0x310 [uds]
Nov 28 09:52:08 storageqe-90 kernel: makeIndex+0x4c/0x4f0 [uds]
Nov 28 09:52:08 storageqe-90 kernel: ? makeRequestQueue+0xd7/0x100 [uds]
Nov 28 09:52:08 storageqe-90 kernel: ? randomCompileTimeAssertions+0x10/0x10 [uds]
Nov 28 09:52:08 storageqe-90 kernel: makeLocalIndexRouter+0x137/0x1b0 [uds]
Nov 28 09:52:08 storageqe-90 kernel: ? updateRequestContextStats+0x100/0x100 [uds]
Nov 28 09:52:08 storageqe-90 kernel: makeLocalGrid+0x118/0x210 [uds]
Nov 28 09:52:08 storageqe-90 kernel: makeLocalIndex+0x263/0x2c0 [uds]
Nov 28 09:52:08 storageqe-90 kernel: changeDedupeState+0x102/0x400 [kvdo]
Nov 28 09:52:08 storageqe-90 kernel: workQueueRunner+0x1b6/0x650 [kvdo]
Nov 28 09:52:08 storageqe-90 kernel: ? finish_wait+0x80/0x80
Nov 28 09:52:08 storageqe-90 kernel: ? stringToUInt+0x60/0x60 [kvdo]
Nov 28 09:52:08 storageqe-90 kernel: kthread+0x112/0x130
Nov 28 09:52:08 storageqe-90 kernel: ? kthread_bind+0x30/0x30
Nov 28 09:52:08 storageqe-90 kernel: ret_from_fork+0x22/0x40
Nov 28 09:52:08 storageqe-90 kernel: uds: kvdo10:dedupeQ: could not allocate index: UDS Internal Error: Assertion failed (66568)
Nov 28 09:52:08 storageqe-90 kernel: uds: kvdo10:dedupeQ: failed to create index: UDS Internal Error: Assertion failed (66568)
Nov 28 09:52:08 storageqe-90 kernel: uds: kvdo10:dedupeQ: Failed to make router: UDS Internal Error: Assertion failed (66568)
Nov 28 09:52:08 storageqe-90 kernel: uds: kvdo10:dedupeQ: Failed creating index: UDS Internal Error: Assertion failed (66568)
Nov 28 09:52:08 storageqe-90 kernel: kvdo10:dedupeQ: Error creating index dev=/dev/disk/by-id/md-uuid-2aa5cfc3:9d9502c8:90ccb9b0:067e070f offset=4096 size=2781704192: UDS Internal Error: Assertion failed (66568)
Nov 28 09:52:08 storageqe-90 kernel: kvdo10:dedupeQ: Setting UDS index target state to error
Nov 28 09:52:08 storageqe-90 kernel: kvdo10:dmsetup: device 'vdo2' stopped


I'll try to come with some reliable reproducer, as I too am having hard time reproducing it again.
Comment 4 Jakub Krysl 2018-11-28 09:27:34 UTC 
I got another a bit different assertion error:

/var/log/messages
Nov 28 10:16:26 storageqe-90 UDS/vdodmeventd[18347]: INFO   (vdodmeventd/18347) VDO device vdo2 is now unregistered from dmeventd
Nov 28 10:16:26 storageqe-90 dmeventd[12699]: No longer monitoring VDO pool vdo2.
Nov 28 10:16:26 storageqe-90 kernel: kvdo30:dmsetup: suspending device 'vdo2'
Nov 28 10:16:26 storageqe-90 kernel: kvdo30:dmsetup: device 'vdo2' suspended
Nov 28 10:16:26 storageqe-90 kernel: kvdo30:dmsetup: stopping device 'vdo2'
Nov 28 10:16:34 storageqe-90 kernel: kvdo30:dmsetup: Setting UDS index target state to closed
Nov 28 10:16:34 storageqe-90 kernel: uds: kvdo30:dedupeQ: beginning save (vcn 4294967295)
Nov 28 10:16:43 storageqe-90 kernel: kvdo30:dmsetup: device 'vdo2' stopped
Nov 28 10:17:00 storageqe-90 vdo[18549]: ERROR - VDO volume vdo2 already exists
Nov 28 10:17:08 storageqe-90 kernel: kvdo31:dmsetup: underlying device, REQ_FLUSH: supported, REQ_FUA: supported
Nov 28 10:17:08 storageqe-90 kernel: kvdo31:dmsetup: Using write policy async automatically.
Nov 28 10:17:08 storageqe-90 kernel: kvdo31:dmsetup: starting device 'vdo2'
Nov 28 10:17:08 storageqe-90 kernel: kvdo31:dmsetup: zones: 1 logical, 1 physical, 1 hash; base threads: 5
Nov 28 10:17:09 storageqe-90 restraintd[2414]: *** Current Time: Wed Nov 28 10:17:09 2018 Localwatchdog at:  * Disabled! *
Nov 28 10:17:12 storageqe-90 kernel: kvdo31:journalQ: VDO commencing normal operation
Nov 28 10:17:12 storageqe-90 kernel: kvdo31:dmsetup: Setting UDS index target state to online
Nov 28 10:17:12 storageqe-90 kernel: kvdo31:dmsetup: device 'vdo2' started
Nov 28 10:17:12 storageqe-90 kernel: kvdo31:dmsetup: resuming device 'vdo2'
Nov 28 10:17:12 storageqe-90 kernel: kvdo31:dmsetup: device 'vdo2' resumed
Nov 28 10:17:12 storageqe-90 kernel: uds: kvdo31:dedupeQ: creating index: dev=/dev/disk/by-id/md-uuid-1ec5399e:07c206e4:1e50fadf:0fa23eef offset=4096 size=2781704192
Nov 28 10:17:12 storageqe-90 kernel: kvdo31:packerQ: compression is enabled
Nov 28 10:17:12 storageqe-90 UDS/vdodmeventd[18608]: INFO   (vdodmeventd/18608) VDO device vdo2 is now registered with dmeventd for monitoring
Nov 28 10:17:12 storageqe-90 lvm[12699]: Monitoring VDO pool vdo2.
Nov 28 10:17:16 storageqe-90 UDS/vdodmeventd[18618]: INFO   (vdodmeventd/18618) VDO device vdo2 is now unregistered from dmeventd
Nov 28 10:17:16 storageqe-90 dmeventd[12699]: No longer monitoring VDO pool vdo2.
Nov 28 10:17:16 storageqe-90 kernel: kvdo31:dmsetup: suspending device 'vdo2'
Nov 28 10:17:16 storageqe-90 kernel: kvdo31:dmsetup: device 'vdo2' suspended
Nov 28 10:17:16 storageqe-90 kernel: kvdo31:dmsetup: stopping device 'vdo2'
Nov 28 10:17:16 storageqe-90 kernel: kvdo31:dmsetup: Setting UDS index target state to closed
Nov 28 10:17:19 storageqe-90 kernel: uds: kvdo31:dedupeQ: assertion "page is smaller than a record: 2" (bytesPerPage >= BYTES_PER_RECORD) failed at /builddir/build/BUILD/kvdo-2f1ca5020fb69bbbb6338a6d6e60f31e44a2d26a/obj/./uds/geometry.c:42
Nov 28 10:17:19 storageqe-90 kernel: uds: kvdo31:dedupeQ: [backtrace]
Nov 28 10:17:19 storageqe-90 kernel: CPU: 12 PID: 18584 Comm: kvdo31:dedupeQ Kdump: loaded Tainted: G           OE    --------- ---  4.18.0-40.el8.x86_64 #1
Nov 28 10:17:19 storageqe-90 kernel: Hardware name: Supermicro AS -2023US-TR4/H11DSU-iN, BIOS 1.1a 04/26/2018
Nov 28 10:17:19 storageqe-90 kernel: Call Trace:
Nov 28 10:17:19 storageqe-90 kernel: dump_stack+0x5c/0x80
Nov 28 10:17:19 storageqe-90 kernel: assertionFailed+0x4f/0x70 [uds]
Nov 28 10:17:19 storageqe-90 kernel: makeGeometry+0x18e/0x1f0 [uds]
Nov 28 10:17:19 storageqe-90 kernel: ? updateRequestContextStats+0x100/0x100 [uds]
Nov 28 10:17:19 storageqe-90 kernel: makeConfiguration+0x78/0xe0 [uds]
Nov 28 10:17:19 storageqe-90 kernel: makeLocalGrid+0xec/0x210 [uds]
Nov 28 10:17:19 storageqe-90 kernel: makeLocalIndex+0x263/0x2c0 [uds]
Nov 28 10:17:19 storageqe-90 kernel: changeDedupeState+0x102/0x400 [kvdo]
Nov 28 10:17:19 storageqe-90 kernel: workQueueRunner+0x1b6/0x650 [kvdo]
Nov 28 10:17:19 storageqe-90 kernel: ? finish_wait+0x80/0x80
Nov 28 10:17:19 storageqe-90 kernel: ? stringToUInt+0x60/0x60 [kvdo]
Nov 28 10:17:19 storageqe-90 kernel: kthread+0x112/0x130
Nov 28 10:17:19 storageqe-90 kernel: ? kthread_bind+0x30/0x30
Nov 28 10:17:19 storageqe-90 kernel: ret_from_fork+0x22/0x40
Nov 28 10:17:19 storageqe-90 kernel: uds: kvdo31:dedupeQ: Failed to allocate config: UDS Internal Error: UDS data structures are in an invalid state (66564)
Nov 28 10:17:19 storageqe-90 kernel: uds: kvdo31:dedupeQ: Failed creating index: UDS Internal Error: UDS data structures are in an invalid state (66564)
Nov 28 10:17:19 storageqe-90 kernel: kvdo31:dedupeQ: Error creating index dev=/dev/disk/by-id/md-uuid-1ec5399e:07c206e4:1e50fadf:0fa23eef offset=4096 size=2781704192: UDS Internal Error: UDS data structures are in an invalid state (66564)
Nov 28 10:17:19 storageqe-90 kernel: kvdo31:dedupeQ: Setting UDS index target state to error
Nov 28 10:17:19 storageqe-90 kernel: kvdo31:dmsetup: device 'vdo2' stopped


I repeatedly removed and created VDO on the device, even wrote a bit of data to it (60M) to make it a bit slower on removal. The whole issue seems to be some sort of race condition, where index is being created at the same time as the old is still removing.
I am not able to easily reproduce it yet, but the race condition seems to be the right explanation for this. The device is really slow:
# dd if=/dev/urandom of=/dev/mapper/vdo2 bs=4K count=20000 status=progress oflag=direct
73179136 bytes (73 MB, 70 MiB) copied, 14 s, 5.2 MB/s
20000+0 records in
20000+0 records out
81920000 bytes (82 MB, 78 MiB) copied, 14.4893 s, 5.7 MB/s
The speed of this seems a bit too low, as writing to disks directly happens at 60MB/s, directio to vdo on just disk runs at roughly 45MB/s. So the raid 6 slows that a lot and I am able to hit this race. The conditions looks like interrupted vdo removal and removing again right away and creating new device after few seconds.

But still I am not able to get to the point where I was when I reported this yet. At that time each consecutive vdo creation reproduced it.
In previous comment I reproduced it and was not able to reproduce it on new raid on different disks, so it is most probably some remnant on the drives that causes this.
Comment 8 Jakub Krysl 2019-02-28 14:18:56 UTC 
I've found somewhat reliable reproducer for this. Reproducibility is not 100%, seems to be around 40%. 

# Create new MD RAID 6
mdadm --create md127 --level 6 --raid-devices 4 /dev/sd[i,j,k,l]
# Keep creating and removing VDO device on topo
for i in `seq 1 10`; do vdo create --name vdo2 --device /dev/md127 --verbose --vdoSlabSize 8G; vdo remove --all; done
# The calltrace sometimes appears at the end of vdo removal

It seems to be some kind of race condition, as the requirement is to remove the vdo device quite soon after creation, delay in matter of seconds fails to reproduce this. Raid 6 under is also a requirement as it seems to slow down the whole creation quite a lot. I did not manage to reproduce it without the raid.

Managed to reproduce on storageqe-90 using local disks with 4K physical size sectors.
kmod-kvdo-6.2.0.293-47.el8.x86_64
vdo-6.2.0.293-10.el8.x86_64
kernel-4.18.0-67.el8.x86_64
Comment 9 Jakub Krysl 2019-02-28 14:43:47 UTC 
So further testing seems to show some dependency on stage of synchronization of the raid6 (on 1% resync now). I created new raid on /dev/sd[a,b,c,d] and failed to reproduce in ~30 tries. I kept trying and suddenly started to show the ~40% reproducibility rate (6 traces so far on /dev/sd[a,b,c,d], got around 30 of them in total)
Comment 10 Bryan Gurney 2019-02-28 14:58:11 UTC 
With the option "--uds-memory-size=0.25", the index of this VDO volume will cover the first 2.5 GB of the block device.  I wonder if there's some kind of interference while md is syncing the beginning of the array.
Comment 11 Jakub Krysl 2019-07-22 10:34:49 UTC 
I tried to reproduce this again with newest compose RHEL-8.1-20190701.0, but 200 cycles of reproducer from #c8 (and sync to 6%) could not hit a single trace on the same system. So I tested with the original compose RHEL-8.0-20181120.0 and managed to reproduce after 4 (!!!) cycles:


Jul 22 12:24:44 storageqe-90 kernel: kvdo3:dmsetup: device 'vdo2' stopped
Jul 22 12:24:46 storageqe-90 kernel: kvdo4:dmsetup: underlying device, REQ_FLUSH: supported, REQ_FUA: supported
Jul 22 12:24:46 storageqe-90 kernel: kvdo4:dmsetup: Using write policy async automatically.
Jul 22 12:24:46 storageqe-90 kernel: kvdo4:dmsetup: starting device 'vdo2'
Jul 22 12:24:46 storageqe-90 kernel: kvdo4:dmsetup: zones: 1 logical, 1 physical, 1 hash; base threads: 5
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:journalQ: VDO commencing normal operation
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:dmsetup: Setting UDS index target state to online
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:dmsetup: device 'vdo2' started
Jul 22 12:24:48 storageqe-90 kernel: uds: kvdo4:dedupeQ: creating index: dev=/dev/disk/by-id/md-uuid-6be0d15a:dad0e03a:b30390bc:8c9cd2d0 offset=4096 size=2781704192
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:dmsetup: resuming device 'vdo2'
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:dmsetup: device 'vdo2' resumed
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:packerQ: compression is enabled
Jul 22 12:24:48 storageqe-90 UDS/vdodmeventd[13680]: INFO   (vdodmeventd/13680) VDO device vdo2 is now registered with dmeventd for monitoring
Jul 22 12:24:48 storageqe-90 lvm[13310]: Monitoring VDO pool vdo2.
Jul 22 12:24:48 storageqe-90 UDS/vdodmeventd[13688]: INFO   (vdodmeventd/13688) VDO device vdo2 is now unregistered from dmeventd
Jul 22 12:24:48 storageqe-90 dmeventd[13310]: No longer monitoring VDO pool vdo2.
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:dmsetup: suspending device 'vdo2'
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:dmsetup: device 'vdo2' suspended
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:dmsetup: stopping device 'vdo2'
Jul 22 12:24:48 storageqe-90 kernel: kvdo4:dmsetup: Setting UDS index target state to closed
Jul 22 12:24:48 storageqe-90 kernel: uds: kvdo4:dedupeQ: Using 16 indexing zones for concurrency.
Jul 22 12:24:55 storageqe-90 kernel: uds: kvdo4:dedupeQ: assertion "delta lists per chapter (67108864) is too large" (((deltaListsPerChapter - 1) <= ((uint16_t)~0ul))) failed at /builddir/build/BUILD/kvdo-2f1ca5020fb69bbbb6338a6d6e60f31e44a2d26a/obj/./uds/indexPageMap.c:73
Jul 22 12:24:55 storageqe-90 kernel: uds: kvdo4:dedupeQ: [backtrace]
Jul 22 12:24:55 storageqe-90 kernel: CPU: 4 PID: 13661 Comm: kvdo4:dedupeQ Kdump: loaded Tainted: G           OE    --------- ---  4.18.0-40.el8.x86_64 #1
Jul 22 12:24:55 storageqe-90 kernel: Hardware name: Supermicro AS -2023US-TR4/H11DSU-iN, BIOS 1.1a 04/26/2018
Jul 22 12:24:55 storageqe-90 kernel: Call Trace:
Jul 22 12:24:55 storageqe-90 kernel: dump_stack+0x5c/0x80
Jul 22 12:24:55 storageqe-90 kernel: assertionFailed+0x4f/0x70 [uds]
Jul 22 12:24:55 storageqe-90 kernel: ? makePageCache+0x1cf/0x280 [uds]
Jul 22 12:24:55 storageqe-90 kernel: makeIndexPageMap+0xf5/0x110 [uds]
Jul 22 12:24:55 storageqe-90 kernel: allocateVolume+0x365/0x4d0 [uds]
Jul 22 12:24:55 storageqe-90 kernel: makeVolume+0x83/0x1e0 [uds]
Jul 22 12:24:55 storageqe-90 kernel: allocateIndex+0x1df/0x310 [uds]
Jul 22 12:24:55 storageqe-90 kernel: makeIndex+0x4c/0x4f0 [uds]
Jul 22 12:24:55 storageqe-90 kernel: ? makeRequestQueue+0xd7/0x100 [uds]
Jul 22 12:24:55 storageqe-90 kernel: ? randomCompileTimeAssertions+0x10/0x10 [uds]
Jul 22 12:24:55 storageqe-90 kernel: makeLocalIndexRouter+0x137/0x1b0 [uds]
Jul 22 12:24:55 storageqe-90 kernel: ? updateRequestContextStats+0x100/0x100 [uds]
Jul 22 12:24:55 storageqe-90 kernel: makeLocalGrid+0x118/0x210 [uds]
Jul 22 12:24:55 storageqe-90 kernel: makeLocalIndex+0x263/0x2c0 [uds]
Jul 22 12:24:55 storageqe-90 kernel: changeDedupeState+0x102/0x400 [kvdo]
Jul 22 12:24:55 storageqe-90 kernel: workQueueRunner+0x1b6/0x650 [kvdo]
Jul 22 12:24:55 storageqe-90 kernel: ? finish_wait+0x80/0x80
Jul 22 12:24:55 storageqe-90 kernel: ? stringToUInt+0x60/0x60 [kvdo]
Jul 22 12:24:55 storageqe-90 kernel: kthread+0x112/0x130
Jul 22 12:24:55 storageqe-90 kernel: ? kthread_bind+0x30/0x30
Jul 22 12:24:55 storageqe-90 kernel: ret_from_fork+0x22/0x40
Jul 22 12:24:55 storageqe-90 kernel: uds: kvdo4:dedupeQ: could not allocate index: UDS Internal Error: UDS data structures are in an invalid state (66564)
Jul 22 12:24:55 storageqe-90 kernel: uds: kvdo4:dedupeQ: failed to create index: UDS Internal Error: UDS data structures are in an invalid state (66564)
Jul 22 12:24:55 storageqe-90 kernel: uds: kvdo4:dedupeQ: Failed to make router: UDS Internal Error: UDS data structures are in an invalid state (66564)
Jul 22 12:24:55 storageqe-90 kernel: uds: kvdo4:dedupeQ: Failed creating index: UDS Internal Error: UDS data structures are in an invalid state (66564)
Jul 22 12:24:55 storageqe-90 kernel: kvdo4:dedupeQ: Error creating index dev=/dev/disk/by-id/md-uuid-6be0d15a:dad0e03a:b30390bc:8c9cd2d0 offset=4096 size=2781704192: UDS Internal Error: UDS data structures are in an invalid state (66564)
Jul 22 12:24:55 storageqe-90 kernel: kvdo4:dedupeQ: Setting UDS index target state to error
Jul 22 12:24:55 storageqe-90 kernel: kvdo4:dmsetup: device 'vdo2' stopped


So it seems it got fixed somewhere along the road. But before closing I would like to know when exactly it got fixed and what was the cause. My guess is MegaRaid driver interfering with mdadm sync and providing false data at crucial moment...
Comment 12 Sweet Tea Dorminy 2019-07-23 17:52:10 UTC 
Attempts at reproducing indicate that this is a problem when we get a partly valid UDS index on disk -- we try to udsRebuildLocalIndex() and get all the way to getting a weird delta list number, due to the garbage on disk. We thought garbage on disk would throw back a UDS error, but this form of garbage gets an assertion failure, resulting in a hang/stop rather than a reformatting of the old index.
Comment 13 Sweet Tea Dorminy 2019-07-23 23:22:49 UTC 
#c12 ^that comment is probably wrong, please ignore.
Comment 14 Thomas Jaskiewicz 2019-07-24 20:13:18 UTC 
This is caused by a race that you only see if you do a dmsetup create followed immediately by a dmsetup remove.  The index part of vdo create is done in the kernel by an asynchronous background thread.  An immediate dmsetup remove can free a block of memory that the index creation is still using.

The symptom will likely be an assertion failure inside a makeIndex call.
Comment 15 Sweet Tea Dorminy 2019-07-25 02:14:09 UTC 
I have tested on storageqe-90 a scratch version with the race fixed, and was unable to reproduce it while the raceless version showed it nearly every time. I am hopeful that this is also reflected in QE's testing when a version is created with the fix.
Comment 17 Jakub Krysl 2019-08-20 10:51:44 UTC 
kmod-kvdo-6.2.1.134-56.el8.x86_64

Using direct dmsetup now failed to reproduce after 1000 cycles:
# mdadm --create md127 --level 6 --raid-devices 4 /dev/sd[i,j,k,l]; vdoformat /dev/md127 --slab-bits=21; for i in `seq 1 1000`; do dmsetup create vdo1 --uuid VDO-d87a7dfc-4d4b-4749-a2e0-7e5c3bf244dd --table '0 38995340448 vdo V2 /dev/md127 4883152384 4096 32768 16380 on auto vdo maxDiscard 1 ack 1 bio 4 bioRotationInterval 64 cpu 2 hash 1 logical 1 physical 1'; dmsetup remove vdo1; done
Comment 20 errata-xmlrpc 2019-11-05 22:12:24 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-2019:3548