Feature/logging setup (#221)

* Add LOGGING config

- Add colorlog for local development
- Add helper function for logging extra

* Use log_extra with logging extra

Author: thenav56

apps/etl/extraction/sources/base/extract.py

@@ -2,6 +2,7 @@
 from celery.utils.log import get_task_logger
 
 from apps.etl.models import ExtractionData
+from main.logging import log_extra
 
 logger = get_task_logger(__name__)
 
@@ -61,7 +62,9 @@ def pull_data(self, source: int, retry_count: int, timeout: int = 30, ext_object
                 instance_obj.save()
 
                 if not response.status_code == 204:  # bypass exception when content is empty
-                    logger.error("Request failed with status", exc_info=True, extra={"response_code": response.status_code})
+                    logger.error(
+                        "Request failed with status", exc_info=True, extra=log_extra({"response_code": response.status_code})
+                    )
                     raise Exception("Request failed")
 
             resp_status = ExtractionData.Status.SUCCESS
@@ -80,6 +83,6 @@ def pull_data(self, source: int, retry_count: int, timeout: int = 30, ext_object
                 "resp_text": "",
             }
         except requests.exceptions.RequestException:
-            logger.error("Extraction failed", exc_info=True, extra={"source": source})
+            logger.error("Extraction failed", exc_info=True, extra=log_extra({"source": source}))
             # FIXME: Check if this creates duplicate entry in Sentry. if yes, remove this.
             raise

apps/etl/extraction/sources/base/handler.py

@@ -11,6 +11,7 @@
 )
 from apps.etl.models import ExtractionData
 from main.celery import app
+from main.logging import log_extra
 
 logger = logging.getLogger(__name__)
 
@@ -154,9 +155,11 @@ def handle_extraction(cls, url: str, params: dict, headers: dict, source: int) -
             logger.error(
                 "extraction failed",
                 exc_info=True,
-                extra={
-                    "source": instance.source,
-                },
+                extra=log_extra(
+                    {
+                        "source": instance.source,
+                    }
+                ),
             )
             raise
 

apps/etl/extraction/sources/desinventar/extract.py

@@ -7,6 +7,7 @@
 from apps.etl.extraction.sources.base.utils import manage_duplicate_file_content
 from apps.etl.models import ExtractionData
 from main.celery import app
+from main.logging import log_extra
 
 logger = logging.getLogger(__name__)
 
@@ -91,9 +92,11 @@ def handle_extraction(cls, url: str, params: dict, headers: dict, source: int) -
             logger.error(
                 "extraction failed",
                 exc_info=True,
-                extra={
-                    "source": instance.source,
-                },
+                extra=log_extra(
+                    {
+                        "source": instance.source,
+                    }
+                ),
             )
             raise
 

apps/etl/extraction/sources/emdat/extract.py

@@ -9,6 +9,7 @@
 from django.core.files.base import ContentFile
 
 from apps.etl.models import ExtractionData, HazardType
+from main.logging import log_extra
 
 logger = logging.getLogger(__name__)
 
@@ -151,6 +152,6 @@ def import_hazard_data(variables, **kwargs):
         # Set extraction status to Fail
         emdat_instance.status = ExtractionData.Status.FAILED
         emdat_instance.save(update_fields=["status"])
-        logger.error("Extraction failed", exc_info=True, extra={"source": ExtractionData.Source.EMDAT})
+        logger.error("Extraction failed", exc_info=True, extra=log_extra({"source": ExtractionData.Source.EMDAT}))
         # FIXME: Check if this creates duplicate entry in Sentry. if yes, remove this.
         raise

apps/etl/extraction/sources/gfd/extract.py

@@ -13,6 +13,7 @@
 from apps.etl.extraction.sources.base.utils import manage_duplicate_file_content
 from apps.etl.models import ExtractionData
 from main.celery import app
+from main.logging import log_extra
 
 logger = logging.getLogger(__name__)
 
@@ -144,9 +145,11 @@ def handle_extraction(cls, url: str, source: int, start_date, end_date) -> int:
             logger.error(
                 "extraction failed",
                 exc_info=True,
-                extra={
-                    "source": instance.source,
-                },
+                extra=log_extra(
+                    {
+                        "source": instance.source,
+                    }
+                ),
             )
             raise
 

apps/etl/extraction/sources/idu/extract.py

@@ -13,6 +13,7 @@
 )
 from apps.etl.models import ExtractionData
 from main.celery import app
+from main.logging import log_extra
 
 logger = logging.getLogger(__name__)
 
@@ -166,8 +167,10 @@ def handle_extraction(url) -> dict:
             logger.error(
                 "IDU extraction failed",
                 exc_info=True,
-                extra={
-                    "source": ExtractionData.Source.IDU,
-                },
+                extra=log_extra(
+                    {
+                        "source": ExtractionData.Source.IDU,
+                    }
+                ),
             )
             raise

apps/etl/extraction/sources/ifrc_event/extract.py

@@ -9,6 +9,7 @@
 from apps.etl.extraction.sources.base.utils import manage_duplicate_file_content
 from apps.etl.models import ExtractionData
 from main.celery import app
+from main.logging import log_extra
 
 logger = logging.getLogger(__name__)
 
@@ -119,9 +120,11 @@ def handle_extraction(cls, url: str, params: dict, headers: dict, source: int) -
             logger.error(
                 "extraction failed",
                 exc_info=True,
-                extra={
-                    "source": instance.source,
-                },
+                extra=log_extra(
+                    {
+                        "source": instance.source,
+                    }
+                ),
             )
             raise
 

apps/etl/transform/sources/desinventar.py

@@ -9,6 +9,7 @@
 from apps.etl.models import ExtractionData, Transform
 from apps.etl.transform.sources.handler import BaseTransformerHandler
 from main.celery import app
+from main.logging import log_extra
 
 logger = logging.getLogger(__name__)
 
@@ -55,7 +56,7 @@ def handle_transformation(cls, extraction_id, country_code, iso3):
             logger.info("Transformation ended")
 
         except Exception as e:
-            logger.error("Transformation failed", exc_info=True, extra={"extraction_id": extraction_obj.id})
+            logger.error("Transformation failed", exc_info=True, extra=log_extra({"extraction_id": extraction_obj.id}))
             transform_obj.status = Transform.Status.FAILED
             transform_obj.save(update_fields=["status"])
             # FIXME: Check if this creates duplicate entry in Sentry. if yes, remove this.

apps/etl/transform/sources/emdat.py

@@ -9,6 +9,7 @@
 
 from apps.etl.models import ExtractionData, PyStacLoadData, Transform
 from apps.etl.utils import read_file_data
+from main.logging import log_extra
 from main.managers import BulkCreateManager
 
 logger = logging.getLogger(__name__)
@@ -68,7 +69,9 @@ def transform_data(source, transformer, data_source, extraction_id, data):
         transform_obj.status = Transform.Status.SUCCESS
         transform_obj.save(update_fields=["status"])
     except Exception as e:
-        logger.error("Transformation failed", exc_info=True, extra={"extraction_id": ext_instance.id, "source": source})
+        logger.error(
+            "Transformation failed", exc_info=True, extra=log_extra({"extraction_id": ext_instance.id, "source": source})
+        )
         # update transformation status to success
         transform_obj.status = Transform.Status.FAILED
         transform_obj.save(update_fields=["status"])

apps/etl/transform/sources/gdacs.py

@@ -12,6 +12,7 @@
 
 from apps.etl.models import ExtractionData, PyStacLoadData, Transform
 from apps.etl.utils import read_file_data
+from main.logging import log_extra
 from main.managers import BulkCreateManager
 
 logger = logging.getLogger(__name__)
@@ -45,7 +46,7 @@ def transform_event_data(event_extraction_data):
         transform_obj.status = Transform.Status.SUCCESS
         transform_obj.save(update_fields=["status"])
     except Exception as e:
-        logger.error("Gdacs transformation failed", exc_info=True, extra={"extraction_id": gdacs_instance.id})
+        logger.error("Gdacs transformation failed", exc_info=True, extra=log_extra({"extraction_id": gdacs_instance.id}))
 
         transform_obj.status = Transform.Status.FAILED
         transform_obj.save(update_fields=["status"])
@@ -109,7 +110,7 @@ def transform_geo_data(geo_data_extraction_id, event_extraction_id):
         transform_obj.save(update_fields=["status"])
 
     except Exception as e:
-        logger.error("Gdacs transformation failed", exc_info=True, extra={"extraction_id": gdacs_instance.id})
+        logger.error("Gdacs transformation failed", exc_info=True, extra=log_extra({"extraction_id": gdacs_instance.id}))
 
         transform_obj.status = Transform.Status.FAILED
         transform_obj.save(update_fields=["status"])
@@ -152,7 +153,7 @@ def transform_impact_data(event_data):
         transform_obj.status = Transform.Status.SUCCESS
         transform_obj.save(update_fields=["status"])
     except Exception as e:
-        logger.error("Gdacs transformation failed", exc_info=True, extra={"extraction_id": gdacs_instance.id})
+        logger.error("Gdacs transformation failed", exc_info=True, extra=log_extra({"extraction_id": gdacs_instance.id}))
 
         transform_obj.status = Transform.Status.FAILED
         transform_obj.save(update_fields=["status"])

apps/etl/transform/sources/glide.py

@@ -6,6 +6,7 @@
 
 from apps.etl.models import ExtractionData, PyStacLoadData, Transform
 from apps.etl.utils import read_file_data
+from main.logging import log_extra
 from main.managers import BulkCreateManager
 
 logger = logging.getLogger(__name__)
@@ -41,7 +42,7 @@ def transform_glide_event_data(extraction_id):
         transform_obj.status = Transform.Status.SUCCESS
         transform_obj.save(update_fields=["status"])
     except Exception as e:
-        logger.error("Glide transformation failed", exc_info=True, extra={"extraction_id": glide_instance.id})
+        logger.error("Glide transformation failed", exc_info=True, extra=log_extra({"extraction_id": glide_instance.id}))
         transform_obj.status = Transform.Status.FAILED
         transform_obj.save(update_fields=["status"])
         # FIXME: Check if this creates duplicate entry in Sentry. if yes, remove this.

apps/etl/transform/sources/handler.py

@@ -7,6 +7,7 @@
 
 from apps.etl.models import ExtractionData, PyStacLoadData, Transform
 from main.celery import app
+from main.logging import log_extra
 from main.managers import BulkCreateManager
 
 logger = logging.getLogger(__name__)
@@ -64,7 +65,7 @@ def handle_transformation(cls, extraction_id: int, geocoder: Optional[MontyGeoCo
             logger.info("Transformation ended")
 
         except Exception as e:
-            logger.error("Transformation failed", exc_info=True, extra={"extraction_id": extraction_obj.id})
+            logger.error("Transformation failed", exc_info=True, extra=log_extra({"extraction_id": extraction_obj.id}))
             transform_obj.status = Transform.Status.FAILED
             transform_obj.save(update_fields=["status"])
             # FIXME: Check if this creates duplicate entry in Sentry. if yes, remove this.

apps/etl/transform/sources/pdc.py

@@ -6,6 +6,7 @@
 
 from apps.etl.models import ExtractionData, Transform
 from main.celery import app
+from main.logging import log_extra
 
 from .handler import BaseTransformerHandler
 
@@ -73,7 +74,7 @@ def handle_transformation(cls, extraction_id, geo_json_id):
             logger.info("Transformation ended")
 
         except Exception as e:
-            logger.error("Transformation failed", exc_info=True, extra={"extraction_id": extraction_obj.id})
+            logger.error("Transformation failed", exc_info=True, extra=log_extra({"extraction_id": extraction_obj.id}))
             transform_obj.status = Transform.Status.FAILED
             transform_obj.save(update_fields=["status"])
             # FIXME: Check if this creates duplicate entry in Sentry. if yes, remove this.

apps/etl/transform/sources/usgs.py

@@ -8,6 +8,7 @@
 
 from apps.etl.models import ExtractionData, PyStacLoadData, Transform
 from apps.etl.utils import read_file_data
+from main.logging import log_extra
 from main.managers import BulkCreateManager
 
 logger = logging.getLogger(__name__)
@@ -45,7 +46,7 @@ def transform_usgs_event_data(extraction_id):
         transform_obj.status = Transform.Status.SUCCESS
         transform_obj.save(update_fields=["status"])
     except Exception as e:
-        logger.error("usgs transformation failed", exc_info=True, extra={"extraction_id": usgs_instance.id})
+        logger.error("usgs transformation failed", exc_info=True, extra=log_extra({"extraction_id": usgs_instance.id}))
         transform_obj.status = Transform.Status.FAILED
         transform_obj.save(update_fields=["status"])
         raise e

main/logging.py

@@ -0,0 +1,24 @@
+import logging
+
+EXTRA_CONTEXT_KEY = "CONTEXT"
+
+
+def log_render_extra_context(record: logging.LogRecord):
+    """
+    Append extra->context to logs
+    NOTE: This will appear in logs when used with logger.xxx(..., extra={'context': {..content}})
+    """
+    extra_str = ""
+    if extra_raw := getattr(record, EXTRA_CONTEXT_KEY, None):
+        extra_str = f" - EXTRA:{str(extra_raw)}"
+    record.custom_extra = extra_str
+    return True
+
+
+def log_extra(extra: dict):
+    """
+    Basic helper function to view extra argument in logs using log_render_extra_context
+    """
+    return {
+        EXTRA_CONTEXT_KEY: extra,
+    }