dmesg spam

dmesg spam

[Andrew Morton]

With latest -mm, running fc8 I am getting this in the logs,
once per second.

sr0: CDROM not ready.  Make sure there is a disc in the drive.
sr0: CDROM not ready.  Make sure there is a disc in the drive.
sr0: CDROM not ready.  Make sure there is a disc in the drive.
sr0: CDROM not ready.  Make sure there is a disc in the drive.
sr0: CDROM not ready.  Make sure there is a disc in the drive.
sr0: CDROM not ready.  Make sure there is a disc in the drive.
sr0: CDROM not ready.  Make sure there is a disc in the drive.
sr0: CDROM not ready.  Make sure there is a disc in the drive.
sr0: CDROM not ready.  Make sure there is a disc in the drive.

Re: dmesg spam

[Bartlomiej Zolnierkiewicz]

On Sunday 03 February 2008, Andrew Morton wrote:
> 
> With latest -mm, running fc8 I am getting this in the logs,
                           ^^^
=> SCSI/libata

cc:ing Jeff

> once per second.
> 
> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> sr0: CDROM not ready.  Make sure there is a disc in the drive.

Re: dmesg spam

[Andrew Morton]

On Mon, 4 Feb 2008 15:24:55 +0100 Bartlomiej Zolnierkiewicz <bzolnier@gmail.com> wrote:

> On Sunday 03 February 2008, Andrew Morton wrote:
> > 
> > With latest -mm, running fc8 I am getting this in the logs,
>                            ^^^
> => SCSI/libata
> 
> cc:ing Jeff
> 
> > once per second.
> > 
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > sr0: CDROM not ready.  Make sure there is a disc in the drive.

Well..  it's coming out of the kernel.  Presumably it's that cdrom polling
thing in KDE.  James recently made changes to sr_ioctl.c but I've been
buried in more terminal regressions than this one.

Re: dmesg spam

[Jeff Garzik]

Andrew Morton wrote:
> On Mon, 4 Feb 2008 15:24:55 +0100 Bartlomiej Zolnierkiewicz <bzolnier@gmail.com> wrote:
> 
>> On Sunday 03 February 2008, Andrew Morton wrote:
>>> With latest -mm, running fc8 I am getting this in the logs,
>>                            ^^^
>> => SCSI/libata
>>
>> cc:ing Jeff
>>
>>> once per second.
>>>
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
>>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> 
> Well..  it's coming out of the kernel.  Presumably it's that cdrom polling
> thing in KDE.  James recently made changes to sr_ioctl.c but I've been
> buried in more terminal regressions than this one.

I don't see this in upstream...  can you isolate it to a particular git 
tree?

Clearly userland is initiating a once-per-second poll.  That is quite 
normal for 99% of CDROMs, which do not support async notification.

But also clearly that message is printk'd way too much in your case.

	Jeff

Re: dmesg spam

[James Bottomley]

On Mon, 2008-02-04 at 12:05 -0800, Andrew Morton wrote:
> On Mon, 4 Feb 2008 15:24:55 +0100 Bartlomiej Zolnierkiewicz <bzolnier@gmail.com> wrote:
> 
> > On Sunday 03 February 2008, Andrew Morton wrote:
> > > 
> > > With latest -mm, running fc8 I am getting this in the logs,
> >                            ^^^
> > => SCSI/libata
> > 
> > cc:ing Jeff
> > 
> > > once per second.
> > > 
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > > sr0: CDROM not ready.  Make sure there is a disc in the drive.
> 
> Well..  it's coming out of the kernel.  Presumably it's that cdrom polling
> thing in KDE.  James recently made changes to sr_ioctl.c but I've been
> buried in more terminal regressions than this one.

You're thinking of this one?

commit 210ba1d1724f5c4ed87a2ab1a21ca861a915f734
Author: James Bottomley <James.Bottomley@HansenPartnership.com>
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 <tasio@tasio.net>
 
You could try reversing it if you want, but I'm not certain that's the
problem (the patch only affected sr_do_status, which is a cdrom internal
thing).

The message comes from sr_ioctl.c:sr_do_ioctl().  Which means some user
level application is poking the drive with a command that's returning
NOT_READY.  Apparently it will shut up if quiet is set in the packet
command structure.

It could be the application is getting the wrong idea of the status from
sr_do_staus() which leads it to send commands which require a medium?
But we'll need a bit of debugging to determine this.

James

Re: dmesg spam

[James Bottomley]

On Mon, 2008-02-04 at 15:14 -0500, Jeff Garzik wrote:
> Andrew Morton wrote:
> > On Mon, 4 Feb 2008 15:24:55 +0100 Bartlomiej Zolnierkiewicz <bzolnier@gmail.com> wrote:
> > 
> >> On Sunday 03 February 2008, Andrew Morton wrote:
> >>> With latest -mm, running fc8 I am getting this in the logs,
> >>                            ^^^
> >> => SCSI/libata
> >>
> >> cc:ing Jeff
> >>
> >>> once per second.
> >>>
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> >>> sr0: CDROM not ready.  Make sure there is a disc in the drive.
> > 
> > Well..  it's coming out of the kernel.  Presumably it's that cdrom polling
> > thing in KDE.  James recently made changes to sr_ioctl.c but I've been
> > buried in more terminal regressions than this one.
> 
> I don't see this in upstream...  can you isolate it to a particular git 
> tree?

It's here in sr_ioctl.c:

int sr_do_ioctl(Scsi_CD *cd, struct packet_command *cgc)
{
[...]
                case NOT_READY: /* This happens if there is no disc in
drive */
[...]
                        if (!cgc->quiet)
                                printk(KERN_INFO "%s: CDROM not ready.
Make sure there is a disc in the drive.\n", cd->cdi.name);
#ifdef DEBUG
                        scsi_print_sense_hdr("sr", &sshdr);
#endif


> Clearly userland is initiating a once-per-second poll.  That is quite 
> normal for 99% of CDROMs, which do not support async notification.
> 
> But also clearly that message is printk'd way too much in your case.

I'm not averse to simply nuking the printk ... it's probably valueless
in a modern kernel, since something dbussy is supposed to tell you to
put a CD in the drive, not something in the kernel.

I am however interested to see if it's a symptom of something else that
might be a bigger problem.

James

Re: dmesg spam

[Jeff Garzik]

James Bottomley wrote:
> The message comes from sr_ioctl.c:sr_do_ioctl().  Which means some user
> level application is poking the drive with a command that's returning
> NOT_READY.  Apparently it will shut up if quiet is set in the packet
> command structure.
> 
> It could be the application is getting the wrong idea of the status from
> sr_do_staus() which leads it to send commands which require a medium?
> But we'll need a bit of debugging to determine this.


Userland polling of the cdrom is quite normal (if unfortunately), 
regardless of medium presence.  Probably HAL or dbus.

In theory, the userland app should (a) set quiet and (b) handle 
not-ready condition just fine.

I presume that (b) is ok, since not-ready just means to continue polling 
the cdrom ad infinitum, until media appears.

A useful experiment, if only to confirm the obvious, would be to insert 
some media.

What controller and device is in use?

	Jeff

Re: dmesg spam

[Jeff Garzik]

James Bottomley wrote:
> It's here in sr_ioctl.c:

Ah, indeed.  My grep-fu sucks today.


> I'm not averse to simply nuking the printk ... it's probably valueless
> in a modern kernel, since something dbussy is supposed to tell you to
> put a CD in the drive, not something in the kernel.

The reverse...  dbussy/HAL is implementing autodetection of media 
insertion, by polling ad infinitum.

	Jeff

Re: dmesg spam

[James Bottomley]

On Mon, 2008-02-04 at 15:24 -0500, Jeff Garzik wrote:
> James Bottomley wrote:
> > It's here in sr_ioctl.c:
> 
> Ah, indeed.  My grep-fu sucks today.
> 
> 
> > I'm not averse to simply nuking the printk ... it's probably valueless
> > in a modern kernel, since something dbussy is supposed to tell you to
> > put a CD in the drive, not something in the kernel.
> 
> The reverse...  dbussy/HAL is implementing autodetection of media 
> insertion, by polling ad infinitum.

Understood ... I meant the day of the user relying on a message from a
kernel printk to tell them they need a CD in the drive is long over.

James

Re: dmesg spam

[Andrew Morton]

On Mon, 04 Feb 2008 15:21:54 -0500
Jeff Garzik <jeff@garzik.org> wrote:

> James Bottomley wrote:
> > The message comes from sr_ioctl.c:sr_do_ioctl().  Which means some user
> > level application is poking the drive with a command that's returning
> > NOT_READY.  Apparently it will shut up if quiet is set in the packet
> > command structure.
> > 
> > It could be the application is getting the wrong idea of the status from
> > sr_do_staus() which leads it to send commands which require a medium?
> > But we'll need a bit of debugging to determine this.
> 
> 
> Userland polling of the cdrom is quite normal (if unfortunately), 
> regardless of medium presence.  Probably HAL or dbus.
> 
> In theory, the userland app should (a) set quiet and (b) handle 
> not-ready condition just fine.
> 
> I presume that (b) is ok, since not-ready just means to continue polling 
> the cdrom ad infinitum, until media appears.
> 
> A useful experiment, if only to confirm the obvious, would be to insert 
> some media.
> 
> What controller and device is in use?
> 

It's the thinkpad t61p.  Currently five miles away, powered off.  It's all
new Intel stuff iirc.

http://userweb.kernel.org/~akpm/dmesg-t61p.txt has some info but not the
right info afaict.

Bisection time I guess.  That'll be a new experience.

Re: dmesg spam

[Andrew Morton]

On Mon, 04 Feb 2008 14:44:18 -0600 James Bottomley <James.Bottomley@HansenPartnership.com> wrote:

> 
> On Mon, 2008-02-04 at 15:24 -0500, Jeff Garzik wrote:
> > James Bottomley wrote:
> > > It's here in sr_ioctl.c:
> > 
> > Ah, indeed.  My grep-fu sucks today.
> > 
> > 
> > > I'm not averse to simply nuking the printk ... it's probably valueless
> > > in a modern kernel, since something dbussy is supposed to tell you to
> > > put a CD in the drive, not something in the kernel.
> > 
> > The reverse...  dbussy/HAL is implementing autodetection of media 
> > insertion, by polling ad infinitum.
> 
> Understood ... I meant the day of the user relying on a message from a
> kernel printk to tell them they need a CD in the drive is long over.
> 

OK, sorry, I'm hopelessly full of it.  These messages also are produced by
2.6.24, 2.6.23 and 2.6.23.1-49.fc8.

I don't think anyone would miss this message were it to bite the D key.