[BUG: UML 2.6.11-rc4-bk-latest] sleeping function called from invalid context and segmentation fault

[BUG: UML 2.6.11-rc4-bk-latest] sleeping function called from invalid context and segmentation fault

[Anton Altaparmakov]

Hi,

I get a few Debug messages of the form from UML:

Debug: sleeping function called from invalid context at
include/asm/arch/semaphore.h:107
in_atomic():0, irqs_disabled():1
Call Trace:
087d77b0:  [<0809aaa5>] __might_sleep+0x135/0x180
087d77d8:  [<084d377f>] mcount+0xf/0x20
087d77e0:  [<0807cc13>] uml_console_write+0x33/0x80
087d7800:  [<080a2138>] __call_console_drivers+0x88/0xc0
087d7830:  [<080a2b9c>] release_console_sem+0x33c/0x5f0
087d7850:  [<080a3a69>] vprintk+0x309/0x5f0
087d7868:  [<084d377f>] mcount+0xf/0x20
087d78a0:  [<080a23f6>] printk+0x26/0x40
087d78b0:  [<081678a2>] d_splice_alias+0x2f2/0x3e0
087d78c0:  [<0807f272>] line_ioctl+0x102/0x120
087d78dc:  [<0807f170>] line_ioctl+0x0/0x120
087d78e0:  [<0807f17a>] line_ioctl+0xa/0x120
087d78f0:  [<0832b83d>] tty_ioctl+0x2bd/0x2a00
087d7930:  [<08073539>] get_signals+0x49/0xb0
087d7940:  [<08155fb1>] link_path_walk+0x1931/0x2580
087d7948:  [<081e3d00>] ext3_permission+0x0/0x30
087d7970:  [<0809115b>] os_window_size+0x2b/0x80
087d7990:  [<0807e5f2>] generic_window_size+0x32/0xb0
087d79c0:  [<0807d3cb>] chan_window_size+0x8b/0xa0
087d79e0:  [<080801b3>] line_open+0x93/0x240
087d7a10:  [<0807cb7c>] con_open+0x2c/0x40
087d7a30:  [<083293b2>] tty_open+0x332/0x750
087d7a58:  [<084d377f>] mcount+0xf/0x20
087d7a68:  [<08144e48>] exact_match+0x8/0x20
087d7a90:  [<08073218>] enable_mask+0x78/0xb0
087d7aa0:  [<0807331e>] set_signals+0xce/0x2a0
087d7ad0:  [<0815b49e>] do_ioctl+0x6e/0xe0
087d7b00:  [<0815b608>] vfs_ioctl+0xf8/0x960
087d7b40:  [<084d377f>] mcount+0xf/0x20
087d7b60:  [<0815becf>] sys_ioctl+0x5f/0xb0
087d7b74:  [<084d377f>] mcount+0xf/0x20
087d7b90:  [<0807b162>] execute_syscall_skas+0xc2/0xe0
087d7bb0:  [<0807b0ae>] execute_syscall_skas+0xe/0xe0
087d7be0:  [<0806fa1c>] syscall_trace+0xc/0x200
087d7c00:  [<084d377f>] mcount+0xf/0x20
087d7c20:  [<0807b1fb>] handle_syscall+0x5b/0xb0
087d7c30:  [<08093c52>] save_registers+0x42/0xb0
087d7c50:  [<0807a19d>] userspace+0x45d/0x6e0
087d7c78:  [<0807e000>] chan_interrupt+0x250/0x420
087d7cb0:  [<0809c8c1>] schedule_tail+0x21/0x100
087d7cc4:  [<08068250>] init+0x0/0x410
087d7cd0:  [<0807aed7>] new_thread_handler+0x117/0x190
087d7d20:  [<084c2358>] __restore+0x0/0x8
087d7d60:  [<084c2511>] kill+0x11/0x20

Most are coming via uml_console_write.  If interested you can get the
full UML console log (starting uml, logging in as root and shutting it
down again) here:

http://www-uxsup.csx.cam.ac.uk/~aia21/linux/uml/uml-console-log.txt

Also, once the UML has shutdown, the gnome-terminals (which I use
instead of xterm) do not disappear and I get the following segmentation
fault on the host:

vmlinux umid=uml0 mem=256m ubd0=ubd0 ubd1=/usr/src/ntfs_hdd10
eth0=tuntap,uml0,fe:fd:dd:f8:a6:4e ssl=none con=xterm
xterm=gnome-terminal,-t,-x root=/dev/ubda1
Set 'uml0' persistent and owned by uid 29847
Starting uml...
Checking for /proc/mm...found
Checking for the skas3 patch in the host...found
Checking PROT_EXEC mmap in /tmp...OK
 
/home/aia21/bin/my-start-uml: line 76:  9613 Segmentation
fault      /bin/bash -c "./$KERNEL $UML_ARGS $*"
Set 'uml0' nonpersistent

Best regards,

        Anton
-- 
Anton Altaparmakov <aia21 at cam.ac.uk> (replace at with @)
Unix Support, Computing Service, University of Cambridge, CB2 3QH, UK
Linux NTFS maintainer / IRC: #ntfs on irc.freenode.net
WWW: http://linux-ntfs.sf.net/ & http://www-stu.christs.cam.ac.uk/~aia21/

Re: [uml-devel] [BUG: UML 2.6.11-rc4-bk-latest] sleeping function called from invalid context and segmentation fault

[Blaisorblade]

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

On Monday 14 February 2005 12:48, Anton Altaparmakov wrote:
> Hi,
>
> I get a few Debug messages of the form from UML:
>
> Debug: sleeping function called from invalid context at
> include/asm/arch/semaphore.h:107
> in_atomic():0, irqs_disabled():1
> Call Trace:
> 087d77b0:  [<0809aaa5>] __might_sleep+0x135/0x180
> 087d77d8:  [<084d377f>] mcount+0xf/0x20
> 087d77e0:  [<0807cc13>] uml_console_write+0x33/0x80

> Most are coming via uml_console_write.
The problem is that the UML tty drivers use a semaphore instead of a spinlock 
for the locking, which also causes some other problems.

The attached patch should fix this, but I've not yet made sure it is not 
deadlock-prone (I didn't hit any during some very limited testing).

So it's not yet ready for 2.6.11.
-- 
Paolo Giarrusso, aka Blaisorblade
Linux registered user n. 292729
http://www.user-mode-linux.org/~blaisorblade

[-- Attachment #2: uml-console-redo-locking.patch --]
[-- Type: text/x-diff, Size: 8382 bytes --]



Signed-off-by: Paolo 'Blaisorblade' Giarrusso <blaisorblade@yahoo.it>
---

 linux-2.6.11-paolo/arch/um/drivers/line.c          |   49 +++++++++------------
 linux-2.6.11-paolo/arch/um/drivers/ssl.c           |   16 +-----
 linux-2.6.11-paolo/arch/um/drivers/stdio_console.c |   16 +-----
 linux-2.6.11-paolo/arch/um/include/line.h          |   16 ------
 4 files changed, 31 insertions(+), 66 deletions(-)

diff -puN arch/um/drivers/line.c~uml-console-redo-locking arch/um/drivers/line.c
--- linux-2.6.11/arch/um/drivers/line.c~uml-console-redo-locking	2005-02-07 19:16:49.954057296 +0100
+++ linux-2.6.11-paolo/arch/um/drivers/line.c	2005-02-07 19:16:49.969055016 +0100
@@ -52,6 +52,7 @@ static int write_room(struct line *dev)
 	return (n - 1);
 }
 
+/* Must be called while holding line->lock!*/
 static int buffer_data(struct line *line, const char *buf, int len)
 {
 	int end, room;
@@ -84,6 +85,7 @@ static int buffer_data(struct line *line
 	return(len);
 }
 
+/* Must be called while holding line->lock!*/
 static int flush_buffer(struct line *line)
 {
 	int n, count;
@@ -122,16 +124,13 @@ int line_write(struct tty_struct *tty, c
 
 	if(tty->stopped) return 0;
 
-	down(&line->sem);
-	if(line->head != line->tail){
-		local_irq_save(flags);
+	spin_lock_irqsave(&line->lock, flags);
+	if (line->head != line->tail){
 		ret = buffer_data(line, buf, len);
 		err = flush_buffer(line);
-		local_irq_restore(flags);
 		if(err <= 0)
 			ret = err;
-	}
-	else {
+	} else {
 		n = write_chan(&line->chan_list, buf, len, 
 			       line->driver->write_irq);
 		if(n < 0){
@@ -144,8 +143,8 @@ int line_write(struct tty_struct *tty, c
 		if(len > 0)
 			ret += buffer_data(line, buf + n, len);
 	}
- out_up:
-	up(&line->sem);
+out_up:
+	spin_unlock_irqrestore(&line->lock, flags);
 	return(ret);
 }
 
@@ -260,6 +259,7 @@ static irqreturn_t line_write_interrupt(
 	struct line *line = tty->driver_data;
 	int err;
 
+	spin_lock(&line->lock);
 	err = flush_buffer(line);
 	if(err == 0)
 		return(IRQ_NONE);
@@ -267,6 +267,7 @@ static irqreturn_t line_write_interrupt(
 		line->head = line->buffer;
 		line->tail = line->buffer;
 	}
+	spin_unlock(&line->lock);
 
 	if(tty == NULL)
 		return(IRQ_NONE);
@@ -336,7 +337,9 @@ int line_open(struct line *lines, struct
 	line = &lines[tty->index];
 	tty->driver_data = line;
 
-	down(&line->sem);
+	/* The IRQ which takes this lock is not yet enabled and won't be run
+	 * before the end, so we don't need to use spin_lock_irq.*/
+	spin_lock(&line->lock);
 	if (tty->count == 1) {
 		if (!line->valid) {
 			err = -ENODEV;
@@ -349,6 +352,7 @@ int line_open(struct line *lines, struct
 			err = open_chan(&line->chan_list);
 			if(err) goto out;
 		}
+		/* Here the interrupt is registered.*/
 		enable_chan(&line->chan_list, tty);
 		INIT_WORK(&line->task, line_timer_cb, tty);
 	}
@@ -362,7 +366,7 @@ int line_open(struct line *lines, struct
 	line->count++;
 
 out:
-	up(&line->sem);
+	spin_unlock(&line->lock);
 	return(err);
 }
 
@@ -370,13 +374,17 @@ void line_close(struct tty_struct *tty, 
 {
 	struct line *line = tty->driver_data;
 
-	down(&line->sem);
+	spin_lock_irq(&line->lock);
+
+	/* We ignore the error anyway! */
+	flush_buffer(line);
+
 	line->count--;
 	if (tty->count == 1) {
 		line_disable(tty, -1);
 		tty->driver_data = NULL;
 	}
-	up(&line->sem);
+	spin_unlock_irq(&line->lock);
 }
 
 void close_lines(struct line *lines, int nlines)
@@ -474,13 +482,13 @@ int line_get_config(char *name, struct l
 
 	line = &lines[dev];
 
-	down(&line->sem);
+	spin_lock(&line->lock);
 	if(!line->valid)
 		CONFIG_CHUNK(str, size, n, "none", 1);
 	else if(line->count == 0)
 		CONFIG_CHUNK(str, size, n, line->init_str, 1);
 	else n = chan_config_string(&line->chan_list, str, size, error_out);
-	up(&line->sem);
+	spin_unlock(&line->lock);
 
 	return(n);
 }
@@ -553,7 +561,7 @@ void lines_init(struct line *lines, int 
 	for(i = 0; i < nlines; i++){
 		line = &lines[i];
 		INIT_LIST_HEAD(&line->chan_list);
-		sema_init(&line->sem, 1);
+		spin_lock_init(&line->lock);
 		if(line->init_str != NULL){
 			line->init_str = uml_strdup(line->init_str);
 			if(line->init_str == NULL)
@@ -668,14 +676,3 @@ char *add_xterm_umid(char *base)
 	snprintf(title, len, "%s (%s)", base, umid);
 	return(title);
 }
-
-/*
- * Overrides for Emacs so that we follow Linus's tabbing style.
- * Emacs will notice this stuff at the end of the file and automatically
- * adjust the settings for this buffer only.  This must remain at the end
- * of the file.
- * ---------------------------------------------------------------------------
- * Local variables:
- * c-file-style: "linux"
- * End:
- */
diff -puN arch/um/include/line.h~uml-console-redo-locking arch/um/include/line.h
--- linux-2.6.11/arch/um/include/line.h~uml-console-redo-locking	2005-02-07 19:16:49.961056232 +0100
+++ linux-2.6.11-paolo/arch/um/include/line.h	2005-02-07 19:16:49.969055016 +0100
@@ -10,7 +10,7 @@
 #include "linux/workqueue.h"
 #include "linux/tty.h"
 #include "linux/interrupt.h"
-#include "asm/semaphore.h"
+#include "linux/spinlock.h"
 #include "chan_user.h"
 #include "mconsole_kern.h"
 
@@ -37,7 +37,7 @@ struct line {
 	struct list_head chan_list;
 	int valid;
 	int count;
-	struct semaphore sem;
+	spinlock_t lock;
 	char *buffer;
 	char *head;
 	char *tail;
@@ -52,7 +52,6 @@ struct line {
 	  init_pri :	INIT_STATIC, \
 	  chan_list : 	{ }, \
 	  valid :	1, \
-	  sem : 	{ }, \
 	  buffer :	NULL, \
 	  head :	NULL, \
 	  tail :	NULL, \
@@ -95,14 +94,3 @@ extern int line_get_config(char *dev, st
 			   int size, char **error_out);
 
 #endif
-
-/*
- * Overrides for Emacs so that we follow Linus's tabbing style.
- * Emacs will notice this stuff at the end of the file and automatically
- * adjust the settings for this buffer only.  This must remain at the end
- * of the file.
- * ---------------------------------------------------------------------------
- * Local variables:
- * c-file-style: "linux"
- * End:
- */
diff -puN arch/um/drivers/ssl.c~uml-console-redo-locking arch/um/drivers/ssl.c
--- linux-2.6.11/arch/um/drivers/ssl.c~uml-console-redo-locking	2005-02-07 19:16:49.963055928 +0100
+++ linux-2.6.11-paolo/arch/um/drivers/ssl.c	2005-02-07 19:16:49.970054864 +0100
@@ -171,10 +171,11 @@ static void ssl_console_write(struct con
 			      unsigned len)
 {
 	struct line *line = &serial_lines[c->index];
+	unsigned long flags;
 
-	down(&line->sem);
+	spin_lock_irqsave(&line->lock, flags);
 	console_write_chan(&line->chan_list, string, len);
-	up(&line->sem);
+	spin_unlock_irqrestore(&line->lock, flags);
 }
 
 static struct tty_driver *ssl_console_device(struct console *c, int *index)
@@ -238,14 +239,3 @@ static int ssl_chan_setup(char *str)
 
 __setup("ssl", ssl_chan_setup);
 __channel_help(ssl_chan_setup, "ssl");
-
-/*
- * Overrides for Emacs so that we follow Linus's tabbing style.
- * Emacs will notice this stuff at the end of the file and automatically
- * adjust the settings for this buffer only.  This must remain at the end
- * of the file.
- * ---------------------------------------------------------------------------
- * Local variables:
- * c-file-style: "linux"
- * End:
- */
diff -puN arch/um/drivers/stdio_console.c~uml-console-redo-locking arch/um/drivers/stdio_console.c
--- linux-2.6.11/arch/um/drivers/stdio_console.c~uml-console-redo-locking	2005-02-07 19:16:49.966055472 +0100
+++ linux-2.6.11-paolo/arch/um/drivers/stdio_console.c	2005-02-07 19:16:49.970054864 +0100
@@ -126,10 +126,11 @@ static void uml_console_write(struct con
 			  unsigned len)
 {
 	struct line *line = &vts[console->index];
+	unsigned long flags;
 
-	down(&line->sem);
+	spin_lock_irqsave(&line->lock, flags);
 	console_write_chan(&line->chan_list, string, len);
-	up(&line->sem);
+	spin_unlock_irqrestore(&line->lock, flags);
 }
 
 static struct tty_driver *uml_console_device(struct console *c, int *index)
@@ -192,14 +193,3 @@ static int console_chan_setup(char *str)
 }
 __setup("con", console_chan_setup);
 __channel_help(console_chan_setup, "con");
-
-/*
- * Overrides for Emacs so that we follow Linus's tabbing style.
- * Emacs will notice this stuff at the end of the file and automatically
- * adjust the settings for this buffer only.  This must remain at the end
- * of the file.
- * ---------------------------------------------------------------------------
- * Local variables:
- * c-file-style: "linux"
- * End:
- */
_

Re: [uml-devel] [BUG: UML 2.6.11-rc4-bk-latest] sleeping function called from invalid context and segmentation fault

[Anton Altaparmakov]

On Wed, 2005-02-16 at 19:35 +0100, Blaisorblade wrote:
> On Monday 14 February 2005 12:48, Anton Altaparmakov wrote:
> > Hi,
> >
> > I get a few Debug messages of the form from UML:
> >
> > Debug: sleeping function called from invalid context at
> > include/asm/arch/semaphore.h:107
> > in_atomic():0, irqs_disabled():1
> > Call Trace:
> > 087d77b0:  [<0809aaa5>] __might_sleep+0x135/0x180
> > 087d77d8:  [<084d377f>] mcount+0xf/0x20
> > 087d77e0:  [<0807cc13>] uml_console_write+0x33/0x80
> 
> > Most are coming via uml_console_write.
> The problem is that the UML tty drivers use a semaphore instead of a spinlock 
> for the locking, which also causes some other problems.
> 
> The attached patch should fix this, but I've not yet made sure it is not 
> deadlock-prone (I didn't hit any during some very limited testing).
> 
> So it's not yet ready for 2.6.11.

Trying with the above patch in now only get two "sleeping function
called from invalid context" warnings during boot and none during
running.  However I get a lot of those errors:

arch/um/drivers/line.c:262: spin_lock(arch/um/drivers/line.c:085b5900)
already locked by arch/um/drivers/line.c/262

Also both before and after the patch I see a lot of messages like:

kernel: line_write_room: tty2: no room left in buffer

Best regards,

        Anton
-- 
Anton Altaparmakov <aia21 at cam.ac.uk> (replace at with @)
Unix Support, Computing Service, University of Cambridge, CB2 3QH, UK
Linux NTFS maintainer / IRC: #ntfs on irc.freenode.net
WWW: http://linux-ntfs.sf.net/ & http://www-stu.christs.cam.ac.uk/~aia21/

Re: [uml-devel] [BUG: UML 2.6.11-rc4-bk-latest] sleeping function called from invalid context and segmentation fault

[Blaisorblade]

On Friday 18 February 2005 16:33, Anton Altaparmakov wrote:
> On Wed, 2005-02-16 at 19:35 +0100, Blaisorblade wrote:
> > On Monday 14 February 2005 12:48, Anton Altaparmakov wrote:
> > > Hi,
> > >
> > > I get a few Debug messages of the form from UML:
> > >
> > > Debug: sleeping function called from invalid context at
> > > include/asm/arch/semaphore.h:107
> > > in_atomic():0, irqs_disabled():1
> > > Call Trace:
> > > 087d77b0:  [<0809aaa5>] __might_sleep+0x135/0x180
> > > 087d77d8:  [<084d377f>] mcount+0xf/0x20
> > > 087d77e0:  [<0807cc13>] uml_console_write+0x33/0x80
> > >
> > > Most are coming via uml_console_write.
> >
> > The problem is that the UML tty drivers use a semaphore instead of a
> > spinlock for the locking, which also causes some other problems.
> >
> > The attached patch should fix this, but I've not yet made sure it is not
> > deadlock-prone (I didn't hit any during some very limited testing).
> >
> > So it's not yet ready for 2.6.11.
>
> Trying with the above patch in now only get two "sleeping function
> called from invalid context" warnings during boot and none during
> running.
I'll look at whether I can produce them... if it's no problem, post their 
traces anyway, please.
> However I get a lot of those errors: 
>
> arch/um/drivers/line.c:262: spin_lock(arch/um/drivers/line.c:085b5900)
> already locked by arch/um/drivers/line.c/262
Ok, I'll be looking into them ASAP (which infortunately means not very soon, 
sorry).

At a quick look, I see that line 262 is a "spin_lock" called by 
line_write_interrupt. I used spin_lock_irqsave everywhere else... but 
actually the interrupt must explicitly disable interrupts (I forgot) so, the 
simple answer seems to be using spin_lock_irqsave() would fix it. I cannot 
make a patch now.
> Also both before and after the patch I see a lot of messages like:
>
> kernel: line_write_room: tty2: no room left in buffer
I've never seen them... which is your test case?
Anyway, I'm not sure this is a needed warning: 

in include/linux/tty_driver.h, the .write_room member must tell the available 
space... it's reasonable that the TTY layer will call a flush_buffers 
function. However, looking at stdio_console, I'm seeing that, in fact, there 
is no flush_chars function(!!). I'll provide one ASAP.

-- 
Paolo Giarrusso, aka Blaisorblade
Linux registered user n. 292729
http://www.user-mode-linux.org/~blaisorblade

Re: [uml-devel] [BUG: UML 2.6.11-rc4-bk-latest] sleeping function called from invalid context and segmentation fault

[Blaisorblade]

On Tuesday 22 February 2005 21:41, Blaisorblade wrote:
> On Friday 18 February 2005 16:33, Anton Altaparmakov wrote:
> > On Wed, 2005-02-16 at 19:35 +0100, Blaisorblade wrote:
> > > On Monday 14 February 2005 12:48, Anton Altaparmakov wrote:
> > > > Hi,
> > > >
> > > > I get a few Debug messages of the form from UML:
> > > >
> > > > Debug: sleeping function called from invalid context at
> > > > include/asm/arch/semaphore.h:107
> > > > in_atomic():0, irqs_disabled():1
> > > > Call Trace:
> > > > 087d77b0:  [<0809aaa5>] __might_sleep+0x135/0x180
> > > > 087d77d8:  [<084d377f>] mcount+0xf/0x20
> > > > 087d77e0:  [<0807cc13>] uml_console_write+0x33/0x80
> > > >
> > > > Most are coming via uml_console_write.
> > >
> > > The problem is that the UML tty drivers use a semaphore instead of a
> > > spinlock for the locking, which also causes some other problems.
> > >
> > > The attached patch should fix this, but I've not yet made sure it is
> > > not deadlock-prone (I didn't hit any during some very limited testing).
> > >
> > > So it's not yet ready for 2.6.11.
> >
> > Trying with the above patch in now only get two "sleeping function
> > called from invalid context" warnings during boot and none during
> > running.
>
> I'll look at whether I can produce them... if it's no problem, post their
> traces anyway, please.
I'm not able... I *did* enable CONFIG_DEBUG_SPINLOCK and 
CONFIG_DEBUG_SPINLOCK_SLEEP, but still I don't get them.

Maybe I have not an interesting enough test case (or kobject debugging is 
flooding the dmesg ring buffer, which is doing too).

> > However I get a lot of those errors:
> >
> > arch/um/drivers/line.c:262: spin_lock(arch/um/drivers/line.c:085b5900)
> > already locked by arch/um/drivers/line.c/262
>
> Ok, I'll be looking into them ASAP (which infortunately means not very
> soon, sorry).

> At a quick look, I see that line 262 is a "spin_lock" called by
> line_write_interrupt. I used spin_lock_irqsave everywhere else... but
> actually the interrupt must explicitly disable interrupts (I forgot) so,
> the simple answer seems to be using spin_lock_irqsave() would fix it.
I've done this in the patch I'm working on. I've various stuff on the press, 
however it should go in for 2.6.12-rc1, I hope.
> I 
> cannot make a patch now.
>
> > Also both before and after the patch I see a lot of messages like:
> >
> > kernel: line_write_room: tty2: no room left in buffer

> I've never seen them... 
Ok, correction, I've seen a lot of these...
> Anyway, I'm not sure this is a needed warning:
>
> in include/linux/tty_driver.h, the .write_room member must tell the
> available space... it's reasonable that the TTY layer will call a
> flush_buffers function. However, looking at stdio_console, I'm seeing that,
> in fact, there is no flush_chars function(!!). I'll provide one ASAP.
I've not yet removed the warning in the patch, just to be a bit too careful. 
I'm providing a flush_chars and flush_buffers method.

That said, there must be something else going on... it is easy to get the 
"repeated chars" problem (cat a file is enough), which I thought linked to 
this: it's when some data is printed and re-printed many times...

, and everybody started noticing it just around 2.6.9 / 2.6.10. I'm not sure, 
but maybe something else is causing the problem...

I'm going to work on the ring-buffer handling too, so that I make sure the 
unusual code paths are also correct (which code paths are usual and which are 
unusual could have changed).
-- 
Paolo Giarrusso, aka Blaisorblade
Linux registered user n. 292729
http://www.user-mode-linux.org/~blaisorblade