Reduce log severity from attachment queue service

packages/powersync/CHANGELOG.md

@@ -1,3 +1,7 @@
+## 2.3.4 (unreleased)
+
+- Reduce log noise from attachments service ([#408](https://github.com/powersync-ja/powersync.dart/issues/408)).
+
 ## 2.3.3
 
 - Restore the ability to call `disconnect()` on closed databases.

packages/powersync/lib/src/attachments/attachment_queue_service.dart

@@ -180,6 +180,7 @@ base class AttachmentQueue {
       var previouslyConnected = _db.currentStatus.connected;
       _syncStatusSubscription = _db.statusStream.listen((status) {
         if (!previouslyConnected && status.connected) {
+          _logger.fine('Scanning attachments after connecting');
           _syncingService.triggerSync();
         }
 

packages/powersync/lib/src/attachments/sync/syncing_service.dart

@@ -72,9 +72,9 @@ final class SyncingService {
       final attachments = await attachmentsService.withContext(
         (context) => context.getActiveAttachments(),
       );
-      logger.info('Found ${attachments.length} active attachments');
+      logger.finest('Found ${attachments.length} active attachments');
 
-      await handleSync(
+      await _handleSync(
         attachments,
         isActive: () => sub == _syncSubscription,
       );
@@ -88,7 +88,7 @@ final class SyncingService {
     _periodicSubscription = Stream<void>.periodic(period, (_) {}).listen((
       _,
     ) {
-      logger.info('Periodically syncing attachments');
+      logger.finer('Periodically syncing attachments (interval $period)');
       triggerSync();
     });
   }
@@ -133,43 +133,38 @@ final class SyncingService {
   /// [isActive]: Polled between attachments; when it returns `false` the loop
   /// exits early. Used by `stopSync` to interrupt a running batch within one
   /// attachment's processing time.
-  Future<void> handleSync(
+  Future<void> _handleSync(
     List<Attachment> attachments, {
     bool Function()? isActive,
   }) async {
-    logger.info('Starting handleSync with ${attachments.length} attachments');
+    logger.finer('Starting handleSync with ${attachments.length} attachments');
 
     for (final attachment in attachments) {
       if (isActive != null && !isActive()) {
         logger.info('Sync cancelled; stopping iteration early');
         return;
       }
 
-      logger.info(
+      logger.finest(
         'Processing attachment ${attachment.id} with state: ${attachment.state}',
       );
 
       try {
         final Attachment updated;
         switch (attachment.state) {
           case AttachmentState.queuedDownload:
-            logger.info('Downloading [${attachment.filename}]');
-            updated = await downloadAttachment(attachment);
+            updated = await _downloadAttachment(attachment);
           case AttachmentState.queuedUpload:
-            logger.info('Uploading [${attachment.filename}]');
-            updated = await uploadAttachment(attachment);
+            updated = await _uploadAttachment(attachment);
           case AttachmentState.queuedDelete:
-            logger.info('Deleting [${attachment.filename}]');
             // `deleteAttachment` needs a context (it removes the row in a
             // transaction); briefly re-acquire the mutex for just this row.
             updated = await attachmentsService.withContext(
               (context) => deleteAttachment(attachment, context),
             );
           case AttachmentState.synced:
-            logger.info('Attachment ${attachment.id} is already synced');
-            continue;
           case AttachmentState.archived:
-            logger.info('Attachment ${attachment.id} is archived');
+            // Nothing to do for these attachments.
             continue;
         }
 
@@ -186,8 +181,9 @@ final class SyncingService {
   ///
   /// [attachment]: The attachment to upload.
   /// Returns the updated attachment with its new state.
-  Future<Attachment> uploadAttachment(Attachment attachment) async {
-    logger.info('Starting upload for attachment ${attachment.id}');
+  Future<Attachment> _uploadAttachment(Attachment attachment) async {
+    logger.info(
+        'Starting upload for attachment ${attachment.id} (local filename ${attachment.filename})');
     try {
       if (attachment.localUri == null) {
         throw Exception('No localUri for attachment $attachment');
@@ -209,11 +205,12 @@ final class SyncingService {
         e,
         st,
       );
-      if (errorHandler != null) {
-        final shouldRetry =
-            await errorHandler!.onUploadError(attachment, e, st);
+      if (errorHandler case final errorHandler?) {
+        final shouldRetry = await errorHandler.onUploadError(attachment, e, st);
         if (!shouldRetry) {
-          logger.info('Attachment with ID ${attachment.id} has been archived');
+          logger.info(
+            'Attachment with ID ${attachment.id} has been archived after upload error',
+          );
           return attachment.copyWith(state: AttachmentState.archived);
         }
       }
@@ -225,7 +222,7 @@ final class SyncingService {
   ///
   /// [attachment]: The attachment to download.
   /// Returns the updated attachment with its new state.
-  Future<Attachment> downloadAttachment(Attachment attachment) async {
+  Future<Attachment> _downloadAttachment(Attachment attachment) async {
     logger.info('Starting download for attachment ${attachment.id}');
     final attachmentPath = attachment.filename;
     try {
@@ -239,19 +236,23 @@ final class SyncingService {
         hasSynced: true,
       );
     } catch (e, st) {
-      if (errorHandler != null) {
+      logger.warning(
+        'Download error for attachment $attachment',
+        e,
+        st,
+      );
+
+      if (errorHandler case final errorHandler?) {
         final shouldRetry =
-            await errorHandler!.onDownloadError(attachment, e, st);
+            await errorHandler.onDownloadError(attachment, e, st);
         if (!shouldRetry) {
-          logger.info('Attachment with ID ${attachment.id} has been archived');
+          logger.warning(
+            'Attachment with ID ${attachment.id} has been archived after download error',
+          );
           return attachment.copyWith(state: AttachmentState.archived);
         }
       }
-      logger.warning(
-        'Download attachment error for attachment $attachment',
-        e,
-        st,
-      );
+
       return attachment;
     }
   }
@@ -274,15 +275,17 @@ final class SyncingService {
       await context.deleteAttachment(attachment.id);
       return attachment.copyWith(state: AttachmentState.archived);
     } catch (e, st) {
-      if (errorHandler != null) {
-        final shouldRetry =
-            await errorHandler!.onDeleteError(attachment, e, st);
+      logger.warning('Error deleting attachment: $e', e, st);
+
+      if (errorHandler case final errorHandler?) {
+        final shouldRetry = await errorHandler.onDeleteError(attachment, e, st);
         if (!shouldRetry) {
-          logger.info('Attachment with ID ${attachment.id} has been archived');
+          logger.warning(
+            'Attachment with ID ${attachment.id} has been archived after error on delete.',
+          );
           return attachment.copyWith(state: AttachmentState.archived);
         }
       }
-      logger.warning('Error deleting attachment: $e', e, st);
       return attachment;
     }
   }

packages/powersync/test/attachments/attachment_test.dart

@@ -16,6 +16,7 @@ void main() {
   late LocalStorage localStorage;
   late AttachmentQueue queue;
   late StreamQueue<List<Attachment>> attachments;
+  late List<LogRecord> logRecords;
 
   Stream<List<WatchedAttachmentItem>> watchAttachments() {
     return db
@@ -34,11 +35,15 @@ void main() {
   setUp(() async {
     remoteStorage = MockRemoteStorage();
     localStorage = LocalStorage.inMemory();
+    final logger = Logger.detached('PowerSyncTest')..level = Level.ALL;
+    final records = <LogRecord>[];
+    logRecords = records;
+    logger.onRecord.listen(records.add);
 
     final (raw, database) = await testUtils.openInMemoryDatabase(
       schema: _schema,
       // Uncomment to see test logs
-      logger: Logger.detached('PowerSyncTest'),
+      logger: logger,
     );
     await database.initialize();
     db = database;
@@ -103,6 +108,19 @@ void main() {
 
     // File should have been deleted too
     expect(await localStorage.fileExists(localUri), isFalse);
+
+    final nonVerboseMessages = [
+      for (final LogRecord(:level, :message) in logRecords)
+        if (level >= Level.INFO) message
+    ];
+    expect(nonVerboseMessages, [
+      'Watching attachments...',
+      'AttachmentQueue started syncing.',
+      startsWith('Starting download for attachment'),
+      startsWith('Successfully downloaded file'),
+      'Deleting 1 archived attachments (exceeding maxArchivedCount=0)...',
+      'Deleted 1 archived attachments.'
+    ]);
   });
 
   test('stores relative paths', () async {
@@ -324,6 +342,20 @@ void main() {
       isA<Attachment>()
           .having((e) => e.state, 'state', AttachmentState.archived)
     ]);
+
+    expect(
+      logRecords,
+      contains(
+        isA<LogRecord>()
+            .having((e) => e.level, 'level', Level.WARNING)
+            .having(
+              (e) => e.message,
+              'message',
+              contains('Download error for attachment'),
+            )
+            .having((e) => e.error, 'error', 'test error'),
+      ),
+    );
   });
 
   test('stopSyncing interrupts an in-flight batch', () async {