[PATCH v4] ata: libata-eh: Honor all EH scheduling requests

[PATCH v4] ata: libata-eh: Honor all EH scheduling requests

[linan666]

From: Li Nan <linan122@huawei.com>

If a disk is removed and quickly inserted when an I/O error is processing,
the disk may not be able to be re-added. The function call timeline is as
follows:

  interrupt                            scsi_eh

  ahci_error_intr
   ata_port_freeze
    __ata_port_freeze
     =>ahci_freeze (turn IRQ off)
    ata_port_abort
     ata_do_link_abort
      ata_port_schedule_eh
       =>ata_std_sched_eh
        ata_eh_set_pending
	 set EH_PENDING
        scsi_schedule_eh
         shost->host_eh_scheduled++ (=1)
                                       scsi_error_handler
                                        =>ata_scsi_error
                                         ata_scsi_port_error_handler
					  clear EH_PENDING
                                          =>ahci_error_handler
                                          . sata_pmp_error_handler
                                          .  ata_eh_reset
                                          .   ata_eh_thaw_port
                                          .   . =>ahci_thaw (turn IRQ on)
  ahci_error_intr			  .   .
   ata_port_freeze			  .   .
    __ata_port_freeze			  .   .
     =>ahci_freeze (turn IRQ off)	  .   .
    ...					  .   .
        ata_eh_set_pending		  .   .
	 set EH_PENDING			  .   .
        scsi_schedule_eh		  .   .
         shost->host_eh_scheduled++ (=2)  .   .
					  .   clear EH_PENDING
					  check EH_PENDING
                                          =>ata_std_end_eh
                                           host->host_eh_scheduled = 0;

'host_eh_scheduled' is 0 and scsi eh thread will not be scheduled again.
The ata port remains frozen and will never be enabled.

To fix this issue, decrease 'host_eh_scheduled' instead of setting it to 0
so that EH is scheduled again to re-enable the port. Also move the update
of 'nr_active_links' to 0 when 'host_eh_scheduled' is 0 to
ata_scsi_port_error_handler().

Cc: stable@vger.kernel.org
Fixes: ad9e27624479 ("[PATCH] libata-eh-fw: update ata_scsi_error() for new EH")
Reported-by: luojian <luojian5@huawei.com>
Signed-off-by: Li Nan <linan122@huawei.com>
Reviewed-by: Niklas Cassel <niklas.cassel@wdc.com>
---
Changes in v4:
 - add fix tag and Cc stable

 drivers/ata/libata-eh.c | 14 +++++++-------
 1 file changed, 7 insertions(+), 7 deletions(-)

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 159ba6ba19eb..2d5ecd68b7e0 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -735,6 +735,12 @@ void ata_scsi_port_error_handler(struct Scsi_Host *host, struct ata_port *ap)
 	 */
 	ap->ops->end_eh(ap);
 
+	if (!ap->scsi_host->host_eh_scheduled) {
+		/* make sure nr_active_links is zero after EH */
+		WARN_ON(ap->nr_active_links);
+		ap->nr_active_links = 0;
+	}
+
 	spin_unlock_irqrestore(ap->lock, flags);
 	ata_eh_release(ap);
 
@@ -946,9 +952,7 @@ EXPORT_SYMBOL_GPL(ata_std_sched_eh);
  */
 void ata_std_end_eh(struct ata_port *ap)
 {
-	struct Scsi_Host *host = ap->scsi_host;
-
-	host->host_eh_scheduled = 0;
+	ap->scsi_host->host_eh_scheduled--;
 }
 EXPORT_SYMBOL(ata_std_end_eh);
 
@@ -3922,10 +3926,6 @@ void ata_eh_finish(struct ata_port *ap)
 			}
 		}
 	}
-
-	/* make sure nr_active_links is zero after EH */
-	WARN_ON(ap->nr_active_links);
-	ap->nr_active_links = 0;
 }
 
 /**
-- 
2.39.2

Re: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests

[kernel test robot]

Hello,

kernel test robot noticed "kernel_BUG_at_drivers/ata/libata-sff.c" on:

commit: d3d099d5c2dd38db84abd96df39f9f0828c16b7b ("[PATCH v4] ata: libata-eh: Honor all EH scheduling requests")
url: https://github.com/intel-lab-lkp/linux/commits/linan666-huaweicloud-com/ata-libata-eh-Honor-all-EH-scheduling-requests/20230906-164907
base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git 65d6e954e37872fd9afb5ef3fc0481bb3c2f20f4
patch link: https://lore.kernel.org/all/20230906084212.1016634-1-linan666@huaweicloud.com/
patch subject: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests

in testcase: boot

compiler: gcc-12
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

(please refer to attached dmesg/kmsg for entire log/backtrace)


+------------------------------------------+------------+------------+
|                                          | 65d6e954e3 | d3d099d5c2 |
+------------------------------------------+------------+------------+
| boot_successes                           | 8          | 0          |
| boot_failures                            | 0          | 4          |
| kernel_BUG_at_drivers/ata/libata-sff.c   | 0          | 4          |
| invalid_opcode:#[##]                     | 0          | 4          |
| RIP:ata_sff_pio_task[libata]             | 0          | 4          |
| Kernel_panic-not_syncing:Fatal_exception | 0          | 4          |
+------------------------------------------+------------+------------+


If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202309071557.3a90e7a8-oliver.sang@intel.com


[   29.974031][    T8] ------------[ cut here ]------------
[   29.974432][    T8] kernel BUG at drivers/ata/libata-sff.c:1220!
[   29.974866][    T8] invalid opcode: 0000 [#1] SMP PTI
[   29.975228][    T8] CPU: 0 PID: 8 Comm: kworker/0:0 Not tainted 6.5.0-11939-gd3d099d5c2dd #1
[   29.975817][    T8] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[   29.976529][    T8] Workqueue: ata_sff ata_sff_pio_task [libata]
[ 29.977003][ T8] RIP: 0010:ata_sff_pio_task (drivers/ata/libata-sff.c:1220 (discriminator 1)) libata
[ 29.977518][ T8] Code: 35 a6 0d 01 00 48 8d 90 b8 00 00 00 e8 da a6 fb f4 e9 cc fe ff ff 84 c0 0f 89 e7 fe ff ff e9 4b ff ff ff 0f 0b e9 1c ff ff ff <0f> 0b 66 66 2e 0f 1f 84 00 00 00 00 00 66 66 2e 0f 1f 84 00 00 00
All code
========
   0:	35 a6 0d 01 00       	xor    $0x10da6,%eax
   5:	48 8d 90 b8 00 00 00 	lea    0xb8(%rax),%rdx
   c:	e8 da a6 fb f4       	callq  0xfffffffff4fba6eb
  11:	e9 cc fe ff ff       	jmpq   0xfffffffffffffee2
  16:	84 c0                	test   %al,%al
  18:	0f 89 e7 fe ff ff    	jns    0xffffffffffffff05
  1e:	e9 4b ff ff ff       	jmpq   0xffffffffffffff6e
  23:	0f 0b                	ud2    
  25:	e9 1c ff ff ff       	jmpq   0xffffffffffffff46
  2a:*	0f 0b                	ud2    		<-- trapping instruction
  2c:	66 66 2e 0f 1f 84 00 	data16 nopw %cs:0x0(%rax,%rax,1)
  33:	00 00 00 00 
  37:	66                   	data16
  38:	66                   	data16
  39:	2e                   	cs
  3a:	0f                   	.byte 0xf
  3b:	1f                   	(bad)  
  3c:	84 00                	test   %al,(%rax)
	...

Code starting with the faulting instruction
===========================================
   0:	0f 0b                	ud2    
   2:	66 66 2e 0f 1f 84 00 	data16 nopw %cs:0x0(%rax,%rax,1)
   9:	00 00 00 00 
   d:	66                   	data16
   e:	66                   	data16
   f:	2e                   	cs
  10:	0f                   	.byte 0xf
  11:	1f                   	(bad)  
  12:	84 00                	test   %al,(%rax)
	...
[   29.978931][    T8] RSP: 0018:ffffb84cc004be40 EFLAGS: 00010046
[   29.979363][    T8] RAX: 0000000000000000 RBX: ffff88a1d49180b8 RCX: ffff88a4efc2d5e8
[   29.979906][    T8] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88a1fa6299c0
[   29.980449][    T8] RBP: ffff88a1d49180b8 R08: ff6565725e607360 R09: ffff88a4ea0e32c0
[   29.980994][    T8] R10: 0000000000000008 R11: fefefefefefefeff R12: ffff88a4ea592200
[   29.981559][    T8] R13: 0000000000000000 R14: ffff88a4ea592205 R15: ffff88a1d49180c0
[   29.982108][    T8] FS:  0000000000000000(0000) GS:ffff88a4efc00000(0000) knlGS:0000000000000000
[   29.982720][    T8] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   29.983173][    T8] CR2: 00007f1549cb1028 CR3: 000000011465a000 CR4: 00000000000406f0
[   29.983726][    T8] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   29.984856][    T8] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[   29.986008][    T8] Call Trace:
[   29.987041][    T8]  <TASK>
[ 29.987799][ T8] ? die (arch/x86/kernel/dumpstack.c:421 arch/x86/kernel/dumpstack.c:434 arch/x86/kernel/dumpstack.c:447) 
[ 29.988599][ T8] ? do_trap (arch/x86/kernel/traps.c:112 arch/x86/kernel/traps.c:153) 
[ 29.989418][ T8] ? ata_sff_pio_task (drivers/ata/libata-sff.c:1220 (discriminator 1)) libata
[ 29.990388][ T8] ? do_error_trap (arch/x86/include/asm/traps.h:59 arch/x86/kernel/traps.c:174) 
[ 29.991210][ T8] ? ata_sff_pio_task (drivers/ata/libata-sff.c:1220 (discriminator 1)) libata
[ 29.992148][ T8] ? exc_invalid_op (arch/x86/kernel/traps.c:265) 
[ 29.992972][ T8] ? ata_sff_pio_task (drivers/ata/libata-sff.c:1220 (discriminator 1)) libata
[ 29.993919][ T8] ? asm_exc_invalid_op (arch/x86/include/asm/idtentry.h:568) 
[ 29.994748][ T8] ? ata_sff_pio_task (drivers/ata/libata-sff.c:1220 (discriminator 1)) libata
[ 29.995668][ T8] process_one_work (kernel/workqueue.c:2635) 
[ 29.996515][ T8] worker_thread (kernel/workqueue.c:2697 kernel/workqueue.c:2784) 
[ 29.997328][ T8] ? __pfx_worker_thread (kernel/workqueue.c:2730) 
[ 29.998163][ T8] kthread (kernel/kthread.c:388) 
[ 29.998902][ T8] ? __pfx_kthread (kernel/kthread.c:341) 
[ 29.999685][ T8] ret_from_fork (arch/x86/kernel/process.c:153) 
[ 30.000452][ T8] ? __pfx_kthread (kernel/kthread.c:341) 
[ 30.001228][ T8] ret_from_fork_asm (arch/x86/entry/entry_64.S:312) 
[   30.002045][    T8]  </TASK>
[   30.002705][    T8] Modules linked in: intel_rapl_msr sr_mod intel_rapl_common crct10dif_pclmul crc32_pclmul crc32c_intel cdrom bochs ghash_clmulni_intel drm_vram_helper drm_kms_helper drm_ttm_helper sha512_ssse3 ttm ata_generic rapl ppdev drm ata_piix joydev serio_raw libata i2c_piix4 parport_pc parport
[   30.005504][    T8] ---[ end trace 0000000000000000 ]---
[ 30.006390][ T8] RIP: 0010:ata_sff_pio_task (drivers/ata/libata-sff.c:1220 (discriminator 1)) libata
[ 30.007379][ T8] Code: 35 a6 0d 01 00 48 8d 90 b8 00 00 00 e8 da a6 fb f4 e9 cc fe ff ff 84 c0 0f 89 e7 fe ff ff e9 4b ff ff ff 0f 0b e9 1c ff ff ff <0f> 0b 66 66 2e 0f 1f 84 00 00 00 00 00 66 66 2e 0f 1f 84 00 00 00
All code
========
   0:	35 a6 0d 01 00       	xor    $0x10da6,%eax
   5:	48 8d 90 b8 00 00 00 	lea    0xb8(%rax),%rdx
   c:	e8 da a6 fb f4       	callq  0xfffffffff4fba6eb
  11:	e9 cc fe ff ff       	jmpq   0xfffffffffffffee2
  16:	84 c0                	test   %al,%al
  18:	0f 89 e7 fe ff ff    	jns    0xffffffffffffff05
  1e:	e9 4b ff ff ff       	jmpq   0xffffffffffffff6e
  23:	0f 0b                	ud2    
  25:	e9 1c ff ff ff       	jmpq   0xffffffffffffff46
  2a:*	0f 0b                	ud2    		<-- trapping instruction
  2c:	66 66 2e 0f 1f 84 00 	data16 nopw %cs:0x0(%rax,%rax,1)
  33:	00 00 00 00 
  37:	66                   	data16
  38:	66                   	data16
  39:	2e                   	cs
  3a:	0f                   	.byte 0xf
  3b:	1f                   	(bad)  
  3c:	84 00                	test   %al,(%rax)
	...

Code starting with the faulting instruction
===========================================
   0:	0f 0b                	ud2    
   2:	66 66 2e 0f 1f 84 00 	data16 nopw %cs:0x0(%rax,%rax,1)
   9:	00 00 00 00 
   d:	66                   	data16
   e:	66                   	data16
   f:	2e                   	cs
  10:	0f                   	.byte 0xf
  11:	1f                   	(bad)  
  12:	84 00                	test   %al,(%rax)


The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20230907/202309071557.3a90e7a8-oliver.sang@intel.com



-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests

[Niklas Cassel]

On Thu, Sep 07, 2023 at 03:43:19PM +0800, kernel test robot wrote:
> 
> 
> Hello,
> 
> kernel test robot noticed "kernel_BUG_at_drivers/ata/libata-sff.c" on:
> 
> commit: d3d099d5c2dd38db84abd96df39f9f0828c16b7b ("[PATCH v4] ata: libata-eh: Honor all EH scheduling requests")
> url: https://github.com/intel-lab-lkp/linux/commits/linan666-huaweicloud-com/ata-libata-eh-Honor-all-EH-scheduling-requests/20230906-164907
> base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git 65d6e954e37872fd9afb5ef3fc0481bb3c2f20f4
> patch link: https://lore.kernel.org/all/20230906084212.1016634-1-linan666@huaweicloud.com/
> patch subject: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests
> 
> in testcase: boot
> 
> compiler: gcc-12
> test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

Unfortunately the problem reported by the kernel test robot is very real.
I could reproduce without too much effort in QEMU.

The problem is basically that we cannot simply perform a host_eh_scheduled--;
in ata_std_end_eh().

ata_std_end_eh() is called at the end of ata_scsi_port_error_handler(),
so it is called once every time ata_scsi_port_error_handler() is called.

However, ata_scsi_port_error_handler() will be called by SCSI EH each
time SCSI wakes up.

SCSI EH will sleep as long as:
if ((shost->host_failed == 0 && shost->host_eh_scheduled == 0) ||
                    shost->host_failed != scsi_host_busy(shost)) {
	schedule();
	continue;
}


The methods in libata which we use to trigger EH are:

1) ata_std_sched_eh(), which calls scsi_schedule_eh(), which does
host_eh_scheduled++;

2) ata_qc_schedule_eh(), which will end up in scsi_timeout,
which calls scsi_eh_scmd_add() which does:
host_failed++;


So before this patch, setting host_eh_scheduled = 0; in ata_std_end_eh()
makes us say that works because it only negates the EH scheduled by
ata_std_sched_eh().

However, if we do host_eh_scheduled--, then if the EH was triggered by
ata_qc_schedule_eh(), then host_eh_scheduled will decrease < 0,
which will trigger SCSI EH to wake up again :)

We could do something like only decreasing host_eh_scheduled if it is > 0.
The QCs added to EH using ata_qc_schedule_eh() will be handled by
ata_eh_finish(), which will iterate over all QCs owned by EH, and will
either fail or retry each QC. After that scsi_error_handler() has finished
the call to eh_strategy_handler() (ata_scsi_error()) it will unconditionally
set host_failed to 0:
https://github.com/torvalds/linux/blob/v6.5/drivers/scsi/scsi_error.c#L2331-L2337

So something like this on top of the patch in $subject:

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 2d5ecd68b7e0..9ab12d7f6d9f 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -952,7 +952,13 @@ EXPORT_SYMBOL_GPL(ata_std_sched_eh);
  */
 void ata_std_end_eh(struct ata_port *ap)
 {
-       ap->scsi_host->host_eh_scheduled--;
+       struct Scsi_Host *host = ap->scsi_host;
+       unsigned long flags;
+
+       spin_lock_irqsave(host->host_lock, flags);
+       if (host->host_eh_scheduled > 0)
+               host->host_eh_scheduled--;
+       spin_unlock_irqrestore(host->host_lock, flags);
 }
 EXPORT_SYMBOL(ata_std_end_eh);


With that incremental patch, I can no longer reproduce the crash reported
by the kernel test robot in my QEMU setup.



It might be worth mentioning that the race window for the bug that the patch
in $subject is fixing, should be much smaller after this patch is in:
https://lore.kernel.org/linux-ide/20230907081710.4946-1-Chloe_Chen@asmedia.com.tw/

Li Nan, perhaps you could see if you can still reproduce your original
problem with the patch from the ASMedia guys?

However, even with the ASMedia patch, it should still be theoretically
possible to get an error irq after ata_eh_reset() has called ahci_thaw(),
so I suppose that this patch still makes some sense...


Kind regards,
Niklas

Re: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests

[Damien Le Moal]

On 9/8/23 06:02, Niklas Cassel wrote:
> On Thu, Sep 07, 2023 at 03:43:19PM +0800, kernel test robot wrote:
>>
>>
>> Hello,
>>
>> kernel test robot noticed "kernel_BUG_at_drivers/ata/libata-sff.c" on:
>>
>> commit: d3d099d5c2dd38db84abd96df39f9f0828c16b7b ("[PATCH v4] ata: libata-eh: Honor all EH scheduling requests")
>> url: https://github.com/intel-lab-lkp/linux/commits/linan666-huaweicloud-com/ata-libata-eh-Honor-all-EH-scheduling-requests/20230906-164907
>> base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git 65d6e954e37872fd9afb5ef3fc0481bb3c2f20f4
>> patch link: https://lore.kernel.org/all/20230906084212.1016634-1-linan666@huaweicloud.com/
>> patch subject: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests
>>
>> in testcase: boot
>>
>> compiler: gcc-12
>> test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
> 
> Unfortunately the problem reported by the kernel test robot is very real.
> I could reproduce without too much effort in QEMU.
> 
> The problem is basically that we cannot simply perform a host_eh_scheduled--;
> in ata_std_end_eh().
> 
> ata_std_end_eh() is called at the end of ata_scsi_port_error_handler(),
> so it is called once every time ata_scsi_port_error_handler() is called.
> 
> However, ata_scsi_port_error_handler() will be called by SCSI EH each
> time SCSI wakes up.
> 
> SCSI EH will sleep as long as:
> if ((shost->host_failed == 0 && shost->host_eh_scheduled == 0) ||
>                     shost->host_failed != scsi_host_busy(shost)) {
> 	schedule();
> 	continue;
> }
> 
> 
> The methods in libata which we use to trigger EH are:
> 
> 1) ata_std_sched_eh(), which calls scsi_schedule_eh(), which does
> host_eh_scheduled++;
> 
> 2) ata_qc_schedule_eh(), which will end up in scsi_timeout,
> which calls scsi_eh_scmd_add() which does:
> host_failed++;
> 
> 
> So before this patch, setting host_eh_scheduled = 0; in ata_std_end_eh()
> makes us say that works because it only negates the EH scheduled by
> ata_std_sched_eh().
> 
> However, if we do host_eh_scheduled--, then if the EH was triggered by
> ata_qc_schedule_eh(), then host_eh_scheduled will decrease < 0,
> which will trigger SCSI EH to wake up again :)
> 
> We could do something like only decreasing host_eh_scheduled if it is > 0.
> The QCs added to EH using ata_qc_schedule_eh() will be handled by
> ata_eh_finish(), which will iterate over all QCs owned by EH, and will
> either fail or retry each QC. After that scsi_error_handler() has finished
> the call to eh_strategy_handler() (ata_scsi_error()) it will unconditionally
> set host_failed to 0:
> https://github.com/torvalds/linux/blob/v6.5/drivers/scsi/scsi_error.c#L2331-L2337
> 
> So something like this on top of the patch in $subject:
> 
> diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
> index 2d5ecd68b7e0..9ab12d7f6d9f 100644
> --- a/drivers/ata/libata-eh.c
> +++ b/drivers/ata/libata-eh.c
> @@ -952,7 +952,13 @@ EXPORT_SYMBOL_GPL(ata_std_sched_eh);
>   */
>  void ata_std_end_eh(struct ata_port *ap)
>  {
> -       ap->scsi_host->host_eh_scheduled--;
> +       struct Scsi_Host *host = ap->scsi_host;
> +       unsigned long flags;
> +
> +       spin_lock_irqsave(host->host_lock, flags);
> +       if (host->host_eh_scheduled > 0)
> +               host->host_eh_scheduled--;
> +       spin_unlock_irqrestore(host->host_lock, flags);
>  }
>  EXPORT_SYMBOL(ata_std_end_eh);
> 
> 
> With that incremental patch, I can no longer reproduce the crash reported
> by the kernel test robot in my QEMU setup.

I am not confident that playing with host_eh_schedule count is the right
approach. A better solution may be to change the timing of clearing
ATA_PFLAG_EH_PENDING. Right now, this is done on entry to
ata_scsi_port_error_handler(), unconditionally. So ata_eh_reset() should not
need to clear the flag again. If we remove that, then a new interrupt received
after ata_eh_thaw() and setting EH_PENDING would be cought by the retry loop in
ata_scsi_port_error_handler(), which would run again ap->ops->error_handler(ap).

So let's try this fix instead:

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 159ba6ba19eb..d1d081aa0c95 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -2807,7 +2807,6 @@ int ata_eh_reset(struct ata_link *link, int classify,
        memset(&link->eh_info, 0, sizeof(link->eh_info));
        if (slave)
                memset(&slave->eh_info, 0, sizeof(link->eh_info));
-       ap->pflags &= ~ATA_PFLAG_EH_PENDING;
        spin_unlock_irqrestore(link->ap->lock, flags);

        if (ata_port_is_frozen(ap))

Li,

Can you please test this ?

> 
> 
> 
> It might be worth mentioning that the race window for the bug that the patch
> in $subject is fixing, should be much smaller after this patch is in:
> https://lore.kernel.org/linux-ide/20230907081710.4946-1-Chloe_Chen@asmedia.com.tw/
> 
> Li Nan, perhaps you could see if you can still reproduce your original
> problem with the patch from the ASMedia guys?


> 
> However, even with the ASMedia patch, it should still be theoretically
> possible to get an error irq after ata_eh_reset() has called ahci_thaw(),
> so I suppose that this patch still makes some sense...
> 
> 
> Kind regards,
> Niklas

-- 
Damien Le Moal
Western Digital Research

Re: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests

[Li Nan]

在 2023/9/8 5:02, Niklas Cassel 写道:
> On Thu, Sep 07, 2023 at 03:43:19PM +0800, kernel test robot wrote:

[snip]

> 
> It might be worth mentioning that the race window for the bug that the patch
> in $subject is fixing, should be much smaller after this patch is in:
> https://lore.kernel.org/linux-ide/20230907081710.4946-1-Chloe_Chen@asmedia.com.tw/
> 
> Li Nan, perhaps you could see if you can still reproduce your original
> problem with the patch from the ASMedia guys?
> 

Thanks for your suggestion. We have briefly tested this patch and it can
fix the original problem . More tests is underway.

-- 
Thanks,
Nan

Re: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests

[Li Nan]

在 2023/9/11 15:16, Damien Le Moal 写道:
> On 9/8/23 06:02, Niklas Cassel wrote:
>> On Thu, Sep 07, 2023 at 03:43:19PM +0800, kernel test robot wrote:
> 
> I am not confident that playing with host_eh_schedule count is the right

Yeah, If there is some way can wake up EH without inc host_eh_schedule,
dec count becomes risky.

> approach. A better solution may be to change the timing of clearing
> ATA_PFLAG_EH_PENDING. Right now, this is done on entry to
> ata_scsi_port_error_handler(), unconditionally. So ata_eh_reset() should not
> need to clear the flag again. If we remove that, then a new interrupt received
> after ata_eh_thaw() and setting EH_PENDING would be cought by the retry loop in
> ata_scsi_port_error_handler(), which would run again ap->ops->error_handler(ap).
> 
> So let's try this fix instead:
> 
> diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
> index 159ba6ba19eb..d1d081aa0c95 100644
> --- a/drivers/ata/libata-eh.c
> +++ b/drivers/ata/libata-eh.c
> @@ -2807,7 +2807,6 @@ int ata_eh_reset(struct ata_link *link, int classify,
>          memset(&link->eh_info, 0, sizeof(link->eh_info));
>          if (slave)
>                  memset(&slave->eh_info, 0, sizeof(link->eh_info));
> -       ap->pflags &= ~ATA_PFLAG_EH_PENDING;
>          spin_unlock_irqrestore(link->ap->lock, flags);
> 
>          if (ata_port_is_frozen(ap))
> 
> Li,
> 
> Can you please test this ?
> 

OK, Let us test this patch.

>>
>>
>> It might be worth mentioning that the race window for the bug that the patch
>> in $subject is fixing, should be much smaller after this patch is in:
>> https://lore.kernel.org/linux-ide/20230907081710.4946-1-Chloe_Chen@asmedia.com.tw/
>>
>> Li Nan, perhaps you could see if you can still reproduce your original
>> problem with the patch from the ASMedia guys?
> 
> 
>>
>> However, even with the ASMedia patch, it should still be theoretically
>> possible to get an error irq after ata_eh_reset() has called ahci_thaw(),
>> so I suppose that this patch still makes some sense...
>>
>>
>> Kind regards,
>> Niklas
> 

-- 
Thanks,
Nan

Re: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests

[Niklas Cassel]

On Mon, Sep 11, 2023 at 04:16:55PM +0900, Damien Le Moal wrote:
> On 9/8/23 06:02, Niklas Cassel wrote:
> > On Thu, Sep 07, 2023 at 03:43:19PM +0800, kernel test robot wrote:
> >>
> >>
> >> Hello,
> >>
> >> kernel test robot noticed "kernel_BUG_at_drivers/ata/libata-sff.c" on:
> >>
> >> commit: d3d099d5c2dd38db84abd96df39f9f0828c16b7b ("[PATCH v4] ata: libata-eh: Honor all EH scheduling requests")
> >> url: https://github.com/intel-lab-lkp/linux/commits/linan666-huaweicloud-com/ata-libata-eh-Honor-all-EH-scheduling-requests/20230906-164907
> >> base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git 65d6e954e37872fd9afb5ef3fc0481bb3c2f20f4
> >> patch link: https://lore.kernel.org/all/20230906084212.1016634-1-linan666@huaweicloud.com/
> >> patch subject: [PATCH v4] ata: libata-eh: Honor all EH scheduling requests
> >>
> >> in testcase: boot
> >>
> >> compiler: gcc-12
> >> test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
> > 
> > Unfortunately the problem reported by the kernel test robot is very real.
> > I could reproduce without too much effort in QEMU.
> > 
> > The problem is basically that we cannot simply perform a host_eh_scheduled--;
> > in ata_std_end_eh().
> > 
> > ata_std_end_eh() is called at the end of ata_scsi_port_error_handler(),
> > so it is called once every time ata_scsi_port_error_handler() is called.
> > 
> > However, ata_scsi_port_error_handler() will be called by SCSI EH each
> > time SCSI wakes up.
> > 
> > SCSI EH will sleep as long as:
> > if ((shost->host_failed == 0 && shost->host_eh_scheduled == 0) ||
> >                     shost->host_failed != scsi_host_busy(shost)) {
> > 	schedule();
> > 	continue;
> > }
> > 
> > 
> > The methods in libata which we use to trigger EH are:
> > 
> > 1) ata_std_sched_eh(), which calls scsi_schedule_eh(), which does
> > host_eh_scheduled++;
> > 
> > 2) ata_qc_schedule_eh(), which will end up in scsi_timeout,
> > which calls scsi_eh_scmd_add() which does:
> > host_failed++;
> > 
> > 
> > So before this patch, setting host_eh_scheduled = 0; in ata_std_end_eh()
> > makes us say that works because it only negates the EH scheduled by
> > ata_std_sched_eh().
> > 
> > However, if we do host_eh_scheduled--, then if the EH was triggered by
> > ata_qc_schedule_eh(), then host_eh_scheduled will decrease < 0,
> > which will trigger SCSI EH to wake up again :)
> > 
> > We could do something like only decreasing host_eh_scheduled if it is > 0.
> > The QCs added to EH using ata_qc_schedule_eh() will be handled by
> > ata_eh_finish(), which will iterate over all QCs owned by EH, and will
> > either fail or retry each QC. After that scsi_error_handler() has finished
> > the call to eh_strategy_handler() (ata_scsi_error()) it will unconditionally
> > set host_failed to 0:
> > https://github.com/torvalds/linux/blob/v6.5/drivers/scsi/scsi_error.c#L2331-L2337
> > 
> > So something like this on top of the patch in $subject:
> > 
> > diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
> > index 2d5ecd68b7e0..9ab12d7f6d9f 100644
> > --- a/drivers/ata/libata-eh.c
> > +++ b/drivers/ata/libata-eh.c
> > @@ -952,7 +952,13 @@ EXPORT_SYMBOL_GPL(ata_std_sched_eh);
> >   */
> >  void ata_std_end_eh(struct ata_port *ap)
> >  {
> > -       ap->scsi_host->host_eh_scheduled--;
> > +       struct Scsi_Host *host = ap->scsi_host;
> > +       unsigned long flags;
> > +
> > +       spin_lock_irqsave(host->host_lock, flags);
> > +       if (host->host_eh_scheduled > 0)
> > +               host->host_eh_scheduled--;
> > +       spin_unlock_irqrestore(host->host_lock, flags);
> >  }
> >  EXPORT_SYMBOL(ata_std_end_eh);
> > 
> > 
> > With that incremental patch, I can no longer reproduce the crash reported
> > by the kernel test robot in my QEMU setup.
> 
> I am not confident that playing with host_eh_schedule count is the right
> approach. A better solution may be to change the timing of clearing
> ATA_PFLAG_EH_PENDING. Right now, this is done on entry to
> ata_scsi_port_error_handler(), unconditionally. So ata_eh_reset() should not
> need to clear the flag again. If we remove that, then a new interrupt received
> after ata_eh_thaw() and setting EH_PENDING would be cought by the retry loop in
> ata_scsi_port_error_handler(), which would run again ap->ops->error_handler(ap).

I agree that removing the clearing of ATA_PFLAG_EH_PENDING from ata_eh_reset()
would be a nicer fix, if that can be done without introducing regressions.

Looking at git blame:
https://github.com/torvalds/linux/commit/1e641060c4b564e820abdb6a4c7a603a0d386250

It seems that the patch was added because some controllers "may set spuruious
error conditions during reset."

Looking at the original bug report that resulted in this workaround:
https://marc.info/?l=linux-ide&m=124765325828495&w=2

PxIS is:
[    1.497808] ata3: irq_stat 0x00400040, connection status changed

Which means that PxIS.PCS and PxIS.PRCS was set.

PxIS.PCS:
"Port Connect Change Status (PCS): 1=Change in Current Connect Status. 0=No
change in Current Connect Status. This bit reflects the state of PxSERR.DIAG.X.
This bit is only cleared when PxSERR.DIAG.X is cleared."

PxIS.PRCS:
"PhyRdy Change Status (PRCS): When set to ‘1’ indicates the internal PhyRdy signal
changed state. This bit reflects the state of PxSERR.DIAG.N. To clear this bit,
software must clear PxSERR.DIAG.N to ‘0’."

So it seems that these IRQ bits get set as a result of the COMRESET itself.
Thus the patch in:
https://lore.kernel.org/linux-ide/b991c72c-99da-e4f2-055b-fa8b12e0efc4@kernel.org/T/#t
which clears PxIS before the COMRESET), is not relevant to this workaround.


Looking a bit closer at the original bug report, the user is simply complaining
that he is seeing a hard reset after probing:
[    1.521856] ata8: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xf t4
[    1.521908] ata8: irq_stat 0x00400040, connection status changed
[    1.521962] ata8: hard resetting link

But other than that, the HBA and drive works as it should:
https://marc.info/?l=linux-ide&m=124709313323657&w=2


Looking at the AHCI 1.3.1 specification, after the host has issued a COMRESET,
the device will reply will a COMINIT.

"When a COMINIT is received, the PxSSTS.DET field shall be set to 1h.
When the communication negotiation sequence is complete and PhyRdy is true
the PxSSTS.DET field shall be set to 3h."

And according to "10.4.2 Port Reset" in AHCI 1.3.1, after issuing a COMRESET,
software must wait for PxSSTS.DET to be set to 3h.


This is done by sata_link_hardreset(), which calls sata_link_resume(),
which calls sata_link_debounce(), which waits for PxSSTS.DET to be != 0x1,
additionally it will return 0 if PxSSTS.DET == 0x1 and timeout is reached.......
(This is a bit unfortunate, and not according to AHCI spec, as it should
strictly wait for it to be 0x3... perhaps there should at least be a warning
if we return while the value is not 0x3.....)

While calling sata_link_hardreset(), port is frozen/IRQs are masked, so this
shouldn't trigger a PhyRdy IRQ. Additionally thawing the port clears pending
IRQs, so any COMINIT received before PxSSTS.DET gets set to 0x3 should not
trigger an IRQ when thawing the port.

If we assume that sata_link_debounce() is not broken and the reason why
sata_link_debounce() returned was because PxSSTS.DET == 0x3, then the most
logical thing is that this is an unsolicited COMINIT (i.e. we received a
COMINIT after PxSSTS.DET was set to 0x3), see:
"6.2.2.3 Recovery of Unsolicited COMINIT" in AHCI 1.3.1.

The spec claims that we should perform an additional COMRESET when this happens
(when PxIS.PCS is set), which is exactly what libahci does:
https://github.com/torvalds/linux/blob/v6.5/drivers/ata/libahci.c#L1834
https://github.com/torvalds/linux/blob/v6.5/include/linux/libata.h#L1555


Since we clear both PxIS and PxSERR after a reset, before thawing the port,
the only logical thing is that we are receiving an unsolicited COMINIT,
and when receiving an unsolicited COMINIT, the proper action is to perform
an additional hardreset. Since the original author was simply complaining
about reset print in dmesg, and that his system was still working, I suggest
that we remove the clearing of ATA_PFLAG_EH_PENDING from ata_eh_reset(), as
it appears that everything is working as per the spec.

Perhaps we should also add a warning in sata_link_debounce() or
sata_link_resume(), so that we can be confident that PxSSTS.DET is 0x3 before
clearing SError and PxIS. (Because if this is not the case, then the bug is
that libata is continuing/resuming before the link has been fully established.)


Kind regards,
Niklas