Autosign resigning too fast after dnssec-settime calls

Job #3570991 failed for ce1db001:

I've seen autosign fail in the ZSK roll test several times and it appears to be because dnssec-signzone is being called in the same second as dnssec-settime. dnssec-signzone uses the phase is set and is in the past as the determinant of when things change. Should this be made is set and is now or in the past? Which behaviour is consistent with named's behaviour? Which behaviour is less error prone? If we don't change the behaviour we need to add sleeps to ensure the tests succeed.

       -S     This option enables smart signing, which instructs dnssec-signzone to search the key repository for keys that match the zone
              being signed, and to include them in the zone if appropriate.

              When a key is found, its timing metadata is examined to determine how it should be used, according to the following rules.
              Each successive rule takes priority over the prior ones:
                 If no timing metadata has been set for the key, the key is published in the zone and used to sign the zone.

                 If the key's publication date is set and is in the past, the key is published in the zone.

                 If the key's activation date is set and is in the past, the key is published (regardless of publication date) and used to
                 sign the zone.

                 If the key's revocation date is set and is in the past, and the key is published, then the key is revoked, and the revoked
                 key is used to sign the zone.

                 If either the key's unpublication or deletion date is set and in the past, the key is NOT published or used to sign the
                 zone, regardless of any other metadata.

                 If the key's sync publication date is set and is in the past, synchronization records (type CDS and/or CDNSKEY) are
                 created.

                 If the key's sync deletion date is set and is in the past, synchronization records (type CDS and/or CDNSKEY) are removed.

2023-08-08 00:59:52 INFO:autosign     I:autosign_tmp_x_6wkr8z:preparing ZSK roll
2023-08-08 00:59:52 INFO:autosign     I:autosign_tmp_x_6wkr8z:ns1 A zone reload and thaw was started.
2023-08-08 00:59:52 INFO:autosign     I:autosign_tmp_x_6wkr8z:ns1 Check the logs to see the result.
2023-08-08 00:59:56 INFO:autosign     I:autosign_tmp_x_6wkr8z:revoking key to duplicated key ID
2023-08-08 00:59:56 INFO:autosign     dnssec-settime: warning: Permissions on the file ns2/Kbar.+013+59973.private have changed from 0644 to 0600 as a result of this operation.
2023-08-08 00:59:56 INFO:autosign     I:autosign_tmp_x_6wkr8z:ns2 A zone reload and thaw was started.
2023-08-08 00:59:56 INFO:autosign     I:autosign_tmp_x_6wkr8z:ns2 Check the logs to see the result.
2023-08-08 00:59:56 INFO:autosign     I:autosign_tmp_x_6wkr8z:waiting for changes to take effect
2023-08-08 01:00:01 INFO:autosign     I:autosign_tmp_x_6wkr8z:checking former standby key 5259 is now active (53)
2023-08-08 01:00:01 INFO:autosign     I:autosign_tmp_x_6wkr8z:failed

echo_i "preparing ZSK roll"
starttime=$($PERL -e 'print time(), "\n";')
oldfile=$(cat active.key)
oldid=$(keyfile_to_key_id "$(cat active.key)")
newfile=$(cat standby.key)
newid=$(keyfile_to_key_id "$(cat standby.key)")
$SETTIME -K ns1 -I now -D now+25 $oldfile > settime.out.test$n.1 || ret=1
$SETTIME -K ns1 -i 0 -S $oldfile $newfile > settime.out.test$n.2 || ret=1

# note previous zone serial number
oldserial=$($DIG $DIGOPTS +short soa . @10.53.0.1 | awk '{print $3}')

($RNDCCMD 10.53.0.1 freeze . 2>&1 | sed 's/^/ns1 /' | cat_i) || ret=1
cp ns1/root.db.signed ns1/root.db.1
$SIGNER -S -o . -O full -K ns1 -f ns1/root.db.signed ns1/root.db.1 > signing.root.out$n 2>&1 || ret=1
($RNDCCMD 10.53.0.1 thaw . 2>&1 | sed 's/^/ns1 /' | cat_i) || ret=1
sleep 4 
            
echo_i "revoking key to duplicated key ID"
$SETTIME -R now -K ns2 Kbar.+013+59973.key > settime.out.test$n.3 || ret=1
                
($RNDCCMD 10.53.0.2 freeze bar. 2>&1 | sed 's/^/ns2 /' | cat_i) || ret=1
cp ns2/bar.db.signed ns2/bar.db
$SIGNER -S -o bar. -O full -K ns2 ns2/bar.db > signing.bar.out$n 2>&1 || ret=1
($RNDCCMD 10.53.0.2 thaw bar. 2>&1 | sed 's/^/ns2 /' | cat_i) || ret=1
        
echo_i "waiting for changes to take effect"
sleep 5

echo_i "checking former standby key $newid is now active ($n)"
ret=0
$DIG $DIGOPTS dnskey . @10.53.0.1 > dig.out.ns1.test$n || ret=1
grep 'RRSIG.*'" $newid "'\. ' dig.out.ns1.test$n > /dev/null || ret=1
n=$((n + 1))
if [ $ret != 0 ]; then echo_i "failed"; fi
status=$((status + ret))

08-Aug-2023 00:59:52.469 allocate new control connection
08-Aug-2023 00:59:52.469 received control channel command 'freeze .'
08-Aug-2023 00:59:52.469 loop exclusive mode: starting
08-Aug-2023 00:59:52.469 loop exclusive mode: started
08-Aug-2023 00:59:52.469 zone_dump: zone ./IN: enter
08-Aug-2023 00:59:52.469 loop exclusive mode: ending
08-Aug-2023 00:59:52.469 loop exclusive mode: ended
08-Aug-2023 00:59:52.469 freezing zone './IN': success
08-Aug-2023 00:59:52.469 freeing control connection
08-Aug-2023 00:59:52.497 dump_done: zone ./IN: enter
08-Aug-2023 00:59:52.497 zone_journal_compact: zone ./IN: target journal size 7662
08-Aug-2023 00:59:52.497 zone ./IN: dns_journal_compact: success
08-Aug-2023 00:59:52.509 allocate new control connection
08-Aug-2023 00:59:52.509 received control channel command 'thaw .' 
08-Aug-2023 00:59:52.509 loop exclusive mode: starting
08-Aug-2023 00:59:52.509 loop exclusive mode: started 
08-Aug-2023 00:59:52.509 zone ./IN: starting load
08-Aug-2023 00:59:52.509 zone_startload: zone ./IN: enter
08-Aug-2023 00:59:52.509 loop exclusive mode: ending
08-Aug-2023 00:59:52.509 loop exclusive mode: ended
08-Aug-2023 00:59:52.509 thawing zone './IN': success
08-Aug-2023 00:59:52.509 freeing control connection
08-Aug-2023 00:59:52.509 zone_loaddone: zone ./IN: enter
08-Aug-2023 00:59:52.509 zone ./IN: number of nodes in database: 5
08-Aug-2023 00:59:52.509 zone ./IN: loaded; checking validity
08-Aug-2023 00:59:52.509 dns_zone_verifydb: zone ./IN: enter
08-Aug-2023 00:59:52.509 zone ./IN: zone serial (2000042101) unchanged. zone may fail to transfer to secondaries.
08-Aug-2023 00:59:52.509 zone ./IN: replacing zone database 
08-Aug-2023 00:59:52.509 calling free_rbtdb(.)
08-Aug-2023 00:59:52.509 done free_rbtdb(.)
08-Aug-2023 00:59:52.509 zone ./IN: loaded serial 2000042101 (DNSSEC signed)
08-Aug-2023 00:59:52.509 zone_postload: zone ./IN: done
08-Aug-2023 00:59:52.509 zone__settimer: zone ./IN: enter