2008-06-06 14:06:44

by Geert Uytterhoeven

[permalink] [raw]
Subject: [regression/bisected] corrupt CD data after media change and delay

Hi all,

When mounting a CD/DVD more than 30 seconds after inserting it, and reading
from it, we get:

attempt to access beyond end of device
sr0: rw=0, want=371932, limit=371928
Buffer I/O error on device sr0, logical block 92982
attempt to access beyond end of device
sr0: rw=0, want=371936, limit=371928
Buffer I/O error on device sr0, logical block 92983
attempt to access beyond end of device
sr0: rw=0, want=371940, limit=371928
Buffer I/O error on device sr0, logical block 92984
attempt to access beyond end of device
sr0: rw=0, want=371944, limit=371928
Buffer I/O error on device sr0, logical block 92985
attempt to access beyond end of device
sr0: rw=0, want=371948, limit=371928
Buffer I/O error on device sr0, logical block 92986
...

It can be reproduced on a PS3 with busybox userland using:

# Insert first CD
$ mount /dev/sr0 /mnt
$ ls -R /mnt
$ umount /mnt
$ eject
# Remove first CD

# Insert second CD
# Wait at least 30 seconds
$ mount /dev/sr0 /mnt
$ tar cf /dev/null /mnt

It does not happen when mounting the second CD within 30 seconds after
inserting it, which is consistent with

#define SR_TIMEOUT (30 * HZ)

I can't seem to reproduce it with a Debian or Fedora Core 6 userland.

The problem is present in 2.6.25.
2.6.24 is OK.

After bisecting, it seems to be introduced by

commit 210ba1d1724f5c4ed87a2ab1a21ca861a915f734
Author: James Bottomley <[email protected]>
Date: Sat Jan 5 10:39:51 2008 -0600

[SCSI] sr: update to follow tray status correctly

Based on an original patch from: David Martin <[email protected]>

When trying to get the drive status via ioctl CDROM_DRIVE_STATUS, with
no disk it gives CDS_TRAY_OPEN even if the tray is closed.

ioctl works as expected with ide-cd driver.

Gentoo bug report: http://bugs.gentoo.org/show_bug.cgi?id=196879

Cc: Maarten Bressers <[email protected]>
Signed-off-by: James Bottomley <[email protected]>

After reverting both 210ba1d1724f5c4ed87a2ab1a21ca861a915f734 and

commit 38582a62ecd337de4212004c7d4844899dc57890
Author: James Bottomley <[email protected]>
Date: Wed Feb 6 13:01:58 2008 -0600

[SCSI] sr: fix test unit ready responses

Commit 210ba1d1724f5c4ed87a2ab1a21ca861a915f734 updated sr.c to use
the scsi_test_unit_ready() function. Unfortunately, this has the
wrong characteristic of eating NOT_READY returns which sr.c relies on
for tray status.

Fix by rolling an internal sr_test_unit_ready() that doesn't do this.

Tested-by: Daniel Drake <[email protected]>
Signed-off-by: James Bottomley <[email protected]>

(which reverse-depends on it), the problem goes away.

As I have not much of a clue about what's really going wrong, I added the debug
code below, and retried.

1. Mount first CD, read, unmount, eject:

+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
Sense Key : 0x2 [current]
+5+ CDS_DISC_OK
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
Sense Key : 0x2 [current]
+5+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
ISO 9660 Extensions: RRIP_1991A
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]


2. Mount second CD more than 30 seconds after insertion, try to read, unmount,
eject:

+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
ISO 9660 Extensions: Microsoft Joliet Level 3
ISO 9660 Extensions: RRIP_1991A
attempt to access beyond end of device
sr0: rw=0, want=371932, limit=371928
Buffer I/O error on device sr0, logical block 92982
attempt to access beyond end of device
sr0: rw=0, want=371936, limit=371928
Buffer I/O error on device sr0, logical block 92983
[...]
sr 0:0:0:0: [sr0] Device not ready: Sense Key : 0x2 [current]
sr 0:0:0:0: [sr0] Device not ready: ASC=0x3a ASCQ=0x0
end_request: I/O error, dev sr0, sector 367332
__ratelimit: 76 messages suppressed
...
sr 0:0:0:0: [sr0] Device not ready: Sense Key : 0x2 [current]
sr 0:0:0:0: [sr0] Device not ready: ASC=0x3a ASCQ=0x0
end_request: I/O error, dev sr0, sector 215608
__ratelimit: 12 messages suppressed
Buffer I/O error on device sr0, logical block 53902
Buffer I/O error on device sr0, logical block 53903
Buffer I/O error on device sr0, logical block 53904
Buffer I/O error on device sr0, logical block 53905
Buffer I/O error on device sr0, logical block 53906
Buffer I/O error on device sr0, logical block 53907
Buffer I/O error on device sr0, logical block 53908
sr 0:0:0:0: [sr0] Device not ready: Sense Key : 0x2 [current]
sr 0:0:0:0: [sr0] Device not ready: ASC=0x3a ASCQ=0x0
end_request: I/O error, dev sr0, sector 215608
sr 0:0:0:0: [sr0] Device not ready: Sense Key : 0x2 [current]
sr 0:0:0:0: [sr0] Device not ready: ASC=0x3a ASCQ=0x0
end_request: I/O error, dev sr0, sector 270656
__ratelimit: 27 messages suppressed
Buffer I/O error on device sr0, logical block 67664
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]


3. Mount second CD immediately after insertion, read, unmount, eject:

+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
Sense Key : 0x2 [current]
+5+ CDS_DISC_OK
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
Sense Key : 0x2 [current]
+5+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
ISO 9660 Extensions: Microsoft Joliet Level 3
ISO 9660 Extensions: RRIP_1991A
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+1+ CDS_DISC_OK
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
+0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]


When running a Debian userland, I see some debug messages every few seconds.
Probably there's a deamon polling all drives with removable media, preventing
the problem from happening.

Is this a bug in the generic SCSI CD-ROM code, or does it merely expose a bug
in the ps3rom driver?

Thanks in advance!

Index: ps3-linux-2.6/drivers/scsi/sr.c
===================================================================
--- ps3-linux-2.6.orig/drivers/scsi/sr.c 2008-06-06 14:59:50.000000000 +0200
+++ ps3-linux-2.6/drivers/scsi/sr.c 2008-06-06 15:30:03.000000000 +0200
@@ -178,6 +178,8 @@ int sr_test_unit_ready(struct scsi_devic
the_result = scsi_execute_req(sdev, cmd, DMA_NONE, NULL,
0, sshdr, SR_TIMEOUT,
retries--);
+ printk("+0+ the_result = 0x%x ", the_result);
+ scsi_show_sense_hdr(&sshdr);

} while (retries > 0 &&
(!scsi_status_is_good(the_result) ||
Index: ps3-linux-2.6/drivers/scsi/sr_ioctl.c
===================================================================
--- ps3-linux-2.6.orig/drivers/scsi/sr_ioctl.c 2008-06-06 14:59:50.000000000 +0200
+++ ps3-linux-2.6/drivers/scsi/sr_ioctl.c 2008-06-06 15:04:28.000000000 +0200
@@ -306,23 +306,32 @@ int sr_drive_status(struct cdrom_device_
/* we have no changer support */
return -EINVAL;
}
- if (0 == sr_test_unit_ready(cd->device, &sshdr))
+ if (0 == sr_test_unit_ready(cd->device, &sshdr)) {
+ printk("+1+ CDS_DISC_OK\n");
return CDS_DISC_OK;
+ }
+ scsi_show_sense_hdr(&sshdr);

if (!cdrom_get_media_event(cdi, &med)) {
- if (med.media_present)
+ if (med.media_present) {
+ printk("+2+ CDS_DISC_OK\n");
return CDS_DISC_OK;
- else if (med.door_open)
+ } else if (med.door_open) {
+ printk("+3+ CDS_TRAY_OPEN\n");
return CDS_TRAY_OPEN;
- else
+ } else {
+ printk("+4+ CDS_NO_DISC\n");
return CDS_NO_DISC;
+ }
}

/*
* 0x04 is format in progress .. but there must be a disc present!
*/
- if (sshdr.sense_key == NOT_READY && sshdr.asc == 0x04)
+ if (sshdr.sense_key == NOT_READY && sshdr.asc == 0x04) {
+ printk("+5+ CDS_DISC_OK\n");
return CDS_DISC_OK;
+ }

/*
* If not using Mt Fuji extended media tray reports,
@@ -331,11 +340,15 @@ int sr_drive_status(struct cdrom_device_
*/
if (scsi_sense_valid(&sshdr) &&
/* 0x3a is medium not present */
- sshdr.asc == 0x3a)
+ sshdr.asc == 0x3a) {
+ printk("+6+ CDS_NO_DISC\n");
return CDS_NO_DISC;
- else
+ } else {
+ printk("+7+ CDS_TRAY_OPEN\n");
return CDS_TRAY_OPEN;
+ }

+ printk("+8+ CDS_DRIVE_NOT_READY\n");
return CDS_DRIVE_NOT_READY;
}


With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone: +32 (0)2 700 8453
Fax: +32 (0)2 700 8622
E-mail: [email protected]
Internet: http://www.sony-europe.com/

Sony Technology and Software Centre Europe
A division of Sony Service Centre (Europe) N.V.
Registered office: Technologielaan 7 · B-1840 Londerzeel · Belgium
VAT BE 0413.825.160 · RPR Brussels
Fortis 293-0376800-10 GEBA-BE-BB


2008-06-06 15:13:54

by James Bottomley

[permalink] [raw]
Subject: Re: [regression/bisected] corrupt CD data after media change and delay

On Fri, 2008-06-06 at 16:06 +0200, Geert Uytterhoeven wrote:
> Hi all,
>
> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
> from it, we get:
>
> attempt to access beyond end of device
> sr0: rw=0, want=371932, limit=371928
> Buffer I/O error on device sr0, logical block 92982
> attempt to access beyond end of device
> sr0: rw=0, want=371936, limit=371928
> Buffer I/O error on device sr0, logical block 92983
> attempt to access beyond end of device
> sr0: rw=0, want=371940, limit=371928
> Buffer I/O error on device sr0, logical block 92984
> attempt to access beyond end of device
> sr0: rw=0, want=371944, limit=371928
> Buffer I/O error on device sr0, logical block 92985
> attempt to access beyond end of device
> sr0: rw=0, want=371948, limit=371928
> Buffer I/O error on device sr0, logical block 92986
> ...
>
> It can be reproduced on a PS3 with busybox userland using:
>
> # Insert first CD
> $ mount /dev/sr0 /mnt
> $ ls -R /mnt
> $ umount /mnt
> $ eject
> # Remove first CD
>
> # Insert second CD
> # Wait at least 30 seconds
> $ mount /dev/sr0 /mnt
> $ tar cf /dev/null /mnt
>
> It does not happen when mounting the second CD within 30 seconds after
> inserting it, which is consistent with
>
> #define SR_TIMEOUT (30 * HZ)
>
> I can't seem to reproduce it with a Debian or Fedora Core 6 userland.
>
> The problem is present in 2.6.25.
> 2.6.24 is OK.

Hmm ... how are you preventing HAL from automatically mounting the CD?

Also, in the two different situations, what does

cat /sys/block/sr0/size

(assuming your cd is sr0) give you? My first theory is an incorrect
size propagating from something.

James

2008-06-06 17:28:09

by Geert Uytterhoeven

[permalink] [raw]
Subject: Re: [regression/bisected] corrupt CD data after media change and delay

On Fri, 6 Jun 2008, James Bottomley wrote:
> On Fri, 2008-06-06 at 16:06 +0200, Geert Uytterhoeven wrote:
> > When mounting a CD/DVD more than 30 seconds after inserting it, and reading
> > from it, we get:
> >
> > attempt to access beyond end of device
> > sr0: rw=0, want=371932, limit=371928
> > Buffer I/O error on device sr0, logical block 92982
> > attempt to access beyond end of device
> > sr0: rw=0, want=371936, limit=371928
> > Buffer I/O error on device sr0, logical block 92983
> > attempt to access beyond end of device
> > sr0: rw=0, want=371940, limit=371928
> > Buffer I/O error on device sr0, logical block 92984
> > attempt to access beyond end of device
> > sr0: rw=0, want=371944, limit=371928
> > Buffer I/O error on device sr0, logical block 92985
> > attempt to access beyond end of device
> > sr0: rw=0, want=371948, limit=371928
> > Buffer I/O error on device sr0, logical block 92986
> > ...
> >
> > It can be reproduced on a PS3 with busybox userland using:
> >
> > # Insert first CD
> > $ mount /dev/sr0 /mnt
> > $ ls -R /mnt
> > $ umount /mnt
> > $ eject
> > # Remove first CD
> >
> > # Insert second CD
> > # Wait at least 30 seconds
> > $ mount /dev/sr0 /mnt
> > $ tar cf /dev/null /mnt
> >
> > It does not happen when mounting the second CD within 30 seconds after
> > inserting it, which is consistent with
> >
> > #define SR_TIMEOUT (30 * HZ)
> >
> > I can't seem to reproduce it with a Debian or Fedora Core 6 userland.
> >
> > The problem is present in 2.6.25.
> > 2.6.24 is OK.
>
> Hmm ... how are you preventing HAL from automatically mounting the CD?

By not running HAL?

> Also, in the two different situations, what does
>
> cat /sys/block/sr0/size
>
> (assuming your cd is sr0) give you? My first theory is an incorrect
> size propagating from something.

I'll give that a try on Monday...

With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone: +32 (0)2 700 8453
Fax: +32 (0)2 700 8622
E-mail: [email protected]
Internet: http://www.sony-europe.com/

Sony Technology and Software Centre Europe
A division of Sony Service Centre (Europe) N.V.
Registered office: Technologielaan 7 · B-1840 Londerzeel · Belgium
VAT BE 0413.825.160 · RPR Brussels
Fortis 293-0376800-10 GEBA-BE-BB

2008-06-09 12:55:37

by Geert Uytterhoeven

[permalink] [raw]
Subject: Re: [regression/bisected] corrupt CD data after media change and delay

On Fri, 6 Jun 2008, James Bottomley wrote:
> On Fri, 2008-06-06 at 16:06 +0200, Geert Uytterhoeven wrote:
> > When mounting a CD/DVD more than 30 seconds after inserting it, and reading
> > from it, we get:
> >
> > attempt to access beyond end of device
> > sr0: rw=0, want=371932, limit=371928
> > Buffer I/O error on device sr0, logical block 92982
> > attempt to access beyond end of device
> > sr0: rw=0, want=371936, limit=371928
> > Buffer I/O error on device sr0, logical block 92983
> > attempt to access beyond end of device
> > sr0: rw=0, want=371940, limit=371928
> > Buffer I/O error on device sr0, logical block 92984
> > attempt to access beyond end of device
> > sr0: rw=0, want=371944, limit=371928
> > Buffer I/O error on device sr0, logical block 92985
> > attempt to access beyond end of device
> > sr0: rw=0, want=371948, limit=371928
> > Buffer I/O error on device sr0, logical block 92986
> > ...
> >
> > It can be reproduced on a PS3 with busybox userland using:
> >
> > # Insert first CD
> > $ mount /dev/sr0 /mnt
> > $ ls -R /mnt
> > $ umount /mnt
> > $ eject
> > # Remove first CD
> >
> > # Insert second CD
> > # Wait at least 30 seconds
> > $ mount /dev/sr0 /mnt
> > $ tar cf /dev/null /mnt
> >
> > It does not happen when mounting the second CD within 30 seconds after
> > inserting it, which is consistent with
> >
> > #define SR_TIMEOUT (30 * HZ)
> >
> > I can't seem to reproduce it with a Debian or Fedora Core 6 userland.
> >
> > The problem is present in 2.6.25.
> > 2.6.24 is OK.
>
> Also, in the two different situations, what does
>
> cat /sys/block/sr0/size
>
> (assuming your cd is sr0) give you? My first theory is an incorrect
> size propagating from something.

Nice first theory!

Initially /sys/block/sr0/size is 2097151.

After inserting the first CD, and mounting it, /sys/block/sr0/size is changed
to the size of the first CD (in 512 byte blocks).

After ejecting the first CD and inserting the second CD, the behavior is like
this:
1. when immediately mounting the CD, /sys/block/sr0/size is updated to the
size of the second CD,
2. when waiting more than 30 seconds before mounting the CD,
/sys/block/sr0/size is not updated, and keeps the old value.

Surprisingly, it doesn't behave like this when inserting the first CD.
/sys/block/sr0/size is always updated, whether I wait 30 seconds before
mounting it or not.

With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone: +32 (0)2 700 8453
Fax: +32 (0)2 700 8622
E-mail: [email protected]
Internet: http://www.sony-europe.com/

Sony Technology and Software Centre Europe
A division of Sony Service Centre (Europe) N.V.
Registered office: Technologielaan 7 · B-1840 Londerzeel · Belgium
VAT BE 0413.825.160 · RPR Brussels
Fortis 293-0376800-10 GEBA-BE-BB

2008-06-09 13:54:42

by Geert Uytterhoeven

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Mon, 9 Jun 2008, Geert Uytterhoeven wrote:
> On Fri, 6 Jun 2008, James Bottomley wrote:
> > On Fri, 2008-06-06 at 16:06 +0200, Geert Uytterhoeven wrote:
> > > When mounting a CD/DVD more than 30 seconds after inserting it, and reading
> > > from it, we get:
> > >
> > > attempt to access beyond end of device
> > > sr0: rw=0, want=371932, limit=371928
> > > Buffer I/O error on device sr0, logical block 92982
> > > attempt to access beyond end of device
> > > sr0: rw=0, want=371936, limit=371928
> > > Buffer I/O error on device sr0, logical block 92983
> > > attempt to access beyond end of device
> > > sr0: rw=0, want=371940, limit=371928
> > > Buffer I/O error on device sr0, logical block 92984
> > > attempt to access beyond end of device
> > > sr0: rw=0, want=371944, limit=371928
> > > Buffer I/O error on device sr0, logical block 92985
> > > attempt to access beyond end of device
> > > sr0: rw=0, want=371948, limit=371928
> > > Buffer I/O error on device sr0, logical block 92986
> > > ...
> > >
> > > It can be reproduced on a PS3 with busybox userland using:
> > >
> > > # Insert first CD
> > > $ mount /dev/sr0 /mnt
> > > $ ls -R /mnt
> > > $ umount /mnt
> > > $ eject
> > > # Remove first CD
> > >
> > > # Insert second CD
> > > # Wait at least 30 seconds
> > > $ mount /dev/sr0 /mnt
> > > $ tar cf /dev/null /mnt
> > >
> > > It does not happen when mounting the second CD within 30 seconds after
> > > inserting it, which is consistent with
> > >
> > > #define SR_TIMEOUT (30 * HZ)
> > >
> > > I can't seem to reproduce it with a Debian or Fedora Core 6 userland.
> > >
> > > The problem is present in 2.6.25.
> > > 2.6.24 is OK.
> >
> > Also, in the two different situations, what does
> >
> > cat /sys/block/sr0/size
> >
> > (assuming your cd is sr0) give you? My first theory is an incorrect
> > size propagating from something.
>
> Nice first theory!
>
> Initially /sys/block/sr0/size is 2097151.
>
> After inserting the first CD, and mounting it, /sys/block/sr0/size is changed
> to the size of the first CD (in 512 byte blocks).
>
> After ejecting the first CD and inserting the second CD, the behavior is like
> this:
> 1. when immediately mounting the CD, /sys/block/sr0/size is updated to the
> size of the second CD,
> 2. when waiting more than 30 seconds before mounting the CD,
> /sys/block/sr0/size is not updated, and keeps the old value.
>
> Surprisingly, it doesn't behave like this when inserting the first CD.
> /sys/block/sr0/size is always updated, whether I wait 30 seconds before
> mounting it or not.

I managed to reproduce it on my laptop (Core 2 Duo, SATA DVD-RAM, running
Ubuntu 8.04 for amd64), by booting Debian's 2.6.25 kernel into recovery mode.
So the problem is not PS3-specific.

Worse, I never got an updated /sys/block/sr0/size for the second CD, not even
when mounting it ASAP (which is ca. 15-20 seconds after inserting it). It
always stayed at the value for the first CD.

Note that Debian's tar is `smart' and optimizes `tar cf /dev/null' by never
reading the input files, so you have to e.g. pipe the resulting archive to
`cat > /dev/null' or so.

With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone: +32 (0)2 700 8453
Fax: +32 (0)2 700 8622
E-mail: [email protected]
Internet: http://www.sony-europe.com/

Sony Technology and Software Centre Europe
A division of Sony Service Centre (Europe) N.V.
Registered office: Technologielaan 7 · B-1840 Londerzeel · Belgium
VAT BE 0413.825.160 · RPR Brussels
Fortis 293-0376800-10 GEBA-BE-BB

2008-06-09 15:05:37

by James Bottomley

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Mon, 2008-06-09 at 15:54 +0200, Geert Uytterhoeven wrote:
> I managed to reproduce it on my laptop (Core 2 Duo, SATA DVD-RAM, running
> Ubuntu 8.04 for amd64), by booting Debian's 2.6.25 kernel into recovery mode.
> So the problem is not PS3-specific.
>
> Worse, I never got an updated /sys/block/sr0/size for the second CD, not even
> when mounting it ASAP (which is ca. 15-20 seconds after inserting it). It
> always stayed at the value for the first CD.
>
> Note that Debian's tar is `smart' and optimizes `tar cf /dev/null' by never
> reading the input files, so you have to e.g. pipe the resulting archive to
> `cat > /dev/null' or so.

Well, we have the taxonomy. It's something to do with the media change
trigger. Could you try getting the output of this patch and correlate
the prints with your success and failure cases?

Thanks,

James

---

diff --git a/drivers/scsi/sr.c b/drivers/scsi/sr.c
index 7ee86d4..2b58772 100644
--- a/drivers/scsi/sr.c
+++ b/drivers/scsi/sr.c
@@ -212,6 +212,8 @@ static int sr_media_change(struct cdrom_device_info *cdi, int slot)
if (retval || (scsi_sense_valid(sshdr) &&
/* 0x3a is medium not present */
sshdr->asc == 0x3a)) {
+ printk("+10+ the result = 0x%x, skip size update ", retval);
+ scsi_show_sense_hdr(&sshdr);
/* Media not present or unable to test, unit probably not
* ready. This usually means there is no disc in the drive.
* Mark as changed, and we will figure it out later once
@@ -232,7 +234,7 @@ static int sr_media_change(struct cdrom_device_info *cdi, int slot)
sr_cd_check(cdi);
get_sectorsize(cd);
}
-
+ printk("+11+ Return forcing update is %d\n", retval);
out:
/* Notify userspace, that media has changed. */
if (retval != cd->previous_state)

2008-06-09 15:27:38

by Geert Uytterhoeven

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

Hi James,

On Mon, 9 Jun 2008, James Bottomley wrote:
> On Mon, 2008-06-09 at 15:54 +0200, Geert Uytterhoeven wrote:
> > I managed to reproduce it on my laptop (Core 2 Duo, SATA DVD-RAM, running
> > Ubuntu 8.04 for amd64), by booting Debian's 2.6.25 kernel into recovery mode.
> > So the problem is not PS3-specific.
> >
> > Worse, I never got an updated /sys/block/sr0/size for the second CD, not even
> > when mounting it ASAP (which is ca. 15-20 seconds after inserting it). It
> > always stayed at the value for the first CD.
>
> Well, we have the taxonomy. It's something to do with the media change
> trigger. Could you try getting the output of this patch and correlate
> the prints with your success and failure cases?

Sure!

Inserting first CD, mounting:

| +0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 1
^
OK

| ISO 9660 Extensions: RRIP_1991A

Unmounting first CD:

| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 0

Ejecting first CD:

| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 0

Inserting second CD, mounting after 30 seconds:

| +0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 0
^
Not updated!
| ISO 9660 Extensions: Microsoft Joliet Level 3
| ISO 9660 Extensions: RRIP_1991A

=> failed!

Unmounting second CD:

| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 0

Ejecting second CD:

| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 0

Inserting second CD, mounting immediately:

| +0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
| +0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
| +0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
| Sense Key : 0x2 [current]
| +5+ CDS_DISC_OK
| +0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
| +0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
| +0+ the_result = 0x8000002 Sense Key : 0x0 [current] [descriptor]
| Sense Key : 0x2 [current]
| +5+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 1
^
OK

| ISO 9660 Extensions: Microsoft Joliet Level 3
| ISO 9660 Extensions: RRIP_1991A

=> success!

Unmounting second CD:

| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +1+ CDS_DISC_OK
| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 0

Ejecting second CD:

| +0+ the_result = 0x0 Sense Key : 0x0 [current] [descriptor]
| +11+ Return forcing update is 0

With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone: +32 (0)2 700 8453
Fax: +32 (0)2 700 8622
E-mail: [email protected]
Internet: http://www.sony-europe.com/

Sony Technology and Software Centre Europe
A division of Sony Service Centre (Europe) N.V.
Registered office: Technologielaan 7 · B-1840 Londerzeel · Belgium
VAT BE 0413.825.160 · RPR Brussels
Fortis 293-0376800-10 GEBA-BE-BB

2008-06-13 17:33:19

by Geert Uytterhoeven

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
> from it, we get:

Apparently the fix didn't make it to all the CCed lists...

http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0

With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone: +32 (0)2 700 8453
Fax: +32 (0)2 700 8622
E-mail: [email protected]
Internet: http://www.sony-europe.com/

Sony Technology and Software Centre Europe
A division of Sony Service Centre (Europe) N.V.
Registered office: Technologielaan 7 · B-1840 Londerzeel · Belgium
VAT BE 0413.825.160 · RPR Brussels
Fortis 293-0376800-10 GEBA-BE-BB

2008-06-18 08:47:52

by Alessandro Suardi

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Fri, Jun 13, 2008 at 7:33 PM, Geert Uytterhoeven
<[email protected]> wrote:
> On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
>> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
>> from it, we get:
>
> Apparently the fix didn't make it to all the CCed lists...
>
> http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0

Oh, that's in mainline ? I still have the problem of having to
insert DVD / try accessing it and get errors / eject / re-insert
and then it magically works... the messages have changed
from what they were as reported here

http://bugzilla.kernel.org/show_bug.cgi?id=10116

(see comments #8 and #9) to these ones, in 2.6.26-rc6-git4:

Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Result:
hostbyte=0x00 driverbyte=0x08
Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Sense Key : 0x3 [current]
Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] ASC=0x11 ASCQ=0x0
Jun 17 22:38:43 sandman kernel: end_request: I/O error, dev sr0, sector 232
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 29
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 30
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 31
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 32
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 33
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 34
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 35
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 36
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 37
Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 38

here I eject and reinsert the disc, and:

Jun 17 22:39:10 sandman kernel: UDF-fs: No VRS found

lo and behold, no problem.

This does not, alas, happen every time. It might be at the first
DVD access after booting the laptop, but I haven't investigated
in this detail yet.

--alessandro

"Give me love / Or give me hate
Give me anything that's not just ok"

(Sophia, 'Weightless')

2008-06-18 11:14:00

by Geert Uytterhoeven

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Wed, 18 Jun 2008, Alessandro Suardi wrote:
> On Fri, Jun 13, 2008 at 7:33 PM, Geert Uytterhoeven
> <[email protected]> wrote:
> > On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
> >> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
> >> from it, we get:
> >
> > Apparently the fix didn't make it to all the CCed lists...
> >
> > http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0
>
> Oh, that's in mainline ? I still have the problem of having to

Not yet, it's in the scsi-rc-fixes-2.6 tree.

> insert DVD / try accessing it and get errors / eject / re-insert
> and then it magically works... the messages have changed
> from what they were as reported here
>
> http://bugzilla.kernel.org/show_bug.cgi?id=10116
>
> (see comments #8 and #9) to these ones, in 2.6.26-rc6-git4:
>
> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Result:
> hostbyte=0x00 driverbyte=0x08
> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Sense Key : 0x3 [current]
> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] ASC=0x11 ASCQ=0x0
> Jun 17 22:38:43 sandman kernel: end_request: I/O error, dev sr0, sector 232
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 29
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 30
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 31
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 32
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 33
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 34
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 35
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 36
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 37
> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 38
>
> here I eject and reinsert the disc, and:
>
> Jun 17 22:39:10 sandman kernel: UDF-fs: No VRS found
>
> lo and behold, no problem.
>
> This does not, alas, happen every time. It might be at the first
> DVD access after booting the laptop, but I haven't investigated
> in this detail yet.

Does /sys/block/sr0/size reflect the correct size of the DVD?

Did you try applying the patch?

With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone: +32 (0)2 700 8453
Fax: +32 (0)2 700 8622
E-mail: [email protected]
Internet: http://www.sony-europe.com/

Sony Technology and Software Centre Europe
A division of Sony Service Centre (Europe) N.V.
Registered office: Technologielaan 7 · B-1840 Londerzeel · Belgium
VAT BE 0413.825.160 · RPR Brussels
Fortis 293-0376800-10 GEBA-BE-BB

2008-06-18 12:16:04

by Alessandro Suardi

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Wed, Jun 18, 2008 at 1:13 PM, Geert Uytterhoeven
<[email protected]> wrote:
> On Wed, 18 Jun 2008, Alessandro Suardi wrote:
>> On Fri, Jun 13, 2008 at 7:33 PM, Geert Uytterhoeven
>> <[email protected]> wrote:
>> > On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
>> >> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
>> >> from it, we get:
>> >
>> > Apparently the fix didn't make it to all the CCed lists...
>> >
>> > http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0
>>
>> Oh, that's in mainline ? I still have the problem of having to
>
> Not yet, it's in the scsi-rc-fixes-2.6 tree.
>
>> insert DVD / try accessing it and get errors / eject / re-insert
>> and then it magically works... the messages have changed
>> from what they were as reported here
>>
>> http://bugzilla.kernel.org/show_bug.cgi?id=10116
>>
>> (see comments #8 and #9) to these ones, in 2.6.26-rc6-git4:
>>
>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Result:
>> hostbyte=0x00 driverbyte=0x08
>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Sense Key : 0x3 [current]
>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] ASC=0x11 ASCQ=0x0
>> Jun 17 22:38:43 sandman kernel: end_request: I/O error, dev sr0, sector 232
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 29
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 30
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 31
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 32
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 33
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 34
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 35
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 36
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 37
>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 38
>>
>> here I eject and reinsert the disc, and:
>>
>> Jun 17 22:39:10 sandman kernel: UDF-fs: No VRS found
>>
>> lo and behold, no problem.
>>
>> This does not, alas, happen every time. It might be at the first
>> DVD access after booting the laptop, but I haven't investigated
>> in this detail yet.
>
> Does /sys/block/sr0/size reflect the correct size of the DVD?
>
> Did you try applying the patch?

ATM I'm away from home (as usual), I'll post back when
I have the info you asked for and tried applying the
above patch. Thanks !

--alessandro

"Give me love / Or give me hate
Give me anything that's not just ok"

(Sophia, 'Weightless')

2008-06-21 14:18:29

by Alessandro Suardi

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

[dropped David Martin from CC: list as I get permanent delivery errors]

On Wed, Jun 18, 2008 at 2:15 PM, Alessandro Suardi
<[email protected]> wrote:
> On Wed, Jun 18, 2008 at 1:13 PM, Geert Uytterhoeven
> <[email protected]> wrote:
>> On Wed, 18 Jun 2008, Alessandro Suardi wrote:
>>> On Fri, Jun 13, 2008 at 7:33 PM, Geert Uytterhoeven
>>> <[email protected]> wrote:
>>> > On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
>>> >> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
>>> >> from it, we get:
>>> >
>>> > Apparently the fix didn't make it to all the CCed lists...
>>> >
>>> > http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0
>>>
>>> Oh, that's in mainline ? I still have the problem of having to
>>
>> Not yet, it's in the scsi-rc-fixes-2.6 tree.
>>
>>> insert DVD / try accessing it and get errors / eject / re-insert
>>> and then it magically works... the messages have changed
>>> from what they were as reported here
>>>
>>> http://bugzilla.kernel.org/show_bug.cgi?id=10116
>>>
>>> (see comments #8 and #9) to these ones, in 2.6.26-rc6-git4:
>>>
>>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Result:
>>> hostbyte=0x00 driverbyte=0x08
>>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Sense Key : 0x3 [current]
>>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] ASC=0x11 ASCQ=0x0
>>> Jun 17 22:38:43 sandman kernel: end_request: I/O error, dev sr0, sector 232
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 29
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 30
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 31
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 32
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 33
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 34
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 35
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 36
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 37
>>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 38
>>>
>>> here I eject and reinsert the disc, and:
>>>
>>> Jun 17 22:39:10 sandman kernel: UDF-fs: No VRS found
>>>
>>> lo and behold, no problem.
>>>
>>> This does not, alas, happen every time. It might be at the first
>>> DVD access after booting the laptop, but I haven't investigated
>>> in this detail yet.
>>
>> Does /sys/block/sr0/size reflect the correct size of the DVD?
>>
>> Did you try applying the patch?
>
> ATM I'm away from home (as usual), I'll post back when
> I have the info you asked for and tried applying the
> above patch. Thanks !

Sigh. I haven't been able to reproduce the problem once since
I posted this. Will keep trying...

--alessandro

"Give me love / Or give me hate
Give me anything that's not just ok"

(Sophia, 'Weightless')

2008-06-22 08:18:58

by Geert Uytterhoeven

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Sat, 21 Jun 2008, Alessandro Suardi wrote:
> On Wed, Jun 18, 2008 at 2:15 PM, Alessandro Suardi
> <[email protected]> wrote:
> > On Wed, Jun 18, 2008 at 1:13 PM, Geert Uytterhoeven
> > <[email protected]> wrote:
> >> On Wed, 18 Jun 2008, Alessandro Suardi wrote:
> >>> On Fri, Jun 13, 2008 at 7:33 PM, Geert Uytterhoeven
> >>> <[email protected]> wrote:
> >>> > On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
> >>> >> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
> >>> >> from it, we get:
> >>> >
> >>> > Apparently the fix didn't make it to all the CCed lists...
> >>> >
> >>> > http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0
> >>>
> >>> Oh, that's in mainline ? I still have the problem of having to
> >>
> >> Not yet, it's in the scsi-rc-fixes-2.6 tree.
> >>
> >>> insert DVD / try accessing it and get errors / eject / re-insert
> >>> and then it magically works... the messages have changed
> >>> from what they were as reported here
> >>>
> >>> http://bugzilla.kernel.org/show_bug.cgi?id=10116
> >>>
> >>> (see comments #8 and #9) to these ones, in 2.6.26-rc6-git4:
> >>>
> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Result:
> >>> hostbyte=0x00 driverbyte=0x08
> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Sense Key : 0x3 [current]
> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] ASC=0x11 ASCQ=0x0
> >>> Jun 17 22:38:43 sandman kernel: end_request: I/O error, dev sr0, sector 232
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 29
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 30
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 31
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 32
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 33
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 34
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 35
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 36
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 37
> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 38
> >>>
> >>> here I eject and reinsert the disc, and:
> >>>
> >>> Jun 17 22:39:10 sandman kernel: UDF-fs: No VRS found
> >>>
> >>> lo and behold, no problem.
> >>>
> >>> This does not, alas, happen every time. It might be at the first
> >>> DVD access after booting the laptop, but I haven't investigated
> >>> in this detail yet.
> >>
> >> Does /sys/block/sr0/size reflect the correct size of the DVD?
> >>
> >> Did you try applying the patch?
> >
> > ATM I'm away from home (as usual), I'll post back when
> > I have the info you asked for and tried applying the
> > above patch. Thanks !
>
> Sigh. I haven't been able to reproduce the problem once since
> I posted this. Will keep trying...

Perhaps because the fix is now in mainline?

With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone: +32 (0)2 700 8453
Fax: +32 (0)2 700 8622
E-mail: [email protected]
Internet: http://www.sony-europe.com/

Sony Technology and Software Centre Europe
A division of Sony Service Centre (Europe) N.V.
Registered office: Technologielaan 7 · B-1840 Londerzeel · Belgium
VAT BE 0413.825.160 · RPR Brussels
Fortis 293-0376800-10 GEBA-BE-BB

2008-06-22 13:14:45

by Alessandro Suardi

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Sun, Jun 22, 2008 at 10:18 AM, Geert Uytterhoeven
<[email protected]> wrote:
> On Sat, 21 Jun 2008, Alessandro Suardi wrote:
>> On Wed, Jun 18, 2008 at 2:15 PM, Alessandro Suardi
>> <[email protected]> wrote:
>> > On Wed, Jun 18, 2008 at 1:13 PM, Geert Uytterhoeven
>> > <[email protected]> wrote:
>> >> On Wed, 18 Jun 2008, Alessandro Suardi wrote:
>> >>> On Fri, Jun 13, 2008 at 7:33 PM, Geert Uytterhoeven
>> >>> <[email protected]> wrote:
>> >>> > On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
>> >>> >> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
>> >>> >> from it, we get:
>> >>> >
>> >>> > Apparently the fix didn't make it to all the CCed lists...
>> >>> >
>> >>> > http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0
>> >>>
>> >>> Oh, that's in mainline ? I still have the problem of having to
>> >>
>> >> Not yet, it's in the scsi-rc-fixes-2.6 tree.
>> >>
>> >>> insert DVD / try accessing it and get errors / eject / re-insert
>> >>> and then it magically works... the messages have changed
>> >>> from what they were as reported here
>> >>>
>> >>> http://bugzilla.kernel.org/show_bug.cgi?id=10116
>> >>>
>> >>> (see comments #8 and #9) to these ones, in 2.6.26-rc6-git4:
>> >>>
>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Result:
>> >>> hostbyte=0x00 driverbyte=0x08
>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Sense Key : 0x3 [current]
>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] ASC=0x11 ASCQ=0x0
>> >>> Jun 17 22:38:43 sandman kernel: end_request: I/O error, dev sr0, sector 232
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 29
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 30
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 31
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 32
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 33
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 34
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 35
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 36
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 37
>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 38
>> >>>
>> >>> here I eject and reinsert the disc, and:
>> >>>
>> >>> Jun 17 22:39:10 sandman kernel: UDF-fs: No VRS found
>> >>>
>> >>> lo and behold, no problem.
>> >>>
>> >>> This does not, alas, happen every time. It might be at the first
>> >>> DVD access after booting the laptop, but I haven't investigated
>> >>> in this detail yet.
>> >>
>> >> Does /sys/block/sr0/size reflect the correct size of the DVD?
>> >>
>> >> Did you try applying the patch?
>> >
>> > ATM I'm away from home (as usual), I'll post back when
>> > I have the info you asked for and tried applying the
>> > above patch. Thanks !
>>
>> Sigh. I haven't been able to reproduce the problem once since
>> I posted this. Will keep trying...
>
> Perhaps because the fix is now in mainline?

Eh, that may be a reason :)

I'm indeed tracking mainline and haven't reproduced with
at least six different discs in -rc7.

--alessandro

"Give me love / Or give me hate
Give me anything that's not just ok"

(Sophia, 'Weightless')

2008-07-11 21:26:02

by Alessandro Suardi

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Sun, Jun 22, 2008 at 3:14 PM, Alessandro Suardi
<[email protected]> wrote:
> On Sun, Jun 22, 2008 at 10:18 AM, Geert Uytterhoeven
> <[email protected]> wrote:
>> On Sat, 21 Jun 2008, Alessandro Suardi wrote:
>>> On Wed, Jun 18, 2008 at 2:15 PM, Alessandro Suardi
>>> <[email protected]> wrote:
>>> > On Wed, Jun 18, 2008 at 1:13 PM, Geert Uytterhoeven
>>> > <[email protected]> wrote:
>>> >> On Wed, 18 Jun 2008, Alessandro Suardi wrote:
>>> >>> On Fri, Jun 13, 2008 at 7:33 PM, Geert Uytterhoeven
>>> >>> <[email protected]> wrote:
>>> >>> > On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
>>> >>> >> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
>>> >>> >> from it, we get:
>>> >>> >
>>> >>> > Apparently the fix didn't make it to all the CCed lists...
>>> >>> >
>>> >>> > http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0
>>> >>>
>>> >>> Oh, that's in mainline ? I still have the problem of having to
>>> >>
>>> >> Not yet, it's in the scsi-rc-fixes-2.6 tree.
>>> >>
>>> >>> insert DVD / try accessing it and get errors / eject / re-insert
>>> >>> and then it magically works... the messages have changed
>>> >>> from what they were as reported here
>>> >>>
>>> >>> http://bugzilla.kernel.org/show_bug.cgi?id=10116
>>> >>>
>>> >>> (see comments #8 and #9) to these ones, in 2.6.26-rc6-git4:
>>> >>>
>>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Result:
>>> >>> hostbyte=0x00 driverbyte=0x08
>>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Sense Key : 0x3 [current]
>>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] ASC=0x11 ASCQ=0x0
>>> >>> Jun 17 22:38:43 sandman kernel: end_request: I/O error, dev sr0, sector 232
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 29
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 30
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 31
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 32
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 33
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 34
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 35
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 36
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 37
>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 38
>>> >>>
>>> >>> here I eject and reinsert the disc, and:
>>> >>>
>>> >>> Jun 17 22:39:10 sandman kernel: UDF-fs: No VRS found
>>> >>>
>>> >>> lo and behold, no problem.
>>> >>>
>>> >>> This does not, alas, happen every time. It might be at the first
>>> >>> DVD access after booting the laptop, but I haven't investigated
>>> >>> in this detail yet.
>>> >>
>>> >> Does /sys/block/sr0/size reflect the correct size of the DVD?
>>> >>
>>> >> Did you try applying the patch?
>>> >
>>> > ATM I'm away from home (as usual), I'll post back when
>>> > I have the info you asked for and tried applying the
>>> > above patch. Thanks !
>>>
>>> Sigh. I haven't been able to reproduce the problem once since
>>> I posted this. Will keep trying...
>>
>> Perhaps because the fix is now in mainline?
>
> Eh, that may be a reason :)
>
> I'm indeed tracking mainline and haven't reproduced with
> at least six different discs in -rc7.

Just had the symptoms again in -rc9-git9 :(

Relevant part of dmesg:

<mount -r /cdrom, access file with gmplayer>

SELinux: initialized (dev fuse, type fuse), uses genfs_contexts
ISO 9660 Extensions: Microsoft Joliet Level 3
ISO 9660 Extensions: RRIP_1991A
SELinux: initialized (dev sr0, type iso9660), uses genfs_contexts
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
Buffer I/O error on device sr0, logical block 2110628
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
Buffer I/O error on device sr0, logical block 2110629
attempt to access beyond end of device
sr0: rw=0, want=8442524, limit=2097151
Buffer I/O error on device sr0, logical block 2110630
attempt to access beyond end of device
sr0: rw=0, want=8442528, limit=2097151
Buffer I/O error on device sr0, logical block 2110631
attempt to access beyond end of device
sr0: rw=0, want=8442532, limit=2097151
Buffer I/O error on device sr0, logical block 2110632
attempt to access beyond end of device
sr0: rw=0, want=8442536, limit=2097151
Buffer I/O error on device sr0, logical block 2110633
attempt to access beyond end of device
sr0: rw=0, want=8442540, limit=2097151
Buffer I/O error on device sr0, logical block 2110634
attempt to access beyond end of device
sr0: rw=0, want=8442544, limit=2097151
Buffer I/O error on device sr0, logical block 2110635
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
Buffer I/O error on device sr0, logical block 2110628
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
Buffer I/O error on device sr0, logical block 2110629
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442516, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=8442520, limit=2097151

<here I eject, reinsert and remount the DVD>

UDF-fs: No VRS found
ISO 9660 Extensions: Microsoft Joliet Level 3
ISO 9660 Extensions: RRIP_1991A
SELinux: initialized (dev sr0, type iso9660), uses genfs_contexts

<now works fine>

Have to say that I didn't wait N seconds in the beginning,
but just rather

- plop cdrom in
- close tray
- mount -r /cdrom while disc is still spinning

Unfortunately I only have this after eject/remount:

[asuardi@sandman ~]$ cat /sys/block/sr0/size
9133120

Final note, as I said earlier in the thread, this is definitely
an occurrence of first device access after boot - as I just
rebooted:

[asuardi@sandman ~]$ uptime
23:25:28 up 17 min, 6 users, load average: 0.09, 0.18, 0.15
[asuardi@sandman ~]$ uname -a
Linux sandman 2.6.26-rc9-git9 #7 Fri Jul 11 21:59:15 CEST 2008 i686
i686 i386 GNU/Linux

Thanks,

--alessandro

"Give me love / Or give me hate
Give me anything that's not just ok"

(Sophia, 'Weightless')

2008-07-12 12:08:37

by Alessandro Suardi

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Fri, Jul 11, 2008 at 11:25 PM, Alessandro Suardi
<[email protected]> wrote:
> On Sun, Jun 22, 2008 at 3:14 PM, Alessandro Suardi
> <[email protected]> wrote:
>> On Sun, Jun 22, 2008 at 10:18 AM, Geert Uytterhoeven
>> <[email protected]> wrote:
>>> On Sat, 21 Jun 2008, Alessandro Suardi wrote:
>>>> On Wed, Jun 18, 2008 at 2:15 PM, Alessandro Suardi
>>>> <[email protected]> wrote:
>>>> > On Wed, Jun 18, 2008 at 1:13 PM, Geert Uytterhoeven
>>>> > <[email protected]> wrote:
>>>> >> On Wed, 18 Jun 2008, Alessandro Suardi wrote:
>>>> >>> On Fri, Jun 13, 2008 at 7:33 PM, Geert Uytterhoeven
>>>> >>> <[email protected]> wrote:
>>>> >>> > On Fri, 6 Jun 2008, Geert Uytterhoeven wrote:
>>>> >>> >> When mounting a CD/DVD more than 30 seconds after inserting it, and reading
>>>> >>> >> from it, we get:
>>>> >>> >
>>>> >>> > Apparently the fix didn't make it to all the CCed lists...
>>>> >>> >
>>>> >>> > http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Fjejb%2Fscsi-rc-fixes-2.6.git;a=commitdiff_plain;h=d1daeabf0da5bfa1943272ce508e2ba785730bf0
>>>> >>>
>>>> >>> Oh, that's in mainline ? I still have the problem of having to
>>>> >>
>>>> >> Not yet, it's in the scsi-rc-fixes-2.6 tree.
>>>> >>
>>>> >>> insert DVD / try accessing it and get errors / eject / re-insert
>>>> >>> and then it magically works... the messages have changed
>>>> >>> from what they were as reported here
>>>> >>>
>>>> >>> http://bugzilla.kernel.org/show_bug.cgi?id=10116
>>>> >>>
>>>> >>> (see comments #8 and #9) to these ones, in 2.6.26-rc6-git4:
>>>> >>>
>>>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Result:
>>>> >>> hostbyte=0x00 driverbyte=0x08
>>>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] Sense Key : 0x3 [current]
>>>> >>> Jun 17 22:38:43 sandman kernel: sr 1:0:0:0: [sr0] ASC=0x11 ASCQ=0x0
>>>> >>> Jun 17 22:38:43 sandman kernel: end_request: I/O error, dev sr0, sector 232
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 29
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 30
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 31
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 32
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 33
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 34
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 35
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 36
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 37
>>>> >>> Jun 17 22:38:43 sandman kernel: Buffer I/O error on device sr0, logical block 38
>>>> >>>
>>>> >>> here I eject and reinsert the disc, and:
>>>> >>>
>>>> >>> Jun 17 22:39:10 sandman kernel: UDF-fs: No VRS found
>>>> >>>
>>>> >>> lo and behold, no problem.
>>>> >>>
>>>> >>> This does not, alas, happen every time. It might be at the first
>>>> >>> DVD access after booting the laptop, but I haven't investigated
>>>> >>> in this detail yet.
>>>> >>
>>>> >> Does /sys/block/sr0/size reflect the correct size of the DVD?
>>>> >>
>>>> >> Did you try applying the patch?
>>>> >
>>>> > ATM I'm away from home (as usual), I'll post back when
>>>> > I have the info you asked for and tried applying the
>>>> > above patch. Thanks !
>>>>
>>>> Sigh. I haven't been able to reproduce the problem once since
>>>> I posted this. Will keep trying...
>>>
>>> Perhaps because the fix is now in mainline?
>>
>> Eh, that may be a reason :)
>>
>> I'm indeed tracking mainline and haven't reproduced with
>> at least six different discs in -rc7.
>
> Just had the symptoms again in -rc9-git9 :(
>
> Relevant part of dmesg:
>
> <mount -r /cdrom, access file with gmplayer>
>
> SELinux: initialized (dev fuse, type fuse), uses genfs_contexts
> ISO 9660 Extensions: Microsoft Joliet Level 3
> ISO 9660 Extensions: RRIP_1991A
> SELinux: initialized (dev sr0, type iso9660), uses genfs_contexts
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> Buffer I/O error on device sr0, logical block 2110628
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> Buffer I/O error on device sr0, logical block 2110629
> attempt to access beyond end of device
> sr0: rw=0, want=8442524, limit=2097151
> Buffer I/O error on device sr0, logical block 2110630
> attempt to access beyond end of device
> sr0: rw=0, want=8442528, limit=2097151
> Buffer I/O error on device sr0, logical block 2110631
> attempt to access beyond end of device
> sr0: rw=0, want=8442532, limit=2097151
> Buffer I/O error on device sr0, logical block 2110632
> attempt to access beyond end of device
> sr0: rw=0, want=8442536, limit=2097151
> Buffer I/O error on device sr0, logical block 2110633
> attempt to access beyond end of device
> sr0: rw=0, want=8442540, limit=2097151
> Buffer I/O error on device sr0, logical block 2110634
> attempt to access beyond end of device
> sr0: rw=0, want=8442544, limit=2097151
> Buffer I/O error on device sr0, logical block 2110635
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> Buffer I/O error on device sr0, logical block 2110628
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> Buffer I/O error on device sr0, logical block 2110629
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442516, limit=2097151
> attempt to access beyond end of device
> sr0: rw=0, want=8442520, limit=2097151
>
> <here I eject, reinsert and remount the DVD>
>
> UDF-fs: No VRS found
> ISO 9660 Extensions: Microsoft Joliet Level 3
> ISO 9660 Extensions: RRIP_1991A
> SELinux: initialized (dev sr0, type iso9660), uses genfs_contexts
>
> <now works fine>
>
> Have to say that I didn't wait N seconds in the beginning,
> but just rather
>
> - plop cdrom in
> - close tray
> - mount -r /cdrom while disc is still spinning
>
> Unfortunately I only have this after eject/remount:
>
> [asuardi@sandman ~]$ cat /sys/block/sr0/size
> 9133120
>
> Final note, as I said earlier in the thread, this is definitely
> an occurrence of first device access after boot - as I just
> rebooted:
>
> [asuardi@sandman ~]$ uptime
> 23:25:28 up 17 min, 6 users, load average: 0.09, 0.18, 0.15
> [asuardi@sandman ~]$ uname -a
> Linux sandman 2.6.26-rc9-git9 #7 Fri Jul 11 21:59:15 CEST 2008 i686
> i686 i386 GNU/Linux

And yet again, in 2.6.26-rc9-git10 freshly compiled/booted,
when trying to access the Fedora9 DVD to install a bunch
of packages needed to build SDLmame...

SELinux: initialized (dev fuse, type fuse), uses genfs_contexts
ISO 9660 Extensions: Microsoft Joliet Level 3
ISO 9660 Extensions: RRIP_1991A
SELinux: initialized (dev sr0, type iso9660), uses genfs_contexts
attempt to access beyond end of device
sr0: rw=0, want=3291924, limit=2097151
Buffer I/O error on device sr0, logical block 822980
attempt to access beyond end of device
sr0: rw=0, want=3291928, limit=2097151
Buffer I/O error on device sr0, logical block 822981
attempt to access beyond end of device
sr0: rw=0, want=3291932, limit=2097151
Buffer I/O error on device sr0, logical block 822982
attempt to access beyond end of device
sr0: rw=0, want=3291936, limit=2097151
Buffer I/O error on device sr0, logical block 822983
attempt to access beyond end of device
sr0: rw=0, want=3291940, limit=2097151
Buffer I/O error on device sr0, logical block 822984
attempt to access beyond end of device
sr0: rw=0, want=3291944, limit=2097151
Buffer I/O error on device sr0, logical block 822985
attempt to access beyond end of device
sr0: rw=0, want=3291948, limit=2097151
Buffer I/O error on device sr0, logical block 822986
attempt to access beyond end of device
sr0: rw=0, want=3291952, limit=2097151
Buffer I/O error on device sr0, logical block 822987
attempt to access beyond end of device
sr0: rw=0, want=3291924, limit=2097151
Buffer I/O error on device sr0, logical block 822980
attempt to access beyond end of device
sr0: rw=0, want=3291928, limit=2097151
Buffer I/O error on device sr0, logical block 822981
attempt to access beyond end of device
sr0: rw=0, want=3291924, limit=2097151
attempt to access beyond end of device
sr0: rw=0, want=3291928, limit=2097151
[asuardi@sandman sdlmame0126]$ h | grep siz
958 cat /sys/block/sr0/size
1031 h | grep siz
[asuardi@sandman sdlmame0126]$ !958
cat /sys/block/sr0/size
6993536

<eject, remount DVD>

[asuardi@sandman sdlmame0126]$ !mount
mount -r /cdrom
[asuardi@sandman sdlmame0126]$ cat /sys/block/sr0/size
6993536

<now everything works fine>

Possibly a new bug then - since size is always the same ?

--alessandro

"Give me love / Or give me hate
Give me anything that's not just ok"

(Sophia, 'Weightless')

2008-07-13 13:34:10

by James Bottomley

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Sat, 2008-07-12 at 14:08 +0200, Alessandro Suardi wrote:
> On Fri, Jul 11, 2008 at 11:25 PM, Alessandro Suardi
> sr0: rw=0, want=3291928, limit=2097151
> [asuardi@sandman sdlmame0126]$ h | grep siz
> 958 cat /sys/block/sr0/size
> 1031 h | grep siz
> [asuardi@sandman sdlmame0126]$ !958
> cat /sys/block/sr0/size
> 6993536
>
> <eject, remount DVD>
>
> [asuardi@sandman sdlmame0126]$ !mount
> mount -r /cdrom
> [asuardi@sandman sdlmame0126]$ cat /sys/block/sr0/size
> 6993536
>
> <now everything works fine>
>
> Possibly a new bug then - since size is always the same ?

It looks like a re-manifestation of Geert's bug.

You said everything worked in -rc7, and there actually have been no sr
changes at all between then and now, so I'm a bit confused as to how it
could reappear. Could you try a bisection search for it (first
re-verify -rc7 is OK, just in case that's a false negative).

Thanks,

James

2008-07-23 20:25:33

by Alessandro Suardi

[permalink] [raw]
Subject: Re: [Cbe-oss-dev] [regression/bisected] corrupt CD data after media change and delay

On Sun, Jul 13, 2008 at 3:33 PM, James Bottomley
<[email protected]> wrote:
> On Sat, 2008-07-12 at 14:08 +0200, Alessandro Suardi wrote:
>> On Fri, Jul 11, 2008 at 11:25 PM, Alessandro Suardi
>> sr0: rw=0, want=3291928, limit=2097151
>> [asuardi@sandman sdlmame0126]$ h | grep siz
>> 958 cat /sys/block/sr0/size
>> 1031 h | grep siz
>> [asuardi@sandman sdlmame0126]$ !958
>> cat /sys/block/sr0/size
>> 6993536
>>
>> <eject, remount DVD>
>>
>> [asuardi@sandman sdlmame0126]$ !mount
>> mount -r /cdrom
>> [asuardi@sandman sdlmame0126]$ cat /sys/block/sr0/size
>> 6993536
>>
>> <now everything works fine>
>>
>> Possibly a new bug then - since size is always the same ?
>
> It looks like a re-manifestation of Geert's bug.
>
> You said everything worked in -rc7, and there actually have been no sr
> changes at all between then and now, so I'm a bit confused as to how it
> could reappear. Could you try a bisection search for it (first
> re-verify -rc7 is OK, just in case that's a false negative).

I have been away a few days - I'll try this weekend rebuilding
older kernels (I save religiously my .configs for every kernel
I built in the last, um, five years at least) and give the reboot/
DVD mount/access sequence a go...

The good news is that in 2.6.26-git4, -git9, -git10 I have been
unable to reproduce the issue a single time. Still, I'm willing
to make a bit more effort in trying to reproduce.

--alessandro

"Give me love / Or give me hate
Give me anything that's not just ok"

(Sophia, 'Weightless')