[Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing

[Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing

[Markus Trippelsdorf]

Printing with CUPS is broken on the current git tree. Whenever I print a page
the job just sits in the CUPS queue showing "processing". But it never reaches
the printer.  (My CUPS version is 1.5.2. Filesystem is xfs.)

I've bisected this issue to:

commit 7157486541bffc0dfec912e21ae639b029dae3d3
Author: Miklos Szeredi <mszeredi@suse.cz>
Date:   Tue Jun 5 15:10:14 2012 +0200

    vfs: do_last(): common slow lookup
    
    Make the slow lookup part of O_CREAT and non-O_CREAT opens common.
    
    This allows atomic_open to be hooked into the slow lookup part.
    
    Signed-off-by: Miklos Szeredi <mszeredi@suse.cz>
    Signed-off-by: Al Viro <viro@zeniv.linux.org.uk>

`
-- 
Markus

Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing

[Al Viro]

On Sat, Jul 28, 2012 at 12:43:16PM +0200, Markus Trippelsdorf wrote:
> Printing with CUPS is broken on the current git tree. Whenever I print a page
> the job just sits in the CUPS queue showing "processing". But it never reaches
> the printer.  (My CUPS version is 1.5.2. Filesystem is xfs.)
> 
> I've bisected this issue to:
> 
> commit 7157486541bffc0dfec912e21ae639b029dae3d3
> Author: Miklos Szeredi <mszeredi@suse.cz>
> Date:   Tue Jun 5 15:10:14 2012 +0200
> 
>     vfs: do_last(): common slow lookup
>     
>     Make the slow lookup part of O_CREAT and non-O_CREAT opens common.
>     
>     This allows atomic_open to be hooked into the slow lookup part.
>     
>     Signed-off-by: Miklos Szeredi <mszeredi@suse.cz>
>     Signed-off-by: Al Viro <viro@zeniv.linux.org.uk>

Hmm...  Looking at that commit, we seem to have one change introduced by it.  Namely,
behaviour of open(path, O_EXCL) (note that O_EXCL without O_CREAT is an undefined
by POSIX and makes no damn sense anyway).

Could you try the patch below, just to make sure that I'm not misreading the
situation?  If that's really happening that way, it should spew a warning,
restore the old behaviour by removing that stray O_EXCL and, if it comes
from open(2)/openat(2), print the syscall arguments.

We'll need to restore the original behaviour anyway, undefined or no undefined,
but if we really catch CUPS doing that, we ought to report that as a bug to
whatever bugtracking system CUPS uses; at the very least, it's a portability
headache waiting to happen.

diff --git a/fs/open.c b/fs/open.c
index 8d2c897..20a3ceb 100644
--- a/fs/open.c
+++ b/fs/open.c
@@ -893,6 +893,9 @@ static inline int build_open_flags(int flags, umode_t mode, struct open_flags *o
 		op->intent |= LOOKUP_CREATE;
 		if (flags & O_EXCL)
 			op->intent |= LOOKUP_EXCL;
+	} else {
+		WARN_ON(flags & O_EXCL);
+		op->open_flag &= ~O_EXCL;
 	}
 
 	if (flags & O_DIRECTORY)
@@ -943,6 +946,10 @@ long do_sys_open(int dfd, const char __user *filename, int flags, umode_t mode)
 	int fd = PTR_ERR(tmp);
 
 	if (!IS_ERR(tmp)) {
+		if ((flags & O_EXCL) && !(flags & O_CREAT)) {
+			printk(KERN_ERR "WTF: open(\"%s\", %d)", filename, flags);
+		}
+				
 		fd = get_unused_fd_flags(flags);
 		if (fd >= 0) {
 			struct file *f = do_filp_open(dfd, tmp, &op, lookup);

Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing

[Markus Trippelsdorf]

On 2012.07.30 at 07:50 +0100, Al Viro wrote:
> On Sat, Jul 28, 2012 at 12:43:16PM +0200, Markus Trippelsdorf wrote:
> > Printing with CUPS is broken on the current git tree. Whenever I print a page
> > the job just sits in the CUPS queue showing "processing". But it never reaches
> > the printer.  (My CUPS version is 1.5.2. Filesystem is xfs.)
> > 
> > I've bisected this issue to:
> > 
> > commit 7157486541bffc0dfec912e21ae639b029dae3d3
> > Author: Miklos Szeredi <mszeredi@suse.cz>
> > Date:   Tue Jun 5 15:10:14 2012 +0200
> > 
> >     vfs: do_last(): common slow lookup
> >     
> >     Make the slow lookup part of O_CREAT and non-O_CREAT opens common.
> >     
> >     This allows atomic_open to be hooked into the slow lookup part.
> >     
> >     Signed-off-by: Miklos Szeredi <mszeredi@suse.cz>
> >     Signed-off-by: Al Viro <viro@zeniv.linux.org.uk>
> 
> Hmm...  Looking at that commit, we seem to have one change introduced by it.  Namely,
> behaviour of open(path, O_EXCL) (note that O_EXCL without O_CREAT is an undefined
> by POSIX and makes no damn sense anyway).
> 
> Could you try the patch below, just to make sure that I'm not misreading the
> situation?  If that's really happening that way, it should spew a warning,
> restore the old behaviour by removing that stray O_EXCL and, if it comes
> from open(2)/openat(2), print the syscall arguments.
> 
> We'll need to restore the original behaviour anyway, undefined or no undefined,
> but if we really catch CUPS doing that, we ought to report that as a bug to
> whatever bugtracking system CUPS uses; at the very least, it's a portability
> headache waiting to happen.

Looks like you're right. The first warning happens during startup. The last one
when I print a test page (which now succeeds).  
Thanks Al.

------------[ cut here ]------------
WARNING: at fs/open.c:899 do_sys_open+0x1e5/0x220()
Hardware name: System Product Name
Pid: 207, comm: X Not tainted 3.5.0-07078-gf7da9cd-dirty #199
Call Trace:
 [<ffffffff810555a4>] ? warn_slowpath_common+0x74/0xb0
 [<ffffffff810dd405>] ? do_sys_open+0x1e5/0x220
 [<ffffffff814a64a2>] ? system_call_fastpath+0x16/0x1b
---[ end trace 9a333bfb6a9cbe80 ]---
------------[ cut here ]------------
WARNING: at fs/open.c:899 do_sys_open+0x1e5/0x220()
Hardware name: System Product Name
Pid: 384, comm: usb Tainted: G        W    3.5.0-07078-gf7da9cd-dirty #199
Call Trace:
WTF: open("/dev/input/mice", 34946)
 [<ffffffff810555a4>] ? warn_slowpath_common+0x74/0xb0
 [<ffffffff810dd405>] ? do_sys_open+0x1e5/0x220
 [<ffffffff814a64a2>] ? system_call_fastpath+0x16/0x1b
---[ end trace 9a333bfb6a9cbe81 ]---
WTF: open("/dev/usblp0", 32898)
------------[ cut here ]------------
WARNING: at fs/open.c:899 do_sys_open+0x1e5/0x220()
Hardware name: System Product Name
Pid: 384, comm: usb Tainted: G        W    3.5.0-07078-gf7da9cd-dirty #199
Call Trace:
 [<ffffffff810555a4>] ? warn_slowpath_common+0x74/0xb0
 [<ffffffff810dd405>] ? do_sys_open+0x1e5/0x220
 [<ffffffff814a64a2>] ? system_call_fastpath+0x16/0x1b
---[ end trace 9a333bfb6a9cbe82 ]---
------------[ cut here ]------------
WARNING: at fs/open.c:899 do_sys_open+0x1e5/0x220()
Hardware name: System Product Name
Pid: 87, comm: cupsd Tainted: G        W    3.5.0-07078-gf7da9cd-dirty #199
Call Trace:
WTF: open("/dev/usb/lp0", 32898)
 [<ffffffff810555a4>] ? warn_slowpath_common+0x74/0xb0
 [<ffffffff810dd405>] ? do_sys_open+0x1e5/0x220
 [<ffffffff814a64a2>] ? system_call_fastpath+0x16/0x1b
---[ end trace 9a333bfb6a9cbe83 ]---


-- 
Markus

Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing

[Al Viro]

On Mon, Jul 30, 2012 at 09:10:23AM +0200, Markus Trippelsdorf wrote:
> 
> Looks like you're right. The first warning happens during startup. The last one
> when I print a test page (which now succeeds).  
> Thanks Al.

> WTF: open("/dev/input/mice", 34946)
> WTF: open("/dev/usblp0", 32898)
> WTF: open("/dev/usb/lp0", 32898)

Ahhh...  OK, yes - it's the case we had missed (and where the manpage
needs correction, BTW).  O_EXCL for *devices* has additional semantics;
it's not "fail if exists", it's "fail if already opened by somebody".
No need to pester CUPS folks (except that I really hope that this
open of /dev/input/mice does *not* come from them)...

All right, the proper fix is *not* removing O_EXCL from flags; we want
it to reach ->f_flags, so that device open would work correctly.  I think
we need this, but I wonder if that's all; ->atomic_open() instances
might need to be corrected as well.  I've pushed this into for-next/for-linus
for now:

commit f8310c59201b183ebee2e3fe0c7242f5729be0af
Author: Al Viro <viro@zeniv.linux.org.uk>
Date:   Mon Jul 30 11:50:30 2012 +0400

    fix O_EXCL handling for devices
    
    O_EXCL without O_CREAT has different semantics; it's "fail if already opened",
    not "fail if already exists".  commit 71574865 broke that...
    
    Signed-off-by: Al Viro <viro@zeniv.linux.org.uk>

diff --git a/fs/namei.c b/fs/namei.c
index 618d353..e133bf3 100644
--- a/fs/namei.c
+++ b/fs/namei.c
@@ -2418,7 +2418,7 @@ static int atomic_open(struct nameidata *nd, struct dentry *dentry,
 	if ((open_flag & O_CREAT) && !IS_POSIXACL(dir))
 		mode &= ~current_umask();
 
-	if (open_flag & O_EXCL) {
+	if ((open_flag & (O_EXCL | O_CREAT)) == (O_EXCL | O_CREAT)) {
 		open_flag &= ~O_TRUNC;
 		*opened |= FILE_CREATED;
 	}
@@ -2742,7 +2742,7 @@ retry_lookup:
 	}
 
 	error = -EEXIST;
-	if (open_flag & O_EXCL)
+	if ((open_flag & (O_EXCL | O_CREAT)) == (O_EXCL | O_CREAT))
 		goto exit_dput;
 
 	error = follow_managed(path, nd->flags);

Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing

[Markus Trippelsdorf]

On 2012.07.30 at 08:56 +0100, Al Viro wrote:
> On Mon, Jul 30, 2012 at 09:10:23AM +0200, Markus Trippelsdorf wrote:
> > 
> > Looks like you're right. The first warning happens during startup. The last one
> > when I print a test page (which now succeeds).  
> > Thanks Al.
> 
> > WTF: open("/dev/input/mice", 34946)
> > WTF: open("/dev/usblp0", 32898)
> > WTF: open("/dev/usb/lp0", 32898)
> 
> Ahhh...  OK, yes - it's the case we had missed (and where the manpage
> needs correction, BTW).  O_EXCL for *devices* has additional semantics;
> it's not "fail if exists", it's "fail if already opened by somebody".
> No need to pester CUPS folks (except that I really hope that this
> open of /dev/input/mice does *not* come from them)...

I've omitted some WTF's from my former reply, because they happend after
I've sent it.

Jul 30 09:06:51 x4 kernel: ------------[ cut here ]------------
Jul 30 09:06:51 x4 kernel: WARNING: at fs/open.c:899 do_sys_open+0x1e5/0x220()
Jul 30 09:06:51 x4 kernel: Hardware name: System Product Name
Jul 30 09:06:51 x4 kernel: Pid: 87, comm: cupsd Tainted: G        W    3.5.0-07078-gf7da9cd-dirty #199
Jul 30 09:06:51 x4 kernel: Call Trace:
Jul 30 09:06:51 x4 kernel: WTF: open("/dev/usb/lp0", 32898)
Jul 30 09:06:51 x4 kernel: [<ffffffff810555a4>] ? warn_slowpath_common+0x74/0xb0
Jul 30 09:06:51 x4 kernel: [<ffffffff810dd405>] ? do_sys_open+0x1e5/0x220
Jul 30 09:06:51 x4 kernel: [<ffffffff814a64a2>] ? system_call_fastpath+0x16/0x1b
Jul 30 09:06:51 x4 kernel: ---[ end trace 9a333bfb6a9cbe83 ]---
Jul 30 09:07:19 x4 kernel: WTF: open("/var/spool/cups/a00018", 32897)
Jul 30 09:07:19 x4 kernel: ------------[ cut here ]------------
Jul 30 09:07:19 x4 kernel: WARNING: at fs/open.c:899 do_sys_open+0x1e5/0x220()
Jul 30 09:07:19 x4 kernel: Hardware name: System Product Name
Jul 30 09:07:19 x4 kernel: Pid: 87, comm: cupsd Tainted: G        W    3.5.0-07078-gf7da9cd-dirty #199
Jul 30 09:07:19 x4 kernel: Call Trace:
Jul 30 09:07:19 x4 kernel: [<ffffffff810555a4>] ? warn_slowpath_common+0x74/0xb0
Jul 30 09:07:19 x4 kernel: [<ffffffff810dd405>] ? do_sys_open+0x1e5/0x220
Jul 30 09:07:19 x4 kernel: [<ffffffff814a64a2>] ? system_call_fastpath+0x16/0x1b
Jul 30 09:07:19 x4 kernel: ---[ end trace 9a333bfb6a9cbe84 ]---
Jul 30 09:30:40 x4 kernel: WTF: open("/var/cache/cups/job.cache.O", 32897)
Jul 30 09:30:40 x4 kernel: ------------[ cut here ]------------
Jul 30 09:30:40 x4 kernel: WARNING: at fs/open.c:899 do_sys_open+0x1e5/0x220()
Jul 30 09:30:40 x4 kernel: Hardware name: System Product Name
Jul 30 09:30:40 x4 kernel: Pid: 87, comm: cupsd Tainted: G        W    3.5.0-07078-gf7da9cd-dirty #199
Jul 30 09:30:40 x4 kernel: Call Trace:
Jul 30 09:30:40 x4 kernel: [<ffffffff810555a4>] ? warn_slowpath_common+0x74/0xb0
Jul 30 09:30:40 x4 kernel: [<ffffffff810dd405>] ? do_sys_open+0x1e5/0x220
Jul 30 09:30:40 x4 kernel: [<ffffffff814a64a2>] ? system_call_fastpath+0x16/0x1b
Jul 30 09:30:40 x4 kernel: ---[ end trace 9a333bfb6a9cbe85 ]---

/var/spool/cups/a00018 & /var/cache/cups/job.cache.O are not devices AFAICS.

-- 
Markus

Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing

[Al Viro]

On Mon, Jul 30, 2012 at 10:05:36AM +0200, Markus Trippelsdorf wrote:
> On 2012.07.30 at 08:56 +0100, Al Viro wrote:
> > On Mon, Jul 30, 2012 at 09:10:23AM +0200, Markus Trippelsdorf wrote:
> > > 
> > > Looks like you're right. The first warning happens during startup. The last one
> > > when I print a test page (which now succeeds).  
> > > Thanks Al.
> > 
> > > WTF: open("/dev/input/mice", 34946)
> > > WTF: open("/dev/usblp0", 32898)
> > > WTF: open("/dev/usb/lp0", 32898)
> > 
> > Ahhh...  OK, yes - it's the case we had missed (and where the manpage
> > needs correction, BTW).  O_EXCL for *devices* has additional semantics;
> > it's not "fail if exists", it's "fail if already opened by somebody".
> > No need to pester CUPS folks (except that I really hope that this
> > open of /dev/input/mice does *not* come from them)...
> 
> I've omitted some WTF's from my former reply, because they happend after
> I've sent it.

> Jul 30 09:07:19 x4 kernel: WTF: open("/var/spool/cups/a00018", 32897)
> Jul 30 09:30:40 x4 kernel: WTF: open("/var/cache/cups/job.cache.O", 32897)

> /var/spool/cups/a00018 & /var/cache/cups/job.cache.O are not devices AFAICS.

Yecch...  AFAICS, there's a couple of places in CUPS likely to do that -
cupsGetFile() and cupsdRemoveFile(); this seems to be the former.  In the best
case there's enough locking to make that a piece of harmless cargo-cult
programming.  In the worst...