libata: Fix failed assertion in ata_qc_complete()
PATCH 1/1 libata: Fix failed assertion in ata_qc_complete()
Hi Jeff,
(This is the patch #4 in the summary.)
Problem:
'assert(qc->flags & ATA_QCFLAG_ACTIVE)' assertion failed in ata_pio_complete().
Root cause:
Please see the detailed dmesg log in the follow-up mail.
Change:
- Reorder the clearing of the 'qc->flags &= ~ATA_QCFLAG_ACTIVE' flag to be _before_ 'qc->complete_fn(qc, drv_stat)' instead of _after_.
- Add a comment per Tejun's advice.
Attached please find the patch against the linux-2.6.git tree (HEAD 9b4311eedb17fa88f02e4876cd6aa9a08e383cd6) for your review. Thanks.
Albert
drivers/scsi/libata-core.c renamed from drivers/scsi/libata-core.c.ori +6 -1
@@ -3086,9 +3086,14 @@if (likely (qc->flags &ATA_QCFLAG_DMAMAP ))ata_sg_clean (qc); +/* atapi: inactivate qc to prevent the interrupt handler from +* completing the command twice, before the scsi error handler +* is called. +*/ + qc->flags &= ~ATA_QCFLAG_ACTIVE ; +/* call completion callback */ rc = qc->complete_fn (qc, drv_stat); - qc->flags &= ~ATA_QCFLAG_ACTIVE ;/* if callback indicates not to complete command (non-zero), * return immediately
Hi Jeff,
Quoted 10 lines
(This is the patch #4 in the summary.)
Problem:'assert(qc->flags & ATA_QCFLAG_ACTIVE)' assertion failed in
ata_pio_complete().Root cause:
Please see the detailed dmesg log in the follow-up mail.
Attached please find the detailed trace of the problem.
Albert
The following is the log of the problematic transation:
Jun 27 07:14:46 lintest kernel: ata_scsi_dump_cdb: CDB (1:0,0,0) 43 00 00 00 00 00 00 00 0c Jun 27 07:14:46 lintest kernel: ata_scsi_translate: ENTER Jun 27 07:14:46 lintest kernel: ata_dev_select: ENTER, ata1: device 0, wait 1 Jun 27 07:14:46 lintest kernel: ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 Jun 27 07:14:46 lintest kernel: ata_tf_load_pio: device 0xA0 Jun 27 07:14:46 lintest kernel: ata_exec_command_pio: ata1: cmd 0xA0 Jun 27 07:14:46 lintest kernel: ata_scsi_translate: EXIT Jun 27 07:14:46 lintest kernel: atapi_packet_task: busy wait Jun 27 07:14:46 lintest kernel: atapi_packet_task: send cdb Jun 27 07:14:46 lintest kernel: atapi_packet_task: EXIT Jun 27 07:14:46 lintest kernel: ata_pio_task: pio_task_state 4 Jun 27 07:14:46 lintest kernel: ata_pio_block: ENTER Jun 27 07:14:46 lintest kernel: ata_qc_complete: ENTER Jun 27 07:14:46 lintest kernel: atapi_qc_complete: request check condition
<== The scsi error handler comes in early,
before ata_qc_complete() clears the ATA_QCFLAG_ACTIVE flag.
Jun 27 07:14:46 lintest kernel: ata_scsi_error: ENTER Jun 27 07:14:46 lintest kernel: ata_eng_timeout: ENTER Jun 27 07:14:46 lintest kernel: ata_qc_timeout: ENTER Jun 27 07:14:46 lintest kernel: __ata_qc_complete: ENTER Jun 27 07:14:46 lintest kernel: __ata_qc_complete: EXIT Jun 27 07:14:46 lintest kernel: atapi_request_sense: ATAPI request sense Jun 27 07:14:46 lintest kernel: ata_dev_select: ENTER, ata1: device 0, wait 1 Jun 27 07:14:46 lintest kernel: ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 Jun 27 07:14:46 lintest kernel: ata_tf_load_pio: device 0xA0 Jun 27 07:14:46 lintest kernel: ata_exec_command_pio: ata1: cmd 0xA0
<= scsi error handler has done calling __ata_qc_complete()
to full complete the original command.
It is now trying to get sense data.
The qc is made active again.
So, ATA_QCFLAG_ACTIVE is set again.
Jun 27 07:14:46 lintest kernel: atapi_packet_task: busy wait Jun 27 07:14:46 lintest kernel: atapi_packet_task: send cdb Jun 27 07:14:46 lintest kernel: atapi_packet_task: EXIT Jun 27 07:14:46 lintest kernel: ata_pio_task: pio_task_state 4 Jun 27 07:14:46 lintest kernel: ata_pio_block: ENTER
Jun 27 07:14:46 lintest kernel: ata_qc_complete: EXIT - need request sense later Jun 27 07:14:46 lintest kernel: ata_pio_block: EXIT 1
<= ata_qc_complete() races with the scsi error handler here.
ata_qc_complete() clears the ATA_QCFLAG_ACTIVE flag here.
<= ata_qc_complete() exits, leaving ATA_QCFLAG_ACTIVE flag cleared.
Jun 27 07:14:46 lintest kernel: __atapi_pio_bytes: data read Jun 27 07:14:46 lintest kernel: ata_pio_block: EXIT 2 Jun 27 07:14:46 lintest kernel: ata_pio_task: pio_task_state 4 Jun 27 07:14:46 lintest kernel: ata_pio_block: ENTER Jun 27 07:14:46 lintest kernel: Assertion failed! qc->flags & ATA_QCFLAG_ACTIVE,/root/build/linux-2.6.5-7.179/drivers/scsi/libata-core.c,ata_qc_complete,line=2906
<= The "get sense data" thread finds ATA_QCFLAG_ACTIVE flag to be cleared and displays error.
Jun 27 07:14:46 lintest kernel: ata_qc_complete: ENTER Jun 27 07:14:46 lintest kernel: __ata_qc_complete: ENTER Jun 27 07:14:46 lintest kernel: __ata_qc_complete: EXIT Jun 27 07:14:46 lintest kernel: ata_qc_complete: EXIT Jun 27 07:14:46 lintest kernel: ata_pio_block: EXIT 1 Jun 27 07:14:46 lintest kernel: atapi_request_sense: EXIT Jun 27 07:14:46 lintest kernel: ata_qc_timeout: Got sense data Jun 27 07:14:46 lintest kernel: ata_qc_timeout: EXIT Jun 27 07:14:46 lintest kernel: ata_eng_timeout: EXIT Jun 27 07:14:46 lintest kernel: ata_scsi_error: EXIT
==============
The following is the log of a normal transation:
Jun 27 07:14:46 lintest kernel: ata_scsi_dump_cdb: CDB (1:0,0,0) 43 00 00 00 00 00 00 00 0c Jun 27 07:14:46 lintest kernel: ata_scsi_translate: ENTER Jun 27 07:14:46 lintest kernel: ata_dev_select: ENTER, ata1: device 0, wait 1 Jun 27 07:14:46 lintest kernel: ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 Jun 27 07:14:46 lintest kernel: ata_tf_load_pio: device 0xA0 Jun 27 07:14:46 lintest kernel: ata_exec_command_pio: ata1: cmd 0xA0 Jun 27 07:14:46 lintest kernel: ata_scsi_translate: EXIT Jun 27 07:14:46 lintest kernel: atapi_packet_task: busy wait Jun 27 07:14:46 lintest kernel: atapi_packet_task: send cdb Jun 27 07:14:46 lintest kernel: atapi_packet_task: EXIT Jun 27 07:14:46 lintest kernel: ata_pio_task: pio_task_state 4 Jun 27 07:14:46 lintest kernel: ata_pio_block: ENTER Jun 27 07:14:46 lintest kernel: ata_qc_complete: ENTER Jun 27 07:14:46 lintest kernel: atapi_qc_complete: request check condition Jun 27 07:14:46 lintest kernel: ata_qc_complete: EXIT - need request sense later Jun 27 07:14:46 lintest kernel: ata_pio_block: EXIT 1 Jun 27 07:14:46 lintest kernel: ata_scsi_error: ENTER Jun 27 07:14:46 lintest kernel: ata_eng_timeout: ENTER Jun 27 07:14:46 lintest kernel: ata_qc_timeout: ENTER Jun 27 07:14:46 lintest kernel: __ata_qc_complete: ENTER Jun 27 07:14:46 lintest kernel: __ata_qc_complete: EXIT Jun 27 07:14:46 lintest kernel: atapi_request_sense: ATAPI request sense Jun 27 07:14:46 lintest kernel: ata_dev_select: ENTER, ata1: device 0, wait 1 Jun 27 07:14:46 lintest kernel: ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20 Jun 27 07:14:46 lintest kernel: ata_tf_load_pio: device 0xA0 Jun 27 07:14:46 lintest kernel: ata_exec_command_pio: ata1: cmd 0xA0 Jun 27 07:14:46 lintest kernel: atapi_packet_task: busy wait Jun 27 07:14:46 lintest kernel: atapi_packet_task: send cdb Jun 27 07:14:46 lintest kernel: atapi_packet_task: EXIT Jun 27 07:14:46 lintest kernel: ata_pio_task: pio_task_state 4 Jun 27 07:14:46 lintest kernel: ata_pio_block: ENTER Jun 27 07:14:46 lintest kernel: __atapi_pio_bytes: data read Jun 27 07:14:46 lintest kernel: ata_pio_block: EXIT 2 Jun 27 07:14:46 lintest kernel: ata_pio_task: pio_task_state 4 Jun 27 07:14:46 lintest kernel: ata_pio_block: ENTER Jun 27 07:14:46 lintest kernel: ata_qc_complete: ENTER Jun 27 07:14:46 lintest kernel: __ata_qc_complete: ENTER Jun 27 07:14:46 lintest kernel: __ata_qc_complete: EXIT Jun 27 07:14:46 lintest kernel: ata_qc_complete: EXIT Jun 27 07:14:46 lintest kernel: ata_pio_block: EXIT 1 Jun 27 07:14:46 lintest kernel: atapi_request_sense: EXIT Jun 27 07:14:46 lintest kernel: ata_qc_timeout: Got sense data Jun 27 07:14:46 lintest kernel: ata_qc_timeout: EXIT Jun 27 07:14:46 lintest kernel: ata_eng_timeout: EXIT Jun 27 07:14:46 lintest kernel: ata_scsi_error: EXIT