diff --git a/docbot/app.py b/docbot/app.py index 5b708f3..fe020b7 100644 --- a/docbot/app.py +++ b/docbot/app.py @@ -1,8 +1,16 @@ +import logging + from elasticapm.contrib.flask import ElasticAPM from prometheus_flask_exporter import PrometheusMetrics from flask import Flask, request from .handlers import webhook_handler, list_events_handler +from .logging_config import LOGGING_CONFIG + + +logging.config.dictConfig(LOGGING_CONFIG) + +log = logging.getLogger(__name__) app = Flask(__name__) @@ -10,7 +18,7 @@ app.config['ELASTIC_APM'] = { 'SERVICE_NAME': 'docbot', } -apm = ElasticAPM(app) +apm = ElasticAPM(app, logging=True) metrics = PrometheusMetrics(app) @@ -28,4 +36,8 @@ def index() -> str: def webhook() -> str: data: dict = request.json event: str = request.headers.get('X-GitHub-Event') - return webhook_handler(data, event) + extra = { + 'X-GitHub-Delivery': request.headers.get('X-GitHub-Delivery') + } + log.info('Accepted webhook from GitHub service', extra=extra) + return webhook_handler(data, event, extra) diff --git a/docbot/github.py b/docbot/github.py index 7a81c3e..c18af17 100644 --- a/docbot/github.py +++ b/docbot/github.py @@ -1,34 +1,40 @@ +import logging + import requests from .metrics import Metrics from .utils import create_event +log = logging.getLogger(__name__) + + class GitHub: def __init__(self, token: str) -> None: self.token: str = token - def send_comment(self, body, issue_api, to): + def send_comment(self, body, issue_api, to, extra): create_event(to, 'send_comment', body) body = {'body': '@{}: {}'.format(to, body)} url = '{}/comments'.format(issue_api) - status_code = self._send_request(url, body) - print('Sent comment: {}'.format(status_code)) + self._send_request(url, body) + log.info('Sent comment', extra=extra) - def get_comments(self, issue_api) -> dict: + def get_comments(self, issue_api, extra) -> dict: body = {'since': '1970-01-01T00:00:00Z'} url = '{}/comments'.format(issue_api) r = self._send_request(url, body, method='get') + log.info('Received comments', extra=extra) return r.json() - def create_issue(self, title, description, src_url, author, doc_repo_url): + def create_issue(self, title, description, src_url, author, doc_repo_url, extra): create_event(author, 'create_issue', title) description = '{}\nRequested by @{} in {}.'.format(description, author, src_url) body = {'title': title, 'body': description} url = '{}/issues'.format(doc_repo_url) - status_code = self._send_request(url, body) - print('Created issue: {}'.format(status_code)) + self._send_request(url, body) + log.info('Created issue', extra=extra) @Metrics.github_latency.time() def _send_request(self, url, body, method='post'): @@ -36,6 +42,6 @@ def _send_request(self, url, body, method='post'): 'Authorization': 'token {}'.format(self.token), } r = requests.request(method, url, json=body, headers=headers) - print(r.status_code) + log.info('Response status code: %s', r.status_code) r.raise_for_status() return r diff --git a/docbot/handlers.py b/docbot/handlers.py index f32bebf..3713d66 100644 --- a/docbot/handlers.py +++ b/docbot/handlers.py @@ -1,41 +1,54 @@ +import logging + from .utils import last_events from . import settings from .processors import process_issue_comment, process_issue_state_change, \ process_commit -def webhook_handler(data: dict, event: str) -> str: - if event is None or data is None: - return 'Event or data was not found' +log = logging.getLogger(__name__) - if 'issue' in data: - issue = data['issue'] - if 'state' not in issue: - return 'Event is not needed.' - issue_state = issue['state'] - issue_api = issue['url'] - issue_url = issue['html_url'] - issue_repo = data['repository']['full_name'] - - if event == 'issue_comment': - return process_issue_comment(data, issue_state, - issue_api) - elif event == 'issues': - doc_repo_url = settings.doc_repo_urls.get(issue_repo) - return process_issue_state_change(data, issue_api, - issue_url, doc_repo_url) + +def webhook_handler(data: dict, event: str, extra: dict) -> str: + try: + log.info('Start <%s> event processing', event, extra=extra) + if event is None or data is None: + return 'Event or data was not found' + + if 'issue' in data: + issue = data['issue'] + if 'state' not in issue: + return 'Event is not needed.' + issue_state = issue['state'] + issue_api = issue['url'] + issue_url = issue['html_url'] + issue_repo = data['repository']['full_name'] + + if event == 'issue_comment': + return process_issue_comment(data, issue_state, + issue_api, extra) + elif event == 'issues': + doc_repo_url = settings.doc_repo_urls.get(issue_repo) + return process_issue_state_change(data, issue_api, + issue_url, doc_repo_url, extra) + else: + return 'Event "{}" is not needed.'.format(event) + elif event == 'push': + repo = data['repository'] + branch = '/'.join(data['ref'].split('/')[2:]) + is_master_push = repo['master_branch'] == branch + issue_repo = settings.doc_repo_urls.get(repo['full_name']) + for c in data['commits']: + process_commit(c, is_master_push, issue_repo, extra) + return 'Webhook was processed' else: - return 'Event "{}" is not needed.'.format(event) - elif event == 'push': - repo = data['repository'] - branch = '/'.join(data['ref'].split('/')[2:]) - is_master_push = repo['master_branch'] == branch - issue_repo = settings.doc_repo_urls.get(repo['full_name']) - for c in data['commits']: - process_commit(c, is_master_push, issue_repo) - return 'Webhook was processed' - else: - return 'Event is not needed.' + return 'Event is not needed.' + except Exception as e: + log.error( + 'Webhook processing error: %s', e, exc_info=True, extra=extra + ) + return str(e) + def list_events_handler() -> str: diff --git a/docbot/logging_config.py b/docbot/logging_config.py new file mode 100644 index 0000000..eac6af5 --- /dev/null +++ b/docbot/logging_config.py @@ -0,0 +1,36 @@ +from dataclasses import dataclass +import ecs_logging + + +LOGGING_CONFIG = { + 'version': 1, + 'disable_existing_loggers': False, + 'formatters': { + 'ecs': { + '()': ecs_logging.StdlibFormatter + }, + 'default': { + 'format': '[%(asctime)s] - %(message)s', + } + }, + 'handlers': { + 'ecs-stdout': { + 'class': 'logging.StreamHandler', + 'formatter': 'ecs' + } + }, + 'loggers': { + '': { + 'level': 'INFO', + 'handlers': ['ecs-stdout'], + }, + 'elasticapm': { + 'level': 'WARN', + 'handlers': ['ecs-stdout'], + }, + 'urllib3.connectionpool': { + 'level': 'ERROR', + 'handlers': ['ecs-stdout'], + }, + } +} diff --git a/docbot/processors.py b/docbot/processors.py index dcd07dc..ddf7c54 100644 --- a/docbot/processors.py +++ b/docbot/processors.py @@ -1,7 +1,12 @@ +import logging + from . import settings from .github import GitHub from .utils import create_event + +log = logging.getLogger(__name__) + github = GitHub(settings.token) @@ -25,42 +30,48 @@ def parse_comment(body): 'description': body[pos:]}, None -def process_issue_comment(body, issue_state, issue_api) -> str: +def process_issue_comment(body, issue_state, issue_api, extra) -> str: action = body['action'] if (action != 'created' and action != 'edited') or \ issue_state != 'open': + log.info('Not needed', extra=extra) return 'Not needed.' comment = body['comment'] author = comment['user']['login'] comment, error = parse_comment(comment['body']) if error: - print('Error during request processing: {}'.format(error)) - github.send_comment(error, issue_api, author) + log.error('Error during request processing: %s', error, extra=extra) + github.send_comment(error, issue_api, author, extra) elif comment: - print('Request is processed ok') + log.info('Request is processed ok', extra=extra) if action == 'edited': - github.send_comment('Accept edited.', issue_api, author) + github.send_comment('Accept edited.', issue_api, author, extra) else: - github.send_comment('Accept.', issue_api, author) + github.send_comment('Accept.', issue_api, author, extra) else: - print('Ignore non-request comments') + log.debug('Ignore non-request comments', extra=extra) + log.info('Doc request is processed', extra=extra) return 'Doc request is processed.' -def process_issue_state_change(body, issue_api, issue_url, doc_repo_url): +def process_issue_state_change(body, issue_api, issue_url, doc_repo_url, extra): action = body['action'] if action != 'closed': + log.info('Not needed', extra=extra) return 'Not needed.' - comments = github.get_comments(issue_api) + comments = github.get_comments(issue_api, extra) for c in comments: comment, error = parse_comment(c['body']) + if error: + log.error('Error during request processing: %s', error, extra=extra) if comment: github.create_issue(comment["title"], comment["description"], - issue_url, c['user']['login'], doc_repo_url) + issue_url, c['user']['login'], doc_repo_url, extra) + log.info('Issue %s is processed', comment["title"], extra=extra) return 'Issue is processed.' -def process_commit(c, is_master_push, doc_repo_url): +def process_commit(c, is_master_push, doc_repo_url, extra): body = c['message'] request_pos = body.find(settings.bot_name) if request_pos == -1: @@ -69,11 +80,14 @@ def process_commit(c, is_master_push, doc_repo_url): author = c['author']['username'] comment, error = parse_comment(request) if error: - print('Error during request processing: {}'.format(error)) + log.error('Error during request processing: %s', error, extra=extra) create_event(author, 'process_commit', error) else: create_event(author, 'process_commit', 'Accept') if is_master_push: + log.info( + 'Trying to create issue on Github %s', comment['title'], extra=extra + ) github.create_issue(comment['title'], comment['description'], c['url'], - author, doc_repo_url) + author, doc_repo_url, extra) diff --git a/requirements.txt b/requirements.txt index f86fe3a..b0bb155 100644 --- a/requirements.txt +++ b/requirements.txt @@ -2,6 +2,7 @@ blinker==1.4 certifi==2022.6.15 charset-normalizer==2.0.12 click==8.1.3 +ecs-logging==2.0.0 elastic-apm==6.9.1 Flask==2.1.2 gunicorn==20.1.0