Renovate logging

Details:

- Changed the logging so that it can now reasonably be used together
  with other projects that use logging. This is done by
  centralizing the log_init() function in the utils module, and
  by changing it such that the log level is alwqys set, but the
  file handler is set only when a log file is specified. As a result,
  the loggers now propagate to the Python root logger when the
  log_file parameter is not set.

  So playbooks using the zhmc modules have two choices:
  - Specify a log file via the log_file parameter
  - Do not specify a log file and configure the Python root
    logger as needed.

- Added log_file support to all modules that did not have it yet.

- Changed the format of log messages from:
    %(asctime)s %(name)s %(message)s
    with the default date format (e.g. 2019-02-20 10:54:26,123)
  To:
    %(asctime)s %(levelname)s %(name)s %(process)d %(message)s
    with the default date format (e.g. 2019-02-20 10:54:26,123)
  to be more in sync with common log formats.

- Removed the unused log() function in the utils module because
  logging is now done directly to Python loggers.

Signed-off-by: Andreas Maier <maiera@de.ibm.com>

tests/function/test_func_partition.py

@@ -992,6 +992,7 @@ def test_success(
             'name': self.partition_name,
             'state': desired_state,
             'properties': input_props,
+            'log_file': None,
             'faked_session': self.session,
         }
 
@@ -1069,6 +1070,7 @@ def test_facts_success(
             'cpc_name': self.cpc.name,
             'name': self.partition_name,
             'state': desired_state,
+            'log_file': None,
             'faked_session': self.session,
         }
 
@@ -1196,6 +1198,7 @@ def test_error_properties(
             'name': self.partition_name,
             'state': desired_state,
             'properties': props,
+            'log_file': None,
             'faked_session': self.session,
         }
 
@@ -1263,6 +1266,7 @@ def test_boot_storage_success(
             'name': self.partition_name,
             'state': desired_state,
             'properties': properties,
+            'log_file': None,
             'faked_session': self.session,
         }
 
@@ -1341,6 +1345,7 @@ def test_boot_storage_error_hba_not_found(
             'name': self.partition_name,
             'state': desired_state,
             'properties': properties,
+            'log_file': None,
             'faked_session': self.session,
         }
 
@@ -1404,6 +1409,7 @@ def test_boot_network_success(
             'name': self.partition_name,
             'state': desired_state,
             'properties': properties,
+            'log_file': None,
             'faked_session': self.session,
         }
 
@@ -1480,6 +1486,7 @@ def test_boot_network_error_hba_not_found(
             'name': self.partition_name,
             'state': desired_state,
             'properties': properties,
+            'log_file': None,
             'faked_session': self.session,
         }
 
@@ -1555,6 +1562,7 @@ def test_crypto_config_success(
             'name': self.partition_name,
             'state': desired_state,
             'properties': properties,
+            'log_file': None,
             'faked_session': self.session,
         }
 
@@ -1740,6 +1748,7 @@ def test_crypto_config_parm_errors(
             'name': self.partition_name,
             'state': desired_state,
             'properties': input_props,
+            'log_file': None,
             'faked_session': self.session,
         }
 

tests/unit/test_hba.py

@@ -49,6 +49,7 @@ def test_main_success(
             'partition_name': 'fake-partition-name',
             'name': 'fake-hba-name',
             'state': 'absent',
+            'log_file': None,
         }
 
         # Return values of perform_task()
@@ -82,6 +83,7 @@ def test_main_success(
             state=dict(required=True, type='str',
                        choices=['absent', 'present']),
             properties=dict(required=False, type='dict', default={}),
+            log_file=dict(required=False, type='str', default=None),
             faked_session=dict(required=False, type='object'),
         )
         assert(ansible_mod_cls.call_args ==
@@ -121,6 +123,7 @@ def test_main_param_error(
             'partition_name': 'fake-partition-name',
             'name': 'fake-hba-name',
             'state': 'absent',
+            'log_file': None,
         }
 
         # Exception raised by perform_task()
@@ -174,6 +177,7 @@ def test_pt_present(
         # Prepare input arguments
         params = {
             'state': 'present',
+            'log_file': None,
         }
 
         # Prepare return values
@@ -215,6 +219,7 @@ def test_pt_absent(
         # Prepare input arguments
         params = {
             'state': 'absent',
+            'log_file': None,
         }
 
         # Prepare return values

tests/unit/test_nic.py

@@ -49,6 +49,7 @@ def test_main_success(
             'partition_name': 'fake-partition-name',
             'name': 'fake-nic-name',
             'state': 'absent',
+            'log_file': None,
         }
 
         # Return values of perform_task()
@@ -82,6 +83,7 @@ def test_main_success(
             state=dict(required=True, type='str',
                        choices=['absent', 'present']),
             properties=dict(required=False, type='dict', default={}),
+            log_file=dict(required=False, type='str', default=None),
             faked_session=dict(required=False, type='object'),
         )
         assert(ansible_mod_cls.call_args ==
@@ -121,6 +123,7 @@ def test_main_param_error(
             'partition_name': 'fake-partition-name',
             'name': 'fake-nic-name',
             'state': 'absent',
+            'log_file': None,
         }
 
         # Exception raised by perform_task()
@@ -174,6 +177,7 @@ def test_pt_present(
         # Prepare input arguments
         params = {
             'state': 'present',
+            'log_file': None,
         }
 
         # Prepare return values
@@ -215,6 +219,7 @@ def test_pt_absent(
         # Prepare input arguments
         params = {
             'state': 'absent',
+            'log_file': None,
         }
 
         # Prepare return values

tests/unit/test_partition.py

@@ -45,6 +45,7 @@ def test_main_success(self, ansible_mod_cls, perform_task_func):
             'cpc_name': 'fake-cpc-name',
             'name': 'fake-name',
             'state': 'absent',
+            'log_file': None,
         }
         check_mode = False
 
@@ -78,6 +79,7 @@ def test_main_success(self, ansible_mod_cls, perform_task_func):
             state=dict(required=True, type='str',
                        choices=['absent', 'stopped', 'active', 'facts']),
             properties=dict(required=False, type='dict', default={}),
+            log_file=dict(required=False, type='str', default=None),
             faked_session=dict(required=False, type='object'),
         )
         assert(ansible_mod_cls.call_args ==
@@ -113,6 +115,7 @@ def test_main_param_error(self, ansible_mod_cls, perform_task_func):
             'cpc_name': 'fake-cpc-name',
             'name': 'fake-name',
             'state': 'absent',
+            'log_file': None,
         }
         check_mode = False
 
@@ -167,6 +170,7 @@ def test_pt_active(self, ensure_stopped_func, ensure_active_func,
         # Prepare input arguments
         params = {
             'state': 'active',
+            'log_file': None,
         }
         check_mode = True
 
@@ -210,6 +214,7 @@ def test_pt_stopped(self, ensure_stopped_func, ensure_active_func,
         # Prepare input arguments
         params = {
             'state': 'stopped',
+            'log_file': None,
         }
         check_mode = True
 
@@ -253,6 +258,7 @@ def test_pt_absent(self, ensure_stopped_func, ensure_active_func,
         # Prepare input arguments
         params = {
             'state': 'absent',
+            'log_file': None,
         }
         check_mode = False
 

tests/unit/test_virtual_function.py

@@ -49,6 +49,7 @@ def test_main_success(
             'partition_name': 'fake-partition-name',
             'name': 'fake-vfunction-name',
             'state': 'absent',
+            'log_file': None,
         }
 
         # Return values of perform_task()
@@ -82,6 +83,7 @@ def test_main_success(
             state=dict(required=True, type='str',
                        choices=['absent', 'present']),
             properties=dict(required=False, type='dict', default={}),
+            log_file=dict(required=False, type='str', default=None),
             faked_session=dict(required=False, type='object'),
         )
         assert(ansible_mod_cls.call_args ==
@@ -121,6 +123,7 @@ def test_main_param_error(
             'partition_name': 'fake-partition-name',
             'name': 'fake-vfunction-name',
             'state': 'absent',
+            'log_file': None,
         }
 
         # Exception raised by perform_task()
@@ -174,6 +177,7 @@ def test_pt_present(
         # Prepare input arguments
         params = {
             'state': 'present',
+            'log_file': None,
         }
 
         # Prepare return values
@@ -215,6 +219,7 @@ def test_pt_absent(
         # Prepare input arguments
         params = {
             'state': 'absent',
+            'log_file': None,
         }
 
         # Prepare return values

zhmc_ansible_modules/utils/__init__.py

@@ -16,7 +16,7 @@
 Utility functions for use by more than one Ansible module.
 """
 
-from datetime import datetime
+import logging
 
 from ansible.module_utils import six
 
@@ -460,24 +460,57 @@ def process_normal_property(
     return create_props, update_props, deactivate
 
 
-def log(msg, file='debug.log'):
+def log_init(logger_name, log_file=None):
     """
-    Append a one-line message to a log file, adding some header info to the
-    begin of the line.
+    Set up logging for the loggers of the current Ansible module, and for the
+    loggers of the underlying zhmcclient package.
 
-    The header info that is added to each line, is:
-      yyyy-mm-dd hh:mm:ss.uuuuuu msg
+    The log level of these loggers is set to debug.
+
+    If a log file is specified, a log file handler for that log file (with a
+    log formatter) is created and attached to these loggers.
 
     Parameters:
 
-      msg (string): The message. Any newlines in the message are replaced by
-        blanks.
+        logger_name (string): Name of the logger to be used for the current
+          Ansible module.
 
-      file (string): Path name of the log file to append the message to.
+        log_file (string): Path name of a log file to log to, or `None`.
+          If `None`, logging will be propagated to the Python root logger.
     """
-    msg = msg.replace('\n', ' ') + '\n'
-    ts_dt = datetime.now()
-    ts_str = ts_dt.strftime('%Y-%m-%d %H:%M:%S.%f')
-    line = "{0} {1}".format(ts_str, msg)
-    with open(file, 'a') as fp:
-        fp.write(line)
+
+    # The datefmt parameter of logging.Formatter() supports the datetime
+    # formatting placeholders of time.strftime(). Unfortunately, the %f
+    # placeholder for microseconds is not supported by time.strftime().
+    # If datefmt=None, the milliseconds are added manually by the
+    # logging.Formatter() class. So this is a choice between precision and
+    # indicating the timezone offset.
+    # The time is in the local timezone.
+    #
+    DATEFMT = '%Y-%m-%dT%H:%M:%S%z'  # 2019-02-20T10:54:26+0100
+    # DATEFMT = None  # 2019-02-20 10:54:26,123 (= local time)
+
+    if log_file:
+        handler = logging.FileHandler(log_file)
+        fmt = logging.Formatter(
+            fmt='%(asctime)s %(levelname)s %(name)s %(process)d %(message)s',
+            datefmt=DATEFMT)
+        handler.setFormatter(fmt)
+    else:
+        handler = None
+
+    logger = logging.getLogger(logger_name)
+    logger.setLevel(logging.DEBUG)
+    if handler:
+        logger.addHandler(handler)
+
+    logger = logging.getLogger('zhmcclient.hmc')
+    logger.setLevel(logging.DEBUG)
+    if handler:
+        logger.addHandler(handler)
+
+    if False:  # Too much gorp, disabled for now
+        logger = logging.getLogger('zhmcclient.api')
+        logger.setLevel(logging.DEBUG)
+        if handler:
+            logger.addHandler(handler)