Modifying data files while named is reloading

[Laurent Weislo]

Hi,

We had a strange behaviour with our old master running bind version: 9.3.6
release: 20.P1.el5.

We modify NSC m4 data files when adding one or more A records and use the
make command to build the full environment on the master itself. At the end
of the build, an HUP signal is sent to the named process. After the signal
is sent, if a new change comes in, the process occurs again, thus modifying
the files (that are supposed to be already loaded by named).
After a bunch of years and under heavy load on the master, we lost almost
4K records because the domain file seems to have been loaded while being
generated.

My questions are:
- is 'rndc reload' returning when all zone files have been reloaded or is
it returning while the loading process is ongoing ?
- same question with sending a HUP signal ? does it behave like 'rndc
reload' ?
- how to ensure that named has loaded the files before modifying them again
since they are at the same location ?

The log message reports 'loading configuration', but why not 'configuration
files loaded' ?

Below is the event timeline, I hope it is clear enough for everyone:
1. Oct 16 17:24:18 SLAVE1 named[29671]: [ID 873579 daemon.info] transfer
of 'our.domain.com/IN' from 192.168.122.100#53: Transfer completed: 10
messages, *14890* records, 413507 bytes, 0.249 secs (1660670 bytes/sec)
2. (10/16/2018 17:28:57.202:1683726) : user pid=7501 uid=root
auid=unknown(65030) msg='cmd=/sbin/service named reload (terminal=?
res=success)'
3. Oct 16 17:28:57 MASTER named[3292]: loading configuration from
'/etc/named.conf' -> 2018101639
4. AUTOMATION TOOL:16-10 17:28:57 newhostname 1045 Add DNS START
5. 2018-10-16 17:29:00 +0200 (Tue, 16 Oct 2018) | 1 line IDXXX: Add DNS
entry newhostname with 10.10.10.10 | r20907 |
6. Oct 16 17:29:02 MASTER named[3292]: zone/our.domain.com:11473: file
does not end with newline <- NSC make is running, generating new files
because newhostname is added to a m4 file.
7. Oct 16 17:29:02 MASTER named[3292]: zone our.domain.com/IN: loaded
serial 2018101640
8. Oct 16 17:29:02 MASTER named[3292]: zone our.domain.com/IN: sending
notifies (serial 2018101640)
9. Oct 16 17:29:19 SLAVE1 named[29671]: [ID 873579 daemon.info] transfer
of 'our.domain.com/IN' from 192.168.122.100#53: Transfer completed: 7
messages, *10806* records, 302763 bytes, 0.192 secs (1576890 bytes/sec)
10. (10/16/2018 17:34:27.798:1683828) : user pid=12079 uid=root
auid=unknown(65030) msg='cmd=/sbin/service named reload (terminal=?
res=success)'
11. Oct 16 17:34:27 MASTER named[3292]: loading configuration from
'/etc/named.conf' -> 2018101640
12. AUTOMATION TOOL:16-10 17:34:28 newhostname 1045 Add DNS SUCCESS
13. Oct 16 17:34:33 MASTER named[3292]: zone our.domain.com/IN: zone serial
unchanged
14. Oct 16 17:34:33 MASTER named[3292]: zone our.domain.com/IN: loaded
serial 2018101640
15. Oct 16 17:34:33 MASTER named[3292]: zone our.domain.com/IN: sending
notifies (serial 2018101640)
16. (10/16/2018 17:39:59.934:1683878) : user pid=15753 uid=root
auid=unknown(65030) msg='cmd=/sbin/service named reload (terminal=?
res=success)'
17. Oct 16 17:40:52 SLAVE1 named[29671]: [ID 873579 daemon.info] transfer
of 'our.domain.com/IN' from 192.168.122.100#53: Transfer completed: 10
messages, *14893* records, 413605 bytes, 0.255 secs (1621980 bytes/sec)


Thank you for you help and sorry to bother you with that.

[Anne Bennett]

Post by Laurent Weislo
After a bunch of years and under heavy load on the master, we lost almost
4K records because the domain file seems to have been loaded while being
generated.

Wouldn't the best solution be to modify your generation process
to write to temporary files, and then to move them into place
when fully built, rather than leaving significant amounts of
time during which your zone file is in a partially built state?


Anne.

[Barry Margolin]

Post by Anne Bennett

Post by Laurent Weislo
After a bunch of years and under heavy load on the master, we lost almost
4K records because the domain file seems to have been loaded while being
generated.

Wouldn't the best solution be to modify your generation process
to write to temporary files, and then to move them into place
when fully built, rather than leaving significant amounts of
time during which your zone file is in a partially built state?

This is definitely the right solution. As long as you're moving within
the same filesystem, this is an atomic rename operation.

[Bob Harold]

Post by Laurent Weislo
Hi,
We had a strange behaviour with our old master running bind version: 9.3.6
release: 20.P1.el5.
We modify NSC m4 data files when adding one or more A records and use the
make command to build the full environment on the master itself. At the end
of the build, an HUP signal is sent to the named process. After the signal
is sent, if a new change comes in, the process occurs again, thus modifying
the files (that are supposed to be already loaded by named).
After a bunch of years and under heavy load on the master, we lost almost
4K records because the domain file seems to have been loaded while being
generated.
- is 'rndc reload' returning when all zone files have been reloaded or is
it returning while the loading process is ongoing ?

I believe that rndc returns immediately, while the loading process is just
starting.

Post by Laurent Weislo
- same question with sending a HUP signal ? does it behave like 'rndc
reload' ?

Signals like 'HUP' always return immediately, they have no way of knowing
what the process will do with the signal, if anything.

Post by Laurent Weislo
- how to ensure that named has loaded the files before modifying them
again since they are at the same location ?

Good question. For sure, as Anne says, you want to build temporary files
and 'move' them to the final location, so that there are never partial
files in place.

Post by Laurent Weislo
The log message reports 'loading configuration', but why not
'configuration files loaded' ?

I believe that the process starts with:
18-Oct-2018 12:55:29.975 general: info: received control channel command
'reload'
18-Oct-2018 12:55:29.975 general: info: loading configuration from
'/etc/named.conf'

And ends with:
18-Oct-2018 12:55:30.358 general: notice: all zones loaded
--
Bob Harold

Post by Laurent Weislo
1. Oct 16 17:24:18 SLAVE1 named[29671]: [ID 873579 daemon.info] transfer
of 'our.domain.com/IN' from 192.168.122.100#53: Transfer completed: 10
messages, *14890* records, 413507 bytes, 0.249 secs (1660670 bytes/sec)
2. (10/16/2018 17:28:57.202:1683726) : user pid=7501 uid=root
auid=unknown(65030) msg='cmd=/sbin/service named reload (terminal=?
res=success)'
3. Oct 16 17:28:57 MASTER named[3292]: loading configuration from
'/etc/named.conf' -> 2018101639
4. AUTOMATION TOOL:16-10 17:28:57 newhostname 1045 Add DNS START
5. 2018-10-16 17:29:00 +0200 (Tue, 16 Oct 2018) | 1 line IDXXX: Add DNS
entry newhostname with 10.10.10.10 | r20907 |
6. Oct 16 17:29:02 MASTER named[3292]: zone/our.domain.com:11473: file
does not end with newline <- NSC make is running, generating new files
because newhostname is added to a m4 file.
7. Oct 16 17:29:02 MASTER named[3292]: zone our.domain.com/IN: loaded
serial 2018101640
8. Oct 16 17:29:02 MASTER named[3292]: zone our.domain.com/IN: sending
notifies (serial 2018101640)
9. Oct 16 17:29:19 SLAVE1 named[29671]: [ID 873579 daemon.info] transfer
of 'our.domain.com/IN' from 192.168.122.100#53: Transfer completed: 7
messages, *10806* records, 302763 bytes, 0.192 secs (1576890 bytes/sec)
10. (10/16/2018 17:34:27.798:1683828) : user pid=12079 uid=root
auid=unknown(65030) msg='cmd=/sbin/service named reload (terminal=?
res=success)'
11. Oct 16 17:34:27 MASTER named[3292]: loading configuration from
'/etc/named.conf' -> 2018101640
12. AUTOMATION TOOL:16-10 17:34:28 newhostname 1045 Add DNS SUCCESS
13. Oct 16 17:34:33 MASTER named[3292]: zone our.domain.com/IN: zone
serial unchanged
14. Oct 16 17:34:33 MASTER named[3292]: zone our.domain.com/IN: loaded
serial 2018101640
15. Oct 16 17:34:33 MASTER named[3292]: zone our.domain.com/IN: sending
notifies (serial 2018101640)
16. (10/16/2018 17:39:59.934:1683878) : user pid=15753 uid=root
auid=unknown(65030) msg='cmd=/sbin/service named reload (terminal=?
res=success)'
17. Oct 16 17:40:52 SLAVE1 named[29671]: [ID 873579 daemon.info] transfer
of 'our.domain.com/IN' from 192.168.122.100#53: Transfer completed: 10
messages, *14893* records, 413605 bytes, 0.255 secs (1621980 bytes/sec)
Thank you for you help and sorry to bother you with that.
_______________________________________________
Please visit https://lists.isc.org/mailman/listinfo/bind-users to
unsubscribe from this list
bind-users mailing list
https://lists.isc.org/mailman/listinfo/bind-users