Added basic logging structure (#10)

app.py

@@ -7,11 +7,14 @@
 from flask import Flask, request, send_file, jsonify
 from flask_cors import CORS
 
+from setup_logging import setup_logger
+
 
 def create_app():
     app = Flask(__name__)
+    setup_logger(app.logger)
+    logger = app.logger
     CORS(app)
-    # app.config["CORS_HEADERS"] = "Content-Type"
 
     server_dir = os.path.dirname(os.path.abspath(__file__))
     dirs = {
@@ -45,6 +48,7 @@ def receive_image():
                         dirs["status"] + os.sep + os.path.basename(f.name), "w"
                     ).close()
                     path = f.name.split(os.sep)[-1]
+                    logger.info(f"Request Created for Background Service {path}")
             except:
                 pass
             if (
@@ -78,6 +82,7 @@ def process_status(path):
             status = 2
             os.remove(dirs["error"] + os.sep + path)
             shutil.rmtree(dirs["outfiles"] + os.sep + path)
+            logger.info(f"Cleaned Processing Data for Errored Request {path}")
         elif fontfile:
             status = 0
         elif statusfile:
@@ -96,6 +101,7 @@ def fetch_font(path):
         if os.path.exists(fontpath):
             fontfile = send_file(fontpath, as_attachment=True)
             shutil.rmtree(dirs["outfiles"] + os.sep + path)
+            logger.info(f"Sent and cleaned fontfile path {path}")
             return fontfile
         return jsonify(error="File Not Found!")
 

background.py

@@ -5,12 +5,15 @@
 import time
 from uuid import uuid4
 import subprocess
+import logging
 
 
 import firebase_admin
 from firebase_admin import credentials
 from firebase_admin import storage
 
+logger = logging.getLogger("background")
+
 use_firebase = False
 if os.path.exists("firebasekey.json"):
     use_firebase = True
@@ -24,74 +27,92 @@
 
 
 def handwrite_background():
-    server_dir = os.path.dirname(os.path.abspath(__file__))
-    dirs = {}
-
-    for dir_name in ["infiles", "outfiles", "status", "error"]:
-        dirs[dir_name] = os.path.join(server_dir, dir_name)
-        shutil.rmtree(dirs[dir_name], ignore_errors=True)
-        os.makedirs(dirs[dir_name])
-
-    prev_time = time.time()
-    count = 0
-    while True:
-        # TODO
-        # We are processing one at a time
-        # in batches of 3, these batches are for
-        # future threading support.
-        if len(CURRENT_Q) == 0:
-            mtime = lambda x: os.stat(dirs["status"] + os.sep + x).st_mtime
-            files = sorted(os.listdir(dirs["status"]), key=mtime)
-            while len(CURRENT_Q) < 4 and files:
-                CURRENT_Q.append(files.pop(0))
-
-        if CURRENT_Q:
-            name = CURRENT_Q.pop(0)
-            image_name = name + ".jpg"
-            temp_dir = tempfile.mkdtemp()
-            os.makedirs(dirs["outfiles"] + os.sep + name)
-            try:
-                subprocess.check_output(
-                    [
-                        "handwrite",
-                        dirs["infiles"] + os.sep + image_name,
-                        dirs["outfiles"] + os.sep + name,
-                        "--directory",
-                        temp_dir,
-                        "--config",
-                        os.path.dirname(os.path.abspath(__file__)) + "/default.json",
-                    ]
-                )
-                if use_firebase:
-                    try:
-                        metadata = {"firebaseStorageDownloadTokens": uuid4()}
-                        blob = bucket.blob(name)
-                        blob.metadata = metadata
-                        blob.upload_from_filename(dirs["infiles"] + os.sep + image_name)
-                    except:
-                        print(f"Firebase: Image Upload Failed: {image_name}")
-            except:
-                open(dirs["error"] + os.sep + name, "w").close()
-                print(f"Unable to process Image: {image_name}")
-            os.remove(dirs["infiles"] + os.sep + image_name)
-            os.remove(dirs["status"] + os.sep + name)
-            shutil.rmtree(temp_dir)
-            count += 1
-
-        if count == 6:
-            gc.collect()
-            count = 0
-
-        if (time.time() - prev_time) / 60 > 2:
-            for dir_name in ["outfiles", "error"]:
-                for fd in os.listdir(dirs[dir_name]):
-                    path = dirs[dir_name] + os.sep + fd
-                    if (time.time() - os.stat(path).st_mtime) / 60 > 10:
-                        print(f"Deleting: {path}")
-                        if dir_name == "outfiles":
-                            shutil.rmtree(path)
-                        else:
-                            os.remove(path)
-            prev_time = time.time()
-
-        time.sleep(0.1)
+    try:
+        server_dir = os.path.dirname(os.path.abspath(__file__))
+        dirs = {}
+
+        for dir_name in ["infiles", "outfiles", "status", "error"]:
+            dirs[dir_name] = os.path.join(server_dir, dir_name)
+            shutil.rmtree(dirs[dir_name], ignore_errors=True)
+            os.makedirs(dirs[dir_name])
+            logger.debug(f"Created directory: {dirs[dir_name]}")
+
+        prev_time = time.time()
+        count = 0
+        while True:
+            # TODO
+            # We are processing one at a time
+            # in batches of 3, these batches are for
+            # future threading support.
+            if len(CURRENT_Q) == 0:
+                mtime = lambda x: os.stat(dirs["status"] + os.sep + x).st_mtime
+                files = sorted(os.listdir(dirs["status"]), key=mtime)
+                while len(CURRENT_Q) < 4 and files:
+                    CURRENT_Q.append(files.pop(0))
+
+            if CURRENT_Q:
+                name = CURRENT_Q.pop(0)
+                logger.debug(f"Started font creation {name}")
+                image_name = name + ".jpg"
+                temp_dir = tempfile.mkdtemp()
+                os.makedirs(dirs["outfiles"] + os.sep + name)
+
+                try:
+                    logger.info(f"Calling handwrite for {name}")
+                    subprocess.check_output(
+                        [
+                            "handwrite",
+                            dirs["infiles"] + os.sep + image_name,
+                            dirs["outfiles"] + os.sep + name,
+                            "--directory",
+                            temp_dir,
+                            "--config",
+                            os.path.dirname(os.path.abspath(__file__))
+                            + "/default.json",
+                        ]
+                    )
+
+                    if use_firebase:
+                        try:
+                            logger.info(f"Firebase Upload Started {name}")
+                            metadata = {"firebaseStorageDownloadTokens": uuid4()}
+                            blob = bucket.blob(name)
+                            blob.metadata = metadata
+                            blob.upload_from_filename(
+                                dirs["infiles"] + os.sep + image_name
+                            )
+                            logger.debug(f"Firebase Upload Successful {name}")
+                        except:
+                            logger.error(f"Firebase Upload Failed {name}")
+                    logger.debug(f"Font Generation Complete {name}")
+
+                except:
+                    open(dirs["error"] + os.sep + name, "w").close()
+                    logger.info(f"Unable to process Image: {name}")
+
+                os.remove(dirs["infiles"] + os.sep + image_name)
+                os.remove(dirs["status"] + os.sep + name)
+                shutil.rmtree(temp_dir)
+                logger.debug(f"Post Process Cleanup Completed {name}")
+
+                # count += 1
+
+            # if count == 6:
+            # gc.collect()
+            # count = 0
+
+            if (time.time() - prev_time) / 60 > 2:
+                for dir_name in ["outfiles", "error"]:
+                    for fd in os.listdir(dirs[dir_name]):
+                        path = dirs[dir_name] + os.sep + fd
+                        if (time.time() - os.stat(path).st_mtime) / 60 > 10:
+                            logger.info(f"Deleting (Timeout): {path}")
+                            if dir_name == "outfiles":
+                                shutil.rmtree(path)
+                            else:
+                                os.remove(path)
+                prev_time = time.time()
+
+            time.sleep(0.1)
+    except:
+        logger.exception("Background Service Crashed")

config.py

@@ -1,7 +1,14 @@
+from setup_logging import setup_logger
 import threading
+import logging
+
+from setup_logging import setup_logger
 from background import handwrite_background
 
 
 def on_starting(server):
+    logger = logging.getLogger("background")
+    setup_logger(logger)
     t = threading.Thread(target=handwrite_background)
     t.start()
+    logger.info("Background Service Thread Started")

setup_logging.py

@@ -0,0 +1,7 @@
+import logging
+
+
+def setup_logger(logger):
+    gunicorn_logger = logging.getLogger("gunicorn.error")
+    logger.handlers = gunicorn_logger.handlers
+    logger.setLevel(gunicorn_logger.level)