Re: [Bug-xorriso] building libisofs-1.4.4, libburn-1.4.4, libisoburn-1.4.4 on OpenBSD

[Thomas Schmitt]

Hi,

SASANO Takayoshi wrote:
> Now I am testing manual_burn script of xorriso-1.4.5 with OpenBSD-5.9/amd64,
> sometimes hang-ups the system with pciide driver.

Ouch.

> When I use AHCI driver, system did not hang-up but drive not ready error
> occurs like this.
> libburn : FAILURE : Asynchronous SCSI error : See MMC specs: Sense Key 2 
> "Drive not ready", ASC 00 ASCQ 00.

The command -scsi_log "on" shows on stderr the SCSI commands as they are
sent to the operating systems and the replies which libburn gets from
the operating system. That's quite verbous, of course.

Give -scsi_log early, so that logging starts early. I now tested:

  xorriso -scsi_log on -for_backup \
          -outdev /dev/sr0 -blank as_needed \
          -map /usr/bin/vim.tiny /test \
     2>&1 | tee -i /tmp/xorriso.log

(/usr/bin/vim.tiny is 1 MB of size. Short enough to be done quickly.)

-----------------------------------------------------------------------

Here is how a successful blank run should look like.

After some drive and media inspection, the BLANK command with "Immed" bit
and "Minimally Blank" bit gets sent. It ends quickly while the drive
begins to do the lengthy work.

  BLANK
  a1 11 00 00 00 00 00 00 00 00 00 00 
       3147 us     [ 7252567 ]

"3147 us" is the time in microseconds between comand sent and reply
delivered by kernel.
"[ 7252567 ]" is the timestamp in microseconds since start of libburn.

Next, the drive gets asked whether the BLANK command is already done:

  TEST UNIT READY
  00 00 00 00 00 00 
  +++ sense data = 71 00 02 00 00 00 00 0A 00 00 00 00 04 07 00 80 00 00
  +++ key=2  asc=04h  ascq=07h
       6191 us     [ 7258860 ]

The Sense code stems from the drive. MMC specs list it as

  2 =     DRIVE NOT READY
  04,07 = LOGICAL UNIT NOT READY, OPERATION IN PROGRESS

This reply is expected and causes libburn to inquire the progress counter

  REQUEST SENSE
  03 00 00 00 12 00 
  From drive: 18b
  70 00 02 00 00 00 00 0a 00 00 00 00 04 07 00 80 00 00 
        390 us     [ 7259410 ]

then to wait a short while and to repeat the inquiry

  TEST UNIT READY
  00 00 00 00 00 00 
  +++ sense data = 71 00 02 00 00 00 00 0A 00 00 00 00 04 07 00 80 00 00
  +++ key=2  asc=04h  ascq=07h
       7204 us     [ 8266831 ]

At some point of time, the drive reports to be ready again:

  TEST UNIT READY
  00 00 00 00 00 00 
        547 us     [ 36596601 ]

In this case blanking at 10x speed lasted 29344034 microseconds.
(Some drives would need a bit more time.)

In my test run, the drive now gets inspected again and reports the
new medium state. A CUE SHEET gets sent to tell the drive the track layout.
Then WRITE commands get sent. Finally a TEST UNIT READY loop waits for
the drive to report to have finished.
Another drive and medium inspection happens before the program ends.

-----------------------------------------------------------------------

Your kernel reports that the drive reports 2,0,0

  2 =     DRIVE NOT READY
  0,0 =   NO ADDITIONAL SENSE INFORMATION

The blanking loop in libburn is not happy with that.
It is in libburn/drive.c , burn_disc_erase_sync(), which first waits for
the first progress indication to arrive or the drive to become ready:

#else /* Libburn_old_progress_looP */

        while (1) {
                ret = d->get_erase_progress(d);
                if (ret == -2 || ret > 0)
        break;
                ...
        }

Your run probably gets ret == -3 in this loop.

d->get_erase_progress() is actually  libburn/spc.c, spc_get_erase_progress():

/* @return -3 = other error reported
           -2 = drive is ready ,
           -1 = not ready, but no progress reported ,
           >= 0 progress indication between 0 and 65535
*/

Then another loop waits for the drive to become ready.

        while (1) {
                ret = d->get_erase_progress(d);
                if(ret == -2)
        break;
                if (ret == -3)
                        was_error = 1;
                if (ret >= 0)
                        d->progress.sector = ret;
                sleep(1);
        }

I am now pondering whether it is a bug that the second loop does not
break on -3 ...
The second loop shall end when a BLANK command without Immed bit would
have ended.
... but at some point the drive should become ready again. Error or not.

Whatever, the first loop must be rugged and stand a few error complaints
until the drive says "ready" or "in progress". It seems that this is the
loop which reports the errors in your test.


Key = 2 , ASC = 0, and ASCQ = 0 does not really look like a genuine reply
from an optical drive. Rather like a synthetic one from a driver.
Can it be that OpenBSD produces such a Sense Code to tell the caller of
the ioctl that it does not dare to send a command to the drive ?

Did you wait for at least 12 minutes divided by CD-RW speed before
aborting? (E.g. 3 minutes at with a 4x CD-RW ?)
Did aborting work ?

-----------------------------------------------------------------------

Have a nice day :)

Thomas