Re: [BUG] 2.6.24-rc5: 'sysctl table check failed' when turning on printer

Re: [BUG] 2.6.24-rc5: 'sysctl table check failed' when turning on printer

[Eric W. Biederman]

Ingo Molnar <mingo@elte.hu> writes:

> Eric,
>
> you added these warnings, right?

Yes, and the particular warning that is triggering this is
the first time I have seen it.  I didn't know we had any
sysctl users that were buggy in attempting to create the
same file twice.


This sounds like we have a leak or a reference counting bug that
is registering the sysctl field twice.

My hunch is something is going wrong when loading or unloading
the module.

I only see the single instance of the string "timeslice" in
the kernel.  So it doesn't look like there are multiple
modules registering the same sysctl just a logic bug.

I took a quick look at drivers/char/ppdev.c but I don't
recognize the idiom so I can't spot where we are doing something
wrong. 

Looking in drivers/parport/procfs.c
parport_proc_register and parport_proc_unregister look fine adding a
sysctl entry when registering and removing it when unregistering.

Similarly looking in drivers/parport/share.c
parport_register_device and parport_unregister_device look fine.

The logic in ppdev though looks odd.  But not so odd I can
say it is broken or immediately recommend a fix.

The net result where we only have a file in /proc/sys when
you have opened the parallel port and run the right ioctl
is most definitely weird.

I took a quick skim through the git logs and it doesn't look like
anyone has done anything significant to ppdev.c in years.  So I don't
expect there is anyone who knows what that code is doing off their
head.

Currently the error handling appears robust it should
not prevent the printer from being used.

So it looks like my warnings have uncovered yet another
ancient sysctl usage bug.

If someone else doesn't figure out what is going wrong before
I get to it.  I will try and take a look and see if I can figure
out what is going wrong in ppdev.c.

Short of two programs coming in and simultaneously trying to claim
the parallel port and there being not exclusion in ppdev.c I don't
have a clue what could cause the reported error.

Eric

> (Resending as there were no replies on my first post mid December; issue
> is still there with -rc6.)
>
> This is the first time I've seen this error. Last time I used the printer 
> was with 2.6.24-rc3 and that time this error did not occur.
> The error occurs when I start a print job, not when I turn the printer on.
>
> System is Pentium D x86_64 kernel running Debian unstable.
> Printer is a HP Photosmart P1100 connected via parallel port.
>
> Not sure who should be CCed on this.
>
> ppdev0: registered pardevice
> sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl
> already exists
> Pid: 14491, comm: hpijs Not tainted 2.6.24-rc5 #1
>
> Call Trace:
>  [<ffffffff8024c0b0>] set_fail+0x3f/0x47
>  [<ffffffff8024c566>] sysctl_check_table+0x4ae/0x4fb
>  [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
>  [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
>  [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
>  [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
>  [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
>  [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
>  [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
>  [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
>  [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
>  [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
>  [<ffffffff8023ca15>] register_sysctl_table+0x52/0x9d
>  [<ffffffff881d97cb>] :parport:parport_device_proc_register+0xc3/0xe3
>  [<ffffffff881d7da7>] :parport:parport_register_device+0x206/0x267
>  [<ffffffff884171ae>] :ppdev:pp_irq+0x0/0x40
>  [<ffffffff8841774f>] :ppdev:pp_ioctl+0x13f/0x77c
>  [<ffffffff80296a11>] do_ioctl+0x55/0x6b
>  [<ffffffff80296c6a>] vfs_ioctl+0x243/0x25c
>  [<ffffffff80296cd4>] sys_ioctl+0x51/0x71
>  [<ffffffff8020beee>] system_call+0x7e/0x83
>
> Cheers,
> FJP
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>
> ----------

Re: [BUG] 2.6.24-rc5: 'sysctl table check failed' when turning on printer

[Frans Pop]

On Sunday 06 January 2008, Eric W. Biederman wrote:
> Short of two programs coming in and simultaneously trying to claim
> the parallel port and there being not exclusion in ppdev.c I don't
> have a clue what could cause the reported error.

That could well be the root cause as the full log shows:

Jan  6 01:21:02 faramir kernel: ppdev0: registered pardevice
Jan  6 01:21:03 faramir kernel: sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice  Sysctl already exists
Jan  6 01:21:03 faramir kernel: Pid: 11078, comm: hpijs Not tainted 2.6.24-rc6 #1
Jan  6 01:21:03 faramir kernel:
Jan  6 01:21:03 faramir kernel: Call Trace:
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c104>] set_fail+0x3f/0x47
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c5ba>] sysctl_check_table+0x4ae/0x4fb
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c0b6>] sysctl_check_lookup+0xc1/0xd0
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c5d0>] sysctl_check_table+0x4c4/0x4fb
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c0b6>] sysctl_check_lookup+0xc1/0xd0
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c5d0>] sysctl_check_table+0x4c4/0x4fb
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c0b6>] sysctl_check_lookup+0xc1/0xd0
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c5d0>] sysctl_check_table+0x4c4/0x4fb
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c0b6>] sysctl_check_lookup+0xc1/0xd0
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c5d0>] sysctl_check_table+0x4c4/0x4fb
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c0b6>] sysctl_check_lookup+0xc1/0xd0
Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c5d0>] sysctl_check_table+0x4c4/0x4fb
Jan  6 01:21:03 faramir kernel:  [<ffffffff8023ca8d>] register_sysctl_table+0x52/0x9d
Jan  6 01:21:03 faramir kernel:  [<ffffffff881ea7cb>] :parport:parport_device_proc_register+0xc3/0xe3
Jan  6 01:21:03 faramir kernel:  [<ffffffff881e8da7>] :parport:parport_register_device+0x206/0x267
Jan  6 01:21:03 faramir kernel:  [<ffffffff884151ae>] :ppdev:pp_irq+0x0/0x40
Jan  6 01:21:03 faramir kernel:  [<ffffffff8841574f>] :ppdev:pp_ioctl+0x13f/0x77c
Jan  6 01:21:03 faramir kernel:  [<ffffffff80296a55>] do_ioctl+0x55/0x6b
Jan  6 01:21:03 faramir kernel:  [<ffffffff80296cae>] vfs_ioctl+0x243/0x25c
Jan  6 01:21:03 faramir kernel:  [<ffffffff80296d18>] sys_ioctl+0x51/0x71
Jan  6 01:21:03 faramir kernel:  [<ffffffff8020beee>] system_call+0x7e/0x83
Jan  6 01:21:03 faramir kernel:
Jan  6 01:21:03 faramir kernel: ppdev0: registered pardevice
Jan  6 01:22:10 faramir kernel: ppdev0: released pardevice because user-space forgot
Jan  6 01:22:10 faramir kernel: ppdev0: unregistered pardevice
Jan  6 01:22:11 faramir kernel: ppdev0: unregistered pardevice
Jan  6 03:24:57 faramir kernel: fuse exit

Sorry for not providing that info earlier, but the first time I had this
issue I had two print jobs after eachother and because of that I overlooked
the double registering.

I am printing through CUPS on a fairly standard Debian unstable system
running the KDE desktop.

Re: [BUG] 2.6.24-rc5: 'sysctl table check failed' when turning on printer

[Eric W. Biederman]

Frans Pop <elendil@planet.nl> writes:

> On Sunday 06 January 2008, Eric W. Biederman wrote:
>> Short of two programs coming in and simultaneously trying to claim
>> the parallel port and there being not exclusion in ppdev.c I don't
>> have a clue what could cause the reported error.
>
> That could well be the root cause as the full log shows:

Ok.  Looking at it there is mutual exclusion for the parallel port
after we register.

So my guess is:

Two programs open the parellel port device.
The open goes through ppdev.c
ppdev.c uses the same name for both.
parport doesn't do any mutual exclusion (except for claim).
Everything except sysctl happens inside of the claim so we
haven't seen any other bugs.

So if my guess is right we need to move the register_sysctl_table
call into the claim logic.  And the unregister_syctl_table
call into the unclaim logic.

I've got to run.

Later,
Eric



> Jan  6 01:21:02 faramir kernel: ppdev0: registered pardevice
> Jan 6 01:21:03 faramir kernel: sysctl table check failed:
> /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
> Jan 6 01:21:03 faramir kernel: Pid: 11078, comm: hpijs Not tainted 2.6.24-rc6 #1
> Jan  6 01:21:03 faramir kernel:
> Jan  6 01:21:03 faramir kernel: Call Trace:
> Jan  6 01:21:03 faramir kernel:  [<ffffffff8024c104>] set_fail+0x3f/0x47
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c5ba>]
> sysctl_check_table+0x4ae/0x4fb
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c0b6>]
> sysctl_check_lookup+0xc1/0xd0
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c5d0>]
> sysctl_check_table+0x4c4/0x4fb
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c0b6>]
> sysctl_check_lookup+0xc1/0xd0
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c5d0>]
> sysctl_check_table+0x4c4/0x4fb
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c0b6>]
> sysctl_check_lookup+0xc1/0xd0
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c5d0>]
> sysctl_check_table+0x4c4/0x4fb
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c0b6>]
> sysctl_check_lookup+0xc1/0xd0
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c5d0>]
> sysctl_check_table+0x4c4/0x4fb
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c0b6>]
> sysctl_check_lookup+0xc1/0xd0
> Jan 6 01:21:03 faramir kernel: [<ffffffff8024c5d0>]
> sysctl_check_table+0x4c4/0x4fb
> Jan 6 01:21:03 faramir kernel: [<ffffffff8023ca8d>]
> register_sysctl_table+0x52/0x9d
> Jan 6 01:21:03 faramir kernel: [<ffffffff881ea7cb>]
> :parport:parport_device_proc_register+0xc3/0xe3
> Jan 6 01:21:03 faramir kernel: [<ffffffff881e8da7>]
> :parport:parport_register_device+0x206/0x267
> Jan  6 01:21:03 faramir kernel:  [<ffffffff884151ae>] :ppdev:pp_irq+0x0/0x40
> Jan 6 01:21:03 faramir kernel: [<ffffffff8841574f>] :ppdev:pp_ioctl+0x13f/0x77c
> Jan  6 01:21:03 faramir kernel:  [<ffffffff80296a55>] do_ioctl+0x55/0x6b
> Jan  6 01:21:03 faramir kernel:  [<ffffffff80296cae>] vfs_ioctl+0x243/0x25c
> Jan  6 01:21:03 faramir kernel:  [<ffffffff80296d18>] sys_ioctl+0x51/0x71
> Jan  6 01:21:03 faramir kernel:  [<ffffffff8020beee>] system_call+0x7e/0x83
> Jan  6 01:21:03 faramir kernel:
> Jan  6 01:21:03 faramir kernel: ppdev0: registered pardevice
> Jan 6 01:22:10 faramir kernel: ppdev0: released pardevice because user-space
> forgot
> Jan  6 01:22:10 faramir kernel: ppdev0: unregistered pardevice
> Jan  6 01:22:11 faramir kernel: ppdev0: unregistered pardevice
> Jan  6 03:24:57 faramir kernel: fuse exit
>
> Sorry for not providing that info earlier, but the first time I had this
> issue I had two print jobs after eachother and because of that I overlooked
> the double registering.
>
> I am printing through CUPS on a fairly standard Debian unstable system
> running the KDE desktop.

[BUG] 2.6.24-rc5: 'sysctl table check failed' when turning on printer

[Frans Pop]

(Resending as there were no replies on my first post mid December; issue
is still there with -rc6.)

This is the first time I've seen this error. Last time I used the printer 
was with 2.6.24-rc3 and that time this error did not occur.
The error occurs when I start a print job, not when I turn the printer on.

System is Pentium D x86_64 kernel running Debian unstable.
Printer is a HP Photosmart P1100 connected via parallel port.

Not sure who should be CCed on this.

ppdev0: registered pardevice
sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice  Sysctl already exists
Pid: 14491, comm: hpijs Not tainted 2.6.24-rc5 #1

Call Trace:
 [<ffffffff8024c0b0>] set_fail+0x3f/0x47
 [<ffffffff8024c566>] sysctl_check_table+0x4ae/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8023ca15>] register_sysctl_table+0x52/0x9d
 [<ffffffff881d97cb>] :parport:parport_device_proc_register+0xc3/0xe3
 [<ffffffff881d7da7>] :parport:parport_register_device+0x206/0x267
 [<ffffffff884171ae>] :ppdev:pp_irq+0x0/0x40
 [<ffffffff8841774f>] :ppdev:pp_ioctl+0x13f/0x77c
 [<ffffffff80296a11>] do_ioctl+0x55/0x6b
 [<ffffffff80296c6a>] vfs_ioctl+0x243/0x25c
 [<ffffffff80296cd4>] sys_ioctl+0x51/0x71
 [<ffffffff8020beee>] system_call+0x7e/0x83

Cheers,
FJP

[BUG] 2.6.24-rc5: 'sysctl table check failed' when turning on printer

[Frans Pop]

This is the first time I've seen this error. Last time I used the printer 
was with 2.6.24-rc3 and that time this error did not occur.

System is Pentium D x86_64 kernel running Debian unstable.
Printer is a HP Photosmart P1100 connected via parallel port.

Not sure who should be CCed on this.

ppdev0: registered pardevice
sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice  
Sysctl already exists
Pid: 14491, comm: hpijs Not tainted 2.6.24-rc5 #1

Call Trace:
 [<ffffffff8024c0b0>] set_fail+0x3f/0x47
 [<ffffffff8024c566>] sysctl_check_table+0x4ae/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8024c062>] sysctl_check_lookup+0xc1/0xd0
 [<ffffffff8024c57c>] sysctl_check_table+0x4c4/0x4fb
 [<ffffffff8023ca15>] register_sysctl_table+0x52/0x9d
 [<ffffffff881d97cb>] :parport:parport_device_proc_register+0xc3/0xe3
 [<ffffffff881d7da7>] :parport:parport_register_device+0x206/0x267
 [<ffffffff884171ae>] :ppdev:pp_irq+0x0/0x40
 [<ffffffff8841774f>] :ppdev:pp_ioctl+0x13f/0x77c
 [<ffffffff80296a11>] do_ioctl+0x55/0x6b
 [<ffffffff80296c6a>] vfs_ioctl+0x243/0x25c
 [<ffffffff80296cd4>] sys_ioctl+0x51/0x71
 [<ffffffff8020beee>] system_call+0x7e/0x83

Cheers,
FJP