Merge ~stanley31/oem-qa-autosummary:add_logging into ~pieq/oem-qa-autosummary:master

[StanleyHuang]

add logging into the front-end and back-end script.

Attached the logs under gunicorn and flask.

## The logging under gunicorn ##
(venv) stanley@stanley-ThinkPad-T490:~/Desktop/Git_Repos/oem-qa-autosummary$ gunicorn -w 2 -b 0.0.0.0:8080 -t 120 webapp:app
[2021-06-22 10:16:59 +0800] [16505] [INFO] Starting gunicorn 20.1.0
[2021-06-22 10:16:59 +0800] [16505] [INFO] Listening at: http://0.0.0.0:8080 (16505)
[2021-06-22 10:16:59 +0800] [16505] [INFO] Using worker: sync
[2021-06-22 10:16:59 +0800] [16507] [INFO] Booting worker with pid: 16507
[2021-06-22 10:16:59 +0800] [16508] [INFO] Booting worker with pid: 16508
[2021-06-22T10:16:59] [summary.py/MailContentNotFoundError] [ERROR] the mail.content file is not found on the WebDAV server
[2021-06-22T10:16:59] [summary.py/Sha256FileNotFoundError] [ERROR] sha256sum file for a given image is not found on the WebDAV server
[2021-06-22T10:16:59] [summary.py/MailContentNotFoundError] [ERROR] the mail.content file is not found on the WebDAV server
[2021-06-22T10:16:59] [summary.py/Sha256FileNotFoundError] [ERROR] sha256sum file for a given image is not found on the WebDAV server

[2021-06-22T10:17:17] [__init__.py/index] [INFO] Route to index page, method: GET
[2021-06-22T10:17:17] [__init__.py/index] [DEBUG] selected_project:
[2021-06-22T10:17:26] [__init__.py/index] [INFO] Route to index page, method: POST
[2021-06-22T10:17:33] [__init__.py/index] [DEBUG] selected_project: sutton
[2021-06-22T10:17:50] [__init__.py/generate_summary] [INFO] Route to summary page
[2021-06-22T10:17:50] [summary.py/__init__] [INFO] Summary object initailizing
[2021-06-22T10:17:50] [summary.py/__init__] [DEBUG] Prepare launchpad API for sutton - p350-tr-sff-alpha
[2021-06-22T10:17:51] [summary.py/__init__] [DEBUG] Prepare WEBDAV API with sutton
[2021-06-22T10:17:51] [summary.py/get_image_info_from_mail_content] [INFO] Try to get mail.content file from WebDAV server. URI: /share/sutton/bachman/p350-tr-sff-alpha/mail.content
[2021-06-22T10:17:55] [summary.py/get_image_info_from_mail_content] [DEBUG] Image: pc-sutton-bachman-focal-amd64-X00-20210601-872.iso, SHA256: e10a62404d8350a4927c2d693d2cf4ae99520e40460da58e3c471ba0c2088718
[2021-06-22T10:17:55] [summary.py/get_new_bugs] [INFO] Collecting new bugs
[2021-06-22T10:17:56] [summary.py/get_new_bugs] [DEBUG] Search bugs from 2021-06-01 00:00:00 to 2021-06-22 10:16:59.275233 for sutton project
[2021-06-22T10:17:57] [summary.py/get_new_bugs] [DEBUG] 47 bugs found, analysing
[2021-06-22T10:17:57] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930543 bug
[2021-06-22T10:18:01] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930786 bug
[2021-06-22T10:18:04] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930789 bug
[2021-06-22T10:18:06] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930791 bug
[2021-06-22T10:18:09] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930793 bug

## The logging under flask ##
(venv) stanley@stanley-ThinkPad-T490:~/Desktop/Git_Repos/oem-qa-autosummary$ flask run
 * Serving Flask app 'webapp' (lazy loading)
 * Environment: development
 * Debug mode: on
[2021-06-22T10:19:18] [summary.py/MailContentNotFoundError] [ERROR] the mail.content file is not found on the WebDAV server
[2021-06-22T10:19:18] [summary.py/Sha256FileNotFoundError] [ERROR] sha256sum file for a given image is not found on the WebDAV server
[2021-06-22T10:19:22] [_internal.py/_log] [INFO] * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
[2021-06-22T10:19:22] [_internal.py/_log] [INFO] * Restarting with stat
 * Debugger is active!
 * Debugger PIN: 143-224-034
[2021-06-22T10:19:22] [summary.py/MailContentNotFoundError] [ERROR] the mail.content file is not found on the WebDAV server
[2021-06-22T10:19:22] [summary.py/Sha256FileNotFoundError] [ERROR] sha256sum file for a given image is not found on the WebDAV server
[2021-06-22T10:19:40] [__init__.py/index] [INFO] Route to index page, method: GET
[2021-06-22T10:19:40] [__init__.py/index] [DEBUG] selected_project:
[2021-06-22T10:19:47] [__init__.py/index] [INFO] Route to index page, method: POST
[2021-06-22T10:19:54] [__init__.py/index] [DEBUG] selected_project: sutton
[2021-06-22T10:20:12] [__init__.py/generate_summary] [INFO] Route to summary page
[2021-06-22T10:20:12] [summary.py/__init__] [INFO] Summary object initailizing
[2021-06-22T10:20:12] [summary.py/__init__] [DEBUG] Prepare launchpad API for sutton - p350-tr-sff-alpha
[2021-06-22T10:20:14] [summary.py/__init__] [DEBUG] Prepare WEBDAV API with sutton
[2021-06-22T10:20:14] [summary.py/get_image_info_from_mail_content] [INFO] Try to get mail.content file from WebDAV server. URI: /share/sutton/bachman/p350-tr-sff-alpha/mail.content
[2021-06-22T10:20:18] [summary.py/get_image_info_from_mail_content] [DEBUG] Image: pc-sutton-bachman-focal-amd64-X00-20210601-872.iso, SHA256: e10a62404d8350a4927c2d693d2cf4ae99520e40460da58e3c471ba0c2088718
[2021-06-22T10:20:18] [summary.py/get_new_bugs] [INFO] Collecting new bugs
[2021-06-22T10:20:18] [summary.py/get_new_bugs] [DEBUG] Search bugs from 2021-06-01 00:00:00 to 2021-06-22 10:19:22.523878 for sutton project
[2021-06-22T10:20:20] [summary.py/get_new_bugs] [DEBUG] 47 bugs found, analysing
[2021-06-22T10:20:20] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930543 bug
[2021-06-22T10:20:25] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930786 bug
[2021-06-22T10:20:27] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930789 bug
[2021-06-22T10:20:30] [summary.py/get_new_bugs] [DEBUG] handle https://api.launchpad.net/devel/sutton/+bug/1930791 bug

[Pierre Equoy (pieq)]

Thanks a lot, that will provide much more information that the current situation!

I added a bunch of comments below.

Since we use Python 3.6+, we can use f-strings instead of `.format()` or `%s`, such as:

    f"Preparing Launchpad API for {self.project_name} - {self.milestone_name}..."

Make sure you use this everywhere, cause I think it's easier to read :)

Then, you can amend your last commit (no need to create a new one) and push the update here.

review: Needs Fixing

[Pierre Equoy (pieq)]

Thanks for taking my comments into account!

The content looks good, but I would like to avoid having multiple commits for the same thing.

Could you squash your four commits into one ? This is explained in step 2 of the Checkbox contributing guide:

https://checkbox.readthedocs.io/en/latest/contributing.html#what-to-do-if-reviewers-suggest-changes-in-your-merge-request

It's basically using the `git rebase -i ...` command, and squashing your 4 commits into one. You can then rewrite the commit title/body (no need to mention "fixed bugs" since it will be one commit).

Don't hesitate to ask me if you need help, I know rebasing/squashing is a bit weird...

Thanks again!

review: Needs Fixing

[StanleyHuang (stanley31)]

@pieq,
I have squashing all commits into one, please help to review it again. Thanks.

> Thanks for taking my comments into account!
>
> The content looks good, but I would like to avoid having multiple commits for
> the same thing.
>
> Could you squash your four commits into one ? This is explained in step 2 of
> the Checkbox contributing guide:
>
> https://checkbox.readthedocs.io/en/latest/contributing.html#what-to-do-if-
> reviewers-suggest-changes-in-your-merge-request
>
> It's basically using the `git rebase -i ...` command, and squashing your 4
> commits into one. You can then rewrite the commit title/body (no need to
> mention "fixed bugs" since it will be one commit).
>
> Don't hesitate to ask me if you need help, I know rebasing/squashing is a bit
> weird...
>
> Thanks again!

[Pierre Equoy (pieq)]

Awesome, thanks a lot Stanley!

+1

review: Approve

diff --git a/autosummary/summary.py b/autosummary/summary.py
index 9d3b2b9..c38c071 100644
--- a/autosummary/summary.py
+++ b/autosummary/summary.py
@@ -6,29 +6,32 @@ from datetime import datetime
 
 from webdav3.client import Client
 
-logger = logging.getLogger(__name__)
 
 WEBDAV_CREDENTIALS = os.environ.get("WEBDAV_CREDENTIALS")
 
 
 class MailContentNotFoundError(FileNotFoundError):
     """Raised when the mail.content file is not found on the WebDAV server"""
-
+    logging.error("the mail.content file is not found on the WebDAV server")
     pass
 
 
 class Sha256FileNotFoundError(FileNotFoundError):
     """Raised when the sha256sum file for a given image is not found on the WebDAV server"""
-
+    logging.error(
+        "sha256sum file for a given image is not found on the WebDAV server")
     pass
 
 
 class Summary:
     def __init__(self, launchpad, project_name, milestone_name, image_name=""):
+        logging.info("Initailizing Summary object")
         self.project_name = project_name
         self.milestone_name = milestone_name
         self.launchpad = launchpad
 
+        logging.info((f"Preparing launchpad API for {self.project_name} "
+                      f"- {self.milestone_name}"))
         self.lp_project = self.launchpad.projects[self.project_name]
         self.lp_milestone = self.lp_project.getMilestone(name=self.milestone_name)
         self.series_name = self.lp_milestone.series_target.name
@@ -39,6 +42,7 @@ class Summary:
             "webdav_login": user,
             "webdav_password": passwd,
         }
+        logging.info(f"Preparing WebDAV API as user {user}")
         self.webdav_client = Client(webdav_options)
 
         if not image_name:
@@ -47,10 +51,12 @@ class Summary:
             self.image_name = image_name
             self.image_sha256 = self.get_image_sha256()
         self.image_date = get_date_from_image_name(self.image_name)
-
         self.new_bugs = self.get_new_bugs()
         self.milestone_bugs = self.lp_milestone.searchTasks()
+        logging.info(f"{len(self.milestone_bugs)} milestone bugs found.")
         self.reopened_bugs = get_reopen_bugs(self.milestone_bugs)
+        logging.info(f"{len(self.reopened_bugs)} reopen bugs found.")
+        logging.info("Summary object initialized")
 
     def get_webdav_credentials(self, config=WEBDAV_CREDENTIALS):
         with open(config) as f:
@@ -67,18 +73,23 @@ class Summary:
         in the same project between `created_since` and `created_before`. Bugs
         assigned to different series are ignored.
         """
+        logging.info("Collecting new bugs")
         team = self.launchpad.people["oem-qa"]
 
         if created_since is None:
             created_since = self.image_date
         new_bugs = []
+        logging.info((f"Search bugs from {created_since} to {created_before}"
+                      f" for {self.project_name} project"))
         bugs = self.lp_project.searchTasks(
             created_since=created_since, created_before=created_before
         )
 
+        logging.info(f"{len(bugs)} bugs found, analysing")
         check_pattern = ["[checkbox]", "plainbox"]
-
+        target_milestone = self.lp_milestone.series_target
         for bug in bugs:
+            logging.info(f"handle {bug} bug")
             if bug.owner in team.members:
                 # To exclude checkbox-related bugs from summary report
                 if (
@@ -86,17 +97,14 @@ class Summary:
                     and "checkbox" not in bug.bug.tags
                 ):
                     if bug.milestone:
-                        if (
-                            bug.milestone.series_target
-                            == self.lp_milestone.series_target
-                        ):
+                        if bug.milestone.series_target == target_milestone:
                             new_bugs.append(bug)
                     else:
                         # No milestone/series defined yet, assuming it should be part of
                         # the list
                         new_bugs.append(bug)
                 else:
-                    logger.info(f"Excluding Checkbox-related {bug.title}")
+                    logging.info(f"Excluding Checkbox-related {bug.title}")
         return new_bugs
 
     def get_image_info_from_mail_content(self):
@@ -109,7 +117,8 @@ class Summary:
         image_sha256 = ""
         buff = io.BytesIO()
         uri = os.path.join(self.get_milestone_uri(), "mail.content")
-
+        logging.info(
+            f"Try to get mail.content file from WebDAV server. URI: {uri}")
         try:
             self.webdav_client.download_from(buff, uri)
             buff.seek(0)
@@ -125,6 +134,7 @@ class Summary:
         except Exception:
             raise MailContentNotFoundError()
 
+        logging.info(f"Image: {image_name}, SHA256: {image_sha256}")
         return image_name, image_sha256
 
     def get_image_sha256(self):
@@ -178,6 +188,7 @@ def get_reopen_bugs(bugs):
 
     Return a list of reopened bugs.
     """
+    logging.info("Collecting reopen bugs")
     closed_statuses = ["Invalid", "Won't Fix", "Fix Committed", "Fix Released"]
     open_statuses = ["Confirmed", "Incomplete", "Triaged", "In Progress"]
     reopen_bugs = []
diff --git a/logging_conf.py b/logging_conf.py
new file mode 100644
index 0000000..0143717
--- /dev/null
+++ b/logging_conf.py
@@ -0,0 +1,22 @@
+import os
+from logging.config import dictConfig
+
+autosummary_logging_conf = dictConfig({
+    'version': 1,
+    'formatters': {
+        'default': {
+            'format': '[%(asctime)s] [%(filename)s/%(funcName)s] [%(levelname)s] %(message)s',
+            'datefmt': '%Y-%m-%dT%H:%M:%S'
+        },
+    },
+    'handlers': {
+        'stdout': {
+            'class': "logging.StreamHandler",
+            'stream': 'ext://sys.stdout',
+            'formatter': 'default'
+        }
+    },
+    'root': {
+        'handlers': ['stdout'],
+        'level': os.getenv('APP_LOG_LEVEL', 'INFO')},
+})
\ No newline at end of file
diff --git a/webapp/__init__.py b/webapp/__init__.py
index 93f4e0d..befaea5 100644
--- a/webapp/__init__.py
+++ b/webapp/__init__.py
@@ -5,14 +5,12 @@ import os
 import requests
 
 from flask import Flask, redirect, request, render_template, url_for, jsonify
-from flask.logging import default_handler
 from launchpadlib.launchpad import Launchpad
 from markupsafe import escape
 
 from autosummary import summary
+from logging_conf import autosummary_logging_conf
 
-root = logging.getLogger()
-root.addHandler(default_handler)
 
 app = Flask(__name__)
 
@@ -95,6 +93,7 @@ def bug_title(bug_task):
 
 @app.route("/", methods=("GET", "POST"))
 def index():
+    logging.info(f"Route to index page, method: {request.method}")
     milestones = None
     selected_project = ""
     projects = sorted(summary.get_available_projects())
@@ -105,6 +104,7 @@ def index():
             milestones = sorted(
                 summary.get_active_milestones(launchpad, selected_project)
             )
+    logging.info(f"selected_project: {selected_project}")
 
     return render_template(
         "index.html",
@@ -116,6 +116,7 @@ def index():
 
 @app.route("/summary", methods=("POST",))
 def generate_summary():
+    logging.info("Route to summary page")
     project = request.form.get("project")
     milestone = request.form.get("milestone")
     image_name = request.form.get("image_name")
@@ -140,6 +141,7 @@ def generate_summary():
         nb_high_bugs = len(high_new_bugs) + len(high_reopened_bugs)
     except summary.MailContentNotFoundError:
         error = "No release e-mail was found for this release."
+        logging.error(error)
         # Asking for manual input of the image name instead
         return render_template(
             "image_info.html",
@@ -157,6 +159,7 @@ def generate_summary():
             f"Could not find sha256 for image named {image_name}. "
             f"Please make sure this image is available on oem-share."
         )
+        logging.error(error)
         return render_template(
             "image_info.html",
             error=error,
@@ -208,6 +211,8 @@ def add_test_status():
         )
         response = res.json()
         status_code = res.status_code
+        logging.info((f"Add status status code: {status_code},"
+                      f" response: {response}"))
     except requests.exceptions.ConnectionError:
         response = None
         logging.exception("Cannot connect to Auto Test Status Tracker Web Service")