Fix a race between "rndc reconfig" and waiting for a ./DNSKEY fetch to complete
Calling nextpart() after reconfiguring ns1 is not safe, because the expected log message may appear in ns5/named.run before nextpart() is run. With the TTL for ./DNSKEY set to 20 seconds, ns5 will refresh it after 10 seconds, by which time wait_for_log() will already have failed. This results in a false negative. However, just calling nextpart() before reconfiguring ns1 would introduce a different problem: if ns5 refreshed ./DNSKEY between these two steps, the subsequent wait_for_log() call would return immediately as it would come across the log message about a failure while refreshing ./DNSKEY instead of the expected success. This in turn would result in a different false negative as the root key would still be uninitialized by the time "rndc secroots" is called. Prevent both kinds of false negatives by: - calling nextpart() before reconfiguring ns1, in order to prevent the first case described above, - looking for a more specific log message, in order to prevent the second case described above. Also look for a more specific log message in the first part of the relevant check, not to fix any problem, but just to emphasize that a different fetch result is expected in that case. With these tweaks in place, if a (failed) ./DNSKEY refresh is scheduled between nextpart() and reconfiguring ns1, wait_for_log() will just wait for two more seconds (one "hour"), at which point another refresh attempt will be made that will succeed.
Showing with 3 additions and 3 deletions