Bind9 service don't start after reboot

UCS - Univention Corporate Server
,
1

Hi to everyone,
i did upgrade my UCS server 4.4 to 5.0-1 errata279.

Unfortunately after reboot, i found out that bind9 was not running.
Below the result of cat command on syslog

Apr  6 04:52:12 zbdc01 systemd[1]: Started LSB: Univention Directory Policy.
Apr  6 04:52:13 zbdc01 systemd[1]: bind9.service: Control process exited, code=exited, status=124/n/a
Apr  6 04:52:14 zbdc01 freeradius[637]: tls: Using cached TLS configuration from previous invocation
Apr  6 04:52:14 zbdc01 freeradius[637]: rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output
Apr  6 04:52:15 zbdc01 freeradius[637]: rlm_ldap: libldap vendor: OpenLDAP, version: 20447
Apr  6 04:52:15 zbdc01 freeradius[637]: rlm_ldap (ldap): Initialising connection pool
Apr  6 04:52:15 zbdc01 freeradius[637]: rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked
Apr  6 04:52:15 zbdc01 freeradius[637]: rlm_mschap (mschap): authenticating by calling 'ntlm_auth'
Apr  6 04:52:15 zbdc01 freeradius[637]: Ignoring "sql" (see raddb/mods-available/README.rst)
Apr  6 04:52:15 zbdc01 freeradius[637]: radiusd: #### Skipping IP addresses and Ports ####
Apr  6 04:52:15 zbdc01 freeradius[637]: Configuration appears to be OK
Apr  6 04:52:15 zbdc01 freeradius[637]: rlm_ldap (ldap): Removing connection pool
Apr  6 04:52:16 zbdc01 systemd[1]: Started FreeRADIUS multi-protocol policy server.
Apr  6 04:52:21 zbdc01 named[1005]: samba_dlz: started for DN DC=mydomain,DC=it
Apr  6 04:52:21 zbdc01 named[1005]: samba_dlz: starting configure
Apr  6 04:52:22 zbdc01 named[1005]: samba_dlz: trying partition 'CN=MicrosoftDNS,DC=DomainDnsZones,DC=mydomain,DC=it'
Apr  6 04:52:22 zbdc01 named[1005]: samba_dlz: configured writeable zone 'mydomain.it'
Apr  6 04:52:22 zbdc01 named[1005]: samba_dlz: trying partition 'CN=MicrosoftDNS,DC=DomainDnsZones,DC=mydomain,DC=it'
Apr  6 04:52:22 zbdc01 named[1005]: samba_dlz: configured writeable zone '0.1.10.in-addr.arpa'
Apr  6 04:52:22 zbdc01 named[1005]: samba_dlz: trying partition 'CN=MicrosoftDNS,DC=DomainDnsZones,DC=mydomain,DC=it'
Apr  6 04:52:22 zbdc01 named[1005]: samba_dlz: configured writeable zone '0.2.10.in-addr.arpa'
Apr  6 04:52:22 zbdc01 named[1005]: samba_dlz: trying partition 'CN=MicrosoftDNS,DC=ForestDnsZones,DC=mydomain,DC=it'
Apr  6 04:52:22 zbdc01 named[1005]: samba_dlz: configured writeable zone '_msdcs.mydomain.it'
Apr  6 04:52:22 zbdc01 named[1005]: none:106: 'max-cache-size 90%' - setting to 7149MB (out of 7943MB)
Apr  6 04:52:22 zbdc01 named[1005]: loading configuration: shutting down
Apr  6 04:52:22 zbdc01 named[1005]: exiting (due to fatal error)
Apr  6 04:52:22 zbdc01 named[1005]: ../../../bin/named/client.c:3516: unexpected error:
Apr  6 04:52:22 zbdc01 named[1005]: isc_socket_accept() failed: shutting down
Apr  6 04:52:22 zbdc01 named[1005]: ../../../bin/named/client.c:3516: unexpected error:
Apr  6 04:52:22 zbdc01 named[1005]: isc_socket_accept() failed: shutting down
Apr  6 04:52:22 zbdc01 named[1005]: ../../../bin/named/client.c:3516: unexpected error:
Apr  6 04:52:22 zbdc01 named[1005]: isc_socket_accept() failed: shutting down
Apr  6 04:52:23 zbdc01 systemd[1]: bind9.service: Main process exited, code=exited, status=1/FAILURE
Apr  6 04:52:23 zbdc01 systemd[1]: bind9.service: Failed with result 'exit-code'.
Apr  6 04:52:23 zbdc01 systemd[1]: Failed to start BIND Domain Name Server with samba4 backend.

I tried to search in google about this issue “isc_socket_accept() failed: shutting down” and i found this in Bind repository

bind9/CHANGES at main · isc-projects/bind9 · GitHub where they talk about a fix on isc_socket_accept

"

1562. [bug] isc_socket_create() and isc_socket_accept() could
leak memory under error conditions. [RT #10230]

"

If i do start bind9 service manually (in GUI) it starts and works without any issue …
So i did a workaround, implementing a crontab script that check if exists a MainPID of bind9.service, otherwise it starts the service. But what can i do to fix this problem ufficially?

Thanks
Leonardo

2

We have the same problem: after reboot bind9 does not start automatically on one of two UCS systems. After starting the service manually from GUI it is workuíng fine. The other UCS system (Backup Server, installed identically) does not have the problem.

3

I have the same problem here:

Jun 16 19:33:39 ucs named[947]: ----------------------------------------------------
Jun 16 19:33:39 ucs named[947]: BIND 9 is maintained by Internet Systems Consortium,
Jun 16 19:33:39 ucs named[947]: Inc. (ISC), a non-profit 501(c)(3) public-benefit
Jun 16 19:33:39 ucs named[947]: corporation.  Support and training for BIND 9 are
Jun 16 19:33:39 ucs named[947]: available at https://www.isc.org/support
Jun 16 19:33:39 ucs named[947]: ----------------------------------------------------
Jun 16 19:33:39 ucs named[947]: adjusted limit on open files from 524288 to 1048576
Jun 16 19:33:39 ucs named[947]: found 4 CPUs, using 4 worker threads
Jun 16 19:33:39 ucs named[947]: using 3 UDP listeners per interface
Jun 16 19:33:39 ucs named[947]: using up to 4096 sockets
Jun 16 19:33:39 ucs named[947]: loading configuration from '/etc/bind/named.conf.samba4'
Jun 16 19:33:39 ucs named[947]: reading built-in trust anchors from file '/etc/bind/bind.keys'
Jun 16 19:33:40 ucs named[947]: GeoIP Country (IPv4) (type 1) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP Country (IPv6) (type 12) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP City (IPv4) (type 2) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP City (IPv4) (type 6) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP City (IPv6) (type 30) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP City (IPv6) (type 31) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP Region (type 3) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP Region (type 7) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP ISP (type 4) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP Org (type 5) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP AS (type 9) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP Domain (type 11) DB not available
Jun 16 19:33:40 ucs named[947]: GeoIP NetSpeed (type 10) DB not available
Jun 16 19:33:40 ucs named[947]: using default UDP/IPv4 port range: [32768, 60999]
Jun 16 19:33:40 ucs named[947]: using default UDP/IPv6 port range: [32768, 60999]
Jun 16 19:33:40 ucs named[947]: listening on IPv6 interfaces, port 53
Jun 16 19:33:40 ucs named[947]: listening on IPv4 interface lo, 127.0.0.1#53
Jun 16 19:33:40 ucs named[947]: listening on IPv4 interface eth0, XXXXXXXXX#53
Jun 16 19:33:40 ucs named[947]: generating session key for dynamic DNS
Jun 16 19:33:40 ucs named[947]: sizing zone task pool based on 3 zones
Jun 16 19:33:40 ucs named[947]: Loading 'samba4.zone' using driver dlopen
Jun 16 19:34:02 ucs named[947]: samba_dlz: started for DN XXXXXXXXX
Jun 16 19:34:02 ucs named[947]: samba_dlz: starting configure
Jun 16 19:34:05 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:05 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: trying partition 'XXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: configured writeable zone 'XXXXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: pre-W2k3 zone found
Jun 16 19:34:06 ucs named[947]: samba_dlz: Ignoring duplicate zone 'XXXXXXXXX' from 'XXXXXXXXX'
Jun 16 19:34:06 ucs named[947]: samba_dlz: Ignoring dnsZone XXXXXXXXX
Jun 16 19:34:06 ucs named[947]: none:106: 'max-cache-size 90%' - setting to 1777MB (out of 1974MB)
Jun 16 19:34:06 ucs named[947]: additionally listening on IPv4 interface docker0, 172.17.42.1#53
Jun 16 19:34:06 ucs named[947]: could not listen on UDP socket: shutting down
Jun 16 19:34:06 ucs named[947]: creating IPv4 interface docker0 failed; interface ignored
Jun 16 19:34:06 ucs named[947]: loading configuration: shutting down
Jun 16 19:34:06 ucs named[947]: exiting (due to fatal error)
Jun 16 19:34:06 ucs named[947]: ../../../bin/named/client.c:3516: unexpected error:
Jun 16 19:34:06 ucs named[947]: isc_socket_accept() failed: shutting down
Jun 16 19:34:06 ucs named[947]: ../../../bin/named/client.c:3516: unexpected error:
Jun 16 19:34:06 ucs named[947]: isc_socket_accept() failed: shutting down
Jun 16 19:34:06 ucs named[947]: ../../../bin/named/client.c:3516: unexpected error:
Jun 16 19:34:06 ucs named[947]: isc_socket_accept() failed: shutting down
Jun 16 19:34:06 ucs named[947]: samba_dlz: shutting down

Only the automatic start seems to be a problem, manual start of bin9 works without issues. Thank You

4

You do not have the same problem. But indeed yours eems to be similar. In the original post there was no information about the reason as it got cut by the author.

However, for your case it appears to be clear if you read the log entries. First, you have a duplicate zone. Go an search the forum for related entries - you will find a solution there.
Second, Looks like your bind is configured to listen on interface docker0 which is not up and running when bind9 starts. I assume it will be created at a later stage- when docker starts. So when you start bind9 after docker you should not have any issues. Please confirm,

Why this happens here I can not tell you. Might be a manual misoconfiguration of the docker interface or an unneeded entry for the listening interfaces for bind. I do not know- time for you to troubleshoot.

Hope it helps

/KNEBB

5

I compared syslog messages of failed bind9 autostart with the syslog message of successful manual start of bind9.
In case of failed autostart I have
samba4[1058]: rndc: connect failed: 127.0.0.1#953: connection refused
When starting bind9 manually the syslog shows at the same position
named[5829]: loading configuration from '/etc/bind/named.conf.samba4'
Probably bind9 is starting before samba4 is ready with starting? But I have not yet had enough time to look into it in more detail.

6

The problem resists after upgrading to UCS 5.0.2.

7

This is a duplicate from the following question:
https://help.univention.com/t/bind9-fails-to-start-automatically/20758

I had the same issue!

I have a large blacklist of domains and it seems that bind needs too long for samba to be able to connect to it.

I now increased the timeout specified in the following line of /usr/lib/univention-bind/samba4:

/usr/bin/timeout 30 /bin/sh -c "until rndc -p 953 status | grep --quiet 'server is up and running'; do sleep 1; 

--- /usr/lib/univention-bind/samba4        
+++ /usr/lib/univention-bind/samba4    
@@ -55,7 +55,7 @@
                /usr/sbin/rndc -p 953 stop
                ;;
        wait-for-startup)
-               /usr/bin/timeout 30 /bin/sh -c \
+               /usr/bin/timeout 270 /bin/sh -c \
                        "until rndc -p 953 status | grep --quiet 'server is up and running'; do sleep 1; done"
                ;;
 esac

Same Problem Description here:
https://bugzilla.redhat.com/show_bug.cgi?id=1069678