diff --git a/.reuse/dep5 b/.reuse/dep5 new file mode 100755 index 0000000..8b2f31e --- /dev/null +++ b/.reuse/dep5 @@ -0,0 +1,28 @@ +Format: https://www.debian.org/doc/packaging-manuals/copyright-format/1.0/ +Upstream-Name: cf-python-logging-support +Source: https://github.com/SAP/cf-python-logging-support +Disclaimer: The code in this project may include calls to APIs (“API Calls”) of + SAP or third-party products or services developed outside of this project + (“External Products”). + “APIs” means application programming interfaces, as well as their respective + specifications and implementing code that allows software to communicate with + other software. + API Calls to External Products are not licensed under the open source license + that governs this project. The use of such API Calls and related External + Products are subject to applicable additional agreements with the relevant + provider of the External Products. In no event shall the open source license + that governs this project grant any rights in or to any External Products,or + alter, expand or supersede any terms of the applicable additional agreements. + If you have a valid license agreement with SAP for the use of a particular SAP + External Product, then you may make use of any API Calls included in this + project’s code for that SAP External Product, subject to the terms of such + license agreement. If you do not have a valid license agreement for the use of + a particular SAP External Product, then you may only make use of any API Calls + in this project for that SAP External Product for your internal, non-productive + and non-commercial test and evaluation of such API Calls. Nothing herein grants + you any rights to use or access any SAP External Product, or provide any third + parties the right to use of access any SAP External Product, through API Calls. + +Files: * +Copyright: 2017-2021 SAP SE or an SAP affiliate company and cf-python-logging-support contributors +License: Apache-2.0 \ No newline at end of file diff --git a/.travis.yml b/.travis.yml index 49b5c7a..d047e91 100644 --- a/.travis.yml +++ b/.travis.yml @@ -5,9 +5,9 @@ matrix: include: - python: 2.7 env: TOXENV=py27 - - python: 3.6 - env: TOXENV=py36 - - python: 3.6 + - python: 3.8 + env: TOXENV=py38 + - python: 3.8 env: TOXENV=lint install: - pip install tox diff --git a/CHANGELOG.md b/CHANGELOG.md index 88670de..7a6dfaf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,79 @@ This project adheres to [Semantic Versioning](http://semver.org/). The format is based on [Keep a Changelog](http://keepachangelog.com/). + +## 4.2.7 - 2024-06-27 + +### Fixed + + - Remove stacktrace from the message element of the log + +## 4.2.6 - 2024-02-26 + +### Update + + - Update django version => 3.2.24 + +## 4.2.5 - 2023-07-28 + +### Fixed + +- Include stacktrace also for non-error log level if exc_info is present + +## 4.2.4 - 2022-04-26 + +### Update + + - Update django version => 2.2.28 + +## 4.2.3 - 2022-03-23 + +### Fixed + + - Fix stacktrace not showing in kibana + +## 4.2.2 - 2021-04-01 + +### Fixed + + - Fix stacktrace format + +## 4.2.1 - 2021-02-23 + +### Added + + - Add support for custom fields + +### Fixed + + - Fix context store for Sanic + +## 4.1.1 - 2019-04-19 + +### Fixed + + - Fix logging not usable outside request + +## 4.1.0 - 2018-09-13 + +### Added + + - Django support + +## 4.0.1 - 2018-07-10 + +### Fixed + + - Log error throws an exception + +## 4.0.0 - 2018-07-04 + +### Added + - Log exception stacktrace + +### Changed + - Incompatible change: removed `log` function from request in falcon support + ## 3.3.1 - 2018-06-18 ### Fixed diff --git a/LICENSES/Apache-2.0.txt b/LICENSES/Apache-2.0.txt new file mode 100644 index 0000000..137069b --- /dev/null +++ b/LICENSES/Apache-2.0.txt @@ -0,0 +1,73 @@ +Apache License +Version 2.0, January 2004 +http://www.apache.org/licenses/ + +TERMS AND CONDITIONS FOR USE, REPRODUCTION, AND DISTRIBUTION + +1. Definitions. + +"License" shall mean the terms and conditions for use, reproduction, and distribution as defined by Sections 1 through 9 of this document. + +"Licensor" shall mean the copyright owner or entity authorized by the copyright owner that is granting the License. + +"Legal Entity" shall mean the union of the acting entity and all other entities that control, are controlled by, or are under common control with that entity. For the purposes of this definition, "control" means (i) the power, direct or indirect, to cause the direction or management of such entity, whether by contract or otherwise, or (ii) ownership of fifty percent (50%) or more of the outstanding shares, or (iii) beneficial ownership of such entity. + +"You" (or "Your") shall mean an individual or Legal Entity exercising permissions granted by this License. + +"Source" form shall mean the preferred form for making modifications, including but not limited to software source code, documentation source, and configuration files. + +"Object" form shall mean any form resulting from mechanical transformation or translation of a Source form, including but not limited to compiled object code, generated documentation, and conversions to other media types. + +"Work" shall mean the work of authorship, whether in Source or Object form, made available under the License, as indicated by a copyright notice that is included in or attached to the work (an example is provided in the Appendix below). + +"Derivative Works" shall mean any work, whether in Source or Object form, that is based on (or derived from) the Work and for which the editorial revisions, annotations, elaborations, or other modifications represent, as a whole, an original work of authorship. For the purposes of this License, Derivative Works shall not include works that remain separable from, or merely link (or bind by name) to the interfaces of, the Work and Derivative Works thereof. + +"Contribution" shall mean any work of authorship, including the original version of the Work and any modifications or additions to that Work or Derivative Works thereof, that is intentionally submitted to Licensor for inclusion in the Work by the copyright owner or by an individual or Legal Entity authorized to submit on behalf of the copyright owner. For the purposes of this definition, "submitted" means any form of electronic, verbal, or written communication sent to the Licensor or its representatives, including but not limited to communication on electronic mailing lists, source code control systems, and issue tracking systems that are managed by, or on behalf of, the Licensor for the purpose of discussing and improving the Work, but excluding communication that is conspicuously marked or otherwise designated in writing by the copyright owner as "Not a Contribution." + +"Contributor" shall mean Licensor and any individual or Legal Entity on behalf of whom a Contribution has been received by Licensor and subsequently incorporated within the Work. + +2. Grant of Copyright License. Subject to the terms and conditions of this License, each Contributor hereby grants to You a perpetual, worldwide, non-exclusive, no-charge, royalty-free, irrevocable copyright license to reproduce, prepare Derivative Works of, publicly display, publicly perform, sublicense, and distribute the Work and such Derivative Works in Source or Object form. + +3. Grant of Patent License. Subject to the terms and conditions of this License, each Contributor hereby grants to You a perpetual, worldwide, non-exclusive, no-charge, royalty-free, irrevocable (except as stated in this section) patent license to make, have made, use, offer to sell, sell, import, and otherwise transfer the Work, where such license applies only to those patent claims licensable by such Contributor that are necessarily infringed by their Contribution(s) alone or by combination of their Contribution(s) with the Work to which such Contribution(s) was submitted. If You institute patent litigation against any entity (including a cross-claim or counterclaim in a lawsuit) alleging that the Work or a Contribution incorporated within the Work constitutes direct or contributory patent infringement, then any patent licenses granted to You under this License for that Work shall terminate as of the date such litigation is filed. + +4. Redistribution. You may reproduce and distribute copies of the Work or Derivative Works thereof in any medium, with or without modifications, and in Source or Object form, provided that You meet the following conditions: + + (a) You must give any other recipients of the Work or Derivative Works a copy of this License; and + + (b) You must cause any modified files to carry prominent notices stating that You changed the files; and + + (c) You must retain, in the Source form of any Derivative Works that You distribute, all copyright, patent, trademark, and attribution notices from the Source form of the Work, excluding those notices that do not pertain to any part of the Derivative Works; and + + (d) If the Work includes a "NOTICE" text file as part of its distribution, then any Derivative Works that You distribute must include a readable copy of the attribution notices contained within such NOTICE file, excluding those notices that do not pertain to any part of the Derivative Works, in at least one of the following places: within a NOTICE text file distributed as part of the Derivative Works; within the Source form or documentation, if provided along with the Derivative Works; or, within a display generated by the Derivative Works, if and wherever such third-party notices normally appear. The contents of the NOTICE file are for informational purposes only and do not modify the License. You may add Your own attribution notices within Derivative Works that You distribute, alongside or as an addendum to the NOTICE text from the Work, provided that such additional attribution notices cannot be construed as modifying the License. + + You may add Your own copyright statement to Your modifications and may provide additional or different license terms and conditions for use, reproduction, or distribution of Your modifications, or for any such Derivative Works as a whole, provided Your use, reproduction, and distribution of the Work otherwise complies with the conditions stated in this License. + +5. Submission of Contributions. Unless You explicitly state otherwise, any Contribution intentionally submitted for inclusion in the Work by You to the Licensor shall be under the terms and conditions of this License, without any additional terms or conditions. Notwithstanding the above, nothing herein shall supersede or modify the terms of any separate license agreement you may have executed with Licensor regarding such Contributions. + +6. Trademarks. This License does not grant permission to use the trade names, trademarks, service marks, or product names of the Licensor, except as required for reasonable and customary use in describing the origin of the Work and reproducing the content of the NOTICE file. + +7. Disclaimer of Warranty. Unless required by applicable law or agreed to in writing, Licensor provides the Work (and each Contributor provides its Contributions) on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied, including, without limitation, any warranties or conditions of TITLE, NON-INFRINGEMENT, MERCHANTABILITY, or FITNESS FOR A PARTICULAR PURPOSE. You are solely responsible for determining the appropriateness of using or redistributing the Work and assume any risks associated with Your exercise of permissions under this License. + +8. Limitation of Liability. In no event and under no legal theory, whether in tort (including negligence), contract, or otherwise, unless required by applicable law (such as deliberate and grossly negligent acts) or agreed to in writing, shall any Contributor be liable to You for damages, including any direct, indirect, special, incidental, or consequential damages of any character arising as a result of this License or out of the use or inability to use the Work (including but not limited to damages for loss of goodwill, work stoppage, computer failure or malfunction, or any and all other commercial damages or losses), even if such Contributor has been advised of the possibility of such damages. + +9. Accepting Warranty or Additional Liability. While redistributing the Work or Derivative Works thereof, You may choose to offer, and charge a fee for, acceptance of support, warranty, indemnity, or other liability obligations and/or rights consistent with this License. However, in accepting such obligations, You may act only on Your own behalf and on Your sole responsibility, not on behalf of any other Contributor, and only if You agree to indemnify, defend, and hold each Contributor harmless for any liability incurred by, or claims asserted against, such Contributor by reason of your accepting any such warranty or additional liability. + +END OF TERMS AND CONDITIONS + +APPENDIX: How to apply the Apache License to your work. + +To apply the Apache License to your work, attach the following boilerplate notice, with the fields enclosed by brackets "[]" replaced with your own identifying information. (Don't include the brackets!) The text should be enclosed in the appropriate comment syntax for the file format. We also recommend that a file or class name and description of purpose be included on the same "printed page" as the copyright notice for easier identification within third-party archives. + +Copyright [yyyy] [name of copyright owner] + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + +http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. diff --git a/README.rst b/README.rst index 84721cf..c95b330 100644 --- a/README.rst +++ b/README.rst @@ -2,6 +2,9 @@ Python logging library to emit JSON logs in a SAP CloudFoundry environment. =========================================================================== +.. image:: https://api.reuse.software/badge/github.com/SAP/cf-python-logging-support + :target: https://api.reuse.software/info/github.com/SAP/cf-python-logging-support + This is a collection of support libraries for Python applications running on Cloud Foundry that serve two main purposes: provide (a) means to emit structured application log messages and (b) instrument web applications of your application stack to collect request metrics. @@ -23,6 +26,7 @@ Features * `Flask 0.1x `__ * `Sanic 0.5.x `__ * `Falcon `__ + * `Django `__ * Extensible to support others 6. Includes CF-specific information (space id, app id, etc.) to logs. @@ -121,12 +125,13 @@ Falcon import falcon from sap.cf_logging import falcon_logging + from sap.cf_logging.core.constants import REQUEST_KEY class Resource: def on_get(self, req, resp): - # Use the log() method of the req object to log additional messages - req.log('Resource requested') + extra = {REQUEST_KEY: req} + logging.getLogger('my.logger').log('Resource requested', extra=extra) resp.media = {'name': 'Cloud Foundry'} @@ -136,7 +141,72 @@ Falcon app.add_route('/resource', Resource()) falcon_logging.init(app) -**Note**: Use the ``log`` method of ``req`` since it will include the ``correlation_id`` from the ``req`` object in the logs. +Django +^^^^^^ + +.. code:: bash + + django-admin startproject example + +.. code:: python + + # example/settings.py + + MIDDLEWARES = [ + # ..., + 'sap.cf_logging.django_logging.LoggingMiddleware' + ] + + # example/wsgi.py + + # ... + from sap.cf_logging import django_logging + + os.environ.setdefault("DJANGO_SETTINGS_MODULE", "sap_logtesting.settings") + django_logging.init() + + # ... + +Create a new app + +.. code:: bash + + python manage.py startapp example_app + +.. code:: python + + # example_app/views.py + + import logging + + from django.http import HttpResponse + from sap.cf_logging.core.constants import REQUEST_KEY + + def index(request): + extra = {REQUEST_KEY: request} + logger = logging.getLogger('my.logger') + logger.info("Resource requested", extra=extra) + return HttpResponse("ok") + + # example_app/urls.py + + from django.conf.urls import url + + from . import views + + urlpatterns = [ + url('^$', views.index) + ] + + # example/urls.py + + from django.contrib import admin + from django.conf.urls import url, include + + urlpatterns = [ + url('admin/', admin.site.urls), + url('example/', include('example_app.urls')) + ] General ^^^^^^^ @@ -155,6 +225,39 @@ General 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. + +Custom Fields +""""""""""""" + +To use custom fields. Pass a dictionary property custom_fields to the initialize method: + +.. code:: python + + import logging + from sap import cf_logging + cf_logging.init(custom_fields={"foo": "default", "bar": None}) + +Here we mark the two fields: foo and bar as custom_fields. Logging with: + +.. code:: python + + logging.getLogger('my.logger').debug('Hi') + +The property foo will be output as a custom field with a value "default". The property bar will not be logged, as it does not have a value. + +To log bar, provide a value when logging: + +.. code:: python + + logging.getLogger('my.logger').debug('Hi', extra={"bar": "new_value"}) + +It is also possible to log foo with a different value: + +.. code:: python + + logging.getLogger('my.logger').debug('Hi', extra={"foo": "hello"}) + + Setting and getting correlation ID """""""""""""""""""""""""""""""""" @@ -240,9 +343,5 @@ See `CHANGELOG file `__. - - - +Copyright (c) 2017-2021 SAP SE or an SAP affiliate company and cf-python-logging-support contributors. Please see our `LICENSE file `__ for copyright and license information. Detailed information including third-party components and their licensing/copyright information is available `via the REUSE tool `__. diff --git a/conftest.py b/conftest.py index 2912813..3f00811 100644 --- a/conftest.py +++ b/conftest.py @@ -1,4 +1,5 @@ import sys + if sys.version_info < (3, 5): collect_ignore = ['tests/test_sanic_logging.py'] diff --git a/sap/cf_logging/__init__.py b/sap/cf_logging/__init__.py index be194c1..2a45bc9 100644 --- a/sap/cf_logging/__init__.py +++ b/sap/cf_logging/__init__.py @@ -10,7 +10,7 @@ from sap.cf_logging.record.request_log_record import RequestWebRecord from sap.cf_logging.record.simple_log_record import SimpleLogRecord -__version__ = '3.3.1' +__version__ = '4.2.7' _SETUP_DONE = False FRAMEWORK = None @@ -35,7 +35,7 @@ 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): +def init(cfl_framework=None, level=defaults.DEFAULT_LOGGING_LEVEL, custom_fields=None): """ 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 or JobFramework() + FRAMEWORK = cfl_framework or JobFramework(custom_fields=custom_fields) logging.setLoggerClass(CfLogger) diff --git a/sap/cf_logging/core/constants.py b/sap/cf_logging/core/constants.py index 98a2dea..2005287 100644 --- a/sap/cf_logging/core/constants.py +++ b/sap/cf_logging/core/constants.py @@ -5,3 +5,5 @@ LOG_SENSITIVE_CONNECTION_DATA = 'LOG_SENSITIVE_CONNECTION_DATA' LOG_REMOTE_USER = 'LOG_REMOTE_USER' LOG_REFERER = 'LOG_REFERER' + +STACKTRACE_MAX_SIZE = 55 * 1024 diff --git a/sap/cf_logging/core/context.py b/sap/cf_logging/core/context.py index a07f484..5c1add9 100644 --- a/sap/cf_logging/core/context.py +++ b/sap/cf_logging/core/context.py @@ -2,7 +2,7 @@ _CORRELATION_ID_KEY = 'correlation_id' -class Context(object): +class Context(object): # pylint: disable=useless-object-inheritance """ Class for getting and setting context variables """ def set(self, key, value, request): diff --git a/sap/cf_logging/core/framework.py b/sap/cf_logging/core/framework.py index 17a890c..eca7618 100644 --- a/sap/cf_logging/core/framework.py +++ b/sap/cf_logging/core/framework.py @@ -13,10 +13,11 @@ def _check_instance(obj, clazz): raise TypeError('Provided object is not valid {}'.format(clazz.__name__)) -class Framework(object): +class Framework(object): # pylint: disable=useless-object-inheritance """ Framework class holds Context, RequestReader, ResponseReader """ - def __init__(self, name, context, request_reader, response_reader): + # pylint: disable=too-many-arguments + def __init__(self, name, context, request_reader, response_reader, custom_fields=None): if not name or not isinstance(name, STR_CLASS): raise TypeError('Provided name is not valid string') _check_instance(context, Context) @@ -26,6 +27,12 @@ def __init__(self, name, context, request_reader, response_reader): self._context = context self._request_reader = request_reader self._response_reader = response_reader + self._custom_fields = custom_fields or {} + + @property + def custom_fields(self): + """ Get the custom fields """ + return self._custom_fields @property def context(self): diff --git a/sap/cf_logging/core/request_reader.py b/sap/cf_logging/core/request_reader.py index 80459b3..83012f1 100644 --- a/sap/cf_logging/core/request_reader.py +++ b/sap/cf_logging/core/request_reader.py @@ -5,7 +5,7 @@ 'X-CorrelationID', 'X-Request-ID', 'X-Vcap-Request-Id'] -class RequestReader(object): +class RequestReader(object): # pylint: disable=useless-object-inheritance """ Helper class for extracting logging-relevant information from HTTP request object """ diff --git a/sap/cf_logging/core/response_reader.py b/sap/cf_logging/core/response_reader.py index 8d5a1f1..55c8530 100644 --- a/sap/cf_logging/core/response_reader.py +++ b/sap/cf_logging/core/response_reader.py @@ -1,7 +1,7 @@ """ Module for the ResponseReader class """ -class ResponseReader(object): +class ResponseReader(object): # pylint: disable=useless-object-inheritance """ Helper class for extracting logging-relevant information from HTTP response object """ diff --git a/sap/cf_logging/django_logging/__init__.py b/sap/cf_logging/django_logging/__init__.py new file mode 100644 index 0000000..a171abd --- /dev/null +++ b/sap/cf_logging/django_logging/__init__.py @@ -0,0 +1,65 @@ +""" Logging support for Django based applications """ +import logging +from datetime import datetime + +from sap import cf_logging +from sap.cf_logging import defaults +from sap.cf_logging.core.constants import REQUEST_KEY, RESPONSE_KEY +from sap.cf_logging.core.framework import Framework +from sap.cf_logging.django_logging.context import DjangoContext +from sap.cf_logging.django_logging.request_reader import DjangoRequestReader +from sap.cf_logging.django_logging.response_reader import DjangoResponseReader + +DJANGO_FRAMEWORK_NAME = 'django.framework' + + +class LoggingMiddleware(object): # pylint: disable=useless-object-inheritance + """ Django logging middleware """ + + def __init__(self, get_response, logger_name='cf.django.logger'): + self._logger_name = logger_name + self._get_response = get_response + + def __call__(self, request): + self.process_request(request) + response = self._get_response(request) + + response = self.process_response(request, response) + return response + + def process_request(self, request):# pylint: disable=no-self-use + """ + Process the request before routing it. + + :param request: - Django Request object + """ + framework = cf_logging.FRAMEWORK + cid = framework.request_reader.get_correlation_id(request) + framework.context.set_correlation_id(cid, request) + framework.context.set('request_started_at', datetime.utcnow(), request) + + def process_response(self, request, response): + """ + Post-processing of the response (after routing). + + :param request: - Django Request object + :param request: - Django Response object + """ + cf_logging.FRAMEWORK.context.set( + 'response_sent_at', datetime.utcnow(), request) + extra = {REQUEST_KEY: request, RESPONSE_KEY: response} + logging.getLogger(self._logger_name).info('', extra=extra) + return response + + +def init(level=defaults.DEFAULT_LOGGING_LEVEL, custom_fields=None): + """ + Initializes logging in JSON format. + + :param level: - valid log level from standard logging package (optional) + """ + framework = Framework(DJANGO_FRAMEWORK_NAME, DjangoContext(), + DjangoRequestReader(), DjangoResponseReader(), + custom_fields=custom_fields) + + cf_logging.init(framework, level) diff --git a/sap/cf_logging/django_logging/context.py b/sap/cf_logging/django_logging/context.py new file mode 100644 index 0000000..c35cc9b --- /dev/null +++ b/sap/cf_logging/django_logging/context.py @@ -0,0 +1,28 @@ +""" +Django logging context - used by the logging package to keep +request specific data, needed for logging purposes. +For example correlation_id needs to be stored during request processing, +so all log entries contain it. +""" + +from sap.cf_logging.core.context import Context + + +def _init_context(request): + if not hasattr(request, 'context'): + request.context = {} + +class DjangoContext(Context): + """ Stores logging context in Django's request objecct """ + + def set(self, key, value, request): + if request is None: + return + _init_context(request) + request.context[key] = value + + def get(self, key, request): + if request is None: + return None + _init_context(request) + return request.context.get(key) if request else None diff --git a/sap/cf_logging/django_logging/request_reader.py b/sap/cf_logging/django_logging/request_reader.py new file mode 100644 index 0000000..e912974 --- /dev/null +++ b/sap/cf_logging/django_logging/request_reader.py @@ -0,0 +1,34 @@ +""" Django request reader """ + +from sap.cf_logging import defaults +from sap.cf_logging.core.request_reader import RequestReader + + +class DjangoRequestReader(RequestReader): + """ Read log related properties out of Django request """ + + def get_remote_user(self, request): + return request.META.get('REMOTE_USER') or defaults.UNKNOWN + + def get_protocol(self, request): + return request.scheme + + def get_content_length(self, request): + return request.META.get('CONTENT_LENGTH') or defaults.UNKNOWN + + def get_remote_ip(self, request): + return request.META.get('REMOTE_ADDR') + + def get_remote_port(self, request): + return request.META.get('SERVER_PORT') or defaults.UNKNOWN + + def get_http_header(self, request, header_name, default=None): + if request is None: + return default + + if header_name in request.META: + return request.META.get(header_name) + if header_name.upper() in request.META: + return request.META.get(header_name.upper()) + + return default diff --git a/sap/cf_logging/django_logging/response_reader.py b/sap/cf_logging/django_logging/response_reader.py new file mode 100644 index 0000000..7338f93 --- /dev/null +++ b/sap/cf_logging/django_logging/response_reader.py @@ -0,0 +1,15 @@ +""" Django response reader """ +from sap.cf_logging.core.response_reader import ResponseReader + + +class DjangoResponseReader(ResponseReader): + """ Read log related properties out of Django response """ + + def get_status_code(self, response): + return response.status_code + + def get_response_size(self, response): + return len(response.content) + + def get_content_type(self, response): + return response.get('Content-Type') diff --git a/sap/cf_logging/falcon_logging/__init__.py b/sap/cf_logging/falcon_logging/__init__.py index 8c94a6b..988f84c 100644 --- a/sap/cf_logging/falcon_logging/__init__.py +++ b/sap/cf_logging/falcon_logging/__init__.py @@ -15,13 +15,13 @@ FALCON_FRAMEWORK_NAME = 'falcon.framework' -class LoggingMiddleware: +class LoggingMiddleware(object): # pylint: disable=useless-object-inheritance """ Falcon logging middleware """ def __init__(self, logger_name='cf.falcon.logger'): self._logger_name = logger_name - def process_request(self, request, response): # pylint: disable=unused-argument + def process_request(self, request, response): # pylint: disable=unused-argument,no-self-use """Process the request before routing it. :param request: - Falcon Request object @@ -31,8 +31,6 @@ def process_request(self, request, response): # pylint: disable=unused-argument cid = framework.request_reader.get_correlation_id(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) def process_response(self, request, response, resource, req_succeeded): # pylint: disable=unused-argument """Post-processing of the response (after routing). @@ -49,7 +47,7 @@ def process_response(self, request, response, resource, req_succeeded): # pylint logging.getLogger(self._logger_name).info('', extra=extra) -def init(app, level=defaults.DEFAULT_LOGGING_LEVEL, username_key='username'): +def init(app, level=defaults.DEFAULT_LOGGING_LEVEL, username_key='username', custom_fields=None): """ Initializes logging in JSON format. :param app: - Falcon application object @@ -62,5 +60,6 @@ def init(app, level=defaults.DEFAULT_LOGGING_LEVEL, username_key='username'): raise TypeError('application should be instance of Falcon API') framework = Framework(FALCON_FRAMEWORK_NAME, FalconContext(), - FalconRequestReader(username_key), FalconResponseReader()) + FalconRequestReader(username_key), FalconResponseReader(), + custom_fields=custom_fields) cf_logging.init(framework, level) diff --git a/sap/cf_logging/falcon_logging/context.py b/sap/cf_logging/falcon_logging/context.py index 046ee4e..317385b 100644 --- a/sap/cf_logging/falcon_logging/context.py +++ b/sap/cf_logging/falcon_logging/context.py @@ -11,7 +11,8 @@ class FalconContext(Context): """ Stores logging context in Falcon's request object""" def set(self, key, value, request): - request.context[key] = value + if request: + request.context[key] = value def get(self, key, request): return request.context.get(key) if request else None diff --git a/sap/cf_logging/flask_logging/__init__.py b/sap/cf_logging/flask_logging/__init__.py index 5a09db5..384e5ca 100644 --- a/sap/cf_logging/flask_logging/__init__.py +++ b/sap/cf_logging/flask_logging/__init__.py @@ -47,7 +47,7 @@ def _wrapper(response): return _wrapper -def init(app, level=defaults.DEFAULT_LOGGING_LEVEL): +def init(app, level=defaults.DEFAULT_LOGGING_LEVEL, custom_fields=None): """ Initializes logging in JSON format. Adds before and after request handlers to `app` object to enable request info log. @@ -57,7 +57,7 @@ def init(app, level=defaults.DEFAULT_LOGGING_LEVEL): if not isinstance(app, flask.Flask): raise TypeError('application should be instance of Flask') - _init_framework(level) + _init_framework(level, custom_fields=custom_fields) @app.before_request @before_request @@ -70,9 +70,10 @@ def _app_after_request(response): return response -def _init_framework(level): +def _init_framework(level, custom_fields): logging.getLogger('werkzeug').disabled = True framework = Framework(FLASK_FRAMEWORK_NAME, - FlaskContext(), FlaskRequestReader(), FlaskResponseReader()) + FlaskContext(), FlaskRequestReader(), FlaskResponseReader(), + custom_fields=custom_fields) cf_logging.init(framework, level) diff --git a/sap/cf_logging/flask_logging/context.py b/sap/cf_logging/flask_logging/context.py index 0e3dd71..cd74ff9 100644 --- a/sap/cf_logging/flask_logging/context.py +++ b/sap/cf_logging/flask_logging/context.py @@ -11,7 +11,8 @@ class FlaskContext(Context): """ Stores logging context in Flask's request scope """ def set(self, key, value, request): - setattr(g, key, value) + if g: + setattr(g, key, value) def get(self, key, request): - return getattr(g, key, None) + return getattr(g, key, None) if g else None diff --git a/sap/cf_logging/formatters/stacktrace_formatter.py b/sap/cf_logging/formatters/stacktrace_formatter.py new file mode 100644 index 0000000..44543d5 --- /dev/null +++ b/sap/cf_logging/formatters/stacktrace_formatter.py @@ -0,0 +1,51 @@ +""" +Module for formatting utilities for stacktrace +generated by user logging.exception call +""" +import re + +from sap.cf_logging.core import constants + + +def format_stacktrace(stacktrace): + """ + Removes tab characters + Truncates stacktrace to maximum size + + :param stacktrace: string representation of a stacktrace + """ + if not isinstance(stacktrace, str): + return '' + + stacktrace = re.sub('\t', ' ', stacktrace) + + if len(stacktrace) <= constants.STACKTRACE_MAX_SIZE: + return stacktrace + + stacktrace_beginning = _stacktrace_beginning( + stacktrace, constants.STACKTRACE_MAX_SIZE // 3 + ) + + stacktrace_end = _stacktrace_end( + stacktrace, (constants.STACKTRACE_MAX_SIZE // 3) * 2 + ) + + new_stacktrace = "-------- STACK TRACE TRUNCATED --------\n" + stacktrace_beginning +\ + "-------- OMITTED --------\n" + stacktrace_end + + return new_stacktrace + +def _stacktrace_beginning(stacktrace, size): + """ Gets the first `size` bytes of the stacktrace """ + if len(stacktrace) <= size: + return stacktrace + + return stacktrace[:size] + +def _stacktrace_end(stacktrace, size): + """ Gets the last `size` bytes of the stacktrace """ + stacktrace_length = len(stacktrace) + if stacktrace_length <= size: + return stacktrace + + return stacktrace[:-(stacktrace_length-size)] diff --git a/sap/cf_logging/job_logging/framework.py b/sap/cf_logging/job_logging/framework.py index 61f7f8b..3533e61 100644 --- a/sap/cf_logging/job_logging/framework.py +++ b/sap/cf_logging/job_logging/framework.py @@ -11,10 +11,11 @@ class JobFramework(Framework): """ Simple framework using default request and response readers. Uses JobContext to keeping properties in memory """ - def __init__(self, context=None): + def __init__(self, context=None, custom_fields=None): super(JobFramework, self).__init__( JOB_FRAMEWORK_NAME, context or JobContext(), RequestReader(), - ResponseReader() + ResponseReader(), + custom_fields=custom_fields ) diff --git a/sap/cf_logging/record/application_info.py b/sap/cf_logging/record/application_info.py index 8ea112f..f866f0a 100644 --- a/sap/cf_logging/record/application_info.py +++ b/sap/cf_logging/record/application_info.py @@ -8,7 +8,7 @@ LAYER = 'python' COMPONENT_ID = util.get_vcap_param('application_id', defaults.UNKNOWN) COMPONENT_NAME = util.get_vcap_param('name', defaults.UNKNOWN) -COMPONENT_INSTANCE = os.getenv('CF_INSTANCE_INDEX', 0) +COMPONENT_INSTANCE = int(os.getenv('CF_INSTANCE_INDEX', "0")) SPACE_ID = util.get_vcap_param('space_id', defaults.UNKNOWN) SPACE_NAME = util.get_vcap_param('space_name', defaults.UNKNOWN) CONTAINER_ID = os.getenv('CF_INSTANCE_IP', defaults.UNKNOWN) diff --git a/sap/cf_logging/record/simple_log_record.py b/sap/cf_logging/record/simple_log_record.py index 256f12d..af8f151 100644 --- a/sap/cf_logging/record/simple_log_record.py +++ b/sap/cf_logging/record/simple_log_record.py @@ -1,11 +1,15 @@ """ Module SimpleLogRecord """ import logging +import traceback + 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 +from sap.cf_logging.formatters.stacktrace_formatter import format_stacktrace + _SKIP_ATTRIBUTES = ["type", "written_at", "written_ts", "correlation_id", "remote_user", "referer", "x_forwarded_for", "protocol", "method", "remote_ip", "request_size_b", "remote_host", "remote_port", "request_received_at", "direction", @@ -29,8 +33,17 @@ def __init__(self, extra, framework, *args, **kwargs): self.correlation_id = framework.context.get_correlation_id(request) or defaults.UNKNOWN + self.custom_fields = {} + for key, value in framework.custom_fields.items(): + if extra and key in extra: + if extra[key] is not None: + self.custom_fields[key] = extra[key] + elif value is not None: + self.custom_fields[key] = value + self.extra = dict((key, value) for key, value in extra.items() - if key not in _SKIP_ATTRIBUTES) if extra else {} + if key not in _SKIP_ATTRIBUTES and + key not in framework.custom_fields.keys()) if extra else {} for key, value in self.extra.items(): setattr(self, key, value) @@ -59,9 +72,24 @@ def format(self): 'logger': self.name, 'thread': self.threadName, 'level': self.levelname, - 'line_no': self.lineno, 'msg': self.getMessage(), }) + if self.exc_info: + stacktrace = ''.join(traceback.format_exception(*self.exc_info)) + stacktrace = format_stacktrace(stacktrace) + record['stacktrace'] = stacktrace.split('\n') + + record.update(self.extra) + if len(self.custom_fields) > 0: + record.update(self._format_custom_fields()) return record + + def _format_custom_fields(self): + res = {"#cf": {"string": []}} + for i, (key, value) in enumerate(self.custom_fields.items()): + res['#cf']['string'].append( + {"k": str(key), "v": str(value), "i": i} + ) + return res diff --git a/sap/cf_logging/sanic_logging/__init__.py b/sap/cf_logging/sanic_logging/__init__.py index 87fe562..ec1be21 100644 --- a/sap/cf_logging/sanic_logging/__init__.py +++ b/sap/cf_logging/sanic_logging/__init__.py @@ -48,7 +48,7 @@ def _wrapper(request, response): return _wrapper -def init(app, level=defaults.DEFAULT_LOGGING_LEVEL, custom_framework=None): +def init(app, level=defaults.DEFAULT_LOGGING_LEVEL, custom_framework=None, custom_fields=None): """ Initializes logging in JSON format. Adds before and after request handlers to the `app` object to enable request info log. @@ -65,7 +65,8 @@ def init(app, level=defaults.DEFAULT_LOGGING_LEVEL, custom_framework=None): SANIC_FRAMEWORK_NAME, SanicContext(), SanicRequestReader(), - SanicResponseReader() + SanicResponseReader(), + custom_fields=custom_fields ) cf_logging.init(framework, level) diff --git a/sap/cf_logging/sanic_logging/context.py b/sap/cf_logging/sanic_logging/context.py index 22f381e..8776ad6 100644 --- a/sap/cf_logging/sanic_logging/context.py +++ b/sap/cf_logging/sanic_logging/context.py @@ -7,24 +7,15 @@ CONTEXT_NAME = 'cf_logger_context' -def _init_context(request): - if CONTEXT_NAME not in request: - request[CONTEXT_NAME] = {} - - class SanicContext(Context): """ Stores logging context in Sanic's request object """ def set(self, key, value, request): - if request is None: - return - _init_context(request) - request[CONTEXT_NAME][key] = value + if request is not None: + setattr(request.ctx, key, value) def get(self, key, request): if request is None: return None - _init_context(request) - if key in request[CONTEXT_NAME]: - return request[CONTEXT_NAME][key] - return None + + return getattr(request.ctx, key, None) diff --git a/setup.py b/setup.py index 2d86cd2..48e8966 100644 --- a/setup.py +++ b/setup.py @@ -37,6 +37,10 @@ 'Programming Language :: Python :: 3.4', 'Programming Language :: Python :: 3.5', 'Programming Language :: Python :: 3.6', + 'Programming Language :: Python :: 3.8', + 'Programming Language :: Python :: 3.9', + 'Programming Language :: Python :: 3.10', + 'Programming Language :: Python :: 3.11', 'Topic :: Software Development :: Libraries :: Python Modules', 'Topic :: Software Development', 'Topic :: System :: Logging', diff --git a/test-requirements.txt b/test-requirements.txt index 188d8f5..8758159 100644 --- a/test-requirements.txt +++ b/test-requirements.txt @@ -1,12 +1,17 @@ asyncio falcon -falcon-auth +falcon-auth==1.0.3; python_version == '2.7' +falcon-auth; python_version >= '3.5' Flask sanic; python_version >= '3.5' +sanic-testing==0.3.0; python_version >= '3.5' aiohttp; python_version >= '3.5' -sonic182-json-validator==0.0.12 -pytest==3.2.2 -pytest-cov==2.5.1 -pytest-mock==1.6.3 -pylint +sonic182-json-validator +pytest +pytest-cov +pytest-mock +pylint==1.9.5; python_version == '2.7' +pylint==2.5.3; python_version >= '3.5' tox +django==1.11.29; python_version == '2.7' +django==3.2.25; python_version >= '3.5' diff --git a/tests/common_test_params.py b/tests/common_test_params.py index 78debfc..e971738 100644 --- a/tests/common_test_params.py +++ b/tests/common_test_params.py @@ -22,7 +22,7 @@ def get_web_record_header_fixtures(): 'response_content_type': v_str('text/plain'), 'request': v_str('/test/path')}) ] - for header in ['x-Correlation-ID', 'X-CorrelationID', 'X-Request-ID', 'X-Vcap-Request-Id']: + for header in ['X-Correlation-ID', 'X-CorrelationID', 'X-Request-ID', 'X-Vcap-Request-Id']: test_cases.append(({header: '298ebf9d-be1d-11e7-88ff-2c44fd152864'}, {'correlation_id': v_str('298ebf9d-be1d-11e7-88ff-2c44fd152864')})) diff --git a/tests/django_logging/__init__.py b/tests/django_logging/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/tests/django_logging/test_app/__init__.py b/tests/django_logging/test_app/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/tests/django_logging/test_app/settings.py b/tests/django_logging/test_app/settings.py new file mode 100644 index 0000000..11df7b2 --- /dev/null +++ b/tests/django_logging/test_app/settings.py @@ -0,0 +1,17 @@ +""" Example django test app settings """ +SECRET_KEY = 'fake-key' +INSTALLED_APPS = [ + "tests", +] + +DATABASES = { + 'default': { + 'ENGINE': 'django.db.backends.sqlite3' + } +} + +ROOT_URLCONF = 'tests.django_logging.test_app.urls' + +MIDDLEWARE = [ + 'sap.cf_logging.django_logging.LoggingMiddleware', +] diff --git a/tests/django_logging/test_app/test_django_logging.py b/tests/django_logging/test_app/test_django_logging.py new file mode 100644 index 0000000..6d4c681 --- /dev/null +++ b/tests/django_logging/test_app/test_django_logging.py @@ -0,0 +1,101 @@ +""" Module that tests the integration of cf_logging with Django """ +import sys +import os +import pytest + +from django.test import Client +from django.conf.urls import url +from django.conf import settings + +from sap import cf_logging +from sap.cf_logging import django_logging +from tests.log_schemas import WEB_LOG_SCHEMA +from tests.common_test_params import ( + v_str, get_web_record_header_fixtures +) +from tests.util import ( + check_log_record, + enable_sensitive_fields_logging, + config_logger +) + +from tests.django_logging.test_app.views import UserLoggingView + + +os.environ['DJANGO_SETTINGS_MODULE'] = 'tests.django_logging.test_app.settings' + + +@pytest.fixture(autouse=True) +def before_each(): + """ enable all fields to be logged """ + enable_sensitive_fields_logging() + yield + + +FIXTURE = get_web_record_header_fixtures() + +@pytest.mark.parametrize('headers, expected', FIXTURE) +def test_django_request_log(headers, expected): + """ That the expected records are logged by the logging library """ + _set_up_django_logging() + _check_django_request_log(headers, expected) + + +def test_web_log(): + """ That the custom properties are logged """ + _user_logging({}, {'myproperty': 'myval'}, {'myproperty': v_str('myval')}) + + +def test_correlation_id(): + """ Test the correlation id is logged when coming from the headers """ + _user_logging( + {'X-CorrelationID': '298ebf9d-be1d-11e7-88ff-2c44fd152860'}, + {}, + {'correlation_id': v_str('298ebf9d-be1d-11e7-88ff-2c44fd152860')}, + True + ) + + +def test_missing_request(): + """ That the correlation id is missing when the request is missing """ + _user_logging( + {'X-CorrelationID': '298ebf9d-be1d-11e7-88ff-2c44fd152860'}, + {}, + {'correlation_id': v_str('-')}, + False + ) + +def test_custom_fields_set(): + """ Test custom fields are set up """ + _set_up_django_logging() + assert 'cf1' in cf_logging.FRAMEWORK.custom_fields.keys() + +def _check_django_request_log(headers, expected): + _, stream = config_logger('cf.django.logger') + + client = Client() + _check_expected_response(client.get('/test/path', **headers), body='Hello test!') + assert check_log_record(stream, WEB_LOG_SCHEMA, expected) == {} + + +# Helper functions +def _set_up_django_logging(): + cf_logging._SETUP_DONE = False # pylint: disable=protected-access + django_logging.init(custom_fields={'cf1': None}) + + +def _check_expected_response(response, status_code=200, body='ok'): + assert response.status_code == status_code + if body is not None: + assert response.content.decode() == body + + +def _user_logging(headers, extra, expected, provide_request=False): + sys.modules[settings.ROOT_URLCONF].urlpatterns.append( + url('^test/user/logging$', UserLoggingView.as_view(provide_request=provide_request), + {'extra': extra, 'expected': expected})) + + + _set_up_django_logging() + client = Client() + _check_expected_response(client.get('/test/user/logging', **headers)) diff --git a/tests/django_logging/test_app/urls.py b/tests/django_logging/test_app/urls.py new file mode 100644 index 0000000..f4c2337 --- /dev/null +++ b/tests/django_logging/test_app/urls.py @@ -0,0 +1,9 @@ +""" Urls for example django test app """ +from django.conf.urls import url + +from tests.django_logging.test_app.views import IndexView + +# pylint: disable=invalid-name +urlpatterns = [ + url("^test/path$", IndexView.as_view(), name='log-index') +] diff --git a/tests/django_logging/test_app/views.py b/tests/django_logging/test_app/views.py new file mode 100644 index 0000000..a01b26c --- /dev/null +++ b/tests/django_logging/test_app/views.py @@ -0,0 +1,37 @@ +""" Views for example django test app """ +import logging + +from django.http import HttpResponse +from django.views import generic + +from sap.cf_logging.core.constants import REQUEST_KEY +from tests.util import config_logger, check_log_record +from tests.log_schemas import JOB_LOG_SCHEMA + +# pylint: disable=unused-argument + +class IndexView(generic.View): + """ View that is hit on the index route """ + def get(self, request): # pylint: disable=no-self-use + """ Return a basic http response """ + return HttpResponse("Hello test!", content_type='text/plain') + + +class UserLoggingView(generic.View): + """ View that logs custom user information """ + provide_request = False + + def __init__(self, *args, **kwargs): + self.logger, self.stream = config_logger('user.logging') + super(UserLoggingView, self).__init__(*args, **kwargs) + + def get(self, request, *args, **kwargs): + """ Log a custom user message with the logger """ + expected = kwargs.get('expected') or {} + extra = kwargs.get('extra') or {} + if self.provide_request: + extra.update({REQUEST_KEY: request}) + + self.logger.log(logging.INFO, 'in route headers', extra=extra) + assert check_log_record(self.stream, JOB_LOG_SCHEMA, expected) == {} + return HttpResponse("ok", content_type='text/plain') diff --git a/tests/log_schemas.py b/tests/log_schemas.py index 6b215f7..39cbafc 100644 --- a/tests/log_schemas.py +++ b/tests/log_schemas.py @@ -22,11 +22,26 @@ 'logger': u.string(u.WORD), 'thread': u.string(u.WORD), 'level': u.enum(u.LEVEL), - 'line_no': u.pos_num(), 'written_at': u.iso_datetime(), 'written_ts': u.pos_num(), 'msg': u.string(u.WORD), - 'component_type': u.string(r'^application$') + 'component_type': u.string(r'^application$'), +}) + +CUST_FIELD_SCHEMA = u.extend(JOB_LOG_SCHEMA, { + '#cf': { + 'type': dict, + 'properties': { + 'string': {'type' : list, 'items': { + 'type': dict, + 'properties': { + 'v': u.string(u.WORD), + 'k': u.string(u.WORD), + 'i': u.pos_num() + } + }} + } + } }) WEB_LOG_SCHEMA = u.extend(CF_ATTRIBUTES_SCHEMA, { diff --git a/tests/schema_util.py b/tests/schema_util.py index a355d0e..98e230b 100644 --- a/tests/schema_util.py +++ b/tests/schema_util.py @@ -6,7 +6,7 @@ IP = r'[[0-9]+|.?]+\d$' HOST_NAME = r'[[0-9]+|.?]+\d$' -LEVEL = ['CRITICAL', 'ERROR', 'WARNING', 'INFO', 'NOTSET'] +LEVEL = ['CRITICAL', 'ERROR', 'WARNING', 'INFO', 'DEBUG', 'NOTSET'] def num(val=None): diff --git a/tests/test_falcon_logging.py b/tests/test_falcon_logging.py index ec48427..229bb69 100644 --- a/tests/test_falcon_logging.py +++ b/tests/test_falcon_logging.py @@ -6,11 +6,16 @@ from falcon_auth import FalconAuthMiddleware, BasicAuthBackend from sap import cf_logging from sap.cf_logging import falcon_logging +from sap.cf_logging.core.constants import REQUEST_KEY 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 ) -from tests.util import check_log_record, config_root_logger, enable_sensitive_fields_logging +from tests.util import ( + check_log_record, + config_logger, + enable_sensitive_fields_logging +) # pylint: disable=protected-access, missing-docstring,too-few-public-methods @@ -47,7 +52,7 @@ def test_falcon_request_log(headers, expected): _check_falcon_request_log(app, headers, expected) -class User(object): +class User(object): # pylint: disable=useless-object-inheritance def __init__(self, key, name): self.key = key self.name = name @@ -73,7 +78,7 @@ def test_falcon_request_logs_user(user): def _check_falcon_request_log(app, headers, expected): - _, stream = config_root_logger('cf.falcon.logger') + _, stream = config_logger('cf.falcon.logger') client = testing.TestClient(app) _check_expected_response( @@ -85,32 +90,47 @@ def test_web_log(): """ That the custom properties are logged """ _user_logging({}, {'myprop': 'myval'}, {'myprop': v_str('myval')}) +def test_logging_without_request(): + """ Test logger is usable in non request context """ + app = falcon.API() + _set_up_falcon_logging(app) + cf_logging.FRAMEWORK.context.set_correlation_id('value') + + logger, stream = config_logger('main.logger') + logger.info('works') + assert check_log_record(stream, JOB_LOG_SCHEMA, {'msg': v_str('works')}) == {} + def test_correlation_id(): """ Test the correlation id is logged when coming from the headers """ _user_logging( - {'X-CorrelationID': '298ebf9d-be1d-11e7-88ff-2c44fd152860'}, + {'X-Correlation-ID': '298ebf9d-be1d-11e7-88ff-2c44fd152860'}, {}, {'correlation_id': v_str('298ebf9d-be1d-11e7-88ff-2c44fd152860')} ) +def test_custom_fields_set(): + """ Test custom fields are set up """ + app = falcon.API() + _set_up_falcon_logging(app) + assert 'cf1' in cf_logging.FRAMEWORK.custom_fields.keys() # Helper functions def _set_up_falcon_logging(app, *args): cf_logging._SETUP_DONE = False - falcon_logging.init(app, logging.DEBUG, *args) - + falcon_logging.init(app, logging.DEBUG, *args, custom_fields={'cf1': None}) -class UserResourceRoute: +class UserResourceRoute(object): # pylint: disable=useless-object-inheritance def __init__(self, extra, expected): self.extra = extra self.expected = expected + self.logger, self.stream = config_logger('user.logging') 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, JOB_LOG_SCHEMA, self.expected) == {} + self.extra.update({REQUEST_KEY: req}) + self.logger.log(logging.INFO, 'in route headers', extra=self.extra) + assert check_log_record(self.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 dd1b4a2..65a4c72 100644 --- a/tests/test_flask_logging.py +++ b/tests/test_flask_logging.py @@ -5,9 +5,13 @@ from flask import Response from sap import cf_logging from sap.cf_logging import flask_logging -from tests.log_schemas import WEB_LOG_SCHEMA, JOB_LOG_SCHEMA +from tests.log_schemas import WEB_LOG_SCHEMA, JOB_LOG_SCHEMA, CUST_FIELD_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 +from tests.util import ( + check_log_record, + enable_sensitive_fields_logging, + config_logger, +) # pylint: disable=protected-access @@ -26,6 +30,7 @@ def test_flask_requires_valid_app(): @pytest.fixture(autouse=True) def before_each(): + # pylint: disable=duplicate-code """ enable all fields to be logged """ enable_sensitive_fields_logging() yield @@ -42,7 +47,7 @@ def _root(): return Response('ok', mimetype='text/plain') _set_up_flask_logging(app) - _, stream = config_root_logger('cf.flask.logger') + _, stream = config_logger('cf.flask.logger') client = app.test_client() _check_expected_response(client.get('/test/path', headers=headers)) @@ -61,10 +66,26 @@ def test_correlation_id(): {'correlation_id': v_str('298ebf9d-be1d-11e7-88ff-2c44fd152860')}) +def test_logging_without_request(): + """ Test logger is usable in non request context """ + app = Flask(__name__) + _set_up_flask_logging(app) + logger, stream = config_logger('main.logger') + logger.info('works') + assert check_log_record(stream, JOB_LOG_SCHEMA, {'msg': v_str('works')}) == {} + +def test_custom_field_loggin(): + """ Test custom fields are generated """ + app = Flask(__name__) + _set_up_flask_logging(app) + logger, stream = config_logger('main.logger') + logger.info('works', extra={'cf1': 'yes'}) + assert check_log_record(stream, CUST_FIELD_SCHEMA, {}) == {} + # Helper functions def _set_up_flask_logging(app, level=logging.DEBUG): cf_logging._SETUP_DONE = False - flask_logging.init(app, level) + flask_logging.init(app, level, custom_fields={'cf1': None, 'cf2': None}) def _user_logging(headers, extra, expected): @@ -72,7 +93,7 @@ def _user_logging(headers, extra, expected): @app.route('/test/user/logging') def _logging_correlation_id_route(): - logger, stream = config_root_logger('user.logging') + logger, stream = config_logger('user.logging') logger.info('in route headers', extra=extra) assert check_log_record(stream, JOB_LOG_SCHEMA, expected) == {} return Response('ok') diff --git a/tests/test_job_logging.py b/tests/test_job_logging.py index 3290d82..b7e1aec 100644 --- a/tests/test_job_logging.py +++ b/tests/test_job_logging.py @@ -8,7 +8,7 @@ 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 +from tests.util import config_logger # pylint: disable=protected-access @@ -19,11 +19,18 @@ def before_each(): cf_logging._SETUP_DONE = False -def test_log_in_expected_format(): +@pytest.mark.parametrize('log_callback', [ + lambda logger, msg: logger.debug('message: %s', msg), + lambda logger, msg: logger.info('message: %s', msg), + lambda logger, msg: logger.warning('message: %s', msg), + lambda logger, msg: logger.error('message: %s', msg), + lambda logger, msg: logger.critical('message: %s', msg) +]) +def test_log_in_expected_format(log_callback): """ Test the cf_logger as a standalone """ cf_logging.init(level=logging.DEBUG) - logger, stream = config_root_logger('cli.test') - logger.info('hi') + logger, stream = config_logger('cli.test') + log_callback(logger, 'hi') log_json = JSONDecoder().decode(stream.getvalue()) _, error = JsonValidator(JOB_LOG_SCHEMA).validate(log_json) @@ -36,7 +43,7 @@ def test_set_correlation_id(): cf_logging.init(level=logging.DEBUG) cf_logging.FRAMEWORK.context.set_correlation_id(correlation_id) - logger, stream = config_root_logger('cli.test') + logger, stream = config_logger('cli.test') logger.info('hi') log_json = JSONDecoder().decode(stream.getvalue()) @@ -46,6 +53,46 @@ def test_set_correlation_id(): assert log_json['correlation_id'] == correlation_id assert cf_logging.FRAMEWORK.context.get_correlation_id() == correlation_id + +def test_exception_stacktrace(): + """ Test exception stacktrace is logged """ + cf_logging.init(level=logging.DEBUG) + logger, stream = config_logger('cli.test') + + try: + return 1 / 0 + except ZeroDivisionError: + logger.exception('zero division error') + log_json = JSONDecoder().decode(stream.getvalue()) + _, error = JsonValidator(JOB_LOG_SCHEMA).validate(log_json) + + assert error == {} + assert 'ZeroDivisionError' in str(log_json['stacktrace']) + assert log_json["msg"] == 'zero division error' + + +def test_exception_stacktrace_info_level(): + """ Test exception stacktrace is logged """ + cf_logging.init(level=logging.DEBUG) + logger, stream = config_logger('cli.test') + + try: + return 1 / 0 + except ZeroDivisionError as exc: + logger.info('zero division error', exc_info=exc) + log_json = JSONDecoder().decode(stream.getvalue()) + _, error = JsonValidator(JOB_LOG_SCHEMA).validate(log_json) + + assert error == {} + assert 'ZeroDivisionError' in str(log_json['stacktrace']) + assert log_json["msg"] == 'zero division error' + + +def test_custom_fields_set(): + """ Test custom fields are set up """ + cf_logging.init(level=logging.DEBUG, custom_fields={'cf1': None}) + assert 'cf1' in cf_logging.FRAMEWORK.custom_fields.keys() + def test_thread_safety(): """ test context keeps separate correlation ID per thread """ class _SampleThread(threading.Thread): diff --git a/tests/test_sanic_logging.py b/tests/test_sanic_logging.py index df338b8..56993ac 100644 --- a/tests/test_sanic_logging.py +++ b/tests/test_sanic_logging.py @@ -9,7 +9,11 @@ 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 +from tests.util import ( + check_log_record, + config_logger, + enable_sensitive_fields_logging, +) # pylint: disable=protected-access @@ -22,12 +26,14 @@ 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.fixture(autouse=True) def before_each(): """ enable all fields to be logged """ enable_sensitive_fields_logging() yield + @pytest.mark.parametrize("headers, expected", FIXTURE) def test_sanic_request_log(headers, expected): """ Test that the JSON logs contain the expected properties based on the @@ -45,7 +51,8 @@ async def _headers_route(request): _, stream = config_logger('cf.sanic.logger') client = app.test_client - _check_expected_response(client.get('/test/path', headers=headers)[1], 200, 'ok') + _check_expected_response(client.get( + '/test/path', headers=headers)[1], 200, 'ok') assert check_log_record(stream, WEB_LOG_SCHEMA, expected) == {} @@ -70,11 +77,17 @@ def test_logs_correlation_id(): '298ebf9d-be1d-11e7-88ff-2c44fd152860')}, True) +def test_custom_fields_set(): + """ Test custom fields are set up """ + app = sanic.Sanic('test cf_logging') + _set_up_sanic_logging(app) + assert 'cf1' in cf_logging.FRAMEWORK.custom_fields.keys() + # Helper functions def _set_up_sanic_logging(app, level=logging.DEBUG): cf_logging._SETUP_DONE = False - sanic_logging.init(app, level) + sanic_logging.init(app, level, custom_fields={'cf1': None}) def _user_logging(headers, extra, expected, provide_request=False): diff --git a/tests/unit/formatters/test_json_formatter.py b/tests/unit/formatters/test_json_formatter.py index c63e233..56b3b8d 100644 --- a/tests/unit/formatters/test_json_formatter.py +++ b/tests/unit/formatters/test_json_formatter.py @@ -18,7 +18,7 @@ def test_unknown_records_format(): def test_non_json_serializable(): """ test json formatter handles non JSON serializable object """ - class _MyClass(object): # pylint: disable=too-few-public-methods + class _MyClass(object): # pylint: disable=too-few-public-methods,useless-object-inheritance pass extra = {'cls': _MyClass()} @@ -27,3 +27,24 @@ class _MyClass(object): # pylint: disable=too-few-public-methods record_object = json.loads(FORMATTER.format(log_record)) assert record_object.get('cls') is not None assert 'MyClass' in record_object.get('cls') + +def test_stacktrace_is_added_to_msg_field(): + """ + Tests that JSONFormatter adds stracktrace to msg field. The stacktrace field + is no longer rendered in Kibana, see https://github.com/SAP/cf-python-logging-support/issues/45 + for related report. + """ + # Generate exception for the test + try: + raise ValueError("Dummy Exception") + except ValueError as e: + exc_info = (type(e), e, e.__traceback__) + + framework = JobFramework() + extra = {} + + log_record = SimpleLogRecord(extra, framework, 'name', logging.ERROR, FILE, LINE, 'Error found!', [], exc_info) + record_object = json.loads(FORMATTER.format(log_record)) + assert "Dummy Exception" in "".join(record_object["stacktrace"]) + expected_msg = "Error found!" + assert record_object["msg"] == expected_msg diff --git a/tests/unit/formatters/test_stacktrace_formatter.py b/tests/unit/formatters/test_stacktrace_formatter.py new file mode 100644 index 0000000..086461a --- /dev/null +++ b/tests/unit/formatters/test_stacktrace_formatter.py @@ -0,0 +1,24 @@ +""" Module testing the functionality of the StacktraceFormatter class """ +from sap.cf_logging.formatters.stacktrace_formatter import format_stacktrace + + +STACKTRACE = ''.join(['Traceback (most recent call last):\n', + 'File "nonexistent_file.py", line 100, in nonexistent_function\n', + 'raise ValueError("Oh no")\n', + 'ValueError: Oh no']) + + +def test_stacktrace_not_truncated(): + """ Test that stacktrace is not truncated when smaller than the stacktrace maximum size """ + formatted = format_stacktrace(STACKTRACE) + assert "TRUNCATED" not in formatted + assert "OMITTED" not in formatted + + +def test_stacktrace_truncated(monkeypatch): + """ Test that stacktrace is truncated when bigger than the stacktrace maximum size """ + monkeypatch.setattr('sap.cf_logging.core.constants.STACKTRACE_MAX_SIZE', 120) + + formatted = ''.join(format_stacktrace(STACKTRACE)) + assert "TRUNCATED" in formatted + assert "OMITTED" in formatted diff --git a/tests/unit/test_init.py b/tests/unit/test_init.py index db49d5a..aeaeaec 100644 --- a/tests/unit/test_init.py +++ b/tests/unit/test_init.py @@ -32,8 +32,11 @@ def _make_record(extra): return cf_logger.makeRecord('', '', '', '', '', '', '', '', extra=extra) -def test_init_cf_logger_simple_log(): +def test_init_cf_logger_simple_log(mocker): """ tests CfLogger creates SimpleLogRecord if extra is incomplete """ + framework = mocker.Mock(Framework) + mocker.patch.object(framework, 'custom_fields', return_value=None) + cf_logging.init(framework) assert isinstance(_make_record(extra={}), SimpleLogRecord) assert isinstance(_make_record(extra={REQUEST_KEY: {}}), SimpleLogRecord) assert isinstance(_make_record(extra={RESPONSE_KEY: {}}), SimpleLogRecord) diff --git a/tests/util.py b/tests/util.py index 4afa5dc..04c7086 100644 --- a/tests/util.py +++ b/tests/util.py @@ -25,14 +25,6 @@ def check_log_record(stream, schema, expected): return error -def config_root_logger(logger_name): - """ Function to configure a JSONLogger and print the output into a stream""" - stream = io.StringIO() - logging.getLogger().handlers[0].stream = stream - logger = logging.getLogger(logger_name) - return logger, stream - - def config_logger(logger_name): """ Function to configure a JSONLogger and print the output into a stream""" stream = io.StringIO() diff --git a/tox.ini b/tox.ini index 41591b2..7dad122 100644 --- a/tox.ini +++ b/tox.ini @@ -1,5 +1,5 @@ [tox] -envlist = py27,py36,lint +envlist = py27,py38,lint [testenv] deps = -rtest-requirements.txt @@ -7,11 +7,12 @@ deps = -rtest-requirements.txt [testenv:py27] commands = py.test {posargs} -[testenv:py36] +[testenv:py38] +setenv = SANIC_REGISTER = False commands = py.test --cov=sap tests {posargs} [testenv:lint] -basepython=python3.6 +basepython=python3.8 commands= pylint sap - pylint tests + pylint --extension-pkg-whitelist=falcon tests