Charm blocked after bind service fails to start

[John George]

During a foundation cloud deployment designate-bind units are blocked waiting for bind.

The syslog from the designate-bind unit reports that bind failed to start.
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: ----------------------------------------------------
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: BIND 9 is maintained by Internet Systems Consortium,
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: Inc. (ISC), a non-profit 501(c)(3) public-benefit
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: corporation. Support and training for BIND 9 are
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: available at https://www.isc.org/support
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: ----------------------------------------------------
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: found 20 CPUs, using 20 worker threads
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: using 10 UDP listeners per interface
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: using up to 4096 sockets
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: loading configuration from '/etc/bind/named.conf'
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: open: /etc/bind/named.conf: permission denied
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: loading configuration: permission denied
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: exiting (due to fatal error)
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 systemd[1]: bind9.service: Main process exited, code=exited, status=1/FAILURE

The test run details are available at https://solutions.qa.canonical.com/#/qa/testRun/a1d6eafb-298e-48d3-a70f-c79792a77cac and I've attach the crashdump.

[John A Meinel (jameinel)]

This failure is surprising:
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: open: /etc/bind/named.conf: permission denied
Jul 19 07:43:58 juju-f3de6a-1-lxd-3 named[28676]: loading configuration: permission denied

Crashdump doesn't seem to capture those files (it grabs /etc/netplan and /etc/network but not /etc/bind).

There is a warning in the unit log:
2018-07-19 07:43:50 WARNING juju-log cluster:6: Request for sync sent but remote sync time is too old, defering until a more up-to-date target is available

I'm not sure where that is coming from.

We can see the charm writing the files here:
2018-07-19 07:43:58 DEBUG juju-log dns-backend:76: Writing file /etc/bind/named.conf.options root:root 640
2018-07-19 07:43:58 DEBUG worker.uniter.jujuc server.go:181 running hook tool "juju-log"
2018-07-19 07:43:58 DEBUG worker.uniter.jujuc server.go:181 running hook tool "network-get"
2018-07-19 07:43:58 DEBUG worker.uniter.jujuc server.go:181 running hook tool "juju-log"
2018-07-19 07:43:58 DEBUG juju-log dns-backend:76: Writing file /etc/bind/named.conf root:root 640

Those both seem to be happening in 07:43:58. So it seems we just wrote the file, but bind is failing to read it?

[John George (jog)]

I logged into a live test system and can see that /etc/bind/named.conf does exist.

ubuntu@juju-700af8-1-lxd-3:/etc/bind$ ls -l
total 52
-rw-r--r-- 1 root root 3954 Jan 16 2018 bind.keys
-rw-r--r-- 1 root root 237 Jan 16 2018 db.0
-rw-r--r-- 1 root root 271 Jan 16 2018 db.127
-rw-r--r-- 1 root root 237 Jan 16 2018 db.255
-rw-r--r-- 1 root root 353 Jan 16 2018 db.empty
-rw-r--r-- 1 root root 270 Jan 16 2018 db.local
-rw-r--r-- 1 root root 3171 Jan 16 2018 db.root
-rw-r----- 1 root root 587 Jul 20 12:13 named.conf
-rw-r--r-- 1 root bind 490 Jan 16 2018 named.conf.default-zones
-rw-r--r-- 1 root bind 165 Jan 16 2018 named.conf.local
-rw-r----- 1 root root 1188 Jul 20 12:13 named.conf.options
-rw-r----- 1 root root 76 Jul 20 12:12 rndc.key
-rw-r--r-- 1 root root 1317 Jan 16 2018 zones.rfc1918
ubuntu@juju-700af8-1-lxd-3:/etc/bind$ cat /etc/bind/named.conf
cat: /etc/bind/named.conf: Permission denied
ubuntu@juju-700af8-1-lxd-3:/etc/bind$ sudo cat /etc/bind/named.conf
// This is the primary configuration file for the BIND DNS server named.
//
// Please read /usr/share/doc/bind9/README.Debian.gz for information on the
// structure of BIND configuration files in Debian, *BEFORE* you customize
// this configuration file.
//
// If you are just adding zones, please do that in /etc/bind/named.conf.local

include "/etc/bind/named.conf.options";
include "/etc/bind/named.conf.local";
include "/etc/bind/named.conf.default-zones";

controls {
  inet 127.0.0.1 allow {localhost;};
  inet 192.168.33.147 allow { 10.244.40.215;10.244.41.1;10.244.41.11; };
};

[James Page (james-page)]

Note that this is with the master branch/next charms; stable charms are OK

[John George (jog)]

I checked another deployment done with Juju 2.4.0 and file permissions are set to:
-r--r--r-- 1 root root 589 Jul 11 21:32 named.conf

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/584373
Committed: https://git.openstack.org/cgit/openstack/charm-designate-bind/commit/?id=cd14d5a18e6e899728f5965b7eb52c3ab4547e5f
Submitter: Zuul
Branch: master

commit cd14d5a18e6e899728f5965b7eb52c3ab4547e5f
Author: James Page <email address hidden>
Date: Fri Jul 20 09:29:58 2018 -0400

    Fix group permissions for bind access

    Ensure generated configuration files are readable by the bind
    user (required due to switch in default permissions to 0640
    in charms.openstack).

    Change-Id: I88bf4e93ea07621bda8c87f0f98f1c438bfe2be4
    Closes-Bug: 1782640