diff --git a/iib/workers/config.py b/iib/workers/config.py index b507178cc..970f9829c 100644 --- a/iib/workers/config.py +++ b/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 = {} diff --git a/iib/workers/tasks/utils.py b/iib/workers/tasks/utils.py index 378fc459a..7e04ccc3e 100644 --- a/iib/workers/tasks/utils.py +++ b/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: diff --git a/tests/test_workers/test_tasks/test_utils.py b/tests/test_workers/test_tasks/test_utils.py index 723a9dfa8..8ec5ec573 100644 --- a/tests/test_workers/test_tasks/test_utils.py +++ b/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')