Feature/logging

.github/workflows/deploy.yml

@@ -43,7 +43,7 @@ jobs:
     runs-on: ubuntu-20.04
     defaults:
       run:
-        working-directory: ./cd/terraform
+        working-directory: ./infra/terraform
     env:
       OS_AUTH_URL: https://auth.cloud.ovh.net/v3
       OS_REGION_NAME: "GRA7"

.github/workflows/develop.yml

@@ -21,6 +21,9 @@ jobs:
     steps:
     - uses: actions/checkout@v2
     - name: Build the Docker image
+      env:
+          X_OVH_TOKEN: ${{ secrets.X_OVH_TOKEN }}
+          API_OVH_TOKEN: ${{ secrets.API_OVH_TOKEN }}
       run: TAG=${{ needs.get-version.outputs.version }} docker-compose -f docker-compose-prod.yml build
     - name: Login to GHCR
       if: success()
@@ -31,8 +34,8 @@ jobs:
         password: ${{ secrets.GITHUB_TOKEN }}
     - name: Push on GHCR
       run: |
-        ./cd/scripts/docker-push.sh ${{ needs.get-version.outputs.version }} v${{ needs.get-version.outputs.version }}
-        ./cd/scripts/docker-push.sh ${{ needs.get-version.outputs.version }} develop
+        ./infra/scripts/docker-push.sh ${{ needs.get-version.outputs.version }} v${{ needs.get-version.outputs.version }}
+        ./infra/scripts/docker-push.sh ${{ needs.get-version.outputs.version }} develop
     - name: Delete untagged images
       uses: vlaurin/action-ghcr-prune@main
       with:
@@ -73,8 +76,8 @@ jobs:
       - uses: actions/checkout@v2
       - name: Test ip
         run : |
-          ./cd/scripts/test-alive.sh ${{ secrets.PREPROD_SERVER_IP }}
+          ./infra/scripts/test-alive.sh ${{ secrets.PREPROD_SERVER_IP }}
       - name: Test DNS
         if: success()
         run : |
-          ./cd/scripts/test-alive.sh preprod.basegun.fr
+          ./infra/scripts/test-alive.sh preprod.basegun.fr

.github/workflows/release.yml

@@ -38,5 +38,5 @@ jobs:
         password: ${{ secrets.GITHUB_TOKEN }}
     - name: Push on GHCR
       run: |
-        ./cd/scripts/docker-push.sh ${{ steps.get_version.outputs.VERSION }} ${{ steps.get_version.outputs.VERSION }}
-        ./cd/scripts/docker-push.sh ${{ steps.get_version.outputs.VERSION }} latest
+        ./infra/scripts/docker-push.sh ${{ steps.get_version.outputs.VERSION }} ${{ steps.get_version.outputs.VERSION }}
+        ./infra/scripts/docker-push.sh ${{ steps.get_version.outputs.VERSION }} latest

.gitignore

@@ -5,7 +5,8 @@ env/
 .env
 __pycache__
 weights/
+logs/
 temp/
-openrc.sh
+*openrc.sh
 .terraform*
 .secrets

backend/requirements.txt

@@ -2,4 +2,8 @@ fastapi==0.68.0
 uvicorn==0.14.0
 torch==1.10.2+cpu
 torchvision==0.11.3+cpu
-python-multipart>=0.0.5
+python-multipart>=0.0.5
+gelf-formatter==0.2.1
+pyyaml>=5.4.1
+user-agents==2.2.0
+ua-parser

backend/src/main.py

@@ -1,36 +1,83 @@
 import shutil
 import os
 from uuid import uuid4
-from fastapi import FastAPI, File, UploadFile, HTTPException
+import logging
+from logging.handlers import TimedRotatingFileHandler
+from datetime import datetime
+import time
+import json
+from fastapi import Request, FastAPI, File, Form, UploadFile, HTTPException
 from fastapi.responses import PlainTextResponse, FileResponse
 from fastapi.middleware.cors import CORSMiddleware
-from PIL import UnidentifiedImageError
+from gelfformatter import GelfFormatter
+from user_agents import parse
 from src.model import load_model_inference, predict_image
 
-app = FastAPI()
 
-origins = [
+def init_variable(var_name: str, path: str) -> str:
+    """Inits global variable for folder path
+
+    Args:
+        var_name (str): variable name in environ
+        path (str): folder path
+
+    Returns:
+        str: final variable value
+    """
+    if var_name in os.environ:
+        VAR = os.environ[var_name]
+    else:
+        VAR = os.path.abspath(os.path.join(
+                os.path.dirname(os.path.abspath(__file__)),
+                path))
+        print("WARNING: The variable "+var_name+" is not set. Using", VAR)
+    os.makedirs(VAR, exist_ok = True)
+    return VAR
+
+
+def setup_logs(log_dir: str) -> logging.Logger:
+    """Setup environment for logs
+
+    Args:
+        log_dir (str): folder for log storage
+
+        logging.Logger: logger object
+    """
+    print(">>> Reload logs config")
+    # clear previous logs
+    for f in os.listdir(log_dir):
+        os.remove(os.path.join(log_dir, f))
+    # configure new logs
+    formatter = GelfFormatter()
+    logger = logging.getLogger("Basegun")
+    # new log file at midnight
+    log_file = os.path.join(log_dir, "log.json")
+    handler = TimedRotatingFileHandler(
+        log_file,
+        when="midnight",
+        interval=1,
+        backupCount=7)
+    logger.setLevel(logging.INFO)
+    handler.setFormatter(formatter)
+    logger.addHandler(handler)
+    return logger
+
+
+####################
+#      SETUP       #
+####################
+
+# FastAPI Setup
+app = FastAPI()
+origins = [ # allow requests from front-end
     "http://basegun.fr",
     "https://basegun.fr",
+    "http://preprod.basegun.fr",
+    "https://preprod.basegun.fr",
     "http://localhost",
     "http://localhost:8080",
     "http://localhost:3000"
 ]
-
-MODEL_PATH = os.path.join(
-            os.path.dirname(os.path.abspath(__file__)),
-            "weights/model.pth")
-
-if "PATH_IMGS" in os.environ:
-    PATH_IMGS = os.environ["PATH_IMGS"]
-else:
-    PATH_IMGS = os.path.abspath(os.path.join(
-            os.path.dirname(os.path.abspath(__file__)),
-            "../../frontend/public/temp"))
-    print("WARNING: The variable PATH_IMGS is not set. Using", PATH_IMGS)
-os.makedirs(PATH_IMGS, exist_ok = True)
-
-# allow requests from front-end
 app.add_middleware(
     CORSMiddleware,
     allow_origins=origins,
@@ -39,43 +86,110 @@
     allow_headers=["*"],
 )
 
+# Image storage
+PATH_IMGS = init_variable("PATH_IMGS", "../../frontend/public/temp")
+
+# Logs
+PATH_LOGS = init_variable("PATH_LOGS", "../logs")
+logger = setup_logs(PATH_LOGS)
+
+# Load model
+MODEL_PATH = os.path.join(
+            os.path.dirname(os.path.abspath(__file__)),
+            "weights/model.pth")
 model = None
 if os.path.exists(MODEL_PATH):
     model = load_model_inference(MODEL_PATH)
+if not model:
+    raise RuntimeError("Model not found")
 
 
+####################
+#     ROUTES       #
+####################
 @app.get("/", response_class=PlainTextResponse)
 def home():
     return "Basegun backend"
 
-
 @app.get("/version", response_class=PlainTextResponse)
 def version():
     if "VERSION" in os.environ:
         return os.environ["VERSION"]
     else:
         return "-1.0"
 
+@app.get("/logs")
+def logs(request: Request):
+    request_url = request.url._url
+    if ("localhost" in request_url or "preprod" in request_url):
+        with open(os.path.join(PATH_LOGS, "log.json"), "r") as f:
+            lines = f.readlines()
+            res = [json.loads(l) for l in lines]
+            res.reverse()
+            return res
+    else:
+        return PlainTextResponse("Forbidden")
 
 @app.post("/upload")
-async def imageupload(image: UploadFile = File(...)):
-    if model:
-        input_path = os.path.join(
-                        PATH_IMGS, # store image in PATH_IMGS folder
-                        # rename with uuid for secure filename but keep original file ext
-                        str(uuid4()) + os.path.splitext(image.filename)[1]
-                    )
-        with open(f'{input_path}', "wb") as buffer:
-            shutil.copyfileobj(image.file, buffer)
-        try:
-            label, confidence = predict_image(model, input_path)
-            print("Finished processing, result:", input_path, label, confidence)
-        except UnidentifiedImageError:
-            raise HTTPException(status_code=400, detail="Corrupted image file")
-        except Exception as e:
-            raise HTTPException(status_code=500, detail=str(e))
+async def imageupload(
+    request: Request,
+    image: UploadFile = File(...),
+    date: float = Form(...),
+    userId: str = Form(...),
+    geolocation: str = Form(...) ):
+
+    input_path = os.path.join(PATH_IMGS,
+                    # rename with uuid for secure filename but keep original file ext
+                    str(uuid4()) + os.path.splitext(image.filename)[1]
+                )
+
+    user_agent = parse(request.headers.get("user-agent"))
+    device = "other"
+    if user_agent.is_mobile:
+        device = "mobile"
+    elif user_agent.is_pc:
+        device = "pc"
+    elif user_agent.is_tablet:
+        device = "tablet"
+
+    extras_logging = {
+        "bg_date": datetime.now().isoformat(),
+        "bg_image_url": input_path,
+        "bg_upload_time": round(time.time()-date, 2),
+        "bg_user_id": userId,
+        "bg_geolocation": geolocation,
+        "bg_device": device,
+        "bg_device_family": user_agent.device.family,
+        "bg_device_os": user_agent.os.family,
+        "bg_device_browser": user_agent.browser.family
+    }
+
+    # write image locally
+    with open(f"{input_path}", "wb") as buffer:
+        shutil.copyfileobj(image.file, buffer)
+
+    try:
+        start = time.time()
+        label, confidence = predict_image(model, input_path)
+        extras_logging["bg_label"] = label
+        extras_logging["bg_confidence"] = confidence
+        extras_logging["bg_model_time"] = round(time.time()-start, 2)
+        logger.info("Identification request", extra=extras_logging)
+    except Exception as e:
+        extras_logging["bg_error_type"] = e.__class__.__name__
+        logger.exception(e, extra=extras_logging)
+        raise HTTPException(status_code=500, detail=str(e))
 
-    else:
-        raise HTTPException(status_code=404, detail="Model not found")
     return {"file_name": input_path, "label": label, "confidence": confidence}
 
+
+@app.post("/feedback")
+async def log_feedback(request: Request):
+    res = await request.json()
+    extras_logging = {
+        "bg_date": datetime.now().isoformat(),
+        "bg_image_url": res["image_url"],
+        "bg_feedback": res["feedback"]
+    }
+    logger.info("Identification feedback", extra=extras_logging)
+    return

backend/tests/test_api.py

@@ -1,15 +1,14 @@
-import sys
 import unittest
 import os
+import time
+import json
 import requests
 from PIL import Image, ImageChops
-from src.main import PATH_IMGS
 
 class TestModel(unittest.TestCase):
     def __init__(self, *args, **kwargs):
         super(TestModel, self).__init__(*args, **kwargs)
         self.url = "http://localhost:5000"
-        self.assertTrue(os.path.exists(PATH_IMGS))
 
     def test_home(self):
         """Checks that the route / is alive"""
@@ -23,22 +22,26 @@ def test_version(self):
         self.assertEqual(r.text, os.environ["VERSION"])
         self.assertEqual(len(r.text.split('.')), 2) # checks version has format X.Y
 
-    def test_upload(self):
+    def test_upload_and_logs(self):
         """Checks that the file upload works properly"""
         path = os.path.join(
             os.path.dirname(os.path.abspath(__file__)),
             "revolver.jpg")
+        user, geoloc = ("2ea26", "12.666,7.666")
+
         with open(path, 'rb') as f:
-            r = requests.post(self.url + "/upload", files={"image": f})
+            r = requests.post(self.url + "/upload",
+                files={"image": f},
+                data={"date": time.time(), "userId": user, "geolocation": geoloc})
+        self.assertEqual(r.status_code, 200)
         res = r.json()
 
         # checks that the input file has been written
         self.assertTrue("file_name" in res.keys())
-        output_path = os.path.join(PATH_IMGS, res["file_name"])
-        self.assertTrue(os.path.exists(output_path))
+        self.assertTrue(os.path.exists(res["file_name"]))
         # checks that written file is exactly the same as input file
         with Image.open(path) as image_one:
-            with Image.open(output_path) as image_two:
+            with Image.open(res["file_name"]) as image_two:
                 self.assertEqual(image_one.size, image_two.size)
                 diff = ImageChops.difference(image_one, image_two)
                 self.assertFalse(diff.getbbox())
@@ -47,3 +50,32 @@ def test_upload(self):
         self.assertEqual(res["label"], "revolver")
         self.assertTrue("confidence" in res.keys())
         self.assertAlmostEqual(res["confidence"], 99.05, places=1)
+        # checks that the result is written in logs
+        r = requests.get(self.url + "/logs")
+        self.assertEqual(r.status_code, 200)
+        log = r.json()[0]
+        self.assertEqual(
+            set(log.keys()),
+            {'timestamp', '_bg_device', 'host', '_bg_model_time', 'version', '_bg_device_os', '_bg_device_family',
+            'short_message', '_bg_confidence', '_bg_upload_time', '_bg_date', '_bg_user_id', '_bg_label', '_bg_image_url',
+            'level', '_bg_geolocation', '_bg_device_browser'}
+        )
+        self.assertEqual(log["level"], 6)
+        self.assertEqual(log["short_message"], "Identification request")
+        self.assertEqual(log["_bg_user_id"], user)
+        self.assertEqual(log["_bg_geolocation"], geoloc)
+        self.assertTrue(log["_bg_upload_time"]>=0)
+
+    def test_feedback_and_logs(self):
+        """Checks that the feedback works properly"""
+        r = requests.post(self.url + "/feedback",
+                json={"image_url": "test", "feedback": False})
+        self.assertEqual(r.status_code, 200)
+        r = requests.get(self.url + "/logs")
+        self.assertEqual(r.status_code, 200)
+        res = r.json()
+        log = r.json()[0]
+        self.assertEqual(log["level"], 6)
+        self.assertEqual(log["short_message"], "Identification feedback")
+        self.assertEqual(log["_bg_image_url"], "test")
+        self.assertFalse(log["_bg_feedback"])