Log multiple lines, log tests, and logging bug fixes (#527)

mishaschwartz · web-flow · commit 81ad9d1ee5cc · 2025-05-02T07:57:11.000-05:00
## Overview

Changes:

- Log multiple lines

Allow the `log` command (defined in `scripts/logging.include.sh`) to log
messages that span multiple lines.
  This also adds unit tests for the `scripts/logging.include.sh` file.

Fixes:

- Logging bug fixes:

- Setting `NO_COLOR` or setting `BIRDHOUSE_COLOR` to a non-integer value
raised an error since `BIRDHOUSE_COLOR`
was tested with the numeric comparison `-eq`. This has now been fixed.

- Providing an invalid log message level (e.g. `log BADLEVEL message`)
would log a critical error message but not
exit unless the `set -o pipefail` option was set. This has been updated
so that the script will exit as intended
    even if the `pipefail` option is not set.

## Changes

**Non-breaking changes**
- logging behaviour changes for multiline logs
- bug fixes

**Breaking changes**
- None

## Related Issue / Discussion

## Additional Information

Links to other issues or sources.

## CI Operations

&lt;!--
The test suite can be run using a different DACCS config with
``birdhouse_daccs_configs_branch: branch_name`` in the PR description.
To globally skip the test suite regardless of the commit message use
``birdhouse_skip_ci`` set to ``true`` in the PR description.

Using ``[&lt;cmd&gt;]`` (with the brackets) where ``&lt;cmd&gt; = skip ci`` in the
commit message will override ``birdhouse_skip_ci`` from the PR
description.
Such commit command can be used to override the PR description behavior
for a specific commit update.
However, a commit message cannot 'force run' a PR which the description
turns off the CI.
To run the CI, the PR should instead be updated with a ``true`` value,
and a running message can be posted in following PR comments to trigger
tests once again.
--&gt;

birdhouse_daccs_configs_branch: master
birdhouse_skip_ci: false
diff --git a/.bumpversion.cfg b/.bumpversion.cfg
@@ -1,5 +1,5 @@
 [bumpversion]
-current_version = 2.13.1
+current_version = 2.13.2
 commit = True
 tag = False
 tag_name = {new_version}
@@ -30,11 +30,11 @@ search = {current_version}
 replace = {new_version}
 
 [bumpversion:file:RELEASE.txt]
-search = {current_version} 2025-04-28T19:56:45Z
+search = {current_version} 2025-05-02T12:53:59Z
 replace = {new_version} {utcnow:%Y-%m-%dT%H:%M:%SZ}
 
 [bumpversion:part:releaseTime]
-values = 2025-04-28T19:56:45Z
+values = 2025-05-02T12:53:59Z
 
 [bumpversion:file(version):birdhouse/components/canarie-api/docker_configuration.py.template]
 search = 'version': '{current_version}'
diff --git a/CHANGES.md b/CHANGES.md
@@ -17,6 +17,27 @@
 
 [//]: # (list changes here, using '-' for each new entry, remove this when items are added)
 
+[2.13.2](https://github.com/bird-house/birdhouse-deploy/tree/2.13.2) (2025-05-02)
+------------------------------------------------------------------------------------------------------------------
+
+## Changes
+
+- Log multiple lines
+
+  Allow the `log` command (defined in `scripts/logging.include.sh`) to log messages that span multiple lines.
+  This also adds unit tests for the `scripts/logging.include.sh` file.
+
+## Fixes
+
+- Logging bug fixes:
+
+  - Setting `NO_COLOR` or setting `BIRDHOUSE_COLOR` to a non-integer value raised an error since `BIRDHOUSE_COLOR`
+    was tested with the numeric comparison `-eq`. This has now been fixed.
+
+  - Providing an invalid log message level (e.g. `log BADLEVEL message`) would log a critical error message but not
+    exit unless the `set -o pipefail` option was set. This has been updated so that the script will exit as intended
+    even if the `pipefail` option is not set.
+
 [2.13.1](https://github.com/bird-house/birdhouse-deploy/tree/2.13.1) (2025-04-28)
 ------------------------------------------------------------------------------------------------------------------
 
diff --git a/Makefile b/Makefile
@@ -1,7 +1,7 @@
 # Generic variables
 override SHELL       := bash
 override APP_NAME    := birdhouse-deploy
-override APP_VERSION := 2.13.1
+override APP_VERSION := 2.13.2
 
 # utility to remove comments after value of an option variable
 override clean_opt = $(shell echo "$(1)" | $(_SED) -r -e "s/[ '$'\t'']+$$//g")
diff --git a/README.rst b/README.rst
@@ -18,13 +18,13 @@ for a full-fledged production platform.
     * - citation
       - | |citation|
 
-.. |commits-since| image:: https://img.shields.io/github/commits-since/bird-house/birdhouse-deploy/2.13.1.svg
+.. |commits-since| image:: https://img.shields.io/github/commits-since/bird-house/birdhouse-deploy/2.13.2.svg
     :alt: Commits since latest release
-    :target: https://github.com/bird-house/birdhouse-deploy/compare/2.13.1...master
+    :target: https://github.com/bird-house/birdhouse-deploy/compare/2.13.2...master
 
-.. |latest-version| image:: https://img.shields.io/badge/tag-2.13.1-blue.svg?style=flat
+.. |latest-version| image:: https://img.shields.io/badge/tag-2.13.2-blue.svg?style=flat
     :alt: Latest Tag
-    :target: https://github.com/bird-house/birdhouse-deploy/tree/2.13.1
+    :target: https://github.com/bird-house/birdhouse-deploy/tree/2.13.2
 
 .. |readthedocs| image:: https://readthedocs.org/projects/birdhouse-deploy/badge/?version=latest
     :alt: ReadTheDocs Build Status (latest version)
diff --git a/RELEASE.txt b/RELEASE.txt
@@ -1 +1 @@
-2.13.1 2025-04-28T19:56:45Z
+2.13.2 2025-05-02T12:53:59Z
diff --git a/birdhouse/components/canarie-api/docker_configuration.py.template b/birdhouse/components/canarie-api/docker_configuration.py.template
@@ -108,8 +108,8 @@ SERVICES = {
             # NOTE:
             #   Below version and release time auto-managed by 'make VERSION=x.y.z bump'.
             #   Do NOT modify it manually. See 'Tagging policy' in 'birdhouse/README.rst'.
-            'version': '2.13.1',
-            'releaseTime': '2025-04-28T19:56:45Z',
+            'version': '2.13.2',
+            'releaseTime': '2025-05-02T12:53:59Z',
             'institution': '${BIRDHOUSE_INSTITUTION}',
             'researchSubject': '${BIRDHOUSE_SUBJECT}',
             'supportEmail': '${BIRDHOUSE_SUPPORT_EMAIL}',
@@ -141,8 +141,8 @@ PLATFORMS = {
             # NOTE:
             #   Below version and release time auto-managed by 'make VERSION=x.y.z bump'.
             #   Do NOT modify it manually. See 'Tagging policy' in 'birdhouse/README.rst'.
-            'version': '2.13.1',
-            'releaseTime': '2025-04-28T19:56:45Z',
+            'version': '2.13.2',
+            'releaseTime': '2025-05-02T12:53:59Z',
             'institution': '${BIRDHOUSE_INSTITUTION}',
             'researchSubject': '${BIRDHOUSE_SUBJECT}',
             'supportEmail': '${BIRDHOUSE_SUPPORT_EMAIL}',
diff --git a/birdhouse/scripts/logging.include.sh b/birdhouse/scripts/logging.include.sh
@@ -5,7 +5,7 @@ if [ -z "${BIRDHOUSE_COLOR}" ] && [ -z "${NO_COLOR}" ]; then
     BIRDHOUSE_COLOR=1
 fi 
 
-if [ "${BIRDHOUSE_COLOR}" -eq "1" ]; then
+if [ "${BIRDHOUSE_COLOR}" = "1" ]; then
     BLUE=$(tput setaf 12)
     GRAY=$(tput setaf 8)
     CYAN=$(tput setaf 6)
@@ -25,6 +25,7 @@ if [ "${BIRDHOUSE_BACKWARD_COMPATIBLE_ALLOWED}" = 'True' ] || [ "${__BIRDHOUSE_S
     # (this supports backwards compatible scripts that don't use the interface)
     BIRDHOUSE_LOG_DEST_OVERRIDE=${BIRDHOUSE_LOG_DEST_OVERRIDE:-"DEBUG:fd:1:INFO:fd:1:WARN:fd:2:ERROR:fd:2:CRITICAL:fd:2"}
 fi
+# These logging prefixes are right-padded with space characters to ensure that each prefix is a fixed width of 10 characters.
 export LOG_DEBUG="${GRAY}DEBUG${NORMAL}:    "
 export LOG_INFO="${BLUE}INFO${NORMAL}:     "
 export LOG_WARN="${YELLOW}WARNING${NORMAL}:  "
@@ -58,7 +59,15 @@ export LOG_CRITICAL="${REG_BG_BOLD}CRITICAL${NORMAL}: "  # to report misuse of f
 log_dest() {
     level=$1
     option=$2
-    read log_line || true
+    log_line=
+    while IFS= read -r line; do
+        if [ -z "${log_line}" ]; then
+            log_line="$line"
+        else
+            # pad the next line by 10 space characters so that it aligns with the first line in the message.
+            log_line="${log_line}\n          ${line}"
+        fi
+    done
     if [ -n "${log_line}" ]; then
         log_quiet="${BIRDHOUSE_LOG_QUIET}"
         log_fd="${BIRDHOUSE_LOG_FD}"
@@ -84,12 +93,12 @@ log_dest() {
             done
         fi
         if [ "${log_quiet}" = "True" ]; then
-            echo "$log_line" >> "${log_file:-/dev/null}"
+            printf "${log_line}\n" >> "${log_file:-/dev/null}"
         else
             if [ -n "${log_file}" ]; then
-                echo "$log_line" | tee -a "${log_file}" 1>&"${log_fd}"
+                printf "${log_line}\n" | tee -a "${log_file}" 1>&"${log_fd}"
             else
-                echo "$log_line" 1>&"${log_fd}"
+                printf "${log_line}\n" 1>&"${log_fd}"
             fi
         fi
     fi
@@ -128,28 +137,26 @@ log() {
                 echo "${LOG_CRITICAL}Invalid: log message is missing." | log_dest CRITICAL
                 exit 2
             fi
-            {
-                case "${BIRDHOUSE_LOG_LEVEL}-${level}" in
-                    DEBUG-DEBUG)
-                        echo "${LOG_DEBUG}$*"
-                    ;;
-                    DEBUG-INFO|INFO-INFO)
-                        echo "${LOG_INFO}$*"
-                    ;;
-                    DEBUG-WARN|INFO-WARN|WARN-WARN)
-                        echo "${LOG_WARN}$*"
-                    ;;
-                    *-ERROR)
-                        echo "${LOG_ERROR}$*"
-                    ;;
-                    *-DEBUG|*-INFO|*-WARN)
-                    ;;
-                    *)
-                        echo "${LOG_CRITICAL}Invalid log level: [${level}]" | log_dest CRITICAL
-                        exit 2
-                    ;;
-                esac
-            } | log_dest ${level}
+            case "${BIRDHOUSE_LOG_LEVEL}-${level}" in
+                DEBUG-DEBUG)
+                    echo "${LOG_DEBUG}$*" | log_dest DEBUG
+                ;;
+                DEBUG-INFO|INFO-INFO)
+                    echo "${LOG_INFO}$*" | log_dest INFO
+                ;;
+                DEBUG-WARN|INFO-WARN|WARN-WARN)
+                    echo "${LOG_WARN}$*" | log_dest WARN
+                ;;
+                *-ERROR)
+                    echo "${LOG_ERROR}$*" | log_dest ERROR
+                ;;
+                *-DEBUG|*-INFO|*-WARN)
+                ;;
+                *)
+                    echo "${LOG_CRITICAL}Invalid log level: [${level}]" | log_dest CRITICAL
+                    exit 2
+                ;;
+            esac
         ;;
         *)
             echo "${LOG_CRITICAL}Invalid log level setting: [BIRDHOUSE_LOG_LEVEL=${BIRDHOUSE_LOG_LEVEL}]." | log_dest CRITICAL
diff --git a/docs/source/conf.py b/docs/source/conf.py
@@ -69,9 +69,9 @@
 # built documents.
 #
 # The short X.Y version.
-version = '2.13.1'
+version = '2.13.2'
 # The full version, including alpha/beta/rc tags.
-release = '2.13.1'
+release = '2.13.2'
 
 # The language for content autogenerated by Sphinx. Refer to documentation
 # for a list of supported languages.
diff --git a/tests/unit/test_cli.py b/tests/unit/test_cli.py
@@ -180,70 +180,70 @@ def test_configs_set_env_file(cli_path, run, local_env_file, tmp_path, flag):
 
 @pytest.mark.parametrize("flag", ["-s", "--log-stdout"])
 def test_log_stdout(cli_path, run, logging_script, flag):
-    proc = run(f"{cli_path} {flag} compose", compose=logging_script)
+    proc = run(f"{cli_path} {flag} compose", compose=logging_script, expect_error=True)
     check_log_output(DEFAULT_LOG_CHECK_LEVELS, proc.stdout)
 
 
 @pytest.mark.parametrize("flag", ["--log-file ", "-l ", "--log-file=", "-l="])
 def test_log_file(cli_path, run, flag, tmp_path, logging_script):
     log_path = tmp_path / "test.log"
-    proc = run(f"{cli_path} {flag}{log_path} compose", compose=logging_script)
+    proc = run(f"{cli_path} {flag}{log_path} compose", compose=logging_script, expect_error=True)
     with open(log_path) as f:
         check_log_output(DEFAULT_LOG_CHECK_LEVELS, f.read())
     check_log_output(DEFAULT_LOG_CHECK_LEVELS, proc.stderr)
     assert not proc.stdout
 
 
 def test_default_log_fd(cli_path, run, logging_script):
-    proc = run(f"{cli_path} compose", compose=logging_script)
+    proc = run(f"{cli_path} compose", compose=logging_script, expect_error=True)
     check_log_output(DEFAULT_LOG_CHECK_LEVELS, proc.stderr)
     assert not proc.stdout
 
 
 @pytest.mark.parametrize("flag", ["-q", "--quiet"])
 def test_log_quiet(cli_path, run, logging_script, flag):
-    proc = run(f"{cli_path} {flag} compose", compose=logging_script)
+    proc = run(f"{cli_path} {flag} compose", compose=logging_script, expect_error=True)
     assert not proc.stdout
 
 
 def test_log_file_stdout(cli_path, run, tmp_path, logging_script):
     log_path = tmp_path / "test.log"
-    proc = run(f"{cli_path} -l {log_path} -s compose", compose=logging_script)
+    proc = run(f"{cli_path} -l {log_path} -s compose", compose=logging_script, expect_error=True)
     with open(log_path) as f:
         check_log_output(DEFAULT_LOG_CHECK_LEVELS, f.read())
     check_log_output(DEFAULT_LOG_CHECK_LEVELS, proc.stdout)
 
 
 def test_log_file_quiet(cli_path, run, tmp_path, logging_script):
     log_path = tmp_path / "test.log"
-    proc = run(f"{cli_path} -l {log_path} -q compose", compose=logging_script)
+    proc = run(f"{cli_path} -l {log_path} -q compose", compose=logging_script, expect_error=True)
     with open(log_path) as f:
         check_log_output(DEFAULT_LOG_CHECK_LEVELS, f.read())
     assert not proc.stdout
 
 
 @pytest.mark.parametrize("flag", ["-L ", "--log-level ", "-L=", "--log-level="])
 def test_log_level_flags(cli_path, run, logging_script, flag):
-    proc = run(f"{cli_path} {flag}DEBUG compose", compose=logging_script)
+    proc = run(f"{cli_path} {flag}DEBUG compose", compose=logging_script, expect_error=True)
     check_log_output(LOG_CHECK_LEVELS, proc.stderr)
 
 
 @pytest.mark.parametrize("level", LOG_LEVELS)
 def test_log_level(cli_path, run, logging_script, level):
-    proc = run(f"{cli_path} -L {level} compose", compose=logging_script)
+    proc = run(f"{cli_path} -L {level} compose", compose=logging_script, expect_error=True)
     check_log_output(LOG_CHECK_LEVELS[LOG_CHECK_LEVELS.index(level) :], proc.stderr)
 
 
 @pytest.mark.parametrize("level", LOG_LEVELS)
 def test_log_override_stdout(cli_path, run, logging_script, level):
-    proc = run(f"{cli_path} -L DEBUG -s {level} compose", compose=logging_script)
+    proc = run(f"{cli_path} -L DEBUG -s {level} compose", compose=logging_script, expect_error=True)
     check_log_output([level_ for level_ in LOG_CHECK_LEVELS if level_ != level], proc.stderr)
     check_log_output([level], proc.stdout)
 
 
 @pytest.mark.parametrize("level", LOG_LEVELS)
 def test_log_override_quiet(cli_path, run, logging_script, level):
-    proc = run(f"{cli_path} -L DEBUG -q {level} compose", compose=logging_script)
+    proc = run(f"{cli_path} -L DEBUG -q {level} compose", compose=logging_script, expect_error=True)
     check_log_output([level_ for level_ in LOG_CHECK_LEVELS if level_ != level], proc.stderr)
     check_log_output([], proc.stdout)
 
@@ -254,6 +254,7 @@ def test_log_override_file(cli_path, run, logging_script, tmp_path, level):
     proc = run(
         f"{cli_path} -L DEBUG -l {level} {log_file} compose",
         compose=logging_script,
+        expect_error=True,
     )
     with open(log_file) as f:
         check_log_output([level], f.read())
@@ -265,6 +266,7 @@ def test_configs_log_override_multiple(cli_path, run, logging_script, tmp_path):
     proc = run(
         f"{cli_path} -L DEBUG -l DEBUG {log_file} -s INFO " f"-q WARN -l ERROR {log_file} -q ERROR compose",
         compose=logging_script,
+        expect_error=True,    
     )
     check_log_output(["DEBUG"], proc.stderr)
     check_log_output(["INFO"], proc.stdout)
@@ -278,6 +280,7 @@ def test_configs_log_override_file_default(cli_path, run, logging_script, tmp_pa
     proc = run(
         f"{cli_path} -L DEBUG -l {log_file} -l ERROR {error_log_file} compose",
         compose=logging_script,
+        expect_error=True,    
     )
     check_log_output(LOG_LEVELS, proc.stderr)
     with open(log_file) as f:
diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py

Original file line number	Diff line number	Diff line change
`@@ -1 +1 @@`
`1`		`-2.13.1 2025-04-28T19:56:45Z`
	`1`	`+2.13.2 2025-05-02T12:53:59Z`