Bug 9668

Summary:	SATA DVD drive & UDF filesystem problem
Product:	IO/Storage	Reporter:	Milan Kocian (milan.kocian)
Component:	Serial ATA	Assignee:	Tejun Heo (tj)
Status:	RESOLVED CODE_FIX
Severity:	normal	CC:	bfennema, jack, kjchmielewski, protasnb, tj
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	2.6.23.12	Subsystem:
Regression:	No	Bisected commit-id:
Attachments:	boot log bad mount good mount log sr-media-changed-dbg.patch sr-use-last_written.patch sr-media-changed-dbg-1.patch

Description Milan Kocian 2007-12-31 10:57:49 UTC

Most recent kernel where this bug did not occur:
Distribution: Debian Unstable
Hardware Environment: P4, ICH7 chipset, NEC DVD_RW ND-4550A ATAPI CD/DVD-ROM
Software Environment: Vanilla kernel 2.6.23.12
Problem Description:
I mount dvd discs (udf) with piix and ide_cd modules without problem (on hw decribed higher). Then I put NEC drive to new mainboard (ICH9 + jmicron SATA/PATA chips) and use ahci (jmicron) + sr_mod modules. And now I see this (on some discs which was functional in old eviroment):

# mount -t udf /dev/scd0 /mnt
attempt to access beyond end of device
sr0: rw=0, want=68, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17591644, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17590620, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17590396, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17591636, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17590612, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17590388, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17591044, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17590020, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17589796, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17591036, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17590012, limit=4
attempt to access beyond end of device
sr0: rw=0, want=17589788, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14434196, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14433172, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14432948, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14434188, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14433164, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14432940, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14433596, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14432572, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14432348, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14433588, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14432564, limit=4
attempt to access beyond end of device
sr0: rw=0, want=14432340, limit=4
attempt to access beyond end of device
sr0: rw=0, want=1252, limit=4
attempt to access beyond end of device
sr0: rw=0, want=1028, limit=4
UDF-fs: No partition found (1)

I thought that may be problem in combination drive/chipset so I borrowed pure SATA DVD drive Optiarc (SONY) and I see the same problem. SATA drive was tested in ICH7 (ahci) and in ICH9 (ata_piix) environment. Problem was with SONY DVD-R discs (I don't have much more other dvd's with udf so I can't test more types). When I return to old drive with piix and ide_cd, I see no problem with it.

I think that may be problem in cooperation between sata driver and sr_mod and only in the given cases.

Steps to reproduce:
SATA dvd drive and some types of DVD discs.

Comment 1 Milan Kocian 2008-01-01 07:59:59 UTC

Interesting difference from dvd+rw-mediainfo command:
(the same dvd medium)

sm:~# diff -u minfo.scd minfo.hde       
--- minfo.scd	2008-01-01 16:33:38.215638808 +0100
+++ minfo.hde	2008-01-01 16:33:12.075626631 +0100
@@ -1,24 +1,22 @@
-INQUIRY:                [Optiarc ][DVD RW AD-7173S ][1-01]
+INQUIRY:                [_NEC    ][DVD_RW ND-4550A ][1.06]
 GET [CURRENT] CONFIGURATION:
  Mounted Media:         11h, DVD-R Sequential
  Media ID:              SONY16D1    
 READ DVD STRUCTURE[#10h]:
  Media Book Type:       00h, DVD-ROM book [revision 0]
  Legacy lead-out at:    2298496*2KB=4707319808
@@ -31,17 +29,18 @@
  State of Last Session: complete
  Number of Tracks:      2
 READ TRACK INFORMATION[#1]:
- Track State:           complete incremental
+ Track State:           complete
  Track Start Address:   0*2KB
  Free Blocks:           0*2KB
- Track Size:            2286112*2KB
+ Track Size:            196607*2KB
 READ TRACK INFORMATION[#2]:
- Track State:           complete incremental
- Track Start Address:   2286128*2KB
+ Track State:           complete
+ Track Start Address:   0*2KB
  Free Blocks:           0*2KB
  Track Size:            16*2KB
+ Last Recorded Address: 2286111*2KB
 FABRICATED TOC:
  Track#1  :             14@0
- Track#AA :             14@4294770689
+ Track#AA :             14@2286112
  Multi-session Info:    #1@0
 READ CAPACITY:          0*2048=0

Comment 2 Milan Kocian 2008-01-13 09:31:22 UTC

I tried to test older kernels. The same result. Only it's interesting that every kernel version reads the same dvd disc differently (imho want= is sector number ?).

2.6.16.57 does'nt detect device
2.6.18.8:
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=68, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9144576, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9143552, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9143328, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9144568, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9143544, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9143320, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9143976, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9142952, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9142728, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9143968, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9142944, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=9142720, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7503244, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7502220, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7501996, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7503236, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7502212, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7501988, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7502644, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7501620, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7501396, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7502636, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7501612, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=7501388, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=1252, limit=4
Jan 13 15:35:10 sm kernel: attempt to access beyond end of device
Jan 13 15:35:10 sm kernel: sr0: rw=0, want=1028, limit=4

2.6.20.21:
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=68, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276581648, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276580624, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276580400, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276581640, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276580616, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276580392, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276581048, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276580024, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276579800, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276581040, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276580016, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=276579792, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226938796, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226937772, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226937548, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226938788, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226937764, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226937540, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226938196, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226937172, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226936948, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226938188, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226937164, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=226936940, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=1252, limit=4
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=1028, limit=4

Comment 3 Natalie Protasevich 2008-03-15 14:09:02 UTC

Is this still a problem? Copying to UDF maintainer to help classify the bug: is it SATA or UDF issue.

Comment 4 Milan Kocian 2008-03-16 02:55:20 UTC

Yes, I tested 2.6.24.3 and I see the same behaviour. It's not probably UDF bug. IMHO there may be problem in SATA or sr_mod in scsi layer. See diff higher. The difference in cd drive is unsubstantial because I can reproduce it with the same drive. Once connected to IDE (using ide_cd) an second connected to SATA (using sr_mod and ahci). Unfortunately I don't have scsi dvd or other SATA then ahci for testing to resolve where is problem exactly.

Comment 5 Tejun Heo 2008-03-17 23:43:35 UTC

Do non-UDF medias work okay?

Comment 6 Milan Kocian 2008-03-18 01:13:16 UTC

As far as I know yes.

Comment 7 Milan Kocian 2008-12-15 01:32:13 UTC

Tested kernel 2.6.27.4. The problem still persists.

Comment 8 kjchmielewski 2009-08-20 20:23:04 UTC

Same problem here kernel 2.6.29.6

Comment 9 Tejun Heo 2009-08-27 07:21:49 UTC

cc'ing Jan Kara.  Jan, this one looks pretty similar to the bnc one.  Is this the same issue?

Comment 10 Jan Kara 2009-08-27 10:27:44 UTC

Tejun, this really looks like a problem in scsi layer / driver - note that the error messages are like:
Jan 13 17:11:42 sm kernel: attempt to access beyond end of device
Jan 13 17:11:42 sm kernel: sr0: rw=0, want=68, limit=4

So the block layer thinks that the medium has 4 sectors - not quite right. From what dvd+rw-mediainfo writes, it should be definitely more...

Comment 11 Tejun Heo 2009-08-27 11:36:41 UTC

Heh.. yes indeed.  Milan, can you please post full kernel log including the booting part?  Is there any chance the media is corrupt?

Comment 12 Jan Kara 2009-08-27 12:12:31 UTC

I wouldn't say the media is corrupt since he can mount it just fine with the other drive. Also what dvd+rw-mediainfo on that media says in both drives looks sane so it shouldn't be a problem like that one drive is able to read information from the media and the other drive is not...

OTOH the information reported by the drives *do* differ slightly so maybe that's triggering the problem. But I'd still rather suspect some obscure difference between ide_cd and sr_mod. But you are more knowledgeable in that area :)

Comment 13 Milan Kocian 2009-08-27 12:28:15 UTC

(In reply to comment #11)
> Heh.. yes indeed.  Milan, can you please post full kernel log including the
> booting part?  Is there any chance the media is corrupt?

Ok, I will send it over weekend (I must find problematic DVD discs :-)). I don't know if it's corrupted. But if yes then IDE layer knows to repair it (by some magic :-)) and mount it without problem (and medium is playable).
I remind that the identical NEC DVD drive connected via IDE (intel PIIX + ATA drivers + ide_cd module) is working. But connected via SATA (jmicron chip with PATA/SATA connectors + ahci driver + sr_mod module) is not working. (same medium of course).

I have new idea: I will try to use ATA SFF driver with PATA drive on older board to exclude ahci driver from path. ATA SFF drivers use sr_mod as pure SATA drivers, isn't it ? (It wasn't usable two years ago.)

Comment 14 Tejun Heo 2009-08-31 08:19:26 UTC

Hmmm... ahci or libata-sff shouldn't make any difference.  They basically go through the same path and the problem is likely to be somewhere in the sr or its interaction with the block layer.  Media revalidation, resizing and all those.  Anyways, please locate a problematic media and post full kernel log.  Let's see where it's going wrong.

Thanks.

Comment 15 Milan Kocian 2009-08-31 19:50:29 UTC

Created attachment 22934 [details]
boot log

Comment 16 Milan Kocian 2009-08-31 19:51:45 UTC

Created attachment 22935 [details]
bad mount

Comment 17 Milan Kocian 2009-08-31 19:52:44 UTC

Created attachment 22936 [details]
good mount log

Comment 18 Milan Kocian 2009-08-31 20:04:49 UTC

Oops thee new messages, sorry.
Here is boot log in first attachment. There is new warning (I think, its unsubstantial for this problem because I didn't see this warning in the past).

Bad mount is output from command (message is shorter compared to older kernels):
mount -t udf /dev/sr0 /mnt

good mount is output from command:
mount -t udf /dev/hdb /mnt

(yes now I have two drives to easy test it). Latest stable vanilla kernel 2.6.30.5. As you said, I didn't test ATA SFF.

Comment 19 Tejun Heo 2009-09-01 09:01:21 UTC

Created attachment 22950 [details]
sr-media-changed-dbg.patch

Can you please do the followings?

1. apply the attached patch and build kernel w/ PRINTK_TIMESTAMP on
2. boot the new kernel w/o any media in the drive.
3. shutdown hal
4. put an iso media into the drive and mount / umount.
5. remove the iso media
6. insert the problematic media and try mount.

One difference between ide-cd and sr is that ide-cd will always check media size on open while sr would do that only after it saw an UNIT ATTENTION.  If the drive isn't reporting UA for whatever reason, sr will stay optimistic and believe that the media hasn't changed.

Another thing to try is finding out what happens if the cdrom which currently is driven by ide-cd is driven by libata/sr.  Does it also fail to mount the udf media?

Thanks.

Comment 20 Milan Kocian 2009-09-01 18:55:45 UTC

Here are results of the tests. At first, I tried to use ATA SFF driver (pata_it8213 (unfortunately experimental)) for IDE drive, so yesterday's hdb is today's sr1. sr0 is sr0.

---NO PROBLEM medium in sr0:
ep  1 20:23:45 dv kernel: [  499.559764] sr 1:0:0:0: XXX UA on SR_TUR
Sep  1 20:23:45 dv kernel: [  499.613752] XXX sr0: sr_media_change() entered
Sep  1 20:23:45 dv kernel: [  499.614241] XXX sr0: sr_media_change: cd->device->changed=1
Sep  1 20:23:45 dv kernel: [  499.618564] XXX sr0: get_sectorsize: sect=2048 cap=6677612
Sep  1 20:23:49 dv kernel: [  503.202648] UDF-fs: Partition marked readonly; forcing readonly mount
Sep  1 20:23:49 dv kernel: [  503.232186] UDF-fs INFO UDF: Mounting volume 'MY_DATA_121905', timestamp 1970/01/01 00:00 (1000)

---PROBLEM medium in sr0:
Sep  1 20:25:28 dv kernel: [  602.599884] sr 1:0:0:0: XXX UA on SR_TUR
Sep  1 20:25:28 dv kernel: [  602.654669] XXX sr0: sr_media_change() entered
Sep  1 20:25:28 dv kernel: [  602.654911] XXX sr0: sr_media_change: cd->device->changed=1
Sep  1 20:25:28 dv kernel: [  602.660506] XXX sr0: get_sectorsize: sect=2048 cap=4
Sep  1 20:25:28 dv kernel: [  602.660563] attempt to access beyond end of device
Sep  1 20:25:28 dv kernel: [  602.660609] sr0: rw=0, want=68, limit=4
Sep  1 20:25:28 dv kernel: [  602.669176] attempt to access beyond end of device
Sep  1 20:25:28 dv kernel: [  602.669223] sr0: rw=0, want=1028, limit=4
Sep  1 20:25:28 dv kernel: [  602.669269] attempt to access beyond end of device
Sep  1 20:25:28 dv kernel: [  602.669314] sr0: rw=0, want=2052, limit=4
Sep  1 20:25:28 dv kernel: [  602.669359] UDF-fs: No anchor found
Sep  1 20:25:28 dv kernel: [  602.669407] UDF-fs: No partition found (1)
Sep  1 20:25:28 dv kernel: [  602.669592] XXX sr0: sr_media_change() entered
Sep  1 20:25:28 dv kernel: [  602.669765] XXX sr0: sr_media_change: cd->device->changed=0
Sep  1 20:25:28 dv kernel: [  602.671548] XXX sr0: sr_media_change() entered
Sep  1 20:25:28 dv kernel: [  602.671731] XXX sr0: sr_media_change: cd->device->changed=0
Sep  1 20:25:28 dv kernel: [  602.701224] XXX sr0: sr_media_change() entered
Sep  1 20:25:28 dv kernel: [  602.702918] XXX sr0: sr_media_change: cd->device->changed=0
Sep  1 20:25:28 dv kernel: [  602.703714] XXX sr0: sr_media_change() entered
Sep  1 20:25:28 dv kernel: [  602.703968] XXX sr0: sr_media_change: cd->device->changed=0

---NO PROBLEM medium in sr1 (yesterday's hdb) !!!!!?????:
Sep  1 20:33:22 dv kernel: [ 1075.975045] XXX sr1: sr_media_change() entered
Sep  1 20:33:22 dv kernel: [ 1075.975405] XXX sr1: sr_media_change: cd->device->changed=0
Sep  1 20:33:22 dv kernel: [ 1075.975458] attempt to access beyond end of device
Sep  1 20:33:22 dv kernel: [ 1075.975504] sr1: rw=0, want=68, limit=4
Sep  1 20:33:22 dv kernel: [ 1075.981605] attempt to access beyond end of device
Sep  1 20:33:22 dv kernel: [ 1075.981652] sr1: rw=0, want=1028, limit=4
Sep  1 20:33:22 dv kernel: [ 1075.982420] attempt to access beyond end of device
Sep  1 20:33:22 dv kernel: [ 1075.982466] sr1: rw=0, want=2052, limit=4
Sep  1 20:33:22 dv kernel: [ 1075.982511] UDF-fs: No anchor found
Sep  1 20:33:22 dv kernel: [ 1075.982555] UDF-fs: No partition found (1)
Sep  1 20:33:22 dv kernel: [ 1075.983851] XXX sr1: sr_media_change() entered
Sep  1 20:33:22 dv kernel: [ 1075.984467] XXX sr1: sr_media_change: cd->device->changed=0

---PROBLEM medium in sr1:
ep  1 20:28:50 dv kernel: [  804.626062] sr 6:0:1:0: XXX UA on SR_TUR
Sep  1 20:28:50 dv kernel: [  804.653428] XXX sr1: sr_media_change() entered
Sep  1 20:28:50 dv kernel: [  804.653902] XXX sr1: sr_media_change: cd->device->changed=1
Sep  1 20:28:50 dv kernel: [  804.658812] XXX sr1: get_sectorsize: sect=2048 cap=4
Sep  1 20:28:50 dv kernel: [  804.658872] attempt to access beyond end of device
Sep  1 20:28:50 dv kernel: [  804.658917] sr1: rw=0, want=68, limit=4
Sep  1 20:28:50 dv kernel: [  804.666123] attempt to access beyond end of device
Sep  1 20:28:50 dv kernel: [  804.666169] sr1: rw=0, want=1028, limit=4
Sep  1 20:28:50 dv kernel: [  804.666217] attempt to access beyond end of device
Sep  1 20:28:50 dv kernel: [  804.666262] sr1: rw=0, want=2052, limit=4
Sep  1 20:28:50 dv kernel: [  804.666306] UDF-fs: No anchor found
Sep  1 20:28:50 dv kernel: [  804.666355] UDF-fs: No partition found (1)
Sep  1 20:28:50 dv kernel: [  804.670282] XXX sr1: sr_media_change() entered
Sep  1 20:28:50 dv kernel: [  804.670617] XXX sr1: sr_media_change: cd->device->changed=0
Sep  1 20:28:50 dv kernel: [  804.672510] XXX sr1: sr_media_change() entered
Sep  1 20:28:50 dv kernel: [  804.672879] XXX sr1: sr_media_change: cd->device->changed=0
Sep  1 20:28:50 dv kernel: [  804.688467] XXX sr1: sr_media_change() entered
Sep  1 20:28:50 dv kernel: [  804.688884] XXX sr1: sr_media_change: cd->device->changed=0
Sep  1 20:28:50 dv kernel: [  804.690596] XXX sr1: sr_media_change() entered
Sep  1 20:28:50 dv kernel: [  804.691020] XXX sr1: sr_media_change: cd->device->changed=0

Comment 21 Tejun Heo 2009-09-02 02:42:44 UTC

Hmm... I see two problems here.

1. sr1 didn't report UA on media change and thus not triggering get_sectorsize().  Is this reproducible?  Also, I suppose the limit=4 comes from previous attempt of trying to load problem media in sr1, right?

2. get_sectorsize() apparently doesn't work for your problem media.  I'll try to find out what the difference is between ide-cd and sr_mod.

Thanks.

Comment 22 Tejun Heo 2009-09-02 06:34:28 UTC

Created attachment 22969 [details]
sr-use-last_written.patch

Does the attached patch make any difference?

Comment 23 Milan Kocian 2009-09-02 17:14:24 UTC

I tested your last patch and here is result. It's match better but still not excellent :-)). See logs and note bellow:

---sr0 with problematic medium is OK:
Sep  2 18:22:24 dv kernel: [   85.394038] XXX sr0: sr_media_change() entered
Sep  2 18:22:24 dv kernel: [   85.395267] XXX sr1: sr_media_change: media unavailable
Sep  2 18:22:24 dv kernel: [   85.395900] XXX sr0: sr_media_change: media unavailable
Sep  2 18:23:22 dv kernel: [  143.552144] sr 1:0:0:0: XXX UA on SR_TUR
Sep  2 18:23:22 dv kernel: [  143.607166] XXX sr0: sr_media_change() entered
Sep  2 18:23:22 dv kernel: [  143.607407] XXX sr0: sr_media_change: cd->device->changed=1
Sep  2 18:23:22 dv kernel: [  143.620610] XXX sr0: get_sectorsize: sect=2048 cap=9119552
Sep  2 18:23:25 dv kernel: [  147.181538] UDF-fs: Partition marked readonly; forcing readonly mount
Sep  2 18:23:25 dv kernel: [  147.211211] UDF-fs INFO UDF: Mounting volume 'LOTR_1', timestamp 2007/12/22 18:26 (1000)

---sr0 with no problematic medium is OK:
Sep  2 18:24:49 dv kernel: [  231.027826] sr 1:0:0:0: XXX UA on SR_TUR
Sep  2 18:24:49 dv kernel: [  231.081355] XXX sr0: sr_media_change() entered
Sep  2 18:24:49 dv kernel: [  231.081541] XXX sr0: sr_media_change: cd->device->changed=1
Sep  2 18:24:49 dv kernel: [  231.091635] XXX sr0: get_sectorsize: sect=2048 cap=6677612
Sep  2 18:24:53 dv kernel: [  234.681654] UDF-fs: Partition marked readonly; forcing readonly mount
Sep  2 18:24:53 dv kernel: [  234.711157] UDF-fs INFO UDF: Mounting volume 'MY_DATA_121905', timestamp 1970/01/01 00:00 (1000)

---sr1 (old hdb) with problematic medium is OK:
Sep  2 18:25:17 dv kernel: [  258.434976] sr 6:0:1:0: XXX UA on SR_TUR
Sep  2 18:25:17 dv kernel: [  258.462248] XXX sr1: sr_media_change() entered
Sep  2 18:25:17 dv kernel: [  258.462979] XXX sr1: sr_media_change: cd->device->changed=1
Sep  2 18:25:17 dv kernel: [  258.477695] XXX sr1: get_sectorsize: sect=2048 cap=9119420
Sep  2 18:25:21 dv kernel: [  262.501816] UDF-fs: Partition marked readonly; forcing readonly mount
Sep  2 18:25:21 dv kernel: [  262.531487] UDF-fs INFO UDF: Mounting volume 'LOTR_1', timestamp 2007/12/22 18:26 (1000)

---sr1 (old hdb) with NO problematic medium is BAD:
Sep  2 18:37:22 dv kernel: [  983.599622] sr 6:0:1:0: XXX UA on SR_TUR
Sep  2 18:37:22 dv kernel: [  983.752082] XXX sr1: sr_media_change() entered
Sep  2 18:37:22 dv kernel: [  983.752463] XXX sr1: sr_media_change: cd->device->changed=1
Sep  2 18:37:22 dv kernel: [  983.766116] XXX sr1: get_sectorsize: sect=2048 cap=4
Sep  2 18:37:22 dv kernel: [  983.766178] attempt to access beyond end of device
Sep  2 18:37:22 dv kernel: [  983.766224] sr1: rw=0, want=68, limit=4
Sep  2 18:37:22 dv kernel: [  983.772725] attempt to access beyond end of device
Sep  2 18:37:22 dv kernel: [  983.772772] sr1: rw=0, want=1028, limit=4
Sep  2 18:37:25 dv kernel: [  986.654893] attempt to access beyond end of device
Sep  2 18:37:25 dv kernel: [  986.654940] sr1: rw=0, want=2052, limit=4
Sep  2 18:37:25 dv kernel: [  986.654985] UDF-fs: No anchor found
Sep  2 18:37:25 dv kernel: [  986.655035] UDF-fs: No partition found (1)
Sep  2 18:37:25 dv kernel: [  986.656084] XXX sr1: sr_media_change() entered
Sep  2 18:37:25 dv kernel: [  986.656433] XXX sr1: sr_media_change: cd->device->changed=0
Sep  2 18:37:25 dv kernel: [  986.658038] XXX sr1: sr_media_change() entered
Sep  2 18:37:25 dv kernel: [  986.658341] XXX sr1: sr_media_change: cd->device->changed=0

-----------

sr1 with NO problematic medium has problem. I have read your first item in comment #21 but I can't confirm your teories. I have minimal knowledge in this area. By now I found only one medium not working in sr1. Curious :-).
Many thanks for your effort.

Comment 24 Tejun Heo 2009-09-03 13:40:58 UTC

Created attachment 22988 [details]
sr-media-changed-dbg-1.patch

Can you please try this with the non-working media?  Thanks.

Comment 25 Milan Kocian 2009-09-03 21:35:39 UTC

Log from non-working media in sr1:

Sep  3 23:16:18 dv kernel: [ 4903.170478] sr 6:0:1:0: XXX UA on SR_TUR
Sep  3 23:16:18 dv kernel: [ 4903.189357] XXX sr1: sr_media_change() entered
Sep  3 23:16:18 dv kernel: [ 4903.192416] XXX sr1: sr_media_change: cd->device->changed=1
Sep  3 23:16:18 dv kernel: [ 4903.196334] XXX sr1: get_sectorsize: READ_CAPACITY 1
Sep  3 23:16:18 dv kernel: [ 4903.203091] XXX sr1: get_sectorsize: last_written 1
Sep  3 23:16:18 dv kernel: [ 4903.203137] XXX sr1: get_sectorsize: sect=2048 cap=4
Sep  3 23:16:18 dv kernel: [ 4903.203195] attempt to access beyond end of device
Sep  3 23:16:18 dv kernel: [ 4903.203241] sr1: rw=0, want=68, limit=4
Sep  3 23:16:18 dv kernel: [ 4903.209865] attempt to access beyond end of device
Sep  3 23:16:18 dv kernel: [ 4903.209912] sr1: rw=0, want=1028, limit=4
Sep  3 23:16:21 dv kernel: [ 4906.115013] attempt to access beyond end of device
Sep  3 23:16:21 dv kernel: [ 4906.115060] sr1: rw=0, want=2052, limit=4
Sep  3 23:16:21 dv kernel: [ 4906.115105] UDF-fs: No anchor found
Sep  3 23:16:21 dv kernel: [ 4906.115149] UDF-fs: No partition found (1)
Sep  3 23:16:21 dv kernel: [ 4906.115781] XXX sr1: sr_media_change() entered
Sep  3 23:16:21 dv kernel: [ 4906.116211] XXX sr1: sr_media_change: cd->device->changed=0

Comment 26 Milan Kocian 2009-09-03 22:34:09 UTC

Just to be sure I tested this non-working media in IDE drive (sr1) by using IDE subsystem. And I see the identical problem with mounting:

Sep  4 00:15:51 dv kernel: [ 8475.746782] Uniform CD-ROM driver Revision: 3.20
Sep  4 00:16:35 dv kernel: [ 8519.639302] attempt to access beyond end of device
Sep  4 00:16:35 dv kernel: [ 8519.639322] hdb: rw=0, want=68, limit=4
Sep  4 00:16:35 dv kernel: [ 8519.645969] attempt to access beyond end of device
Sep  4 00:16:35 dv kernel: [ 8519.645987] hdb: rw=0, want=1028, limit=4
Sep  4 00:16:38 dv kernel: [ 8522.531978] attempt to access beyond end of device
Sep  4 00:16:38 dv kernel: [ 8522.531996] hdb: rw=0, want=2052, limit=4
Sep  4 00:16:38 dv kernel: [ 8522.532019] UDF-fs: No anchor found
Sep  4 00:16:38 dv kernel: [ 8522.532033] UDF-fs: No partition found (1)

It looks like problem with IDE device. Device don't read this medium by using both layers. 
So are we ready ? :-))

Comment 27 Tejun Heo 2009-09-04 02:07:50 UTC

Yeah, looks that way.  Will post patch upstream.  Thanks.

Comment 28 Milan Kocian 2009-09-04 06:45:38 UTC

Ok. Many times thanks. Shall I close the bug ?

Comment 29 Tejun Heo 2009-09-04 06:49:24 UTC

I'll and am resolving as CODE_FIX.  Thanks a lot.  :-)