Re: iov_iter_pipe warning.

[Al Viro]

On Wed, Apr 12, 2017 at 10:35:19AM -0400, Dave Jones wrote:

> [ 4140.040002] asked to read 8, claims to have read 4
> [ 4140.051634] actual size of data in pipe 8 
> [ 4140.063234] [0:8

> [ 4140.342955] ---[ end trace d074a8823fe244d4 ]---
> [ 4140.353868] in->f_op = ffffffffa02dc980, ->splice_write = ffffffff812b2c20

IOW, we just had someone's ->read_iter() return 4 after having deposited 8
bytes.  The next question is which file_operations had that been, whether
it was O_DIRECT or not and where in file had we been reading from...

diff --git a/fs/splice.c b/fs/splice.c
index 006ba50f4ece..0e67ddf8618d 100644
--- a/fs/splice.c
+++ b/fs/splice.c
@@ -284,6 +284,43 @@ void splice_shrink_spd(struct splice_pipe_desc *spd)
 	kfree(spd->partial);
 }
 
+static bool 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 "]");
+		return true;
+	}
+	return false;
+}
+
+static inline bool insane_splice_read(struct pipe_inode_info *pipe,
+					size_t len, long ret)
+{
+	if (ret <= 0 || pipe != current->splice_pipe)
+		return false;
+	return test_it(pipe, len, ret);
+}
+
 /**
  * generic_file_splice_read - splice data from file to a pipe
  * @in:		file to splice from
@@ -311,8 +348,14 @@ ssize_t generic_file_splice_read(struct file *in, loff_t *ppos,
 	kiocb.ki_pos = *ppos;
 	ret = call_read_iter(in, &kiocb, &to);
 	if (ret > 0) {
-		*ppos = kiocb.ki_pos;
 		file_accessed(in);
+		if (unlikely(insane_splice_read(pipe, len, ret))) {
+			printk(KERN_ERR "f_op: %p, f_flags: %d, pos: %lld/%lld, size: %lld",
+				in->f_op, in->f_flags, (long long)*ppos,
+				(long long)kiocb.ki_pos,
+				(long long)i_size_read(file_inode(in)));
+		}
+		*ppos = kiocb.ki_pos;
 	} else if (ret < 0) {
 		to.idx = idx;
 		to.iov_offset = 0;
@@ -394,7 +437,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 +491,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 +1014,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))