1057934 – NFS access failures and hang up from fast mounting

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1057934 - NFS access failures and hang up from fast mounting

Summary: NFS access failures and hang up from fast mounting

Keywords:
Status:	CLOSED DUPLICATE of bug 1063752
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	autofs
Sub Component:
Version:	7.0
Hardware:	All
OS:	Linux
Priority:	medium
Severity:	high
Target Milestone:	rc
Target Release:	---
Assignee:	Ian Kent
QA Contact:	Filesystem QE
Docs Contact:
URL:
Whiteboard:
Depends On:	1063752 1065155
Blocks:	1084391
TreeView+	depends on / blocked

Reported:	2014-01-26 03:35 UTC by JianHong Yin
Modified:	2014-04-04 08:52 UTC (History)
CC List:	5 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:	128966
Clones:	1084391 (view as bug list)
Environment:
Last Closed:	2014-02-25 17:32:25 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Comment 1 JianHong Yin 2014-01-26 03:40:29 UTC

version info
------------------------------------------------
Time & CURDIR : [2014-01-25 21:07:02 @/mnt/tests/CoreOS/autofs/bugzillas]
Case Name     : /CoreOS/autofs/bugzillas
$HOSTNAME     : intel-chiefriver-01.lab.eng.rdu.redhat.com
Distro Info   : RedHatEnterpriseServer 7.0 : RHEL-7.0-20140116.1
NVR & host    : Linux intel-chiefriver-01.lab.eng.rdu.redhat.com 3.10.0-71.el7.x86_64 #1 SMP Tue Jan 14 13:54:16 EST 2014 x86_64 x86_64 x86_64 GNU/Linux
Package Info  :
	autofs-5.0.7-38.el7.x86_64
------------------------------------------------

the beaker job task:
https://beaker.engineering.redhat.com/jobs/582715

login the client, show the mount info
[root@intel-chiefriver-01 ~]# mount | tail -n2
intel-waimeabay-hedt-01.lab.eng.rdu.redhat.com:/export/340 on /test/340 type nfs4 (rw,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=10.12.0.54,local_lock=none,addr=10.12.0.55)
intel-waimeabay-hedt-01.lab.eng.rdu.redhat.com:/export/341 on /test/341 type nfs4 (rw,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=10.12.0.54,local_lock=none,addr=10.12.0.55)
[root@intel-chiefriver-01 ~]#

the test hangup:
	for i in `seq 800`; do
		ls /test/$i

Comment 5 Ian Kent 2014-01-26 12:08:25 UTC

Quoting from a ten year old bug is confusing to say the least.
The old bug may be relevant but you haven't provided any
information to support that. Or any information at all really.

How about you post a full autofs debug log to start with.

Comment 6 JianHong Yin 2014-01-27 03:59:24 UTC

(In reply to Ian Kent from comment #5)
> Quoting from a ten year old bug is confusing to say the least.
> The old bug may be relevant but you haven't provided any
> information to support that. Or any information at all really.
> 
> How about you post a full autofs debug log to start with.
OK. I has rewrite the test case, add more debug info in TESTOUTPUT.
...

the result:
https://beaker.engineering.redhat.com/jobs/583043

Comment 7 JianHong Yin 2014-01-27 05:12:23 UTC

https://beaker.engineering.redhat.com/jobs/583045

The full test log:
http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2014/01/5830/583045/1209104/18806159/TESTOUT.log

Comment 8 Ian Kent 2014-01-27 23:26:07 UTC

(In reply to Yin.JianHong from comment #7)
> https://beaker.engineering.redhat.com/jobs/583045
> 
> The full test log:
> http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2014/01/5830/583045/
> 1209104/18806159/TESTOUT.log

This log isn't that useful.
More than two thirds of it is missing.

This does sound like reserved port exhaustion.

You have configured the system to have 500 reserved ports usable
so if reserved ports are being used by autofs or mount.nfs then
you won't get 500 successful mounts, it will be some number less
than that. It depends on how many reserved ports are used when
each mount is done and how slowly the mounts take to complete.
If mounting itself is slow you may get more mounts as the
reserved ports become available for re-use after the wait
timeout. 

There are two things we can do to get more information.

First, check what MOUNT_WAIT in the autofs configuration.
If it is not set to -1 then set it to -1 and re-run the test.

If you get more successful mounts then perhaps autofs is using
reserved ports and I can have a look at that.

Second, capture the output of "netstat --inet" and check how
many ports are in a TIME_WAIT state. You need to do this when
mounts start failing or the TIME_WAIT may expire and we won't
get a true picture of what's happening.

This will tell us if we actually do have a reserved port
exhaustion problem.

Ian

Ian

Comment 11 JianHong Yin 2014-01-28 06:59:48 UTC

If not change the /proc/sys/sunrpc/{min,max}_resvport
(use the default value), get the same result:
    https://beaker.engineering.redhat.com/jobs/584051

And the test run in RHEL6 works fine:
    https://beaker.engineering.redhat.com/jobs/584089

Comment 17 JianHong Yin 2014-02-08 02:19:40 UTC

I open the rpcdebug switch:
  http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2014/02/5889/588967/1220463/19039857/TESTOUT.log

The /var/log/messages in latest two mount:(/test/341, /test/342)
-------------------------------------------------------
Feb  7 06:50:26 ibm-ls21-04 automount[11844]: mount_mount: mount(nfs): mounted ibm-ls21-03.rhts.eng.bos.redhat.com:/export/341 on /test/341
Feb  7 06:50:26 ibm-ls21-04 automount[11844]: dev_ioctl_send_ready: token = 680
Feb  7 06:50:26 ibm-ls21-04 automount[11844]: mounted /test/341
Feb  7 06:50:26 ibm-ls21-04 kernel: [13479.816394] RPC:       looking up Generic cred
Feb  7 06:50:26 ibm-ls21-04 kernel: [13479.843039] RPC:       new task initialized, procpid 12037
Feb  7 06:50:26 ibm-ls21-04 kernel: [13479.875900] RPC:       allocated task ffff880228198100
Feb  7 06:50:26 ibm-ls21-04 kernel: [13479.906675] RPC:  8739 __rpc_execute flags=0x80
Feb  7 06:50:27 ibm-ls21-04 kernel: [13479.933861] RPC:  8739 call_start nfs4 proc ACCESS (sync)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13479.966200] RPC:  8739 call_reserve (status 0)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13479.992822] RPC:  8739 reserved req ffff880227d0ac00 xid 3dc27c3f
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.029319] RPC:       wake_up_first(ffff88012968e190 "xprt_sending")
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.067902] RPC:  8739 call_reserveresult (status 0)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.097646] RPC:  8739 call_refresh (status 0)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.124270] RPC:  8739 refreshing UNIX cred ffff88020f61b900
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.158160] RPC:  8739 call_refreshresult (status 0)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.187906] RPC:  8739 call_allocate (status 0)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.215040] RPC:  8739 allocated buffer of size 3228 at ffff8801182bf000
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.255186] RPC:  8739 call_bind (status 0)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.280236] RPC:  8739 call_connect xprt ffff88012968e000 is connected
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.319338] RPC:  8739 call_transmit (status 0)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.346481] RPC:  8739 xprt_prepare_transmit
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.372054] RPC:  8739 rpc_xdr_encode (status 0)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.399713] RPC:  8739 marshaling UNIX cred ffff88020f61b900
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.433611] RPC:  8739 using AUTH_UNIX cred ffff88020f61b900 to wrap rpc data
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.476351] RPC:  8739 xprt_transmit(172)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.500414] RPC:       xs_tcp_send_request(172) = 172
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502607] RPC:       xs_tcp_data_ready...
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502608] RPC:       xs_tcp_data_recv started
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502610] RPC:       reading TCP record fragment of length 124
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502610] RPC:       reading XID (4 bytes)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502611] RPC:       reading reply for XID 3dc27c3f
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502612] RPC:       reading CALL/REPLY flag (4 bytes)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502612] RPC:       read reply XID 3dc27c3f
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502614] RPC:       XID 3dc27c3f read 116 bytes
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502615] RPC:       xprt = ffff88012968e000, tcp_copied = 124, tcp_offset = 124, tcp_reclen = 124
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502616] RPC:  8739 xid 3dc27c3f complete (124 bytes received)
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.502619] RPC:       xs_tcp_data_recv done
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.878438] RPC:  8739 xmit complete
Feb  7 06:50:27 ibm-ls21-04 kernel: [13480.899881] RPC:       wake_up_first(ffff88012968e190 "xprt_sending")
Feb  7 06:50:28 ibm-ls21-04 kernel: [13480.938440] RPC:  8739 call_status (status 124)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13480.965578] RPC:  8739 call_decode (status 124)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13480.992718] RPC:  8739 validating UNIX cred ffff88020f61b900
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.026627] RPC:  8739 using AUTH_UNIX cred ffff88020f61b900 to unwrap rpc data
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.070401] RPC:  8739 call_decode result 0
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.095452] RPC:       wake_up_first(ffff8802172d2a98 "NFSv4.0 transport Slot table")
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.142351] RPC:  8739 return 0, status 0
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.166367] RPC:  8739 release task
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.187270] RPC:       freeing buffer of size 3228 at ffff8801182bf000
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.226368] RPC:  8739 release request ffff880227d0ac00
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.257665] RPC:       wake_up_first(ffff88012968e320 "xprt_backlog")
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.296241] RPC:       rpc_release_client(ffff8801276d1800)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.329623] RPC:  8739 freeing task
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.350556] RPC:       looking up Generic cred
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.377160] RPC:       new task initialized, procpid 12037
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.410018] RPC:       allocated task ffff880228198000
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.440784] RPC:  8740 __rpc_execute flags=0x80
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.467968] RPC:  8740 call_start nfs4 proc GETATTR (sync)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.500826] RPC:  8740 call_reserve (status 0)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.527443] RPC:  8740 reserved req ffff880227d0ac00 xid 3ec27c3f
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.563943] RPC:       wake_up_first(ffff88012968e190 "xprt_sending")
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.602519] RPC:  8740 call_reserveresult (status 0)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.632259] RPC:  8740 call_refresh (status 0)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.658879] RPC:  8740 looking up UNIX cred
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.683941] RPC:       looking up UNIX cred
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.709016] RPC:  8740 refreshing UNIX cred ffff88020f61b900
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.742895] RPC:  8740 call_refreshresult (status 0)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.772636] RPC:  8740 call_allocate (status 0)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.799777] RPC:  8740 allocated buffer of size 3228 at ffff88011919d000
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.839912] RPC:  8740 call_bind (status 0)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.864971] RPC:  8740 call_connect xprt ffff88012968e000 is connected
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.904280] RPC:  8740 call_transmit (status 0)
Feb  7 06:50:28 ibm-ls21-04 kernel: [13481.931417] RPC:  8740 xprt_prepare_transmit
Feb  7 06:50:29 ibm-ls21-04 kernel: [13481.957016] RPC:  8740 rpc_xdr_encode (status 0)
Feb  7 06:50:29 ibm-ls21-04 kernel: [13481.984654] RPC:  8740 marshaling UNIX cred ffff88020f61b900
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.018554] RPC:  8740 using AUTH_UNIX cred ffff88020f61b900 to wrap rpc data
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.061290] RPC:  8740 xprt_transmit(164)
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085320] RPC:       xs_tcp_send_request(164) = 164
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085552] RPC:       xs_tcp_data_ready...
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085554] RPC:       xs_tcp_data_recv started
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085556] RPC:       reading TCP record fragment of length 188
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085556] RPC:       reading XID (4 bytes)
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085558] RPC:       reading reply for XID 3ec27c3f
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085558] RPC:       reading CALL/REPLY flag (4 bytes)
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085559] RPC:       read reply XID 3ec27c3f
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085561] RPC:       XID 3ec27c3f read 180 bytes
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085562] RPC:       xprt = ffff88012968e000, tcp_copied = 188, tcp_offset = 188, tcp_reclen = 188
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085564] RPC:  8740 xid 3ec27c3f complete (188 bytes received)
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.085567] RPC:       xs_tcp_data_recv done
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.462936] RPC:  8740 xmit complete
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.484337] RPC:       wake_up_first(ffff88012968e190 "xprt_sending")
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.522911] RPC:  8740 call_status (status 188)
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.550048] RPC:  8740 call_decode (status 188)
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.577203] RPC:  8740 validating UNIX cred ffff88020f61b900
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.611090] RPC:  8740 using AUTH_UNIX cred ffff88020f61b900 to unwrap rpc data
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.654869] RPC:  8740 call_decode result 0
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.679923] RPC:       wake_up_first(ffff8802172d2a98 "NFSv4.0 transport Slot table")
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.726827] RPC:  8740 return 0, status 0
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.750843] RPC:  8740 release task
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.771752] RPC:       freeing buffer of size 3228 at ffff88011919d000
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.810840] RPC:  8740 release request ffff880227d0ac00
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.842138] RPC:       wake_up_first(ffff88012968e320 "xprt_backlog")
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.880722] RPC:       rpc_release_client(ffff8801276d1800)
Feb  7 06:50:29 ibm-ls21-04 kernel: [13482.914333] RPC:  8740 freeing task
Feb  7 06:50:30 ibm-ls21-04 kernel: [13482.935270] RPC:       new task initialized, procpid 12037
Feb  7 06:50:30 ibm-ls21-04 kernel: [13482.968123] RPC:       allocated task ffff88012993bc00
Feb  7 06:50:30 ibm-ls21-04 kernel: [13482.998892] RPC:  8741 __rpc_execute flags=0x80
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.026085] RPC:  8741 call_start nfs4 proc READDIR (sync)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.058934] RPC:  8741 call_reserve (status 0)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.085563] RPC:  8741 reserved req ffff880227d0ac00 xid 3fc27c3f
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.122058] RPC:       wake_up_first(ffff88012968e190 "xprt_sending")
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.160633] RPC:  8741 call_reserveresult (status 0)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.190372] RPC:  8741 call_refresh (status 0)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.216996] RPC:  8741 refreshing UNIX cred ffff88020f61b900
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.250893] RPC:  8741 call_refreshresult (status 0)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.280629] RPC:  8741 call_allocate (status 0)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.307770] RPC:  8741 allocated buffer of size 7400 at ffff880129b4c000
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.347920] RPC:  8741 call_bind (status 0)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.372967] RPC:  8741 call_connect xprt ffff88012968e000 is connected
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.412071] RPC:  8741 call_transmit (status 0)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.439204] RPC:  8741 xprt_prepare_transmit
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.464785] RPC:  8741 rpc_xdr_encode (status 0)
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.492443] RPC:  8741 marshaling UNIX cred ffff88020f61b900
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.526342] RPC:  8741 using AUTH_UNIX cred ffff88020f61b900 to wrap rpc data
Feb  7 06:50:30 ibm-ls21-04 kernel: [13483.569080] RPC:  8741 xprt_transmit(188)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593143] RPC:       xs_tcp_send_request(188) = 188
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593366] RPC:       xs_tcp_data_ready...
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593368] RPC:       xs_tcp_data_recv started
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593369] RPC:       reading TCP record fragment of length 68
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593370] RPC:       reading XID (4 bytes)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593371] RPC:       reading reply for XID 3fc27c3f
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593371] RPC:       reading CALL/REPLY flag (4 bytes)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593372] RPC:       read reply XID 3fc27c3f
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593373] RPC:       XID 3fc27c3f read 60 bytes
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593374] RPC:       xprt = ffff88012968e000, tcp_copied = 68, tcp_offset = 68, tcp_reclen = 68
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593375] RPC:  8741 xid 3fc27c3f complete (68 bytes received)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.593379] RPC:       xs_tcp_data_recv done
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.967890] RPC:  8741 xmit complete
Feb  7 06:50:31 ibm-ls21-04 kernel: [13483.989348] RPC:       wake_up_first(ffff88012968e190 "xprt_sending")
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.027904] RPC:  8741 call_status (status 68)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.054516] RPC:  8741 call_decode (status 68)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.081134] RPC:  8741 validating UNIX cred ffff88020f61b900
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.115041] RPC:  8741 using AUTH_UNIX cred ffff88020f61b900 to unwrap rpc data
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.158828] RPC:  8741 call_decode result 8
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.183868] RPC:       wake_up_first(ffff8802172d2a98 "NFSv4.0 transport Slot table")
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.230778] RPC:  8741 return 0, status 8
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.254781] RPC:  8741 release task
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.275683] RPC:       freeing buffer of size 7400 at ffff880129b4c000
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.314777] RPC:  8741 release request ffff880227d0ac00
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.346074] RPC:       wake_up_first(ffff88012968e320 "xprt_backlog")
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.384653] RPC:       rpc_release_client(ffff8801276d1800)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.418033] RPC:  8741 freeing task
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: handle_packet: type = 3
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: handle_packet_missing_indirect: token 683, name 342, request pid 12575
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: attempting to mount entry /test/342
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: lookup_mount: lookup(file): looking up 342
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: lookup_mount: lookup(file): 342 -> ibm-ls21-03.rhts.eng.bos.redhat.com:/export/&
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: parse_mount: parse(sun): expanded entry: ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: parse_mount: parse(sun): gathered options:
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: parse_mount: parse(sun): dequote("ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342") -> ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: parse_mount: parse(sun): core of entry: options=, loc=ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: sun_mount: parse(sun): mounting root /test, mountpoint 342, what ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342, fstype nfs, options (null)
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: mount_mount: mount(nfs): root=/test name=342 what=ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342, fstype=nfs, options=(null)
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: get_nfs_info: called with host ibm-ls21-03.rhts.eng.bos.redhat.com(10.16.67.13) proto 6 version 0x40
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: get_nfs_info: nfs v4 rpc ping time: 0.000163
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: get_nfs_info: host ibm-ls21-03.rhts.eng.bos.redhat.com cost 163 weight 0
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: prune_host_list: selected subset of hosts that support NFS4 over TCP
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: mount_mount: mount(nfs): calling mkdir_path /test/342
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: mount_mount: mount(nfs): calling mount -t nfs ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342 /test/342
Feb  7 06:50:31 ibm-ls21-04 automount[11844]: spawn_mount: mtab link detected, passing -n to mount
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.586291] RPC:       creating nfs client for ibm-ls21-03.rhts.eng.bos.redhat.com (xprt ffff88012968e000)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.644487] RPC:       creating UNIX authenticator for client ffff880118f3f000
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.687765] RPC:       creating GSS authenticator for client ffff8801293cdc00
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.730571] RPC:       new task initialized, procpid 12579
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.763410] RPC:       allocated task ffff8802290c9000
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.794192] RPC:  8742 __rpc_execute flags=0x80
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.821363] RPC:  8742 call_start nfs4 proc LOOKUP_ROOT (sync)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.856263] RPC:  8742 call_reserve (status 0)
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.882883] RPC:  8742 reserved req ffff880227d0ac00 xid 40c27c3f
Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.919383] RPC:       wake_up_first(ffff88012968e190 "xprt_sending")
Feb  7 06:50:32 ibm-ls21-04 kernel: [13484.957958] RPC:  8742 call_reserveresult (status 0)
Feb  7 06:50:32 ibm-ls21-04 kernel: [13484.987691] RPC:  8742 call_refresh (status 0)
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.014314] RPC:  8742 looking up RPCSEC_GSS cred
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.042489] RPC:       looking up RPCSEC_GSS cred
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.070669] RPC:       gss_create_cred for uid 0, flavor 390005
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.106287] RPC:       gss_create_upcall for uid 0
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.134988] RPC: AUTH_GSS upcall failed. Please check user daemon is running.
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.177718] RPC:  8742 call_refreshresult (status -13)
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.208497] RPC:  8742 call_refreshresult: refresh creds failed with error -13
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.251757] RPC:  8742 return 0, status -13
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.276813] RPC:  8742 release task
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.297718] RPC:  8742 release request ffff880227d0ac00
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.329016] RPC:       wake_up_first(ffff88012968e320 "xprt_backlog")
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.367590] RPC:       rpc_release_client(ffff880118f3f000)
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.400968] RPC:  8742 freeing task
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.421867] RPC:       creating GSS authenticator for client ffff8801293cdc00
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.464609] RPC:       destroying GSS authenticator ffff8801193b6798 flavor 390005
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.509954] RPC:       new task initialized, procpid 12579
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.542798] RPC:       allocated task ffff8802290c9000
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.573583] RPC:  8743 __rpc_execute flags=0x80
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.600726] RPC:  8743 sleep_on(queue "NFSv4.0 transport Slot table" time 4308152897)
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.647622] RPC:  8743 added to queue ffff8802172d2a98 "NFSv4.0 transport Slot table"
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.694513] RPC:  8743 sync task going to sleep
Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.728035] RPC:       gss_free_cred cred=ffff8802286746c0
Feb  7 06:50:47 ibm-ls21-04 logger: 2014-02-07 06:50:47 /usr/bin/rhts-test-runner.sh 30087 13500 hearbeat...

Comment 18 Ian Kent 2014-02-09 02:21:23 UTC

(In reply to Yin.JianHong from comment #17)
> I open the rpcdebug switch:
>  
> http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2014/02/5889/588967/
> 1220463/19039857/TESTOUT.log
> 
> The /var/log/messages in latest two mount:(/test/341, /test/342)
> -------------------------------------------------------

snip ...

> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: handle_packet: type = 3
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]:
> handle_packet_missing_indirect: token 683, name 342, request pid 12575
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: attempting to mount entry
> /test/342
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: lookup_mount: lookup(file):
> looking up 342
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: lookup_mount: lookup(file):
> 342 -> ibm-ls21-03.rhts.eng.bos.redhat.com:/export/&
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: parse_mount: parse(sun):
> expanded entry: ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: parse_mount: parse(sun):
> gathered options:
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: parse_mount: parse(sun):
> dequote("ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342") ->
> ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: parse_mount: parse(sun): core
> of entry: options=, loc=ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: sun_mount: parse(sun):
> mounting root /test, mountpoint 342, what
> ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342, fstype nfs, options (null)
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: mount_mount: mount(nfs):
> root=/test name=342 what=ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342,
> fstype=nfs, options=(null)
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: get_nfs_info: called with host
> ibm-ls21-03.rhts.eng.bos.redhat.com(10.16.67.13) proto 6 version 0x40
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: get_nfs_info: nfs v4 rpc ping
> time: 0.000163
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: get_nfs_info: host
> ibm-ls21-03.rhts.eng.bos.redhat.com cost 163 weight 0
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: prune_host_list: selected
> subset of hosts that support NFS4 over TCP
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: mount_mount: mount(nfs):
> calling mkdir_path /test/342
> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: mount_mount: mount(nfs):
> calling mount -t nfs ibm-ls21-03.rhts.eng.bos.redhat.com:/export/342
> /test/342

Mount command, no GSS auth in that ...

> Feb  7 06:50:31 ibm-ls21-04 automount[11844]: spawn_mount: mtab link
> detected, passing -n to mount
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.586291] RPC:       creating nfs
> client for ibm-ls21-03.rhts.eng.bos.redhat.com (xprt ffff88012968e000)
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.644487] RPC:       creating UNIX
> authenticator for client ffff880118f3f000
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.687765] RPC:       creating GSS
> authenticator for client ffff8801293cdc00

So why is this happening ....

> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.730571] RPC:       new task
> initialized, procpid 12579
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.763410] RPC:       allocated task
> ffff8802290c9000
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.794192] RPC:  8742 __rpc_execute
> flags=0x80
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.821363] RPC:  8742 call_start
> nfs4 proc LOOKUP_ROOT (sync)
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.856263] RPC:  8742 call_reserve
> (status 0)
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.882883] RPC:  8742 reserved req
> ffff880227d0ac00 xid 40c27c3f
> Feb  7 06:50:31 ibm-ls21-04 kernel: [13484.919383] RPC:      
> wake_up_first(ffff88012968e190 "xprt_sending")
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13484.957958] RPC:  8742
> call_reserveresult (status 0)
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13484.987691] RPC:  8742 call_refresh
> (status 0)
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.014314] RPC:  8742 looking up
> RPCSEC_GSS cred
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.042489] RPC:       looking up
> RPCSEC_GSS cred
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.070669] RPC:      
> gss_create_cred for uid 0, flavor 390005
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.106287] RPC:      
> gss_create_upcall for uid 0
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.134988] RPC: AUTH_GSS upcall
> failed. Please check user daemon is running.

Ummm .... no surprise there since GSS isn't being used or
asked for so it's probably not set up.

> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.177718] RPC:  8742
> call_refreshresult (status -13)
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.208497] RPC:  8742
> call_refreshresult: refresh creds failed with error -13
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.251757] RPC:  8742 return 0,
> status -13
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.276813] RPC:  8742 release task
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.297718] RPC:  8742 release
> request ffff880227d0ac00
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.329016] RPC:      
> wake_up_first(ffff88012968e320 "xprt_backlog")
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.367590] RPC:      
> rpc_release_client(ffff880118f3f000)
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.400968] RPC:  8742 freeing task
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.421867] RPC:       creating GSS
> authenticator for client ffff8801293cdc00
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.464609] RPC:       destroying GSS
> authenticator ffff8801193b6798 flavor 390005
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.509954] RPC:       new task
> initialized, procpid 12579
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.542798] RPC:       allocated task
> ffff8802290c9000
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.573583] RPC:  8743 __rpc_execute
> flags=0x80
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.600726] RPC:  8743 sleep_on(queue
> "NFSv4.0 transport Slot table" time 4308152897)

Mmmm ... added to a wait queue ... but waiting for what!

Is it this that waits forever?
Why is the wait not abandoned when the mount process is terminated?

> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.647622] RPC:  8743 added to queue
> ffff8802172d2a98 "NFSv4.0 transport Slot table"
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.694513] RPC:  8743 sync task
> going to sleep
> Feb  7 06:50:32 ibm-ls21-04 kernel: [13485.728035] RPC:       gss_free_cred
> cred=ffff8802286746c0
> Feb  7 06:50:47 ibm-ls21-04 logger: 2014-02-07 06:50:47
> /usr/bin/rhts-test-runner.sh 30087 13500 hearbeat...

Help me out here folks ....
Ian

Comment 19 JianHong Yin 2014-02-11 06:35:38 UTC

I create a new nfs test case: reproduce this bug:
/CoreOS/nfs-utils/Regression/fast-mount
  https://beaker.engineering.redhat.com/jobs/590762

So this is not an autofs bug, instead nfs-kernel or nfs-utils.

Comment 21 Ric Wheeler 2014-02-25 17:32:25 UTC

Please reopen if this is not a duplicate.

*** This bug has been marked as a duplicate of bug 1063752 ***

Note You need to log in before you can comment on or make changes to this bug.