Log errors from watched queries

.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.

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 = <RowType = any>(options: InternalHookOptions<RowTy
   const runQuery = React.useCallback(
     async (signal?: AbortSignal) => {
       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 = <RowType = any>(options: InternalHookOptions<RowTy
           error: undefined
         }));
       } catch (error) {
+        // Matches the logging done by watched queries, so that `runQueryOnce` failures are just as
+        // discoverable.
+        powerSync.logger.log({
+          level: LogLevels.error,
+          message: compiledQuery ? `Error in watched query: ${compiledQuery.sql}` : 'Error in watched query',
+          error
+        });
         setOutputState((prev) => ({
           ...prev,
           isLoading: false,

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', () => {
     <PowerSyncContext.Provider value={db}>{children}</PowerSyncContext.Provider>
   );
 
+  /**
+   * 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<typeof spyOnErrorLogs>,
+    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<any> = {
+          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<any> = {
+          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');

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', () => {

packages/shared-internals/src/client/watched/AbstractQueryProcessor.ts

@@ -132,12 +132,31 @@ export abstract class AbstractQueryProcessor<
    */
   protected abstract linkQuery(options: LinkQueryOptions<Data>): Promise<void>;
 
+  /**
+   * 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<MutableWatchedQueryState<Data>>) {
     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;

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<typeof spyOnLogger>) =>
+    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;