Bug 577659

Summary: /dev/cdrom may be removed after CD loaded
Product: [Fedora] Fedora Reporter: Steve Tyler <stephent98>
Component: udevAssignee: Harald Hoyer <harald>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 12CC: a-j, djg, harald, horsley1953, ian, jonathan, pnewell
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: udev-145-20.fc12 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2010-04-23 18:58:20 EDT Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
Attachments:
Description Flags
output of "udevadm info --query=all --name=sr0"
none
shell script using wodim to burn a CDRW, checkisomd5 to test the disc
none
perl script implementing udev stress test none

Description Steve Tyler 2010-03-28 13:32:40 EDT
Description of problem:
When I insert a CD, the links /dev/cdrom, /dev/dvd, etc. are sometimes removed.

Usually the links are restored after the disc is ejected.
Sometimes loading another disc restores the links.

Version-Release number of selected component (if applicable):
udev-145-19.fc12.x86_64

How reproducible:
Usually.
Sometimes ejecting restores the links.
Sometime loading restores the links.

Steps to Reproduce:
1. rm /etc/udev/rules.d/70-persistent-cd.rules
2. Restart.
3. $ ls -l /dev | grep 'sr[0-9]'
4. Insert CD.
5. $ ls -l /dev | grep 'sr[0-9]' # may need to repeat several times
6. Eject CD.
7. $ ls -l /dev | grep 'sr[0-9]'
 
Actual results at step 5:
[stephent@walnut ~]$ ls -l /dev | grep 'sr[0-9]'
lrwxrwxrwx  1 root root           3 2010-03-28 09:32 scd0 -> sr0
brw-rw----+ 1 root cdrom    11,   0 2010-03-28 09:32 sr0

Expected results at step 5:
[stephent@walnut ~]$ ls -l /dev | grep 'sr[0-9]'
lrwxrwxrwx  1 root root           3 2010-03-28 10:01 cdrom -> sr0
lrwxrwxrwx  1 root root           3 2010-03-28 10:01 cdrw -> sr0
lrwxrwxrwx  1 root root           3 2010-03-28 10:01 dvd -> sr0
lrwxrwxrwx  1 root root           3 2010-03-28 10:01 dvdrw -> sr0
lrwxrwxrwx  1 root root           3 2010-03-28 09:32 scd0 -> sr0
brw-rw----+ 1 root cdrom    11,   0 2010-03-28 09:32 sr0

Additional info:

This returns without error:
$ sudo rpm -Va '*udev*'

I removed all custom udev rules files and RCS directories.
Comment 1 Steve Tyler 2010-03-28 13:40:08 EDT
Downgrading udev seems to fix this bug:
udev-145-12.fc12.x86_64
Comment 2 Steve Tyler 2010-03-28 17:41:44 EDT
Created attachment 403141 [details]
output of "udevadm info --query=all --name=sr0"

It looks there are two patches in udev-145-19 that could be related to this bug:
0004-fix-single-session-CD-detection.patch
0005-fix-previous-commit-for-CD-detection.patch
http://koji.fedoraproject.org/koji/rpminfo?rpmID=1882675

This attachment shows the output of

$ udevadm info --query=all --name=sr0

before an audio CD was inserted and after.

Before, all the links were present, and after, they were missing.
Comment 3 Steve Tyler 2010-03-29 08:59:38 EDT
This bug may also occur on a fairly fresh F13 install.

After a data CD was loaded:

[stephent@spruce ~]$ rpm -q udev
udev-151-7.fc13.x86_64
[stephent@spruce ~]$ ls -l /dev | grep 'sr[0-9]'
lrwxrwxrwx. 1 root root           3 Mar 29 05:49 scd0 -> sr0
brw-rw----+ 1 root cdrom    11,   0 Mar 29 05:49 sr0
[stephent@spruce ~]$ 

[stephent@spruce ~]$ udevadm info --query=all --name=sr0
P: /devices/pci0000:00/0000:00:11.0/host3/target3:0:0/3:0:0:0/block/sr0
N: sr0
S: block/11:0
S: scd0
S: disk/by-path/pci-0000:00:11.0-scsi-3:0:0:0
E: UDEV_LOG=3
E: DEVPATH=/devices/pci0000:00/0000:00:11.0/host3/target3:0:0/3:0:0:0/block/sr0
E: MAJOR=11
E: MINOR=0
E: DEVNAME=/dev/sr0
E: DEVTYPE=disk
E: SUBSYSTEM=block
E: ID_SCSI=1
E: ID_VENDOR=ATAPI
E: ID_VENDOR_ENC=ATAPI\x20\x20\x20
E: ID_MODEL=iHAS424_Y
E: ID_MODEL_ENC=iHAS424\x20\x20\x20Y\x20\x20\x20\x20\x20
E: ID_REVISION=ZL1U
E: ID_TYPE=cd
E: ID_BUS=scsi
E: ID_PATH=pci-0000:00:11.0-scsi-3:0:0:0
E: UDISKS_PRESENTATION_NOPOLICY=0
E: DEVLINKS=/dev/block/11:0 /dev/scd0 /dev/disk/by-path/pci-0000:00:11.0-scsi-3:0:0:0

After the data CD was ejected (tray is open):

[stephent@spruce ~]$ ls -l /dev | grep 'sr[0-9]'
lrwxrwxrwx. 1 root root           3 Mar 29 05:56 cdrom -> sr0
lrwxrwxrwx. 1 root root           3 Mar 29 05:56 cdrw -> sr0
lrwxrwxrwx. 1 root root           3 Mar 29 05:56 dvd -> sr0
lrwxrwxrwx. 1 root root           3 Mar 29 05:56 dvdrw -> sr0
lrwxrwxrwx. 1 root root           3 Mar 29 05:56 scd0 -> sr0
brw-rw----+ 1 root cdrom    11,   0 Mar 29 05:56 sr0
[stephent@spruce ~]$ udevadm info --query=all --name=sr0
P: /devices/pci0000:00/0000:00:11.0/host3/target3:0:0/3:0:0:0/block/sr0
N: sr0
S: block/11:0
S: scd0
S: disk/by-path/pci-0000:00:11.0-scsi-3:0:0:0
S: cdrom
S: cdrw
S: dvd
S: dvdrw
E: UDEV_LOG=3
E: DEVPATH=/devices/pci0000:00/0000:00:11.0/host3/target3:0:0/3:0:0:0/block/sr0
E: MAJOR=11
E: MINOR=0
E: DEVNAME=/dev/sr0
E: DEVTYPE=disk
E: SUBSYSTEM=block
E: ID_CDROM=1
E: ID_CDROM_CD_R=1
E: ID_CDROM_CD_RW=1
E: ID_CDROM_DVD=1
E: ID_CDROM_DVD_R=1
E: ID_CDROM_DVD_RW=1
E: ID_CDROM_DVD_RAM=1
E: ID_CDROM_DVD_PLUS_R=1
E: ID_CDROM_DVD_PLUS_RW=1
E: ID_CDROM_DVD_PLUS_R_DL=1
E: ID_CDROM_MRW=1
E: ID_CDROM_MRW_W=1
E: ID_SCSI=1
E: ID_VENDOR=ATAPI
E: ID_VENDOR_ENC=ATAPI\x20\x20\x20
E: ID_MODEL=iHAS424_Y
E: ID_MODEL_ENC=iHAS424\x20\x20\x20Y\x20\x20\x20\x20\x20
E: ID_REVISION=ZL1U
E: ID_TYPE=cd
E: ID_BUS=scsi
E: ID_PATH=pci-0000:00:11.0-scsi-3:0:0:0
E: ACL_MANAGE=1
E: GENERATED=1
E: UDISKS_PRESENTATION_NOPOLICY=0
E: DEVLINKS=/dev/block/11:0 /dev/scd0 /dev/disk/by-path/pci-0000:00:11.0-scsi-3:0:0:0 /dev/cdrom /dev/cdrw /dev/dvd /dev/dvdrw
Comment 4 Harald Hoyer 2010-03-29 10:54:27 EDT
this is most likely the result of a firmware bug in your cdrom
Comment 5 Steve Tyler 2010-03-29 15:58:29 EDT
(In reply to comment #4)
> this is most likely the result of a firmware bug in your cdrom    

The optical drive is a new LiteOn iHAS424 SATA drive with firmware ZL1U. The LiteOn web site does not show any firmware upgrades.

http://us.liteonit.com/us/index.php?option=com_content&task=view&id=279&Itemid=67&limit=1&limitstart=2

[stephent@walnut ~]$ sudo hdparm -I /dev/sr0

/dev/sr0:

ATAPI CD-ROM, with removable media
	Model Number:       ATAPI   iHAS424   Y                     
	Firmware Revision:  ZL1U    
	Transport:          Serial, ATA8-AST, SATA 1.0a, SATA II Extensions, SATA Rev 2.5, SATA Rev 2.6
Standards:
	Likely used CD-ROM ATAPI-1
Configuration:
	DRQ response: 50us.
	Packet size: 12 bytes
	cache/buffer size  = unknown
Capabilities:
	LBA, IORDY(can be disabled)
	DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 *udma5 
	     Cycle time: min=120ns recommended=120ns
	PIO: pio0 pio1 pio2 pio3 pio4 
	     Cycle time: no flow control=120ns  IORDY flow control=120ns
Commands/features:
	Enabled	Supported:
	   *	Power Management feature set
	   *	PACKET command feature set
	   *	DEVICE_RESET command
	   *	NOP cmd
	   *	Gen1 signaling speed (1.5Gb/s)
	   *	Host-initiated interface power management
	   *	Phy event counters
	    	Device-initiated interface power management
	   *	Software settings preservation
[stephent@walnut ~]$
Comment 6 Steve Tyler 2010-03-29 16:42:01 EDT
(In reply to comment #5)

> The optical drive is a new LiteOn iHAS424 SATA drive with firmware ZL1U. The
> LiteOn web site does not show any firmware upgrades.

Pulled the drive ...

From the label on the case:
Manufactured Date: December 2009

According to a review at newegg.com, LiteOn says of the iHAS424:
"Please be informed that the models made in December 2009 or after that time support Windows 7 OS."

http://www.newegg.com/Product/ProductReview.aspx?Item=27-106-335&SortField=0&SummaryType=0&Pagesize=10&SelectedRating=-1&PurchaseMark=&VideoOnlyMark=False&VendorMark=&Page=1&Keywords=firmware
Comment 7 Steve Tyler 2010-03-29 17:25:50 EDT
In F12, I enabled udev debug logging and could not get this bug to occur (although this bug is not reliably reproducible).

$ sudo udevadm control --log-priority=debug

After trying several CDs (audio and data), I disabled udev debug logging.

$ sudo udevadm control --log-priority=err

This bug was reproduced with the next audio CD I inserted.

[stephent@walnut ~]$ ls -l /dev | grep 'sr[0-9]'
lrwxrwxrwx  1 root root           3 2010-03-29 13:45 scd0 -> sr0
brw-rw----+ 1 root cdrom    11,   0 2010-03-29 13:45 sr0


BTW, when this bug occurs, discs do not automount.
Comment 8 Steve Tyler 2010-03-29 17:37:25 EDT
man open:
"The behavior of O_EXCL is undefined if O_CREAT is not specified."

udev.git-38a3cde11bc77af49a96245b8a8a0f2b583a344c.patch
+       fd = open(node, O_RDONLY|O_NONBLOCK|(is_mounted(node) ? 0 : O_EXCL));
Comment 9 David Gesswein 2010-03-30 20:38:35 EDT
We are seeing the same issue with our Fedora 12 laptop with drive Model=TSSTcorpCDW/DVD, FwRev=AC01. Before recent updates device always stayed around now it sometimes disappears.
udevadm trigger makes it reappear.
Comment 10 Harald Hoyer 2010-03-31 04:12:57 EDT
you can try to reproduce the problem by:

- kill udevd
- insert CD
- run "cdrom_id --export /dev/sr0" several times

If you see different outputs of "cdrom_id --export /dev/sr0" then the firmware is somehow broken. Windows queries the cdrom status only _one_ time. With udev it might happen to be queried several times.
Comment 11 Steve Tyler 2010-03-31 06:02:20 EDT
sudo killall udevd(In reply to comment #10)
> you can try to reproduce the problem by:
> 
> - kill udevd
> - insert CD
> - run "cdrom_id --export /dev/sr0" several times
> 
> If you see different outputs of "cdrom_id --export /dev/sr0" then the firmware
> is somehow broken. Windows queries the cdrom status only _one_ time. With udev
> it might happen to be queried several times.    

Seems to be the same every time. This is with an audio CD.

$ sudo killall udevd
...
[stephent@walnut ~]$ eject /dev/sr0
[stephent@walnut ~]$ /lib/udev/cdrom_id --export /dev/sr0
got 0 3
got 0 0
got 0 5
got 0 11
got 0 17
got 253 3
got 0 15
got 8 1
got 253 4
got 0 18
got 0 19
got 0 20
ID_CDROM=1
ID_CDROM_CD_R=1
ID_CDROM_CD_RW=1
ID_CDROM_DVD=1
ID_CDROM_DVD_R=1
ID_CDROM_DVD_RW=1
ID_CDROM_DVD_RAM=1
ID_CDROM_DVD_PLUS_R=1
ID_CDROM_DVD_PLUS_RW=1
ID_CDROM_DVD_PLUS_R_DL=1
ID_CDROM_MRW=1
ID_CDROM_MRW_W=1
[stephent@walnut ~]$ eject -t /dev/sr0
[stephent@walnut ~]$ /lib/udev/cdrom_id --export /dev/sr0
got 0 3
got 0 0
got 0 5
got 0 11
got 0 17
got 253 3
got 0 15
got 8 1
got 253 4
got 0 18
got 0 19
got 0 20
ID_CDROM=1
ID_CDROM_CD_R=1
ID_CDROM_CD_RW=1
ID_CDROM_DVD=1
ID_CDROM_DVD_R=1
ID_CDROM_DVD_RW=1
ID_CDROM_DVD_RAM=1
ID_CDROM_DVD_PLUS_R=1
ID_CDROM_DVD_PLUS_RW=1
ID_CDROM_DVD_PLUS_R_DL=1
ID_CDROM_MRW=1
ID_CDROM_MRW_W=1
ID_CDROM_MEDIA=1
ID_CDROM_MEDIA_CD=1
ID_CDROM_MEDIA_SESSION_COUNT=1
ID_CDROM_MEDIA_TRACK_COUNT=20
ID_CDROM_MEDIA_TRACK_COUNT_AUDIO=20
[stephent@walnut ~]$
Comment 12 Harald Hoyer 2010-03-31 06:19:14 EDT
You said, this only happens 'sometimes' ... you might have to run cdrom_id several times...
Comment 13 Steve Tyler 2010-03-31 07:37:35 EDT
AFAICT, the only unusual behavior is a brief stall if the command is run while the drive light is on. After the drive light is off, the command reports the ID_CDROM_MEDIA values. What other "different outputs" do you want me to look for?

# load audio CD here
[stephent@walnut ~]$ /lib/udev/cdrom_id --export /dev/sr0
got 0 3
got 0 0
got 0 5
got 0 11
got 0 17
got 253 3
got 0 15
got 8 1
got 253 4
got 0 18
got 0 19
got 0 20
<<<<<<<<<<<<<<<<<<<< stalls briefly here while drive light is on
ID_CDROM=1
ID_CDROM_CD_R=1
ID_CDROM_CD_RW=1
ID_CDROM_DVD=1
ID_CDROM_DVD_R=1
ID_CDROM_DVD_RW=1
ID_CDROM_DVD_RAM=1
ID_CDROM_DVD_PLUS_R=1
ID_CDROM_DVD_PLUS_RW=1
ID_CDROM_DVD_PLUS_R_DL=1
ID_CDROM_MRW=1
ID_CDROM_MRW_W=1
[stephent@walnut ~]$ /lib/udev/cdrom_id --export /dev/sr0
got 0 3
got 0 0
got 0 5
got 0 11
got 0 17
got 253 3
got 0 15
got 8 1
got 253 4
got 0 18
got 0 19
got 0 20
ID_CDROM=1
ID_CDROM_CD_R=1
ID_CDROM_CD_RW=1
ID_CDROM_DVD=1
ID_CDROM_DVD_R=1
ID_CDROM_DVD_RW=1
ID_CDROM_DVD_RAM=1
ID_CDROM_DVD_PLUS_R=1
ID_CDROM_DVD_PLUS_RW=1
ID_CDROM_DVD_PLUS_R_DL=1
ID_CDROM_MRW=1
ID_CDROM_MRW_W=1
ID_CDROM_MEDIA=1
ID_CDROM_MEDIA_CD=1
ID_CDROM_MEDIA_SESSION_COUNT=1
ID_CDROM_MEDIA_TRACK_COUNT=20
ID_CDROM_MEDIA_TRACK_COUNT_AUDIO=20
[stephent@walnut ~]$
Comment 14 Steve Tyler 2010-03-31 08:01:15 EDT
With udevd and this shell script running, cdrom_id reported "unable to open '/dev/sr0'" while an audio CD was loading. There are missing seconds when cdrom_id stalls.

[stephent@walnut ~]$ while true; do sleep 1; date; /lib/udev/cdrom_id --export /dev/sr0 > /dev/null; done;

...
Wed Mar 31 04:52:50 PDT 2010
Wed Mar 31 04:52:51 PDT 2010
Wed Mar 31 04:52:53 PDT 2010
Wed Mar 31 04:52:54 PDT 2010
Wed Mar 31 04:52:56 PDT 2010
Wed Mar 31 04:52:57 PDT 2010
unable to open '/dev/sr0'
Wed Mar 31 04:52:58 PDT 2010
Wed Mar 31 04:52:59 PDT 2010
Wed Mar 31 04:53:00 PDT 2010
Wed Mar 31 04:53:01 PDT 2010
^C
[stephent@walnut ~]$
Comment 15 Steve Tyler 2010-03-31 08:08:06 EDT
Same thing happens after "sudo killall udevd". Sometimes while the shell script is running and the CD is loading, cdrom_id reports "unable to open '/dev/sr0'".

NB: I have nautilus automount enabled.

...
Wed Mar 31 05:03:57 PDT 2010
Wed Mar 31 05:03:58 PDT 2010
Wed Mar 31 05:03:59 PDT 2010
Wed Mar 31 05:04:01 PDT 2010
unable to open '/dev/sr0'
Wed Mar 31 05:04:02 PDT 2010
Wed Mar 31 05:04:03 PDT 2010
Wed Mar 31 05:04:04 PDT 2010
Wed Mar 31 05:04:06 PDT 2010
Wed Mar 31 05:04:07 PDT 2010
^C
[stephent@walnut ~]$ ps -ef | grep udevd
stephent  3656  2291  0 05:04 pts/1    00:00:00 grep udevd
[stephent@walnut ~]$
Comment 16 Steve Tyler 2010-03-31 08:19:18 EDT
After downgrading udev and killing udevd, the "unable to open '/dev/sr0'" messages do not appear.

udev-145-12.fc12.x86_64
Comment 17 Steve Tyler 2010-03-31 09:05:18 EDT
cdrom_id doesn't report errno.

	fd = open(node, O_RDONLY|O_NONBLOCK|(is_mounted(node) ? 0 : O_EXCL));
	if (fd < 0) {
		info(udev, "unable to open '%s'\n", node);
		fprintf(stderr, "unable to open '%s'\n", node);
		rc = 1;
		goto exit;
	}

http://git.kernel.org/?p=linux/hotplug/udev.git;a=blob;f=extras/cdrom_id/cdrom_id.c;h=e485768de41154488a3b4d659dbfb8fd47e629bd;hb=HEAD#l595
Comment 18 Harald Hoyer 2010-03-31 09:14:32 EDT
cdrom_id uses O_EXCL to open the device exclusively. So, if any application has the device opened with O_EXCL already (like a CD burning app), cdrom_id will fail.
Comment 19 Harald Hoyer 2010-03-31 10:23:01 EDT
Can you please test this version?

http://harald.fedorapeople.org/downloads/udev/udev-145-19.1.fc12.src.rpm
Comment 20 Steve Tyler 2010-03-31 13:45:41 EDT
(In reply to comment #19)
> Can you please test this version?
> 
> http://harald.fedorapeople.org/downloads/udev/udev-145-19.1.fc12.src.rpm    

Could you build it for me?
I'm not set up to build rpms.
Comment 21 Steve Tyler 2010-03-31 15:31:13 EDT
(In reply to comment #18)
> cdrom_id uses O_EXCL to open the device exclusively. So, if any application has
> the device opened with O_EXCL already (like a CD burning app), cdrom_id will
> fail.    

After looking at udev-145-cdrom_retry.patch, ISTM that a burner app. that holds the device open for longer than about 100 * 0.8 = 80 seconds will cause the same problem to occur. Also, there will be 100 calls to fprintf (which could report the retry counter, BTW).

I have a burner script that uses wodim ...
man wodim:
"If you use speed=0 with a MMC compliant drive, wodim  will switch  to  the  lowest possible speed for drive and medium."
Comment 22 David Gesswein 2010-03-31 22:19:53 EDT
Based on the failure rate we were seeing before installing the version you provided it seems to fix the problem.
Comment 23 Harald Hoyer 2010-04-01 04:11:36 EDT
(In reply to comment #20)
> (In reply to comment #19)
> > Can you please test this version?
> > 
> > http://harald.fedorapeople.org/downloads/udev/udev-145-19.1.fc12.src.rpm    
> 
> Could you build it for me?
> I'm not set up to build rpms.    

$ sudo yum install rpm-build libtool automake autoconf sed libselinux-devel flex libsepol-devel glib2-devel bison findutils MAKEDEV gperf libtool libusb-devel libacl-devel libxslt hwdata gobject-introspection-devel gtk-doc usbutils libtool

$ rpmbuild --rebuild http://harald.fedorapeople.org/downloads/udev/udev-145-19.1.fc12.src.rpm
Comment 24 Harald Hoyer 2010-04-01 04:13:39 EDT
(In reply to comment #21)
> (In reply to comment #18)
> > cdrom_id uses O_EXCL to open the device exclusively. So, if any application has
> > the device opened with O_EXCL already (like a CD burning app), cdrom_id will
> > fail.    
> 
> After looking at udev-145-cdrom_retry.patch, ISTM that a burner app. that holds
> the device open for longer than about 100 * 0.8 = 80 seconds will cause the
> same problem to occur. Also, there will be 100 calls to fprintf (which could
> report the retry counter, BTW).
> 
> I have a burner script that uses wodim ...
> man wodim:
> "If you use speed=0 with a MMC compliant drive, wodim  will switch  to  the 
> lowest possible speed for drive and medium."    

If the burner app close(), then another udev "change" event for the cdrom will be sent, so cdrom_id is called again.
Comment 25 Steve Tyler 2010-04-01 16:14:20 EDT
(In reply to comment #23)
...
> $ sudo yum install rpm-build libtool automake autoconf sed libselinux-devel
> flex libsepol-devel glib2-devel bison findutils MAKEDEV gperf libtool
> libusb-devel libacl-devel libxslt hwdata gobject-introspection-devel gtk-doc
> usbutils libtool
> 
> $ rpmbuild --rebuild
> http://harald.fedorapeople.org/downloads/udev/udev-145-19.1.fc12.src.rpm    

Thanks. That was much easier than I expected. (I actually had .rpmmacros already configured for extracting source.)
Comment 26 Steve Tyler 2010-04-01 16:39:15 EDT
(In reply to comment #24)
...
> If the burner app close(), then another udev "change" event for the cdrom will
> be sent, so cdrom_id is called again.    

OK. I was thinking of the test scenario in which cdrom_id is repeatedly called directly.

Here is a report from my first attempt at a stress test:

Procedure:
1. Tile three terminal windows (arrange them so that automounted disc icons will be visible).
2. In one terminal:
   $ watch -d -n 1 "ls -l /dev | grep 'sr[0-9]'"
3. In the other two terminals:
   $ watch -d -n 1 "/lib/udev/cdrom_id --export /dev/sr0 2>&1"
4. Repeatedly load and eject CDs (audio and data). Also mix in a few empty tray closings and openings.

Notes:
1. udevd is left running.
2. nautilus automount is enabled.
3. Other polling apps. are left running:
[stephent@walnut ~]$ ps -ef | grep sr0
root      1414  1370  0 12:56 ?        00:00:00 hald-addon-storage: polling /dev/sr0 (every 2 sec)
root      1994  1868  0 12:56 ?        00:00:00 devkit-disks-daemon: polling /dev/sr0
stephent  7037  6902  0 13:22 pts/3    00:00:00 grep sr0
[stephent@walnut ~]$ 

Results:
At no time did the optical device links disappear for longer than one second.

The cdrom_id processes frequently reported one or more instances of
"unable to open '%s' exclusively: retrying\n" (text is from the patch, the test methodology doesn't capture the real text).

Sometimes the eject button on the optical drive had no effect when a disc was mounted, so the disc had to be ejected by right clicking on the disc icon.
Comment 27 Steve Tyler 2010-04-01 17:27:28 EDT
Created attachment 404101 [details]
shell script using wodim to burn a CDRW, checkisomd5 to test the disc

Stress test #2 burns a CDRW using wodim.

Procedure (Steps 1, 2, and 3 are the same as in comment 26.):
1. Tile three terminal windows (arrange them so that automounted disc icons
will be visible).
2. In one terminal:
   $ watch -d -n 1 "ls -l /dev | grep 'sr[0-9]'"
3. In the other two terminals:
   $ watch -d -n 1 "/lib/udev/cdrom_id --export /dev/sr0 2>&1"
4. Load a CDRW.
5. Run the attached shell script from a terminal window:
   $ isoburn.sh Fedora-13-Beta-i386-netinst.iso

Results:
At no time did the optical device links disappear for longer than one second.

The cdrom_id processes displayed
"unable to open '/dev/sr0' exclusively: retrying"
(message copied from the terminal)
for most of the test.

Notes:
It is useful to open another window while running the stress tests:
$ watch -d -n 1 'lsof /dev/sr0'

When an audio CD is mounted on the desktop, 'lsof /dev/sr0' shows that gvfsd-cdd has /dev/sr0 open continuously.

[stephent@walnut ~]$ lsof /dev/sr0
COMMAND     PID     USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
gvfsd-cdd 13595 stephent    7r   BLK   11,0      0t0 3253 /dev/sr0
Comment 28 Steve Tyler 2010-04-02 09:51:23 EDT
Created attachment 404184 [details]
perl script implementing udev stress test

The attached perl script stresses udev by repeatedly opening and closing /dev/sr0.

Procedure for udev stress test #3:
1. Tile five terminal windows.
2. $ watch -d -n 1 "ls -l /dev | grep 'sr[0-9]'"
3. $ watch -d -n 1 'lsof /dev/sr0'
4. In the remaining three terminals:
   $ ./udev-stress-1.pl
5. Load a CD.
6. Wait for 40 to 80 seconds.

Results:
After 40 to 80 seconds, the optical device links disappear. They are not restored by killing the udev-stress-1.pl processes. After killing the udev-stress-1.pl processes and ejecting the disc, the links are restored. The links may be temporarily restored while the udev-stress-1.pl processes are running by ejecting and immediately reloading the disc.

This stress test also prevents nautilus from automounting the disc.
Comment 29 Tom Horsley 2010-04-10 16:17:27 EDT
I also had my /dev/cdrom, et.al. links disappear in similar fashion after
recent updates to fedora 12 (exactly which ones, I'm not sure since I
don't use the dvdrw drive every day).

Aside from the links disappearing, I also had my system crash today after
ejecting a dvdrw I just wrote. The only trace in the log files was this
in /var/log/messages:

Apr 10 11:44:06 zooty kernel: iTCO_wdt: Unexpected close, not stopping watchdog!

Presumably that is related to these message I get on normal boot:

Apr 10 11:22:56 zooty kernel: iTCO_vendor_support: vendor-support=0
Apr 10 11:22:56 zooty kernel: ppdev: user-space parallel port driver
Apr 10 11:22:56 zooty kernel: iTCO_wdt: Intel TCO WatchDog Timer Driver v1.05
Apr 10 11:22:56 zooty kernel: iTCO_wdt: Found a ICH10 TCO device (Version=2, TCOBASE=0x0860)
Apr 10 11:22:56 zooty kernel: iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0

I see there is a closed bug that says udev-145-19.fc12.x86_64 is supposed
to fix the watchdog problem, but that's what I have installed. I've never
gotten the watchdog error before, so I'm figuring a recent update has
triggered it as well (maybe the udev update?)

And in the continued collection of weird udev results, my original /dev/cdrom
links went away because the /etc/udev/rules.d/70-persistent-cd.rules
file suddenly decided my DVD drive was on the :04: pci bus:

# DVD-RW_DVR-117D (pci-0000:04:00.0-scsi-0:0:0:0)
SUBSYSTEM=="block", ENV{ID_CDROM}=="?*", ENV{ID_PATH}=="pci-0000:04:00.0-scsi-0:0:0:0", SYMLINK+="cdrom", ENV{GENERATED}="1"
SUBSYSTEM=="block", ENV{ID_CDROM}=="?*", ENV{ID_PATH}=="pci-0000:04:00.0-scsi-0:0:0:0", SYMLINK+="cdrw", ENV{GENERATED}="1"
SUBSYSTEM=="block", ENV{ID_CDROM}=="?*", ENV{ID_PATH}=="pci-0000:04:00.0-scsi-0:0:0:0", SYMLINK+="dvd", ENV{GENERATED}="1"
SUBSYSTEM=="block", ENV{ID_CDROM}=="?*", ENV{ID_PATH}=="pci-0000:04:00.0-scsi-0:0:0:0", SYMLINK+="dvdrw", ENV{GENERATED}="1"

The previous version was identical to this new re-generated version
but everything said pci-0000:03:00.0

Somehow I have a feeling that all this mystery is related, happening as it
did at the same time (or at least I noticed it all at the same time :-).
Comment 30 Tom Horsley 2010-04-11 11:15:49 EDT
I have a feeling someone has hard coded a timeout somewhere that they
"just know" is longer than any drive could possibly take to recognize
media, but some drives, in fact, take a lot longer than that for some
media. I see the disappearing links when loading a dual layer DVD-RW
backup disk I've previously written, but not when loading a CDR data
disk.
Comment 31 Steve Tyler 2010-04-11 16:20:11 EDT
(In reply to comment #29)
...
> And in the continued collection of weird udev results, my original /dev/cdrom
> links went away because the /etc/udev/rules.d/70-persistent-cd.rules
> file suddenly decided my DVD drive was on the :04: pci bus:
...
> The previous version was identical to this new re-generated version
> but everything said pci-0000:03:00.0
> 
> Somehow I have a feeling that all this mystery is related, happening as it
> did at the same time (or at least I noticed it all at the same time :-).    

Did you move or replace your optical drive?
Bug 570490 - /dev/cdrom not created after optical drive replaced
Comment 32 Tom Horsley 2010-04-11 16:43:25 EDT
Nope, no changes to the hardware of any kind. I noticed someone else on
the fedora users list complaining that their drive switched from :02
to :03 as well. It is like something changed the kernel bus enumeration
ordering.
Comment 33 Andrew Junev 2010-04-12 11:43:27 EDT
I have exactly the same problem on a 32-bit Fedora 12. In my case, the problem is 100% reproducible - symlinks always disappear when I insert a disc (well, at least that's the case with all the data CDs and data DVDs I tried).


My system is:
# uname -a
Linux frontend1 2.6.32.11-99.fc12.i686.PAE #1 SMP Mon Apr 5 16:15:03 EDT 2010 i686 i686 i386 GNU/Linux

The content of 70-persistent-cd.rules file is:

# DVD-RW_DVR-111 (pci-0000:02:00.0-scsi-0:0:0:0)
SUBSYSTEM=="block", ENV{ID_CDROM}=="?*", ENV{ID_PATH}=="pci-0000:02:00.0-scsi-0:0:0:0", SYMLINK+="cdrom", ENV{GENERATED}="1"
SUBSYSTEM=="block", ENV{ID_CDROM}=="?*", ENV{ID_PATH}=="pci-0000:02:00.0-scsi-0:0:0:0", SYMLINK+="cdrw", ENV{GENERATED}="1"
SUBSYSTEM=="block", ENV{ID_CDROM}=="?*", ENV{ID_PATH}=="pci-0000:02:00.0-scsi-0:0:0:0", SYMLINK+="dvd", ENV{GENERATED}="1"
SUBSYSTEM=="block", ENV{ID_CDROM}=="?*", ENV{ID_PATH}=="pci-0000:02:00.0-scsi-0:0:0:0", SYMLINK+="dvdrw", ENV{GENERATED}="1"



Downgrading udev (as Steve mentions in his comment above) with 'yum downgrade udev': 

Running Transaction
  Installing     : udev-145-12.fc12.i686                                    1/2
  Cleanup        : udev-145-19.fc12.i686                                    2/2

Removed:
  udev.i686 0:145-19.fc12

Installed:
  udev.i686 0:145-12.fc12

Complete!

actually solves the problem. Symlinks are not removed anymore and automount works fine too.
Comment 34 Fedora Update System 2010-04-13 12:40:44 EDT
udev-145-20.fc12 has been submitted as an update for Fedora 12.
http://admin.fedoraproject.org/updates/udev-145-20.fc12
Comment 35 Steve Tyler 2010-04-13 16:24:09 EDT
(In reply to comment #34)
> udev-145-20.fc12 has been submitted as an update for Fedora 12.
> http://admin.fedoraproject.org/updates/udev-145-20.fc12    

The device links remain while running stress test #3 (Comment 28).

However, after the udev-stress-1.pl processes are killed,
the optical drive spins up, but the disc does not automount.
If the udev-stress-1.pl processes are killed, and the disc is ejected and immediately reloaded, the disc automounts.

I have reproduced this problem with an audio CD and a data CD.
Comment 36 Harald Hoyer 2010-04-14 03:00:33 EDT
(In reply to comment #35)
> However, after the udev-stress-1.pl processes are killed,
> the optical drive spins up, but the disc does not automount.

The disc might not automount, because you have been blocking the desktop automounter and poller. You might file a bug against the desktop automounter and the desktop poller.
Comment 37 Fedora Update System 2010-04-14 23:16:01 EDT
udev-145-20.fc12 has been pushed to the Fedora 12 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update udev'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/udev-145-20.fc12
Comment 38 Andrew Junev 2010-04-15 04:21:15 EDT
Just did a quick test. udev-145-20.fc12 seem to solve this issue for me. 
Thanks a lot!
Comment 39 Fedora Update System 2010-04-23 18:57:50 EDT
udev-145-20.fc12 has been pushed to the Fedora 12 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 40 Ian Dall 2010-07-25 03:17:28 EDT
This is NOT FIXED for me (with 32-bit Fedora).

With both udev-145-20 and udev-145-21 symlinks go away when I eject a DVD.
Maybe this is what is supposed to happen, but the don't come back when I load a new DVD.

If I watch with udevmonitor:


 # udevadm monitor
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing
KERNEL - the kernel uevent

KERNEL[1280041133.038515] change   /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0 (scsi)
KERNEL[1280041133.039366] change   /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0/block/sr0 (block)
UDEV  [1280041133.039404] change   /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0 (scsi)
UDEV  [1280041133.241138] change   /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0/block/sr0 (block)
KERNEL[1280041165.012205] change   /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0 (scsi)
KERNEL[1280041165.013369] change   /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0/block/sr0 (block)
UDEV  [1280041165.013407] change   /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0 (scsi)
UDEV  [1280041165.659009] change   /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0/block/sr0 (block)

If I trigger with:

 # udevadm trigger /devices/pci0000:00/0000:00:1f.1/host1/target1:0:0/1:0:0:0

I get /dev/dvd1 created. If I trigger again I get /dev/dvd2 etc. The only way to induce udev to create /dev/dvd is to restart udevd with "/sbin/start_udev"
Comment 41 Ian Dall 2010-07-26 04:57:07 EDT
I have realised that this is not really the same bug at all (although the symptoms are similar).