Request for Info: DMA timeout rq->buffer = NULL ?

Request for Info: DMA timeout rq->buffer = NULL ?

[Prarit Bhargava]

I've come across a situation which appears to be an issue where a 
request has had a DMA timeout and then been reissued in PIO mode.  The 
core issue is that the function ide_dma_timeout_retry sets the 
rq->buffer = NULL.  Later on, when this request is retried in PIO mode 
we hit a BUG() because of the NULL rq->buffer pointer.

I'm wondering exactly why rq->buffer = NULL?

I'm on 2 processor IA64 platform using the SGI IOC4 IDE driver. 

Details are as follows:

A request is created, bogus request = 0xe00000307a98cf18 .

The request is issued to the drive.  For some reason it's timer
fires waiting for DMA.

ide-io.c:1264: ide_timer_expiry is called because of the timeout

ide-io.c:1334 ide_dma_timeout_retry is called.

ide-io.c:1204: ide_dma_timeout_retry

This function puts the drive into PIO mode and turns off DMA.
The drive is un-busy'd.  Part of this procedure is to NULL out the
rq->buffer.

ide-io.c:1346: ide_do_request is called

ide-io.c;1055: ide_do_request

The request is re-issued with the drive in PIO mode and the busted 
rq->buffer = NULL request.

ide-io.c:1178: start_request is called.

ide-io.c:837: start_request

ide-io.c:920: (DRIVER(drive)->do_request(drive, rq, block)) is called.

This resolves to a call to ide-cd.c:2048:ide_do_rw_cdrom.

ide-cd.c;2048: ide_do_rw_cdrom

ide-cd.c:2071:cdrom_start_read is called

ide-cd.c:1411:cdrom_start_read

ide-cd.c:1421:restore_request is called

ide-cd.c:1393:restore_request

This function calculates rq->hard_cur_sectors, etc., based on the
values of rq->buffer.  The problem is that rq->buffer = NULL.
Obviously, all calculations in this function are bogus.

ide-cd.c:1441: cdrom_start_packet_command is issued with the bogus request,
and with cdrom_read_intr as the interrupt handler.

Sometime later, an interrupt occurs and ide-cd.c:1110:cdrom_read_intr
runs.

ide-cd.c:1110:cdrom_read_intr

ide-cd.c:1129:cdrom_decode_status is called

ide-cd.c:711:cdrom_decode_status

ide-cd.c:870:cdrom_queue_request_sense is called

ide-cd.c:573 cdrom_queue_request_sense

This function adds a new request (I will refer to this as the sense 
request) 0xe00000307be66960,
to the queue which simply will query the CDROM for sense.

The sense request stores the bogus request on line 592:
        rq->buffer = (void *) 0xe00000307a98cf18;

This function issues the command directly to the drive and preempts any 
existing commands.

Eventually a cdrom_pc_intr occurs which returns the sense request.

Another cdrom_pc_intr occurs in order to remove
the sense request, 0xe00000307be66960, from the queue.

ide-cd.c:1449:cdrom_pc_intr

ide-cd.c:1482: cdrom_end_request called

ide-cd.c:653:cdrom_end_request

((rq->flags & REQ_SENSE) && uptodate) = 1 and the value of failed is the 
bogus request.

ide-cd.c:678:ide_end_dequeued_request called

ide-io.c:206: ide_end_dequeued_request

This function has been called with the bogus request, and a negative 
value for nr_sectors.
As you climb through the code, the return in this function depends on 
the return value from
drivers/block/ll_rw_blk.c:2798:__end_that_request_first .

In this function, nr_bytes = nr_sectors << 9.  However, nr_bytes and 
nr_sectors are
negative numbers because of the bogus request value of 
rq->nr_hard_sectors being
munged earlier on.

This causes a return of 1 from __end_that_request_first.
...

We're totally out in the weeds here.  __end_that_request_first is coded 
correctly and
correctly returns 1 ("not done") all the way up to 
ide_end_dequeued_request ... and
then you hit

ide-cd.c:679:BUG()