k3b dvd burning crashes with growisofs and -use-the-force-luke=dao: option

Hi,

did you wait the time necessary to write a full gigabyte
when -use-the-force-luke=dao was in effect ?

Why i ask:

-use-the-force-luke=dao:96525 tells growisofs to use
write type DAO rather than Incremental. Further it predicts
the track size as 96525 blocks of 2048 bytes.

The number has to match exactly the size of the input ISO image.
I.e. show-musikprojekt.iso must have 197,683,200 bytes.
Since you did not have to remove option
-use-the-force-luke=tracksize:96525, i assume that ISO size
and number do match.

You already noticed a difference between DAO and Incremental
at the start of a burn session. DAO knows the size of the track
in advance and thus writes the table-of-content first.
Incremental does not know how many blocks will be written and
thus writes the table-of-content after the track was written.

Another difference is that DAO results in a medium state that
complies with the DVD-ROM standard ECMA-267. Its section 10.6
demands that the medium gets burned a ring of at least 70
millimeters. This is the width of a session of about 1 GB.

So any DAO session lasts at least as long as a 1 GB session.

If your drive does not end a DAO session after a due waiting time,
then it is probably at the edge of failure. In this case you
should be mistrusting towards its allegedly successful runs.
Do checkread.

Have a nice day :)

Thomas

Hi,

thanks for your detailed answer. And yes, you're right, I should wait
until the burning process has finished ;-)

Here are the last few lines output:

197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
   197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
   197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
   197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
   197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
:-[ WRITE@LBA=17900h failed with SK=0h/ASC=00h/ACQ=03h]: Input/output error
:-( write failed: Input/output error
/dev/sr0: flushing cache

What do you think, is this a drive issue like you mentioned before or
something else? I found some bug reports with similar errors.

btw, I found a dvd+r double layer disc in my working desk and tried this
one. Besides dummy write has not worked and I've wasted a double layer
disc for about 200 MByte of data, everything went fine.

The not working disc is a dvd-r type.

Thanks,

Jan.

Am 14.08.2014 um 08:58 schrieb Thomas Schmitt:
> Hi,
>
> did you wait the time necessary to write a full gigabyte
> when -use-the-force-luke=dao was in effect ?
>
> Why i ask:
>
> -use-the-force-luke=dao:96525 tells growisofs to use
> write type DAO rather than Incremental. Further it predicts
> the track size as 96525 blocks of 2048 bytes.
>
> The number has to match exactly the size of the input ISO image.
> I.e. show-musikprojekt.iso must have 197,683,200 bytes.
> Since you did not have to remove option
> -use-the-force-luke=tracksize:96525, i assume that ISO size
> and number do match.
>
> You already noticed a difference between DAO and Incremental
> at the start of a burn session. DAO knows the size of the track
> in advance and thus writes the table-of-content first.
> Incremental does not know how many blocks will be written and
> thus writes the table-of-content after the track was written.
>
> Another difference is that DAO results in a medium state that
> complies with the DVD-ROM standard ECMA-267. Its section 10.6
> demands that the medium gets burned a ring of at least 70
> millimeters. This is the width of a session of about 1 GB.
>
> So any DAO session lasts at least as long as a 1 GB session.
>
> If your drive does not end a DAO session after a due waiting time,
> then it is probably at the edge of failure. In this case you
> should be mistrusting towards its allegedly successful runs.
> Do checkread.
>
>
> Have a nice day :)
>
> Thomas
>

Hi,

> I should wait until the burning process has finished ;-)

It did not help, though. :(

> :-[ WRITE@LBA=17900h failed with SK=0h/ASC=00h/ACQ=03h]: Input/output error

Now this is a strange SCSI error code.
SK=0h/ASC=00h means that nothing can be reported.
But ACQ=03h means that there is something special with
that nothing.
0,0,3 does not appear in the list of official SCSI errors.

> What do you think, is this a drive issue like you mentioned before or
> something else?

The suspected reason for long waiting plus something else,
i guess.

The complained write address 17900h is in decimal notation
96512. That's 13 blocks less than the reserved size of 96525.
A DVD write command of growisofs sends up to 16 blocks.
So this was the last WRITE command of the burn run.

The drive thus noticed that all payload has been transmitted
and began to fill up the DVD to the 70 millimeter limit.
In the course of this operation, something bad happened to
medium, drive, bus, or kernel.
growisofs pervceived a error indication and got above error
code from the kernel.

The error code may well be fabricated by kernel or bus
controller in order to indicate some error that did not
happen in the drive. Check your system log for messages
related to "sr0".

Timeouts should rather be reported with "SK=Bh".
Nevertheless it might be that some participant in the
communications chain lost patience and aborted the WRITE
command.

If so, then the drive might even have finished the burn.
After that last WRITE command, there would be nothing more
to do.

To get more insight you could do:

- Write a larger ISO image so that the last WRITE command
  lasts less long. About 800 MB would be a good size.
  E.g. just a stream of zeros:
    dd if=/dev/zero bs=2048 count=400000 | growisofs ...

- Write the small image to DVD-R or unformatted DVD-RW
  without -use-the-force=dummy , wait until the error is
  reported, watch the drive LED to stop giving signs of work,
  eject the medium, load it again and check whether the
  content is readable.
  E.g. by
    dd if=/dev/sr0 bs=2048 count=96525 | \
    diff - medien/filme/DVD-ABBILDER/show-musikprojekt.iso

> I found a dvd+r double layer disc in my working desk and tried this
> one. Besides dummy write has not worked and I've wasted a double layer
> disc for about 200 MByte of data, everything went fine.

DVD+R and DVD+R DL are not capable of dummy writing.
It's not very provident of growisofs to start the burn run
in this case. Especially if closing the medium is requested
by -dvd-compat or -use-the-force-luke=dao.

> The not working disc is a dvd-r type.

I presumed this from your description of the differences at
burn start between dao and not dao. It's typical for DVD-R
and unformatted DVD-RW.

Have a nice day :)

Thomas

Hi,

ok, I followed your instructions. First I wrote the larger image with

  dd if=/dev/zero bs=2048 count=400000 | /usr/bin/growisofs -Z
/dev/sr0=/dev/fd/0 -use-the-force-luke=notray -use-the-force-luke=tty
-use-the-force-luke=4gms -use-the-force-luke=tracksize:400000
-use-the-force-luke=dummy -use-the-force-luke=dao:400000 -dvd-compat
-speed=8 -use-the-force-luke=bufsize:32m

and, hu, everything went fine :-), no kernel messages.

Then I wrote the smaller image without the dummy-option:

cat medien/filme/DVD-ABBILDER/show-musikprojekt.iso | /usr/bin/growisofs
-Z /dev/sr0=/dev/fd/0 -use-the-force-luke=notray -use-the-force-luke=tty
-use-the-force-luke=4gms -use-the-force-luke=tracksize:96525
-use-the-force-luke=dao:96525 -dvd-compat -speed=8
-use-the-force-luke=bufsize:32mExecuting 'builtin_dd if=/dev/fd/0
of=/dev/sr0 obs=32k seek=0'

last lines of growisofs again:

197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
   197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
   197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
   197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
   197656576/197683200 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%
:-[ WRITE@LBA=17900h failed with SK=0h/ASC=00h/ACQ=03h]: Input/output error
:-( write failed: Input/output error
/dev/sr0: flushing cache

As you can see, I didn't have to wait until the drive has stopped
working because growisofs finished itself...

When growisofs told me of that error the kernel bailed out:

Aug 15 12:53:54 t500 kernel: [23704.924138] ata2.00: exception Emask 0x0
SAct 0x0 SErr 0x0 action 0x6 frozen
Aug 15 12:53:54 t500 kernel: [23704.924149] sr 1:0:0:0: [sr0] CDB:
Aug 15 12:53:54 t500 kernel: [23704.924152] Write(10): 2a 00 00 01 79 00
00 00 0d 00
Aug 15 12:53:54 t500 kernel: [23704.924165] ata2.00: cmd
a0/01:00:00:00:80/00:00:00:00:00/a0 tag 10 dma 32768 out
Aug 15 12:53:54 t500 kernel: [23704.924165] res
40/00:03:00:00:80/00:00:00:00:00/a0 Emask 0x4 (timeout)
Aug 15 12:53:54 t500 kernel: [23704.924169] ata2.00: status: { DRDY }
Aug 15 12:53:54 t500 kernel: [23704.924174] ata2: hard resetting link
Aug 15 12:53:55 t500 kernel: [23705.244130] ata2: SATA link up 1.5 Gbps
(SStatus 113 SControl 300)
Aug 15 12:53:55 t500 kernel: [23705.249443] ata2.00: ACPI cmd
e3/00:1f:00:00:00:a0 (IDLE) succeeded
Aug 15 12:53:55 t500 kernel: [23705.250313] ata2.00: ACPI cmd
e3/00:02:00:00:00:a0 (IDLE) succeeded
Aug 15 12:53:55 t500 kernel: [23705.260834] ata2.00: ACPI cmd
e3/00:1f:00:00:00:a0 (IDLE) succeeded
Aug 15 12:53:55 t500 kernel: [23705.261646] ata2.00: ACPI cmd
e3/00:02:00:00:00:a0 (IDLE) succeeded
Aug 15 12:53:55 t500 kernel: [23705.265583] ata2.00: configured for UDMA/133
Aug 15 12:53:55 t500 kernel: [23705.284079] ata2: EH complete

At last I compared the disc with the image, they seem to be identical:

dd if=/dev/sr0 bs=2048 count=96525 |diff -
medien/filme/DVD-ABBILDER/show-musikprojekt.iso
96525+0 Datensätze ein
96525+0 Datensätze aus
197683200 Bytes (198 MB) kopiert, 40,6439 s, 4,9 MB/s

btw., with bigger images the error occurs again, but this is what you
ex...

Hi,

> First I wrote the larger image [...] and, hu, everything went fine :-)

Less idle time with the last WRITE command.

> Then I wrote the smaller image without the dummy-option:
> ...
> As you can see, I didn't have to wait until the drive has stopped
> working because growisofs finished itself...

I expected the drive to work on for a while, after the kernel
brutally ended the SCSI transaction of the last WRITE command.
At that time, the burner has every information it needs to finish
the burn job. But it might last a few minutes until its really done.

> :-[ WRITE@LBA=17900h failed with SK=0h/ASC=00h/ACQ=03h]: Input/output error
> ...
> Aug 15 12:53:54 t500 kernel: [23704.924138] ata2.00: exception Emask 0x0
> SAct 0x0 SErr 0x0 action 0x6 frozen
> Aug 15 12:53:54 t500 kernel: [23704.924149] sr 1:0:0:0: [sr0] CDB:
> Aug 15 12:53:54 t500 kernel: [23704.924152] Write(10): 2a 00 00 01 79 00
> 00 00 0d 00

So here we have the last WRITE command for block 0x17900.

> Aug 15 12:53:54 t500 kernel: [23704.924174] ata2: hard resetting link

This might have caused the burner to end prematurely.
Not sure, though.

> At last I compared the disc with the image, they seem to be identical:

It might of course be, that the kernel gets aware only when the
burner wants to deliver the status of the final WRITE.

Or it might be that the burned area ends less than 70 millimeters
away from the center of the DVD's hole. Please measure. :))

Whatever, the final error happens late enough so that the payload
data are already written to the medium, and that the medium does
not stay in an intermediate unusable state.

> btw., with bigger images the error occurs again, but this is what you
> expected, isn't it?

Not at all.
There is hardly a reason for a long execution time with the last
WRITE command, after the 70 millimeter limit was surpassed.

How long did the burner chew on the medium with 100% messages ?
  4251353088/4251365376 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%

> Aug 15 14:17:53 t500 kernel: [28743.900148] Write(10): 2a 00 00 1f ac d0
> 00 00 06 00

The failing WRITE is indeed the last one: 0x1facd0 = 2075856 decimal
with announced image size of 2075862.

If the execution time of this WRITE really justifies a timeout,
then your burner has a problem with DVD-R. This might be with
DVD-R in general, or just with the individual DVD-R which you
tired.

Have a nice day :)

Thomas

Hi,

> Or it might be that the burned area ends less than 70 millimeters
> away from the center of the DVD's hole. Please measure. :))

You mean 7 millimeters? The burned area is exactly 7 mm, or ends -
measured from the center at 29,5 mm.

> How long did the burner chew on the medium with 100% messages ?
> 4251353088/4251365376 (100.0%) @0.0x, remaining 0:00 RBU 0.1% UBU 100.0%

19 lines in the log. I haven't taken the exact time.

> If the execution time of this WRITE really justifies a timeout,
> then your burner has a problem with DVD-R. This might be with
> DVD-R in general, or just with the individual DVD-R which you
> tired.

This is, what I was thinking from time to time. Now I tested the smaller
image with a external drive, with success. But there is one difference
as you can see at the end of the log:

    38928384/197683200 (19.7%) @7.2x, remaining 1:29 RBU 100.0% UBU 100.0%
    72810496/197683200 (36.8%) @7.3x, remaining 0:42 RBU 100.0% UBU 100.0%
   107249664/197683200 (54.3%) @7.5x, remaining 0:24 RBU 100.0% UBU 94.1%
   142245888/197683200 (72.0%) @7.6x, remaining 0:12 RBU 100.0% UBU 100.0%
   177799168/197683200 (89.9%) @7.7x, remaining 0:03 RBU 59.3% UBU 100.0%
builtin_dd: 96528*2KB out @ average 3.9x1352KBps
/dev/sr1: flushing cache

The drive finishes immediately after the data stream has ended and
doesn't fill any disc space which is, as far as I understood, against
the specs. One can see it too on the burned disc: The written area is
smaller (about 5 mm, or 27,5 from the center).

At last I tried a different blank disc (with different manufacturer id),
but the results have kept the same. Maybe the internal drive simply
doesn't like dvd-r discs.

Now I am a little bit lost and thinking about giving up with this topic:
I have one drive, which fails to write, and another which writes the
image without errors but not like the specifications want it to be.

I can take dvd+ discs for my internal drive, which worked, or choose
cdrecord at the k3b advanced settings, which worked as well for me (btw,
cdrecord does something similar as growisofs at the end of burning and
fills up the disc. But the overall written area is much bigger - about
12 mm.)

If you want, you can close the bug report.

Thanks a lot for your help.
Have a nice day, jan.

Hi,

> You mean 7 millimeters? The burned area is exactly 7 mm, or ends -
> measured from the center at 29,5 mm.

Urm ... reading again ECMA-167 ...
10.6.1 Sub-divisions of the Information Zone,
Table 1 - End of the Information Zone.
It may vary 70.0 to 117.0 mm.

It talks of diameteri "d 10", though, not of radius.
My fault. 35 mm, then.

Measuring a blank DVD-R with a 1970s Geodreieck ...
29.5 mm is very narrow. Are you sure this DVD was written with
-use-the-force-luke=dao:... ?

> 19 lines in the log. I haven't taken the exact time.

growisofs.c:progress_print() sleeps by poll(2) with timeout 3333.
That's milliseconds. I.e. the last WRITE lasted roughly 60 seconds.

I believe to see in growisofs_mmc.cpp:poor_mans_pwrite64() that
the timeout for DAO should be 180 seconds. The default timeout is
60 seconds.

Well, i am not the author of growisofs, but rather a competitor.
Maybe i misinterpret its timeout settings.

> Now I tested the smaller image with a external drive, with success.
> The drive finishes immediately after the data stream has ended and
> doesn't fill any disc space which is, as far as I understood, against
> the specs. One can see it too on the burned disc: The written area is
> smaller (about 5 mm, or 27,5 from the center)

If this was really a DAO run, then the drive decided to not obey
the specs.
A burn program is supposed to announce the number of payload blocks
and not the minimum disc size. It's up to the drive to write a
compliant track to the medium.

> Maybe the internal drive simply doesn't like dvd-r discs.

At least there seems to be a mismatch of timeout and drive behavior.
One could do experiments in the growisofs source code to enlarge
the timeouts.

> Now I am a little bit lost and thinking about giving up with this topic:
> I have one drive, which fails to write, and another which writes the
> image without errors but not like the specifications want it to be.

The minimum size should be no problem with any computer DVD drive.
Only the brain damaged entertainment video DVD drives are said
to depend on this part of ECMA-267.

After all, the other write type Incremental is the default for
growisofs and my own program xorriso. It does not impose a minimum
size.

> cdrecord at the k3b advanced settings, which worked as well for me

Might be that it has set a longer timeout and that growisofs for
some reason failed to recognize the need for that.

Selfish question: How do xorriso or cdrskin perform ?

  xorriso -as cdrecord -v -dao dev=/dev/sr0 speed=8 fs=32m medien/filme/DVD-ABBILDER/show-musikprojekt.iso

resp.

  cdrskin -v -dao dev=/dev/sr0 speed=8 fs=32m medien/filme/DVD-ABBILDER/show-musikprojekt.iso

> If you want, you can close the bug report.

I hold no admin rank at Ubuntu or Launchpad.

Actually it might well be a bug in growisofs by setting the wrong
SG_IO timeout for the write type.

But growisofs upstream is not maintained any more. So there is few
use in diagnosing the problem, unless you want to run a fixed
growisofs on your machine(s). In that case, i could make proposals.

Have a nice day :)

Thomas

Correction: It's ECMA-267 not ECMA-167.

Hi,

> But growisofs upstream is not maintained any more. So there is few
> use in diagnosing the problem, unless you want to run a fixed
> growisofs on your machine(s). In that case, i could make proposals.

thanks again for your diagnose :-) At least I am going to know what to
deal with now and stay with a probably unfixed growisofs..

> Measuring a blank DVD-R with a 1970s Geodreieck ...
> 29.5 mm is very narrow. Are you sure this DVD was written with
> -use-the-force-luke=dao:... ?

I'm really sure I did..

> Selfish question: How do xorriso or cdrskin perform ?
>
> xorriso -as cdrecord -v -dao dev=/dev/sr0 speed=8 fs=32m medien/filme
> /DVD-ABBILDER/show-musikprojekt.iso
>
> resp.
>
> cdrskin -v -dao dev=/dev/sr0 speed=8 fs=32m medien/filme/DVD-ABBILDER
> /show-musikprojekt.iso

mj@t500:~$ xorriso -as cdrecord -v -dao dev=/dev/sr0 speed=8 fs=32m
medien/filme/DVD-ABBILDER/show-musikprojekt.iso
xorriso 1.3.2 : RockRidge filesystem manipulator, libburnia project.

Drive current: -outdev '/dev/sr0'
Media current: DVD-R sequential recording
Media status : is blank
Media summary: 0 sessions, 0 data blocks, 0 data, 4489m free
Beginning to write data track.
xorriso : UPDATE : 0 of 188 MB written (fifo 99%) [buf 0%]
xorriso : UPDATE : 0 of 188 MB written (fifo 99%) [buf 0%] 0.0x.
xorriso : UPDATE : 0 of 188 MB written (fifo 99%) [buf 0%] 0.0x.
xorriso : UPDATE : 0 of 188 MB written (fifo 99%) [buf 0%] 0.0x.
...
xorriso : UPDATE : 188 of 188 MB written (fifo 0%) [buf 100%] 0.0x.
xorriso : UPDATE : 188 of 188 MB written (fifo 0%) [buf 100%] 0.0x.
xorriso : UPDATE : 188 of 188 MB written (fifo 0%) [buf 100%] 0.0x.
Writing to '/dev/sr0' completed successfully.

xorriso : NOTE : Re-assessing -outdev '/dev/sr0'
xorriso : NOTE : Disc status unsuitable for writing
Drive current: -outdev '/dev/sr0'
Media current: DVD-ROM
Media status : is written , is closed
Media summary: 1 session, 96675 data blocks, 189m data, 0 free

mj@t500:~$ cdrskin -v -dao dev=/dev/sr0 speed=8 fs=32m
medien/filme/DVD-ABBILDER/show-musikprojekt.iso
cdrskin 1.3.4 : limited cdrecord compatibility wrapper for libburn
cdrskin: verbosity level : 1
cdrskin: NOTE : greying out all drives besides given dev='/dev/sr0'
cdrskin: scanning for devices ...
cdrskin: ... scanning for devices done
cdrskin: beginning to burn disc
cdrskin: status 1 burn_disc_blank "The drive holds a blank disc"
Current: DVD-R sequential recording
Track 01: data 188 MB
Total size: 188 MB (21:29.00) = 96525 sectors
Lout start: 188 MB (21:31/00) = 96675 sectors
Starting to write CD/DVD at speed 8 in real SAO mode for single session.
Last chance to quit, starting real write in 0 seconds. Operation starts.
Waiting for reader process to fill input buffer ... input buffer ready.
Starting new track at sector: 0
Track 01: 188 of 188 MB written (fifo 100%) [buf 100%] 1.5x.
cdrskin: thank you for being patient for 245 seconds
Track 01: Total bytes read/written: 197683200/197683200 (96525 sectors).
Writing time: 246.104s
Cdrskin: fifo had 96525 puts and 96525 gets.
Cdrskin: fifo was 0 times empty and 6597 times full, min fill was 99%.
Min drive buf...

Hi,

> With both programs [xorriso and cdrskin] the written area measured
> from the center of disc is about 35 mm :-)

Hrmpf. Obviously i do not understand the source code of
growisofs enough to explain the difference. If it
actually decides to do DAO, then i am sure it will yield
the same result as libburn based programs.

But obviously it finds a way to do it differently and to
then run into trouble. Because this is not a widespread
complaint, it seems that your DVD burner gives some reply
which confuses growisofs.

Have a nice day :)

Thomas

Status changed to 'Confirmed' because the bug affects multiple users.

Hi,

this might be the same growisofs bug as
  https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=794868
where a remedy patch was tested by a user but not yet applied to the
Debian package of dvd+rw-tools.

-------------------------------------------------------------------
Remedy for the wrong last WRITE transaction:
-------------------------------------------------------------------
--- growisofs_mmc-7.1-11.cpp 2015-08-07 13:07:52.000000000 +0200
+++ growisofs_mmc.cpp 2015-08-07 14:06:31.375597960 +0200
@@ -540,7 +540,7 @@ ssize_t poor_mans_pwrite64 (int fd,const
        // own higher HZ value and disrespects the user-land one.
        // Sending them down as milliseconds is just safer...
        //
- if (!(errcode=cmd.transport (WRITE,(void *)buff,size)))
+ if (!(errcode=cmd.transport (WRITE,(void *)buff,nbl*2048)))
            break;

        //--- WRITE failed ---//

----------------------------------------------------------------
Remedy for the wrong error code display:
----------------------------------------------------------------
--- transport-7.1-11.hxx 2015-08-07 13:07:52.000000000 +0200
+++ transport.hxx 2015-08-07 13:43:02.759592641 +0200
@@ -70,7 +70,12 @@ inline long getmsecs()
 #ifndef FATAL_START
 #define FATAL_START(er) (0x80|(er))
 #endif
-#define ERRCODE(s) ((((s)[2]&0x0F)<<16)|((s)[12]<<8)|((s)[13]))
+#define ERRCODE_FIXED(s) ((((s)[2]&0x0F)<<16)|((s)[12]<<8)|((s)[13]))
+#define ERRCODE_DESCR(s) ((((s)[1]&0x0F)<<16)|((s)[2]<<8)|((s)[3]))
+#define ERRCODE(s) ((s)[0] == 0x70 || (s)[0] == 0x71 ? \
+ ERRCODE_FIXED(s) : \
+ ((s)[0] == 0x72 || (s)[0] == 0x73 ? \
+ ERRCODE_DESCR(s) : 0))
 #define SK(errcode) (((errcode)>>16)&0xF)
 #define ASC(errcode) (((errcode)>>8)&0xFF)
----------------------------------------------------------------

Have a nice day :)

Thomas