diff --git a/README.rst b/README.rst index 1dd94d8..3c86551 100644 --- a/README.rst +++ b/README.rst @@ -151,10 +151,35 @@ General logger = logging.getLogger("cli.logger") logger.info('hi') -**Notes**: - All loggers set up and created before the initialization of the Cloud Foundry logging library will -be left untouched. - When using Flask and Sanic with the logging library a before and +**Notes**: All loggers set up and created before the initialization of the Cloud Foundry logging library will +be left untouched. When using Flask and Sanic with the logging library before and after request middleware is attached, and it will capture response times for each request. +Setting and getting correlation ID +"""""""""""""""""""""""""""""""""" + +When using cf_logging in a web application you don't need to set the correlation ID, because the logging library will fetch it from the HTTP headers and set it. +For non web applications you could set the correlation ID manually, so that the log entries can be filtered later on based on the correlation_id. + +Setting and getting the correlation_id can be done via: + +.. code:: python + + cf_logging.FRAMEWORK.context.get_correlation_id() + cf_logging.FRAMEWORK.context.set_correlation_id(value) + +Whenever a correlation id is set after initializing cf_logging without a specific framework (ex: cf_logging.init()) - this same correlation ID would be used for each log record. + +If you need a *thread safe* correlation ID, you can reuse the ``cf_logging.job_loffing.framework.JobFramework`` and provide your own context implementation that is *thread safe*. + +If you need to get the correlation_id in a web application, take into account the framework you are using. +In async frameworks like Sanic and Falcon the context is stored into the request object and you need to provide the request to the call: + +.. code:: python + + cf_logging.FRAMEWORK.context.get_correlation_id(request) + + Logging sensitive data ^^^^^^^^^^^^^^^^^^^^^^ diff --git a/sap/cf_logging/__init__.py b/sap/cf_logging/__init__.py index 7f84f03..0b1e5c6 100644 --- a/sap/cf_logging/__init__.py +++ b/sap/cf_logging/__init__.py @@ -4,10 +4,11 @@ from sap.cf_logging import defaults from sap.cf_logging.core.constants import REQUEST_KEY, RESPONSE_KEY -from sap.cf_logging.record.request_log_record import RequestWebRecord -from sap.cf_logging.record.simple_log_record import SimpleLogRecord from sap.cf_logging.core.framework import Framework from sap.cf_logging.formatters.json_formatter import JsonFormatter +from sap.cf_logging.job_logging.framework import JobFramework +from sap.cf_logging.record.request_log_record import RequestWebRecord +from sap.cf_logging.record.simple_log_record import SimpleLogRecord __version__ = '3.2.0' @@ -34,7 +35,6 @@ def makeRecord(self, name, level, fn, lno, msg, msgargs, exc_info, return cls(extra, FRAMEWORK, name, level, fn, lno, msg, msgargs, exc_info, func, *args, **kwargs) - def init(cfl_framework=None, level=defaults.DEFAULT_LOGGING_LEVEL): """ Initialize function. It sets up the logging library to output JSON formatted messages. @@ -50,7 +50,7 @@ def init(cfl_framework=None, level=defaults.DEFAULT_LOGGING_LEVEL): raise TypeError('expecting framework of type {}'.format(Framework.__name__)) _SETUP_DONE = True - FRAMEWORK = cfl_framework + FRAMEWORK = cfl_framework or JobFramework() logging.setLoggerClass(CfLogger) diff --git a/sap/cf_logging/core/context.py b/sap/cf_logging/core/context.py index 464069e..a07f484 100644 --- a/sap/cf_logging/core/context.py +++ b/sap/cf_logging/core/context.py @@ -1,5 +1,6 @@ """ Module Context """ +_CORRELATION_ID_KEY = 'correlation_id' class Context(object): """ Class for getting and setting context variables """ @@ -11,3 +12,15 @@ def set(self, key, value, request): def get(self, key, request): """ Get session variable """ raise NotImplementedError + + def get_correlation_id(self, request=None): + """ Gets the current correlation_id. Ensure that you are calling this method in the + appropriate location of your code having in mind which framework you are using. """ + + return self.get(_CORRELATION_ID_KEY, request) + + def set_correlation_id(self, value, request=None): + """ Sets the current correlation_id. Ensure that you are calling this method in the + appropriate location of your code having in mind which framework you are using. """ + + return self.set(_CORRELATION_ID_KEY, value, request) diff --git a/sap/cf_logging/falcon_logging/__init__.py b/sap/cf_logging/falcon_logging/__init__.py index 146a780..8c94a6b 100644 --- a/sap/cf_logging/falcon_logging/__init__.py +++ b/sap/cf_logging/falcon_logging/__init__.py @@ -29,7 +29,7 @@ def process_request(self, request, response): # pylint: disable=unused-argument """ framework = cf_logging.FRAMEWORK cid = framework.request_reader.get_correlation_id(request) - framework.context.set('correlation_id', cid, request) + framework.context.set_correlation_id(cid, request) framework.context.set('request_started_at', datetime.utcnow(), request) request.log = lambda msg, lvl=logging.INFO, extra={}: logging.getLogger( self._logger_name).log(lvl, msg, extra=extra.update({REQUEST_KEY: request}) or extra) diff --git a/sap/cf_logging/flask_logging/__init__.py b/sap/cf_logging/flask_logging/__init__.py index fce12df..5a09db5 100644 --- a/sap/cf_logging/flask_logging/__init__.py +++ b/sap/cf_logging/flask_logging/__init__.py @@ -27,7 +27,7 @@ def before_request(wrapped): def _wrapper(): framework = cf_logging.FRAMEWORK cid = framework.request_reader.get_correlation_id(request) - framework.context.set('correlation_id', cid, request) + framework.context.set_correlation_id(cid, request) framework.context.set('request_started_at', datetime.utcnow(), request) return wrapped() return _wrapper diff --git a/sap/cf_logging/job_logging/__init__.py b/sap/cf_logging/job_logging/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/sap/cf_logging/job_logging/context.py b/sap/cf_logging/job_logging/context.py new file mode 100644 index 0000000..4c0e7cd --- /dev/null +++ b/sap/cf_logging/job_logging/context.py @@ -0,0 +1,15 @@ +""" Job logging context - used by the logging package to keep log data """ +from sap.cf_logging.core.context import Context + + +class JobContext(Context): + """ Stores logging context in dict """ + + def __init__(self): + self._mem_store = {} + + def set(self, key, value, request): + self._mem_store[key] = value + + def get(self, key, request): + return self._mem_store[key] if key in self._mem_store else None diff --git a/sap/cf_logging/job_logging/framework.py b/sap/cf_logging/job_logging/framework.py new file mode 100644 index 0000000..61f7f8b --- /dev/null +++ b/sap/cf_logging/job_logging/framework.py @@ -0,0 +1,20 @@ +""" Framework to be used by worker/job running applications """ +from sap.cf_logging.core.framework import Framework +from sap.cf_logging.job_logging.context import JobContext +from sap.cf_logging.core.request_reader import RequestReader +from sap.cf_logging.core.response_reader import ResponseReader + +JOB_FRAMEWORK_NAME = 'job.framework' + + +class JobFramework(Framework): + """ Simple framework using default request and response readers. + Uses JobContext to keeping properties in memory """ + + def __init__(self, context=None): + super(JobFramework, self).__init__( + JOB_FRAMEWORK_NAME, + context or JobContext(), + RequestReader(), + ResponseReader() + ) diff --git a/sap/cf_logging/record/simple_log_record.py b/sap/cf_logging/record/simple_log_record.py index a9c80da..256f12d 100644 --- a/sap/cf_logging/record/simple_log_record.py +++ b/sap/cf_logging/record/simple_log_record.py @@ -1,6 +1,7 @@ """ Module SimpleLogRecord """ import logging from datetime import datetime +from sap.cf_logging import defaults from sap.cf_logging.core.constants import REQUEST_KEY, RESPONSE_KEY from sap.cf_logging.record import application_info from sap.cf_logging.record import util @@ -26,11 +27,7 @@ def __init__(self, extra, framework, *args, **kwargs): request = extra[REQUEST_KEY] if extra and REQUEST_KEY in extra else None - correlation_id = None - if framework: - correlation_id = framework.context.get('correlation_id', request) - - self.correlation_id = correlation_id or '-' + self.correlation_id = framework.context.get_correlation_id(request) or defaults.UNKNOWN self.extra = dict((key, value) for key, value in extra.items() if key not in _SKIP_ATTRIBUTES) if extra else {} diff --git a/sap/cf_logging/sanic_logging/__init__.py b/sap/cf_logging/sanic_logging/__init__.py index 864eaf6..87fe562 100644 --- a/sap/cf_logging/sanic_logging/__init__.py +++ b/sap/cf_logging/sanic_logging/__init__.py @@ -26,7 +26,7 @@ def before_request(wrapped): @wraps(wrapped) def _wrapper(request): correlation_id = cf_logging.FRAMEWORK.request_reader.get_correlation_id(request) - cf_logging.FRAMEWORK.context.set('correlation_id', correlation_id, request) + cf_logging.FRAMEWORK.context.set_correlation_id(correlation_id, request) cf_logging.FRAMEWORK.context.set('request_started_at', datetime.utcnow(), request) return wrapped(request) diff --git a/tests/log_schemas.py b/tests/log_schemas.py index 076c236..6b215f7 100644 --- a/tests/log_schemas.py +++ b/tests/log_schemas.py @@ -13,7 +13,7 @@ 'component_type': u.string(u.TEXT) } -CLI_LOG_SCHEMA = u.extend(CF_ATTRIBUTES_SCHEMA, { +JOB_LOG_SCHEMA = u.extend(CF_ATTRIBUTES_SCHEMA, { 'type': { 'in': ['log'], 'in_error': 'Invalid "type" property' diff --git a/tests/test_cli_logging.py b/tests/test_cli_logging.py deleted file mode 100644 index e609e17..0000000 --- a/tests/test_cli_logging.py +++ /dev/null @@ -1,22 +0,0 @@ -""" Module to test the cf_logging library """ -import logging -from json import JSONDecoder -from json_validator.validator import JsonValidator -from sap import cf_logging -from tests.log_schemas import CLI_LOG_SCHEMA -from tests.util import config_root_logger - - -# pylint: disable=protected-access - -def test_critical(): - """ Test the cf_logger as a standalone """ - cf_logging.init(level=logging.DEBUG) - logger, stream = config_root_logger('cli.test') - logger.info('hi') - log_json = JSONDecoder().decode(stream.getvalue()) - _, error = JsonValidator(CLI_LOG_SCHEMA).validate(log_json) - - cf_logging._SETUP_DONE = False - - assert error == {} diff --git a/tests/test_falcon_logging.py b/tests/test_falcon_logging.py index d7b20e1..ec48427 100644 --- a/tests/test_falcon_logging.py +++ b/tests/test_falcon_logging.py @@ -6,7 +6,7 @@ from falcon_auth import FalconAuthMiddleware, BasicAuthBackend from sap import cf_logging from sap.cf_logging import falcon_logging -from tests.log_schemas import WEB_LOG_SCHEMA, CLI_LOG_SCHEMA +from tests.log_schemas import WEB_LOG_SCHEMA, JOB_LOG_SCHEMA from tests.common_test_params import ( v_str, auth_basic, get_web_record_header_fixtures ) @@ -15,7 +15,7 @@ # pylint: disable=protected-access, missing-docstring,too-few-public-methods -@pytest.yield_fixture(autouse=True) +@pytest.fixture(autouse=True) def before_each(): """ enable all fields to be logged """ enable_sensitive_fields_logging() @@ -110,7 +110,7 @@ def __init__(self, extra, expected): def on_get(self, req, resp): _, stream = config_root_logger('user.logging') req.log('in route headers', extra=self.extra) - assert check_log_record(stream, CLI_LOG_SCHEMA, self.expected) == {} + assert check_log_record(stream, JOB_LOG_SCHEMA, self.expected) == {} resp.set_header('Content-Type', 'text/plain') resp.status = falcon.HTTP_200 diff --git a/tests/test_flask_logging.py b/tests/test_flask_logging.py index db64beb..dd1b4a2 100644 --- a/tests/test_flask_logging.py +++ b/tests/test_flask_logging.py @@ -5,7 +5,7 @@ from flask import Response from sap import cf_logging from sap.cf_logging import flask_logging -from tests.log_schemas import WEB_LOG_SCHEMA, CLI_LOG_SCHEMA +from tests.log_schemas import WEB_LOG_SCHEMA, JOB_LOG_SCHEMA from tests.common_test_params import v_str, v_num, auth_basic, get_web_record_header_fixtures from tests.util import check_log_record, config_root_logger, enable_sensitive_fields_logging @@ -24,7 +24,7 @@ def test_flask_requires_valid_app(): FIXTURE.append(({}, {'response_size_b': v_num(val=2)})) -@pytest.yield_fixture(autouse=True) +@pytest.fixture(autouse=True) def before_each(): """ enable all fields to be logged """ enable_sensitive_fields_logging() @@ -74,7 +74,7 @@ def _user_logging(headers, extra, expected): def _logging_correlation_id_route(): logger, stream = config_root_logger('user.logging') logger.info('in route headers', extra=extra) - assert check_log_record(stream, CLI_LOG_SCHEMA, expected) == {} + assert check_log_record(stream, JOB_LOG_SCHEMA, expected) == {} return Response('ok') _set_up_flask_logging(app) diff --git a/tests/test_job_logging.py b/tests/test_job_logging.py new file mode 100644 index 0000000..971e96a --- /dev/null +++ b/tests/test_job_logging.py @@ -0,0 +1,44 @@ +""" Module to test the cf_logging library """ +import logging +from json import JSONDecoder +import pytest +from json_validator.validator import JsonValidator +from sap import cf_logging +from tests.log_schemas import JOB_LOG_SCHEMA +from tests.util import config_root_logger + +# pylint: disable=protected-access + + +@pytest.fixture(autouse=True) +def before_each(): + """ reset logging framework """ + cf_logging._SETUP_DONE = False + + +def test_log_in_expected_format(): + """ Test the cf_logger as a standalone """ + cf_logging.init(level=logging.DEBUG) + logger, stream = config_root_logger('cli.test') + logger.info('hi') + log_json = JSONDecoder().decode(stream.getvalue()) + _, error = JsonValidator(JOB_LOG_SCHEMA).validate(log_json) + + assert error == {} + + +def test_set_correlation_id(): + """ Test setting correlation_id """ + correlation_id = '1234' + cf_logging.init(level=logging.DEBUG) + cf_logging.FRAMEWORK.context.set_correlation_id(correlation_id) + + logger, stream = config_root_logger('cli.test') + logger.info('hi') + + log_json = JSONDecoder().decode(stream.getvalue()) + _, error = JsonValidator(JOB_LOG_SCHEMA).validate(log_json) + + assert error == {} + assert log_json['correlation_id'] == correlation_id + assert cf_logging.FRAMEWORK.context.get_correlation_id() == correlation_id diff --git a/tests/test_sanic_logging.py b/tests/test_sanic_logging.py index 767dfc7..df338b8 100644 --- a/tests/test_sanic_logging.py +++ b/tests/test_sanic_logging.py @@ -6,7 +6,7 @@ from sap import cf_logging from sap.cf_logging import sanic_logging -from tests.log_schemas import WEB_LOG_SCHEMA, CLI_LOG_SCHEMA +from tests.log_schemas import WEB_LOG_SCHEMA, JOB_LOG_SCHEMA from tests.common_test_params import v_str, v_num, get_web_record_header_fixtures from tests.schema_util import extend from tests.util import check_log_record, config_logger, enable_sensitive_fields_logging @@ -22,7 +22,7 @@ def test_sanic_requires_valid_app(): FIXTURE = get_web_record_header_fixtures() FIXTURE.append(({'no-content-length': '1'}, {'response_size_b': v_num(-1)})) -@pytest.yield_fixture(autouse=True) +@pytest.fixture(autouse=True) def before_each(): """ enable all fields to be logged """ enable_sensitive_fields_logging() @@ -85,7 +85,7 @@ async def _logging_correlation_id_route(request): logger, stream = config_logger('user.logging') new_extra = extend(extra, {'request': request}) if provide_request else extra logger.info('in route headers', extra=new_extra) - assert check_log_record(stream, CLI_LOG_SCHEMA, expected) == {} + assert check_log_record(stream, JOB_LOG_SCHEMA, expected) == {} return text('ok') _set_up_sanic_logging(app) diff --git a/tests/unit/formatters/test_json_formatter.py b/tests/unit/formatters/test_json_formatter.py index eeee274..c63e233 100644 --- a/tests/unit/formatters/test_json_formatter.py +++ b/tests/unit/formatters/test_json_formatter.py @@ -1,6 +1,7 @@ """ Tests json log formatting """ import json import logging +from sap.cf_logging.job_logging.framework import JobFramework from sap.cf_logging.record.simple_log_record import SimpleLogRecord from sap.cf_logging.formatters.json_formatter import JsonFormatter @@ -19,8 +20,10 @@ def test_non_json_serializable(): """ test json formatter handles non JSON serializable object """ class _MyClass(object): # pylint: disable=too-few-public-methods pass + extra = {'cls': _MyClass()} - log_record = SimpleLogRecord(extra, None, 'name', LEVEL, FILE, LINE, 'msg', [], EXC_INFO) + framework = JobFramework() + log_record = SimpleLogRecord(extra, framework, 'name', LEVEL, FILE, LINE, 'msg', [], EXC_INFO) record_object = json.loads(FORMATTER.format(log_record)) assert record_object.get('cls') is not None assert 'MyClass' in record_object.get('cls') diff --git a/tests/unit/record/test_request_log_record.py b/tests/unit/record/test_request_log_record.py index 2d7b7fa..a77e6be 100644 --- a/tests/unit/record/test_request_log_record.py +++ b/tests/unit/record/test_request_log_record.py @@ -14,7 +14,7 @@ FRAMEWORK = None -@pytest.yield_fixture(autouse=True) +@pytest.fixture(autouse=True) def before_each_setup_mocks(mocker): context = Context() mocker.patch.object(context, 'get', return_value=None)