Hi
The following sort of regression was noticed while updating a client
running Debian buster (with autofs 5.1.2 based) to Debian bullseye
(5.1.7 based autofs), but verified it's still present with 5.1.8. The
folloing setup is present:
There is a NFS server, dualstacked, with both public IPv4 and IPv6
addresses resolvable in DNS. As I cannot put the public IPs here in
the report, let's assume It is called nfs-server with addresses
192.168.122.188 and fc00:192:168:122::188.
The client initially running Debian buster, is not dualstacked, has
only IPv4 and has correct routing, e.g. pinging to nfs-server will as
well go to the IPv4 address of nfs-server, or any tcp connection will
go to IPv4 (e.g. ssh -vvv nfs-server).
Automount configuration is fairly simple:
auto.master:
[...]
/home /etc/auto/homes01
[...]
and /etc/auto/homes01
[...]
* nfs-server:/srv/homes/homes01/&
[...]
(note in fact the real configuration is slightly more complex,
nosuid,rw,hard,proto=tcp as options, but veried as wel stripping down the
options, even dropping proto=tcp). I hope I correctly de-anonymized
not messing up with paths in the logs below.
After the update to autofs 5.1.7 based version there is a 10s delay on
mounts from the servers.
In the following logs I had to slightly deanonymize the names. But I
think the delay problem is seen enough by the timestamps.
Before the update, with autofs 5.1.2:
Jul 09 11:54:41 clienthost automount[5143]: handle_packet: type = 3
Jul 09 11:54:41 clienthost automount[5143]: handle_packet_missing_indirect: token 26, name username, request pid 5285
Jul 09 11:54:41 clienthost automount[5143]: attempting to mount entry /home/username
Jul 09 11:54:41 clienthost automount[5143]: lookup_mount: lookup(program): username -> -nosuid,rw,hard,proto=tcp nfs-server:/srv/homes/homes01/username
Jul 09 11:54:41 clienthost automount[5143]: parse_mount: parse(sun): expanded entry: -nosuid,rw,hard,proto=tcp nfs-server:/srv/homes/homes01/username
Jul 09 11:54:41 clienthost automount[5143]: parse_mount: parse(sun): gathered options: nosuid,rw,hard,proto=tcp
Jul 09 11:54:41 clienthost automount[5143]: parse_mount: parse(sun): dequote("nfs-server:/srv/homes/homes01/username") -> nfs-server:/srv/homes/homes01/username
Jul 09 11:54:41 clienthost automount[5143]: parse_mount: parse(sun): core of entry: options=nosuid,rw,hard,proto=tcp, loc=nfs-server:/srv/homes/homes01/username
Jul 09 11:54:41 clienthost automount[5143]: sun_mount: parse(sun): mounting root /home, mountpoint username, what nfs-server:/srv/homes/homes01/username, fstype nfs, options nosuid,rw,hard,proto=tcp
Jul 09 11:54:41 clienthost automount[5143]: mount_mount: mount(nfs): root=/home name=username what=nfs-server:/srv/homes/homes01/username, fstype=nfs, options=nosuid,rw,hard,proto=tcp
Jul 09 11:54:41 clienthost automount[5143]: mount_mount: mount(nfs): nfs options="nosuid,rw,hard,proto=tcp", nobind=0, nosymlink=0, ro=0
Jul 09 11:54:41 clienthost automount[5143]: get_nfs_info: called with host nfs-server(192.168.122.188) proto 6 version 0x30
Jul 09 11:54:41 clienthost automount[5143]: get_nfs_info: nfs v3 rpc ping time: 0.000000
Jul 09 11:54:41 clienthost automount[5143]: get_nfs_info: host nfs-server cost 0 weight 0
Jul 09 11:54:41 clienthost automount[5143]: prune_host_list: selected subset of hosts that support NFS3 over TCP
Jul 09 11:54:41 clienthost automount[5143]: mount_mount: mount(nfs): calling mkdir_path /home/username
Jul 09 11:54:41 clienthost automount[5143]: mount_mount: mount(nfs): calling mount -t nfs -s -o nosuid,rw,hard,proto=tcp nfs-server:/srv/homes/homes01/username /home/username
Jul 09 11:54:41 clienthost automount[5143]: mount_mount: mount(nfs): mounted nfs-server:/srv/homes/homes01/username on /home/username
Jul 09 11:54:41 clienthost automount[5143]: dev_ioctl_send_ready: token = 26
Jul 09 11:54:41 clienthost automount[5143]: mounted /home/username
After the update to 5.1.7 (or 5.1.8):
Jul 09 11:56:23 clienthost automount[6952]: handle_packet: type = 3
Jul 09 11:56:23 clienthost automount[6952]: handle_packet_missing_indirect: token 33, name username, request pid 7104
Jul 09 11:56:23 clienthost automount[6952]: attempting to mount entry /home/username
Jul 09 11:56:23 clienthost automount[6952]: lookup_mount: lookup(program): username -> -nosuid,rw,hard,proto=tcp nfs-server:/srv/homes/homes01/username
Jul 09 11:56:23 clienthost automount[6952]: parse_mount: parse(sun): expanded entry: -nosuid,rw,hard,proto=tcp nfs-server:/srv/homes/homes01/username
Jul 09 11:56:23 clienthost automount[6952]: parse_mount: parse(sun): gathered options: nosuid,rw,hard,proto=tcp
Jul 09 11:56:23 clienthost automount[6952]: parse_mount: parse(sun): dequote("nfs-server:/srv/homes/homes01/username") -> nfs-server:/srv/homes/homes01/username
Jul 09 11:56:23 clienthost automount[6952]: parse_mount: parse(sun): core of entry: options=nosuid,rw,hard,proto=tcp, loc=nfs-server:/srv/homes/homes01/username
Jul 09 11:56:23 clienthost automount[6952]: sun_mount: parse(sun): mounting root /home, mountpoint username, what nfs-server:/srv/homes/homes01/username, fstype nfs, options nosuid,rw,hard,proto=tcp
Jul 09 11:56:23 clienthost automount[6952]: mount(nfs): root=/home name=username what=nfs-server:/srv/homes/homes01/username, fstype=nfs, options=nosuid,rw,hard,proto=tcp
Jul 09 11:56:23 clienthost automount[6952]: mount(nfs): nfs options="nosuid,rw,hard,proto=tcp", nobind=0, nosymlink=0, ro=0
Jul 09 11:56:23 clienthost automount[6952]: get_nfs_info: called with host nfs-server(192.168.122.188) proto 6 version 0x20
Jul 09 11:56:23 clienthost automount[6952]: get_nfs_info: nfs v3 rpc ping time: 0.000184
Jul 09 11:56:23 clienthost automount[6952]: get_nfs_info: host nfs-server cost 183 weight 0
Jul 09 11:56:23 clienthost automount[6952]: prune_host_list: selected subset of hosts that support NFS3 over TCP
Jul 09 11:56:23 clienthost automount[6952]: get_supported_ver_and_cost: called with host nfs-server(fc00:192:168:122::188) version 0x20
Jul 09 11:56:33 clienthost automount[6952]: get_supported_ver_and_cost: rpc ping time 0.000352
Jul 09 11:56:33 clienthost automount[6952]: get_supported_ver_and_cost: cost 352 weight 0
Jul 09 11:56:33 clienthost automount[6952]: mount_mount: mount(nfs): calling mkdir_path /home/username
Jul 09 11:56:33 clienthost automount[6952]: mount(nfs): calling mount -t nfs -s -o nosuid,rw,hard,proto=tcp nfs-server:/srv/homes/homes01/username /home/username
Jul 09 11:56:33 clienthost automount[6952]: mount_mount: mount(nfs): mounted nfs-server:/srv/homes/homes01/username on /home/username
Jul 09 11:56:33 clienthost automount[6952]: dev_ioctl_send_ready: token = 33
Jul 09 11:56:33 clienthost automount[6952]: mounted /home/username
while first get_nfs_info is called again with host
nfs-server(192.168.12.2188), there is a get_supported_ver_and_cost
with the IPv6 address, hanging for 10s.
If I just revert c578e5b37c3c ("autofs-5.1.5 - Fix NFS mount from IPv6
addresses") then the mount is again quick, but logs an additional
Jul 09 16:31:34 clienthost automount[12045]: check_address_proto: requested protocol does not match address
so likely not the right fix.
I suspect mounts from server, which are dualstacked, but route to them
is only IPv4, are not correctly handled after 90532146bc0e
("autofs-5.1.3 - fix ipv6 proto option handling") and c578e5b37c3c
("autofs-5.1.5 - Fix NFS mount from IPv6 addresses").
(note the package in Debian *is* built with --with-libtirpc).
Does any of the above make sense?
Regards,
Salvatore
