Merge pull request #287 from roboflow/feature/add_lambda_logger

Add structured API logger
roboflow · Feb 27, 2024 · 851f538 · 851f538
2 parents a6acb3f + 69b8c2c
commit 851f538
Show file tree

Hide file tree

Showing 21 changed files with 85 additions and 16 deletions.
diff --git a/docker/dockerfiles/Dockerfile.device_manager b/docker/dockerfiles/Dockerfile.device_manager
@@ -28,5 +28,6 @@ COPY docker/config/device_manager.py device_manager.py
 ENV NUM_WORKERS=1
 ENV PORT=9101
 ENV HOST=0.0.0.0
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn device_manager:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/docker/dockerfiles/Dockerfile.onnx.cpu b/docker/dockerfiles/Dockerfile.onnx.cpu
@@ -64,5 +64,6 @@ ENV HOST=0.0.0.0
 ENV PORT=9001
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn cpu_http:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/docker/dockerfiles/Dockerfile.onnx.cpu.parallel b/docker/dockerfiles/Dockerfile.onnx.cpu.parallel
@@ -63,6 +63,7 @@ ENV REDIS_PORT="6380"
 ENV CORE_MODELS_ENABLED=false
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT redis-server --io-threads 3 --save --port $REDIS_PORT & \
     celery -A inference.enterprise.parallel.tasks worker --prefetch-multiplier 2 --concurrency $NUM_CELERY_WORKERS -Q pre --loglevel=WARNING & \

diff --git a/docker/dockerfiles/Dockerfile.onnx.cpu.slim b/docker/dockerfiles/Dockerfile.onnx.cpu.slim
@@ -48,5 +48,6 @@ ENV HOST=0.0.0.0
 ENV PORT=9001
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn cpu_http:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/docker/dockerfiles/Dockerfile.onnx.gpu b/docker/dockerfiles/Dockerfile.onnx.gpu
@@ -64,5 +64,6 @@ ENV HOST=0.0.0.0
 ENV PORT=9001
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn gpu_http:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/docker/dockerfiles/Dockerfile.onnx.gpu.parallel b/docker/dockerfiles/Dockerfile.onnx.gpu.parallel
@@ -61,5 +61,6 @@ ENV CORE_MODELS_ENABLED=false
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
 ENV REDIS_HOST=localhost
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT python3 entrypoint.py
diff --git a/docker/dockerfiles/Dockerfile.onnx.gpu.slim b/docker/dockerfiles/Dockerfile.onnx.gpu.slim
@@ -46,5 +46,6 @@ ENV HOST=0.0.0.0
 ENV PORT=9001
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn gpu_http:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/docker/dockerfiles/Dockerfile.onnx.jetson.4.5.0 b/docker/dockerfiles/Dockerfile.onnx.jetson.4.5.0
@@ -66,5 +66,6 @@ ENV PORT=9001
 ENV OPENBLAS_CORETYPE=ARMV8
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn gpu_http:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/docker/dockerfiles/Dockerfile.onnx.jetson.4.6.1 b/docker/dockerfiles/Dockerfile.onnx.jetson.4.6.1
@@ -84,5 +84,6 @@ ENV PORT=9001
 ENV OPENBLAS_CORETYPE=ARMV8
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn gpu_http:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/docker/dockerfiles/Dockerfile.onnx.jetson.5.1.1 b/docker/dockerfiles/Dockerfile.onnx.jetson.5.1.1
@@ -70,5 +70,6 @@ ENV OPENBLAS_CORETYPE=ARMV8
 ENV LD_PRELOAD=/usr/lib/aarch64-linux-gnu/libgomp.so.1
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
 ENV WORKFLOWS_MAX_CONCURRENT_STEPS=1
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn gpu_http:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/docker/dockerfiles/Dockerfile.onnx.lambda b/docker/dockerfiles/Dockerfile.onnx.lambda
@@ -63,6 +63,7 @@ ENV DOCTR_MULTIPROCESSING_DISABLE=TRUE
 ENV REDIS_SSL=true
 ENV WORKFLOWS_STEP_EXECUTION_MODE=remote
 ENV WORKFLOWS_REMOTE_API_TARGET=hosted
+ENV API_LOGGING_ENABLED=True
 
 WORKDIR ${LAMBDA_TASK_ROOT}
 RUN rm -rf /build

diff --git a/docker/dockerfiles/Dockerfile.onnx.lambda.slim b/docker/dockerfiles/Dockerfile.onnx.lambda.slim
@@ -55,6 +55,7 @@ ENV DISABLE_VERSION_CHECK=true
 ENV REDIS_SSL=true
 ENV WORKFLOWS_STEP_EXECUTION_MODE=remote
 ENV WORKFLOWS_REMOTE_API_TARGET=hosted
+ENV API_LOGGING_ENABLED=True
 
 WORKDIR ${LAMBDA_TASK_ROOT}
 

diff --git a/docker/dockerfiles/Dockerfile.onnx.trt b/docker/dockerfiles/Dockerfile.onnx.trt
@@ -48,5 +48,6 @@ ENV NUM_WORKERS=1
 ENV HOST=0.0.0.0
 ENV PORT=9001
 ENV WORKFLOWS_STEP_EXECUTION_MODE=local
+ENV API_LOGGING_ENABLED=True
 
 ENTRYPOINT uvicorn gpu_http:app --workers $NUM_WORKERS --host $HOST --port $PORT
diff --git a/inference/core/interfaces/http/http_api.py b/inference/core/interfaces/http/http_api.py
@@ -4,6 +4,7 @@
 from time import sleep
 from typing import Any, List, Optional, Union
 
+import asgi_correlation_id
 import uvicorn
 from fastapi import BackgroundTasks, FastAPI, Path, Query, Request
 from fastapi.middleware.cors import CORSMiddleware
@@ -122,10 +123,7 @@
     serialise_workflow_result,
 )
 from inference.core.managers.base import ModelManager
-from inference.core.roboflow_api import (
-    get_roboflow_workspace,
-    get_workflow_specification,
-)
+from inference.core.roboflow_api import get_workflow_specification
 from inference.core.utils.notebooks import start_notebook
 from inference.enterprise.workflows.complier.core import compile_and_execute_async
 from inference.enterprise.workflows.complier.entities import StepExecutionMode
@@ -281,6 +279,7 @@ def __init__(
                 strip_dirs=False,
                 sort_by="cumulative",
             )
+        app.add_middleware(asgi_correlation_id.CorrelationIdMiddleware)
 
         if METRICS_ENABLED:
 

diff --git a/inference/core/logger.py b/inference/core/logger.py
@@ -1,14 +1,56 @@
 import logging
+import os
 import warnings
+from typing import Any
 
 from rich.logging import RichHandler
+from structlog.processors import CallsiteParameter
 
 from inference.core.env import LOG_LEVEL
-
-logger = logging.getLogger("inference")
-logger.setLevel(LOG_LEVEL)
-logger.addHandler(RichHandler())
-logger.propagate = False
+from inference.core.utils.environment import str2bool
 
 if LOG_LEVEL == "ERROR" or LOG_LEVEL == "FATAL":
     warnings.filterwarnings("ignore", category=UserWarning, module="onnxruntime.*")
+
+
+def add_correlation(
+    logger: logging.Logger, method_name: str, event_dict: dict[str, Any]
+) -> dict[str, Any]:
+    from asgi_correlation_id import correlation_id
+
+    request_id = correlation_id.get()
+    if request_id:
+        event_dict["request_id"] = request_id
+    return event_dict
+
+
+if str2bool(os.getenv("API_LOGGING_ENABLED", "False")):
+    import structlog
+
+    structlog.configure(
+        processors=[
+            add_correlation,
+            structlog.stdlib.filter_by_level,
+            structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M.%S"),
+            structlog.processors.StackInfoRenderer(),
+            structlog.processors.format_exc_info,
+            structlog.processors.CallsiteParameterAdder(
+                [
+                    CallsiteParameter.FILENAME,
+                    CallsiteParameter.FUNC_NAME,
+                    CallsiteParameter.LINENO,
+                ],
+            ),
+            structlog.processors.JSONRenderer(),
+        ],
+        wrapper_class=structlog.stdlib.BoundLogger,
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        cache_logger_on_first_use=True,
+    )
+    logger = structlog.get_logger("inference")
+    logger.setLevel(LOG_LEVEL)
+else:
+    logger = logging.getLogger("inference")
+    logger.setLevel(LOG_LEVEL)
+    logger.addHandler(RichHandler())
+    logger.propagate = False
diff --git a/inference/core/models/base.py b/inference/core/models/base.py
@@ -3,6 +3,7 @@
 
 import numpy as np
 
+from inference.core import logger
 from inference.core.entities.requests.inference import InferenceRequest
 from inference.core.entities.responses.inference import InferenceResponse
 from inference.core.models.types import PreprocessReturnMetadata
@@ -17,6 +18,9 @@ class BaseInference:
     def infer(self, image: Any, **kwargs) -> Any:
         """Runs inference on given data."""
         preproc_image, returned_metadata = self.preprocess(image, **kwargs)
+        logger.debug(
+            f"Preprocessed input shape: {getattr(preproc_image, 'shape', None)}"
+        )
         predicted_arrays = self.predict(preproc_image, **kwargs)
         postprocessed = self.postprocess(predicted_arrays, returned_metadata, **kwargs)
 
@@ -34,7 +38,7 @@ def postprocess(
         self,
         predictions: Tuple[np.ndarray, ...],
         preprocess_return_metadata: PreprocessReturnMetadata,
-        **kwargs
+        **kwargs,
     ) -> Any:
         raise NotImplementedError
 

diff --git a/inference/core/models/keypoints_detection_base.py b/inference/core/models/keypoints_detection_base.py
@@ -148,9 +148,7 @@ def make_response(
                             "keypoints": model_keypoints_to_response(
                                 keypoints_metadata=self.keypoints_metadata,
                                 keypoints=pred[7:],
-                                predicted_object_class_id=int(
-                                    pred[4 + len(self.get_class_names)]
-                                ),
+                                predicted_object_class_id=int(pred[6]),
                                 keypoint_confidence_threshold=keypoint_confidence_threshold,
                             ),
                         }

diff --git a/inference/core/models/roboflow.py b/inference/core/models/roboflow.py
@@ -631,6 +631,7 @@ def merge_inference_results(self, inference_results: List[Any]) -> Any:
         return list(itertools.chain(*inference_results))
 
     def validate_model(self) -> None:
+        logger.debug("Starting model validation")
         if not self.load_weights:
             return
         try:
@@ -649,15 +650,21 @@ def validate_model(self) -> None:
             raise ModelArtefactError(
                 f"Unable to validate model classes. Cause: {e}"
             ) from e
+        logger.debug("Model validation finished")
 
     def run_test_inference(self) -> None:
         test_image = (np.random.rand(1024, 1024, 3) * 255).astype(np.uint8)
-        return self.infer(test_image)
+        logger.debug(f"Running test inference. Image size: {test_image.shape}")
+        result = self.infer(test_image)
+        logger.debug(f"Test inference finished.")
+        return result
 
     def get_model_output_shape(self) -> Tuple[int, int, int]:
         test_image = (np.random.rand(1024, 1024, 3) * 255).astype(np.uint8)
+        logger.debug(f"Getting model output shape. Image size: {test_image.shape}")
         test_image, _ = self.preprocess(test_image)
         output = self.predict(test_image)[0]
+        logger.debug(f"Model output shape test finished.")
         return output.shape
 
     def validate_model_classes(self) -> None:
@@ -673,6 +680,7 @@ def get_infer_bucket_file_list(self) -> list:
 
     def initialize_model(self) -> None:
         """Initializes the ONNX model, setting up the inference session and other necessary properties."""
+        logger.debug("Getting model artefacts")
         self.get_model_artifacts()
         logger.debug("Creating inference session")
         if self.load_weights or not self.has_model_metadata:
@@ -755,6 +763,7 @@ def initialize_model(self) -> None:
                 logger.debug(
                     f"Model {self.endpoint} is loaded with dynamic batching disabled"
                 )
+        logger.debug("Model initialisation finished.")
 
     def load_image(
         self,

diff --git a/inference/core/utils/image_utils.py b/inference/core/utils/image_utils.py
@@ -14,6 +14,7 @@
 from PIL import Image
 from requests import RequestException
 
+from inference.core import logger
 from inference.core.entities.requests.inference import InferenceRequestImage
 from inference.core.env import ALLOW_NUMPY_INPUT
 from inference.core.exceptions import (
@@ -78,6 +79,7 @@ def load_image(
             value, cv_imread_flags=cv_imread_flags
         )
     np_image = convert_gray_image_to_bgr(image=np_image)
+    logger.debug(f"Loaded inference image. Shape: {getattr(np_image, 'shape', None)}")
     return np_image, is_bgr
 
 

diff --git a/inference/core/version.py b/inference/core/version.py
@@ -1,4 +1,4 @@
-__version__ = "0.9.14"
+__version__ = "0.9.15rc1"
 
 
 if __name__ == "__main__":

diff --git a/requirements/requirements.http.txt b/requirements/requirements.http.txt
@@ -1,4 +1,6 @@
 uvicorn[standard]<=0.22.0
 python-multipart<=0.0.6
 fastapi-cprofile<=0.0.2
-orjson>=3.9.10
+orjson>=3.9.10
+asgi_correlation_id>=4.3.1
+structlog>=24.1.0