analyze performance upgrade

django_project/IoTAnalyzer/analyze/security_analysis.py

@@ -5,15 +5,43 @@ from __future__ import annotations
 import json
 import logging
 import os
+import threading
+import time
+import traceback
 
 from django.conf import settings
-from analyzer import AnalysisEngine, extract_urls, extract_hashes
-from analyzer.extract_pyshark import build_context_from_pcap
+from django.db import connection
+from analyzer import AnalysisEngine, extract_urls, extract_hashes, __version__ as analyzer_version
+from analyzer.extract_tshark import build_context_from_pcap
 from analyzer.findings import Severity
+from analyzer import logutil
 from IoTAnalyzer.models import FindingReport, UrlRaw, HashRaw
 
 logger = logging.getLogger(__name__)
 
+
+def analysis_log_path(filename: str) -> str | None:
+    """Per-capture log written next to the upload."""
+    path = resolve_capture_path(filename)
+    if not path:
+        return None
+    return path + ".analysis.log"
+
+
+def _error_summary(exc: BaseException) -> str:
+    """Short, user-facing description of a failure with the failing location."""
+    tb = traceback.extract_tb(exc.__traceback__)
+    where = f" ({tb[-1].filename.rsplit('/', 1)[-1]}:{tb[-1].lineno})" if tb else ""
+    return f"{type(exc).__name__}: {exc}{where}"[:1000]
+
+
+def _set_error(file_id: int, message: str | None) -> None:
+    from IoTAnalyzer.models import File
+    try:
+        File.objects.filter(id=file_id).update(error_message=message)
+    except Exception as exc:
+        logger.warning("Could not store error message for file=%s: %s", file_id, exc)
+
 _CANDIDATE_DIRS = [
     str(settings.CAPTURE_UPLOAD_DIR),
 ]
@@ -109,38 +137,103 @@ def _persist_artifacts(ctx, raw_dataset_id: int) -> None:
         logger.exception("Hash persistence failed: %s", exc)
 
 
-def analyze_capture(filename: str, file_id: int, raw_dataset_id: int | None = None):
-    """Analyze a capture once and persist findings plus extracted artifacts."""
+def analyze_capture(filename: str, file_id: int, raw_dataset_id: int | None = None,
+                    packet_limit: int | None = None, device_ip: str | None = None):
+    """Analyze a capture once and persist findings plus extracted artifacts.
+
+    ``device_ip`` is the address entered at upload time. It focuses the report on
+    the device under test; when omitted it is looked up from the File record.
+    Raises on failure so the caller can record the reason.
+    """
     path = resolve_capture_path(filename)
     if not path:
-        logger.warning("Capture file not found: %s", filename)
-        return None
+        logger.error("Capture file not found: %s (searched: %s)", filename, _CANDIDATE_DIRS)
+        raise FileNotFoundError(f"Capture file {filename} not found in {_CANDIDATE_DIRS}")
 
-    try:
-        ctx = build_context_from_pcap(path)
-        result = AnalysisEngine().analyze_context(ctx)
-    except Exception as exc:
-        logger.exception("Security analysis failed for %s: %s", filename, exc)
-        return None
+    if packet_limit is None:
+        packet_limit = getattr(settings, "CAPTURE_PACKET_LIMIT", 0)
 
-    try:
-        # Reanalysis replaces the previous report atomically at the file level.
-        FindingReport.objects.filter(file_id=file_id).delete()
-        FindingReport.objects.create(
-            file_id=file_id,
-            result_json=json.dumps(result.to_dict()),
-            finding_count=len(result.findings),
-            max_severity=_max_severity(result),
-        )
-        logger.info("Stored finding report: file_id=%s, findings=%s",
-                    file_id, len(result.findings))
-    except Exception as exc:
-        logger.exception("Finding report persistence failed: %s", exc)
+    if device_ip is None:
+        try:
+            from IoTAnalyzer.models import File
+            device_ip = File.objects.filter(id=file_id).values_list("ip_address", flat=True).first()
+        except Exception:
+            device_ip = None
+
+    started = time.time()
+    logger.info("Capture analysis start: file_id=%s path=%s device_ip=%s packet_limit=%s analyzer=%s",
+                file_id, path, device_ip, packet_limit or "unlimited", analyzer_version)
+    ctx = build_context_from_pcap(path, packet_limit=packet_limit or None, device_ip=device_ip)
+    if ctx.truncated:
+        logger.warning("Capture %s analyzed partially: %s", file_id, ctx.truncation_reason)
+    result = AnalysisEngine().analyze_context(ctx)
+
+    # Reanalysis replaces the previous report atomically at the file level.
+    payload = json.dumps(result.to_dict())
+    FindingReport.objects.filter(file_id=file_id).delete()
+    FindingReport.objects.create(
+        file_id=file_id,
+        result_json=payload,
+        finding_count=len(result.findings),
+        max_severity=_max_severity(result),
+    )
+    logger.info("Stored finding report: file_id=%s findings=%s max_severity=%s json=%d bytes",
+                file_id, len(result.findings), _max_severity(result), len(payload))
 
     _persist_artifacts(ctx, raw_dataset_id)
-
+    logger.info("Capture analysis finished: file_id=%s in %.1fs", file_id, time.time() - started)
     return result
 
 
 def run_security_analysis(filename: str, file_id: int):
-    return analyze_capture(filename, file_id, raw_dataset_id=None)
+    try:
+        return analyze_capture(filename, file_id, raw_dataset_id=None)
+    except Exception as exc:
+        logger.exception("Security analysis failed for %s: %s", filename, exc)
+        return None
+
+
+def start_capture_analysis(file_id: int, filename: str, raw_dataset_id: int | None = None,
+                           synchronous: bool = False) -> None:
+    """Analyze a capture off the request thread and keep File.status current.
+
+    A multi-hundred-megabyte capture takes far longer than any sane HTTP
+    timeout, so the upload response must not wait for the analysis.
+    """
+    if synchronous:
+        _run_capture_analysis(file_id, filename, raw_dataset_id, close_conn=False)
+        return
+    thread = threading.Thread(
+        target=_run_capture_analysis,
+        args=(file_id, filename, raw_dataset_id),
+        daemon=True,
+        name=f"capture-analysis-{file_id}",
+    )
+    thread.start()
+
+
+def _run_capture_analysis(file_id: int, filename: str, raw_dataset_id: int | None = None,
+                          close_conn: bool = True) -> None:
+    from IoTAnalyzer.models import File
+
+    status = "analysis_failed"
+    error = None
+    log_path = analysis_log_path(filename)
+    try:
+        with logutil.run_log(log_path):
+            _set_error(file_id, None)
+            result = analyze_capture(filename, file_id, raw_dataset_id)
+            status = "analyzed" if result is not None else "analysis_failed"
+    except Exception as exc:
+        error = _error_summary(exc)
+        logger.exception("Capture analysis failed for file=%s: %s", file_id, error)
+    finally:
+        try:
+            File.objects.filter(id=file_id).update(status=status, error_message=error)
+            logger.info("Capture %s completed with status %s%s", file_id, status,
+                        f" (log: {log_path})" if log_path else "")
+        except Exception as exc:
+            logger.exception("Could not persist status for file=%s: %s", file_id, exc)
+        # Close only the worker thread's connection, never the request connection.
+        if close_conn:
+            connection.close()

django_project/IoTAnalyzer/db_create.py

@@ -84,7 +84,7 @@ def create_capture(
     filename: str,
     ip_address: str,
 ) -> File:
-    """Create capture metadata, analyze the stored file, and update its status."""
+    """Create capture metadata and hand the analysis to a background worker."""
     firmware_version = _required_text(firmware_version, "Firmware version", 100)
     filename = os.path.basename(_required_text(filename, "Capture filename", 255))
     if os.path.splitext(filename)[1].lower() not in CAPTURE_EXTENSIONS:
@@ -113,10 +113,10 @@ def create_capture(
             raise ValidationError("This capture is already registered for the device.")
         raw_dataset = RawDataset.objects.create(file=file_entry)
 
-    from .analyze.security_analysis import analyze_capture
+    from .analyze.security_analysis import start_capture_analysis
 
-    result = analyze_capture(filename, file_entry.id, raw_dataset.id)
-    file_entry.status = "analyzed" if result is not None else "analysis_failed"
-    file_entry.save(update_fields=["status"])
-    logger.info("Capture %s completed with status %s", file_entry.id, file_entry.status)
+    # The analysis reads the whole capture with tshark and can run for many
+    # minutes, so it must not block the upload response.
+    start_capture_analysis(file_entry.id, filename, raw_dataset.id)
+    logger.info("Capture %s registered, analysis queued", file_entry.id)
     return file_entry

django_project/IoTAnalyzer/middleware.py

@@ -0,0 +1,36 @@
+"""Request logging for the API."""
+
+from __future__ import annotations
+
+import logging
+import time
+import uuid
+
+logger = logging.getLogger("IoTAnalyzer.request")
+
+
+class RequestLogMiddleware:
+    """Log one line per API request with duration, status, user and a request id."""
+
+    def __init__(self, get_response):
+        self.get_response = get_response
+
+    def __call__(self, request):
+        started = time.time()
+        request_id = request.headers.get("X-Request-ID") or uuid.uuid4().hex[:12]
+        request.request_id = request_id
+        try:
+            response = self.get_response(request)
+        except Exception:
+            logger.exception("%s %s failed after %.0f ms [rid=%s]", request.method,
+                             request.get_full_path(), (time.time() - started) * 1000, request_id)
+            raise
+        response["X-Request-ID"] = request_id
+        if request.path.startswith("/api/") and request.path != "/api/health":
+            user = getattr(getattr(request, "user", None), "username", None) or "-"
+            level = logging.WARNING if response.status_code >= 500 else \
+                logging.INFO if response.status_code >= 400 else logging.DEBUG
+            logger.log(level, "%s %s -> %s in %.0f ms user=%s [rid=%s]", request.method,
+                       request.get_full_path(), response.status_code,
+                       (time.time() - started) * 1000, user, request_id)
+        return response

django_project/IoTAnalyzer/migrations/0002_file_error_message.py

@@ -0,0 +1,16 @@
+from django.db import migrations, models
+
+
+class Migration(migrations.Migration):
+
+    dependencies = [
+        ("IoTAnalyzer", "0001_initial"),
+    ]
+
+    operations = [
+        migrations.AddField(
+            model_name="file",
+            name="error_message",
+            field=models.TextField(blank=True, null=True),
+        ),
+    ]

django_project/IoTAnalyzer/models.py

@@ -128,6 +128,8 @@ class File(models.Model):
     filename = models.CharField(max_length=255)
     ip_address = models.GenericIPAddressField()
     status = models.CharField(max_length=50, default="pending")
+    # Last analysis failure, shown in the UI so nobody has to dig through logs first.
+    error_message = models.TextField(null=True, blank=True)
     upload_time = models.DateTimeField(auto_now_add=True)
 
     def to_json(self):
@@ -137,6 +139,7 @@ class File(models.Model):
             "ip_address": self.ip_address,
             "firmware_version": self.firmware.version,
             "status": self.status,
+            "error_message": self.error_message,
             "upload_time": self.upload_time.isoformat(),
         }
 

django_project/IoTAnalyzer/urls.py

@@ -28,5 +28,6 @@ urlpatterns = [
     path("api/get_cloud_results/<int:file_id>", views.CloudResultsView.as_view(), name="cloud_results"),
     path("api/start_analysis/<int:file_id>", views.StartAnalysisView.as_view(), name="start_analysis"),
     path("api/get_analysis_status/<int:file_id>", views.AnalysisStatusView.as_view(), name="analysis_status"),
+    path("api/get_analysis_log/<int:file_id>", views.AnalysisLogView.as_view(), name="analysis_log"),
     path("api/get_report/<int:file_id>/<str:fmt>", views.ReportView.as_view(), name="report"),
 ]

django_project/IoTAnalyzer/views.py

@@ -1,7 +1,11 @@
 """REST endpoints exposed by IoT PreTester 4.6 Demo."""
 
 import json
+import logging
+import os
 import re
+import shutil
+import subprocess
 from pathlib import Path
 from uuid import uuid4
 
@@ -16,7 +20,7 @@ from rest_framework.permissions import AllowAny, IsAdminUser
 from rest_framework.response import Response
 from rest_framework.views import APIView
 
-from .analyze.security_analysis import collect_cloud_results
+from .analyze.security_analysis import analysis_log_path, collect_cloud_results
 from .db_create import (
     create_capture,
     create_device_type,
@@ -48,16 +52,56 @@ from .user_funcs import (
 )
 
 
+logger = logging.getLogger(__name__)
+
+
 def _validation_error(exc: ValidationError) -> Response:
     messages = getattr(exc, "messages", [str(exc)])
     return Response({"error": messages[0]}, status=status.HTTP_400_BAD_REQUEST)
 
 
+def _tool_version(name: str, args=("-v",)) -> str | None:
+    """First line of a tool's version output, or None when it is missing."""
+    path = shutil.which(name)
+    if not path:
+        return None
+    try:
+        out = subprocess.run([path, *args], capture_output=True, text=True, timeout=15)
+        first = (out.stdout or out.stderr or "").strip().splitlines()
+        return first[0][:120] if first else path
+    except Exception as exc:
+        return f"{path} (version check failed: {exc})"
+
+
 class HealthView(APIView):
+    """Service status including the external tools the analysis depends on."""
+
     permission_classes = [AllowAny]
 
     def get(self, request):
-        return Response({"status": "ok", "service": "IoT PreTester 4.6 Demo"})
+        from analyzer import __version__ as analyzer_version
+
+        tshark = _tool_version(os.environ.get("TSHARK_PATH") or "tshark")
+        upload_dir = str(settings.CAPTURE_UPLOAD_DIR)
+        data = {
+            "status": "ok" if tshark else "degraded",
+            "service": "IoT PreTester 4.6 Demo",
+            "analyzer_version": analyzer_version,
+            "tools": {
+                "tshark": tshark,
+                "hashcat": _tool_version("hashcat", ("--version",)),
+                "nmap": _tool_version("nmap", ("--version",)),
+            },
+            "upload_dir": upload_dir,
+            "upload_dir_writable": os.access(upload_dir, os.W_OK),
+            "log_dir": str(getattr(settings, "LOG_DIR", "")),
+            "log_level": getattr(settings, "LOG_LEVEL", "INFO"),
+            "packet_limit": settings.CAPTURE_PACKET_LIMIT or "unlimited",
+        }
+        if not tshark:
+            data["error"] = "tshark is not installed; capture analysis cannot run."
+            logger.error("Health check: tshark not found on PATH")
+        return Response(data)
 
 
 class LoginView(APIView):
@@ -293,15 +337,30 @@ class DeleteDeviceTypeView(APIView):
         return Response({"status": "success"})
 
 
+# Capture status -> payload shown while no finding report exists yet.
+_PENDING_CAPTURE_STATES = {
+    "analyzing": ("analyzing", "The security analysis is still running."),
+    "pending": ("analyzing", "The security analysis is queued."),
+    "analysis_failed": ("failed", "The security analysis failed. The error and the analysis log are shown below."),
+}
+
+
 class FindingsView(APIView):
     def get(self, request, file_id):
-        get_object_or_404(File, id=file_id)
+        capture = get_object_or_404(File, id=file_id)
         report = FindingReport.objects.filter(file_id=file_id).first()
         if report is None:
-            return Response(
+            state, message = _PENDING_CAPTURE_STATES.get(
+                capture.status,
+                ("empty", "No security analysis is available for this capture."),
+            )
+            response = Response(
                 {
-                    "status": "empty",
-                    "message": "No security analysis is available for this capture.",
+                    "status": state,
+                    "capture_status": capture.status,
+                    "message": message,
+                    "error": capture.error_message,
+                    "log_available": _log_exists(capture),
                     "summary": {
                         "total": 0,
                         "by_severity": {},
@@ -312,7 +371,47 @@ class FindingsView(APIView):
                     "findings": [],
                 }
             )
-        return Response(json.loads(report.result_json))
+            response["Cache-Control"] = "no-store"
+            return response
+        payload = json.loads(report.result_json)
+        payload["status"] = "ready"
+        payload["capture_status"] = capture.status
+        payload["error"] = capture.error_message
+        payload["log_available"] = _log_exists(capture)
+        response = Response(payload)
+        response["Cache-Control"] = "no-store"
+        return response
+
+
+def _log_exists(capture: File) -> bool:
+    path = analysis_log_path(capture.filename)
+    return bool(path and os.path.exists(path))
+
+
+class AnalysisLogView(APIView):
+    """Tail of the per-capture analysis log for troubleshooting."""
+
+    def get(self, request, file_id):
+        from analyzer.logutil import tail
+
+        capture = get_object_or_404(File, id=file_id)
+        path = analysis_log_path(capture.filename)
+        try:
+            lines = max(20, min(int(request.GET.get("lines", 400)), 5000))
+        except (TypeError, ValueError):
+            lines = 400
+        if not path or not os.path.exists(path):
+            return Response(
+                {"file_id": capture.id, "status": capture.status, "error": capture.error_message,
+                 "log": "", "available": False,
+                 "message": "No analysis log exists for this capture yet."},
+            )
+        response = Response({
+            "file_id": capture.id, "status": capture.status, "error": capture.error_message,
+            "available": True, "path": os.path.basename(path), "log": tail(path, lines),
+        })
+        response["Cache-Control"] = "no-store"
+        return response
 
 
 class CloudResultsView(APIView):