[Pkg-dns-devel] Bug#826241: Bug#826241: Bug#826241: Bug#826241: Bug#826241: unbound: Provide $named facility under systemd

Sat Jul 9 21:36:17 UTC 2016

Michael Biebl wrote:
> Am 05.07.2016 um 01:36 schrieb Robert Edmonds:
> > I tested this (actually your later version with the typo fix), but it
> > seems unbound-resolvconf.service starts, but then immediately stops:
> 
> ..
> 
> > Do we need to set “RemainAfterExit=yes” in unbound-resolvconf.service?
> 
> RemainAfterExit=yes is typically used for Type=oneshot services. But in
> this specific case, where we use Type=simple deliberately even though we
> don't start a long running process, RemainAfterExit=yes seems like the
> correct fix.

Hi, Michael:

This almost works. I have “systemctl stop unbound“ and “systemctl start
unbound“ working correctly with unbound, resolvconf, and postfix
installed.

But it looks like “systemctl restart unbound“ takes 90 seconds to
complete, though it eventually exits with return code 0. When “systemctl
restart unbound“ is running, I see the following initially printed to
the journal:

Jul 09 21:25:08 debian systemd[1]: Stopping Unbound DNS server via resolvconf...
Jul 09 21:25:08 debian systemd[1]: Stopped target Host and Network Name Lookups.
Jul 09 21:25:08 debian systemd[1]: Stopping Host and Network Name Lookups.

“systemctl list-jobs“ shows the following, with job 228 highlighted:

    JOB UNIT                       TYPE    STATE  
    227 nss-lookup.target          start   waiting
    228 unbound-resolvconf.service restart running
    166 unbound.service            restart waiting
    229 postfix.service            reload  waiting

    4 jobs listed.

and I see this familiar group of processes in the process tree:

[...] /bin/sh -e /usr/lib/unbound/package-helper resolvconf_stop
[...]  \_ run-parts --arg=-d --arg=lo.unbound /etc/resolvconf/update.d
[...]      \_ run-parts /etc/resolvconf/update-libc.d
[...]          \_ /bin/sh -e /etc/resolvconf/update-libc.d/postfix
[...]              \_ /bin/sh -e /etc/init.d/postfix reload
[...]                  \_ /bin/systemctl --no-pager reload postfix.service

Then, about 90 seconds after “systemctl restart unbound“ is executed,
the following is written to the journal:

Jul 09 21:26:38 debian systemd[1]: unbound-resolvconf.service: Stopping timed out. Terminating.
Jul 09 21:26:38 debian systemd[1]: Stopped Unbound DNS server via resolvconf.
Jul 09 21:26:38 debian systemd[1]: unbound-resolvconf.service: Unit entered failed state.
Jul 09 21:26:38 debian systemd[1]: unbound-resolvconf.service: Failed with result 'timeout'.
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info: service stopped (unbound 1.5.9).
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info: server stats for thread 0: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info: server stats for thread 0: requestlist max 2 avg 1 exceeded 0 jostled 0
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info: average recursion processing time 2.150202 sec
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info: histogram of recursion processing times
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info: [25%]=0 median[50%]=0 [75%]=0
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info: lower(secs) upper(secs) recursions
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info:    1.000000    2.000000 1
Jul 09 21:26:38 debian unbound[1631]: [1631:0] info:    2.000000    4.000000 1
Jul 09 21:26:38 debian systemd[1]: Stopping Unbound DNS server...
Jul 09 21:26:38 debian systemd[1]: Stopped Unbound DNS server.
Jul 09 21:26:38 debian systemd[1]: Starting Unbound DNS server...
Jul 09 21:26:38 debian package-helper[1897]: /var/lib/unbound/root.key has content
Jul 09 21:26:38 debian package-helper[1897]: success: the anchor is ok
Jul 09 21:26:38 debian systemd[1]: Started Unbound DNS server.
Jul 09 21:26:38 debian systemd[1]: Started Unbound DNS server via resolvconf.
Jul 09 21:26:38 debian systemd[1]: Reached target Host and Network Name Lookups.
Jul 09 21:26:38 debian systemd[1]: Reloading LSB: Postfix Mail Transport Agent.
Jul 09 21:26:38 debian unbound[1909]: [1909:0] notice: init module 0: validator
Jul 09 21:26:38 debian unbound[1909]: [1909:0] notice: init module 1: iterator
Jul 09 21:26:38 debian unbound[1909]: [1909:0] info: start of service (unbound 1.5.9).
Jul 09 21:26:38 debian postfix[1917]: Postfix is running with backwards-compatible default settings
Jul 09 21:26:38 debian postfix[1917]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Jul 09 21:26:38 debian postfix[1917]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
Jul 09 21:26:38 debian postfix/master[1783]: reload -- version 3.1.0, configuration /etc/postfix
Jul 09 21:26:38 debian postfix[1911]: Reloading Postfix configuration...done.
Jul 09 21:26:38 debian systemd[1]: Reloaded LSB: Postfix Mail Transport Agent.
Jul 09 21:26:38 debian systemd[1]: Reloading LSB: Postfix Mail Transport Agent.
Jul 09 21:26:38 debian postfix[1972]: Postfix is running with backwards-compatible default settings
Jul 09 21:26:38 debian postfix[1972]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Jul 09 21:26:38 debian postfix[1972]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
Jul 09 21:26:38 debian postfix/master[1783]: reload -- version 3.1.0, configuration /etc/postfix
Jul 09 21:26:38 debian postfix[1969]: Reloading Postfix configuration...done.
Jul 09 21:26:38 debian systemd[1]: Reloaded LSB: Postfix Mail Transport Agent.

I'm not quite sure what the issue is. Any ideas? This is on an
up-to-date stretch VM, with these unbound packages installed:

    https://people.debian.org/~edmonds/build/unbound/1.5.9-2/

along with resolvconf and postfix from testing.

-- 
Robert Edmonds
edmonds at debian.org