Intermittent FTL test failure (ASAN)

[jimharris]

https://dqtibwqq6s6ux.cloudfront.net/results/autotest-per-patch/builds/26350/archive/nvme_autotest/build.log

Relevant part of the log:

Running I/O for 4 seconds...

==2690298==ERROR: AddressSanitizer: heap-use-after-free on address 0x60b0000105a0 at pc 0x0000006bc515 bp 0x7ffdb4b61580 sp 0x7ffdb4b61570
READ of size 8 at 0x60b0000105a0 thread T0 (reactor_0)
#0 0x6bc514 in ftl_anm_log_page_cb /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_anm.c:185
#1 0x56e31a in nvme_user_copy_cmd_complete /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme.c:189
#2 0x54811c in nvme_complete_request /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme_internal.h:941
#3 0x5563c2 in nvme_pcie_qpair_complete_tracker /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme_pcie.c:1241
#4 0x561767 in nvme_pcie_qpair_process_completions /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme_pcie.c:2091
#5 0x57a8b7 in nvme_transport_qpair_process_completions /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme_transport.c:221
#6 0x566518 in spdk_nvme_qpair_process_completions /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme_qpair.c:413
#7 0x56d53a in spdk_nvme_wait_for_completion_robust_lock /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme.c:125
#8 0x56d797 in spdk_nvme_wait_for_completion /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme.c:139
#9 0x55b016 in nvme_pcie_ctrlr_delete_io_qpair /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme_pcie.c:1627
#10 0x579b58 in nvme_transport_ctrlr_delete_io_qpair /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme_transport.c:179
#11 0x5147ed in spdk_nvme_ctrlr_free_io_qpair /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/nvme/nvme_ctrlr.c:348
#12 0x6d2d94 in ftl_dev_free_thread /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_init.c:616
#13 0x6d6761 in ftl_dev_free_sync /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_init.c:950
#14 0x6d7447 in ftl_halt_poller /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_init.c:991
#15 0x7681e7 in spdk_thread_poll /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/thread/thread.c:492
#16 0x74d4a6 in _spdk_reactor_run /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/reactor.c:247
#17 0x74e227 in spdk_reactors_start /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/reactor.c:331
#18 0x74735f in spdk_app_start /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/app.c:680
#19 0x41422f in main /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/test/bdev/bdevperf/bdevperf.c:1153
#20 0x7f514e12f11a in __libc_start_main (/lib64/libc.so.6+0x2311a)
#21 0x408379 in _start (/var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/test/bdev/bdevperf/bdevperf+0x408379)

0x60b0000105a0 is located 32 bytes inside of 104-byte region [0x60b000010580,0x60b0000105e8)
freed by thread T0 (reactor_0) here:
#0 0x7f51516cd880 in __interceptor_free (/lib64/libasan.so.5+0xee880)
#1 0x6bddda in ftl_anm_ctrlr_free /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_anm.c:303
#2 0x6bfaa3 in ftl_anm_unregister_device /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_anm.c:420
#3 0x6d7433 in ftl_halt_poller /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_init.c:990
#4 0x7681e7 in spdk_thread_poll /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/thread/thread.c:492
#5 0x74d4a6 in _spdk_reactor_run /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/reactor.c:247
#6 0x74e227 in spdk_reactors_start /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/reactor.c:331
#7 0x74735f in spdk_app_start /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/app.c:680
#8 0x41422f in main /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/test/bdev/bdevperf/bdevperf.c:1153
#9 0x7f514e12f11a in __libc_start_main (/lib64/libc.so.6+0x2311a)

previously allocated by thread T0 (reactor_0) here:
#0 0x7f51516cde50 in calloc (/lib64/libasan.so.5+0xeee50)
#1 0x6bde0d in ftl_anm_ctrlr_alloc /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_anm.c:311
#2 0x6be712 in ftl_anm_register_device /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_anm.c:374
#3 0x6d23ba in _ftl_dev_init_thread /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_init.c:568
#4 0x765935 in _spdk_msg_queue_run_batch /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/thread/thread.c:388
#5 0x766b5b in spdk_thread_poll /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/thread/thread.c:440
#6 0x74d4a6 in _spdk_reactor_run /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/reactor.c:247
#7 0x74e227 in spdk_reactors_start /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/reactor.c:331
#8 0x74735f in spdk_app_start /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/event/app.c:680
#9 0x41422f in main /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/test/bdev/bdevperf/bdevperf.c:1153
#10 0x7f514e12f11a in __libc_start_main (/lib64/libc.so.6+0x2311a)

SUMMARY: AddressSanitizer: heap-use-after-free /var/jenkins/workspace/NVMe_tests/nvme_autotest/spdk/lib/ftl/ftl_anm.c:185 in ftl_anm_log_page_cb
Shadow bytes around the buggy address:
0x0c167fffa060: 00 00 00 00 00 fa fa fa fa fa fa fa fa fa 00 00
0x0c167fffa070: 00 00 00 00 00 00 00 00 00 00 00 fa fa fa fa fa
0x0c167fffa080: fa fa fa fa 00 00 00 00 00 00 00 00 00 00 00 00
0x0c167fffa090: 00 fa fa fa fa fa fa fa fa fa 00 00 00 00 00 00
0x0c167fffa0a0: 00 00 00 00 00 00 00 fa fa fa fa fa fa fa fa fa
=>0x0c167fffa0b0: fd fd fd fd[fd]fd fd fd fd fd fd fd fd fa fa fa
0x0c167fffa0c0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c167fffa0d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c167fffa0e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c167fffa0f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c167fffa100: 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
==2690298==ABORTING

[jimharris]

Looks like there's a pending anm log page event that doesn't complete until after the ctrlr has been freed.

[changpe1]

@jimharris I posted a patch https://review.gerrithub.io/#/c/spdk/spdk/+/448524/ to fix the issue. In ftl_halt_poller(), the controller will be released prior IO queue pair still exist.

[changpe1]

closing the issue now as the patch has been merged.