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

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 <[email protected]>
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.

`

Markus

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.

index 8d2c897..20a3ceb 100644
@@ -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);

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

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 <[email protected]>
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...

index 618d353..e133bf3 100644
@@ -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);

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

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...