Re: iov_iter_pipe warning.

[Al Viro]

On Tue, Apr 11, 2017 at 10:29:11PM -0400, Dave Jones wrote:
> On Wed, Apr 12, 2017 at 02:15:32AM +0100, Al Viro wrote:
>  > On Tue, Apr 11, 2017 at 08:58:53PM -0400, Dave Jones wrote:
>  > > [  462.696557] in->f_op = ffffffffa02df980, ->splice_write = ffffffff812b2b20
>  > > $ grep ffffffffa02df980 /proc/kallsyms 
>  > > ffffffffa02df980 r nfs4_file_operations	[nfsv4]
>  > > $ grep ffffffff812b2b20 /proc/kallsyms 
>  > > ffffffff812b2b20 T iter_file_splice_write
>  > 
>  > Let's try to figure out whether it's read or write side going wrong.
>  > 
>  > diff --git a/fs/splice.c b/fs/splice.c
>  > index 006ba50f4ece..0a7c0bd3e164 100644
>  > --- a/fs/splice.c
>  > +++ b/fs/splice.c
>  > @@ -970,10 +970,26 @@ ssize_t splice_direct_to_actor(struct file *in, struct splice_desc *sd,
>  >  	while (len) {
>  >  		size_t read_len;
>  >  		loff_t pos = sd->pos, prev_pos = pos;
>  > +		if (WARN_ON(pipe->nrbufs)) {
>  > +			printk(KERN_ERR "in->f_op = %p, ->splice_write = %p\n",
>  > +				in->f_op,
>  > +				sd->u.file->f_op->splice_write);
>  > +		}
>  >  
>  >  		ret = do_splice_to(in, &pos, pipe, len, flags);
>  >  		if (unlikely(ret <= 0))
>  >  			goto out_release;
>  > +		{
>  > +			int idx = pipe->curbuf;
>  > +			int n = pipe->nrbufs;
>  > +			size_t size = 0;
>  > +			while (n--) {
>  > +				size += pipe->bufs[idx++].len;
>  > +				if (idx == pipe->buffers)
>  > +					idx = 0;
>  > +			}
>  > +			WARN_ON(size != ret);
>  > +		}
>  >  
>  >  		read_len = ret;
>  >  		sd->total_len = read_len;
> 
> WARNING: CPU: 0 PID: 21500 at fs/splice.c:985 splice_direct_to_actor+0x13f/0x280
> CPU: 0 PID: 21500 Comm: trinity-c4 Not tainted 4.11.0-rc6-think+ #10 
> Call Trace:
>  dump_stack+0x68/0x93
>  __warn+0xcb/0xf0
>  warn_slowpath_null+0x1d/0x20
>  splice_direct_to_actor+0x13f/0x280
>  ? generic_pipe_buf_nosteal+0x10/0x10
>  do_splice_direct+0x9e/0xd0
>  do_sendfile+0x1d7/0x3c0
>  SyS_sendfile64+0x73/0xe0
>  do_syscall_64+0x66/0x1d0
>  entry_SYSCALL64_slow_path+0x25/0x25
> RIP: 0033:0x7febc78b30f9
> RSP: 002b:00007ffd767b6398 EFLAGS: 00000246
>   ORIG_RAX: 0000000000000028
> RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007febc78b30f9
> RDX: 00007febc5c1e000 RSI: 0000000000000130 RDI: 0000000000000130
> RBP: 00007febc7f66000 R08: 0000000000000ff1 R09: fffffffffffffffd
> R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007febc7f66048 R14: 00007febc7f89ad8 R15: 00007febc7f66000
> ---[ end trace d002d06d5879c8a9 ]---
> in->f_op = ffffffffa02df980, ->splice_write = ffffffff812b2b20
> 
> This time around it locked up completely. Weird.

No idea about the lockup, but this definitely looks like the read side being
bogus.  Let's try this:

diff --git a/fs/splice.c b/fs/splice.c
index 006ba50f4ece..73ff284fb20f 100644
--- a/fs/splice.c
+++ b/fs/splice.c
@@ -284,6 +284,41 @@ void splice_shrink_spd(struct splice_pipe_desc *spd)
 	kfree(spd->partial);
 }
 
+static void test_it(struct pipe_inode_info *pipe, size_t len, long ret)
+{
+	int idx = pipe->curbuf;
+	int n = pipe->nrbufs;
+	size_t size = 0;
+	while (n--) {
+		size += pipe->bufs[idx++].len;
+		if (idx == pipe->buffers)
+			idx = 0;
+	}
+	if (WARN_ON(size != ret)) {
+		char c = '[';
+		printk(KERN_ERR "asked to read %zu, claims to have read %ld",
+			len, ret);
+		printk(KERN_CONT "actual size of data in pipe %zd ", size);
+		for (n = pipe->nrbufs, idx = pipe->curbuf; n--; ) {
+			printk(KERN_CONT "%c%d:%u", c, idx,
+				pipe->bufs[idx].len);
+			c = ',';
+			if (++idx == pipe->buffers)
+				idx = 0;
+		}
+		if (c == ' ')
+			printk(KERN_CONT "]");
+	}
+}
+
+static inline void insane_splice_read(struct pipe_inode_info *pipe,
+					size_t len, long ret)
+{
+	if (ret <= 0 || pipe != current->splice_pipe)
+		return;
+	test_it(pipe, len, ret);
+}
+
 /**
  * generic_file_splice_read - splice data from file to a pipe
  * @in:		file to splice from
@@ -313,6 +348,7 @@ ssize_t generic_file_splice_read(struct file *in, loff_t *ppos,
 	if (ret > 0) {
 		*ppos = kiocb.ki_pos;
 		file_accessed(in);
+		insane_splice_read(pipe, len, ret);
 	} else if (ret < 0) {
 		to.idx = idx;
 		to.iov_offset = 0;
@@ -394,7 +430,7 @@ static ssize_t default_file_splice_read(struct file *in, loff_t *ppos,
 	struct page **pages;
 	unsigned int nr_pages;
 	size_t offset, dummy, copied = 0;
-	ssize_t res;
+	ssize_t res, old_len = len;
 	int i;
 
 	if (pipe->nrbufs == pipe->buffers)
@@ -448,6 +484,7 @@ static ssize_t default_file_splice_read(struct file *in, loff_t *ppos,
 		put_page(pages[i]);
 	kvfree(pages);
 	iov_iter_advance(&to, copied);	/* truncates and discards */
+	insane_splice_read(pipe, old_len, res);
 	return res;
 }
 
@@ -970,6 +1007,11 @@ ssize_t splice_direct_to_actor(struct file *in, struct splice_desc *sd,
 	while (len) {
 		size_t read_len;
 		loff_t pos = sd->pos, prev_pos = pos;
+		if (WARN_ON(pipe->nrbufs)) {
+			printk(KERN_ERR "in->f_op = %p, ->splice_write = %p\n",
+				in->f_op,
+				sd->u.file->f_op->splice_write);
+		}
 
 		ret = do_splice_to(in, &pos, pipe, len, flags);
 		if (unlikely(ret <= 0))