Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Damien Le Moal]

On 6/22/24 12:31 PM, Yihang Li wrote:
> Hi Damien,
> 
> Thanks for your reply.
> 
> On 2024/6/19 7:11, Damien Le Moal wrote:
>> On 6/18/24 22:29, Yihang Li wrote:
>>> Hi Damien,
>>>
>>> I found out that two issues is caused by commit 0c76106cb975 ("scsi: sd:
>>> Fix TCG OPAL unlock on system resume") and 626b13f015e0 ("scsi: Do not
>>> rescan devices with a suspended queue").
>>>
>>> The two issues as follows for the situation that there are ATA disks
>>> connected with SAS controller:
>>
>> Which controller ? What is the driver ?
> 
> I'm using the hisi_sas_v3_hw driver and it supports HiSilicon's SAS controller.

I do not have access to this HBA, but I have one that uses libsas/pm8001 driver
so I will try to test with that.

>>> (1) FLR is triggered after all disks and controller are suspended. As a
>>> result, the number of disks is abnormal.
>>
>> I am assuming here that FLR means PCI "Function Level Reset" ?
> 
> Yes, I am talking about the PCI "Function Level Reset"
> 
>> FLR and disk/controller suspend execution timing are unrelated. FLR can be
>> triggered at any time through sysfs. So please give details here. Why is FLR
>> done when the system is being suspended ?
> 
> Yes, it is because FLR can be triggered at any time that we are testing the
> reliability of executing FLR commands after disk/controller suspended.

"can be triggered" ? FLR is not a random asynchronous event. It is an action
that is *issued* by a user with sys admin rights. And such users can do a lot
of things that can break a machine...

I fail to see the point of doing a function reset while the device is
suspended. But granted, I guess the device should comeback up in such case,
though I would like to hear what the PCI guys have to say about this.

Bjorn,

Is reseting a suspended PCI device something that should be/is supported ?

> Also, the system does not suspended because we have multiple controllers and
> we only suspend one of them and the attached disk devices while the system is
> running in the other controller.
> 
>>
>>> (2) After all disks and controller are suspended, and resuming all disks
>>> again, the driver reference counting is not 0 (The value of "Used" in the
>>> lsmod command output is not 0).
>>
>> Resuming all disks again ? So you mean system resume ?
>> Are we talking about system suspend to ram ? Hybernation ? or something else ?
>> (e.g. a controller reset through PCI FLR ?)
> 
> As mentioned earlier, we have multiple controllers, only suspend one of them and
> the attached data disks, and then resuming the disks again.
> 
>>
>> Please clarify exactly what your adapter is and the full procedure you do to
>> trigger the issue so that we can try to recreate it.
> 
> The system has two HiSilicon's SAS controllers. Controller A is connected to the
> system disk, and controller B is connected to multiple SATA disks.
> 
> The issue 1:
> a. Suspend all disks on controller B.
> b. Suspend controller B.
> c. Trigger the PCI FLR on controller B through sysfs.
> d. The SATA disks connected to controller B is disabled by libata layer.

Thank you for the explanation, but as Niklas said, it would be a lot easier for
me to recreate the issue if you send the exact commands you execute to trigger
the issue. E.g. "suspend all disks" in step a can have a lot of different
meaning depending on which type os suspend you are using... So please send the
exact commands you use.
is what exactly ? autosuspend ? or something else ?

> 
> kernel message is as follows:
> [root@localhost]# echo 1 > /sys/bus/pci/devices/0000:b4:02.0/reset		------> trigger PCI FLR
> [  270.479991] hisi_sas_v3_hw 0000:b4:02.0: resuming from operating state [D0]	------> resuming SAS controller
> [  271.819775] hisi_sas_v3_hw 0000:b4:02.0: waiting up to 25 seconds for 7 phys to resume
> [  271.820324] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
> [  271.835183] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
> [  271.835199] hisi_sas_v3_hw 0000:b4:02.0: dev[8:5] found
> [  271.835786] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy5 link_rate=10(sata)
> [  271.835791] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy6 link_rate=10(sata)
> [  271.846911] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy4 link_rate=10(sata)
> [  271.851676] hisi_sas_v3_hw 0000:b4:02.0: dev[9:5] found
> [  271.851688] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
> [  271.851702] sas: ata5: end_device-6:0: dev error handler
> [  271.851708] sas: ata6: end_device-6:1: dev error handler
> [  271.851710] sas: ata7: end_device-6:2: dev error handler
> [  271.851716] sas: ata8: end_device-6:3: dev error handler
> [  271.851717] sas: ata9: end_device-6:4: dev error handler
> [  271.851718] sas: ata10: end_device-6:5: dev error handler
> [  271.855161] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy1 link_rate=10(sata)
> [  271.855547] hisi_sas_v3_hw 0000:b4:02.0: dev[10:5] found
> [  271.855760] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy7 phy_state=0x73
> [  271.855763] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy7 down
> [  271.899322] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy3 link_rate=11
> [  271.902737] hisi_sas_v3_hw 0000:b4:02.0: dev[11:5] found
> [  271.950079] hisi_sas_v3_hw 0000:b4:02.0: dev[12:5] found
> [  271.955569] hisi_sas_v3_hw 0000:b4:02.0: dev[13:5] found
> [  271.961037] hisi_sas_v3_hw 0000:b4:02.0: dev[14:1] found
> [  271.961052] hisi_sas_v3_hw 0000:b4:02.0: end of resuming controller	------> end of resuming controller
> [  271.973073] hisi_sas_v3_hw 0000:b4:02.0: FLR prepare			------> PCI FLR start
> [  272.032623] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
> [  272.039656] sas: sas_form_port: phy7 belongs to port0 already(1)!
> [  272.201518] ata5.00: configured for UDMA/133
> [  272.207713] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
> [  272.217777] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
> [  272.227672] sas: ata5: end_device-6:0: dev error handler
> [  272.227676] sas: ata6: end_device-6:1: dev error handler
> [  272.227682] sas: ata7: end_device-6:2: dev error handler
> [  272.227688] sas: ata8: end_device-6:3: dev error handler
> [  272.227695] sas: ata10: end_device-6:5: dev error handler
> [  272.227694] sas: ata9: end_device-6:4: dev error handler
> [  274.888594] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
> [  274.895614] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy5 link_rate=10(sata)
> [  274.895616] sas: sas_form_port: phy7 belongs to port0 already(1)!
> [  274.900251] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
> [  274.902647] sas: sas_form_port: phy5 belongs to port1 already(1)!
> [  274.902833] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy6 link_rate=10(sata)
> [  274.903023] sas: sas_form_port: phy0 belongs to port2 already(1)!
> [  274.914529] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy1 link_rate=10(sata)
> [  274.916099] sas: sas_form_port: phy6 belongs to port3 already(1)!
> [  274.916259] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy4 link_rate=10(sata)
> [  274.916439] sas: sas_form_port: phy1 belongs to port5 already(1)!
> [  274.961013] sas: sas_form_port: phy4 belongs to port4 already(1)!
> [  274.967338] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy3 link_rate=11
> [  274.983663] sas: sas_form_port: phy3 belongs to port6 already(1)!
> [  275.037230] hisi_sas_v3_hw 0000:b4:02.0: FLR done			------> PCI FLR done
> [  275.037232] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy0 phy_state=0xfa
> [  275.049223] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy0 down
> [  275.204142] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
> [  275.211001] sas: sas_form_port: phy0 belongs to port2 already(1)!
> [  278.223079] hisi_sas_v3_hw 0000:b4:02.0: entering suspend state	------> the controller suspend again
> [  280.527655] ata7.00: qc timeout after 5000 msecs (cmd 0x27)		------> revalidate ATA devices
> [  280.535667] sas: sas_ata_internal_abort: Task 00000000682de2e7 already finished.
> [  280.543483] ata7.00: failed to read native max address (err_mask=0x4)
> [  280.551671] ata7.00: HPA support seems broken, skipping HPA handling
> [  280.558317] ata7.00: revalidation failed (errno=-5)
> [  280.563437] sas: Executing internal abort failed 5000000000000600 (-22)
> [  280.571670] hisi_sas_v3_hw 0000:b4:02.0: I_T nexus reset: internal abort (-22)
> [  280.579338] sas: ata7: end_device-6:2: Unable to reset ata device?
> [  280.751675] sas: lldd_execute_task returned: -22
> [  280.759664] ata7.00: failed to IDENTIFY (I/O error, err_mask=0x40)
> [  280.766063] ata7.00: revalidation failed (errno=-5)
> [  285.911663] sas: Executing internal abort failed 5000000000000600 (-22)
> [  285.919667] hisi_sas_v3_hw 0000:b4:02.0: I_T nexus reset: internal abort (-22)
> [  285.927353] sas: ata7: end_device-6:2: Unable to reset ata device?
> [  286.095677] sas: lldd_execute_task returned: -22
> [  286.103666] ata7.00: failed to IDENTIFY (I/O error, err_mask=0x40)
> [  286.110078] ata7.00: revalidation failed (errno=-5)			------> revalidation failed due to the controller is suspend state
> [  286.119424] ata7.00: disable device					------> disable device due to revalidation failed
> [  286.123185] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
> [  286.133236] sas: sas_resume_sata: for direct-attached device 5000000000000600 returned -19
> ...
> 
> The issue 2:
> a. Suspend all disks on controller B.
> b. Suspend controller B.
> c. Resuming all disks on controller B.
> d. Run the "lsmod" command to check the driver reference counting.
> 
> Thanks,
> Yihang
> 
>>
>>> For the issue 1, After all disks and controller are suspended, FLR command
>>> will resuming the controller and all sas ports. libsas layer will call
>>> ata_sas_port_resume() to resume ata port and schedule EH to recover it.
>>> In libata standard error handler ata_std_error_handler(), it will call ata
>>> reset function, revalidate ATA devices and issue ATA device command
>>> ATA_CMD_READ_NATIVE_MAX_EXT to read native max address. This command will
>>> failed due to the controller enter suspend state again and libata disable
>>> the device finally. The controller enter suspend state again because FLR
>>> command completes and the runtime PM usage counter is 0.
>>>
>>> In commit 0c76106cb975 ("scsi: sd: Fix TCG OPAL unlock on system resume")
>>> and 626b13f015e0 ("scsi: Do not rescan devices with a suspended queue"),
>>> use blk_queue_pm_only() to check the device request queue state, if the
>>> device request queue is not running, the device will not be rescanned.
>>> Therefore, the runtime PM usage counter of the controller will not
>>> increase so that the controller enters the suspended state again.
>>>
>>> For the issue 2, the cause is unknown.
>>>
>>> How to solve these two issues?
>>>
>>> regards,
>>> Yihang
>>>
>>

-- 
Damien Le Moal
Western Digital Research

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Yihang Li]

Hi Damien, Niklas,

Thanks for discussion here

On 2024/6/24 8:10, Damien Le Moal wrote:
> On 6/22/24 12:31 PM, Yihang Li wrote:
>> Hi Damien,
>>
>> Thanks for your reply.
>>
>> On 2024/6/19 7:11, Damien Le Moal wrote:
>>> On 6/18/24 22:29, Yihang Li wrote:
>>>> Hi Damien,
>>>>
>>>> I found out that two issues is caused by commit 0c76106cb975 ("scsi: sd:
>>>> Fix TCG OPAL unlock on system resume") and 626b13f015e0 ("scsi: Do not
>>>> rescan devices with a suspended queue").
>>>>
>>>> The two issues as follows for the situation that there are ATA disks
>>>> connected with SAS controller:
>>>
>>> Which controller ? What is the driver ?
>>
>> I'm using the hisi_sas_v3_hw driver and it supports HiSilicon's SAS controller.
> 
> I do not have access to this HBA, but I have one that uses libsas/pm8001 driver
> so I will try to test with that.

I will help with some tests if needed.

> 
>>>> (1) FLR is triggered after all disks and controller are suspended. As a
>>>> result, the number of disks is abnormal.
>>>
>>> I am assuming here that FLR means PCI "Function Level Reset" ?
>>
>> Yes, I am talking about the PCI "Function Level Reset"
>>
>>> FLR and disk/controller suspend execution timing are unrelated. FLR can be
>>> triggered at any time through sysfs. So please give details here. Why is FLR
>>> done when the system is being suspended ?
>>
>> Yes, it is because FLR can be triggered at any time that we are testing the
>> reliability of executing FLR commands after disk/controller suspended.
> 
> "can be triggered" ? FLR is not a random asynchronous event. It is an action
> that is *issued* by a user with sys admin rights. And such users can do a lot
> of things that can break a machine...
> 
> I fail to see the point of doing a function reset while the device is
> suspended. But granted, I guess the device should comeback up in such case,
> though I would like to hear what the PCI guys have to say about this.

I agree with the view that the device should comeback up to normal operation.
But at the moment, that's not the case.

> 
> Bjorn,
> 
> Is reseting a suspended PCI device something that should be/is supported ?
> 
>> Also, the system does not suspended because we have multiple controllers and
>> we only suspend one of them and the attached disk devices while the system is
>> running in the other controller.
>>
>>>
>>>> (2) After all disks and controller are suspended, and resuming all disks
>>>> again, the driver reference counting is not 0 (The value of "Used" in the
>>>> lsmod command output is not 0).
>>>
>>> Resuming all disks again ? So you mean system resume ?
>>> Are we talking about system suspend to ram ? Hybernation ? or something else ?
>>> (e.g. a controller reset through PCI FLR ?)
>>
>> As mentioned earlier, we have multiple controllers, only suspend one of them and
>> the attached data disks, and then resuming the disks again.
>>
>>>
>>> Please clarify exactly what your adapter is and the full procedure you do to
>>> trigger the issue so that we can try to recreate it.
>>
>> The system has two HiSilicon's SAS controllers. Controller A is connected to the
>> system disk, and controller B is connected to multiple SATA disks.
>>
>> The issue 1:
>> a. Suspend all disks on controller B.
>> b. Suspend controller B.
>> c. Trigger the PCI FLR on controller B through sysfs.
>> d. The SATA disks connected to controller B is disabled by libata layer.
> 
> Thank you for the explanation, but as Niklas said, it would be a lot easier for
> me to recreate the issue if you send the exact commands you execute to trigger
> the issue. E.g. "suspend all disks" in step a can have a lot of different
> meaning depending on which type os suspend you are using... So please send the
> exact commands you use.
> is what exactly ? autosuspend ? or something else ?

OK, first of all, I have the following controllers and disks in my system:
[root@localhost ~]# lsscsi -v
[6:0:0:0]    disk    ATA      SAMSUNG MZ7KM480 104Q  /dev/sda
  dir: /sys/bus/scsi/devices/6:0:0:0  [/sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0]
[6:0:1:0]    disk    ATA      HGST HUS724040AL A8B0  /dev/sdb
  dir: /sys/bus/scsi/devices/6:0:1:0  [/sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:1/end_device-6:1/target6:0:1/6:0:1:0]
[6:0:2:0]    disk    ATA      MG04ACA400N      FJ3J  /dev/sdc
  dir: /sys/bus/scsi/devices/6:0:2:0  [/sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:2/end_device-6:2/target6:0:2/6:0:2:0]
[6:0:3:0]    disk    ATA      MG04ACA400N      FJ3J  /dev/sdd
  dir: /sys/bus/scsi/devices/6:0:3:0  [/sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:3/end_device-6:3/target6:0:3/6:0:3:0]
[6:0:4:0]    disk    ATA      ST4000NM0035-1V4 TN03  /dev/sde
  dir: /sys/bus/scsi/devices/6:0:4:0  [/sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:4/end_device-6:4/target6:0:4/6:0:4:0]
[6:0:5:0]    disk    ATA      ST4000NM0035-1V4 TN03  /dev/sdf
  dir: /sys/bus/scsi/devices/6:0:5:0  [/sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:5/end_device-6:5/target6:0:5/6:0:5:0]
[6:0:6:0]    disk    SEAGATE  ST4000NM0025     N003  /dev/sdg
  dir: /sys/bus/scsi/devices/6:0:6:0  [/sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0]
[N:0:1:1]    dsk/nvm HWE56P433T2M002N__1                        /dev/nvme0n1	------> this is my system disk
  dir: /sys/class/nvme/nvme0/nvme0n1  [/sys/devices/pci0000:00/0000:00:0c.0/0000:03:00.0/nvme/nvme0/nvme0n1]

All disks are connected to the HiSilicon's SAS controller (0000:b4:02.0),
and my system disk is connected to another controller (0000:03:00.0).

In step a, I suspend all disks by issuing the following command to all disks
attached to the SAS controller 0000:b4:02.0:
[root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/control
[root@localhost ~]# echo 5000 > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/autosuspend_delay_ms
...
[root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/control
[root@localhost ~]# echo 5000 > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/autosuspend_delay_ms

Step b, Suspend the SAS controller:
[root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/power/control

At this point, the SAS controller is suspended. Next step c is trigger PCI FLR.
[root@localhost ~]# echo 1 > /sys/bus/pci/devices/0000:b4:02.0/reset

These are the exact commands triggered by issue 1.

> 
>>
>> kernel message is as follows:
>> [root@localhost]# echo 1 > /sys/bus/pci/devices/0000:b4:02.0/reset		------> trigger PCI FLR
>> [  270.479991] hisi_sas_v3_hw 0000:b4:02.0: resuming from operating state [D0]	------> resuming SAS controller
>> [  271.819775] hisi_sas_v3_hw 0000:b4:02.0: waiting up to 25 seconds for 7 phys to resume
>> [  271.820324] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
>> [  271.835183] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
>> [  271.835199] hisi_sas_v3_hw 0000:b4:02.0: dev[8:5] found
>> [  271.835786] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy5 link_rate=10(sata)
>> [  271.835791] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy6 link_rate=10(sata)
>> [  271.846911] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy4 link_rate=10(sata)
>> [  271.851676] hisi_sas_v3_hw 0000:b4:02.0: dev[9:5] found
>> [  271.851688] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
>> [  271.851702] sas: ata5: end_device-6:0: dev error handler
>> [  271.851708] sas: ata6: end_device-6:1: dev error handler
>> [  271.851710] sas: ata7: end_device-6:2: dev error handler
>> [  271.851716] sas: ata8: end_device-6:3: dev error handler
>> [  271.851717] sas: ata9: end_device-6:4: dev error handler
>> [  271.851718] sas: ata10: end_device-6:5: dev error handler
>> [  271.855161] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy1 link_rate=10(sata)
>> [  271.855547] hisi_sas_v3_hw 0000:b4:02.0: dev[10:5] found
>> [  271.855760] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy7 phy_state=0x73
>> [  271.855763] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy7 down
>> [  271.899322] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy3 link_rate=11
>> [  271.902737] hisi_sas_v3_hw 0000:b4:02.0: dev[11:5] found
>> [  271.950079] hisi_sas_v3_hw 0000:b4:02.0: dev[12:5] found
>> [  271.955569] hisi_sas_v3_hw 0000:b4:02.0: dev[13:5] found
>> [  271.961037] hisi_sas_v3_hw 0000:b4:02.0: dev[14:1] found
>> [  271.961052] hisi_sas_v3_hw 0000:b4:02.0: end of resuming controller	------> end of resuming controller
>> [  271.973073] hisi_sas_v3_hw 0000:b4:02.0: FLR prepare			------> PCI FLR start
>> [  272.032623] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
>> [  272.039656] sas: sas_form_port: phy7 belongs to port0 already(1)!
>> [  272.201518] ata5.00: configured for UDMA/133
>> [  272.207713] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
>> [  272.217777] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
>> [  272.227672] sas: ata5: end_device-6:0: dev error handler
>> [  272.227676] sas: ata6: end_device-6:1: dev error handler
>> [  272.227682] sas: ata7: end_device-6:2: dev error handler
>> [  272.227688] sas: ata8: end_device-6:3: dev error handler
>> [  272.227695] sas: ata10: end_device-6:5: dev error handler
>> [  272.227694] sas: ata9: end_device-6:4: dev error handler
>> [  274.888594] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
>> [  274.895614] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy5 link_rate=10(sata)
>> [  274.895616] sas: sas_form_port: phy7 belongs to port0 already(1)!
>> [  274.900251] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
>> [  274.902647] sas: sas_form_port: phy5 belongs to port1 already(1)!
>> [  274.902833] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy6 link_rate=10(sata)
>> [  274.903023] sas: sas_form_port: phy0 belongs to port2 already(1)!
>> [  274.914529] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy1 link_rate=10(sata)
>> [  274.916099] sas: sas_form_port: phy6 belongs to port3 already(1)!
>> [  274.916259] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy4 link_rate=10(sata)
>> [  274.916439] sas: sas_form_port: phy1 belongs to port5 already(1)!
>> [  274.961013] sas: sas_form_port: phy4 belongs to port4 already(1)!
>> [  274.967338] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy3 link_rate=11
>> [  274.983663] sas: sas_form_port: phy3 belongs to port6 already(1)!
>> [  275.037230] hisi_sas_v3_hw 0000:b4:02.0: FLR done			------> PCI FLR done
>> [  275.037232] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy0 phy_state=0xfa
>> [  275.049223] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy0 down
>> [  275.204142] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
>> [  275.211001] sas: sas_form_port: phy0 belongs to port2 already(1)!
>> [  278.223079] hisi_sas_v3_hw 0000:b4:02.0: entering suspend state	------> the controller suspend again
>> [  280.527655] ata7.00: qc timeout after 5000 msecs (cmd 0x27)		------> revalidate ATA devices
>> [  280.535667] sas: sas_ata_internal_abort: Task 00000000682de2e7 already finished.
>> [  280.543483] ata7.00: failed to read native max address (err_mask=0x4)
>> [  280.551671] ata7.00: HPA support seems broken, skipping HPA handling
>> [  280.558317] ata7.00: revalidation failed (errno=-5)
>> [  280.563437] sas: Executing internal abort failed 5000000000000600 (-22)
>> [  280.571670] hisi_sas_v3_hw 0000:b4:02.0: I_T nexus reset: internal abort (-22)
>> [  280.579338] sas: ata7: end_device-6:2: Unable to reset ata device?
>> [  280.751675] sas: lldd_execute_task returned: -22
>> [  280.759664] ata7.00: failed to IDENTIFY (I/O error, err_mask=0x40)
>> [  280.766063] ata7.00: revalidation failed (errno=-5)
>> [  285.911663] sas: Executing internal abort failed 5000000000000600 (-22)
>> [  285.919667] hisi_sas_v3_hw 0000:b4:02.0: I_T nexus reset: internal abort (-22)
>> [  285.927353] sas: ata7: end_device-6:2: Unable to reset ata device?
>> [  286.095677] sas: lldd_execute_task returned: -22
>> [  286.103666] ata7.00: failed to IDENTIFY (I/O error, err_mask=0x40)
>> [  286.110078] ata7.00: revalidation failed (errno=-5)			------> revalidation failed due to the controller is suspend state
>> [  286.119424] ata7.00: disable device					------> disable device due to revalidation failed
>> [  286.123185] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
>> [  286.133236] sas: sas_resume_sata: for direct-attached device 5000000000000600 returned -19
>> ...
>>
>> The issue 2:
>> a. Suspend all disks on controller B.
>> b. Suspend controller B.
>> c. Resuming all disks on controller B.
>> d. Run the "lsmod" command to check the driver reference counting.

The following is the exact commands triggered by issue 2, and it's also on this
same machine.

Step a is to suspend all disks attached to the SAS controller:
[root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/control
[root@localhost ~]# echo 5000 > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/autosuspend_delay_ms
...
[root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/control
[root@localhost ~]# echo 5000 > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/autosuspend_delay_ms

Step b is to suspend the SAS controller:
[root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/power/control

Step c is to resuming all suspend disks:
[root@localhost ~]# echo on > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/control
...
[root@localhost ~]# echo on > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/control

Step d is to check the driver reference counting:
[root@localhost ~]# lsmod | grep hisi_sas_v3_hw
hisi_sas_v3_hw         77824  1436

>>
>> Thanks,
>> Yihang
>>
>>>
>>>> For the issue 1, After all disks and controller are suspended, FLR command
>>>> will resuming the controller and all sas ports. libsas layer will call
>>>> ata_sas_port_resume() to resume ata port and schedule EH to recover it.
>>>> In libata standard error handler ata_std_error_handler(), it will call ata
>>>> reset function, revalidate ATA devices and issue ATA device command
>>>> ATA_CMD_READ_NATIVE_MAX_EXT to read native max address. This command will
>>>> failed due to the controller enter suspend state again and libata disable
>>>> the device finally. The controller enter suspend state again because FLR
>>>> command completes and the runtime PM usage counter is 0.
>>>>
>>>> In commit 0c76106cb975 ("scsi: sd: Fix TCG OPAL unlock on system resume")
>>>> and 626b13f015e0 ("scsi: Do not rescan devices with a suspended queue"),
>>>> use blk_queue_pm_only() to check the device request queue state, if the
>>>> device request queue is not running, the device will not be rescanned.
>>>> Therefore, the runtime PM usage counter of the controller will not
>>>> increase so that the controller enters the suspended state again.
>>>>
>>>> For the issue 2, the cause is unknown.
>>>>
>>>> How to solve these two issues?
>>>>
>>>> regards,
>>>> Yihang
>>>>
>>>
> 

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Bjorn Helgaas]

On Mon, Jun 24, 2024 at 09:10:41AM +0900, Damien Le Moal wrote:
> On 6/22/24 12:31 PM, Yihang Li wrote:
> > Hi Damien,
> > 
> > Thanks for your reply.
> > 
> > On 2024/6/19 7:11, Damien Le Moal wrote:
> >> On 6/18/24 22:29, Yihang Li wrote:
> >>> Hi Damien,
> >>>
> >>> I found out that two issues is caused by commit 0c76106cb975 ("scsi: sd:
> >>> Fix TCG OPAL unlock on system resume") and 626b13f015e0 ("scsi: Do not
> >>> rescan devices with a suspended queue").
> >>>
> >>> The two issues as follows for the situation that there are ATA disks
> >>> connected with SAS controller:
> >>
> >> Which controller ? What is the driver ?
> > 
> > I'm using the hisi_sas_v3_hw driver and it supports HiSilicon's SAS controller.
> 
> I do not have access to this HBA, but I have one that uses libsas/pm8001 driver
> so I will try to test with that.
> 
> >>> (1) FLR is triggered after all disks and controller are suspended. As a
> >>> result, the number of disks is abnormal.
> >>
> >> I am assuming here that FLR means PCI "Function Level Reset" ?
> > 
> > Yes, I am talking about the PCI "Function Level Reset"
> > 
> >> FLR and disk/controller suspend execution timing are unrelated. FLR can be
> >> triggered at any time through sysfs. So please give details here. Why is FLR
> >> done when the system is being suspended ?
> > 
> > Yes, it is because FLR can be triggered at any time that we are testing the
> > reliability of executing FLR commands after disk/controller suspended.
> 
> "can be triggered" ? FLR is not a random asynchronous event. It is an action
> that is *issued* by a user with sys admin rights. And such users can do a lot
> of things that can break a machine...
> 
> I fail to see the point of doing a function reset while the device is
> suspended. But granted, I guess the device should comeback up in such case,
> though I would like to hear what the PCI guys have to say about this.
> 
> Bjorn,
> 
> Is reseting a suspended PCI device something that should be/is supported ?

I doubt it.  The PCI core should be preserving all the generic PCI
state across suspend/resume.  The driver should only need to
save/restore device-specific things the PCI core doesn't know about.

A reset will clear out most state, and the driver doesn't know the
reset happened, so it will expect most device state to have been
preserved.

Bjorn

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Damien Le Moal]

On 6/27/24 00:15, Bjorn Helgaas wrote:
>>> Yes, I am talking about the PCI "Function Level Reset"
>>>
>>>> FLR and disk/controller suspend execution timing are unrelated. FLR can be
>>>> triggered at any time through sysfs. So please give details here. Why is FLR
>>>> done when the system is being suspended ?
>>>
>>> Yes, it is because FLR can be triggered at any time that we are testing the
>>> reliability of executing FLR commands after disk/controller suspended.
>>
>> "can be triggered" ? FLR is not a random asynchronous event. It is an action
>> that is *issued* by a user with sys admin rights. And such users can do a lot
>> of things that can break a machine...
>>
>> I fail to see the point of doing a function reset while the device is
>> suspended. But granted, I guess the device should comeback up in such case,
>> though I would like to hear what the PCI guys have to say about this.
>>
>> Bjorn,
>>
>> Is reseting a suspended PCI device something that should be/is supported ?
> 
> I doubt it.  The PCI core should be preserving all the generic PCI
> state across suspend/resume.  The driver should only need to
> save/restore device-specific things the PCI core doesn't know about.
> 
> A reset will clear out most state, and the driver doesn't know the
> reset happened, so it will expect most device state to have been
> preserved.

That is what I suspected. However, checking the code, reset_store() in
pci-sysfs.c does:

	pm_runtime_get_sync(dev);
	result = pci_reset_function(pdev);
	pm_runtime_put(dev);

and pm_runtime_get_sync() calls __pm_runtime_resume() which will resume a
suspended device.

So while I still think it is not a good idea to reset a suspended device, things
should still work as execpected and not cause any problem with the device state,
right ?

Yihang,

I think that the issue at hand here is that once the reset finishes, the
controller goes back to suspended state, and I suspect that is because of the
"auto" setting for its power/control. That triggers because the FLR is done
after the controller resumed but *before* the revalidation of the drives
connected to it completes. So FLR makes the revalidation fail (scsi
scan/revalidation is asynchronous...).

This seems to me to be the expected behavior for what you are doing and I fail
to see how that ever worked correctly, even before 0c76106cb975 and 626b13f015e0.

Could you try this: add a call to msleep(30000) at the end of _resume_v3_hw(). I.e.:

diff --git a/drivers/scsi/hisi_sas/hisi_sas_v3_hw.c
b/drivers/scsi/hisi_sas/hisi_sas_v3_hw.c
index feda9b54b443..54224568d749 100644
--- a/drivers/scsi/hisi_sas/hisi_sas_v3_hw.c
+++ b/drivers/scsi/hisi_sas/hisi_sas_v3_hw.c
@@ -5104,6 +5104,8 @@ static int _resume_v3_hw(struct device *device)

        dev_warn(dev, "end of resuming controller\n");

+       msleep(30000);
+
        return 0;
 }

To see if it makes any difference to actually wait for the connected disks to
resume correctly before doing the FLR.	

-- 
Damien Le Moal
Western Digital Research

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Yihang Li]

On 2024/6/27 8:56, Damien Le Moal wrote:
> On 6/27/24 00:15, Bjorn Helgaas wrote:
>>>> Yes, I am talking about the PCI "Function Level Reset"
>>>>
>>>>> FLR and disk/controller suspend execution timing are unrelated. FLR can be
>>>>> triggered at any time through sysfs. So please give details here. Why is FLR
>>>>> done when the system is being suspended ?
>>>>
>>>> Yes, it is because FLR can be triggered at any time that we are testing the
>>>> reliability of executing FLR commands after disk/controller suspended.
>>>
>>> "can be triggered" ? FLR is not a random asynchronous event. It is an action
>>> that is *issued* by a user with sys admin rights. And such users can do a lot
>>> of things that can break a machine...
>>>
>>> I fail to see the point of doing a function reset while the device is
>>> suspended. But granted, I guess the device should comeback up in such case,
>>> though I would like to hear what the PCI guys have to say about this.
>>>
>>> Bjorn,
>>>
>>> Is reseting a suspended PCI device something that should be/is supported ?
>>
>> I doubt it.  The PCI core should be preserving all the generic PCI
>> state across suspend/resume.  The driver should only need to
>> save/restore device-specific things the PCI core doesn't know about.
>>
>> A reset will clear out most state, and the driver doesn't know the
>> reset happened, so it will expect most device state to have been
>> preserved.
> 
> That is what I suspected. However, checking the code, reset_store() in
> pci-sysfs.c does:
> 
> 	pm_runtime_get_sync(dev);
> 	result = pci_reset_function(pdev);
> 	pm_runtime_put(dev);
> 
> and pm_runtime_get_sync() calls __pm_runtime_resume() which will resume a
> suspended device.
> 
> So while I still think it is not a good idea to reset a suspended device, things
> should still work as execpected and not cause any problem with the device state,
> right ?
> 
> Yihang,
> 
> I think that the issue at hand here is that once the reset finishes, the
> controller goes back to suspended state, and I suspect that is because of the
> "auto" setting for its power/control. That triggers because the FLR is done
> after the controller resumed but *before* the revalidation of the drives
> connected to it completes. So FLR makes the revalidation fail (scsi
> scan/revalidation is asynchronous...).
> 
> This seems to me to be the expected behavior for what you are doing and I fail
> to see how that ever worked correctly, even before 0c76106cb975 and 626b13f015e0.

I think that before 0c76106cb975 and 626b13f015e0, sd_resume() will be called in the
scsi scan process, which will bump up power.usage_count of the controller so that
the controller cannot goes back to suspended state. Then revalidation will not fail.

> 
> Could you try this: add a call to msleep(30000) at the end of _resume_v3_hw(). I.e.:
> 
> diff --git a/drivers/scsi/hisi_sas/hisi_sas_v3_hw.c
> b/drivers/scsi/hisi_sas/hisi_sas_v3_hw.c
> index feda9b54b443..54224568d749 100644
> --- a/drivers/scsi/hisi_sas/hisi_sas_v3_hw.c
> +++ b/drivers/scsi/hisi_sas/hisi_sas_v3_hw.c
> @@ -5104,6 +5104,8 @@ static int _resume_v3_hw(struct device *device)
> 
>         dev_warn(dev, "end of resuming controller\n");
> 
> +       msleep(30000);
> +
>         return 0;
>  }
> 
> To see if it makes any difference to actually wait for the connected disks to
> resume correctly before doing the FLR.	

On my system, it takes about 50s for all disks to resume properly, so I waited
about 60s before doing FLR, and finally it looks like the revalidation is successful.

kernel message is as follows:
[root@localhost ~]# echo 1 > /sys/bus/pci/devices/0000:b4:02.0/reset
[  320.872531] hisi_sas_v3_hw 0000:b4:02.0: resuming from operating state [D0]
[  322.112424] hisi_sas_v3_hw 0000:b4:02.0: waiting up to 25 seconds for 7 phys to resume
[  322.112974] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
[  322.127517] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
[  322.127530] hisi_sas_v3_hw 0000:b4:02.0: dev[8:5] found
[  322.127727] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy5 link_rate=10(sata)
[  322.128053] hisi_sas_v3_hw 0000:b4:02.0: dev[9:5] found
[  322.128062] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  322.128074] sas: ata5: end_device-6:0: dev error handler
[  322.128079] sas: ata6: end_device-6:1: dev error handler
[  322.128083] sas: ata7: end_device-6:2: dev error handler
[  322.128086] sas: ata8: end_device-6:3: dev error handler
[  322.128088] sas: ata10: end_device-6:5: dev error handler
[  322.128087] sas: ata9: end_device-6:4: dev error handler
[  322.128321] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy6 link_rate=10(sata)
[  322.128557] hisi_sas_v3_hw 0000:b4:02.0: dev[10:5] found
[  322.128729] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy7 phy_state=0x61
[  322.128922] hisi_sas_v3_hw 0000:b4:02.0: dev[11:5] found
[  322.129113] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy7 down
[  322.221484] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy1 link_rate=10(sata)
[  322.228246] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy3 link_rate=11
[  322.228253] hisi_sas_v3_hw 0000:b4:02.0: dev[12:5] found
[  322.228425] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy4 link_rate=10(sata)
[  322.246798] hisi_sas_v3_hw 0000:b4:02.0: dev[13:1] found
[  322.252300] hisi_sas_v3_hw 0000:b4:02.0: dev[14:5] found
[  322.252309] hisi_sas_v3_hw 0000:b4:02.0: end of resuming controller	------> 60s wait starts
[  322.285369] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
[  322.292150] sas: sas_form_port: phy7 belongs to port0 already(1)!
[  322.454227] ata5.00: configured for UDMA/133
[  322.458896] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  322.468976] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  322.476376] sas: ata5: end_device-6:0: dev error handler
[  322.476380] sas: ata6: end_device-6:1: dev error handler
[  322.476385] sas: ata7: end_device-6:2: dev error handler
[  322.476387] sas: ata8: end_device-6:3: dev error handler
[  322.476391] sas: ata10: end_device-6:5: dev error handler
[  322.476390] sas: ata9: end_device-6:4: dev error handler
[  322.512627] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy0 phy_state=0xfa
[  322.519225] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy0 down
[  322.696838] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
[  322.703610] sas: sas_form_port: phy0 belongs to port2 already(1)!
[  327.884363] ata7.00: qc timeout after 5000 msecs (cmd 0x27)
[  330.774555] ata7.00: failed to read native max address (err_mask=0x4)
[  330.784372] ata7.00: HPA support seems broken, skipping HPA handling
[  330.790898] ata7.00: revalidation failed (errno=-5)
[  330.796785] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy0 phy_state=0xfa
[  330.803408] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy0 down
[  331.190903] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
[  331.197699] sas: sas_form_port: phy0 belongs to port2 already(1)!
[  331.358141] ata7.00: configured for UDMA/100
[  331.366659] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  331.376728] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  331.384382] sas: ata5: end_device-6:0: dev error handler
[  331.384388] sas: ata6: end_device-6:1: dev error handler
[  331.384393] sas: ata7: end_device-6:2: dev error handler
[  331.384398] sas: ata8: end_device-6:3: dev error handler
[  331.384402] sas: ata9: end_device-6:4: dev error handler
[  331.384403] sas: ata10: end_device-6:5: dev error handler
[  331.417834] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy5 phy_state=0xdb
[  331.424468] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy5 down
[  331.578409] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy5 link_rate=10(sata)
[  331.585200] sas: sas_form_port: phy5 belongs to port1 already(1)!
[  331.755728] ata6.00: configured for UDMA/133
[  331.764497] ata6.00: Entering active power mode
[  341.964384] ata6.00: qc timeout after 10000 msecs (cmd 0x40)
[  344.874106] ata6.00: VERIFY failed (err_mask=0x4)
[  344.880648] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy5 phy_state=0xdb
[  344.887617] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy5 down
[  345.048407] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy5 link_rate=10(sata)
[  345.055238] sas: sas_form_port: phy5 belongs to port1 already(1)!
[  345.224989] ata6.00: configured for UDMA/133
[  345.232464] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  345.242523] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  345.252377] sas: ata5: end_device-6:0: dev error handler
[  345.252381] sas: ata6: end_device-6:1: dev error handler
[  345.252386] sas: ata7: end_device-6:2: dev error handler
[  345.252391] sas: ata8: end_device-6:3: dev error handler
[  345.252396] sas: ata9: end_device-6:4: dev error handler
[  345.252397] sas: ata10: end_device-6:5: dev error handler
[  345.252608] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy6 phy_state=0xbb
[  345.252612] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy6 down
[  345.424843] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy6 link_rate=10(sata)
[  345.431625] sas: sas_form_port: phy6 belongs to port3 already(1)!
[  350.668364] ata8.00: qc timeout after 5000 msecs (cmd 0x27)
[  353.731804] ata8.00: failed to read native max address (err_mask=0x4)
[  353.740363] ata8.00: HPA support seems broken, skipping HPA handling
[  353.746961] ata8.00: revalidation failed (errno=-5)
[  353.752314] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy6 phy_state=0xbb
[  353.759186] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy6 down
[  354.156360] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy6 link_rate=10(sata)
[  354.163189] sas: sas_form_port: phy6 belongs to port3 already(1)!
[  354.330161] ata8.00: configured for UDMA/100
[  354.338661] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  354.348719] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  354.356381] sas: ata5: end_device-6:0: dev error handler
[  354.356387] sas: ata6: end_device-6:1: dev error handler
[  354.356393] sas: ata7: end_device-6:2: dev error handler
[  354.356398] sas: ata8: end_device-6:3: dev error handler
[  354.356403] sas: ata10: end_device-6:5: dev error handler
[  354.356403] sas: ata9: end_device-6:4: dev error handler
[  354.389685] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy1 phy_state=0xf9
[  354.396304] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy1 down
[  354.579128] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy1 link_rate=10(sata)
[  354.585924] sas: sas_form_port: phy1 belongs to port5 already(1)!
[  362.320531] ata10.00: configured for UDMA/133
[  362.328435] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  362.338494] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  362.348383] sas: ata5: end_device-6:0: dev error handler
[  362.348387] sas: ata6: end_device-6:1: dev error handler
[  362.348392] sas: ata7: end_device-6:2: dev error handler
[  362.348397] sas: ata8: end_device-6:3: dev error handler
[  362.348401] sas: ata9: end_device-6:4: dev error handler
[  362.348401] sas: ata10: end_device-6:5: dev error handler
[  362.348631] hisi_sas_v3_hw 0000:b4:02.0: phydown: phy4 phy_state=0xeb
[  362.348635] hisi_sas_v3_hw 0000:b4:02.0: ignore flutter phy4 down
[  362.531118] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy4 link_rate=10(sata)
[  362.537917] sas: sas_form_port: phy4 belongs to port4 already(1)!
[  370.299911] ata9.00: configured for UDMA/133
[  370.308446] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  382.412358] hisi_sas_v3_hw 0000:b4:02.0: FLR prepare			------> 60s wait ends
[  384.873251] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy7 link_rate=10(sata)
[  384.880073] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy5 link_rate=10(sata)
[  384.880081] sas: sas_form_port: phy7 belongs to port0 already(1)!
[  384.884906] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy0 link_rate=10(sata)
[  384.887280] sas: sas_form_port: phy5 belongs to port1 already(1)!
[  384.887565] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy6 link_rate=10(sata)
[  384.887903] sas: sas_form_port: phy0 belongs to port2 already(1)!
[  384.903979] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy1 link_rate=10(sata)
[  384.907420] sas: sas_form_port: phy6 belongs to port3 already(1)!
[  384.907804] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy4 link_rate=10(sata)
[  384.908202] sas: sas_form_port: phy1 belongs to port5 already(1)!
[  384.946977] sas: sas_form_port: phy4 belongs to port4 already(1)!
[  384.951984] hisi_sas_v3_hw 0000:b4:02.0: phyup: phy3 link_rate=11
[  384.968358] sas: sas_form_port: phy3 belongs to port6 already(1)!
[  385.030251] hisi_sas_v3_hw 0000:b4:02.0: FLR done
[  388.662363] hisi_sas_v3_hw 0000:b4:02.0: entering suspend state
[  389.079453] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  389.085530] sas: ata5: end_device-6:0: dev error handler
[  389.085535] sas: ata6: end_device-6:1: dev error handler
[  389.085538] sas: ata7: end_device-6:2: dev error handler
[  389.085542] sas: ata8: end_device-6:3: dev error handler
[  389.085548] sas: ata10: end_device-6:5: dev error handler
[  389.085547] sas: ata9: end_device-6:4: dev error handler
[  389.085799] sas: lldd_execute_task returned: -22
[  389.124371] ata5.00: Check power mode failed (err_mask=0x40)
[  389.130250] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  389.140306] hisi_sas_v3_hw 0000:b4:02.0: dev[8:5] is gone
[  389.148375] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  389.154605] sas: ata5: end_device-6:0: dev error handler
[  389.154610] sas: ata6: end_device-6:1: dev error handler
[  389.154615] sas: ata7: end_device-6:2: dev error handler
[  389.154620] sas: ata8: end_device-6:3: dev error handler
[  389.154621] sas: ata9: end_device-6:4: dev error handler
[  389.154624] sas: ata10: end_device-6:5: dev error handler
[  389.188449] sas: lldd_execute_task returned: -22
[  389.193265] ata6.00: Check power mode failed (err_mask=0x40)
[  389.199101] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  389.209155] hisi_sas_v3_hw 0000:b4:02.0: dev[10:5] is gone
[  389.216375] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  389.222612] sas: ata5: end_device-6:0: dev error handler
[  389.222616] sas: ata6: end_device-6:1: dev error handler
[  389.222620] sas: ata7: end_device-6:2: dev error handler
[  389.222624] sas: ata8: end_device-6:3: dev error handler
[  389.222628] sas: lldd_execute_task returned: -22
[  389.222628] sas: ata9: end_device-6:4: dev error handler
[  389.222629] sas: ata10: end_device-6:5: dev error handler
[  389.222631] ata7.00: Check power mode failed (err_mask=0x40)
[  389.266550] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  389.282963] hisi_sas_v3_hw 0000:b4:02.0: dev[9:5] is gone
[  389.292377] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  389.298581] sas: ata5: end_device-6:0: dev error handler
[  389.298585] sas: ata6: end_device-6:1: dev error handler
[  389.298589] sas: ata7: end_device-6:2: dev error handler
[  389.298593] sas: ata8: end_device-6:3: dev error handler
[  389.298594] sas: ata9: end_device-6:4: dev error handler
[  389.298595] sas: ata10: end_device-6:5: dev error handler
[  389.298599] sas: lldd_execute_task returned: -22
[  389.298603] ata8.00: Check power mode failed (err_mask=0x40)
[  389.342460] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  389.358932] hisi_sas_v3_hw 0000:b4:02.0: dev[11:5] is gone
[  389.368379] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  389.374656] sas: ata5: end_device-6:0: dev error handler
[  389.374661] sas: ata6: end_device-6:1: dev error handler
[  389.374666] sas: ata7: end_device-6:2: dev error handler
[  389.374671] sas: ata8: end_device-6:3: dev error handler
[  389.374671] sas: ata9: end_device-6:4: dev error handler
[  389.374674] sas: ata10: end_device-6:5: dev error handler
[  389.374676] sas: lldd_execute_task returned: -22
[  389.374678] ata9.00: Check power mode failed (err_mask=0x40)
[  389.418651] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  389.435009] hisi_sas_v3_hw 0000:b4:02.0: dev[14:5] is gone
[  389.444379] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[  389.450645] sas: ata5: end_device-6:0: dev error handler
[  389.450651] sas: ata6: end_device-6:1: dev error handler
[  389.450656] sas: ata7: end_device-6:2: dev error handler
[  389.450660] sas: ata8: end_device-6:3: dev error handler
[  389.450664] sas: ata10: end_device-6:5: dev error handler
[  389.450664] sas: ata9: end_device-6:4: dev error handler
[  389.450668] sas: lldd_execute_task returned: -22
[  389.450670] ata10.00: Check power mode failed (err_mask=0x40)
[  389.494657] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0 tries: 1
[  389.510999] hisi_sas_v3_hw 0000:b4:02.0: dev[12:5] is gone
[  389.520363] hisi_sas_v3_hw 0000:b4:02.0: dev[13:1] is gone
[  389.526056] hisi_sas_v3_hw 0000:b4:02.0: end of suspending controller

Yihang

> 

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Damien Le Moal]

On 6/24/24 21:10, Yihang Li wrote:
>> Thank you for the explanation, but as Niklas said, it would be a lot easier for
>> me to recreate the issue if you send the exact commands you execute to trigger
>> the issue. E.g. "suspend all disks" in step a can have a lot of different
>> meaning depending on which type os suspend you are using... So please send the
>> exact commands you use.
>> is what exactly ? autosuspend ? or something else ?

I am failing to recreate the exact same issue. I do see a lot of bad things
happening though, but that is not looking like what you sent. I do endup with
the 4 drives connected on my HBA being disabled by libata as revalidate/IDENTIFY
fails. And even worse: I hit a deadlock on dev->mutex when I try to do "rmmod
pm80xx" after running your test.

I am using a pm80xx adapter as that is the only libsas adapter I have.

I think your test just kicked a big can of worms... There seem to be a lot of
wrong things going on, but I now need to sort out if the problems are with the
pm80xx driver, libsas, libata or sd. Probably a combination of all.

ATA device suspend/resume has been a constant source of issues since scsi layer
switched to doing PM operations asynchronouly. Your issue is latest one.
This will take a while to debug.

> In step a, I suspend all disks by issuing the following command to all disks
> attached to the SAS controller 0000:b4:02.0:
> [root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/control
> [root@localhost ~]# echo 5000 > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/autosuspend_delay_ms
> ...
> [root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/control
> [root@localhost ~]# echo 5000 > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/autosuspend_delay_ms

This works as expected on my system and I see my drives going to sleep after 5s.

> Step b, Suspend the SAS controller:
> [root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/power/control

This has no effect for me. Can you confirm that your controller is actually
sleeping ? I.e., what do the following show ?

cat /sys/devices/pci0000:b4/0000:b4:02.0/power/runtime_active_kids
cat /sys/devices/pci0000:b4/0000:b4:02.0/power/runtime_status

?

> At this point, the SAS controller is suspended. Next step c is trigger PCI FLR.
> [root@localhost ~]# echo 1 > /sys/bus/pci/devices/0000:b4:02.0/reset

What does

cat /sys/bus/pci/devices/0000:b4:02.0/reset_method

is on your system ?

Mine is "bus" only.

>>> The issue 2:
>>> a. Suspend all disks on controller B.
>>> b. Suspend controller B.
>>> c. Resuming all disks on controller B.
>>> d. Run the "lsmod" command to check the driver reference counting.

What is the reference count before you do step (a), after you run step (b) and
at step (d) ?

For my system using the pm80xx driver, I get:

pm80xx                352256  0
libsas                155648  1 pm80xx

before and after, and that is all normal. But there is the difference that
suspending the pm80xx controller does not seem to be supported and does nothing.

-- 
Damien Le Moal
Western Digital Research

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Bjorn Helgaas]

[+cc Alex]

On Thu, Jun 27, 2024 at 09:56:02AM +0900, Damien Le Moal wrote:
> On 6/27/24 00:15, Bjorn Helgaas wrote:
> >>> Yes, I am talking about the PCI "Function Level Reset"
> >>>
> >>>> FLR and disk/controller suspend execution timing are unrelated.
> >>>> FLR can be triggered at any time through sysfs. So please give
> >>>> details here. Why is FLR done when the system is being
> >>>> suspended ?
> >>>
> >>> Yes, it is because FLR can be triggered at any time that we are
> >>> testing the reliability of executing FLR commands after
> >>> disk/controller suspended.
> >>
> >> "can be triggered" ? FLR is not a random asynchronous event. It
> >> is an action that is *issued* by a user with sys admin rights.
> >> And such users can do a lot of things that can break a machine...
> >>
> >> I fail to see the point of doing a function reset while the
> >> device is suspended. But granted, I guess the device should
> >> comeback up in such case, though I would like to hear what the
> >> PCI guys have to say about this.
> >>
> >> Bjorn,
> >>
> >> Is reseting a suspended PCI device something that should be/is
> >> supported ?
> > 
> > I doubt it.  The PCI core should be preserving all the generic PCI
> > state across suspend/resume.  The driver should only need to
> > save/restore device-specific things the PCI core doesn't know about.
> > 
> > A reset will clear out most state, and the driver doesn't know the
> > reset happened, so it will expect most device state to have been
> > preserved.
> 
> That is what I suspected. However, checking the code, reset_store() in
> pci-sysfs.c does:
> 
> 	pm_runtime_get_sync(dev);
> 	result = pci_reset_function(pdev);
> 	pm_runtime_put(dev);
> 
> and pm_runtime_get_sync() calls __pm_runtime_resume() which will
> resume a suspended device.
> 
> So while I still think it is not a good idea to reset a suspended
> device, things should still work as execpected and not cause any
> problem with the device state, right ?

The reset will clear almost all state, including both the generic PCI
part that pci_reset_function() saves/restores *and* any
device-specific state the PCI core doesn't know about.

That device-specific state isn't saved and restored anywhere in the
sysfs reset path, and the driver doesn't know this reset happened, so
I think all bets are off and we shouldn't expect the driver to work
afterwards.

A user-space reset might make sense if there's no driver bound to the
device, but I don't think it does if there is a driver (except maybe a
trivial stub driver that doesn't actually operate the device).

Bjorn

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Damien Le Moal]

On 7/2/24 05:39, Bjorn Helgaas wrote:
> [+cc Alex]
> 
> On Thu, Jun 27, 2024 at 09:56:02AM +0900, Damien Le Moal wrote:
>> On 6/27/24 00:15, Bjorn Helgaas wrote:
>>>>> Yes, I am talking about the PCI "Function Level Reset"
>>>>>
>>>>>> FLR and disk/controller suspend execution timing are unrelated.
>>>>>> FLR can be triggered at any time through sysfs. So please give
>>>>>> details here. Why is FLR done when the system is being
>>>>>> suspended ?
>>>>>
>>>>> Yes, it is because FLR can be triggered at any time that we are
>>>>> testing the reliability of executing FLR commands after
>>>>> disk/controller suspended.
>>>>
>>>> "can be triggered" ? FLR is not a random asynchronous event. It
>>>> is an action that is *issued* by a user with sys admin rights.
>>>> And such users can do a lot of things that can break a machine...
>>>>
>>>> I fail to see the point of doing a function reset while the
>>>> device is suspended. But granted, I guess the device should
>>>> comeback up in such case, though I would like to hear what the
>>>> PCI guys have to say about this.
>>>>
>>>> Bjorn,
>>>>
>>>> Is reseting a suspended PCI device something that should be/is
>>>> supported ?
>>>
>>> I doubt it.  The PCI core should be preserving all the generic PCI
>>> state across suspend/resume.  The driver should only need to
>>> save/restore device-specific things the PCI core doesn't know about.
>>>
>>> A reset will clear out most state, and the driver doesn't know the
>>> reset happened, so it will expect most device state to have been
>>> preserved.
>>
>> That is what I suspected. However, checking the code, reset_store() in
>> pci-sysfs.c does:
>>
>> 	pm_runtime_get_sync(dev);
>> 	result = pci_reset_function(pdev);
>> 	pm_runtime_put(dev);
>>
>> and pm_runtime_get_sync() calls __pm_runtime_resume() which will
>> resume a suspended device.
>>
>> So while I still think it is not a good idea to reset a suspended
>> device, things should still work as execpected and not cause any
>> problem with the device state, right ?
> 
> The reset will clear almost all state, including both the generic PCI
> part that pci_reset_function() saves/restores *and* any
> device-specific state the PCI core doesn't know about.
> 
> That device-specific state isn't saved and restored anywhere in the
> sysfs reset path, and the driver doesn't know this reset happened, so
> I think all bets are off and we shouldn't expect the driver to work
> afterwards.
> 
> A user-space reset might make sense if there's no driver bound to the
> device, but I don't think it does if there is a driver (except maybe a
> trivial stub driver that doesn't actually operate the device).

OK, makes sense.

I amstill looking into this though because I did find a nasty issue: if the HBA
is reset while all the drives connected to it are suspended (spun down), the
drives are never woken up and the drive re-scan trigerred by the PCI reset fails
with command timeouts. And even worse, I hit a deadlock when unloading the
driver after that happens.

All of that should not be happening: the HBA reset should simply result in
either all drives coming back or the drives (scsi devices) being dropped and
re-scan creating new ones. But that I think is not a PCI issue but rather a HBA
driver issue, or a problem with libsas/scsi/libata power management.

Thanks for the comments.

-- 
Damien Le Moal
Western Digital Research

Re: [bug report] scsi: SATA devices missing after FLR is triggered during HBA suspended

[Yihang Li]

On 2024/7/1 11:03, Damien Le Moal wrote:
> On 6/24/24 21:10, Yihang Li wrote:
>>> Thank you for the explanation, but as Niklas said, it would be a lot easier for
>>> me to recreate the issue if you send the exact commands you execute to trigger
>>> the issue. E.g. "suspend all disks" in step a can have a lot of different
>>> meaning depending on which type os suspend you are using... So please send the
>>> exact commands you use.
>>> is what exactly ? autosuspend ? or something else ?
> 
> I am failing to recreate the exact same issue. I do see a lot of bad things
> happening though, but that is not looking like what you sent. I do endup with
> the 4 drives connected on my HBA being disabled by libata as revalidate/IDENTIFY
> fails. And even worse: I hit a deadlock on dev->mutex when I try to do "rmmod
> pm80xx" after running your test.
> 
> I am using a pm80xx adapter as that is the only libsas adapter I have.
> 
> I think your test just kicked a big can of worms... There seem to be a lot of
> wrong things going on, but I now need to sort out if the problems are with the
> pm80xx driver, libsas, libata or sd. Probably a combination of all.
> 
> ATA device suspend/resume has been a constant source of issues since scsi layer
> switched to doing PM operations asynchronouly. Your issue is latest one.
> This will take a while to debug.
> 
>> In step a, I suspend all disks by issuing the following command to all disks
>> attached to the SAS controller 0000:b4:02.0:
>> [root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/control
>> [root@localhost ~]# echo 5000 > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:0/end_device-6:0/target6:0:0/6:0:0:0/power/autosuspend_delay_ms
>> ...
>> [root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/control
>> [root@localhost ~]# echo 5000 > /sys/devices/pci0000:b4/0000:b4:02.0/host6/port-6:6/end_device-6:6/target6:0:6/6:0:6:0/power/autosuspend_delay_ms
> 
> This works as expected on my system and I see my drives going to sleep after 5s.
> 
>> Step b, Suspend the SAS controller:
>> [root@localhost ~]# echo auto > /sys/devices/pci0000:b4/0000:b4:02.0/power/control
> 
> This has no effect for me. Can you confirm that your controller is actually
> sleeping ? I.e., what do the following show ?
> 
> cat /sys/devices/pci0000:b4/0000:b4:02.0/power/runtime_active_kids
> cat /sys/devices/pci0000:b4/0000:b4:02.0/power/runtime_status

I don't have a sysfs node for runtime_active_kids in my system.
My controller runtime_status has changed to "suspended" after step b.

[root@localhost ~]# cat /sys/devices/pci0000:b4/0000:b4:02.0/power/runtime_status
suspended


> 
> ?
> 
>> At this point, the SAS controller is suspended. Next step c is trigger PCI FLR.
>> [root@localhost ~]# echo 1 > /sys/bus/pci/devices/0000:b4:02.0/reset
> 
> What does
> 
> cat /sys/bus/pci/devices/0000:b4:02.0/reset_method
> 
> is on your system ?
> 
> Mine is "bus" only.

The results in my system are as follows:

[root@localhost ~]# cat /sys/devices/pci0000:b4/0000:b4:02.0/reset_method
acpi flr pm


> 
>>>> The issue 2:
>>>> a. Suspend all disks on controller B.
>>>> b. Suspend controller B.
>>>> c. Resuming all disks on controller B.
>>>> d. Run the "lsmod" command to check the driver reference counting.
> 
> What is the reference count before you do step (a), after you run step (b) and
> at step (d) ?

Before step a, the hisi_sas driver reference count is 0.
After step b, the driver reference count is 0.
At step d, the reference count is 2405 (this value is not the same every time).

hisi_sas_v3_hw         77824  2405
hisi_sas_main          45056  1 hisi_sas_v3_hw
libsas                 98304  2 hisi_sas_v3_hw,hisi_sas_main


> 
> For my system using the pm80xx driver, I get:
> 
> pm80xx                352256  0
> libsas                155648  1 pm80xx
> 
> before and after, and that is all normal. But there is the difference that
> suspending the pm80xx controller does not seem to be supported and does nothing.
>