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

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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




[Index of Archives]     [Kernel Newbies]     [Security]     [Netfilter]     [Bugtraq]     [Linux FS]     [Yosemite Forum]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Samba]     [Video 4 Linux]     [Device Mapper]     [Linux Resources]

  Powered by Linux