dnsmasq starts with error on Ubuntu Xenial amd64 when squid installed

Note that this does not apply to bionic release nor artful for which everything seems to be working very smoothly

I works also very well with trusty

I confirm that every second
 $ systemctl restart dnsmasq
hangs

Also I confirm that removing squid resolved the situation.

I found that it does this:
1. /bin/sh /etc/init.d/dnsmasq systemd-stop-resolvconf
2. /bin/sh /etc/init.d/dnsmasq systemd-start-resolvconf

Both will call hooks like:

0 0 11642 11634 20 0 4364 660 wait S ? 0:00 \_ run-parts --arg=-a --arg=lo.dnsmasq /etc/resolvconf/update.d
0 0 11659 11642 20 0 4364 664 wait S ? 0:00 \_ run-parts /etc/resolvconf/update-libc.d
0 0 11672 11659 20 0 4504 704 wait S ? 0:00 \_ /bin/sh /etc/resolvconf/update-libc.d/squid
0 0 11673 11672 20 0 4504 1648 wait S ? 0:00 \_ /bin/sh /usr/sbin/invoke-rc.d squid reload
4 0 11691 11673 20 0 24888 1388 poll_s S ? 0:00 \_ systemctl reload squid.service

This is what actually times out - the squid hook.

The "systemctl reload squid.service" call seems to take too long every second time?!

A single "systemctl reload squid.service" for these seems to take ~100 seconds for me.
OTOH a direct call to it is fast every time.

This needs to be debugged in detail, but seems well reproducible.

This is complicated indeed. I also spotted this in the logs during the long wait:
Oct 25 21:16:07 xenial-squid-dnsmasq systemd[1]: nss-lookup.target: Job nss-lookup.target/start failed with result 'dependency'.

and nss-lookup.target has something related to dnsmasq:
root@xenial-squid-dnsmasq:~# systemctl status nss-lookup.target
● nss-lookup.target - Host and Network Name Lookups
   Loaded: loaded (/etc/insserv.conf.d/dnsmasq; static; vendor preset: enabled)
  Drop-In: /run/systemd/generator/nss-lookup.target.d
           └─50-hard-dependency-dnsmasq-$named.conf
   Active: active since Thu 2018-10-25 21:19:41 UTC; 53s ago
     Docs: man:systemd.special(7)

Regardless of resolvconf or dnsmasq, squid itself takes about 30s to restart. I wonder if it depends on dnsmasq via nss-lookup, then when dnsmasq is restarted, that tries to restart squid, which takes 30s each time? I couldn't reproduce the "squid reload" blocking when I run it manually, but I do see it happening in the ps fauxw tree, just like Christian did.

OK, I've spent some time investigating this one, so I decided to post my progress here. Unfortunately I don't have a full fix yet, but I managed to find some interesting pointers related to systemd.

First of all, I confirmed what Christian and Andreas were seeing: the problem happens on every second "systemctl start dnsmasq.service"; squid takes 30 seconds to restart regardless of dnsmasq/resolvconf (this is still true nowadays, with groovy); nss-lookup.target fails to start on xenial, but does start on bionic; the issue doesn't seem to happen on bionic.

As for the systemd bits I mentioned, I found these issues:

- https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1417010
- https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=777113

The good news is that they are really similar to what we're experiencing here, even though our problem doesn't seem to be cirular dependencies on systemd service files. The bad news is that the fix proposed by Martin Pitt (the last one, that ended up landing) is already available on xenial.

One of the suggested fixes was to add a "--no-block" on /usr/sbin/invoke-rc.d's "systemctl reload" command. I did that, and it obviously "solves" the issue, although I'm not confident that it's the proper fix for this.

Something that caught my attention is the fact that the process that is hung is actually the "systemctl reload squid", and not squid itself. I verified that "/etc/init.d/squid reload" actually exits successfully, but for some reason "systemctl reload squid" keeps waiting. With what I know so far, I feel inclined to say that this is a systemd issue, and not a dnsmasq/squid/resolvconf one (of course, we can talk about squid's 30-second restart, but that's orthogonal).

I'll let you know when I have more data (or hopefully a fix). Meanwhile, I'd appreciate comments/feedback, if you have any.

Sergio:
> ... reload" actually exits successfully ... systemctl ... keeps waiting

For the systemd side I'd wonder as there are so myn type= options if it is not getting that squid is restarted.
(https://www.freedesktop.org/software/systemd/man/systemd.service.html#Options) maybe worth to experiment with them?

Sergio:
> "squid takes 30 seconds to restart regardless of dnsmasq/resolvconf (this is still true nowadays, with groovy)"

<snip>
I'm ashamed - it seems I have taken the most complex way to resolve a simple thing.
Imagine a very complex debugging through strace and gdb to reach a trivial config option - I removed the debugging section as it has no meaning
</snip>

The 30 seconds on squid are just the default config of it.
You can set any other value to get it's restart to be quicker (but also more rude to potential clients).

/etc/squid/squid.conf:
# TAG: shutdown_lifetime time-units
# When SIGTERM or SIGHUP is received, the cache is put into
# "shutdown pending" mode until all active sockets are closed.
# This value is the lifetime to set for all open descriptors
# during shutdown mode. Any active clients after this many
# seconds will receive a 'timeout' message.
#Default:
# shutdown_lifetime 30 seconds
shutdown_lifetime 5 seconds

So squid to shut down / restart in 30 seconds is normal/expected.

And reload command is
ExecReload=/bin/kill -HUP $MAINPID

MAINPID is the parent, this will make it not trigger the 30 sec on "systemctl reload" but only on "systemctl restart"

     CGroup: /system.slice/squid.service
             ├─4011 /usr/sbin/squid --foreground -sYC <-- gets HUP for reload
             ├─4013 (squid-1) --kid squid-1 --foreground -sYC
             ├─4014 (logfile-daemon) /var/log/squid/access.log
             └─4015 (pinger)

On reload is replaced with
     CGroup: /system.slice/squid.service
             ├─4011 /usr/sbin/squid --foreground -sYC
             ├─4013 (squid-1) --kid squid-1 --foreground -sYC
             ├─4024 (pinger)
             ├─4048 (logfile-daemon) /var/log/squid/access.log
             └─4049 (pinger)

And after the delay just one is left:
     CGroup: /system.slice/squid.service
             ├─4011 /usr/sbin/squid --foreground -sYC
             ├─4013 (squid-1) --kid squid-1 --foreground -sYC
             ├─4048 (logfile-daemon) /var/log/squid/access.log
             └─4049 (pinger)

So to summarize:
- squid shutdown/restart is intentionally slow to be graceful
- squid reload is fast

Since Sergio mentioned groovy, this really only is a xenial issue:

Test:
1. install dnsqmasq+squid
2. ensure dnsmasq is able to run (port collision >=Focal)
3. stop/start dnsmasq in a loop

for i in $(seq 1 4); do date; echo "-"; systemctl stop dnsmasq; date; echo "+"; systemctl start dnsmasq; date; done

Xenial: slow
Bionic: fast
Focal: fast
Groovy: fast

Xenial:
Wed Sep 2 06:24:15 UTC 2020
-
Wed Sep 2 06:24:15 UTC 2020
+
Job for dnsmasq.service failed because a timeout was exceeded. See "systemctl status dnsmasq.service" and "journalctl -xe" for details.
Wed Sep 2 06:25:46 UTC 2020
Wed Sep 2 06:25:46 UTC 2020
-
Wed Sep 2 06:25:46 UTC 2020
+
Wed Sep 2 06:25:47 UTC 2020
Wed Sep 2 06:25:47 UTC 2020
-
Wed Sep 2 06:25:47 UTC 2020
+
Job for dnsmasq.service failed because a timeout was exceeded. See "systemctl status dnsmasq.service" and "journalctl -xe" for details.
Wed Sep 2 06:27:18 UTC 2020
Wed Sep 2 06:27:18 UTC 2020
-
Wed Sep 2 06:27:18 UTC 2020
+
Wed Sep 2 06:27:18 UTC 2020

So as the bug was already flagged, this is really only a xenial issue anymore.
And the fact that it is "ok" for squid to take 30 second for a restart is intentional as outlined above.

As already reported dnsmasq hangs on the hooks:
             ├─2089 /bin/sh /etc/init.d/dnsmasq systemd-start-resolvconf
             ├─2097 run-parts --arg=-a --arg=lo.dnsmasq /etc/resolvconf/update.d
             ├─2116 run-parts /etc/resolvconf/update-libc.d
             ├─2129 /bin/sh /etc/resolvconf/update-libc.d/squid
             ├─2130 /bin/sh /usr/sbin/invoke-rc.d squid reload
             └─2148 systemctl reload squid.service

The hierarchy of these is:
run-parts /etc/resolvconf/update-libc.d
  -> /etc/resolvconf/update-libc.d/squid
    -> /usr/sbin/invoke-rc.d squid reload

The actual reload is done really fast:
Sep 02 06:32:19 x2 systemd[1]: Reloading LSB: Squid HTTP Proxy version 3.x.
Sep 02 06:32:19 x2 squid[2505]: * Reloading Squid HTTP Proxy configuration files
Sep 02 06:32:19 x2 squid[2505]: ...done.
Sep 02 06:32:19 x2 systemd[1]: Reloaded LSB: Squid HTTP Proxy version 3.x.

But in ps hierarchy the systemctl reload hangs still
0 0 2737 1 20 0 4500 1372 wait Ss ? 0:00 /bin/sh /etc/init.d/dnsmasq systemd-start-resolvconf
0 0 2745 2737 20 0 4360 644 wait S ? 0:00 \_ run-parts --arg=-a --arg=lo.dnsmasq /etc/resolvconf/update.d
0 0 2763 2745 20 0 4360 1184 wait S ? 0:00 \_ run-parts /etc/resolvconf/update-libc.d
0 0 2776 2763 20 0 4500 692 wait S ? 0:00 \_ /bin/sh /etc/resolvconf/update-libc.d/squid
0 0 2777 2776 20 0 4500 1300 wait S ? 0:00 \_ /bin/sh /usr/sbin/invoke-rc.d squid reload
0 0 2795 2777 20 0 24884 1068 poll_s S ? 0:00 \_ systemctl reload squid.service

The delay on that is actually 90 seconds.
And it waits until killed:
     0.000000 ppoll([{fd=3, events=POLLIN}], 1, NULL, NULL, 8) = 1 ([{fd=3, revents=POLLIN}]) <53.100476>
    53.101445 +++ killed by SIGKILL +++
Due to
  Sep 02 06:37:19 x2 systemd[1]: dnsmasq.service: Start-post operation timed out. Stopping.

The old init script reload in xenial was:
    reload|force-reload)
        res=`$DAEMON -k parse -f $CONFIG 2>&1 | grep -o "FATAL: .*"`
        if test -n "$res";
        then
                log_failure_msg "$res"
                exit 3
        else
                log_action_msg "Reloading $DESC configuration files"
                start-stop-daemon --stop --signal 1 \
                        --pidfile $PIDFILE --quiet --exec $DAEMON
                log_action_end_msg 0
        fi
        ;;

But all these actions directly executed are always fast:
- /usr/sbin/invoke-rc.d squid reload
- systemctl reload squid
- start-stop-daemon --stop --signal 1 --pidfile /var/run/squid.pid --quiet --exec /usr/sbin/squid

I can make "systemctl reload squid" hang thou - if I invoke it at the right time.
To do so I replaced /etc/resolvconf/update-libc.d/squid with a debug hook that waits on me:
echo "DEBUG DEBUG DEBUG"
echo "would call 'invoke-rc.d squid reload' now"
echo "instead wait until /tmp/foo was touched"
f="/tmp/foo"
start=$(date -r $f);
new=$(date -r $f);
while [ "$start" = "$new" ]; do
  sleep 2;
  new=$(date -r $f);
done;
echo "DEBUG D...

Thanks for the further investigation, Christian.

So, it doesn't seem to me that /bin/systemd-tty-ask-password-agent is the culprit here. Actually, if you look at when it is invoked, you will notice that it is only executed when the systemctl command is issued from the tty, which is not our case here: the command that is hanging ("systemctl reload squid") is being invoked indirectly due to the start of dnsmasq.service.

When we issue a "systemctl start dnsmasq", we can see /bin/systemd-tty-ask-password-agent there, but not as a child of the "systemctl reload squid":

root 9164 0.0 0.0 26164 1040 pts/0 S+ 22:23 0:00 | \_ systemctl start dnsmasq.service
root 9165 0.0 0.0 12512 2084 pts/0 S+ 22:23 0:00 | \_ /bin/bash /bin/systemd-tty-ask-password-agent --watch

This is because we invoked "systemctl start dnsmasq" from the tty. We can easily verify that /bin/systemd-tty-ask-password-agent is not to blame by using "systemctl --no-ask-password stop dnsmasq" and then "systemctl --no-ask-password start dnsmasq", and verifying that the hang still happens even though /bin/systemd-tty-ask-password-agent was not invoked.

Anyway, continuing the investigation here, this is the output of "systemctl list-jobs":

$ systemctl list-jobs --all
 JOB UNIT TYPE STATE
2512 dnsmasq.service start running
2561 squid.service reload waiting
2560 nss-lookup.target start waiting

3 jobs listed.

Nothing really new here, except the fact that the squid reload happens *because* of the nss-lookup.target start, and both jobs are blocked waiting. It's interesting to notice that squid's SysV init file says that squid "Should-Start: $named", which translated to squid trying to start nss-lookup.target itself. I think this is a strong indicator that we might be seeing a deadlock here.

After a bit more investigation, I found https://github.com/systemd/systemd/issues/10464, which led me to https://github.com/systemd/systemd/pull/13860. I tried backporting the patch (which is very simple) and seeing if it had any impact, but unfortunately it didn't.

I then did a quick test and hacked /usr/sbin/invoke-rc.d, specifically around line 570, and commented out the "if" surrounding sctl_args="--job-mode=ignore-dependencies" (in other words, I made systemctl always use this option), and unsurprisingly the bug went away. However, just like with the "--no-block" hack I mentioned in my previous comment, I'm not sure this is a good solution for the problem.

As I'm running out of ideas here, I'd like to propose a possible fix for the problem, based on what Martin Pitt wrote in one of the bug reports I mentioned (https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=777113). I'd like to suggest that we expand /etc/resolvconf/update-libc.d/squid to take into account whether systemd is being used behind the scenes, and invoke systemctl to reload squid while also passing "--no-block" to it. Something like this:

 if [ -d /run/systemd ]; then
   systemctl --no-block reload squid
 else
   invoke-rc.d squid reload || true
 fi

Based on local tests here, this works and has the benefit of u...

Thanks for --no-ask-password Sergio.

I like the suggestion of making /etc/resolvconf/update-libc.d/squid systemd aware.
From similar checks I know that you also want to check if it is active:

if [ -d /run/systemd/system ]; then
! systemctl is-active -q squid.service || systemctl reload squid.service >/dev/null

The above is untested, but you get my point - don't reload if it isn't active.

On Friday, September 04 2020, Christian Ehrhardt  wrote:

> Thanks for --no-ask-password Sergio.
>
> I like the suggestion of making /etc/resolvconf/update-libc.d/squid systemd aware.
>>From similar checks I know that you also want to check if it is active:
>
> if [ -d /run/systemd/system ]; then
> ! systemctl is-active -q squid.service || systemctl reload squid.service >/dev/null
>
> The above is untested, but you get my point - don't reload if it isn't
> active.

Thanks, Christian. Good point about checking whether the service is
active; I'll incorporate that into the solution.

I'll prepare an MP soon, then.

Cheers,

--
Sergio
GPG key ID: E92F D0B3 6B14 F1F4 D8E0 EB2F 106D A1C8 C3CB BF14

I'm marking the dnsmasq bug as Invalid since this is a problem with squid/systemd.

On Xenial the source package is squid3, not squid, so I'll add/adjust tasks for that so the tracking works correctly.

On Bionic the code suggests that the same problem might exist, but it appears that nobody has reproduced it there so there is no need for an SRU to Bionic. However, if somebody is affected then we can look again. I'll leave an Incomplete task for Bionic to try to highlight that. We don't have any specific policy or pattern to track this kind of thing so I'm being inventive with the bug status here.

Excerpts from #ubuntu-devel:

17:32 <rbasak> cpaelzer, sergiodj: in bug 1761096, did you ever find out why Bionic are unaffected, or did you decide it wasn't worth investigating further?

17:32 <rbasak> *is*

17:38 <sergiodj> rbasak: we could not find exactly why Bionic is not affected. my hypothesis is that between Xenial and Bionic there was a fix on systemd which addressed this issue, but I could not pinpoint exactly what was done

17:39 <sergiodj> arguably, the best scenario would be to backport this fix to Xenial's systemd, but since we had already spent a non-trivial amount of time investigating this (without finding anything concrete on systemd's side), I opted for the second best thing to do, which is to use --no-block to workaround this bug

Hello Olivier, or anyone else affected,

Accepted squid3 into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/squid3/3.5.12-1ubuntu7.14 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-xenial to verification-done-xenial. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-xenial. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Verifying that the bug is fixed.

First, reproducing the bug. After firing up the container, while running "apt install squid dnsmasq -y", I see:

# apt install squid dnsmasq -y
...
Setting up dnsmasq (2.75-1ubuntu0.16.04.5) ...
Job for dnsmasq.service failed because a timeout was exceeded. See "systemctl status dnsmasq.service" and "journalctl -xe" for details.
invoke-rc.d: initscript dnsmasq, action "start" failed.
● dnsmasq.service - dnsmasq - A lightweight DHCP and caching DNS server
   Loaded: loaded (/lib/systemd/system/dnsmasq.service; enabled; vendor preset: enabled)
  Drop-In: /run/systemd/generator/dnsmasq.service.d
           └─50-dnsmasq-$named.conf, 50-insserv.conf-$named.conf
   Active: failed (Result: timeout) since Wed 2020-09-16 15:43:01 UTC; 11ms ago
  Process: 1565 ExecStartPost=/etc/init.d/dnsmasq systemd-start-resolvconf (code=killed, signal=TERM)
  Process: 1554 ExecStart=/etc/init.d/dnsmasq systemd-exec (code=exited, status=0/SUCCESS)
  Process: 1553 ExecStartPre=/usr/sbin/dnsmasq --test (code=exited, status=0/SUCCESS)
 Main PID: 1564 (code=exited, status=0/SUCCESS)

Sep 16 15:41:31 squid-bug1761096 dnsmasq[1564]: started, version 2.75 cachesize 150
Sep 16 15:41:31 squid-bug1761096 dnsmasq[1564]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify
Sep 16 15:41:31 squid-bug1761096 dnsmasq[1564]: DNS service limited to local subnets
Sep 16 15:41:31 squid-bug1761096 dnsmasq[1564]: read /etc/hosts - 7 addresses
Sep 16 15:41:31 squid-bug1761096 dnsmasq[1564]: reading /var/run/dnsmasq/resolv.conf
Sep 16 15:41:31 squid-bug1761096 dnsmasq[1564]: using nameserver 10.101.133.1#53
Sep 16 15:43:01 squid-bug1761096 systemd[1]: dnsmasq.service: Start-post operation timed out. Stopping.
Sep 16 15:43:01 squid-bug1761096 systemd[1]: Failed to start dnsmasq - A lightweight DHCP and caching DNS server.
Sep 16 15:43:01 squid-bug1761096 systemd[1]: dnsmasq.service: Unit entered failed state.
Sep 16 15:43:01 squid-bug1761096 systemd[1]: dnsmasq.service: Failed with result 'timeout'.
...

We also see the bug happening while restarting the dnsmasq.service:

# systemctl restart dnsmasq.service
Job for dnsmasq.service failed because a timeout was exceeded. See "systemctl status dnsmasq.service" and "journalctl -xe" for details.
# systemctl status dnsmasq.service
● dnsmasq.service - dnsmasq - A lightweight DHCP and caching DNS server
   Loaded: loaded (/lib/systemd/system/dnsmasq.service; enabled; vendor preset: enabled)
  Drop-In: /run/systemd/generator/dnsmasq.service.d
           └─50-dnsmasq-$named.conf, 50-insserv.conf-$named.conf
   Active: failed (Result: timeout) since Wed 2020-09-16 15:47:22 UTC; 17s ago
  Process: 1744 ExecStop=/etc/init.d/dnsmasq systemd-stop-resolvconf (code=killed, signal=TERM)
  Process: 1808 ExecStartPost=/etc/init.d/dnsmasq systemd-start-resolvconf (code=killed, signal=TERM)
  Process: 1799 ExecStart=/etc/init.d/dnsmasq systemd-exec (code=exited, status=0/SUCCESS)
  Process: 1798 ExecStartPre=/usr/sbin/dnsmasq --test (code=exited, status=0/SUCCESS)
 Main PID: 1807 (code=exited, status=0/SUCCESS)

Sep 16 15:45:52 squid-bug1761096 dnsmasq[180...

This bug was fixed in the package squid3 - 3.5.12-1ubuntu7.14

---------------
squid3 (3.5.12-1ubuntu7.14) xenial; urgency=medium

  * d/squid.resolvconf: Invoke "systemctl reload --no-block" if we are
    using systemd. This prevents squid from blocking if the reload
    action is being issued indirectly because of another
    service (e.g., because dnsmasq has been restarted), which may
    cause a deadlock and prevent the whole transaction to
    complete. (LP: #1761096)

 -- Sergio Durigan Junior <email address hidden> Fri, 04 Sep 2020 08:31:36 -0400

The verification of the Stable Release Update for squid3 has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.