fix: improve performances and logging for SCIO importer (#546)

Signed-off-by: tdruez <tdruez@aboutcode.org>

Author: tdruez

compose.dev.yml

@@ -22,8 +22,6 @@ services:
   web:
     build: .
     image: dejacode:dev
-    env_file:
-      - .env
     environment:
       - DATABASE_HOST=db
       - DATABASE_PASSWORD=dejacode
@@ -37,6 +35,7 @@ services:
     ports:
       - "8000:8000"
     volumes:
+      - ./.env:/opt/dejacode/.env
       - ./component_catalog:/opt/dejacode/component_catalog
       - ./dejacode:/opt/dejacode/dejacode
       - ./dejacode_toolkit:/opt/dejacode/dejacode_toolkit

dejacode/settings.py

@@ -586,6 +586,11 @@ def get_fake_redis_connection(config, use_strict_redis):
             "propagate": False,
             "level": DEJACODE_LOG_LEVEL,
         },
+        "product_portfolio": {
+            "handlers": ["null"] if IS_TESTS else ["console"],
+            "propagate": False,
+            "level": "DEBUG" if DEBUG else DEJACODE_LOG_LEVEL,
+        },
     },
 }
 
@@ -717,6 +722,7 @@ def get_fake_redis_connection(config, use_strict_redis):
 
 # Default to 5 seconds.
 DEJACODE_INTEGRATION_REQUESTS_TIMEOUT = env.int("DEJACODE_INTEGRATION_REQUESTS_TIMEOUT", default=5)
+CREATE_DEPENDENCIES_DEFAULT = env.bool("CREATE_DEPENDENCIES_DEFAULT", default=True)
 
 if IS_TESTS:
     # Silent the django-axes logging during tests

product_portfolio/forms.py

@@ -9,6 +9,7 @@
 import json
 
 from django import forms
+from django.conf import settings
 from django.core.exceptions import ValidationError
 from django.db import transaction
 from django.forms import BaseModelFormSet
@@ -557,7 +558,7 @@ class ImportFromScanForm(forms.Form):
     create_dependencies = forms.BooleanField(
         label=_("Create Dependencies"),
         required=False,
-        initial=False,
+        initial=settings.CREATE_DEPENDENCIES_DEFAULT,
         help_text=_(
             "When checked, dependency relationships between packages discovered in the "
             "import will be created on the Product."
@@ -664,7 +665,7 @@ class BaseProductImportFormView(forms.Form):
     create_dependencies = forms.BooleanField(
         label=_("Create Dependencies"),
         required=False,
-        initial=False,
+        initial=settings.CREATE_DEPENDENCIES_DEFAULT,
         help_text=_(
             "When checked, dependency relationships between packages discovered in the "
             "import will be created on the Product."
@@ -1002,7 +1003,7 @@ class PullProjectDataForm(forms.Form):
     create_dependencies = forms.BooleanField(
         label=_("Create Dependencies"),
         required=False,
-        initial=False,
+        initial=settings.CREATE_DEPENDENCIES_DEFAULT,
         help_text=_(
             "When checked, dependency relationships between packages discovered in the "
             "import will be created on the Product."

product_portfolio/importers.py

@@ -7,7 +7,10 @@
 #
 
 import json
+import logging
+import time
 from collections import defaultdict
+from contextlib import contextmanager
 from contextlib import suppress
 
 from django import forms
@@ -48,6 +51,16 @@
 from product_portfolio.models import ProductRelationStatus
 from product_portfolio.models import ScanCodeProject
 
+logger = logging.getLogger(__name__)
+
+
+@contextmanager
+def log_elapsed(label):
+    """Context manager that logs the elapsed time of the wrapped block."""
+    start = time.perf_counter()
+    yield
+    logger.info(f"{label}: {time.perf_counter() - start:.1f}s")
+
 
 class CleanProductMixin(ComponentRelatedFieldImportMixin):
     def clean_product(self):
@@ -683,33 +696,57 @@ def __init__(
         self.package_uid_mapping = {}
 
         self.user = user
+        self.dataspace = product.dataspace
         self.project_uuid = project_uuid
         self.product = product
         self.update_existing = update_existing
         self.scan_all_packages = scan_all_packages
         self.infer_download_urls = infer_download_urls
         self.create_dependencies = create_dependencies
 
-        scancodeio = ScanCodeIO(user.dataspace)
-        self.packages = scancodeio.fetch_project_packages(self.project_uuid)
-        self.dependencies = scancodeio.fetch_project_dependencies(self.project_uuid)
-        if not self.packages and not self.dependencies:
+    def save(self):
+        save_start = time.perf_counter()
+
+        scancodeio = ScanCodeIO(self.dataspace)
+
+        with log_elapsed("fetch_project_packages"):
+            self.packages = scancodeio.fetch_project_packages(self.project_uuid)
+
+        if not self.packages:
             raise Exception("Packages could not be fetched from ScanCode.io")
 
-    def save(self):
-        self.import_packages()
         if self.create_dependencies:
-            self.import_dependencies()
+            with log_elapsed("fetch_project_dependencies"):
+                self.dependencies = scancodeio.fetch_project_dependencies(self.project_uuid)
+
+        with log_elapsed("import_packages"):
+            self.import_packages()
+
+        if self.create_dependencies:
+            with log_elapsed("import_dependencies"):
+                self.import_dependencies()
 
         if self.scan_all_packages:
             transaction.on_commit(lambda: self.product.scan_all_packages_task(self.user))
+            logger.info("scan_all_packages: scheduled")
 
         if self.user.dataspace.enable_vulnerablecodedb_access:
-            self.product.fetch_vulnerabilities()
+            with log_elapsed("fetch_vulnerabilities"):
+                self.product.fetch_vulnerabilities()
+
+        logger.info(f"save total: {time.perf_counter() - save_start:.1f}s")
 
         return dict(self.created), dict(self.existing), dict(self.errors)
 
     def import_packages(self):
+        # Pre-fetch once to avoid repeated DB lookups in DefaultOnAdditionMixin.save().
+        self.default_review_status = ProductRelationStatus.objects.get_default_on_addition_qs(
+            self.dataspace
+        ).first()
+        self.default_purpose = ProductItemPurpose.objects.get_default_on_addition_qs(
+            self.dataspace
+        ).first()
+
         for package_data in self.packages:
             self.import_package(package_data)
 
@@ -767,8 +804,9 @@ def import_package(self, package_data):
         if not package:
             try:
                 package = Package.create_from_data(self.user, package_data, validate=True)
-            except ValidationError as errors:
-                self.errors["package"].append(str(errors))
+            except ValidationError as error:
+                logger.error(f"Failed to create package: {error}\n{package_data}")
+                self.errors["package"].append(str(error))
                 return
             self.created["package"].append(str(package))
 
@@ -780,8 +818,11 @@ def import_package(self, package_data):
                 "license_expression": package.license_expression,
                 "notes": "Imported from ScanCode.io",
                 "created_by": self.user,
+                "review_status": self.default_review_status,
+                "purpose": self.default_purpose,
             },
         )
+
         package_uid = package_data.get("package_uid") or package.uuid
         self.package_uid_mapping[package_uid] = package
 
@@ -846,7 +887,7 @@ def look_for_existing_package(self, package_data):
             return package
 
         # 2. If the package data does not include a download_url value:
-        # Attemp to find an existing package using purl-only match.
+        # Attempt to find an existing package using purl-only match.
         if not package_data.get("download_url"):
             purl_lookups = {field: package_data.get(field, "") for field in PACKAGE_URL_FIELDS}
             same_purl_packages = package_qs.filter(**purl_lookups)