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

[Markus Trippelsdorf <markus@trippelsdorf.de>]

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