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

Groups > linux.kernel > #1175054 > unrolled thread

Re: [git pull] vfs part 2

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: [git pull] vfs part 2 Andrey Ryabinin <a.ryabinin@samsung.com> - 2015-07-01 10:00 +0200
    Re: [git pull] vfs part 2 Al Viro <viro@ZenIV.linux.org.uk> - 2015-07-01 10:30 +0200
      Re: [git pull] vfs part 2 Andrey Ryabinin <a.ryabinin@samsung.com> - 2015-07-01 10:50 +0200
        Re: [git pull] vfs part 2 Al Viro <viro@ZenIV.linux.org.uk> - 2015-07-01 11:00 +0200
          Re: running out of tags in 9P (was Re: [git pull] vfs part 2) Al Viro <viro@ZenIV.linux.org.uk> - 2015-07-02 10:30 +0200
            Re: running out of tags in 9P (was Re: [git pull] vfs part 2) Al Viro <viro@ZenIV.linux.org.uk> - 2015-07-02 10:50 +0200
              Re: running out of tags in 9P (was Re: [git pull] vfs part 2) Andrey Ryabinin <a.ryabinin@samsung.com> - 2015-07-02 14:30 +0200
                Re: running out of tags in 9P (was Re: [git pull] vfs part 2) Al Viro <viro@ZenIV.linux.org.uk> - 2015-07-03 11:50 +0200
                  [PATCH] forgetting to cancel request in interrupted zero-copy 9P RPC  (was Re: [git pull] vfs part 2) Al Viro <viro@ZenIV.linux.org.uk> - 2015-07-03 17:10 +0200

#1175054 — Re: [git pull] vfs part 2

On 07/01/2015 09:27 AM, Al Viro wrote:
> On Mon, Jun 22, 2015 at 03:02:11PM +0300, Andrey Ryabinin wrote:
>> On 06/22/2015 12:12 AM, Al Viro wrote:
>>> On Thu, Apr 23, 2015 at 01:16:15PM +0300, Andrey Ryabinin wrote:
>>>> This change caused following:
>>>
>>>> This could happen when p9pdu_readf() changes 'count' to some value > iov_iter_count(from):
>>>>
>>>> p9_client_write():
>>>> <...>
>>>> 		int count = iov_iter_count(from);
>>>> <...>
>>>> 		*err = p9pdu_readf(req->rc, clnt->proto_version, "d", &count);
>>>> <...>
>>>> 		iov_iter_advance(from, count);
>>>
>>> *blink*
>>>
>>> That's a bug, all right, but I would love to see how you trigger it.
>>> It would require server to respond to "write that many bytes" with "OK,
>>> <greater number> bytes written".  We certainly need to cope with that
>>> (we can't trust the server to be sane), but if that's what is going on,
>>> you've got a server bug as well.
>>>
>>> Could you check if the patch below triggers WARN_ON() in it on your
>>> reproducer?  p9_client_read() has a similar issue as well...
>>>
>>
>> I've tried something like your patch before to check the read side
>> and I haven't seen anything before and don't see it right now.
>> Though, this doesn't mean that there is no problem with read.
>> I mean that trinity hits this on write and may just not hit this on read.
> 
> "This" being the WARN_ON() in that patch? 

Yes.


> Could you please run the same
> test with the following delta and post its printks? 

# dmesg | grep fucked

[  114.732166] fucked: sent 2037, server says it got 2047 (err = 0)
[  124.937105] fucked: sent 27, server says it got 4096 (err = 0)
[  154.075400] fucked: sent 19, server says it got 4096 (err = 0)

> It's one thing if
> you are hitting a buggy server, it gets confused and tells you it has
> written more bytes than you told it to write.  Quite a different story
> in case if we are miscalculating the size we are putting into RWRITE
> packet and/or advancing the iterator when we shouldn't...
> 
> What server are you using, BTW?  And which transport (virtio or network -
> IOW, is it zero-copy path or not)?

qemu v2.2.1, virtio transport.

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [next] | [standalone]

#1175086

On Wed, Jul 01, 2015 at 10:50:59AM +0300, Andrey Ryabinin wrote:

> # dmesg | grep fucked
> 
> [  114.732166] fucked: sent 2037, server says it got 2047 (err = 0)
> [  124.937105] fucked: sent 27, server says it got 4096 (err = 0)
> [  154.075400] fucked: sent 19, server says it got 4096 (err = 0)
> 
> > It's one thing if
> > you are hitting a buggy server, it gets confused and tells you it has
> > written more bytes than you told it to write.  Quite a different story
> > in case if we are miscalculating the size we are putting into RWRITE
								  TWRITE,
sorry about the braino.

> > packet and/or advancing the iterator when we shouldn't...
> > 
> > What server are you using, BTW?  And which transport (virtio or network -
> > IOW, is it zero-copy path or not)?
> 
> qemu v2.2.1, virtio transport.

Hmm...  The first one should've hit the zero-copy path then, the last two
are too short for that...  *grumble*

I wonder if these short writes are getting matched with response from wrong
request - that would explain full-page responses...

Could you check if 3.19 was getting anything similar?   I.e. in
p9_client_write() there add
	if (count > rsize)
		printk(KERN_ERR "bogus RWRITE: %d -> %d\n", rsize, count);
just before
	p9_debug(P9_DEBUG_9P, "<<< RWRITE count %d\n", count);
and see if that triggers...
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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

#1175096

On 07/01/2015 11:27 AM, Al Viro wrote:
> 
> Could you check if 3.19 was getting anything similar?   I.e. in
> p9_client_write() there add
> 	if (count > rsize)
> 		printk(KERN_ERR "bogus RWRITE: %d -> %d\n", rsize, count);
> just before
> 	p9_debug(P9_DEBUG_9P, "<<< RWRITE count %d\n", count);
> and see if that triggers...
> 

Yeah, the same thing:
	[  125.962374] bogus RWRITE: 27 -> 4096
	[  207.587632] bogus RWRITE: 27 -> 4096
	[  215.055627] bogus RWRITE: 27 -> 4096
	[  235.583138] bogus RWRITE: 27 -> 4096
	[  245.749174] bogus RWRITE: 27 -> 4096
	[  246.759270] bogus RWRITE: 27 -> 4096
	[  248.020787] bogus RWRITE: 27 -> 4096
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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

#1175098

On Wed, Jul 01, 2015 at 11:41:04AM +0300, Andrey Ryabinin wrote:
> On 07/01/2015 11:27 AM, Al Viro wrote:
> > 
> > Could you check if 3.19 was getting anything similar?   I.e. in
> > p9_client_write() there add
> > 	if (count > rsize)
> > 		printk(KERN_ERR "bogus RWRITE: %d -> %d\n", rsize, count);
> > just before
> > 	p9_debug(P9_DEBUG_9P, "<<< RWRITE count %d\n", count);
> > and see if that triggers...
> > 
> 
> Yeah, the same thing:
> 	[  125.962374] bogus RWRITE: 27 -> 4096
> 	[  207.587632] bogus RWRITE: 27 -> 4096
> 	[  215.055627] bogus RWRITE: 27 -> 4096
> 	[  235.583138] bogus RWRITE: 27 -> 4096
> 	[  245.749174] bogus RWRITE: 27 -> 4096
> 	[  246.759270] bogus RWRITE: 27 -> 4096
> 	[  248.020787] bogus RWRITE: 27 -> 4096

Hrm...  Could you add (int)req->rc->id, (int)req->rc->tag and (int)req->tc->tag
to that printk (on either kernel, the problem's apparently not new)?

The question is whether we are mismatching replies, sending bogus requests or
if it's really the server sending bogus replies.  Which qemu version are
you using, BTW?
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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

#1175803 — Re: running out of tags in 9P (was Re: [git pull] vfs part 2)

On Thu, Jul 02, 2015 at 11:19:03AM +0300, Andrey Ryabinin wrote:
> Besides qemu, I've also tried kvmtool with the same result. IOW I'm seeing
> this under kvmtool as well. It just takes a bit longer to reproduce
> this in kvmtool.
> 
> > The bug I suspected to be the cause of that is in tag allocation in
> > net/9p/client.c - we could end up wrapping around 2^16 with enough pending
> > requests and that would have triggered that kind of mess.  However, Andrey
> > doesn't see that test (tag wraparound in p9_client_prepare_req()) trigger.
> > BTW, was that on the run where debugging printk in p9_client_write() *did*
> > trigger?
> 
> Yes, WARN_ON_ONCE() in p9_client_prepare_req() didn't trigger,
> but debug printk in p9_client_write() *did* trigger.

Bloody wonderful...  Could you check if v9fs_write() in qemu
hw/9pfs/virtio-9p.c ever gets to
    offset = 7;
    err = pdu_marshal(pdu, offset, "d", total);
with total > count on your testcase?
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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

#1175831 — Re: running out of tags in 9P (was Re: [git pull] vfs part 2)

On Thu, Jul 02, 2015 at 09:25:30AM +0100, Al Viro wrote:
> On Thu, Jul 02, 2015 at 11:19:03AM +0300, Andrey Ryabinin wrote:
> > Besides qemu, I've also tried kvmtool with the same result. IOW I'm seeing
> > this under kvmtool as well. It just takes a bit longer to reproduce
> > this in kvmtool.
> > 
> > > The bug I suspected to be the cause of that is in tag allocation in
> > > net/9p/client.c - we could end up wrapping around 2^16 with enough pending
> > > requests and that would have triggered that kind of mess.  However, Andrey
> > > doesn't see that test (tag wraparound in p9_client_prepare_req()) trigger.
> > > BTW, was that on the run where debugging printk in p9_client_write() *did*
> > > trigger?
> > 
> > Yes, WARN_ON_ONCE() in p9_client_prepare_req() didn't trigger,
> > but debug printk in p9_client_write() *did* trigger.
> 
> Bloody wonderful...  Could you check if v9fs_write() in qemu
> hw/9pfs/virtio-9p.c ever gets to
>     offset = 7;
>     err = pdu_marshal(pdu, offset, "d", total);
> with total > count on your testcase?

Another thing that might be worth checking: in p9_tag_alloc() (net/9p/client.c)
before
        req->status = REQ_STATUS_ALLOC;
check that req->status == REQ_STATUS_IDLE and yell if it isn't.

BTW, the loop in there (
                /* check again since original check was outside of lock */
                while (tag >= c->max_tag) {
) looks fishy.  If we get more than P9_ROW_MAXTAG allocations at once,
we'll have trouble, but I doubt that this is what we are hitting.  In any
case, adding WARN_ON(c->req[row]); right after
                        row = (tag / P9_ROW_MAXTAG);
wouldn't hurt.  I would be very surprised if that one triggered, though.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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

#1175933 — Re: running out of tags in 9P (was Re: [git pull] vfs part 2)

On 07/02/2015 11:42 AM, Al Viro wrote:
> On Thu, Jul 02, 2015 at 09:25:30AM +0100, Al Viro wrote:
>> On Thu, Jul 02, 2015 at 11:19:03AM +0300, Andrey Ryabinin wrote:
>>> Besides qemu, I've also tried kvmtool with the same result. IOW I'm seeing
>>> this under kvmtool as well. It just takes a bit longer to reproduce
>>> this in kvmtool.
>>>
>>>> The bug I suspected to be the cause of that is in tag allocation in
>>>> net/9p/client.c - we could end up wrapping around 2^16 with enough pending
>>>> requests and that would have triggered that kind of mess.  However, Andrey
>>>> doesn't see that test (tag wraparound in p9_client_prepare_req()) trigger.
>>>> BTW, was that on the run where debugging printk in p9_client_write() *did*
>>>> trigger?
>>>
>>> Yes, WARN_ON_ONCE() in p9_client_prepare_req() didn't trigger,
>>> but debug printk in p9_client_write() *did* trigger.
>>
>> Bloody wonderful...  Could you check if v9fs_write() in qemu
>> hw/9pfs/virtio-9p.c ever gets to
>>     offset = 7;
>>     err = pdu_marshal(pdu, offset, "d", total);
>> with total > count on your testcase?

Added:
+    if (total > count)
+           *(char *)0 = 0

and never hit this condition.

> 
> Another thing that might be worth checking: in p9_tag_alloc() (net/9p/client.c)
> before
>         req->status = REQ_STATUS_ALLOC;
> check that req->status == REQ_STATUS_IDLE and yell if it isn't.
> 

diff --git a/net/9p/client.c b/net/9p/client.c
index 6f4c4c8..16a17a0 100644
--- a/net/9p/client.c
+++ b/net/9p/client.c
@@ -286,6 +286,8 @@ p9_tag_alloc(struct p9_client *c, u16 tag, unsigned int max_size)
        p9pdu_reset(req->rc);

        req->tc->tag = tag-1;
+       if (WARN_ON(req->status != REQ_STATUS_IDLE))
+               pr_err("req->status: %d\n", req->status);
        req->status = REQ_STATUS_ALLOC;

        return req;

[  150.155020] ------------[ cut here ]------------
[  150.156700] WARNING: CPU: 2 PID: 2304 at ../net/9p/client.c:289 p9_client_prepare_req+0x3b0/0x550()
[  150.158404] Modules linked in:
[  150.160177] CPU: 2 PID: 2304 Comm: trinity-c84 Not tainted 4.1.0-rc8+ #409
[  150.161794] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5.1-0-g8936dbb-20141113_115728-nilsson.home.kraxel.org 04/01/2014
[  150.165540]  0000000000000009 ffff8801ed13f7a8 ffffffff8161434b 0000000000000000
[  150.170939]  0000000000000000 ffff8801ed13f7f8 ffffffff8107cf99 ffff8801f451d5f0
[  150.175942]  ffffffff815f6760 0000000000000003 ffff8800bbac00e0 ffff8800bbac00f0
[  150.178393] Call Trace:
[  150.178883]  [<ffffffff8161434b>] dump_stack+0x45/0x57
[  150.179914]  [<ffffffff8107cf99>] warn_slowpath_common+0x99/0xe0
[  150.181375]  [<ffffffff815f6760>] ? p9_client_prepare_req+0x3b0/0x550
[  150.182597]  [<ffffffff8107d145>] warn_slowpath_null+0x15/0x20
[  150.184067]  [<ffffffff815f6760>] p9_client_prepare_req+0x3b0/0x550
[  150.185043]  [<ffffffff815fb1e2>] p9_client_zc_rpc.constprop.5+0xe2/0x730
[  150.186229]  [<ffffffff8161ba46>] ? _raw_spin_unlock+0x16/0x70
[  150.187049]  [<ffffffff815fb100>] ? p9_client_xattrwalk+0x1b0/0x1b0
[  150.188477]  [<ffffffff812b1b5e>] ? idr_remove+0x2ce/0x420
[  150.189443]  [<ffffffff815f5af0>] ? v9fs_unregister_trans+0x70/0x70
[  150.190456]  [<ffffffff812b1890>] ? idr_mark_full+0x80/0x80
[  150.191489]  [<ffffffff815f5af0>] ? v9fs_unregister_trans+0x70/0x70
[  150.193911]  [<ffffffff8161bae7>] ? _raw_spin_unlock_irqrestore+0x47/0xb0
[  150.195462]  [<ffffffff815fcae4>] ? p9_idpool_put+0x54/0x60
[  150.196729]  [<ffffffff812c9906>] ? iov_iter_advance+0xb6/0x240
[  150.199766]  [<ffffffff815fbea3>] p9_client_write+0x333/0x3d0
[  150.201073]  [<ffffffff811a882e>] ? kasan_kmalloc+0x5e/0x70
[  150.202512]  [<ffffffff815fbb70>] ? p9_client_readdir+0x340/0x340
[  150.204115]  [<ffffffff811c80dd>] ? rw_copy_check_uvector+0xed/0x170
[  150.204960]  [<ffffffff812d82d6>] ? __percpu_counter_add+0x26/0xb0
[  150.206517]  [<ffffffff8113574a>] ? generic_write_checks+0xfa/0x1e0
[  150.208092]  [<ffffffff8125c054>] v9fs_file_write_iter+0xc4/0x200
[  150.209642]  [<ffffffff811c9840>] ? __sb_end_write+0x80/0x80
[  150.211305]  [<ffffffff8125bf90>] ? v9fs_file_lock_dotl+0x3d0/0x3d0
[  150.216908]  [<ffffffff81128d14>] ? ctx_sched_in.isra.57+0xe4/0x2f0
[  150.221069]  [<ffffffff811c6d84>] ? rw_verify_area+0x54/0x150
[  150.222570]  [<ffffffff811c7363>] do_readv_writev+0x223/0x450
[  150.229044]  [<ffffffff811290b7>] ? perf_event_context_sched_in.isra.61+0x127/0x180
[  150.231020]  [<ffffffff8125bf90>] ? v9fs_file_lock_dotl+0x3d0/0x3d0
[  150.231862]  [<ffffffff811c7140>] ? vfs_write+0x1e0/0x1e0
[  150.232583]  [<ffffffff81129b7a>] ? __perf_event_task_sched_in+0x5a/0xa0
[  150.233471]  [<ffffffff810aee08>] ? finish_task_switch+0xa8/0x1b0
[  150.234282]  [<ffffffff8161588b>] ? __schedule+0x3db/0xc90
[  150.235020]  [<ffffffff81616197>] ? schedule+0x57/0xd0
[  150.235709]  [<ffffffff8161ba46>] ? _raw_spin_unlock+0x16/0x70
[  150.236493]  [<ffffffff81618a0f>] ? __mutex_lock_slowpath+0x1df/0x200
[  150.239059]  [<ffffffff811c9840>] ? __sb_end_write+0x80/0x80
[  150.242120]  [<ffffffff81618830>] ? __ww_mutex_lock_interruptible+0xe0/0xe0
[  150.245274]  [<ffffffff810ecfd3>] ? hrtimer_start+0x13/0x20
[  150.247527]  [<ffffffff810ee54d>] ? do_setitimer+0x30d/0x400
[  150.249351]  [<ffffffff811c764e>] vfs_writev+0x4e/0x70
[  150.250378]  [<ffffffff811c8348>] SyS_writev+0xa8/0x140
[  150.251545]  [<ffffffff811c82a0>] ? SyS_readv+0x140/0x140
[  150.253208]  [<ffffffff8161c2ae>] system_call_fastpath+0x12/0x71
[  150.256990] ---[ end trace 4f640ea141ed3d61 ]---
[  150.259076] 9pnet: req->status: 4

> BTW, the loop in there (
>                 /* check again since original check was outside of lock */
>                 while (tag >= c->max_tag) {
> ) looks fishy.  If we get more than P9_ROW_MAXTAG allocations at once,
> we'll have trouble, but I doubt that this is what we are hitting.  In any
> case, adding WARN_ON(c->req[row]); right after

I didn't get this. c->reqs[row] is always non-NULL as it should be, so this warning
will trigger all the time.



>                         row = (tag / P9_ROW_MAXTAG);
> wouldn't hurt.  I would be very surprised if that one triggered, though.
> 

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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

#1176454 — Re: running out of tags in 9P (was Re: [git pull] vfs part 2)

On Fri, Jul 03, 2015 at 11:19:31AM +0300, Andrey Ryabinin wrote:
> On 07/02/2015 07:49 PM, Al Viro wrote:
> > On Thu, Jul 02, 2015 at 05:43:32PM +0100, Al Viro wrote:
> >>  	req->tc->tag = tag-1;
> >> +	if (req->status != REQ_STATUS_IDLE)
> >> +		pr_err("using tag %d with odd status (%d)", tag, req->status);
> > 
> > Should be tag - 1 here, actually.
> 
> So, with this change:
> 
> [   81.654695] 9pnet: late delivery, tag 2 already freed
> [   81.655186] 9pnet: mismatched reply [tag = 2]
> [   85.014795] 9pnet: late delivery, tag 4 already freed
> [   85.015753] 9pnet: late delivery, tag 4 already freed
> [   85.016473] 9pnet: late delivery, tag 4 already freed
> [   87.275842] 9pnet: mismatched reply [tag = 5]
> [   88.943223] 9pnet: late delivery, tag 4 already freed
> [   88.943790] 9pnet: late delivery, tag 4 already freed
> [   88.944320] 9pnet: late delivery, tag 4 already freed
> [   88.945050] 9pnet: mismatched reply [tag = 4]
> [  105.551220] 9pnet: late delivery, tag 3 already freed
> [  105.552065] 9pnet: late delivery, tag 3 already freed
> [  114.528467] 9pnet: late delivery, tag 4 already freed
> [  164.791295] 9pnet: late delivery, tag 2 already freed
> [  164.792156] 9pnet: using tag 2 with odd status (4)
> [  164.864398] 9pnet: mismatched reply [tag = 4]
> [  166.419993] 9pnet: mismatched reply [tag = 3]
> [  174.062625] 9pnet: late delivery, tag 3 already freed
> [  174.063121] 9pnet: late delivery, tag 3 already freed
> [  174.063637] 9pnet: late delivery, tag 3 already freed
> [  174.064018] 9pnet: late delivery, tag 3 already freed
> [  174.064547] 9pnet: mismatched reply [tag = 3]
> [  175.418729] 9pnet: late delivery, tag 3 already freed
> [  177.911727] 9pnet: mismatched reply [tag = 1]
> [  235.748520] 9pnet: late delivery, tag 1 already freed
> [  235.749595] 9pnet: using tag 1 with odd status (4)
> [  243.496782] 9pnet: late delivery, tag 6 already freed
> [  243.497697] 9pnet: late delivery, tag 6 already freed
> [  243.499079] 9pnet: mismatched reply [tag = 6]
> [  243.736388] 9pnet: late delivery, tag 1 already freed
> [  243.740019] 9pnet: late delivery, tag 1 already freed
> [  248.337712] 9pnet: late delivery, tag 2 already freed
> [  249.872950] 9pnet: mismatched reply [tag = 9]
> [  252.448858] 9pnet: mismatched reply [tag = 8]
> [  252.668878] 9pnet: mismatched reply [tag = 11]

FWIW, I'd reproduced it here as well.  With the addition of checking in
p9_client_cb() whether the tag is already freed in IDR, reporting ->status
when it's not "sent" and reporting Tflush, I've got this:

[ 2754.713015] 9pnet: flushing 1
[ 2755.516123] 9pnet: flush 1 [3]done
[ 2758.443265] 9pnet: flushing 16
[ 2768.655768] 9pnet: flush 16 [8]done
[ 2783.939538] 9pnet: flushing 30
[ 2786.067856] 9pnet: flush 30 [3]done
[ 2809.784119] 9pnet: [ffff880113213000] delivery in 0, tag 1
[ 2809.948681] 9pnet: [ffff880113213000] using tag 1 with odd status (4)

Here we have delivery when that sucker is into p9_free_req(), but hasn't
removed from IDR yet.

[ 2809.948681] 9pnet: [ffff880113213000] delivery in 0, tag 1
[ 2816.767861] 9pnet: [ffff880113213000] using tag 1 with odd status (4)

Ditto.

[ 2816.767861] 9pnet: flushing 4
[ 2816.769484] 9pnet: flush 4 [5]done
[ 2846.327753] 9pnet: flushing 3
[ 2854.876131] 9pnet: flush 3 [4]done
[ 2856.492801] 9pnet: flushing 6
[ 2857.675642] 9pnet: flush 6 [1]done
[ 2860.051701] 9pnet: [ffff880113213000] delivery in 0, tag 1
[ 2860.052941] 9pnet: [ffff880113213000] late delivery, tag 1 already freed in IDR
[ 2860.680181] 9pnet: [ffff880113213000] using tag 1 with odd status (4)

This has hit between p9_free_req() and reallocating that request.

[ 2909.911815] 9pnet: [ffff880113213000] delivery in 4, tag 1
[ 2909.913145] 9pnet: [ffff880113213000] late delivery, tag 1 already freed in IDR

... while _this_ one has raced with p9_free_req() in a different way.

[ 2910.852202] 9pnet: flushing 3
[ 2917.985941] 9pnet: flush 3 [4]done
[ 2937.600652] 9pnet: flushing 2
[ 2939.775354] 9pnet: flush 2 [4]done
[ 2961.521600] 9pnet: [ffff880113213000] delivery in 0, tag 1
[ 2962.320383] 9pnet: [ffff880113213000] using tag 1 with odd status (4)

Same at the very first one.

[ 2962.320383] 9pnet: [ffff880113213000] delivery in 4, tag 8
[ 3001.578372] 9pnet: [ffff880113213000] delivery in 4, tag 6

Those had hit before p9_free_req().

AFAICS, we get occasional stray responses from somewhere.  And no, it doesn't
seem to be related to flushes or to dropping chan->lock in req_done() (this
run had been with chan->lock taken on the outside of the loop).

What I really don't understand is WTF is it playing with p9_tag_lookup() -
it's stashing req->tc via virtqueue_add_sgs() opaque data argument, fetches
it back in req_done(), then picks ->tag from it and uses p9_tag_lookup() to
find req.  Why not simply pass req instead?  I had been wrong about that
p9_tag_lookup() being able to return NULL, but why bother with it at all?
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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

#1176648 — [PATCH] forgetting to cancel request in interrupted zero-copy 9P RPC (was Re: [git pull] vfs part 2)

On Fri, Jul 03, 2015 at 10:42:10AM +0100, Al Viro wrote:

> AFAICS, we get occasional stray responses from somewhere.  And no, it doesn't
> seem to be related to flushes or to dropping chan->lock in req_done() (this
> run had been with chan->lock taken on the outside of the loop).
> 
> What I really don't understand is WTF is it playing with p9_tag_lookup() -
> it's stashing req->tc via virtqueue_add_sgs() opaque data argument, fetches
> it back in req_done(), then picks ->tag from it and uses p9_tag_lookup() to
> find req.  Why not simply pass req instead?  I had been wrong about that
> p9_tag_lookup() being able to return NULL, but why bother with it at all?


Got it.  What happens is that on zero-copy path a signal hitting in the
end of p9_virtio_zc_request() is treated as "it hadn't been sent, got
an error, fuck off and mark the tag ready for reuse".  No TFLUSH issued,
etc.  As the result, when reply finally *does* arrive (we had actually
sent the request), it plays hell on the entire thing - tag might very
well have been reused by then and an unrelated request sent with the
same tag.  Depending on the timing, results can get rather ugly.

There are still other bogosities found in this thread, and at the very
least we need to cope with genuine corrupted response from server, but
the patch below fixes the problem with stray responses here and stops the
"what do you mean, you'd written 4K?  I've only sent 30 bytes!" problems
here.  10 minutes of trinity running without triggering it, while without
that patch it triggers in 2-3 minutes.

Could you verify that the patch below deals with your setup as well?
If it does, I'm going to put it into tonight's pull request, after I get
some sleep...  Right now I'm about to crawl in direction of bed - 25 hours
of uptime is a bit too much... ;-/

diff --git a/net/9p/client.c b/net/9p/client.c
index 6f4c4c8..8c4941d 100644
--- a/net/9p/client.c
+++ b/net/9p/client.c
@@ -843,7 +843,8 @@ static struct p9_req_t *p9_client_zc_rpc(struct p9_client *c, int8_t type,
 	if (err < 0) {
 		if (err == -EIO)
 			c->status = Disconnected;
-		goto reterr;
+		if (err != -ERESTARTSYS)
+			goto reterr;
 	}
 	if (req->status == REQ_STATUS_ERROR) {
 		p9_debug(P9_DEBUG_ERROR, "req_status error %d\n", req->t_err);
@@ -1647,7 +1648,10 @@ p9_client_write(struct p9_fid *fid, u64 offset, struct iov_iter *from, int *err)
 		if (*err) {
 			trace_9p_protocol_dump(clnt, req->rc);
 			p9_free_req(clnt, req);
+			break;
 		}
+		if (rsize < count)
+			pr_err("mismatched reply [tag = %d]\n", req->tc->tag);
 
 		p9_debug(P9_DEBUG_9P, "<<< RWRITE count %d\n", count);
 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web