diff --git a/.changeset/log-watched-query-errors.md b/.changeset/log-watched-query-errors.md new file mode 100644 index 000000000..ae4a4625b --- /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. 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 be434c0d4..dc79a9109 100644 --- a/packages/react/src/hooks/watched/useSingleQuery.ts +++ b/packages/react/src/hooks/watched/useSingleQuery.ts @@ -1,3 +1,4 @@ +import { CompiledQuery, LogLevels } from '@powersync/common'; import React from 'react'; import { QueryResult } from './watch-types.js'; import { InternalHookOptions } from './watch-utils.js'; @@ -18,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], @@ -36,6 +40,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..2b9843719 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.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. + 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,85 @@ 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 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); + + 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 4edbd3f6b..885513ceb 100644 --- a/packages/shared-internals/src/client/BasePowerSyncDatabase.ts +++ b/packages/shared-internals/src/client/BasePowerSyncDatabase.ts @@ -706,10 +706,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 }) - } = 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'); } @@ -743,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 04b27a9b3..7b2c496fb 100644 --- a/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts +++ b/packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts @@ -132,12 +132,31 @@ 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') { + // `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', + error: update.error + }); + } await this.iterateAsyncListenersWithError(async (l) => l.onError?.(update.error!)); // An error always stops for the current fetching state update.isFetching = false; 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;