Configure code to use log format from software.conf in upgrade scripts

This commit stardandizes the log format to be fetched from the
software.conf file in the upgrade-scripts, it also have a check
to use a default one in case the log format is not present in the
file which can happen in a 24.09 to 25.09 upgrade.

PASS: Performed and upgrade from stx10 -> stx11 and verified the logs.
PASS: Fresh install of stx11 and verified the logs.
PASS: Check software.conf have logging_default_format_string key
and value.

Story: 2011357
Task: 51916

Change-Id: I559c9d62d019b3662ff0d23a37989645fb154da1
Signed-off-by: Luis Eduardo Bonatti <luizeduardo.bonatti@windriver.com>

controllerconfig/controllerconfig/controllerconfig/common/constants.py

@@ -1,5 +1,5 @@
 #
-# Copyright (c) 2016-2020 Wind River Systems, Inc.
+# Copyright (c) 2016-2025 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
@@ -24,3 +24,8 @@ POSTGRESQL_DEFAULT_PORT = 5432
 
 IPV4_FAMILY = 4
 IPV6_FAMILY = 6
+
+LOG_DEFAULT_FORMAT = ('%(asctime)s.%(msecs)03d USM - %(exec)s [%(process)s: '
+                      '%(thread)d]: %(filename)s(%(lineno)s): '
+                      '%(levelname)s: %(message)s')
+USM_LOG_FILE = '/var/log/software.log'

controllerconfig/controllerconfig/controllerconfig/common/usm_log.py

@@ -0,0 +1,56 @@
+#
+# Copyright (c) 2025 Wind River Systems, Inc.
+#
+# SPDX-License-Identifier: Apache-2.0
+#
+
+import configparser
+import logging
+import os
+import sys
+
+from controllerconfig.common import constants
+
+LOG = logging.getLogger('main_logger')
+
+logging_default_format_string = None
+software_conf_mtime = 0
+software_conf = '/etc/software/software.conf'
+
+
+def configure_logging(filename=constants.USM_LOG_FILE, log_level=logging.INFO):
+    read_log_config()
+
+    my_exec = os.path.basename(sys.argv[0])
+
+    log_format = logging_default_format_string
+    log_format = log_format.replace('%(exec)s', my_exec)
+    formatter = logging.Formatter(log_format, datefmt="%FT%T")
+
+    LOG.setLevel(log_level)
+    main_log_handler = logging.FileHandler(filename)
+    main_log_handler.setFormatter(formatter)
+    LOG.addHandler(main_log_handler)
+
+
+def read_log_config():
+    global software_conf_mtime  # pylint: disable=global-statement
+    global software_conf  # pylint: disable=global-statement
+
+    if software_conf_mtime == os.stat(software_conf).st_mtime:
+        # The file has not changed since it was last read
+        return
+
+    global logging_default_format_string  # pylint: disable=global-statement
+
+    config = configparser.ConfigParser(interpolation=None)
+
+    config.read(software_conf)
+    software_conf_mtime = os.stat(software_conf).st_mtime
+    # TODO(lbonatti) Remove this constants.LOG_DEFAULT_FORMAT when
+    #  logging_default_format_string is present in stx11, when this
+    #  becomes the N release.
+    logging_default_format_string = config.get(
+        "DEFAULT", "logging_default_format_string",
+        fallback=constants.LOG_DEFAULT_FORMAT
+    )

controllerconfig/controllerconfig/upgrade-scripts/06-remove_legacy_upgrade_tables.py

@@ -7,14 +7,18 @@
 # database table
 #
 
-import logging as LOG
+import logging
 import sys
 
 from packaging import version
 import psycopg2
 
+from controllerconfig.common.usm_log import configure_logging
+
 DEFAULT_POSTGRES_PORT = 5432
 
+LOG = logging.getLogger('main_logger')
+
 
 def main():
     action = None
@@ -36,10 +40,7 @@ def main():
             print("Invalid option %s." % sys.argv[arg])
             return 1
         arg += 1
-    log_format = ('%(asctime)s: ' + '[%(process)s]: '
-                  '%(filename)s(%(lineno)s): %(levelname)s: %(message)s')
-    LOG.basicConfig(filename="/var/log/software.log",
-                    format=log_format, level=LOG.INFO, datefmt="%FT%T")
+    configure_logging()
     LOG.info(
         "%s invoked from_release = %s to_release = %s action = %s"
         % (sys.argv[0], from_release, to_release, action)

controllerconfig/controllerconfig/upgrade-scripts/07-populate-ihost-sw-version-field.py

@@ -6,15 +6,19 @@
 # The purpose of this script is to populate the sw_version
 # field on i_host table.
 
-import logging as LOG
+import logging
 import sys
 import psycopg2
 from six.moves import configparser
 
+from controllerconfig.common.usm_log import configure_logging
+
 CONTROLLER_0_HOSTNAME = "controller-0"
 CONTROLLER_1_HOSTNAME = "controller-1"
 DEFAULT_POSTGRES_PORT = 5432
 
+LOG = logging.getLogger('main_logger')
+
 
 def main():
     action = None
@@ -36,10 +40,7 @@ def main():
             print("Invalid option %s." % sys.argv[arg])
             return 1
         arg += 1
-    log_format = ('%(asctime)s: ' + '[%(process)s]: '
-                  '%(filename)s(%(lineno)s): %(levelname)s: %(message)s')
-    LOG.basicConfig(filename="/var/log/software.log",
-                    format=log_format, level=LOG.INFO, datefmt="%FT%T")
+    configure_logging()
     LOG.info(
         "%s invoked from_release = %s to_release = %s action = %s"
         % (sys.argv[0], from_release, to_release, action)
@@ -59,7 +60,7 @@ def main():
 
 def populate_ihost_sw_version(conn, to_release):
     """
-    Populate the sw_version field of i_host table
+    Populate the sw_version field of i_host table for simplex
     """
     hostname = CONTROLLER_1_HOSTNAME
     if get_system_mode() == "simplex":

controllerconfig/controllerconfig/upgrade-scripts/08-activate-keystone.py

@@ -1,9 +1,10 @@
 #!/usr/bin/env python
-# Copyright (c) 2024 Wind River Systems, Inc.
+# Copyright (c) 2025 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
-import logging as LOG
+
+import logging
 from oslo_config import cfg
 import os
 from six.moves import configparser
@@ -11,9 +12,12 @@ import sys
 import subprocess
 
 from cgtsclient import client as cgts_client
+from controllerconfig.common.usm_log import configure_logging
 
 CONF = cfg.CONF
 
+LOG = logging.getLogger('main_logger')
+
 
 class CgtsClient(object):
     SYSINV_API_VERSION = "1"
@@ -54,10 +58,7 @@ def main():
             return 1
         arg += 1
 
-    log_format = ('%(asctime)s: ' + '[%(process)s]: '
-                  '%(filename)s(%(lineno)s): %(levelname)s: %(message)s')
-    LOG.basicConfig(filename="/var/log/software.log",
-                    format=log_format, level=LOG.INFO, datefmt="%FT%T")
+    configure_logging()
     LOG.info("%s invoked from_release = %s to_release = %s action = %s"
              % (sys.argv[0], from_release, to_release, action))
     res = 0

controllerconfig/controllerconfig/upgrade-scripts/11-update-static-hieradata.py

@@ -1,9 +1,10 @@
 #!/usr/bin/env python
-# Copyright (c) 2023-2024 Wind River Systems, Inc.
+# Copyright (c) 2023-2025 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
-import logging as LOG
+
+import logging
 import os
 import shutil
 import subprocess
@@ -11,6 +12,10 @@ import sys
 import tempfile
 import yaml
 
+from controllerconfig.common.usm_log import configure_logging
+
+LOG = logging.getLogger('main_logger')
+
 
 def get_list_of_keys(from_release, to_release):
     keys = {"static": [], "secure_static": []}
@@ -39,10 +44,7 @@ def main():
             return 1
         arg += 1
 
-    log_format = ('%(asctime)s: ' + '[%(process)s]: '
-                  '%(filename)s(%(lineno)s): %(levelname)s: %(message)s')
-    LOG.basicConfig(filename="/var/log/software.log",
-                    format=log_format, level=LOG.INFO, datefmt="%FT%T")
+    configure_logging()
 
     LOG.info("%s invoked from_release = %s to_release = %s action = %s"
              % (sys.argv[0], from_release, to_release, action))

controllerconfig/controllerconfig/upgrade-scripts/197-reset-config-target.py

@@ -1,5 +1,5 @@
 #!/usr/bin/env python
-# Copyright (c) 2021-2024 Wind River Systems, Inc.
+# Copyright (c) 2021-2025 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
@@ -8,12 +8,15 @@
 # requests in N+1 release and not due to potential stale configuration
 # from N release.
 
-import logging as LOG
+import logging
 import sys
 
 from psycopg2.extras import RealDictCursor
 from controllerconfig import utils
 from controllerconfig.common import constants
+from controllerconfig.common.usm_log import configure_logging
+
+LOG = logging.getLogger('main_logger')
 
 
 def main():
@@ -37,10 +40,7 @@ def main():
             return 1
         arg += 1
 
-    log_format = ('%(asctime)s: ' + '[%(process)s]: '
-                  '%(filename)s(%(lineno)s): %(levelname)s: %(message)s')
-    LOG.basicConfig(filename="/var/log/software.log",
-                    format=log_format, level=LOG.INFO, datefmt="%FT%T")
+    configure_logging()
 
     LOG.debug("%s invoked with from_release = %s to_release = %s action = %s"
               % (sys.argv[0], from_release, to_release, action))

controllerconfig/controllerconfig/upgrade-scripts/198-update-isystem-data.py

@@ -1,5 +1,5 @@
 #!/usr/bin/python
-# Copyright (c) 2024 Wind River Systems, Inc.
+# Copyright (c) 2025 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
@@ -7,10 +7,13 @@
 # in i_system table during the USM upgrade
 
 
-import logging as LOG
+import logging
 import psycopg2
 import sys
 
+from controllerconfig.common.usm_log import configure_logging
+
+LOG = logging.getLogger('main_logger')
 
 DEFAULT_POSTGRES_PORT = 5432
 
@@ -37,10 +40,7 @@ def main():
             return 1
         arg += 1
 
-    log_format = ('%(asctime)s: ' + '[%(process)s]: '
-                  '%(filename)s(%(lineno)s): %(levelname)s: %(message)s')
-    LOG.basicConfig(filename="/var/log/software.log",
-                    format=log_format, level=LOG.INFO, datefmt="%FT%T")
+    configure_logging()
 
     if action in ["activate", "activate-rollback"]:
         try:

controllerconfig/controllerconfig/upgrade-scripts/199-reconfigure-keystone-endpoints.py

@@ -8,7 +8,7 @@
 # Needs to run at the end of the upgrade activation, to reduce the
 # stabilization time after upgrade is concluded (less reconfigurations).
 
-import logging as LOG
+import logging
 import socket
 import sys
 from time import sleep
@@ -18,6 +18,9 @@ from oslo_context import context as mycontext
 from six.moves import configparser
 from sysinv.conductor import rpcapiproxy as conductor_rpcapi
 
+from controllerconfig.common.usm_log import configure_logging
+
+LOG = logging.getLogger('main_logger')
 CONF = cfg.CONF
 SYSINV_CONFIG_FILE = '/etc/sysinv/sysinv.conf'
 
@@ -55,10 +58,7 @@ def main():
             return 1
         arg += 1
 
-    log_format = ('%(asctime)s: ' + '[%(process)s]: '
-                  '%(filename)s(%(lineno)s): %(levelname)s: %(message)s')
-    LOG.basicConfig(filename="/var/log/software.log",
-                    format=log_format, level=LOG.INFO, datefmt="%FT%T")
+    configure_logging()
 
     # Activate
     if action == 'activate':

controllerconfig/controllerconfig/upgrade-scripts/20-enable-fluxcd-controllers.py

@@ -1,5 +1,5 @@
 #!/usr/bin/python
-# Copyright (c) 2022-2024 Wind River Systems, Inc.
+# Copyright (c) 2022-2025 Wind River Systems, Inc.
 #
 # SPDX-License-Identifier: Apache-2.0
 #
@@ -7,7 +7,8 @@
 # in kubernetes
 #
 # This script can be removed in the release that follows stx7
-import logging as LOG
+
+import logging
 import subprocess
 import sys
 
@@ -15,6 +16,10 @@ from sysinv.common import exception
 from sysinv.common.retrying import retry
 from sysinv.common.kubernetes import test_k8s_health
 
+from controllerconfig.common.usm_log import configure_logging
+
+LOG = logging.getLogger('main_logger')
+
 
 def main():
     action = None
@@ -35,10 +40,7 @@ def main():
             print("Invalid option %s." % sys.argv[arg])
             return 1
         arg += 1
-    log_format = ('%(asctime)s: ' + '[%(process)s]: '
-                  '%(filename)s(%(lineno)s): %(levelname)s: %(message)s')
-    LOG.basicConfig(filename="/var/log/software.log",
-                    format=log_format, level=LOG.INFO, datefmt="%FT%T")
+    configure_logging()
 
     if action == 'activate' and from_release >= '21.12':
         LOG.info("%s invoked with from_release = %s to_release = %s "