Dear NFS (client) developers,
Today I notice, that during mount nfs client sends two EXCHANGE_ID operations:
4 0.000380551 131.169.185.213 → 131.169.191.144 NFS V4 NULL Call
6 0.001052087 131.169.191.144 → 131.169.185.213 NFS V4 NULL Reply (Call In 4)
8 0.001501687 131.169.185.213 → 131.169.191.144 NFS V4 Call EXCHANGE_ID
9 0.002105356 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 8) EXCHANGE_ID
11 0.002489297 131.169.185.213 → 131.169.191.144 NFS V4 Call EXCHANGE_ID <----------------------------------- A second one
12 0.003422630 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 11) EXCHANGE_ID
14 0.003569542 131.169.185.213 → 131.169.191.144 NFS V4 Call CREATE_SESSION
17 0.004701642 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 14) CREATE_SESSION
18 0.004822235 131.169.185.213 → 131.169.191.144 NFS V4 Call RECLAIM_COMPLETE
19 0.005317324 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 18) RECLAIM_COMPLETE
20 0.005489908 131.169.185.213 → 131.169.191.144 NFS V4 Call SECINFO_NO_NAME
21 0.006648815 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 20) SECINFO_NO_NAME
I observe this with kernel 5.6 and 5.5. On opposite, the older kernels, like in RHEL7 don't do this
Older kernel (3.10.0-1062.12.1.el7.x86_64)
$ tshark -r ex_id_el7.pcap -Y nfs
8 0.006731652 131.169.240.106 -> 131.169.240.145 NFS 336 V4 Call EXCHANGE_ID
9 0.008812988 131.169.240.145 -> 131.169.240.106 NFS 224 V4 Reply (Call In 8) EXCHANGE_ID
10 0.009127689 131.169.240.106 -> 131.169.240.145 NFS 292 V4 Call CREATE_SESSION
13 0.012583411 131.169.240.145 -> 131.169.240.106 NFS 196 V4 Reply (Call In 10) CREATE_SESSION
14 0.012805867 131.169.240.106 -> 131.169.240.145 NFS 208 V4 Call RECLAIM_COMPLETE
15 0.013716790 131.169.240.145 -> 131.169.240.106 NFS 160 V4 Reply (Call In 14) RECLAIM_COMPLETE
16 0.013981538 131.169.240.106 -> 131.169.240.145 NFS 216 V4 Call SECINFO_NO_NAME
17 0.019359329 131.169.240.145 -> 131.169.240.106 NFS 176 V4 Reply (Call In 16) SECINFO_NO_NAME
This is of course not a big problem, but can point to an unintended change or error. The capture
file available at:
https://sas.desy.de/index.php/s/3sRA9WD5BEpZH7z
Regards,
Tigran.
Hi,
I did some investigation and found that indeed there are two places
there nfs4_proc_exchange_id is called: once in nfs41_init_clientid,
and second time in nfs41_discover_server_trunking.
The nfs41_discover_server_trunking at the and calls nfs4_schedule_state_manager,
which itself call nfs4_reclaim_lease:
mount.nfs-3305 [003] .... 1044.170706: nfs4_exchange_id: error=0 (OK) dstaddr=localhost
::1-manager-3308 [003] .... 1044.170748: nfs4_state_mgr: hostname=localhost clp state=MANAGER_RUNNING|CHECK_LEASE|RECLAIM_NOGRACE|0x4000
::1-manager-3308 [000] .... 1044.171910: nfs4_exchange_id: error=0 (OK) dstaddr=localhost
::1-manager-3308 [000] .... 1044.173263: nfs4_create_session: error=0 (OK) dstaddr=localhost
::1-manager-3308 [000] .... 1044.173272: nfs4_state_mgr: hostname=localhost clp state=MANAGER_RUNNING|CHECK_LEASE|SERVER_SCOPE_MISMATCH
::1-manager-3308 [000] .... 1044.173275: nfs4_setup_sequence: session=0x71274229 slot_nr=0 seq_nr=1 highest_used_slotid=0
::1-manager-3308 [000] .... 1044.174065: nfs4_sequence_done: error=0 (OK) session=0x71274229 slot_nr=0 seq_nr=1 highest_slotid=15 target_highest_slotid=15 status_flags=0 ()
::1-manager-3308 [000] .... 1044.174068: nfs4_reclaim_complete: error=0 (OK) dstaddr=localhost
Not a big deal, but still can be a result of unintended changes.
Regards,
Tigran.
----- Original Message -----
> From: "Tigran Mkrtchyan" <[email protected]>
> To: "linux-nfs" <[email protected]>
> Sent: Wednesday, April 15, 2020 11:39:16 AM
> Subject: multiple EXCHANGE_ID diring a mount.
> Dear NFS (client) developers,
>
> Today I notice, that during mount nfs client sends two EXCHANGE_ID operations:
>
>
> 4 0.000380551 131.169.185.213 → 131.169.191.144 NFS V4 NULL Call
> 6 0.001052087 131.169.191.144 → 131.169.185.213 NFS V4 NULL Reply (Call In 4)
> 8 0.001501687 131.169.185.213 → 131.169.191.144 NFS V4 Call EXCHANGE_ID
> 9 0.002105356 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 8)
> EXCHANGE_ID
> 11 0.002489297 131.169.185.213 → 131.169.191.144 NFS V4 Call EXCHANGE_ID
> <----------------------------------- A second one
> 12 0.003422630 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 11)
> EXCHANGE_ID
> 14 0.003569542 131.169.185.213 → 131.169.191.144 NFS V4 Call CREATE_SESSION
> 17 0.004701642 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 14)
> CREATE_SESSION
> 18 0.004822235 131.169.185.213 → 131.169.191.144 NFS V4 Call RECLAIM_COMPLETE
> 19 0.005317324 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 18)
> RECLAIM_COMPLETE
> 20 0.005489908 131.169.185.213 → 131.169.191.144 NFS V4 Call SECINFO_NO_NAME
> 21 0.006648815 131.169.191.144 → 131.169.185.213 NFS V4 Reply (Call In 20)
> SECINFO_NO_NAME
>
>
> I observe this with kernel 5.6 and 5.5. On opposite, the older kernels, like in
> RHEL7 don't do this
>
> Older kernel (3.10.0-1062.12.1.el7.x86_64)
>
> $ tshark -r ex_id_el7.pcap -Y nfs
> 8 0.006731652 131.169.240.106 -> 131.169.240.145 NFS 336 V4 Call EXCHANGE_ID
> 9 0.008812988 131.169.240.145 -> 131.169.240.106 NFS 224 V4 Reply (Call In 8)
> EXCHANGE_ID
> 10 0.009127689 131.169.240.106 -> 131.169.240.145 NFS 292 V4 Call CREATE_SESSION
> 13 0.012583411 131.169.240.145 -> 131.169.240.106 NFS 196 V4 Reply (Call In 10)
> CREATE_SESSION
> 14 0.012805867 131.169.240.106 -> 131.169.240.145 NFS 208 V4 Call
> RECLAIM_COMPLETE
> 15 0.013716790 131.169.240.145 -> 131.169.240.106 NFS 160 V4 Reply (Call In 14)
> RECLAIM_COMPLETE
> 16 0.013981538 131.169.240.106 -> 131.169.240.145 NFS 216 V4 Call
> SECINFO_NO_NAME
> 17 0.019359329 131.169.240.145 -> 131.169.240.106 NFS 176 V4 Reply (Call In 16)
> SECINFO_NO_NAME
>
>
> This is of course not a big problem, but can point to an unintended change or
> error. The capture
> file available at:
>
> https://sas.desy.de/index.php/s/3sRA9WD5BEpZH7z
>
> Regards,
> Tigran.