Add a basic logging to the service

Added a basic logging and configuration of loggers.
Request processing is related to the cross-service `X-GitHub-Delivery`.

Resolves #28

Author: Oleg Chaplashkin

docbot/app.py

@@ -1,16 +1,24 @@
+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__)
 
 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)

docbot/github.py

@@ -1,41 +1,47 @@
+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'):
         headers = {
             '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

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:

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'],
+        },
+    }
+}

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)

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