Some cleanup of debug logging.

Author: rkistner

packages/common/src/client/sync/bucket/SqliteBucketStorage.ts

@@ -94,11 +94,11 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
   async saveSyncData(batch: SyncDataBatch, fixedKeyFormat: boolean = false) {
     await this.writeTransaction(async (tx) => {
       for (const b of batch.buckets) {
-        const result = await tx.execute('INSERT INTO powersync_operations(op, data) VALUES(?, ?)', [
+        await tx.execute('INSERT INTO powersync_operations(op, data) VALUES(?, ?)', [
           'save',
           JSON.stringify({ buckets: [b.toJSON(fixedKeyFormat)] })
         ]);
-        this.logger.debug('saveSyncData', JSON.stringify(result));
+        this.logger.debug(`Saved batch of data for  bucket: ${b.bucket}, operations: ${b.data.length}`);
       }
     });
   }
@@ -117,7 +117,7 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
       await tx.execute('INSERT INTO powersync_operations(op, data) VALUES(?, ?)', ['delete_bucket', bucket]);
     });
 
-    this.logger.debug('done deleting bucket');
+    this.logger.debug(`Done deleting bucket ${bucket}`);
   }
 
   async hasCompletedSync() {
@@ -141,6 +141,11 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
       }
       return { ready: false, checkpointValid: false, checkpointFailures: r.checkpointFailures };
     }
+    if (priority == null) {
+      this.logger.debug(`Validated checksums checkpoint ${checkpoint.last_op_id}`);
+    } else {
+      this.logger.debug(`Validated checksums for partial checkpoint ${checkpoint.last_op_id}, priority ${priority}`);
+    }
 
     let buckets = checkpoint.buckets;
     if (priority !== undefined) {
@@ -160,7 +165,6 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
 
     const valid = await this.updateObjectsFromBuckets(checkpoint, priority);
     if (!valid) {
-      this.logger.debug('Not at a consistent checkpoint - cannot update local db');
       return { ready: false, checkpointValid: true };
     }
 
@@ -223,7 +227,6 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
     ]);
 
     const resultItem = rs.rows?.item(0);
-    this.logger.debug('validateChecksums priority, checkpoint, result item', priority, checkpoint, resultItem);
     if (!resultItem) {
       return {
         checkpointValid: false,
@@ -264,34 +267,32 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
 
     const opId = await cb();
 
-    this.logger.debug(`[updateLocalTarget] Updating target to checkpoint ${opId}`);
-
     return this.writeTransaction(async (tx) => {
       const anyData = await tx.execute('SELECT 1 FROM ps_crud LIMIT 1');
       if (anyData.rows?.length) {
         // if isNotEmpty
-        this.logger.debug('updateLocalTarget', 'ps crud is not empty');
+        this.logger.debug(`New data uploaded since write checkpoint ${opId} - need new write checkpoint`);
         return false;
       }
 
       const rs = await tx.execute("SELECT seq FROM sqlite_sequence WHERE name = 'ps_crud'");
       if (!rs.rows?.length) {
         // assert isNotEmpty
-        throw new Error('SQlite Sequence should not be empty');
+        throw new Error('SQLite Sequence should not be empty');
       }
 
       const seqAfter: number = rs.rows?.item(0)['seq'];
-      this.logger.debug('seqAfter', JSON.stringify(rs.rows?.item(0)));
       if (seqAfter != seqBefore) {
-        this.logger.debug('seqAfter != seqBefore', seqAfter, seqBefore);
+        this.logger.debug(
+          `New data uploaded since write checpoint ${opId} - need new write checkpoint (sequence updated)`
+        );
+
         // New crud data may have been uploaded since we got the checkpoint. Abort.
         return false;
       }
 
-      const response = await tx.execute("UPDATE ps_buckets SET target_op = CAST(? as INTEGER) WHERE name='$local'", [
-        opId
-      ]);
-      this.logger.debug(['[updateLocalTarget] Response from updating target_op ', JSON.stringify(response)]);
+      this.logger.debug(`Updating target write checkpoint to ${opId}`);
+      await tx.execute("UPDATE ps_buckets SET target_op = CAST(? as INTEGER) WHERE name='$local'", [opId]);
       return true;
     });
   }

packages/common/src/client/sync/stream/AbstractStreamingSyncImplementation.ts

@@ -327,11 +327,10 @@ export abstract class AbstractStreamingSyncImplementation
 
   async getWriteCheckpoint(): Promise<string> {
     const clientId = await this.options.adapter.getClientId();
-    this.logger.debug(`Creating write checkpoint for ${clientId}`);
     let path = `/write-checkpoint2.json?client_id=${clientId}`;
     const response = await this.options.remote.get(path);
     const checkpoint = response['data']['write_checkpoint'] as string;
-    this.logger.debug(`Got write checkpoint: ${checkpoint}`);
+    this.logger.debug(`Created write checkpoint: ${checkpoint}`);
     return checkpoint;
   }
 
@@ -374,10 +373,10 @@ The next upload iteration will be delayed.`);
               });
             } else {
               // Uploading is completed
-              this.logger.debug('Upload complete, creating write checkpoint');
               const neededUpdate = await this.options.adapter.updateLocalTarget(() => this.getWriteCheckpoint());
-              if (neededUpdate == false) {
-                this.logger.debug('No write checkpoint needed');
+              if (neededUpdate == false && checkedCrudItem != null) {
+                // Only log this if there was something to upload
+                this.logger.debug('Upload complete, no write checkpoint needed.');
               }
               break;
             }
@@ -1090,20 +1089,20 @@ The next upload iteration will be delayed.`);
     let result = await this.options.adapter.syncLocalDatabase(checkpoint);
 
     if (!result.checkpointValid) {
-      this.logger.debug('Checksum mismatch in checkpoint, will reconnect');
+      this.logger.debug(`Checksum mismatch in checkpoint ${checkpoint.last_op_id}, will reconnect`);
       // This means checksums failed. Start again with a new checkpoint.
       // TODO: better back-off
       await new Promise((resolve) => setTimeout(resolve, 50));
       return { applied: false, endIteration: true };
     } else if (!result.ready) {
       this.logger.debug(
-        'Could not apply checkpoint due to local data. We will retry applying the checkpoint after that upload is completed.'
+        `Could not apply checkpoint ${checkpoint.last_op_id} due to local data. We will retry applying the checkpoint after that upload is completed.`
       );
 
       return { applied: false, endIteration: false };
     }
 
-    this.logger.debug('validated checkpoint', checkpoint);
+    this.logger.debug(`Applied checkpoint ${checkpoint.last_op_id}`, checkpoint);
     this.updateSyncStatus({
       connected: true,
       lastSyncedAt: new Date(),