diff --git a/extension/reviewbotext/compat/__init__.py b/extension/reviewbotext/compat/__init__.py new file mode 100644 index 0000000000000000000000000000000000000000..cbfc91a36477212f8469a5c2b1898fdc56a5d552 --- /dev/null +++ b/extension/reviewbotext/compat/__init__.py @@ -0,0 +1,5 @@ +"""Compatibility modules for Review Board and Djblets. + +Version Added: + 4.0.1 +""" diff --git a/extension/reviewbotext/compat/logs.py b/extension/reviewbotext/compat/logs.py new file mode 100644 index 0000000000000000000000000000000000000000..08bbbc9f58c15721965b992c1b832c53d7c4d55d --- /dev/null +++ b/extension/reviewbotext/compat/logs.py @@ -0,0 +1,299 @@ +"""Compatibility logging code for modern versions of Review Board. + +Version Added: + 4.0.1 +""" + +from __future__ import annotations + +from typing import TYPE_CHECKING + +from djblets.log import (TimedLogInfo as DjbletsTimedLogInfo, + log_timed as djblets_log_timed) + +if TYPE_CHECKING or hasattr(DjbletsTimedLogInfo, '__enter__'): + TimedLogInfo = DjbletsTimedLogInfo + log_timed = djblets_log_timed +else: + import logging + from datetime import UTC, datetime + from typing import Literal, Mapping, Optional + from uuid import uuid4 + + if TYPE_CHECKING: + from django.http import HttpRequest + + class TimedLogInfo(DjbletsTimedLogInfo): + """Tracks the time between operations for logging purposes. + + This is created and returned by :py:func:`log_timed` to track how long + an operation takes, warning or critical-erroring if it takes too long. + + This class is a backport compatibility class for + :py:class:`djblets.log.TimedLogInfo`. It will be removed when + Djblets 5.3 is the minimum version required for Integrations. + + Version Added: + 4.0.1 + """ + + ###################### + # Instance variables # + ###################### + + #: Extra information to include with all log items. + #: + #: This will be populated with ``request``. + #: + #: Version Added: + #: 5.3 + extra: Mapping[str, object] + + #: The logger used for all log entries. + #: + #: Version Added: + #: 5.3 + logger: logging.Logger + + #: The trace ID to include in log messages. + #: + #: This is used to help follow the chain of events in a series of logs. + #: + #: Version Added: + #: 5.3 + trace_id: str + + def __init__( + self, + *, + message: str, + warning_at: float, + critical_at: float, + default_level: int, + log_beginning: bool, + request: Optional[HttpRequest], + extra: Mapping[str, object] = {}, + logger: Optional[logging.Logger] = None, + trace_id: Optional[str] = None, + ) -> None: + """Initialize the state for the timer. + + Args: + message (str): + The message to show for the log entries., + + warning_at (float): + The number of seconds at which to log warnings. + + This may contain fractions of seconds. + + critical_at (float): + The number of seconds at which to log critical errors. + + This may contain fractions of seconds. + + default_level (int): + The default log level for the timing information. + + log_beginning (bool): + Whether to log the beginning time for the operation. + + request (django.http.HttpRequest, optional): + The optional HTTP request associated with the operation. + + extra (dict, optional): + Extra information to include with all log items. + + This will be populated with ``request`` and ``trace_id``. + + logger (logging.Logger, optional): + The logger used for all log entries. + + trace_id (str, optional): + The trace ID to include in log messages. + + This is used to help follow the chain of events in a + series of logs. + """ + self.message = message + self.warning_at = warning_at + self.critical_at = critical_at + self.default_level = default_level + self.start_time = datetime.now(UTC) + self.request = request + + if logger is None: + logger = logging.getLogger() + + if not trace_id: + trace_id = str(uuid4()) + + extra = { + **extra, + 'request': self.request, + 'trace_id': trace_id, + } + + self.extra = extra + self.logger = logger + self.trace_id = trace_id + + if log_beginning: + logger.log(default_level, + f'[%s] Begin: {message}', + trace_id, + extra=extra) + + def __enter__(self) -> TimedLogInfo: + """Enter the context for the timer. + + This will open the context and return itself, allowing the timer + to automatically complete when the context ends. + + Context: + TimedLogInfo: + This object. + """ + return self + + def __exit__(self, *args, **kwargs) -> Literal[False]: + """Exit the context for the timer. + + This will log the end time of the operation, stopping the timer. + + Args: + *args (tuple, unused): + Unused positional arguments. + + **kwargs (dict, unused): + Unused keyword arguments. + """ + self.done() + + return False + + def done(self) -> None: + """Stop the timed logging operation. + + The resulting time of the operation will be written to the log + file. The log level depends on how long the operation takes. + """ + delta = datetime.now(UTC) - self.start_time + level = self.default_level + logger = self.logger + message = self.message + extra = self.extra + trace_id = self.trace_id + total_seconds = delta.total_seconds() + + if total_seconds >= self.critical_at: + level = logging.CRITICAL + elif total_seconds >= self.warning_at: + level = logging.WARNING + + logger.log(self.default_level, + f'[%s] End: {message}', + trace_id, + extra=extra) + logger.log(level, + f'[%s] {message} took %d.%06d seconds', + trace_id, + delta.seconds, + delta.microseconds, + extra=extra) + + def log_timed( + message: str, + *, + warning_at: float = 5, + critical_at: float = 15, + log_beginning: bool = True, + default_level: int = logging.DEBUG, + request: Optional[HttpRequest] = None, + extra: Mapping[str, object] = {}, + logger: Optional[logging.Logger] = None, + trace_id: Optional[str] = None, + ) -> TimedLogInfo: + """Times an operation, logging timing information. + + This will display a log message at the start of an operation and at the + end, displaying the time taken for the operation. The final log entry's + level will depend on the amount of time taken, switching to a warning + if at ``warning_at`` seconds and a critical error at ``critical_at`` + seconds. + + This function can be called directly or used as a context manager. + + This class is a backport compatibility class for + :py:class:`djblets.log.TimedLogInfo`. It will be removed when + Djblets 5.3 is the minimum version required for Integrations. + + Version Added: + 4.0.1 + + Args: + message (str): + The message to show for the log entries., + + warning_at (int): + The number of seconds at which to log warnings. + + This may contain fractions of seconds. + + critical_at (int): + The number of seconds at which to log critical errors. + + This may contain fractions of seconds. + + default_level (int): + The default log level for the timing information. + + log_beginning (bool): + Whether to log the beginning time for the operation. + + request (django.http.HttpRequest, optional): + The optional HTTP request associated with the operation. + + extra (dict, optional): + Extra information to include with all log items. + + This will be populated with ``request`` and ``trace_id``. + + logger (logging.Logger, optional): + The logger used for all log entries. + + trace_id (str, optional): + The trace ID to include in log messages. + + This is used to help follow the chain of events in a series of + logs. + + If not provided, one will be generated. This can then be + accessed on :py:attr:`TimedLogInfo.trace_id`. + + Example: + .. code-block:: python + + from djblets.log import log_timed + + # As a direct function call: + t = log_timed('Doing a thing') + + try: + ... + finally: + t.done() + + # As a context manager: + with log_timed('Doing a thing') as t: + ... + """ + return TimedLogInfo(message=message, + warning_at=warning_at, + critical_at=critical_at, + default_level=default_level, + log_beginning=log_beginning, + request=request, + extra=extra, + logger=logger, + trace_id=trace_id) diff --git a/extension/reviewbotext/extension.py b/extension/reviewbotext/extension.py index baf9903c45932b9e72508079d6b9c220606f7b85..d1857a15c85321c0a748dacf87ca08ebcb9b0974 100644 --- a/extension/reviewbotext/extension.py +++ b/extension/reviewbotext/extension.py @@ -1,3 +1,8 @@ +"""Main extension for Review Bot.""" + +from __future__ import annotations + +import logging from importlib import import_module from celery import Celery, VERSION as CELERY_VERSION @@ -12,11 +17,15 @@ from reviewboard.admin.server import get_server_url from reviewboard.extensions.base import Extension from reviewboard.extensions.hooks import IntegrationHook +from reviewbotext.compat.logs import log_timed from reviewbotext.integration import ReviewBotIntegration from reviewbotext.resources import (review_bot_review_resource, tool_resource) +logger = logging.getLogger(__name__) + + class ReviewBotExtension(Extension): """An extension for communicating with Review Bot.""" @@ -140,4 +149,8 @@ class ReviewBotExtension(Extension): 'session': self.login_user(), 'url': get_server_url(), } - self.celery.control.broadcast('update_tools_list', payload=payload) + + with log_timed('Refreshing Review Bot tools list', + logger=logger): + self.celery.control.broadcast('update_tools_list', + payload=payload) diff --git a/extension/reviewbotext/integration.py b/extension/reviewbotext/integration.py index 70bba2333b5945adae952c7d24e88f1fd2315481..0a900f5d92105d177392043a4d2bcc82f47dc438 100644 --- a/extension/reviewbotext/integration.py +++ b/extension/reviewbotext/integration.py @@ -1,3 +1,7 @@ +"""Main integration support for Review Bot.""" + +from __future__ import annotations + import json import logging from datetime import datetime @@ -11,10 +15,14 @@ from reviewboard.integrations.base import Integration from reviewboard.reviews.models import StatusUpdate from reviewboard.reviews.signals import review_request_published +from reviewbotext.compat.logs import log_timed from reviewbotext.forms import ReviewBotConfigForm from reviewbotext.models import Tool +logger = logging.getLogger(__name__) + + class ReviewBotIntegration(Integration): """The integration for Review Bot. @@ -92,9 +100,9 @@ class ReviewBotIntegration(Integration): try: tool = Tool.objects.get(pk=tool_id) except Tool.DoesNotExist: - logging.error('Skipping Review Bot integration config %s (%d) ' - 'because Tool with pk=%d does not exist.', - config.name, config.pk, tool_id) + logger.error('Skipping Review Bot integration config %s (%d) ' + 'because Tool with pk=%d does not exist.', + config.name, config.pk, tool_id) review_settings = { 'max_comments': config.settings.get( @@ -115,9 +123,9 @@ class ReviewBotIntegration(Integration): tool_options = json.loads( config.settings.get('tool_options', '{}')) except Exception as e: - logging.exception('Failed to parse tool_options for Review ' - 'Bot integration config %s (%d): %s', - config.name, config.pk, e) + logger.exception('Failed to parse tool_options for Review ' + 'Bot integration config %s (%d): %s', + config.name, config.pk, e) tool_options = {} yield config, tool, tool_options, review_settings @@ -200,21 +208,27 @@ class ReviewBotIntegration(Integration): if tool.working_directory_required: queue = '%s.%s' % (queue, repository.name) - extension.celery.send_task( - 'reviewbot.tasks.RunTool', - kwargs={ - 'server_url': server_url, - 'session': session, - 'username': user.username, - 'review_request_id': review_request_id, - 'diff_revision': diffset.revision, - 'status_update_id': status_update.pk, - 'review_settings': review_settings, - 'tool_options': tool_options, - 'repository_name': repository.name, - 'base_commit_id': diffset.base_commit_id, - }, - queue=queue) + with log_timed(f'Sending automatic run task to Review Bot ' + f'queue {queue} for review request ' + f'{review_request.pk}, diff revision ' + f'{diffset.revision}, status update ID ' + f'{status_update.pk}', + logger=logger): + extension.celery.send_task( + 'reviewbot.tasks.RunTool', + kwargs={ + 'server_url': server_url, + 'session': session, + 'username': user.username, + 'review_request_id': review_request_id, + 'diff_revision': diffset.revision, + 'status_update_id': status_update.pk, + 'review_settings': review_settings, + 'tool_options': tool_options, + 'repository_name': repository.name, + 'base_commit_id': diffset.base_commit_id, + }, + queue=queue) def _drop_old_issues(self, user, service_id, review_request): """Drop old issues associated with the given tool config. @@ -307,23 +321,28 @@ class ReviewBotIntegration(Integration): diffset = DiffSet.objects.filter( history=review_request.diffset_history_id).earliest() except DiffSet.DoesNotExist: - logging.error('Unable to determine diffset when running ' - 'Review Bot tool for status update %d', - status_update.pk) + logger.error('Unable to determine diffset when running ' + 'Review Bot tool for status update %d', + status_update.pk) return - extension.celery.send_task( - 'reviewbot.tasks.RunTool', - kwargs={ - 'server_url': server_url, - 'session': session, - 'username': user.username, - 'review_request_id': review_request.get_display_id(), - 'diff_revision': diffset.revision, - 'status_update_id': status_update.pk, - 'review_settings': review_settings, - 'tool_options': tool_options, - 'repository_name': repository.name, - 'base_commit_id': diffset.base_commit_id, - }, - queue=queue) + with log_timed(f'Sending manual run task to Review Bot queue {queue} ' + f'for review request {review_request.pk}, ' + f'diff revision {diffset.revision}, ' + f'status update ID {status_update.pk}', + logger=logger): + extension.celery.send_task( + 'reviewbot.tasks.RunTool', + kwargs={ + 'server_url': server_url, + 'session': session, + 'username': user.username, + 'review_request_id': review_request.get_display_id(), + 'diff_revision': diffset.revision, + 'status_update_id': status_update.pk, + 'review_settings': review_settings, + 'tool_options': tool_options, + 'repository_name': repository.name, + 'base_commit_id': diffset.base_commit_id, + }, + queue=queue) diff --git a/extension/reviewbotext/views.py b/extension/reviewbotext/views.py index 6426e5846219ba82a1f5204171fae04b242e5b04..9b533898a0f28be46b2e7d86d940d55309864a1f 100644 --- a/extension/reviewbotext/views.py +++ b/extension/reviewbotext/views.py @@ -1,3 +1,8 @@ +"""Views for managing Review Bot.""" + +from __future__ import annotations + +import logging import json from django.contrib.auth.models import User @@ -5,7 +10,7 @@ from django.db import IntegrityError, transaction from django.http import (HttpResponse, HttpResponseBadRequest, HttpResponseForbidden) -from django.shortcuts import get_object_or_404, render +from django.shortcuts import get_object_or_404 from django.views.generic import TemplateView, View from djblets.avatars.services import URLAvatarService from djblets.db.query import get_object_or_none @@ -14,9 +19,13 @@ from reviewboard.admin.server import get_server_url from reviewboard.avatars import avatar_services from reviewboard.site.urlresolvers import local_site_reverse +from reviewbotext.compat.logs import log_timed from reviewbotext.extension import ReviewBotExtension +logger = logging.getLogger(__name__) + + def _serialize_user(request, user): """Serialize a user into a JSON-encodable format. @@ -273,10 +282,14 @@ class WorkerStatusView(View): 'session': extension.login_user(), 'url': get_server_url(), } - reply = extension.celery.control.broadcast('update_tools_list', - payload=payload, - reply=True, - timeout=10) + + with log_timed('Fetching Review Bot worker status', + logger=logger): + reply = extension.celery.control.broadcast( + 'update_tools_list', + payload=payload, + reply=True, + timeout=10) state = 'success' error = None