From 41fca4569839afe3aac20d3f93e2a51fbfb46891 Mon Sep 17 00:00:00 2001 From: Bao Nguyen Date: Fri, 14 Aug 2026 09:00:39 +0700 Subject: [PATCH 1/2] Log errors from watched queries Errors raised while resolving or executing a watched query were only reported on the query state and to error listeners. Neither is inspected by default, so `useQuery` appeared to silently do nothing when the query was invalid. Log the error with the database's logger from `AbstractQueryProcessor`, which covers both the table resolution and query execution paths, and do the same for the `runQueryOnce` path in `useSingleQuery`. The default `onError` handler of `watchWithCallback` logged the error itself. That is now handled by the watched query, so the default handler no longer logs to avoid emitting the same error twice. --- .changeset/log-watched-query-errors.md | 6 ++ .../react/src/hooks/watched/useSingleQuery.ts | 8 ++ packages/react/tests/useQuery.test.tsx | 95 ++++++++++++++++++- .../src/client/BasePowerSyncDatabase.ts | 4 +- .../client/watched/AbstractQueryProcessor.ts | 10 ++ 5 files changed, 121 insertions(+), 2 deletions(-) create mode 100644 .changeset/log-watched-query-errors.md diff --git a/.changeset/log-watched-query-errors.md b/.changeset/log-watched-query-errors.md new file mode 100644 index 000000000..c2454de6e --- /dev/null +++ b/.changeset/log-watched-query-errors.md @@ -0,0 +1,6 @@ +--- +'@powersync/shared-internals': patch +'@powersync/react': patch +--- + +Log errors from watched queries with the PowerSync database's logger. Failures such as invalid SQL or a missing table previously only surfaced on the query state, so `useQuery` appeared to silently do nothing. diff --git a/packages/react/src/hooks/watched/useSingleQuery.ts b/packages/react/src/hooks/watched/useSingleQuery.ts index be434c0d4..a4890805a 100644 --- a/packages/react/src/hooks/watched/useSingleQuery.ts +++ b/packages/react/src/hooks/watched/useSingleQuery.ts @@ -1,3 +1,4 @@ +import { LogLevels } from '@powersync/common'; import React from 'react'; import { QueryResult } from './watch-types.js'; import { InternalHookOptions } from './watch-utils.js'; @@ -36,6 +37,13 @@ export const useSingleQuery = (options: InternalHookOptions ({ ...prev, isLoading: false, diff --git a/packages/react/tests/useQuery.test.tsx b/packages/react/tests/useQuery.test.tsx index 273b5730e..c6dd04ebf 100644 --- a/packages/react/tests/useQuery.test.tsx +++ b/packages/react/tests/useQuery.test.tsx @@ -5,7 +5,7 @@ import { eq } from 'drizzle-orm'; import { sqliteTable, text } from 'drizzle-orm/sqlite-core'; import pDefer from 'p-defer'; import React, { useEffect } from 'react'; -import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { beforeEach, describe, expect, it, onTestFinished, vi } from 'vitest'; import { PowerSyncContext } from '../src/hooks/PowerSyncContext'; import { useQuery } from '../src/hooks/watched/useQuery'; import { useWatchedQuerySubscription } from '../src/hooks/watched/useWatchedQuerySubscription'; @@ -22,6 +22,47 @@ describe('useQuery', () => { {children} ); + /** + * Watches both the database logger (the structured record) and `console.error` (what a developer + * actually sees, since the default logger forwards error records there). + */ + const spyOnErrorLogs = (db: commonSdk.AbstractPowerSyncDatabase) => { + const logger = vi.spyOn(db.logger, 'log'); + const consoleError = vi.spyOn(console, 'error'); + onTestFinished(() => { + logger.mockRestore(); + consoleError.mockRestore(); + }); + return { logger, consoleError }; + }; + + const expectLoggedError = ( + spies: ReturnType, + expectedMessage: string, + expectedLogMessage = 'Error in watched query' + ) => { + const errorRecords = spies.logger.mock.calls + .map(([record]) => record) + .filter((record) => record.level >= commonSdk.LogLevels.error); + + expect(errorRecords.length).toBeGreaterThan(0); + // The log has to carry the underlying error, otherwise it does not help with discovery. + expect( + errorRecords.some( + (record) => record.message == expectedLogMessage && (record.error as Error)?.message == expectedMessage + ) + ).toBe(true); + // The issue reports an empty console, so assert on the actual developer-visible output too. + expect( + spies.consoleError.mock.calls.some( + ([message, error]) => + typeof message == 'string' && + message.includes(expectedLogMessage) && + (error as Error)?.message == expectedMessage + ) + ).toBe(true); + }; + const testCases = [ { mode: 'normal', @@ -76,6 +117,58 @@ describe('useQuery', () => { ); }); + it('should log the error when a watched query fails to resolve its tables', async () => { + const db = openPowerSync(); + const spies = spyOnErrorLogs(db); + + renderHook(() => useQuery('SELECT * from faketable', []), { + wrapper: ({ children }) => testWrapper({ children, db }) + }); + + await waitFor(async () => expectLoggedError(spies, 'no such table: faketable'), { + timeout: 2000, + interval: 100 + }); + }); + + it('should log the error when a watched query fails while executing', async () => { + const db = openPowerSync(); + const spies = spyOnErrorLogs(db); + + // The tables of this query resolve successfully, the failure only happens once the query is + // executed. This is the path a query builder such as Kysely takes when the generated SQL is + // valid but execution fails at runtime. + const query: commonSdk.CompilableQuery = { + compile: () => ({ sql: 'SELECT * from lists', parameters: [] }), + execute: async () => { + throw new Error('simulated execute failure'); + } + }; + + renderHook(() => useQuery(query), { + wrapper: ({ children }) => testWrapper({ children, db }) + }); + + await waitFor(async () => expectLoggedError(spies, 'simulated execute failure'), { + timeout: 2000, + interval: 100 + }); + }); + + it('should log the error when a query with the runQueryOnce flag fails', async () => { + const db = openPowerSync(); + const spies = spyOnErrorLogs(db); + + renderHook(() => useQuery('SELECT * from faketable', [], { runQueryOnce: true }), { + wrapper: ({ children }) => testWrapper({ children, db }) + }); + + await waitFor(async () => expectLoggedError(spies, 'no such table: faketable'), { + timeout: 2000, + interval: 100 + }); + }); + it('should rerun the query when refresh is used', async () => { const db = openPowerSync(); const getAllSpy = vi.spyOn(db, 'getAll'); diff --git a/packages/shared-internals/src/client/BasePowerSyncDatabase.ts b/packages/shared-internals/src/client/BasePowerSyncDatabase.ts index fba0cd78a..e12662858 100644 --- a/packages/shared-internals/src/client/BasePowerSyncDatabase.ts +++ b/packages/shared-internals/src/client/BasePowerSyncDatabase.ts @@ -656,7 +656,9 @@ SELECT * FROM crud_entries; watchWithCallback(sql: string, parameters?: any[], handler?: WatchHandler, options?: SQLWatchOptions): void { const { onResult, - onError = (e: Error) => this.logger.log({ level: LogLevels.error, message: 'Error in watch', error: e }) + // The watched query already logs errors with this database's logger, so the default handler + // only has to avoid rethrowing. + onError = () => {} } = handler ?? {}; if (!onResult) { throw new Error('onResult is required'); diff --git a/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts b/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts index 04b27a9b3..dfe59e9b4 100644 --- a/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts +++ b/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts @@ -138,6 +138,16 @@ export abstract class AbstractQueryProcessor< } if (typeof update.error !== 'undefined') { + if (update.error) { + // Errors are also reported on the query state and to error listeners, but those are easy to + // miss. Logging makes failures such as invalid SQL discoverable without extra wiring. + // Note that `error: null` is used to clear a previous error, which should not be logged. + this.options.db.logger.log({ + level: LogLevels.error, + message: 'Error in watched query', + error: update.error + }); + } await this.iterateAsyncListenersWithError(async (l) => l.onError?.(update.error!)); // An error always stops for the current fetching state update.isFetching = false; From afdfbc53b59af3f004b74303b2ecb89255753dd2 Mon Sep 17 00:00:00 2001 From: Bao Nguyen Date: Sat, 22 Aug 2026 15:57:22 +0700 Subject: [PATCH 2/2] Only log watched query errors when nothing else handles them Review feedback on #1068. The processor now skips its log when a listener registered an `onError` handler, since such a listener already reports the error itself. That makes `watchWithCallback`'s default `onError` unnecessary: it is left undefined when the caller does not supply one, restoring the original behaviour of that API for callers that do handle errors, while callers that do not still get a log. `useSingleQuery` hoists `compiledQuery` out of the try block (still only assigned inside it, so a throwing `compile()` leaves it undefined) so the generated SQL can be included in the log when `execute` fails. --- .changeset/log-watched-query-errors.md | 2 +- .../react/src/hooks/watched/useSingleQuery.ts | 9 ++- packages/react/tests/useQuery.test.tsx | 29 ++++++++- .../src/client/BasePowerSyncDatabase.ts | 13 ++-- .../client/watched/AbstractQueryProcessor.ts | 17 +++-- packages/web/tests/watch.test.ts | 65 +++++++++++++++++++ 6 files changed, 117 insertions(+), 18 deletions(-) diff --git a/.changeset/log-watched-query-errors.md b/.changeset/log-watched-query-errors.md index c2454de6e..ae4a4625b 100644 --- a/.changeset/log-watched-query-errors.md +++ b/.changeset/log-watched-query-errors.md @@ -3,4 +3,4 @@ '@powersync/react': patch --- -Log errors from watched queries with the PowerSync database's logger. Failures such as invalid SQL or a missing table previously only surfaced on the query state, so `useQuery` appeared to silently do nothing. +Log errors from watched queries with the PowerSync database's logger. Failures such as invalid SQL or a missing table previously only surfaced on the query state, so `useQuery` appeared to silently do nothing. Queries whose listeners register an `onError` handler are left alone, since those report errors themselves. diff --git a/packages/react/src/hooks/watched/useSingleQuery.ts b/packages/react/src/hooks/watched/useSingleQuery.ts index a4890805a..dc79a9109 100644 --- a/packages/react/src/hooks/watched/useSingleQuery.ts +++ b/packages/react/src/hooks/watched/useSingleQuery.ts @@ -1,4 +1,4 @@ -import { LogLevels } from '@powersync/common'; +import { CompiledQuery, LogLevels } from '@powersync/common'; import React from 'react'; import { QueryResult } from './watch-types.js'; import { InternalHookOptions } from './watch-utils.js'; @@ -19,8 +19,11 @@ export const useSingleQuery = (options: InternalHookOptions { setOutputState((prev) => ({ ...prev, isLoading: true, isFetching: true, error: undefined })); + // Declared here, but only assigned inside the try block, so that the generated SQL can be reported + // when `execute` fails. It stays undefined if `compile` itself is what threw. + let compiledQuery: CompiledQuery | undefined; try { - const compiledQuery = query.compile(); + compiledQuery = query.compile(); const result = await query.execute({ sql: compiledQuery.sql, parameters: [...compiledQuery.parameters], @@ -41,7 +44,7 @@ export const useSingleQuery = (options: InternalHookOptions ({ diff --git a/packages/react/tests/useQuery.test.tsx b/packages/react/tests/useQuery.test.tsx index c6dd04ebf..2b9843719 100644 --- a/packages/react/tests/useQuery.test.tsx +++ b/packages/react/tests/useQuery.test.tsx @@ -49,7 +49,7 @@ describe('useQuery', () => { // The log has to carry the underlying error, otherwise it does not help with discovery. expect( errorRecords.some( - (record) => record.message == expectedLogMessage && (record.error as Error)?.message == expectedMessage + (record) => record.message.includes(expectedLogMessage) && (record.error as Error)?.message == expectedMessage ) ).toBe(true); // The issue reports an empty console, so assert on the actual developer-visible output too. @@ -155,6 +155,33 @@ describe('useQuery', () => { }); }); + it('should include the generated SQL when a runQueryOnce query fails to execute', async () => { + const db = openPowerSync(); + const spies = spyOnErrorLogs(db); + + // `compile` succeeds here, only `execute` fails. The compiled SQL is the interesting part of such + // a failure, since the caller only ever supplied a query builder. + const sql = 'SELECT * from lists WHERE name = ?'; + const query: commonSdk.CompilableQuery = { + compile: () => ({ sql, parameters: ['a name'] }), + execute: async () => { + throw new Error('simulated execute failure'); + } + }; + + renderHook(() => useQuery(query, [], { runQueryOnce: true }), { + wrapper: ({ children }) => testWrapper({ children, db }) + }); + + await waitFor( + async () => expectLoggedError(spies, 'simulated execute failure', `Error in watched query: ${sql}`), + { + timeout: 2000, + interval: 100 + } + ); + }); + it('should log the error when a query with the runQueryOnce flag fails', async () => { const db = openPowerSync(); const spies = spyOnErrorLogs(db); diff --git a/packages/shared-internals/src/client/BasePowerSyncDatabase.ts b/packages/shared-internals/src/client/BasePowerSyncDatabase.ts index ec2e92aae..885513ceb 100644 --- a/packages/shared-internals/src/client/BasePowerSyncDatabase.ts +++ b/packages/shared-internals/src/client/BasePowerSyncDatabase.ts @@ -706,12 +706,9 @@ SELECT * FROM crud_entries; } watchWithCallback(sql: string, parameters?: any[], handler?: WatchHandler, options?: SQLWatchOptions): void { - const { - onResult, - // The watched query already logs errors with this database's logger, so the default handler - // only has to avoid rethrowing. - onError = () => {} - } = handler ?? {}; + // `onError` is deliberately left undefined when the caller did not supply one: the watched query logs + // unhandled errors with this database's logger, and registering a handler here would suppress that. + const { onResult, onError } = handler ?? {}; if (!onResult) { throw new Error('onResult is required'); } @@ -745,9 +742,7 @@ SELECT * FROM crud_entries; } onResult(data); }, - onError: (error) => { - onError(error); - } + onError }); options?.signal?.addEventListener('abort', () => { diff --git a/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts b/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts index dfe59e9b4..7b2c496fb 100644 --- a/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts +++ b/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts @@ -132,16 +132,25 @@ export abstract class AbstractQueryProcessor< */ protected abstract linkQuery(options: LinkQueryOptions): Promise; + /** + * Whether any of the registered listeners handles errors itself. + * These are the listeners which {@link AbstractQueryProcessor.updateState} reports errors to. + */ + protected get hasErrorListener(): boolean { + return (this.listenerCounts[WatchedQueryListenerEvent.ON_ERROR] ?? 0) > 0; + } + protected async updateState(update: Partial>) { if (this._closed) { return; } if (typeof update.error !== 'undefined') { - if (update.error) { - // Errors are also reported on the query state and to error listeners, but those are easy to - // miss. Logging makes failures such as invalid SQL discoverable without extra wiring. - // Note that `error: null` is used to clear a previous error, which should not be logged. + // `error: null` is used to clear a previous error, which should not be logged. + if (update.error && !this.hasErrorListener) { + // Errors are also reported on the query state, but that is easy to miss. Logging makes failures such as + // invalid SQL discoverable without extra wiring. Listeners which registered an `onError` handler report + // errors themselves, so logging here would only duplicate their output. this.options.db.logger.log({ level: LogLevels.error, message: 'Error in watched query', diff --git a/packages/web/tests/watch.test.ts b/packages/web/tests/watch.test.ts index 6e3eabee7..0739a184a 100644 --- a/packages/web/tests/watch.test.ts +++ b/packages/web/tests/watch.test.ts @@ -2,6 +2,7 @@ import { CommonPowerSyncDatabase, ArrayComparator, GetAllQuery, + LogLevels, QueryResult, WatchedQueryDifferential, WatchedQueryState @@ -41,6 +42,20 @@ describe('Watch Tests', { sequential: true }, () => { await powersync.close(); }); + const spyOnLogger = (db: CommonPowerSyncDatabase) => { + const logSpy = vi.spyOn(db.logger, 'log'); + onTestFinished(() => logSpy.mockRestore()); + return logSpy; + }; + + /** + * The error records a watched query logged because nothing else handled the error. + */ + const watchedQueryErrorLogs = (logSpy: ReturnType) => + logSpy.mock.calls + .map(([record]) => record) + .filter((record) => record.level >= LogLevels.error && record.message.includes('Error in watched query')); + it('watch outside throttle limits', async () => { const abortController = new AbortController(); @@ -493,6 +508,56 @@ describe('Watch Tests', { sequential: true }, () => { expect(receivedErrorCount).equals(1); }); + it('should log watch errors when no onError callback is supplied', async () => { + const abortController = new AbortController(); + onTestFinished(() => abortController.abort()); + const logSpy = spyOnLogger(powersync); + + powersync.watch( + 'INVALID SQL QUERY', // Simulate an error with bad SQL + [], + { onResult: () => {} }, + { signal: abortController.signal, throttleMs: throttleDuration } + ); + + await vi.waitFor( + () => { + expect(watchedQueryErrorLogs(logSpy).length).toBeGreaterThan(0); + }, + { timeout: 2000 } + ); + }); + + it('should not log watch errors when an onError callback is supplied', async () => { + const abortController = new AbortController(); + onTestFinished(() => abortController.abort()); + const logSpy = spyOnLogger(powersync); + + let receivedErrorCount = 0; + powersync.watch( + 'INVALID SQL QUERY', // Simulate an error with bad SQL + [], + { + onResult: () => {}, + onError: () => { + receivedErrorCount++; + } + }, + { signal: abortController.signal, throttleMs: throttleDuration } + ); + + await vi.waitFor( + () => { + expect(receivedErrorCount).toBeGreaterThan(0); + }, + { timeout: 2000 } + ); + + // The watched query logs before dispatching to error listeners, so any log for this error would + // already have been recorded here. + expect(watchedQueryErrorLogs(logSpy)).toEqual([]); + }); + it('should throttle watch callback overflow', async () => { const overflowAbortController = new AbortController(); const updatesCount = 25;