2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Vegard Nossum]

Hi,

First the confessions: It's fedora-patched kernel, 2.6.25.11-97.fc9,
tainted by NVIDIA driver. So feel free to drop to /dev/null until I
can reproduce on a clean and recent kernel. (But -rc3 didn't boot for
me, and I don't have anything else handy atm.)

By bashing on random device nodes (with mknod + mmap as root), I got a
few messages of this kind:

idr_remove called for id=236 which is not allocated.
Pid: 3019, comm: a.out Tainted: P         2.6.25.11-97.fc9.i686 #1
 [<c04f030c>] idr_remove+0xd5/0x138
 [<c0540bfc>] release_dev+0x5bd/0x5cf
 [<c04909fd>] ? d_free+0x3b/0x4d
 [<c04955d0>] ? mntput_no_expire+0x16/0x69
 [<c048309d>] ? __fput+0x149/0x151
 [<c0540d8c>] tty_release+0x12/0x1c
 [<c0483001>] __fput+0xad/0x151
 [<c04830bc>] fput+0x17/0x19
 [<c04807df>] filp_close+0x50/0x5a
 [<c0480852>] sys_close+0x69/0xa1
 [<c0405bf2>] syscall_call+0x7/0xb
 [<c0620000>] ? agp_amd64_probe+0x134/0x3ee
 =======================

idr_remove called for id=127 which is not allocated.
Pid: 3019, comm: a.out Tainted: P         2.6.25.11-97.fc9.i686 #1
 [<c04f030c>] idr_remove+0xd5/0x138
 [<c0540bfc>] release_dev+0x5bd/0x5cf
 [<c04909fd>] ? d_free+0x3b/0x4d
 [<c04955d0>] ? mntput_no_expire+0x16/0x69
 [<c048309d>] ? __fput+0x149/0x151
 [<c0540d8c>] tty_release+0x12/0x1c
 [<c0483001>] __fput+0xad/0x151
 [<c04830bc>] fput+0x17/0x19
 [<c04807df>] filp_close+0x50/0x5a
 [<c0480852>] sys_close+0x69/0xa1
 [<c0405bf2>] syscall_call+0x7/0xb
 =======================

It looks scary. Or is it purely my own fault?

Thanks,


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

Re: 2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Alan Cox]

> idr_remove called for id=236 which is not allocated.
> Pid: 3019, comm: a.out Tainted: P         2.6.25.11-97.fc9.i686 #1
>  [<c04f030c>] idr_remove+0xd5/0x138

There were (and probably are) tty races and there might be some more so
I'd actually be interested to know if its repeatable and if you can
provide the test code that triggers it.

Could be nVidiot stuff but quite frankly it looks like a quite believable
real pty layer race in areas of code that were touched recently.

Alan

Re: 2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Vegard Nossum]

On Fri, Aug 15, 2008 at 5:11 PM, Vegard Nossum <vegard.nossum@gmail.com> wrote:
> Hi,
>
> First the confessions: It's fedora-patched kernel, 2.6.25.11-97.fc9,
> tainted by NVIDIA driver. So feel free to drop to /dev/null until I
> can reproduce on a clean and recent kernel. (But -rc3 didn't boot for
> me, and I don't have anything else handy atm.)

I did get -rc3 working with some command line options.

>
> By bashing on random device nodes (with mknod + mmap as root), I got a
> few messages of this kind:
>
> idr_remove called for id=236 which is not allocated.
> Pid: 3019, comm: a.out Tainted: P         2.6.25.11-97.fc9.i686 #1
>  [<c04f030c>] idr_remove+0xd5/0x138
>  [<c0540bfc>] release_dev+0x5bd/0x5cf
>  [<c04909fd>] ? d_free+0x3b/0x4d
>  [<c04955d0>] ? mntput_no_expire+0x16/0x69
>  [<c048309d>] ? __fput+0x149/0x151
>  [<c0540d8c>] tty_release+0x12/0x1c
>  [<c0483001>] __fput+0xad/0x151
>  [<c04830bc>] fput+0x17/0x19
>  [<c04807df>] filp_close+0x50/0x5a
>  [<c0480852>] sys_close+0x69/0xa1
>  [<c0405bf2>] syscall_call+0x7/0xb
>  [<c0620000>] ? agp_amd64_probe+0x134/0x3ee
>  =======================

Now it looks more like this (with very frequent messages):

ida_remove called for id=112 which is not allocated.
ida_remove called for id=67 which is not allocated.
ida_remove called for id=191 which is not allocated.
ida_remove called for id=23 which is not allocated.

..and with no backtrace, so I guess it means "not harmful". Sorry for the noise.


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

Re: 2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Alan Cox]

> ida_remove called for id=112 which is not allocated.
> ida_remove called for id=67 which is not allocated.
> ida_remove called for id=191 which is not allocated.
> ida_remove called for id=23 which is not allocated.
> 
> ..and with no backtrace, so I guess it means "not harmful". Sorry for the noise.

Thats definitely not good and wants digging into further.

Re: 2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Vegard Nossum]

[-- Attachment #1: Type: text/plain, Size: 915 bytes --]

On Fri, Aug 15, 2008 at 5:28 PM, Alan Cox <alan@lxorguk.ukuu.org.uk> wrote:
>> ida_remove called for id=112 which is not allocated.
>> ida_remove called for id=67 which is not allocated.
>> ida_remove called for id=191 which is not allocated.
>> ida_remove called for id=23 which is not allocated.
>>
>> ..and with no backtrace, so I guess it means "not harmful". Sorry for the noise.
>
> Thats definitely not good and wants digging into further.
>

Okay!

I've attached my program. On 2.6.27-rc3 the message appears at least a
couple of times per second, so you should have no trouble in
reproducing it. On the 2.6.25 I get it maybe once a minute.

Compile with: gcc -std=gnu99


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: mknod.c --]
[-- Type: text/x-csrc; name=mknod.c, Size: 1804 bytes --]

#include <sys/mman.h>
#include <sys/stat.h>
#include <sys/types.h>

#include <fcntl.h>
#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <unistd.h>

#ifdef CONFIG_LOGGING
static FILE *logfile;
#endif

static const char *devname = "/tmp/dev";

static void do_one(mode_t mode, unsigned int maj, unsigned int min)
{
#if CONFIG_LOGGING
	fprintf(logfile, "%d, %d\n", maj, min);
	fflush(logfile);
	fsync(fileno(logfile));
#endif

	if (mknod(devname, mode | 0644, makedev(maj, min)) == -1)
		return;

	int fd = open(devname, O_RDONLY, 0644);
	if (fd == -1)
		goto ret_mknod;

	char *ptr = mmap(NULL, getpagesize(), PROT_READ, MAP_SHARED | MAP_ANONYMOUS, fd, 0);
	if (ptr == MAP_FAILED)
		goto ret_open;

	munmap(ptr, getpagesize());

ret_open:
	close(fd);
ret_mknod:
	unlink(devname);
}

static void do_both(unsigned int maj, unsigned int min)
{
	do_one(S_IFCHR, maj, min);
	do_one(S_IFBLK, maj, min);
}

static int blacklisted(unsigned int maj, unsigned int min)
{
	/* Watchdog; will kill the system anyway */
	if (maj == 10) {
		if (min == 130)
			return 1;
		if (min >= 212 && min <= 215)
			return 1;
	}

	return 0;
}

int
main(int argc, char *argv[])
{
#ifdef CONFIG_LOGGING
	logfile = fopen("mknod-logfile.txt", "w");
	if (!logfile)
		exit(EXIT_FAILURE);
#endif

	unlink(devname);

// XXX
#ifndef CONFIG_RANDOMIZE
	srand(time(NULL));
	srand(getpid() * rand());

	while (1) {
		unsigned int i = rand() % 256;
		unsigned int j = rand() % 256;

		if (blacklisted(i, j))
			continue;

		do_both(i, j);
	}
#else
	for (unsigned int i = 0; i < 128; ++i) {
		printf("maj: %d\n", i);

		for (unsigned int j = 0; j < 128; ++j) {
			if (blacklisted(i, j))
				continue;

			do_both(i, j);
		}
	}
	doit(S_IFCHR, 10, 130);
#endif

#ifdef CONFIG_LOGGING
	fclose(logfile);
#endif
	return EXIT_SUCCESS;
}

Re: 2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Vegard Nossum]

On Fri, Aug 15, 2008 at 5:28 PM, Alan Cox <alan@lxorguk.ukuu.org.uk> wrote:
>> ida_remove called for id=112 which is not allocated.
>> ida_remove called for id=67 which is not allocated.
>> ida_remove called for id=191 which is not allocated.
>> ida_remove called for id=23 which is not allocated.
>>
>> ..and with no backtrace, so I guess it means "not harmful". Sorry for the noise.
>
> Thats definitely not good and wants digging into further.

Hi,

I've now been digging. This reproduces it accurately:

# mknod fubar c 128 42
# cat fubar
<ctrl-c>

idr_remove called for id=42 which is not allocated.

Major nr. 128 is UNIX98_PTY_MASTER_MAJOR. The
Documentation/devices.txt tells us to access these through /dev/ptmx
only. So when we don't follow that rule, tty_open() is called instead
of ptmx_open() when the device is opened. ptmx_open() would allocate a
new id to use. But since we call tty_open(), it will use tty->index
which is set from get_tty_driver() -- calculated using the minor
number that we provided!

The only thing I don't understand is why we don't get _two_ errors on
close() -- I would expect to get one for the slave too. But maybe the
slave is never created. What do you think of this theory?


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

Re: 2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Alan Cox]

On Fri, 15 Aug 2008 23:26:28 +0200
"Vegard Nossum" <vegard.nossum@gmail.com> wrote:

> On Fri, Aug 15, 2008 at 5:28 PM, Alan Cox <alan@lxorguk.ukuu.org.uk> wrote:
> >> ida_remove called for id=112 which is not allocated.
> >> ida_remove called for id=67 which is not allocated.
> >> ida_remove called for id=191 which is not allocated.
> >> ida_remove called for id=23 which is not allocated.
> >>
> >> ..and with no backtrace, so I guess it means "not harmful". Sorry for the noise.
> >
> > Thats definitely not good and wants digging into further.
> 
> Hi,
> 
> I've now been digging. This reproduces it accurately:
> 
> # mknod fubar c 128 42
> # cat fubar
> <ctrl-c>
> 
> idr_remove called for id=42 which is not allocated.

pty: If the administrator creates a device not for a ptmx slave don't error

From: Alan Cox <alan@redhat.com>


The open path for ptmx slaves is via the ptmx device. Opening them any
other way is not allowed. Vegard Nossum found that previously this was not
the case and mknod foo c 128 42; cat foo would produce nasty diagnostics
---

 drivers/char/tty_io.c |   19 +++++++++++++------
 1 files changed, 13 insertions(+), 6 deletions(-)


diff --git a/drivers/char/tty_io.c b/drivers/char/tty_io.c
index 53b62c4..430c266 100644
--- a/drivers/char/tty_io.c
+++ b/drivers/char/tty_io.c
@@ -1217,7 +1217,8 @@ static void tty_line_name(struct tty_driver *driver, int index, char *p)
  *	init_dev		-	initialise a tty device
  *	@driver: tty driver we are opening a device on
  *	@idx: device index
- *	@tty: returned tty structure
+ *	@ret_tty: returned tty structure
+ *	@first_ok: ok to open a new device (used by ptmx)
  *
  *	Prepare a tty device. This may not be a "new" clean device but
  *	could also be an active device. The pty drivers require special
@@ -1238,7 +1239,7 @@ static void tty_line_name(struct tty_driver *driver, int index, char *p)
  */
 
 static int init_dev(struct tty_driver *driver, int idx,
-	struct tty_struct **ret_tty)
+	struct tty_struct **ret_tty, int first_ok)
 {
 	struct tty_struct *tty, *o_tty;
 	struct ktermios *tp, **tp_loc, *o_tp, **o_tp_loc;
@@ -1269,6 +1270,12 @@ static int init_dev(struct tty_driver *driver, int idx,
 	}
 	if (tty) goto fast_track;
 
+	if (driver->subtype == PTY_TYPE_MASTER &&
+		(driver->flags & TTY_DRIVER_DEVPTS_MEM) && !first_ok) {
+		printk("SLAP\n");
+		retval = -EIO;
+		goto end_init;
+	}
 	/*
 	 * First time open is complex, especially for PTY devices.
 	 * This code guarantees that either everything succeeds and the
@@ -1403,7 +1410,7 @@ static int init_dev(struct tty_driver *driver, int idx,
 
 	if (retval)
 		goto release_mem_out;
-	 goto success;
+	goto success;
 
 	/*
 	 * This fast open can be used if the tty is already open.
@@ -1785,7 +1792,7 @@ static void release_dev(struct file *filp)
 }
 
 /**
- *	tty_open		-	open a tty device
+ *	__tty_open		-	open a tty device
  *	@inode: inode of device file
  *	@filp: file pointer to tty
  *
@@ -1864,7 +1871,7 @@ retry_open:
 		return -ENODEV;
 	}
 got_driver:
-	retval = init_dev(driver, index, &tty);
+	retval = init_dev(driver, index, &tty, 0);
 	mutex_unlock(&tty_mutex);
 	if (retval)
 		return retval;
@@ -1961,7 +1968,7 @@ static int __ptmx_open(struct inode *inode, struct file *filp)
 		return index;
 
 	mutex_lock(&tty_mutex);
-	retval = init_dev(ptm_driver, index, &tty);
+	retval = init_dev(ptm_driver, index, &tty, 1);
 	mutex_unlock(&tty_mutex);
 
 	if (retval)

Re: 2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Vegard Nossum]

On Tue, Aug 19, 2008 at 12:15 AM, Alan Cox <alan@lxorguk.ukuu.org.uk> wrote:
> pty: If the administrator creates a device not for a ptmx slave don't error
>
> From: Alan Cox <alan@redhat.com>
>
>
> The open path for ptmx slaves is via the ptmx device. Opening them any
> other way is not allowed. Vegard Nossum found that previously this was not
> the case and mknod foo c 128 42; cat foo would produce nasty diagnostics
> ---

Thanks, this seems to work for me. I do get a "SLAP" in dmesg each
time, however :-)


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

Re: 2.6.25.11-97.fc9 (P): idr_remove called for id=236 which is not allocated

[Alan Cox]

> > The open path for ptmx slaves is via the ptmx device. Opening them any
> > other way is not allowed. Vegard Nossum found that previously this was not
> > the case and mknod foo c 128 42; cat foo would produce nasty diagnostics
> > ---
> 
> Thanks, this seems to work for me. I do get a "SLAP" in dmesg each
> time, however :-)

Thanks - pushed to -next (without the printk)