Re: iov_iter_pipe warning.

[Dave Jones <davej@codemonkey.org.uk>]

On Fri, Apr 28, 2017 at 05:43:13PM +0100, Al Viro wrote:
 > On Fri, Apr 28, 2017 at 11:29:55AM -0400, Dave Jones wrote:
 > > On Fri, Apr 21, 2017 at 06:54:30PM +0100, Al Viro wrote:
 > >  > On Wed, Apr 12, 2017 at 03:03:18PM -0400, Dave Jones wrote:
 > >  > 
 > >  > > Well it's been running an hour without incident, which looks promising.
 > >  > > I'll leave it run, but I'd say you're on the right track given how quick
 > >  > > it reproduced so far.
 > >  > 
 > >  > Could you try this and see if it works?  What happens is that unlike
 > >  > e.g. generic_file_read_iter/generic_file_write_iter, NFS O_DIRECT handling
 > >  > does not make sure that iov_iter had been advanced by the amount
 > >  > actually transferred - it is left advanced by the amount *requested*.
 > > 
 > > Crap. So I never ran it long enough it seems. I can still hit that trace.
 > > I re-added one of your earlier debug patches, and got this..
 > 
 > Could you send me the diff against something from mainline (identified by
 > sha1, ideally)?

currently running v4.11-rc8-75-gf83246089ca0

sunrpc bit is for the other unrelated problem I'm chasing.

note also, I saw the backtrace without the fs/splice.c changes.



diff --git a/fs/nfs/direct.c b/fs/nfs/direct.c
index aab32fc3d6a8..c1b5fed7c863 100644
--- a/fs/nfs/direct.c
+++ b/fs/nfs/direct.c
@@ -537,7 +537,7 @@ static ssize_t nfs_direct_read_schedule_iovec(struct nfs_direct_req *dreq,
 
 	if (put_dreq(dreq))
 		nfs_direct_complete(dreq);
-	return 0;
+	return requested_bytes;
 }
 
 /**
@@ -566,7 +566,7 @@ ssize_t nfs_file_direct_read(struct kiocb *iocb, struct iov_iter *iter)
 	struct inode *inode = mapping->host;
 	struct nfs_direct_req *dreq;
 	struct nfs_lock_context *l_ctx;
-	ssize_t result = -EINVAL;
+	ssize_t result = -EINVAL, requested;
 	size_t count = iov_iter_count(iter);
 	nfs_add_stats(mapping->host, NFSIOS_DIRECTREADBYTES, count);
 
@@ -600,14 +600,19 @@ ssize_t nfs_file_direct_read(struct kiocb *iocb, struct iov_iter *iter)
 	nfs_start_io_direct(inode);
 
 	NFS_I(inode)->read_io += count;
-	result = nfs_direct_read_schedule_iovec(dreq, iter, iocb->ki_pos);
+	requested = nfs_direct_read_schedule_iovec(dreq, iter, iocb->ki_pos);
 
 	nfs_end_io_direct(inode);
 
-	if (!result) {
+	if (requested > 0) {
 		result = nfs_direct_wait(dreq);
-		if (result > 0)
+		if (result > 0) {
+			requested -= result;
 			iocb->ki_pos += result;
+		}
+		iov_iter_revert(iter, requested);
+	} else {
+		result = requested;
 	}
 
 out_release:
@@ -954,7 +959,7 @@ static ssize_t nfs_direct_write_schedule_iovec(struct nfs_direct_req *dreq,
 
 	if (put_dreq(dreq))
 		nfs_direct_write_complete(dreq);
-	return 0;
+	return requested_bytes;
 }
 
 /**
@@ -979,7 +984,7 @@ static ssize_t nfs_direct_write_schedule_iovec(struct nfs_direct_req *dreq,
  */
 ssize_t nfs_file_direct_write(struct kiocb *iocb, struct iov_iter *iter)
 {
-	ssize_t result = -EINVAL;
+	ssize_t result = -EINVAL, requested;
 	size_t count;
 	struct file *file = iocb->ki_filp;
 	struct address_space *mapping = file->f_mapping;
@@ -1022,7 +1027,7 @@ ssize_t nfs_file_direct_write(struct kiocb *iocb, struct iov_iter *iter)
 
 	nfs_start_io_direct(inode);
 
-	result = nfs_direct_write_schedule_iovec(dreq, iter, pos);
+	requested = nfs_direct_write_schedule_iovec(dreq, iter, pos);
 
 	if (mapping->nrpages) {
 		invalidate_inode_pages2_range(mapping,
@@ -1031,13 +1036,17 @@ ssize_t nfs_file_direct_write(struct kiocb *iocb, struct iov_iter *iter)
 
 	nfs_end_io_direct(inode);
 
-	if (!result) {
+	if (requested > 0) {
 		result = nfs_direct_wait(dreq);
 		if (result > 0) {
+			requested -= result;
 			iocb->ki_pos = pos + result;
 			/* XXX: should check the generic_write_sync retval */
 			generic_write_sync(iocb, result);
 		}
+		iov_iter_revert(iter, requested);
+	} else {
+		result = requested;
 	}
 out_release:
 	nfs_direct_req_release(dreq);
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))
diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
index 7bfe1fb42add..eb5297573a8a 100644
--- a/net/sunrpc/svc_xprt.c
+++ b/net/sunrpc/svc_xprt.c
@@ -927,6 +927,15 @@ int svc_send(struct svc_rqst *rqstp)
 	if (!xprt)
 		goto out;
 
+        if (WARN_ON(rqstp->rq_res.head[0].iov_len +
+                rqstp->rq_res.page_len +
+                rqstp->rq_res.tail[0].iov_len > rqstp->rq_reserved)) {
+
+		printk("dbg: rqstp->rq_res.head[0].iov_len:%ld\n", rqstp->rq_res.head[0].iov_len);
+		printk("dbg: rqstp->rq_res.page_len:%d\n", rqstp->rq_res.page_len);
+		printk("dbg: rqstp->rq_reserved:%d\n", rqstp->rq_reserved);
+        }
+
 	/* release the receive skb before sending the reply */
 	rqstp->rq_xprt->xpt_ops->xpo_release_rqst(rqstp);
 
@@ -936,6 +945,8 @@ int svc_send(struct svc_rqst *rqstp)
 		xb->page_len +
 		xb->tail[0].iov_len;
 
+	WARN_ON(xb->len > rqstp->rq_reserved);
+
 	/* Grab mutex to serialize outgoing data. */
 	mutex_lock(&xprt->xpt_mutex);
 	if (test_bit(XPT_DEAD, &xprt->xpt_flags)
@@ -944,6 +955,7 @@ int svc_send(struct svc_rqst *rqstp)
 	else
 		len = xprt->xpt_ops->xpo_sendto(rqstp);
 	mutex_unlock(&xprt->xpt_mutex);
+
 	rpc_wake_up(&xprt->xpt_bc_pending);
 	svc_xprt_release(rqstp);