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

Groups > linux.kernel > #1620640 > 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. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-10 21:30 +0200
    Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-10 21:50 +0200
      Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-10 22:00 +0200
        Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-11 01:50 +0200
          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-11 02:30 +0200
            Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-11 05:10 +0200
              Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-11 05:30 +0200
                Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-11 23:00 +0200
                  Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-11 23:20 +0200
                    Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 00:30 +0200
                      Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 01:30 +0200
                        Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 01:40 +0200
                          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 01:50 +0200
                        Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 01:50 +0200
                          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 02:00 +0200
                            Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 02:10 +0200
                              Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 02:20 +0200
                                Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 03:00 +0200
                                  Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 03:20 +0200
                                    Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 04:30 +0200
                                      Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 05:00 +0200
                                        Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 16:40 +0200
                                          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 17:30 +0200
                                            Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 18:30 +0200
                                              Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 19:10 +0200
                                                Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 21:10 +0200
                                                  Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-21 21:10 +0200
                          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 02:00 +0200

Page 1 of 2  [1] 2  Next page →

#1620640 — Re: iov_iter_pipe warning.

On Tue, Mar 21, 2017 at 04:59:01PM -0400, Dave Jones wrote:
> WARNING: CPU: 0 PID: 9290 at lib/iov_iter.c:836 iov_iter_pipe+0x71/0x80
> CPU: 0 PID: 9290 Comm: trinity-c7 Not tainted 4.11.0-rc3-think+ #3 
> Call Trace:
>  dump_stack+0x68/0x93
>  __warn+0xcb/0xf0
>  warn_slowpath_null+0x1d/0x20
>  iov_iter_pipe+0x71/0x80
>  generic_file_splice_read+0x37/0x140
>  do_splice_to+0x79/0x90
>  splice_direct_to_actor+0xb8/0x220
>  ? generic_pipe_buf_nosteal+0x10/0x10
>  do_splice_direct+0x9e/0xd0
>  do_sendfile+0x1d7/0x3c0
>  SyS_sendfile64+0x73/0xe0
>  do_syscall_64+0x66/0x1d0

Cute...  We have ->splice_read() called in attempt to shove something into
a full internal pipe.  How do you achieve that situation?  actor() callback
claiming to have drained more than it actually had to?

Do you have a reliable reproducer?

[toc] | [next] | [standalone]

#1620663

On Mon, Apr 10, 2017 at 08:28:00PM +0100, Al Viro wrote:
 > On Tue, Mar 21, 2017 at 04:59:01PM -0400, Dave Jones wrote:
 > > WARNING: CPU: 0 PID: 9290 at lib/iov_iter.c:836 iov_iter_pipe+0x71/0x80
 > > CPU: 0 PID: 9290 Comm: trinity-c7 Not tainted 4.11.0-rc3-think+ #3 
 > > Call Trace:
 > >  dump_stack+0x68/0x93
 > >  __warn+0xcb/0xf0
 > >  warn_slowpath_null+0x1d/0x20
 > >  iov_iter_pipe+0x71/0x80
 > >  generic_file_splice_read+0x37/0x140
 > >  do_splice_to+0x79/0x90
 > >  splice_direct_to_actor+0xb8/0x220
 > >  ? generic_pipe_buf_nosteal+0x10/0x10
 > >  do_splice_direct+0x9e/0xd0
 > >  do_sendfile+0x1d7/0x3c0
 > >  SyS_sendfile64+0x73/0xe0
 > >  do_syscall_64+0x66/0x1d0
 > 
 > Cute...  We have ->splice_read() called in attempt to shove something into
 > a full internal pipe.  How do you achieve that situation?  actor() callback
 > claiming to have drained more than it actually had to?
 > 
 > Do you have a reliable reproducer?

Not reliable, but I'll see if I can find some time to narrow it down
this week.  I've been working on better logging of "wtf just happened"
the last few weeks, so it should get easier once I finish that work.

	Dave

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

#1620681

On Mon, Apr 10, 2017 at 03:42:06PM -0400, Dave Jones wrote:
>  > Do you have a reliable reproducer?
> 
> Not reliable, but I'll see if I can find some time to narrow it down
> this week.  I've been working on better logging of "wtf just happened"
> the last few weeks, so it should get easier once I finish that work.

I would suggest
	a) slapping WARN_ON(pipe->nr_bufs); right before the loop
in splice_direct_to_actor().  Internal pipe should be empty when we
enter this function.
	b) the same WARN_ON() in the very end of the loop body.

We should have started with empty pipe.  We'd called ->splice_read()
and it had returned a positive number (in read_len).  That should be
the amount we'd pushed in there.  Then we call actor(), with
sd->total_len set to read_len.  Its return value is
	* positive (or we would've buggered off)
	* no less than read_len (ditto)
so it should have drained the pipe entirely, leaving it empty again.

Finding it not just non-empty, but full means that something's very
wrong.  The actor here is essentially ->splice_write(), and I'm really
curious which file is the target.  Actually, could you turn those
WARN_ON() into
	if (WARN_ON(pipe->nr_bufs))
		printk(KERN_ERR "->splice_write = %p",
			sd->u.file->f_op->splice_write);
and see which function it is?

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

#1620780

On Mon, Apr 10, 2017 at 08:57:11PM +0100, Al Viro wrote:
 > On Mon, Apr 10, 2017 at 03:42:06PM -0400, Dave Jones wrote:
 > >  > Do you have a reliable reproducer?
 > > 
 > > Not reliable, but I'll see if I can find some time to narrow it down
 > > this week.  I've been working on better logging of "wtf just happened"
 > > the last few weeks, so it should get easier once I finish that work.
 > 
 > I would suggest
 > 	a) slapping WARN_ON(pipe->nr_bufs); right before the loop
 > in splice_direct_to_actor().  Internal pipe should be empty when we
 > enter this function.
 > 	b) the same WARN_ON() in the very end of the loop body.
 > 
 > We should have started with empty pipe.  We'd called ->splice_read()
 > and it had returned a positive number (in read_len).  That should be
 > the amount we'd pushed in there.  Then we call actor(), with
 > sd->total_len set to read_len.  Its return value is
 > 	* positive (or we would've buggered off)
 > 	* no less than read_len (ditto)
 > so it should have drained the pipe entirely, leaving it empty again.
 > 
 > Finding it not just non-empty, but full means that something's very
 > wrong.  The actor here is essentially ->splice_write(), and I'm really
 > curious which file is the target.  Actually, could you turn those
 > WARN_ON() into
 > 	if (WARN_ON(pipe->nr_bufs))
 > 		printk(KERN_ERR "->splice_write = %p",
 > 			sd->u.file->f_op->splice_write);
 > and see which function it is?

s/nr_bufs/nrbufs/ aside, I tried this, and it didn't trigger, even
though I hit the iov_iter_pipe WARN again.

	Dave

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

#1620802

On Mon, Apr 10, 2017 at 07:48:30PM -0400, Dave Jones wrote:
>  > 	if (WARN_ON(pipe->nr_bufs))
>  > 		printk(KERN_ERR "->splice_write = %p",
>  > 			sd->u.file->f_op->splice_write);
>  > and see which function it is?
> 
> s/nr_bufs/nrbufs/ aside, I tried this, and it didn't trigger, even
> though I hit the iov_iter_pipe WARN again.

Huh?  So you have WARN_ON(pipe->nrbufs == pipe->buffers) trigger depite
WARN_ON(pipe->nrbufs) *not* triggering a bit earlier?  Nuts...

Let's do this:
	* in generic_file_splice_read(): WARN_ON(pipe->nrbufs == pipe->buffers)
*and* WARN_ON(!pipe->buffers) in the very beginning.
	* in do_splice_to(): ditto.
	* in splice_direct_to_actor(): if (WARN_ON... from upthread (with the
typo fix, of course).
	* in iov_iter_pipe() turn the test into
	if (WARN_ON(pipe->nrbufs == pipe->buffers))
		WARN_ON(pipe != current->splice_pipe);

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

#1620855

On Tue, Apr 11, 2017 at 01:22:15AM +0100, Al Viro wrote:

 > 	* in do_splice_to(): WARN_ON(pipe->nrbufs == pipe->buffers)

Hit this one.

 > 	* in generic_file_splice_read(): WARN_ON(pipe->nrbufs == pipe->buffers)

followed by this one.

Then the usual iov_iter trace.

	Dave

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

#1620868

On Mon, Apr 10, 2017 at 11:05:32PM -0400, Dave Jones wrote:
> On Tue, Apr 11, 2017 at 01:22:15AM +0100, Al Viro wrote:
> 
>  > 	* in do_splice_to(): WARN_ON(pipe->nrbufs == pipe->buffers)
> 
> Hit this one.

But not WARN_ON(pipe->nrbufs) in its caller *or* WARN_ON(!pipe->buffers)
in do_splice_to() itself?

How the devil can that be possible?

Again, to make sure we are on the same page: in
	if (WARN_ON(pipe->nrbufs)) {
		printk(KERN_ERR "->splice_write = %p",
			sd->u.file->f_op->splice_write);
	}
        while (len) {
                size_t read_len;
                loff_t pos = sd->pos, prev_pos = pos;

                ret = do_splice_to(in, &pos, pipe, len, flags);
		...
		... (not a single continue in sight)
		...
		if (WARN_ON(pipe->nrbufs)) {
			printk(KERN_ERR "->splice_write = %p",
				sd->u.file->f_op->splice_write);
		}
	}
neither of those WARN_ON() triggers.  In do_splice_to()
	WARN_ON(pipe->nrbufs == pipe->buffers);
does trigger, but
	WARN_ON(!pipe->buffers);
does not.  And pipe is equal to current->splice_pipe, so nobody else could
see it, let alone be messing with it.

How can that be possible?  Non-triggering WARN_ON() in caller of do_splice_to()
mean that pipe->nrbufs is zero.  Triggering WARN_ON() in do_splice_to() means
that it's equal to pipe->buffers, but WARN_ON(!pipe->buffers) manages to avoid
being triggered?  Can you confirm all that?  Because if that's the case,
the next possibility is random memory corruption and/or pipe_info dangling
pointers/use-after-free/etc.

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

#1621616

On Tue, Apr 11, 2017 at 04:28:39AM +0100, Al Viro wrote:
 > On Mon, Apr 10, 2017 at 11:05:32PM -0400, Dave Jones wrote:
 > > On Tue, Apr 11, 2017 at 01:22:15AM +0100, Al Viro wrote:
 > > 
 > >  > 	* in do_splice_to(): WARN_ON(pipe->nrbufs == pipe->buffers)
 > > 
 > > Hit this one.
 > 
 > But not WARN_ON(pipe->nrbufs) in its caller *or* WARN_ON(!pipe->buffers)
 > in do_splice_to() itself?
 > 
 > How the devil can that be possible?
 > 
 > Again, to make sure we are on the same page: in
 > 	if (WARN_ON(pipe->nrbufs)) {
 > 		printk(KERN_ERR "->splice_write = %p",
 > 			sd->u.file->f_op->splice_write);
 > 	}
 >         while (len) {
 >                 size_t read_len;
 >                 loff_t pos = sd->pos, prev_pos = pos;
 > 
 >                 ret = do_splice_to(in, &pos, pipe, len, flags);
 > 		...
 > 		... (not a single continue in sight)
 > 		...
 > 		if (WARN_ON(pipe->nrbufs)) {
 > 			printk(KERN_ERR "->splice_write = %p",
 > 				sd->u.file->f_op->splice_write);
 > 		}
 > 	}

Ah, missed adding this 2nd WARN_ON.

 > neither of those WARN_ON() triggers.  In do_splice_to()
 > 	WARN_ON(pipe->nrbufs == pipe->buffers);
 > does trigger, but
 > 	WARN_ON(!pipe->buffers);
 > does not.  And pipe is equal to current->splice_pipe, so nobody else could
 > see it, let alone be messing with it.
 > 
 > How can that be possible?  Non-triggering WARN_ON() in caller of do_splice_to()
 > mean that pipe->nrbufs is zero.  Triggering WARN_ON() in do_splice_to() means
 > that it's equal to pipe->buffers, but WARN_ON(!pipe->buffers) manages to avoid
 > being triggered?  Can you confirm all that?
 
asides from above, yeah, same.

 > Because if that's the case,
 > the next possibility is random memory corruption and/or pipe_info dangling
 > pointers/use-after-free/etc.

I've been tied up with other stuff today, so while I was preoccupied, I
did a run with KASAN to see if anything fell out.  That seems to slow
things down enough that I don't trigger anything. Been running all day
without incident.

I'll turn it back off, and retry with the missing WARN from above added.

	Dave

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

#1621629

On Tue, Apr 11, 2017 at 04:53:36PM -0400, Dave Jones wrote:
>  > 		if (WARN_ON(pipe->nrbufs)) {
>  > 			printk(KERN_ERR "->splice_write = %p",
>  > 				sd->u.file->f_op->splice_write);
>  > 		}
>  > 	}
> 
> Ah, missed adding this 2nd WARN_ON.

Good - it means that we don't have to chase memory corruption yet.  That
smells like some ->splice_write() claiming it has copied more than it
has drained from the pipe.

> I'll turn it back off, and retry with the missing WARN from above added.

Please, do.  And it would be nice if you printed sd->u.file->f_op as well
(in the same printk).

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

#1621664

On Tue, Apr 11, 2017 at 10:12:16PM +0100, Al Viro wrote:
 > On Tue, Apr 11, 2017 at 04:53:36PM -0400, Dave Jones wrote:
 > >  > 		if (WARN_ON(pipe->nrbufs)) {
 > >  > 			printk(KERN_ERR "->splice_write = %p",
 > >  > 				sd->u.file->f_op->splice_write);
 > >  > 		}
 > >  > 	}
 > > 
 > > Ah, missed adding this 2nd WARN_ON.
 > 
 > Good - it means that we don't have to chase memory corruption yet.  That
 > smells like some ->splice_write() claiming it has copied more than it
 > has drained from the pipe.
 > 
 > > I'll turn it back off, and retry with the missing WARN from above added.
 > 
 > Please, do.  And it would be nice if you printed sd->u.file->f_op as well
 > (in the same printk).

Will add that for the next run. In the meantime..

[ 2675.049082] WARNING: CPU: 0 PID: 10149 at fs/splice.c:1020 splice_direct_to_actor+0x20c/0x2b0
[ 2675.061581] CPU: 0 PID: 10149 Comm: trinity-c2 Not tainted 4.11.0-rc6-think+ #6 
[ 2675.086528] Call Trace:
[ 2675.098901]  dump_stack+0x68/0x93
[ 2675.111242]  __warn+0xcb/0xf0
[ 2675.123467]  warn_slowpath_null+0x1d/0x20
[ 2675.135602]  splice_direct_to_actor+0x20c/0x2b0
[ 2675.147636]  ? generic_pipe_buf_nosteal+0x10/0x10
[ 2675.159675]  do_splice_direct+0x9e/0xd0
[ 2675.171837]  do_sendfile+0x1d7/0x3c0
[ 2675.183762]  SyS_sendfile64+0x73/0xe0
[ 2675.195944]  do_syscall_64+0x66/0x1d0
[ 2675.208090]  entry_SYSCALL64_slow_path+0x25/0x25
[ 2675.220256] RIP: 0033:0x7fcf6cdb80f9
[ 2675.232338] RSP: 002b:00007fff12252418 EFLAGS: 00000246
[ 2675.244447]  ORIG_RAX: 0000000000000028
[ 2675.256474] RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007fcf6cdb80f9
[ 2675.268528] RDX: 00007fcf6af23000 RSI: 0000000000000187 RDI: 0000000000000158
[ 2675.280680] RBP: 00007fcf6d479000 R08: 9696969696969696 R09: adadadadadadadad
[ 2675.292870] R10: 0000000000000508 R11: 0000000000000246 R12: 0000000000000002
[ 2675.305049] R13: 00007fcf6d479048 R14: 00007fcf6d48ead8 R15: 00007fcf6d479000
[ 2675.317455] ---[ end trace 9e4e62cfabcb9081 ]---
[ 2675.329626] ->splice_write = ffffffff812b3130

$ grep ffffffff812b3130 /proc/kallsyms 
ffffffff812b3130 T generic_splice_sendpage

This one spat out all by itself.

	Dave

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

#1621688

On Tue, Apr 11, 2017 at 06:25:02PM -0400, Dave Jones wrote:

> ffffffff812b3130 T generic_splice_sendpage
> 
> This one spat out all by itself.

No need to print ->f_op for that one - can be only socket_file_ops.  Now,
the address family of that socket would be interesting...

How about adding to that printk (under if (WARN_ON()) something like
	file = sd->u.file;
	if (file->f_op->splice_write == generic_splice_sendpage) {
		struct socket *sock = file->private_data;
		printk(KERN_ERR "socket [%d, %p]\n", sock->type, sock->ops);
	}
	printk(KERN_ERR "in->f_op = %p\n", in->f_op);

Said that, we seem to have
	* a pipe with some amount of data in it
	* generic_splice_sendpage() called on that pipe, with len equal to
the amount in the pipe.  Hopefully.
	* generic_splice_sendpage() returning the value equal to len...
	* ... and not draining the pipe entirely.

generic_splice_sendpage() is calling this:

ssize_t __splice_from_pipe(struct pipe_inode_info *pipe, struct splice_desc *sd,
                           splice_actor *actor)
{
        int ret;

        splice_from_pipe_begin(sd); 
        do {
                cond_resched();
                ret = splice_from_pipe_next(pipe, sd);
                if (ret > 0)
                        ret = splice_from_pipe_feed(pipe, sd, actor);
        } while (ret > 0);
        splice_from_pipe_end(pipe, sd);

        return sd->num_spliced ? sd->num_spliced : ret;
}

It has returned a positive number.  That must have been sd->num_spliced.
splice_from_pipe_begin() sets it to 0 and the only place where it is
updated is
                ret = actor(pipe, buf, sd);
                if (ret <= 0)
                        return ret;

                buf->offset += ret;
                buf->len -= ret;

                sd->num_spliced += ret;
                sd->len -= ret;
                sd->pos += ret;
                sd->total_len -= ret;

                if (!buf->len) {
                        pipe_buf_release(pipe, buf);
                        pipe->curbuf = (pipe->curbuf + 1) & (pipe->buffers - 1);
                        pipe->nrbufs--;

in splice_from_pipe_feed().  Whatever actor() is doing, the amount we
drain from the pipe is equal to the amount we add to ->num_spliced.

In other words, sending part looks reasonably solid.  Another thing that
might have happened is
                ret = do_splice_to(in, &pos, pipe, len, flags);
                if (unlikely(ret <= 0))
                        goto out_release;
returning less than it has actually dumped into the pipe in some situations.

Which means default_file_splice_read() called on an empty pipe and
returning less than it has put there.  The thing is, the last thing
that function does is
        iov_iter_advance(&to, copied);  /* truncates and discards */
	return res;
and we would have to have copied > res > 0 for that scenario to happen...

Interesting...  How about
	if (res > 0 && pipe == current->splice_pipe) {
		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(len != res);
	}
just before the return in default_file_splice_read()?  WARN_ON_ONCE,
perhaps, to avoid cascades...

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

#1621689

On Wed, Apr 12, 2017 at 12:28:42AM +0100, Al Viro wrote:
 > On Tue, Apr 11, 2017 at 06:25:02PM -0400, Dave Jones wrote:
 > 
 > > ffffffff812b3130 T generic_splice_sendpage
 > > 
 > > This one spat out all by itself.
 > 
 > No need to print ->f_op for that one - can be only socket_file_ops.  Now,
 > the address family of that socket would be interesting...

Turned out to be..

 ->splice_write = ffffffff812b2b70 sd->u.file->f_op=ffffffffa02e0980
$ grep ffffffffa02e0980 /proc/kallsyms 
ffffffffa02e0980 r nfs4_file_operations	[nfsv4]

dir test is running from is /home on nfs, so that makes sense.

 > How about adding to that printk (under if (WARN_ON()) something like
 > 	file = sd->u.file;
 > 	if (file->f_op->splice_write == generic_splice_sendpage) {
 > 		struct socket *sock = file->private_data;
 > 		printk(KERN_ERR "socket [%d, %p]\n", sock->type, sock->ops);
 > 	}
 > 	printk(KERN_ERR "in->f_op = %p\n", in->f_op);

Ack.

 > Interesting...  How about
 > 	if (res > 0 && pipe == current->splice_pipe) {
 > 		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(len != res);
 > 	}
 > just before the return in default_file_splice_read()?  WARN_ON_ONCE,
 > perhaps, to avoid cascades...

Sure, up next. Gimme an hour, it seems to be reproducing fairly quickly
tonight.

	Dave.

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

#1621697

On Tue, Apr 11, 2017 at 07:34:37PM -0400, Dave Jones wrote:
> On Wed, Apr 12, 2017 at 12:28:42AM +0100, Al Viro wrote:
>  > On Tue, Apr 11, 2017 at 06:25:02PM -0400, Dave Jones wrote:
>  > 
>  > > ffffffff812b3130 T generic_splice_sendpage
>  > > 
>  > > This one spat out all by itself.
>  > 
>  > No need to print ->f_op for that one - can be only socket_file_ops.  Now,
>  > the address family of that socket would be interesting...
> 
> Turned out to be..
> 
>  ->splice_write = ffffffff812b2b70 sd->u.file->f_op=ffffffffa02e0980
> $ grep ffffffffa02e0980 /proc/kallsyms 
> ffffffffa02e0980 r nfs4_file_operations	[nfsv4]

Lovely...  So now we get it not only on splice to socket, but on
splice to regular file on NFS as well?  That makes lying splice_read()
more likely...

>  > Interesting...  How about
>  > 	if (res > 0 && pipe == current->splice_pipe) {
>  > 		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(len != res);
>  > 	}
>  > just before the return in default_file_splice_read()?  WARN_ON_ONCE,
>  > perhaps, to avoid cascades...
> 
> Sure, up next. Gimme an hour, it seems to be reproducing fairly quickly
> tonight.

Makes sense - now it screams on non-empty pipe in the beginning of loop
body; originally it was only for _full_ pipe (i.e. for leftovers from
several iterations filling the entire thing up), which should've been
harder to trigger...

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

#1621695

On Wed, Apr 12, 2017 at 12:28:42AM +0100, Al Viro wrote:
 > On Tue, Apr 11, 2017 at 06:25:02PM -0400, Dave Jones wrote:
 > 
 > > ffffffff812b3130 T generic_splice_sendpage
 > > 
 > > This one spat out all by itself.
 > 
 > No need to print ->f_op for that one - can be only socket_file_ops.  Now,
 > the address family of that socket would be interesting...
 > 
 > How about adding to that printk (under if (WARN_ON()) something like
 > 	file = sd->u.file;
 > 	if (file->f_op->splice_write == generic_splice_sendpage) {
 > 		struct socket *sock = file->private_data;
 > 		printk(KERN_ERR "socket [%d, %p]\n", sock->type, sock->ops);
 > 	}
 > 	printk(KERN_ERR "in->f_op = %p\n", in->f_op);

Ugh, this explodes with a million errors when I try to compile it. 
It misses socket definition, and include <linux/net.h> causes another
cascade of errors about linkage.h and nonsense.

Send me a diff, I'll check in later.

	Dave

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

#1621702

On Wed, Apr 12, 2017 at 12:51:58AM +0100, Al Viro wrote:
> On Tue, Apr 11, 2017 at 07:45:58PM -0400, Dave Jones wrote:
> >  > 	if (file->f_op->splice_write == generic_splice_sendpage) {
> >  > 		struct socket *sock = file->private_data;
> >  > 		printk(KERN_ERR "socket [%d, %p]\n", sock->type, sock->ops);
> >  > 	}
> >  > 	printk(KERN_ERR "in->f_op = %p\n", in->f_op);
> > 
> > Ugh, this explodes with a million errors when I try to compile it. 
> > It misses socket definition, and include <linux/net.h> causes another
> > cascade of errors about linkage.h and nonsense.
> 
> Ignore the socket part - you've already triggered it with NFS file as
> destination, so this is not particularly interesting.  I would still like
> to see in->f_op and even more - the checks in default_file_splice_read().

... and the latter had a braino - WARN_ON(size != ret), not len != ret.
Diff follows:

diff --git a/fs/splice.c b/fs/splice.c
index 006ba50f4ece..43dd9b3140ee 100644
--- a/fs/splice.c
+++ b/fs/splice.c
@@ -448,6 +448,18 @@ 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 */
+	if (res > 0 && pipe == current->splice_pipe) {
+		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 != res);
+	}
+
 	return res;
 }
 
@@ -970,6 +982,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->buffers)) {
+			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))

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

#1621704

On Wed, Apr 12, 2017 at 12:56:41AM +0100, Al Viro wrote:
 > On Wed, Apr 12, 2017 at 12:51:58AM +0100, Al Viro wrote:
 > > On Tue, Apr 11, 2017 at 07:45:58PM -0400, Dave Jones wrote:
 > > >  > 	if (file->f_op->splice_write == generic_splice_sendpage) {
 > > >  > 		struct socket *sock = file->private_data;
 > > >  > 		printk(KERN_ERR "socket [%d, %p]\n", sock->type, sock->ops);
 > > >  > 	}
 > > >  > 	printk(KERN_ERR "in->f_op = %p\n", in->f_op);
 > > > 
 > > > Ugh, this explodes with a million errors when I try to compile it. 
 > > > It misses socket definition, and include <linux/net.h> causes another
 > > > cascade of errors about linkage.h and nonsense.
 > > 
 > > Ignore the socket part - you've already triggered it with NFS file as
 > > destination, so this is not particularly interesting.  I would still like
 > > to see in->f_op and even more - the checks in default_file_splice_read().
 > 
 > ... and the latter had a braino - WARN_ON(size != ret), not len != ret.
 > Diff follows:
 
super fast repro..

[   51.795286] WARNING: CPU: 1 PID: 2057 at fs/splice.c:985 splice_direct_to_actor+0x13f/0x280
[   51.806721] CPU: 1 PID: 2057 Comm: trinity-c3 Not tainted 4.11.0-rc6-think+ #9 
[   51.814567] ------------[ cut here ]------------
[   51.814573] WARNING: CPU: 2 PID: 2018 at fs/splice.c:985 splice_direct_to_actor+0x13f/0x280
[   51.852613] Call Trace:
[   51.864076]  dump_stack+0x68/0x93
[   51.875475]  __warn+0xcb/0xf0
[   51.886831]  warn_slowpath_null+0x1d/0x20
[   51.898162]  splice_direct_to_actor+0x13f/0x280
[   51.909509]  ? generic_pipe_buf_nosteal+0x10/0x10
[   51.920949]  do_splice_direct+0x9e/0xd0
[   51.932166]  do_sendfile+0x1d7/0x3c0
[   51.943349]  SyS_sendfile64+0x73/0xe0
[   51.954495]  do_syscall_64+0x66/0x1d0
[   51.965630]  entry_SYSCALL64_slow_path+0x25/0x25
[   51.976718] RIP: 0033:0x7f3e6ecc80f9
[   51.987732] RSP: 002b:00007ffcb8b38728 EFLAGS: 00000246
[   51.998705]  ORIG_RAX: 0000000000000028
[   52.009546] RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007f3e6ecc80f9
[   52.020507] RDX: 00007f3e6f264000 RSI: 000000000000011a RDI: 000000000000019b
[   52.031427] RBP: 00007f3e6f382000 R08: 0000000000000010 R09: 0000000000000000
[   52.042263] R10: 0000000000000005 R11: 0000000000000246 R12: 0000000000000002
[   52.053040] R13: 00007f3e6f382048 R14: 00007f3e6f39ead8 R15: 00007f3e6f382000
[   52.063787] CPU: 2 PID: 2018 Comm: trinity-c6 Not tainted 4.11.0-rc6-think+ #9 
[   52.063997] ---[ end trace 51a5bc02dc45a59d ]---
[   52.063998] in->f_op = ffffffff81c26480, ->splice_write =           (null)
[   52.106748] Call Trace:
[   52.117338]  dump_stack+0x68/0x93
[   52.127832]  __warn+0xcb/0xf0
[   52.138224]  warn_slowpath_null+0x1d/0x20
[   52.148737]  splice_direct_to_actor+0x13f/0x280
[   52.159331]  ? generic_pipe_buf_nosteal+0x10/0x10
[   52.169897]  do_splice_direct+0x9e/0xd0
[   52.180412]  do_sendfile+0x1d7/0x3c0
[   52.190821]  SyS_sendfile64+0x73/0xe0
[   52.201210]  do_syscall_64+0x66/0x1d0
[   52.211503]  entry_SYSCALL64_slow_path+0x25/0x25
[   52.221740] RIP: 0033:0x7f3e6ecc80f9
[   52.231955] RSP: 002b:00007ffcb8b38728 EFLAGS: 00000246
[   52.242137]  ORIG_RAX: 0000000000000028
[   52.252235] RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007f3e6ecc80f9
[   52.262453] RDX: 00007f3e6f263000 RSI: 000000000000011d RDI: 000000000000011d
[   52.272637] RBP: 00007f3e6f36d000 R08: 00000000000000c7 R09: ffffffffffffffef
[   52.282775] R10: 0000000000000004 R11: 0000000000000246 R12: 0000000000000002
[   52.292889] R13: 00007f3e6f36d048 R14: 00007f3e6f39ead8 R15: 00007f3e6f36d000
[   52.304196] ---[ end trace 51a5bc02dc45a59e ]---
[   52.314808] in->f_op = ffffffff81c26480, ->splice_write = ffffffff812b2b20

$ grep  ffffffff812b2b20 /proc/kallsyms 
ffffffff812b2b20 T iter_file_splice_write
$ grep ffffffff81c26480 /proc/kallsyms 
ffffffff81c26480 r shmem_file_operations

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

#1621708

On Tue, Apr 11, 2017 at 08:06:07PM -0400, Dave Jones wrote:
> On Wed, Apr 12, 2017 at 12:56:41AM +0100, Al Viro wrote:
>  > On Wed, Apr 12, 2017 at 12:51:58AM +0100, Al Viro wrote:
>  > > On Tue, Apr 11, 2017 at 07:45:58PM -0400, Dave Jones wrote:
>  > > >  > 	if (file->f_op->splice_write == generic_splice_sendpage) {
>  > > >  > 		struct socket *sock = file->private_data;
>  > > >  > 		printk(KERN_ERR "socket [%d, %p]\n", sock->type, sock->ops);
>  > > >  > 	}
>  > > >  > 	printk(KERN_ERR "in->f_op = %p\n", in->f_op);
>  > > > 
>  > > > Ugh, this explodes with a million errors when I try to compile it. 
>  > > > It misses socket definition, and include <linux/net.h> causes another
>  > > > cascade of errors about linkage.h and nonsense.
>  > > 
>  > > Ignore the socket part - you've already triggered it with NFS file as
>  > > destination, so this is not particularly interesting.  I would still like
>  > > to see in->f_op and even more - the checks in default_file_splice_read().
>  > 
>  > ... and the latter had a braino - WARN_ON(size != ret), not len != ret.
>  > Diff follows:
>  
> super fast repro..

Alas, that's just another braino - it checks for non-zero ->buffers (always
true) rather than non-zero ->nrbufs (non-empty pipe).  Sorry.  Fixed diff
follows:

diff --git a/fs/splice.c b/fs/splice.c
index 006ba50f4ece..43dd9b3140ee 100644
--- a/fs/splice.c
+++ b/fs/splice.c
@@ -448,6 +448,18 @@ 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 */
+	if (res > 0 && pipe == current->splice_pipe) {
+		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 != res);
+	}
+
 	return res;
 }
 
@@ -970,6 +982,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))

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

#1621727

On Wed, Apr 12, 2017 at 01:17:46AM +0100, Al Viro wrote:
 > On Tue, Apr 11, 2017 at 08:06:07PM -0400, Dave Jones wrote:
 > > On Wed, Apr 12, 2017 at 12:56:41AM +0100, Al Viro wrote:
 > >  > On Wed, Apr 12, 2017 at 12:51:58AM +0100, Al Viro wrote:
 > >  > > On Tue, Apr 11, 2017 at 07:45:58PM -0400, Dave Jones wrote:
 > >  > > >  > 	if (file->f_op->splice_write == generic_splice_sendpage) {
 > >  > > >  > 		struct socket *sock = file->private_data;
 > >  > > >  > 		printk(KERN_ERR "socket [%d, %p]\n", sock->type, sock->ops);
 > >  > > >  > 	}
 > >  > > >  > 	printk(KERN_ERR "in->f_op = %p\n", in->f_op);
 > >  > > > 
 > >  > > > Ugh, this explodes with a million errors when I try to compile it. 
 > >  > > > It misses socket definition, and include <linux/net.h> causes another
 > >  > > > cascade of errors about linkage.h and nonsense.
 > >  > > 
 > >  > > Ignore the socket part - you've already triggered it with NFS file as
 > >  > > destination, so this is not particularly interesting.  I would still like
 > >  > > to see in->f_op and even more - the checks in default_file_splice_read().
 > >  > 
 > >  > ... and the latter had a braino - WARN_ON(size != ret), not len != ret.
 > >  > Diff follows:
 > >  
 > > super fast repro..
 > 
 > Alas, that's just another braino - it checks for non-zero ->buffers (always
 > true) rather than non-zero ->nrbufs (non-empty pipe).  Sorry.  Fixed diff
 > follows:
 
[  462.415864] WARNING: CPU: 0 PID: 21500 at fs/splice.c:985 splice_direct_to_actor+0x13f/0x280
[  462.428443] CPU: 0 PID: 21500 Comm: trinity-c4 Not tainted 4.11.0-rc6-think+ #10 
[  462.453818] Call Trace:
[  462.466415]  dump_stack+0x68/0x93
[  462.478920]  __warn+0xcb/0xf0
[  462.491367]  warn_slowpath_null+0x1d/0x20
[  462.503823]  splice_direct_to_actor+0x13f/0x280
[  462.516236]  ? generic_pipe_buf_nosteal+0x10/0x10
[  462.528606]  do_splice_direct+0x9e/0xd0
[  462.540825]  do_sendfile+0x1d7/0x3c0
[  462.552910]  SyS_sendfile64+0x73/0xe0
[  462.564989]  do_syscall_64+0x66/0x1d0
[  462.576949]  entry_SYSCALL64_slow_path+0x25/0x25
[  462.588872] RIP: 0033:0x7febc78b30f9
[  462.600809] RSP: 002b:00007ffd767b6398 EFLAGS: 00000246
[  462.612790]  ORIG_RAX: 0000000000000028
[  462.624684] RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007febc78b30f9
[  462.636737] RDX: 00007febc5c1e000 RSI: 0000000000000130 RDI: 0000000000000130
[  462.648756] RBP: 00007febc7f66000 R08: 0000000000000ff1 R09: fffffffffffffffd
[  462.660709] R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000000002
[  462.672627] R13: 00007febc7f66048 R14: 00007febc7f89ad8 R15: 00007febc7f66000
[  462.684586] ---[ end trace d002d06d5879c8a9 ]---
[  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

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

#1621736

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;

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

#1621748

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

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

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | linux.kernel

csiph-web