Bug 984764

Summary: bind-chroot-9.9.3-3.P1.fc19.x86_64 failed to start
Product: [Fedora] Fedora Reporter: Indra Kurniawan <ikurniawan.fedora>
Component: bindAssignee: Tomáš Hozza <thozza>
Status: CLOSED NOTABUG QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: unspecified    
Version: 19CC: ikurniawan.fedora, paul, thozza, vonsch
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-08-14 14:16:53 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Indra Kurniawan 2013-07-15 22:22:24 UTC
Description of problem:
bind-chroot-9.9.3-3.P1.fc19.x86_64 failed to start

Version-Release number of selected component (if applicable):
bind-chroot-9.9.3-3.P1.fc19.x86_64

How reproducible:
Install bind and bind-chroot package, start the service.

Steps to Reproduce:
1. yum install bind bind-chroot
2. systemctl enable named-chroot.service
3. systemctl start named-chroot.service

Actual results:
systemd[1]: PID file /var/named/chroot/run/named/named.pid not readable (yet?) after start.
systemd[1]: named-chroot.service operation timed out. Terminating.

Expected results:
systemd[1]: Started Berkeley Internet Name Domain (DNS).

Additional info:
Suggested fix

--- /usr/lib/systemd/system/named-chroot.service-original	2013-07-16 05:14:23.553148169 +0700
+++ /usr/lib/systemd/system/named-chroot.service	2013-07-16 04:47:30.771152192 +0700
@@ -12,7 +12,7 @@
 Type=forking
 EnvironmentFile=-/etc/sysconfig/named
 Environment=KRB5_KTNAME=/etc/named.keytab
-PIDFile=/var/named/chroot/run/named/named.pid
+PIDFile=/var/named/chroot/var/run/named/named.pid
 
 ExecStartPre=/usr/libexec/generate-rndc-key.sh
 ExecStartPre=/usr/libexec/setup-named-chroot.sh /var/named/chroot on

Comment 1 Tomáš Hozza 2013-07-16 07:16:13 UTC
Hi.

Do you have 

pid-file      "/run/named/named.pid";

in options section of your named.conf?

Note that we moved named.pid in F19 from /var/run/named to /run/named.

http://docs.fedoraproject.org/en-US/Fedora/19/html/Release_Notes/sect-Release_Notes-Changes_for_Desktop.html#idm263813278160

Comment 2 Indra Kurniawan 2013-07-16 12:17:09 UTC
Hi Tomas,

I was upgrading from F18 to F19 via fedup-cli, and yes that pid-file found on "/run/named/named.pid" but it just an empty file.

[root@tontot ~]# file /run/named/named.pid
/run/named/named.pid: empty


I revert back the named-chroot.service for testing.
From PIDFile=/var/named/chroot/var/run/named/named.pid to PIDFile=/var/named/chroot/run/named/named.pid

Checking the service that already running.

[root@tontot ~]# systemctl status named-chroot.service 
named-chroot.service - Berkeley Internet Name Domain (DNS)
   Loaded: loaded (/usr/lib/systemd/system/named-chroot.service; enabled)
   Active: active (running) since Tue 2013-07-16 04:48:05 WIT; 14h ago
  Process: 32194 ExecStart=/usr/sbin/named -u named -t /var/named/chroot $OPTIONS (code=exited, status=0/SUCCESS)
  Process: 32191 ExecStartPre=/usr/sbin/named-checkconf -t /var/named/chroot -z /etc/named.conf (code=exited, status=0/SUCCESS)
  Process: 32169 ExecStartPre=/usr/libexec/setup-named-chroot.sh /var/named/chroot on (code=exited, status=0/SUCCESS)
  Process: 32168 ExecStartPre=/usr/libexec/generate-rndc-key.sh (code=exited, status=0/SUCCESS)
 Main PID: 32197 (named)
   CGroup: name=systemd:/system/named-chroot.service
           └─32197 /usr/sbin/named -u named -t /var/named/chroot -4

Jul 16 04:48:03 tontot.rndc.or.id named-checkconf[32191]: zone ads.linuxjournal.com/IN: loaded serial 2002061000
Jul 16 04:48:03 tontot.rndc.or.id named-checkconf[32191]: zone ads.linuxsecurity.com/IN: loaded serial 2002061000
Jul 16 04:48:03 tontot.rndc.or.id named-checkconf[32191]: zone ads.livenation.com/IN: loaded serial 2002061000
Jul 16 04:48:03 tontot.rndc.or.id named-checkconf[32191]: zone ads.localnow.com/IN: loaded serial 2002061000
Jul 16 04:48:03 tontot.rndc.or.id named-checkconf[32191]: zone ads.lvz-online.de/IN: loaded serial 2002061000
Jul 16 04:48:03 tontot.rndc.or.id named-checkconf[32191]: zone ads.mambocommunities.com/IN: loaded serial 2002061000
Jul 16 04:48:03 tontot.rndc.or.id named-checkconf[32191]: zone ads.mariuana.it/IN: loaded serial 2002061000
Jul 16 04:48:03 tontot.rndc.or.id named-checkconf[32191]: zone ads.massinfra.nl/IN: loaded serial 2002061000
Jul 16 04:48:04 tontot.rndc.or.id named[32197]: using built-in DLV key for view _default
Jul 16 04:48:05 tontot.rndc.or.id systemd[1]: Started Berkeley Internet Name Domain (DNS).


Reloading the systemd daemon and try to start the named-chroot.service after reverting into default PIDFile.

[root@tontot ~]# systemctl --system daemon-reload
[root@tontot ~]# systemctl restart named-chroot.service 
Job for named-chroot.service failed. See 'systemctl status named-chroot.service' and 'journalctl -xn' for details.
[root@tontot ~]# systemctl status named-chroot.service
named-chroot.service - Berkeley Internet Name Domain (DNS)
   Loaded: loaded (/usr/lib/systemd/system/named-chroot.service; enabled)
   Active: failed (Result: timeout) since Tue 2013-07-16 19:02:43 WIT; 1min 13s ago
  Process: 16345 ExecStopPost=/usr/libexec/setup-named-chroot.sh /var/named/chroot off (code=exited, status=0/SUCCESS)
  Process: 16340 ExecStop=/bin/sh -c /usr/sbin/rndc stop > /dev/null 2>&1 || /bin/kill -TERM $MAINPID (code=exited, status=0/SUCCESS)
  Process: 16418 ExecStart=/usr/sbin/named -u named -t /var/named/chroot $OPTIONS (code=exited, status=0/SUCCESS)
  Process: 16415 ExecStartPre=/usr/sbin/named-checkconf -t /var/named/chroot -z /etc/named.conf (code=exited, status=0/SUCCESS)
  Process: 16389 ExecStartPre=/usr/libexec/setup-named-chroot.sh /var/named/chroot on (code=exited, status=0/SUCCESS)
  Process: 16387 ExecStartPre=/usr/libexec/generate-rndc-key.sh (code=exited, status=0/SUCCESS)
 Main PID: 16261 (code=exited, status=0/SUCCESS)
   CGroup: name=systemd:/system/named-chroot.service

Jul 16 19:01:12 tontot.rndc.or.id named-checkconf[16415]: zone ads.linuxjournal.com/IN: loaded serial 2002061000
Jul 16 19:01:13 tontot.rndc.or.id named[16421]: using built-in DLV key for view _default
Jul 16 19:01:15 tontot.rndc.or.id systemd[1]: Failed to read PID from file /var/named/chroot/run/named/named.pid: Invalid argument
Jul 16 19:02:43 tontot.rndc.or.id systemd[1]: named-chroot.service operation timed out. Terminating.
Jul 16 19:02:43 tontot.rndc.or.id named[16421]: no longer listening on 127.0.0.1#53
Jul 16 19:02:43 tontot.rndc.or.id named[16421]: no longer listening on 119.110.69.99#53
Jul 16 19:02:43 tontot.rndc.or.id named[16421]: no longer listening on 10.8.0.1#53
Jul 16 19:02:43 tontot.rndc.or.id named[16421]: no longer listening on 10.8.0.9#53
Jul 16 19:02:43 tontot.rndc.or.id systemd[1]: Failed to start Berkeley Internet Name Domain (DNS).
Jul 16 19:02:43 tontot.rndc.or.id systemd[1]: Unit named-chroot.service entered failed state.
[root@tontot ~]# journalctl -xn
-- Logs begin at Mon 2013-07-08 04:43:06 WIT, end at Tue 2013-07-16 19:04:01 WIT. --
Jul 16 19:02:43 tontot.rndc.or.id systemd[1]: named-chroot.service operation timed out. Terminating.
Jul 16 19:02:43 tontot.rndc.or.id systemd-journal[271]: Suppressed 2134 messages from /system/named-chroot.service
-- Subject: Messages from a service have been suppressed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- Documentation: man:journald.conf(5)
-- 
-- A service has logged too many messages within a time period. Messages
-- from the service have been dropped.
-- 
-- Note that only messages from the service in question have been
-- dropped, other services' messages are unaffected.
-- 
-- The limits when messages are dropped may be configured with
-- RateLimitInterval= and RateLimitBurst= in
-- /etc/systemd/journald.conf. See journald.conf(5) for details.
Jul 16 19:02:43 tontot.rndc.or.id named[16421]: no longer listening on 127.0.0.1#53
Jul 16 19:02:43 tontot.rndc.or.id named[16421]: no longer listening on 119.110.69.99#53
Jul 16 19:02:43 tontot.rndc.or.id named[16421]: no longer listening on 10.8.0.1#53
Jul 16 19:02:43 tontot.rndc.or.id named[16421]: no longer listening on 10.8.0.9#53
Jul 16 19:02:43 tontot.rndc.or.id systemd[1]: Failed to start Berkeley Internet Name Domain (DNS).
-- Subject: Unit named-chroot.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- Documentation: http://www.freedesktop.org/wiki/Software/systemd/catalog/be02cf6855d2428ba40df7e9d022f03d
-- 
-- Unit named-chroot.service has failed.
-- 
-- The result is failed.
Jul 16 19:02:43 tontot.rndc.or.id systemd[1]: Unit named-chroot.service entered failed state.
Jul 16 19:03:01 tontot.rndc.or.id CROND[16483]: (root) CMD (/usr/sbin/systemstats > /dev/null 2>&1)
Jul 16 19:04:01 tontot.rndc.or.id CROND[16558]: (root) CMD (/usr/sbin/systemstats > /dev/null 2>&1)

And named-chroot.service failed to start again.

[root@tontot ~]# uname -a
Linux tontot.rndc.or.id 3.9.9-302.fc19.x86_64 #1 SMP Sat Jul 6 13:41:07 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
[root@tontot ~]# cat /etc/redhat-release 
Fedora release 19 (Schrödinger’s Cat)
[root@tontot ~]# 

Any hints ?

Comment 3 Indra Kurniawan 2013-07-16 12:29:52 UTC
Hi Tomas,

I also followed your hint about putting this directive :

pid-file      "/run/named/named.pid";

on my named.conf

And here's the result :

[root@tontot ~]# grep -i pid /etc/named.conf
	pid-file	"/run/named/named.pid";
[root@tontot ~]# file /run/named/named.pid 
/run/named/named.pid: empty
[root@tontot ~]# systemctl start named-chroot.service
Job for named-chroot.service failed. See 'systemctl status named-chroot.service' and 'journalctl -xn' for details.
[root@tontot ~]# systemctl status named-chroot.service
named-chroot.service - Berkeley Internet Name Domain (DNS)
   Loaded: loaded (/usr/lib/systemd/system/named-chroot.service; enabled)
   Active: failed (Result: timeout) since Tue 2013-07-16 19:20:02 WIT; 1min 37s ago
  Process: 16345 ExecStopPost=/usr/libexec/setup-named-chroot.sh /var/named/chroot off (code=exited, status=0/SUCCESS)
  Process: 16340 ExecStop=/bin/sh -c /usr/sbin/rndc stop > /dev/null 2>&1 || /bin/kill -TERM $MAINPID (code=exited, status=0/SUCCESS)
  Process: 17866 ExecStart=/usr/sbin/named -u named -t /var/named/chroot $OPTIONS (code=exited, status=0/SUCCESS)
  Process: 17863 ExecStartPre=/usr/sbin/named-checkconf -t /var/named/chroot -z /etc/named.conf (code=exited, status=0/SUCCESS)
  Process: 17841 ExecStartPre=/usr/libexec/setup-named-chroot.sh /var/named/chroot on (code=exited, status=0/SUCCESS)
  Process: 17840 ExecStartPre=/usr/libexec/generate-rndc-key.sh (code=exited, status=0/SUCCESS)
 Main PID: 16261 (code=exited, status=0/SUCCESS)
   CGroup: name=systemd:/system/named-chroot.service

Jul 16 19:18:31 tontot.rndc.or.id named-checkconf[17863]: zone ads.massinfra.nl/IN: loaded serial 2002061000
Jul 16 19:18:32 tontot.rndc.or.id named[17869]: using built-in DLV key for view _default
Jul 16 19:18:34 tontot.rndc.or.id systemd[1]: Failed to read PID from file /var/named/chroot/run/named/named.pid: Invalid argument
Jul 16 19:20:02 tontot.rndc.or.id systemd[1]: named-chroot.service operation timed out. Terminating.
Jul 16 19:20:02 tontot.rndc.or.id named[17869]: no longer listening on 127.0.0.1#53
Jul 16 19:20:02 tontot.rndc.or.id named[17869]: no longer listening on 119.110.69.99#53
Jul 16 19:20:02 tontot.rndc.or.id named[17869]: no longer listening on 10.8.0.1#53
Jul 16 19:20:02 tontot.rndc.or.id named[17869]: no longer listening on 10.8.0.9#53
Jul 16 19:20:02 tontot.rndc.or.id systemd[1]: Failed to start Berkeley Internet Name Domain (DNS).
Jul 16 19:20:02 tontot.rndc.or.id systemd[1]: Unit named-chroot.service entered failed state.
[root@tontot ~]# journalctl -xn
-- Logs begin at Mon 2013-07-08 04:43:06 WIT, end at Tue 2013-07-16 19:21:01 WIT. --
Jul 16 19:20:01 tontot.rndc.or.id CROND[17980]: (root) CMD (/usr/sbin/systemstats > /dev/null 2>&1)
Jul 16 19:20:02 tontot.rndc.or.id systemd[1]: named-chroot.service operation timed out. Terminating.
Jul 16 19:20:02 tontot.rndc.or.id systemd-journal[271]: Suppressed 2127 messages from /system/named-chroot.service
-- Subject: Messages from a service have been suppressed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- Documentation: man:journald.conf(5)
-- 
-- A service has logged too many messages within a time period. Messages
-- from the service have been dropped.
-- 
-- Note that only messages from the service in question have been
-- dropped, other services' messages are unaffected.
-- 
-- The limits when messages are dropped may be configured with
-- RateLimitInterval= and RateLimitBurst= in
-- /etc/systemd/journald.conf. See journald.conf(5) for details.
Jul 16 19:20:02 tontot.rndc.or.id named[17869]: no longer listening on 127.0.0.1#53
Jul 16 19:20:02 tontot.rndc.or.id named[17869]: no longer listening on 119.110.69.99#53
Jul 16 19:20:02 tontot.rndc.or.id named[17869]: no longer listening on 10.8.0.1#53
Jul 16 19:20:02 tontot.rndc.or.id named[17869]: no longer listening on 10.8.0.9#53
Jul 16 19:20:02 tontot.rndc.or.id systemd[1]: Failed to start Berkeley Internet Name Domain (DNS).
-- Subject: Unit named-chroot.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- Documentation: http://www.freedesktop.org/wiki/Software/systemd/catalog/be02cf6855d2428ba40df7e9d022f03d
-- 
-- Unit named-chroot.service has failed.
-- 
-- The result is failed.
Jul 16 19:20:02 tontot.rndc.or.id systemd[1]: Unit named-chroot.service entered failed state.
Jul 16 19:21:01 tontot.rndc.or.id CROND[18066]: (root) CMD (/usr/sbin/systemstats > /dev/null 2>&1)
[root@tontot ~]# 


The named-chroot.service still failed to start.

Comment 4 Tomáš Hozza 2013-07-16 14:54:06 UTC
Can you please check mounts? named-chroot.service is written in such
an unfortunate way, that if starting named in a chroot fails, files and
dirs mounted into /vat/named/chroot remain mounted. So even if you changed
the named.conf after upgrading to F19, the file bind mounted into
/var/named/chroot/etc/named.conf remains the same (without pid-file statement).

Can you please try to run:
# ./usr/libexec/setup-named-chroot.sh /var/named/chroot off

Check if everything in /var/named/chroot was unmounted and then try to start
named-chroot again.

Anyway I think that named-chroot.service should unmount all mounted files
dirs if starting named in chroot fails. I'll reuse this Bug is the above
will process help you.

Comment 5 Paul Howarth 2013-07-28 14:40:07 UTC
(In reply to Tomas Hozza from comment #4)
> Can you please check mounts? named-chroot.service is written in such
> an unfortunate way, that if starting named in a chroot fails, files and
> dirs mounted into /vat/named/chroot remain mounted. So even if you changed
> the named.conf after upgrading to F19, the file bind mounted into
> /var/named/chroot/etc/named.conf remains the same (without pid-file
> statement).
> 
> Can you please try to run:
> # ./usr/libexec/setup-named-chroot.sh /var/named/chroot off
> 
> Check if everything in /var/named/chroot was unmounted and then try to start
> named-chroot again.

After adding pid-file to named.conf and then running that script sufficient times to unmount everything in the chroot (there were several versions of everything mounted on top of each other after multiple failed attempts to start named-chroot, visible from "mount" output), I was then able to start named-chroot.

> Anyway I think that named-chroot.service should unmount all mounted files
> dirs if starting named in chroot fails. I'll reuse this Bug is the above
> will process help you.

I think that's a good idea too.

Comment 6 Tomáš Hozza 2013-08-14 14:16:53 UTC
Closing this Bug as NOTABUG, since the issue was caused by missing pid-file
statement in named.conf which then broke the named-chroot.

Anyway I created a new Bug #997030 to track cleanup and fixing of 
named(-sdb)-chroot.service but there is a bug in systemd that needs to be
fixed first.