Re: [PATCH 00/16] scsi: libsas and users: Factor out LLDD TMF code

From: Damien Le Moal
Date: Thu Feb 03 2022 - 22:03:02 EST

Next message: Sergey Senozhatsky: "Re: [PATCH v1] printk: Fix incorrect __user type in proc_dointvec_minmax_sysadmin()"
Previous message: Anshuman Khandual: "Re: [RFC V1 04/31] powerpc/mm: Enable ARCH_HAS_VM_GET_PAGE_PROT"
In reply to: Damien Le Moal: "Re: [PATCH 00/16] scsi: libsas and users: Factor out LLDD TMF code"
Next in thread: John Garry: "Re: [PATCH 00/16] scsi: libsas and users: Factor out LLDD TMF code"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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

Next message: Sergey Senozhatsky: "Re: [PATCH v1] printk: Fix incorrect __user type in proc_dointvec_minmax_sysadmin()"
Previous message: Anshuman Khandual: "Re: [RFC V1 04/31] powerpc/mm: Enable ARCH_HAS_VM_GET_PAGE_PROT"
In reply to: Damien Le Moal: "Re: [PATCH 00/16] scsi: libsas and users: Factor out LLDD TMF code"
Next in thread: John Garry: "Re: [PATCH 00/16] scsi: libsas and users: Factor out LLDD TMF code"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]