Bug 606237 - Finalizing of burnt CD-Rs takes a very long time or gets stuck
Finalizing of burnt CD-Rs takes a very long time or gets stuck
Status: CLOSED NOTABUG
Product: Fedora
Classification: Fedora
Component: cdrkit (Show other bugs)
13
All Linux
low Severity high
: ---
: ---
Assigned To: Roman Rakus
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2010-06-21 03:50 EDT by James
Modified: 2014-01-12 19:12 EST (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2010-07-06 08:36:28 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description James 2010-06-21 03:50:37 EDT
Description of problem:
Burning an ordinary data CD project (using either GNOME CD Creator or K3B) proceeds in a straightforward manner, until the finalizing stage. Then, the drive will repeatedly grunt, spin down and spin up again. Sometimes this process halts and the burn process completes. Other times, when using K3B and wodim, the latter gets stuck in uninterruptible sleep and the system must be forcibly rebooted. Nevertheless, the burnt CD is usable.

                       Drive: /dev/scd0
Vendor                      : TSSTcorp
Model                       : CDDVDW SN-S082H 
Revision                    : SB00


Version-Release number of selected component (if applicable):
kernel-2.6.33.5-124.fc13.x86_64
wodim-1.1.10-1.fc13.x86_64
genisoimage-1.1.10-1.fc13.x86_64

How reproducible:
Always.

Steps to Reproduce:
1. Burn a disc.
  
Actual results:
Lots of grunting/never finished finalizing.

Expected results:
Finalizing finishes without fuss.
Comment 1 Roman Rakus 2010-06-23 10:17:15 EDT
Do you see something in /var/log/messages?
Comment 2 James 2010-06-23 12:29:17 EDT
(In reply to comment #1)
> Do you see something in /var/log/messages?    

Nothing unusual (i.e., apart from the standard "This disc doesn't have any tracks I recognize!") from either the kernel or any tools.
Comment 3 James 2010-07-04 17:13:48 EDT
Happened again after I burned an audio CD. The drive cycled and grunted fifteen times before I killed all instances of udevd. It was still locked. Then I noticed:

 1372 ?        D      0:10 hald-addon-storage: no polling because /dev/sr0 is locked via O_EXCL

killed that, and the system recovered.
Comment 4 James 2010-07-04 17:16:28 EDT
Following was in dmesg:

INFO: task hald-addon-stor:1372 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
hald-addon-st D ffff880037579528     0  1372   1329 0x00000080
 ffff88006aa4bbd8 0000000000000086 000000000000001b 0000000000000010
 ffff88006aa4bb58 ffff88007bde8a20 ffff88006aa4bb58 ffff88006aa4a000
 000000000000f970 0000000000014b80 ffff88006aaf2b48 00000000811c876c
Call Trace:
 [<ffffffff81204195>] ? kobject_get+0x1a/0x22
 [<ffffffff8142e93d>] __mutex_lock_common+0x17f/0x25e
 [<ffffffff811f7b7b>] ? exact_match+0x0/0xa
 [<ffffffff8142ea30>] __mutex_lock_slowpath+0x14/0x16
 [<ffffffff8142eb28>] mutex_lock+0x2c/0x46
 [<ffffffff811f80e1>] ? get_gendisk+0x2b/0xb8
 [<ffffffff81127cc0>] __blkdev_get+0x89/0x391
 [<ffffffff81127fd5>] ? blkdev_open+0x0/0xa7
 [<ffffffff81127fd3>] blkdev_get+0xb/0xd
 [<ffffffff81128046>] blkdev_open+0x71/0xa7
 [<ffffffff81100594>] __dentry_open+0x208/0x33f
 [<ffffffff811c3bd1>] ? security_inode_permission+0x1c/0x1e
 [<ffffffff81100790>] nameidata_to_filp+0x3a/0x4b
 [<ffffffff8110d6f4>] do_filp_open+0x571/0xaea
 [<ffffffff8120bb6d>] ? __strncpy_from_user+0x29/0x53
 [<ffffffff8142fbb6>] ? _raw_spin_unlock+0x26/0x31
 [<ffffffff811002a3>] do_sys_open+0x5e/0x10a
 [<ffffffff81100378>] sys_open+0x1b/0x1d
 [<ffffffff81009c02>] system_call_fastpath+0x16/0x1b
INFO: task udisks-daemon:1918 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
udisks-daemon D 00000000ffffffff     0  1918   1905 0x00000080
 ffff88005f961798 0000000000000082 ffff88005f961760 ffff88005f96175c
 ffff88005f961728 0000000000000000 0000000000000400 ffff88005f960000
 000000000000f970 0000000000014b80 ffff88006333cb08 0000000101e2082a
Call Trace:
 [<ffffffff8142e438>] schedule_timeout+0x31/0xde
 [<ffffffff81203efc>] ? kobject_put+0x47/0x4b
 [<ffffffff8142f971>] ? _raw_spin_lock_irq+0x1d/0x3c
 [<ffffffff812cbf30>] ? scsi_request_fn+0x403/0x4c6
 [<ffffffff8142d82f>] wait_for_common+0xac/0xfd
 [<ffffffff8103ce52>] ? default_wake_function+0x0/0xf
 [<ffffffff811efdb1>] ? __generic_unplug_device+0x2d/0x31
 [<ffffffff8142d90a>] wait_for_completion+0x18/0x1a
 [<ffffffff811f5ee0>] blk_execute_rq+0xa1/0xd1
 [<ffffffff811f0c3e>] ? blk_get_request+0x3c/0x6c
 [<ffffffff812cd02a>] scsi_execute+0xf1/0x143
 [<ffffffff812cd12f>] scsi_execute_req+0xb3/0xe5
 [<ffffffff812d7dc2>] sr_test_unit_ready+0x60/0xc6
 [<ffffffff812d80dc>] ? sr_media_change+0x39/0x2ad
 [<ffffffff812d8124>] sr_media_change+0x81/0x2ad
 [<ffffffff8142f9b5>] ? _raw_spin_lock_irqsave+0x25/0x47
 [<ffffffff8142fbf4>] ? _raw_spin_unlock_irqrestore+0x33/0x3e
 [<ffffffff811c7f28>] ? rcu_read_unlock+0x23/0x2e
 [<ffffffff812f8742>] media_changed+0x4f/0x87
 [<ffffffff812f87a6>] cdrom_media_changed+0x2c/0x32
 [<ffffffff812d7e7b>] sr_block_media_changed+0x14/0x16
 [<ffffffff811271bd>] check_disk_change+0x24/0x56
 [<ffffffff812fbc93>] cdrom_open+0x427/0x49b
 [<ffffffff811f7fd2>] ? get_disk+0xec/0x110
 [<ffffffff81204195>] ? kobject_get+0x1a/0x22
 [<ffffffff812d7ff7>] sr_block_open+0x8b/0xa8
 [<ffffffff81203efc>] ? kobject_put+0x47/0x4b
 [<ffffffff81127eb1>] __blkdev_get+0x27a/0x391
 [<ffffffff81127fd5>] ? blkdev_open+0x0/0xa7
 [<ffffffff81127fd3>] blkdev_get+0xb/0xd
 [<ffffffff81128046>] blkdev_open+0x71/0xa7
 [<ffffffff81100594>] __dentry_open+0x208/0x33f
 [<ffffffff811c3bd1>] ? security_inode_permission+0x1c/0x1e
 [<ffffffff81100790>] nameidata_to_filp+0x3a/0x4b
 [<ffffffff8110d6f4>] do_filp_open+0x571/0xaea
 [<ffffffff8120bb6d>] ? __strncpy_from_user+0x29/0x53
 [<ffffffff8142fbb6>] ? _raw_spin_unlock+0x26/0x31
 [<ffffffff811002a3>] do_sys_open+0x5e/0x10a
 [<ffffffff81100378>] sys_open+0x1b/0x1d
 [<ffffffff81009c02>] system_call_fastpath+0x16/0x1b
INFO: task cdrdao:25112 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
cdrdao        D 0000000000000002     0 25112  20737 0x00000080
 ffff880021f67978 0000000000000086 ffff880021f678e8 ffffffff8142f9ed
 ffff880021f678e8 ffff88003869c380 ffff880021f67938 ffff880021f66000
 000000000000f970 0000000000014b80 ffff88004dfaab48 0000000000000000
Call Trace:
 [<ffffffff8142f9ed>] ? _raw_spin_lock+0x16/0x35
 [<ffffffff81203efc>] ? kobject_put+0x47/0x4b
 [<ffffffff8142e438>] schedule_timeout+0x31/0xde
 [<ffffffff811efcc5>] ? __blk_run_queue+0x4a/0x70
 [<ffffffff8142d82f>] wait_for_common+0xac/0xfd
 [<ffffffff8103ce52>] ? default_wake_function+0x0/0xf
 [<ffffffff811efd9e>] ? __generic_unplug_device+0x1a/0x31
 [<ffffffff8142d90a>] wait_for_completion+0x18/0x1a
 [<ffffffff811f5ee0>] blk_execute_rq+0xa1/0xd1
 [<ffffffff811ef789>] ? freed_request+0x26/0x43
 [<ffffffff811ce30f>] ? selinux_capable+0x1c/0x3a
 [<ffffffff811c2ec1>] ? security_capable+0x25/0x27
 [<ffffffff81052202>] ? capable+0x22/0x41
 [<ffffffff811f9629>] sg_io+0x292/0x3dc
 [<ffffffff811f9ce4>] scsi_cmd_ioctl+0x240/0x430
 [<ffffffff81110321>] ? pollwake+0x4d/0x4f
 [<ffffffff811c7f28>] ? rcu_read_unlock+0x23/0x2e
 [<ffffffff811c86ec>] ? avc_has_perm_noaudit+0x477/0x4a0
 [<ffffffff812fc440>] cdrom_ioctl+0x3f/0xccf
 [<ffffffff811c876c>] ? avc_has_perm+0x57/0x69
 [<ffffffff812d7ec8>] sr_block_ioctl+0x4b/0x81
 [<ffffffff811f7195>] __blkdev_driver_ioctl+0x75/0x9e
 [<ffffffff811f7ae4>] blkdev_ioctl+0x66f/0x6a3
 [<ffffffff81126f48>] block_ioctl+0x32/0x36
 [<ffffffff8110eab6>] vfs_ioctl+0x2d/0xa1
 [<ffffffff8110f026>] do_vfs_ioctl+0x485/0x4cb
 [<ffffffff8110f0bd>] sys_ioctl+0x51/0x74
 [<ffffffff81009c02>] system_call_fastpath+0x16/0x1b
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
sr 1:0:0:0: [sr0] CDB: Synchronize Cache(10): 35 00 00 00 00 00 00 00 00 00
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         res 40/00:02:00:0c:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
ata2.00: status: { DRDY }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
Comment 5 James 2010-07-04 18:03:33 EDT
(In reply to comment #3)
> Happened again after I burned an audio CD. The drive cycled and grunted fifteen
> times before I killed all instances of udevd. It was still locked. Then I
> noticed:
> 
>  1372 ?        D      0:10 hald-addon-storage: no polling because /dev/sr0 is
> locked via O_EXCL
> 
> killed that, and the system recovered.    

...Could be a red-herring. The problem also happens when hal is completely killed and I burn a CD using Brasero. udisks-daemon gets stuck in D sleep. I only managed to get back normal operation having killed all of udev and udisks I could, and then kept pressing the eject button on the drive.
Comment 6 James 2010-07-04 18:14:32 EDT
More info: I tried burning with no udev or udisks, just cdrdao, and the problem's still there:

$ cdrdao write -v3 brasero.toc
Cdrdao version 1.2.3 - (C) Andreas Mueller <andreas@daneb.de>
Format converter enabled for extensions: ogg
Detected SG driver version: 3.5.27
Detected SG driver version: 3.5.27
/dev/sr0: TSSTcorp CDDVDW SN-S082H	Rev: SB00
Using driver: Generic SCSI-3/MMC - Version 2.0 (options 0x0000)

/dev/sr0: SCSI command Rezero Unit (0x01) failed: Bad address.
/dev/sr0: SCSI command Rezero Unit (0x01) failed: Bad address.
Starting write at speed 24...
Pausing 10 seconds - hit CTRL-C to abort.
Process can be aborted with QUIT signal (usually CTRL-\).
WARNING: No super user permission to setup real time scheduling.
Waiting for reader process
Buffer filled
Awaken, will start writing
Turning BURN-Proof on
Enabling JustLink.
Session format: 0
Drive accepted write parameter mode page variant 0.
Executing power calibration...
Power calibration successful.

Cue Sheet (variant 0):
CTL/  TNO  INDEX  DATA  SCMS  MIN  SEC  FRAME
ADR               FORM
01    00    00     01    00   00   00   00
01    01    00     00    00   00   00   00
01    01    01     00    00   00   02   00
01    02    00     00    00   26   42   10
01    02    01     00    00   26   42   22
01    aa    01     01    00   52   08   00
Drive accepted cue sheet variant 0.
Writing track 01 (mode AUDIO/AUDIO )...
Writing track 02 (mode AUDIO/AUDIO )....
Wrote 525 of 525 MB (Buffers 100% 100%).
Wrote 234450 blocks. Buffer fill min 93%/max 100%.

followed by a bunch of grunting from the drive, and then I eventually killed cdrdao. The following:

ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
sr 1:0:0:0: [sr0] CDB: Synchronize Cache(10): 35 00 00 00 00 00 00 00 00 00
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         res 40/00:02:00:0c:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
ata2.00: status: { DRDY }
ata2: link is slow to respond, please be patient (ready=0)

showed up in dmesg. So I guess this rules out u(whatever) interfering... possible kernel bug?
Comment 7 James 2010-07-06 08:36:28 EDT
Seems the drive was marginal/faulty/had compatibility issues. Replaced with an Optiarc AD-7590A and no longer have any problems.

Note You need to log in before you can comment on or make changes to this bug.