Merge pull request #51 from steamcmd/improve-logging

Improve logging

Author: jonakoudijs

.github/workflows/deploy.yml

@@ -20,7 +20,7 @@ jobs:
     runs-on: ubuntu-22.04
     needs: check-requirements
     steps:
-      - uses: actions/checkout@v3
+      - uses: actions/checkout@v4
       - name: Parse API Version
         run: echo "API_VERSION=$(echo $GITHUB_REF | awk -F '/' '{print $NF}' | cut -c 2-)" >> $GITHUB_ENV
       - name: Docker Login
@@ -37,7 +37,7 @@ jobs:
     name: Update Readme
     runs-on: ubuntu-22.04
     steps:
-      - uses: actions/checkout@v3
+      - uses: actions/checkout@v4
       - name: Update Docker Hub Description
         uses: peter-evans/dockerhub-description@v2
         env:
@@ -50,7 +50,7 @@ jobs:
     runs-on: ubuntu-22.04
     needs: [check-requirements, build-image]
     steps:
-      - uses: actions/checkout@v3
+      - uses: actions/checkout@v4
       - uses: superfly/flyctl-actions/setup-flyctl@master
       - name: Parse API Version
         run: echo "API_VERSION=$(echo $GITHUB_REF | awk -F '/' '{print $NF}' | cut -c 2-)" >> $GITHUB_ENV
@@ -64,7 +64,7 @@ jobs:
     runs-on: ubuntu-22.04
     needs: [check-requirements, build-image]
     steps:
-      - uses: actions/checkout@v3
+      - uses: actions/checkout@v4
       - name: Parse API Version
         run: echo "API_VERSION=$(echo $GITHUB_REF | awk -F '/' '{print $NF}' | cut -c 2-)" >> $GITHUB_ENV
       - name: Deploy API on Render.com

.github/workflows/test.yml

@@ -13,24 +13,15 @@ jobs:
     name: Test Image
     runs-on: ubuntu-22.04
     steps:
-      - uses: actions/checkout@v3
+      - uses: actions/checkout@v4
       - name: Build Image
         run: docker build -t steamcmd/api:latest .
 
   python-lint:
     name: Python Lint
     runs-on: ubuntu-22.04
     steps:
-      - uses: actions/checkout@v3
-      - uses: ricardochaves/python-lint@v1.3.0
+      - uses: actions/checkout@v4
+      - uses: jpetrucciani/ruff-check@main
         with:
-          # python files
-          python-root-list: "src"
-          # enabled linters
-          use-black: true
-          # disabled linters
-          use-pylint: false
-          use-pycodestyle: false
-          use-flake8: false
-          use-mypy: false
-          use-isort: false
+          path: 'src/'

README.md

@@ -84,8 +84,8 @@ possible as well.
 
 All the settings are optional. Keep in mind that when you choose a cache type
 that you will need to set the corresponding cache settings for that type as well
-(ex.: `REDIS_HOST`, `REDIS_PORT`, `REDIS_PASSWORD` is required when using the
-**redis** type).
+(ex.: `REDIS_HOST`, `REDIS_PORT`, `REDIS_PASSWORD` or `REDIS_URL` is required
+when using the **redis** type).
 
 All the available options in an `.env` file:
 ```
@@ -106,6 +106,9 @@ REDIS_PASSWORD="YourRedisP@ssword!"
 # (see: https://redis-py.readthedocs.io/en/stable/#quickly-connecting-to-redis)
 REDIS_URL="redis://YourUsername:YourRedisP@ssword!@your.redis.host.example.com:6379"
 
+# logging
+LOG_LEVEL=info
+
 # deta
 DETA_BASE_NAME="steamcmd"
 DETA_PROJECT_KEY="YourDet@ProjectKey!"

docker-compose.yml

@@ -1,4 +1,3 @@
-version: '3'
 services:
   web:
     build: .
@@ -16,6 +15,7 @@ services:
       CACHE_EXPIRATION: 120
       REDIS_HOST: redis
       REDIS_PORT: 6379
+      LOG_LEVEL: info
       PYTHONUNBUFFERED: "TRUE"
     restart: always
   redis:

requirements.txt

@@ -2,8 +2,9 @@ fastapi
 redis
 deta
 
-python-dotenv
 semver
+python-dotenv
+logfmter
 
 steam[client]
 gevent

src/functions.py

@@ -3,51 +3,62 @@
 """
 
 # import modules
-import os, json, gevent, datetime, redis
+import os
+import json
+import gevent
+import redis
+import logging
 from steam.client import SteamClient
 from deta import Deta
 
 
 def app_info(app_id):
-    connect_retries = 3
-    connect_timeout = 5
-    current_time = str(datetime.datetime.now())
+    connect_retries = 2
+    connect_timeout = 3
+
+    logging.info("Started requesting app info", extra={"app_id": app_id})
 
     try:
         # Sometimes it hangs for 30+ seconds. Normal connection takes about 500ms
         for _ in range(connect_retries):
-            count = _ + 1
-            count = str(count)
+            count = str(_)
 
             try:
                 with gevent.Timeout(connect_timeout):
-                    print("Connecting via steamclient")
-                    print(
-                        "Retrieving app info for: "
-                        + str(app_id)
-                        + ", retry count: "
-                        + count
+                    logging.info(
+                        "Retrieving app info from steamclient",
+                        extra={"app_id": app_id, "retry_count": count},
                     )
 
+                    logging.debug("Connecting via steamclient to steam api")
                     client = SteamClient()
                     client.anonymous_login()
                     client.verbose_debug = False
+
+                    logging.debug("Requesting app info from steam api")
                     info = client.get_product_info(apps=[app_id], timeout=1)
 
                     return info
 
             except gevent.timeout.Timeout:
+                logging.warning(
+                    "Encountered timeout when trying to connect to steam api. Retrying.."
+                )
                 client._connecting = False
 
             else:
-                print("Succesfully retrieved app info for app id: " + str(app_id))
+                logging.info("Succesfully retrieved app info", extra={"app_id": app_id})
                 break
         else:
+            logging.error(
+                "Max connect retries exceeded",
+                extra={"connect_retries": connect_retries},
+            )
             raise Exception(f"Max connect retries ({connect_retries}) exceeded")
 
     except Exception as err:
-        print("Failed in retrieving app info for app id: " + str(app_id))
-        print(err)
+        logging.error("Failed in retrieving app info", extra={"app_id": app_id})
+        logging.error(err, extra={"app_id": app_id})
 
 
 def cache_read(app_id):
@@ -61,7 +72,10 @@ def cache_read(app_id):
         return deta_read(app_id)
     else:
         # print query parse error and return empty dict
-        print("Incorrect set cache type: " + os.environ["CACHE_TYPE"])
+        logging.error(
+            "Set incorrect cache type",
+            extra={"app_id": app_id, "cache_type": os.environ["CACHE_TYPE"]},
+        )
 
     # return failed status
     return False
@@ -78,7 +92,10 @@ def cache_write(app_id, data):
         return deta_write(app_id, data)
     else:
         # print query parse error and return empty dict
-        print("Incorrect set cache type: " + os.environ["CACHE_TYPE"])
+        logging.error(
+            "Set incorrect cache type",
+            extra={"app_id": app_id, "cache_type": os.environ["CACHE_TYPE"]},
+        )
 
     # return failed status
     return False
@@ -130,13 +147,13 @@ def redis_read(app_id):
         # return cached data
         return data
 
-    except Exception as read_error:
+    except Exception as redis_error:
         # print query parse error and return empty dict
-        print(
-            "The following error occured while trying to read and decode "
-            + "from Redis cache: \n > "
-            + str(read_error)
+        logging.error(
+            "An error occured while trying to read and decode from Redis cache",
+            extra={"app_id": app_id, "error_msg": redis_error},
         )
+
         # return failed status
         return False
 
@@ -162,15 +179,35 @@ def redis_write(app_id, data):
 
     except Exception as redis_error:
         # print query parse error and return empty dict
-        print(
-            "The following error occured while trying to write to Redis cache: \n > "
-            + str(redis_error)
+        logging.error(
+            "An error occured while trying to write to Redis cache",
+            extra={"app_id": app_id, "error_msg": redis_error},
         )
 
     # return fail status
     return False
 
 
+def log_level(level):
+    """
+    Sets lowest level to log.
+    """
+
+    match level:
+        case "debug":
+            logging.getLogger().setLevel(logging.DEBUG)
+        case "info":
+            logging.getLogger().setLevel(logging.INFO)
+        case "warning":
+            logging.getLogger().setLevel(logging.WARNING)
+        case "error":
+            logging.getLogger().setLevel(logging.ERROR)
+        case "critical":
+            logging.getLogger().setLevel(logging.CRITICAL)
+        case _:
+            logging.getLogger().setLevel(logging.WARNING)
+
+
 def deta_read(app_id):
     """
     Read app info from Deta base cache.

src/main.py

@@ -3,11 +3,14 @@
 """
 
 # import modules
-from deta import Deta
-from typing import Union
-from fastapi import FastAPI, Response, status
-from functions import app_info, cache_read, cache_write
-import os, datetime, json, semver, typing
+import os
+import json
+import semver
+import typing
+import logging
+from fastapi import FastAPI, Response
+from functions import app_info, cache_read, cache_write, log_level
+from logfmter import Logfmter
 
 # load configuration
 from dotenv import load_dotenv
@@ -17,6 +20,15 @@
 # initialise app
 app = FastAPI()
 
+# set logformat
+formatter = Logfmter(keys=["level"], mapping={"level": "levelname"})
+handler = logging.StreamHandler()
+handler.setFormatter(formatter)
+logging.basicConfig(handlers=[handler])
+
+if "LOG_LEVEL" in os.environ:
+    log_level(os.environ["LOG_LEVEL"])
+
 
 # include "pretty" for backwards compatibility
 class PrettyJSONResponse(Response):
@@ -35,26 +47,50 @@ def render(self, content: typing.Any) -> bytes:
 
 @app.get("/v1/info/{app_id}", response_class=PrettyJSONResponse)
 def read_app(app_id: int, pretty: bool = False):
+    logging.info("Requested app info", extra={"app_id": app_id})
+
     if "CACHE" in os.environ and os.environ["CACHE"]:
         info = cache_read(app_id)
 
         if not info:
-            print("App info: " + str(app_id) + " could not be find in the cache")
+            logging.info(
+                "App info could not be found in cache", extra={"app_id": app_id}
+            )
             info = app_info(app_id)
             cache_write(app_id, info)
+        else:
+            logging.info(
+                "App info succesfully retrieved from cache",
+                extra={"app_id": app_id},
+            )
 
     else:
         info = app_info(app_id)
 
+    if info is None:
+        logging.info(
+            "The SteamCMD backend returned no actual data and failed",
+            extra={"app_id": app_id},
+        )
+        # return empty result for not found app
+        return {"data": {app_id: {}}, "status": "failed", "pretty": pretty}
+
     if not info["apps"]:
+        logging.info(
+            "No app has been found at Steam but the request was succesfull",
+            extra={"app_id": app_id},
+        )
         # return empty result for not found app
         return {"data": {app_id: {}}, "status": "success", "pretty": pretty}
 
+    logging.info("Succesfully retrieved app info", extra={"app_id": app_id})
     return {"data": info["apps"], "status": "success", "pretty": pretty}
 
 
 @app.get("/v1/version", response_class=PrettyJSONResponse)
 def read_item(pretty: bool = False):
+    logging.info("Requested api version")
+
     # check if version succesfully read and parsed
     if "VERSION" in os.environ and os.environ["VERSION"]:
         return {
@@ -63,6 +99,9 @@ def read_item(pretty: bool = False):
             "pretty": pretty,
         }
     else:
+        logging.warning(
+            "No version has been defined and could therefor not satisfy the request"
+        )
         return {
             "status": "error",
             "data": "Something went wrong while retrieving and parsing the current API version. Please try again later",