Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
From:   Michael Wakabayashi <mwakabayashi@vmware.com>
To:     Olga Kornievskaia <aglo@umich.edu>
CC:     "linux-nfs@vger.kernel.org" <linux-nfs@vger.kernel.org>
Subject: Re: NFSv4: Mounting NFS server which is down, blocks all other NFS
 mounts on same machine
Thread-Topic: NFSv4: Mounting NFS server which is down, blocks all other NFS
 mounts on same machine
Thread-Index: AQHXSrzxNwU+/2izAUaNQrMQbCMgXKrrMRoAgADowkM=
Date:   Thu, 20 May 2021 09:51:54 +0000
Message-ID: <CO1PR05MB810173C0D970DE22AA9535B8B72A9@CO1PR05MB8101.namprd05.prod.outlook.com>
References: <CO1PR05MB810163D3FD8705AFF519F0B4B72D9@CO1PR05MB8101.namprd05.prod.outlook.com>,<CAN-5tyGgWx6F2s=t+0UAJJZEAEfNnv+Sq8eeBbnQYocKOOK8Jg@mail.gmail.com>
In-Reply-To: <CAN-5tyGgWx6F2s=t+0UAJJZEAEfNnv+Sq8eeBbnQYocKOOK8Jg@mail.gmail.com>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="Windows-1252"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: d3b899fe-e398-41d1-8118-08d91b74e662
X-MS-Exchange-CrossTenant-originalarrivaltime: 20 May 2021 09:51:54.4210
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: b39138ca-3cee-4b4a-a4d6-cd83d9dd62f0
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: YXSASwz/7KdrV+5aIvObcbYonlMkSPNok9ZcquDupdize26rMRML+z8248lJuPfKvvG3cQ/ZTRGcBKuZwEl19A==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: MW4PR05MB8697
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org

Hi Orna,=0A=
=0A=
Thank you for looking.=0A=
=0A=
I spent a couple of hours trying to get various=0A=
SystemTap=A0NFS scripts working but mostly got errors.=0A=
=0A=
For example:=0A=
> root@mikes-ubuntu-21-04:~/src/systemtap-scripts/tracepoints# stap nfs4_fs=
info.stp=0A=
>=A0semantic error: unable to find tracepoint variable '$status' (alternati=
ves: $$parms, $$vars, $task, $$name): identifier '$status' at nfs4_fsinfo.s=
tp:7:11=0A=
>=A0=A0 =A0 =A0 =A0 source: terror =3D $status=0A=
>=A0=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 ^=0A=
>=A0Pass 2: analysis failed. =A0[man error::pass2]=0A=
=0A=
If you have any stap scripts that work on Ubuntu=0A=
that you'd=A0like me to run=A0or have pointers on how=0A=
to setup my Ubuntu=A0environment to run them=0A=
successfully,=A0please let me know and I can try again..=0A=
=0A=
=0A=
Here's the call trace for the mount.nfs command=0A=
mounting the bad NFS server/10.1.1.1:=0A=
=0A=
[Thu May 20 08:53:35 2021] task:mount.nfs =A0 =A0 =A0 state:D stack: =A0 =
=A00 pid:13903 ppid: 13900 flags:0x00004000=0A=
[Thu May 20 08:53:35 2021] Call Trace:=0A=
[Thu May 20 08:53:35 2021] =A0? rpc_init_task+0x150/0x150 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0__schedule+0x23d/0x670=0A=
[Thu May 20 08:53:35 2021] =A0? rpc_init_task+0x150/0x150 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0schedule+0x4f/0xc0=0A=
[Thu May 20 08:53:35 2021] =A0rpc_wait_bit_killable+0x25/0xb0 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0__wait_on_bit+0x33/0xa0=0A=
[Thu May 20 08:53:35 2021] =A0? call_reserveresult+0xa0/0xa0 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0out_of_line_wait_on_bit+0x8d/0xb0=0A=
[Thu May 20 08:53:35 2021] =A0? var_wake_function+0x30/0x30=0A=
[Thu May 20 08:53:35 2021] =A0__rpc_execute+0xd4/0x290 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0rpc_execute+0x5e/0x80 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0rpc_run_task+0x13d/0x180 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0rpc_call_sync+0x51/0xa0 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0rpc_create_xprt+0x177/0x1c0 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0rpc_create+0x11f/0x220 [sunrpc]=0A=
[Thu May 20 08:53:35 2021] =A0? __memcg_kmem_charge+0x7d/0xf0=0A=
[Thu May 20 08:53:35 2021] =A0? _cond_resched+0x1a/0x50=0A=
[Thu May 20 08:53:35 2021] =A0nfs_create_rpc_client+0x13a/0x180 [nfs]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_init_client+0x205/0x290 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0? __fscache_acquire_cookie+0x10a/0x210 [fscac=
he]=0A=
[Thu May 20 08:53:35 2021] =A0? nfs_fscache_get_client_cookie+0xa9/0x120 [n=
fs]=0A=
[Thu May 20 08:53:35 2021] =A0? nfs_match_client+0x37/0x2a0 [nfs]=0A=
[Thu May 20 08:53:35 2021] =A0nfs_get_client+0x14d/0x190 [nfs]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_set_client+0xd3/0x120 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_init_server+0xf8/0x270 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_create_server+0x58/0xa0 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_try_get_tree+0x3a/0xc0 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0nfs_get_tree+0x38/0x50 [nfs]=0A=
[Thu May 20 08:53:35 2021] =A0vfs_get_tree+0x2a/0xc0=0A=
[Thu May 20 08:53:35 2021] =A0do_new_mount+0x14b/0x1a0=0A=
[Thu May 20 08:53:35 2021] =A0path_mount+0x1d4/0x4e0=0A=
[Thu May 20 08:53:35 2021] =A0__x64_sys_mount+0x108/0x140=0A=
[Thu May 20 08:53:35 2021] =A0do_syscall_64+0x38/0x90=0A=
[Thu May 20 08:53:35 2021] =A0entry_SYSCALL_64_after_hwframe+0x44/0xa9=0A=
=0A=
=0A=
Here's the call trace for the mount.nfs command=0A=
mounting an available NFS server/10.188.76.67 (which was=0A=
blocked by the first mount.nfs command above):=0A=
[Thu May 20 08:53:35 2021] task:mount.nfs =A0 =A0 =A0 state:D stack: =A0 =
=A00 pid:13910 ppid: 13907 flags:0x00004000 =0A=
[Thu May 20 08:53:35 2021] Call Trace:=0A=
[Thu May 20 08:53:35 2021] =A0__schedule+0x23d/0x670=0A=
[Thu May 20 08:53:35 2021] =A0schedule+0x4f/0xc0=0A=
[Thu May 20 08:53:35 2021] =A0nfs_wait_client_init_complete+0x5a/0x90 [nfs]=
=0A=
[Thu May 20 08:53:35 2021] =A0? wait_woken+0x80/0x80=0A=
[Thu May 20 08:53:35 2021] =A0nfs_match_client+0x1de/0x2a0 [nfs]=0A=
[Thu May 20 08:53:35 2021] =A0? pcpu_block_update_hint_alloc+0xcc/0x2d0=0A=
[Thu May 20 08:53:35 2021] =A0nfs_get_client+0x62/0x190 [nfs]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_set_client+0xd3/0x120 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_init_server+0xf8/0x270 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_create_server+0x58/0xa0 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0nfs4_try_get_tree+0x3a/0xc0 [nfsv4]=0A=
[Thu May 20 08:53:35 2021] =A0nfs_get_tree+0x38/0x50 [nfs]=0A=
[Thu May 20 08:53:35 2021] =A0vfs_get_tree+0x2a/0xc0=0A=
[Thu May 20 08:53:35 2021] =A0do_new_mount+0x14b/0x1a0=0A=
[Thu May 20 08:53:35 2021] =A0path_mount+0x1d4/0x4e0=0A=
[Thu May 20 08:53:35 2021] =A0__x64_sys_mount+0x108/0x140=0A=
[Thu May 20 08:53:35 2021] =A0do_syscall_64+0x38/0x90=0A=
[Thu May 20 08:53:35 2021] =A0entry_SYSCALL_64_after_hwframe+0x44/0xa9=0A=
=0A=
I've pasted the entire dmesg output=A0here:=A0https://pastebin.com/90QJyAL9=
=0A=
=0A=
=0A=
This is the command I ran to mount an unreachable NFS server:=0A=
date; time strace mount.nfs 10.1.1.1:/nopath /tmp/mnt.dead; date=0A=
The strace log:=A0https://pastebin.com/5yVhm77u=0A=
=0A=
This is the command I ran to mount the available NFS server:=0A=
date; time strace mount.nfs 10.188.76.67:/ /tmp/mnt.alive ; date=0A=
The strace log:=A0https://pastebin.com/kTimQ6vH=0A=
=0A=
The procedure:=0A=
- run dmesg -C to clear dmesg logs=0A=
- run mount.nfs on 10.1.1.1 (this IP address is down/not responding to ping=
) which hung=0A=
- run mount.nfs on 10.188.76.67=A0 which also hung=0A=
- "echo t >=A0/proc/sysrq-trigger" to dump the call traces for hung process=
es=0A=
- dmesg -T > dmesg.log to save the dmesg logs=0A=
- control-Z the mount.nfs command to 10.1.1.1=0A=
- "kill -9 %1" in the terminal to kill the mount.nfs to 10.1.1.1=0A=
- mount.nfs to 10.188.76.67 immediately mounts successfully=0A=
  after the first mount is killed (we can see this by the timestamp in the =
logs files)=0A=
=0A=
=0A=
Thanks, Mike=0A=
=0A=
=0A=
=0A=
From: Olga Kornievskaia <aglo@umich.edu>=0A=
Sent: Wednesday, May 19, 2021 12:15 PM=0A=
To: Michael Wakabayashi <mwakabayashi@vmware.com>=0A=
Cc: linux-nfs@vger.kernel.org <linux-nfs@vger.kernel.org>=0A=
Subject: Re: NFSv4: Mounting NFS server which is down, blocks all other NFS=
 mounts on same machine =0A=
=A0=0A=
On Sun, May 16, 2021 at 11:18 PM Michael Wakabayashi=0A=
<mwakabayashi@vmware.com> wrote:=0A=
>=0A=
> Hi,=0A=
>=0A=
> We're seeing what looks like an NFSv4 issue.=0A=
>=0A=
> Mounting an NFS server that is down (ping to this NFS server's IP address=
 does not respond) will block _all_ other NFS mount attempts even if the NF=
S servers are available and working properly (these subsequent mounts hang)=
.=0A=
>=0A=
> If I kill the NFS mount process that's trying to mount the dead NFS serve=
r, the NFS mounts that were blocked will immediately unblock and mount succ=
essfully, which suggests the first mount command is blocking the other moun=
t commands.=0A=
>=0A=
>=0A=
> I verified this behavior using a newly built mount.nfs command from the r=
ecent nfs-utils 2.5.3 package installed on a recent version of Ubuntu Cloud=
 Image 21.04:=0A=
> * https://nam04.safelinks.protection.outlook.com/?url=3Dhttps%3A%2F%2Fsou=
rceforge.net%2Fprojects%2Fnfs%2Ffiles%2Fnfs-utils%2F2.5.3%2F&amp;data=3D04%=
7C01%7Cmwakabayashi%40vmware.com%7Cfe9df245d11945bd70fd08d91afa7565%7Cb3913=
8ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C0%7C637570485288219912%7CUnknown%7CTWFpbG=
Zsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C=
1000&amp;sdata=3D90wWL%2FDqjJMsdlFDxF3hlmyhuS86VwNrtOD%2BLTGxY20%3D&amp;res=
erved=3D0=0A=
> * https://nam04.safelinks.protection.outlook.com/?url=3Dhttps%3A%2F%2Fclo=
ud-images.ubuntu.com%2Freleases%2Fhirsute%2Frelease-20210513%2Fubuntu-21.04=
-server-cloudimg-amd64.ova&amp;data=3D04%7C01%7Cmwakabayashi%40vmware.com%7=
Cfe9df245d11945bd70fd08d91afa7565%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C=
0%7C637570485288219912%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoi=
V2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&amp;sdata=3DiWIB0PuQ1HiOpFGmo=
ViTmzreirD8EJRAkG%2BOw57QTKs%3D&amp;reserved=3D0=0A=
>=0A=
>=0A=
> The reason this looks like it is specific to NFSv4 is from the following =
output showing "vers=3D4.2":=0A=
> > $ strace /sbin/mount.nfs <unreachable-IP-address>:/path /tmp/mnt=0A=
> > [ ... cut ... ]=0A=
> > mount("<unreadhable-IP-address>:/path", "/tmp/mnt", "nfs", 0, "vers=3D4=
.2,addr=3D<unreachable-IP-address>,clien"...^C^Z=0A=
>=0A=
> Also, if I try the same mount.nfs commands but specifying NFSv3, the moun=
t to the dead NFS server hangs, but the mounts to the operational NFS serve=
rs do not block and mount successfully; this bug doesn't happen when using =
NFSv3.=0A=
>=0A=
>=0A=
> We reported this issue under util-linux here:=0A=
> https://nam04.safelinks.protection.outlook.com/?url=3Dhttps%3A%2F%2Fgithu=
b.com%2Fkarelzak%2Futil-linux%2Fissues%2F1309&amp;data=3D04%7C01%7Cmwakabay=
ashi%40vmware.com%7Cfe9df245d11945bd70fd08d91afa7565%7Cb39138ca3cee4b4aa4d6=
cd83d9dd62f0%7C0%7C0%7C637570485288219912%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiM=
C4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&amp;sdata=
=3DWLxFM2Ls5PodPjrvA%2FZninvvHF6LlrO9ywSEMwgcR50%3D&amp;reserved=3D0=0A=
> [mounting nfs server which is down blocks all other nfs mounts on same ma=
chine #1309]=0A=
>=0A=
> I also found an older bug on this mailing list that had similar symptoms =
(but could not tell if it was the same problem or not):=0A=
> https://nam04.safelinks.protection.outlook.com/?url=3Dhttps%3A%2F%2Fpatch=
work.kernel.org%2Fproject%2Flinux-nfs%2Fpatch%2F87vaori26c.fsf%40notabene.n=
eil.brown.name%2F&amp;data=3D04%7C01%7Cmwakabayashi%40vmware.com%7Cfe9df245=
d11945bd70fd08d91afa7565%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C0%7C63757=
0485288219912%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiL=
CJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&amp;sdata=3DY6A61VJQ6IDwsvUjjBc%2Fjrf8=
0rvGSkaIjc0UhWRQ9kk%3D&amp;reserved=3D0=0A=
> [[PATCH/RFC] NFSv4: don't let hanging mounts block other mounts]=0A=
>=0A=
> Thanks, Mike=0A=
=0A=
Hi Mike,=0A=
=0A=
This is not a helpful reply but I was curious if I could reproduce=0A=
your issue but was not successful. I'm able to initiate a mount to an=0A=
unreachable-IP-address which hangs and then do another mount to an=0A=
existing server without issues. Ubuntu 21.04 seems to be 5.11 based so=0A=
I tried upstream 5.11 and I tried the latest upstream nfs-utils=0A=
(instead of what my distro has which was an older version).=0A=
=0A=
To debug, perhaps get an output of the nfs4 and sunrpc tracepoints.=0A=
Or also get output from dmesg after doing =93echo t >=0A=
/proc/sysrq-trigger=94 to see where the mounts are hanging.=