Super aggressive logging

2025-07-21 16:12:50 +02:00
parent 4c4a1991ca
commit a90a38bdcf
4 changed files with 468 additions and 68 deletions
--- a/mobile/apps/photos/lib/services/machine_learning/face_thumbnail_generator.dart
+++ b/mobile/apps/photos/lib/services/machine_learning/face_thumbnail_generator.dart
@@ -35,14 +35,27 @@ class FaceThumbnailGenerator extends SuperIsolate {
  /// Uses [generateFaceThumbnailsUsingCanvas] inside the isolate.
  Future<List<Uint8List>> generateFaceThumbnails(
    String imagePath,
-    List<FaceBox> faceBoxes,
-  ) async {
+    List<FaceBox> faceBoxes, {
+    int? fileID,
+  }) async {
    try {
      _logger.info(
-        "Generating face thumbnails for ${faceBoxes.length} face boxes in $imagePath",
+        "[$fileID] FaceThumbnailGenerator START: Generating face thumbnails for ${faceBoxes.length} face boxes in $imagePath",
      );
+
+      _logger
+          .info("[$fileID] Converting ${faceBoxes.length} face boxes to JSON");
      final List<Map<String, dynamic>> faceBoxesJson =
          faceBoxes.map((box) => box.toJson()).toList();
+      _logger.info(
+        "[$fileID] Face boxes converted to JSON, preparing isolate operation",
+      );
+
+      _logger.info(
+        "[$fileID] Running generateFaceThumbnails in isolate with imagePath: $imagePath",
+      );
+      final stopwatch = Stopwatch()..start();
+
      final List<Uint8List> faces = await runInIsolate(
        IsolateOperation.generateFaceThumbnails,
        {
@@ -50,15 +63,54 @@ class FaceThumbnailGenerator extends SuperIsolate {
          'faceBoxesList': faceBoxesJson,
        },
      ).then((value) => value.cast<Uint8List>());
-      _logger.info("Generated face thumbnails");
-      final compressedFaces =
-          await compressFaceThumbnails({'listPngBytes': faces});
+
+      stopwatch.stop();
      _logger.info(
-        "Compressed face thumbnails from sizes ${faces.map((e) => e.length / 1024).toList()} to ${compressedFaces.map((e) => e.length / 1024).toList()} kilobytes",
+        "[$fileID] Isolate operation completed in ${stopwatch.elapsedMilliseconds}ms",
      );
+      _logger.info(
+        "[$fileID] Generated ${faces.length} face thumbnails with sizes: ${faces.map((e) => '${(e.length / 1024).toStringAsFixed(1)}KB').toList()}",
+      );
+
+      if (faces.length != faceBoxes.length) {
+        _logger.severe(
+          "[$fileID] Mismatch: Expected ${faceBoxes.length} face thumbnails but got ${faces.length}",
+        );
+      }
+
+      _logger.info("[$fileID] Starting face thumbnail compression");
+      final compressionStopwatch = Stopwatch()..start();
+
+      final compressedFaces =
+          await compressFaceThumbnails({'listPngBytes': faces}, fileID: fileID);
+
+      compressionStopwatch.stop();
+      _logger.info(
+        "[$fileID] Compression completed in ${compressionStopwatch.elapsedMilliseconds}ms",
+      );
+      _logger.info(
+        "[$fileID] Compressed face thumbnails from sizes ${faces.map((e) => '${(e.length / 1024).toStringAsFixed(1)}KB').toList()} to ${compressedFaces.map((e) => '${(e.length / 1024).toStringAsFixed(1)}KB').toList()}",
+      );
+
+      final totalOriginalSize =
+          faces.fold<int>(0, (sum, face) => sum + face.length);
+      final totalCompressedSize =
+          compressedFaces.fold<int>(0, (sum, face) => sum + face.length);
+      final compressionRatio = totalOriginalSize > 0
+          ? (totalCompressedSize / totalOriginalSize * 100).toStringAsFixed(1)
+          : "0.0";
+
+      _logger.info(
+        "[$fileID] FaceThumbnailGenerator END: Total size reduced from ${(totalOriginalSize / 1024).toStringAsFixed(1)}KB to ${(totalCompressedSize / 1024).toStringAsFixed(1)}KB (${compressionRatio}% of original)",
+      );
+
      return compressedFaces;
    } catch (e, s) {
-      _logger.severe("Failed to generate face thumbnails", e, s);
+      _logger.severe(
+        "[$fileID] Failed to generate face thumbnails for $imagePath",
+        e,
+        s,
+      );
      rethrow;
    }
  }
--- a/mobile/apps/photos/lib/utils/face/face_thumbnail_cache.dart
+++ b/mobile/apps/photos/lib/utils/face/face_thumbnail_cache.dart
@@ -46,8 +46,12 @@ Uint8List? checkInMemoryCachedCropForPersonOrClusterID(
  return cachedCover;
 }

-Uint8List? _checkInMemoryCachedCropForFaceID(String faceID) {
+Uint8List? _checkInMemoryCachedCropForFaceID(String faceID, int? fileID) {
+  _logger.info("[$fileID] Checking in-memory cache for faceID: $faceID");
  final Uint8List? cachedCover = _faceCropCache.get(faceID);
+  _logger.info(
+    "[$fileID] In-memory cache result for faceID $faceID: ${cachedCover != null ? 'found (${cachedCover.length} bytes)' : 'not found'}",
+  );
  return cachedCover;
 }

@@ -80,10 +84,21 @@ Future<void> _putCachedCropForFaceID(
  String faceID,
  Uint8List data, [
  String? personOrClusterID,
+  int? fileID,
 ]) async {
+  _logger.info(
+    "[$fileID] _putCachedCropForFaceID: faceID=$faceID, dataSize=${data.length} bytes, personOrClusterID=$personOrClusterID",
+  );
  _faceCropCache.put(faceID, data);
+  _logger.info("[$fileID] Put faceID $faceID in memory cache");
  if (personOrClusterID != null) {
+    _logger.info(
+      "[$fileID] Putting faceID $faceID for personOrClusterID $personOrClusterID in DB",
+    );
    await putFaceIdCachedForPersonOrCluster(personOrClusterID, faceID);
+    _logger.info(
+      "[$fileID] Successfully put faceID $faceID for personOrClusterID $personOrClusterID in DB",
+    );
  }
 }

@@ -108,104 +123,265 @@ Future<Map<String, Uint8List>?> getCachedFaceCrops(
  String? personOrClusterID,
  required bool useTempCache,
 }) async {
+  _logger.info(
+    "[${enteFile.uploadedFileID}] getCachedFaceCrops START: faces=${faces.length}, fetchAttempt=$fetchAttempt, useFullFile=$useFullFile, personOrClusterID=$personOrClusterID, useTempCache=$useTempCache",
+  );
  try {
    final faceIdToCrop = <String, Uint8List>{};
    final facesWithoutCrops = <String, FaceBox>{};
-    _logger.info("Now getting cached face crops for ${faces.length} faces");
+    _logger.info(
+      "[${enteFile.uploadedFileID}] Initialized maps: faceIdToCrop and facesWithoutCrops",
+    );
+    _logger.info(
+      "[${enteFile.uploadedFileID}] Processing ${faces.length} faces with IDs: ${faces.map((f) => f.faceID).toList()}",
+    );
+
+    // Validate faces have valid detection boxes
    for (final face in faces) {
-      final Uint8List? cachedFace =
-          _checkInMemoryCachedCropForFaceID(face.faceID);
+      if (face.detection.box.width <= 0 || face.detection.box.height <= 0) {
+        _logger.severe(
+          "[${enteFile.uploadedFileID}] Face ${face.faceID} has invalid detection box: ${face.detection.box}",
+        );
+      }
+    }
+
+    for (final face in faces) {
+      _logger.info(
+        "[${enteFile.uploadedFileID}] face ${face.faceID} has score ${face.score}",
+      );
+      _logger
+          .info("[${enteFile.uploadedFileID}] Processing face ${face.faceID}");
+      final Uint8List? cachedFace = _checkInMemoryCachedCropForFaceID(
+        face.faceID,
+        enteFile.uploadedFileID,
+      );
      if (cachedFace != null) {
+        _logger.info(
+          "[${enteFile.uploadedFileID}] Found face ${face.faceID} in memory cache, size: ${cachedFace.length} bytes",
+        );
        faceIdToCrop[face.faceID] = cachedFace;
      } else {
-        final faceCropCacheFile = cachedFaceCropPath(face.faceID, useTempCache);
-        if ((await faceCropCacheFile.exists())) {
+        _logger.info(
+          "[${enteFile.uploadedFileID}] Face ${face.faceID} not in memory cache, checking file cache",
+        );
+        final faceCropCacheFile = cachedFaceCropPath(
+          face.faceID,
+          useTempCache,
+          enteFile.uploadedFileID,
+        );
+        _logger.info(
+          "[${enteFile.uploadedFileID}] Cache file path for face ${face.faceID}: ${faceCropCacheFile.path}",
+        );
+
+        // Check if cache directory exists
+        final cacheDir = faceCropCacheFile.parent;
+        if (!(await cacheDir.exists())) {
+          _logger.severe(
+            "[${enteFile.uploadedFileID}] Cache directory does not exist: ${cacheDir.path}",
+          );
          try {
-            final data = await faceCropCacheFile.readAsBytes();
-            if (data.isNotEmpty) {
-              await _putCachedCropForFaceID(
-                face.faceID,
-                data,
-                personOrClusterID,
-              );
-              faceIdToCrop[face.faceID] = data;
-            } else {
-              _logger.severe(
-                "Cached face crop for faceID ${face.faceID} is empty, deleting file ${faceCropCacheFile.path}",
-              );
-              await faceCropCacheFile.delete();
-              facesWithoutCrops[face.faceID] = face.detection.box;
-            }
+            await cacheDir.create(recursive: true);
+            _logger.info(
+              "[${enteFile.uploadedFileID}] Created cache directory: ${cacheDir.path}",
+            );
          } catch (e, s) {
            _logger.severe(
-              "Error reading cached face crop for faceID ${face.faceID} from file ${faceCropCacheFile.path}",
+              "[${enteFile.uploadedFileID}] Failed to create cache directory: ${cacheDir.path}",
              e,
              s,
            );
            facesWithoutCrops[face.faceID] = face.detection.box;
+            continue;
+          }
+        }
+
+        if ((await faceCropCacheFile.exists())) {
+          _logger.info(
+            "[${enteFile.uploadedFileID}] Cache file exists for face ${face.faceID}, attempting to read",
+          );
+          try {
+            final data = await faceCropCacheFile.readAsBytes();
+            _logger.info(
+              "[${enteFile.uploadedFileID}] Read ${data.length} bytes from cache file for face ${face.faceID}",
+            );
+            if (data.isNotEmpty) {
+              _logger.info(
+                "[${enteFile.uploadedFileID}] Cache file data is valid for face ${face.faceID}, putting in memory cache",
+              );
+              await _putCachedCropForFaceID(
+                face.faceID,
+                data,
+                personOrClusterID,
+                enteFile.uploadedFileID,
+              );
+              faceIdToCrop[face.faceID] = data;
+              _logger.info(
+                "[${enteFile.uploadedFileID}] Successfully cached face ${face.faceID} from file",
+              );
+            } else {
+              _logger.severe(
+                "[${enteFile.uploadedFileID}] Cached face crop for faceID ${face.faceID} is empty, deleting file ${faceCropCacheFile.path}",
+              );
+              await faceCropCacheFile.delete();
+              facesWithoutCrops[face.faceID] = face.detection.box;
+              _logger.info(
+                "[${enteFile.uploadedFileID}] Added face ${face.faceID} to facesWithoutCrops due to empty cache file",
+              );
+            }
+          } catch (e, s) {
+            _logger.severe(
+              "[${enteFile.uploadedFileID}] Error reading cached face crop for faceID ${face.faceID} from file ${faceCropCacheFile.path}",
+              e,
+              s,
+            );
+            facesWithoutCrops[face.faceID] = face.detection.box;
+            _logger.info(
+              "[${enteFile.uploadedFileID}] Added face ${face.faceID} to facesWithoutCrops due to read error",
+            );
          }
        } else {
+          _logger.info(
+            "[${enteFile.uploadedFileID}] Cache file does not exist for face ${face.faceID}",
+          );
          facesWithoutCrops[face.faceID] = face.detection.box;
+          _logger.info(
+            "[${enteFile.uploadedFileID}] Added face ${face.faceID} to facesWithoutCrops",
+          );
        }
      }
    }
+    _logger.info(
+      "[${enteFile.uploadedFileID}] Cache check complete: ${faceIdToCrop.length} faces found in cache, ${facesWithoutCrops.length} faces need generation",
+    );
    if (facesWithoutCrops.isEmpty) {
-      _logger.info("All face crops gotten from cache");
+      _logger.info(
+        "[${enteFile.uploadedFileID}] All face crops gotten from cache, returning ${faceIdToCrop.length} crops",
+      );
      return faceIdToCrop;
    }
+    _logger.info(
+      "[${enteFile.uploadedFileID}] Faces without crops: ${facesWithoutCrops.keys.toList()}",
+    );

    if (!useFullFile) {
+      _logger.info(
+        "[${enteFile.uploadedFileID}] Using thumbnail mode, checking thumbnail cache for ${facesWithoutCrops.length} faces",
+      );
      for (final face in faces) {
        if (facesWithoutCrops.containsKey(face.faceID)) {
          final Uint8List? cachedFaceThumbnail =
              _faceCropThumbnailCache.get(face.faceID);
          if (cachedFaceThumbnail != null) {
+            _logger.info(
+              "[${enteFile.uploadedFileID}] Found face ${face.faceID} in thumbnail cache, size: ${cachedFaceThumbnail.length} bytes",
+            );
            faceIdToCrop[face.faceID] = cachedFaceThumbnail;
            facesWithoutCrops.remove(face.faceID);
+          } else {
+            _logger.info(
+              "[${enteFile.uploadedFileID}] Face ${face.faceID} not found in thumbnail cache",
+            );
          }
        }
      }
+      _logger.info(
+        "[${enteFile.uploadedFileID}] After thumbnail cache check: ${facesWithoutCrops.length} faces still need generation",
+      );
      if (facesWithoutCrops.isEmpty) {
+        _logger.info(
+          "[${enteFile.uploadedFileID}] All faces found in thumbnail cache, returning ${faceIdToCrop.length} crops",
+        );
        return faceIdToCrop;
      }
    }

+    _logger.info(
+      "[${enteFile.uploadedFileID}] Starting face crop generation for ${facesWithoutCrops.length} faces using ${useFullFile ? 'full file' : 'thumbnail'}",
+    );
    final result = await _getFaceCropsUsingHeapPriorityQueue(
      enteFile,
      facesWithoutCrops,
      useFullFile: useFullFile,
    );
+    _logger.info(
+      "[${enteFile.uploadedFileID}] Face crop generation completed, result: ${result != null ? 'success with ${result.length} crops' : 'null'}",
+    );
    if (result == null) {
+      _logger.severe(
+        "[${enteFile.uploadedFileID}] Face crop generation returned null, returning ${faceIdToCrop.isEmpty ? 'null' : '${faceIdToCrop.length} cached crops'}",
+      );
      return (faceIdToCrop.isEmpty) ? null : faceIdToCrop;
    }
+    _logger.info(
+      "[${enteFile.uploadedFileID}] Processing ${result.length} generated face crops",
+    );
    for (final entry in result.entries) {
      final Uint8List? computedCrop = result[entry.key];
      if (computedCrop != null) {
+        _logger.info(
+          "[${enteFile.uploadedFileID}] Processing generated crop for face ${entry.key}, size: ${computedCrop.length} bytes",
+        );
        faceIdToCrop[entry.key] = computedCrop;
        if (useFullFile) {
+          _logger.info(
+            "[${enteFile.uploadedFileID}] Caching generated crop for face ${entry.key} in memory and file",
+          );
          await _putCachedCropForFaceID(
            entry.key,
            computedCrop,
            personOrClusterID,
+            enteFile.uploadedFileID,
+          );
+          final faceCropCacheFile = cachedFaceCropPath(
+            entry.key,
+            useTempCache,
+            enteFile.uploadedFileID,
          );
-          final faceCropCacheFile = cachedFaceCropPath(entry.key, useTempCache);
          try {
-            // ignore: unawaited_futures
-            faceCropCacheFile.writeAsBytes(computedCrop);
+            _logger.info(
+              "[${enteFile.uploadedFileID}] Writing crop to file: ${faceCropCacheFile.path}",
+            );
+
+            // Ensure directory exists before writing
+            final cacheDir = faceCropCacheFile.parent;
+            if (!(await cacheDir.exists())) {
+              _logger.severe(
+                "[${enteFile.uploadedFileID}] Creating cache directory before write: ${cacheDir.path}",
+              );
+              await cacheDir.create(recursive: true);
+            }
+
+            await faceCropCacheFile.writeAsBytes(computedCrop);
+            _logger.info(
+              "[${enteFile.uploadedFileID}] Successfully wrote crop file for face ${entry.key}",
+            );
          } catch (e, s) {
            _logger.severe(
-              "Error writing cached face crop for faceID ${entry.key} to file ${faceCropCacheFile.path}",
+              "[${enteFile.uploadedFileID}] Error writing cached face crop for faceID ${entry.key} to file ${faceCropCacheFile.path}",
              e,
              s,
            );
          }
        } else {
+          _logger.info(
+            "[${enteFile.uploadedFileID}] Caching generated crop for face ${entry.key} in thumbnail cache",
+          );
          _faceCropThumbnailCache.put(entry.key, computedCrop);
        }
+      } else {
+        _logger.severe(
+          "[${enteFile.uploadedFileID}] Generated crop for face ${entry.key} is null",
+        );
      }
    }
+    _logger.info(
+      "[${enteFile.uploadedFileID}] Final result: ${faceIdToCrop.length} total face crops, returning ${faceIdToCrop.isEmpty ? 'null' : 'map with ${faceIdToCrop.length} entries'}",
+    );
    return faceIdToCrop.isEmpty ? null : faceIdToCrop;
  } catch (e, s) {
+    _logger.severe(
+      "[${enteFile.uploadedFileID}] getCachedFaceCrops EXCEPTION: faces=${faces.map((face) => face.faceID).toList()}, error=$e",
+    );
    if (e is! TaskQueueTimeoutException &&
        e is! TaskQueueOverflowException &&
        e is! TaskQueueCancelledException) {
@@ -213,9 +389,12 @@ Future<Map<String, Uint8List>?> getCachedFaceCrops(
        final backoff = Duration(
          milliseconds: 100 * pow(2, fetchAttempt + 1).toInt(),
        );
+        _logger.info(
+          "[${enteFile.uploadedFileID}] Will retry after ${backoff.inMilliseconds}ms delay",
+        );
        await Future.delayed(backoff);
        _logger.severe(
-          "Error getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()}, retrying (attempt ${fetchAttempt + 1}) in ${backoff.inMilliseconds} ms",
+          "[${enteFile.uploadedFileID}] Error getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()}, retrying (attempt ${fetchAttempt + 1}) in ${backoff.inMilliseconds} ms",
          e,
          s,
        );
@@ -228,15 +407,18 @@ Future<Map<String, Uint8List>?> getCachedFaceCrops(
        );
      }
      _logger.severe(
-        "Error getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()}",
+        "[${enteFile.uploadedFileID}] Error getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()}",
        e,
        s,
      );
    } else {
      _logger.severe(
-        "Stopped getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()} due to $e",
+        "[${enteFile.uploadedFileID}] Stopped getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()} due to $e",
      );
    }
+    _logger.info(
+      "[${enteFile.uploadedFileID}] getCachedFaceCrops returning null due to exception",
+    );
    return null;
  }
 }
@@ -303,6 +485,9 @@ Future<Map<String, Uint8List>?> _getFaceCropsUsingHeapPriorityQueue(
  Map<String, FaceBox> faceBoxeMap, {
  bool useFullFile = true,
 }) async {
+  _logger.info(
+    "[${file.uploadedFileID}] _getFaceCropsUsingHeapPriorityQueue START: faces=${faceBoxeMap.length}, useFullFile=$useFullFile",
+  );
  final completer = Completer<Map<String, Uint8List>?>();

  late final TaskQueue relevantTaskQueue;
@@ -310,21 +495,46 @@ Future<Map<String, Uint8List>?> _getFaceCropsUsingHeapPriorityQueue(
  if (useFullFile) {
    relevantTaskQueue = _queueFullFileFaceGenerations;
    taskId = [file.uploadedFileID!, "-full"].join();
+    _logger.info(
+      "[${file.uploadedFileID}] Using full file task queue with taskId: $taskId",
+    );
  } else {
    relevantTaskQueue = _queueThumbnailFaceGenerations;
    taskId = [file.uploadedFileID!, "-thumbnail"].join();
+    _logger.info(
+      "[${file.uploadedFileID}] Using thumbnail task queue with taskId: $taskId",
+    );
  }

-  await relevantTaskQueue.addTask(taskId, () async {
-    final faceCrops = await _getFaceCrops(
-      file,
-      faceBoxeMap,
-      useFullFile: useFullFile,
+  _logger.info("[${file.uploadedFileID}] Adding task to queue: $taskId");
+  try {
+    await relevantTaskQueue.addTask(taskId, () async {
+      _logger.info("[${file.uploadedFileID}] Task $taskId started execution");
+      final faceCrops = await _getFaceCrops(
+        file,
+        faceBoxeMap,
+        useFullFile: useFullFile,
+      );
+      _logger.info(
+        "[${file.uploadedFileID}] Task $taskId completed, result: ${faceCrops != null ? '${faceCrops.length} crops' : 'null'}",
+      );
+      completer.complete(faceCrops);
+    });
+  } catch (e, s) {
+    _logger.severe(
+      "[${file.uploadedFileID}] Error adding task $taskId to queue",
+      e,
+      s,
    );
-    completer.complete(faceCrops);
-  });
+    completer.complete(null);
+  }

-  return completer.future;
+  _logger.info("[${file.uploadedFileID}] Waiting for task $taskId to complete");
+  final result = await completer.future;
+  _logger.info(
+    "[${file.uploadedFileID}] _getFaceCropsUsingHeapPriorityQueue END: taskId=$taskId, result=${result != null ? '${result.length} crops' : 'null'}",
+  );
+  return result;
 }

 Future<Map<String, Uint8List>?> _getFaceCrops(
@@ -333,39 +543,79 @@ Future<Map<String, Uint8List>?> _getFaceCrops(
  bool useFullFile = true,
 }) async {
  _logger.info(
-    "`_getFaceCrops` started for ${file.uploadedFileID} and ${faceBoxeMap.length} faces",
+    "[${file.uploadedFileID}] _getFaceCrops START: faces=${faceBoxeMap.length}, useFullFile=$useFullFile, fileType=${file.fileType}",
  );
  late String? imagePath;
  if (useFullFile && file.fileType != FileType.video) {
+    _logger.info("[${file.uploadedFileID}] Getting full file");
    final File? ioFile = await getFile(file);
    if (ioFile == null) {
-      _logger.severe("Failed to get file for face crop generation");
+      _logger.severe(
+        "[${file.uploadedFileID}] Failed to get file for face crop generation",
+      );
      return null;
    }
    imagePath = ioFile.path;
+    _logger.info(
+      "[${file.uploadedFileID}] Got full file path: $imagePath, exists: ${await ioFile.exists()}",
+    );
  } else {
+    _logger.info("[${file.uploadedFileID}] Getting thumbnail");
    final thumbnail = await getThumbnailForUploadedFile(file);
    if (thumbnail == null) {
-      _logger.severe("Failed to get thumbnail for face crop generation");
+      _logger.severe(
+        "[${file.uploadedFileID}] Failed to get thumbnail for face crop generation",
+      );
      return null;
    }
    imagePath = thumbnail.path;
+    _logger.info(
+      "[${file.uploadedFileID}] Got thumbnail path: $imagePath, exists: ${await thumbnail.exists()}",
+    );
  }
+
+  _logger.info("[${file.uploadedFileID}] Preparing face data for generation");
  final List<String> faceIds = [];
  final List<FaceBox> faceBoxes = [];
  for (final e in faceBoxeMap.entries) {
    faceIds.add(e.key);
    faceBoxes.add(e.value);
+    _logger.info(
+      "[${file.uploadedFileID}] Face ${e.key}: box=${e.value.x}, ${e.value.y}, ${e.value.width}, ${e.value.height}",
+    );
  }
-  final List<Uint8List> faceCrop =
-      await FaceThumbnailGenerator.instance.generateFaceThumbnails(
-    // await generateJpgFaceThumbnails(
-    imagePath,
-    faceBoxes,
+
+  _logger.info(
+    "[${file.uploadedFileID}] Calling FaceThumbnailGenerator with ${faceBoxes.length} face boxes",
  );
-  final Map<String, Uint8List> result = {};
-  for (int i = 0; i < faceCrop.length; i++) {
-    result[faceIds[i]] = faceCrop[i];
+  try {
+    final List<Uint8List> faceCrop =
+        await FaceThumbnailGenerator.instance.generateFaceThumbnails(
+      imagePath,
+      faceBoxes,
+      fileID: file.uploadedFileID,
+    );
+    _logger.info(
+      "[${file.uploadedFileID}] FaceThumbnailGenerator returned ${faceCrop.length} crops",
+    );
+
+    final Map<String, Uint8List> result = {};
+    for (int i = 0; i < faceCrop.length; i++) {
+      result[faceIds[i]] = faceCrop[i];
+      _logger.info(
+        "[${file.uploadedFileID}] Mapped face ${faceIds[i]} to crop of size ${faceCrop[i].length} bytes",
+      );
+    }
+    _logger.info(
+      "[${file.uploadedFileID}] _getFaceCrops END: returning ${result.length} face crops",
+    );
+    return result;
+  } catch (e, s) {
+    _logger.severe(
+      "[${file.uploadedFileID}] Error in FaceThumbnailGenerator.generateFaceThumbnails",
+      e,
+      s,
+    );
+    return null;
  }
-  return result;
 }
--- a/mobile/apps/photos/lib/utils/image_ml_util.dart
+++ b/mobile/apps/photos/lib/utils/image_ml_util.dart
@@ -146,20 +146,43 @@ Future<List<Uint8List>> generateFaceThumbnailsUsingCanvas(
  List<FaceBox> faceBoxes,
 ) async {
  int i = 0; // Index of the faceBox, initialized here for logging purposes
+
+  _logger.info(
+    "generateFaceThumbnailsUsingCanvas START: Processing ${faceBoxes.length} face boxes from $imagePath",
+  );
+
  try {
+    _logger.info("Decoding image from path: $imagePath");
+    final stopwatch = Stopwatch()..start();
+
    final decodedImage = await decodeImageFromPath(
      imagePath,
      includeRgbaBytes: false,
    );
    final Image img = decodedImage.image;
+
+    stopwatch.stop();
+    _logger.info(
+      "Image decoded successfully: ${img.width}x${img.height} in ${stopwatch.elapsedMilliseconds}ms",
+    );
    final futureFaceThumbnails = <Future<Uint8List>>[];
+    _logger.info("Starting face crop processing for ${faceBoxes.length} faces");
+
    for (final faceBox in faceBoxes) {
+      _logger.info(
+        "Processing face $i/${faceBoxes.length}: relative box=(${faceBox.x.toStringAsFixed(3)}, ${faceBox.y.toStringAsFixed(3)}, ${faceBox.width.toStringAsFixed(3)}, ${faceBox.height.toStringAsFixed(3)})",
+      );
+
      // Note that the faceBox values are relative to the image size, so we need to convert them to absolute values first
      final double xMinAbs = faceBox.x * img.width;
      final double yMinAbs = faceBox.y * img.height;
      final double widthAbs = faceBox.width * img.width;
      final double heightAbs = faceBox.height * img.height;

+      _logger.info(
+        "Face $i absolute coordinates: (${xMinAbs.toStringAsFixed(1)}, ${yMinAbs.toStringAsFixed(1)}, ${widthAbs.toStringAsFixed(1)}, ${heightAbs.toStringAsFixed(1)})",
+      );
+
      // Calculate the crop values by adding some padding around the face and making sure it's centered
      const regularPadding = 0.4;
      const minimumPadding = 0.1;
@@ -178,6 +201,10 @@ Future<List<Uint8List>> generateFaceThumbnailsUsingCanvas(
      final widthCropSafe = widthCrop.clamp(0, img.width - xCropSafe);
      final heightCropSafe = heightCrop.clamp(0, img.height - yCropSafe);

+      _logger.info(
+        "Face $i final crop area: (${xCropSafe.toStringAsFixed(1)}, ${yCropSafe.toStringAsFixed(1)}, ${widthCropSafe.toStringAsFixed(1)}, ${heightCropSafe.toStringAsFixed(1)})",
+      );
+
      futureFaceThumbnails.add(
        _cropAndEncodeCanvas(
          img,
@@ -189,12 +216,22 @@ Future<List<Uint8List>> generateFaceThumbnailsUsingCanvas(
      );
      i++;
    }
+
+    _logger.info("All face crop futures created, waiting for completion...");
+    final cropStopwatch = Stopwatch()..start();
+
    final List<Uint8List> faceThumbnails =
        await Future.wait(futureFaceThumbnails);
+
+    cropStopwatch.stop();
+    _logger.info(
+      "generateFaceThumbnailsUsingCanvas END: Generated ${faceThumbnails.length} thumbnails in ${cropStopwatch.elapsedMilliseconds}ms, sizes: ${faceThumbnails.map((t) => '${(t.length / 1024).toStringAsFixed(1)}KB').toList()}",
+    );
+
    return faceThumbnails;
  } catch (e, s) {
    _logger.severe(
-      'Error generating face thumbnails. cropImage problematic input argument: ${i}th facebox: ${faceBoxes[i].toString()}',
+      'generateFaceThumbnailsUsingCanvas ERROR: Failed at face $i/${faceBoxes.length}. FaceBox: ${i < faceBoxes.length ? faceBoxes[i].toString() : "index out of bounds"}. ImagePath: $imagePath',
      e,
      s,
    );
@@ -533,6 +570,11 @@ Future<Uint8List> _cropAndEncodeCanvas(
  required double width,
  required double height,
 }) async {
+  _logger.info(
+    "_cropAndEncodeCanvas: Cropping ${image.width}x${image.height} image at (${x.toStringAsFixed(1)}, ${y.toStringAsFixed(1)}) with size ${width.toStringAsFixed(1)}x${height.toStringAsFixed(1)}",
+  );
+
+  final cropStopwatch = Stopwatch()..start();
  final croppedImage = await _cropImage(
    image,
    x: x,
@@ -540,14 +582,39 @@ Future<Uint8List> _cropAndEncodeCanvas(
    width: width,
    height: height,
  );
-  return await _encodeImageToPng(croppedImage);
+  cropStopwatch.stop();
+
+  _logger.info(
+    "_cropAndEncodeCanvas: Crop completed in ${cropStopwatch.elapsedMilliseconds}ms, result: ${croppedImage.width}x${croppedImage.height}",
+  );
+
+  final encodeStopwatch = Stopwatch()..start();
+  final result = await _encodeImageToPng(croppedImage);
+  encodeStopwatch.stop();
+
+  _logger.info(
+    "_cropAndEncodeCanvas: PNG encoding completed in ${encodeStopwatch.elapsedMilliseconds}ms, size: ${(result.length / 1024).toStringAsFixed(1)}KB",
+  );
+
+  return result;
 }

-Future<List<Uint8List>> compressFaceThumbnails(Map args) async {
+Future<List<Uint8List>> compressFaceThumbnails(Map args, {int? fileID}) async {
+  _logger.info("[$fileID] compressFaceThumbnails START");
  final listPngBytes = args['listPngBytes'] as List<Uint8List>;
  final List<Future<Uint8List>> compressedBytesList = [];
+
+  _logger.info(
+    "[$fileID] compressFaceThumbnails START: Processing ${listPngBytes.length} thumbnails with quality=$_faceThumbnailCompressionQuality, minDimension=$_faceThumbnailMinDimension",
+  );
+
  try {
-    for (final pngBytes in listPngBytes) {
+    for (int i = 0; i < listPngBytes.length; i++) {
+      final pngBytes = listPngBytes[i];
+      _logger.info(
+        "[$fileID] Compressing thumbnail $i/${listPngBytes.length}, original size: ${(pngBytes.length / 1024).toStringAsFixed(1)}KB",
+      );
+
      final compressedBytes = FlutterImageCompress.compressWithList(
        pngBytes,
        quality: _faceThumbnailCompressionQuality,
@@ -557,10 +624,29 @@ Future<List<Uint8List>> compressFaceThumbnails(Map args) async {
      );
      compressedBytesList.add(compressedBytes);
    }
-    return await Future.wait(compressedBytesList);
+
+    _logger.info(
+      "[$fileID] Starting Future.wait for ${compressedBytesList.length} compression tasks",
+    );
+    final stopwatch = Stopwatch()..start();
+
+    final result = await Future.wait(compressedBytesList);
+
+    stopwatch.stop();
+    _logger.info(
+      "[$fileID] compressFaceThumbnails END: All ${result.length} compressions completed in ${stopwatch.elapsedMilliseconds}ms",
+    );
+
+    for (int i = 0; i < result.length; i++) {
+      _logger.info(
+        "[$fileID] Thumbnail $i: ${(listPngBytes[i].length / 1024).toStringAsFixed(1)}KB -> ${(result[i].length / 1024).toStringAsFixed(1)}KB (${((result[i].length / listPngBytes[i].length) * 100).toStringAsFixed(1)}%)",
+      );
+    }
+
+    return result;
  } catch (e, s) {
    _logger.severe(
-      'Failed to compress face thumbnail, using original. Size: ${listPngBytes.map((e) => e.length).toList()} bytes',
+      '[$fileID] Failed to compress face thumbnails. Original sizes: ${listPngBytes.map((e) => '${(e.length / 1024).toStringAsFixed(1)}KB').toList()}',
      e,
      s,
    );
--- a/mobile/apps/photos/lib/utils/thumbnail_util.dart
+++ b/mobile/apps/photos/lib/utils/thumbnail_util.dart
@@ -242,16 +242,28 @@ File cachedThumbnailPath(EnteFile file) {
  );
 }

-File cachedFaceCropPath(String faceID, bool useTempCache) {
+File cachedFaceCropPath(String faceID, bool useTempCache, [int? fileID]) {
+  final logger = Logger("FaceCropUtils");
+  logger.info(
+    "[$fileID] cachedFaceCropPath called: faceID=$faceID, useTempCache=$useTempCache",
+  );
+
  late final String thumbnailCacheDirectory;
  if (useTempCache) {
    thumbnailCacheDirectory =
        Configuration.instance.getThumbnailCacheDirectory();
+    logger
+        .info("[$fileID] Using temp cache directory: $thumbnailCacheDirectory");
  } else {
    thumbnailCacheDirectory =
        Configuration.instance.getPersonFaceThumbnailCacheDirectory();
+    logger.info(
+      "[$fileID] Using person face cache directory: $thumbnailCacheDirectory",
+    );
  }
-  return File(
-    thumbnailCacheDirectory + "/" + faceID,
-  );
+
+  final filePath = thumbnailCacheDirectory + "/" + faceID;
+  logger.info("[$fileID] Generated cache file path: $filePath");
+
+  return File(filePath);
 }