Milliseconds provisioner/hook timing

CHANGELOG.md

@@ -11,6 +11,7 @@ permalink: /docs/en-US/changelog/
 ### Enhancements
 
 * Upgraded MariaDB from 10.5 to 10.11 ( #2728 )
+* Provisioner/Hook timings now show milliseconds ( #2735 )
 * Added a `skip_site_provisioner_update` option to prevent site provisioners being overwritten by updates ( #2733 )
 * Only start services that aren't running in post-up scripts ( #2732 )
 

provision/core/mariadb/provision.sh

@@ -136,11 +136,20 @@ function mysql_setup() {
   # happens after a `vagrant halt`. Check to see if it's running before
   # deciding whether to start or restart.
   if service mariadb status > /dev/null; then
-    vvv_info " * Starting the mariadb service"
-    service mariadb restart
+    vvv_info " * Restarting the mariadb service"
+    if ! service mariadb restart; then
+      vvv_error " * Restarting the MariaDB failed! Fetching service status."
+      service mariadb status
+      exit 1
+    fi
   else
     vvv_info " * Restarting mariadb service"
     service mariadb start
+    if ! service mariadb start; then
+      vvv_error " * Starting MariaDB failed! Fetching service status."
+      service mariadb status
+      exit 1
+    fi
   fi
 
   # IMPORT SQL

provision/provision-helpers.sh

@@ -78,6 +78,7 @@ function check_network_connection_to_host() {
     return 0
   fi
   vvv_error " ! Network connection issues found. Unable to reach <url>${url}</url>"
+  wget --spider --timeout=5 --tries=3 "${url}"
   return 1
 }
 export -f check_network_connection_to_host
@@ -119,7 +120,7 @@ function network_check() {
     vvv_error " "
     vvv_error "VVV tried to check several domains it needs for provisioning but ${#failed_hosts[@]} of ${#hosts_to_test[@]} failed:"
     vvv_error " "
-    for url in "${hosts_to_test[@]}"; do
+    for url in "${failed_hosts[@]}"; do
       echo -e "${CRESET} [${RED}x${CRESET}] ${url}${RED}|"
     done
     vvv_error " "
@@ -394,9 +395,13 @@ vvv_hook() {
     return 1
   fi
 
-  local hook_var_prios="VVV_HOOKS_${1}"
-  local start
-  start=$(date +%s)
+  local hook_var_prios
+  local hook_elapsed
+  local hook_end_timestamp
+  local hook_start_timestamp
+
+  hook_var_prios="VVV_HOOKS_${1}"
+  hook_start_timestamp="$(date -u +"%s.%2N")"
   vvv_info " ▷ Running <b>${1}</b><info> hook"
   eval "if [ -z \"\${${hook_var_prios}}\" ]; then return 0; fi"
   local sorted
@@ -409,9 +414,10 @@ vvv_hook() {
       $f
     done
   done
-  local end
-  end=$(date +%s)
-  vvv_success " ✔ Finished <b>${1}</b><success> hook in </success><b>$((end - start))s</b>"
+  hook_end_timestamp="$(date -u +"%s.%2N")"
+  hook_elapsed=$(date -u -d "0 ${hook_end_timestamp} seconds - ${hook_start_timestamp} seconds" +"%-Mm %-Ss %-3Nms")
+
+  vvv_success " ✔ Finished <b>${1}</b><success> hook in </success><b>${hook_elapsed}</b>"
 }
 export -f vvv_hook
 

provision/provisioners.sh

@@ -13,6 +13,7 @@ exec 7>&2
 source /srv/provision/provision-helpers.sh
 
 VVV_PROVISIONER_RUNNING=""
+VVV_PROVISIONER_START_TIMESTAMP=0
 
 # @description Signal that a provisioner has begun, and setup timings, failed provisioner flags, etc
 # @arg $1 string Name of the provisioner
@@ -21,18 +22,21 @@ function provisioner_begin() {
   touch "/vagrant/failed_provisioners/provisioner-${VVV_PROVISIONER_RUNNING}"
   log_to_file "provisioner-${VVV_PROVISIONER_RUNNING}"
   vvv_success " ▷ Running the <b>'${VVV_PROVISIONER_RUNNING}'</b><success> provisioner...</success>"
-  start_seconds="$(date +%s)"
+  VVV_PROVISIONER_START_TIMESTAMP="$(date -u +"%s.%2N")"
   trap "provisioner_end" EXIT
 }
 
 # @description Signal that a provisioner has finished
 # @arg $1 string Name of the provisioner
 function provisioner_end() {
   local PROVISION_SUCCESS="${1:-"1"}"
-  local end_seconds="$(date +%s)"
-  local elapsed="$(( end_seconds - start_seconds ))"
+  local end_timestamp
+  local elapsed
+
+  end_timestamp="$(date -u +"%s.%2N")"
+  elapsed=$(date -u -d "0 ${end_timestamp} seconds - ${VVV_PROVISIONER_START_TIMESTAMP} seconds" +"%-Mm %-Ss %-3Nms")
   if [[ $PROVISION_SUCCESS -eq "0" ]]; then
-    vvv_success " ✔ The <b>'${VVV_PROVISIONER_RUNNING}'</b><success> provisioner completed in </success><b>${elapsed}</b><success> seconds.</success>"
+    vvv_success " ✔ The <b>'${VVV_PROVISIONER_RUNNING}'</b><success> provisioner completed in </success><b>${elapsed}</b><success>.</success>"
     rm -f "/vagrant/failed_provisioners/provisioner-${VVV_PROVISIONER_RUNNING}"
   else
     vvv_error " ! The <b>'${VVV_PROVISIONER_RUNNING}'</b><error> provisioner ran into problems, the full log is available at <b>'${VVV_CURRENT_LOG_FILE}'</b><error>. It completed in <b>${elapsed}</b><error> seconds."
@@ -41,13 +45,13 @@ function provisioner_end() {
   trap - EXIT
 }
 
-if [[ ! -z $VVV_LOG ]]; then
+if [[ -n $VVV_LOG ]]; then
   provisioner_begin "${VVV_LOG}"
 fi
 
 # @description Signal that a provisioner has finished with success
 function provisioner_success() {
-  if [[ ! -z $VVV_LOG ]]; then
+  if [[ -n $VVV_LOG ]]; then
     provisioner_end 0
   fi
 }