* [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing
@ 2012-07-28 10:43 Markus Trippelsdorf
2012-07-30 6:50 ` Al Viro
0 siblings, 1 reply; 6+ messages in thread
From: Markus Trippelsdorf @ 2012-07-28 10:43 UTC (permalink / raw)
To: linux-kernel; +Cc: Miklos Szeredi, Al Viro
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
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing 2012-07-28 10:43 [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing Markus Trippelsdorf @ 2012-07-30 6:50 ` Al Viro 2012-07-30 7:10 ` Markus Trippelsdorf 0 siblings, 1 reply; 6+ messages in thread From: Al Viro @ 2012-07-30 6:50 UTC (permalink / raw) To: Markus Trippelsdorf; +Cc: linux-kernel, Miklos Szeredi 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); ^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing 2012-07-30 6:50 ` Al Viro @ 2012-07-30 7:10 ` Markus Trippelsdorf 2012-07-30 7:56 ` Al Viro 0 siblings, 1 reply; 6+ messages in thread From: Markus Trippelsdorf @ 2012-07-30 7:10 UTC (permalink / raw) To: Al Viro; +Cc: linux-kernel, Miklos Szeredi 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 ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing 2012-07-30 7:10 ` Markus Trippelsdorf @ 2012-07-30 7:56 ` Al Viro 2012-07-30 8:05 ` Markus Trippelsdorf 0 siblings, 1 reply; 6+ messages in thread From: Al Viro @ 2012-07-30 7:56 UTC (permalink / raw) To: Markus Trippelsdorf; +Cc: linux-kernel, Miklos Szeredi 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); ^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing 2012-07-30 7:56 ` Al Viro @ 2012-07-30 8:05 ` Markus Trippelsdorf 2012-07-30 8:26 ` Al Viro 0 siblings, 1 reply; 6+ messages in thread From: Markus Trippelsdorf @ 2012-07-30 8:05 UTC (permalink / raw) To: Al Viro; +Cc: linux-kernel, Miklos Szeredi 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 ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing 2012-07-30 8:05 ` Markus Trippelsdorf @ 2012-07-30 8:26 ` Al Viro 0 siblings, 0 replies; 6+ messages in thread From: Al Viro @ 2012-07-30 8:26 UTC (permalink / raw) To: Markus Trippelsdorf; +Cc: linux-kernel, Miklos Szeredi 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... ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2012-07-30 8:26 UTC | newest] Thread overview: 6+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2012-07-28 10:43 [Bisected] commit 71574865 (vfs: do_last(): common slow lookup) breaks CUPS printing Markus Trippelsdorf 2012-07-30 6:50 ` Al Viro 2012-07-30 7:10 ` Markus Trippelsdorf 2012-07-30 7:56 ` Al Viro 2012-07-30 8:05 ` Markus Trippelsdorf 2012-07-30 8:26 ` Al Viro
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox