Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1632970 > unrolled thread

Re: iov_iter_pipe warning.

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-28 17:40 +0200
    Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-28 18:50 +0200
      Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-28 19:00 +0200
        Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-28 19:30 +0200
          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-28 20:30 +0200
            Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-29 04:00 +0200
              Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-29 04:50 +0200
                Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-29 18:00 +0200
                  [git pull] vfs.git fix (Re: iov_iter_pipe warning.) Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-29 22:50 +0200

#1632970 — Re: iov_iter_pipe warning.

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

WARNING: CPU: 1 PID: 20100 at fs/splice.c:297 test_it+0x7d/0x120
CPU: 1 PID: 20100 Comm: trinity-c49 Not tainted 4.11.0-rc8-think+ #3 
Call Trace:
 dump_stack+0x68/0x93
 __warn+0xcb/0xf0
 warn_slowpath_null+0x1d/0x20
 test_it+0x7d/0x120
 generic_file_splice_read+0x19a/0x1e0
 do_splice_to+0x79/0x90
 splice_direct_to_actor+0xc6/0x280
 ? generic_pipe_buf_nosteal+0x10/0x10
 do_splice_direct+0x9e/0xd0
 do_sendfile+0x1d7/0x3c0
 SyS_sendfile64+0xc9/0xe0
 do_syscall_64+0x66/0x1d0
 entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x7f8b83b59099
RSP: 002b:00007ffd7967da68 EFLAGS: 00000246
 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007f8b83b59099
RDX: 0000000000000000 RSI: 0000000000000131 RDI: 0000000000000195
RBP: 00007f8b840d1000 R08: 0000000000000073 R09: fffffffffffffffc
R10: 000000000000040f R11: 0000000000000246 R12: 0000000000000002
R13: 00007f8b840d1048 R14: 00007f8b8422fad8 R15: 00007f8b840d1000
---[ end trace 70d344adaede0734 ]---
asked to read 1039, claims to have read 62
actual size of data in pipe 977 
[0:977
]
f_op: ffffffffa02dd980, f_flags: 313346, pos: 4478229749/4478229811, size: 4478229811
------------[ cut here ]------------
WARNING: CPU: 1 PID: 20100 at fs/splice.c:1017 splice_direct_to_actor+0x13f/0x280
CPU: 1 PID: 20100 Comm: trinity-c49 Tainted: G        W       4.11.0-rc8-think+ #3 
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+0xc9/0xe0
 do_syscall_64+0x66/0x1d0
 entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x7f8b83b59099
RSP: 002b:00007ffd7967da68 EFLAGS: 00000246
 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007f8b83b59099
RDX: 0000000000000000 RSI: 0000000000000131 RDI: 0000000000000195
RBP: 00007f8b840d1000 R08: 0000000000000073 R09: fffffffffffffffc
R10: 000000000000040f R11: 0000000000000246 R12: 0000000000000002
R13: 00007f8b840d1048 R14: 00007f8b8422fad8 R15: 00007f8b840d1000
---[ end trace 70d344adaede0735 ]---
in->f_op = ffffffffa02dd980, ->splice_write = ffffffff812b1db0


$ grep ffffffffa02dd980 /proc/kallsyms 
ffffffffa02dd980 r nfs4_file_operations	[nfsv4]
$ grep ffffffff812b1db0 /proc/kallsyms 
ffffffff812b1db0 T iter_file_splice_write

[toc] | [next] | [standalone]

#1633020

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

[toc] | [prev] | [next] | [standalone]

#1633025

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

[toc] | [prev] | [next] | [standalone]

#1633039

On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
> 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.

	Interesting...  Could you add this and see if that triggers?

diff --git a/fs/splice.c b/fs/splice.c
index 540c4a44756c..12a12d9c313f 100644
--- a/fs/splice.c
+++ b/fs/splice.c
@@ -306,6 +306,9 @@ 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) {
+		if (WARN_ON(iov_iter_count(&to) != len - ret))
+			printk(KERN_ERR "ops %p: was %zd, left %zd, returned %d\n",
+				in->f_op, len, iov_iter_count(&to), ret);
 		*ppos = kiocb.ki_pos;
 		file_accessed(in);
 	} else if (ret < 0) {

[toc] | [prev] | [next] | [standalone]

#1633078

On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
> On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
> > 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.
> 
> 	Interesting...  Could you add this and see if that triggers?

Gyah...  It's a bloody dumb braino in iov_iter_revert() for pipe-backed
ones.  Sorry, the oneliner below should fix it.

diff --git a/lib/iov_iter.c b/lib/iov_iter.c
index f7c93568ec99..4952311422c1 100644
--- a/lib/iov_iter.c
+++ b/lib/iov_iter.c
@@ -798,7 +798,7 @@ void iov_iter_revert(struct iov_iter *i, size_t unroll)
 		while (1) {
 			size_t n = off - pipe->bufs[idx].offset;
 			if (unroll < n) {
-				off -= (n - unroll);
+				off -= unroll;
 				break;
 			}
 			unroll -= n;

[toc] | [prev] | [next] | [standalone]

#1633230

On Fri, Apr 28, 2017 at 07:25:12PM +0100, Al Viro wrote:
 > On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
 > > On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
 > > > 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.
 > > 
 > > 	Interesting...  Could you add this and see if that triggers?
 > 
 > Gyah...  It's a bloody dumb braino in iov_iter_revert() for pipe-backed
 > ones.  Sorry, the oneliner below should fix it.

5 hrs in, looking good so far.

	Dave

[toc] | [prev] | [next] | [standalone]

#1633235

On Fri, Apr 28, 2017 at 09:58:47PM -0400, Dave Jones wrote:
> On Fri, Apr 28, 2017 at 07:25:12PM +0100, Al Viro wrote:
>  > On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
>  > > On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
>  > > > 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.
>  > > 
>  > > 	Interesting...  Could you add this and see if that triggers?
>  > 
>  > Gyah...  It's a bloody dumb braino in iov_iter_revert() for pipe-backed
>  > ones.  Sorry, the oneliner below should fix it.
> 
> 5 hrs in, looking good so far.

Mind your Tested-by on the fix?

[toc] | [prev] | [next] | [standalone]

#1633304

On Sat, Apr 29, 2017 at 03:47:36AM +0100, Al Viro wrote:
 > On Fri, Apr 28, 2017 at 09:58:47PM -0400, Dave Jones wrote:
 > > On Fri, Apr 28, 2017 at 07:25:12PM +0100, Al Viro wrote:
 > >  > On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
 > >  > > On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
 > >  > > > 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.
 > >  > > 
 > >  > > 	Interesting...  Could you add this and see if that triggers?
 > >  > 
 > >  > Gyah...  It's a bloody dumb braino in iov_iter_revert() for pipe-backed
 > >  > ones.  Sorry, the oneliner below should fix it.
 > > 
 > > 5 hrs in, looking good so far.
 > 
 > Mind your Tested-by on the fix?

Sure.

Tested-by: Dave Jones <davej@codemonkey.org.uk>

[toc] | [prev] | [next] | [standalone]

#1633342 — [git pull] vfs.git fix (Re: iov_iter_pipe warning.)

On Sat, Apr 29, 2017 at 11:51:40AM -0400, Dave Jones wrote:

>  > >  > Gyah...  It's a bloody dumb braino in iov_iter_revert() for pipe-backed
>  > >  > ones.  Sorry, the oneliner below should fix it.
>  > > 
>  > > 5 hrs in, looking good so far.
>  > 
>  > Mind your Tested-by on the fix?
> 
> Sure.
> 
> Tested-by: Dave Jones <davej@codemonkey.org.uk>

The following changes since commit 1741937d475d91ed95abb37f07e8571e23b9a7fe:

  uapi: change the type of struct statx_timestamp.tv_nsec to unsigned (2017-04-26 21:19:05 -0400)

are available in the git repository at:

  git://git.kernel.org/pub/scm/linux/kernel/git/viro/vfs.git for-linus

for you to fetch changes up to 4fa55cefee1bbecadb4c9f47d40a92f65dc44351:

  fix a braino in ITER_PIPE iov_iter_revert() (2017-04-29 16:42:30 -0400)

----------------------------------------------------------------
Al Viro (1):
      fix a braino in ITER_PIPE iov_iter_revert()

 lib/iov_iter.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web