Re: iov_iter_pipe warning.

From: Dave Jones
Date: Tue Apr 11 2017 - 22:29:25 EST


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.

Dave