Bug#710490: autofs caches hostname lookup failures - doesn't work if started before network ready

[John Hughes]

Package: autofs
Version: 5.0.7-3
Severity: normal

Dear Maintainer,

* What led up to the situation?

We use autofs to mount home directories from a nfs4 server.

The clients get their IP address and so on from a DHCP server.

* What exactly did you do (or not do) that was effective (or
ineffective)?

Boot the system.

* What was the outcome of this action?

autofs starts before the (rather slow) DHCP connection is initialised, so
the hostname lookup for the nfs4 server fails.

When the user tries to log on (after the DHCP connection has been initialised)
autofs still claims that it can't find the nfs4 server.

If autofs is restarted it works.

* What outcome did you expect instead?

Autofs should retry hostname lookups.

My autofs config is:

/etc/auto.master:
/home file:/etc/auto.home

/etc/auto.home:
* -fstype=nfs4,sec=krb5 olympic.calvaedi.com:/home/&

/var/log/syslog shows:

May 31 12:06:49 celtic rsyslogd: [origin software="rsyslogd" swVersion="7.3.15" x-pid="2287" x-info="http://www.rsyslog.com"] start
....
automount does lookup before network ready, fails:

May 31 12:07:22 celtic automount[2669]: add_host_addrs: hostname lookup failed: Name or service not known

Network comes up:

May 31 12:07:24 celtic dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 12
May 31 12:07:29 celtic NetworkManager[2856]: <info> (eth0): IP6 addrconf timed out or failed.
May 31 12:07:29 celtic NetworkManager[2856]: <info> Activation (eth0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
May 31 12:07:29 celtic NetworkManager[2856]: <info> Activation (eth0) Stage 4 of 5 (IPv6 Configure Timeout) started...
May 31 12:07:29 celtic NetworkManager[2856]: <info> Activation (eth0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
May 31 12:07:36 celtic dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
May 31 12:07:43 celtic dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 10
May 31 12:07:43 celtic dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
May 31 12:07:43 celtic dhclient: DHCPOFFER from 192.168.6.215
May 31 12:07:43 celtic dhclient: DHCPACK from 192.168.6.215
May 31 12:07:43 celtic NetworkManager[2856]: <info> (eth0): DHCPv4 state changed preinit -> bound
May 31 12:07:43 celtic dhclient: bound to 192.168.6.107 -- renewal in 239 seconds.
May 31 12:07:43 celtic NetworkManager[2856]: <info> address 192.168.6.107
May 31 12:07:43 celtic NetworkManager[2856]: <info> prefix 24 (255.255.255.0)
May 31 12:07:43 celtic NetworkManager[2856]: <info> gateway 192.168.6.1
May 31 12:07:43 celtic NetworkManager[2856]: <info> nameserver '192.168.6.1'
May 31 12:07:43 celtic NetworkManager[2856]: <info> domain name 'calvaedi.com'
May 31 12:07:43 celtic NetworkManager[2856]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
May 31 12:07:43 celtic NetworkManager[2856]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Commit) started...
May 31 12:07:43 celtic avahi-daemon[2787]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.6.107.
May 31 12:07:43 celtic avahi-daemon[2787]: New relevant interface eth0.IPv4 for mDNS.
May 31 12:07:43 celtic avahi-daemon[2787]: Registering new address record for 192.168.6.107 on eth0.IPv4.
May 31 12:07:44 celtic NetworkManager[2856]: <info> (eth0): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
May 31 12:07:44 celtic NetworkManager[2856]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Commit) complete.
May 31 12:07:44 celtic NetworkManager[2856]: <info> (eth0): device state change: secondaries -> activated (reason 'none') [90 100 0]
May 31 12:07:44 celtic ntpd[2487]: Listen normally on 5 eth0 192.168.6.107 UDP 123
May 31 12:07:44 celtic ntpd[2487]: peers refreshed
May 31 12:07:45 celtic NetworkManager[2856]: <info> Policy set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS.
May 31 12:07:45 celtic NetworkManager[2856]: <info> Activation (eth0) successful, device activated.
May 31 12:07:45 celtic dbus[2737]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
May 31 12:07:45 celtic dbus[2737]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 31 12:07:45 celtic kernel: [ 67.385301] NFS: Registering the id_resolver key type
May 31 12:07:45 celtic kernel: [ 67.385317] Key type id_resolver registered
May 31 12:07:45 celtic kernel: [ 67.385319] Key type id_legacy registered
May 31 12:07:45 celtic kernel: [ 67.553059] sha1_ssse3: Using AVX optimized SHA-1 implementation
May 31 12:07:50 celtic nslcd[2481]: [200854] <passwd="john"> connected to LDAP server ldaps://olympic.calvaedi.com
May 31 12:07:50 celtic nslcd[2481]: [200854] <passwd="john"> (re)loading /etc/nsswitch.conf
....

User attempts to log on, automount keeps complaining that it can't
find the nfs server, fails to mount home directory:

May 31 12:13:06 celtic automount[2669]: add_host_addrs: hostname lookup failed: Name or service not known
May 31 12:13:12 celtic automount[2669]: add_host_addrs: hostname lookup failed: Name or service not known
May 31 12:13:25 celtic automount[2669]: add_host_addrs: hostname lookup failed: Name or service not known

-- System Information:
Debian Release: jessie/sid
APT prefers unstable
APT policy: (500, 'unstable'), (1, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 3.8-2-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash

Versions of packages autofs depends on:
ii libc6 2.17-3
ii libxml2 2.8.0+dfsg1-7+nmu1
ii multiarch-support 2.17-3
ii ucf 3.0027

Versions of packages autofs recommends:
ii kmod 9-3
ii module-init-tools 9-3
ii nfs-common 1:1.2.6-3

autofs suggests no packages.

-- Configuration Files:
/etc/default/autofs changed:
MASTER_MAP_NAME="/etc/auto.master"
TIMEOUT=300
BROWSE_MODE="no"


-- no debconf information


--
To UNSUBSCRIBE, email to debian-bugs-...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org

[John Hughes]

On reflection, and checking some systems that haven't been updated, I'm
99% sure this is not a bug in autofs but in some library routine.

I'll investigate to see what I can find.

[Petter Reinholdtsen]

Control: user debia...@lists.debian.org
Control: usertag -1 + debian-edu

I believe I ran into a similar problem in Debian Edu when booting a
workstation with a slow DHCP server, autofs did not work. Any hope to
have this fixed in Jessie?

Our best idea so far is to reload autofs using a hook in
/etc/dhcp/dhclient-exit-hooks.d/ to reload autofs when dhclient is done.
Would that be an OK approach to add to autofs?

--
Happy hacking
Petter Reinholdtsen

[Michael Tokarev]

13.11.2014 19:21, Petter Reinholdtsen wrote:
> Control: user debia...@lists.debian.org
> Control: usertag -1 + debian-edu
>
> I believe I ran into a similar problem in Debian Edu when booting a
> workstation with a slow DHCP server, autofs did not work. Any hope to
> have this fixed in Jessie?

There's no hope to have anything fixed in autofs. Consider the project
is dead upstream -- the amount of upstream bugs is astonishing but
upstream is afraid to change anything risking to break things which
works now.

Thanks,

/mjt

[Petter Reinholdtsen]

I'm testing this script in
/etc/dhcp/dhclient-exit-hooks.d/autofs-reload, to see if I still am
able to trigger the race.

#!/bin/sh
# Workaround for 710490 where autofs cache failing DNS entries
# when started before the network is up.

if [ -r /etc/debian-edu/config ] ; then
. /etc/debian-edu/config
fi

if [ false = "$DHCP_AUTOFS_UPDATE" ] ; then
exit 0
fi

case $reason in
BOUND|RENEW|REBIND|REBOOT)
service autofs reload
;;
EXPIRE|FAIL|RELEASE|STOP)
;;
esac

--
Happy hacking
Petter Reinholdtsen

[Petter Reinholdtsen]

The testing indicate that reloading work as intended, and I have not
been able to reproduce the broken autofs with this hook in place.
Note I adjusted it slightly to syslog when it is called, to make it
easier to understand why autofs is reloaded when reading the log.

This is the version we have in Debian Edu git now:

#!/bin/sh
# Workaround for 710490 where autofs cache failing DNS entries
# when started before the network is up.
if [ -r /etc/debian-edu/config ] ; then
. /etc/debian-edu/config
fi
if [ false = "$DHCP_AUTOFS_UPDATE" ] ; then
exit 0
fi
case $reason in
BOUND|RENEW|REBIND|REBOOT)

logger -t autofs-reload "reloading autofs from dhcp exit hook"

service autofs reload
;;
EXPIRE|FAIL|RELEASE|STOP)
;;
esac

Perhaps this hook should be part of the autofs package instead of
being in the debian-edu-config package?

[John Hughes]

One of my workstations had a bad ethernet cable, so it was connecting to the switch at 100M instead of 1G.  The extra negotiation time meant that automount was always being started before the network was ready.

(Debian bullseye).

--

John HUGHES
Directeur technique
CalvaEDI
An Esker Company
58/A rue du Dessous des Berges, 75013 Paris
Tel. : (+33) 1 4313 3131
Fax : (+33) 1 4313 3139

[Michael Tokarev]

Please let the thing die already. It's been several debian releases :)

Yes, automount is easy to use with its auto.net map, but it really is
not a big deal to generate list of systemd automount units for this,
or just a bunch of fstab records (with x-systemd.automount option).

/mjt