enh: functional tests: lower default_timeout, print elapsed_ms for each test

docker/Dockerfile.tester

@@ -2,7 +2,7 @@ FROM debian:trixie
 LABEL maintainer="stephane.lesimple+bastion@ovhcloud.com"
 
 # install prerequisites
-RUN apt-get update && DEBIAN_FRONTEND=noninteractive apt-get install -y jq netcat-traditional openssh-client procps bsdutils screen expect shellcheck libperl-critic-perl fping curl rsync moreutils
+RUN apt-get update && DEBIAN_FRONTEND=noninteractive apt-get install -y jq netcat-traditional openssh-client procps bsdutils screen expect shellcheck libperl-critic-perl fping curl rsync moreutils bc
 
 # add our code
 COPY . /opt/bastion

tests/functional/launch_tests_on_instance.sh

@@ -227,9 +227,10 @@ check_sourced_module_output()
 
     jq="jq --raw-output --compact-output --sort-keys"
     js="--json-greppable"
-    default_timeout=$((30 * opt_slowness_factor))
+    default_timeout=$((8 * opt_slowness_factor))
     t="timeout --foreground $default_timeout"
     tf="timeout --foreground $((default_timeout / 2))"
+    td="timeout --foreground $((default_timeout * 2))"
     a0="  $t ssh -F $mytmpdir/ssh_config -i $account0key1file $account0@$remote_ip -p $remote_port -- $js "
     a0f="$tf ssh -F $mytmpdir/ssh_config -i $account0key1file $account0@$remote_ip -p $remote_port -- $js "
     a1="  $t ssh -F $mytmpdir/ssh_config -i $account1key1file $account1@$remote_ip -p $remote_port -- $js "
@@ -238,6 +239,7 @@ check_sourced_module_output()
     a3="  $t ssh -F $mytmpdir/ssh_config -i $account3key1file $account3@$remote_ip -p $remote_port -- $js "
     a4="  $t ssh -F $mytmpdir/ssh_config -i $account4key1file $account4@$remote_ip -p $remote_port -- $js "
     a4f="$tf ssh -F $mytmpdir/ssh_config -i $account4key1file $account4@$remote_ip -p $remote_port -- $js "
+    a4d="$td ssh -F $mytmpdir/ssh_config -i $account4key1file $account4@$remote_ip -p $remote_port -- $js "
     a4np="$t ssh -F $mytmpdir/ssh_config -o PubkeyAuthentication=no $account4@$remote_ip -p $remote_port -- $js "
     r0="  $t ssh -F $mytmpdir/ssh_config -i $rootkeyfile           root@$remote_ip -p $remote_port -- "
 
@@ -450,6 +452,15 @@ run()
     fi
     case="$1"
     shift
+
+    # before replacing $basename with the current test's basename, print elapsed_ms for the previous test
+    if [ -n "${previous_test_t0:-}" ]; then
+        local elapsed_ms
+        elapsed_ms=$(perl -MTime::HiRes=time -e 'printf "%.0f\n", ((time() * 1000) - '"$previous_test_t0"')')
+        infomsg "elapsed_ms $elapsed_ms $basename"
+    fi
+    previous_test_t0=$(perl -MTime::HiRes=time -e 'printf "%.0f\n", time() * 1000')
+
     basename=$(printf '%04d-%s-%s' $testno $name $case | sed -re "s=/=_=g")
 
     # if we're about to run a script, keep a copy there
@@ -700,7 +711,7 @@ dump_vars_and_funcs()
 {
     set | grep -v -E '^('\
 'testno|section|code_warn_exclude|COPROC_PID|LINES|COLUMNS|PIPESTATUS|_|'\
-'BASH_LINENO|basename|case|json|name|tmpscript|grepit|got|isbad|'\
+'BASH_LINENO|basename|case|json|name|tmpscript|grepit|got|isbad|previous_test_t0|'\
 'nbfailedgrep|nbfailedcon|nbfailedgeneric|nbfailedlog|nbfailedret|shouldbe|modulename)='
 }
 

tests/functional/tests.d/370-mfa.sh

@@ -147,8 +147,8 @@ testsuite_mfa()
         contain REGEX 'Password:|Password for'
 
         # connect to 127.7.7.7 with MFA JIT, bad password
-        script a4_connect_g3_server_badpass "echo 'set timeout 45; \
-            spawn $a4 root@127.7.7.7; \
+        script a4_connect_g3_server_badpass "echo 'set timeout $((default_timeout * 2)); \
+            spawn $a4d root@127.7.7.7; \
             expect \"is required (password)\" { sleep 0.1; }; \
             expect \":\" { sleep 0.2; send \"$a4_password\\n\"; }; \
             expect \"is required (password)\" { sleep 0.1; }; \
@@ -184,8 +184,8 @@ testsuite_mfa()
         success a4_gen_self_egress_pass $a0 --osh accountGeneratePassword --account $account4 --do-it
         json .command accountGeneratePassword .error_code OK
 
-        script a4_connect_g3_server_selfpass_jitmfa "echo 'set timeout $default_timeout; \
-            spawn $a4 root@127.7.7.7 -P; \
+        script a4_connect_g3_server_selfpass_jitmfa "echo 'set timeout $((default_timeout * 2)); \
+            spawn $a4d root@127.7.7.7 -P; \
             expect \"is required (password)\" { sleep 0.1; }; \
             expect \":\" { sleep 0.2; send \"$a4_password\\n\"; }; \
             expect \"is required (password)\" { sleep 0.1; }; \
@@ -217,8 +217,8 @@ testsuite_mfa()
         contain REGEX 'Password:|Password for'
         json .command groupGeneratePassword .error_code OK
 
-        script a4_connect_g3_server_grouppass_jitmfa "echo 'set timeout $default_timeout; \
-            spawn $a4 root@127.7.7.7 --password $group3; \
+        script a4_connect_g3_server_grouppass_jitmfa "echo 'set timeout $((default_timeout * 2)); \
+            spawn $a4d root@127.7.7.7 --password $group3; \
             expect \"is required (password)\" { sleep 0.1; }; \
             expect \":\" { sleep 0.2; send \"$a4_password\\n\"; }; \
             expect \"is required (password)\" { sleep 0.1; }; \