diff --git a/packages/powersync/CHANGELOG.md b/packages/powersync/CHANGELOG.md index 4531c04e..fea724a2 100644 --- a/packages/powersync/CHANGELOG.md +++ b/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. diff --git a/packages/powersync/lib/src/attachments/attachment_queue_service.dart b/packages/powersync/lib/src/attachments/attachment_queue_service.dart index 9d8dcc5a..20ccbe2d 100644 --- a/packages/powersync/lib/src/attachments/attachment_queue_service.dart +++ b/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(); } diff --git a/packages/powersync/lib/src/attachments/sync/syncing_service.dart b/packages/powersync/lib/src/attachments/sync/syncing_service.dart index 37eaba84..ba61354d 100644 --- a/packages/powersync/lib/src/attachments/sync/syncing_service.dart +++ b/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.periodic(period, (_) {}).listen(( _, ) { - logger.info('Periodically syncing attachments'); + logger.finer('Periodically syncing attachments (interval $period)'); triggerSync(); }); } @@ -133,11 +133,11 @@ 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 handleSync( + Future _handleSync( List 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()) { @@ -145,7 +145,7 @@ final class SyncingService { return; } - logger.info( + logger.finest( 'Processing attachment ${attachment.id} with state: ${attachment.state}', ); @@ -153,23 +153,18 @@ final class SyncingService { 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 uploadAttachment(Attachment attachment) async { - logger.info('Starting upload for attachment ${attachment.id}'); + Future _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 downloadAttachment(Attachment attachment) async { + Future _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; } } diff --git a/packages/powersync/test/attachments/attachment_test.dart b/packages/powersync/test/attachments/attachment_test.dart index 16f8996c..d62b4fdd 100644 --- a/packages/powersync/test/attachments/attachment_test.dart +++ b/packages/powersync/test/attachments/attachment_test.dart @@ -16,6 +16,7 @@ void main() { late LocalStorage localStorage; late AttachmentQueue queue; late StreamQueue> attachments; + late List logRecords; Stream> 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 = []; + 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() .having((e) => e.state, 'state', AttachmentState.archived) ]); + + expect( + logRecords, + contains( + isA() + .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 {