From 6c764bdfb4320c83a1624132f4887b3ee4b78203 Mon Sep 17 00:00:00 2001 From: Sourya Vatsyayan Date: Tue, 10 Sep 2019 19:57:36 +0530 Subject: [PATCH 1/3] [Fix niteoweb/pyramid_heroku#22] Add request_id... ... to sentry and structlog logs Signed-off-by: Sourya Vatsyayan --- pyramid_heroku/request_id.py | 50 ++++++++++++++ pyramid_heroku/tests/__init__.py | 9 +++ pyramid_heroku/tests/test_request_id.py | 92 +++++++++++++++++++++++++ 3 files changed, 151 insertions(+) create mode 100644 pyramid_heroku/request_id.py create mode 100644 pyramid_heroku/tests/test_request_id.py diff --git a/pyramid_heroku/request_id.py b/pyramid_heroku/request_id.py new file mode 100644 index 0000000..427b735 --- /dev/null +++ b/pyramid_heroku/request_id.py @@ -0,0 +1,50 @@ +"""Set request ID in Sentry logs if sentry is imported, and in structlog logs +if structlog is imported. +""" + + +try: + import sentry_sdk + IS_SENTRY_ENABLED = True +except ImportError: + IS_SENTRY_ENABLED = False + +try: + import structlog + IS_STRUCTLOG_ENABLED = True +except ImportError: + IS_STRUCTLOG_ENABLED = False + + +def includeme(config): + config.add_tween("pyramid_heroku.request_id.RequestIDLogger") + + +class RequestIDLogger(object): + """Set request ID in sentry and structlog logs. + + If the request headers contain a request ID (X-Request-ID), it should be + logged for better debugging. In case sentry is being used, log the request + ID along with other info. Similarly, if structlog is being used, add the + request ID in the logs. + """ + + def __init__(self, handler, _): + self.handler = handler + + def __call__(self, request): + request_id = request.headers.get("X-Request-ID") + + if request_id is not None: + if IS_SENTRY_ENABLED: + with sentry_sdk.configure_scope() as scope: + scope.set_tag("request_id", request_id) + + if IS_STRUCTLOG_ENABLED: + WrappedDictClass = structlog.threadlocal.wrap_dict(dict) + wrapped_request_id = WrappedDictClass({ + "request_id": request_id + }) + structlog.configure(context_class=WrappedDictClass) + + return self.handler(request) diff --git a/pyramid_heroku/tests/__init__.py b/pyramid_heroku/tests/__init__.py index e69de29..69cc928 100644 --- a/pyramid_heroku/tests/__init__.py +++ b/pyramid_heroku/tests/__init__.py @@ -0,0 +1,9 @@ +import unittest + +from .test_herokuapp_access import TestHerokuappAccessTween +from .test_migrate import TestHerokuMigrate +from .test_request_id import TestRequestIDLogger +from .test_utils import test_expandvars_dict, test_safe_eval + +if __name__ == "__main__": + unittest.main() diff --git a/pyramid_heroku/tests/test_request_id.py b/pyramid_heroku/tests/test_request_id.py new file mode 100644 index 0000000..5796f0c --- /dev/null +++ b/pyramid_heroku/tests/test_request_id.py @@ -0,0 +1,92 @@ +"""Tests for RequestIDLogger tween""" + +from contextlib import contextmanager +from pyramid import request +from pyramid import testing + +import unittest +from unittest import mock +import structlog +import sys + + +SENTRY_TAGS = {} + +class MockScope(object): + + def __init__(self): + # reset the tags for every new test + SENTRY_TAGS = {} + + def set_tag(self, key, value): + SENTRY_TAGS[key] = value + + +class MockSentrySDK: + @classmethod + def configure_scope(cls): + @contextmanager + def inner(): + yield MockScope() + return inner() + + +sys.modules['sentry_sdk'] = MockSentrySDK + + +class TestRequestIDLogger(unittest.TestCase): + def setUp(self): + self.config = testing.setUp() + self.request = request.Request({}) + + self.handler = mock.Mock() + self.registry = None + + self.request_id = "some-random-requestid" + + def tearDown(self): + testing.tearDown() + + def test_request_id_in_sentry(self): + from pyramid_heroku.request_id import RequestIDLogger + + self.request.headers["X-Request-ID"] = self.request_id + RequestIDLogger(self.handler, self.registry)(self.request) + self.handler.assert_called_with(self.request) + self.assertEqual(SENTRY_TAGS, {"request_id": self.request_id}) + + def test_request_id_in_structlog(self): + structlog.reset_defaults() + from pyramid_heroku.request_id import RequestIDLogger + + context_class = structlog.get_config().get('context_class') + self.assertEqual(context_class, dict) + + self.request.headers["X-Request-ID"] = self.request_id + RequestIDLogger(self.handler, self.registry)(self.request) + self.handler.assert_called_with(self.request) + + context_class = structlog.get_config().get('context_class') + self.assertEqual( + context_class._tl.dict_, {"request_id": self.request_id} + ) + + def test_no_request_id_in_sentry(self): + from pyramid_heroku.request_id import RequestIDLogger + + RequestIDLogger(self.handler, self.registry)(self.request) + self.handler.assert_called_with(self.request) + self.assertEqual(SENTRY_TAGS, {}) + + def test_no_request_id_in_structlog(self): + structlog.reset_defaults() + from pyramid_heroku.request_id import RequestIDLogger + + context_class = structlog.get_config().get('context_class') + self.assertEqual(context_class, dict) + + RequestIDLogger(self.handler, self.registry)(self.request) + self.handler.assert_called_with(self.request) + + context_class = structlog.get_config().get('context_class') + self.assertEqual(context_class, dict) From dd7140c59c27b55a71098b46f156a1e65d86a3d1 Mon Sep 17 00:00:00 2001 From: Sourya Vatsyayan Date: Tue, 10 Sep 2019 22:38:11 +0530 Subject: [PATCH 2/3] Use sentry_sdk instead of mocked sentry Mocking module imports doesn't go along well with pytest. sys.modules doesn't remain the same throughout. Besides, the previous implementation used global vars in tests, which is not really recommended. Signed-off-by: Sourya Vatsyayan --- Pipfile | 1 + Pipfile.lock | 22 ++++++++++----- pyramid_heroku/request_id.py | 3 +- pyramid_heroku/tests/__init__.py | 8 ------ pyramid_heroku/tests/test_request_id.py | 37 +++++++------------------ 5 files changed, 27 insertions(+), 44 deletions(-) diff --git a/Pipfile b/Pipfile index ae44c5e..790579f 100644 --- a/Pipfile +++ b/Pipfile @@ -18,6 +18,7 @@ structlog = "*" black = "==18.9b0" mypy = "*" typecov = "*" +sentry-sdk = "*" [requires] python_version = "3.7" diff --git a/Pipfile.lock b/Pipfile.lock index 8c329a6..4870e09 100644 --- a/Pipfile.lock +++ b/Pipfile.lock @@ -1,7 +1,7 @@ { "_meta": { "hash": { - "sha256": "9d41fca0afc6d664be9f78ea1e57ed666e22ce109b1a06daf3a03b30b4874dfe" + "sha256": "19e6a5a41637c9c843a50c28b3e26e36d0e05ade2c58f5e2d623dc30d385e7e8" }, "pipfile-spec": 6, "requires": { @@ -268,11 +268,11 @@ }, "importlib-metadata": { "hashes": [ - "sha256:23d3d873e008a513952355379d93cbcab874c58f4f034ff657c7a87422fa64e8", - "sha256:80d2de76188eabfbfcf27e6a37342c2827801e59c4cc14b0371c56fed43820e3" + "sha256:0c505102757e7fa28b9f0958d8bc81301159dea16e2649858c92edc158b78a83", + "sha256:9a9f75ce32e78170905888acbf2376a81d3f21ecb3bb4867050413411d3ca7a9" ], "markers": "python_version < '3.8'", - "version": "==0.19" + "version": "==0.21" }, "mock": { "hashes": [ @@ -343,11 +343,11 @@ }, "pytest": { "hashes": [ - "sha256:95b1f6db806e5b1b5b443efeb58984c24945508f93a866c1719e1a507a957d7c", - "sha256:c3d5020755f70c82eceda3feaf556af9a341334414a8eca521a18f463bcead88" + "sha256:95d13143cc14174ca1a01ec68e84d76ba5d9d493ac02716fd9706c949a505210", + "sha256:b78fe2881323bd44fd9bd76e5317173d4316577e7b1cddebae9136a4495ec865" ], "index": "pypi", - "version": "==5.1.1" + "version": "==5.1.2" }, "requests": { "hashes": [ @@ -364,6 +364,14 @@ "index": "pypi", "version": "==0.10.6" }, + "sentry-sdk": { + "hashes": [ + "sha256:528f936118679e9a52dacb96bfefe20acb5d63e0797856c64a582cc3c2bc1f9e", + "sha256:b4edcb1296fee107439345d0f8b23432b8732b7e28407f928367d0a4a36301a9" + ], + "index": "pypi", + "version": "==0.11.2" + }, "six": { "hashes": [ "sha256:3350809f0555b11f552448330d0b52d5f24c91a322ea4a15ef22629740f3761c", diff --git a/pyramid_heroku/request_id.py b/pyramid_heroku/request_id.py index 427b735..ef04abe 100644 --- a/pyramid_heroku/request_id.py +++ b/pyramid_heroku/request_id.py @@ -2,7 +2,6 @@ if structlog is imported. """ - try: import sentry_sdk IS_SENTRY_ENABLED = True @@ -42,7 +41,7 @@ def __call__(self, request): if IS_STRUCTLOG_ENABLED: WrappedDictClass = structlog.threadlocal.wrap_dict(dict) - wrapped_request_id = WrappedDictClass({ + _ = WrappedDictClass({ "request_id": request_id }) structlog.configure(context_class=WrappedDictClass) diff --git a/pyramid_heroku/tests/__init__.py b/pyramid_heroku/tests/__init__.py index 69cc928..8b13789 100644 --- a/pyramid_heroku/tests/__init__.py +++ b/pyramid_heroku/tests/__init__.py @@ -1,9 +1 @@ -import unittest -from .test_herokuapp_access import TestHerokuappAccessTween -from .test_migrate import TestHerokuMigrate -from .test_request_id import TestRequestIDLogger -from .test_utils import test_expandvars_dict, test_safe_eval - -if __name__ == "__main__": - unittest.main() diff --git a/pyramid_heroku/tests/test_request_id.py b/pyramid_heroku/tests/test_request_id.py index 5796f0c..14283c2 100644 --- a/pyramid_heroku/tests/test_request_id.py +++ b/pyramid_heroku/tests/test_request_id.py @@ -7,31 +7,7 @@ import unittest from unittest import mock import structlog -import sys - - -SENTRY_TAGS = {} - -class MockScope(object): - - def __init__(self): - # reset the tags for every new test - SENTRY_TAGS = {} - - def set_tag(self, key, value): - SENTRY_TAGS[key] = value - - -class MockSentrySDK: - @classmethod - def configure_scope(cls): - @contextmanager - def inner(): - yield MockScope() - return inner() - - -sys.modules['sentry_sdk'] = MockSentrySDK +import sentry_sdk class TestRequestIDLogger(unittest.TestCase): @@ -44,16 +20,22 @@ def setUp(self): self.request_id = "some-random-requestid" + self.some_random_dsn = "https://some@random.dsn/12345" + def tearDown(self): testing.tearDown() def test_request_id_in_sentry(self): + sentry_sdk.init(self.some_random_dsn) from pyramid_heroku.request_id import RequestIDLogger self.request.headers["X-Request-ID"] = self.request_id RequestIDLogger(self.handler, self.registry)(self.request) self.handler.assert_called_with(self.request) - self.assertEqual(SENTRY_TAGS, {"request_id": self.request_id}) + self.assertEqual( + sentry_sdk.Hub.current._stack[-1][1]._tags, + {"request_id": self.request_id} + ) def test_request_id_in_structlog(self): structlog.reset_defaults() @@ -72,11 +54,12 @@ def test_request_id_in_structlog(self): ) def test_no_request_id_in_sentry(self): + sentry_sdk.init(self.some_random_dsn) from pyramid_heroku.request_id import RequestIDLogger RequestIDLogger(self.handler, self.registry)(self.request) self.handler.assert_called_with(self.request) - self.assertEqual(SENTRY_TAGS, {}) + self.assertEqual(sentry_sdk.Hub.current._stack[-1][1]._tags, {}) def test_no_request_id_in_structlog(self): structlog.reset_defaults() From a4448a9ab7b3d581378e714534548b5b56e0afad Mon Sep 17 00:00:00 2001 From: Sourya Vatsyayan Date: Thu, 12 Sep 2019 21:51:38 +0530 Subject: [PATCH 3/3] Conditionally remove sentry_sdk and structlog in tests This brings up test coverage to 100%. B-) Also, add type hints in some functions and the global vars. Signed-off-by: Sourya Vatsyayan --- pyramid_heroku/request_id.py | 39 +++++++++----- pyramid_heroku/tests/test_request_id.py | 69 ++++++++++++++++++++----- 2 files changed, 82 insertions(+), 26 deletions(-) diff --git a/pyramid_heroku/request_id.py b/pyramid_heroku/request_id.py index ef04abe..90b06e3 100644 --- a/pyramid_heroku/request_id.py +++ b/pyramid_heroku/request_id.py @@ -2,17 +2,22 @@ if structlog is imported. """ +IS_SENTRY_INSTALLED: bool +IS_STRUCTLOG_INSTALLED: bool + try: import sentry_sdk - IS_SENTRY_ENABLED = True + + IS_SENTRY_INSTALLED = True except ImportError: - IS_SENTRY_ENABLED = False + IS_SENTRY_INSTALLED = False try: import structlog - IS_STRUCTLOG_ENABLED = True + + IS_STRUCTLOG_INSTALLED = True except ImportError: - IS_STRUCTLOG_ENABLED = False + IS_STRUCTLOG_INSTALLED = False def includeme(config): @@ -34,16 +39,22 @@ def __init__(self, handler, _): def __call__(self, request): request_id = request.headers.get("X-Request-ID") - if request_id is not None: - if IS_SENTRY_ENABLED: - with sentry_sdk.configure_scope() as scope: - scope.set_tag("request_id", request_id) + if request_id is None: + return self.handler(request) - if IS_STRUCTLOG_ENABLED: - WrappedDictClass = structlog.threadlocal.wrap_dict(dict) - _ = WrappedDictClass({ - "request_id": request_id - }) - structlog.configure(context_class=WrappedDictClass) + if IS_SENTRY_INSTALLED: + self.set_sentry_scope(request_id) + + if IS_STRUCTLOG_INSTALLED: + self.set_structlog_context(request_id) return self.handler(request) + + def set_sentry_scope(self, request_id: int) -> None: + with sentry_sdk.configure_scope() as scope: + scope.set_tag("request_id", request_id) + + def set_structlog_context(self, request_id: int) -> None: + WrappedDictClass = structlog.threadlocal.wrap_dict(dict) + _ = WrappedDictClass({"request_id": request_id}) + structlog.configure(context_class=WrappedDictClass) diff --git a/pyramid_heroku/tests/test_request_id.py b/pyramid_heroku/tests/test_request_id.py index 14283c2..6f70a22 100644 --- a/pyramid_heroku/tests/test_request_id.py +++ b/pyramid_heroku/tests/test_request_id.py @@ -1,13 +1,14 @@ """Tests for RequestIDLogger tween""" -from contextlib import contextmanager from pyramid import request from pyramid import testing +from importlib import reload import unittest from unittest import mock import structlog import sentry_sdk +import sys class TestRequestIDLogger(unittest.TestCase): @@ -26,6 +27,7 @@ def tearDown(self): testing.tearDown() def test_request_id_in_sentry(self): + sentry_sdk.Hub.current._stack[-1][1].clear() sentry_sdk.init(self.some_random_dsn) from pyramid_heroku.request_id import RequestIDLogger @@ -33,27 +35,25 @@ def test_request_id_in_sentry(self): RequestIDLogger(self.handler, self.registry)(self.request) self.handler.assert_called_with(self.request) self.assertEqual( - sentry_sdk.Hub.current._stack[-1][1]._tags, - {"request_id": self.request_id} + sentry_sdk.Hub.current._stack[-1][1]._tags, {"request_id": self.request_id} ) def test_request_id_in_structlog(self): structlog.reset_defaults() from pyramid_heroku.request_id import RequestIDLogger - context_class = structlog.get_config().get('context_class') + context_class = structlog.get_config().get("context_class") self.assertEqual(context_class, dict) self.request.headers["X-Request-ID"] = self.request_id RequestIDLogger(self.handler, self.registry)(self.request) self.handler.assert_called_with(self.request) - context_class = structlog.get_config().get('context_class') - self.assertEqual( - context_class._tl.dict_, {"request_id": self.request_id} - ) + context_class = structlog.get_config().get("context_class") + self.assertEqual(context_class._tl.dict_, {"request_id": self.request_id}) - def test_no_request_id_in_sentry(self): + def test_request_id_not_in_header_sentry(self): + sentry_sdk.Hub.current._stack[-1][1].clear() sentry_sdk.init(self.some_random_dsn) from pyramid_heroku.request_id import RequestIDLogger @@ -61,15 +61,60 @@ def test_no_request_id_in_sentry(self): self.handler.assert_called_with(self.request) self.assertEqual(sentry_sdk.Hub.current._stack[-1][1]._tags, {}) - def test_no_request_id_in_structlog(self): + def test_request_id_not_in_header_structlog(self): structlog.reset_defaults() from pyramid_heroku.request_id import RequestIDLogger - context_class = structlog.get_config().get('context_class') + context_class = structlog.get_config().get("context_class") self.assertEqual(context_class, dict) RequestIDLogger(self.handler, self.registry)(self.request) self.handler.assert_called_with(self.request) - context_class = structlog.get_config().get('context_class') + context_class = structlog.get_config().get("context_class") self.assertEqual(context_class, dict) + + def test_smooth_run_without_sentry(self): + + structlog.reset_defaults() + + # remove sentry_sdk from modules to disable its import, + # in order to cover the code that runs without sentry + from pyramid_heroku import request_id + + sys.modules["sentry_sdk"] = None + reload(request_id) + + self.request.headers["X-Request-ID"] = self.request_id + request_id.RequestIDLogger(self.handler, self.registry)(self.request) + self.handler.assert_called_with(self.request) + + # structlog is still there + context_class = structlog.get_config().get("context_class") + self.assertEqual(context_class._tl.dict_, {"request_id": self.request_id}) + + # revert sys.modules to its original state + sys.modules["sentry_sdk"] = sentry_sdk + + def test_smooth_run_without_structlog(self): + sentry_sdk.Hub.current._stack[-1][1].clear() + sentry_sdk.init(self.some_random_dsn) + + # remove structlog from modules to disable its import, + # in order to cover the code that runs without structlog + from pyramid_heroku import request_id + + sys.modules["structlog"] = None + reload(request_id) + + from pyramid_heroku import request_id + + self.request.headers["X-Request-ID"] = self.request_id + request_id.RequestIDLogger(self.handler, self.registry)(self.request) + self.handler.assert_called_with(self.request) + self.assertEqual( + sentry_sdk.Hub.current._stack[-1][1]._tags, {"request_id": self.request_id} + ) + + # revert sys.modules to its original state + sys.modules["structlog"] = structlog