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.

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 = <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: '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 == 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<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 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

@@ -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');

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;