From f266b207df48d0c46c32b99f4ea7532219ad4b13 Mon Sep 17 00:00:00 2001 From: Kiran Jonnalagadda Date: Fri, 28 Jul 2023 15:58:55 +0530 Subject: [PATCH 1/5] Log template rendering time to statsd --- pyproject.toml | 1 - src/baseframe/statsd.py | 74 ++++++++++++++++++++++++---- tests/baseframe_tests/statsd_test.py | 54 +++++++++++++++++++- 3 files changed, 117 insertions(+), 12 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 5665b583..40a54299 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -123,7 +123,6 @@ sections = [ [tool.mypy] files = '**/*.py' exclude = 'node_modules' -plugins = ['sqlalchemy.ext.mypy.plugin'] ignore_missing_imports = true show_error_codes = true warn_unreachable = true diff --git a/src/baseframe/statsd.py b/src/baseframe/statsd.py index ed31d797..b1fd9e72 100644 --- a/src/baseframe/statsd.py +++ b/src/baseframe/statsd.py @@ -4,8 +4,18 @@ import typing as t from datetime import timedelta -from flask import Flask, current_app, request, request_finished, request_started +from flask import ( + Flask, + before_render_template, + current_app, + g, + request, + request_finished, + request_started, + template_rendered, +) from flask_wtf import FlaskForm +from jinja2 import Template from statsd import StatsClient from statsd.client.timer import Timer from statsd.client.udp import Pipeline @@ -15,7 +25,8 @@ __all__ = ['Statsd'] -START_TIME_ATTR = 'statsd_start_time' +REQUEST_START_TIME_ATTR = 'statsd_request_start_time' +TEMPLATE_START_TIME_ATTR = 'statsd_template_start_time' TagsType = t.Dict[str, t.Union[int, str, None]] @@ -41,6 +52,7 @@ class Statsd: STATSD_RATE = 1 STATSD_TAGS = False STATSD_REQUEST_LOG = True + STATSD_RENDERTEMPLATE_LOG = True STATSD_FORM_LOG = True If the statsd server supports tags, the ``STATSD_TAGS`` parameter may be set to a @@ -92,6 +104,11 @@ def init_app(self, app: Flask) -> None: request_started.connect(self._request_started, app) request_finished.connect(self._request_finished, app) + if app.config.setdefault('STATSD_RENDERTEMPLATE_LOG', True): + # Flask's render_template also sends before and after signals + before_render_template.connect(self._before_render_template, app) + template_rendered.connect(self._template_rendered, app) + def _metric_name(self, name: str, tags: t.Optional[TagsType] = None) -> str: if tags is None: tags = {} @@ -209,10 +226,11 @@ def pipeline(self) -> Pipeline: def _request_started(self, app: Flask) -> None: if app.config['STATSD_RATE'] != 0: - setattr(request, START_TIME_ATTR, time.time()) + setattr(g, REQUEST_START_TIME_ATTR, time.time()) def _request_finished(self, app: Flask, response: Response) -> None: - if hasattr(request, START_TIME_ATTR): + if hasattr(g, REQUEST_START_TIME_ATTR): + start_time = getattr(g, REQUEST_START_TIME_ATTR) metrics = [ ( 'request_handlers', @@ -226,20 +244,56 @@ def _request_finished(self, app: Flask, response: Response) -> None: {'endpoint': '_overall', 'status_code': response.status_code}, ) ) - + duration = int((time.time() - start_time) * 1000) for metric_name, tags in metrics: # Use `timing` instead of `timer` because we record it as two metrics. # Convert time from seconds:float to milliseconds:int - self.timing( - metric_name, - int((time.time() - getattr(request, START_TIME_ATTR)) * 1000), - tags=tags, - ) + self.timing(metric_name, duration, tags=tags) # The timer metric also registers a count, making the counter metric # seemingly redundant, but the counter metric also includes a rate, so # we use both: timer (via `timing`) and counter (via `incr`). self.incr(metric_name, tags=tags) + def _before_render_template(self, app: Flask, template: Template, **kwargs) -> None: + if app.config['STATSD_RATE'] != 0: + if not hasattr(g, TEMPLATE_START_TIME_ATTR): + setattr(g, TEMPLATE_START_TIME_ATTR, {}) + getattr(g, TEMPLATE_START_TIME_ATTR)[template] = time.time() + + def _template_rendered(self, app: Flask, template: Template, **kwargs) -> None: + start_time = getattr(g, TEMPLATE_START_TIME_ATTR, {}).get(template) + if not start_time: + current_app.logger.warning( + "flask.template_rendered signal was called with template %s but" + " flask.before_render_template was not called first", + template, + ) + return + + metrics: t.List[t.Tuple[str, t.Dict[str, t.Optional[t.Union[int, str]]]]] = [ + ( + 'render_template', + {'template': template.name or '_str'}, + ) + ] + if not app.config['STATSD_TAGS']: + metrics.append( + ( + 'render_template', + {'template': '_overall'}, + ) + ) + + duration = int((time.time() - start_time) * 1000) + for metric_name, tags in metrics: + # Use `timing` instead of `timer` because we record it as two metrics. + # Convert time from seconds:float to milliseconds:int + self.timing(metric_name, duration, tags=tags) + # The timer metric also registers a count, making the counter metric + # seemingly redundant, but the counter metric also includes a rate, so + # we use both: timer (via `timing`) and counter (via `incr`). + self.incr(metric_name, tags=tags) + @form_validation_success.connect def _statsd_form_validation_success(form: FlaskForm) -> None: diff --git a/tests/baseframe_tests/statsd_test.py b/tests/baseframe_tests/statsd_test.py index dc148ae6..6060204a 100644 --- a/tests/baseframe_tests/statsd_test.py +++ b/tests/baseframe_tests/statsd_test.py @@ -7,7 +7,7 @@ from unittest.mock import patch import pytest -from flask import Flask +from flask import Flask, render_template_string from flask_babel import Babel from statsd.client.timer import Timer from statsd.client.udp import Pipeline @@ -285,6 +285,58 @@ def test_request_handler_disabled(app, view) -> None: mock_timing.assert_not_called() +def test_render_template_notags(app, statsd) -> None: + with patch('statsd.StatsClient.incr') as mock_incr: + with patch('statsd.StatsClient.timing') as mock_timing: + with app.app_context(): + render_template_string("Test template") + assert mock_incr.call_count == 2 + assert mock_timing.call_count == 2 + assert [c.args[0] for c in mock_incr.call_args_list] == [ + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__str', + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__overall', + ] + assert [c.args[0] for c in mock_incr.call_args_list] == [ + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__str', + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__overall', + ] + + +def test_render_template_tags(app, statsd) -> None: + app.config['STATSD_TAGS'] = ',' + with patch('statsd.StatsClient.incr') as mock_incr: + with patch('statsd.StatsClient.timing') as mock_timing: + with app.app_context(): + render_template_string("Test template") + assert mock_incr.call_count == 1 + assert mock_timing.call_count == 1 + assert ( + mock_incr.call_args.args[0] + == 'flask_app.render_template,template=_str,' + 'app=baseframe_tests.statsd_test' + ) + assert ( + mock_incr.call_args.args[0] + == 'flask_app.render_template,template=_str,' + 'app=baseframe_tests.statsd_test' + ) + + +def test_render_template_disabled(app, view) -> None: + app.config['STATSD_RENDERTEMPLATE_LOG'] = False + Statsd(app) + with patch('statsd.StatsClient.incr') as mock_incr: + with patch('statsd.StatsClient.timing') as mock_timing: + with app.app_context(): + render_template_string("Test template") + mock_incr.assert_not_called() + mock_timing.assert_not_called() + + def test_form_success(ctx, app, statsd, form) -> None: app.config['STATSD_TAGS'] = ',' with patch('statsd.StatsClient.incr') as mock_incr: From 1e5b364b67d856ddd2b7dc666ecd82162809aa22 Mon Sep 17 00:00:00 2001 From: Kiran Jonnalagadda Date: Fri, 28 Jul 2023 16:07:39 +0530 Subject: [PATCH 2/5] Add docstrings, collapse with statements --- src/baseframe/statsd.py | 8 +- tests/baseframe_tests/statsd_test.py | 154 ++++++++++++++------------- 2 files changed, 84 insertions(+), 78 deletions(-) diff --git a/src/baseframe/statsd.py b/src/baseframe/statsd.py index b1fd9e72..232625b2 100644 --- a/src/baseframe/statsd.py +++ b/src/baseframe/statsd.py @@ -224,7 +224,8 @@ def set( # noqa: A003 def pipeline(self) -> Pipeline: return current_app.extensions['statsd_core'].pipeline() - def _request_started(self, app: Flask) -> None: + @staticmethod + def _request_started(app: Flask) -> None: if app.config['STATSD_RATE'] != 0: setattr(g, REQUEST_START_TIME_ATTR, time.time()) @@ -254,13 +255,16 @@ def _request_finished(self, app: Flask, response: Response) -> None: # we use both: timer (via `timing`) and counter (via `incr`). self.incr(metric_name, tags=tags) - def _before_render_template(self, app: Flask, template: Template, **kwargs) -> None: + @staticmethod + def _before_render_template(app: Flask, template: Template, **kwargs) -> None: + """Record start time when rendering a template.""" if app.config['STATSD_RATE'] != 0: if not hasattr(g, TEMPLATE_START_TIME_ATTR): setattr(g, TEMPLATE_START_TIME_ATTR, {}) getattr(g, TEMPLATE_START_TIME_ATTR)[template] = time.time() def _template_rendered(self, app: Flask, template: Template, **kwargs) -> None: + """Calculate time to render a template and log to statsd.""" start_time = getattr(g, TEMPLATE_START_TIME_ATTR, {}).get(template) if not start_time: current_app.logger.warning( diff --git a/tests/baseframe_tests/statsd_test.py b/tests/baseframe_tests/statsd_test.py index 6060204a..d04c7b6e 100644 --- a/tests/baseframe_tests/statsd_test.py +++ b/tests/baseframe_tests/statsd_test.py @@ -238,103 +238,105 @@ def test_tags(app, ctx, statsd) -> None: def test_request_handler_notags(app, statsd, view) -> None: - with patch('statsd.StatsClient.incr') as mock_incr: - with patch('statsd.StatsClient.timing') as mock_timing: - with app.test_client() as client: - client.get('/') - # First call - mock_incr.assert_any_call( - 'flask_app.baseframe_tests.statsd_test.request_handlers' - '.endpoint_index.status_code_200', - 1, - rate=1, - ) - # Second and last call - mock_incr.assert_called_with( - 'flask_app.baseframe_tests.statsd_test.request_handlers' - '.endpoint__overall.status_code_200', - 1, - rate=1, - ) - mock_timing.assert_called() + """Test request_handlers logging with tags disabled.""" + with patch('statsd.StatsClient.incr') as mock_incr, patch( + 'statsd.StatsClient.timing' + ) as mock_timing, app.test_client() as client: + client.get('/') + # First call + mock_incr.assert_any_call( + 'flask_app.baseframe_tests.statsd_test.request_handlers' + '.endpoint_index.status_code_200', + 1, + rate=1, + ) + # Second and last call + mock_incr.assert_called_with( + 'flask_app.baseframe_tests.statsd_test.request_handlers' + '.endpoint__overall.status_code_200', + 1, + rate=1, + ) + mock_timing.assert_called() def test_request_handler_tags(app, statsd, view) -> None: + """Test request_handlers logging with tags enabled.""" app.config['STATSD_TAGS'] = ',' - with patch('statsd.StatsClient.incr') as mock_incr: - with patch('statsd.StatsClient.timing') as mock_timing: - with app.test_client() as client: - client.get('/') - mock_incr.assert_called_once_with( - 'flask_app.request_handlers,endpoint=index,status_code=200' - ',app=baseframe_tests.statsd_test', - 1, - rate=1, - ) - mock_timing.assert_called_once() + with patch('statsd.StatsClient.incr') as mock_incr, patch( + 'statsd.StatsClient.timing' + ) as mock_timing, app.test_client() as client: + client.get('/') + mock_incr.assert_called_once_with( + 'flask_app.request_handlers,endpoint=index,status_code=200' + ',app=baseframe_tests.statsd_test', + 1, + rate=1, + ) + mock_timing.assert_called_once() def test_request_handler_disabled(app, view) -> None: + """Test request_handlers logging disabled.""" app.config['STATSD_REQUEST_LOG'] = False Statsd(app) - with patch('statsd.StatsClient.incr') as mock_incr: - with patch('statsd.StatsClient.timing') as mock_timing: - with app.test_client() as client: - client.get('/') - mock_incr.assert_not_called() - mock_timing.assert_not_called() + with patch('statsd.StatsClient.incr') as mock_incr, patch( + 'statsd.StatsClient.timing' + ) as mock_timing, app.test_client() as client: + client.get('/') + mock_incr.assert_not_called() + mock_timing.assert_not_called() def test_render_template_notags(app, statsd) -> None: - with patch('statsd.StatsClient.incr') as mock_incr: - with patch('statsd.StatsClient.timing') as mock_timing: - with app.app_context(): - render_template_string("Test template") - assert mock_incr.call_count == 2 - assert mock_timing.call_count == 2 - assert [c.args[0] for c in mock_incr.call_args_list] == [ - 'flask_app.baseframe_tests.statsd_test.render_template' - '.template__str', - 'flask_app.baseframe_tests.statsd_test.render_template' - '.template__overall', - ] - assert [c.args[0] for c in mock_incr.call_args_list] == [ - 'flask_app.baseframe_tests.statsd_test.render_template' - '.template__str', - 'flask_app.baseframe_tests.statsd_test.render_template' - '.template__overall', - ] + """Test render_template logging with tags disabled.""" + with patch('statsd.StatsClient.incr') as mock_incr, patch( + 'statsd.StatsClient.timing' + ) as mock_timing, app.app_context(): + render_template_string("Test template") + assert mock_incr.call_count == 2 + assert mock_timing.call_count == 2 + assert [c.args[0] for c in mock_incr.call_args_list] == [ + 'flask_app.baseframe_tests.statsd_test.render_template.template__str', + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__overall', + ] + assert [c.args[0] for c in mock_incr.call_args_list] == [ + 'flask_app.baseframe_tests.statsd_test.render_template.template__str', + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__overall', + ] def test_render_template_tags(app, statsd) -> None: + """Test render_template logging with tags enabled.""" app.config['STATSD_TAGS'] = ',' - with patch('statsd.StatsClient.incr') as mock_incr: - with patch('statsd.StatsClient.timing') as mock_timing: - with app.app_context(): - render_template_string("Test template") - assert mock_incr.call_count == 1 - assert mock_timing.call_count == 1 - assert ( - mock_incr.call_args.args[0] - == 'flask_app.render_template,template=_str,' - 'app=baseframe_tests.statsd_test' - ) - assert ( - mock_incr.call_args.args[0] - == 'flask_app.render_template,template=_str,' - 'app=baseframe_tests.statsd_test' - ) + with patch('statsd.StatsClient.incr') as mock_incr, patch( + 'statsd.StatsClient.timing' + ) as mock_timing, app.app_context(): + render_template_string("Test template") + assert mock_incr.call_count == 1 + assert mock_timing.call_count == 1 + assert ( + mock_incr.call_args.args[0] == 'flask_app.render_template,template=_str,' + 'app=baseframe_tests.statsd_test' + ) + assert ( + mock_incr.call_args.args[0] == 'flask_app.render_template,template=_str,' + 'app=baseframe_tests.statsd_test' + ) def test_render_template_disabled(app, view) -> None: + """Test render_template logging disabled.""" app.config['STATSD_RENDERTEMPLATE_LOG'] = False Statsd(app) - with patch('statsd.StatsClient.incr') as mock_incr: - with patch('statsd.StatsClient.timing') as mock_timing: - with app.app_context(): - render_template_string("Test template") - mock_incr.assert_not_called() - mock_timing.assert_not_called() + with patch('statsd.StatsClient.incr') as mock_incr, patch( + 'statsd.StatsClient.timing' + ) as mock_timing, app.app_context(): + render_template_string("Test template") + mock_incr.assert_not_called() + mock_timing.assert_not_called() def test_form_success(ctx, app, statsd, form) -> None: From 3768b3cc7442ba489eabbfdacdaed18d43e522b3 Mon Sep 17 00:00:00 2001 From: Kiran Jonnalagadda Date: Fri, 28 Jul 2023 16:11:34 +0530 Subject: [PATCH 3/5] Python 3.7 doesn't have call.args --- tests/baseframe_tests/statsd_test.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tests/baseframe_tests/statsd_test.py b/tests/baseframe_tests/statsd_test.py index d04c7b6e..a579b69e 100644 --- a/tests/baseframe_tests/statsd_test.py +++ b/tests/baseframe_tests/statsd_test.py @@ -296,12 +296,12 @@ def test_render_template_notags(app, statsd) -> None: render_template_string("Test template") assert mock_incr.call_count == 2 assert mock_timing.call_count == 2 - assert [c.args[0] for c in mock_incr.call_args_list] == [ + assert [c[0][0] for c in mock_incr.call_args_list] == [ 'flask_app.baseframe_tests.statsd_test.render_template.template__str', 'flask_app.baseframe_tests.statsd_test.render_template' '.template__overall', ] - assert [c.args[0] for c in mock_incr.call_args_list] == [ + assert [c[0][0] for c in mock_incr.call_args_list] == [ 'flask_app.baseframe_tests.statsd_test.render_template.template__str', 'flask_app.baseframe_tests.statsd_test.render_template' '.template__overall', @@ -318,11 +318,11 @@ def test_render_template_tags(app, statsd) -> None: assert mock_incr.call_count == 1 assert mock_timing.call_count == 1 assert ( - mock_incr.call_args.args[0] == 'flask_app.render_template,template=_str,' + mock_incr.call_args[0][0] == 'flask_app.render_template,template=_str,' 'app=baseframe_tests.statsd_test' ) assert ( - mock_incr.call_args.args[0] == 'flask_app.render_template,template=_str,' + mock_incr.call_args[0][0] == 'flask_app.render_template,template=_str,' 'app=baseframe_tests.statsd_test' ) From 75d51326df4e8d4c2e162b3eda16b68f615b2d0a Mon Sep 17 00:00:00 2001 From: Kiran Jonnalagadda Date: Fri, 28 Jul 2023 16:18:21 +0530 Subject: [PATCH 4/5] More docstrings --- src/baseframe/statsd.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/baseframe/statsd.py b/src/baseframe/statsd.py index 232625b2..2b9d7061 100644 --- a/src/baseframe/statsd.py +++ b/src/baseframe/statsd.py @@ -226,10 +226,12 @@ def pipeline(self) -> Pipeline: @staticmethod def _request_started(app: Flask) -> None: + """Record start time when serving a request.""" if app.config['STATSD_RATE'] != 0: setattr(g, REQUEST_START_TIME_ATTR, time.time()) def _request_finished(self, app: Flask, response: Response) -> None: + """Calculate time to render a response and log to statsd.""" if hasattr(g, REQUEST_START_TIME_ATTR): start_time = getattr(g, REQUEST_START_TIME_ATTR) metrics = [ From af7c31b96351703bf274e62af9f9910daafd41b8 Mon Sep 17 00:00:00 2001 From: Kiran Jonnalagadda Date: Fri, 28 Jul 2023 16:23:40 +0530 Subject: [PATCH 5/5] Drop obsolete `__order__` in LabeledEnum (unrelated to statsd) --- tests/baseframe_tests/forms/fields_test.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/tests/baseframe_tests/forms/fields_test.py b/tests/baseframe_tests/forms/fields_test.py index fc7fb3d7..dcda56a8 100644 --- a/tests/baseframe_tests/forms/fields_test.py +++ b/tests/baseframe_tests/forms/fields_test.py @@ -20,8 +20,6 @@ class MY_ENUM(LabeledEnum): # noqa: N801 SECOND = (2, 'second', "Second") THIRD = (3, 'third', "Third") - __order__ = (FIRST, SECOND, THIRD) - DEFAULT_JSONDATA = {'key': "val"}