Skip to content

Commit fe30b17

Browse files
rkistnerwhygee-dev
rkistner
authored and
whygee-dev
committed
Improve logging (powersync-ja#659)
1 parent 4b1504e commit fe30b17

File tree

7 files changed

+53
-40
lines changed

7 files changed

+53
-40
lines changed

‎.changeset/fresh-laws-join.md‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,8 @@
1+
---
2+
'@powersync/react-native': minor
3+
'@powersync/common': minor
4+
'@powersync/node': minor
5+
'@powersync/web': minor
6+
---
7+
8+
Propagate logger from PowerSyncDatabase to streaming sync and remote implementations, and tweak some log messages.

‎packages/common/src/client/AbstractPowerSyncDatabase.ts‎

Lines changed: 7 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -127,7 +127,6 @@ export const DEFAULT_WATCH_THROTTLE_MS = 30;
127127

128128
export const DEFAULT_POWERSYNC_DB_OPTIONS = {
129129
retryDelayMs: 5000,
130-
logger: Logger.get('PowerSyncDatabase'),
131130
crudUploadThrottleMs: DEFAULT_CRUD_UPLOAD_THROTTLE_MS
132131
};
133132

@@ -176,6 +175,8 @@ export abstract class AbstractPowerSyncDatabase extends BaseObserver<PowerSyncDB
176175

177176
protected runExclusiveMutex: Mutex;
178177

178+
logger: ILogger;
179+
179180
constructor(options: PowerSyncDatabaseOptionsWithDBAdapter);
180181
constructor(options: PowerSyncDatabaseOptionsWithOpenFactory);
181182
constructor(options: PowerSyncDatabaseOptionsWithSettings);
@@ -199,6 +200,8 @@ export abstract class AbstractPowerSyncDatabase extends BaseObserver<PowerSyncDB
199200
throw new Error('The provided `database` option is invalid.');
200201
}
201202

203+
this.logger = options.logger ?? Logger.get(`PowerSyncDatabase[${this._database.name}]`);
204+
202205
this.bucketStorageAdapter = this.generateBucketStorageAdapter();
203206
this.closed = false;
204207
this.currentStatus = new SyncStatus({});
@@ -419,7 +422,7 @@ export abstract class AbstractPowerSyncDatabase extends BaseObserver<PowerSyncDB
419422
try {
420423
schema.validate();
421424
} catch (ex) {
422-
this.options.logger?.warn('Schema validation failed. Unexpected behaviour could occur', ex);
425+
this.logger.warn('Schema validation failed. Unexpected behaviour could occur', ex);
423426
}
424427
this._schema = schema;
425428

@@ -428,10 +431,6 @@ export abstract class AbstractPowerSyncDatabase extends BaseObserver<PowerSyncDB
428431
this.iterateListeners(async (cb) => cb.schemaChanged?.(schema));
429432
}
430433

431-
get logger() {
432-
return this.options.logger!;
433-
}
434-
435434
/**
436435
* Wait for initialization to complete.
437436
* While initializing is automatic, this helps to catch and report initialization errors.
@@ -876,7 +875,7 @@ export abstract class AbstractPowerSyncDatabase extends BaseObserver<PowerSyncDB
876875
* @param options Options for configuring watch behavior
877876
*/
878877
watchWithCallback(sql: string, parameters?: any[], handler?: WatchHandler, options?: SQLWatchOptions): void {
879-
const { onResult, onError = (e: Error) => this.options.logger?.error(e) } = handler ?? {};
878+
const { onResult, onError = (e: Error) => this.logger.error(e) } = handler ?? {};
880879
if (!onResult) {
881880
throw new Error('onResult is required');
882881
}
@@ -1031,7 +1030,7 @@ export abstract class AbstractPowerSyncDatabase extends BaseObserver<PowerSyncDB
10311030
* @returns A dispose function to stop watching for changes
10321031
*/
10331032
onChangeWithCallback(handler?: WatchOnChangeHandler, options?: SQLWatchOptions): () => void {
1034-
const { onChange, onError = (e: Error) => this.options.logger?.error(e) } = handler ?? {};
1033+
const { onChange, onError = (e: Error) => this.logger.error(e) } = handler ?? {};
10351034
if (!onChange) {
10361035
throw new Error('onChange is required');
10371036
}

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

Lines changed: 16 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -92,11 +92,11 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
9292
async saveSyncData(batch: SyncDataBatch, fixedKeyFormat: boolean = false) {
9393
await this.writeTransaction(async (tx) => {
9494
for (const b of batch.buckets) {
95-
const result = await tx.execute('INSERT INTO powersync_operations(op, data) VALUES(?, ?)', [
95+
await tx.execute('INSERT INTO powersync_operations(op, data) VALUES(?, ?)', [
9696
'save',
9797
JSON.stringify({ buckets: [b.toJSON(fixedKeyFormat)] })
9898
]);
99-
this.logger.debug('saveSyncData', JSON.stringify(result));
99+
this.logger.debug(`Saved batch of data for bucket: ${b.bucket}, operations: ${b.data.length}`);
100100
}
101101
});
102102
}
@@ -115,7 +115,7 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
115115
await tx.execute('INSERT INTO powersync_operations(op, data) VALUES(?, ?)', ['delete_bucket', bucket]);
116116
});
117117

118-
this.logger.debug('done deleting bucket');
118+
this.logger.debug(`Done deleting bucket ${bucket}`);
119119
}
120120

121121
async hasCompletedSync() {
@@ -139,6 +139,11 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
139139
}
140140
return { ready: false, checkpointValid: false, checkpointFailures: r.checkpointFailures };
141141
}
142+
if (priority == null) {
143+
this.logger.debug(`Validated checksums checkpoint ${checkpoint.last_op_id}`);
144+
} else {
145+
this.logger.debug(`Validated checksums for partial checkpoint ${checkpoint.last_op_id}, priority ${priority}`);
146+
}
142147

143148
let buckets = checkpoint.buckets;
144149
if (priority !== undefined) {
@@ -158,7 +163,6 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
158163

159164
const valid = await this.updateObjectsFromBuckets(checkpoint, priority);
160165
if (!valid) {
161-
this.logger.debug('Not at a consistent checkpoint - cannot update local db');
162166
return { ready: false, checkpointValid: true };
163167
}
164168

@@ -221,7 +225,6 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
221225
]);
222226

223227
const resultItem = rs.rows?.item(0);
224-
this.logger.debug('validateChecksums priority, checkpoint, result item', priority, checkpoint, resultItem);
225228
if (!resultItem) {
226229
return {
227230
checkpointValid: false,
@@ -262,34 +265,32 @@ export class SqliteBucketStorage extends BaseObserver<BucketStorageListener> imp
262265

263266
const opId = await cb();
264267

265-
this.logger.debug(`[updateLocalTarget] Updating target to checkpoint ${opId}`);
266-
267268
return this.writeTransaction(async (tx) => {
268269
const anyData = await tx.execute('SELECT 1 FROM ps_crud LIMIT 1');
269270
if (anyData.rows?.length) {
270271
// if isNotEmpty
271-
this.logger.debug('updateLocalTarget', 'ps crud is not empty');
272+
this.logger.debug(`New data uploaded since write checkpoint ${opId} - need new write checkpoint`);
272273
return false;
273274
}
274275

275276
const rs = await tx.execute("SELECT seq FROM sqlite_sequence WHERE name = 'ps_crud'");
276277
if (!rs.rows?.length) {
277278
// assert isNotEmpty
278-
throw new Error('SQlite Sequence should not be empty');
279+
throw new Error('SQLite Sequence should not be empty');
279280
}
280281

281282
const seqAfter: number = rs.rows?.item(0)['seq'];
282-
this.logger.debug('seqAfter', JSON.stringify(rs.rows?.item(0)));
283283
if (seqAfter != seqBefore) {
284-
this.logger.debug('seqAfter != seqBefore', seqAfter, seqBefore);
284+
this.logger.debug(
285+
`New data uploaded since write checpoint ${opId} - need new write checkpoint (sequence updated)`
286+
);
287+
285288
// New crud data may have been uploaded since we got the checkpoint. Abort.
286289
return false;
287290
}
288291

289-
const response = await tx.execute("UPDATE ps_buckets SET target_op = CAST(? as INTEGER) WHERE name='$local'", [
290-
opId
291-
]);
292-
this.logger.debug(['[updateLocalTarget] Response from updating target_op ', JSON.stringify(response)]);
292+
this.logger.debug(`Updating target write checkpoint to ${opId}`);
293+
await tx.execute("UPDATE ps_buckets SET target_op = CAST(? as INTEGER) WHERE name='$local'", [opId]);
293294
return true;
294295
});
295296
}

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

Lines changed: 13 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -205,7 +205,6 @@ export const DEFAULT_RETRY_DELAY_MS = 5000;
205205

206206
export const DEFAULT_STREAMING_SYNC_OPTIONS = {
207207
retryDelayMs: DEFAULT_RETRY_DELAY_MS,
208-
logger: Logger.get('PowerSyncStream'),
209208
crudUploadThrottleMs: DEFAULT_CRUD_UPLOAD_THROTTLE_MS
210209
};
211210

@@ -234,6 +233,7 @@ export abstract class AbstractStreamingSyncImplementation
234233
protected abortController: AbortController | null;
235234
protected crudUpdateListener?: () => void;
236235
protected streamingSyncPromise?: Promise<void>;
236+
protected logger: ILogger;
237237

238238
private isUploadingCrud: boolean = false;
239239
private notifyCompletedUploads?: () => void;
@@ -244,6 +244,7 @@ export abstract class AbstractStreamingSyncImplementation
244244
constructor(options: AbstractStreamingSyncImplementationOptions) {
245245
super();
246246
this.options = { ...DEFAULT_STREAMING_SYNC_OPTIONS, ...options };
247+
this.logger = options.logger ?? Logger.get('PowerSyncStream');
247248

248249
this.syncStatus = new SyncStatus({
249250
connected: false,
@@ -318,10 +319,6 @@ export abstract class AbstractStreamingSyncImplementation
318319
return this.syncStatus.connected;
319320
}
320321

321-
protected get logger() {
322-
return this.options.logger!;
323-
}
324-
325322
async dispose() {
326323
this.crudUpdateListener?.();
327324
this.crudUpdateListener = undefined;
@@ -337,7 +334,9 @@ export abstract class AbstractStreamingSyncImplementation
337334
const clientId = await this.options.adapter.getClientId();
338335
let path = `/write-checkpoint2.json?client_id=${clientId}`;
339336
const response = await this.options.remote.get(path);
340-
return response['data']['write_checkpoint'] as string;
337+
const checkpoint = response['data']['write_checkpoint'] as string;
338+
this.logger.debug(`Created write checkpoint: ${checkpoint}`);
339+
return checkpoint;
341340
}
342341

343342
protected async _uploadAllCrud(): Promise<void> {
@@ -379,7 +378,11 @@ The next upload iteration will be delayed.`);
379378
});
380379
} else {
381380
// Uploading is completed
382-
await this.options.adapter.updateLocalTarget(() => this.getWriteCheckpoint());
381+
const neededUpdate = await this.options.adapter.updateLocalTarget(() => this.getWriteCheckpoint());
382+
if (neededUpdate == false && checkedCrudItem != null) {
383+
// Only log this if there was something to upload
384+
this.logger.debug('Upload complete, no write checkpoint needed.');
385+
}
383386
break;
384387
}
385388
} catch (ex) {
@@ -1105,20 +1108,20 @@ The next upload iteration will be delayed.`);
11051108
let result = await this.options.adapter.syncLocalDatabase(checkpoint);
11061109

11071110
if (!result.checkpointValid) {
1108-
this.logger.debug('Checksum mismatch in checkpoint, will reconnect');
1111+
this.logger.debug(`Checksum mismatch in checkpoint ${checkpoint.last_op_id}, will reconnect`);
11091112
// This means checksums failed. Start again with a new checkpoint.
11101113
// TODO: better back-off
11111114
await new Promise((resolve) => setTimeout(resolve, 50));
11121115
return { applied: false, endIteration: true };
11131116
} else if (!result.ready) {
11141117
this.logger.debug(
1115-
'Could not apply checkpoint due to local data. We will retry applying the checkpoint after that upload is completed.'
1118+
`Could not apply checkpoint ${checkpoint.last_op_id} due to local data. We will retry applying the checkpoint after that upload is completed.`
11161119
);
11171120

11181121
return { applied: false, endIteration: false };
11191122
}
11201123

1121-
this.logger.debug('validated checkpoint', checkpoint);
1124+
this.logger.debug(`Applied checkpoint ${checkpoint.last_op_id}`, checkpoint);
11221125
this.updateSyncStatus({
11231126
connected: true,
11241127
lastSyncedAt: new Date(),

‎packages/node/src/db/PowerSyncDatabase.ts‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -64,7 +64,7 @@ export class PowerSyncDatabase extends AbstractPowerSyncDatabase {
6464
}
6565

6666
protected generateBucketStorageAdapter(): BucketStorageAdapter {
67-
return new SqliteBucketStorage(this.database);
67+
return new SqliteBucketStorage(this.database, this.logger);
6868
}
6969

7070
connect(
@@ -78,7 +78,7 @@ export class PowerSyncDatabase extends AbstractPowerSyncDatabase {
7878
connector: PowerSyncBackendConnector,
7979
options: NodeAdditionalConnectionOptions
8080
): AbstractStreamingSyncImplementation {
81-
const logger = this.options.logger;
81+
const logger = this.logger;
8282
const remote = new NodeRemote(connector, logger, {
8383
dispatcher: options.dispatcher,
8484
...(this.options as NodePowerSyncDatabaseOptions).remoteOptions

‎packages/react-native/src/db/PowerSyncDatabase.ts‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -39,14 +39,14 @@ export class PowerSyncDatabase extends AbstractPowerSyncDatabase {
3939
}
4040

4141
protected generateBucketStorageAdapter(): BucketStorageAdapter {
42-
return new ReactNativeBucketStorageAdapter(this.database);
42+
return new ReactNativeBucketStorageAdapter(this.database, this.logger);
4343
}
4444

4545
protected generateSyncStreamImplementation(
4646
connector: PowerSyncBackendConnector,
4747
options: RequiredAdditionalConnectionOptions
4848
): AbstractStreamingSyncImplementation {
49-
const remote = new ReactNativeRemote(connector);
49+
const remote = new ReactNativeRemote(connector, this.logger);
5050

5151
return new ReactNativeStreamingSyncImplementation({
5252
adapter: this.bucketStorageAdapter,
@@ -57,7 +57,8 @@ export class PowerSyncDatabase extends AbstractPowerSyncDatabase {
5757
},
5858
retryDelayMs: options.retryDelayMs,
5959
crudUploadThrottleMs: options.crudUploadThrottleMs,
60-
identifier: this.database.name
60+
identifier: this.database.name,
61+
logger: this.logger
6162
});
6263
}
6364
}

‎packages/web/src/db/PowerSyncDatabase.ts‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -186,7 +186,7 @@ export class PowerSyncDatabase extends AbstractPowerSyncDatabase {
186186
connector: PowerSyncBackendConnector,
187187
options: RequiredAdditionalConnectionOptions
188188
): StreamingSyncImplementation {
189-
const remote = new WebRemote(connector);
189+
const remote = new WebRemote(connector, this.logger);
190190
const syncOptions: WebStreamingSyncImplementationOptions = {
191191
...(this.options as {}),
192192
retryDelayMs: options.retryDelayMs,
@@ -198,7 +198,8 @@ export class PowerSyncDatabase extends AbstractPowerSyncDatabase {
198198
await this.waitForReady();
199199
await connector.uploadData(this);
200200
},
201-
identifier: this.database.name
201+
identifier: this.database.name,
202+
logger: this.logger
202203
};
203204

204205
switch (true) {

0 commit comments

Comments
 (0)