libata: PIO race condition fixes

Jeff,

Two more libata misc patches for your review.

1. Fix race condition in ata_pio_task().
2. Remove 'case ATA_PROT_ATAPI' in the ata_host_intr() interrupt handler.

Albert

Jeff,

This is patch 1/2.
Problem:
'assert(qc != NULL)' failed in ata_pio_block() and ata_pio_complete().

Root cause:
Race condition in ata_pio_task() when accessing 'ap->pio_task_state' after ata_qc_complete():
If the next command is queued after ata_qc_complete() and before ata_pio_task() checks 'ap->pio_task_state', 'ap->pio_task_state' might have been changed from PIO_ST_IDLE to PIO_ST by ata_qc_issue_prot(). This will cause ata_pio_task() to run extra steps even if the command is finished.
The extra steps race with the next command and causing trouble.

Changes:
- Let ata_pio_complete() and ata_pio_block() return explicitly whether queuing next step is needed.
- Use the return value to determine whether next step is needed, instead of checking the volatile 'ap->pio_task_state' variable.

Attached please find the patch against the linux-2.6.git tree (HEAD ee98689be1b054897ff17655008c3048fe88be94) for your review. Thanks.

Albert

@@ -2455,7 +2455,7 @@
  *	None.  (executing in kernel thread context)
  */
 
-static void ata_pio_complete (struct ata_port *ap)
+static int ata_pio_complete (struct ata_port *ap)
 {
 	struct ata_queued_cmd *qc;
 	u8 drv_stat;

@@ -2475,14 +2475,14 @@
 		if (drv_stat & (ATA_BUSY | ATA_DRQ)) {
 			ap->pio_task_state = PIO_ST_LAST_POLL;
 			ap->pio_task_timeout = jiffies + ATA_TMOUT_PIO;
-			return;
+			return 1; /* queue next step */
 		}
 	}
 
 	drv_stat = ata_wait_idle(ap);
 	if (!ata_ok(drv_stat)) {
 		ap->pio_task_state = PIO_ST_ERR;
-		return;
+		return 1; /* queue next step */
 	}
 
 	qc = ata_qc_from_tag(ap, ap->active_tag);

@@ -2493,6 +2493,7 @@
 	ata_irq_on(ap);
 
 	ata_qc_complete(qc, drv_stat);
+	return 0; /* last step */
 }
 
 

@@ -2683,7 +2684,7 @@
  *	None.  (executing in kernel thread context)
  */
 
-static void ata_pio_block(struct ata_port *ap)
+static int ata_pio_block(struct ata_port *ap)
 {
 	struct ata_queued_cmd *qc;
 	u8 status;

@@ -2703,7 +2704,7 @@
 		if (status & ATA_BUSY) {
 			ap->pio_task_state = PIO_ST_POLL;
 			ap->pio_task_timeout = jiffies + ATA_TMOUT_PIO;
-			return;
+			return 1; /* queue next step */
 		}
 	}
 

@@ -2718,7 +2719,7 @@
 			ata_irq_on(ap);
 
 			ata_qc_complete(qc, status);
-			return;
+			return 0; /* last step */
 		}
 
 		atapi_pio_bytes(qc);

@@ -2726,11 +2727,13 @@
 		/* handle BSY=0, DRQ=0 as error */
 		if ((status & ATA_DRQ) == 0) {
 			ap->pio_task_state = PIO_ST_ERR;
-			return;
+			return 1; /* queue next step */
 		}
 
 		ata_pio_sector(qc);
 	}
+
+	return 1; /* queue next step */
 }
 
 static void ata_pio_error(struct ata_port *ap)

@@ -2756,21 +2759,20 @@
 {
 	struct ata_port *ap = _data;
 	unsigned long timeout = 0;
+	int next_step;
 
 	switch (ap->pio_task_state) {
-	case PIO_ST_IDLE:
-		return;
-
 	case PIO_ST:
-		ata_pio_block(ap);
+		next_step = ata_pio_block(ap);
 		break;
 
 	case PIO_ST_LAST:
-		ata_pio_complete(ap);
+		next_step = ata_pio_complete(ap);
 		break;
 
 	case PIO_ST_POLL:
 	case PIO_ST_LAST_POLL:
+		next_step = 1;
 		timeout = ata_pio_poll(ap);
 		break;
 

@@ -2778,11 +2780,26 @@
 	case PIO_ST_ERR:
 		ata_pio_error(ap);
 		return;
+	default:
+		printk(KERN_ERR "Unknown PIO task state %u\n", 
+		       ap->pio_task_state);
+		return;
 	}
 
+	/* Don't access ap->pio_task_state here.
+	 *
+	 * Access ap->pio_task_state here will cause race condition
+	 * between this code path and the ata_qc_issue_prot() code path:
+	 * If ata_qc_complete() has been called above, the SCSI layer 
+	 * might have sent the next command to libata for queuing.
+	 * And ap->pio_task_state might have been changed
+	 * by ata_qc_issue_prot(). 
+	 */
+	if (!next_step)
+		return;
+
 	if (timeout)
-		queue_delayed_work(ata_wq, &ap->pio_task,
-				   timeout);
+		queue_delayed_work(ata_wq, &ap->pio_task, timeout);
 	else
 		queue_work(ata_wq, &ap->pio_task);
 }

Jeff,

This is patch 1/2. (The previous subject is incorrect. Resend it here.) Problem:
'assert(qc != NULL)' failed in ata_pio_block() and ata_pio_complete().

Root cause:
Race condition in ata_pio_task() when accessing 'ap->pio_task_state' after ata_qc_complete():
If the next command is queued after ata_qc_complete() and before ata_pio_task() checks 'ap->pio_task_state', 'ap->pio_task_state' might have been changed from PIO_ST_IDLE to PIO_ST by ata_qc_issue_prot(). This will cause ata_pio_task() to run extra steps even if the command is finished.
The extra steps race with the next command and causing trouble.

Changes:
- Let ata_pio_complete() and ata_pio_block() return explicitly whether queuing next step is needed.
- Use the return value to determine whether next step is needed, instead of checking the volatile 'ap->pio_task_state' variable.

Attached please find the patch against the linux-2.6.git tree (HEAD ee98689be1b054897ff17655008c3048fe88be94) for your review. Thanks.

Albert

@@ -2455,7 +2455,7 @@
  *	None.  (executing in kernel thread context)
  */
 
-static void ata_pio_complete (struct ata_port *ap)
+static int ata_pio_complete (struct ata_port *ap)
 {
 	struct ata_queued_cmd *qc;
 	u8 drv_stat;

@@ -2475,14 +2475,14 @@
 		if (drv_stat & (ATA_BUSY | ATA_DRQ)) {
 			ap->pio_task_state = PIO_ST_LAST_POLL;
 			ap->pio_task_timeout = jiffies + ATA_TMOUT_PIO;
-			return;
+			return 1; /* queue next step */
 		}
 	}
 
 	drv_stat = ata_wait_idle(ap);
 	if (!ata_ok(drv_stat)) {
 		ap->pio_task_state = PIO_ST_ERR;
-		return;
+		return 1; /* queue next step */
 	}
 
 	qc = ata_qc_from_tag(ap, ap->active_tag);

@@ -2493,6 +2493,7 @@
 	ata_irq_on(ap);
 
 	ata_qc_complete(qc, drv_stat);
+	return 0; /* last step */
 }
 
 

@@ -2683,7 +2684,7 @@
  *	None.  (executing in kernel thread context)
  */
 
-static void ata_pio_block(struct ata_port *ap)
+static int ata_pio_block(struct ata_port *ap)
 {
 	struct ata_queued_cmd *qc;
 	u8 status;

@@ -2703,7 +2704,7 @@
 		if (status & ATA_BUSY) {
 			ap->pio_task_state = PIO_ST_POLL;
 			ap->pio_task_timeout = jiffies + ATA_TMOUT_PIO;
-			return;
+			return 1; /* queue next step */
 		}
 	}
 

@@ -2718,7 +2719,7 @@
 			ata_irq_on(ap);
 
 			ata_qc_complete(qc, status);
-			return;
+			return 0; /* last step */
 		}
 
 		atapi_pio_bytes(qc);

@@ -2726,11 +2727,13 @@
 		/* handle BSY=0, DRQ=0 as error */
 		if ((status & ATA_DRQ) == 0) {
 			ap->pio_task_state = PIO_ST_ERR;
-			return;
+			return 1; /* queue next step */
 		}
 
 		ata_pio_sector(qc);
 	}
+
+	return 1; /* queue next step */
 }
 
 static void ata_pio_error(struct ata_port *ap)

@@ -2756,21 +2759,20 @@
 {
 	struct ata_port *ap = _data;
 	unsigned long timeout = 0;
+	int next_step;
 
 	switch (ap->pio_task_state) {
-	case PIO_ST_IDLE:
-		return;
-
 	case PIO_ST:
-		ata_pio_block(ap);
+		next_step = ata_pio_block(ap);
 		break;
 
 	case PIO_ST_LAST:
-		ata_pio_complete(ap);
+		next_step = ata_pio_complete(ap);
 		break;
 
 	case PIO_ST_POLL:
 	case PIO_ST_LAST_POLL:
+		next_step = 1;
 		timeout = ata_pio_poll(ap);
 		break;
 

@@ -2778,11 +2780,26 @@
 	case PIO_ST_ERR:
 		ata_pio_error(ap);
 		return;
+	default:
+		printk(KERN_ERR "Unknown PIO task state %u\n", 
+		       ap->pio_task_state);
+		return;
 	}
 
+	/* Don't access ap->pio_task_state here.
+	 *
+	 * Access ap->pio_task_state here will cause race condition
+	 * between this code path and the ata_qc_issue_prot() code path:
+	 * If ata_qc_complete() has been called above, the SCSI layer 
+	 * might have sent the next command to libata for queuing.
+	 * And ap->pio_task_state might have been changed
+	 * by ata_qc_issue_prot(). 
+	 */
+	if (!next_step)
+		return;
+
 	if (timeout)
-		queue_delayed_work(ata_wq, &ap->pio_task,
-				   timeout);
+		queue_delayed_work(ata_wq, &ap->pio_task, timeout);
 	else
 		queue_work(ata_wq, &ap->pio_task);
 }

Jeff,

Attached please find the detailed debug trace with annotation for the problem. Hopefully it can help to make the problem description clearer.

Albert

<3>ata_scsi_dump_cdb: CDB (1:0,0,0) be 00 00 04 0c b4 00 00 01 <3>ata_scsi_translate: ENTER
<3>ata_dev_select: ENTER, ata1: device 0, wait 1 <3>ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 <3>ata_tf_load_pio: device 0xA0 <3>ata_exec_command_pio: ata1: cmd 0xA0 <3>ata_scsi_translate: EXIT
<3>atapi_packet_task: busy wait <3>atapi_packet_task: send cdb
<3>atapi_packet_task: EXIT
<3>ata_pio_task: pio_task_state 4
<3>ata_pio_block: ENTER
<3>__atapi_pio_bytes: data read
<3>ata_pio_block: EXIT 2
<3>ata_pio_task: pio_task_state 5 <3>ata_pio_complete: ENTER
<3>ata_qc_complete: ENTER
<3>__ata_qc_complete: ENTER
<3>__ata_qc_complete: EXIT
<3>ata_qc_complete: EXIT

<== Oops! ata_pio_complete() does not return yet, and the next command comes in!
The missing ata_pio_complete() will cause trouble later.

<3>ata_scsi_dump_cdb: CDB (1:0,1,0) be 00 00 04 0d 24 00 00 01 <3>ata_scsi_translate: ENTER
<3>ata_dev_select: ENTER, ata1: device 1, wait 1 <3>ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 <3>ata_tf_load_pio: device 0xB0 <3>ata_exec_command_pio: ata1: cmd 0xA0 <3>ata_scsi_translate: EXIT
<3>atapi_packet_task: busy wait <3>atapi_packet_task: send cdb
<3>atapi_packet_task: EXIT
<3>ata_pio_task: pio_task_state 4
<3>ata_pio_block: ENTER
<3>__atapi_pio_bytes: data read
<3>ata_pio_block: EXIT 2
<3>ata_pio_task: pio_task_state 5 <3>ata_pio_complete: ENTER
<3>ata_qc_complete: ENTER
<3>__ata_qc_complete: ENTER
<3>__ata_qc_complete: EXIT
<3>ata_qc_complete: EXIT
<3>ata_pio_complete: EXIT

<== This "READ CD" completed normally.

<3>ata_scsi_dump_cdb: CDB (1:0,1,0) be 00 00 04 0d 24 00 00 01 <3>ata_scsi_translate: ENTER
<3>ata_dev_select: ENTER, ata1: device 1, wait 1 <3>ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 <3>ata_tf_load_pio: device 0xB0 <3>ata_exec_command_pio: ata1: cmd 0xA0 <3>ata_scsi_translate: EXIT
<3>atapi_packet_task: busy wait <3>atapi_packet_task: send cdb
<3>atapi_packet_task: EXIT
<3>ata_pio_task: pio_task_state 4
<3>ata_pio_block: ENTER
<3>__atapi_pio_bytes: data read
<3>ata_pio_block: EXIT 2
<3>ata_pio_task: pio_task_state 5 <3>ata_pio_complete: ENTER
<3>ata_qc_complete: ENTER
<3>__ata_qc_complete: ENTER
<3>__ata_qc_complete: EXIT
<3>ata_qc_complete: EXIT
<3>ata_pio_complete: EXIT

<== This "READ CD" completed normally.

<3>ata_scsi_dump_cdb: CDB (1:0,0,0) be 00 00 04 0c b6 00 00 01 <3>ata_scsi_translate: ENTER
<3>ata_dev_select: ENTER, ata1: device 0, wait 1 <3>ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 <3>ata_tf_load_pio: device 0xA0 <3>ata_exec_command_pio: ata1: cmd 0xA0 <3>ata_scsi_translate: EXIT
<3>atapi_packet_task: busy wait <3>atapi_packet_task: send cdb
<3>atapi_packet_task: EXIT
<3>ata_pio_task: pio_task_state 4
<3>ata_pio_block: ENTER
<3>ata_pio_complete: EXIT <== The previous missing ata_pio_complete().

                            <== Since pio_task_state was changed to 4 now, 
                            <== it will queue an extra ata_pio_task() and
                            <== starts racing with the current command.

<3>ata_pio_task: pio_task_state 4 (Oop! Extra ata_pio_task() queued!)
<3>ata_pio_block: ENTER
<3>__atapi_pio_bytes: data read
<3>__atapi_pio_bytes: ata1: padding 2336 bytes (Oop! extra data read!) <3>ata_pio_block: EXIT 2
<3>ata_pio_task: pio_task_state 5
<3>ata_pio_complete: ENTER
<3>ata_qc_complete: ENTER
<3>__ata_qc_complete: ENTER
<3>__ata_qc_complete: EXIT
<3>ata_qc_complete: EXIT
<3>ata_pio_complete: EXIT

<== The ata_pio_complete() was called twice!

<3>ata_scsi_dump_cdb: CDB (1:0,1,0) be 00 00 04 0d 26 00 00 01 <3>ata_scsi_translate: ENTER
<3>ata_dev_select: ENTER, ata1: device 1, wait 1 <3>ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 <3>ata_tf_load_pio: device 0xB0 <3>ata_exec_command_pio: ata1: cmd 0xA0 <3>ata_scsi_translate: EXIT
<3>atapi_packet_task: busy wait <3>atapi_packet_task: send cdb
<3>atapi_packet_task: EXIT
<3>ata_pio_task: pio_task_state 4
<3>ata_pio_block: ENTER
<3>__atapi_pio_bytes: data read
<3>ata_pio_block: EXIT 2
<3>ata_pio_task: pio_task_state 5 <3>ata_pio_complete: ENTER
<3>ata_qc_complete: ENTER
<3>__ata_qc_complete: ENTER
<3>__ata_qc_complete: EXIT
<3>ata_qc_complete: EXIT
<3>ata_pio_complete: EXIT
<3>ata_scsi_dump_cdb: CDB (1:0,0,0) be 00 00 04 0c b6 00 00 01 <3>ata_scsi_translate: ENTER
<3>ata_dev_select: ENTER, ata1: device 0, wait 1 <3>ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 <3>ata_tf_load_pio: device 0xA0 <3>ata_exec_command_pio: ata1: cmd 0xA0 <3>ata_scsi_translate: EXIT
<3>atapi_packet_task: busy wait <3>atapi_packet_task: send cdb
<3>atapi_packet_task: EXIT
<3>ata_pio_task: pio_task_state 4
<3>ata_pio_block: ENTER
<3>__atapi_pio_bytes: data read
<3>ata_pio_block: EXIT 2
<3>ata_pio_task: pio_task_state 5 <3>ata_pio_complete: ENTER
<3>ata_qc_complete: ENTER
<3>__ata_qc_complete: ENTER
<3>__ata_qc_complete: EXIT
<3>ata_qc_complete: EXIT
<3>ata_pio_complete: EXIT
<3>ata_scsi_dump_cdb: CDB (1:0,1,0) be 00 00 04 0d 26 00 00 01 <3>ata_scsi_translate: ENTER
<3>ata_dev_select: ENTER, ata1: device 1, wait 1 <3>ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 <3>ata_tf_load_pio: device 0xB0 <3>ata_exec_command_pio: ata1: cmd 0xA0 <3>ata_scsi_translate: EXIT
<3>atapi_packet_task: busy wait <3>atapi_packet_task: send cdb
<3>atapi_packet_task: EXIT
<3>ata_pio_task: pio_task_state 4
<3>ata_pio_block: ENTER
<3>__atapi_pio_bytes: data read
<3>ata_pio_block: EXIT 2
<3>ata_pio_task: pio_task_state 5 <3>ata_pio_complete: ENTER
<3>ata_qc_complete: ENTER
<3>__ata_qc_complete: ENTER
<3>__ata_qc_complete: EXIT
<3>ata_qc_complete: EXIT
<3>ata_pio_complete: EXIT
<3>ata_pio_block: EXIT 2

<== stopped in kdb. tcp/ip stack is victim.

[12]kdb> bt
Stack traceback for pid 13774
0xc000000123f60210 13774 13509 1 12 R 0xc000000123f606c0 *hxecom
SP(esp) PC(eip) Function(args)

0xc0000001220eb4e0  0xc0000000002fff60  .skb_release_data +0x120
0xc0000001220eb4e0  0xc0000000002ffb74 (lr) .kfree_skbmem +0x20
0xc0000001220eb570  0xc0000000002ffb74  .kfree_skbmem +0x20
0xc0000001220eb600  0xc0000000002ffce8  .__kfree_skb +0x148
0xc0000001220eb6b0  0xc000000000339e2c  .tcp_recvmsg +0x6e8
0xc0000001220eb830  0xc0000000003631b8  .inet_recvmsg +0x58
--- Exception: c0000001220eb9d8:  NO_SYMBOL or Userspace
0xc0000001220ebb20  0xc00000021fcd1b80  NO_SYMBOL or Userspace +0x58
0xc0000001220ebb20  0xc0000000000cd2cc (lr) .fget +0x2c
0xc00000000006ffa0  0x7c2004ac38000000  NO_SYMBOL or Userspace
    kdb: Not a kernel-space address 0x60000000e81c0048 

0x60000000e81c0038 0x0000000000000000
<Stack contents outside of kernel space. 60000000e81c0038>

Hi Jeff,

This is patch 2/2.
Problem:
Given ATA_PROT_ATAPI is handled with interrupt off.
=> If any interrupt occurs with protocol ATA_PROT_ATAPI, it is not our interrupt and should be ignored. (This problem is previously indicated by Bart as in:
http://marc.theaimsgroup.com/?l=linux-ide&m=111822488916620&w=2 )

In ata_pio_complete(), we have the following code:

	ata_irq_on(ap);
	// interrupt here might cause double completion of the command.
	ata_qc_complete(qc, drv_stat);

So, there might be race condition between ata_pio_complete() and interrupt handler.

Changes:
- Remove 'case ATA_PROT_ATAPI' in ata_host_intr().

Attached please find the patch against the linux-2.6.git tree for your review. Thanks.

Albert

@@ -3506,7 +3506,6 @@
 
 	case ATA_PROT_DMA:
 	case ATA_PROT_ATAPI_DMA:
-	case ATA_PROT_ATAPI:
 		/* check status of DMA engine */
 		host_stat = ap->ops->bmdma_status(ap);
 		VPRINTK("ata%u: host_stat 0x%X\n", ap->id, host_stat);