The allocation failure is somewhat expected. What isn't is what happened afterward:

    call_reserveresult: status=0, but no request slot, exiting

...and that means that the rpc_task exits with -EIO. I don't see any obvious way to get to call_reserveresult with tk_status == 0 and tk_rqstp == NULL however.

I think I may see the bug...

xprt_alloc_slot does this:

        switch (PTR_ERR(req)) {
        case -ENOMEM:
                rpc_delay(task, HZ >> 2);
                dprintk("RPC:       dynamic allocation of request slot "
                                "failed! Retrying\n");
                break;

...rpc_delay calls:

    rpc_sleep_on(&delay_queue, task, __rpc_atrun);

...and __rpc_atrun does this:

static void __rpc_atrun(struct rpc_task *task)
{
        task->tk_status = 0;
}

... __rpc_atrun becomes the task->tk_callback, so it's going to get run after the task gets woken back up and reset the tk_status to 0.

It's not yet clear to me how to fix this. Perhaps we need a rpc_delay variant that doesn't reset the status?

cc'ing Andy since he did most of the upstream work on this...

Created attachment 585018 [details]
patch -- don't call rpc_delay() after -ENOMEM error from xprt_dynamic_alloc_slot()

Here's a potential patch which should do the right thing. Untested so far,
but it does build.

Jeff, how reproducible is this? Would it be possible to rerun your tests on these low memory hosts and verify that this fixes the issue? If not, maybe we could try to verify this with a fault injection patch that makes every N-th allocation in xprt_dynamic_alloc_slot fail...

Jeff,
 I did verify that it was reproducible. Can you push a scratch build into brew. Let me know the taskid I will re-run the tests.

Thanks,
Jeff

Ok, scratch build kicked off...

Note that we'll also want to suppress those page allocation failure warnings
as well so that this code doesn't spam the logs. I have a patch for that too,
but left it out of this scratch build for now so we could verify that we're
getting some allocation failures during the test run.

Ok, testing last night was somewhat promising. Instead of failing with EIO, we
got this error from the cthon 30M test instead:

write/read 30 MB file
Error: can't sync bigfile37336: Connection timed out

...which is -ETIMEDOUT. In the kernel log, I see a bunch of page allocation failures and then eventually, this:

call_reserveresult: unrecognized error -110, exiting
call_reserveresult: unrecognized error -110, exiting
call_reserveresult: unrecognized error -110, exiting

...I *think* the -ETIMEDOUT is most likely coming from __rpc_queue_timer_fn(). IOW after we get a number of delays, eventually we hit a major RPC timeout and then end up failing the call.

Probably the right solution is to make call_reserveresult handle that error like it would -EAGAIN. Another idea would be to add a new rpc_action that resets the tk_status back to -EAGAIN when the task is ready to run again, but that doesn't
seem quite as clean to me.

Created attachment 585310 [details]
patch -- fix loss of task->tk_status after rpc_delay call in xprt_alloc_slot

Ok, attempt #2...

This adds a new rpc_action that simply resets the task->tk_status back to -EAGAIN afterward. That seems to be the right thing to do since rpc_delay does something similar (resetting it back to 0).

Trond may have a different opinion once I send this upstream, but let's see if this takes care of the problem and then we'll worry about the implementation details.

Note that my analysis in comment #10 is a little off. It looks like we'll always end up with the tk_status getting set to -ETIMEDOUT after the delay due to the fact that the tk_timeout is set to 0 in xprt_reserve.

Jeff Burke reran the test with the new patch last night and it passed this time. I've sent that patch to the upstream mailing list and am waiting for review. I'll plan to post it for 6.3 next week...

This request was evaluated by Red Hat Product Management for inclusion
in a Red Hat Enterprise Linux maintenance release. Product Management has 
requested further review of this request by Red Hat Engineering, for potential
inclusion in a Red Hat Enterprise Linux Update release for currently deployed 
products. This request is not yet committed for inclusion in an Update release.

Created attachment 585624 [details]
patch -- fix loss of task->tk_status after rpc_delay call in xprt_alloc_slot

Trond went with a different patch upstream that moves the error handling into
xprt_alloc_slot, so we'll probably go with a same for RHEL6.

Patch(es) available on kernel-2.6.32-274.el6

(In reply to comment #10)
> Ok, testing last night was somewhat promising. Instead of failing with EIO,
> we
> got this error from the cthon 30M test instead:
> 
> write/read 30 MB file
> Error: can't sync bigfile37336: Connection timed out
> 
> ...which is -ETIMEDOUT. In the kernel log, I see a bunch of page allocation
> failures and then eventually, this:
> 
> call_reserveresult: unrecognized error -110, exiting
> call_reserveresult: unrecognized error -110, exiting
> call_reserveresult: unrecognized error -110, exiting
> 
hi Jeff,
I still got I/O error when I run connectathon against secure nfs:
[root@dell-pesc430-03 cthon04]# ./runcthon --server intel-d3x1311-01.rhts.eng.bos.redhat.com --serverdir /nfs --onlykrb5 --onlyv3| tee log
Fri May 25 05:36:11 EDT 2012
serverdir=/nfs
./server -s -o udp,nfsvers=3,sec=krb5 -m /mnt/nfsv3udp -p /nfs/nfsv3udp intel-d3x1311-01.rhts.eng.bos.redhat.com
./server -s -o tcp,nfsvers=3,sec=krb5 -m /mnt/nfsv3tcp -p /nfs/nfsv3tcp intel-d3x1311-01.rhts.eng.bos.redhat.com
Waiting for 's' to finish...
The '-s' test using '-o udp,nfsvers=3,sec=krb5' args to intel-d3x1311-01.rhts.eng.bos.redhat.com: Failed!!
 Done: 05:39:19 AM
./server -s -o udp,nfsvers=3,sec=krb5i -m /mnt/nfsv3udp -p /nfs/nfsv3udp intel-d3x1311-01.rhts.eng.bos.redhat.com
./server -s -o tcp,nfsvers=3,sec=krb5i -m /mnt/nfsv3tcp -p /nfs/nfsv3tcp intel-d3x1311-01.rhts.eng.bos.redhat.com
Waiting for 's' to finish...
The '-s' test using '-o udp,nfsvers=3,sec=krb5i' args to intel-d3x1311-01.rhts.eng.bos.redhat.com: Failed!!
 Done: 05:39:35 AM
./server -s -o udp,nfsvers=3,sec=krb5p -m /mnt/nfsv3udp -p /nfs/nfsv3udp intel-d3x1311-01.rhts.eng.bos.redhat.com
./server -s -o tcp,nfsvers=3,sec=krb5p -m /mnt/nfsv3tcp -p /nfs/nfsv3tcp intel-d3x1311-01.rhts.eng.bos.redhat.com
Waiting for 's' to finish...
The '-s' test using '-o udp,nfsvers=3,sec=krb5p' args to intel-d3x1311-01.rhts.eng.bos.redhat.com: Failed!!
 Done: 05:39:53 AM

From the nfsudp log:
...
write/read 30 MB file
Error: can't sync bigfile17395: Input/output error
special tests failed
Tests failed, leaving /mnt/nfsv3udp mounted
                                                  
No page allocation failure in /var/log/message.

My test server is intel-d3x1311-01.rhts.eng.bos.redhat.com, client is dell-pesc430-03.rhts.eng.bos.redhat.com:
[root@dell-pesc430-03 cthon04]# free -m
             total       used       free     shared    buffers     cached
Mem:           994        258        736          0         15         81
-/+ buffers/cache:        161        833
Swap:         2015          0       2015

Is the same problem with the bug?

No, this bug is only a problem with TCP and you had a failure over UDP.

It seems like we had a bug reported recently where we were seeing test failures with krb5p mounts, but I can't seem to find it at the moment.

That may be related to bug 747496...

(In reply to comment #28)
> That may be related to bug 747496...
yes, confirm the failure is relate to krb5p/krb5i mounts with UDP, thanks.

Run several connectathon testing on kernel and kernel-debug against 2.6.32-278.el6, also clone the failed job in comment #20, results show good now:
https://beaker.engineering.redhat.com/jobs/242539
https://beaker.engineering.redhat.com/jobs/242541, https://beaker.engineering.redhat.com/jobs/243300

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2012-0862.html