On 2/4/22 09:36, Damien Le Moal wrote: > On 2/4/22 00:55, John Garry wrote: >> On 03/02/2022 09:44, Damien Le Moal wrote: >> >> Hi Damien, >> >>>>>> [ 385.102073] sas: Enter sas_scsi_recover_host busy: 1 failed: 1 >>>>>> [ 385.108026] sas: sas_scsi_find_task: aborting task 0x000000007068ed73 >>>>>> [ 405.561099] pm80xx0:: pm8001_exec_internal_task_abort 757:TMF task >> >> Contrary to mentioning TMF in the log, this is not a TMF but rather an >> internal abort timing out. I don't think that this should ever happen. >> This command should just abort pending IO commands in the controller and >> not send anything to the target. So for this to timeout means a HW fault >> or driver bug. And I did not touch this code for pm8001. >> >>>>>> timeout. >>>>>> [ 405.568236] sas: sas_scsi_find_task: task 0x000000007068ed73 is >>>>>> aborted >>>>>> [ 405.574930] sas: sas_eh_handle_sas_errors: task 0x000000007068ed73 is >>>>>> aborted >>>>>> [ 411.192602] ata21.00: qc timeout (cmd 0xec) >>>>>> [ 431.672122] pm80xx0:: pm8001_exec_internal_task_abort 757:TMF task >>>>>> timeout. >>>>>> [ 431.679282] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4) >>>>>> [ 431.685544] ata21.00: revalidation failed (errno=-5) >>>>>> [ 441.911948] ata21.00: qc timeout (cmd 0xec) >>>>>> [ 462.391545] pm80xx0:: pm8001_exec_internal_task_abort 757:TMF task >>>>>> timeout. >>>>>> [ 462.398696] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4) >>>>>> [ 462.404992] ata21.00: revalidation failed (errno=-5) >>>>>> [ 492.598769] ata21.00: qc timeout (cmd 0xec) >>>>>> ... >>>>>> >> >> Do you have a fuller dmesg with my series? > > Here it is below. Conditions: I rebased everything on Linus latest > master, applied your series and the patch you sent below, rebooted with > pm80xx module option logging_level=31. > > Device scan is all OK. With the system idle, I simply start libzbc tests > on the SATA SMR drive I have on the HBA. > > The first command issued is 0x63 == NCQ NON DATA and seems to be OK, but > it seems that there are inconsistencies. And that may be what breaks the > adapter/driver state because everything after that command miserably > fails and does not complete. > > The inconsistency is this line says: > [ 137.193944] pm80xx0:: pm80xx_chip_sata_req 4581:no data > Which seems to be sensical for NCQ_NON_DATA command, but then, this line > seems wrong: > [ 137.228015] pm80xx0:: mpi_sata_completion 2515:FPDMA len = 8 > > I need to go and check the specs what the FIS reply format is for > NCQ_NON_DATA. > > > [ 137.187184] pm80xx0:: pm8001_queue_command 408:pm8001_task_exec device > [ 137.193944] pm80xx0:: pm80xx_chip_sata_req 4581:no data > [ 137.199339] pm80xx0:: pm80xx_chip_sata_req 4682:Sending Normal SATA > command 0x63 inb 4 > [ 137.207577] pm80xx0:: pm8001_mpi_msg_consume 1446:: CI=46 PI=47 > msgHeader=8104200d > [ 137.215399] pm80xx0:: mpi_sata_completion 2481:IO_SUCCESS > [ 137.220961] pm80xx0:: mpi_sata_completion 2503:SAS_PROTO_RESPONSE > len = 20 > [ 137.228015] pm80xx0:: mpi_sata_completion 2515:FPDMA len = 8 > [ 137.233878] pm80xx0:: pm8001_mpi_msg_free_set 1403: CI=47 PI=47 > [ 137.236696] pm80xx0:: pm8001_queue_command 408:pm8001_task_exec device > [ 137.247102] pm80xx0:: pm80xx_chip_sata_req 4585:DMA > [ 137.252186] pm80xx0:: pm80xx_chip_sata_req 4593:FPDMA > [ 137.257400] pm80xx0:: pm80xx_chip_sata_req 4682:Sending Normal SATA > command 0x65 inb f > [ 167.506280] sas: Enter sas_scsi_recover_host busy: 1 failed: 1 > [ 167.512363] sas: sas_scsi_find_task: aborting task 0x00000000aa372627 > [ 167.519049] pm80xx0:: pm8001_chip_abort_task 4607:cmd_tag = 2, abort > task tag = 0x1 > [ 187.969173] pm80xx0:: pm8001_exec_internal_task_abort 753:TMF task > timeout. > [ 187.976450] sas: sas_scsi_find_task: task 0x00000000aa372627 is aborted > [ 187.983244] sas: sas_eh_handle_sas_errors: task 0x00000000aa372627 is > aborted > [ 188.144734] pm80xx0:: pm8001_queue_command 408:pm8001_task_exec device > [ 188.151555] pm80xx0:: pm80xx_chip_sata_req 4588:PIO > [ 188.156648] pm80xx0:: pm80xx_chip_sata_req 4682:Sending Normal SATA > command 0xec inb 8 > [ 193.600813] ata21.00: qc timeout (cmd 0xec) > [ 193.605976] pm80xx0:: pm8001_chip_abort_task 4607:cmd_tag = 4, abort > task tag = 0x3 > [ 214.080236] pm80xx0:: pm8001_exec_internal_task_abort 753:TMF task > timeout. > [ 214.087563] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4) > [ 214.093929] ata21.00: revalidation failed (errno=-5) > [ 214.256233] pm80xx0:: pm8001_queue_command 408:pm8001_task_exec device > [ 214.263043] pm80xx0:: pm80xx_chip_sata_req 4588:PIO > [ 214.268128] pm80xx0:: pm80xx_chip_sata_req 4682:Sending Normal SATA > command 0xec inb 8 > [ 224.319899] ata21.00: qc timeout (cmd 0xec) > [ 224.324317] pm80xx0:: pm8001_chip_abort_task 4607:cmd_tag = 6, abort > task tag = 0x5 > [ 244.799433] pm80xx0:: pm8001_exec_internal_task_abort 753:TMF task > timeout. > [ 244.806750] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4) > [ 244.813110] ata21.00: revalidation failed (errno=-5) > [ 244.975500] pm80xx0:: pm8001_queue_command 408:pm8001_task_exec device > [ 244.982314] pm80xx0:: pm80xx_chip_sata_req 4588:PIO > [ 244.987400] pm80xx0:: pm80xx_chip_sata_req 4682:Sending Normal SATA > command 0xec inb 8 > [ 275.006814] ata21.00: qc timeout (cmd 0xec) > [ 275.011236] pm80xx0:: pm8001_chip_abort_task 4607:cmd_tag = 8, abort > task tag = 0x7 > [ 295.486387] pm80xx0:: pm8001_exec_internal_task_abort 753:TMF task > timeout. > [ 295.494025] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4) > [ 295.500390] ata21.00: revalidation failed (errno=-5) > [ 295.509179] ata21.00: disable device > [ 295.670556] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 1 > tries: 1 > [ 295.670570] sd 19:0:2:0: [sdj] REPORT ZONES start lba 0 failed > [ 295.689972] sd 19:0:2:0: [sdj] REPORT ZONES: Result: hostbyte=DID_OK > driverbyte=DRIVER_OK > [ 295.700621] sd 19:0:2:0: [sdj] Sense Key : Not Ready [current] > [ 295.708975] sd 19:0:2:0: [sdj] Add. Sense: Logical unit not ready, > hard reset required > [ 295.719331] sd 19:0:2:0: [sdj] 0 4096-byte logical blocks: (0 B/0 B) > [ 295.728727] sd 19:0:2:0: [sdj] Write Protect is on > [ 295.737928] sdj: detected capacity change from 39063650304 to 0 > [ 295.826347] sd 19:0:2:0: [sdj] tag#158 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 295.838761] sd 19:0:2:0: [sdj] tag#158 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 295.920864] sd 19:0:2:0: [sdj] tag#780 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 295.933341] sd 19:0:2:0: [sdj] tag#780 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 296.010417] sd 19:0:2:0: [sdj] tag#248 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 296.022275] sd 19:0:2:0: [sdj] tag#248 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 296.101348] sd 19:0:2:0: [sdj] tag#949 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 296.113924] sd 19:0:2:0: [sdj] tag#949 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 296.192258] sd 19:0:2:0: [sdj] tag#25 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 296.204788] sd 19:0:2:0: [sdj] tag#25 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 296.284546] sd 19:0:2:0: [sdj] tag#273 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 296.297126] sd 19:0:2:0: [sdj] tag#273 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 296.376896] sd 19:0:2:0: [sdj] tag#653 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 296.389475] sd 19:0:2:0: [sdj] tag#653 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 296.468095] sd 19:0:2:0: [sdj] tag#159 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 296.479974] sd 19:0:2:0: [sdj] tag#159 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 296.560861] sd 19:0:2:0: [sdj] tag#274 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 296.572792] sd 19:0:2:0: [sdj] tag#274 CDB: Test Unit Ready 00 00 00 > 00 00 00 > [ 296.654506] sd 19:0:2:0: [sdj] tag#727 FAILED Result: > hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s > [ 296.667151] sd 19:0:2:0: [sdj] tag#727 CDB: Test Unit Ready 00 00 00 > 00 00 00 > > After these messages, the tests exit on failure (drive dropped) and > there are no more messages. Doing rmmod or anything else get stuck too. > I have to reset the machine to get back to a good state. > > I am starting to think that NCQ NON DATA command is being very badly > handled... Switching the tests to run with all non-NCQ commands is > working fine, albeit horribly slow (much slower than with other HBAs, > e.g. Broadcom). > > Digging... I missed a KASAN splat during device scan on boot: 33.725184] ================================================================== [ 33.746168] BUG: KASAN: use-after-free in __lock_acquire+0x41a5/0x5b50 [ 33.764181] Read of size 8 at addr ffff88818a318660 by task kworker/u64:6/583 [ 33.786726] [ 33.802181] CPU: 6 PID: 583 Comm: kworker/u64:6 Not tainted 5.17.0-rc2+ #1425 [ 33.823777] Hardware name: Supermicro Super Server/H12SSL-NT, BIOS 2.1 06/02/2021 [ 33.845112] Workqueue: events_unbound async_run_entry_fn [ 33.864185] Call Trace: [ 33.880147] <TASK> [ 33.896183] dump_stack_lvl+0x45/0x59 [ 33.913180] print_address_description.constprop.0+0x1f/0x120 [ 33.932108] ? __lock_acquire+0x41a5/0x5b50 [ 33.949156] kasan_report.cold+0x83/0xdf [ 33.965184] ? __lock_acquire+0x41a5/0x5b50 [ 33.982178] __lock_acquire+0x41a5/0x5b50 [ 33.998919] ? _raw_spin_unlock_irqrestore+0x23/0x40 [ 34.019831] ? pm8001_mpi_build_cmd+0x3ad/0x780 [pm80xx] [ 34.039171] ? lockdep_hardirqs_on_prepare+0x3e0/0x3e0 [ 34.057941] ? pm80xx_chip_sata_req+0xa78/0x1cb0 [pm80xx] [ 34.076181] lock_acquire+0x194/0x490 [ 34.092185] ? pm8001_queue_command+0x842/0x1150 [pm80xx] [ 34.113174] ? lock_release+0x6b0/0x6b0 [ 34.130184] _raw_spin_lock+0x2c/0x40 [ 34.147848] ? pm8001_queue_command+0x842/0x1150 [pm80xx] [ 34.165964] pm8001_queue_command+0x842/0x1150 [pm80xx] [ 34.185178] ? __raw_spin_lock_init+0x3b/0x110 [ 34.202748] sas_ata_qc_issue+0x6d8/0xba0 [libsas] [ 34.220097] ata_qc_issue+0x4f8/0xcc0 [libata] [ 34.242185] ata_exec_internal_sg+0xacd/0x1790 [libata] [ 34.261176] ? ata_qc_issue+0xcc0/0xcc0 [libata] [ 34.279059] ? memset+0x20/0x40 [ 34.296170] ata_read_log_page+0x361/0x5d0 [libata] [ 34.313999] ? ata_dev_set_feature+0x330/0x330 [libata] [ 34.332183] ? ata_dev_set_feature+0x330/0x330 [libata] [ 34.353174] ? vsprintf+0x10/0x10 [ 34.369194] ata_identify_page_supported+0xb8/0x2e0 [libata] [ 34.388168] ata_dev_configure+0x161b/0x4b90 [libata] [ 34.407172] ? _raw_spin_trylock_bh+0x50/0x70 [ 34.424188] ? ata_do_dev_read_id+0xe0/0xe0 [libata] [ 34.442100] ? ata_hpa_resize+0xce0/0xce0 [libata] [ 34.458927] ? memcpy+0x39/0x60 [ 34.475172] ? ata_dev_read_id+0xf70/0xf70 [libata] [ 34.492172] ata_dev_revalidate+0x172/0x2b0 [libata] [ 34.508945] ata_do_set_mode+0x11f5/0x2410 [libata] [ 34.525762] ? find_held_lock+0x2c/0x110 [ 34.542169] ? ata_dev_revalidate+0x2b0/0x2b0 [libata] [ 34.558174] ? ata_eh_recover+0x181e/0x33e0 [libata] [ 34.575698] ata_set_mode+0x2e8/0x3f0 [libata] [ 34.592016] ? lockdep_hardirqs_on_prepare+0x273/0x3e0 [ 34.609166] ? _raw_spin_unlock_irqrestore+0x2d/0x40 [ 34.625180] ? trace_hardirqs_on+0x1c/0x110 [ 34.641190] ata_eh_recover+0x23be/0x33e0 [libata] [ 34.658188] ? sas_ata_hard_reset+0x310/0x310 [libsas] [ 34.675144] ? sas_ata_qc_fill_rtf+0x90/0x90 [libsas] [ 34.691182] ? ata_link_nr_enabled+0x50/0x50 [libata] [ 34.708173] ? find_held_lock+0x2c/0x110 [ 34.723717] ? lock_release+0x1dd/0x6b0 [ 34.740168] ? ata_scsi_port_error_handler+0x4d1/0xe60 [libata] [ 34.758180] ? sas_ata_hard_reset+0x310/0x310 [libsas] [ 34.774868] ? sas_ata_hard_reset+0x310/0x310 [libsas] [ 34.791740] ? sas_ata_qc_fill_rtf+0x90/0x90 [libsas] [ 34.808169] ata_do_eh+0x75/0x150 [libata] [ 34.824178] ? trace_hardirqs_on+0x1c/0x110 [ 34.840176] ata_scsi_port_error_handler+0x536/0xe60 [libata] [ 34.857110] ? sas_fail_probe.constprop.0+0xb5/0xb5 [libsas] [ 34.874168] async_sas_ata_eh+0xcf/0x112 [libsas] [ 34.890978] async_run_entry_fn+0x93/0x500 [ 34.907184] process_one_work+0x7f0/0x1310 [ 34.923188] ? lock_release+0x6b0/0x6b0 [ 34.939169] ? pwq_dec_nr_in_flight+0x230/0x230 [ 34.955754] ? rwlock_bug.part.0+0x90/0x90 [ 34.972232] worker_thread+0x598/0xf70 [ 34.987993] ? process_one_work+0x1310/0x1310 [ 35.004971] kthread+0x28f/0x330 [ 35.020168] ? kthread_complete_and_exit+0x20/0x20 [ 35.037168] ret_from_fork+0x1f/0x30 [ 35.052525] </TASK> [ 35.066623] [ 35.081181] Allocated by task 583: [ 35.097188] kasan_save_stack+0x1e/0x40 [ 35.113930] __kasan_slab_alloc+0x64/0x80 [ 35.130571] kmem_cache_alloc+0x1a6/0x450 [ 35.148041] sas_alloc_task+0x1b/0x80 [libsas] [ 35.163187] sas_ata_qc_issue+0x1a8/0xba0 [libsas] [ 35.180145] ata_qc_issue+0x4f8/0xcc0 [libata] [ 35.195456] ata_exec_internal_sg+0xacd/0x1790 [libata] [ 35.213179] ata_read_log_page+0x361/0x5d0 [libata] [ 35.228915] ata_identify_page_supported+0xb8/0x2e0 [libata] [ 35.246182] ata_dev_configure+0x161b/0x4b90 [libata] [ 35.262189] ata_dev_revalidate+0x172/0x2b0 [libata] [ 35.280168] ata_do_set_mode+0x11f5/0x2410 [libata] [ 35.296178] ata_set_mode+0x2e8/0x3f0 [libata] [ 35.311176] ata_eh_recover+0x23be/0x33e0 [libata] [ 35.327168] ata_do_eh+0x75/0x150 [libata] [ 35.342188] ata_scsi_port_error_handler+0x536/0xe60 [libata] [ 35.360166] async_sas_ata_eh+0xcf/0x112 [libsas] [ 35.376365] async_run_entry_fn+0x93/0x500 [ 35.392175] process_one_work+0x7f0/0x1310 [ 35.408169] worker_thread+0x598/0xf70 [ 35.424172] kthread+0x28f/0x330 [ 35.439850] ret_from_fork+0x1f/0x30 [ 35.456177] [ 35.469109] Freed by task 0: [ 35.482174] kasan_save_stack+0x1e/0x40 [ 35.496889] kasan_set_track+0x21/0x30 [ 35.512165] kasan_set_free_info+0x20/0x30 [ 35.527168] __kasan_slab_free+0xd8/0x110 [ 35.542454] kmem_cache_free.part.0+0x67/0x170 [ 35.559111] mpi_sata_completion+0x99c/0x2d70 [pm80xx] [ 35.576044] process_oq+0xbd2/0x7c20 [pm80xx] [ 35.592169] pm80xx_chip_isr+0x94/0x130 [pm80xx] [ 35.608180] tasklet_action_common.constprop.0+0x24b/0x2f0 [ 35.625171] __do_softirq+0x1b5/0x82d [ 35.640187] [ 35.653755] The buggy address belongs to the object at ffff88818a318640 [ 35.653755] which belongs to the cache sas_task of size 320 [ 35.688176] The buggy address is located 32 bytes inside of [ 35.688176] 320-byte region [ffff88818a318640, ffff88818a318780) [ 35.723167] The buggy address belongs to the page: [ 35.740168] page:000000006ae5e64e refcount:1 mapcount:0 mapping:0000000000000000 index:0xffff88818a3184c0 pfn:0x18a318 [ 35.762689] flags: 0x20000000000200(slab|node=0|zone=2) [ 35.780183] raw: 0020000000000200 ffff888100f02440 ffff888100f02440 ffff888100f09e00 [ 35.800300] raw: ffff88818a3184c0 ffff88818a318040 0000000100000008 0000000000000000 [ 35.821174] page dumped because: kasan: bad access detected [ 35.840167] [ 35.855170] Memory state around the buggy address: [ 35.873169] ffff88818a318500: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 35.893918] ffff88818a318580: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 35.913172] >ffff88818a318600: fc fc fc fc fc fc fc fc fa fb fb fb fb fb fb fb [ 35.932176] ^ [ 35.953171] ffff88818a318680: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb [ 35.974171] ffff88818a318700: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb [ 35.994168] ================================================================== This is the submission path, not completion. The code is: (gdb) list *(pm8001_queue_command+0x842) 0x3d42 is in pm8001_queue_command (drivers/scsi/pm8001/pm8001_sas.c:491). 486 atomic_dec(&pm8001_dev->running_req); 487 goto err_out_tag; 488 } 489 /* TODO: select normal or high priority */ 490 spin_lock(&t->task_state_lock); 491 t->task_state_flags |= SAS_TASK_AT_INITIATOR; 492 spin_unlock(&t->task_state_lock); 493 } while (0); 494 rc = 0; 495 goto out_done; So the task is already completed when the submission path tries to set the state flag ? Debugging... -- Damien Le Moal Western Digital Research
