Fix kasp timing issue on Windows

This fixes another intermittent failure in the kasp system test.
It does not happen often, except for in the Windows platform tests
where it takes a long time to run the tests.

In the "kasp" system test, there is an "rndc reconfig" call which
triggers a new rekey event.  check_next_key_event() verifies the time
remaining from the moment "rndc reconfig" is called until the next key
event.  However, the next key event time is calculated from the key
times provided during key creation (i.e. during test setup).  Given
this, if "rndc reconfig" is called a significant amount of time after
the test is started, some check_next_key_event() checks will fail.

Fix by calculating the time passed since the start of the test and
when 'rndc reconfig' happens.  Substract this time from the
calculated next key event.

This only needs to be done after an "rndc reconfig" on zones where
the keymgr needs to wait for a period of time (for example for keys
to become OMNIPRESENT, or HIDDEN). This is on step 2 and step 5 of
the algorithm rollover.  In step 2 there is a waiting period before
the DNSKEY is OMNIPRESENT, in step 5 there is a waiting period
before the DNSKEY is HIDDEN.

In step 1 new keys are created, in step 3 and 4 key states just
entered OMNIPRESENT, and in step 6 we no longer care because the
key lifetime is unlimited and we default to checking once per hour.

Regardless of our indifference about the next key event after step 6,
change some of the key timings in the setup script to better
reflect reality: DNSKEY is in HIDDEN after step 5, DS times have
changed when the new DS became active.

diff --git a/CHANGES b/CHANGES
index 26d160b18d85eba5e93adaa736145bb639bcd5e8..3c771b5e6c0f79bf20aeaeeba69aeac9227660ba 100644 (file)
--- a/CHANGES
+++ b/CHANGES
@@ -1,3 +1,5 @@
+5375.  [test]          Fix timing issue in kasp test. [GL #1669]
+
 5374.  [bug]           Statistics counters counting recursive clients and
                        active connections could underflow. [GL #1087]
 

diff --git a/bin/tests/system/kasp/ns6/setup.sh b/bin/tests/system/kasp/ns6/setup.sh
index 430e1c9e3e38a7819043e8f521d6c7a69c654142..8d01bd23b9d1f6cba7ce490f7b8793e5f2f06e66 100644 (file)
--- a/bin/tests/system/kasp/ns6/setup.sh
+++ b/bin/tests/system/kasp/ns6/setup.sh
@@ -193,9 +193,9 @@ TactN="now-40h"
 TpubN1="now-40h"
 TactN1="now-31h"
 TremN="now-2h"
-$SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $U $TremN  -r $U $TremN  -d $H $TremN  "$KSK1" > settime.out.$zone.1 2>&1
+$SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $U $TremN  -r $U $TremN  -d $H $TactN1 "$KSK1" > settime.out.$zone.1 2>&1
 $SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $U $TremN  -z $U $TremN                "$ZSK1" > settime.out.$zone.2 2>&1
-$SETTIME -s -P $TpubN1 -A $TactN1        -g $O -k $O $TpubN1 -r $O $TpubN1 -d $O $TremN  "$KSK2" > settime.out.$zone.1 2>&1
+$SETTIME -s -P $TpubN1 -A $TactN1        -g $O -k $O $TpubN1 -r $O $TpubN1 -d $O $TactN1 "$KSK2" > settime.out.$zone.1 2>&1
 $SETTIME -s -P $TpubN1 -A $TactN1        -g $O -k $O $TpubN1 -z $R $TpubN1               "$ZSK2" > settime.out.$zone.2 2>&1
 # Fake lifetime of old algorithm keys.
 echo "Lifetime: 0" >> "${KSK1}.state"
@@ -218,10 +218,11 @@ ZSK2=$($KEYGEN -a ECDSAP256SHA256 -L 3600 $zone 2> keygen.out.$zone.2)
 TactN="now-47h"
 TpubN1="now-47h"
 TactN1="now-38h"
-TremN="now-9h"
-$SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $U $TremN  -r $U $TremN  -d $H $TremN  "$KSK1" > settime.out.$zone.1 2>&1
-$SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $U $TremN  -z $U $TremN                "$ZSK1" > settime.out.$zone.2 2>&1
-$SETTIME -s -P $TpubN1 -A $TactN1        -g $O -k $O $TpubN1 -r $O $TpubN1 -d $O $TremN  "$KSK2" > settime.out.$zone.1 2>&1
+TdeaN="now-9h"
+TremN="now-7h"
+$SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $H $TremN  -r $U $TdeaN  -d $H $TactN1 "$KSK1" > settime.out.$zone.1 2>&1
+$SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $H $TremN  -z $U $TdeaN                "$ZSK1" > settime.out.$zone.2 2>&1
+$SETTIME -s -P $TpubN1 -A $TactN1        -g $O -k $O $TpubN1 -r $O $TpubN1 -d $O $TactN1 "$KSK2" > settime.out.$zone.1 2>&1
 $SETTIME -s -P $TpubN1 -A $TactN1        -g $O -k $O $TpubN1 -z $R $TpubN1               "$ZSK2" > settime.out.$zone.2 2>&1
 # Fake lifetime of old algorithm keys.
 echo "Lifetime: 0" >> "${KSK1}.state"
@@ -333,9 +334,10 @@ TactN="now-47h"
 TpubN1="now-47h"
 TactN1="now-44h"
 TsubN1="now-38h"
-TremN="now-9h"
-$SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $U $TremN  -r $U $TremN  -z $U $TremN  -d $H $TremN  "$CSK1" > settime.out.$zone.1 2>&1
-$SETTIME -s -P $TpubN1 -A $TpubN1        -g $O -k $O $TactN1 -r $O $TactN1 -z $O $TsubN1 -d $O $TremN  "$CSK2" > settime.out.$zone.1 2>&1
+TdeaN="now-9h"
+TremN="now-7h"
+$SETTIME -s -P $TactN  -A $TactN  -I now -g $H -k $H $TremN  -r $U $TdeaN  -z $U $TdeaN  -d $H $TactN1 "$CSK1" > settime.out.$zone.1 2>&1
+$SETTIME -s -P $TpubN1 -A $TpubN1        -g $O -k $O $TactN1 -r $O $TactN1 -z $O $TsubN1 -d $O $TactN1 "$CSK2" > settime.out.$zone.1 2>&1
 # Fake lifetime of old algorithm keys.
 echo "Lifetime: 0" >> "${CSK1}.state"
 cat template.db.in "${CSK1}.key" "${CSK2}.key" > "$infile"

diff --git a/bin/tests/system/kasp/tests.sh b/bin/tests/system/kasp/tests.sh
index 3e7e41c406967639532a84c808d8d6371efc0f5f..95c4e2392a223b60a236e84619f4c78f261391a6 100644 (file)
--- a/bin/tests/system/kasp/tests.sh
+++ b/bin/tests/system/kasp/tests.sh
@@ -13,6 +13,7 @@
 SYSTEMTESTTOP=..
 . "$SYSTEMTESTTOP/conf.sh"
 
+start_time="$(TZ=UTC date +%s)"
 status=0
 n=0
 
@@ -3052,6 +3053,11 @@ echo_i "reconfig dnssec-policy to trigger algorithm rollover"
 copy_setports ns6/named2.conf.in ns6/named.conf
 rndc_reconfig ns6 10.53.0.6
 
+# Calculate time passed to correctly check for next key events.
+now="$(TZ=UTC date +%s)"
+time_passed=$((now-start_time))
+echo_i "${time_passed} seconds passed between start of tests and reconfig"
+
 #  The NSEC record at the apex of the zone and its RRSIG records are
 #  added as part of the last step in signing a zone.  We wait for the
 #  NSEC records to appear before proceeding with a counter to prevent
@@ -3326,8 +3332,11 @@ dnssec_verify
 # algorithm.  This is the max-zone-ttl plus zone propagation delay
 # plus retire safety: 6h + 1h + 2h.  But three hours have already passed
 # (the time it took to make the DNSKEY omnipresent), so the next event
-# should be scheduled in 6 hour: 21600 seconds.
-check_next_key_event 21600
+# should be scheduled in 6 hour: 21600 seconds.  Prevent intermittent
+# false positives on slow platforms by subtracting the number of seconds
+# which passed between key creation and invoking 'rndc reconfig'.
+next_time=$((21600-time_passed))
+check_next_key_event $next_time
 
 #
 # Zone: step3.algorithm-roll.kasp
@@ -3399,8 +3408,11 @@ dnssec_verify
 # Next key event is when the RSASHA1 signatures become HIDDEN.  This happens
 # after the max-zone-ttl plus zone propagation delay plus retire safety
 # (6h + 1h + 2h) minus the time already passed since the UNRETENTIVE state has
-# been reached (2h): 9h - 2h = 7h = 25200
-check_next_key_event 25200
+# been reached (2h): 9h - 2h = 7h = 25200 seconds. Prevent intermittent
+# false positives on slow platforms by subtracting the number of seconds
+# which passed between key creation and invoking 'rndc reconfig'.
+next_time=$((25200-time_passed))
+check_next_key_event $next_time
 
 #
 # Zone: step6.algorithm-roll.kasp
@@ -3498,8 +3510,11 @@ dnssec_verify
 # algorithm.  This is the max-zone-ttl plus zone propagation delay
 # plus retire safety: 6h + 1h + 2h.  But three hours have already passed
 # (the time it took to make the DNSKEY omnipresent), so the next event
-# should be scheduled in 6 hour: 21600 seconds.
-check_next_key_event 21600
+# should be scheduled in 6 hour: 21600 seconds.  Prevent intermittent
+# false positives on slow platforms by subtracting the number of seconds
+# which passed between key creation and invoking 'rndc reconfig'.
+next_time=$((21600-time_passed))
+check_next_key_event $next_time
 
 #
 # Zone: step3.csk-algorithm-roll.kasp
@@ -3567,8 +3582,11 @@ dnssec_verify
 # Next key event is when the RSASHA1 signatures become HIDDEN.  This happens
 # after the max-zone-ttl plus zone propagation delay plus retire safety
 # (6h + 1h + 2h) minus the time already passed since the UNRETENTIVE state has
-# been reached (2h): 9h - 2h = 7h = 25200
-check_next_key_event 25200
+# been reached (2h): 9h - 2h = 7h = 25200 seconds.  Prevent intermittent
+# false positives on slow platforms by subtracting the number of seconds
+# which passed between key creation and invoking 'rndc reconfig'.
+next_time=$((25200-time_passed))
+check_next_key_event $next_time
 
 #
 # Zone: step6.csk-algorithm-roll.kasp