Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752433AbdDLC6q (ORCPT ); Tue, 11 Apr 2017 22:58:46 -0400 Received: from zeniv.linux.org.uk ([195.92.253.2]:44188 "EHLO ZenIV.linux.org.uk" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751685AbdDLC6n (ORCPT ); Tue, 11 Apr 2017 22:58:43 -0400 Date: Wed, 12 Apr 2017 03:58:42 +0100 From: Al Viro To: Dave Jones , Linux Kernel Subject: Re: iov_iter_pipe warning. Message-ID: <20170412025842.GO29622@ZenIV.linux.org.uk> References: <20170411222502.ldgahltwvrrxdbbw@codemonkey.org.uk> <20170411232842.GI29622@ZenIV.linux.org.uk> <20170411234558.zyzxznzaas3ge7qe@codemonkey.org.uk> <20170411235158.GK29622@ZenIV.linux.org.uk> <20170411235641.GL29622@ZenIV.linux.org.uk> <20170412000607.ob4cjv7vof3f64uu@codemonkey.org.uk> <20170412001746.GM29622@ZenIV.linux.org.uk> <20170412005853.vqyuo6722tmthn5u@codemonkey.org.uk> <20170412011532.GN29622@ZenIV.linux.org.uk> <20170412022911.nhefjqlnyrk3n7rr@codemonkey.org.uk> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20170412022911.nhefjqlnyrk3n7rr@codemonkey.org.uk> User-Agent: Mutt/1.7.1 (2016-10-04) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 5045 Lines: 155 On Tue, Apr 11, 2017 at 10:29:11PM -0400, Dave Jones wrote: > 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. No idea about the lockup, but this definitely looks like the read side being bogus. Let's try this: diff --git a/fs/splice.c b/fs/splice.c index 006ba50f4ece..73ff284fb20f 100644 --- a/fs/splice.c +++ b/fs/splice.c @@ -284,6 +284,41 @@ void splice_shrink_spd(struct splice_pipe_desc *spd) kfree(spd->partial); } +static void 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 "]"); + } +} + +static inline void insane_splice_read(struct pipe_inode_info *pipe, + size_t len, long ret) +{ + if (ret <= 0 || pipe != current->splice_pipe) + return; + test_it(pipe, len, ret); +} + /** * generic_file_splice_read - splice data from file to a pipe * @in: file to splice from @@ -313,6 +348,7 @@ ssize_t generic_file_splice_read(struct file *in, loff_t *ppos, if (ret > 0) { *ppos = kiocb.ki_pos; file_accessed(in); + insane_splice_read(pipe, len, ret); } else if (ret < 0) { to.idx = idx; to.iov_offset = 0; @@ -394,7 +430,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 +484,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 +1007,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))