Improve logging for deploy start shell scripts

This commit improves logging during deploy start by:
1. Creating a common module to be sourced by shell scripts to
   load general-use functions, thus reducing code duplication
   between the scripts
2. Replacing plain "echo" commands on the scripts by logging
   functions present on the common module
3. Adding timestamps to the log messages
4. Centralizing all scripts logs into software.log, favouring
   the troubleshooting, now that log lines contain timestamps
   and the process/script that generated them

This commit also deletes the ostree_mounts.yaml file since
it would be used by apt-ostree integration, which was dropped.

Test Plan
PASS: run deploy start successfully and verify that deploy start
      log messages are logged with the expected format

Story: 2010676
Task: 49607

Change-Id: I0bdebde8147faa5b29a642e35bfaf26e9862ed0a
Signed-off-by: Heitor Matsui <heitorvieira.matsui@windriver.com>

software/debian/deb_folder/rules

@@ -74,8 +74,6 @@ override_dh_install:
         ${ROOT}/etc/software/${METADATA_FILE}
 	install -m 755 scripts/chroot_mounts.sh \
 		${ROOT}/usr/sbin/software-deploy/chroot_mounts.sh
-	install -m 444 scripts/ostree_mounts.yaml \
-        ${ROOT}/etc/software/ostree_mounts.yaml
 	install -m 755 scripts/create_postgresql_database.sh \
 		${ROOT}/usr/sbin/software-deploy/create_postgresql_database.sh
 	install -m 755 scripts/usm_load_import \
@@ -84,4 +82,6 @@ override_dh_install:
 		${ROOT}/usr/sbin/software-deploy/sync-controllers-feed
 	install -m 755 scripts/deploy-cleanup \
 		${ROOT}/usr/sbin/software-deploy/deploy-cleanup
+	install -m 755 scripts/shell-utils \
+		${ROOT}/usr/sbin/software-deploy/shell-utils
 	dh_install

software/scripts/chroot_mounts.sh

@@ -5,6 +5,15 @@
 # SPDX-License-Identifier: Apache-2.0
 #
 
+script_dir=$(dirname $0)
+shell_utils=${script_dir}/shell-utils
+if [ -f $shell_utils ]; then
+    source $shell_utils
+else
+    echo "ERROR: ${shell_utils} module not found."
+    exit 1
+fi
+
 DEV_PATH=/dev
 PLATFORM_PATH=/opt/platform
 RABBIT_PATH=/var/lib/rabbitmq
@@ -34,8 +43,8 @@ handle_error() {
     local exit_code="$1"
     local error_message="$2"
 
-    echo "Error: $error_message" >&2
+    log "$error_message" >&2
-    echo "Please check the error details and take appropriate action for recovery." >&2
+    log "Please check the error details and take appropriate action for recovery." >&2
 
     # attempt to unmount if there were successful mounts before the error
     umount_all
@@ -50,7 +59,7 @@ mount_all() {
         src=${src_dst[0]}
         dst=${src_dst[1]}
 
-        echo "mount --bind ${src} ${dst}"
+        info "Bind mounting ${src} -> ${dst}"
         sudo mkdir -p ${dst}
         sudo mount --bind ${src} ${dst} || handle_error 1 "Failed to bind mount ${src} to ${dst}"
     done
@@ -65,12 +74,12 @@ umount_all() {
         src=${src_dst[0]}
         dst=${src_dst[1]}
 
-        echo "sudo umount $dst"
+        info "Unmounting $dst"
         umount_output=$(sudo umount $dst 2>&1)
         if [ $? -ne 0 ]; then
             # ignore messages that are not harmful
             if [[ ! $umount_output =~ ("not mounted"|"no mount point specified") ]]; then
-                echo $umount_output
+                error "$umount_output"
                 rc=1
             fi
         fi
@@ -94,16 +103,16 @@ check_all() {
         fi
     done
     if [[ ${#mounted[@]} -gt 0 ]]; then
-        echo "Mounted mount points:"
+        info "Mounted mount points:"
         for mnt in ${mounted[@]}; do
-            echo $mnt
+            info $mnt
         done
     fi
     return $rc
 }
 
 if [ -z "$1" ]; then
-    echo "Error: OSTree deployment branch parameter is missing."
+    error "OSTree deployment branch parameter is missing."
     exit 1
 fi
 

software/scripts/create_postgresql_database.sh

@@ -1,13 +1,22 @@
 #!/bin/bash
 #
-# Copyright (c) 2023 Wind River Systems, Inc.
+# Copyright (c) 2023-2024 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
 #
 # This script is used create a 2nd instance of postgres on a DX upgrade.
 # It needs the port number as parameter and it should be different from the default.
+#
 
+script_dir=$(dirname $0)
+shell_utils=${script_dir}/shell-utils
+if [ -f $shell_utils ]; then
+    source $shell_utils
+else
+    echo "ERROR: ${shell_utils} module not found."
+    exit 1
+fi
 
 DEFAULT_POSTGRESQL_PORT=5432
 POSTGRESQL_PATH=/var/lib/postgresql
@@ -16,7 +25,7 @@ POSTGRESQL_RUNTIME=/var/run/postgresql
 INFO_FILE=/etc/build.info
 
 if [ -z "$1" ]; then
-    echo "Error: Port parameter is missing."
+    error "'Port' parameter is missing."
     exit 1
 fi
 
@@ -24,7 +33,7 @@ PORT="$1"
 
 # Prevent issues with the default postgres port
 if [ "$PORT" -eq "$DEFAULT_POSTGRESQL_PORT" ]; then
-    echo "Error: Port number should be different from the default."
+    error "Port number should be different from the default."
     exit 1
 fi
 
@@ -32,8 +41,8 @@ cleanup_and_exit() {
     local exit_code="$1"
     local error_message="$2"
 
-    echo "Error: $error_message" >&2
+    error "$error_message" >&2
-    echo "Please check the error details and take appropriate action for recovery." >&2
+    error "Please check the error details and take appropriate action for recovery." >&2
 
     exit "$exit_code"
 }

software/scripts/deploy-cleanup

@@ -15,10 +15,14 @@
 # automatic cleanup process fails.
 #
 
-log() {
+script_dir=$(dirname $0)
-  type=$1
+shell_utils=${script_dir}/shell-utils
-  echo "[$(date --iso-8601=seconds)] $type: $2"
+if [ -f $shell_utils ]; then
-}
+    source $shell_utils
+else
+    echo "ERROR: ${shell_utils} module not found."
+    exit 1
+fi
 
 stop_database() {
     local rootdir=$1
@@ -27,7 +31,7 @@ stop_database() {
 
     # attempt to stop temporary database if still up
     tmp_db_dir=${rootdir}/var/lib/postgresql/${to_ver}
-    log "INFO" "Attempting to stop the temporary database in ${tmp_db_dir}..."
+    info "Attempting to stop the temporary database in ${tmp_db_dir}..."
     if [ -d $tmp_db_dir ]; then
         lsof $tmp_db_dir
         if [ $? -eq 0 ]; then
@@ -35,15 +39,15 @@ stop_database() {
             sudo -u postgres ${tmp_db_bin_dir}/pg_ctl -D ${tmp_db_dir} stop
             if [ $? -ne 0 ]; then
                 rc=1
-                log "ERROR" "Error stopping database."
+                error "Error stopping database."
             else
-                log "INFO" "Success stopping database."
+                info "Success stopping database."
             fi
         else
-            log "INFO" "Database is not running."
+            info "Database is not running."
         fi
     else
-        log "WARN" "No database found in the specified directory."
+        warning "No database found in the specified directory."
     fi
     return $rc
 }
@@ -52,20 +56,20 @@ unmount_filesystems() {
     local rootdir=$1
     local rc=0
 
-    log "INFO" "Attempting to unmount filesystems under ${rootdir}..."
+    info "Attempting to unmount filesystems under ${rootdir}..."
     k8s_umount_output=$(sudo umount ${rootdir}/usr/local/kubernetes/current 2>&1)
     if [ $? -ne 0 ]; then
         if [[ ! $k8s_umount_output =~ "not mounted" ]]; then
             rc=1
-            log "ERROR" $k8s_umount_output
+            error $k8s_umount_output
         fi
     fi
     sudo ${rootdir}/usr/sbin/software-deploy/chroot_mounts.sh ${rootdir} -u
     if [ $? -ne 0 ]; then
         rc=1
-        log "ERROR" "Error unmounting filesystems."
+        error "Error unmounting filesystems."
     else
-        log "INFO" "Success unmounting filesystems."
+        info "Success unmounting filesystems."
     fi
     return $rc
 }
@@ -75,14 +79,14 @@ remove_temp_directories() {
     local rootdir=$2
     local rc=0
 
-    log "INFO" "Attempting to remove temporary deployment directories [${repo}, ${rootdir}]..."
+    info "Attempting to remove temporary deployment directories [${repo}, ${rootdir}]..."
     sudo ${rootdir}/usr/sbin/software-deploy/chroot_mounts.sh ${rootdir} -c
     if [ $? -ne 0 ]; then
        rc=1
-       log "ERROR" "Some mount points are still mounted, cannot proceed with the cleanup."
+       error "Some mount points are still mounted, cannot proceed with the cleanup."
     else
         rm -rf $repo $rootdir
-        log "INFO" "Temporary deployment directories removed successfully."
+        info "Temporary deployment directories removed successfully."
     fi
     return $rc
 }
@@ -90,7 +94,7 @@ remove_temp_directories() {
 # script usage
 if [ $# -ne 3 ]; then
     echo
-    echo "usage: deploy-start-cleanup <tmp_ostree_repo_dir> <tmp_root_dir> <action>"
+    echo "usage: deploy-cleanup <tmp_ostree_repo_dir> <tmp_root_dir> <action>"
     echo -e "\nParameters"
     echo "=========="
     echo "tmp_ostree_repo_dir: temporary ostree repo directory (example: /sysroot/upgrade/ostree_repo)"
@@ -111,14 +115,14 @@ action=$3
 # basic checks
 for dir in $repo $rootdir; do
     if [ ! -d $dir ]; then
-        log "ERROR" "Specified directory $dir does not exist, cannot proceed with cleanup."
+        error "Specified directory $dir does not exist, cannot proceed with cleanup."
         exit 1
     fi
 done
 
 target_build_info=${rootdir}/usr/etc/build.info
 if [ ! -f $target_build_info ]; then
-    log "ERROR" "Cannot get target release build-info information, cannot proceed with cleanup."
+    error "Cannot get target release build-info information, cannot proceed with cleanup."
     exit 1
 fi
 
@@ -126,7 +130,7 @@ fi
 to_ver=$(cat $target_build_info | grep SW_VERSION | cut -d'"' -f2)
 
 # main
-log "INFO" "Starting cleanup for staging directories [${repo}, ${rootdir}]..."
+info "Starting cleanup for staging directories [${repo}, ${rootdir}]..."
 case $action in
     "db")
         stop_database $rootdir $to_ver
@@ -143,13 +147,13 @@ case $action in
         remove_temp_directories $repo $rootdir
     ;;
     *)
-        log "ERROR" "Invalid action specified: ${action}"
+        error "Invalid action specified: ${action}"
     ;;
 esac
 rc=$?
 if [ $rc -ne 0 ]; then
-    log "ERROR" "Error cleaning up [${repo}, ${rootdir}], please check the logs, take manual actions and retry the script."
+    error "Error cleaning up [${repo}, ${rootdir}], please check the logs, take manual actions and retry the script."
 fi
-log "INFO" "Cleanup script ended."
+info "Cleanup script ended."
 
 exit $rc

software/scripts/ostree_mounts.yaml

@@ -1,10 +0,0 @@
----
-- "{{ OSTREE_DEPLOYMENT_BRANCH }}/usr/etc:{{ OSTREE_DEPLOYMENT_BRANCH }}/etc"
-- "/dev:{{ OSTREE_DEPLOYMENT_BRANCH }}/dev"
-- "/proc:{{ OSTREE_DEPLOYMENT_BRANCH }}/proc"
-- "/opt/platform:{{ OSTREE_DEPLOYMENT_BRANCH }}/opt/platform"
-- "/var/lib/rabbitmq:{{ OSTREE_DEPLOYMENT_BRANCH }}/var/lib/rabbitmq"
-- "/var/log:{{ OSTREE_DEPLOYMENT_BRANCH }}/var/log"
-- >
-  "/var/lib/postgresql/upgrade:
-  {{ OSTREE_DEPLOYMENT_BRANCH }}/var/lib/postgresql/upgrade"

software/scripts/shell-utils

@@ -0,0 +1,29 @@
+# !/bin/bash
+#
+# Copyright (c) 2024 Wind River Systems, Inc.
+#
+# SPDX-License-Identifier: Apache-2.0
+#
+# File containing common shell functions that
+# can be sourced and used by other shell scripts.
+#
+
+log()
+{
+    script_name=$(basename $0)
+    log_type=$1
+    shift
+    echo "$(date -Iseconds | cut -d'+' -f1): ${script_name}[${$}]: ${log_type}: ${@}"
+}
+
+info() {
+    log "INFO" $@
+}
+
+warning() {
+    log "WARNING" $@
+}
+
+error() {
+    log "ERROR" $@ >&2
+}

software/scripts/software-deploy-start

@@ -13,10 +13,17 @@
 # 5. perform data migration
 #
 
-# TODO: centralize USM upgrade scripts output into one single log
+exec 2>&1 >> /var/log/software.log
-exec > /var/log/deploy_start.log 2>&1
+
+script_dir=$(dirname $0)
+shell_utils=${script_dir}/shell-utils
+if [ -f $shell_utils ]; then
+    source $shell_utils
+else
+    echo "ERROR: ${shell_utils} module not found."
+    exit 1
+fi
 
-exec_path=$(dirname $0)
 usage()
 {
     echo "usage: $0 from_ver to_ver k8s_ver postgresql_port feed [commit_id|latest_commit]"
@@ -63,10 +70,10 @@ handle_error() {
     local error_message="$2"
     local state="start-failed"
 
-    echo "Error: ${error_message}" >&2
+    error "${error_message}" >&2
-    echo "Please check the error details and take appropriate action for recovery." >&2
+    error "Please check the error details and take appropriate action for recovery." >&2
 
-    echo "Update deploy state ${state}." >&2
+    error "Update deploy state ${state}." >&2
     deploy_update_state ${state}
 
     # cleanup before exiting
@@ -77,13 +84,14 @@ handle_error() {
 
 for dir in $rootdir $repo; do
     if [ -e ${dir} ]; then
-        echo "${dir} already exists. Please ensure to clean up environment to continue." >&2
+        error "${dir} already exists. Please ensure to clean up environment to continue." >&2
         exit 1
     fi
 done
 
 sudo mkdir ${repo} -p
 
+info "Initializing ostree repo..."
 sudo ostree --repo=${repo} init --mode=archive || handle_error $? "Failed to init repo"
 sudo ostree --repo=${repo} remote add ${instbr} ${feed_url} --no-gpg-verify || handle_error $? "Failed to remote add repo"
 sudo ostree --repo=${repo} pull --depth=-1 --mirror ${instbr}:${instbr} || handle_error $? "Failed to pull repo"
@@ -92,23 +100,27 @@ sudo ostree --repo=${repo} pull --depth=-1 --mirror ${instbr}:${instbr} || handl
 if [ -z ${commit_id} ]; then
     # get commit id, only latest for now
     commit_id=$(ostree rev-parse --repo=${repo} ${instbr})
-    echo "latest commit id ${commit_id}"
+    info "Latest commit id ${commit_id}"
     if [ -z "${commit_id}" ]; then
         handle_error 1 "Failed to retrieve commit id"
     fi
 fi
 
-echo "checkout commit id ${commit_id}"
+info "Checkout commit id ${commit_id}"
 
+info "Checking out ostree repo..."
 sudo ostree --repo=${repo} checkout ${commit_id} ${rootdir} || handle_error $? "Failed to checkout ${commit_id}"
 
 # create proper mounts on deploy file system
+info "Creating mount points..."
 sudo ${rootdir}/usr/sbin/software-deploy/chroot_mounts.sh ${rootdir} || handle_error $? "Failed to mount required mount points"
 
 sudo mount --bind ${rootdir}/usr/local/kubernetes/${k8s_ver} ${rootdir}/usr/local/kubernetes/current
 sudo cp /etc/kubernetes/admin.conf ${rootdir}/etc/kubernetes/
+info "Mount points created successfully"
 
-DATA_PREP_SCRIPT="${exec_path}/prep-data-migration"
+info "Preparing for data migration..."
+DATA_PREP_SCRIPT="${script_dir}/prep-data-migration"
 # OS_AUTH_URL, OS_USERNAME, OS_PASSWORD, OS_PROJECT_NAME, OS_USER_DOMAIN_NAME,
 # OS_PROJECT_DOMAIN_NAME, OS_REGION_NAME are in env variables.
 cmd_line=" --rootdir=${rootdir} --from_release=${from_ver} --to_release=${to_ver}"
@@ -118,17 +130,27 @@ cmd_line+=" --project_domain_name=${OS_PROJECT_DOMAIN_NAME} --region_name=${OS_R
 prep_cmd="${DATA_PREP_SCRIPT} ${cmd_line}"
 
 ${prep_cmd} || handle_error $? "Failed to extract data for migration"
+info "Data migration preparations complete."
 
+info "Creating temporary database..."
 sudo chroot ${rootdir} /usr/sbin/software-deploy/create_postgresql_database.sh ${port} || handle_error $? "Failed to start 2nd instance of postgresql"
-sudo chroot ${rootdir} /usr/bin/software-migrate ${from_ver} ${to_ver} ${port} || handle_error $? "Failed to migrate data"
+info "Database creation complete."
 
+info "Starting data migration..."
+sudo chroot ${rootdir} /usr/bin/software-migrate ${from_ver} ${to_ver} ${port} || handle_error $? "Failed to migrate data"
+info "Data migration completed."
+
+info "Syncing feed between controllers..."
 SYNC_CONTROLLERS_SCRIPT="/usr/sbin/software-deploy/sync-controllers-feed"
 sync_controllers_cmd="${SYNC_CONTROLLERS_SCRIPT} ${cmd_line} --feed=${feed}"
 ${sync_controllers_cmd} || handle_error $? "Failed to sync feeds"
+info "Feed sync complete."
 
 state="start-done"
 deploy_update_state $state
-echo "Update deploy state ${state}."
+info "Update deploy state ${state}."
 
 # cleanup after successful data migration
+info "Starting cleanup..."
 deploy_cleanup
+info "Cleanup complete."