[Pkg-utopia-maintainers] Bug#559927: /usr/lib/avahi/avahi-daemon-check-dns.sh significantly delays the boot sequence

Sun Jun 22 08:34:53 UTC 2014

Package: avahi-daemon
Version: 0.6.31-4
Followup-For: Bug #559927

Dear Maintainer,

This bug is still present in the current version of avahi-daemon. In my case,
the delay introduced by the 'host -t soa local.' of avahi-daemon-check-dns.sh is
exactly of 10 seconds, always. I've patched the script to measure the elapsed
time (the patch is attached below), and logged the boot sequence using bootlogd. I
include you an example of the output (ASCII color codes removed).

The thing is I am using my own DNS server, so I have in my /etc/resolv.conf:

    nameserver 127.0.0.1

When the ifup of the eth0 invokes avahi-daemon-check-dns.sh, the bind9 daemon is
not running yet, and probably the 'host' command is running out its timeouts
trying to resolve the .local zone without success. If I use remote DNS servers
in /etc/resolv.conf, the script is working as intended and the delayed time is
about 2 seconds (that time depends of the latency of the DNS server responses
obviously).

Note that later, when the system already boots up and bind9 is running, the time
of a invocation to 'host -t soa local.' is less than 0.1 seconds, 0.01 in the
median time (when cached):

    $ time host -t soa local.
    Host local. not found: 3(NXDOMAIN)

    real    0m0.088s
    user    0m0.008s
    sys     0m0.000s

I know this delay can be avoided by disabling the check of the unicast .local
zone using AVAHI_DAEMON_DETECT_LOCAL=0 in /etc/default/avahi-daemon. But I'd
like to say that the assumption that you can always make a DNS resolution after
the interface is up is a risky one, and in a local DNS configuration is
blantanly false. Perhaps you could consider to move the checking just when the
avahi daemon is launched, and not as a part of the ifupdown process (that can
also introduce the delay not only in the boot sequence but also in the shutdown
process).

-- System Information:
Debian Release: jessie/sid
  APT prefers testing
  APT policy: (600, 'testing'), (100, 'unstable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

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

Versions of packages avahi-daemon depends on:
ii  adduser              3.113+nmu3
ii  bind9-host [host]    1:9.9.5.dfsg-4
ii  dbus                 1.8.4-1
ii  init-system-helpers  1.19
ii  libavahi-common3     0.6.31-4
ii  libavahi-core7       0.6.31-4
ii  libc6                2.19-1
ii  libcap2              1:2.22-1.2
ii  libdaemon0           0.14-6
ii  libdbus-1-3          1.8.4-1
ii  libexpat1            2.1.0-6
ii  lsb-base             4.1+Debian13

Versions of packages avahi-daemon recommends:
ii  libnss-mdns  0.10-6

Versions of packages avahi-daemon suggests:
pn  avahi-autoipd  <none>

-- no debconf information
-------------- next part --------------
57a58,59
>   DEBUG_HOST_CMD_TIME=`LC_ALL=C date +%T`
>   echo "\n[$DEBUG_HOST_CMD_TIME] Before calling host -t soa local."
59a62,63
>     DEBUG_HOST_CMD_TIME=`LC_ALL=C date +%T`
>     echo "[$DEBUG_HOST_CMD_TIME] After calling host -t soa local."
63a68,69
>     DEBUG_HOST_CMD_TIME=`LC_ALL=C date +%T`
>     echo "[$DEBUG_HOST_CMD_TIME] After calling host -t soa local."
-------------- next part --------------
Sun Jun 22 09:27:08 2014: [....] Setting parameters of disc: (none) [ok] .
Sun Jun 22 09:27:08 2014: [....] Setting preliminary keymap... [ok] done.
Sun Jun 22 09:27:08 2014: [....] Activating swap... [ok] done.
Sun Jun 22 09:27:08 2014: [....] Checking root file system...fsck from util-linux 2.20.1
Sun Jun 22 09:27:09 2014: /dev/sda2: clean, 155869/3055616 files, 2107894/12207104 blocks
Sun Jun 22 09:27:09 2014:  [ok] done.
Sun Jun 22 09:27:09 2014: [....] Activating lvm and md swap... [ok] done.
Sun Jun 22 09:27:09 2014: [....] Checking file systems...fsck from util-linux 2.20.1
Sun Jun 22 09:27:10 2014: /dev/sda3: clean, 239788/12214272 files, 16711162/48828160 blocks
Sun Jun 22 09:27:10 2014:  [ok] done.
Sun Jun 22 09:27:10 2014: [....] Cleaning up temporary files... /tmp [ok] .
Sun Jun 22 09:27:10 2014: Loading kernel module firewire-sbp2.
Sun Jun 22 09:27:10 2014: modprobe: FATAL: Module firewire-sbp2 not found.
Sun Jun 22 09:27:10 2014: Loading kernel module loop.
Sun Jun 22 09:27:10 2014: Loading kernel module coretemp.
Sun Jun 22 09:27:10 2014: Loading kernel module f71882fg.
Sun Jun 22 09:27:10 2014: Loading kernel module coretemp.
Sun Jun 22 09:27:10 2014: Loading kernel module f71882fg.
Sun Jun 22 09:27:10 2014: Loading kernel module fuse.
Sun Jun 22 09:27:10 2014: [....] Mounting local filesystems... [ok] done.
Sun Jun 22 09:27:10 2014: [....] Activating swapfile swap... [ok] done.
Sun Jun 22 09:27:10 2014: [....] Cleaning up temporary files... [ok] .
Sun Jun 22 09:27:11 2014: [....] Setting kernel variables ... [ok] done.
Sun Jun 22 09:27:14 2014: [....] Configuring network interfaces...
Sun Jun 22 09:27:14 2014: [09:27:12] Before calling host -t soa local.
Sun Jun 22 09:27:22 2014: [09:27:22] After calling host -t soa local.
Sun Jun 22 09:27:22 2014:  [ok] done.
Sun Jun 22 09:27:22 2014: [....] Starting rpcbind daemon... [ok] .
Sun Jun 22 09:27:22 2014: [....] Starting NFS common utilities: statd [ok] .
Sun Jun 22 09:27:22 2014: [....] Cleaning up temporary files... [ok] .
Sun Jun 22 09:27:23 2014: [....] Setting up ALSA... [ok] done.
Sun Jun 22 09:27:23 2014: Setting console screen modes.
Sun Jun 22 09:27:23 2014: [....] Setting up console font and keymap... [ok] done.
Sun Jun 22 09:27:23 2014: [....] Setting up X socket directories... /tmp/.X11-unix /tmp/.ICE-unix [ok] .
Sun Jun 22 09:27:23 2014: [....] Setting sensors limits [ok] .
Sun Jun 22 09:27:23 2014: INIT: Entering runlevel: 2
Sun Jun 22 09:27:23 2014: Using makefile-style concurrent boot in runlevel 2.
Sun Jun 22 09:27:23 2014: [....] Starting NFS common utilities: statd [ok] .
Sun Jun 22 09:27:23 2014: [....] Not starting fancontrol; run pwmconfig first. [warn] (warning).
Sun Jun 22 09:27:23 2014: [....] Starting enhanced syslogd: rsyslogd [ok] .
Sun Jun 22 09:27:24 2014: [....] Starting deferred execution scheduler: atd [ok] .
Sun Jun 22 09:27:24 2014: [....] Starting domain name service...: bind9 [ok] .
Sun Jun 22 09:27:24 2014: [....] Starting CUPS Bonjour daemon: cups-browsed [ok] .
Sun Jun 22 09:27:24 2014: [....] Starting system message bus: dbus [ok] .
Sun Jun 22 09:27:24 2014: [....] Starting Light Display Manager: lightdm [ok] .
Sun Jun 22 09:27:24 2014: [....] Starting periodic command scheduler: cron [ok] .
Sun Jun 22 09:27:25 2014: [....] Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon [ok] .
Sun Jun 22 09:27:25 2014: saned disabled; edit /etc/default/saned
Sun Jun 22 09:27:25 2014: [....] Starting MTA: exim4 [ok] .
Sun Jun 22 09:27:25 2014: Not starting fetchmail daemon, disabled via /etc/default/fetchmail.
Sun Jun 22 09:27:26 2014: [....] Starting Common Unix Printing System: cupsd [ok] .