[Burner]Sometimes, it failed to burn the image DVD after burning the data CD.

[kyt]

[Machine]
Dell Vostro 3900
  [Version]
1804 final 20180427.3 enhanced
  [Details]
[Burner]Sometimes, it failed to burn the image DVD after burning the data CD.
【麒麟刻录】[概率性]先刻录数据再刻录镜像，镜像无法刻录
  [Test Case]
1. Open Burner
2. Burn the data CD
3. burn the image DVD
Expected Result: Passed
Actual Result:Failed

[kyt (952456204-6)]

 kylin@kylin-Vostro-3900:~$ brasero

(brasero:1669): Gtk-WARNING **: 15:49:45.814: Theme parsing error: gtk-main.css:243:37: Failed to import: 打开文件 /usr/share/themes/ukui-theme/gtk-3.0/mate-applications.css 时出错：没有那个文件或目录

(brasero:1669): GLib-CRITICAL **: 15:49:47.164: g_key_file_load_from_file: assertion 'file != NULL' failed

** (brasero:1669): WARNING **: 15:49:47.165: Could not establish a connection to Tracker: Failed to load SPARQL backend: Key file does not have group “DomainOntology”
Gtk-Message: 15:49:49.509: GtkDialog mapped without a transient parent. This is discouraged.

(brasero:1669): Gtk-WARNING **: 15:49:51.598: Failed to measure available space: 不支持指定位置

(brasero:1669): Gtk-WARNING **: 15:49:51.598: Failed to measure available space: 不支持指定位置
Gtk-Message: 15:49:58.302: GtkDialog mapped without a transient parent. This is discouraged.

(brasero:1669): Gtk-WARNING **: 15:50:01.554: Failed to measure available space: 不支持指定位置

(brasero:1669): Gtk-WARNING **: 15:50:01.555: Failed to measure available space: 不支持指定位置

(brasero:1669): Gtk-WARNING **: 15:50:11.274: Failed to measure available space: 不支持指定位置

(brasero:1669): Gtk-WARNING **: 15:50:11.274: Failed to measure available space: 不支持指定位置

** (brasero:1669): WARNING **: 15:50:11.508: Error showing notification

(brasero:1669): Gtk-WARNING **: 15:50:12.976: Failed to measure available space: 不支持指定位置

(brasero:1669): Gtk-WARNING **: 15:50:12.977: Failed to measure available space: 不支持指定位置

[Thomas Schmitt (scdbackup)]

Hi,

it would be interesting to see english translations of the final statements
in burner-session.log:

BurnerLibburn mmc_set_streaming: end_lba=2297887 , r=11080000 , w=11080
BurnerLibburn Something went wrong
BurnerLibburn called burner_job_error
BurnerLibburn finished with an error
BurnerLibburn asked to stop because of an error
        error = 15
        message = "... not understandable for me ..."
BurnerLibburn stopping
Session error : ... not understandable ... burn_record burner-burn.c:2856)

Very suspicious is the line
  mmc_set_streaming: end_lba=2297887 , r=11080000 , w=11080

Write speed is set to 11080 KB/s = 8 x DVD speed.
But read speed is set to 1000 times more. Not realistic at all.
Possibly libburn got a protest reply from the drive when trying to set
this value.

So from where got Brasero the idea to set such a large value.
In
  https://github.com/GNOME/brasero/blob/master/plugins/libburnia/burn-libburn.c
line 559 i see:
        brasero_job_get_rate (BRASERO_JOB (self), &rate);
        burn_drive_set_speed (priv->ctx->drive, rate, 0);

This looks quite wrong, as the libburn calls sets write speed to 0
(which means "maximum speed") and read speed to a value which it obtained
from its own call brasero_job_get_rate().

I can follow that call through
  brasero_burn_session_get_rate
to
  brasero_medium_get_max_write_speed
where a comment says:
   * Note: the speed are in B/sec.
But libburn's burn_drive_set_speed expects KB/s.
So here is the origin of the factor 1000 which inflates 11080 to 11080000.

In summary we have two bugs here:
- Brasero sets read speed to what it believes to be the maximum write speed.
- The belief of Brasero is too high by a factor of 1000 due to an internal
  conversion problem.

Now i wonder why this does not show up more frequently in Brasero logs in
the web. I googled for "Brasero mmc_set_streaming" which yields lots of
problem reports but not with insane "r=" values in that message.

Have a nice day :)

Thomas

[Thomas Schmitt (scdbackup)]

Hi,

i did not notice that this bug report is about kylin-burner which
obviously stems from Brasero's source code, nevertheless.

The bug with operating libburn is present at
  https://github.com/ukui/kylin-burner/blob/master/plugins/libburnia/burn-libburn.c
line 559 like in the original Brasero source.
        burner_job_get_rate (BURNER_JOB (self), &rate);
        burn_drive_set_speed (priv->ctx->drive, rate, 0);

The other assessments stay valid too, with "s/brasero/burner/".

So i am still riddling why libburn reports such an insane setting made
by Burner only if a CD was burned before the DVD. Something must keep
both from falling victim to the wrong speed factor, at least if no
CD was seen previously.

The 16 commits of
  https://github.com/ukui/kylin-burner/commits/master
do not look like they could make a difference.

My finding with Brasero source code are that it first tries to inquire
maximim write speed by SCSI command GET PERFORMANCE and, if no valid reply,
by MODE SENSE of mode page 2Ah.
GET PERFORMANCE should succeed with a DVD burner and a DVD medium. Mode page
2Ah is an older info source for CDs.

My only explanation for the sane values in various Brasero logs in
the web is that speed inquiry failed and Brasero thus submitted 0 as
write speed. But why would it fail ? And why not after burning CD ?

(I am glad that i only have to use my own frontends to libburn. This
 makes riddling much more intimate.)

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

Whatever, a fix for the insane read speed setting could be to replace
"rate" by "0" in line 559 of plugins/libburnia/burn-libburn.c :

- burn_drive_set_speed (priv->ctx->drive, rate, 0);
+ burn_drive_set_speed (priv->ctx->drive, 0, 0);

(The previous line
         burner_job_get_rate (BURNER_JOB (self), &rate);
 is then obsolete.)

It would be interesting to see whether this would help with the Burner
failures describe in this bug report.

Have a nice day :)

Thomas

[Thomas Schmitt (scdbackup)]

Hi,

the speed setting issue should now be fixed by
  https://github.com/ukui/kylin-burner/issues/1
  https://github.com/ukui/kylin-burner/commit/dbcc784a27f500332c909de7269e7921927a5889

As said, it is not clear whether this was the reason for the burn failure
described here. But as soon as a new release of Burner is available it
would be worth a try.

Have a nice day :)

Thomas

[kyt (952456204-6)]

Hi Thomas，
We've tried it in the new version. It wasn't fixed yet.
The new log is attached.

[Thomas Schmitt (scdbackup)]

Hi,

hooray, a readable error message !

> BurnerLibburn SCSI error condition on command 2Ah WRITE(10): [3 73 03] Medium error. Power calibration area error.
> BurnerLibburn Libburn reported an error SCSI error on write(0,16): [3 73 03] Medium error. Power calibration area error.

The error code [3 73 03] stems from the drive. Kernel, libburn, and Burner are
only the messengers and thus are not to blame. Libburn picked the texts out
of a list which is defined in SCSI/MMC specs.

As the SCSI error key 3 and the text "Medium error" says:
The drive does not like the medium.

ASC,ASCQ codes 73,03 and their translation "Power calibration area error"
mean that the drive could not determine a suitable laser beam strength
before it was up to writing the payload data.

The text "write(0,16)" means that the designated write address of the failed
SCSI WRITE command was block 0, and the payload size was 16 blocks (=32 KiB).
This early failure matches the reason that is reported by the drive.

Let's look at the log info about the medium:

> BurnerLibburn dvd/bd Profile= 11h , obs= 32768 , obs_pad= 1

Profile 11h indicates a DVD-R medium.

> BurnerLibburn mmc_set_streaming: end_lba=2298495 , r=33240 , w=22160

libburn decided (after inquiring the drive) that maximum read speed is
24x and maximum write speed is 16x DVD speed. This is plausible for DVD-R,
except the fact that the drive will reach these speeds only at the
outer rim of the medium.

Depending on the drive's firmware it might be worth a try to set a lower
write speed. As it looks in the libburn plugin, there is no provision for
user chosen speed.
A hacker's experiment would be to change plugins/libburnia/burn-libburn.c
line 560 to hardcode a speed of e.g. 8x DVD = 8 * 1385 kB/s = 11080 kB/s.

        burn_drive_set_speed (priv->ctx->drive, 0, 11080);

But in the original log, this speed was already in effect.

At least my drives do not offer less than 8x for the DVD-R media i have:

  $ xorriso -outdev /dev/sr4 -toc -list_speeds
  ...
  Drive type : vendor 'ASUS' product 'BW-16D1HT' revision '1.01'
  ...
  Media current: DVD-R sequential recording
  Media product: RITEKF1 , Ritek Corp
  Media status : is blank
  ...
  Write speed : 22160k , 16.0xD
  Write speed : 16620k , 12.0xD
  Write speed : 11080k , 8.0xD
  ...

Any lower setting will probably lead to a burn attempt with speed 8x.

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

There remains the riddle why you perceive it only after a CD was burnt.

Normally i'd say this is pure statistical incident. But i have a BD burner
(Optiarc BD-5300S) which reproducibly goes mad if i only insert a CD and
eject it immediately.
Afterwards it de-formats any BD-RE medium until i give it a power-off-on
cycle.

We could investigate the SCSI transaction dialog between drive and libburn
by an early call of
  burn_set_scsi_logging(1 | 4); /* Log to /tmp/libburn_sg_command_log and
                                   flush after each line. */
or
  burn_set_scsi_logging(2); /* Log to stderr */

It might be interesting to compare the log of a failed run with the
corresponding part of a log of a successful burn run. Maybe th...

[Thomas Schmitt (scdbackup)]

Hi,

comparing the first log
  https://launchpadlibrarian.net/368232127/burner-session.log
and the second one
  https://launchpadlibrarian.net/368793315/burner-session.log
it becomes obvious that the second run got several steps nearer to a
successful burn run.

After the last libburn debug message of the first log

  mmc_set_streaming: end_lba=2297887 , r=11080000 , w=11080

which stems from burn run preparations, one can see in the second log
the following debug messages from libburn

  Allocating buffer via mmap()
  Profile= 11h , obs= 32768 , obs_pad= 1
  DVD pre-track 01 : get_nwa(0), ret= 1 , d->nwa= 0

These three messages stem from the writer thread that gets created by the
call burn_disc_write(). I.e. they got emitted after all preparations had
succeeded without protest from libburn.

So most probably the reasons of failure in both runs are not the same.

Have a nice day :)

Thomas