Logging improvements

- added request_id to every line of log file
- add worker (process) name to log file
- print host name and username at top of log file

[CLOUDDST-10070]

iib/workers/config.py

@@ -29,7 +29,8 @@ class Config(object):
     iib_organization_customizations = {}
     iib_request_logs_dir = None
     iib_request_logs_format = (
-        '%(asctime)s %(name)s %(levelname)s %(module)s.%(funcName)s %(message)s'
+        '%(asctime)s %(name)s %(processName)s {request_id} '
+        '%(levelname)s %(module)s.%(funcName)s %(message)s'
     )
     iib_request_logs_level = 'DEBUG'
     iib_required_labels = {}

iib/workers/tasks/utils.py

@@ -1,5 +1,7 @@
 # SPDX-License-Identifier: GPL-3.0-or-later
 import base64
+import getpass
+import socket
 from contextlib import contextmanager
 import functools
 import hashlib
@@ -13,6 +15,7 @@
 from typing import Any, Dict, Iterable
 
 from retry import retry
+from celery.app.log import TaskFormatter
 
 from iib.workers.dogpile_cache import (
     create_dogpile_region,
@@ -721,11 +724,13 @@ def request_logger(func):
     def wrapper(*args, **kwargs):
         request_log_handler = None
         if log_dir:
-            log_formatter = logging.Formatter(log_format)
             request_id = _get_function_arg_value('request_id', func, args, kwargs)
             if not request_id:
                 raise IIBError(f'Unable to get "request_id" from {func.__name__}')
-
+            # for better filtering of all logs for one build in SPLUNK
+            log_formatter = TaskFormatter(
+                log_format.format(request_id=f'request-{request_id}'), use_color=False
+            )
             log_file_path = os.path.join(log_dir, f'{request_id}.log')
             request_log_handler = logging.FileHandler(log_file_path)
             request_log_handler.setLevel(log_level)
@@ -734,6 +739,8 @@ def wrapper(*args, **kwargs):
             os.chmod(log_file_path, 0o775)  # nosec
             logger = logging.getLogger()
             logger.addHandler(request_log_handler)
+            worker_info = f'Host: {socket.getfqdn()}; User: {getpass.getuser()}'
+            logger.info(worker_info)
         try:
             return func(*args, **kwargs)
         finally:

tests/test_workers/test_tasks/test_utils.py

@@ -420,15 +420,18 @@ def test_request_logger(mock_ufts3b, tmpdir):
     def mock_handler(spam, eggs, request_id, bacon):
         logging.getLogger('iib.workers.tasks.utils').info('this is a test')
 
-    expected_message = ' iib.workers.tasks.utils INFO test_utils.mock_handler this is a test\n'
+    expected_message = (
+        ' iib.workers.tasks.utils MainProcess request-{rid} '
+        'INFO test_utils.mock_handler this is a test\n'
+    )
 
     mock_handler('spam', 'eggs', 123, 'bacon')
-    assert logs_dir.join('123.log').read().endswith(expected_message)
+    assert logs_dir.join('123.log').read().endswith(expected_message.format(rid=123))
     assert original_handlers_count == len(logging.getLogger().handlers)
     mock_ufts3b.assert_called_with(f'{logs_dir}/123.log', 'request_logs', '123.log')
 
     mock_handler('spam', 'eggs', bacon='bacon', request_id=321)
-    assert logs_dir.join('321.log').read().endswith(expected_message)
+    assert logs_dir.join('321.log').read().endswith(expected_message.format(rid=321))
     assert original_handlers_count == len(logging.getLogger().handlers)
     mock_ufts3b.assert_called_with(f'{logs_dir}/321.log', 'request_logs', '321.log')