Re: iov_iter_pipe warning.

From: Al Viro
Date: Wed Apr 12 2017 - 11:26:13 EST


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